Non-zero metrics in the last 30s (filebeat with docker)

Elastic Stack Beats
,
1

I used docker to run filebeat and always got this message "Non-zero metrics in the last 30s". It seems not to work.
file docker-compose.yml:

    version: '2'
    services:
      filebeat:
        image: elastic/filebeat:7.9.2
        container_name: filebeat
        environment:
          - TZ=Asia/Shanghai
        volumes:
          - ~/:/var/log/:ro
          - ./conf/filebeat.yml:/usr/share/filebeat/filebeat.yml

file ./conf/filebeat.yml:

    filebeat.inputs:
    - type: log
      enabled: true
      paths:
        - /val/log/*.log
        - /val/log/messages

      multiline.type: pattern
      multiline.pattern: '^\['
      multiline.negate: true
      multiline.match: after

    output.logstash:
      hosts: ["10.0.0.164:5044"]

and used command echo "test message" >> ./my.log to write something, but still got "Non-zero metrics in the last 30s".

Can help me to find this issue? Thanks!

2

Hi @linhonghui welcome to.tue community.

1st your filebeat.yml says

filebeat.inputs:
- type: log
  enabled: true
  paths:
    - /val/log/*.log
    - /val/log/messages

Should that be?

- /var/log/*.log
- /var/log/messages

Also Non-zero metrics is not necessarily a bad things can you post your filebeat start up logs?

Please format them with the </> button above.

3

hi stephenb, thank you for your reply.

I mapped ~/ to /var/log and it can access the files when attach into docker container.

bash-4.2$ pwd
/var/log
bash-4.2$ ls -l
total 320
drwxr-xr-x  4 root     root         31 Jul 23 11:32 ldos
drwxr-xr-x  4 root     root         31 Sep 27 17:04 ldos_mobile
drwxr-xr-x  5 root     root         52 Sep 27 17:04 logs
-rw-rw-r--  1 filebeat filebeat     97 Oct  3 12:17 messages
-rw-rw-r--  1 filebeat filebeat     32 Oct  3 12:52 my.log
drwxrwxr-x  6 filebeat filebeat     80 Sep 27 15:05 projects
-rw-rw-r--  1 filebeat filebeat 311438 Oct  1 11:01 sentinl-7.6.1.zip
drwxr-xr-x 30 root     root       4096 Oct  3 11:07 xxl

The logs with command "docker logs filebeat":

2020-10-03T12:51:35.038+0800    INFO    instance/beat.go:640    Home path: [/usr/share/filebeat] Config path: [/usr/share/filebeat] Data path: [/usr/share/filebeat/data] Logs path: [/usr/share/filebeat/logs]
2020-10-03T12:51:35.040+0800    INFO    instance/beat.go:648    Beat ID: f0778e00-08bc-4d09-81af-18dd99287a1e
2020-10-03T12:51:35.041+0800    INFO    [seccomp]       seccomp/seccomp.go:124  Syscall filter successfully installed
2020-10-03T12:51:35.041+0800    INFO    [beat]  instance/beat.go:976    Beat info       {"system_info": {"beat": {"path": {"config": "/usr/share/filebeat", "data": "/usr/share/filebeat/data", "home": "/usr/share/filebeat", "logs": "/usr/share/filebeat/logs"}, "type": "filebeat", "uuid": "f0778e00-08bc-4d09-81af-18dd99287a1e"}}}
2020-10-03T12:51:35.041+0800    INFO    [beat]  instance/beat.go:985    Build info      {"system_info": {"build": {"commit": "2ab907f5ccecf9fd82fe37105082e89fd871f684", "libbeat": "7.9.2", "time": "2020-09-22T23:19:45.000Z", "version": "7.9.2"}}}
2020-10-03T12:51:35.041+0800    INFO    [beat]  instance/beat.go:988    Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":2,"version":"go1.14.7"}}}
2020-10-03T12:51:35.042+0800    INFO    [beat]  instance/beat.go:992    Host info       {"system_info": {"host": {"architecture":"x86_64","boot_time":"2020-09-30T19:05:10+08:00","containerized":true,"name":"a831097e08a9","ip":["127.0.0.1/8","192.168.240.2/20"],"kernel_version":"3.10.0-1062.18.1.el7.x86_64","mac":["02:42:c0:a8:f0:02"],"os":{"family":"redhat","platform":"centos","name":"CentOS Linux","version":"7 (Core)","major":7,"minor":8,"patch":2003,"codename":"Core"},"timezone":"CST","timezone_offset_sec":28800}}}
2020-10-03T12:51:35.042+0800    INFO    [beat]  instance/beat.go:1021   Process info    {"system_info": {"process": {"capabilities": {"inheritable":["chown","dac_override","fowner","fsetid","kill","setgid","setuid","setpcap","net_bind_service","net_raw","sys_chroot","mknod","audit_write","setfcap"],"permitted":null,"effective":null,"bounding":["chown","dac_override","fowner","fsetid","kill","setgid","setuid","setpcap","net_bind_service","net_raw","sys_chroot","mknod","audit_write","setfcap"],"ambient":null}, "cwd": "/usr/share/filebeat", "exe": "/usr/share/filebeat/filebeat", "name": "filebeat", "pid": 1, "ppid": 0, "seccomp": {"mode":"filter","no_new_privs":false}, "start_time": "2020-10-03T12:51:33.850+0800"}}}
2020-10-03T12:51:35.042+0800    INFO    instance/beat.go:299    Setup Beat: filebeat; Version: 7.9.2
2020-10-03T12:51:35.043+0800    INFO    [publisher]     pipeline/module.go:113  Beat name: a831097e08a9
2020-10-03T12:51:35.044+0800    WARN    beater/filebeat.go:178  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2020-10-03T12:51:35.044+0800    INFO    [monitoring]    log/log.go:118  Starting metrics logging every 30s
2020-10-03T12:51:35.045+0800    INFO    instance/beat.go:450    filebeat start running.
2020-10-03T12:51:35.049+0800    INFO    memlog/store.go:119     Loading data file of '/usr/share/filebeat/data/registry/filebeat' succeeded. Active transaction id=0
2020-10-03T12:51:35.049+0800    INFO    memlog/store.go:124     Finished loading transaction log file for '/usr/share/filebeat/data/registry/filebeat'. Active transaction id=0
2020-10-03T12:51:35.049+0800    WARN    beater/filebeat.go:381  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2020-10-03T12:51:35.049+0800    INFO    [registrar]     registrar/registrar.go:109      States Loaded from registrar: 0
2020-10-03T12:51:35.049+0800    INFO    [crawler]       beater/crawler.go:71    Loading Inputs: 1
2020-10-03T12:51:35.050+0800    INFO    log/input.go:157        Configured paths: [/val/log/*.log /val/log/messages]
2020-10-03T12:51:35.050+0800    INFO    [crawler]       beater/crawler.go:141   Starting input (ID: 5255008420351845344)
2020-10-03T12:51:35.050+0800    INFO    [crawler]       beater/crawler.go:108   Loading and starting Inputs completed. Enabled inputs: 1
2020-10-03T12:52:05.048+0800    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":90,"time":{"ms":93}},"total":{"ticks":210,"time":{"ms":217},"value":210},"user":{"ticks":120,"time":{"ms":124}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":9},"info":{"ephemeral_id":"0c326455-223a-47d9-a64d-2311b3027809","uptime":{"ms":30070}},"memstats":{"gc_next":16547760,"memory_alloc":8981960,"memory_total":35382376,"rss":53051392},"runtime":{"goroutines":20}},"filebeat":{"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"output":{"type":"logstash"},"pipeline":{"clients":1,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"cpu":{"cores":2},"load":{"1":0.14,"15":0.09,"5":0.1,"norm":{"1":0.07,"15":0.045,"5":0.05}}}}}}
2020-10-03T12:52:35.049+0800    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":90,"time":{"ms":5}},"total":{"ticks":210,"time":{"ms":8},"value":210},"user":{"ticks":120,"time":{"ms":3}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":9},"info":{"ephemeral_id":"0c326455-223a-47d9-a64d-2311b3027809","uptime":{"ms":60070}},"memstats":{"gc_next":16547760,"memory_alloc":9200008,"memory_total":35600424},"runtime":{"goroutines":20}},"filebeat":{"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":0.09,"15":0.08,"5":0.09,"norm":{"1":0.045,"15":0.04,"5":0.045}}}}}}
2020-10-03T12:53:05.048+0800    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":100,"time":{"ms":5}},"total":{"ticks":230,"time":{"ms":8},"value":230},"user":{"ticks":130,"time":{"ms":3}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":9},"info":{"ephemeral_id":"0c326455-223a-47d9-a64d-2311b3027809","uptime":{"ms":90069}},"memstats":{"gc_next":16547760,"memory_alloc":9485504,"memory_total":35885920},"runtime":{"goroutines":20}},"filebeat":{"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":0.2,"15":0.09,"5":0.12,"norm":{"1":0.1,"15":0.045,"5":0.06}}}}}}
2020-10-03T12:53:35.052+0800    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":100,"time":{"ms":7}},"total":{"ticks":240,"time":{"ms":18},"value":240},"user":{"ticks":140,"time":{"ms":11}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":9},"info":{"ephemeral_id":"0c326455-223a-47d9-a64d-2311b3027809","uptime":{"ms":120071}},"memstats":{"gc_next":15199200,"memory_alloc":9702352,"memory_total":36253736,"rss":270336},"runtime":{"goroutines":20}},"filebeat":{"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":0.12,"15":0.09,"5":0.1,"norm":{"1":0.06,"15":0.045,"5":0.05}}}}}}
2020-10-03T12:54:05.048+0800    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":230,"time":{"ms":121}},"total":{"ticks":440,"time":{"ms":196},"value":440},"user":{"ticks":210,"time":{"ms":75}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":9},"info":{"ephemeral_id":"0c326455-223a-47d9-a64d-2311b3027809","uptime":{"ms":150069}},"memstats":{"gc_next":15199200,"memory_alloc":7805952,"memory_total":36461624},"runtime":{"goroutines":20}},"filebeat":{"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":0}}},"registrar":{"states":{"current":0}},"system":{"load":{"1":0.07,"15":0.09,"5":0.1,"norm":{"1":0.035,"15":0.045,"5":0.05}}}}}}
......

And what's your meaning of format?

4

Hi @linhonghui

Apologies, I just want to confirm one more time that you do not hava a typo in the path to the logs.

In your filebeat config you have

      paths:
        - /val/log/*.log
        - /val/log/messages

you have /val/log/*.log .../val... with an 'l' and
instead of of
/var/log/*.log ... /var... with an 'r' and

even the sample directory listing is

bash-4.2$ pwd
/var/log
bash-4.2$ ls -l

/var/log/ with an 'r'

I think that is the problem, fix your filebeat.yml

The

 Non-zero metrics in the last 30s

Log lines are normal they will print every 30s,
The contain information about
The Health of Filebeat And how much data it is sending since it looks like you have a bad path, it says you are sending no data.

The log also shows that you do not have elasticsearch configure as the output I do not know if that is what you want it means the log lines will not be sent to elasticsearch

5

oh yes, it is my mistake and after corrected, it worked. Thank you!

.....
2020-10-04T17:04:45.993+0800    INFO    log/harvester.go:299    Harvester started for file: /var/log/messages
2020-10-04T17:04:45.994+0800    INFO    log/harvester.go:299    Harvester started for file: /var/log/my.log
2020-10-04T17:04:51.994+0800    INFO    [publisher_pipeline_output]     pipeline/output.go:143  Connecting to backoff(async(tcp://10.0.0.164:5044))
.....

And I just want to test send logs to logstash that will send some notifications to another application.

6

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