logspout icon indicating copy to clipboard operation
logspout copied to clipboard

Published 20 hours ago • verified publisher icon gliderlabs

Logspout does not reconnect

Open hamsterready opened this issue 8 years ago • 2 comments

Hi,

I am running logspout (2 instances)+logstash (1 instance) in docker swarm environment.

When my logstash and logspout services are started I see nice logs in logstash:

rta_logstash.1.mv47vj6kv936@backend-03    | [2017-10-03T10:14:39,084][INFO ][logstash.inputs.syslog   ] new connection {:client=>"10.0.0.36:40408"}
rta_logstash.1.mv47vj6kv936@backend-03    | [2017-10-03T10:14:44,175][INFO ][logstash.inputs.syslog   ] new connection {:client=>"10.0.0.28:50848"}

After that I kill logstash (docker stop) and let the docker swarm to start new instance of logstash, what I see in logstash logs:

rta_logstash.1.mv47vj6kv936@backend-03    | [2017-10-03T10:15:40,772][WARN ][logstash.runner          ] SIGTERM received. Shutting down the agent.
rta_logstash.1.mv47vj6kv936@backend-03    | [2017-10-03T10:15:40,774][WARN ][logstash.agent           ] stopping pipeline {:id=>"main"}
rta_logstash.1.mv47vj6kv936@backend-03    | [2017-10-03T10:15:40,780][FATAL][logstash.runner          ] An unexpected error occurred! {:error=>#<Errno::EBADF: Bad file descriptor - Bad file descriptor>, :backtrace=>["org/jruby/RubyIO.java:3565:in `each'", "/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-input-syslog-3.2.2/lib/logstash/inputs/syslog.rb:182:in `tcp_receiver'", "/usr/share/logstash/vendor/bundle/jruby/1.9/gems/logstash-input-syslog-3.2.2/lib/logstash/inputs/syslog.rb:167:in `tcp_listener'"]}
rta_logstash.1.2pofqsadbyjv@backend-03    | 2017/10/03 10:15:48 Setting 'xpack.monitoring.enabled' from environment.
...
rta_logstash.1.2pofqsadbyjv@backend-03    | [2017-10-03T10:15:58,832][INFO ][logstash.inputs.syslog   ] Starting syslog tcp listener {:address=>"0.0.0.0:5000"}
rta_logstash.1.2pofqsadbyjv@backend-03    | [2017-10-03T10:15:58,832][INFO ][logstash.inputs.syslog   ] Starting syslog udp listener {:address=>"0.0.0.0:5000"}
rta_logstash.1.2pofqsadbyjv@backend-03    | [2017-10-03T10:15:58,885][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}

And there is no new connection log entry from logspout.

In logspout instance I see:

ubuntu@backend-03:~$ docker logs 5843281d3416
2017/10/03 10:14:44 setting allowTTY to: false
2017/10/03 10:14:44 setting retryCount to: 10
# logspout v3.2.3 by gliderlabs
# adapters: raw syslog tcp udp tls
# options : debug:true backlog:false persist:/mnt/routes
# jobs    : http[routes,logs]:80 pump routes
# routes  :
#   ADAPTER	ADDRESS		CONTAINERS	SOURCES	OPTIONS
#   syslog+tcp	logstash:5000	monitorlogs:true	map[]
2017/10/03 10:14:44 pump.Run(): using inactivity timeout:  0s
2017/10/03 10:14:44 pump.pumpLogs(): 5843281d3416 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 0f9edae0b77e started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 7b0935e15bc5 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 50db69b9f6fc started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 49c530ec4ab1 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): fe1f6fc03571 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 3fe97479fc04 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 3ce0afc5a383 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): cf04b571eedd started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 0ac874916228 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 21dc24ef3fc7 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): b50875b97a4b started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 05517e89c3b8 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 48557247c133 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): bb754e4f2d44 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): a50382ec999b started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 67aa1c1e34a0 started, tail: all
2017/10/03 10:14:44 pump.pumpLogs(): 3bd63edf3215 started, tail: all
2017/10/03 10:14:49 pump.Run() event: po8aogcoejsa service:update
2017/10/03 10:14:51 pump.Run() event: 67aa1c1e34a0 exec_create: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:14:51 pump.Run() event: 67aa1c1e34a0 exec_start: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:14:52 pump.Run() event: 0f9edae0b77e exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:14:52 pump.Run() event: 0f9edae0b77e exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:14:58 pump.Run() event: bb754e4f2d44 exec_start: /bin/sh -c node healthcheck.js || exit 1
2017/10/03 10:14:58 pump.Run() event: bb754e4f2d44 exec_create: /bin/sh -c node healthcheck.js || exit 1
2017/10/03 10:15:03 pump.Run() event: 0f9edae0b77e exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:03 pump.Run() event: 0f9edae0b77e exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:06 pump.Run() event: 0f9edae0b77e kill
2017/10/03 10:15:06 pump.Run() event: 0f9edae0b77e die
2017/10/03 10:15:06 pump.pumpLogs(): 0f9edae0b77e stopped
2017/10/03 10:15:07 pump.Run() event: 3piqfpdxy6da network:disconnect
2017/10/03 10:15:07 pump.Run() event: ypv1tcead1po network:disconnect
2017/10/03 10:15:07 pump.Run() event: 0f9edae0b77e stop
2017/10/03 10:15:07 pump.pumpLogs(): 0f9edae0b77e dead
2017/10/03 10:15:07 pump.Run() event: 469e9dbc2407 create
2017/10/03 10:15:09 pump.Run() event: 48aad0fc729f destroy
2017/10/03 10:15:12 pump.Run() event: 3piqfpdxy6da network:connect
2017/10/03 10:15:12 pump.Run() event: ypv1tcead1po network:connect
2017/10/03 10:15:13 pump.Run() event: 469e9dbc2407 start
2017/10/03 10:15:13 pump.pumpLogs(): 469e9dbc2407 started, tail: all
2017/10/03 10:15:21 pump.Run() event: 67aa1c1e34a0 exec_start: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:15:21 pump.Run() event: 67aa1c1e34a0 exec_create: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:15:23 pump.Run() event: 469e9dbc2407 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:23 pump.Run() event: 469e9dbc2407 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:24 pump.Run() event: 469e9dbc2407 health_status: healthy
2017/10/03 10:15:28 pump.Run() event: bb754e4f2d44 exec_start: /bin/sh -c node healthcheck.js || exit 1
2017/10/03 10:15:28 pump.Run() event: bb754e4f2d44 exec_create: /bin/sh -c node healthcheck.js || exit 1
2017/10/03 10:15:34 pump.Run() event: 469e9dbc2407 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:34 pump.Run() event: 469e9dbc2407 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:40 pump.Run() event: 7b0935e15bc5 kill
2017/10/03 10:15:41 pump.Run() event: 7b0935e15bc5 die
2017/10/03 10:15:41 pump.pumpLogs(): 7b0935e15bc5 stopped
2017/10/03 10:15:42 pump.Run() event: 3piqfpdxy6da network:disconnect
2017/10/03 10:15:42 pump.Run() event: 7b0935e15bc5 stop
2017/10/03 10:15:42 pump.pumpLogs(): 7b0935e15bc5 dead
2017/10/03 10:15:42 pump.Run() event: 66f038df5c1f create
2017/10/03 10:15:44 pump.Run() event: 469e9dbc2407 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:44 pump.Run() event: 469e9dbc2407 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:44 pump.Run() event: b3b90a92a954 destroy
2017/10/03 10:15:47 pump.Run() event: 3piqfpdxy6da network:connect
2017/10/03 10:15:48 pump.Run() event: 66f038df5c1f start
2017/10/03 10:15:48 pump.pumpLogs(): 66f038df5c1f started, tail: all
2017/10/03 10:15:51 pump.Run() event: 67aa1c1e34a0 exec_create: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:15:51 pump.Run() event: 67aa1c1e34a0 exec_start: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:15:54 pump.Run() event: 469e9dbc2407 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:54 pump.Run() event: 469e9dbc2407 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:15:59 pump.Run() event: bb754e4f2d44 exec_start: /bin/sh -c node healthcheck.js || exit 1
2017/10/03 10:15:59 pump.Run() event: bb754e4f2d44 exec_create: /bin/sh -c node healthcheck.js || exit 1
2017/10/03 10:16:04 pump.Run() event: 469e9dbc2407 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:04 pump.Run() event: 469e9dbc2407 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:10 pump.Run() event: 469e9dbc2407 kill
2017/10/03 10:16:11 pump.Run() event: 469e9dbc2407 die
2017/10/03 10:16:11 pump.pumpLogs(): 469e9dbc2407 stopped
2017/10/03 10:16:11 pump.Run() event: 3piqfpdxy6da network:disconnect
2017/10/03 10:16:11 pump.Run() event: ypv1tcead1po network:disconnect
2017/10/03 10:16:11 pump.Run() event: 469e9dbc2407 stop
2017/10/03 10:16:11 pump.pumpLogs(): 469e9dbc2407 dead
2017/10/03 10:16:11 pump.Run() event: 2b2993033474 create
2017/10/03 10:16:14 pump.Run() event: 0481c8345126 destroy
2017/10/03 10:16:16 pump.Run() event: ypv1tcead1po network:connect
2017/10/03 10:16:16 pump.Run() event: 3piqfpdxy6da network:connect
2017/10/03 10:16:18 pump.Run() event: 2b2993033474 start
2017/10/03 10:16:18 pump.pumpLogs(): 2b2993033474 started, tail: all
2017/10/03 10:16:22 pump.Run() event: 67aa1c1e34a0 exec_start: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:16:22 pump.Run() event: 67aa1c1e34a0 exec_create: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:16:28 pump.Run() event: 2b2993033474 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:28 pump.Run() event: 2b2993033474 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:28 pump.Run() event: 2b2993033474 health_status: healthy
2017/10/03 10:16:38 pump.Run() event: 2b2993033474 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:38 pump.Run() event: 2b2993033474 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:48 pump.Run() event: 2b2993033474 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:48 pump.Run() event: 2b2993033474 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:52 pump.Run() event: 67aa1c1e34a0 exec_create: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:16:52 pump.Run() event: 67aa1c1e34a0 exec_start: /bin/sh -c curl -f http://localhost:50075/ || exit 1
2017/10/03 10:16:58 pump.Run() event: 2b2993033474 exec_create: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:16:58 pump.Run() event: 2b2993033474 exec_start: /bin/sh -c curl -m 5 http://localhost:8080/ || exit 1
2017/10/03 10:17:00 pump.Run() event: bb754e4f2d44 exec_start: /bin/sh -c node healthcheck.js || exit 1
... and continues like that

I am using syslog+tcp.

I tried with syslog over udp but then I ended up with write operation not permitted error and from what I have seen here https://github.com/gliderlabs/logspout/blob/95b284a5c4ed36317845fc51dcfa9ec9cf0258e9/adapters/syslog/syslog.go#L136 the UDP errors are silently ignored.

Please note that in the docker swarm environment the IP of the service can change after restart.

hamsterready avatar Oct 03 '17 10:10 hamsterready

I'm seeing the same thing. The logs are spammed constantly with the exec_create, exec_start, exec_kill error lines.

I restarted logspout and they continued. Nothing changed with any of the other services.

jazoom avatar Jun 30 '18 23:06 jazoom

I've been seeing this issue recently though I only see this issue when I build logspout from the custom/ folder. When I build logspout from the repo root on master the problem goes away for me. When logstash restarts and the IP changes and logspout service will restart and resolve the new IP.

matutter avatar Aug 04 '20 22:08 matutter