DeadLockTest::setLogFile() - Code Metrics - Inspection of "Merge pull request #19 from terabytesoftw/add-test..." - yiisoft/db-mysql - Measure and Improve Code Quality continuously with Scrutinizer

Passed

Push — master ( 74cbfa...01b9fc )

by Wilmer

created 2020-03-11 13:22 UTC

DeadLockTest::setLogFile() A

↳ Parent: DeadLockTest

Complexity

Conditions	1
Paths	1

Size

Total Lines	3
Code Lines	1

Duplication

Lines	0
Ratio	0 %

Importance

Changes

Metric	Value
cc	1
eloc	1
nc	1
nop	1
dl	0
loc	3
rs	10
c	0
b	0
f	0

<?php

declare(strict_types=1);

namespace Yiisoft\Db\Mysql\Tests;

use Yiisoft\Db\Connection\Connection;
use Yiisoft\Db\Exception\Exception;
use Yiisoft\Db\Transaction\Transaction;

class DeadLockTest extends \Yiisoft\Db\Mysql\Tests\ConnectionTest
{
    /** @var string Shared log filename for children */
    private $logFile;

    public const CHILD_EXIT_CODE_DEADLOCK = 15;

    protected ?string $driverName = 'mysql';

    /**
     * Test deadlock exception.
     *
     * Accident deadlock exception lost while rolling back a transaction or savepoint
     *
     * @link https://github.com/yiisoft/yii2/issues/12715
     * @link https://github.com/yiisoft/yii2/pull/13346
     */
    public function testDeadlockException()
    {
        if (!\function_exists('pcntl_fork')) {
            $this->markTestSkipped('pcntl_fork() is not available');
        }

        if (!\function_exists('posix_kill')) {
            $this->markTestSkipped('posix_kill() is not available');
        }

        if (!\function_exists('pcntl_sigtimedwait')) {
            $this->markTestSkipped('pcntl_sigtimedwait() is not available');
        }

        $this->setLogFile(sys_get_temp_dir() . '/deadlock_' . posix_getpid());
        $this->deleteLog();

        try {
            /**
             * to cause deadlock we do:
             *
             * 1. FIRST errornously forgot "FOR UPDATE" while read the row for next update.
             * 2. SECOND does update the row and locks it exclusively.
             * 3. FIRST tryes to update the row too, but it already has shared lock. Here comes deadlock.
             * FIRST child will send the signal to the SECOND child.
             * So, SECOND child should be forked at first to obtain its PID.
             */

            $pidSecond = pcntl_fork();

            if (-1 === $pidSecond) {
                $this->markTestIncomplete('cannot fork');
            }

            if (0 === $pidSecond) {
                /** SECOND child */
                $this->setErrorHandler();
                exit($this->childrenUpdateLocked());

            }

            $pidFirst = pcntl_fork();

            if (-1 === $pidFirst) {
                $this->markTestIncomplete('cannot fork second child');
            }

            if (0 === $pidFirst) {
                /** FIRST child */
                $this->setErrorHandler();
                exit($this->childrenSelectAndAccidentUpdate($pidSecond));

            }

            /**
             * PARENT
             * nothing to do
             */
        } catch (\Exception $e) {
            /** wait all children */
            while (-1 !== pcntl_wait($status)) {
                /** nothing to do */
            }
            $this->deleteLog();

            throw $e;
        } catch (\Throwable $e) {
            /** wait all children */
            while (-1 !== pcntl_wait($status)) {
                /** nothing to do */
            }
            $this->deleteLog();

            throw $e;
        }

        /**
         * wait all children all must exit with success
         */
        $errors = [];
        $deadlockHitCount = 0;

        while (-1 !== pcntl_wait($status)) {
            if (!pcntl_wifexited($status)) {
                $errors[] = 'child did not exit itself';
            } else {
                $exitStatus = pcntl_wexitstatus($status);
                if (self::CHILD_EXIT_CODE_DEADLOCK === $exitStatus) {
                    $deadlockHitCount++;
                } elseif (0 !== $exitStatus) {
                    $errors[] = 'child exited with error status';
                }
            }
        }

        $logContent = $this->getLogContentAndDelete();

        if ($errors) {
            $this->fail(
                implode('; ', $errors)
                . ($logContent ? ". Shared children log:\n$logContent" : '')
            );
        }
        $this->assertEquals(
            1,
            $deadlockHitCount,
            "exactly one child must hit deadlock; shared children log:\n" . $logContent
        );
    }

    /**
     * Main body of first child process.
     *
     * First child initializes test row and runs two nested {@see Connection::transaction()} to perform following
     * operations:
     * 1. `SELECT ... LOCK IN SHARE MODE` the test row with shared lock instead of needed exclusive lock.
     * 2. Send signal to SECOND child identified by PID {@see $pidSecond}.
     * 3. Waits few seconds.
     * 4. `UPDATE` the test row.
     *
     * @param int $pidSecond
     *
     * @return int Exit code. In case of deadlock exit code is {@see CHILD_EXIT_CODE_DEADLOCK}. In case of success exit
     * code is 0. Other codes means an error.
     */
    private function childrenSelectAndAccidentUpdate(int $pidSecond): int
    {
        try {
            $this->log('child 1: connect');

            /** @var Connection $first */
            $first = $this->getConnection(false, false);

            $this->log('child 1: delete');

            $first->createCommand()
                ->delete('{{customer}}', ['id' => 97])
                ->execute();

            $this->log('child 1: insert');

            /** insert test row */
            $first->createCommand()
                ->insert('{{customer}}', [
                    'id'      => 97,
                    'email'   => '[email protected]',
                    'name'    => 'test',
                    'address' => 'test address',
                ])
                ->execute();

            $this->log('child 1: transaction');

            $first->transaction(function (Connection $first) use ($pidSecond) {
                $first->transaction(function (Connection $first) use ($pidSecond) {
                    $this->log('child 1: select');
                    /** SELECT with shared lock */
                    $first->createCommand('SELECT id FROM {{customer}} WHERE id = 97 LOCK IN SHARE MODE')
                        ->execute();

                    $this->log('child 1: send signal to child 2');
                    // let child to continue
                    if (!posix_kill($pidSecond, SIGUSR1)) {
                        throw new \RuntimeException('Cannot send signal');
                    }

                    /** now child 2 tries to do the 2nd update, and hits the lock and waits */

                    /** delay to let child hit the lock */
                    sleep(2);

                    $this->log('child 1: update');
                    /** now do the 3rd update for deadlock */
                    $first->createCommand()
                        ->update('{{customer}}', ['name' => 'first'], ['id' => 97])
                        ->execute();
                    $this->log('child 1: commit');
                });
            }, Transaction::REPEATABLE_READ);
        } catch (Exception $e) {
            [$sqlError, $driverError, $driverMessage] = $e->errorInfo;
            /** Deadlock found when trying to get lock; try restarting transaction */
            if ('40001' === $sqlError && 1213 === $driverError) {
                return self::CHILD_EXIT_CODE_DEADLOCK;
            }
            $this->log("child 1: ! sql error $sqlError: $driverError: $driverMessage");

            return 1;
        } catch (\Exception $e) {
            $this->log(
                'child 1: ! exit <<' . \get_class($e) . ' #' . $e->getCode() . ': ' . $e->getMessage() . "\n"
                . $e->getTraceAsString() . '>>'
            );

            return 1;
        } catch (\Throwable $e) {
            $this->log(
                'child 1: ! exit <<' . \get_class($e) . ' #' . $e->getCode() . ': ' . $e->getMessage() . "\n"
                . $e->getTraceAsString() . '>>'
            );

            return 1;
        }
        $this->log('child 1: exit');

        return 0;
    }

    /**
     * Main body of second child process.
     *
     * Second child at first will wait the signal from the first child in some seconds.
     *
     * After receiving the signal it runs two nested {@see Connection::transaction()} to perform `UPDATE` with the test
     * row.
     *
     * @return int Exit code. In case of deadlock exit code is {@see CHILD_EXIT_CODE_DEADLOCK}. In case of success exit
     * code is 0. Other codes means an error.
     */
    private function childrenUpdateLocked()
    {
        /** install no-op signal handler to prevent termination */
        if (!pcntl_signal(SIGUSR1, function () {}, false)) {
            $this->log('child 2: cannot install signal handler');

            return 1;
        }

        try {
            /** at first, parent should do 1st select */
            $this->log('child 2: wait signal from child 1');
            if (pcntl_sigtimedwait([SIGUSR1], $info, 10) <= 0) {
                $this->log('child 2: wait timeout exceeded');

                return 1;
            }

            $this->log('child 2: connect');
            /** @var Connection $second */
            $second = $this->getConnection(true, false);
            $second->open();
            /** sleep(1); */
            $this->log('child 2: transaction');
            $second->transaction(function (Connection $second) {
                $second->transaction(function (Connection $second) {
                    $this->log('child 2: update');
                    // do the 2nd update
                    $second->createCommand()
                        ->update('{{customer}}', ['name' => 'second'], ['id' => 97])
                        ->execute();

                    $this->log('child 2: commit');
                });
            }, Transaction::REPEATABLE_READ);
        } catch (Exception $e) {
            [$sqlError, $driverError, $driverMessage] = $e->errorInfo;
            /** Deadlock found when trying to get lock; try restarting transaction */
            if ('40001' === $sqlError && 1213 === $driverError) {
                return self::CHILD_EXIT_CODE_DEADLOCK;
            }
            $this->log("child 2: ! sql error $sqlError: $driverError: $driverMessage");

            return 1;
        } catch (\Exception $e) {
            $this->log(
                'child 2: ! exit <<' . \get_class($e) . ' #' . $e->getCode() . ': ' . $e->getMessage() . "\n"
                . $e->getTraceAsString() . '>>'
            );

            return 1;
        } catch (\Throwable $e) {
            $this->log(
                'child 2: ! exit <<' . \get_class($e) . ' #' . $e->getCode() . ': ' . $e->getMessage() . "\n"
                . $e->getTraceAsString() . '>>'
            );

            return 1;
        }
        $this->log('child 2: exit');

        return 0;
    }

    /**
     * Set own error handler.
     *
     * In case of error in child process its execution bubbles up to phpunit to continue all the rest tests. So, all
     * the rest tests in this case will run both in the child and parent processes. Such mess must be prevented with
     * child's own error handler.
     */
    private function setErrorHandler()
    {
        set_error_handler(function ($errno, $errstr, $errfile, $errline) {
            throw new \ErrorException($errstr, $errno, $errno, $errfile, $errline);
        });
    }

    /**
     * Sets filename for log file shared between children processes.
     *
     * @param string $filename
     */
    private function setLogFile(string $filename): void
    {
        $this->logFile = $filename;
    }

    /**
     * Deletes shared log file.
     *
     * Deletes the file {@see logFile} if it exists.
     */
    private function deleteLog(): void
    {
        if (null !== $this->logFile && is_file($this->logFile)) {
            unlink($this->logFile);
        }
    }

    /**
     * Reads shared log content and deletes the log file.
     *
     * Reads content of log file {@see logFile} and returns it deleting the file.
     *
     * @return string|null String content of the file {@see logFile}. `false` is returned when file cannot be read.
     * `null` is returned when file does not exist or {@see logFile} is not set.
     */
    private function getLogContentAndDelete(): ?string
    {
        if (null !== $this->logFile && is_file($this->logFile)) {
            $content = file_get_contents($this->logFile);
            unlink($this->logFile);

            return $content;
        }
    }

    /**
     * Append message to shared log.
     *
     * @param string $message Message to append to the log. The message will be prepended with timestamp and appended
     * with new line.
     */
    private function log(string $message): void
    {
        if (null !== $this->logFile) {
            $time = microtime(true);
            $timeInt = floor($time);
            $timeFrac = $time - $timeInt;
            $timestamp = date('Y-m-d H:i:s', (int) $timeInt) . '.' . round($timeFrac * 1000);
            file_put_contents($this->logFile, "[$timestamp] $message\n", FILE_APPEND | LOCK_EX);
        }
    }
}


1			<?php
2
3			declare(strict_types=1);
4
5			namespace Yiisoft\Db\Mysql\Tests;
6
7			use Yiisoft\Db\Connection\Connection;
8			use Yiisoft\Db\Exception\Exception;
9			use Yiisoft\Db\Transaction\Transaction;
10
11			class DeadLockTest extends \Yiisoft\Db\Mysql\Tests\ConnectionTest
12			{
13			/** @var string Shared log filename for children */
14			private $logFile;
15
16			public const CHILD_EXIT_CODE_DEADLOCK = 15;
17
18			protected ?string $driverName = 'mysql';
19
20			/**
21			* Test deadlock exception.
22			*
23			* Accident deadlock exception lost while rolling back a transaction or savepoint
24			*
25			* @link https://github.com/yiisoft/yii2/issues/12715
26			* @link https://github.com/yiisoft/yii2/pull/13346
27			*/
28			public function testDeadlockException()
29			{
30			if (!\function_exists('pcntl_fork')) {
31			$this->markTestSkipped('pcntl_fork() is not available');
32			}
33
34			if (!\function_exists('posix_kill')) {
35			$this->markTestSkipped('posix_kill() is not available');
36			}
37
38			if (!\function_exists('pcntl_sigtimedwait')) {
39			$this->markTestSkipped('pcntl_sigtimedwait() is not available');
40			}
41
42			$this->setLogFile(sys_get_temp_dir() . '/deadlock_' . posix_getpid());
43			$this->deleteLog();
44
45			try {
46			/**
47			* to cause deadlock we do:
48			*
49			* 1. FIRST errornously forgot "FOR UPDATE" while read the row for next update.
50			* 2. SECOND does update the row and locks it exclusively.
51			* 3. FIRST tryes to update the row too, but it already has shared lock. Here comes deadlock.
52			* FIRST child will send the signal to the SECOND child.
53			* So, SECOND child should be forked at first to obtain its PID.
54			*/
55
56			$pidSecond = pcntl_fork();
57
58			if (-1 === $pidSecond) {
59			$this->markTestIncomplete('cannot fork');
60			}
61
62			if (0 === $pidSecond) {
63			/** SECOND child */
64			$this->setErrorHandler();
65			exit($this->childrenUpdateLocked());
			0 ignored issues – show Best Practice introduced 2020-02-14 12:51 UTC by Report Bug Copy Issue Report Using `exit` here is not recommended. In general, usage of exit should be done with care and only when running in a scripting context like a CLI script. Loading history...
66			}
67
68			$pidFirst = pcntl_fork();
69
70			if (-1 === $pidFirst) {
71			$this->markTestIncomplete('cannot fork second child');
72			}
73
74			if (0 === $pidFirst) {
75			/** FIRST child */
76			$this->setErrorHandler();
77			exit($this->childrenSelectAndAccidentUpdate($pidSecond));
			0 ignored issues – show Best Practice introduced 2020-02-14 12:51 UTC by Report Bug Copy Issue Report Using `exit` here is not recommended. In general, usage of exit should be done with care and only when running in a scripting context like a CLI script. Loading history...
78			}
79
80			/**
81			* PARENT
82			* nothing to do
83			*/
84			} catch (\Exception $e) {
85			/** wait all children */
86			while (-1 !== pcntl_wait($status)) {
87			/** nothing to do */
88			}
89			$this->deleteLog();
90
91			throw $e;
92			} catch (\Throwable $e) {
93			/** wait all children */
94			while (-1 !== pcntl_wait($status)) {
95			/** nothing to do */
96			}
97			$this->deleteLog();
98
99			throw $e;
100			}
101
102			/**
103			* wait all children all must exit with success
104			*/
105			$errors = [];
106			$deadlockHitCount = 0;
107
108			while (-1 !== pcntl_wait($status)) {
109			if (!pcntl_wifexited($status)) {
110			$errors[] = 'child did not exit itself';
111			} else {
112			$exitStatus = pcntl_wexitstatus($status);
113			if (self::CHILD_EXIT_CODE_DEADLOCK === $exitStatus) {
114			$deadlockHitCount++;
115			} elseif (0 !== $exitStatus) {
116			$errors[] = 'child exited with error status';
117			}
118			}
119			}
120
121			$logContent = $this->getLogContentAndDelete();
122
123			if ($errors) {
124			$this->fail(
125			implode('; ', $errors)
126			. ($logContent ? ". Shared children log:\n$logContent" : '')
127			);
128			}
129			$this->assertEquals(
130			1,
131			$deadlockHitCount,
132			"exactly one child must hit deadlock; shared children log:\n" . $logContent
133			);
134			}
135
136			/**
137			* Main body of first child process.
138			*
139			* First child initializes test row and runs two nested {@see Connection::transaction()} to perform following
140			* operations:
141			* 1. `SELECT ... LOCK IN SHARE MODE` the test row with shared lock instead of needed exclusive lock.
142			* 2. Send signal to SECOND child identified by PID {@see $pidSecond}.
143			* 3. Waits few seconds.
144			* 4. `UPDATE` the test row.
145			*
146			* @param int $pidSecond
147			*
148			* @return int Exit code. In case of deadlock exit code is {@see CHILD_EXIT_CODE_DEADLOCK}. In case of success exit
149			* code is 0. Other codes means an error.
150			*/
151			private function childrenSelectAndAccidentUpdate(int $pidSecond): int
152			{
153			try {
154			$this->log('child 1: connect');
155
156			/** @var Connection $first */
157			$first = $this->getConnection(false, false);
158
159			$this->log('child 1: delete');
160
161			$first->createCommand()
162			->delete('{{customer}}', ['id' => 97])
163			->execute();
164
165			$this->log('child 1: insert');
166
167			/** insert test row */
168			$first->createCommand()
169			->insert('{{customer}}', [
170			'id' => 97,
171			'email' => '[email protected]',
172			'name' => 'test',
173			'address' => 'test address',
174			])
175			->execute();
176
177			$this->log('child 1: transaction');
178
179			$first->transaction(function (Connection $first) use ($pidSecond) {
180			$first->transaction(function (Connection $first) use ($pidSecond) {
181			$this->log('child 1: select');
182			/** SELECT with shared lock */
183			$first->createCommand('SELECT id FROM {{customer}} WHERE id = 97 LOCK IN SHARE MODE')
184			->execute();
185
186			$this->log('child 1: send signal to child 2');
187			// let child to continue
188			if (!posix_kill($pidSecond, SIGUSR1)) {
189			throw new \RuntimeException('Cannot send signal');
190			}
191
192			/** now child 2 tries to do the 2nd update, and hits the lock and waits */
193
194			/** delay to let child hit the lock */
195			sleep(2);
196
197			$this->log('child 1: update');
198			/** now do the 3rd update for deadlock */
199			$first->createCommand()
200			->update('{{customer}}', ['name' => 'first'], ['id' => 97])
201			->execute();
202			$this->log('child 1: commit');
203			});
204			}, Transaction::REPEATABLE_READ);
205			} catch (Exception $e) {
206			[$sqlError, $driverError, $driverMessage] = $e->errorInfo;
207			/** Deadlock found when trying to get lock; try restarting transaction */
208			if ('40001' === $sqlError && 1213 === $driverError) {
209			return self::CHILD_EXIT_CODE_DEADLOCK;
210			}
211			$this->log("child 1: ! sql error $sqlError: $driverError: $driverMessage");
212
213			return 1;
214			} catch (\Exception $e) {
215			$this->log(
216			'child 1: ! exit <<' . \get_class($e) . ' #' . $e->getCode() . ': ' . $e->getMessage() . "\n"
217			. $e->getTraceAsString() . '>>'
218			);
219
220			return 1;
221			} catch (\Throwable $e) {
222			$this->log(
223			'child 1: ! exit <<' . \get_class($e) . ' #' . $e->getCode() . ': ' . $e->getMessage() . "\n"
224			. $e->getTraceAsString() . '>>'
225			);
226
227			return 1;
228			}
229			$this->log('child 1: exit');
230
231			return 0;
232			}
233
234			/**
235			* Main body of second child process.
236			*
237			* Second child at first will wait the signal from the first child in some seconds.
238			*
239			* After receiving the signal it runs two nested {@see Connection::transaction()} to perform `UPDATE` with the test
240			* row.
241			*
242			* @return int Exit code. In case of deadlock exit code is {@see CHILD_EXIT_CODE_DEADLOCK}. In case of success exit
243			* code is 0. Other codes means an error.
244			*/
245			private function childrenUpdateLocked()
246			{
247			/** install no-op signal handler to prevent termination */
248			if (!pcntl_signal(SIGUSR1, function () {}, false)) {
249			$this->log('child 2: cannot install signal handler');
250
251			return 1;
252			}
253
254			try {
255			/** at first, parent should do 1st select */
256			$this->log('child 2: wait signal from child 1');
257			if (pcntl_sigtimedwait([SIGUSR1], $info, 10) <= 0) {
258			$this->log('child 2: wait timeout exceeded');
259
260			return 1;
261			}
262
263			$this->log('child 2: connect');
264			/** @var Connection $second */
265			$second = $this->getConnection(true, false);
266			$second->open();
267			/** sleep(1); */
268			$this->log('child 2: transaction');
269			$second->transaction(function (Connection $second) {
270			$second->transaction(function (Connection $second) {
271			$this->log('child 2: update');
272			// do the 2nd update
273			$second->createCommand()
274			->update('{{customer}}', ['name' => 'second'], ['id' => 97])
275			->execute();
276
277			$this->log('child 2: commit');
278			});
279			}, Transaction::REPEATABLE_READ);
280			} catch (Exception $e) {
281			[$sqlError, $driverError, $driverMessage] = $e->errorInfo;
282			/** Deadlock found when trying to get lock; try restarting transaction */
283			if ('40001' === $sqlError && 1213 === $driverError) {
284			return self::CHILD_EXIT_CODE_DEADLOCK;
285			}
286			$this->log("child 2: ! sql error $sqlError: $driverError: $driverMessage");
287
288			return 1;
289			} catch (\Exception $e) {
290			$this->log(
291			'child 2: ! exit <<' . \get_class($e) . ' #' . $e->getCode() . ': ' . $e->getMessage() . "\n"
292			. $e->getTraceAsString() . '>>'
293			);
294
295			return 1;
296			} catch (\Throwable $e) {
297			$this->log(
298			'child 2: ! exit <<' . \get_class($e) . ' #' . $e->getCode() . ': ' . $e->getMessage() . "\n"
299			. $e->getTraceAsString() . '>>'
300			);
301
302			return 1;
303			}
304			$this->log('child 2: exit');
305
306			return 0;
307			}
308
309			/**
310			* Set own error handler.
311			*
312			* In case of error in child process its execution bubbles up to phpunit to continue all the rest tests. So, all
313			* the rest tests in this case will run both in the child and parent processes. Such mess must be prevented with
314			* child's own error handler.
315			*/
316			private function setErrorHandler()
317			{
318			set_error_handler(function ($errno, $errstr, $errfile, $errline) {
319			throw new \ErrorException($errstr, $errno, $errno, $errfile, $errline);
320			});
321			}
322
323			/**
324			* Sets filename for log file shared between children processes.
325			*
326			* @param string $filename
327			*/
328			private function setLogFile(string $filename): void
329			{
330			$this->logFile = $filename;
331			}
332
333			/**
334			* Deletes shared log file.
335			*
336			* Deletes the file {@see logFile} if it exists.
337			*/
338			private function deleteLog(): void
339			{
340			if (null !== $this->logFile && is_file($this->logFile)) {
341			unlink($this->logFile);
342			}
343			}
344
345			/**
346			* Reads shared log content and deletes the log file.
347			*
348			* Reads content of log file {@see logFile} and returns it deleting the file.
349			*
350			* @return string\|null String content of the file {@see logFile}. `false` is returned when file cannot be read.
351			* `null` is returned when file does not exist or {@see logFile} is not set.
352			*/
353			private function getLogContentAndDelete(): ?string
354			{
355			if (null !== $this->logFile && is_file($this->logFile)) {
356			$content = file_get_contents($this->logFile);
357			unlink($this->logFile);
358
359			return $content;
360			}
361			}
362
363			/**
364			* Append message to shared log.
365			*
366			* @param string $message Message to append to the log. The message will be prepended with timestamp and appended
367			* with new line.
368			*/
369			private function log(string $message): void
370			{
371			if (null !== $this->logFile) {
372			$time = microtime(true);
373			$timeInt = floor($time);
374			$timeFrac = $time - $timeInt;
375			$timestamp = date('Y-m-d H:i:s', (int) $timeInt) . '.' . round($timeFrac * 1000);
376			file_put_contents($this->logFile, "[$timestamp] $message\n", FILE_APPEND \| LOCK_EX);
377			}
378			}
379			}
380

yiisoft / db-mysql

Push — master ( 74cbfa...01b9fc )

DeadLockTest::setLogFile() A

Complexity

Size

Duplication

Importance

Duplication Side-by-Side

Filter issues like