Filebeat not writing to index

aidenosi · May 19, 2021, 2:41pm

Hello,

I've been trying to set up Filebeat (6.8.0) on our Linux machines for a few days now but keep running into this issue where it seems that Filebeat stops communicating/writing to Elastic.

Config below:

filebeat:
  config:
    modules:
      path: /etc/filebeat/modules.d/*.yml
      reload:
        enabled: false
        period: 60s
  inputs:
  - enabled: true
    paths:
    - /var/log/filebeat*
    - /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/*.log
    - /app/CQF0/CONFLUENCE/CONFLUENCE-HOME/logs/attlassian*
    type: log
name: DEV-LINUX-SERVER-LOGS
output:
  elasticsearch:
    hosts:
    - <host>
    index: cqf0-<server>-logs-%{+yyyy.MM.dd}
    password: ${ES_PSW}
    ssl:
      verification_mode: none
    username: ${ES_USR}
path:
  config: /etc/filebeat
  data: /var/lib/filebeat
  home: /usr/share/filebeat
  logs: /var/log/filebeat
setup:
  template:
    name: cqf0-logs
    pattern: cqf0-*
    settings:
      index:
        number_of_shards: 3

Specifically, the issue I'm having is that when I start the Filebeat service, it will create the index in Elastic, and apply the template, ILM policy. That's all good. But then, nothing else is being written to the index after the initial write, even though there is plenty being written to the logs that are targeted.

A colleague who is implementing Filebeat on our Windows machines is using the same config (except for ssl.verification_mode: none) and isn't having any issues.

Filebeat logs don't show any errors, filebeat test config and filebeat test output commands both succeed and don't show any errors (only a warning for SSL verification being turned off).

Is there something I'm missing? Anything else I can check to see if there are errors?

warkolm · May 20, 2021, 1:43am

Can you run Filebeat with filebeat -e -d "*" to get some debug output?

aidenosi · May 20, 2021, 1:35pm

Hi there,

There's quite a bit here, but here's the output of letting it run for about a minute.

2021-05-20T09:26:44.517-0400    INFO    instance/beat.go:611    Home path: [/usr/share/filebeat] Config path: [/etc/filebeat] Data path: [/var/lib/filebeat] Logs path: [/var/log/filebeat]
2021-05-20T09:26:44.517-0400    DEBUG   [beat]  instance/beat.go:648    Beat metadata path: /var/lib/filebeat/meta.json
2021-05-20T09:26:44.517-0400    INFO    instance/beat.go:618    Beat UUID: 7c5de934-012a-454b-981e-64316f93c880
2021-05-20T09:26:44.517-0400    DEBUG   [seccomp]       seccomp/seccomp.go:109  Loading syscall filter  {"seccomp_filter": {"no_new_privs":true,"flag":"tsync","policy":{"default_action":"errno","syscalls":[{"names":["accept","accept4","access","arch_prctl","bind","brk","clock_gettime","clone","close","connect","dup","dup2","epoll_create","epoll_create1","epoll_ctl","epoll_pwait","epoll_wait","exit","exit_group","fchdir","fchmod","fchown","fcntl","fdatasync","flock","fstat","fstatfs","fsync","ftruncate","futex","getcwd","getdents","getdents64","geteuid","getgid","getpeername","getpid","getppid","getrandom","getrlimit","getrusage","getsockname","getsockopt","gettid","gettimeofday","getuid","inotify_add_watch","inotify_init1","inotify_rm_watch","ioctl","kill","listen","lseek","lstat","madvise","mincore","mkdirat","mmap","mprotect","munmap","nanosleep","newfstatat","open","openat","pipe","pipe2","poll","ppoll","pread64","pselect6","pwrite64","read","readlink","readlinkat","recvfrom","recvmmsg","recvmsg","rename","renameat","rt_sigaction","rt_sigprocmask","rt_sigreturn","sched_getaffinity","sched_yield","sendfile","sendmmsg","sendmsg","sendto","set_robust_list","setitimer","setsockopt","shutdown","sigaltstack","socket","splice","stat","statfs","sysinfo","tgkill","time","tkill","uname","unlink","unlinkat","wait4","waitid","write","writev"],"action":"allow"}]}}}
2021-05-20T09:26:44.518-0400    INFO    [seccomp]       seccomp/seccomp.go:116  Syscall filter successfully installed
2021-05-20T09:26:44.518-0400    INFO    [beat]  instance/beat.go:931    Beat info       {"system_info": {"beat": {"path": {"config": "/etc/filebeat", "data": "/var/lib/filebeat", "home": "/usr/share/filebeat", "logs": "/var/log/filebeat"}, "type": "filebeat", "uuid": "7c5de934-012a-454b-981e-64316f93c880"}}}
2021-05-20T09:26:44.518-0400    INFO    [beat]  instance/beat.go:940    Build info      {"system_info": {"build": {"commit": "c01de6731c401c73d03ed996cdf21f5724ad83f4", "libbeat": "6.8.0", "time": "2019-05-15T19:07:08.000Z", "version": "6.8.0"}}}
2021-05-20T09:26:44.518-0400    INFO    [beat]  instance/beat.go:943    Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":4,"version":"go1.10.8"}}}
2021-05-20T09:26:44.519-0400    INFO    [beat]  instance/beat.go:947    Host info       {"system_info": {"host": {"architecture":"x86_64","boot_time":"2021-05-06T08:06:39-04:00","containerized":true,"name":"mrkdlvaiaas2356.devfg.rbc.com","ip":["127.0.0.1/8","10.47.138.122/24"],"kernel_version":"3.10.0-1160.21.1.el7.x86_64","mac":["fa:16:3e:63:3c:9a"],"os":{"family":"redhat","platform":"rhel","name":"Red Hat Enterprise Linux Server","version":"7.9 (Maipo)","major":7,"minor":9,"patch":0,"codename":"Maipo"},"timezone":"EDT","timezone_offset_sec":-14400,"id":"04ddc35ec03045eb9a32f729b48c5d20"}}}
2021-05-20T09:26:44.520-0400    INFO    [beat]  instance/beat.go:976    Process info    {"system_info": {"process": {"capabilities": {"inheritable":null,"permitted":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend"],"effective":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend"],"bounding":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend"],"ambient":null}, "cwd": "/root", "exe": "/usr/share/filebeat/bin/filebeat", "name": "filebeat", "pid": 96933, "ppid": 95879, "seccomp": {"mode":"filter","no_new_privs":true}, "start_time": "2021-05-20T09:26:43.640-0400"}}}
2021-05-20T09:26:44.520-0400    INFO    instance/beat.go:280    Setup Beat: filebeat; Version: 6.8.0
2021-05-20T09:26:44.520-0400    DEBUG   [beat]  instance/beat.go:301    Initializing output plugins
2021-05-20T09:26:44.520-0400    DEBUG   [processors]    processors/processor.go:66      Processors:
2021-05-20T09:26:44.520-0400    DEBUG   [keystore]      keystore/keystore.go:124        accessing key 'ES_USR' from the keystore
2021-05-20T09:26:44.520-0400    DEBUG   [keystore]      keystore/keystore.go:124        accessing key 'ES_PSW' from the keystore
2021-05-20T09:26:44.520-0400    INFO    elasticsearch/client.go:164     Elasticsearch url: https://7f87d5e2751549fd928c21a918d42e96.ece.saifg.rbc.com:9243
2021-05-20T09:26:44.521-0400    DEBUG   [publish]       pipeline/consumer.go:137        start pipeline event consumer
2021-05-20T09:26:44.521-0400    INFO    [publisher]     pipeline/module.go:110  Beat name: DEV-LINUX-SERVER-LOGS
2021-05-20T09:26:44.522-0400    INFO    instance/beat.go:402    filebeat start running.
2021-05-20T09:26:44.522-0400    INFO    [monitoring]    log/log.go:117  Starting metrics logging every 30s
2021-05-20T09:26:44.522-0400    DEBUG   [registrar]     registrar/registrar.go:114      Registry file set to: /var/lib/filebeat/registry
2021-05-20T09:26:44.522-0400    INFO    registrar/registrar.go:134      Loading registrar data from /var/lib/filebeat/registry
2021-05-20T09:26:44.523-0400    INFO    registrar/registrar.go:141      States Loaded from registrar: 75
2021-05-20T09:26:44.523-0400    INFO    crawler/crawler.go:72   Loading Inputs: 1
2021-05-20T09:26:44.523-0400    DEBUG   [processors]    processors/processor.go:66      Processors:
2021-05-20T09:26:44.523-0400    DEBUG   [registrar]     registrar/registrar.go:267      Starting Registrar
2021-05-20T09:26:44.523-0400    DEBUG   [input] log/config.go:201       recursive glob enabled
2021-05-20T09:26:44.523-0400    DEBUG   [input] log/input.go:147        exclude_files: []. Number of stats: 75
2021-05-20T09:26:44.524-0400    DEBUG   [input] file/states.go:68       New state added for /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-07.log
2021-05-20T09:26:44.524-0400    DEBUG   [publish]       pipeline/client.go:193  Pipeline client receives callback 'onFilteredOut' for event: %+v{0001-01-01 00:00:00 +0000 UTC null null {10356612-64776 true <nil> /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-07.log 115301 2021-05-20 09:26:32.93971908 -0400 EDT -1ns log map[] 10356612-64776}}
2021-05-20T09:26:44.524-0400    DEBUG   [input] file/states.go:68       New state added for /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-11.log
2021-05-20T09:26:44.524-0400    DEBUG   [publish]       pipeline/client.go:193  Pipeline client receives callback 'onFilteredOut' for event: %+v{0001-01-01 00:00:00 +0000 UTC null null {10356615-64776 true <nil> /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-11.log 92316 2021-05-20 09:26:32.945033435 -0400 EDT -1ns log map[] 10356615-64776}}
2021-05-20T09:26:44.524-0400    DEBUG   [input] file/states.go:68       New state added for /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/localhost.2021-03-25.log
2021-05-20T09:26:44.524-0400    DEBUG   [acker] beater/acker.go:64      stateful ack    {"count": 1}
2021-05-20T09:26:44.524-0400    DEBUG   [acker] beater/acker.go:64      stateful ack    {"count": 1}
2021-05-20T09:26:44.524-0400    DEBUG   [acker] beater/acker.go:64      stateful ack    {"count": 1}
2021-05-20T09:26:44.524-0400    DEBUG   [registrar]     registrar/registrar.go:345      Processing 1 events
2021-05-20T09:26:44.524-0400    DEBUG   [registrar]     registrar/registrar.go:315      Registrar state updates processed. Count: 1
2021-05-20T09:26:44.524-0400    DEBUG   [registrar]     registrar/registrar.go:335      Registrar states cleaned up. Before: 75, After: 75, Pending: 0
2021-05-20T09:26:44.524-0400    DEBUG   [registrar]     registrar/registrar.go:400      Write registry file: /var/lib/filebeat/registry
2021-05-20T09:26:44.525-0400    DEBUG   [publish]       pipeline/client.go:193  Pipeline client receives callback 'onFilteredOut' for event: %+v{0001-01-01 00:00:00 +0000 UTC null null {10356837-64776 true <nil> /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/localhost.2021-03-25.log 0 2021-05-20 09:26:32.948135663 -0400 EDT -1ns log map[] 10356837-64776}}
2021-05-20T09:26:44.525-0400    DEBUG   [input] file/states.go:68       New state added for /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-05.log
2021-05-20T09:26:44.525-0400    DEBUG   [publish]       pipeline/client.go:193  Pipeline client receives callback 'onFilteredOut' for event: %+v{0001-01-01 00:00:00 +0000 UTC null null {10356611-64776 true <nil> /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-05.log 10321 2021-05-20 09:26:32.950577167 -0400 EDT -1ns log map[] 10356611-64776}}
2021-05-20T09:26:44.525-0400    DEBUG   [input] file/states.go:68       New state added for /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-17.log
2021-05-20T09:26:44.528-0400    DEBUG   [registrar]     registrar/registrar.go:393      Registry file updated. 75 states written.
2021-05-20T09:26:44.528-0400    DEBUG   [registrar]     registrar/registrar.go:345      Processing 1 events
2021-05-20T09:26:44.528-0400    DEBUG   [registrar]     registrar/registrar.go:315      Registrar state updates processed. Count: 1
2021-05-20T09:26:44.528-0400    DEBUG   [registrar]     registrar/registrar.go:335      Registrar states cleaned up. Before: 75, After: 75, Pending: 0
2021-05-20T09:26:44.528-0400    DEBUG   [registrar]     registrar/registrar.go:400      Write registry file: /var/lib/filebeat/registry
2021-05-20T09:26:44.529-0400    DEBUG   [acker] beater/acker.go:64      stateful ack    {"count": 1}
2021-05-20T09:26:44.529-0400    DEBUG   [publish]       pipeline/client.go:193  Pipeline client receives callback 'onFilteredOut' for event: %+v{0001-01-01 00:00:00 +0000 UTC null null {10356616-64776 true <nil> /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-17.log 829 2021-05-20 09:26:32.952649847 -0400 EDT -1ns log map[] 10356616-64776}}
2021-05-20T09:26:44.529-0400    DEBUG   [input] file/states.go:68       New state added for /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/catalina.2021-03-19.log


^Several hundred lines of this

aidenosi · May 20, 2021, 1:35pm

2021-05-20T09:26:44.702-0400    INFO    log/input.go:138        Configured paths: [/var/log/filebeat* /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/*.log /app/CQF0/CONFLUENCE/CONFLUENCE-HOME/logs/attlassian*]
2021-05-20T09:26:44.702-0400    INFO    input/input.go:114      Starting input of type: log; ID: 12694345350154055759
2021-05-20T09:26:44.702-0400    DEBUG   [cfgfile]       cfgfile/reload.go:118   Checking module configs from: /etc/filebeat/modules.d/*.yml
2021-05-20T09:26:44.702-0400    DEBUG   [cfgfile]       cfgfile/reload.go:132   Number of module configs found: 0
2021-05-20T09:26:44.702-0400    INFO    crawler/crawler.go:106  Loading and starting Inputs completed. Enabled inputs: 1
2021-05-20T09:26:44.702-0400    DEBUG   [input] log/input.go:174        Start next scan
2021-05-20T09:26:44.703-0400    INFO    cfgfile/reload.go:150   Config reloader started
2021-05-20T09:26:44.703-0400    DEBUG   [input] log/input.go:267        Skipping directory: /var/log/filebeat
2021-05-20T09:26:44.703-0400    DEBUG   [cfgfile]       cfgfile/reload.go:176   Scan for new config files
2021-05-20T09:26:44.703-0400    DEBUG   [cfgfile]       cfgfile/reload.go:195   Number of module configs found: 0
2021-05-20T09:26:44.703-0400    DEBUG   [reload]        cfgfile/list.go:62      Starting reload procedure, current runners: 0
2021-05-20T09:26:44.703-0400    DEBUG   [reload]        cfgfile/list.go:80      Start list: 0, Stop list: 0
2021-05-20T09:26:44.703-0400    INFO    cfgfile/reload.go:205   Loading of config files completed.
2021-05-20T09:26:44.704-0400    DEBUG   [input] log/input.go:404        Check file for harvesting: /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/host-manager.2021-05-10.log
2021-05-20T09:26:44.704-0400    DEBUG   [input] log/input.go:494        Update existing file for harvesting: /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/host-manager.2021-05-10.log, offset: 0
2021-05-20T09:26:44.704-0400    DEBUG   [input] log/input.go:548        File didn't change: /app/CQF0/CONFLUENCE/CONFLUENCE-DATA/logs/host-manager.2021-05-10.log


^this repeats for several hundred lines


2021-05-20T09:27:14.732-0400    DEBUG   [input] log/input.go:195        input states cleaned up. Before: 75, After: 75, Pending: 0
^C2021-05-20T09:27:19.915-0400  DEBUG   [service]       service/service.go:50   Received sigterm/sigint, stopping
2021-05-20T09:27:19.915-0400    INFO    beater/filebeat.go:442  Stopping filebeat
2021-05-20T09:27:19.915-0400    INFO    crawler/crawler.go:139  Stopping Crawler
2021-05-20T09:27:19.915-0400    INFO    crawler/crawler.go:149  Stopping 1 inputs
2021-05-20T09:27:19.915-0400    INFO    cfgfile/reload.go:208   Dynamic config reloader stopped
2021-05-20T09:27:19.915-0400    INFO    input/input.go:149      input ticker stopped
2021-05-20T09:27:19.915-0400    INFO    input/input.go:167      Stopping Input: 12694345350154055759
2021-05-20T09:27:19.915-0400    DEBUG   [publish]       pipeline/client.go:148  client: closing acker
2021-05-20T09:27:19.915-0400    DEBUG   [publish]       pipeline/client.go:150  client: done closing acker
2021-05-20T09:27:19.915-0400    DEBUG   [publish]       pipeline/client.go:154  client: cancelled 0 events
2021-05-20T09:27:19.915-0400    INFO    crawler/crawler.go:165  Crawler stopped
2021-05-20T09:27:19.915-0400    INFO    registrar/registrar.go:356      Stopping Registrar
2021-05-20T09:27:19.915-0400    INFO    registrar/registrar.go:282      Ending Registrar
2021-05-20T09:27:19.915-0400    DEBUG   [registrar]     registrar/registrar.go:400      Write registry file: /var/lib/filebeat/registry
2021-05-20T09:27:19.925-0400    DEBUG   [registrar]     registrar/registrar.go:393      Registry file updated. 75 states written.
2021-05-20T09:27:19.928-0400    INFO    [monitoring]    log/log.go:152  Total non-zero metrics  {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":70,"time":{"ms":78}},"total":{"ticks":170,"time":{"ms":179},"value":170},"user":{"ticks":100,"time":{"ms":101}}},"handles":{"limit":{"hard":65536,"soft":1024},"open":6},"info":{"ephemeral_id":"599450b6-5cf8-4590-bdde-da23733fa38b","uptime":{"ms":35436}},"memstats":{"gc_next":4404160,"memory_alloc":3254528,"memory_total":8722176,"rss":16748544}},"filebeat":{"events":{"added":75,"done":75},"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0},"reloads":1},"output":{"type":"elasticsearch"},"pipeline":{"clients":0,"events":{"active":0,"filtered":75,"total":75}}},"registrar":{"states":{"current":75,"update":75},"writes":{"success":76,"total":76}},"system":{"cpu":{"cores":4},"load":{"1":0.08,"15":0.21,"5":0.16,"norm":{"1":0.02,"15":0.0525,"5":0.04}}}}}}
2021-05-20T09:27:19.929-0400    INFO    [monitoring]    log/log.go:153  Uptime: 35.440122259s
2021-05-20T09:27:19.929-0400    INFO    [monitoring]    log/log.go:130  Stopping metrics logging.
2021-05-20T09:27:19.929-0400    INFO    instance/beat.go:412    filebeat stopped.

system · June 17, 2021, 3:36pm

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