Icinga / icinga-kubernetes

GNU Affero General Public License v3.0
11 stars 2 forks source link

"Observed a panic" panic="send on closed channel" panicGoValue="\"send on closed channel\"" #142

Open firatalkis opened 4 days ago

firatalkis commented 4 days ago

Hi,

I am getting this error when I start icinga-kubernetes.

mysql -V mysql Ver 15.1 Distrib 10.3.39-MariaDB, for Linux (x86_64) using readline 5.1

cat /etc/os-release NAME="Red Hat Enterprise Linux" VERSION="8.10 (Ootpa)" ID="rhel" ID_LIKE="fedora" VERSION_ID="8.10" PLATFORM_ID="platform:el8" PRETTY_NAME="Red Hat Enterprise Linux 8.10 (Ootpa)"

/usr/sbin/icinga-kubernetes --config /etc/icinga-kubernetes/config.yml
I1017 11:00:05.949731 1527880 main.go:69] Starting Icinga for Kubernetes (v0.2.0)
I1017 11:00:05.953156 1527880 database.go:286] "Connecting to database" logger="database"
E1017 11:00:06.442995 1527880 select.go:526] "Observed a panic" panic="send on closed channel" panicGoValue="\"send on closed channel\"" stacktrace=<
        goroutine 6614 [running]:
        k8s.io/apimachinery/pkg/util/runtime.logPanic({0x21b2988, 0x325faa0}, {0x1bba420, 0x218bd90})
                k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:107 +0xbc
        k8s.io/apimachinery/pkg/util/runtime.handleCrash({0x21b2988, 0x325faa0}, {0x1bba420, 0x218bd90}, {0x325faa0, 0x0, 0x438ec5?})
                k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:82 +0x5e
        k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc0049241c0?})
                k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:59 +0x108
        panic({0x1bba420?, 0x218bd90?})
                runtime/panic.go:785 +0x132
        github.com/icinga/icinga-kubernetes/pkg/database.(*hasMany[...]).StreamInto(0x2190020?, {0x21b2a30, 0xc006bd8c30}, 0xc006bd3180)
                github.com/icinga/icinga-kubernetes/pkg/database/relations.go:76 +0x145
        github.com/icinga/icinga-kubernetes/pkg/database.(*Database).UpsertStreamed.func3.1()
                github.com/icinga/icinga-kubernetes/pkg/database/database.go:573 +0xa5
        golang.org/x/sync/errgroup.(*Group).Go.func1()
                golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x50
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 2351
                golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x96
 >
panic: send on closed channel [recovered]
        panic: send on closed channel

goroutine 6614 [running]:
k8s.io/apimachinery/pkg/util/runtime.handleCrash({0x21b2988, 0x325faa0}, {0x1bba420, 0x218bd90}, {0x325faa0, 0x0, 0x438ec5?})
        k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:89 +0xee
k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc0049241c0?})
        k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:59 +0x108
panic({0x1bba420?, 0x218bd90?})
        runtime/panic.go:785 +0x132
github.com/icinga/icinga-kubernetes/pkg/database.(*hasMany[...]).StreamInto(0x2190020?, {0x21b2a30, 0xc006bd8c30}, 0xc006bd3180)
        github.com/icinga/icinga-kubernetes/pkg/database/relations.go:76 +0x145
github.com/icinga/icinga-kubernetes/pkg/database.(*Database).UpsertStreamed.func3.1()
        github.com/icinga/icinga-kubernetes/pkg/database/database.go:573 +0xa5
golang.org/x/sync/errgroup.(*Group).Go.func1()
        golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x50
created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 2351
        golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x96
lippserd commented 4 days ago

Hi @firatalkis,

Thanks for the report. Could you please run the following command which increases verbosity and post the output:

/usr/sbin/icinga-kubernetes --config /etc/icinga-kubernetes/config.yml -v 2

Best regards, Eric

firatalkis commented 4 days ago

ofcourse :) ı run the command, you can see output below:

/usr/sbin/icinga-kubernetes --config /etc/icinga-kubernetes/config.yml -v 2
I1017 11:12:20.757438 1531365 main.go:69] Starting Icinga for Kubernetes (v0.2.0)
I1017 11:12:20.761276 1531365 database.go:286] "Connecting to database" logger="database"
I1017 11:12:20.772876 1531365 envvar.go:172] "Feature gate default state" feature="WatchListClient" enabled=false
I1017 11:12:20.772909 1531365 envvar.go:172] "Feature gate default state" feature="InformerResourceVersion" enabled=false
I1017 11:12:20.774716 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `daemon_set` with 20 rows in 2.926612ms" logger="database"
I1017 11:12:20.805949 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `node` with 9 rows in 31.824982ms" logger="database"
I1017 11:12:20.806756 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `deployment` with 0 rows in 32.643002ms" logger="database"
I1017 11:12:20.807268 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `service` with 91 rows in 35.08884ms" logger="database"
I1017 11:12:20.807538 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `secret` with 0 rows in 35.032931ms" logger="database"
I1017 11:12:20.815864 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `job` with 101 rows in 34.132704ms" logger="database"
I1017 11:12:20.816305 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `namespace` with 269 rows in 42.234672ms" logger="database"
I1017 11:12:20.827661 1531365 database.go:647] "Finished executing SELECT `last_update`, `pod_uuid`, `container_uuid`, `logs` FROM `container_log` with 0 rows in 43.493352ms" logger="database"
I1017 11:12:20.844629 1531365 database.go:647] "Finished executing DELETE FROM prometheus_pod_metric WHERE timestamp < :time\nORDER BY timestamp LIMIT 5000 with 0 rows in 70.743561ms" logger="database"
I1017 11:12:20.844663 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `stateful_set` with 9 rows in 72.580405ms" logger="database"
I1017 11:12:20.844723 1531365 database.go:647] "Finished executing DELETE FROM prometheus_node_metric WHERE timestamp < :time\nORDER BY timestamp LIMIT 5000 with 0 rows in 71.028083ms" logger="database"
I1017 11:12:20.845550 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `pvc` with 17 rows in 72.777676ms" logger="database"
I1017 11:12:20.846379 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `endpoint_slice` with 974 rows in 74.102343ms" logger="database"
I1017 11:12:20.854149 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `pod` with 0 rows in 26.192304ms" logger="database"
I1017 11:12:20.854460 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `config_map` with 0 rows in 81.900826ms" logger="database"
I1017 11:12:20.854546 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `cron_job` with 5 rows in 81.249443ms" logger="database"
I1017 11:12:20.854581 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `persistent_volume` with 17 rows in 81.542208ms" logger="database"
I1017 11:12:20.854642 1531365 database.go:647] "Finished executing DELETE FROM prometheus_cluster_metric WHERE timestamp < :time\nORDER BY timestamp LIMIT 5000 with 0 rows in 81.085227ms" logger="database"
I1017 11:12:20.854850 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `ingress` with 1 rows in 81.429208ms" logger="database"
I1017 11:12:20.859930 1531365 database.go:647] "Finished executing DELETE FROM prometheus_container_metric WHERE timestamp < :time\nORDER BY timestamp LIMIT 5000 with 0 rows in 86.217467ms" logger="database"
I1017 11:12:20.860001 1531365 database.go:647] "Finished executing DELETE FROM event WHERE created < :time\nORDER BY created LIMIT 5000 with 0 rows in 86.602095ms" logger="database"
I1017 11:12:20.862425 1531365 database.go:647] "Finished executing SELECT `uuid`, `uid`, `namespace`, `name`, `resource_version`, `created` FROM `replica_set` with 0 rows in 90.352533ms" logger="database"
I1017 11:12:20.894458 1531365 reflector.go:368] Caches populated for *v1.Ingress from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:20.905822 1531365 reflector.go:368] Caches populated for *v1.CronJob from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:20.916251 1531365 reflector.go:368] Caches populated for *v1.PersistentVolume from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:20.922596 1531365 reflector.go:368] Caches populated for *v1.StatefulSet from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:20.932786 1531365 reflector.go:368] Caches populated for *v1.PersistentVolumeClaim from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:20.938420 1531365 reflector.go:368] Caches populated for *v1.Node from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:20.966345 1531365 reflector.go:368] Caches populated for *v1.DaemonSet from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:21.010927 1531365 reflector.go:368] Caches populated for *v1.Namespace from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:21.039641 1531365 reflector.go:368] Caches populated for *v1.Job from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:21.100629 1531365 reflector.go:368] Caches populated for *v1.Service from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:21.108996 1531365 reflector.go:368] Caches populated for *v1.EndpointSlice from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:12:21.282547 1531365 database.go:647] "Finished executing INSERT INTO `label` (`uuid`, `name`, `value`) VALUES (:uuid, :name, :value) ON DUPLICATE KEY UPDATE `uuid` = VALUES(`uuid`), `name` = VALUES(`name`), `value` = VALUES(`value`) with 0 rows in 135.535955ms" logger="database"
E1017 11:12:21.282715 1531365 select.go:526] "Observed a panic" panic="send on closed channel" panicGoValue="\"send on closed channel\"" stacktrace=<
        goroutine 6369 [running]:
        k8s.io/apimachinery/pkg/util/runtime.logPanic({0x21b2988, 0x325faa0}, {0x1bba420, 0x218bd90})
                k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:107 +0xbc
        k8s.io/apimachinery/pkg/util/runtime.handleCrash({0x21b2988, 0x325faa0}, {0x1bba420, 0x218bd90}, {0x325faa0, 0x0, 0x438ec5?})
                k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:82 +0x5e
        k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc0007ff340?})
                k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:59 +0x108
        panic({0x1bba420?, 0x218bd90?})
                runtime/panic.go:785 +0x132
        github.com/icinga/icinga-kubernetes/pkg/database.(*hasMany[...]).StreamInto(0x2190020?, {0x21b2a30, 0xc00665ebe0}, 0xc0038f67e0)
                github.com/icinga/icinga-kubernetes/pkg/database/relations.go:76 +0x145
        github.com/icinga/icinga-kubernetes/pkg/database.(*Database).UpsertStreamed.func3.1()
                github.com/icinga/icinga-kubernetes/pkg/database/database.go:573 +0xa5
        golang.org/x/sync/errgroup.(*Group).Go.func1()
                golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x50
        created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 2787
                golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x96
 >
panic: send on closed channel [recovered]
        panic: send on closed channel

goroutine 6369 [running]:
k8s.io/apimachinery/pkg/util/runtime.handleCrash({0x21b2988, 0x325faa0}, {0x1bba420, 0x218bd90}, {0x325faa0, 0x0, 0x438ec5?})
        k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:89 +0xee
k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc0007ff340?})
        k8s.io/apimachinery@v0.31.1/pkg/util/runtime/runtime.go:59 +0x108
panic({0x1bba420?, 0x218bd90?})
        runtime/panic.go:785 +0x132
github.com/icinga/icinga-kubernetes/pkg/database.(*hasMany[...]).StreamInto(0x2190020?, {0x21b2a30, 0xc00665ebe0}, 0xc0038f67e0)
        github.com/icinga/icinga-kubernetes/pkg/database/relations.go:76 +0x145
github.com/icinga/icinga-kubernetes/pkg/database.(*Database).UpsertStreamed.func3.1()
        github.com/icinga/icinga-kubernetes/pkg/database/database.go:573 +0xa5
golang.org/x/sync/errgroup.(*Group).Go.func1()
        golang.org/x/sync@v0.8.0/errgroup/errgroup.go:78 +0x50
created by golang.org/x/sync/errgroup.(*Group).Go in goroutine 2787
        golang.org/x/sync@v0.8.0/errgroup/errgroup.go:75 +0x96

Kind, regards.

lippserd commented 4 days ago

Could you please execute the following in the Icinga for Kubernetes and database and see whether this fixes the issue:

ALTER TABLE label MODIFY COLUMN value varchar(512) COLLATE utf8mb4_unicode_ci NOT NULL;

firatalkis commented 4 days ago

error did not change

I1017 11:22:49.169519 1534104 reflector.go:368] Caches populated for v1.Service from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243 I1017 11:22:49.190376 1534104 reflector.go:368] Caches populated for v1.EndpointSlice from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243 I1017 11:22:49.437892 1534104 database.go:647] "Finished executing INSERT INTO label (uuid, name, value) VALUES (:uuid, :name, :value) ON DUPLICATE KEY UPDATE uuid = VALUES(uuid), name = VALUES(name), value = VALUES(value) with 0 rows in 127.893082ms" logger="database" E1017 11:22:49.439497 1534104 select.go:526] "Observed a panic" panic="send on closed channel" panicGoValue="\"send on closed channel\"" stacktrace=<

lippserd commented 4 days ago

Ok, next try:

ALTER TABLE label MODIFY COLUMN value text NOT NULL;
ALTER TABLE label MODIFY COLUMN name varchar(255) COLLATE utf8mb4_unicode_ci NOT NULL;
firatalkis commented 4 days ago

I think we will have to do it in different tables

I1017 11:32:47.661312 1536958 reflector.go:368] Caches populated for *v1.Service from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:32:47.689154 1536958 reflector.go:368] Caches populated for *v1.EndpointSlice from k8s.io/client-go@v0.31.1/tools/cache/reflector.go:243
I1017 11:32:48.045661 1536958 database.go:647] "Finished executing INSERT INTO `selector` (`uuid`, `name`, `value`) VALUES (:uuid, :name, :value) ON DUPLICATE KEY UPDATE `uuid` = VALUES(`uuid`), `name` = VALUES(`name`), `value` = VALUES(`value`) with 0 rows in 286.655267ms" logger="database"
I1017 11:32:48.045882 1536958 database.go:647] "Finished executing INSERT INTO `service_label` (`service_uuid`, `label_uuid`) VALUES (:service_uuid, :label_uuid) ON DUPLICATE KEY UPDATE `service_uuid` = VALUES(`service_uuid`), `label_uuid` = VALUES(`label_uuid`) with 0 rows in 286.923074ms" logger="database"
I1017 11:32:48.045940 1536958 database.go:647] "Finished executing INSERT INTO `service_selector` (`service_uuid`, `selector_uuid`) VALUES (:service_uuid, :selector_uuid) ON DUPLICATE KEY UPDATE `service_uuid` = VALUES(`service_uuid`), `selector_uuid` = VALUES(`selector_uuid`) with 0 rows in 286.920105ms" logger="database"
I1017 11:32:48.045972 1536958 database.go:647] "Finished executing INSERT INTO `service_annotation` (`service_uuid`, `annotation_uuid`) VALUES (:service_uuid, :annotation_uuid) ON DUPLICATE KEY UPDATE `service_uuid` = VALUES(`service_uuid`), `annotation_uuid` = VALUES(`annotation_uuid`) with 512 rows in 286.912733ms" logger="database"
I1017 11:32:48.046097 1536958 database.go:647] "Finished executing INSERT INTO `service` (`internal_traffic_policy`, `yaml`, `namespace`, `allocate_load_balancer_node_ports`, `load_balancer_class`, `uuid`, `created`, `session_affinity`, `external_traffic_policy`, `uid`, `name`, `cluster_ip`, `type`, `health_check_node_port`, `external_name`, `publish_not_ready_addresses`, `ip_family_policy`, `cluster_ips`, `external_ips`, `ip_families`, `resource_version`) VALUES (:internal_traffic_policy, :yaml, :namespace, :allocate_load_balancer_node_ports, :load_balancer_class, :uuid, :created, :session_affinity, :external_traffic_policy, :uid, :name, :cluster_ip, :type, :health_check_node_port, :external_name, :publish_not_ready_addresses, :ip_family_policy, :cluster_ips, :external_ips, :ip_families, :resource_version) ON DUPLICATE KEY UPDATE `internal_traffic_policy` = VALUES(`internal_traffic_policy`), `yaml` = VALUES(`yaml`), `namespace` = VALUES(`namespace`), `allocate_load_balancer_node_ports` = VALUES(`allocate_load_balancer_node_ports`), `load_balancer_class` = VALUES(`load_balancer_class`), `uuid` = VALUES(`uuid`), `created` = VALUES(`created`), `session_affinity` = VALUES(`session_affinity`), `external_traffic_policy` = VALUES(`external_traffic_policy`), `uid` = VALUES(`uid`), `name` = VALUES(`name`), `cluster_ip` = VALUES(`cluster_ip`), `type` = VALUES(`type`), `health_check_node_port` = VALUES(`health_check_node_port`), `external_name` = VALUES(`external_name`), `publish_not_ready_addresses` = VALUES(`publish_not_ready_addresses`), `ip_family_policy` = VALUES(`ip_family_policy`), `cluster_ips` = VALUES(`cluster_ips`), `external_ips` = VALUES(`external_ips`), `ip_families` = VALUES(`ip_families`), `resource_version` = VALUES(`resource_version`) with 0 rows in 287.427297ms" logger="database"
I1017 11:32:48.046147 1536958 database.go:647] "Finished executing INSERT INTO `annotation` (`uuid`, `name`, `value`) VALUES (:uuid, :name, :value) ON DUPLICATE KEY UPDATE `uuid` = VALUES(`uuid`), `name` = VALUES(`name`), `value` = VALUES(`value`) with 512 rows in 287.345059ms" logger="database"
I1017 11:32:48.046178 1536958 database.go:647] "Finished executing INSERT INTO `service_port` (`node_port`, `service_uuid`, `name`, `protocol`, `app_protocol`, `port`, `target_port`) VALUES (:node_port, :service_uuid, :name, :protocol, :app_protocol, :port, :target_port) ON DUPLICATE KEY UPDATE `node_port` = VALUES(`node_port`), `service_uuid` = VALUES(`service_uuid`), `name` = VALUES(`name`), `protocol` = VALUES(`protocol`), `app_protocol` = VALUES(`app_protocol`), `port` = VALUES(`port`), `target_port` = VALUES(`target_port`) with 239 rows in 287.298572ms" logger="database"
I1017 11:32:48.046264 1536958 database.go:647] "Finished executing INSERT INTO `label` (`uuid`, `name`, `value`) VALUES (:uuid, :name, :value) ON DUPLICATE KEY UPDATE `uuid` = VALUES(`uuid`), `name` = VALUES(`name`), `value` = VALUES(`value`) with 0 rows in 287.347428ms" logger="database"
E1017 11:32:48.055940 1536958 select.go:526] "Observed a panic" panic="send on closed channel" panicGoValue="\"send on closed channel\"" stacktrace=<
lippserd commented 4 days ago

Unfortunately, there is a bug in the code that hides the error returned by the database and just panics instead. Let me fix that first so we can see what the real error is.

lippserd commented 4 days ago

I assume that you have installed Icinga for Kuberentes via packages. You can find an updated version here:

https://nextcloud.icinga.com/index.php/s/qgWJ77Zkas2MiCk

firatalkis commented 4 days ago

yes we are using icinga repo for rhel https://packages.icinga.com.

I have installed the rpm you forwarded and getting same error:

Installed: icinga-kubernetes-0.2.0+1.g8fd8713-1.el8.x86_64

Complete!

F1017 12:03:14.058140 1545693 main.go:385] can't retry: can't perform "INSERT INTO selector (uuid, name, value) VALUES (:uuid, :name, :value) ON DUPLICATE KEY UPDATE uuid = VALUES(uuid), name = VALUES(name), value = VALUES(value)": Error 1406 (22001): Data too long for column 'name' at row 66

lippserd commented 4 days ago

Now we have the real error :)

Error 1406 (22001): Data too long for column 'name' at row 66

ALTER TABLE selector MODIFY COLUMN name varchar(255) COLLATE utf8mb4_unicode_ci NOT NULL;

Length 63 was chosen as selectors use labels and labels can't be longer than 63 characters.

firatalkis commented 4 days ago

Ok, it finally worked :)

lippserd commented 4 days ago

Can you please share the output of SELECT * FROM selector WHERE LENGTH(name) > 63?

firatalkis commented 4 days ago

image