Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[9.x] Refactor scheduled event lifecycle #39539

Merged
merged 6 commits into from
Dec 7, 2021

Conversation

inxilpro
Copy link
Contributor

@inxilpro inxilpro commented Nov 8, 2021

This is building on the work in #39498. I'm submitting it against 9.x because I've changed some method names. This would only affect applications that have custom versions of Scheduling\Event or Scheduling\CallbackEvent.

This PR splits scheduled event execution into three parts:

  1. start: Run before callbacks (removing mutex on exception)
  2. execute: Execute the command or run the callback
  3. finish: Set the exit code, run after callbacks, remove mutex

By doing so, we can improve the handling of mutex's and minimize the difference between foreground/background execution and across regular and callback events:

  • This removes the need for runCommandInBackground and runCommandInForeground because start/finish are considered separate actions in both cases.
  • We can centralize the calls to callBeforeCallbacks and callAfterCallbacks and easily perform exception handling around them.
  • We can eliminate the need for callAfterCallbacks vs callAfterCallbacksWithExitCode — the finish method is used in foreground and background execution in exactly the same way.
  • Much of the logic in CallbackEvent can be removed now that execute is its own discrete step. All the mutex handling and callback logic stays the same and the only real difference is the execution of the event.

It also addresses a potential race condition in CallbackEvent. Because we register a shutdown function to remove the mutex:

register_shutdown_function(function () use ($pid) {
if ($pid === getmypid()) {
$this->removeMutex();
}
});

And we also remove the mutex in a finally block:

} finally {
$this->removeMutex();
parent::callAfterCallbacks($container);
}

...it's possible that the mutex will be removed twice by the same process. I tested this theory by spawning 100 PHP processes concurrently that created and deleted a lock file using both register_shutdown_function and try/finally. I then logged the results to determine if the lock file was inconsistently removed by both methods:

Show test scripts

Test Script

<?php

$lockfile = __DIR__.DIRECTORY_SEPARATOR.'race-condition.lock';

$log = function($msg) {
	return file_put_contents(
		__DIR__.DIRECTORY_SEPARATOR.'race-condition.log', 
		sprintf("[%s] %s: %s\n", getmypid(), microtime(), $msg),
		FILE_APPEND
	);
};

if (!file_exists($lockfile)) {
	touch($lockfile);
	$log('Creating lock file');
} else {
	$log('Lock file already exists');
}

$cb = function($source) use ($lockfile, $log) {
	$exists = 'lock file missing';
	if (file_exists($lockfile)) {
		$exists = 'lock file present';
		unlink($lockfile);
	}
	$log("$source: $exists");
};

register_shutdown_function(fn() => $cb('register_shutdown_function'));

try {
	usleep(random_int(0, 500));
} finally {
	$cb('finally');
}

Runner

#!/usr/bin/env bash

for i in {1..100}; do
  php race-condition.php > /dev/null 2> /dev/null < /dev/null &
done

You can see from the logs that the lock file was sometimes removed by the try/finally code and at other times was removed inside the register_shutdown_function code:

Show log results

Log File

[95110] 0.34478100 1636408103: Creating lock file
[95102] 0.35211500 1636408103: Lock file already exists
[95102] 0.35521700 1636408103: finally: lock file present
[95102] 0.35562500 1636408103: register_shutdown_function: lock file missing
[95103] 0.35845100 1636408103: Creating lock file
[95109] 0.35908100 1636408103: Lock file already exists
[95104] 0.40124600 1636408103: Lock file already exists
[95104] 0.40284500 1636408103: finally: lock file present
[95104] 0.40342800 1636408103: register_shutdown_function: lock file missing
[95107] 0.42654600 1636408103: Lock file already exists
[95107] 0.42747900 1636408103: finally: lock file present
[95107] 0.42781000 1636408103: register_shutdown_function: lock file missing
[95112] 0.44563000 1636408103: Creating lock file
[95112] 0.44647500 1636408103: finally: lock file present
[95112] 0.44676400 1636408103: register_shutdown_function: lock file missing
[95106] 0.44828400 1636408103: Creating lock file
[95106] 0.44916400 1636408103: finally: lock file present
[95106] 0.44957300 1636408103: register_shutdown_function: lock file missing
[95117] 0.47729400 1636408103: Creating lock file
[95116] 0.47743800 1636408103: Creating lock file
[95118] 0.47845300 1636408103: Lock file already exists
[95116] 0.47883800 1636408103: finally: lock file present
[95118] 0.47911900 1636408103: finally: lock file missing
[95117] 0.47898400 1636408103: finally: lock file missing
[95116] 0.47930100 1636408103: register_shutdown_function: lock file missing
[95118] 0.47970600 1636408103: register_shutdown_function: lock file missing
[95117] 0.47996500 1636408103: register_shutdown_function: lock file missing
[95103] 0.51517300 1636408103: finally: lock file missing
[95103] 0.51545400 1636408103: register_shutdown_function: lock file missing
[95138] 0.52634500 1636408103: Creating lock file
[95110] 0.52726700 1636408103: finally: lock file present
[95110] 0.52757600 1636408103: register_shutdown_function: lock file missing
[95138] 0.52921000 1636408103: finally: lock file present
[95137] 0.52938500 1636408103: Creating lock file
[95138] 0.52965400 1636408103: register_shutdown_function: lock file present
[95137] 0.53034800 1636408103: finally: lock file missing
[95137] 0.53062600 1636408103: register_shutdown_function: lock file missing
[95139] 0.53153100 1636408103: Creating lock file
[95139] 0.53235500 1636408103: finally: lock file present
[95139] 0.53266400 1636408103: register_shutdown_function: lock file missing
[95140] 0.53714700 1636408103: Creating lock file
[95140] 0.53797100 1636408103: finally: lock file present
[95140] 0.53835800 1636408103: register_shutdown_function: lock file missing
[95136] 0.54089300 1636408103: Creating lock file
[95136] 0.54149800 1636408103: finally: lock file missing
[95136] 0.54168200 1636408103: register_shutdown_function: lock file missing
[95122] 0.54242300 1636408103: Creating lock file
[95121] 0.54244000 1636408103: Lock file already exists
[95109] 0.54163700 1636408103: finally: lock file present
[95121] 0.54343000 1636408103: finally: lock file missing
[95109] 0.54340100 1636408103: register_shutdown_function: lock file present
[95122] 0.54351000 1636408103: finally: lock file missing
[95121] 0.54357500 1636408103: register_shutdown_function: lock file missing
[95122] 0.54371900 1636408103: register_shutdown_function: lock file missing
[95125] 0.54451900 1636408103: Creating lock file
[95125] 0.54541500 1636408103: finally: lock file present
[95125] 0.54562900 1636408103: register_shutdown_function: lock file missing
[95126] 0.54746000 1636408103: Creating lock file
[95114] 0.54754000 1636408103: Creating lock file
[95130] 0.54756200 1636408103: Lock file already exists
[95131] 0.54777600 1636408103: Lock file already exists
[95114] 0.54813800 1636408103: finally: lock file present
[95114] 0.54837100 1636408103: register_shutdown_function: lock file missing
[95131] 0.54839800 1636408103: finally: lock file missing
[95126] 0.54842200 1636408103: finally: lock file missing
[95130] 0.54848700 1636408103: finally: lock file missing
[95126] 0.54859300 1636408103: register_shutdown_function: lock file missing
[95130] 0.54868800 1636408103: register_shutdown_function: lock file missing
[95131] 0.54869500 1636408103: register_shutdown_function: lock file missing
[95141] 0.55034200 1636408103: Creating lock file
[95141] 0.55107300 1636408103: finally: lock file present
[95141] 0.55126000 1636408103: register_shutdown_function: lock file missing
[95142] 0.55214700 1636408103: Creating lock file
[95135] 0.55234000 1636408103: Lock file already exists
[95142] 0.55298300 1636408103: finally: lock file present
[95135] 0.55314100 1636408103: finally: lock file missing
[95142] 0.55321300 1636408103: register_shutdown_function: lock file missing
[95135] 0.55335500 1636408103: register_shutdown_function: lock file missing
[95111] 0.56088500 1636408103: Creating lock file
[95111] 0.56256700 1636408103: finally: lock file present
[95111] 0.56306800 1636408103: register_shutdown_function: lock file missing
[95113] 0.56952200 1636408103: Creating lock file
[95127] 0.57065400 1636408103: Lock file already exists
[95113] 0.57079600 1636408103: finally: lock file present
[95113] 0.57107300 1636408103: register_shutdown_function: lock file missing
[95105] 0.57130500 1636408103: Creating lock file
[95127] 0.57137900 1636408103: finally: lock file missing
[95127] 0.57161000 1636408103: register_shutdown_function: lock file missing
[95124] 0.57267200 1636408103: Creating lock file
[95105] 0.57293400 1636408103: finally: lock file present
[95124] 0.57331100 1636408103: finally: lock file missing
[95105] 0.57372200 1636408103: register_shutdown_function: lock file missing
[95124] 0.57381900 1636408103: register_shutdown_function: lock file present
[95128] 0.57384100 1636408103: Creating lock file
[95128] 0.57445800 1636408103: finally: lock file missing
[95128] 0.57460100 1636408103: register_shutdown_function: lock file missing
[95108] 0.57643500 1636408103: Creating lock file
[95108] 0.57766100 1636408103: finally: lock file present
[95108] 0.57927900 1636408103: register_shutdown_function: lock file missing
[95145] 0.58022200 1636408103: Creating lock file
[95144] 0.58035800 1636408103: Creating lock file
[95145] 0.58126600 1636408103: finally: lock file present
[95144] 0.58135900 1636408103: finally: lock file missing
[95144] 0.58156900 1636408103: register_shutdown_function: lock file missing
[95145] 0.58158500 1636408103: register_shutdown_function: lock file missing
[95115] 0.58615000 1636408103: Creating lock file
[95146] 0.58721800 1636408103: Lock file already exists
[95129] 0.58745200 1636408103: Lock file already exists
[95115] 0.58771600 1636408103: finally: lock file present
[95120] 0.58776900 1636408103: Lock file already exists
[95115] 0.58795100 1636408103: register_shutdown_function: lock file missing
[95146] 0.58826800 1636408103: finally: lock file missing
[95146] 0.58909100 1636408103: register_shutdown_function: lock file missing
[95147] 0.58933400 1636408103: Creating lock file
[95143] 0.58990100 1636408103: Lock file already exists
[95129] 0.59043200 1636408103: finally: lock file missing
[95129] 0.59059600 1636408103: register_shutdown_function: lock file missing
[95147] 0.59021000 1636408103: finally: lock file present
[95143] 0.59392200 1636408103: finally: lock file missing
[95147] 0.59387300 1636408103: register_shutdown_function: lock file missing
[95119] 0.59489900 1636408103: Creating lock file
[95143] 0.59487000 1636408103: register_shutdown_function: lock file present
[95120] 0.59553800 1636408103: finally: lock file missing
[95120] 0.59577400 1636408103: register_shutdown_function: lock file missing
[95119] 0.59593300 1636408103: finally: lock file missing
[95153] 0.59646300 1636408103: Creating lock file
[95119] 0.59645000 1636408103: register_shutdown_function: lock file present
[95153] 0.59718500 1636408103: finally: lock file missing
[95153] 0.59739400 1636408103: register_shutdown_function: lock file missing
[95123] 0.60066600 1636408103: Creating lock file
[95123] 0.60179200 1636408103: finally: lock file present
[95123] 0.60215900 1636408103: register_shutdown_function: lock file missing
[95180] 0.60410900 1636408103: Creating lock file
[95150] 0.60421700 1636408103: Lock file already exists
[95180] 0.60493400 1636408103: finally: lock file present
[95150] 0.60533200 1636408103: finally: lock file missing
[95180] 0.60538400 1636408103: register_shutdown_function: lock file missing
[95150] 0.60568600 1636408103: register_shutdown_function: lock file missing
[95133] 0.65389800 1636408103: Creating lock file
[95134] 0.65556800 1636408103: Lock file already exists
[95133] 0.66048500 1636408103: finally: lock file present
[95133] 0.66114600 1636408103: register_shutdown_function: lock file missing
[95134] 0.66465900 1636408103: finally: lock file missing
[95134] 0.66508300 1636408103: register_shutdown_function: lock file missing
[95165] 0.66793400 1636408103: Creating lock file
[95161] 0.66882500 1636408103: Lock file already exists
[95132] 0.65356900 1636408103: Lock file already exists
[95165] 0.66934800 1636408103: finally: lock file present
[95165] 0.67007800 1636408103: register_shutdown_function: lock file missing
[95161] 0.67016100 1636408103: finally: lock file missing
[95161] 0.67085600 1636408103: register_shutdown_function: lock file missing
[95160] 0.67401500 1636408103: Creating lock file
[95160] 0.67509800 1636408103: finally: lock file present
[95160] 0.67560300 1636408103: register_shutdown_function: lock file missing
[95168] 0.67680600 1636408103: Creating lock file
[95189] 0.67703200 1636408103: Creating lock file
[95158] 0.67701400 1636408103: Creating lock file
[95175] 0.67778400 1636408103: Lock file already exists
[95168] 0.67792100 1636408103: finally: lock file present
[95189] 0.67807800 1636408103: finally: lock file missing
[95168] 0.67814000 1636408103: register_shutdown_function: lock file missing
[95158] 0.67825300 1636408103: finally: lock file missing
[95189] 0.67826800 1636408103: register_shutdown_function: lock file missing
[95175] 0.67836100 1636408103: finally: lock file missing
[95158] 0.67843100 1636408103: register_shutdown_function: lock file missing
[95175] 0.67854200 1636408103: register_shutdown_function: lock file missing
[95177] 0.67939200 1636408103: Creating lock file
[95191] 0.68040000 1636408103: Lock file already exists
[95177] 0.68042200 1636408103: finally: lock file present
[95177] 0.68083600 1636408103: register_shutdown_function: lock file present
[95163] 0.68088100 1636408103: Creating lock file
[95191] 0.68122000 1636408103: finally: lock file missing
[95191] 0.68136800 1636408103: register_shutdown_function: lock file missing
[95163] 0.68140200 1636408103: finally: lock file missing
[95163] 0.68156700 1636408103: register_shutdown_function: lock file missing
[95193] 0.68200300 1636408103: Lock file already exists
[95183] 0.68206100 1636408103: Lock file already exists
[95190] 0.68225500 1636408103: Creating lock file
[95192] 0.68230800 1636408103: Lock file already exists
[95197] 0.68236100 1636408103: Lock file already exists
[95184] 0.68257000 1636408103: Lock file already exists
[95193] 0.68265500 1636408103: finally: lock file present
[95192] 0.68276700 1636408103: finally: lock file missing
[95200] 0.68266300 1636408103: Lock file already exists
[95201] 0.68272600 1636408103: Lock file already exists
[95184] 0.68309000 1636408103: finally: lock file missing
[95192] 0.68311200 1636408103: register_shutdown_function: lock file missing
[95193] 0.68314500 1636408103: register_shutdown_function: lock file missing
[95183] 0.68315800 1636408103: finally: lock file missing
[95173] 0.68343900 1636408103: Creating lock file
[95184] 0.68342700 1636408103: register_shutdown_function: lock file present
[95190] 0.68348100 1636408103: finally: lock file missing
[95201] 0.68360800 1636408103: finally: lock file missing
[95183] 0.68361400 1636408103: register_shutdown_function: lock file missing
[95200] 0.68377400 1636408103: finally: lock file missing
[95190] 0.68393900 1636408103: register_shutdown_function: lock file missing
[95173] 0.68410100 1636408103: finally: lock file missing
[95201] 0.68416100 1636408103: register_shutdown_function: lock file missing
[95200] 0.68416100 1636408103: register_shutdown_function: lock file missing
[95173] 0.68438400 1636408103: register_shutdown_function: lock file missing
[95197] 0.68513700 1636408103: finally: lock file present
[95197] 0.68530200 1636408103: register_shutdown_function: lock file missing
[95151] 0.68902700 1636408103: Creating lock file
[95151] 0.69015700 1636408103: finally: lock file present
[95151] 0.69043500 1636408103: register_shutdown_function: lock file missing
[95132] 0.69071800 1636408103: finally: lock file missing
[95132] 0.69101800 1636408103: register_shutdown_function: lock file missing
[95198] 0.69297100 1636408103: Creating lock file
[95148] 0.69309700 1636408103: Creating lock file
[95198] 0.69401800 1636408103: finally: lock file present
[95198] 0.69439700 1636408103: register_shutdown_function: lock file missing
[95148] 0.69440500 1636408103: finally: lock file missing
[95148] 0.69480600 1636408103: register_shutdown_function: lock file missing
[95149] 0.69574800 1636408103: Creating lock file
[95154] 0.69594300 1636408103: Creating lock file
[95149] 0.69672800 1636408103: finally: lock file present
[95154] 0.69708600 1636408103: finally: lock file missing
[95149] 0.69711000 1636408103: register_shutdown_function: lock file missing
[95154] 0.69739800 1636408103: register_shutdown_function: lock file missing
[95156] 0.69835600 1636408103: Creating lock file
[95157] 0.69855600 1636408103: Creating lock file
[95176] 0.69885500 1636408103: Creating lock file
[95156] 0.69943800 1636408103: finally: lock file present
[95176] 0.69962700 1636408103: finally: lock file missing
[95157] 0.69955200 1636408103: finally: lock file present
[95156] 0.69969900 1636408103: register_shutdown_function: lock file missing
[95176] 0.70004000 1636408103: register_shutdown_function: lock file missing
[95157] 0.70007300 1636408103: register_shutdown_function: lock file missing
[95167] 0.70203100 1636408103: Creating lock file
[95155] 0.70312200 1636408103: Lock file already exists
[95167] 0.70320000 1636408103: finally: lock file present
[95167] 0.70349700 1636408103: register_shutdown_function: lock file missing
[95155] 0.70394700 1636408103: finally: lock file missing
[95155] 0.70411000 1636408103: register_shutdown_function: lock file missing
[95164] 0.70453100 1636408103: Creating lock file
[95169] 0.70458500 1636408103: Lock file already exists
[95181] 0.70471700 1636408103: Lock file already exists
[95181] 0.70527400 1636408103: finally: lock file missing
[95169] 0.70531900 1636408103: finally: lock file missing
[95164] 0.70525600 1636408103: finally: lock file present
[95181] 0.70541800 1636408103: register_shutdown_function: lock file missing
[95169] 0.70557900 1636408103: register_shutdown_function: lock file missing
[95164] 0.70557900 1636408103: register_shutdown_function: lock file missing
[95199] 0.70806900 1636408103: Creating lock file
[95174] 0.70912200 1636408103: Lock file already exists
[95199] 0.70915200 1636408103: finally: lock file present
[95199] 0.70962100 1636408103: register_shutdown_function: lock file missing
[95174] 0.70970400 1636408103: finally: lock file missing
[95174] 0.70993700 1636408103: register_shutdown_function: lock file missing
[95178] 0.71026100 1636408103: Creating lock file
[95195] 0.71047400 1636408103: Lock file already exists
[95195] 0.71136000 1636408103: finally: lock file present
[95195] 0.71161300 1636408103: register_shutdown_function: lock file missing
[95178] 0.71297200 1636408103: finally: lock file present
[95178] 0.71320400 1636408103: register_shutdown_function: lock file missing
[95179] 0.71750400 1636408103: Creating lock file
[95179] 0.71829200 1636408103: finally: lock file present
[95179] 0.71859300 1636408103: register_shutdown_function: lock file missing
[95188] 0.71937800 1636408103: Creating lock file
[95188] 0.72077200 1636408103: finally: lock file present
[95188] 0.72124800 1636408103: register_shutdown_function: lock file missing
[95152] 0.72276900 1636408103: Creating lock file
[95152] 0.72382900 1636408103: finally: lock file present
[95187] 0.72478800 1636408103: Creating lock file
[95152] 0.72481200 1636408103: register_shutdown_function: lock file present
[95187] 0.72565700 1636408103: finally: lock file missing
[95196] 0.72597200 1636408103: Creating lock file
[95187] 0.72601900 1636408103: register_shutdown_function: lock file present
[95186] 0.72700200 1636408103: Creating lock file
[95196] 0.72702200 1636408103: finally: lock file present
[95185] 0.72709900 1636408103: Lock file already exists
[95196] 0.72726400 1636408103: register_shutdown_function: lock file missing
[95186] 0.72779400 1636408103: finally: lock file missing
[95186] 0.72794500 1636408103: register_shutdown_function: lock file missing
[95185] 0.72799900 1636408103: finally: lock file missing
[95185] 0.72810100 1636408103: register_shutdown_function: lock file missing
[95159] 0.72877400 1636408103: Creating lock file
[95172] 0.72942500 1636408103: Lock file already exists
[95159] 0.72953100 1636408103: finally: lock file present
[95182] 0.72959800 1636408103: Lock file already exists
[95172] 0.72975900 1636408103: finally: lock file missing
[95159] 0.72979600 1636408103: register_shutdown_function: lock file missing
[95172] 0.72987600 1636408103: register_shutdown_function: lock file missing
[95182] 0.73011800 1636408103: finally: lock file missing
[95182] 0.73023400 1636408103: register_shutdown_function: lock file missing
[95166] 0.73182800 1636408103: Creating lock file
[95171] 0.73247500 1636408103: Lock file already exists
[95170] 0.73268800 1636408103: Lock file already exists
[95194] 0.73279300 1636408103: Lock file already exists
[95162] 0.73286300 1636408103: Lock file already exists
[95166] 0.73286500 1636408103: finally: lock file present
[95166] 0.73304700 1636408103: register_shutdown_function: lock file missing
[95170] 0.73312200 1636408103: finally: lock file missing
[95170] 0.73321600 1636408103: register_shutdown_function: lock file missing
[95171] 0.73335700 1636408103: finally: lock file missing
[95171] 0.73346900 1636408103: register_shutdown_function: lock file missing
[95162] 0.73362900 1636408103: finally: lock file missing
[95194] 0.73363000 1636408103: finally: lock file missing
[95162] 0.73375500 1636408103: register_shutdown_function: lock file missing
[95194] 0.73376300 1636408103: register_shutdown_function: lock file missing

As a result, I feel like this refactor is doubly valuable, as it mitigates the race condition while also minimizing the difference between Event and CallbackEvent.

@taylorotwell
Copy link
Member

taylorotwell commented Dec 1, 2021

@inxilpro This works on 8.x but doesn't work on this PR. The "after" log is never written:

CleanShot 2021-12-01 at 08 53 59@2x

That makes me uneasy about this entire PR. 😬 That there could be other subtle (or even not so subtle bugs like this one) present.

@inxilpro
Copy link
Contributor Author

inxilpro commented Dec 1, 2021

@taylorotwell yeah—it's tricky since there aren't really any tests for the scheduler. Let me see what I can come up with. I'll close for now and re-submit if I feel like I have a better way to ensure it doesn't break anything.

@inxilpro inxilpro reopened this Dec 2, 2021
@inxilpro
Copy link
Contributor Author

inxilpro commented Dec 2, 2021

@taylorotwell the issue with doing $schedule->call()->runInBackground() is that runInBackground doesn't actually work on callbacks (it's just ignored in 8.x). Because this refactor unifies the Event and CallbackEvent implementations, that's now an issue. The solution is to trigger an exception when runInBackground() is called on a CallbackEvent, because it's not possible to run callbacks in the background.

(Another solution would be to continue to ignore it, but that seems more like a bug to me.)

@taylorotwell taylorotwell merged commit d8bea92 into laravel:master Dec 7, 2021
@taylorotwell
Copy link
Member

Thanks for contributing to Laravel! ❤️

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants