Passed
Push — master ( 2b1785...29418c )
by Alexander
03:20
created

DeadLockTest::childrenSelectAndAccidentUpdate()   B

Complexity

Conditions 7
Paths 33

Size

Total Lines 81
Code Lines 49

Duplication

Lines 0
Ratio 0 %

Importance

Changes 0
Metric Value
cc 7
eloc 49
nc 33
nop 1
dl 0
loc 81
rs 8.1793
c 0
b 0
f 0

How to fix   Long Method   

Long Method

Small methods make your code easier to understand, in particular if combined with a good name. Besides, if your method is small, finding a good name is usually much easier.

For example, if you find yourself adding comments to a method's body, this is usually a good sign to extract the commented part to a new method, and use the comment as a starting point when coming up with a good name for this new method.

Commonly applied refactorings include:

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