Filebeat panic and exit?

filebeater · August 31, 2019, 12:49am

Hello, I got the following from stderr while running filebeat, and filebeat just exited.
any idea on why filebeat just dies?
thanks!
yan

goroutine 74 [select, 1 minutes]:
github.com/elastic/beats/filebeat/channel.(*subOutlet).OnEvent(0xc00030f830, 0xc6ba485ad0, 0xbf528e77afb98100)
/go/src/github.com/elastic/beats/filebeat/channel/util.go:93 +0x1d9
github.com/elastic/beats/filebeat/harvester.(*Forwarder).Send(0xc0001d3dc8, 0xc6ba485ad0, 0x0, 0x0)
/go/src/github.com/elastic/beats/filebeat/harvester/forwarder.go:50 +0x41
github.com/elastic/beats/filebeat/input/log.(*Harvester).sendEvent(0xc00019d900, 0xc6ba485ad0, 0xc0001d3dc8, 0x7)
/go/src/github.com/elastic/beats/filebeat/input/log/harvester.go:373 +0x77
github.com/elastic/beats/filebeat/input/log.(*Harvester).Run(0xc00019d900, 0x0, 0x0)
/go/src/github.com/elastic/beats/filebeat/input/log/harvester.go:341 +0x4a2
github.com/elastic/beats/filebeat/harvester.(*Registry).Start.func1(0xc000086c80, 0x1cc1760, 0xc00019d900)
/go/src/github.com/elastic/beats/filebeat/harvester/registry.go:96 +0x73
created by github.com/elastic/beats/filebeat/harvester.(*Registry).Start
/go/src/github.com/elastic/beats/filebeat/harvester/registry.go:90 +0x128

jsoriano · August 31, 2019, 12:23pm

Hi @filebeater,

Thanks for reporting this. What version of filebeat are you using? Could you share your configuration?

filebeater · September 3, 2019, 5:56pm

it is filebeat version 7.2 & 7.3.1. config file is copied below:

registry.flush: 1
queue.mem:
  events: 524288
  flush.min_events: 262144
  flush.timeout: 1s

filebeat.max_procs: 3

filebeat.inputs:
- type: log
  paths:
    - logs/reader-logs/*

  close_removed: true
  clean_removed: true
  symlinks: true

  multiline.pattern: '^[[:digit:]]{4,}[[:punct:]][[:digit:]]{2,}|^[I|W|E|F|D|T][[:digit:]]{4,}'
  multiline.negate: true
  multiline.match: after

output.kafka:
   hosts: ["kafka-logging-vip.prod.xxxx.com:16637"]
   topic: 'graph-log'
   partition.hash:
     hash: ['beat.hostname', 'source']
     random: true # if false non-hashable events will be dropped

   required_acks: 1
   compression: gzip
   max_message_bytes: 1000000
   ssl.certificate_authorities: ["/etc/riddler/ca-bundle.crt"]
   ssl.certificate: "/export/home../secure/identity.cert"
   ssl.key: "/export/home../secure/identity.key"
 
  bulk_max_size: 262144
  worker: 1
  client_id: in-beat-lor1-app042833
  channel_buffer_size: 26222400

jsoriano · September 4, 2019, 9:03am

@filebeater thanks, I have edit your last comment to reformat the configuration, you can use the preformatted text option (</>) from the toolbar to format configuration and logs next time.

Regarding the logs, could you paste the whole logs? The ones you posted don't seem to contain the original error.

filebeater · September 4, 2019, 6:35pm

I found out it is due to "run out of the memory", Here are the logs:

fatal error: runtime: out of memory

runtime stack:

runtime.throw(0x1ae16ae, 0x16)

/usr/local/go/src/runtime/panic.go:617 +0x72

runtime.sysMap(0xe988000000, 0x4000000, 0x2bece38)

/usr/local/go/src/runtime/mem_linux.go:170 +0xc7

runtime.(*mheap).sysAlloc(0x2bd38c0, 0xa2000, 0x2bd38d0, 0x51)

/usr/local/go/src/runtime/malloc.go:633 +0x1cd

runtime.(*mheap).grow(0x2bd38c0, 0x51, 0x0)

/usr/local/go/src/runtime/mheap.go:1232 +0x42

runtime.(*mheap).allocSpanLocked(0x2bd38c0, 0x51, 0x2bece48, 0x2bd38d0)

/usr/local/go/src/runtime/mheap.go:1150 +0x3a7

runtime.(*mheap).alloc_m(0x2bd38c0, 0x51, 0x7f868d5a0100, 0x7f868d5aaa88)

/usr/local/go/src/runtime/mheap.go:977 +0xc2

runtime.(*mheap).alloc.func1()

/usr/local/go/src/runtime/mheap.go:1048 +0x4c

runtime.(*mheap).alloc(0x2bd38c0, 0x51, 0x7f87d3010100, 0xc3c5adc300)

/usr/local/go/src/runtime/mheap.go:1047 +0x8a

runtime.largeAlloc(0xa0510, 0xc406a10001, 0x1)

/usr/local/go/src/runtime/malloc.go:1055 +0x99

runtime.mallocgc.func1()

/usr/local/go/src/runtime/malloc.go:950 +0x46

runtime.systemstack(0x0)

/usr/local/go/src/runtime/asm_amd64.s:351 +0x66

runtime.mstart()

/usr/local/go/src/runtime/proc.go:1153

goroutine 580 [running]:

runtime.systemstack_switch()

/usr/local/go/src/runtime/asm_amd64.s:311 fp=0xc0038c56f8 sp=0xc0038c56f0 pc=0xb16040

runtime.mallocgc(0xa0510, 0x1989580, 0xe97ee4f701, 0x0)

/usr/local/go/src/runtime/malloc.go:949 +0x872 fp=0xc0038c5798 sp=0xc0038c56f8 pc=0xac7052

runtime.newobject(0x1989580, 0xc0038c5800)

/usr/local/go/src/runtime/malloc.go:1068 +0x38 fp=0xc0038c57c8 sp=0xc0038c5798 pc=0xac7358

compress/flate.NewWriter(0x1c9ff80, 0xe986d365d0, 0x4, 0xa, 0xa, 0x0)

/usr/local/go/src/compress/flate/deflate.go:667 +0x31 fp=0xc0038c5810 sp=0xc0038c57c8 pc=0xe3fe01

compress/gzip.(*Writer).Write(0xe987900d10, 0xe98746aa80, 0xa67, 0xa67, 0x0, 0x0, 0x14acc34)

/usr/local/go/src/compress/gzip/gzip.go:191 +0x2f7 fp=0xc0038c5860 sp=0xc0038c5810 pc=0xe4a247

github.com/elastic/beats/vendor/github.com/Shopify/sarama.compress(0x1ca3301, 0x4, 0xe98746aa80, 0xa67, 0xa67, 0x0, 0x0, 0x0, 0x0, 0x0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/compress.go:47 +0x1e6 fp=0xc0038c5910 sp=0xc0038c5860 pc=0x14a1376

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*RecordBatch).encodeRecords(0xe97c24bb80, 0x1cea400, 0xe981955f20, 0x0, 0x0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/record_batch.go:194 +0xf1 fp=0xc0038c5980 sp=0xc0038c5910 pc=0x14c6711

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*RecordBatch).encode(0xe97c24bb80, 0x1cea400, 0xe981955f20, 0x193fb20, 0xe97df19c50)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/record_batch.go:81 +0x374 fp=0xc0038c59e8 sp=0xc0038c5980 pc=0x14c5c64

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*Records).encode(0xc0038c5b10, 0x1cea400, 0xe981955f20, 0x0, 0x0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/records.go:63 +0xc4 fp=0xc0038c5a50 sp=0xc0038c59e8 pc=0x14c69a4

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*ProduceRequest).encode(0xe981955ee0, 0x1cea400, 0xe981955f20, 0x0, 0x0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/produce_request.go:106 +0x2a4 fp=0xc0038c5bf8 sp=0xc0038c5a50 pc=0x14be444

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*request).encode(0xe986d365a0, 0x1cea400, 0xe981955f20, 0xe97f310d20, 0xf0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/request.go:32 +0x13c fp=0xc0038c5c30 sp=0xc0038c5bf8 pc=0x14c75cc

github.com/elastic/beats/vendor/github.com/Shopify/sarama.encode(0x1ca1080, 0xe986d365a0, 0x1cdd0c0, 0xc0002a21b0, 0x0, 0xb, 0x0, 0x0, 0xc0038c5d01)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/encoder_decoder.go:24 +0x90 fp=0xc0038c5ca8 sp=0xc0038c5c30 pc=0x14acaa0

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*Broker).send(0xc002d81080, 0x1cd2260, 0xe981955ee0, 0xe981955f01, 0x0, 0x0, 0x0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/broker.go:581 +0x26b fp=0xc0038c5e00 sp=0xc0038c5ca8 pc=0x149829b

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*Broker).sendAndReceive(0xc002d81080, 0x1cd2260, 0xe981955ee0, 0x1ca1000, 0xe981955f00, 0x2000107, 0x0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/broker.go:612 +0x72 fp=0xc0038c5ee8 sp=0xc0038c5e00 pc=0x14987c2

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*Broker).Produce(0xc002d81080, 0xe981955ee0, 0xe979057601, 0x0, 0x0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/broker.go:278 +0xe8 fp=0xc0038c5f38 sp=0xc0038c5ee8 pc=0x1496bb8

github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*asyncProducer).newBrokerProducer.func1()

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/async_producer.go:629 +0xb1 fp=0xc0038c5fb8 sp=0xc0038c5f38 pc=0x14cbe71

github.com/elastic/beats/vendor/github.com/Shopify/sarama.withRecover(0xc3c5f36da0)

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/utils.go:45 +0x43 fp=0xc0038c5fd8 sp=0xc0038c5fb8 pc=0x14ca863

runtime.goexit()

/usr/local/go/src/runtime/asm_amd64.s:1337 +0x1 fp=0xc0038c5fe0 sp=0xc0038c5fd8 pc=0xb18111

created by github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*asyncProducer).newBrokerProducer

/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/async_producer.go:625 +0x1f6

filebeater · September 4, 2019, 6:43pm

One thing We find really surprising is that: filebeat consumed much more memory than expected:
we set "channel_buffer_size: 26222400" and we have 512 kafka partitions, which is ~13G in total,
however, it consumes up to 91G runtime: It quickly ramped up to using 91G of memory in a couple of minutes after filebeat restarted. BEATSVERSION=7.3.1 GOVERSION=1.12.9.
hmm, looking up filebeat documentation again, I am confused whether channel_buffer_size is per kafka partition or per kafka broker. If it was per kafka broker, it makes even less sense now, since filoebeat is only connected to "45" kafka brokers per filebeat log:

2019-09-04T20:52:15.672Z INFO kafka/log.go:53 client/brokers registered new broker #38457 at [hostname:port]

an earlier version of filebeat and GO (BEATSVERSION=6.1.3. GOVERSION=1.8.3) consumes up to 43G of memory, still much more than what we expected, but much less than a newer version of filebeat/go). Disclaimer: we did not have chance to verify whether the upgrade is due to GO version upgrade or Filebeat version upgrade or a combo of both.

Timestamp, VSZ, RSS, %MEM

2019/09/03 17:44:37 420912 17424 0.01
2019/09/03 17:44:57 422476 17680 0.01
2019/09/03 17:45:17 83626024 6637376 2.52
2019/09/03 17:45:37 139713048 22859348 8.67
2019/09/03 17:45:57 148985864 39280920 14.90
2019/09/03 17:46:17  172069584 57875380  21.96
2019/09/03 17:46:37 194879332 75969164 28.82
2019/09/03 17:46:57 210748936 91502184 34.72

jsoriano · September 5, 2019, 7:41am

@filebeater could you upload a memory profile?

You can enable profiling adding the -httpprof localhost:6060 flag to filebeat, and get a memory profile downloading http://localhost:6060/debug/pprof/heap.

filebeater · September 12, 2019, 4:59pm

btw, the above memory usage is observed in our production running. Since that incident, we have since rolled back the filebeat from 7.3 to 6.1.3, we have not observed in production since.
This is not readily repro in our experiment setup, i will keep an eye on this..
On a related note, this is from our experiment: filebeat existed right after start, complaining about:
out of memory: cannot allocate 209715200-byte block (9326067712 in use)
fatal error: out of memory

filebeat-7.2/filebeat -c filebeat-7.2/filebeat.yml -path.data ./data -path.logs ./logs
runtime: out of memory: cannot allocate 209715200-byte block (9326067712 in use)
fatal error: out of memory

runtime stack:
runtime.throw(0x1ad4851, 0xd)
	/usr/local/go/src/runtime/panic.go:617 +0x72
runtime.largeAlloc(0xc800000, 0x7f5700000001, 0xc0004a6c00)
	/usr/local/go/src/runtime/malloc.go:1057 +0x16b
runtime.mallocgc.func1()
	/usr/local/go/src/runtime/malloc.go:950 +0x46
runtime.systemstack(0x0)
	/usr/local/go/src/runtime/asm_amd64.s:351 +0x66
runtime.mstart()
	/usr/local/go/src/runtime/proc.go:1153

goroutine 113 [running]:
runtime.systemstack_switch()
	/usr/local/go/src/runtime/asm_amd64.s:311 fp=0xc0043b7da0 sp=0xc0043b7d98 pc=0xb16040
runtime.mallocgc(0xc800000, 0x1929d20, 0x1, 0xc1193f1ee8)
	/usr/local/go/src/runtime/malloc.go:949 +0x872 fp=0xc0043b7e40 sp=0xc0043b7da0 pc=0xac7052
runtime.makechan(0x189d3c0, 0x1900000, 0xc000000200)
	/usr/local/go/src/runtime/chan.go:106 +0x156 fp=0xc0043b7e88 sp=0xc0043b7e40 pc=0xabfd36
github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*asyncProducer).newPartitionProducer(0xc0002850a0, 0xc00013cfe0, 0x9, 0x1d2, 0xc01bfd6ea0)
	/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/async_producer.go:472 +0x46 fp=0xc0043b7ee0 sp=0xc0043b7e88 pc=0x1490e36
github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*topicProducer).dispatch(0xc008093380)
	/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/async_producer.go:391 +0x135 fp=0xc0043b7fa0 sp=0xc0043b7ee0 pc=0x1490a35
github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*topicProducer).dispatch-fm()
	/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/async_producer.go:376 +0x2a fp=0xc0043b7fb8 sp=0xc0043b7fa0 pc=0x14d360a
github.com/elastic/beats/vendor/github.com/Shopify/sarama.withRecover(0xc01423f530)
	/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/utils.go:45 +0x43 fp=0xc0043b7fd8 sp=0xc0043b7fb8 pc=0x14ca863
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1337 +0x1 fp=0xc0043b7fe0 sp=0xc0043b7fd8 pc=0xb18111
created by github.com/elastic/beats/vendor/github.com/Shopify/sarama.(*asyncProducer).newTopicProducer
	/go/src/github.com/elastic/beats/vendor/github.com/Shopify/sarama/async_producer.go:372 +0x1ab

goroutine 1 [chan receive]:
github.com/elastic/beats/filebeat/beater.(*signalWait).Wait(...)
	/go/src/github.com/elastic/beats/filebeat/beater/signalwait.go:45
github.com/elastic/beats/filebeat/beater.(*Filebeat).Run(0xc0003e4320, 0xc00046bd40, 0x0, 0x0)
	/go/src/github.com/elastic/beats/filebeat/beater/filebeat.go:400 +0xe9e
github.com/elastic/beats/libbeat/cmd/instance.(*Beat).launch(0xc00046bd40, 0x1ace7c0, 0x8, 0x1ace7c0, 0x8, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:431 +0x61d
github.com/elastic/beats/libbeat/cmd/instance.Run.func1(0x1ace7c0, 0x8, 0x1ace7c0, 0x8, 0x0, 0x0, 0x1ace7c0, 0x8, 0x1ace7c0, 0x8, ...)
	/go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:182 +0x51d
github.com/elastic/beats/libbeat/cmd/instance.Run(0x1ace7c0, 0x8, 0x1ace7c0, 0x8, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc000464000, ...)
	/go/src/github.com/elastic/beats/libbeat/cmd/instance/beat.go:183 +0xbe
github.com/elastic/beats/libbeat/cmd.genRunCmd.func1(0xc000462280, 0xc00045c100, 0x0, 0x8)
	/go/src/github.com/elastic/beats/libbeat/cmd/run.go:36 +0x9a
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).execute(0xc000462280, 0xc00003c0a0, 0x8, 0x8, 0xc000462280, 0xc00003c0a0)
	/go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:704 +0x289
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0xc000462280, 0x1784259, 0xc0004e1f88, 0xc0000a2058)
	/go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:785 +0x2ca
github.com/elastic/beats/vendor/github.com/spf13/cobra.(*Command).Execute(...)
	/go/src/github.com/elastic/beats/vendor/github.com/spf13/cobra/command.go:738
main.main()
	/go/src/github.com/elastic/beats/x-pack/filebeat/main.go:22 +0x30

system · October 10, 2019, 4:59pm

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