Bug #25615: Scheduler floods sys_log in endless loop if a task is running and multiple executions isn't allowed - TYPO3 Core - TYPO3 Forge

Actions

Copy link

Bug #25615

closed

Scheduler floods sys_log in endless loop if a task is running and multiple executions isn't allowed

Added by Christian Kuhn over 14 years ago. Updated over 10 years ago.

Status:

Closed

Priority:

Must have

Assignee:

Francois Suter

Category:

scheduler

Target version:

Start date:

2009-09-26

Due date:

% Done:

Estimated time:

TYPO3 Version:

PHP Version:

Tags:

Complexity:

Is Regression:

Sprint Focus:

Description

How to reproduce:
- Create a sleep test task with 300 seconds
- Call the scheduler cli to start the 5 minute task
- Call a second cli while the first cli is still running. This cli will only end after the first cli terminated, hammering sys_log table as fast as it can with messages like "[scheduler]: Task is already running and multiple executions are not allowed, skipping! Class: tx_scheduler_SleepTask, UID: 3"

This is because the fetchTask() in the cli class fetches the running task again and again so that hasTask will never be false:
The following queries will be executed in an endless loop until the first cli terminates:

157 Query       SELECT serialized_task_object
            FROM tx_scheduler_task
            WHERE
                disable = 0 AND nextexecution != 0 AND nextexecution <= 1253990423
            LIMIT 1

157 Query       SELECT serialized_executions
            FROM tx_scheduler_task
            WHERE
                uid = 3
            LIMIT 1

157 Query       INSERT INTO sys_log
                (
                    userid,
                    type,
                    action,
                    error,
                    details_nr,
                    details,
                    log_data,
                    tablename,
                    recuid,
                    IP,
                    tstamp,
                    event_pid,
                    NEWid,
                    workspace
                ) VALUES (
                    '20',
                    '4',
                    '0',
                    '0',
                    '0',
                    '[scheduler]: Task is already running and multiple executions are not allowed, skipping! Class: tx_scheduler_SleepTask, UID: 3',
                    'a:0:{}',
                    '',
                    '0',
                    '',
                    '1253990423',
                    '-1',
                    '',
                    '0'
                )

(issue imported from #M12068)

Related issues 1 (0 open — 1 closed)

Actions

Copy link

Updated by Christian Kuhn over 14 years ago

For your amusement here is a sum-up of what happened to us tonight on one of our development servers:

- Yesterday we created the scheduler cli cronjob to call the scheduler every minute.
- We scheduled our first task to be executed 1 minute after midnight. This daily task is expected to later run several minutes in production.
- At midnight the cli executed the task, set up his information in serialized_executions and failed with a call to an undefined function due to a programming error in the task (well, it's development ;), so that it was never marked as done again.
- One minute later the next cli started and run into the endless loop (because the failed task was not marked as done), starting to write sys_log entries as fast as it could. This cli never died (well, maybe after max_execution_time, but I'm not sure here).
- One minute later the next task started writing to sys_log and so on, until after about one and a half hours max_connections (100) of mysql was reached, so every cli call forked now sent a mail to us, telling that it was unable to connect to the database.
- Around 3 o'clock the daily mysqldump started and happily dumped the database to the filesystem, sys_log was about 15 gig at that time, this took about 45 minutes.
- At 4 o'clock the daily backup rotation script started and rotated the db dump into the backup system.
- At 11 o'clock the first developer called and said he is unable to log in to the backend because the login in unable to connect to the database. We quickly discovered the problem, killed the running cli's and stopped the cronjob.
- At this point we had about 100 cli php scripts running with full cpu load on a 8 processor system. They created about 40gig of garbage in the innodb sys_log table, with several other gigs of garbage in the sql dump and the backup system. Thanks to the developer working this saturday we were able to kill everything before the filesystem was completely full (we were at 80%).
- It took us quite some time clean this mess up and to track the root of this hazard. Biggest problem was to shrink the main ibdata1 file of mysql again, which we now changed to one innodb file per innodb table (my.cnf: innodb_file_per_table)
- We decided to not run the cronjob again until this bug is fixed ^^

Actions

Copy link

Updated by Francois Suter over 14 years ago

As discussed per mail, the best solution is to also calculate the next execution time even when an execution is skipped. This is equivalent to what you said: calculating the next execution time earlier, right at the start of tx_scheduler::executeTask().

I have patched my local install and it seems to work. However it does change a bit the reporting of tx_scheduler::executeTask(), so I just need to think a bit more about it and with a rested brain ;-)

Patch will come soon anyway.

Actions

Copy link