Filebeat stops sending logs after kubernetes deployment restart

Kamil_Glod · July 23, 2018, 7:06am

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:

---
apiVersion: v1
kind: ConfigMap
metadata:
  name: filebeat-config
  namespace: kube-system
  labels:
    k8s-app: filebeat
data:
  filebeat.yml: |-
    filebeat.autodiscover:
      providers:
        - type: kubernetes
          templates:
            - condition:
                equals:
                  kubernetes.namespace: default
              config:
                - type: docker
                  containers.ids:
                    - "${data.kubernetes.container.id}"
    processors:
      - add_cloud_metadata:
    setup.template.name: "filebeat"
    setup.template.pattern: "filebeat-*"
    output.elasticsearch:
      hosts: ['${ELASTICSEARCH_HOST}:${ELASTICSEARCH_PORT}']
      index: "filebeat-%{[beat.version]}-test-%{+yyyy.MM.dd}"
---
apiVersion: extensions/v1beta1
kind: DaemonSet
metadata:
  name: filebeat
  namespace: kube-system
  labels:
    k8s-app: filebeat
spec:
  template:
    metadata:
      labels:
        k8s-app: filebeat
    spec:
      serviceAccountName: filebeat
      terminationGracePeriodSeconds: 30
      containers:
      - name: filebeat
        image: docker.elastic.co/beats/filebeat:6.3.1
        args: [
          "-c", "/etc/filebeat.yml",
          "-e",
        ]
        env:
        - name: ELASTICSEARCH_HOST
          value: xxxxxxxxx.xxx
        - name: ELASTICSEARCH_PORT
          value: "9200"
        securityContext:
          runAsUser: 0
        resources:
          limits:
            memory: 200Mi
          requests:
            cpu: 100m
            memory: 100Mi
        volumeMounts:
        - name: config
          mountPath: /etc/filebeat.yml
          readOnly: true
          subPath: filebeat.yml
        - name: data
          mountPath: /usr/share/filebeat/data
        - name: varlibdockercontainers
          mountPath: /var/lib/docker/containers
          readOnly: true
      volumes:
      - name: config
        configMap:
          defaultMode: 0600
          name: filebeat-config
      - name: varlibdockercontainers
        hostPath:
          path: /var/lib/docker/containers
      # data folder stores a registry of read status for all files, so we don't send everything again on a Filebeat pod restart
      - name: data
        hostPath:
          path: /var/lib/filebeat-data
          type: DirectoryOrCreate
---
apiVersion: rbac.authorization.k8s.io/v1beta1
kind: ClusterRoleBinding
metadata:
  name: filebeat
subjects:
- kind: ServiceAccount
  name: filebeat
  namespace: kube-system
roleRef:
  kind: ClusterRole
  name: filebeat
  apiGroup: rbac.authorization.k8s.io
---
apiVersion: rbac.authorization.k8s.io/v1beta1
kind: ClusterRole
metadata:
  name: filebeat
  labels:
    k8s-app: filebeat
rules:
- apiGroups: [""] # "" indicates the core API group
  resources:
  - namespaces
  - pods
  verbs:
  - get
  - watch
  - list
---
apiVersion: v1
kind: ServiceAccount
metadata:
  name: filebeat
  namespace: kube-system
  labels:
    k8s-app: filebeat
---

I'm deploying this setup using kubectl apply -f filebeat-kubernetes.yaml command

Kamil_Glod · July 23, 2018, 7:08am

Here is an filebeat pod logs output:


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

Kamil_Glod · July 23, 2018, 7:18am

more logs (there is a number of chars limitation per comment):

2018-07-23T07:02:11.959Z	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[pod-template-hash:3884902594 type:api app:internal-tools] 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:556704 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-23T07:02:11Z Status:False 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:false RestartCount:0 State:{Running:{StartedAt:}}}] InitContainerStatuses:[] HostIP:10.190.8.2 Phase:Running PodIP:10.176.0.92 StartTime:2018-07-23T06:57:02Z}}
2018-07-23T07:02:11.960Z	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:[0xc420460630]], generated configs: [0xc420460630]
2018-07-23T07:02:11.960Z	DEBUG	[autodiscover]	autodiscover/autodiscover.go:172	Config &{{<nil> } <nil> 0xc4202969a0} is not running
2018-07-23T07:02:11.960Z	DEBUG	[autodiscover]	autodiscover/autodiscover.go:108	Got a start event: map[config:[0xc4201a2690] start: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"}}}], generated configs: [0xc4201a2690]
2018-07-23T07:02:11.960Z	DEBUG	[autodiscover]	autodiscover/autodiscover.go:196	Got a meta field in the event
2018-07-23T07:02:11.960Z	WARN	[cfgwarn]	docker/input.go:29	EXPERIMENTAL: Docker input is enabled.
2018-07-23T07:02:11.960Z	INFO	log/input.go:113	Configured paths: [/var/lib/docker/containers/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a/*.log]
2018-07-23T07:02:11.960Z	INFO	autodiscover/autodiscover.go:144	Autodiscover starting runner: input [type=docker, ID=15580441539700056235]
2018-07-23T07:02:11.960Z	INFO	input/input.go:88	Starting input of type: docker; ID: 15580441539700056235 
2018-07-23T07:02:11.961Z	INFO	log/harvester.go:228	Harvester started for file: /var/lib/docker/containers/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a-json.log

Kamil_Glod · July 23, 2018, 7:20am

2018-07-23T07:02:12.962Z	INFO	log/harvester.go:245	File was removed: /var/lib/docker/containers/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a-json.log. Closing because close_removed is enabled.
2018-07-23T07:02:17.617Z	DEBUG	[kubernetes]	kubernetes/kubernetes.go:91	Watcher Pod update: &{APIVersion: Kind: Metadata:{Annotations:map[] CreationTimestamp:2018-07-23T06:57:02Z DeletionTimestamp:2018-07-23T07:01:58Z GenerateName:internal-tools-api-7dd8f469f8- Labels:map[app:internal-tools pod-template-hash:3884902594 type:api] 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:556712 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-23T07:02:11Z Status:False 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:false RestartCount:0 State:{Running:{StartedAt:}}}] InitContainerStatuses:[] HostIP:10.190.8.2 Phase:Running PodIP:10.176.0.92 StartTime:2018-07-23T06:57:02Z}}
2018-07-23T07:02:17.618Z	DEBUG	[autodiscover]	autodiscover/autodiscover.go:156	Got a stop event: map[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:[0xc4204707b0] stop:true host:10.176.0.92], generated configs: [0xc4204707b0]
2018-07-23T07:02:17.618Z	INFO	autodiscover/autodiscover.go:181	Autodiscover stopping runner: input [type=docker, ID=15580441539700056235]
2018-07-23T07:02:17.618Z	DEBUG	[autodiscover]	autodiscover/autodiscover.go:108	Got a start event: map[start: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:[0xc42021c5d0]], generated configs: [0xc42021c5d0]
2018-07-23T07:02:17.618Z	DEBUG	[autodiscover]	autodiscover/autodiscover.go:196	Got a meta field in the event
2018-07-23T07:02:17.618Z	WARN	[cfgwarn]	docker/input.go:29	EXPERIMENTAL: Docker input is enabled.

Kamil_Glod · July 23, 2018, 7:20am

2018-07-23T07:02:17.619Z	INFO	input/input.go:122	input ticker stopped
2018-07-23T07:02:17.619Z	INFO	input/input.go:139	Stopping Input: 15580441539700056235
2018-07-23T07:02:17.619Z	INFO	log/input.go:113	Configured paths: [/var/lib/docker/containers/962aa5c65df8e52e9e04e1266d5b325f08da6871f959ec08ac53a74048146d2a/*.log]
2018-07-23T07:02:17.619Z	INFO	autodiscover/autodiscover.go:144	Autodiscover starting runner: input [type=docker, ID=15580441539700056235]
2018-07-23T07:02:17.619Z	INFO	input/input.go:88	Starting input of type: docker; ID: 15580441539700056235 
2018-07-23T07:02:17.622Z	DEBUG	[kubernetes]	kubernetes/kubernetes.go:96	Watcher Pod delete: &{APIVersion: Kind: Metadata:{Annotations:map[] CreationTimestamp:2018-07-23T06:57:02Z DeletionTimestamp:2018-07-23T07:01:58Z GenerateName:internal-tools-api-7dd8f469f8- Labels:map[pod-template-hash:3884902594 type:api app:internal-tools] 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:556713 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-23T07:02:11Z Status:False 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:false RestartCount:0 State:{Running:{StartedAt:}}}] InitContainerStatuses:[] HostIP:10.190.8.2 Phase:Running PodIP:10.176.0.92 StartTime:2018-07-23T06:57:02Z}}

Kamil_Glod · July 23, 2018, 8:42am

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

exekias · July 23, 2018, 3:14pm

Hi @Kamil_Glod,

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.

Best regards

Kamil_Glod · July 24, 2018, 6:42am

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}

Kamil_Glod · August 17, 2018, 7:48am

@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

Kamil_Glod · August 17, 2018, 7:55am

Here is my present filebeat config:

setup.template.name: "filebeat"
    setup.template.pattern: "filebeat-*"
    filebeat.autodiscover:
      providers:
        - type: kubernetes
          templates:
            - condition:
                equals:
                  kubernetes.namespace: default
                  kubernetes.labels.type: gui
              config:
                - module: nginx
                  access:
                    input:
                      type: docker
                      containers.stream: stdout
                      containers.ids:
                        - "${data.kubernetes.container.id}"
                      fields_under_root: true
                      fields:
                        index_name: nginx
                  error:
                    input:
                      type: docker
                      containers.stream: stderr
                      containers.ids:
                        - "${data.kubernetes.container.id}"
                      fields_under_root: true
                      fields:
                        index_name: nginx
            - condition:
                equals:
                  kubernetes.namespace: default
                  kubernetes.labels.type: api
              config:
                - type: docker
                  containers.ids:
                    - "${data.kubernetes.container.id}"
                  json.add_error_key: true
                  fields_under_root: true
                  processors:
                    - rename:
                        fields:
                        - from: "json.index_name"
                          to: "index_name"

    processors:
      - add_cloud_metadata:
      - add_kubernetes_metadata:
          in_cluster: true
    output.elasticsearch:
      hosts: ['${ELASTICSEARCH_HOST}:${ELASTICSEARCH_PORT}']
      index: "filebeat-%{[index_name]}-%{+yyyy.MM.dd}"
      indices:
        - index: "filebeat-unknown-%{+yyyy.MM.dd}"
          when:
            not:
              has_fields: "index_name"

system · September 14, 2018, 7:56am

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.