DB::rollback() it's doesn't work in concurrent access

[Linij]

My project env：
1.laravel 5.7.6
2.mysql 8.0.12 The transaction level RR
3.php 7.1.22

Description ：

The problem is the first transaction is success execute。

second and three transaction is rollback，but they insert
the order table record still in database。

I don't know why the transaction rolled back the data is still there。

logging：

I use three threads to simulate ordering,
this is simplified version my log。

[2018-10-03 17:44:13] dev.INFO: php-thread-id-32993 transaction start
[2018-10-03 17:44:13] dev.INFO: php-thread-id-33136 transaction start

[2018-10-03 17:44:13] dev.INFO: {"sql":"select * from h8_finance_account_logs where user_id = ? order by id desc limit 1 for update","bindings":[1010001],"time":0.59,"connection":{},"connectionName":"mysql"} (X-LOCK the record)

[2018-10-03 17:44:13] dev.INFO: 32993 GET X-LOCK

[2018-10-03 17:44:13] dev.INFO: php-thread-id-32643 transaction start

... do business (like insert order table)

[2018-10-03 17:44:13] dev.INFO: {"sql":"insert into h8_finance_account_logs (user_id),"bindings":[1010001],"time":0.67,"connection":{},"connectionName":"mysql"} (insert new log)
[2018-10-03 17:44:13] dev.INFO: {"sql":"select * from h8_finance_account_logs where user_id = ? order by id desc limit 1 for update","bindings":[1010001],"time":0.59,"connection":{},"connectionName":"mysql"} (X-LOCK the record)

[2018-10-03 17:44:13] dev.INFO: {"sql":"select * from h8_finance_account_logs where user_id = ? order by id desc limit 1 for update","bindings":[1010001],"time":0.59,"connection":{},"connectionName":"mysql"} (X-LOCK the record)

[2018-10-03 17:44:13] dev.INFO: 32643 GET X-LOCK

[2018-10-03 17:44:13] dev.INFO: 33136 GET X-LOCK

[2018-10-03 17:44:13] dev.INFO: {"sql":"insert into h8_finance_account_logs (user_id)[1010001],"time":0.34,"connection":{},"connectionName":"mysql"}
(thread 32993 insert second record)

[2018-10-03 17:44:13] dev.INFO: 32993 commit success

At this point transaction 1 has completed the commit,

next second and three transaction will be

... do business (like insert order table)

But they have no balance to pay the order，so they will be rollback。

[2018-10-03 17:44:13] dev.INFO: php-thread-id-33136 rollback
[2018-10-03 17:44:13] dev.INFO: php-thread-id-32643 rollback

All three processes perform the same logic
1.Place the order
2.pay
3.commit or rollback

[laurencei]

Hi,

Can you provide some exact code to replicate this?

[sisve]

I'm worried about php-thread-id-$id. Are you running multithreaded php? I'm pretty sure Laravel does not even attempt at supporting that.

[Linij]

2tables:

• php Thread Safety disabled

create table finance_logs 
(
  id int,
 amount int,
 user_id int
)

create table orderx
(
 id int,
 order_no
)

Initialization data
+------+--------+---------+
| id   | amount | user_id |
+------+--------+---------+
|    1 |    100 |    1001 |
+------+--------+---------+
1 rows in set (0.00 sec)

public function create()
    {
        try {
            DB::beginTransaction();

            info(getmypid() . '--transaction start');

            $money = DB::table('finance_logs')
                ->where('user_id', 1001)
                ->orderBy('id', 'desc')
                ->limit(1)
                ->lockForUpdate()
                ->value('amount');

            info(getmypid() . '--get x lock');

            // create order
            DB::table('orderx')->insert(['order_no' => rand(100000, 999999)]);
            $price = 100;
            if(!$this->pay($price)){
                throw new \Exception('pay encounter error');
            }else{
                DB::commit();  
                return true;
            }
            throw  new \Exception('pay error');
        } catch (\Exception $exception) {
            DB::rollBack();
            info(getmypid() . 'rollback');
            info($exception->getMessage());
            return false;
        }
    }

public function pay($price)
    {
        try {
            DB::beginTransaction();
            $money = DB::table('finance_logs')
                ->where('user_id', 1001)
                ->orderBy('id', 'desc')
                ->limit(1)
                ->lockForUpdate()
                ->value('amount');
            if ($money < $price) {
                throw new \Exception('balance no');
            }
            DB::table('finance_logs')->insert(['user_id' => 1001, 'amount' => ($money - $price)]);
            DB::commit();
            return true;
        } catch (\Exception $exception) {
            DB::rollBack();
            return false;
        }
    }

Complete the log：

[2018-10-04 16:34:01] dev.INFO: 52887--transaction start
[2018-10-04 16:34:01] dev.INFO: 52898--transaction start
[2018-10-04 16:34:01] dev.INFO: {"sql":"select amount from h8_finance_logs where user_id = ? order by id desc limit 1 for update","bindings":[1001],"time":0.47,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: 52887--get x lock
[2018-10-04 16:34:01] dev.INFO: {"sql":"insert into h8_orderx (order_no) values (?)","bindings":[229919],"time":0.34,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: {"sql":"select amount from h8_finance_logs where user_id = ? order by id desc limit 1 for update","bindings":[1001],"time":0.37,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: {"sql":"insert into h8_finance_logs (user_id, amount) values (?, ?)","bindings":[1001,0],"time":0.36,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: {"sql":"select amount from h8_finance_logs where user_id = ? order by id desc limit 1 for update","bindings":[1001],"time":2.39,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: 52898--get x lock
[2018-10-04 16:34:01] dev.INFO: 53093--transaction start
[2018-10-04 16:34:01] dev.INFO: 52887rollback
[2018-10-04 16:34:01] dev.INFO: {"sql":"select amount from h8_finance_logs where user_id = ? order by id desc limit 1 for update","bindings":[1001],"time":11.05,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: {"sql":"insert into h8_orderx (order_no) values (?)","bindings":[862307],"time":13.86,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: pay error
[2018-10-04 16:34:01] dev.INFO: 53093--get x lock
[2018-10-04 16:34:01] dev.INFO: {"sql":"insert into h8_orderx (order_no) values (?)","bindings":[394616],"time":0.3,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: {"sql":"select amount from h8_finance_logs where user_id = ? order by id desc limit 1 for update","bindings":[1001],"time":0.37,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: {"sql":"select amount from h8_finance_logs where user_id = ? order by id desc limit 1 for update","bindings":[1001],"time":1.75,"connection":{},"connectionName":"mysql"}
[2018-10-04 16:34:01] dev.INFO: 53093rollback
[2018-10-04 16:34:01] dev.INFO: pay encounter error
[2018-10-04 16:34:01] dev.ERROR: SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT trans2 does not exist {"userId":1010001,"exception":"[object] (Doctrine\DBAL\Driver\PDOException(code: 42000): SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT trans2 does not exist at /Users/linji/gitroot/hk8591/api/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOConnection.php:62, PDOException(code: 42000): SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT trans2 does not exist at /Users/linji/gitroot/hk8591/api/vendor/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOConnection.php:60)
[stacktrace]
#0 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Database/Concerns/ManagesTransactions.php(212): Doctrine\DBAL\Driver\PDOConnection->exec('ROLLBACK TO SAV...')
#1 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Database/Concerns/ManagesTransactions.php(190): Illuminate\Database\Connection->performRollBack(1)
#2 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Database/DatabaseManager.php(327): Illuminate\Database\Connection->rollBack()
#3 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Support/Facades/Facade.php(223): Illuminate\Database\DatabaseManager->__call('rollBack', Array)
#4 /Users/linji/gitroot/hk8591/api/app/Services/OrderService.php(94): Illuminate\Support\Facades\Facade::__callStatic('rollBack', Array)
#5 /Users/linji/gitroot/hk8591/api/app/Api/V1/Controllers/OrderController.php(79): App\Services\OrderService->create(Object(App\Models\User), Array, NULL, true, NULL)
#6 [internal function]: App\Api\V1\Controllers\OrderController->placeTheOrder(Object(App\Api\V1\Requests\Order\PlaceTheOrderRequest))
#7 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Controller.php(54): call_user_func_array(Array, Array)
#8 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/ControllerDispatcher.php(45): Illuminate\Routing\Controller->callAction('placeTheOrder', Array)
#9 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Route.php(212): Illuminate\Routing\ControllerDispatcher->dispatch(Object(Illuminate\Routing\Route), Object(App\Api\V1\Controllers\OrderController), 'placeTheOrder')
#10 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Route.php(169): Illuminate\Routing\Route->runController()
#11 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Router.php(679): Illuminate\Routing\Route->run()
#12 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(30): Illuminate\Routing\Router->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#13 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Middleware/ThrottleRequests.php(58): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#14 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Illuminate\Routing\Middleware\ThrottleRequests->handle(Object(Illuminate\Http\Request), Object(Closure), 100)
#15 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#16 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Middleware/SubstituteBindings.php(41): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#17 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Illuminate\Routing\Middleware\SubstituteBindings->handle(Object(Illuminate\Http\Request), Object(Closure))
#18 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#19 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Auth/Middleware/Authenticate.php(43): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#20 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Illuminate\Auth\Middleware\Authenticate->handle(Object(Illuminate\Http\Request), Object(Closure), 'api')
#21 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#22 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(104): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#23 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Router.php(681): Illuminate\Pipeline\Pipeline->then(Object(Closure))
#24 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Router.php(656): Illuminate\Routing\Router->runRouteWithinStack(Object(Illuminate\Routing\Route), Object(Illuminate\Http\Request))
#25 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Router.php(622): Illuminate\Routing\Router->runRoute(Object(Illuminate\Http\Request), Object(Illuminate\Routing\Route))
#26 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Router.php(611): Illuminate\Routing\Router->dispatchToRoute(Object(Illuminate\Http\Request))
#27 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Foundation/Http/Kernel.php(176): Illuminate\Routing\Router->dispatch(Object(Illuminate\Http\Request))
#28 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(30): Illuminate\Foundation\Http\Kernel->Illuminate\Foundation\Http\{closure}(Object(Illuminate\Http\Request))
#29 /Users/linji/gitroot/hk8591/api/app/Http/Middleware/WhiteIp.php(25): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#30 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): App\Http\Middleware\WhiteIp->handle(Object(Illuminate\Http\Request), Object(Closure))
#31 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#32 /Users/linji/gitroot/hk8591/api/app/Http/Middleware/Maintain.php(49): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#33 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): App\Http\Middleware\Maintain->handle(Object(Illuminate\Http\Request), Object(Closure))
#34 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#35 /Users/linji/gitroot/hk8591/api/app/Http/Middleware/UnifiedResponse.php(22): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#36 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): App\Http\Middleware\UnifiedResponse->handle(Object(Illuminate\Http\Request), Object(Closure))
#37 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#38 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Session/Middleware/StartSession.php(63): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#39 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Illuminate\Session\Middleware\StartSession->handle(Object(Illuminate\Http\Request), Object(Closure))
#40 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#41 /Users/linji/gitroot/hk8591/api/vendor/fideloper/proxy/src/TrustProxies.php(57): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#42 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Fideloper\Proxy\TrustProxies->handle(Object(Illuminate\Http\Request), Object(Closure))
#43 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#44 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Foundation/Http/Middleware/TransformsRequest.php(31): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#45 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Illuminate\Foundation\Http\Middleware\TransformsRequest->handle(Object(Illuminate\Http\Request), Object(Closure))
#46 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#47 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Foundation/Http/Middleware/TransformsRequest.php(31): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#48 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Illuminate\Foundation\Http\Middleware\TransformsRequest->handle(Object(Illuminate\Http\Request), Object(Closure))
#49 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#50 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Foundation/Http/Middleware/ValidatePostSize.php(27): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#51 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Illuminate\Foundation\Http\Middleware\ValidatePostSize->handle(Object(Illuminate\Http\Request), Object(Closure))
#52 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#53 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Foundation/Http/Middleware/CheckForMaintenanceMode.php(62): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#54 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(151): Illuminate\Foundation\Http\Middleware\CheckForMaintenanceMode->handle(Object(Illuminate\Http\Request), Object(Closure))
#55 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Routing/Pipeline.php(53): Illuminate\Pipeline\Pipeline->Illuminate\Pipeline\{closure}(Object(Illuminate\Http\Request))
#56 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Pipeline/Pipeline.php(104): Illuminate\Routing\Pipeline->Illuminate\Routing\{closure}(Object(Illuminate\Http\Request))
#57 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Foundation/Http/Kernel.php(151): Illuminate\Pipeline\Pipeline->then(Object(Closure))
#58 /Users/linji/gitroot/hk8591/api/vendor/laravel/framework/src/Illuminate/Foundation/Http/Kernel.php(116): Illuminate\Foundation\Http\Kernel->sendRequestThroughRouter(Object(Illuminate\Http\Request))
#59 /Users/linji/gitroot/hk8591/api/public/index.php(55): Illuminate\Foundation\Http\Kernel->handle(Object(Illuminate\Http\Request))
#60 {main}
"}

Result：

mysql> select * from h8_finance_logs;
+------+--------+---------+
| id   | amount | user_id |
+------+--------+---------+
|    1 |    100 |    1001 |
| 1004 |      0 |    1001 |
+------+--------+---------+

mysql> select * from h8_orderx;
+-----+----------+
| id  | order_no |
+-----+----------+
| 121 |   574112 |
| 122 |   515789 |
| 123 |   135378 |
+-----+----------+

[Linij]

I think I have a lock problem with the transaction，
In the log can not be found save point,
In the log At least twice rollback,but It's still written three records into h8_orderx.

i use try{} catch(\Exception $e){} has problem?

[laurencei]

This code:

            if(!$this->pay($price)){
                throw new \Exception('pay encounter error');
            }else{
                DB::commit();
            }
            throw  new \Exception('pay error');

Means that it will always throw an exception?

[Linij]

i forget return true，It has been updated

[laurencei]

Sorry, but its still not clear what the actual issue is here.

As @sisve said - it looks like your doing something with threads within the one call? That's unlikely to work.

If you can provide a clearer and simple demostration of what the bug is in the framework, we can reopen the ticket.