Add_docker_metadata not working with match_source: false

pa.cloud · June 21, 2018, 1:24pm

Hi,

Though I could successfully use add_docker_metadata with "~" as well as if I set match_source: true

But i am unable to get it to work if i set match_source: false. Please see my config below.
Not sure if it's because of the "fields" in match_fields/match_pids, though i've tried with some other fields as well..it more looks like at runtime the value of the fields is not found. Although I see no clue in logs (even debug level)

============================

filebeat.prospectors:

- type: docker

  enabled: true
  containers:
    path: /var/lib/docker/containers
    ids: "*"
  processors:
    - add_docker_metadata:
        host: "unix:///var/run/docker.sock"
        match_fields: ["system.process.cgroup.id"]
        match_pids: ["process.pid", "process.ppid"]
        match_source: false
        match_source_index: 4
        match_short_id: true

====================================

I've tried this with filebeat 6.2.4 as well as 6.3
Tried both with

type: log and
type: docker

Any help/pointer is appreciated.

TIA

kvch · June 21, 2018, 1:26pm

Could you please format your config using </>? Also, please attach the debug logs.

pa.cloud · June 21, 2018, 2:02pm

Please find logs below. Fwiw, i changed the config to monitor just my container "9010..", instead of ids: "*"

2018-06-21T19:03:59.239+0530    INFO    instance/beat.go:468    Home path: [/usr/share/filebeat] Config path: [/etc/filebeat] Data path: [/var/lib/filebeat] Logs path: [/var/log/filebeat]
2018-06-21T19:03:59.240+0530    DEBUG   [beat]  instance/beat.go:495    Beat metadata path: /var/lib/filebeat/meta.json
2018-06-21T19:03:59.240+0530    INFO    instance/beat.go:475    Beat UUID: 6eb6cbf3-c9be-4866-a634-141b64e1098f
2018-06-21T19:03:59.240+0530    INFO    instance/beat.go:213    Setup Beat: filebeat; Version: 6.2.4
2018-06-21T19:03:59.240+0530    DEBUG   [beat]  instance/beat.go:230    Initializing output plugins
2018-06-21T19:03:59.240+0530    DEBUG   [processors]    processors/processor.go:49      Processors:
2018-06-21T19:03:59.240+0530    INFO    elasticsearch/client.go:145     Elasticsearch url: http://localhost:9200
2018-06-21T19:03:59.241+0530    INFO    pipeline/module.go:76   Beat name: 2030021817
2018-06-21T19:03:59.241+0530    INFO    instance/beat.go:301    filebeat start running.
2018-06-21T19:03:59.241+0530    DEBUG   [registrar]     registrar/registrar.go:90       Registry file set to: /var/lib/filebeat/registry
2018-06-21T19:03:59.241+0530    INFO    registrar/registrar.go:110      Loading registrar data from /var/lib/filebeat/registry
2018-06-21T19:03:59.241+0530    INFO    [monitoring]    log/log.go:97   Starting metrics logging every 30s
2018-06-21T19:03:59.242+0530    INFO    registrar/registrar.go:121      States Loaded from registrar: 93
2018-06-21T19:03:59.242+0530    INFO    crawler/crawler.go:48   Loading Prospectors: 1
2018-06-21T19:03:59.243+0530    WARN    [cfgwarn]       docker/prospector.go:25 EXPERIMENTAL: Docker prospector is enabled.
2018-06-21T19:03:59.243+0530    DEBUG   [docker]        docker/watcher.go:156   Start docker containers scanner
2018-06-21T19:03:59.243+0530    DEBUG   [registrar]     registrar/registrar.go:152      Starting Registrar
2018-06-21T19:03:59.248+0530    DEBUG   [bus]   bus/bus.go:55   docker: map[start:true container:0xc4204764d0]
2018-06-21T19:03:59.248+0530    DEBUG   [bus]   bus/bus.go:55   docker: map[start:true container:0xc420476540]
2018-06-21T19:03:59.248+0530    DEBUG   [bus]   bus/bus.go:55   docker: map[start:true container:0xc4204765b0]
2018-06-21T19:03:59.248+0530    DEBUG   [processors]    processors/processor.go:49      Processors: add_docker_metadata=[match_fields=[system.process.cgroup.id] match_pids=[process.pid, process.ppid]]
2018-06-21T19:03:59.248+0530    DEBUG   [prospector]    log/config.go:178       recursive glob enabled
2018-06-21T19:03:59.249+0530    DEBUG   [prospector]    log/prospector.go:120   exclude_files: []. Number of stats: 93
2018-06-21T19:03:59.249+0530    DEBUG   [prospector]    file/states.go:51       New state added for /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log
2018-06-21T19:03:59.249+0530    DEBUG   [registrar]     registrar/registrar.go:228      Processing 1 events
2018-06-21T19:03:59.249+0530    DEBUG   [prospector]    log/prospector.go:141   Prospector with previous states loaded: 1
2018-06-21T19:03:59.250+0530    INFO    log/prospector.go:111   Configured paths: [/var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/*.log]
2018-06-21T19:03:59.250+0530    DEBUG   [prospector]    prospector/prospector.go:87     Starting prospector of type: docker; ID: 14577626411652778845
2018-06-21T19:03:59.250+0530    DEBUG   [registrar]     registrar/registrar.go:200      Registrar state updates processed. Count: 1
2018-06-21T19:03:59.250+0530    DEBUG   [registrar]     registrar/registrar.go:218      Registrar states cleaned up. Before: 93, After: 93, Pending: 0
2018-06-21T19:03:59.250+0530    DEBUG   [registrar]     registrar/registrar.go:259      Write registry file: /var/lib/filebeat/registry
2018-06-21T19:03:59.250+0530    DEBUG   [cfgfile]       cfgfile/reload.go:95    Checking module configs from: /etc/filebeat/modules.d/*.yml
2018-06-21T19:03:59.250+0530    DEBUG   [cfgfile]       cfgfile/reload.go:109   Number of module configs found: 0
2018-06-21T19:03:59.250+0530    DEBUG   [prospector]    log/prospector.go:147   Start next scan
2018-06-21T19:03:59.250+0530    INFO    crawler/crawler.go:82   Loading and starting Prospectors completed. Enabled prospectors: 1
2018-06-21T19:03:59.250+0530    INFO    cfgfile/reload.go:127   Config reloader started
2018-06-21T19:03:59.250+0530    DEBUG   [cfgfile]       cfgfile/reload.go:151   Scan for new config files
2018-06-21T19:03:59.250+0530    DEBUG   [prospector]    log/prospector.go:362   Check file for harvesting: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log
2018-06-21T19:03:59.250+0530    DEBUG   [prospector]    log/prospector.go:448   Update existing file for harvesting: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log, offset: 101944
2018-06-21T19:03:59.250+0530    DEBUG   [prospector]    log/prospector.go:502   File didn't change: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log
2018-06-21T19:03:59.250+0530    DEBUG   [prospector]    log/prospector.go:168   Prospector states cleaned up. Before: 1, After: 1, Pending: 0
2018-06-21T19:03:59.250+0530    DEBUG   [cfgfile]       cfgfile/reload.go:170   Number of module configs found: 0
2018-06-21T19:03:59.250+0530    INFO    cfgfile/reload.go:219   Loading of config files completed.
2018-06-21T19:03:59.479+0530    DEBUG   [registrar]     registrar/registrar.go:284      Registry file updated. 93 states written.
2018-06-21T19:04:09.250+0530    DEBUG   [prospector]    prospector/prospector.go:124    Run prospector
2018-06-21T19:04:49.252+0530    DEBUG   [prospector]    log/prospector.go:147   Start next scan
2018-06-21T19:04:49.252+0530    DEBUG   [prospector]    log/prospector.go:362   Check file for harvesting: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log
2018-06-21T19:04:49.252+0530    DEBUG   [prospector]    log/prospector.go:448   Update existing file for harvesting: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log, offset: 101944

pa.cloud · June 21, 2018, 2:03pm

2018-06-21T19:04:49.252+0530    DEBUG   [prospector]    log/prospector.go:457   Resuming harvesting of file: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log, offset: 101944, new size: 104630
2018-06-21T19:04:49.253+0530    DEBUG   [harvester]     log/harvester.go:442    Set previous offset for file: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log. Offset: 101944
2018-06-21T19:04:49.253+0530    DEBUG   [harvester]     log/harvester.go:433    Setting offset for file: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log. Offset: 101944
2018-06-21T19:04:49.253+0530    DEBUG   [harvester]     log/harvester.go:348    Update state: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log, offset: 101944
2018-06-21T19:04:49.253+0530    DEBUG   [prospector]    log/prospector.go:168   Prospector states cleaned up. Before: 1, After: 1, Pending: 0
2018-06-21T19:04:49.253+0530    DEBUG   [registrar]     registrar/registrar.go:228      Processing 1 events
2018-06-21T19:04:49.253+0530    DEBUG   [registrar]     registrar/registrar.go:200      Registrar state updates processed. Count: 1
2018-06-21T19:04:49.253+0530    INFO    log/harvester.go:216    Harvester started for file: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log
2018-06-21T19:04:49.253+0530    DEBUG   [registrar]     registrar/registrar.go:259      Write registry file: /var/lib/filebeat/registry
2018-06-21T19:04:49.254+0530    DEBUG   [publish]       pipeline/processor.go:275       Publish event: {
  "@timestamp": "2018-06-21T13:34:44.117Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "6.2.4"
  },
  "message": "2018-06-21 13:34:44.115 4325315 [http-nio-9090-exec-5] INFO  mylog",
  "prospector": {
    "type": "docker"
  },
  "beat": {
    "name": "2030021817",
    "hostname": "2030021817",
    "version": "6.2.4"
  },
  "source": "/var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log",
  "offset": 102788,
  "stream": "stdout"
}
2018-06-21T19:04:49.254+0530    DEBUG   [harvester]     log/log.go:85   End of file reached: /var/lib/docker/containers/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7/901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7-json.log; Backoff now.
2018-06-21T19:04:49.315+0530    DEBUG   [registrar]     registrar/registrar.go:284      Registry file updated. 93 states written.
2018-06-21T19:04:50.254+0530    DEBUG   [elasticsearch] elasticsearch/client.go:666     ES Ping(url=http://localhost:9200)
2018-06-21T19:04:50.255+0530    DEBUG   [harvester]     log/log.go:85   End of file reached:

pa.cloud · June 22, 2018, 10:15am

Just to add, i couldn't spot any difference in logs for success/failure case.
Just changing the "match_source: " to true in mentioned config emits the metadata.

Also, I noticed the fields of my container map. Should it contain the fields specified in match_fields/match_pids to work without match_source ?

/var/log/filebeat/filebeat.3:2018-06-22T14:41:02.623+0530       DEBUG   [docker]
    docker/watcher.go:207   Got a new docker event: {exec_create: bash  901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7 
myservice25:latest container exec_create: bash  {901039ed0f29f80e5a464d16f4fb2262b716d9d2a2671bfd8dab8810e1a846f7 
map[service.name:myservice service.version:docktest execID:84ad266925ba5a8fbb5a3f325dd1cfe39bb873a8920281eed66016d4ebf74f82 
image:myservice25:latest name:myservice25]} local 1529658662 1529658662623494207}

Please advise.

pa.cloud · June 25, 2018, 5:22am

Hi, kvch,
I have provided debug logs. Would really appreciate if I can get some pointer.

I feel it's because of fields not being present in the container map. Can anyone guide what needs to be done to get them in map:

match_fields: ["system.process.cgroup.id"]
match_pids: ["process.pid", "process.ppid"]

I don't see them in map...

map[service.name:myservice service.version:docktest execID:84ad266925ba5a8fbb5a3f325dd1cfe39bb873a8920281eed66016d4ebf74f82 
image:myservice25:latest name:myservice25]} local 1529658662 1529658662623494207}

TIA

kvch · June 25, 2018, 3:34pm

If you disable match_source, log paths are not matching. Thus, events are not going to be enriched.
sytem.process.cgroup.id, process.pid and process.ppid fields are not present in Filebeat events by default. It's provided by Metricbeat automaticcaly. You need to add those fields to your event manually in case of Filebeat.

What is it that you are trying to achieve by disabling this option?

pa.cloud · June 25, 2018, 4:41pm

Thanks for replying.
Can you please guide me how to add those fields. Is there any link/documentation that i can refer to?

I want to log to custom location (volume)...so my log path would not have container id.

pa.cloud · June 27, 2018, 11:09am

Hi,
Can anyone please let me know how can I get additional fields (process.pid, process.ppid or any other which can enable enriching of logs with docker metadata.

I tried include_fields: and fields: but it didn't work

- type: docker

  fields: #      =====> DOESN'T SEEM TO HELP
    docker: true
    system: true
    auditd: true

  enabled: true
  containers:
    path: /var/lib/docker/containers
    ids: "*"
  processors:
    - include_fields:  #    ====> DOESN'T SEEM TO HELP
        fields: ["docker.container.id", "process.pid", "process.ppid"]
    - add_docker_metadata:
        host: "unix:///var/run/docker.sock"
        match_fields: ["docker.container.id", "system.process.cgroup.id"]
        match_pids: ["process.pid", "process.ppid"]
        match_source: false
        match_source_index: 4
        match_short_id: false

kvch · June 27, 2018, 4:13pm

By manually I meant that Filebeat does not support this unfortunately.

system · July 25, 2018, 4:13pm

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

Topic		Replies	Views
[Filebeat] Windows: add_docker_metadata cannot extract Container ID Beats	1	756	November 21, 2018
Missing docker metadata in filebeat Beats docker , filebeat	5	1341	June 16, 2020
Error with filebeat on kubernetes 1.20 using add_kubernetes_metadata Beats filebeat	1	474	January 12, 2021
Add docker metadata not working even after trying all possible combinations Beats filebeat	9	1193	December 25, 2018
Filebeat add docker metada fail Beats filebeat	2	370	August 18, 2020

Add_docker_metadata not working with match_source: false

Related topics