Skip to content

Scheduled ->everyMinute() task is running twice per minute #435

Closed
@emilebourquin

Description

@emilebourquin

Steps To Reproduce

  1. Install a brand-new copy of Laravel in a new test directory

  2. Change contents of routes/console.php to:

<?php
use Illuminate\Support\Facades\Log;

Schedule::call(function () {
    Log::debug('THIS IS A SCHEDULED LOG ENTRY '.time());
})->everyMinute();
  1. Add a file named Dockerfile_scheduled:
FROM serversideup/php:8.3-cli
USER www-data
COPY --chown=www-data:www-data ./src /var/www/html
CMD ["php", "artisan", "schedule:work"]
  1. Build the Docker image using the command:
docker build -t test_scheduled -f Dockerfile_scheduled .
  1. In Docker Desktop, run the test_scheduled image

  2. Observe the log of the container

2024-09-25 09:23:10    INFO  Running scheduled tasks every minute.  
2024-09-25 09:23:10 
2024-09-25 09:24:00   2024-09-25 16:24:00 Running [Callback] ......................... 2.29ms DONE
2024-09-25 09:24:00   2024-09-25 16:24:00 Running [Callback] ......................... 0.05ms DONE
2024-09-25 09:24:00 
2024-09-25 09:25:00   2024-09-25 16:25:00 Running [Callback] ......................... 6.69ms DONE
2024-09-25 09:25:00   2024-09-25 16:25:00 Running [Callback] ......................... 0.07ms DONE
2024-09-25 09:25:00 
2024-09-25 09:26:00   2024-09-25 16:26:00 Running [Callback] ......................... 2.19ms DONE
2024-09-25 09:26:00   2024-09-25 16:26:00 Running [Callback] ......................... 0.05ms DONE
  1. Observe the Laravel log file
[2024-09-25 16:24:00] local.DEBUG: THIS IS A SCHEDULED LOG ENTRY 1727281440
[2024-09-25 16:24:00] local.DEBUG: THIS IS A SCHEDULED LOG ENTRY 1727281440
[2024-09-25 16:25:00] local.DEBUG: THIS IS A SCHEDULED LOG ENTRY 1727281500
[2024-09-25 16:25:00] local.DEBUG: THIS IS A SCHEDULED LOG ENTRY 1727281500
[2024-09-25 16:26:00] local.DEBUG: THIS IS A SCHEDULED LOG ENTRY 1727281560
[2024-09-25 16:26:00] local.DEBUG: THIS IS A SCHEDULED LOG ENTRY 1727281560

Observations
The Container log file shows the first callback run in a few milliseconds, and the second run in 100ths of a millisecond, as if the same PHP process is running the second closure call quickly, as it has already been loaded into memory/bytecode.

I built the Dockerfile with procps in it:

FROM serversideup/php:8.3-cli
USER root
RUN apt-get update \
    && apt-get install -y procps \
    && apt-get clean \
    && rm -rf /var/lib/apt/lists/* /tmp/* /var/tmp/* /usr/share/doc/*
USER www-data
COPY --chown=www-data:www-data ./src /var/www/html
CMD ["php", "artisan", "schedule:work"]

and "ps ax" shows:

PID TTY      STAT   TIME COMMAND
    1 ?        Ss     0:00 php artisan schedule:work
   17 pts/0    Ss     0:00 /bin/sh
   29 pts/0    R+     0:00 ps ax

Outcome

I expect the scheduled closure to run once per minute.

The scheduled closure runs twice per minute.

Affected Docker Images

serversideup/php:8.3-cli

Anything else?

No response

Metadata

Metadata

Assignees

Labels

🥶 Bug: Upstream DependencyBugs that affect this project, but need to be fixed in an upsteam library.

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions