Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Spool to disk causes process to hang at start #9874

Closed
andrewkroh opened this issue Jan 3, 2019 · 2 comments
Closed

Spool to disk causes process to hang at start #9874

andrewkroh opened this issue Jan 3, 2019 · 2 comments
Labels
libbeat

Comments

@andrewkroh
Copy link
Member

andrewkroh commented Jan 3, 2019 •
edited
Loading

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 [e5afe89 built 2018-12-28 23:39:49 +0000 UTC]) and it started up fine.

For confirmed bugs, please report:

queue:
  spool:
    size: 250 MiB
  • ./filebeat test config -e -d "*" or ./filebeat -e -d "*"
  • It will hang.
  • Dump stack. Ctrl+\
{"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
Copy link
Member Author

@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
Copy link
Member Author

I tested with a patch similar to elastic/go-txfile#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.

@urso urso mentioned this issue Jan 24, 2019
Merged
urso pushed a commit that referenced this issue Jan 27, 2019
Update go-txfile 0.0.6 (#10289)
0b8bdd5 
Closes: #9874
@urso urso mentioned this issue Jan 31, 2019
Merged
urso pushed a commit to urso/beats that referenced this issue Jan 31, 2019
Update go-txfile 0.0.6 (elastic#10289)
1ad9bc2 
Closes: elastic#9874
(cherry picked from commit 0b8bdd5)
urso pushed a commit that referenced this issue Feb 3, 2019
Update go-txfile 0.0.6 (#10289) (#10459)
c239964 
Closes: #9874
(cherry picked from commit 0b8bdd5)
@JohnLyman JohnLyman mentioned this issue Feb 8, 2019
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
libbeat
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@andrewkroh