clp-package: query-scheduler sometimes freezes while processing jobs

[kirkrodrigues]

Bug

As the title says. The issue is intermittent in that it doesn't happen for every job, but once a job freezes, no other query jobs can proceed suggesting the query scheduler has frozen.

After running the following command twice:

sbin/search.sh "DESERIALIZE_ERRORS" --count-by-time $((60 * 60 * 1000))

The second job froze. Relevant logs are below.

query_scheduler.log

2025-07-02 13:37:07,828 search-job-handler [INFO] Connected to archive database 10.1.0.22:5101.
2025-07-02 13:37:07,828 search-job-handler [INFO] Query scheduler started.
2025-07-02 13:38:53,213 search-job-handler [INFO] Got reducer for job 1 at 10.1.0.22:5200
2025-07-02 13:38:53,462 search-job-handler [INFO] Dispatched job 1 with 8 archives to search.
2025-07-02 13:38:55,400 search-job-handler [INFO] Search task job-1-task-1 succeeded in 1.009902 second(s).
2025-07-02 13:38:55,400 search-job-handler [INFO] Search task job-1-task-2 succeeded in 0.904199 second(s).
2025-07-02 13:38:55,400 search-job-handler [INFO] Search task job-1-task-3 succeeded in 1.006122 second(s).
2025-07-02 13:38:55,401 search-job-handler [INFO] Search task job-1-task-4 succeeded in 1.329241 second(s).
2025-07-02 13:38:55,401 search-job-handler [INFO] Search task job-1-task-5 succeeded in 1.327435 second(s).
2025-07-02 13:38:55,401 search-job-handler [INFO] Search task job-1-task-6 succeeded in 1.342147 second(s).
2025-07-02 13:38:55,402 search-job-handler [INFO] Search task job-1-task-7 succeeded in 1.402149 second(s).
2025-07-02 13:38:55,402 search-job-handler [INFO] Search task job-1-task-8 succeeded in 1.393261 second(s).
2025-07-02 13:38:55,428 search-job-handler [INFO] Completed job 1.
2025-07-02 13:39:00,437 search-job-handler [INFO] Got reducer for job 2 at 10.1.0.22:5201
2025-07-02 13:39:00,519 search-job-handler [INFO] Dispatched job 2 with 8 archives to search.

worker.log

[2025-07-02 13:38:53,451: INFO/ForkPoolWorker-1] job_orchestration.executor.query.fs_search_task.search[72655868-72e4-410e-9c81-b4e83d96ec7b]: Started search task for job 1
[2025-07-02 13:38:53,451: INFO/ForkPoolWorker-7] job_orchestration.executor.query.fs_search_task.search[743541cb-4794-4a7b-9ce2-63c1edcca999]: Started search task for job 1
[2025-07-02 13:38:53,452: INFO/ForkPoolWorker-8] job_orchestration.executor.query.fs_search_task.search[f2bfb3c5-1b7d-4030-bc36-73454c328cbe]: Started search task for job 1
[2025-07-02 13:38:53,454: INFO/ForkPoolWorker-2] job_orchestration.executor.query.fs_search_task.search[16884c46-b5fc-437b-9088-6811b5b6f29a]: Started search task for job 1
[2025-07-02 13:38:53,455: INFO/ForkPoolWorker-3] job_orchestration.executor.query.fs_search_task.search[3281c3da-2ede-441c-ad75-bfcf2fbbc0e2]: Started search task for job 1
[2025-07-02 13:38:53,456: INFO/ForkPoolWorker-4] job_orchestration.executor.query.fs_search_task.search[56e4984c-9b14-40f3-9348-ada588486174]: Started search task for job 1
[2025-07-02 13:38:53,458: INFO/ForkPoolWorker-5] job_orchestration.executor.query.fs_search_task.search[96cafa6e-79a2-416c-8216-0102295db779]: Started search task for job 1
[2025-07-02 13:38:53,460: INFO/ForkPoolWorker-6] job_orchestration.executor.query.fs_search_task.search[78f32ef5-faac-42c4-a0cc-3215f2cc24d5]: Started search task for job 1
[2025-07-02 13:38:53,464: INFO/ForkPoolWorker-7] job_orchestration.executor.query.fs_search_task.search[743541cb-4794-4a7b-9ce2-63c1edcca999]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/dde43976-1c9f-4ecc-872e-b69cc5ffebd8 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5200 --job-id 1
[2025-07-02 13:38:53,465: INFO/ForkPoolWorker-1] job_orchestration.executor.query.fs_search_task.search[72655868-72e4-410e-9c81-b4e83d96ec7b]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/6f04f109-1e1b-440e-aad8-6d96206efe9c DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5200 --job-id 1
[2025-07-02 13:38:53,466: INFO/ForkPoolWorker-8] job_orchestration.executor.query.fs_search_task.search[f2bfb3c5-1b7d-4030-bc36-73454c328cbe]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/1f4f2e2a-86d2-49dd-aa7a-8df70200003e DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5200 --job-id 1
[2025-07-02 13:38:53,467: INFO/ForkPoolWorker-2] job_orchestration.executor.query.fs_search_task.search[16884c46-b5fc-437b-9088-6811b5b6f29a]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/a78eed10-790e-424b-8af7-64ebb03cb933 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5200 --job-id 1
[2025-07-02 13:38:53,470: INFO/ForkPoolWorker-3] job_orchestration.executor.query.fs_search_task.search[3281c3da-2ede-441c-ad75-bfcf2fbbc0e2]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/a4696c40-afb8-472e-bf68-28c59b198a06 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5200 --job-id 1
[2025-07-02 13:38:53,470: INFO/ForkPoolWorker-7] job_orchestration.executor.query.fs_search_task.search[743541cb-4794-4a7b-9ce2-63c1edcca999]: Waiting for search to finish
[2025-07-02 13:38:53,471: INFO/ForkPoolWorker-5] job_orchestration.executor.query.fs_search_task.search[96cafa6e-79a2-416c-8216-0102295db779]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/6502cbf3-0657-482b-8528-468a00bc5fc5 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5200 --job-id 1
[2025-07-02 13:38:53,472: INFO/ForkPoolWorker-1] job_orchestration.executor.query.fs_search_task.search[72655868-72e4-410e-9c81-b4e83d96ec7b]: Waiting for search to finish
[2025-07-02 13:38:53,472: INFO/ForkPoolWorker-4] job_orchestration.executor.query.fs_search_task.search[56e4984c-9b14-40f3-9348-ada588486174]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/3b0e8c32-cd78-449c-bd70-9c6c144fd011 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5200 --job-id 1
[2025-07-02 13:38:53,472: INFO/ForkPoolWorker-8] job_orchestration.executor.query.fs_search_task.search[f2bfb3c5-1b7d-4030-bc36-73454c328cbe]: Waiting for search to finish
[2025-07-02 13:38:53,473: INFO/ForkPoolWorker-2] job_orchestration.executor.query.fs_search_task.search[16884c46-b5fc-437b-9088-6811b5b6f29a]: Waiting for search to finish
[2025-07-02 13:38:53,476: INFO/ForkPoolWorker-3] job_orchestration.executor.query.fs_search_task.search[3281c3da-2ede-441c-ad75-bfcf2fbbc0e2]: Waiting for search to finish
[2025-07-02 13:38:53,476: INFO/ForkPoolWorker-6] job_orchestration.executor.query.fs_search_task.search[78f32ef5-faac-42c4-a0cc-3215f2cc24d5]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/55cbc4cb-dfb1-42d1-8c16-94a615651b83 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5200 --job-id 1
[2025-07-02 13:38:53,476: INFO/ForkPoolWorker-5] job_orchestration.executor.query.fs_search_task.search[96cafa6e-79a2-416c-8216-0102295db779]: Waiting for search to finish
[2025-07-02 13:38:53,478: INFO/ForkPoolWorker-4] job_orchestration.executor.query.fs_search_task.search[56e4984c-9b14-40f3-9348-ada588486174]: Waiting for search to finish
[2025-07-02 13:38:53,481: INFO/ForkPoolWorker-6] job_orchestration.executor.query.fs_search_task.search[78f32ef5-faac-42c4-a0cc-3215f2cc24d5]: Waiting for search to finish
[2025-07-02 13:38:54,356: INFO/ForkPoolWorker-8] job_orchestration.executor.query.fs_search_task.search[f2bfb3c5-1b7d-4030-bc36-73454c328cbe]: search task 2 completed for job 1
[2025-07-02 13:38:54,457: INFO/ForkPoolWorker-1] job_orchestration.executor.query.fs_search_task.search[72655868-72e4-410e-9c81-b4e83d96ec7b]: search task 3 completed for job 1
[2025-07-02 13:38:54,461: INFO/ForkPoolWorker-7] job_orchestration.executor.query.fs_search_task.search[743541cb-4794-4a7b-9ce2-63c1edcca999]: search task 1 completed for job 1
[2025-07-02 13:38:54,783: INFO/ForkPoolWorker-3] job_orchestration.executor.query.fs_search_task.search[3281c3da-2ede-441c-ad75-bfcf2fbbc0e2]: search task 5 completed for job 1
[2025-07-02 13:38:54,784: INFO/ForkPoolWorker-2] job_orchestration.executor.query.fs_search_task.search[16884c46-b5fc-437b-9088-6811b5b6f29a]: search task 4 completed for job 1
[2025-07-02 13:38:54,798: INFO/ForkPoolWorker-4] job_orchestration.executor.query.fs_search_task.search[56e4984c-9b14-40f3-9348-ada588486174]: search task 6 completed for job 1
[2025-07-02 13:38:54,853: INFO/ForkPoolWorker-6] job_orchestration.executor.query.fs_search_task.search[78f32ef5-faac-42c4-a0cc-3215f2cc24d5]: search task 8 completed for job 1
[2025-07-02 13:38:54,860: INFO/ForkPoolWorker-5] job_orchestration.executor.query.fs_search_task.search[96cafa6e-79a2-416c-8216-0102295db779]: search task 7 completed for job 1
[2025-07-02 13:39:00,487: INFO/ForkPoolWorker-7] job_orchestration.executor.query.fs_search_task.search[b6c2edd9-91f4-4d66-b76f-05bf6b8f78c6]: Started search task for job 2
[2025-07-02 13:39:00,489: INFO/ForkPoolWorker-8] job_orchestration.executor.query.fs_search_task.search[3f70a1ac-1b40-42a6-a4a6-a57f90174ff8]: Started search task for job 2
[2025-07-02 13:39:00,492: INFO/ForkPoolWorker-1] job_orchestration.executor.query.fs_search_task.search[f307b9a8-6b15-4c30-9885-6a795a42fb19]: Started search task for job 2
[2025-07-02 13:39:00,495: INFO/ForkPoolWorker-2] job_orchestration.executor.query.fs_search_task.search[5e382c71-2e1c-4fa8-bd34-f215a4248d4b]: Started search task for job 2
[2025-07-02 13:39:00,498: INFO/ForkPoolWorker-3] job_orchestration.executor.query.fs_search_task.search[e434b617-0890-4384-b302-c98c92c9edfc]: Started search task for job 2
[2025-07-02 13:39:00,501: INFO/ForkPoolWorker-4] job_orchestration.executor.query.fs_search_task.search[8353005e-d544-4b68-90c1-f4318f1605f3]: Started search task for job 2
[2025-07-02 13:39:00,505: INFO/ForkPoolWorker-5] job_orchestration.executor.query.fs_search_task.search[fe01886d-5e17-4aae-8d07-0aba0fa8c207]: Started search task for job 2
[2025-07-02 13:39:00,505: INFO/ForkPoolWorker-8] job_orchestration.executor.query.fs_search_task.search[3f70a1ac-1b40-42a6-a4a6-a57f90174ff8]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/1f4f2e2a-86d2-49dd-aa7a-8df70200003e DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5201 --job-id 2
[2025-07-02 13:39:00,506: INFO/ForkPoolWorker-7] job_orchestration.executor.query.fs_search_task.search[b6c2edd9-91f4-4d66-b76f-05bf6b8f78c6]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/dde43976-1c9f-4ecc-872e-b69cc5ffebd8 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5201 --job-id 2
[2025-07-02 13:39:00,510: INFO/ForkPoolWorker-2] job_orchestration.executor.query.fs_search_task.search[5e382c71-2e1c-4fa8-bd34-f215a4248d4b]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/a78eed10-790e-424b-8af7-64ebb03cb933 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5201 --job-id 2
[2025-07-02 13:39:00,512: INFO/ForkPoolWorker-8] job_orchestration.executor.query.fs_search_task.search[3f70a1ac-1b40-42a6-a4a6-a57f90174ff8]: Waiting for search to finish
[2025-07-02 13:39:00,512: INFO/ForkPoolWorker-7] job_orchestration.executor.query.fs_search_task.search[b6c2edd9-91f4-4d66-b76f-05bf6b8f78c6]: Waiting for search to finish
[2025-07-02 13:39:00,513: INFO/ForkPoolWorker-4] job_orchestration.executor.query.fs_search_task.search[8353005e-d544-4b68-90c1-f4318f1605f3]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/3b0e8c32-cd78-449c-bd70-9c6c144fd011 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5201 --job-id 2
[2025-07-02 13:39:00,513: INFO/ForkPoolWorker-6] job_orchestration.executor.query.fs_search_task.search[43430b10-d9cf-4e0a-9d6f-111d25d9b877]: Started search task for job 2
[2025-07-02 13:39:00,514: INFO/ForkPoolWorker-3] job_orchestration.executor.query.fs_search_task.search[e434b617-0890-4384-b302-c98c92c9edfc]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/a4696c40-afb8-472e-bf68-28c59b198a06 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5201 --job-id 2
[2025-07-02 13:39:00,516: INFO/ForkPoolWorker-1] job_orchestration.executor.query.fs_search_task.search[f307b9a8-6b15-4c30-9885-6a795a42fb19]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/6f04f109-1e1b-440e-aad8-6d96206efe9c DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5201 --job-id 2
[2025-07-02 13:39:00,516: INFO/ForkPoolWorker-5] job_orchestration.executor.query.fs_search_task.search[fe01886d-5e17-4aae-8d07-0aba0fa8c207]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/6502cbf3-0657-482b-8528-468a00bc5fc5 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5201 --job-id 2
[2025-07-02 13:39:00,516: INFO/ForkPoolWorker-2] job_orchestration.executor.query.fs_search_task.search[5e382c71-2e1c-4fa8-bd34-f215a4248d4b]: Waiting for search to finish
[2025-07-02 13:39:00,520: INFO/ForkPoolWorker-4] job_orchestration.executor.query.fs_search_task.search[8353005e-d544-4b68-90c1-f4318f1605f3]: Waiting for search to finish
[2025-07-02 13:39:00,520: INFO/ForkPoolWorker-3] job_orchestration.executor.query.fs_search_task.search[e434b617-0890-4384-b302-c98c92c9edfc]: Waiting for search to finish
[2025-07-02 13:39:00,522: INFO/ForkPoolWorker-6] job_orchestration.executor.query.fs_search_task.search[43430b10-d9cf-4e0a-9d6f-111d25d9b877]: Running: /opt/clp/bin/clo s /home/rodri228/projects/log-compressor/open-source/clp/build/clp-package/var/data/archives/55cbc4cb-dfb1-42d1-8c16-94a615651b83 DESERIALIZE_ERRORS --count-by-time 3600000 reducer --host 10.1.0.22 --port 5201 --job-id 2
[2025-07-02 13:39:00,524: INFO/ForkPoolWorker-1] job_orchestration.executor.query.fs_search_task.search[f307b9a8-6b15-4c30-9885-6a795a42fb19]: Waiting for search to finish
[2025-07-02 13:39:00,524: INFO/ForkPoolWorker-5] job_orchestration.executor.query.fs_search_task.search[fe01886d-5e17-4aae-8d07-0aba0fa8c207]: Waiting for search to finish
[2025-07-02 13:39:00,527: INFO/ForkPoolWorker-6] job_orchestration.executor.query.fs_search_task.search[43430b10-d9cf-4e0a-9d6f-111d25d9b877]: Waiting for search to finish
[2025-07-02 13:39:01,390: INFO/ForkPoolWorker-8] job_orchestration.executor.query.fs_search_task.search[3f70a1ac-1b40-42a6-a4a6-a57f90174ff8]: search task 10 completed for job 2
[2025-07-02 13:39:01,525: INFO/ForkPoolWorker-7] job_orchestration.executor.query.fs_search_task.search[b6c2edd9-91f4-4d66-b76f-05bf6b8f78c6]: search task 9 completed for job 2
[2025-07-02 13:39:01,527: INFO/ForkPoolWorker-1] job_orchestration.executor.query.fs_search_task.search[f307b9a8-6b15-4c30-9885-6a795a42fb19]: search task 11 completed for job 2
[2025-07-02 13:39:01,798: INFO/ForkPoolWorker-3] job_orchestration.executor.query.fs_search_task.search[e434b617-0890-4384-b302-c98c92c9edfc]: search task 13 completed for job 2
[2025-07-02 13:39:01,830: INFO/ForkPoolWorker-2] job_orchestration.executor.query.fs_search_task.search[5e382c71-2e1c-4fa8-bd34-f215a4248d4b]: search task 12 completed for job 2
[2025-07-02 13:39:01,851: INFO/ForkPoolWorker-4] job_orchestration.executor.query.fs_search_task.search[8353005e-d544-4b68-90c1-f4318f1605f3]: search task 14 completed for job 2
[2025-07-02 13:39:01,877: INFO/ForkPoolWorker-6] job_orchestration.executor.query.fs_search_task.search[43430b10-d9cf-4e0a-9d6f-111d25d9b877]: search task 16 completed for job 2
[2025-07-02 13:39:01,920: INFO/ForkPoolWorker-5] job_orchestration.executor.query.fs_search_task.search[fe01886d-5e17-4aae-8d07-0aba0fa8c207]: search task 15 completed for job 2

reducer-*.log

2025-07-02T13:37:13.172+00:00 [info] Starting on host 10.1.0.22 port 5200
2025-07-02T13:37:13.172+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:37:13.172+00:00 [info] Waiting for job...
2025-07-02T13:38:53.212+00:00 [info] Setting up pipeline for job 1
2025-07-02T13:38:55.402+00:00 [info] Accept task cancelled
2025-07-02T13:38:55.408+00:00 [info] Job 1 finished successfully
2025-07-02T13:38:55.408+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:38:55.408+00:00 [info] Waiting for job...
2025-07-02T13:37:13.172+00:00 [info] Starting on host 10.1.0.22 port 5201
2025-07-02T13:37:13.172+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:37:13.172+00:00 [info] Waiting for job...
2025-07-02T13:39:00.437+00:00 [info] Setting up pipeline for job 2
2025-07-02T13:37:13.172+00:00 [info] Starting on host 10.1.0.22 port 5202
2025-07-02T13:37:13.172+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:37:13.172+00:00 [info] Waiting for job...
2025-07-02T13:37:13.172+00:00 [info] Starting on host 10.1.0.22 port 5203
2025-07-02T13:37:13.172+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:37:13.172+00:00 [info] Waiting for job...
2025-07-02T13:37:13.174+00:00 [info] Starting on host 10.1.0.22 port 5204
2025-07-02T13:37:13.174+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:37:13.174+00:00 [info] Waiting for job...
2025-07-02T13:37:13.174+00:00 [info] Starting on host 10.1.0.22 port 5205
2025-07-02T13:37:13.174+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:37:13.174+00:00 [info] Waiting for job...
2025-07-02T13:37:13.174+00:00 [info] Starting on host 10.1.0.22 port 5206
2025-07-02T13:37:13.174+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:37:13.174+00:00 [info] Waiting for job...
2025-07-02T13:37:13.175+00:00 [info] Starting on host 10.1.0.22 port 5207
2025-07-02T13:37:13.175+00:00 [info] Acceptor socket listening successfully
2025-07-02T13:37:13.176+00:00 [info] Waiting for job...

reducer.log

2025-07-02 13:37:13,168 reducer [INFO] Reducers started.
2025-07-02 13:37:13,168 reducer [INFO] Host=10.1.0.22 Base port=5200 Concurrency=8 Upsert Interval=100

CLP version

3520895

Environment

• Ubuntu 22.04
• Docker 27.5.0, build a187fa5

Reproduction steps

sbin/start-clp.sh
sbin/compress.sh logs/hive-24hrs/
sbin/search.sh "DESERIALIZE_ERRORS" --count-by-time $((60 * 60 * 1000))
sbin/search.sh "DESERIALIZE_ERRORS" --count-by-time $((60 * 60 * 1000))

[gibber9809]

So far I have confirmed that the frozen job freezes the scheduler inside of query_scheduler.py:try_getting_task_result. In particular, after async_task_result.ready() returns True async_task_result.get() never returns for the frozen job. Even after adding a timeout to get it seems like the call never returns.

[gibber9809]

There appear to be some existing github issues on the celery repo, some of which are still open and some of which were closed without being solved, that experience the same or similar issue (e.g. 5060, 7392, 2672). The issue seems to come up intermittently when trying to get results from a completed group.

Since this appears to be a longstanding unsolved issue with celery it may be simpler to finish making spider stable and migrating over instead of trying to deeply investigate celery in order to solve the underlying problem.

[gibber9809]

Note that this issue isn't exclusive to reducer jobs -- I can reproduce this freezing issue with search jobs by kicking off multiple search jobs at the same time.

[junhaoliao]

RCA

Setup

1. Apply debug patch to install tools for viewing backtrace and setting up the right permissions for attaching gdb to process

   Index: tools/docker-images/clp-execution-base-ubuntu-jammy/setup-scripts/install-prebuilt-packages.sh
   IDEA additional info:
   Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
   <+>UTF-8
   ===================================================================
   diff --git a/tools/docker-images/clp-execution-base-ubuntu-jammy/setup-scripts/install-prebuilt-packages.sh b/tools/docker-images/clp-execution-base-ubuntu-jammy/setup-scripts/install-prebuilt-packages.sh
   --- a/tools/docker-images/clp-execution-base-ubuntu-jammy/setup-scripts/install-prebuilt-packages.sh	(revision 0892a1cd29920f53185212a25c73415de2f8cc60)
   +++ b/tools/docker-images/clp-execution-base-ubuntu-jammy/setup-scripts/install-prebuilt-packages.sh	(date 1755279703130)
   @@ -11,9 +11,13 @@
      ca-certificates \
      checkinstall \
      curl \
   +  gdb\
      libcurl4 \
      libmariadb-dev \
      libssl-dev \
      python3 \
   +  python3-dbg \
   +  python3-pip \
      rsync \
   +  sudo \
      zstd
   Index: components/clp-package-utils/clp_package_utils/scripts/start_clp.py
   IDEA additional info:
   Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
   <+>UTF-8
   ===================================================================
   diff --git a/components/clp-package-utils/clp_package_utils/scripts/start_clp.py b/components/clp-package-utils/clp_package_utils/scripts/start_clp.py
   --- a/components/clp-package-utils/clp_package_utils/scripts/start_clp.py	(revision 0892a1cd29920f53185212a25c73415de2f8cc60)
   +++ b/components/clp-package-utils/clp_package_utils/scripts/start_clp.py	(date 1755279675357)
   @@ -602,6 +602,7 @@
        # fmt: off
        container_start_cmd = [
            "docker", "run",
   +        "--cap-add=SYS_PTRACE","--security-opt","seccomp=unconfined",
            "-di",
            "--network", "host",
            "-w", str(CONTAINER_CLP_HOME),
   @@ -745,6 +746,7 @@
        # fmt: off
        container_start_cmd = [
            "docker", "run",
   +        "--cap-add=SYS_PTRACE", "--security-opt", "seccomp=unconfined",
            "-di",
            "--network", "host",
            "-w", str(CONTAINER_CLP_HOME),
   Index: components/clp-py-utils/clp_py_utils/clp_config.py
   IDEA additional info:
   Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
   <+>UTF-8
   ===================================================================
   diff --git a/components/clp-py-utils/clp_py_utils/clp_config.py b/components/clp-py-utils/clp_py_utils/clp_config.py
   --- a/components/clp-py-utils/clp_py_utils/clp_config.py	(revision 0892a1cd29920f53185212a25c73415de2f8cc60)
   +++ b/components/clp-py-utils/clp_py_utils/clp_config.py	(date 1755281011110)
   @@ -836,7 +836,8 @@
                    f"Unsupported OS {os_release['ID']} in {OS_RELEASE_FILE_PATH}"
                )
    
   -        self.execution_container = "ghcr.io/y-scope/clp/" + self.execution_container
   +        # self.execution_container = "ghcr.io/y-scope/clp/" + self.execution_container
   +        self.execution_container = "clp-execution-x86-ubuntu-jammy:dev"
    
        def load_database_credentials_from_file(self):
            config = read_yaml_config_file(self.credentials_file_path)
   Index: tools/docker-images/clp-execution-base-ubuntu-jammy/Dockerfile
   IDEA additional info:
   Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
   <+>UTF-8
   ===================================================================
   diff --git a/tools/docker-images/clp-execution-base-ubuntu-jammy/Dockerfile b/tools/docker-images/clp-execution-base-ubuntu-jammy/Dockerfile
   --- a/tools/docker-images/clp-execution-base-ubuntu-jammy/Dockerfile	(revision 0892a1cd29920f53185212a25c73415de2f8cc60)
   +++ b/tools/docker-images/clp-execution-base-ubuntu-jammy/Dockerfile	(date 1755279675365)
   @@ -11,6 +11,18 @@
    RUN apt-get clean \
        && rm -rf /var/lib/apt/lists/* /tmp/* /var/tmp/*
    
   +RUN python3 -m pip install py-spy
   +
   +RUN echo 'root:    ' | chpasswd
   +
   +# Create a new user 'junhao' with UID/GID 1000
   +RUN groupadd -g 1000 junhao \
   +    && useradd -m -u 1000 -g 1000 -s /bin/bash junhao \
   +    && echo 'junhao ALL=(ALL) NOPASSWD:ALL' >> /etc/sudoers
   +
   +# Optionally, set password for the new user (empty here)
   +RUN echo 'junhao:    ' | chpasswd
   +
    # Flatten the image
    FROM scratch
    COPY --from=base / /
   Index: components/job-orchestration/job_orchestration/executor/query/celeryconfig.py
   IDEA additional info:
   Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
   <+>UTF-8
   ===================================================================
   diff --git a/components/job-orchestration/job_orchestration/executor/query/celeryconfig.py b/components/job-orchestration/job_orchestration/executor/query/celeryconfig.py
   --- a/components/job-orchestration/job_orchestration/executor/query/celeryconfig.py	(revision 0892a1cd29920f53185212a25c73415de2f8cc60)
   +++ b/components/job-orchestration/job_orchestration/executor/query/celeryconfig.py	(date 1755279675378)
   @@ -34,3 +34,6 @@
    # TODO: Choose a different serialization format for tasks and results. Sticking with json is
    # probably not a good idea.
    result_serializer = "json"
   +
   +# worker_prefetch_multiplier = 1 # doesn't work
   +# broker_pool_limit = 0
   

2. Reproduce the error

   cd clp-package/sbin
   ./start-clp.sh
   ./compress.sh ~/sample/hive-24hr/

   Then in the webui, perform search with query string "123" 3 times. Stuck should be observed on the 3rd time.

Investigation

In the clp-query_scheduler container:

1. Check process status

   $ top
   # which shows the python3 process's user time never increases

2. Check where it gets blocked

   $ cat /proc/1/wchan
   futex_wait_queue

   which sugguests the process is waiting on some mutex, likely indefinitely given the user time doesn't increase:
   we hit a deadlock!

3. Use gdb to see the stack

   # set encoding to utf-8; otherwise when running `py-bt`, the stack trace cannot be
   # fully displayed due to ASCII decoding errors
   export LC_ALL=C.UTF-8
   
   sudo gdb -p 1
   
   (gdb) py-bt
   
   # press `c` then hit `return` to display the full stack trace

   The trace:

   GNU gdb (Ubuntu 12.1-0ubuntu1~22.04.2) 12.1
   Copyright (C) 2022 Free Software Foundation, Inc.
   License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
   This is free software: you are free to change and redistribute it.
   There is NO WARRANTY, to the extent permitted by law.
   Type "show copying" and "show warranty" for details.
   This GDB was configured as "x86_64-linux-gnu".
   Type "show configuration" for configuration details.
   For bug reporting instructions, please see:
   <https://www.gnu.org/software/gdb/bugs/>.
   Find the GDB manual and other documentation resources online at:
       <http://www.gnu.org/software/gdb/documentation/>.
   
   For help, type "help".
   Type "apropos word" to search for commands related to "word".
   Attaching to process 1
   [New LWP 7]
   [Thread debugging using libthread_db enabled]
   Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
   0x000071a98ecfb117 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
   (gdb) py-bt
   Traceback (most recent call first):
     <built-in method __enter__ of _thread.lock object at remote 0x71a98a1332c0>
     File "/opt/clp/lib/python3/site-packages/redis/client.py", line 858, in execute_command
       with self._lock:
     File "/opt/clp/lib/python3/site-packages/redis/client.py", line 1043, in unsubscribe
       return self.execute_command("UNSUBSCRIBE", *args)
     File "/opt/clp/lib/python3/site-packages/celery/backends/redis.py", line 184, in cancel_for
       self._pubsub.unsubscribe(key)
     File "/opt/clp/lib/python3/site-packages/celery/backends/asynchronous.py", line 216, in on_result_fulfilled
       self.result_consumer.cancel_for(result.id)
     File "/opt/clp/lib/python3/site-packages/celery/backends/asynchronous.py", line 208, in remove_pending_result
       self.on_result_fulfilled(result)
     File "/opt/clp/lib/python3/site-packages/celery/result.py", line 417, in __del__
       self.backend.remove_pending_result(self)
     Garbage-collecting
     File "/opt/clp/lib/python3/site-packages/redis/client.py", line 903, in _execute
       lambda: command(*args, **kwargs),
     File "/opt/clp/lib/python3/site-packages/redis/client.py", line 859, in execute_command
       self._execute(connection, connection.send_command, *args, **kwargs)
     File "/opt/clp/lib/python3/site-packages/redis/client.py", line 1043, in unsubscribe
       return self.execute_command("UNSUBSCRIBE", *args)
     File "/opt/clp/lib/python3/site-packages/celery/backends/redis.py", line 184, in cancel_for
       self._pubsub.unsubscribe(key)
     File "/opt/clp/lib/python3/site-packages/celery/backends/redis.py", line 137, in _maybe_cancel_ready_task
       self.cancel_for(meta['task_id'])
     File "/opt/clp/lib/python3/site-packages/celery/backends/redis.py", line 141, in on_state_change
       self._maybe_cancel_ready_task(meta)
     File "/opt/clp/lib/python3/site-packages/celery/backends/redis.py", line 152, in on_wait_for_pending
       self.on_state_change(meta, None)
     File "/opt/clp/lib/python3/site-packages/celery/backends/asynchronous.py", line 284, in _wait_for_pending
       self.on_wait_for_pending(result, timeout=timeout, **kwargs)
     File "/opt/clp/lib/python3/site-packages/celery/backends/asynchronous.py", line 172, in iter_native
       for _ in self._wait_for_pending(result, no_ack=no_ack, **kwargs):
     File "/opt/clp/lib/python3/site-packages/celery/result.py", line 827, in join_native
       for task_id, meta in self.iter_native(timeout, interval, no_ack,
     File "/opt/clp/lib/python3/site-packages/celery/result.py", line 705, in get
       return (self.join_native if self.supports_native_join else self.join)(
     File "/opt/clp/lib/python3/site-packages/job_orchestration/scheduler/query/query_scheduler.py", line 860, in try_getting_task_result
       return async_task_result.get()
     File "/opt/clp/lib/python3/site-packages/job_orchestration/scheduler/query/query_scheduler.py", line 1053, in check_job_status_and_update_db
       returned_results = try_getting_task_result(job.current_sub_job_async_task_result)
     File "/opt/clp/lib/python3/site-packages/job_orchestration/scheduler/query/query_scheduler.py", line 1090, in handle_job_updates
       await check_job_status_and_update_db(db_conn_pool, results_cache_uri)
     <built-in method task_wakeup of _asyncio.Task object at remote 0x71a98ad30450>
     <built-in method run of _contextvars.Context object at remote 0x71a98ad35900>
     File "/usr/lib/python3.10/asyncio/events.py", line 80, in _run
       self._context.run(self._callback, *self._args)
     File "/usr/lib/python3.10/asyncio/base_events.py", line 1909, in _run_once
       handle._run()
     File "/usr/lib/python3.10/asyncio/base_events.py", line 603, in run_forever
       self._run_once()
     File "/usr/lib/python3.10/asyncio/base_events.py", line 636, in run_until_complete
       self.run_forever()
     File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run
       return loop.run_until_complete(main)
     File "/opt/clp/lib/python3/site-packages/job_orchestration/scheduler/query/query_scheduler.py", line 1229, in <module>
       sys.exit(asyncio.run(main(sys.argv)))
     <built-in method exec of module object at remote 0x71a98eba0950>
     File "/usr/lib/python3.10/runpy.py", line 86, in _run_code
       exec(code, run_globals)
     File "/usr/lib/python3.10/runpy.py", line 196, in _run_module_as_main
       return _run_code(code, main_globals, None,

   The trace (abridged) shows two frames trying to send an UNSUBSCRIBE to Redis, one of which is blocked acquiring a lock, while the other one holding the lock wouldn't release.

where are those invoked?

• one of it <built-in method task_wakeup of _asyncio.Task object at remote 0x71a98ad30450> is from our code:

  • async_task_result.get():

  clp/components/job-orchestration/job_orchestration/scheduler/query/query_scheduler.py

  Lines 857 to 861 in 0892a1c

  	def try_getting_task_result(async_task_result):
  	if not async_task_result.ready():
  	return None
  	return async_task_result.get()

  • ← try_getting_task_result()
  • ← returned_results = try_getting_task_result(job.current_sub_job_async_task_result) :

  clp/components/job-orchestration/job_orchestration/scheduler/query/query_scheduler.py

  Line 1053 in 0892a1c

  returned_results = try_getting_task_result(job.current_sub_job_async_task_result)

• The other one is triggered by “Garbage-collecting”. We have a few del that deletes QueryJob instances, which might contain some AsyncTask references at current_sub_job_async_task_result :

  • clp/components/job-orchestration/job_orchestration/scheduler/scheduler_data.py

    Lines 48 to 53 in 0892a1c

    	class QueryJob(BaseModel, ABC):
    	id: str
    	state: InternalJobState
    	start_time: Optional[datetime.datetime]
    	current_sub_job_async_task_result: Optional[Any]

    
    like

    • clp/components/job-orchestration/job_orchestration/scheduler/query/query_scheduler.py

      Line 971 in 0892a1c

      del active_jobs[job_id]

    • clp/components/job-orchestration/job_orchestration/scheduler/query/query_scheduler.py

      Line 1041 in 0892a1c

      del active_jobs[job_id]

    • clp/components/job-orchestration/job_orchestration/scheduler/query/query_scheduler.py

      Line 1062 in 0892a1c

      del active_jobs[job_id]

    • Similarly, in the compression scheduler:

      clp/components/job-orchestration/job_orchestration/scheduler/compress/compression_scheduler.py

      Line 386 in 0892a1c

      del scheduled_jobs[job_id]

Though both frames should be on the same thread, the async wait on .get() made the garbage collector possible to run. At this point we had identified that those two frames (one explicit call, one destructor) were competing on the Redis backend lock.

Mitigations

NOTE: below are just mitigations. For proper fix, see the "Fix" section:

Calling GroupResult.forget() which calls AsyncResult.forget() for all results

Inspect the Celery source code:

• here's the __del__(self) method that gave us the trouble because it calls self.backend.remove_pending_result(self) :
  https://github.com/celery/celery/blob/33eb14852310996b1909c8388cd319809d6c8626/celery/result.py#L416-L420
• forget() also calls self.backend.remove_pending_result(self):
  https://github.com/celery/celery/blob/33eb14852310996b1909c8388cd319809d6c8626/celery/result.py#L135-L143

Look up the Celery docs:

https://docs.celeryq.dev/en/stable/reference/celery.result.html#celery.result.AsyncResult.forget

forget()[[source]](https://docs.celeryq.dev/en/stable/_modules/celery/result.html#AsyncResult.forget)Forget the result of this task and its parents.

there's also a warning right below:

Backends use resources to store and transmit results. To ensure that resources are released, you must eventually call [get()](https://docs.celeryq.dev/en/stable/reference/celery.result.html#celery.result.AsyncResult.get) or [forget()](https://docs.celeryq.dev/en/stable/reference/celery.result.html#celery.result.AsyncResult.forget) on EVERY AsyncResult instance returned after calling a task.

It appears that we forgot to invoke .forget() on the result when we no longer need them. I tried adding the .forget() call on the GroupResult attribute current_sub_job_async_task_result before the jobs got deleted, and was no longer able to reproduce the stuck.

However, this is only a mitigation. Using .forget() drops the task result and might cause undesired issues in our existing code.

Disabling the Redis connection pool in Celery

I also tried disabling Celery's Redis connection pool by setting broker_pool_limit = 0, which forces a new connection on each use. in https://github.com/y-scope/clp/blob/d969aaf456cc2cc5caa58586d4264718fda94aa0/components/job-orchestration/job_orchestration/executor/query/celeryconfig.py

In practice this greatly reduced the occurrence of the hang (@junhaoliao saw no deadlock cases at all, while @kirkrodrigues was able to rarely reproduce), confirming that the connection pool contention was closely related to the issue. However, disabling pooling can have performance costs and did not completely eliminate the problem in every test, so this too is also only a mitigation, not the true fix.

Fix

With the thought process as we explore mitigations, analysis of the GDB trace and code revealed the root cause: the Celery AsyncResult destructor (__del__) was issuing a Redis UNSUBSCRIBE while another frame still held the redis.PubSub lock, causing the deadlock. This matches similar redis-py issues redis/redis-py#3289 and redis/redis-py#3640 . PR redis/redis-py#3677 finally fixed the issue. The permanent fix for us is to upgrade the Redis client library redis-py that includes the fix. After upgrading our redis-py dependency to 6.4.0 which is the first version including the fix and the latest. @junhaoliao confirmed the stuck condition no longer occurs.