mikroware
commented
5 years ago Yesterday and today it went better for sometime. But now I started to notice that it seems like the callback OnBanCheck does get called in some cases, but only after like 10 or 15 minutes.
When you look at the 2nd code block in the original issue, that is an example of what happened before the below:
[12-12-2018 20:15:05] [DEBUG] mysql_tquery: return value: '1' (../include/features/session_time.inc:129 -> ../include/features/session_time.inc:23 -> ./Mudoo.pwn:145 -> ./../pawno/include/sscanf2.inc:259)
[12-12-2018 20:30:42] [ERROR] error #2013 while executing query "DELETE FROM bans WHERE unban > 0 AND unban < 1544642098": Lost connection to MySQL server during query (../include/utilities/general.inc:189 -> ../include/utilities/account.inc:7 -> ./Mudoo.pwn:100 -> ./../pawno/include/sscanf2.inc:235)
[12-12-2018 20:30:42] [DEBUG] CConnection::GetError(this=0xf5345008, connection=0x97b6008)
[12-12-2018 20:30:42] [DEBUG] CConnection::Execute(query=0x98f1fd4, this=0xf5345008, connection=0x97b6008)
[12-12-2018 20:30:42] [DEBUG] CQuery::Execute(this=0x98f1fd4, connection=0x97b6008)
[12-12-2018 20:30:42] [DEBUG] CCallback::Create(amx=0x974f718, name='OnQueryError', format='dsssd)
[12-12-2018 20:30:42] [DEBUG] CCallback::Create - callback index for 'OnQueryError': -10053
[12-12-2018 20:30:42] [DEBUG] processing specifier 'd'
[12-12-2018 20:30:42] [DEBUG] retrieved and pushed value '2013'
[12-12-2018 20:30:42] [DEBUG] processing specifier 's'
[12-12-2018 20:30:42] [DEBUG] retrieved and pushed value 'Lost connection to MySQL server during query'
[12-12-2018 20:30:42] [DEBUG] processing specifier 's'
[12-12-2018 20:30:42] [DEBUG] retrieved and pushed value ''
[12-12-2018 20:30:42] [DEBUG] processing specifier 's'
[12-12-2018 20:30:42] [DEBUG] retrieved and pushed value 'DELETE FROM bans WHERE unban > 0 AND unban < 1544642098'
[12-12-2018 20:30:42] [DEBUG] processing specifier 'd'
[12-12-2018 20:30:42] [DEBUG] retrieved and pushed value '1'
[12-12-2018 20:30:42] [INFO] Callback 'OnQueryError' set up for delayed execution.
[12-12-2018 20:30:42] [DEBUG] created delayed callback with 5 parameters
[12-12-2018 20:30:42] [DEBUG] CCallback::Execute(amx=0x974f718, index=-10053, num_params=5)
[12-12-2018 20:30:42] [INFO] Executing callback 'úÿ‹T$<…À…§' with 5 parameters...
[12-12-2018 20:30:42] [DEBUG] processing internal specifier 'c'
[12-12-2018 20:30:42] [DEBUG] pushed value '1' onto AMX stack
[12-12-2018 20:30:42] [DEBUG] processing internal specifier 's'
[12-12-2018 20:30:42] [DEBUG] pushed value 'DELETE FROM bans WHERE unban > 0 AND unban < 1544642098' onto AMX stack
[12-12-2018 20:30:42] [DEBUG] processing internal specifier 's'
[12-12-2018 20:30:42] [DEBUG] pushed value '' onto AMX stack
[12-12-2018 20:30:42] [DEBUG] processing internal specifier 's'
[12-12-2018 20:30:42] [DEBUG] pushed value 'Lost connection to MySQL server during query' onto AMX stack
[12-12-2018 20:30:42] [DEBUG] processing internal specifier 'c'
[12-12-2018 20:30:42] [DEBUG] pushed value '2013' onto AMX stack
[12-12-2018 20:30:42] [DEBUG] executing AMX callback with index '-10053'
[12-12-2018 20:30:42] [DEBUG] AMX callback executed with error '0'
[12-12-2018 20:30:42] [INFO] Callback successfully executed.
[12-12-2018 20:30:42] [INFO] query "UPDATE users SET vip=0, vip_expire=0 WHERE vip_expire > 0 AND vip_expire < 1544642098" successfully executed within 36.160 milliseconds
[12-12-2018 20:30:42] [DEBUG] CResultSet::Create(connection=0x97b6008, query_str='UPDATE users SET vip=0, vip_expire=0 WHERE vip_expire > 0 AND vip_expire < 1544642098')
[12-12-2018 20:30:42] [DEBUG] created new resultset '0xf51068f8'
[12-12-2018 20:30:42] [DEBUG] fetched MySQL result '0x0'
[12-12-2018 20:30:42] [DEBUG] CConnection::Execute(query=0x98e0d9c, this=0xf5345008, connection=0x97b6008)
[12-12-2018 20:30:42] [DEBUG] CQuery::Execute(this=0x98e0d9c, connection=0x97b6008)
[12-12-2018 20:30:42] [INFO] query "SELECT * FROM bans WHERE name='Leonardo_Wans' OR ip='95.132.132.253'" successfully executed within 2.298 milliseconds
[12-12-2018 20:30:42] [DEBUG] CResultSet::Create(connection=0x97b6008, query_str='SELECT * FROM bans WHERE name='Leonardo_Wans' OR ip='95.132.132.253'')
[12-12-2018 20:30:42] [DEBUG] created new resultset '0xf5106918'
[12-12-2018 20:30:42] [DEBUG] fetched MySQL result '0xf51066b0'
[12-12-2018 20:30:42] [DEBUG] allocated 0 bytes for PAWN result
[12-12-2018 20:30:42] [DEBUG] CConnection::Execute(query=0x996019c, this=0xf5345008, connection=0x97b6008)
[12-12-2018 20:30:42] [DEBUG] CQuery::Execute(this=0x996019c, connection=0x97b6008)
[12-12-2018 20:30:42] [DEBUG] CCallback::Execute(amx=0x974f718, index=16, num_params=1)
[12-12-2018 20:30:42] [INFO] Executing callback 'OnBanCheck' with 1 parameter...
[12-12-2018 20:30:42] [DEBUG] processing internal specifier 'c'
[12-12-2018 20:30:42] [DEBUG] pushed value '0' onto AMX stack
[12-12-2018 20:30:42] [DEBUG] executing AMX callback with index '16'
[12-12-2018 20:30:42] [DEBUG] cache_get_row_count(0xF58AC5B8) (../include/utilities/account.inc:29)
[12-12-2018 20:30:42] [DEBUG] cache_get_row_count: return value: '1' (../include/utilities/account.inc:29)
[12-12-2018 20:30:42] [INFO] query "DELETE FROM user_online WHERE user_id=0" successfully executed within 0.302 milliseconds
[12-12-2018 20:30:42] [DEBUG] CResultSet::Create(connection=0x97b6008, query_str='DELETE FROM user_online WHERE user_id=0')
[12-12-2018 20:30:42] [DEBUG] created new resultset '0xf5106998'
[12-12-2018 20:30:42] [DEBUG] fetched MySQL result '0x0'
[12-12-2018 20:30:42] [DEBUG] mysql_format(1, 0xF58AC1BC, 255, "SELECT password, id FROM users WHERE name='%e' LIMIT 1") (../include/utilities/account.inc:67)
[12-12-2018 20:30:42] [DEBUG] mysql_format: return value: '52' (../include/utilities/account.inc:67)
[12-12-2018 20:30:42] [DEBUG] mysql_tquery(1, "SELECT password, id FROM users WHERE name='' LIMIT 1", "OnAccountCheck", "i") (../include/utilities/account.inc:68)
[12-12-2018 20:30:42] [DEBUG] CCallback::Create(amx=0x974f718, name='OnAccountCheck', format='i', params=0xf58ac1a4, param_offset=5)
[12-12-2018 20:30:42] [DEBUG] CCallback::Create - callback index for 'OnAccountCheck': 12
[12-12-2018 20:30:42] [DEBUG] processing specifier 'i' with parameter index 0
[12-12-2018 20:30:42] [DEBUG] retrieved and pushed value '0'
[12-12-2018 20:30:42] [INFO] Callback 'OnAccountCheck' set up for delayed execution.
[12-12-2018 20:30:42] [DEBUG] created delayed callback with 1 parameter
[12-12-2018 20:30:42] [DEBUG] CHandle::Execute(this=0x978b6a0, type=1, query=0x98f1fd4)
[12-12-2018 20:30:42] [DEBUG] CHandle::Execute - return value: true
[12-12-2018 20:30:42] [DEBUG] mysql_tquery: return value: '1' (../include/utilities/account.inc:68)
[12-12-2018 20:30:42] [DEBUG] AMX callback executed with error '0'
[12-12-2018 20:30:42] [INFO] Callback successfully executed.
[12-12-2018 20:30:42] [DEBUG] CConnection::Execute(query=0x98f1fd4, this=0xf5345008, connection=0x97b6008)
[12-12-2018 20:30:42] [DEBUG] CQuery::Execute(this=0x98f1fd4, connection=0x97b6008)
[12-12-2018 20:30:42] [INFO] query "SELECT password, id FROM users WHERE name='' LIMIT 1" successfully executed within 11.142 milliseconds
[12-12-2018 20:30:42] [DEBUG] CResultSet::Create(connection=0x97b6008, query_str='SELECT password, id FROM users WHERE name='' LIMIT 1')
[12-12-2018 20:30:42] [DEBUG] created new resultset '0xf51068e0'
[12-12-2018 20:30:42] [DEBUG] fetched MySQL result '0xf5106a40'
[12-12-2018 20:30:42] [DEBUG] allocated 0 bytes for PAWN result
[12-12-2018 20:30:42] [DEBUG] CCallback::Execute(amx=0x974f718, index=12, num_params=1)
[12-12-2018 20:30:42] [INFO] Executing callback 'OnAccountCheck' with 1 parameter...
[12-12-2018 20:30:42] [DEBUG] processing internal specifier 'c'
[12-12-2018 20:30:42] [DEBUG] pushed value '0' onto AMX stack
[12-12-2018 20:30:42] [DEBUG] executing AMX callback with index '12'
[12-12-2018 20:30:42] [DEBUG] cache_get_row_count(0xF58AC5B8) (../include/utilities/account.inc:75)
[12-12-2018 20:30:42] [DEBUG] cache_get_row_count: return value: '1' (../include/utilities/account.inc:75)
[12-12-2018 20:30:42] [DEBUG] AMX callback executed with error '0'
[12-12-2018 20:30:42] [INFO] Callback successfully executed.
I have no clue how and why this is happening. We have been running the exact code without problems on a Debian 8 server before. Recently we switched to a new host and LXC containers and these problems started. These problems do not seem to happen on another server we run with exactly the same setup and mysql config.
So the problem: after a random time the queries seem to stop executing.
Before:
Just a bit later:
As can be seen. No actual execution seems to happen.
The below part is probably a result of the above problem and an edge case. The above happens constantly after server restarts. The below I have only seen once.
At the point of the above logs I was AFK myself ingame. I decided to exit the game. Of course this meant some queries were going to be ran. This actually caused the server to crash and restart as a whole. The crashdetect logs seem to suggest this was caused by mysql. As of there was something unfinished or something.