Strange timing with spoolers and delayed tasks

[chrisdevilliers]

Consider the following task:

@task(executor=TaskExecutor.SPOOLER, at=timedelta(seconds=30))
def delayed_task():
    logger.info("!!! Inside delayed task !!!")
    return SPOOL_OK

and the following uwsgi spooler config:

spooler = ~/projects/backend/spool
spooler-processes = 2
spooler-frequency = 1

I've set the frequency to 1 to illustrate the timing better.
Here is a uwsgi log of calling my delayed_task twice in a row:

*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 621942)
spawned the uWSGI spooler on dir ~/projects/backend/spool with pid 621965
spawned the uWSGI spooler on dir ~/projects/backend/spool with pid 621966
spawned uWSGI worker 1 (pid: 621967, cores: 1)
spawned uWSGI worker 2 (pid: 621969, cores: 1)
spawned uWSGI worker 3 (pid: 621971, cores: 1)
spawned uWSGI worker 4 (pid: 621973, cores: 1)
spawned uWSGI http 1 (pid: 621975)

# Run 1

INFO 2023-07-25 15:45:47,789 tasks 621971 139671951718336 Executing asynchronously <Task: SpoolerTask for "backend.legacy.tasks.delayed_task" with args=(), kwargs={}>
[spooler] written 223 bytes to file ~/projects/backend/spool/uwsgi_spoolfile_on_eos_621971_1_1943507040_1690292747_789700

[spooler ~/projects/backend/spool pid: 621966] managing request uwsgi_spoolfile_on_eos_621971_1_1943507040_1690292747_789700 ...
INFO 2023-07-25 15:46:17,927 tasks 621966 139671951718336 Executing <Task: SpoolerTask for "backend.legacy.tasks.delayed_task" with args=(), kwargs={}>
INFO 2023-07-25 15:46:18,152 tasks 621966 139671951718336 Executing asynchronously <Task: SpoolerTask for "backend.legacy.tasks.delayed_task" with args=(), kwargs={}>
[spooler] written 223 bytes to file ~/projects/backend/spool/uwsgi_spoolfile_on_eos_621966_1_1943507040_1690292778_152761
[spooler ~/projects/backend/spool pid: 621966] done with task uwsgi_spoolfile_on_eos_621971_1_1943507040_1690292747_789700 after 1 seconds

[spooler ~/projects/backend/spool pid: 621965] managing request uwsgi_spoolfile_on_eos_621966_1_1943507040_1690292778_152761 ...
INFO 2023-07-25 15:46:48,305 tasks 621965 139671951718336 Executing <Task: SpoolerTask for "backend.legacy.tasks.delayed_task" with args=(), kwargs={}>
INFO 2023-07-25 15:46:48,538 tasks 621965 139671951718336 Executing asynchronously <Task: SpoolerTask for "backend.legacy.tasks.delayed_task" with args=(), kwargs={}>
[spooler] written 223 bytes to file ~/projects/backend/spool/uwsgi_spoolfile_on_eos_621965_1_1943507040_1690292808_538947
[spooler ~/projects/backend/spool pid: 621965] done with task uwsgi_spoolfile_on_eos_621966_1_1943507040_1690292778_152761 after 0 seconds

[spooler ~/projects/backend/spool pid: 621966] managing request uwsgi_spoolfile_on_eos_621965_1_1943507040_1690292808_538947 ...
INFO 2023-07-25 15:47:18,690 tasks 621966 139671951718336 Executing <Task: SpoolerTask for "backend.legacy.tasks.delayed_task" with args=(), kwargs={}>
INFO 2023-07-25 15:47:18,691 tasks 621966 139671951718336 !!! Inside delayed task !!!
[spooler ~/projects/backend/spool pid: 621966] done with task uwsgi_spoolfile_on_eos_621965_1_1943507040_1690292808_538947 after 0 seconds

# Run 2 (without restarting uwsgi)

INFO 2023-07-25 15:47:26,556 tasks 621971 139671951718336 Executing asynchronously <Task: SpoolerTask for "backend.legacy.tasks.delayed_task" with args=(), kwargs={}>
[spooler] written 223 bytes to file ~/projects/backend/spool/uwsgi_spoolfile_on_eos_621971_2_970558758_1690292846_557172

[spooler ~/projects/backend/spool pid: 621965] managing request uwsgi_spoolfile_on_eos_621971_2_970558758_1690292846_557172 ...
INFO 2023-07-25 15:47:56,702 tasks 621965 139671951718336 Executing <Task: SpoolerTask for "backend.legacy.tasks.delayed_task" with args=(), kwargs={}>
INFO 2023-07-25 15:47:56,702 tasks 621965 139671951718336 !!! Inside delayed task !!!
[spooler ~/projects/backend/spool pid: 621965] done with task uwsgi_spoolfile_on_eos_621971_2_970558758_1690292846_557172 after 0 seconds

You will notice that during the first run the worker creates the spool file, then the second spooler picks up the file and creates a new spool file. The first spooler picks up the new file and create another spool file. Finally the second spooler picks up the file and executes the delayed task 1m30s later. Note the timedelta in the @task was set to 30s.

During the second run the worker creates the spool file and 30s later the first spooler picks up the file and executes the delayed task. From here on forward the delayed task is always executed 30s after the worker creates the spool file as long as uwsgi is not restarted!

The 2nd run is what I would expect to happen. The task is created and executed at the timedelta amount later. The 1st run is almost as if each spooler process first needs to initialise itself and then only can it execute the task causing a 3x delay. This is of course exaggerated as more spooler processes are added, each one having to do a "dummy" run before being able to execute the task.

I tried to debug this and think it has something to do with the importing of the tasks module into the spooler processes, but I ran out of talent. Please help!

[Bahus]

Hello, did you try to add lasy-apps: true in your uwsgi configuration file? How do you trigger the task execution?