[Filebeat] panic: unlock on unlocked mutex

[sakurai-youhei]

Under specific conditions, Filebeat often (not always but once every three to four times) crashes with panic: unlock on unlocked mutex.

• Version: 7.15.2, 7.15.1
• Operating System: Docker, Ubuntu 18.04 LTS (on VM)
• Discuss Forum URL: n/a
• Steps to Reproduce: Run Filebeat via Docker with the following filebeat.yml and files extracted from repro.zip

logging:
  level: debug

output.console:
  enabled: true

filebeat.inputs:
  - type: filestream
    paths:
      - "/var/log/pattern1.log*"
    rotation.external.strategy.copytruncate:
      suffix_regex: '\.\d+$'

  - type: filestream
    paths:
      - "/var/log/pattern2.log*"
    rotation.external.strategy.copytruncate:
      suffix_regex: '\.\d+$'

  - type: filestream
    paths:
      - "/var/log/pattern3.log*"
    rotation.external.strategy.copytruncate:
      suffix_regex: '\.\d+$'

  - type: filestream
    paths:
      - "/var/log/pattern4.log*"
    rotation.external.strategy.copytruncate:
      suffix_regex: '\.\d+$'

  - type: filestream
    paths:
      - "/var/log/pattern5.log*"
    rotation.external.strategy.copytruncate:
      suffix_regex: '\.\d+$'

Repro command: docker run -it --rm -v /path/to/filebeat.yml:/usr/share/filebeat/filebeat.yml:ro -v /path/to/repro:/var/log:ro docker.elastic.co/beats/filebeat:7.15.2 -e -strict.perms=false

Full logs when the crash occurs

2021-11-17T02:37:50.043Z        INFO    instance/beat.go:665    Home path: [/usr/share/filebeat] Config path: [/usr/share/filebeat] Data path: [/usr/share/filebeat/data] Logs path: [/usr/share/filebeat/logs]
2021-11-17T02:37:50.043Z        DEBUG   [beat]  instance/beat.go:723    Beat metadata path: /usr/share/filebeat/data/meta.json
2021-11-17T02:37:50.054Z        INFO    instance/beat.go:673    Beat ID: 6e5f4bc3-7e0b-47d6-9093-14209cc4084f
2021-11-17T02:37:50.054Z        DEBUG   [seccomp]       seccomp/seccomp.go:117  Loading syscall filter  {"seccomp_filter": {"no_new_privs":true,"flag":"tsync","policy":{"default_action":"errno","syscalls":[{"names":["accept","accept4","access","arch_prctl","bind","brk","chmod","chown","clock_gettime","clone","close","connect","dup","dup2","epoll_create","epoll_create1","epoll_ctl","epoll_pwait","epoll_wait","exit","exit_group","fchdir","fchmod","fchmodat","fchown","fchownat","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-11-17T02:37:50.054Z        INFO    [seccomp]       seccomp/seccomp.go:124  Syscall filter successfully installed
2021-11-17T02:37:50.054Z        INFO    [beat]  instance/beat.go:1014   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": "6e5f4bc3-7e0b-47d6-9093-14209cc4084f"}}}
2021-11-17T02:37:50.054Z        INFO    [beat]  instance/beat.go:1023   Build info      {"system_info": {"build": {"commit": "fd322dad6ceafec40c84df4d2a0694ea357d16cc", "libbeat": "7.15.2", "time": "2021-11-04T14:22:49.000Z", "version": "7.15.2"}}}
2021-11-17T02:37:50.054Z        INFO    [beat]  instance/beat.go:1026   Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":4,"version":"go1.16.6"}}}
2021-11-17T02:37:50.055Z        INFO    [beat]  instance/beat.go:1030   Host info       {"system_info": {"host": {"architecture":"x86_64","boot_time":"2021-11-16T13:21:50Z","containerized":true,"name":"b513a1f7f00c","ip":["127.0.0.1/8","172.17.0.2/16"],"kernel_version":"5.10.60.1-microsoft-standard-WSL2","mac":["02:42:ac:11:00:02"],"os":{"type":"linux","family":"redhat","platform":"centos","name":"CentOS Linux","version":"7 (Core)","major":7,"minor":9,"patch":2009,"codename":"Core"},"timezone":"UTC","timezone_offset_sec":0,"id":"1820c6c61258c329e88764d3dc4484f3"}}}
2021-11-17T02:37:50.055Z        INFO    [beat]  instance/beat.go:1059   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": 8, "ppid": 1, "seccomp": {"mode":"filter","no_new_privs":true}, "start_time": "2021-11-17T02:37:49.420Z"}}}
2021-11-17T02:37:50.055Z        INFO    instance/beat.go:309    Setup Beat: filebeat; Version: 7.15.2
2021-11-17T02:37:50.055Z        DEBUG   [beat]  instance/beat.go:335    Initializing output plugins
2021-11-17T02:37:50.055Z        DEBUG   [publisher]     pipeline/consumer.go:148        start pipeline event consumer
2021-11-17T02:37:50.055Z        INFO    [publisher]     pipeline/module.go:113  Beat name: b513a1f7f00c
2021-11-17T02:37:50.056Z        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.
2021-11-17T02:37:50.056Z        INFO    [monitoring]    log/log.go:142  Starting metrics logging every 30s
2021-11-17T02:37:50.056Z        INFO    instance/beat.go:473    filebeat start running.
2021-11-17T02:37:50.056Z        DEBUG   [test]  registrar/migrate.go:304        isFile(/usr/share/filebeat/data/registry) -> false
2021-11-17T02:37:50.056Z        DEBUG   [test]  registrar/migrate.go:304        isFile() -> false
2021-11-17T02:37:50.056Z        DEBUG   [test]  registrar/migrate.go:297        isDir(/usr/share/filebeat/data/registry/filebeat) -> false
2021-11-17T02:37:50.056Z        DEBUG   [registrar]     registrar/migrate.go:84 Registry type '' found
2021-11-17T02:37:50.056Z        DEBUG   [test]  registrar/migrate.go:304        isFile(.bak) -> false
2021-11-17T02:37:50.061Z        INFO    memlog/store.go:119     Loading data file of '/usr/share/filebeat/data/registry/filebeat' succeeded. Active transaction id=0
2021-11-17T02:37:50.061Z        INFO    memlog/store.go:124     Finished loading transaction log file for '/usr/share/filebeat/data/registry/filebeat'. Active transaction id=0
2021-11-17T02:37:50.061Z        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.
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform request:append
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform request:delete
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform request:set
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform response:append
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform response:delete
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform response:set
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform pagination:append
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform pagination:delete
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/transform_registry.go:75     Register transform pagination:set
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/encoding.go:80       <nil>
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/encoding.go:81       <nil>
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/encoding.go:86       <nil>
2021-11-17T02:37:50.061Z        DEBUG   [httpjson.transforms]   v2/encoding.go:87       <nil>
2021-11-17T02:37:50.061Z        INFO    [registrar]     registrar/registrar.go:109      States Loaded from registrar: 0
2021-11-17T02:37:50.061Z        INFO    [crawler]       beater/crawler.go:71    Loading Inputs: 5
2021-11-17T02:37:50.061Z        DEBUG   [scanner]       filestream/fswatch.go:277       recursive glob enabled
2021-11-17T02:37:50.061Z        WARN    [cfgwarn]       filestream/prospector_creator.go:81     EXPERIMENTAL: rotation.external.copytruncate is used.
2021-11-17T02:37:50.061Z        DEBUG   [registrar]     registrar/registrar.go:140      Starting Registrar
2021-11-17T02:37:50.064Z        INFO    [crawler]       beater/crawler.go:141   Starting input (ID: 11831387867980648788)
2021-11-17T02:37:50.065Z        INFO    [input.filestream]      compat/compat.go:111    Input filestream starting      {"id": "A43188949EDA5154"}
2021-11-17T02:37:50.065Z        DEBUG   [scanner]       filestream/fswatch.go:277       recursive glob enabled
2021-11-17T02:37:50.065Z        DEBUG   [input.filestream]      filestream/copytruncate_prospector.go:220       Starting prospector     {"id": "A43188949EDA5154", "prospector": "copy_truncate_file_prospector"}
2021-11-17T02:37:50.065Z        INFO    [file_watcher]  filestream/fswatch.go:137       Start next scan
2021-11-17T02:37:50.068Z        INFO    [crawler]       beater/crawler.go:141   Starting input (ID: 17066447287241108748)
2021-11-17T02:37:50.068Z        DEBUG   [input.filestream]      filestream/copytruncate_prospector.go:268       A new file /var/log/pattern1.log has been found {"id": "A43188949EDA5154", "prospector": "copy_truncate_file_prospector", "operation": "create", "source_name": "native::4503599627818520-47", "os_id": "4503599627818520-47", "new_path": "/var/log/pattern1.log"}
2021-11-17T02:37:50.068Z        INFO    [input.filestream]      compat/compat.go:111    Input filestream starting      {"id": "ECD83362C5EF6D0C"}
2021-11-17T02:37:50.069Z        DEBUG   [input.filestream]      filestream/copytruncate_prospector.go:220       Starting prospector     {"id": "ECD83362C5EF6D0C", "prospector": "copy_truncate_file_prospector"}
2021-11-17T02:37:50.069Z        DEBUG   [input.filestream]      filestream/copytruncate_prospector.go:292       File /var/log/pattern1.log is original  {"id": "A43188949EDA5154", "prospector": "copy_truncate_file_prospector", "operation": "create", "source_name": "native::4503599627818520-47", "os_id": "4503599627818520-47", "new_path": "/var/log/pattern1.log"}
2021-11-17T02:37:50.069Z        DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "A43188949EDA5154", "source": "filestream::.global::native::4503599627818520-47"}
2021-11-17T02:37:50.069Z        DEBUG   [input.filestream]      filestream/copytruncate_prospector.go:268       A new file /var/log/pattern1.log.1 has been found       {"id": "A43188949EDA5154", "prospector": "copy_truncate_file_prospector", "operation": "create", "source_name": "native::12384898975378204-47", "os_id": "12384898975378204-47", "new_path": "/var/log/pattern1.log.1"}
2021-11-17T02:37:50.069Z        DEBUG   [input.filestream]      filestream/copytruncate_prospector.go:287       File /var/log/pattern1.log.1 is rotated {"id": "A43188949EDA5154", "prospector": "copy_truncate_file_prospector", "operation": "create", "source_name": "native::12384898975378204-47", "os_id": "12384898975378204-47", "new_path": "/var/log/pattern1.log.1"}
2021-11-17T02:37:50.069Z        DEBUG   [input.filestream]      input-logfile/harvester.go:225  Continue harvester for file prev=native::4503599627818520-47, next=native::12384898975378204-47 {"id": "A43188949EDA5154"}
panic: unlock on unlocked mutex

goroutine 99 [running]:
github.com/elastic/go-concert/unison.Mutex.Unlock(0xc000056780)
        /go/pkg/mod/github.com/elastic/go-concert@v0.2.0/unison/mutex.go:132 +0x65
github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.releaseResource(0xc0008c4160)
        /go/src/github.com/elastic/beats/filebeat/input/filestream/internal/input-logfile/harvester.go:296 +0x31
github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.(*defaultHarvesterGroup).Continue.func1(0x55a01a37f598, 0xc0008ac240, 0x0, 0x0)
        /go/src/github.com/elastic/beats/filebeat/input/filestream/internal/input-logfile/harvester.go:246 +0x37d
github.com/elastic/go-concert/unison.(*TaskGroup).Go.func1(0xc000b22048, 0xc000118140)
        /go/pkg/mod/github.com/elastic/go-concert@v0.2.0/unison/taskgroup.go:163 +0xb1
created by github.com/elastic/go-concert/unison.(*TaskGroup).Go
        /go/pkg/mod/github.com/elastic/go-concert@v0.2.0/unison/taskgroup.go:159 +0xdc

[elasticmachine]

Pinging @elastic/elastic-agent-data-plane (Team:Elastic-Agent-Data-Plane)

[DanielOliverRJ]

I can confirm we are also seeing this on logs with the following rotation configuration. It appears the reporter has provided a good way to reproduce, but happy to provide further reproduction details if required.

- type: filestream
  rotation.external.strategy.copytruncate:
    suffix_regex: __\d{4}-\d{2}-\d{2}_\d{2}-\d{2}-\d{2}
  paths: [/path/file-*.log]