Infinite loop when using logstash output

[theredcat]

Hello,

I have a infinite loop problem when running httpbeat. It occurs randomly, but faster (10-15sec) using logstash output. With file output it seem to run longer (3-4 min) but ultimatly start to loop. The CPU is then stuck at 100% User.

I've seen that on libbeat that may be related : elastic/beats#878

Maybe you can update the lib version in dependencies ? I'm new to Go and I'm not sure how to do this.

I'm on debian Jessie, up to date, Go 1.5.1 x64

Here is my test config

httpbeat:
  urls:
    -
      cron: "@every 5s"
      url: http://es-03:9200/_cluster/stats
      method: get
      document_type: httpbeat_json
      headers:
      fields:
output:
  file:
    path: "/tmp/filebeat"
    filename: filebeat
    rotate_every_kb: 10000
    number_of_files: 7
  console:
    pretty: true
shipper:
logging:
  to_syslog: true
  files:
    rotateeverybytes: 10485760 # = 10MB

A strace doesn't help at all, the main process is stuck on a system futex call and the third thread is in pure user mode so strace doesn't help here.

Here is the lsof output. I'm testing HTTPBeat monitoring my elasticsearch cluster (es:9200/_cluster/stats) so the es-03.my.tld are connections to ES by httpbeat for checks. I'm not using httpbeat ES output. I'm pretty surprised to see more that one HTTP connection to the es-03 server since there is only one check at a time. Maybe a non-closed socket here ?

COMMAND    PID USER   FD   TYPE             DEVICE SIZE/OFF    NODE NAME
httpbeat 16076 root  cwd    DIR              202,1     4096  434641 /srv/go/src/github.com/christiangalsterer/httpbeat/etc
httpbeat 16076 root  rtd    DIR              202,1     4096       2 /
httpbeat 16076 root  txt    REG              202,1 10931624  285150 /srv/go/src/github.com/christiangalsterer/httpbeat/httpbeat
httpbeat 16076 root  mem    REG              202,1  1738176  268580 /lib/x86_64-linux-gnu/libc-2.19.so
httpbeat 16076 root  mem    REG              202,1   137440  268576 /lib/x86_64-linux-gnu/libpthread-2.19.so
httpbeat 16076 root  mem    REG              202,1   140928  268577 /lib/x86_64-linux-gnu/ld-2.19.so
httpbeat 16076 root    0u   CHR              136,2      0t0       5 /dev/pts/2
httpbeat 16076 root    1u   CHR              136,2      0t0       5 /dev/pts/2
httpbeat 16076 root    2u   CHR              136,2      0t0       5 /dev/pts/2
httpbeat 16076 root    3u  unix 0xffff880204551440      0t0 4378679 socket
httpbeat 16076 root    4u  0000                0,9        0    6706 anon_inode
httpbeat 16076 root    5u  unix 0xffff880204551b40      0t0 4378680 socket
httpbeat 16076 root    6u  unix 0xffff88005b610140      0t0 4378681 socket
httpbeat 16076 root    7u  unix 0xffff88005b3e13c0      0t0 4378682 socket
httpbeat 16076 root    8u  unix 0xffff88005b3e1ac0      0t0 4378683 socket
httpbeat 16076 root    9u  unix 0xffff8800ea7a6180      0t0 4378684 socket
httpbeat 16076 root   10u  unix 0xffff8800ea7a6500      0t0 4378685 socket
httpbeat 16076 root   11u  unix 0xffff880204931780      0t0 4378686 socket
httpbeat 16076 root   12u  IPv4            4380277      0t0     TCP 10.0.42.237:47968->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   13u   REG              202,1   141967  285129 /tmp/filebeat/filebeat
httpbeat 16076 root   14u  IPv4            4382273      0t0     TCP 10.0.42.237:47981->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   15u  IPv4            4382328      0t0     TCP 10.0.42.237:47992->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   17u  IPv4            4380033      0t0     TCP 10.0.42.237:47851->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   18u  IPv4            4380062      0t0     TCP 10.0.42.237:47865->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   19u  IPv4            4380089      0t0     TCP 10.0.42.237:47878->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   20u  IPv4            4380112      0t0     TCP 10.0.42.237:47889->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   21u  IPv4            4380143      0t0     TCP 10.0.42.237:47904->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   22u  IPv4            4380166      0t0     TCP 10.0.42.237:47915->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   23u  IPv4            4380197      0t0     TCP 10.0.42.237:47930->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   24u  IPv4            4380220      0t0     TCP 10.0.42.237:47941->es-03.my.tld:9200 (ESTABLISHED)
httpbeat 16076 root   25u  IPv4            4380248      0t0     TCP 10.0.42.237:47954->es-03.my.tld:9200 (ESTABLISHED)

[theredcat]

And i can confirm that the process is stuck in CPU user mode since the only SIG working is a SIGKILL (kill -9)

[christiangalsterer]

Your first issues seems to be similar/identical to christiangalsterer/execbeat#1 and I try to look into it in the next days.

On the multiple socket items I need to check first.

[christiangalsterer]

@theredcat: I have committed some changes to master. HTTP connections are now reused.
The looping problem I was not able reproduce.
Can you maybe retry with latest version on master?

[theredcat]

It works now! I'll let it run few days before putting it in prod ;-)

[theredcat]

Running for 10 days, with 30 checks "@every 1m" and everythink is fine.

[christiangalsterer]

Sounds like a very thorough test ;-) Thanks for your support. The change is released in 1.0.1