"MySQL server has gone away" when ending game

[jephly]

I'm seeing an error frequently, but not always, when ending my game.
It appears that a SQL UPDATE initiated by the platform, to set a global (id=3), is failing.
Is this something my code might be triggering? Or is this a bug in the platform?

This happens after the "endGame" state is triggered, after stats are written.
(If I view the game page, the game appears to have ended correctly and the stats are correct.)

Here's the error as reported to the client:

Code: Select all

Server syntax error: lettertycoon/lettertycoon/discardCards.html SyntaxError: Unexpected token '<' / <br />
<b>Warning</b>:  Error while sending QUERY packet. PID=1795 in <b>/var/tournoi/release/tournoi-200922-0852-gs/www/include/APP_DbObject.inc.php</b> on line <b>374</b><br />
{"status":"0","error":"Error while processing SQL request: UPDATE global SET global_value=global_value+1 WHERE global_id='3' \nMySQL server has gone away","expected":0,"code":500,"stack":"#0 \/var\/tournoi\/release\/tournoi-200922-0852-gs\/www\/game\/module\/table\/table.game.php(2724): APP_DbObject::DbQuery('UPDATE global S...')\n#1 \/var\/tournoi\/release\/tournoi-200922-0852-gs\/www\/include\/APP_GameAction.inc.php(225): Table->sendNotifications()\n#2 \/var\/tournoi\/release\/tournoi-200922-0852-gs\/www\/include\/APP_GameAction.inc.php(216): APP_GameAction->ajaxResponseWithResult(NULL)\n#3 \/var\/tournoi\/release\/games\/lettertycoon\/999999-9999\/lettertycoon.action.php(134): APP_GameAction->ajaxResponse()\n#4 \/var\/tournoi\/release\/tournoi-200922-0852-gs\/www\/include\/webActionCore.inc.php(135): action_lettertycoon->discardCards()\n#5 \/var\/tournoi\/release\/tournoi-200922-0852-gs\/www\/index.php(230): launchWebAction('lettertycoon', 'action_letterty...', 'discardCards', false, false, NULL, true, false)\n#6 {main}"}

And here's the last bit of the SQL log:

Code: Select all

26/09 08:56:05 [info] [T195582] [2330223/jephly1] notifyNow notification. Type = resultsAvailable2
26/09 08:56:05 [info] [T195582] [2330223/jephly1] after jump to nextState2
26/09 08:56:05 [info] [T195582] [2330223/jephly1] after jump to nextState2
26/09 08:56:05 [info] [T195582] [2330223/jephly1] checkZombieTurn2
26/09 08:56:05 [info] [T195582] [2330223/jephly1] action player number = 02
26/09 08:56:05 [info] [T195582] [2330223/jephly1] after jump to nextState2
26/09 08:56:05 [info] [T195582] [2330223/jephly1] Sending notifications2
26/09 08:56:05 [info] [T195582] [2330223/jephly1] 0.0028610229492188 UPDATE global SET global_value=global_value+1 WHERE global_id='3' 2
26/09 08:56:05 [error] [T195582] [2330223/jephly1] Error (2006) while processing SQL request: MySQL server has gone away - Request: UPDATE global SET global_value=global_value+1 WHERE global_id='3' 2
26/09 08:56:05 [info] [T195582] [2330223/jephly1] DB rollback: action cancelled2
26/09 08:56:05 [error] [T195582] [2330223/jephly1] Unexpected exception: Error while processing SQL request: UPDATE global SET global_value=global_value+1 WHERE global_id='3' M
MySQL server has gone away (BGA service error 1601103365)#
#0 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/table.game.php(2724): APP_DbObject::DbQuery('UPDATE global S...')#
#1 /var/tournoi/release/tournoi-200922-0852-gs/www/include/APP_GameAction.inc.php(225): Table->sendNotifications()#
#2 /var/tournoi/release/tournoi-200922-0852-gs/www/include/APP_GameAction.inc.php(216): APP_GameAction->ajaxResponseWithResult(NULL)#
#3 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.action.php(134): APP_GameAction->ajaxResponse()#
#4 /var/tournoi/release/tournoi-200922-0852-gs/www/include/webActionCore.inc.php(135): action_lettertycoon->discardCards()#
#5 /var/tournoi/release/tournoi-200922-0852-gs/www/index.php(230): launchWebAction('lettertycoon', 'action_letterty...', 'discardCards', false, false, NULL, true, false)#
#6 {main}h
http://1.studio.boardgamearena.com/1/lettertycoon/lettertycoon/discardCards.html?card_ids=61&lock=180d1ab5-4a7d-4ce8-84ba-b9ed308a87bc&table=195582&testuser=2330223&dojo.preventCache=16011033495062
26/09 08:56:05 [notice] [T195582] [2330223/jephly1] ER-500 15838 d5 c2 e15742 m0 I334 A0 V0 T0 /1/lettertycoon/lettertycoon/discardCards.html?card_ids=61&lock=180d1ab5-4a7d-4ce8-84ba-b9ed308a87bc&table=195582&testuser=2330223&dojo.preventCache=1601103349506

[Een]

That's not an issue in your game code. This is linked to timeouts for mysql connections. If a request takes more than a certain time, PHP will timeout it and display this error.

We have raised the timeout value on the studio, but it still happens from time to time.

To solve this, the best would be to upgrade the studio mysql server, when we have the possibility to do so.

[BaronFraser]

Glad to hear it. I've been getting this, too, but have *assumed* that it's not me...

[jephly]

Thanks, that makes sense. I do see a gap of several seconds in the log, just before the bit I posted.

Presumably this doesn't happen with the production MySQL instance?

[jephly]

In further testing, I saw a different error. This also occurs at the same time - after game end, immediately after recording stats.

Code: Select all

26/09 19:19:42 [info] [T193103] [2330222/jephly0] DB rollback: action cancelled2
26/09 19:19:42 [error] [T193103] [2330222/jephly0] Unexpected exception: Failed to send an email to jephly@gmail.com : SMTP Error: data not accepted.SMTP server error: DATA command failed Detail: Ok

SMTP code: 250 Additional SMTP info: 2.1.5#
#0 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/table.game.php(2434): APP_DbObject->masterNodeRequest('gameResult', Array)#
#1 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(460): Table->stGameEnd()#
#2 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(356): Gamestate->jumpToState(99)#
#3 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.game.php(1506): Gamestate->nextState('endGame')#
#4 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(460): LetterTycoon->stEndTurn()#
#5 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(356): Gamestate->jumpToState(76)#
#6 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.game.php(1500): Gamestate->nextState()#
#7 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(460): LetterTycoon->stRefillHand()#
#8 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(356): Gamestate->jumpToState(75)#
#9 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.game.php(1087): Gamestate->nextState('done')#
#10 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.action.php(140): LetterTycoon->skipDiscardCards()#
#11 /var/tournoi/release/tournoi-200922-0852-gs/www/include/webActionCore.inc.php(135): action_lettertycoon->skipDiscardCards()#
#12 /var/tournoi/release/tournoi-200922-0852-gs/www/index.php(230): launchWebAction('lettertycoon', 'action_letterty...', 'skipDiscardCard...', false, false, NULL, true, false)#
#13 {main}h
http://1.studio.boardgamearena.com/1/lettertycoon/lettertycoon/skipDiscardCards.html?lock=b2b5eed2-b740-45ef-8e51-2f97f9c73101&table=193103&testuser=2330222&dojo.preventCache=16011407807102
26/09 19:19:42 [notice] [T193103] [2330222/jephly0] ER-100 1698 d6 c0 e1603 m0 I334 A0 V0 T0 /1/lettertycoon/lettertycoon/skipDiscardCards.html?lock=b2b5eed2-b740-45ef-8e51-2f97f9c73101&table=193103&testuser=2330222&dojo.preventCache=1601140780710

(With this error, the transaction was cancelled, so I was able to try again and it worked. This time, I didn't get the original timeout error, either.)

[Een]

Presumably this doesn't happen with the production MySQL instance?

Not unless you write a real monster of a query

[Een]

In further testing, I saw a different error. This also occurs at the same time - after game end, immediately after recording stats.

Code: Select all

26/09 19:19:42 [info] [T193103] [2330222/jephly0] DB rollback: action cancelled2
26/09 19:19:42 [error] [T193103] [2330222/jephly0] Unexpected exception: Failed to send an email to jephly@gmail.com : SMTP Error: data not accepted.SMTP server error: DATA command failed Detail: Ok

SMTP code: 250 Additional SMTP info: 2.1.5#
#0 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/table.game.php(2434): APP_DbObject->masterNodeRequest('gameResult', Array)#
#1 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(460): Table->stGameEnd()#
#2 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(356): Gamestate->jumpToState(99)#
#3 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.game.php(1506): Gamestate->nextState('endGame')#
#4 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(460): LetterTycoon->stEndTurn()#
#5 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(356): Gamestate->jumpToState(76)#
#6 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.game.php(1500): Gamestate->nextState()#
#7 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(460): LetterTycoon->stRefillHand()#
#8 /var/tournoi/release/tournoi-200922-0852-gs/www/game/module/table/gamestate.game.php(356): Gamestate->jumpToState(75)#
#9 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.game.php(1087): Gamestate->nextState('done')#
#10 /var/tournoi/release/games/lettertycoon/999999-9999/lettertycoon.action.php(140): LetterTycoon->skipDiscardCards()#
#11 /var/tournoi/release/tournoi-200922-0852-gs/www/include/webActionCore.inc.php(135): action_lettertycoon->skipDiscardCards()#
#12 /var/tournoi/release/tournoi-200922-0852-gs/www/index.php(230): launchWebAction('lettertycoon', 'action_letterty...', 'skipDiscardCard...', false, false, NULL, true, false)#
#13 {main}h
http://1.studio.boardgamearena.com/1/lettertycoon/lettertycoon/skipDiscardCards.html?lock=b2b5eed2-b740-45ef-8e51-2f97f9c73101&table=193103&testuser=2330222&dojo.preventCache=16011407807102
26/09 19:19:42 [notice] [T193103] [2330222/jephly0] ER-100 1698 d6 c0 e1603 m0 I334 A0 V0 T0 /1/lettertycoon/lettertycoon/skipDiscardCards.html?lock=b2b5eed2-b740-45ef-8e51-2f97f9c73101&table=193103&testuser=2330222&dojo.preventCache=1601140780710

(With this error, the transaction was cancelled, so I was able to try again and it worked. This time, I didn't get the original timeout error, either.)

This looks like a temporary network/email server issue preventing the end of game email in turn based mode to be sent. Not something to worry about for your game.

[jephly]

Yeah, only saw the email problem that one time.

I also haven't see the SQL server problem for the past day or so - probably it depends on load on the system.