search

taskforcesh / bullmq

BullMQ - Message Queue and Batch processing for NodeJS and Python based on Redis
https://bullmq.io
MIT License
6.16k stars 405 forks source link

[Bug]: Worker stopped processing jobs, and mostly delayed Jobs #2466

Closed wernermorgenstern closed 4 months ago

wernermorgenstern commented 8 months ago

Version

v5.4.2

Platform

NodeJS

What happened?

We have a service, where a worker runs, and processes jobs. After the processing is done, it will create another job, which is delayed (around 64 minutes). Today, I noticed that the service and worker stopped processing jobs. There were no error messages in the logs. When I used BullBoard (I use it as a UI to see jobs), I saw the jobs were still in the delayed state, and like 24 hours overdue.

When I restarted the service, and the worker started, it immediately started processing those delayed jobs. This is not the first it happened. Today I though first checked the delayed jobs.

In today's incident, the service has been running for 4 days.

We run in EKS on AWS (NodeJS service, using Typescript). I use BullMQ Pro. And we are using Groups and each Group has a concurrency set to 1.

How to reproduce.

I don't have any test code for this

Relevant log output

No Logs or error logs were produced

Code of Conduct

ChrisLahaye commented 6 months ago

Hi @manast! We upgraded from 4.14.0 to 5.7.1 and are now experiencing this exact same bug. Jobs stay stuck in delayed until we restart the worker. Our redis version is 7.1.0.

manast commented 6 months ago

Hi @manast! We upgraded from 4.14.0 to 5.7.1 and are now experiencing this exact same bug. Jobs stay stuck in delayed until we restart the worker. Our redis version is 7.1.0.

Do you have any additional information that can help us investigate the issue? Like I write here for example: https://github.com/taskforcesh/bullmq/issues/2466#issuecomment-2039660908

ChrisLahaye commented 6 months ago

Hi @manast! We upgraded from 4.14.0 to 5.7.1 and are now experiencing this exact same bug. Jobs stay stuck in delayed until we restart the worker. Our redis version is 7.1.0.

Do you have any additional information that can help us investigate the issue? Like I write here for example: #2466 (comment)

Unfortunately I don't have more information. According to bull-board the job is scheduled for a time that is in the past, but it won't run until restarting the worker process. I will roll out the latest version and look for BZPOPMIN commands once the issue starts appearing.

ChrisLahaye commented 6 months ago

@manast I have some logs grepped on the queue name ingress:avalanche.

1713444562.989196 [2 10.0.244.85:50236] "evalsha" "06d4f5e167f90874bcdd2976c56ef657191cbb11" "6" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:id" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:events" "\x99\xb7bull:ingress:avalanche:\xa0\xa1*\xcbBx\xef\x14\x12\x82\xc0\x00\xc0\xc0\xc0\xc0\xc0" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44358230,\"timestamp\":1713444557},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "\xde\x00\x06\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xff\xa5delay\xcd\x03\xe8\xa7backoff\xde\x00\x01\xa4type\xa6custom\xb0removeOnComplete\xc3\xacremoveOnFail\xc3\xa5jobId\xc0"
1713444562.989289 [2 lua] "INCR" "bull:ingress:avalanche:id"
1713444562.989307 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713444562.989350 [2 lua] "HMSET" "bull:ingress:avalanche:149094" "name" "*" "data" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44358230,\"timestamp\":1713444557},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "opts" "{\"backoff\":{\"type\":\"custom\"},\"removeOnFail\":true,\"removeOnComplete\":true,\"delay\":1000,\"attempts\":1.7976931348623e+308}" "timestamp" "1713444562988" "delay" "1000" "priority" "0"
1713444562.989394 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "added" "jobId" "149094" "name" "*"
1713444562.989413 [2 lua] "ZADD" "bull:ingress:avalanche:delayed" "7018268934096486" "149094"
1713444562.989427 [2 lua] "XADD" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000" "*" "event" "delayed" "jobId" "149094" "delay" "1713444563988"
1713444562.989439 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713444562.989451 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713444562.989466 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "1713444563988.3999" "1"
1713444562.990414 [2 10.0.244.85:50452] "evalsha" "ac6eda8493b217849bcc9a04125ec35328e13012" "14" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:149093" "bull:ingress:avalanche:metrics:completed" "bull:ingress:avalanche:marker" "149093" "1713444562989" "returnvalue" "null" "completed" "1" "bull:ingress:avalanche:" "\xde\x00\t\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:210401\xa8keepJobs\xde\x00\x01\xa5count\x00\xa7limiter\xc0\xaclockDuration\xcdu0\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xb0\xaemaxMetricsSize\xa0\xa4fpof\xc2\xa4idof\xc2\xa4rdof\xc2"
1713444562.990503 [2 lua] "EXISTS" "bull:ingress:avalanche:149093"
1713444562.990520 [2 lua] "GET" "bull:ingress:avalanche:149093:lock"
1713444562.990531 [2 lua] "DEL" "bull:ingress:avalanche:149093:lock"
1713444562.990538 [2 lua] "SREM" "bull:ingress:avalanche:stalled" "149093"
1713444562.990544 [2 lua] "SCARD" "bull:ingress:avalanche:149093:dependencies"
1713444562.990552 [2 lua] "HMGET" "bull:ingress:avalanche:149093" "parentKey" "parent"
1713444562.990566 [2 lua] "LREM" "bull:ingress:avalanche:active" "-1" "149093"
1713444562.990575 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713444562.990583 [2 lua] "XTRIM" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000"
1713444562.990593 [2 lua] "HINCRBY" "bull:ingress:avalanche:149093" "atm" "1"
1713444562.990607 [2 lua] "DEL" "bull:ingress:avalanche:149093" "bull:ingress:avalanche:149093:logs" "bull:ingress:avalanche:149093:dependencies" "bull:ingress:avalanche:149093:processed" "bull:ingress:avalanche:149093:failed"
1713444562.990629 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "completed" "jobId" "149093" "returnvalue" "null"
1713444562.990640 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713444562.990655 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018268930007040" "LIMIT" "0" "1000"
1713444562.990666 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713444562.990676 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713444562.990681 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713444562.990689 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713444562.991331 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.997"
1713444562.992672 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713444562992" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:210402\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713444562.992751 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713444562.992771 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018268930019328" "LIMIT" "0" "1000"
1713444562.992783 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713444562.992792 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713444562.992799 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713444562.992809 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713444562.993403 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.995"
1713444562.994151 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.995"
1713444564.003089 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713444564002" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:210404\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713444564.003255 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713444564.003298 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018268934156288" "LIMIT" "0" "1000"
1713444564.003317 [2 lua] "ZREM" "bull:ingress:avalanche:delayed" "149094"
1713444564.003330 [2 lua] "HGET" "bull:ingress:avalanche:149094" "priority"
1713444564.003344 [2 lua] "LPUSH" "bull:ingress:avalanche:wait" "149094"
1713444564.003356 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "0" "0"
1713444564.003373 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "waiting" "jobId" "149094" "prev" "delayed"
1713444564.003385 [2 lua] "HSET" "bull:ingress:avalanche:149094" "delay" "0"
1713444564.003399 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713444564.003417 [2 lua] "SET" "bull:ingress:avalanche:149094:lock" "7eaa5009-4183-408b-ac79-7326e73d3c72:210404" "PX" "30000"
1713444564.003431 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "active" "jobId" "149094" "prev" "waiting"
1713444564.003468 [2 lua] "HSET" "bull:ingress:avalanche:149094" "processedOn" "1713444564002"
1713444564.003478 [2 lua] "HINCRBY" "bull:ingress:avalanche:149094" "ats" "1"
1713444564.003489 [2 lua] "HGETALL" "bull:ingress:avalanche:149094"
1713444564.157597 [2 10.0.244.85:50236] "evalsha" "06d4f5e167f90874bcdd2976c56ef657191cbb11" "6" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:id" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:events" "\x99\xb7bull:ingress:avalanche:\xa0\xa1*\xcbBx\xef\x14\x12\xcb\xd0\x00\xc0\xc0\xc0\xc0\xc0" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44358230,\"timestamp\":1713444557},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "\xde\x00\x06\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xff\xa5delay\xcd\x03\xe8\xa7backoff\xde\x00\x01\xa4type\xa6custom\xb0removeOnComplete\xc3\xacremoveOnFail\xc3\xa5jobId\xc0"
1713444564.157687 [2 lua] "INCR" "bull:ingress:avalanche:id"
1713444564.157699 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713444564.157741 [2 lua] "HMSET" "bull:ingress:avalanche:149095" "name" "*" "data" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44358230,\"timestamp\":1713444557},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "opts" "{\"backoff\":{\"type\":\"custom\"},\"removeOnFail\":true,\"removeOnComplete\":true,\"delay\":1000,\"attempts\":1.7976931348623e+308}" "timestamp" "1713444564157" "delay" "1000" "priority" "0"
1713444564.157785 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "added" "jobId" "149095" "name" "*"
1713444564.157803 [2 lua] "ZADD" "bull:ingress:avalanche:delayed" "7018268938884711" "149095"
1713444564.157820 [2 lua] "XADD" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000" "*" "event" "delayed" "jobId" "149095" "delay" "1713444565157"
1713444564.157833 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713444564.157844 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713444564.157859 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "1713444565157.4001" "1"
1713444564.158798 [2 10.0.244.85:50452] "evalsha" "ac6eda8493b217849bcc9a04125ec35328e13012" "14" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:149094" "bull:ingress:avalanche:metrics:completed" "bull:ingress:avalanche:marker" "149094" "1713444564158" "returnvalue" "null" "completed" "1" "bull:ingress:avalanche:" "\xde\x00\t\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:210404\xa8keepJobs\xde\x00\x01\xa5count\x00\xa7limiter\xc0\xaclockDuration\xcdu0\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xb0\xaemaxMetricsSize\xa0\xa4fpof\xc2\xa4idof\xc2\xa4rdof\xc2"
1713444564.158889 [2 lua] "EXISTS" "bull:ingress:avalanche:149094"
1713444564.158906 [2 lua] "GET" "bull:ingress:avalanche:149094:lock"
1713444564.158915 [2 lua] "DEL" "bull:ingress:avalanche:149094:lock"
1713444564.158922 [2 lua] "SREM" "bull:ingress:avalanche:stalled" "149094"
1713444564.158928 [2 lua] "SCARD" "bull:ingress:avalanche:149094:dependencies"
1713444564.158936 [2 lua] "HMGET" "bull:ingress:avalanche:149094" "parentKey" "parent"
1713444564.158950 [2 lua] "LREM" "bull:ingress:avalanche:active" "-1" "149094"
1713444564.158958 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713444564.158967 [2 lua] "XTRIM" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000"
1713444564.158977 [2 lua] "HINCRBY" "bull:ingress:avalanche:149094" "atm" "1"
1713444564.158996 [2 lua] "DEL" "bull:ingress:avalanche:149094" "bull:ingress:avalanche:149094:logs" "bull:ingress:avalanche:149094:dependencies" "bull:ingress:avalanche:149094:processed" "bull:ingress:avalanche:149094:failed"
1713444564.159019 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "completed" "jobId" "149094" "returnvalue" "null"
1713444564.159030 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713444564.159045 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018268934795264" "LIMIT" "0" "1000"
1713444564.159056 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713444564.159065 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713444564.159070 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713444564.159078 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713444564.159723 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.998"
1713444564.160622 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713444564160" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:210405\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713444564.160688 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713444564.160704 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018268934803456" "LIMIT" "0" "1000"
1713444564.160715 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713444564.160723 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713444564.160730 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713444564.160738 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713444564.161293 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.996"
1713444564.162011 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.996"

Does this help?

manast commented 6 months ago

What happens after the last call to bzpopmin ?

manast commented 6 months ago

What I mean, does it just get stuck there or more commands are coming afterwards?

ChrisLahaye commented 6 months ago

@manast Sorry for cutting the log at such a bad line.

1713469356.077448 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469356076" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271793\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469356.077548 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469356.077578 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370482491392" "LIMIT" "0" "1000"
1713469356.077601 [2 lua] "ZREM" "bull:ingress:avalanche:delayed" "169553"
1713469356.077616 [2 lua] "HGET" "bull:ingress:avalanche:169553" "priority"
1713469356.077638 [2 lua] "LPUSH" "bull:ingress:avalanche:wait" "169553"
1713469356.077656 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "0" "0"
1713469356.077675 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "waiting" "jobId" "169553" "prev" "delayed"
1713469356.077689 [2 lua] "HSET" "bull:ingress:avalanche:169553" "delay" "0"
1713469356.077703 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469356.077725 [2 lua] "SET" "bull:ingress:avalanche:169553:lock" "7eaa5009-4183-408b-ac79-7326e73d3c72:271793" "PX" "30000"
1713469356.077740 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "active" "jobId" "169553" "prev" "waiting"
1713469356.077749 [2 lua] "HSET" "bull:ingress:avalanche:169553" "processedOn" "1713469356076"
1713469356.077759 [2 lua] "HINCRBY" "bull:ingress:avalanche:169553" "ats" "1"
1713469356.077770 [2 lua] "HGETALL" "bull:ingress:avalanche:169553"
1713469356.254079 [2 10.0.244.85:50236] "evalsha" "06d4f5e167f90874bcdd2976c56ef657191cbb11" "6" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:id" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:events" "\x99\xb7bull:ingress:avalanche:\xa0\xa1*\xcbBx\xef+\xb7\x8d\xd0\x00\xc0\xc0\xc0\xc0\xc0" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370020,\"timestamp\":1713469351},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "\xde\x00\x06\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xff\xa5delay\xcd\x03\xe8\xa7backoff\xde\x00\x01\xa4type\xa6custom\xb0removeOnComplete\xc3\xacremoveOnFail\xc3\xa5jobId\xc0"
1713469356.254185 [2 lua] "INCR" "bull:ingress:avalanche:id"
1713469356.254200 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469356.254243 [2 lua] "HMSET" "bull:ingress:avalanche:169554" "name" "*" "data" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370020,\"timestamp\":1713469351},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "opts" "{\"backoff\":{\"type\":\"custom\"},\"removeOnFail\":true,\"removeOnComplete\":true,\"delay\":1000,\"attempts\":1.7976931348623e+308}" "timestamp" "1713469356253" "delay" "1000" "priority" "0"
1713469356.254296 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "added" "jobId" "169554" "name" "*"
1713469356.254315 [2 lua] "ZADD" "bull:ingress:avalanche:delayed" "7018370487309906" "169554"
1713469356.254331 [2 lua] "XADD" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000" "*" "event" "delayed" "jobId" "169554" "delay" "1713469357253"
1713469356.254344 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469356.254358 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469356.254375 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "1713469357253.395" "1"
1713469356.255331 [2 10.0.244.85:50452] "evalsha" "ac6eda8493b217849bcc9a04125ec35328e13012" "14" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:169553" "bull:ingress:avalanche:metrics:completed" "bull:ingress:avalanche:marker" "169553" "1713469356254" "returnvalue" "null" "completed" "1" "bull:ingress:avalanche:" "\xde\x00\t\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271793\xa8keepJobs\xde\x00\x01\xa5count\x00\xa7limiter\xc0\xaclockDuration\xcdu0\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xb0\xaemaxMetricsSize\xa0\xa4fpof\xc2\xa4idof\xc2\xa4rdof\xc2"
1713469356.255433 [2 lua] "EXISTS" "bull:ingress:avalanche:169553"
1713469356.255452 [2 lua] "GET" "bull:ingress:avalanche:169553:lock"
1713469356.255462 [2 lua] "DEL" "bull:ingress:avalanche:169553:lock"
1713469356.255469 [2 lua] "SREM" "bull:ingress:avalanche:stalled" "169553"
1713469356.255477 [2 lua] "SCARD" "bull:ingress:avalanche:169553:dependencies"
1713469356.255485 [2 lua] "HMGET" "bull:ingress:avalanche:169553" "parentKey" "parent"
1713469356.255502 [2 lua] "LREM" "bull:ingress:avalanche:active" "-1" "169553"
1713469356.255510 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469356.255520 [2 lua] "XTRIM" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000"
1713469356.255530 [2 lua] "HINCRBY" "bull:ingress:avalanche:169553" "atm" "1"
1713469356.255544 [2 lua] "DEL" "bull:ingress:avalanche:169553" "bull:ingress:avalanche:169553:logs" "bull:ingress:avalanche:169553:dependencies" "bull:ingress:avalanche:169553:processed" "bull:ingress:avalanche:169553:failed"
1713469356.255568 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "completed" "jobId" "169553" "returnvalue" "null"
1713469356.255579 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469356.255594 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370483220480" "LIMIT" "0" "1000"
1713469356.255605 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469356.255615 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469356.255621 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469356.255629 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469356.256357 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.997"
1713469356.259215 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469356258" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271794\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469356.259303 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469356.259327 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370483236864" "LIMIT" "0" "1000"
1713469356.259344 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469356.259353 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469356.259360 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469356.259370 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469356.259993 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.994"
1713469356.260748 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.993"

1713469357.283427 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469357282" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271796\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469357.283537 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469357.283571 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370487431168" "LIMIT" "0" "1000"
1713469357.283591 [2 lua] "ZREM" "bull:ingress:avalanche:delayed" "169554"
1713469357.283604 [2 lua] "HGET" "bull:ingress:avalanche:169554" "priority"
1713469357.283616 [2 lua] "LPUSH" "bull:ingress:avalanche:wait" "169554"
1713469357.283626 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "0" "0"
1713469357.283641 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "waiting" "jobId" "169554" "prev" "delayed"
1713469357.283653 [2 lua] "HSET" "bull:ingress:avalanche:169554" "delay" "0"
1713469357.283665 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469357.283680 [2 lua] "SET" "bull:ingress:avalanche:169554:lock" "7eaa5009-4183-408b-ac79-7326e73d3c72:271796" "PX" "30000"
1713469357.283699 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "active" "jobId" "169554" "prev" "waiting"
1713469357.283708 [2 lua] "HSET" "bull:ingress:avalanche:169554" "processedOn" "1713469357282"
1713469357.283718 [2 lua] "HINCRBY" "bull:ingress:avalanche:169554" "ats" "1"
1713469357.283735 [2 lua] "HGETALL" "bull:ingress:avalanche:169554"
1713469357.482102 [2 10.0.244.85:50236] "evalsha" "06d4f5e167f90874bcdd2976c56ef657191cbb11" "6" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:id" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:events" "\x99\xb7bull:ingress:avalanche:\xa0\xa1*\xcbBx\xef+\xb7\xda\x90\x00\xc0\xc0\xc0\xc0\xc0" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370020,\"timestamp\":1713469351},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "\xde\x00\x06\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xff\xa5delay\xcd\x03\xe8\xa7backoff\xde\x00\x01\xa4type\xa6custom\xb0removeOnComplete\xc3\xacremoveOnFail\xc3\xa5jobId\xc0"
1713469357.482206 [2 lua] "INCR" "bull:ingress:avalanche:id"
1713469357.482220 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469357.482262 [2 lua] "HMSET" "bull:ingress:avalanche:169555" "name" "*" "data" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370020,\"timestamp\":1713469351},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "opts" "{\"backoff\":{\"type\":\"custom\"},\"removeOnFail\":true,\"removeOnComplete\":true,\"delay\":1000,\"attempts\":1.7976931348623e+308}" "timestamp" "1713469357481" "delay" "1000" "priority" "0"
1713469357.482306 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "added" "jobId" "169555" "name" "*"
1713469357.482324 [2 lua] "ZADD" "bull:ingress:avalanche:delayed" "7018370492339795" "169555"
1713469357.482340 [2 lua] "XADD" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000" "*" "event" "delayed" "jobId" "169555" "delay" "1713469358481"
1713469357.482352 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469357.482364 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469357.482378 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "1713469358481.3953" "1"
1713469357.483350 [2 10.0.244.85:50452] "evalsha" "ac6eda8493b217849bcc9a04125ec35328e13012" "14" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:169554" "bull:ingress:avalanche:metrics:completed" "bull:ingress:avalanche:marker" "169554" "1713469357482" "returnvalue" "null" "completed" "1" "bull:ingress:avalanche:" "\xde\x00\t\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271796\xa8keepJobs\xde\x00\x01\xa5count\x00\xa7limiter\xc0\xaclockDuration\xcdu0\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xb0\xaemaxMetricsSize\xa0\xa4fpof\xc2\xa4idof\xc2\xa4rdof\xc2"
1713469357.483443 [2 lua] "EXISTS" "bull:ingress:avalanche:169554"
1713469357.483459 [2 lua] "GET" "bull:ingress:avalanche:169554:lock"
1713469357.483467 [2 lua] "DEL" "bull:ingress:avalanche:169554:lock"
1713469357.483474 [2 lua] "SREM" "bull:ingress:avalanche:stalled" "169554"
1713469357.483480 [2 lua] "SCARD" "bull:ingress:avalanche:169554:dependencies"
1713469357.483488 [2 lua] "HMGET" "bull:ingress:avalanche:169554" "parentKey" "parent"
1713469357.483503 [2 lua] "LREM" "bull:ingress:avalanche:active" "-1" "169554"
1713469357.483511 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469357.483519 [2 lua] "XTRIM" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000"
1713469357.483529 [2 lua] "HINCRBY" "bull:ingress:avalanche:169554" "atm" "1"
1713469357.483543 [2 lua] "DEL" "bull:ingress:avalanche:169554" "bull:ingress:avalanche:169554:logs" "bull:ingress:avalanche:169554:dependencies" "bull:ingress:avalanche:169554:processed" "bull:ingress:avalanche:169554:failed"
1713469357.483566 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "completed" "jobId" "169554" "returnvalue" "null"
1713469357.483577 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469357.483591 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370488250368" "LIMIT" "0" "1000"
1713469357.483602 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469357.483612 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469357.483617 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469357.483625 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469357.484300 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.997"
1713469357.485116 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469357484" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271797\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469357.485194 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469357.485210 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370488258560" "LIMIT" "0" "1000"
1713469357.485221 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469357.485229 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469357.485236 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469357.485244 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469357.485825 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.996"
1713469357.486521 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.995"

1713469358.490691 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469358490" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271799\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469358.490777 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469358.490804 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370492379136" "LIMIT" "0" "1000"
1713469358.490823 [2 lua] "ZREM" "bull:ingress:avalanche:delayed" "169555"
1713469358.490834 [2 lua] "HGET" "bull:ingress:avalanche:169555" "priority"
1713469358.490846 [2 lua] "LPUSH" "bull:ingress:avalanche:wait" "169555"
1713469358.490857 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "0" "0"
1713469358.490871 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "waiting" "jobId" "169555" "prev" "delayed"
1713469358.490883 [2 lua] "HSET" "bull:ingress:avalanche:169555" "delay" "0"
1713469358.490896 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469358.490912 [2 lua] "SET" "bull:ingress:avalanche:169555:lock" "7eaa5009-4183-408b-ac79-7326e73d3c72:271799" "PX" "30000"
1713469358.490927 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "active" "jobId" "169555" "prev" "waiting"
1713469358.490937 [2 lua] "HSET" "bull:ingress:avalanche:169555" "processedOn" "1713469358490"
1713469358.490946 [2 lua] "HINCRBY" "bull:ingress:avalanche:169555" "ats" "1"
1713469358.490957 [2 lua] "HGETALL" "bull:ingress:avalanche:169555"
1713469358.676507 [2 10.0.244.85:50236] "evalsha" "06d4f5e167f90874bcdd2976c56ef657191cbb11" "6" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:id" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:events" "\x99\xb7bull:ingress:avalanche:\xa0\xa1*\xcbBx\xef+\xb8%@\x00\xc0\xc0\xc0\xc0\xc0" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370020,\"timestamp\":1713469351},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "\xde\x00\x06\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xff\xa5delay\xcd\x03\xe8\xa7backoff\xde\x00\x01\xa4type\xa6custom\xb0removeOnComplete\xc3\xacremoveOnFail\xc3\xa5jobId\xc0"
1713469358.676601 [2 lua] "INCR" "bull:ingress:avalanche:id"
1713469358.676615 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469358.676656 [2 lua] "HMSET" "bull:ingress:avalanche:169556" "name" "*" "data" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370020,\"timestamp\":1713469351},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "opts" "{\"backoff\":{\"type\":\"custom\"},\"removeOnFail\":true,\"removeOnComplete\":true,\"delay\":1000,\"attempts\":1.7976931348623e+308}" "timestamp" "1713469358676" "delay" "1000" "priority" "0"
1713469358.676701 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "added" "jobId" "169556" "name" "*"
1713469358.676719 [2 lua] "ZADD" "bull:ingress:avalanche:delayed" "7018370497234516" "169556"
1713469358.676734 [2 lua] "XADD" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000" "*" "event" "delayed" "jobId" "169556" "delay" "1713469359676"
1713469358.676746 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469358.676758 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469358.676772 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "1713469359676.3955" "1"
1713469358.678145 [2 10.0.244.85:50452] "evalsha" "ac6eda8493b217849bcc9a04125ec35328e13012" "14" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:169555" "bull:ingress:avalanche:metrics:completed" "bull:ingress:avalanche:marker" "169555" "1713469358677" "returnvalue" "null" "completed" "1" "bull:ingress:avalanche:" "\xde\x00\t\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271799\xa8keepJobs\xde\x00\x01\xa5count\x00\xa7limiter\xc0\xaclockDuration\xcdu0\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xb0\xaemaxMetricsSize\xa0\xa4fpof\xc2\xa4idof\xc2\xa4rdof\xc2"
1713469358.678222 [2 lua] "EXISTS" "bull:ingress:avalanche:169555"
1713469358.678234 [2 lua] "GET" "bull:ingress:avalanche:169555:lock"
1713469358.678240 [2 lua] "DEL" "bull:ingress:avalanche:169555:lock"
1713469358.678246 [2 lua] "SREM" "bull:ingress:avalanche:stalled" "169555"
1713469358.678252 [2 lua] "SCARD" "bull:ingress:avalanche:169555:dependencies"
1713469358.678260 [2 lua] "HMGET" "bull:ingress:avalanche:169555" "parentKey" "parent"
1713469358.678271 [2 lua] "LREM" "bull:ingress:avalanche:active" "-1" "169555"
1713469358.678278 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469358.678288 [2 lua] "XTRIM" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000"
1713469358.678297 [2 lua] "HINCRBY" "bull:ingress:avalanche:169555" "atm" "1"
1713469358.678310 [2 lua] "DEL" "bull:ingress:avalanche:169555" "bull:ingress:avalanche:169555:logs" "bull:ingress:avalanche:169555:dependencies" "bull:ingress:avalanche:169555:processed" "bull:ingress:avalanche:169555:failed"
1713469358.678331 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "completed" "jobId" "169555" "returnvalue" "null"
1713469358.678341 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469358.678352 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370493145088" "LIMIT" "0" "1000"
1713469358.678362 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469358.678371 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469358.678376 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469358.678384 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469358.679450 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.997"
1713469358.681031 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469358680" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271800\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469358.681098 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469358.681113 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370493157376" "LIMIT" "0" "1000"
1713469358.681124 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469358.681132 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469358.681139 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469358.681147 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469358.681766 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.995"
1713469358.682477 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.994"

1713469359.699194 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469359698" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271802\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469359.699249 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469359.699263 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370497327104" "LIMIT" "0" "1000"
1713469359.699274 [2 lua] "ZREM" "bull:ingress:avalanche:delayed" "169556"
1713469359.699281 [2 lua] "HGET" "bull:ingress:avalanche:169556" "priority"
1713469359.699288 [2 lua] "LPUSH" "bull:ingress:avalanche:wait" "169556"
1713469359.699296 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "0" "0"
1713469359.699306 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "waiting" "jobId" "169556" "prev" "delayed"
1713469359.699315 [2 lua] "HSET" "bull:ingress:avalanche:169556" "delay" "0"
1713469359.699324 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469359.699337 [2 lua] "SET" "bull:ingress:avalanche:169556:lock" "7eaa5009-4183-408b-ac79-7326e73d3c72:271802" "PX" "30000"
1713469359.699351 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "active" "jobId" "169556" "prev" "waiting"
1713469359.699360 [2 lua] "HSET" "bull:ingress:avalanche:169556" "processedOn" "1713469359698"
1713469359.699368 [2 lua] "HINCRBY" "bull:ingress:avalanche:169556" "ats" "1"
1713469359.699376 [2 lua] "HGETALL" "bull:ingress:avalanche:169556"
1713469359.865009 [2 10.0.244.85:50236] "evalsha" "06d4f5e167f90874bcdd2976c56ef657191cbb11" "6" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:id" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:events" "\x99\xb7bull:ingress:avalanche:\xa0\xa1*\xcbBx\xef+\xb8o\x80\x00\xc0\xc0\xc0\xc0\xc0" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370020,\"timestamp\":1713469351},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "\xde\x00\x06\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xff\xa5delay\xcd\x03\xe8\xa7backoff\xde\x00\x01\xa4type\xa6custom\xb0removeOnComplete\xc3\xacremoveOnFail\xc3\xa5jobId\xc0"
1713469359.865101 [2 lua] "INCR" "bull:ingress:avalanche:id"
1713469359.865115 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469359.865160 [2 lua] "HMSET" "bull:ingress:avalanche:169557" "name" "*" "data" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370020,\"timestamp\":1713469351},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "opts" "{\"backoff\":{\"type\":\"custom\"},\"removeOnFail\":true,\"removeOnComplete\":true,\"delay\":1000,\"attempts\":1.7976931348623e+308}" "timestamp" "1713469359864" "delay" "1000" "priority" "0"
1713469359.865204 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "added" "jobId" "169557" "name" "*"
1713469359.865223 [2 lua] "ZADD" "bull:ingress:avalanche:delayed" "7018370502100565" "169557"
1713469359.865238 [2 lua] "XADD" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000" "*" "event" "delayed" "jobId" "169557" "delay" "1713469360864"
1713469359.865249 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469359.865265 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469359.865279 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "1713469360864.3958" "1"
1713469359.866151 [2 10.0.244.85:50452] "evalsha" "ac6eda8493b217849bcc9a04125ec35328e13012" "14" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:169556" "bull:ingress:avalanche:metrics:completed" "bull:ingress:avalanche:marker" "169556" "1713469359865" "returnvalue" "null" "completed" "1" "bull:ingress:avalanche:" "\xde\x00\t\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271802\xa8keepJobs\xde\x00\x01\xa5count\x00\xa7limiter\xc0\xaclockDuration\xcdu0\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xb0\xaemaxMetricsSize\xa0\xa4fpof\xc2\xa4idof\xc2\xa4rdof\xc2"
1713469359.866244 [2 lua] "EXISTS" "bull:ingress:avalanche:169556"
1713469359.866262 [2 lua] "GET" "bull:ingress:avalanche:169556:lock"
1713469359.866271 [2 lua] "DEL" "bull:ingress:avalanche:169556:lock"
1713469359.866278 [2 lua] "SREM" "bull:ingress:avalanche:stalled" "169556"
1713469359.866285 [2 lua] "SCARD" "bull:ingress:avalanche:169556:dependencies"
1713469359.866292 [2 lua] "HMGET" "bull:ingress:avalanche:169556" "parentKey" "parent"
1713469359.866309 [2 lua] "LREM" "bull:ingress:avalanche:active" "-1" "169556"
1713469359.866317 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469359.866327 [2 lua] "XTRIM" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000"
1713469359.866337 [2 lua] "HINCRBY" "bull:ingress:avalanche:169556" "atm" "1"
1713469359.866350 [2 lua] "DEL" "bull:ingress:avalanche:169556" "bull:ingress:avalanche:169556:logs" "bull:ingress:avalanche:169556:dependencies" "bull:ingress:avalanche:169556:processed" "bull:ingress:avalanche:169556:failed"
1713469359.866373 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "completed" "jobId" "169556" "returnvalue" "null"
1713469359.866384 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469359.866399 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370498011136" "LIMIT" "0" "1000"
1713469359.866410 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469359.866420 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469359.866425 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469359.866433 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469359.867050 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.998"
1713469359.867860 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469359867" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271803\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469359.867933 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469359.867951 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370498019328" "LIMIT" "0" "1000"
1713469359.867963 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469359.867971 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469359.867978 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469359.867987 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469359.868554 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.996"
1713469359.869238 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.996"

1713469360.905584 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469360905" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271805\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469360.905686 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469360.905718 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370502270976" "LIMIT" "0" "1000"
1713469360.905736 [2 lua] "ZREM" "bull:ingress:avalanche:delayed" "169557"
1713469360.905749 [2 lua] "HGET" "bull:ingress:avalanche:169557" "priority"
1713469360.905763 [2 lua] "LPUSH" "bull:ingress:avalanche:wait" "169557"
1713469360.905774 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "0" "0"
1713469360.905790 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "waiting" "jobId" "169557" "prev" "delayed"
1713469360.905802 [2 lua] "HSET" "bull:ingress:avalanche:169557" "delay" "0"
1713469360.905814 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469360.905844 [2 lua] "SET" "bull:ingress:avalanche:169557:lock" "7eaa5009-4183-408b-ac79-7326e73d3c72:271805" "PX" "30000"
1713469360.905860 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "active" "jobId" "169557" "prev" "waiting"
1713469360.905870 [2 lua] "HSET" "bull:ingress:avalanche:169557" "processedOn" "1713469360905"
1713469360.905880 [2 lua] "HINCRBY" "bull:ingress:avalanche:169557" "ats" "1"
1713469360.905890 [2 lua] "HGETALL" "bull:ingress:avalanche:169557"
1713469361.094271 [2 10.0.244.85:50236] "evalsha" "06d4f5e167f90874bcdd2976c56ef657191cbb11" "6" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:id" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:events" "\x99\xb7bull:ingress:avalanche:\xa0\xa1*\xcbBx\xef+\xb8\xbcP\x00\xc0\xc0\xc0\xc0\xc0" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370022,\"timestamp\":1713469355},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "\xde\x00\x06\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xff\xa5delay\xcd\x03\xe8\xa7backoff\xde\x00\x01\xa4type\xa6custom\xb0removeOnComplete\xc3\xacremoveOnFail\xc3\xa5jobId\xc0"
1713469361.094366 [2 lua] "INCR" "bull:ingress:avalanche:id"
1713469361.094381 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469361.094423 [2 lua] "HMSET" "bull:ingress:avalanche:169558" "name" "*" "data" "{\"persist\":false,\"meta\":{\"block\":{\"number\":44370022,\"timestamp\":1713469355},\"hasIndexingErrors\":false},\"tokens_createdAt_gt\":\"1694448827\"}" "opts" "{\"backoff\":{\"type\":\"custom\"},\"removeOnFail\":true,\"removeOnComplete\":true,\"delay\":1000,\"attempts\":1.7976931348623e+308}" "timestamp" "1713469361093" "delay" "1000" "priority" "0"
1713469361.094468 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "added" "jobId" "169558" "name" "*"
1713469361.094488 [2 lua] "ZADD" "bull:ingress:avalanche:delayed" "7018370507134550" "169558"
1713469361.094504 [2 lua] "XADD" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000" "*" "event" "delayed" "jobId" "169558" "delay" "1713469362093"
1713469361.094516 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469361.094528 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469361.094542 [2 lua] "ZADD" "bull:ingress:avalanche:marker" "1713469362093.396" "1"
1713469361.095448 [2 10.0.244.85:50452] "evalsha" "ac6eda8493b217849bcc9a04125ec35328e13012" "14" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:completed" "bull:ingress:avalanche:169557" "bull:ingress:avalanche:metrics:completed" "bull:ingress:avalanche:marker" "169557" "1713469361095" "returnvalue" "null" "completed" "1" "bull:ingress:avalanche:" "\xde\x00\t\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271805\xa8keepJobs\xde\x00\x01\xa5count\x00\xa7limiter\xc0\xaclockDuration\xcdu0\xa8attempts\xcb\x7f\xef\xff\xff\xff\xff\xff\xb0\xaemaxMetricsSize\xa0\xa4fpof\xc2\xa4idof\xc2\xa4rdof\xc2"
1713469361.095534 [2 lua] "EXISTS" "bull:ingress:avalanche:169557"
1713469361.095549 [2 lua] "GET" "bull:ingress:avalanche:169557:lock"
1713469361.095558 [2 lua] "DEL" "bull:ingress:avalanche:169557:lock"
1713469361.095564 [2 lua] "SREM" "bull:ingress:avalanche:stalled" "169557"
1713469361.095570 [2 lua] "SCARD" "bull:ingress:avalanche:169557:dependencies"
1713469361.095578 [2 lua] "HMGET" "bull:ingress:avalanche:169557" "parentKey" "parent"
1713469361.095592 [2 lua] "LREM" "bull:ingress:avalanche:active" "-1" "169557"
1713469361.095600 [2 lua] "HGET" "bull:ingress:avalanche:meta" "opts.maxLenEvents"
1713469361.095608 [2 lua] "XTRIM" "bull:ingress:avalanche:events" "MAXLEN" "~" "10000"
1713469361.095617 [2 lua] "HINCRBY" "bull:ingress:avalanche:169557" "atm" "1"
1713469361.095631 [2 lua] "DEL" "bull:ingress:avalanche:169557" "bull:ingress:avalanche:169557:logs" "bull:ingress:avalanche:169557:dependencies" "bull:ingress:avalanche:169557:processed" "bull:ingress:avalanche:169557:failed"
1713469361.095654 [2 lua] "XADD" "bull:ingress:avalanche:events" "*" "event" "completed" "jobId" "169557" "returnvalue" "null"
1713469361.095665 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469361.095678 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370503049216" "LIMIT" "0" "1000"
1713469361.095690 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469361.095699 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469361.095705 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469361.095712 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469361.096497 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.997"
1713469361.097317 [2 10.0.244.85:50452] "evalsha" "135a97538ee393c145e6d418b575b3aa1799c691" "11" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active" "bull:ingress:avalanche:prioritized" "bull:ingress:avalanche:events" "bull:ingress:avalanche:stalled" "bull:ingress:avalanche:limiter" "bull:ingress:avalanche:delayed" "bull:ingress:avalanche:paused" "bull:ingress:avalanche:meta" "bull:ingress:avalanche:pc" "bull:ingress:avalanche:marker" "bull:ingress:avalanche:" "1713469361096" "\xde\x00\x04\xa5token\xd9+7eaa5009-4183-408b-ac79-7326e73d3c72:271806\xaclockDuration\xcdu0\xa7limiter\xc0\xa4name\xc0"
1713469361.097385 [2 lua] "HEXISTS" "bull:ingress:avalanche:meta" "paused"
1713469361.097400 [2 lua] "ZRANGEBYSCORE" "bull:ingress:avalanche:delayed" "0" "7018370503053312" "LIMIT" "0" "1000"
1713469361.097412 [2 lua] "RPOPLPUSH" "bull:ingress:avalanche:wait" "bull:ingress:avalanche:active"
1713469361.097420 [2 lua] "ZPOPMIN" "bull:ingress:avalanche:prioritized"
1713469361.097430 [2 lua] "DEL" "bull:ingress:avalanche:pc"
1713469361.097438 [2 lua] "ZRANGE" "bull:ingress:avalanche:delayed" "0" "0" "WITHSCORES"
1713469361.098025 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.996"
1713469361.098715 [2 10.0.244.85:50454] "bzpopmin" "bull:ingress:avalanche:marker" "0.995"

I don't have the knowledge to fully interprete the commands but I did observe that they come in batches followed by a small delay. I entered a new line manually at the delay, this is after the double bzpopmin. This appears to be the repeating pattern.

manast commented 6 months ago

@ChrisLahaye thanks for the info!

manast commented 6 months ago

In the logs you pasted above I can see jobs are been completed actually. Are this logs produced when you say that no jobs are being processed?

ChrisLahaye commented 6 months ago

@manast Oops, I accidentally shared the logs for a working queue. The following logs is for a queue which isn't processing jobs.

1713519805.515271 [2 10.0.244.85:50398] "evalsha" "4d3d690062d87ee95eb0ee95beddf6b678c9000c" "9" "bull:ingress:optimism:stalled" "bull:ingress:optimism:wait" "bull:ingress:optimism:active" "bull:ingress:optimism:failed" "bull:ingress:optimism:stalled-check" "bull:ingress:optimism:meta" "bull:ingress:optimism:paused" "bull:ingress:optimism:marker" "bull:ingress:optimism:events" "1" "bull:ingress:optimism:" "1713519805514" "30000"
1713519805.515366 [2 lua] "EXISTS" "bull:ingress:optimism:stalled-check"
1713519805.515406 [2 lua] "SET" "bull:ingress:optimism:stalled-check" "1713519805514" "PX" "30000"
1713519805.515422 [2 lua] "HGET" "bull:ingress:optimism:meta" "opts.maxLenEvents"
1713519805.515435 [2 lua] "XTRIM" "bull:ingress:optimism:events" "MAXLEN" "~" "10000"
1713519805.515443 [2 lua] "SMEMBERS" "bull:ingress:optimism:stalled"
1713519805.515456 [2 lua] "LRANGE" "bull:ingress:optimism:active" "0" "-1"

1713519835.516088 [2 10.0.244.85:50398] "evalsha" "4d3d690062d87ee95eb0ee95beddf6b678c9000c" "9" "bull:ingress:optimism:stalled" "bull:ingress:optimism:wait" "bull:ingress:optimism:active" "bull:ingress:optimism:failed" "bull:ingress:optimism:stalled-check" "bull:ingress:optimism:meta" "bull:ingress:optimism:paused" "bull:ingress:optimism:marker" "bull:ingress:optimism:events" "1" "bull:ingress:optimism:" "1713519835515" "30000"
1713519835.516168 [2 lua] "EXISTS" "bull:ingress:optimism:stalled-check"
1713519835.516183 [2 lua] "SET" "bull:ingress:optimism:stalled-check" "1713519835515" "PX" "30000"
1713519835.516197 [2 lua] "HGET" "bull:ingress:optimism:meta" "opts.maxLenEvents"
1713519835.516208 [2 lua] "XTRIM" "bull:ingress:optimism:events" "MAXLEN" "~" "10000"
1713519835.516217 [2 lua] "SMEMBERS" "bull:ingress:optimism:stalled"
1713519835.516228 [2 lua] "LRANGE" "bull:ingress:optimism:active" "0" "-1"

This just keeps repeating. I verified the logs by comparing it with another queue which is also stuck and that one shows the same behavior.

manast commented 6 months ago

@ChrisLahaye could you also share the result of calling CLIENT LIST in a redis queue that is in this state?

manast commented 6 months ago

Also, you say that when the queue is in this state, if a new job is added, the worker will start processing jobs again right?

ChrisLahaye commented 6 months ago

@ChrisLahaye could you also share the result of calling CLIENT LIST in a redis queue that is in this state?

Do I need to use redis-cli and then execute the CLIENT LIST redis command? We have quite a lot of different queues and services using this redis instance. Could you provide some more detailed instructions to get the relevant data?

manast commented 6 months ago

@ChrisLahaye basically what we want is to see which was the latest command issued in the worker's client connection. Unfortunately the queue name is encoded in base64 in the client name so it is not easy to filter it out. But if you send us the complete output we can figure it out.

manast commented 6 months ago

So yes, redis-cli and then CLIENT LIST

ChrisLahaye commented 6 months ago

@manast 

id=467985 addr=10.0.244.85:50442 laddr=10.0.178.10:6379 fd=88 name=bull:aW5ncmVzczpvcHRpbWlzbQ== age=185012 idle=133054 flags=b db=2 sub=0 psub=0 ssub=0 multi=-1 qbuf=0 qbuf-free=0 argv-mem=41 multi-mem=0 rbs=1024 rbp=0 obl=0 oll=0 omem=0 tot-mem=2609 events=r cmd=bzpopmin user=default redir=-1 resp=2
manast commented 6 months ago

And as soon as you add a new job to this queue, the worker wakes up right?

manast commented 6 months ago

Our suspicion here is that it seems that bzpopmin is issuing a timeout value that Redis considers as timeout indefinitely... we are a bit puzzled by this as we are making sure to always use a value larger than 0.002

manast commented 6 months ago

(0.001 in older versions of Redis was considered also as indefinitely timeout as we suspect it was a bug that has been resolved but to be sure we use 0.002 (2ms) minimum timeout)

ChrisLahaye commented 6 months ago

And as soon as you add a new job to this queue, the worker wakes up right?

We haven't tested that. We create the initial job once and then this job keeps rescheduling itself but with different data. We use the following pattern,

const jobOptions: JobsOptions = {
  attempts: Number.MAX_VALUE,
  backoff: { type: 'custom' },
  delay: POLL_DELAY,
  removeOnComplete: true,
  removeOnFail: true,
};

async function processor({ data }: Job<JobData>) {
...
   await queue.add('*', nextData, jobOptions);
...
}

At some point it gets stuck and bull board shows that there is a scheduled job with a timestamp in the past. After restarting the process this job finally runs.

manast commented 6 months ago

@ChrisLahaye it would be useful to know if adding a new job to the queue wakes up the worker, this is the last piece in the puzzle that we need to understand. Also, it is very important to verify that the worker that gets stuck actually is running BullMQ's latest version.

ChrisLahaye commented 6 months ago

@manast after adding a new job to the queue the worker that is stuck awakes and runs the new job as well as the previously stuck jobs.

https://gist.github.com/ChrisLahaye/3f38b27d8ab68b2d3ffc2203a6f6d738

ChrisLahaye commented 6 months ago

Just to confirm, we are running bullmq version 5.7.1

roggervalf commented 6 months ago

hi @ChrisLahaye could you pls use v5.7.3 just in case?

ChrisLahaye commented 6 months ago

We just updated to v5.7.3 and will reach out once a worker gets stuck.

oanguenot commented 6 months ago

@manast, I confirm on my own that adding a new job wakes up the worker. I have upgraded to latest 5.7.3 same as @ChrisLahaye, I will check as soon as I have the issue

ChrisLahaye commented 6 months ago

The issue is still happening on v5.7.3

roggervalf commented 6 months ago

@manast after adding a new job to the queue the worker that is stuck awakes and runs the new job as well as the previously stuck jobs.

https://gist.github.com/ChrisLahaye/3f38b27d8ab68b2d3ffc2203a6f6d738

hi @ChrisLahaye I took a look in your logs but what will help us more is the actual value that is passed into bzpopmin that is causing to be blocked

ChrisLahaye commented 6 months ago

@manast after adding a new job to the queue the worker that is stuck awakes and runs the new job as well as the previously stuck jobs.

https://gist.github.com/ChrisLahaye/3f38b27d8ab68b2d3ffc2203a6f6d738

hi @ChrisLahaye I took a look in your logs but what will help us more is the actual value that is passed into bzpopmin that is causing to be blocked

How do I find that value? Currently doing a grep with the queue name over the monitor output. Is the value filtered out or not in this output?

roggervalf commented 6 months ago

hey @ChrisLahaye so until line 18 in https://gist.github.com/ChrisLahaye/3f38b27d8ab68b2d3ffc2203a6f6d738 is showing when stalled checks are happening, this operation by default it's executed every 30 seconds, I suppose here is where your worker is stopped, what we would like to know if what is happening before. A call to bzpopmin should happen before getting stopped (only calls to stalled-checks are happening)

ChrisLahaye commented 6 months ago

hey @ChrisLahaye so until line 18 in https://gist.github.com/ChrisLahaye/3f38b27d8ab68b2d3ffc2203a6f6d738 is showing when stalled checks are happening, this operation by default it's executed every 30 seconds, I suppose here is where your worker is stopped, what we would like to know if what is happening before. A call to bzpopmin should happen before getting stopped (only calls to stalled-checks are happening)

What do you recommend me to do? Start logging on a working queue and catching when it breaks?

manast commented 6 months ago

@ChrisLahaye in principle, using the latest version you should not get this issue. But if you get it again, then it would be pretty useful to know the arguments on the last call to BZPOPMIN, this is obviously difficult to get because it means you need to have monitor enabled until it happens, which costs quite a lot of CPU if you are processing a lot of jobs, so it may not be feasible in practice. In any case, if it happens again with the latest code, we would need to assume that somehow BZPOPMIN ends up being called with a value that Redis interprets as infinite timeout, and we will need to find a workaround for this. Please keep us posted.

ChrisLahaye commented 6 months ago

@manast is v5.7.4 supposed to fix the issue?

manast commented 6 months ago

5.7.1 for Node and 5.7.2 for Python.

ChrisLahaye commented 6 months ago

Unfortunately we are still experiencing the issue with the latest version. Could you please let me know which version introduced this issue so we can downgrade to that specific version.

matthewgonzalez commented 6 months ago

Hi, we've experienced this 3 times in the past couple of weeks on a critical queue that repeats every 30 seconds.

The repeatable job will get stuck in "delayed", even past the delay timestamp. Manually promoting the job or redeploying the app fixes the immediate issue.

I've bumped Bull to 5.7.1 with no luck. We are on Redis 6.2.6.

roggervalf commented 6 months ago

hi guys, looks like these cases began to happen since version 5.4.1, but we are still working on this case, last version 5.7.6 is related to this issue as well, but also we found an extra edge case in https://github.com/taskforcesh/bullmq/pull/2543

manast commented 6 months ago

@matthewgonzalez we suspect this is a bug in IORedis and we added a workaround for this issue that we hope will mitigate it completely, it has been released in version 5.7.7 (https://github.com/taskforcesh/bullmq/pull/2543)

ChrisLahaye commented 6 months ago

5.7.6 fixes it for us

matthewgonzalez commented 6 months ago

Going to cut a release with 5.7.7 today. Will let you know if we experience again. Thanks so much, BullMQ team.

matthewgonzalez commented 6 months ago

We've actually seen this occur again twice today after having deployed our workers with 5.7.7 last night.

Here's a screenshot of the job stuck in delayed. image

manast commented 6 months ago

@matthewgonzalez is this the only job in the queue (a repeatable jobs) or do you use the same queue with other types of jobs?

manast commented 6 months ago

Also, what are your settings for the repeat job, it would be golden if we could reproduce it ourselves. And which concurrency settings are you using, how many workers, etc.

matthewgonzalez commented 6 months ago

@manast

@matthewgonzalez is this the only job in the queue (a repeatable jobs) or do you use the same queue with other types of jobs?

Yes, the only job in the queue

Also, what are your settings for the repeat job, it would be golden if we could reproduce it ourselves. And which concurrency settings are you using, how many workers, etc.

Here's how we enqueue the job when the server starts:

queue.add('__default__', null, {
    jobId: queueName + '-cron-worker-job',
    repeat: {
      every: 15000, // every 15 seconds
    },
  })

No concurrency set in BullMQ, but we do autoscale our pods up to a maximum of 5 depending on resource utilization.

manast commented 6 months ago

@matthewgonzalez thank you for the info, we will try to reproduce it based on those settings.

roggervalf commented 6 months ago

hi @matthewgonzalez, are you passing a ioredis instance? if yes, are you also setting maxRetriesPerRequest: null ?

matthewgonzalez commented 6 months ago

Yes we are passing in an ioredis instance. Here is how that instance is configured:

export const connection = new IORedis(REDIS_URL, {
  // a warning is thrown on redis startup if these aren't added
  enableReadyCheck: false,
  maxRetriesPerRequest: null,
}).setMaxListeners(4 * queuesMQ.length + 10)
matthewgonzalez commented 5 months ago

We rolled back to 5.4.0 two weeks ago and have not experienced this issue since. Still curious as to the resolution here so we know when it may be safe to attempt to keep BullMQ up-to-date again. Thanks for all your support thus far.

manast commented 5 months ago

I am reopening as it seems this is still not working, until we can reproduce it.

manast commented 5 months ago

For the record, this is the test code I am using and not able to reproduce the issue. I wonder if there is not something more to it, like disconnections or something like that.

const { Queue, Worker } = require("bullmq");

const queueName = "test";

async function start() {
  const queue = new Queue(queueName, {
    connection: { host: "localhost", port: 6379 },
    // a warning is thrown on redis startup if these aren't added
    enableReadyCheck: false,
    maxRetriesPerRequest: null,
  });

  const job = await queue.add("__default__", null, {
    jobId: queueName + "-cron-worker-job",
    repeat: {
      every: 15000, // every 15 seconds
    },
    data: {
      foo: "bar",
    },
  });

  const processFn = async (job) => {
    console.log(`Processing job ${job.id} with data ${job.data}`)
    console.log(`-> ${job.id}`);
    await new Promise((res) => setTimeout(res, 1000));
    console.log(`\t<- ${job.id}`);
  };

  const worker = new Worker(queueName, processFn, {
    connection: {
      host: "localhost",
      port: 6379, // a warning is thrown on redis startup if these aren't added
      enableReadyCheck: false,
      maxRetriesPerRequest: null,
    },
  });

  worker.on("error", (err) => {
    console.error(err);
  });

  worker.on("completed", (job) => {
    console.log(`Job ${job.id} completed`);
  });

  worker.on("failed", (job, err) => {
    console.error(`Job ${job.id} failed with ${err.message}`);
  });
}

start();