search

elastic / beats

:tropical_fish: Beats - Lightweight shippers for Elasticsearch & Logstash
https://www.elastic.co/products/beats
Other
12.17k stars 4.92k forks source link

Spool to disk causes process to hang at start #9874

Closed andrewkroh closed 5 years ago

andrewkroh commented 5 years ago

When using the disk backed queue feature with Filebeat 6.6.0 the Beat is hanging at startup. I tried Filebeat 7.0.0 (filebeat version 7.0.0 (arm), libbeat 7.0.0 [e5afe891595c7d650b3620e03059e0a1e548cbd1 built 2018-12-28 23:39:49 +0000 UTC]) and it started up fine.

For confirmed bugs, please report:

{"level":"warn","timestamp":"2019-01-03T17:32:01.509Z","logger":"cfgwarn","caller":"spool/module.go:43","message":"BETA: Spooling to disk is beta"}
^\SIGQUIT: quit
PC=0x5649b0 m=0 sigcode=128

goroutine 0 [idle]:
runtime.futex(0x177c1b8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x177c1b8, 0x0, 0x0, 0x53c594, ...)
    /usr/local/go/src/runtime/sys_linux_arm.s:266 +0x1c
runtime.futexsleep(0x177c1b8, 0x0, 0xffffffff, 0xffffffff)
    /usr/local/go/src/runtime/os_linux.go:45 +0x74
runtime.notesleep(0x177c1b8)
    /usr/local/go/src/runtime/lock_futex.go:151 +0xac
runtime.stopm()
    /usr/local/go/src/runtime/proc.go:1952 +0xac
runtime.findrunnable(0x12344600, 0x0)
    /usr/local/go/src/runtime/proc.go:2415 +0x378
runtime.schedule()
    /usr/local/go/src/runtime/proc.go:2541 +0x110
runtime.goexit0(0x124a1dc0)
    /usr/local/go/src/runtime/proc.go:2713 +0x1e0
runtime.mcall(0x0)
    /usr/local/go/src/runtime/asm_arm.s:285 +0x5c

goroutine 1 [semacquire]:
sync.runtime_SemacquireMutex(0x12690030, 0x97100)
    /usr/local/go/src/runtime/sema.go:71 +0x2c
sync.(*Mutex).Lock(0x1269002c)
    /usr/local/go/src/sync/mutex.go:134 +0x168
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*reservedLock).Lock(0x1269001c)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/lock.go:104 +0x24
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).Close(0x12690000, 0x0, 0x0)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:239 +0xf8
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).Close-fm(0x0, 0x5098ac)
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/spool.go:111 +0x1c
github.com/elastic/beats/libbeat/publisher/queue/spool.ignoreErr.func1()
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/spool.go:248 +0x1c
github.com/elastic/beats/libbeat/publisher/queue/spool.ifNotOK(0x127a775c, 0x12781998)
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/spool.go:243 +0x30
panic(0xf5c1f0, 0x168cbd0)
    /usr/local/go/src/runtime/panic.go:502 +0x204
sync/atomic.addUint64(0x12690864, 0x1, 0x0, 0x1, 0x1)
    /usr/local/go/src/sync/atomic/64bit_arm.go:31 +0x4c
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).beginTx(0x12690000, 0x0, 0x0, 0x0, 0x0, 0x8, 0x1)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:303 +0x114
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).BeginWith(0x12690000, 0x12350000, 0x0, 0x0, 0x1, 0x12350a00, 0x76d3d364)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:287 +0x3c
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).Begin(0x12690000, 0x1276e474, 0xd6ec80, 0x1276e46c)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:275 +0x38
github.com/elastic/beats/vendor/github.com/elastic/go-txfile/pq.NewStandaloneDelegate(0x12690000, 0x0, 0x0, 0x0, 0x0)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/pq/delegate.go:59 +0x30
github.com/elastic/beats/libbeat/publisher/queue/spool.NewSpool(0x1147548, 0x12780750, 0x123aa900, 0x1b, 0x180, 0x0, 0x0, 0x6400000, 0x0, 0x1000, ...)
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/spool.go:113 +0x2ac
github.com/elastic/beats/libbeat/publisher/queue/spool.create(0x113c940, 0x124b8118, 0x12780750, 0x12785620, 0xf47c30, 0x101e210, 0x12657e00, 0x743c99a8)
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/module.go:65 +0x1b0
github.com/elastic/beats/libbeat/publisher/pipeline.createQueueBuilder.func1(0x113c940, 0x124b8118, 0x1276efc0, 0x743c99a8, 0x1276efc0, 0x127af440)
    /go/src/github.com/elastic/beats/libbeat/publisher/pipeline/module.go:192 +0x40
github.com/elastic/beats/libbeat/publisher/pipeline.New(0x105515d, 0x8, 0x105515d, 0x8, 0x1050a08, 0x5, 0x12656d10, 0xb, 0x12656d10, 0xb, ...)
    /go/src/github.com/elastic/beats/libbeat/publisher/pipeline/pipeline.go:191 +0x230
github.com/elastic/beats/libbeat/publisher/pipeline.Load(0x105515d, 0x8, 0x105515d, 0x8, 0x1050a08, 0x5, 0x12656d10, 0xb, 0x12656d10, 0xb, ...)
    /go/src/github.com/elastic/beats/libbeat/publisher/pipeline/module.go:105 +0x4b0
github.com/elastic/beats/libbeat/cmd/instance.(*Beat).createBeater(0x1267ea20, 0x10b1c8c, 0x0, 0x105515d, 0x8, 0x0)
    /go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:315 +0x2f4
github.com/elastic/beats/libbeat/cmd/instance.(*Beat).launch(0x1267ea20, 0x105515d, 0x8, 0x105515d, 0x8, 0x0, 0x0, 0x0, 0x0, 0x12448900, ...)
    /go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:358 +0x12c
github.com/elastic/beats/libbeat/cmd/instance.Run.func1(0x105515d, 0x8, 0x105515d, 0x8, 0x0, 0x0, 0x105515d, 0x8, 0x105515d, 0x8, ...)
    /go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:184 +0x4e8
github.com/elastic/beats/libbeat/cmd/instance.Run(0x105515d, 0x8, 0x105515d, 0x8, 0x0, 0x0, 0x0, 0x0, 0x12448900, 0x0, ...)
    /go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:185 +0x58
github.com/elastic/beats/libbeat/cmd.genRunCmd.func1(0x12612a00, 0x124af810, 0x0, 0xd)
    /go/src/github.com/elastic/beats/libbeat/cmd/run.go:37 +0x30
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).execute(0x12612a00, 0x123ae008, 0xd, 0xd, 0x12612a00, 0x123ae008)
    /go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:704 +0x210
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0x12612a00, 0x12612a00, 0x105515d, 0x0)
    /go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:785 +0x1f8
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).Execute(0x12612a00, 0x0, 0x12396030)
    /go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:738 +0x1c
main.main()
    /go/src/github.com/elastic/beats/x-pack/filebeat/main.go:22 +0x24

goroutine 36 [syscall]:
os/signal.signal_recv(0x563e2c)
    /usr/local/go/src/runtime/sigqueue.go:139 +0x130
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:22 +0x14
created by os/signal.init.0
    /usr/local/go/src/os/signal/signal_unix.go:28 +0x30

goroutine 93 [semacquire]:
sync.runtime_notifyListWait(0x124e4128, 0x0)
    /usr/local/go/src/runtime/sema.go:510 +0x13c
sync.(*Cond).Wait(0x124e4120)
    /usr/local/go/src/sync/cond.go:56 +0x6c
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*writer).nextCommand(0x1269004c, 0x12570000, 0x400, 0x400, 0x0, 0x0, 0x509800, 0x518200)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/write.go:217 +0x100
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*writer).Run(0x1269004c, 0x10b2f78, 0x1269003c, 0x126701e0)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/write.go:149 +0x21c
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.newFile.func1(0x12690000)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:203 +0x4c
created by github.com/elastic/beats/vendor/github.com/elastic/go-txfile.newFile
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:201 +0x310

trap    0x0
error   0x0
oldmask 0x0
r0      0x177c1b8
r1      0x0
r2      0x0
r3      0x0
r4      0x0
r5      0x0
r6      0x3
r7      0xf0
r8      0x53f0a17f
r9      0x124a1e88
r10     0x177bcc8
fp      0x0
ip      0x126617d3
sp      0x7eb92434
lr      0x53395c
pc      0x5649b0
cpsr    0x20000010
fault   0x0
andrewkroh commented 5 years ago

@urso I built a version of filebeat with tracing enabled and ran it.

$ ./filebeat -E queue.spool.size=5MiB -e -d '*'
2019-01-19T16:21:17.001Z    INFO    instance/beat.go:616    Home path: [/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7] Config path: [/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7] Data path: [/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data] Logs path: [/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/logs]
2019-01-19T16:21:17.001Z    DEBUG   [beat]  instance/beat.go:653    Beat metadata path: /home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data/meta.json
2019-01-19T16:21:17.014Z    INFO    instance/beat.go:623    Beat UUID: 536c94e0-9d3e-445d-aa05-49ed87742d73
2019-01-19T16:21:17.014Z    DEBUG   [seccomp]   seccomp/seccomp.go:109  Loading syscall filter  {"seccomp_filter": {"no_new_privs":true,"flag":"tsync","policy":{"default_action":"allow","syscalls":[{"names":["execve","execveat","fork","vfork"],"action":"errno"}]}}}
2019-01-19T16:21:17.015Z    INFO    [seccomp]   seccomp/seccomp.go:116  Syscall filter successfully installed
2019-01-19T16:21:17.015Z    INFO    [beat]  instance/beat.go:936    Beat info   {"system_info": {"beat": {"path": {"config": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7", "data": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data", "home": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7", "logs": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/logs"}, "type": "filebeat", "uuid": "536c94e0-9d3e-445d-aa05-49ed87742d73"}}}
2019-01-19T16:21:17.015Z    INFO    [beat]  instance/beat.go:945    Build info  {"system_info": {"build": {"commit": "6be849dc5e2d4b232cdc1401319461676539ccc2", "libbeat": "6.7.0", "time": "2019-01-19T16:17:50.000Z", "version": "6.7.0"}}}
2019-01-19T16:21:17.015Z    INFO    [beat]  instance/beat.go:948    Go runtime info {"system_info": {"go": {"os":"linux","arch":"arm","max_procs":4,"version":"go1.10.7"}}}
2019-01-19T16:21:17.020Z    INFO    [beat]  instance/beat.go:952    Host info   {"system_info": {"host": {"architecture":"armv7l","boot_time":"2018-12-03T23:19:23Z","containerized":false,"name":"raspberrypi","ip":[],"kernel_version":"4.14.50-v7+","mac":[],"os":{"family":"","platform":"raspbian","name":"Raspbian GNU/Linux","version":"9 (stretch)","major":9,"minor":0,"patch":0,"codename":"stretch"},"timezone":"UTC","timezone_offset_sec":0,"id":""}}}
2019-01-19T16:21:17.029Z    INFO    [beat]  instance/beat.go:981    Process info    {"system_info": {"process": {"capabilities": {"inheritable":null,"permitted":null,"effective":null,"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","audit_read"],"ambient":null}, "cwd": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7", "exe": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/filebeat", "name": "filebeat", "pid": 18291, "ppid": 18253, "seccomp": {"mode":"filter","no_new_privs":true}, "start_time": "2019-01-19T16:21:16.520Z"}}}
2019-01-19T16:21:17.033Z    INFO    instance/beat.go:281    Setup Beat: filebeat; Version: 6.7.0
2019-01-19T16:21:17.033Z    DEBUG   [beat]  instance/beat.go:302    Initializing output plugins
2019-01-19T16:21:17.039Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:160    add_cloud_metadata: starting to fetch metadata, timeout=3s
2019-01-19T16:21:17.049Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:192    add_cloud_metadata: received disposition for qcloud after 9.301472ms. result=[provider:qcloud, error=failed requesting qcloud metadata: Get http://metadata.tencentyun.com/meta-data/placement/region: dial tcp: lookup metadata.tencentyun.com on xx:53: no such host, metadata={}]
2019-01-19T16:21:20.040Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:192    add_cloud_metadata: received disposition for gce after 3.000977179s. result=[provider:gce, error=failed requesting gce metadata: Get http://169.254.169.254/computeMetadata/v1/?recursive=true&alt=json: dial tcp 169.254.169.254:80: i/o timeout, metadata={}]
2019-01-19T16:21:20.041Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:192    add_cloud_metadata: received disposition for ec2 after 3.001390764s. result=[provider:ec2, error=failed requesting ec2 metadata: Get http://169.254.169.254/2014-02-25/dynamic/instance-identity/document: dial tcp 169.254.169.254:80: i/o timeout, metadata={}]
2019-01-19T16:21:20.041Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:192    add_cloud_metadata: received disposition for digitalocean after 3.001645134s. result=[provider:digitalocean, error=failed requesting digitalocean metadata: Get http://169.254.169.254/metadata/v1.json: dial tcp 169.254.169.254:80: i/o timeout, metadata={}]
2019-01-19T16:21:20.041Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:199    add_cloud_metadata: timed-out waiting for all responses
2019-01-19T16:21:20.041Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:163    add_cloud_metadata: fetchMetadata ran for 3.002015178s
2019-01-19T16:21:20.041Z    INFO    add_cloud_metadata/add_cloud_metadata.go:319    add_cloud_metadata: hosting provider type not detected.
2019-01-19T16:21:20.041Z    DEBUG   [processors]    processors/processor.go:66  Processors: add_host_metadata=[netinfo.enabled=[false], cache.ttl=[5m0s]], add_cloud_metadata=null
2019-01-19T16:21:20.043Z    INFO    elasticsearch/client.go:165 Elasticsearch url: http://localhost:9200
2019-01-19T16:21:20.044Z    WARN    [cfgwarn]   spool/module.go:43  BETA: Spooling to disk is beta
open file: 0x12d44000 (/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data/spool.dat)
meta page:
    version: 1
    pagesize: 4096
    maxsize: 104857600
    root: 0
    txid: 1
    freelist: 0
    wal: 0
    data end: 2
    meta end: 0
async writer: wait next command
    meta total: 0
    checksum: 3039294656
request new transaction (readonly: false)
init new transaction (readonly: false)
start file shutdown: 0x12d44000
^\SIGQUIT: quit
PC=0x566e1c m=0 sigcode=128

goroutine 0 [idle]:
runtime.futex(0x17871e8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x17871e8, 0x0, 0x0, 0x53ea00, ...)
    /usr/local/go/src/runtime/sys_linux_arm.s:266 +0x1c
runtime.futexsleep(0x17871e8, 0x0, 0xffffffff, 0xffffffff)
    /usr/local/go/src/runtime/os_linux.go:45 +0x74
runtime.notesleep(0x17871e8)
    /usr/local/go/src/runtime/lock_futex.go:151 +0xac
runtime.stopm()
    /usr/local/go/src/runtime/proc.go:1952 +0xac
runtime.findrunnable(0x12b47300, 0x0)
    /usr/local/go/src/runtime/proc.go:2415 +0x378
runtime.schedule()
    /usr/local/go/src/runtime/proc.go:2541 +0x110
runtime.park_m(0x12b000e0)
    /usr/local/go/src/runtime/proc.go:2604 +0x90
runtime.mcall(0x0)
    /usr/local/go/src/runtime/asm_arm.s:285 +0x5c

goroutine 1 [semacquire]:
sync.runtime_SemacquireMutex(0x12d44030, 0xe5600)
    /usr/local/go/src/runtime/sema.go:71 +0x2c
sync.(*Mutex).Lock(0x12d4402c)
    /usr/local/go/src/sync/mutex.go:134 +0x168
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*reservedLock).Lock(0x12d4401c)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/lock.go:104 +0x24
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).Close(0x12d44000, 0x0, 0x0)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:239 +0x120
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).Close-fm(0x4, 0x50bd18)
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/spool.go:111 +0x1c
github.com/elastic/beats/libbeat/publisher/queue/spool.ignoreErr.func1()
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/spool.go:248 +0x1c
github.com/elastic/beats/libbeat/publisher/queue/spool.ifNotOK(0x12fb175c, 0x12c2e1c0)
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/spool.go:243 +0x30
panic(0xf641b8, 0x1697bd0)
    /usr/local/go/src/runtime/panic.go:502 +0x204
sync/atomic.addUint64(0x12d44864, 0x1, 0x0, 0x1, 0x1)
    /usr/local/go/src/sync/atomic/64bit_arm.go:31 +0x4c
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).beginTx(0x12d44000, 0x0, 0x0, 0x0, 0x12fb1600, 0x8, 0x1)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:303 +0x140
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).BeginWith(0x12d44000, 0x12b50000, 0x0, 0x0, 0x12d44000, 0x12b54f00, 0x76db86c8)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:287 +0x3c
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*File).Begin(0x12d44000, 0x12d3c324, 0xd74e60, 0x12d3c31c)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:275 +0x38
github.com/elastic/beats/vendor/github.com/elastic/go-txfile/pq.NewStandaloneDelegate(0x12d44000, 0x0, 0x0, 0x0, 0x0)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/pq/delegate.go:59 +0x30
github.com/elastic/beats/libbeat/publisher/queue/spool.NewSpool(0x1150338, 0x12fc03f0, 0x12d112c0, 0x3e, 0x180, 0x0, 0x0, 0x6400000, 0x0, 0x1000, ...)
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/spool.go:113 +0x2ac
github.com/elastic/beats/libbeat/publisher/queue/spool.create(0x11456c8, 0x12c7c118, 0x12fc03f0, 0x12f43640, 0xf4f9d0, 0x1026880, 0x12d12700, 0x711c0418)
    /go/src/github.com/elastic/beats/libbeat/publisher/queue/spool/module.go:65 +0x1b0
github.com/elastic/beats/libbeat/publisher/pipeline.createQueueBuilder.func1(0x11456c8, 0x12c7c118, 0x12fc48d0, 0x711c0418, 0x12fc48d0, 0x12caeb20)
    /go/src/github.com/elastic/beats/libbeat/publisher/pipeline/module.go:192 +0x40
github.com/elastic/beats/libbeat/publisher/pipeline.New(0x105d814, 0x8, 0x105d814, 0x8, 0x10590b9, 0x5, 0x12e1ee30, 0xb, 0x12e1ee30, 0xb, ...)
    /go/src/github.com/elastic/beats/libbeat/publisher/pipeline/pipeline.go:191 +0x230
github.com/elastic/beats/libbeat/publisher/pipeline.Load(0x105d814, 0x8, 0x105d814, 0x8, 0x10590b9, 0x5, 0x12e1ee30, 0xb, 0x12e1ee30, 0xb, ...)
    /go/src/github.com/elastic/beats/libbeat/publisher/pipeline/module.go:105 +0x4b0
github.com/elastic/beats/libbeat/cmd/instance.(*Beat).createBeater(0x12e3ac60, 0x10ba75c, 0x0, 0x105d814, 0x8, 0x0)
    /go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:315 +0x2f4
github.com/elastic/beats/libbeat/cmd/instance.(*Beat).launch(0x12e3ac60, 0x105d814, 0x8, 0x105d814, 0x8, 0x0, 0x0, 0x0, 0x0, 0x12c36b00, ...)
    /go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:358 +0x12c
github.com/elastic/beats/libbeat/cmd/instance.Run.func1(0x105d814, 0x8, 0x105d814, 0x8, 0x0, 0x0, 0x105d814, 0x8, 0x105d814, 0x8, ...)
    /go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:184 +0x4e8
github.com/elastic/beats/libbeat/cmd/instance.Run(0x105d814, 0x8, 0x105d814, 0x8, 0x0, 0x0, 0x0, 0x0, 0x12c36b00, 0x0, ...)
    /go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:185 +0x58
github.com/elastic/beats/libbeat/cmd.genRunCmd.func1(0x12de4c80, 0x12d3d7d0, 0x0, 0x5)
    /go/src/github.com/elastic/beats/libbeat/cmd/run.go:37 +0x30
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).execute(0x12de4c80, 0x12b36038, 0x5, 0x5, 0x12de4c80, 0x12b36038)
    /go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:704 +0x210
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0x12de4c80, 0x12de4c80, 0x105d814, 0x0)
    /go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:785 +0x1f8
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).Execute(0x12de4c80, 0x0, 0x12b420b0)
    /go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:738 +0x1c
main.main()
    /go/src/github.com/elastic/beats/x-pack/filebeat/main.go:22 +0x24

goroutine 37 [syscall]:
os/signal.signal_recv(0x0)
    /usr/local/go/src/runtime/sigqueue.go:139 +0x130
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:22 +0x14
created by os/signal.init.0
    /usr/local/go/src/os/signal/signal_unix.go:28 +0x30

goroutine 28 [semacquire]:
sync.runtime_notifyListWait(0x12caf828, 0x0)
    /usr/local/go/src/runtime/sema.go:510 +0x13c
sync.(*Cond).Wait(0x12caf820)
    /usr/local/go/src/sync/cond.go:56 +0x6c
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*writer).nextCommand(0x12d4404c, 0x12f16000, 0x400, 0x400, 0x0, 0x0, 0x50bd00, 0x51a900)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/write.go:217 +0x124
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.(*writer).Run(0x12d4404c, 0x10bba4c, 0x12d4403c, 0x12c389e0)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/write.go:149 +0x2f4
github.com/elastic/beats/vendor/github.com/elastic/go-txfile.newFile.func1(0x12d44000)
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:203 +0x4c
created by github.com/elastic/beats/vendor/github.com/elastic/go-txfile.newFile
    /go/src/github.com/elastic/beats/vendor/github.com/elastic/go-txfile/file.go:201 +0x310

trap    0x0
error   0x0
oldmask 0x0
r0      0x17871e8
r1      0x0
r2      0x0
r3      0x0
r4      0x0
r5      0x0
r6      0x3
r7      0xf0
r8      0xe030ab38
r9      0x1
r10     0x1786cf8
fp      0x0
ip      0x30
sp      0x7eeb5468
lr      0x535dc8
pc      0x566e1c
cpsr    0x20000010
fault   0x0
andrewkroh commented 5 years ago

I tested with a patch similar to https://github.com/elastic/go-txfile/pull/31 and Filebeat starts up successfully. 😄 Thanks @urso 

diff --git a/dev-tools/mage/build.go b/dev-tools/mage/build.go
index 86bd42093..cdaede088 100644
--- a/dev-tools/mage/build.go
+++ b/dev-tools/mage/build.go
@@ -51,6 +51,7 @@ func DefaultBuildArgs() BuildArgs {
                        "github.com/elastic/beats/libbeat/version.buildTime": "{{ date }}",
                        "github.com/elastic/beats/libbeat/version.commit":    "{{ commit }}",
                },
+               ExtraFlags: []string{"-tags=tracing"},
        }

        repo, err := GetProjectRepoInfo()
diff --git a/vendor/github.com/elastic/go-txfile/file.go b/vendor/github.com/elastic/go-txfile/file.go
index e714df851..1669b7b37 100644
--- a/vendor/github.com/elastic/go-txfile/file.go
+++ b/vendor/github.com/elastic/go-txfile/file.go
@@ -36,6 +36,10 @@ import (
 // pages of type PageSize. Pages within the file are only accessible by page IDs
 // from within active transactions.
 type File struct {
+       // Atomic fields.
+       // Do not move: Must be 64bit-word aligned on some architectures.
+       txids uint64
+
        path      string
        readonly  bool
        file      vfs.File
@@ -52,8 +56,6 @@ type File struct {
        // meta pages
        meta       [2]*metaPage
        metaActive int
-
-       txids uint64
 }

 // internal contants
@@ -296,13 +298,22 @@ func (f *File) beginTx(settings TxOptions) (*Tx, reason) {
        }

        tracef("request new transaction (readonly: %v)\n", settings.Readonly)
+
+       // Acquire transaction log.
+       // Unlock on panic, so applications will not be blocked in case they try to
+       // defer some close operations on the file.
+       ok := false
        lock := f.locks.TxLock(settings.Readonly)
        lock.Lock()
-       tracef("init new transaction (readonly: %v)\n", settings.Readonly)
+       defer cleanup.IfNot(&ok, lock.Unlock)

        txid := atomic.AddUint64(&f.txids, 1)
+
+       tracef("init new transaction (readonly: %v)\n", settings.Readonly)
        tx := newTx(f, txid, lock, settings)
        tracef("begin transaction: %p (readonly: %v)\n", tx, settings.Readonly)
+
+       ok = true
        return tx, nil
 }
$ ./filebeat -E queue.spool.size=5MiB -e -d '*'
2019-01-20T13:54:14.831Z    INFO    instance/beat.go:616    Home path: [/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7] Config path: [/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7] Data path: [/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data] Logs path: [/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/logs]
2019-01-20T13:54:14.831Z    DEBUG   [beat]  instance/beat.go:653    Beat metadata path: /home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data/meta.json
2019-01-20T13:54:14.866Z    INFO    instance/beat.go:623    Beat UUID: 96683e05-0fca-4a90-bcdc-f4aefaffa694
2019-01-20T13:54:14.866Z    DEBUG   [seccomp]   seccomp/seccomp.go:109  Loading syscall filter  {"seccomp_filter": {"no_new_privs":true,"flag":"tsync","policy":{"default_action":"allow","syscalls":[{"names":["execve","execveat","fork","vfork"],"action":"errno"}]}}}
2019-01-20T13:54:14.867Z    INFO    [seccomp]   seccomp/seccomp.go:116  Syscall filter successfully installed
2019-01-20T13:54:14.867Z    INFO    [beat]  instance/beat.go:936    Beat info   {"system_info": {"beat": {"path": {"config": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7", "data": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data", "home": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7", "logs": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/logs"}, "type": "filebeat", "uuid": "96683e05-0fca-4a90-bcdc-f4aefaffa694"}}}
2019-01-20T13:54:14.867Z    INFO    [beat]  instance/beat.go:945    Build info  {"system_info": {"build": {"commit": "6be849dc5e2d4b232cdc1401319461676539ccc2", "libbeat": "6.7.0", "time": "2019-01-20T13:51:01.000Z", "version": "6.7.0"}}}
2019-01-20T13:54:14.867Z    INFO    [beat]  instance/beat.go:948    Go runtime info {"system_info": {"go": {"os":"linux","arch":"arm","max_procs":4,"version":"go1.10.7"}}}
2019-01-20T13:54:14.871Z    INFO    [beat]  instance/beat.go:952    Host info   {"system_info": {"host": {"architecture":"armv7l","boot_time":"2018-12-03T23:19:23Z","containerized":false,"name":"raspberrypi","ip":[],"kernel_version":"4.14.50-v7+","mac":[],"os":{"family":"","platform":"raspbian","name":"Raspbian GNU/Linux","version":"9 (stretch)","major":9,"minor":0,"patch":0,"codename":"stretch"},"timezone":"UTC","timezone_offset_sec":0,"id":"x"}}}
2019-01-20T13:54:14.874Z    INFO    [beat]  instance/beat.go:981    Process info    {"system_info": {"process": {"capabilities": {"inheritable":null,"permitted":null,"effective":null,"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","audit_read"],"ambient":null}, "cwd": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7", "exe": "/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/filebeat", "name": "filebeat", "pid": 20418, "ppid": 20391, "seccomp": {"mode":"filter","no_new_privs":true}, "start_time": "2019-01-20T13:54:14.310Z"}}}
2019-01-20T13:54:14.875Z    INFO    instance/beat.go:281    Setup Beat: filebeat; Version: 6.7.0
2019-01-20T13:54:14.875Z    DEBUG   [beat]  instance/beat.go:302    Initializing output plugins
2019-01-20T13:54:14.879Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:160    add_cloud_metadata: starting to fetch metadata, timeout=3s
2019-01-20T13:54:15.300Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:192    add_cloud_metadata: received disposition for qcloud after 421.076245ms. result=[provider:qcloud, error=failed requesting qcloud metadata: Get http://metadata.tencentyun.com/meta-data/instance-id: dial tcp: lookup metadata.tencentyun.com on x:53: no such host, metadata={}]
2019-01-20T13:54:17.879Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:199    add_cloud_metadata: timed-out waiting for all responses
2019-01-20T13:54:17.880Z    DEBUG   [filters]   add_cloud_metadata/add_cloud_metadata.go:163    add_cloud_metadata: fetchMetadata ran for 3.000893523s
2019-01-20T13:54:17.880Z    INFO    add_cloud_metadata/add_cloud_metadata.go:319    add_cloud_metadata: hosting provider type not detected.
2019-01-20T13:54:17.880Z    DEBUG   [processors]    processors/processor.go:66  Processors: add_host_metadata=[netinfo.enabled=[false], cache.ttl=[5m0s]], add_cloud_metadata=null
2019-01-20T13:54:17.882Z    INFO    elasticsearch/client.go:165 Elasticsearch url: http://localhost:9200
2019-01-20T13:54:17.883Z    WARN    [cfgwarn]   spool/module.go:43  BETA: Spooling to disk is beta
open file: 0x12678000 (/home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data/spool.dat)
meta page:
    version: 1
    pagesize: 4096
    maxsize: 104857600
    root: 0
    txid: 1
    freelist: 0
    wal: 0
    data end: 2
    meta end: 0
    meta total: 0
    checksum: 3039294656
request new transaction (readonly: false)
init new transaction (readonly: false)
begin transaction: 0x126f0500 (readonly: false)
commit transaction: 0x126f0500
schedule write
async writer: wait next command
schedule sync
schedule write
schedule sync
check fsync:  2
outstanding: 1
async writer: received next command
writer message:  1 true false
write at(id=2, off=8192, len=4096)
done fsync
async writer: wait next command
check fsync:  1
outstanding: 1
async writer: received next command
writer message:  1 true false
write at(id=1, off=4096, len=84)
done fsync
async writer: wait next command
tx stats:
  available data pages: 25597
  available meta pages: 0
  total meta pages: 0
    freelist pages: 0
    wal mapping pages: 0
  max pages: 25600
  wal mapped pages: 0
meta page:
    version: 1
    pagesize: 4096
    maxsize: 104857600
    root: 2
    txid: 2
    freelist: 0
    wal: 0
    data end: 3
    meta end: 3
    meta total: 0
    checksum: 569006755
close transaction: 0x126f0500
request new transaction (readonly: true)
init new transaction (readonly: true)
begin transaction: 0x12344200 (readonly: true)
close transaction: 0x12344200
open queue: 0x1265a7c0 (pageSize: 4096)
queue header:
  version: 1
  head(0, 0)
  tail(0, 0)
  read(0, 0)
  data pages 0
request new transaction (readonly: true)
init new transaction (readonly: true)
begin transaction: 0x12344280 (readonly: true)
close transaction: 0x12344280
request new transaction (readonly: true)
init new transaction (readonly: true)
begin transaction: 0x12344300 (readonly: true)
close transaction: 0x12344300
2019-01-20T13:54:18.404Z    DEBUG   [publisher] spool/outbroker.go:149  start output ack loop
2019-01-20T13:54:18.404Z    DEBUG   [publisher] spool/inbroker.go:155   start flush ack loop
2019-01-20T13:54:18.404Z    INFO    [publisher] spool/inbroker.go:219   spool input eventloop start
2019-01-20T13:54:18.404Z    DEBUG   [publish]   pipeline/consumer.go:137    start pipeline event consumer
2019-01-20T13:54:18.405Z    INFO    [publisher] pipeline/module.go:110  Beat name: raspberrypi
2019-01-20T13:54:18.405Z    DEBUG   [publisher] spool/outbroker.go:212  outbroker (stateWaitEvents): waiting for new events
2019-01-20T13:54:18.408Z    INFO    instance/beat.go:403    filebeat start running.
2019-01-20T13:54:18.408Z    INFO    [monitoring]    log/log.go:117  Starting metrics logging every 30s
2019-01-20T13:54:18.408Z    INFO    registrar/registrar.go:97   No registry file found under: /home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data/registry. Creating a new registry file.
2019-01-20T13:54:18.409Z    DEBUG   [registrar] registrar/registrar.go:400  Write registry file: /home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data/registry
2019-01-20T13:54:18.474Z    DEBUG   [registrar] registrar/registrar.go:393  Registry file updated. 0 states written.
2019-01-20T13:54:18.475Z    INFO    registrar/registrar.go:134  Loading registrar data from /home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data/registry
2019-01-20T13:54:18.475Z    INFO    registrar/registrar.go:141  States Loaded from registrar: 0
2019-01-20T13:54:18.475Z    INFO    crawler/crawler.go:72   Loading Inputs: 1
2019-01-20T13:54:18.475Z    DEBUG   [registrar] registrar/registrar.go:267  Starting Registrar
2019-01-20T13:54:18.476Z    DEBUG   [cfgfile]   cfgfile/reload.go:118   Checking module configs from: /home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/modules.d/*.yml
2019-01-20T13:54:18.476Z    DEBUG   [cfgfile]   cfgfile/reload.go:132   Number of module configs found: 0
2019-01-20T13:54:18.476Z    INFO    crawler/crawler.go:106  Loading and starting Inputs completed. Enabled inputs: 0
2019-01-20T13:54:18.476Z    INFO    cfgfile/reload.go:150   Config reloader started
2019-01-20T13:54:18.477Z    DEBUG   [cfgfile]   cfgfile/reload.go:176   Scan for new config files
2019-01-20T13:54:18.477Z    DEBUG   [cfgfile]   cfgfile/reload.go:195   Number of module configs found: 0
2019-01-20T13:54:18.477Z    DEBUG   [reload]    cfgfile/list.go:62  Starting reload procedure, current runners: 0
2019-01-20T13:54:18.478Z    DEBUG   [reload]    cfgfile/list.go:80  Start list: 0, Stop list: 0
2019-01-20T13:54:18.478Z    INFO    cfgfile/reload.go:205   Loading of config files completed.
^C2019-01-20T13:54:29.666Z  DEBUG   [service]   service/service.go:50   Received sigterm/sigint, stopping
2019-01-20T13:54:29.666Z    INFO    beater/filebeat.go:442  Stopping filebeat
2019-01-20T13:54:29.667Z    INFO    crawler/crawler.go:139  Stopping Crawler
2019-01-20T13:54:29.667Z    INFO    crawler/crawler.go:149  Stopping 0 inputs
2019-01-20T13:54:29.667Z    INFO    cfgfile/reload.go:208   Dynamic config reloader stopped
2019-01-20T13:54:29.667Z    INFO    crawler/crawler.go:165  Crawler stopped
2019-01-20T13:54:29.667Z    INFO    registrar/registrar.go:356  Stopping Registrar
2019-01-20T13:54:29.667Z    INFO    registrar/registrar.go:282  Ending Registrar
2019-01-20T13:54:29.668Z    DEBUG   [registrar] registrar/registrar.go:400  Write registry file: /home/akroh/filebeat-6.7.0-SNAPSHOT-linux-armv7/data/registry
2019-01-20T13:54:32.258Z    DEBUG   [registrar] registrar/registrar.go:393  Registry file updated. 0 states written.
2019-01-20T13:54:32.271Z    INFO    [monitoring]    log/log.go:152  Total non-zero metrics  {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":90,"time":{"ms":92}},"total":{"ticks":180,"time":{"ms":185},"value":180},"user":{"ticks":90,"time":{"ms":93}}},"handles":{"limit":{"hard":1048576,"soft":1024},"open":6},"info":{"ephemeral_id":"16e6ab56-c00d-4553-9996-d10e1a0cddcd","uptime":{"ms":17482}},"memstats":{"gc_next":4194304,"memory_alloc":1589784,"memory_total":3415312,"rss":20537344}},"filebeat":{"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0},"reloads":1},"output":{"type":"elasticsearch"},"pipeline":{"clients":0,"events":{"active":0}}},"registrar":{"states":{"current":0},"writes":{"success":2,"total":2}},"system":{"cpu":{"cores":4},"load":{"1":0.14,"15":0.11,"5":0.15,"norm":{"1":0.035,"15":0.0275,"5":0.0375}}}}}}
2019-01-20T13:54:32.273Z    INFO    [monitoring]    log/log.go:153  Uptime: 17.496437014s
2019-01-20T13:54:32.273Z    INFO    [monitoring]    log/log.go:130  Stopping metrics logging.
2019-01-20T13:54:32.273Z    INFO    instance/beat.go:413    filebeat stopped.