NoMethodError: undefined method `[]' for nil:NilClass

[scottrobertson]

[mperham]

I don't know how this could happen. result should never return nil, only a string or raise. Can you easily reproduce the issue? If you can turn on debugging and reproduce the issue, it will help but the debugging will add a LOT of output.

Faktory.configure_worker do |config|
   config.faktory = { debug: true }
end

[jmirmina]

We're currently digging into an unrelated issue (not sure yet if it's something on our end or not) where we were digging into the result method. I remembered seeing this in the middle of that result function and figured I'd chime in: return nil if count == -1

[mperham]

@jmirmina Great find, I was completely blind to that line. This will occur if we call c.Result(nil) on the Faktory server-side but I can't see a code path where that is done in the ack command. It's definitely possible in the code path for other commands, for instance it is a normal part of fetch, when we want to return nil because there is no job to process right now.

I wonder if this issue can come about if we use a Faktory::Client in a thread-unsafe way; maybe it's possible for one thread to request fetch and another thread to receive the reply to ack.

[jason-he-3]

Hello! I've been working with @jmirmina debugging this heavily on our side internally and with regards to what @mperham said about Faktory::Client being used in thread-unsafe ways I highly suspect this to be the case. So a bit of background about our setup, we run our rails setup inside of a standard container that boots up puma and as apart of that setup, we instantiate both as a producer (think: launcher class in this gem in a separate thread in an after initializer, we pass wid and pid to faktory). However, we also push jobs to faktory in this same rails container using the standard workflow where Faktory::Client#push is invoked as apart of a perform_async call and we also process jobs in this same container as well (or as apart of different pods in the same deployment in k8s depending on scaling). However, this seems to have had the unintended effect of sometimes having jobs error on push to faktory because the socket (and therefore connection) is either reaped on the faktory server side (because the producers and consumers are one connection pool now) or as I found today, the socket is somehow still writable on the client side despite being reaped which then doesn't throw an expected Errno::EPIPE (Broken pipe - No message available) when writing to that socket. This was after I had confirmed via the faktory server logs that the connection had been reaped almost 5 minutes prior.

The other thing I've witnessed while sharing a connection pool is that sometimes, there is data in the TCPSocket that I would not otherwise expect to be there. For example, when doing a job push yesterday, I somehow got a message back from faktory server that indicated an Unknown Worker: name message. I know that ultimately, Faktory.server_pool indicates that it is implemented on top of the connection_pool gem which blockingly yields a Faktory::Client object when one is available or otherwise lazily spins one up if the current size is below max. Could this weirdness possibly be attributed to the pool somehow yielding the connection back too soon after previous usage and the buffer not having a chance to fully execute IO#sync (which I could only see happening if we don't read the data in the socket fully, or exception being thrown before it can read) before the next thread uses it and starts reading from that same socket? We never access Faktory::Client directly, only via perform_async and other built-in methods that ultimately access it through Faktory.server/server_pool which ultimately leads to the connection pool. Any thoughts on this would totally be appreciated.

[mperham]

I'll read through the FWR code and make sure it is using connection_pool as expected. If you can give me any more clues or reproduce the issue, that would help a lot too.

[mperham]

What do you think about this?

+++ b/lib/faktory/client.rb
@@ -295,9 +295,12 @@ module Faktory
 
       begin
         yield
-      rescue Errno::EPIPE, Errno::ECONNRESET
+      rescue SystemCallError, SocketError, TimeoutError
         if retryable
           retryable = false
+
+          @sock.close rescue nil
+          @sock = nil
           open(@timeout)
           retry
         else

If the underlying socket raises an exception that is not caught, it could have unread data that will be read on the next use. This change:

1. Adds more exceptions to the set that will result in the socket being discarded.
2. Closes the existing socket so we don't try to use it further.

[jason-he-3]

I think that this should cover the cases I outlined above with things potentially being left over in the buffer - these changes would be perfect. However, I did notice something weird today, here is a stack trace of us getting something unexpected from the buffer when doing a push:

Faktory::CommandError: Unknown worker 4c2b51b7d3572f5a
.../lib/faktory/client.rb:  333:in `result'
.../lib/faktory/client.rb:  343:in `ok'
.../lib/faktory/client.rb:  151:in `block in push'
.../lib/faktory/client.rb:  297:in `transaction'
.../lib/faktory/client.rb:  149:in `push'
.../lib/faktory/job.rb:   93:in `block in client_push'
….5.0/gems/connection_pool-2.2.3/lib/connection_pool.rb:   63:in `block in with'
org/jruby/RubyThread.java:759:in `handle_interrupt'
….5.0/gems/connection_pool-2.2.3/lib/connection_pool.rb:   62:in `block in with'
org/jruby/RubyThread.java:759:in `handle_interrupt'
….5.0/gems/connection_pool-2.2.3/lib/connection_pool.rb:   59:in `with'

Now what was exceptionally weird about this was - as far as I can tell via the faktory-server go code - there is nothing in the push command route that should ever respond with Unknown worker. But if you re-use the same connection for another push, it keeps throwing this exception (side note: This is sourced based on commit e1f61d0). Assuming your calls to read_nonblock in the io handler are working correctly, what I fail to understand is how this could continuously produce this exception on push. Also - I was able to verify that despite this exception being thrown on push, faktory server is accepting the push data with the JID etc and the job does run correctly on an available worker which sort of indicates to me that the issue is still most likely isolated to the ruby side.

[mperham]

That error would happen if the client tries to heartbeat for a worker which has been reaped. It's another case where the connection should be closed so the client opens a new socket and re-authenticates. Sounds like your worker process got into a bad state somehow and FWR's client connection logic isn't yet good enough to gracefully recover from every edge case.

I've committed that change; feel free to run master and see if it improves things.

[arjun810]

We've been running into this recently. I'm not sure what's causing it, but it seems potentially to happen more when we deploy a new version. We're running in ECS, so I don't really understand why that would matter..

[mperham]

@arjun810 Please post a full backtrace when you get one.

[arjun810]

Sorry for the terrible formatting.. copying out of our error tracker.

Details

undefined method [] for nil:NilClass
lib/faktory/client.rb:375 ok	
lib/faktory/client.rb:174 block in push	
lib/faktory/client.rb:320 transaction	
lib/faktory/client.rb:172 push	
lib/active_job/queue_adapters/faktory_adapter.rb:38 block (2 levels) in enqueue_at	
lib/connection_pool.rb:65 block (2 levels) in with	
lib/connection_pool.rb:64 handle_interrupt	
lib/connection_pool.rb:64 block in with	
lib/connection_pool.rb:61 handle_interrupt	
lib/connection_pool.rb:61 with	
lib/active_job/queue_adapters/faktory_adapter.rb:37 block in enqueue_at	
lib/faktory/middleware/chain.rb:129 block in invoke	
lib/faktory/middleware/batch.rb:14 call	
lib/faktory/middleware/chain.rb:131 block in invoke	
lib/faktory/middleware/chain.rb:134 invoke	
lib/active_job/queue_adapters/faktory_adapter.rb:36 enqueue_at	
lib/active_job/queue_adapters/faktory_adapter.rb:14 enqueue	
lib/active_job/enqueuing.rb:67 block in enqueue	
lib/active_support/callbacks.rb:118 block in run_callbacks	
lib/active_job/uniqueness/active_job_patch.rb:53 block (2 levels) in <module:ActiveJobPatch>	
lib/active_support/callbacks.rb:127 instance_exec	
lib/active_support/callbacks.rb:127 block in run_callbacks	
lib/active_job/instrumentation.rb:25 block in instrument	
lib/appsignal/hooks/active_support_notifications.rb:19 block in instrument	
lib/active_support/notifications/instrumenter.rb:24 instrument	
lib/appsignal/hooks/active_support_notifications.rb:18 instrument	
lib/active_job/instrumentation.rb:35 instrument	
lib/active_job/instrumentation.rb:9 block (2 levels) in <module:Instrumentation>	
lib/active_support/callbacks.rb:127 instance_exec	
lib/active_support/callbacks.rb:127 block in run_callbacks	
lib/active_support/tagged_logging.rb:99 block in tagged	
lib/active_support/tagged_logging.rb:37 tagged	
lib/active_support/tagged_logging.rb:99 tagged	
lib/active_job/logging.rb:25 tag_logger	
lib/active_job/logging.rb:14 block (2 levels) in <module:Logging>	
lib/active_support/callbacks.rb:127 instance_exec	
lib/active_support/callbacks.rb:127 block in run_callbacks	
lib/active_support/callbacks.rb:138 run_callbacks	
lib/active_job/enqueuing.rb:63 enqueue	
lib/active_job/enqueuing.rb:30 perform_later	
app/jobs/check_finetuning_job.rb:27 perform	
lib/active_job/execution.rb:59 block in _perform_job	
lib/active_support/callbacks.rb:118 block in run_callbacks	
lib/active_job/uniqueness/active_job_patch.rb:54 block (2 levels) in <module:ActiveJobPatch>	
lib/active_support/callbacks.rb:127 instance_exec	
lib/active_support/callbacks.rb:127 block in run_callbacks	
lib/i18n.rb:322 with_locale	
lib/active_job/translation.rb:9 block (2 levels) in <module:Translation>	
lib/active_support/callbacks.rb:127 instance_exec	
lib/active_support/callbacks.rb:127 block in run_callbacks	
lib/active_support/core_ext/time/zones.rb:66 use_zone	
lib/active_job/timezones.rb:9 block (2 levels) in <module:Timezones>	
lib/active_support/callbacks.rb:127 instance_exec	
lib/active_support/callbacks.rb:127 block in run_callbacks	
lib/active_support/callbacks.rb:138 run_callbacks	
lib/active_job/execution.rb:58 _perform_job	
lib/active_job/instrumentation.rb:20 _perform_job	
lib/active_job/execution.rb:46 perform_now	
lib/active_job/instrumentation.rb:14 block in perform_now	
lib/active_job/instrumentation.rb:25 block in instrument	
lib/appsignal/hooks/active_support_notifications.rb:19 block in instrument	
lib/active_support/notifications/instrumenter.rb:24 instrument	
lib/appsignal/hooks/active_support_notifications.rb:18 instrument	
lib/active_job/instrumentation.rb:35 instrument	
lib/active_job/instrumentation.rb:14 perform_now	
lib/active_job/logging.rb:18 block in perform_now	
lib/active_support/tagged_logging.rb:99 block in tagged	
lib/active_support/tagged_logging.rb:37 tagged	
lib/active_support/tagged_logging.rb:99 tagged	
lib/active_job/logging.rb:25 tag_logger	
lib/active_job/logging.rb:18 perform_now	
lib/active_job/execution.rb:24 block in execute	
lib/active_support/callbacks.rb:118 block in run_callbacks	
lib/active_job/railtie.rb:54 block (4 levels) in <class:Railtie>	
lib/active_support/execution_wrapper.rb:92 wrap	
lib/active_support/reloader.rb:72 block in wrap	
lib/active_support/execution_wrapper.rb:88 wrap	
lib/active_support/reloader.rb:71 wrap	
lib/active_job/railtie.rb:53 block (3 levels) in <class:Railtie>	
lib/active_support/callbacks.rb:127 instance_exec	
lib/active_support/callbacks.rb:127 block in run_callbacks	
lib/active_support/callbacks.rb:138 run_callbacks	
lib/active_job/execution.rb:22 execute	
lib/appsignal/hooks/active_job.rb:56 execute	
lib/active_job/queue_adapters/faktory_adapter.rb:47 perform	
lib/faktory/processor.rb:145 block (2 levels) in process	
lib/faktory/middleware/chain.rb:129 block in invoke	
lib/faktory/middleware/batch.rb:21 call	
lib/faktory/middleware/chain.rb:131 block in invoke	
lib/faktory/middleware/chain.rb:134 invoke	
lib/faktory/processor.rb:144 block in process	
lib/faktory/processor.rb:134 block (3 levels) in dispatch	
lib/faktory/rails.rb:50 block in call	
lib/active_support/execution_wrapper.rb:92 wrap	
lib/active_support/reloader.rb:72 block in wrap	
lib/active_support/execution_wrapper.rb:92 wrap	
lib/active_support/reloader.rb:71 wrap	
lib/faktory/rails.rb:49 call	
lib/faktory/processor.rb:130 block (2 levels) in dispatch	
lib/faktory/job_logger.rb:6 call	
lib/faktory/processor.rb:125 block in dispatch	
lib/faktory/logging.rb:43 with_context	
lib/faktory/logging.rb:37 with_job_hash_context	
lib/faktory/processor.rb:124 dispatch	
lib/faktory/processor.rb:143 process	
lib/faktory/processor.rb:88 process_one	
lib/faktory/processor.rb:71 run	
lib/faktory/util.rb:17 watchdog	
lib/faktory/util.rb:26 block in safe_thread

[arjun810]

Little bit more information for you...

It seems like after our deploy, one of the workers started up unhappy. Here are the logs from that worker's startup.

It eventually does successfully process a job, but then will randomly and intermittently get the same OK failure pasted above.

Details

2023-12-07T17:10:15.008-08:00	7 TID-3fw INFO: Running in ruby 3.2.2 (2023-03-30 revision e51014f9c0) [aarch64-linux]
2023-12-07T17:10:15.009-08:00	7 TID-3fw INFO: See LICENSE and the LGPL-3.0 for licensing details.2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: Error fetching job: Faktory::TimeoutError
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:41:in `block in read_timeout'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:38:in `loop'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:38:in `read_timeout'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:23:in `gets'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:342:in `result'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:379:in `result!'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:183:in `block in fetch'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:320:in `transaction'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:181:in `fetch'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `block in retrieve_work'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:79:in `block in server'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:65:in `block (2 levels) in with'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `handle_interrupt'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `block in with'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:78:in `server'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `retrieve_work'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:100:in `fetch'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:81:in `process_one'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:71:in `run'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:17:in `watchdog'
2023-12-07T17:10:25.483-08:00	7 TID-2d9g ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:26:in `block in safe_thread'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: Error fetching job: Faktory::TimeoutError
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:41:in `block in read_timeout'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:38:in `loop'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:38:in `read_timeout'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:23:in `gets'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:342:in `result'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:379:in `result!'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:183:in `block in fetch'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:320:in `transaction'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:181:in `fetch'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `block in retrieve_work'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:79:in `block in server'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:65:in `block (2 levels) in with'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `handle_interrupt'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `block in with'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:78:in `server'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `retrieve_work'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:100:in `fetch'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:81:in `process_one'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:71:in `run'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:17:in `watchdog'
2023-12-07T17:10:25.504-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:26:in `block in safe_thread'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: Error fetching job: Faktory::TimeoutError
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:41:in `block in read_timeout'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:38:in `loop'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:38:in `read_timeout'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/io.rb:23:in `gets'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:342:in `result'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:379:in `result!'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:183:in `block in fetch'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:320:in `transaction'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:181:in `fetch'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `block in retrieve_work'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:79:in `block in server'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:65:in `block (2 levels) in with'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `handle_interrupt'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `block in with'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:78:in `server'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `retrieve_work'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:100:in `fetch'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:81:in `process_one'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:71:in `run'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:17:in `watchdog'
2023-12-07T17:10:25.533-08:00	7 TID-2dak ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:26:in `block in safe_thread'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: Error fetching job: unexpected token at 'OK'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /usr/local/lib/ruby/3.2.0/json/common.rb:216:in `parse'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /usr/local/lib/ruby/3.2.0/json/common.rb:216:in `parse'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:185:in `fetch'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `block in retrieve_work'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:79:in `block in server'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:65:in `block (2 levels) in with'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `handle_interrupt'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `block in with'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:78:in `server'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `retrieve_work'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:100:in `fetch'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:81:in `process_one'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:71:in `run'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:17:in `watchdog'
2023-12-07T17:10:27.339-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:26:in `block in safe_thread'
2023-12-07T17:10:29.341-08:00	7 TID-2d9g INFO: Faktory is online, 3.857455488 sec downtime
2023-12-07T17:10:29.546-08:00	7 TID-2da0 INFO: Faktory is online, 4.042336297 sec downtime
2023-12-07T17:10:31.361-08:00	7 TID-2db4 INFO: Faktory is online, 4.02209626 sec downtime
2023-12-07T17:10:31.361-08:00	7 TID-2dak INFO: Faktory is online, 5.828125108 sec downtime
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: Error fetching job: unexpected token at 'OK'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /usr/local/lib/ruby/3.2.0/json/common.rb:216:in `parse'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /usr/local/lib/ruby/3.2.0/json/common.rb:216:in `parse'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:185:in `fetch'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `block in retrieve_work'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:79:in `block in server'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:65:in `block (2 levels) in with'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `handle_interrupt'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `block in with'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:78:in `server'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `retrieve_work'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:100:in `fetch'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:81:in `process_one'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:71:in `run'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:17:in `watchdog'
2023-12-07T17:10:40.496-08:00	7 TID-2db4 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:26:in `block in safe_thread'
2023-12-07T17:10:44.517-08:00	7 TID-2db4 INFO: Faktory is online, 4.021023754 sec downtime
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: Error fetching job: unexpected token at 'OK'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /usr/local/lib/ruby/3.2.0/json/common.rb:216:in `parse'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /usr/local/lib/ruby/3.2.0/json/common.rb:216:in `parse'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:185:in `fetch'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `block in retrieve_work'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:79:in `block in server'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:65:in `block (2 levels) in with'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `handle_interrupt'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `block in with'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:78:in `server'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `retrieve_work'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:100:in `fetch'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:81:in `process_one'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:71:in `run'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:17:in `watchdog'
2023-12-07T17:10:49.581-08:00	7 TID-2dbo ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:26:in `block in safe_thread'
2023-12-07T17:10:52.587-08:00	7 TID-2dbo INFO: Faktory is online, 3.006070199 sec downtime
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: Error fetching job: unexpected token at 'OK'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /usr/local/lib/ruby/3.2.0/json/common.rb:216:in `parse'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /usr/local/lib/ruby/3.2.0/json/common.rb:216:in `parse'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/client.rb:185:in `fetch'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `block in retrieve_work'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:79:in `block in server'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:65:in `block (2 levels) in with'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `handle_interrupt'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `block in with'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory.rb:78:in `server'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/fetch.rb:26:in `retrieve_work'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:100:in `fetch'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:81:in `process_one'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/processor.rb:71:in `run'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:17:in `watchdog'
2023-12-07T17:11:10.752-08:00	7 TID-2da0 ERROR: /rails/vendor/ruby/3.2.0/gems/faktory_worker_ruby-1.2.0/lib/faktory/util.rb:26:in `block in safe_thread'
2023-12-07T17:11:16.775-08:00	7 TID-2da0 INFO: Faktory is online, 6.023234352 sec downtime
2023-12-07T17:11:23.790-08:00

7 TID-2dak ERROR: Error fetching job: unexpected token at 'OK'
7 TID-2dak ERROR: Error fetching job: unexpected token at 'OK'