Hi, I'm using filebeat in kubernetes cluster with autodiscovery option. When I deploy daemonset first time everything works correctly but after redeploying one of my test deployments do not send logs from new pods.
Here is my filebeat-kubernetes.yaml file:
2018-07-23T07:01:58.507Z DEBUG [kubernetes] kubernetes/kubernetes.go:91 Watcher Pod update: &{APIVersion: Kind: Metadata:{Annotations:map[] CreationTimestamp:2018-07-23T06:57:02Z DeletionTimestamp:2018-07-23T07:02:28Z GenerateName:internal-tools-api-7dd8f469f8- Labels:map[type:api app:internal-tools pod-template-hash:3884902594] Name:internal-tools-api-7dd8f469f8-dhjlv Namespace:default OwnerReferences:[{APIVersion:extensions/v1beta1 Controller:true Kind:ReplicaSet Name:internal-tools-api-7dd8f469f8 UID:505536f6-8c1a-11e8-8a79-42010aa40ff0}] ResourceVersion:556678 SelfLink:/api/v1/namespaces/default/pods/internal-tools-api-7dd8f469f8-dhjlv UID:9a417d31-8e45-11e8-8a79-42010aa40ff0} Spec:{Containers:[{Image:gcr.io/rtbhouse-apps/internal-tools-api:389158d ImagePullPolicy:IfNotPresent Name:internal-tools-api Ports:[{Name: ContainerPort:5000 Protocol:TCP}] Resources:{} TerminationMessagePath:/dev/termination-log VolumeMounts:[{MountPath:/var/run/secrets/kubernetes.io/serviceaccount Name:default-token-c75zd ReadOnly:true}]}] InitContainers:[] DNSPolicy:ClusterFirst NodeName:gke-rtbhouse-apps-prod-default-pool-12376619-6tjd RestartPolicy:Always SecurityContext:{} ServiceAccount:default ServiceAccountName:default TerminationGracePeriodSeconds:30} Status:{Conditions:[{LastProbeTime:1970-01-01T00:00:00Z LastTransitionTime:2018-07-23T06:57:02Z Status:True Type:Initialized} {LastProbeTime:1970-01-01T00:00:00Z LastTransitionTime:2018-07-23T06:57:22Z Status:True Type:Ready} {LastProbeTime:1970-01-01T00:00:00Z LastTransitionTime:2018-07-23T06:57:02Z Status:True Type:PodScheduled}] ContainerStatuses:[{ContainerID:docker://962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a Image:gcr.io/rtbhouse-apps/internal-tools-api:389158d ImageID:docker-pullable://gcr.io/rtbhouse-apps/internal-tools-api@sha256:86061849bdf4c78542f10ecf9a54be809758a2c29acf0699c3e60c9160feadd5 LastState:{Terminated:{ContainerID: ExitCode:0 FinishedAt: Reason: StartedAt:}} Name:internal-tools-api Ready:true RestartCount:0 State:{Running:{StartedAt:2018-07-23T06:57:04Z}}}] InitContainerStatuses:[] HostIP:10.190.8.2 Phase:Running PodIP:10.176.0.92 StartTime:2018-07-23T06:57:02Z}}
2018-07-23T07:01:58.517Z DEBUG [autodiscover] autodiscover/autodiscover.go:156 Got a stop event: map[stop:true host:10.176.0.92 port:5000 kubernetes:{"annotations":{},"container":{"id":"962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a","image":"gcr.io/rtbhouse-apps/internal-tools-api:389158d","name":"internal-tools-api","runtime":"docker"},"labels":{"app":"internal-tools","pod-template-hash":"3884902594","type":"api"},"namespace":"default","node":{"name":"gke-rtbhouse-apps-prod-default-pool-12376619-6tjd"},"pod":{"name":"internal-tools-api-7dd8f469f8-dhjlv"}} meta:{"kubernetes":{"container":{"name":"internal-tools-api"},"labels":{"app":"internal-tools","pod-template-hash":"3884902594","type":"api"},"namespace":"default","node":{"name":"gke-rtbhouse-apps-prod-default-pool-12376619-6tjd"},"pod":{"name":"internal-tools-api-7dd8f469f8-dhjlv"}}} config:[0xc4203ceea0]], generated configs: [0xc4203ceea0]
2018-07-23T07:01:58.517Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: input [type=docker, ID=15580441539700056235]
2018-07-23T07:01:58.517Z DEBUG [autodiscover] autodiscover/autodiscover.go:108 Got a start event: map[host:10.176.0.92 port:5000 kubernetes:{"annotations":{},"container":{"id":"962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a","image":"gcr.io/rtbhouse-apps/internal-tools-api:389158d","name":"internal-tools-api","runtime":"docker"},"labels":{"app":"internal-tools","pod-template-hash":"3884902594","type":"api"},"namespace":"default","node":{"name":"gke-rtbhouse-apps-prod-default-pool-12376619-6tjd"},"pod":{"name":"internal-tools-api-7dd8f469f8-dhjlv"}} meta:{"kubernetes":{"container":{"name":"internal-tools-api"},"labels":{"app":"internal-tools","pod-template-hash":"3884902594","type":"api"},"namespace":"default","node":{"name":"gke-rtbhouse-apps-prod-default-pool-12376619-6tjd"},"pod":{"name":"internal-tools-api-7dd8f469f8-dhjlv"}}} config:[0xc4203c3560] start:true], generated configs: [0xc4203c3560]
2018-07-23T07:01:58.517Z DEBUG [autodiscover] autodiscover/autodiscover.go:196 Got a meta field in the event
2018-07-23T07:01:58.517Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-07-23T07:01:58.517Z DEBUG [autodiscover] autodiscover/autodiscover.go:140 Failed to create runner with config &{{<nil> } <nil> 0xc42037f400}: Can only start an input when all related states are finished: {Id:0-529259-2049 Finished:false Fileinfo:0xc420443380 Source:/var/lib/docker/containers/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a-json.log Offset:39169 Timestamp:2018-07-23 07:01:45.489377197 +0000 UTC m=+110.116712112 TTL:-1ns Type:docker Meta:map[] FileStateOS:529259-2049}
2018-07-23T07:01:58.517Z INFO input/input.go:122 input ticker stopped
2018-07-23T07:01:58.517Z INFO input/input.go:139 Stopping Input: 15580441539700056235
2018-07-23T07:01:58.517Z INFO log/harvester.go:249 Reader was closed: /var/lib/docker/containers/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a-json.log. Closing.
I do not see any error there, but ealier I saw couple of ERROR logs with Failed to publish events: temporary bulk send failure Config &{{<nil> } <nil> 0xc42004d360} is not running Failed to create runner with config &{{<nil> } <nil> 0xc4202a88c0}: Can only start an input when all related states are finished
message
I just noticed that after about half an hour of deployment logs start to appear in elasticsearch.
Here are some logs for moment before it starts working again:
2018-07-23T08:35:25.844Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: input [type=docker, ID=14798111885389294522]
2018-07-23T08:35:25.844Z DEBUG [autodiscover] autodiscover/autodiscover.go:108 Got a start event: map[kubernetes:{"annotations":{},"container":{"id":"d2937fa160767c2ba6fe55128b8cc63ec566481cd843957bd7d7c09791b6b10d","image":"gcr.io/rtbhouse-apps/internal-tools-api:latest-force1","name":"internal-tools-api","runtime":"docker"},"labels":{"app":"internal-tools","pod-template-hash":"600482006","type":"api"},"namespace":"default","node":{"name":"gke-rtbhouse-apps-prod-default-pool-12376619-btxt"},"pod":{"name":"internal-tools-api-b448d644b-btdmg"}} meta:{"kubernetes":{"container":{"name":"internal-tools-api"},"labels":{"app":"internal-tools","pod-template-hash":"600482006","type":"api"},"namespace":"default","node":{"name":"gke-rtbhouse-apps-prod-default-pool-12376619-btxt"},"pod":{"name":"internal-tools-api-b448d644b-btdmg"}}} config:[0xc4204b9e00] start:true host:10.176.1.119 port:5000], generated configs: [0xc4204b9e00]
2018-07-23T08:35:25.844Z DEBUG [autodiscover] autodiscover/autodiscover.go:196 Got a meta field in the event
2018-07-23T08:35:25.844Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-07-23T08:35:25.844Z INFO log/input.go:113 Configured paths: [/var/lib/docker/containers/d2937fa160767c2ba6fe55128b8cc63ec566481cd843957bd7d7c09791b6b10d/*.log]
2018-07-23T08:35:25.844Z INFO autodiscover/autodiscover.go:144 Autodiscover starting runner: input [type=docker, ID=14798111885389294522]
2018-07-23T08:35:25.844Z INFO input/input.go:88 Starting input of type: docker; ID: 14798111885389294522
2018-07-23T08:35:25.844Z INFO log/harvester.go:228 Harvester started for file: /var/lib/docker/containers/1101a1052f55f45d815ccacab7f181232c49d81b484d0d6159e93398aae56874/1101a1052f55f45d815ccacab7f181232c49d81b484d0d6159e93398aae56874-json.log
2018-07-23T08:35:25.845Z INFO input/input.go:122 input ticker stopped
2018-07-23T08:35:25.845Z INFO input/input.go:139 Stopping Input: 14798111885389294522
2018-07-23T08:35:25.845Z INFO input/input.go:122 input ticker stopped
2018-07-23T08:35:25.845Z INFO input/input.go:139 Stopping Input: 6686231621120938208
2018-07-23T08:35:25.845Z INFO input/input.go:122 input ticker stopped
2018-07-23T08:35:25.845Z INFO input/input.go:139 Stopping Input: 14798111885389294522
2018-07-23T08:35:25.845Z INFO input/input.go:122 input ticker stopped
2018-07-23T08:35:25.845Z INFO input/input.go:139 Stopping Input: 14798111885389294522
Can you please use kubectl create instead of apply? We recently fixed a bug in the manifests, they are being mangled by addon-manager if you use apply.
I tried kubectl create command but there is still problem, here are some logs with error showing up after deployment restart:
2018-07-24T06:35:56.072Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-07-24T06:35:56.073Z INFO log/input.go:113 Configured paths: [/var/lib/docker/containers/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a/*.log]
2018-07-24T06:35:56.074Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-07-24T06:35:56.075Z INFO log/input.go:113 Configured paths: [/var/lib/docker/containers/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a/*.log]
2018-07-24T06:35:56.075Z INFO autodiscover/autodiscover.go:144 Autodiscover starting runner: nginx (access, error)
2018-07-24T06:35:56.075Z INFO elasticsearch/client.go:145 Elasticsearch url: http://xxxxx:9200
2018-07-24T06:35:56.123Z INFO elasticsearch/client.go:690 Connected to Elasticsearch version 6.2.4
2018-07-24T06:35:56.147Z INFO input/input.go:88 Starting input of type: docker; ID: 17732903406378666149
2018-07-24T06:35:56.147Z INFO input/input.go:88 Starting input of type: docker; ID: 11958861679901062464
2018-07-24T06:35:56.148Z INFO log/harvester.go:228 Harvester started for file: /var/lib/docker/containers/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a-json.log
2018-07-24T06:35:56.149Z INFO log/harvester.go:228 Harvester started for file: /var/lib/docker/containers/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a-json.log
2018-07-24T06:36:03.621Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: nginx (access, error)
2018-07-24T06:36:03.622Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-07-24T06:36:03.623Z ERROR fileset/factory.go:72 Error creating input: Can only start an input when all related states are finished: {Id:ea745ab688be85a9-532456-2049 Finished:false Fileinfo:0xc42036ed00 Source:/var/lib/docker/containers/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a-json.log Offset:0 Timestamp:2018-07-24 06:35:56.155564297 +0000 UTC m=+137.149041672 TTL:-1ns Type:docker Meta:map[stream:stdout] FileStateOS:532456-2049}
2018-07-24T06:36:03.623Z INFO input/input.go:122 input ticker stopped
2018-07-24T06:36:03.623Z INFO input/input.go:139 Stopping Input: 17732903406378666149
2018-07-24T06:36:03.623Z INFO log/harvester.go:249 Reader was closed: /var/lib/docker/containers/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a-json.log. Closing.
2018-07-24T06:36:03.623Z INFO input/input.go:122 input ticker stopped
2018-07-24T06:36:03.623Z INFO input/input.go:139 Stopping Input: 11958861679901062464
2018-07-24T06:36:03.623Z INFO log/harvester.go:249 Reader was closed: /var/lib/docker/containers/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a/191e529865c6cb52f0d274524a54823b8892dfc5c71c746cb3fd3734c2c7947a-json.log. Closing.
2018-07-24T06:36:03.652Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: nginx (access, error)
2018-07-24T06:36:03.663Z INFO input/input.go:122 input ticker stopped
2018-07-24T06:36:03.663Z INFO input/input.go:139 Stopping Input: 14465537319353571820
2018-07-24T06:36:03.663Z INFO log/harvester.go:249 Reader was closed: /var/lib/docker/containers/7a51ba466d9b374dca9485714c8c0712ce4c1ba45b301f749929f912be573779/7a51ba466d9b374dca9485714c8c0712ce4c1ba45b301f749929f912be573779-json.log. Closing.
2018-07-24T06:36:03.664Z INFO input/input.go:122 input ticker stopped
2018-07-24T06:36:03.664Z INFO input/input.go:139 Stopping Input: 1783492345100121049
2018-07-24T06:36:03.664Z INFO log/harvester.go:249 Reader was closed: /var/lib/docker/containers/7a51ba466d9b374dca9485714c8c0712ce4c1ba45b301f749929f912be573779/7a51ba466d9b374dca9485714c8c0712ce4c1ba45b301f749929f912be573779-json.log. Closing.
2018-07-24T06:36:03.677Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-07-24T06:36:03.682Z ERROR fileset/factory.go:72 Error creating input: Can only start an input when all related states are finished: {Id:ea745ab688be85a9-532546-2049 Finished:false Fileinfo:0xc42036e270 Source:/var/lib/docker/containers/7a51ba466d9b374dca9485714c8c0712ce4c1ba45b301f749929f912be573779/7a51ba466d9b374dca9485714c8c0712ce4c1ba45b301f749929f912be573779-json.log Offset:14006 Timestamp:2018-07-24 06:36:02.209559477 +0000 UTC m=+143.203036815 TTL:-1ns Type:docker Meta:map[stream:stdout] FileStateOS:532546-2049}
@exekias it turned out that after couple of hours of deploying new version of some service deployment filebeat starts sending logs again. I do not know why it takes so long to discover new deployment and start gather logs. In the filebeat's logs almost every hour I see some logs like:
2018-08-17T05:08:04.864Z ERROR kubernetes/watcher.go:195 kubernetes: Watching API error EOF
2018-08-17T05:08:04.864Z INFO kubernetes/watcher.go:179 kubernetes: Watching API for resource events
2018-08-17T05:08:04.870Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: input [type=docker, ID=9916533147243264720]
2018-08-17T05:08:04.870Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-08-17T05:08:04.870Z WARN [cfgwarn] actions/rename.go:38 BETA: Beta rename processor is used.
2018-08-17T05:08:04.870Z INFO log/input.go:118 Configured paths: [/var/lib/docker/containers/b78bd6d2b720520b8c5acda2f883227d28b815d7ec8c5f1a015cafc966c0a715/*.log]
2018-08-17T05:08:04.871Z INFO autodiscover/autodiscover.go:144 Autodiscover starting runner: input [type=docker, ID=9916533147243264720]
2018-08-17T05:08:04.871Z INFO input/input.go:88 Starting input of type: docker; ID: 9916533147243264720
2018-08-17T05:08:04.871Z INFO input/input.go:122 input ticker stopped
2018-08-17T05:08:04.871Z INFO input/input.go:139 Stopping Input: 9916533147243264720
2018-08-17T05:08:04.873Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: input [type=docker, ID=9916533147243264720]
2018-08-17T05:08:04.873Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-08-17T05:08:04.873Z WARN [cfgwarn] actions/rename.go:38 BETA: Beta rename processor is used.
2018-08-17T05:08:04.873Z INFO input/input.go:122 input ticker stopped
2018-08-17T05:08:04.873Z INFO input/input.go:139 Stopping Input: 9916533147243264720
2018-08-17T05:08:04.873Z INFO log/input.go:118 Configured paths: [/var/lib/docker/containers/b78bd6d2b720520b8c5acda2f883227d28b815d7ec8c5f1a015cafc966c0a715/*.log]
2018-08-17T05:08:04.873Z INFO autodiscover/autodiscover.go:144 Autodiscover starting runner: input [type=docker, ID=9916533147243264720]
2018-08-17T05:08:04.873Z INFO input/input.go:88 Starting input of type: docker; ID: 9916533147243264720
2018-08-17T05:08:04.875Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-08-17T05:08:04.876Z INFO log/input.go:118 Configured paths: [/var/lib/docker/containers/139ee7e94bfeee66501cf8af85c77a717a2e705e4066f30c2b84c98670f71525/*.log]
2018-08-17T05:08:04.876Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-08-17T05:08:04.876Z INFO log/input.go:118 Configured paths: [/var/lib/docker/containers/139ee7e94bfeee66501cf8af85c77a717a2e705e4066f30c2b84c98670f71525/*.log]
2018-08-17T05:08:04.876Z INFO autodiscover/autodiscover.go:144 Autodiscover starting runner: nginx (access, error)
2018-08-17T05:08:04.876Z INFO elasticsearch/client.go:145 Elasticsearch url: http://elastic-host:9200
...
2018-08-17T05:08:05.039Z INFO elasticsearch/client.go:145 Elasticsearch url: http://elastic-host:9200
2018-08-17T05:08:05.158Z INFO elasticsearch/client.go:690 Connected to Elasticsearch version 6.2.4
2018-08-17T05:08:05.176Z INFO input/input.go:88 Starting input of type: docker; ID: 1925167779763515054
2018-08-17T05:08:05.176Z INFO input/input.go:88 Starting input of type: docker; ID: 13550081250833755218
2018-08-17T05:08:05.176Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: input [type=docker, ID=9916533147243264720]
2018-08-17T05:08:05.176Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-08-17T05:08:05.176Z WARN [cfgwarn] actions/rename.go:38 BETA: Beta rename processor is used.
2018-08-17T05:08:05.176Z INFO input/input.go:122 input ticker stopped
2018-08-17T05:08:05.176Z INFO input/input.go:139 Stopping Input: 9916533147243264720
2018-08-17T05:08:05.176Z INFO log/input.go:118 Configured paths: [/var/lib/docker/containers/b78bd6d2b720520b8c5acda2f883227d28b815d7ec8c5f1a015cafc966c0a715/*.log]
2018-08-17T05:08:05.176Z INFO autodiscover/autodiscover.go:144 Autodiscover starting runner: input [type=docker, ID=9916533147243264720]
2018-08-17T05:08:05.176Z INFO input/input.go:88 Starting input of type: docker; ID: 9916533147243264720
2018-08-17T05:08:05.176Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: nginx (access, error)
2018-08-17T05:08:05.176Z INFO input/input.go:122 input ticker stopped
2018-08-17T05:08:05.176Z INFO input/input.go:139 Stopping Input: 1925167779763515054
2018-08-17T05:08:05.176Z INFO input/input.go:122 input ticker stopped
2018-08-17T05:08:05.176Z INFO input/input.go:139 Stopping Input: 13550081250833755218
2018-08-17T05:08:05.178Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-08-17T05:08:05.178Z INFO log/input.go:118 Configured paths: [/var/lib/docker/containers/139ee7e94bfeee66501cf8af85c77a717a2e705e4066f30c2b84c98670f71525/*.log]
2018-08-17T05:08:05.178Z WARN [cfgwarn] docker/input.go:29 EXPERIMENTAL: Docker input is enabled.
2018-08-17T05:08:05.178Z INFO log/input.go:118 Configured paths: [/var/lib/docker/containers/139ee7e94bfeee66501cf8af85c77a717a2e705e4066f30c2b84c98670f71525/*.log]
2018-08-17T05:08:05.178Z INFO autodiscover/autodiscover.go:144 Autodiscover starting runner: nginx (access, error)
2018-08-17T05:08:05.179Z INFO elasticsearch/client.go:145 Elasticsearch url: http://elastic-host:9200
2018-08-17T05:08:05.194Z INFO elasticsearch/client.go:690 Connected to Elasticsearch version 6.2.4
2018-08-17T05:08:05.211Z INFO input/input.go:88 Starting input of type: docker; ID: 1925167779763515054
2018-08-17T05:08:05.211Z INFO input/input.go:88 Starting input of type: docker; ID: 13550081250833755218
2018-08-17T05:09:04.876Z INFO autodiscover/autodiscover.go:181 Autodiscover stopping runner: nginx (error, access)
2018-08-17T05:09:04.876Z INFO input/input.go:122 input ticker stopped
2018-08-17T05:09:04.876Z INFO input/input.go:139 Stopping Input: 1925167779763515054
2018-08-17T05:09:04.877Z INFO input/input.go:122 input ticker stopped
2018-08-17T05:09:04.877Z INFO input/input.go:139 Stopping Input: 13550081250833755218
Apache, Apache Lucene, Apache Hadoop, Hadoop, HDFS and the yellow elephant
logo are trademarks of the
Apache Software Foundation
in the United States and/or other countries.