Aborted task is not logged, only following ones

[nsteinmetz]

Hi,

I noticed that some features did not work on my side (scheduled valve opening/closing) and noticed this in logs:

docker compose logs -f worker_command | grep -v -e send_heartbeat
worker_command-1  | [INFO] 11:35:47: starting worker 7712c013 for 3 functions
worker_command-1  | [INFO] 12:02:46: received signal SIGTERM, shutting down worker 7712c013
worker_command-1  | [INFO] 12:02:46: shutdown worker 7712c013 {failed: 60} after 1619250ms
worker_command-1  | [INFO] 12:03:12: starting worker 36e0f196 for 3 functions
worker_command-1  | [INFO] 13:37:24: received signal SIGTERM, shutting down worker 36e0f196
worker_command-1  | [INFO] 13:37:24: shutdown worker 36e0f196 {completed: 1534} after 92051717ms
worker_command-1  | [INFO] 13:37:51: starting worker a9b0d74e for 3 functions
worker_command-1  | [INFO] 04:00:00: task open_valve □ 5010cbb871f544f0bef45652972920b4 → worker a9b0d74e
worker_command-1  | [INFO] 2025-09-22T04:00:00+0000 - Not Opening valve for zone 94ecea69-8871-4d53-a8ea-f1b5238101eb, we are in a closing phase
worker_command-1  | [INFO] 2025-09-22T04:00:00+0000 - queue valve close_valve 94ecea69-8871-4d53-a8ea-f1b5238101eb bf752743-67ce-425a-9f12-767fb686beb5 2025-09-22 16:00:00+00:00
worker_command-1  | [INFO] 2025-09-22T04:00:00+0000 - queue valve open_valve 94ecea69-8871-4d53-a8ea-f1b5238101eb bf752743-67ce-425a-9f12-767fb686beb5 2025-09-23 04:00:00+00:00
worker_command-1  | [INFO] 04:00:00: task open_valve ■ 5010cbb871f544f0bef45652972920b4 ← None
worker_command-1  | [INFO] 06:12:00: task close_valve ⊘ 92b5d3e2ed7e4716a563b072d20b64cf aborted prior to run
worker_command-1  | [INFO] 07:12:00: task open_valve ⊘ 4584e0d132df428eb4df23054ae5aea4 aborted prior to run
worker_command-1  | [INFO] 16:00:00: task close_valve ⊘ 8cc0a2fef3d345e1a001b83a5ae7e72e aborted prior to run
worker_command-1  | [INFO] 16:00:00: task close_valve ⊘ 0398d8ff550a4022a107003c59037928 aborted prior to run
worker_command-1  | [INFO] 16:00:00: task close_valve ⊘ bdd68ad7bee0490b98228359db64db9c aborted prior to run
worker_command-1  | [INFO] 16:00:00: task close_valve ⊘ a8315b4770854cec99c1ad00624ae7d1 aborted prior to run
worker_command-1  | [INFO] 16:00:00: task close_valve ⊘ db0afa8ceca94d69b107a1a21ee860ea aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 51921047d5314f0cb8fed79c5fa6de21 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 635b10e375964debb8eec597b67a04a2 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 12ecda93aa47446484a1437f8722e082 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 029f6bf257874c5ca0054f0d20e41a9d aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 5764f3df2ae24c2c83de0c92f498997a aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 1544d93be9c64274b32948635e3b370d aborted prior to run
worker_command-1  | [INFO] 04:00:00: task close_valve ⊘ 1c0200a0df9246bfa0b7b5bad5cd64a5 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 5012ee641de8465784973102fa66dfe5 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task close_valve ⊘ 9039ecce38f04c5fa2dbba37678b4f60 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 733d28d8d81a4bd4b4f5f6b6a3b7a80b aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 8fd79dd35df849b2a1bfe06f0adc8227 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 7964e6e0bec5449d830f598fcda18614 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 895e6f62bbf34d1cbe71969370115e1c aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ 93f9f2f4233241a0aceeab3954621ac1 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ a3a97b8c223647a4b78160f386ca2cc6 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ c3119ab78ba14bca94a7c695d4b3bff1 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ e255f652659d464582a836cda0ced789 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ d1b39fc897cd4c35a9fff84dcbe89714 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ f55805d7baf6435987ff38942e9dbd96 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ a909b1721cb842faa53aca1e3a706625 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ f0ef7816ba7b44cea6a7117c63b6a2f5 aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ f15ba67a69b042aebe5b349b9f3e34be aborted prior to run
worker_command-1  | [INFO] 04:00:00: task open_valve ⊘ fefd8503a02c473b92396e18f9eddb75 aborted prior to run

I have no info on the task which aborted in the logs - I could find them on redis (via smembers streaq:worker_command:aborted) but I don't know much about why it aborted.

Shouldn't there be a log for this ?

I'm also surprised to see some arguments being updated in a strange way - is it due to streaq ?

{'f': 'open_valve', 'a': ('e805b707-e298-4e4e-b0ce-7a24ab97f288', '4829449e-7aa1-411b-a782-1420a6ef4251_4829449e-7aa1-411b-a782-1420a6ef4251#2'), 'k': {}, 't': 1758521600098}

{'f': 'open_valve', 'a': ('e805b707-e298-4e4e-b0ce-7a24ab97f288', '4829449e-7aa1-411b-a782-1420a6ef4251_4829449e-7aa1-411b-a782-1420a6ef4251#2'), 'k': {}, 't': 1758521610932}

{'f': 'close_valve', 'a': ('94ecea69-8871-4d53-a8ea-f1b5238101eb', 'bf752743-67ce-425a-9f12-767fb686beb5#2_4ec003a6-b9e3-4d1d-8974-fc3e596a16b7_bf752743-67ce-425a-9f12-767fb686beb5#3'), 'k': {}, 't': 1758563917428}

{'f': 'open_valve', 'a': ('94ecea69-8871-4d53-a8ea-f1b5238101eb', 'bf752743-67ce-425a-9f12-767fb686beb5#2_4ec003a6-b9e3-4d1d-8974-fc3e596a16b7_bf752743-67ce-425a-9f12-767fb686beb5#3'), 'k': {}, 't': 1758563917431}

It should be only:

{'f': 'open_valve', 'a': ('<uuid>', '<uuid>', 'k': {}, 't': <timestamp>}
{'f': 'close_valve', 'a': ('<uuid>', '<uuid>', 'k': {}, 't': <timestamp>}

The second argument should not be a composition of uuids (it may come from my side, I need to check) and having a #2 or #3 ; I don't see how it could be from my side. Maybe related to retry mechanism on streaq side ? But I would expect that arguments remain untouched from one execution to the other.

[nsteinmetz]

For date in logs to ease debugging and monitoring, I opened MR #91

[nsteinmetz]

25) "9245719e7d8c424da8c45060aef393b5" XXX
26) "2136340800000"

27) "f8554bd9de6f4f1ca7abf68da54a0465" XXX
28) "2136340800000"

Those two tasks will never be triggered (somewhere in 2037) - beyond abortion, could it be possible to enforce deletion for such use cases ? I can contribute the code if interested.

[nsteinmetz]

hmm ok my bad - I misunderstood the concept of aborted - it's because they were cancelled (which implies a task abortion). I thought aborted was a failure case.

So all these logs are scheduled/queued actions that were aborted in the meantime.

[nsteinmetz]

so remaining open points are only:

• arguments updated by streaq ?
• task hard deletion

[nsteinmetz]

Hmm if job id gets a #2 or #3 when retried, I can see a case where it can be propagated within my code and passed somehow as an argument 😊

Side effet of arq to streaq migration with some unicity based on function name + args + job id 😅

[Graeme22]

Hi, is there anything still relevant here?

[nsteinmetz]

Hi

Two points remain open:

• Can you confirme the #2 and #3 are retries.
• What about hard deletion (for task that will never happen) ? Are you interested in such a contribution as it seems not available ?

[Graeme22]

• Can you confirme the #2 and #3 are retries.

streaQ will never modify the arguments, could be a problem with your middleware or serialization functions. (Potentially also pickle since I know it can produce different outputs for different python versions)

• What about hard deletion (for task that will never happen) ? Are you interested in such a contribution as it seems not available ?

You can just abort the task no? Why doesn't that work?

[nsteinmetz]

streaQ will never modify the arguments, could be a problem with your middleware or serialization functions. (Potentially also pickle since I know it can produce different outputs for different python versions)

Does the job id have an info about its retry ? Like <job_id>#2 for the 2nd try, <job_id#3> for the 3rd and so on.

I think that the job_id was somehow propagated to my arguments - so I fixed that. It's just to confirm that the #x was coming from streaq.

• What about hard deletion (for task that will never happen) ? Are you interested in such a contribution as it seems not available ?

You can just abort the task no? Why doesn't that work?

With this example, the timestamp is in 2037 ; so it will remain in redis till end of time. I would like to be able to remove such tasks as they will never be triggered and populates the db for nothing valuable.

25) "9245719e7d8c424da8c45060aef393b5" XXX
26) "2136340800000"

27) "f8554bd9de6f4f1ca7abf68da54a0465" XXX
28) "2136340800000"

I agree abortion is enough most of the time and is kind of soft delete. But in a few cases, a hard delete may be required for such edge cases.

[Graeme22]

Does the job id have an info about its retry ? Like <job_id>#2 for the 2nd try, <job_id#3> for the 3rd and so on.

I think that the job_id was somehow propagated to my arguments - so I fixed that. It's just to confirm that the #x was coming from streaq.

Retry info is stored in a separate key, not in the task ID.

With this example, the timestamp is in 2037 ; so it will remain in redis till end of time. I would like to be able to remove such tasks as they will never be triggered and populates the db for nothing valuable.

25) "9245719e7d8c424da8c45060aef393b5" XXX
26) "2136340800000"

27) "f8554bd9de6f4f1ca7abf68da54a0465" XXX
28) "2136340800000"

I agree abortion is enough most of the time and is kind of soft delete. But in a few cases, a hard delete may be required for such edge cases.

When you abort a task all related keys should be removed from Redis. However you can also set an expiration for task data if desired: https://streaq.readthedocs.io/en/latest/api/worker.html#streaq.worker.Worker.task.expire

[nsteinmetz]

Retry info is stored in a separate key, not in the task ID.

Ok - I think I fixed the issue in the meantime but I'll double check in the coming days.

When you abort a task all related keys should be removed from Redis. However you can also set an expiration for task data if desired: https://streaq.readthedocs.io/en/latest/api/worker.html#streaq.worker.Worker.task.expire

I'll investigate this - thanks for the tip.

It was a scheduled task (via <task>.enqueue(<params>).start(schedule=<datetime>)) ; I'll review how task expiration can work in such cases... As task can be scheduled max at a yearly rate, I could indeed add some expiration longer than the next schedule.

But for scheduled/delayed tasks, it won't be remove till trigger if I undersood well ? That's why I thought that these tasks will never be deleted before 2037.

[Graeme22]

Retry info is stored in a separate key, not in the task ID.

Ok - I think I fixed the issue in the meantime but I'll double check in the coming days.

When you abort a task all related keys should be removed from Redis. However you can also set an expiration for task data if desired: https://streaq.readthedocs.io/en/latest/api/worker.html#streaq.worker.Worker.task.expire

I'll investigate this - thanks for the tip.

It was a scheduled task (via <task>.enqueue(<params>).start(schedule=<datetime>)) ; I'll review how task expiration can work in such cases... As task can be scheduled max at a yearly rate, I could indeed add some expiration longer than the next schedule.

But for scheduled/delayed tasks, it won't be remove till trigger if I undersood well ? That's why I thought that these tasks will never be deleted before 2037.

Ah I see what you're saying now. Yes, that's right, I should probably fix that.

[Graeme22]

Looking back over the code, there are subtle reasons why this doesn't delete immediately, but I will try and find a fix.

[Graeme22]

This should be fixed in 66743fb