Worker doesn't reconnect to Faktory if the connection is reset

[valo]

I have a single threaded worker defined as:

w = Worker(queues=['etherbi_decode'],
           concurrency=1,
           executor=ThreadPoolExecutor)

which works for a 2-3 hours and at some point falls into an infinite loop, not getting any new jobs and not sending heartbeats to the faktory server.

Logs from the worker before it falls into infinite loop:

INFO:faktory.connection:Connecting to faktory-faktory:7419 (with password None)
ERROR:faktory.worker:Task failed: 50c676346b5a4307826de2245caf5593
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "etherbi/decoder/decoder_worker.py", line 225, in decode_bucket
    _enqueue_block_decoded_task(task_number, 'calculate_burn_rate', 'etherbi_burn_rate_calculation')
  File "etherbi/decoder/decoder_worker.py", line 187, in _enqueue_block_decoded_task
    if faktory_client.queue(task, queue=queue, args=[task_number]):
  File "/app/src/faktory/faktory/client.py", line 32, in queue
    self.connect()
  File "/app/src/faktory/faktory/client.py", line 21, in connect
    self.is_connected = self.faktory.connect()
  File "/app/src/faktory/faktory/_proto.py", line 64, in connect
    self.socket.connect((self.host, self.port))
socket.timeout: timed out
INFO:__main__:Transaction to 0xaf30d2a7e90d7dc361c8c4585e9bb7d2f6f15bc7 is recognized in block 3917149 on position 98.
INFO:__main__:Transaction to 0xaf30d2a7e90d7dc361c8c4585e9bb7d2f6f15bc7 is recognized in block 3917154 on position 2.
<SOME_WORK_RELATED_LOGS_AS_THE_ABOVE>
INFO:faktory.connection:Connecting to faktory-faktory:7419 (with password None)
INFO:faktory.connection:Disconnected

running sudo strace -p <PID> -e trace=network -f -s 10000 against the process I get infinite stream of

[pid 16254] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid 16254] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid 16254] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid 16254] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid 16254] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid 16254] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid 16254] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid 16254] recvfrom(3, "", 4096, 0, NULL, NULL) = 0

We use python and elixir clients against the same faktory server and so far this behavior is observed only with the python workers.

Worker version: c5cb89b
Server version: 0.7.0

[valo]

I'll try to collect an end-to-end strace with the whole communication between the worker and the faktory server... I hope to have some results in a couple of hours.

[valo]

Managed to get the strace. Seems like the last command to the faktory server is BEAT. Here is the strace just before the infinite loop:

[pid  4950] sendto(3, "ACK {\"jid\": \"a125ff80a3654fa7bd1906f86651611f\"}\r\n", 49, 0, NULL, 0) = 49
[pid  4950] recvfrom(3, "+OK\r\n", 4096, 0, NULL, NULL) = 5
[pid  4950] sendto(3, "BEAT {\"wid\": \"3ff3d2d33f254bd4b3a2e0c25c7b6c53\"}\r\n", 50, 0, NULL, 0) = 50
[pid  4950] recvfrom(3, "+OK\r\n", 4096, 0, NULL, NULL) = 5
[pid  4950] sendto(3, "FETCH etherbi_decode\r\n", 22, 0, NULL, 0) = 22
[pid  4950] recvfrom(3, "$218\r\n{\"jid\":\"bab858ac524f4027bfcf1c285023b37c\",\"queue\":\"etherbi_decode\",\"jobtype\":\"decode\",\"args\":[229469],\"priority\":5,\"created_at\":\"2018-02-03T01:33:14.101
992958Z\",\"enqueued_at\":\"2018-02-03T01:33:14.101999803Z\",\"retry\":5}\r\n", 4096, 0, NULL, NULL) = 226
[pid  4950] sendto(3, "BEAT {\"wid\": \"3ff3d2d33f254bd4b3a2e0c25c7b6c53\"}\r\n", 50, 0, NULL, 0) = 50
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0

[cdrx]

I think it failed before, on the 3rd line we send a BEAT and would expect a json blob back with a state key, but we just get +OK which doesn't make sense.

Did anything change when this started? Update to faktory 0.7?

[valo]

Indeed we upgraded the server to 0.7.0 at end of last week. We downgraded to faktory 0.6.1 and the workers have been running for over 3 hours. So far no problems. Seems like the upgrade might be the cause for the above issue...

[cdrx]

That makes sense then -- I've been running 0.6.1 in production and had no issues. I'll do some testing here with 0.7 and see if I can find a way to reproduce the issue.

Do you know if the elixir worker maintains a separate connection for sending BEATs?

[valo]

I think the elixir client is using a pool of connections, so it will be using different connection each time https://github.com/cjbottaro/faktory_worker_ex/blob/60d265deb72de4deab4086b4704826b01265d475/lib/faktory/heartbeat.ex#L30

Also keep in mind that in our setup the elixir workers have been much less utilized than the python workers, so that might be the reason we didn't see any problems. Anecdotally, the elixir workers seem to be more stable so far...

[valo]

Has been running faktory 0.6.1 all day today and no issues. This really starts to smell like a regression in 0.7.0... May be we should move this issue into the faktory repo?

[mperham]

I think it failed before, on the 3rd line we send a BEAT and would expect a json blob back with a state key, but we just get +OK which doesn't make sense.

The server only sends a JSON state when the state changes. Normal conditions will get an OK response. The wiki documents this and I'm pretty sure it didn't change between 061 and 070.

https://github.com/contribsys/faktory/wiki/Worker-Lifecycle#heartbeat

[valo]

Here is a bit more from the log. Seems like BEAT is indeed returning +OK\r\n. The question is: why the last BEAT caused the connection to fall into this infinite state:

[pid  4950] sendto(3, "FETCH etherbi_decode\r\n", 22, 0, NULL, 0) = 22
[pid  4950] recvfrom(3, "$218\r\n{\"jid\":\"a125ff80a3654fa7bd1906f86651611f\",\"queue\":\"etherbi_decode\",\"jobtype\":\"decode\",\"args\":[229415],\"priority\":5,\"created_at\":\"2018-02-03T01:31:32.598003581Z\",\"enqueued_at\":\"2018-02-03T01:31:32.598009936Z\",\"retry\":5}\r\n", 4096, 0, NULL, NULL) = 226
[pid  4950] sendto(3, "BEAT {\"wid\": \"3ff3d2d33f254bd4b3a2e0c25c7b6c53\"}\r\n", 50, 0, NULL, 0) = 50
[pid  4950] recvfrom(3, "+OK\r\n", 4096, 0, NULL, NULL) = 5
[pid  4950] sendto(3, "BEAT {\"wid\": \"3ff3d2d33f254bd4b3a2e0c25c7b6c53\"}\r\n", 50, 0, NULL, 0) = 50
[pid  4950] recvfrom(3, "+OK\r\n", 4096, 0, NULL, NULL) = 5
[pid  4950] sendto(3, "BEAT {\"wid\": \"3ff3d2d33f254bd4b3a2e0c25c7b6c53\"}\r\n", 50, 0, NULL, 0) = 50
[pid  4950] recvfrom(3, "+OK\r\n", 4096, 0, NULL, NULL) = 5
[pid  4950] sendto(3, "ACK {\"jid\": \"a125ff80a3654fa7bd1906f86651611f\"}\r\n", 49, 0, NULL, 0) = 49
[pid  4950] recvfrom(3, "+OK\r\n", 4096, 0, NULL, NULL) = 5
[pid  4950] sendto(3, "BEAT {\"wid\": \"3ff3d2d33f254bd4b3a2e0c25c7b6c53\"}\r\n", 50, 0, NULL, 0) = 50
[pid  4950] recvfrom(3, "+OK\r\n", 4096, 0, NULL, NULL) = 5
[pid  4950] sendto(3, "FETCH etherbi_decode\r\n", 22, 0, NULL, 0) = 22
[pid  4950] recvfrom(3, "$218\r\n{\"jid\":\"bab858ac524f4027bfcf1c285023b37c\",\"queue\":\"etherbi_decode\",\"jobtype\":\"decode\",\"args\":[229469],\"priority\":5,\"created_at\":\"2018-02-03T01:33:14.101992958Z\",\"enqueued_at\":\"2018-02-03T01:33:14.101999803Z\",\"retry\":5}\r\n", 4096, 0, NULL, NULL) = 226
[pid  4950] sendto(3, "BEAT {\"wid\": \"3ff3d2d33f254bd4b3a2e0c25c7b6c53\"}\r\n", 50, 0, NULL, 0) = 50
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0
[pid  4950] recvfrom(3, "", 4096, 0, NULL, NULL) = 0

[valo]

For sure we are not seeing this behavior with faktory 0.6.1. We've been rolling with it for the past 2 days, while everything else is the same and not problems so far.

[cdrx]

@mperham yes, your right, my bad. The BEAT / +OK is fine.

@valo do you have multiple workers running and if you do, do they all fail at the same time?

[valo]

I have 40-50 workers and they gradually start to fail. I think restarting a worker returns it to a good state. In that sense it is not like the server is going into foobar state, as I don't need to restart the server. I only restart the workers to keep the queue progressing.

[cdrx]

I can reproduce what I think is the same bug, by starting a worker and then killing faktory -- that sends the worker into an infinite loop of read()ing from a dead socket.

I'm surprised this doesn't raise an exception