flakey broker is triggering a case where retryEmptyBeforeExit doesn't work

[reidsunderland]

I haven't been able to reproduce this locally but on GitHub, we often get flakey broker failures like this:

test 23 FAILURE: post test2_f61		 (1605) should have the same number of files of sender 	 (1125)

This post test2_f61 config has inflight 40s, which causes messages to be put into worklist.failed because they are too young:

2026-06-17 23:12:26,967 [WARNING] sarracenia.flow filter file too young: queueing for retry.
2026-06-17 23:12:26,967 [WARNING] sarracenia.flow filter file too young: queueing for retry.
2026-06-17 23:12:26,967 [WARNING] sarracenia.flow filter file too young: queueing for retry.
2026-06-17 23:12:26,967 [WARNING] sarracenia.flow filter file too young: queueing for retry.
2026-06-17 23:12:26,968 [INFO] sarracenia.flow please_stop asked to stop
2026-06-17 23:12:26,968 [INFO] sarracenia.flow _runHousekeeping on_housekeeping pid: 24980 post/test2_f61.conf instance: 0
2026-06-17 23:12:26,979 [INFO] sarracenia.diskqueue on_housekeeping work_retry_00 Number of messages in retry list 35
2026-06-17 23:12:26,979 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current cpu_times: user=0.64 system=0.04
2026-06-17 23:12:26,979 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current mem usage: 82.5MiB, accumulating count (0 or 0/100 so far) before self-setting threshold
2026-06-17 23:12:26,980 [INFO] sarracenia.flowcb.log stats version: 3.03.00rc1, started: now, last_housekeeping:  0.1 seconds ago
2026-06-17 23:12:26,980 [INFO] sarracenia.flowcb.log stats messages received: 0, accepted: 0, rejected: 0   rate accepted: 0.0% or 0.0 m/s
2026-06-17 23:12:26,980 [INFO] sarracenia.flowcb.log stats files transferred: 0 bytes: 0Bytes rate: 0Bytes/sec
2026-06-17 23:12:26,982 [INFO] sarracenia.flow please_stop asked to stop
2026-06-17 23:12:26,982 [INFO] sarracenia.flow _runHousekeeping on_housekeeping pid: 24980 post/test2_f61.conf instance: 0
2026-06-17 23:12:26,982 [INFO] sarracenia.diskqueue on_housekeeping still 22 messages in work_retry_00 list. Resuming retries with /home/runner/.cache/sr3/post/test2_f61/diskqueue_work_retry_00
2026-06-17 23:12:26,983 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current cpu_times: user=0.64 system=0.04
2026-06-17 23:12:26,983 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current mem usage: 82.5MiB, accumulating count (0 or 13/100 so far) before self-setting threshold
2026-06-17 23:12:26,983 [INFO] sarracenia.flowcb.log stats version: 3.03.00rc1, started: now, last_housekeeping:  0.0 seconds ago
2026-06-17 23:12:26,983 [INFO] sarracenia.flowcb.log stats messages received: 13, accepted: 0, rejected: 13   rate accepted: 0.0% or 0.0 m/s
2026-06-17 23:12:26,983 [INFO] sarracenia.flowcb.log stats files transferred: 0 bytes: 0Bytes rate: 0Bytes/sec
2026-06-17 23:12:26,984 [INFO] sarracenia.flow close flow/close completed cleanly pid: 24980 post/test2_f61.conf instance: 0

But once all the messages are in worklist.failed, the post process terminates and doesn't attempt to empty its retry list, even though retryEmptyBeforeExit is set to True in the config. There's something broken in the retryEmptyBeforeExit logic that is not allowing it to detect that there are retries that need to be processed.

[reidsunderland]

It's because retryEmptyBeforeExit only checks if the post retry list, but the "too young" files are placed into the download retry list. It should not exit the post process until both the post and download retry lists are empty.

[reidsunderland]

Now after fixing retryEmptyBeforeExit, sometimes the post test2_f61 is missing some files. More debugging is needed. It's usually not enough to cause the test to fail.

In one attempt, I started looking at an example file, 2020-01-05T03-00-01Z_FPHX14_r9zf_WS.csv and found that it was passed to the sr3_post command, but there was never a log message that said it got posted.

+ sr3_post -c test2_f61.conf -p ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r10zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r10zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r11zf_PA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r11zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r11zf_TD.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r11zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r12zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r12zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r14zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r15zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r15zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r16zf_POP.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r16zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r17zf_PA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r17zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r18zf_POP.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r18zf_TD.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r18zf_WG.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r19zf_PA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r19zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r19zf_TD.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r19zf_WG.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r19zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r1zf_CC.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r1zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r1zf_TD.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r20zf_CC.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r20zf_TD.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r21zf_PA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r21zf_POP.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r21zf_WG.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r21zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r2zf_POP.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r3zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r3zf_TD.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r3zf_WG.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r4zf_CC.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r4zf_PA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r4zf_TD.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r5zf_POP.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r5zf_WG.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r6zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r7zf_PA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r7zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r8zf_CC.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r8zf_POP.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r8zf_WS.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r9zf_POP.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r9zf_TA.csv ./20200105/WXO-DD/meteocode/atl/csv/2020-01-05T03-00-01Z_FPHX14_r9zf_WS.csv
2026-06-19 20:06:00,925 [INFO] sarracenia.moth.amqp putSetup exchange declared: xs_tsource_post (as: amqp://tsource@localhost/)
2026-06-19 20:06:00,947 [INFO] sarracenia.flowcb.gather.file gather len(queued_messages)=25
2026-06-19 20:06:00,947 [WARNING] sarracenia.flow filter file too young: queueing for retry.
..... lots of that message...
2026-06-19 20:06:00,948 [WARNING] sarracenia.flow filter file too young: queueing for retry.

2026-06-19 20:06:00,953 [INFO] sarracenia.flow run retryEmptyBeforeExit=True and there are still messages in the retry queues(post: 0, download: 50)
2026-06-19 20:06:00,954 [INFO] sarracenia.flow _runHousekeeping on_housekeeping pid: 15048 post/test2_f61.conf instance: 0
2026-06-19 20:06:00,964 [INFO] sarracenia.diskqueue on_housekeeping work_retry_00 Number of messages in retry list 50
2026-06-19 20:06:00,965 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current cpu_times: user=0.51 system=0.05
2026-06-19 20:06:00,965 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current mem usage: 110.6MiB, accumulating count (0 or 0/100 so far) before self-setting threshold
2026-06-19 20:06:00,965 [INFO] sarracenia.flowcb.log stats version: 3.03.00rc1, started: now, last_housekeeping:  0.0 seconds ago
2026-06-19 20:06:00,965 [INFO] sarracenia.flowcb.log stats messages received: 0, accepted: 0, rejected: 0   rate accepted: 0.0% or 0.0 m/s
2026-06-19 20:06:00,965 [INFO] sarracenia.flowcb.log stats files transferred: 0 bytes: 0Bytes rate: 0Bytes/sec
2026-06-19 20:06:01,136 [INFO] sarracenia.flow run retryEmptyBeforeExit=True and there are still messages in the retry queues(post: 0, download: 37)
2026-06-19 20:06:01,136 [INFO] sarracenia.flow _runHousekeeping on_housekeeping pid: 15048 post/test2_f61.conf instance: 0
2026-06-19 20:06:01,136 [INFO] sarracenia.diskqueue on_housekeeping still 37 messages in work_retry_00 list. Resuming retries with /home/runner/.cache/sr3/post/test2_f61/diskqueue_work_retry_00
2026-06-19 20:06:01,136 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current cpu_times: user=0.51 system=0.05
2026-06-19 20:06:01,137 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current mem usage: 110.6MiB, accumulating count (0 or 13/100 so far) before self-setting threshold
2026-06-19 20:06:01,137 [INFO] sarracenia.flowcb.log stats version: 3.03.00rc1, started: now, last_housekeeping:  0.2 seconds ago
2026-06-19 20:06:01,137 [INFO] sarracenia.flowcb.log stats messages received: 13, accepted: 0, rejected: 13   rate accepted: 0.0% or 0.0 m/s
2026-06-19 20:06:01,137 [INFO] sarracenia.flowcb.log stats files transferred: 0 bytes: 0Bytes rate: 0Bytes/sec
2026-06-19 20:06:01,337 [INFO] sarracenia.flow run retryEmptyBeforeExit=True and there are still messages in the retry queues(post: 0, download: 24)
2026-06-19 20:06:01,337 [INFO] sarracenia.flow _runHousekeeping on_housekeeping pid: 15048 post/test2_f61.conf instance: 0
2026-06-19 20:06:01,337 [INFO] sarracenia.diskqueue on_housekeeping still 24 messages in work_retry_00 list. Resuming retries with /home/runner/.cache/sr3/post/test2_f61/diskqueue_work_retry_00
2026-06-19 20:06:01,338 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current cpu_times: user=0.52 system=0.06
2026-06-19 20:06:01,338 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current mem usage: 110.6MiB, accumulating count (0 or 26/100 so far) before self-setting threshold
2026-06-19 20:06:01,338 [INFO] sarracenia.flowcb.log stats version: 3.03.00rc1, started: now, last_housekeeping:  0.2 seconds ago
2026-06-19 20:06:01,338 [INFO] sarracenia.flowcb.log stats messages received: 13, accepted: 0, rejected: 13   rate accepted: 0.0% or 0.0 m/s
2026-06-19 20:06:01,338 [INFO] sarracenia.flowcb.log stats files transferred: 0 bytes: 0Bytes rate: 0Bytes/sec
2026-06-19 20:06:01,538 [INFO] sarracenia.flow run retryEmptyBeforeExit=True and there are still messages in the retry queues(post: 0, download: 11)
2026-06-19 20:06:01,538 [INFO] sarracenia.flow _runHousekeeping on_housekeeping pid: 15048 post/test2_f61.conf instance: 0
2026-06-19 20:06:01,539 [INFO] sarracenia.diskqueue on_housekeeping still 11 messages in work_retry_00 list. Resuming retries with /home/runner/.cache/sr3/post/test2_f61/diskqueue_work_retry_00
2026-06-19 20:06:01,540 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current cpu_times: user=0.52 system=0.06
2026-06-19 20:06:01,540 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current mem usage: 110.6MiB, accumulating count (0 or 39/100 so far) before self-setting threshold
2026-06-19 20:06:01,540 [INFO] sarracenia.flowcb.log stats version: 3.03.00rc1, started: now, last_housekeeping:  0.2 seconds ago
2026-06-19 20:06:01,540 [INFO] sarracenia.flowcb.log stats messages received: 13, accepted: 0, rejected: 13   rate accepted: 0.0% or 0.0 m/s
2026-06-19 20:06:01,540 [INFO] sarracenia.flowcb.log stats files transferred: 0 bytes: 0Bytes rate: 0Bytes/sec
2026-06-19 20:06:01,740 [INFO] sarracenia.flow please_stop asked to stop
2026-06-19 20:06:01,740 [INFO] sarracenia.flow _runHousekeeping on_housekeeping pid: 15048 post/test2_f61.conf instance: 0
2026-06-19 20:06:01,741 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current cpu_times: user=0.52 system=0.06
2026-06-19 20:06:01,741 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current mem usage: 110.6MiB, accumulating count (0 or 50/100 so far) before self-setting threshold
2026-06-19 20:06:01,741 [INFO] sarracenia.flowcb.log stats version: 3.03.00rc1, started: now, last_housekeeping:  0.2 seconds ago
2026-06-19 20:06:01,741 [INFO] sarracenia.flowcb.log stats messages received: 11, accepted: 0, rejected: 11   rate accepted: 0.0% or 0.0 m/s
2026-06-19 20:06:01,742 [INFO] sarracenia.flowcb.log stats files transferred: 0 bytes: 0Bytes rate: 0Bytes/sec
2026-06-19 20:06:01,742 [INFO] sarracenia.flow please_stop asked to stop
2026-06-19 20:06:01,742 [INFO] sarracenia.flow _runHousekeeping on_housekeeping pid: 15048 post/test2_f61.conf instance: 0
2026-06-19 20:06:01,743 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current cpu_times: user=0.52 system=0.06
2026-06-19 20:06:01,743 [INFO] sarracenia.flowcb.housekeeping.resources on_housekeeping Current mem usage: 110.6MiB, accumulating count (0 or 50/100 so far) before self-setting threshold
2026-06-19 20:06:01,743 [INFO] sarracenia.flowcb.log stats version: 3.03.00rc1, started: now, last_housekeeping:  0.0 seconds ago
2026-06-19 20:06:01,743 [INFO] sarracenia.flowcb.log stats messages received: 0, accepted: 0, rejected: 0   rate accepted: 0.0% or 0.0 m/s
2026-06-19 20:06:01,743 [INFO] sarracenia.flowcb.log stats files transferred: 0 bytes: 0Bytes rate: 0Bytes/sec
2026-06-19 20:06:01,743 [INFO] sarracenia.flow close flow/close completed cleanly pid: 15048 post/test2_f61.conf instance: 0

So the download retry queue is emptying out, but files never get posted... That could be a bug, needs more investigation.