[MDEV-16308] Out of sync with server Created: 2018-05-28  Updated: 2020-12-08  Resolved: 2020-02-10

Status: Closed
Project: MariaDB Server
Component/s: Protocol
Affects Version/s: 10.2.15
Fix Version/s: 10.2.32, 10.3.23, 10.4.13

Type: Bug Priority: Major
Reporter: Sergii Volikov Assignee: Oleksandr Byelkin
Resolution: Fixed Votes: 0
Labels: None
Environment:

Windows Server 2008 R2.
MySQL Connector Net 6.3.5 (MySQL Connector Net 6.9.11)
.net 4.5.


Attachments: PNG File MySqlErr.png     File MySqlErrlog.pcap     File my.ini    
Issue Links:
Relates
relates to MDEV-21612 Remove COM_MULTI code from server Closed
relates to MDEV-5122 "Commands out of sync", "Malformed pa... Closed

 Description   

После установки mariaDB 10.2.15 начала появляться ошибка:
MySql.Data.MySqlClient.MySqlException: Out of sync with server

Если сразу после ошибки дать повторный запрос - ошибки не будет. В интете не нашел ничего похожего на мой случай. Скрипты разные.
Ошибка не зависит от нагрузки (количества соединений). Она проявляется и ночью, когда нагрузка минимальная, и днем.
Допускаю, что ошибка не связана с версией, но, вроде, других изменений, которые могли привести к данной ошибке не было.



 Comments   
Comment by Vladislav Vaintroub [ 2018-05-28 ]

поделитесь пожалуйста полным стэктрейсом исключения.
Кроме того, вы перестартовали сервер перед тем как получить эти исключения.

Comment by Sergii Volikov [ 2018-05-28 ]

Даже сервер перегружал.
Самое скверное, что не могу найти зависимости проявления этой ошибки. То несколько часов вообще нет ни одной ошибки, то на протяжении 5-10 минут несколько.

System.Web.HttpUnhandledException (0x80004005): Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> MySql.Data.MySqlClient.MySqlException (0x80004005): Out of sync with server
at MySql.Data.MySqlClient.NativeDriver.ReadOk(Boolean read)
at MySql.Data.MySqlClient.NativeDriver.SetDatabase(String dbName)
at MySql.Data.MySqlClient.Driver.SetDatabase(String dbName)
at MySql.Data.MySqlClient.MySqlConnection.ChangeDatabase(String databaseName)
at MySql.Data.MySqlClient.MySqlConnection.Open()
at System.Data.Common.DbDataAdapter.FillInternal(DataSet dataset, DataTable[] datatables, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)
at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)
at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet, String srcTable)
at System.Web.UI.WebControls.SqlDataSourceView.ExecuteSelect(DataSourceSelectArguments arguments)
at System.Web.UI.DataSourceView.Select(DataSourceSelectArguments arguments, DataSourceViewSelectCallback callback)
at System.Web.UI.WebControls.DataBoundControl.PerformSelect()
at System.Web.UI.WebControls.BaseDataBoundControl.DataBind()
at System.Web.UI.WebControls.FormView.DataBind()
at System.Web.UI.WebControls.BaseDataBoundControl.EnsureDataBound()
at System.Web.UI.WebControls.FormView.EnsureDataBound()
at System.Web.UI.WebControls.CompositeDataBoundControl.CreateChildControls()
at System.Web.UI.Control.EnsureChildControls()
at System.Web.UI.Control.PreRenderRecursiveInternal()
at System.Web.UI.Control.PreRenderRecursiveInternal()
at System.Web.UI.Control.PreRenderRecursiveInternal()
at System.Web.UI.Control.PreRenderRecursiveInternal()
at System.Web.UI.Control.PreRenderRecursiveInternal()
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.HandleError(Exception e)
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest()
at System.Web.UI.Page.ProcessRequestWithNoAssert(HttpContext context)
at System.Web.UI.Page.ProcessRequest(HttpContext context)
at ASP.astlo_lkh_well_find_default_aspx.ProcessRequest(HttpContext context)
at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Comment by Vladislav Vaintroub [ 2018-05-28 ]

советую попробовать с ConnectionReset=true опцией в connection string

Comment by Vladislav Vaintroub [ 2018-05-28 ]

Possibly related https://github.com/PyMySQL/PyMySQL/issues/526

Comment by Sergii Volikov [ 2018-05-29 ]

Появилась нагрузка, пошло много ошибок. Пока откатился на 10.2.14.
Попробовал установить ConnectionReset=true - отвалилась некоторая функциональность. Буду разбираться в причинах.

Comment by Sergii Volikov [ 2018-05-29 ]

После отката ошибки не пропали, вроде, субъективно, стали немного меньше.

Comment by Vladislav Vaintroub [ 2018-05-29 ]

можно ко всем типам "ошибок" их stacktrace получить ?
и в том числе к тем которые от ConnectionReset

Comment by Sergii Volikov [ 2018-05-29 ]

Не понял, что значит ко всем? Ошибка, вроде,одна.
Вот с ConnectionReset:

MySql.Data.MySqlClient.MySqlException: Out of sync with server
Generated: Tue, 29 May 2018 05:20:50 GMT

MySql.Data.MySqlClient.MySqlException (0x80004005): Out of sync with server
at MySql.Data.MySqlClient.NativeDriver.ReadOk(Boolean read)
at MySql.Data.MySqlClient.NativeDriver.AuthenticateNew()
at MySql.Data.MySqlClient.NativeDriver.Authenticate()
at MySql.Data.MySqlClient.NativeDriver.Reset()
at MySql.Data.MySqlClient.Driver.Reset()

at MySql.Data.MySqlClient.MySqlPool.GetPooledConnection()
at MySql.Data.MySqlClient.MySqlPool.TryToGetDriver()
at MySql.Data.MySqlClient.MySqlPool.GetConnection()
at MySql.Data.MySqlClient.MySqlConnection.Open()

Comment by Vladislav Vaintroub [ 2018-05-29 ]

Спасибо. ошибка одна, но stacktrace разный. с ConnectionReset более очевидный

Comment by Sergii Volikov [ 2018-05-29 ]

А это ошибка без ConnectionReset

MySql.Data.MySqlClient.MySqlException: Out of sync with server
Generated: Tue, 29 May 2018 05:27:32 GMT

System.Web.HttpUnhandledException (0x80004005): Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> MySql.Data.MySqlClient.MySqlException (0x80004005): Out of sync with server
at MySql.Data.MySqlClient.NativeDriver.ReadOk(Boolean read)
at MySql.Data.MySqlClient.NativeDriver.SetDatabase(String dbName)
at MySql.Data.MySqlClient.Driver.SetDatabase(String dbName)
at MySql.Data.MySqlClient.MySqlConnection.ChangeDatabase(String databaseName)
at MySql.Data.MySqlClient.MySqlConnection.Open()

Comment by Sergii Volikov [ 2018-05-29 ]

Я не могу понять, причину ее появления. Она появилась после установки версии 10.2.15. Тогда почему откат на 10.2.14 не дал результата!? Откат был не через бекап, а удаление 10.2.15 и установка 10.2.14.
Но других причин проявления этой ошибки, кроме установки версии 10.2.15, я не нахожу.

Comment by Sergii Volikov [ 2018-05-29 ]

Для меня проблема приобрела критическое значение. Можете еще будут идеи?

Comment by Sergii Volikov [ 2018-05-29 ]

Эта-же ошибка проявляться на локальной машине с другим клиентом - MySQL Connector Net 6.9.11
Общее у них только сервер MySql

[MySqlException (0x80004005): Out of sync with server]
MySql.Data.MySqlClient.NativeDriver.ReadOk(Boolean read) +266
MySql.Data.MySqlClient.NativeDriver.SetDatabase(String dbName) +108
MySql.Data.MySqlClient.Driver.SetDatabase(String dbName) +11
MySql.Data.MySqlClient.MySqlConnection.ChangeDatabase(String databaseName) +438
MySql.Data.MySqlClient.MySqlConnection.Open() +813

Comment by Vladislav Vaintroub [ 2018-05-29 ]

Я могу предположить , что причина появления - перестартовка сервера, без перестартовки приложения, и пул соединений.
Если почистите пул (или перестартуете приложение), возможно проблемы уйдут.

Это не единственный коннектор кстати говоря, есть и получше в том смысле что меньше багов https://github.com/mysql-net/MySqlConnector

Comment by Sergii Volikov [ 2018-05-29 ]

Как можно выполнить перестартовку сервера без перестартовки приложения?
Кроме того я использую разные приложения локальное и на сервере, где проявляется одинаковая ошибка.
Или я Вас не понял.
MySqlConnector - попробую. Спасибо.

Comment by Vladislav Vaintroub [ 2018-05-29 ]

можно конечно. Мы говорим сервер, подразумеваем базы данных. Другой сервер это веб, их можно в разное время перезапускатъ

Comment by Sergii Volikov [ 2018-05-29 ]

При использовании MySqlConnector появляется ошибка

Packet received out-of-order. Expected 1; got 98.
Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code.

Exception Details: MySql.Data.MySqlClient.MySqlProtocolException: Packet received out-of-order. Expected 1; got 98.

Судя по тому, что она проявляется не всегда, а аналогично "Out of sync with server" можно предположить, что и причина аналогичная.

[MySqlProtocolException: Packet received out-of-order. Expected 1; got 98.]
System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) +99
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) +58
MySqlConnector.Protocol.Serialization.ProtocolUtility.DoReadPayloadAsync(BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 previousPayloads, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) +118
MySqlConnector.Protocol.Serialization.StandardPayloadHandler.ReadPayloadAsync(ArraySegmentHolder`1 cache, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) +54
MySqlConnector.Core.ServerSession.ReceiveReplyAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) +80
System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) +99
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) +58
MySqlConnector.Core.ServerSession.TryAsyncContinuation(Task`1 task) +86
System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke() +56
System.Threading.Tasks.Task.Execute() +47
System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) +99
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) +58
System.Runtime.CompilerServices.ConfiguredValueTaskAwaiter.GetResult() +47
MySqlConnector.Core.<TryResetConnectionAsync>d__57.MoveNext() +2081
System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) +99
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) +58
System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task) +25
MySqlConnector.Core.<GetSessionAsync>d__10.MoveNext() +1204
System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() +26
MySqlConnector.Core.<GetSessionAsync>d__10.MoveNext() +3718
System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) +99
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) +58
System.Runtime.CompilerServices.ConfiguredValueTaskAwaiter.GetResult() +66
MySql.Data.MySqlClient.<CreateSessionAsync>d__87.MoveNext() +1025
System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) +99
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) +58
System.Runtime.CompilerServices.ConfiguredValueTaskAwaiter.GetResult() +66
MySql.Data.MySqlClient.<OpenAsync>d__25.MoveNext() +375
System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) +99
System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) +58
MySql.Data.MySqlClient.MySqlConnection.Open() +61

Comment by Sergii Volikov [ 2018-05-29 ]

Ясно. У меня сервер БД и сервер приложений на одной виртуальной машине.

Comment by Vladislav Vaintroub [ 2018-05-29 ]

о, вот это уже лучше диагностика. Хотя, если бы вы смогли wireshark tracе раздобыть, это было бы идеально

Comment by Sergii Volikov [ 2018-05-29 ]

Удалил последние установленные обновления на сервере - не помогло.

Comment by Sergii Volikov [ 2018-05-29 ]

Простите мою безграмотность, но что такое wireshark tracе? Как его можно получить?

Comment by Vladislav Vaintroub [ 2018-05-29 ]

Wireshark это програмка, которая записывает TCP коммуникацию. но если не знаете, ладно, обойдемся

Comment by Sergii Volikov [ 2018-05-29 ]

Установил. Буду пробовать, что-то получить.

Comment by Sergii Volikov [ 2018-05-29 ]

Вроде получил. Что именно нужно?

No. Time Protocol Length Info
125 5.481586 MySQL 151 Server Greeting proto=10 version=5.5.5-10.2.14-MariaDB-log
135 5.545861 MySQL 356 Login Request user=webuser db=astlo[Malformed Packet]
139 5.550347 MySQL 65 Response OK
141 5.550774 MySQL 73 Request Query
143 5.557442 MySQL 1394 Response
144 5.557446 MySQL 1394 ResponseResponse
146 5.562642 MySQL 1394 ResponseResponse
147 5.562643 MySQL 1394 ResponseResponse
149 5.563193 MySQL 1394 ResponseResponse
150 5.563197 MySQL 1394 ResponseResponse
152 5.567937 MySQL 1394 ResponseResponse
153 5.567939 MySQL 1394 ResponseResponse
154 5.567940 MySQL 1394 ResponseResponse
155 5.567945 MySQL 1394 ResponseResponse
156 5.567947 MySQL 1394 ResponseResponse
158 5.569427 MySQL 1394 ResponseResponse
159 5.569432 MySQL 1394 ResponseResponse
160 5.569433 MySQL 1394 ResponseResponse
162 5.572921 MySQL 1394 ResponseResponse
163 5.572924 MySQL 147 ResponseResponse
165 5.573590 MySQL 98 Request Query
166 5.578667 MySQL 148 Response
167 5.578883 MySQL 73 Request Query
168 5.585289 MySQL 1394 Response
169 5.585293 MySQL 1394 ResponseResponse
170 5.585301 MySQL 1394 ResponseResponse
171 5.585303 MySQL 1394 ResponseResponse
172 5.585306 MySQL 1394 ResponseResponse
173 5.585307 MySQL 1394 ResponseResponse
174 5.585310 MySQL 1394 ResponseResponse
175 5.585311 MySQL 1394 ResponseResponse
177 5.587020 MySQL 1394 ResponseResponse
178 5.587022 MySQL 1148 ResponseResponse
180 5.587517 MySQL 89 Request Query
181 5.593198 MySQL 65 Response OK
182 5.593384 MySQL 64 Request Use Database
183 5.598980 MySQL 65 Response OK
184 5.600193 MySQL 234 Request Query
185 5.605600 MySQL 153 Response
188 5.732250 MySQL 59 Request Ping
189 5.735173 MySQL 76 Response OK
190 5.735286 MySQL 64 Request Use Database
191 5.738636 MySQL 65 Response [TCP segment of a reassembled PDU]
192 5.738925 MySQL 59 Request Quit

Comment by Vladislav Vaintroub [ 2018-05-29 ]

там естъ возможность сохранить как .pcap, вот этот файл было бы неплохо иметь

Comment by Sergii Volikov [ 2018-05-29 ]

Возможно это?

Comment by Sergii Volikov [ 2018-05-29 ]

Куда переслать файл?

Comment by Vladislav Vaintroub [ 2018-05-29 ]

вот это
https://en.wikipedia.org/wiki/Pcap

Kак нибудь сохранить весь trace, но только не в .png картинках

Comment by Sergii Volikov [ 2018-05-29 ]

Отослал на Вашу почту.
Использовал MySQL Connector Net 6.9.12.

Comment by Vladislav Vaintroub [ 2018-05-29 ]

В JIRA есть "Drop files to attach, or browse".

Comment by Sergii Volikov [ 2018-05-29 ]

Я не хочу такие файлы выкладывать в инет для всеобщего обзора.

Comment by Sergii Volikov [ 2018-05-29 ]

Во вложении настройки сервера my.ini

Comment by Sergii Volikov [ 2018-05-29 ]

Вроде локально проблему победил. По крайней мере, теперь не могу воспроизвести ее локально.
Как победил - не знаю, вроде, только установил клиента 6.9.12. Хотя настройки разные делал, но явного, что именно повлияло, если повлияло,а не случайность, сказать не могу.
На сервере тоже установил клиента 6.9.12, но эффекта не обнаружил.
Сервер WEB и БД перестартовывал.

Comment by Vladislav Vaintroub [ 2018-05-29 ]

As diego dupin noted, there is a strange response to a Ping in the attached .pcap
It is longer than it should (14 bytes instead of 7) it has MORE_RESULTS_EXIST flag (???), and it actually has the expected OK packet in padding

So, we did send some junk, I'll try to reproduce it myself with example C program
(the only thing the connection does after login is
1.COM_QUERY SHOW VARIABLES
2. COM_QUERY SELECT TIMEDIFF(NOW(), UTC_TIMESTAMP())
3. COM_QUERY SHOW COLLATION
4. COM_QUERY SET character_set_results=NULL
5. COM_INIT_DB <db>
6. COM_QUERY INSERT INTO as_menu_favorite (UserName,MenuId,CorrDate) VALUE ('CORP
xxx',217,NOW())ON DUPLICATE KEY UPDATE Cnt=Cnt+1,CorrDate=NOW();SELECT URL FROM as_menu WHERE id=217
7.COM_PING
8 COM_INITDB <db>

#41

MySQL Protocol
    Packet Length: 14
    Packet Number: 0
    Affected Rows: 2
    Server Status: 0x000a
        .... .... .... ...0 = In transaction: Not set
        .... .... .... ..1. = AUTO_COMMIT: Set
        .... .... .... .0.. = More results: Not set
        .... .... .... 1... = Multi query - more resultsets: Set
        .... .... ...0 .... = Bad index used: Not set
        .... .... ..0. .... = No index used: Not set
        .... .... .0.. .... = Cursor exists: Not set
        .... .... 0... .... = Last row sent: Not set
        .... ...0 .... .... = database dropped: Not set
        .... ..0. .... .... = No backslash escapes: Not set
        .... .0.. .... .... = Session state changed: Not set
        .... 0... .... .... = Query was slow: Not set
        ...0 .... .... .... = PS Out Params: Not set
    Warnings: 0
    Message: \a
 
0000   2c 76 8a e2 93 d1 00 26 88 fe 97 07 08 00 45 00   ,v.â.Ñ.&.þ....E.
0010   00 3e 26 6e 40 00 7c 06 ba fb 0a 24 07 9f 0a 11   .>&n@.|.ºû.$....
0020   01 7d 0c ea c7 c5 ba 61 63 d3 1e 63 9b 0c 50 18   .}.êÇźacÓ.c..P.
0030   01 fe d3 00 00 00 0e 00 00 00 00 02 00 0a 00 00   .þÓ.............
0040   00 07 00 00 01 00 00 00 02 00 00 00               ............
 
 
Actually only the last 10 bytes are the real OK packet, and before that.
the rest of the TCP 

Comment by Vladislav Vaintroub [ 2018-05-29 ]

Sergey_W, what are your final settings? Anything in the connection string you can share?

Comment by Sergii Volikov [ 2018-05-29 ]

Строка подключения:
Server=localhost;Database=astlo;User Id=webuser;Password=*******************;Default Command Timeout=90;Max Pool Size=200;

Comment by Vladislav Vaintroub [ 2018-05-29 ]

Any changes compared to prior settings?

Comment by Sergii Volikov [ 2018-05-29 ]

На севере проблему победить не удалось. Настройки строки подключения не менялись.
Разница: на сервере указан localhost, на локальном ПК имя сервера. Но это было и раньше.
Ничего не понимаю, почему на локальном ПК нормально, а на сервере проблемы - нормально работать невозможно.
Сервер БД один, разные WEB-сервера. Строки подключения один в один, кроме имени севера, но на сервере ставил имя сервера как указано для ПК. Понимаю, что это никак повлиять не должно, но не знаю, что еще можно предпринять.

Comment by Vladislav Vaintroub [ 2018-05-29 ]

ну баг то вроде есть, доказано .pcap-ом . Надо просто постараться нам воспроизвести

Comment by Sergii Volikov [ 2018-05-30 ]

Изменений в строке подключений не было.
Единственное изменение, вроде,которое могло на это повлиять, это установка версии 10.2.15.
Но все равно возникают вопросы:
1. Почему откат ничего не дал?
2. Почему не воспроизводиться локально, а раньше легко воспроизводилось? Локально обновил клиента, хотя сразу после обновления клиента проблема все равно наблюдалась. pcap - тому пример.
Но меня больше волнует, как сейчас найти временное решение. Пользователи, а их около 1,5 тыс. нормально работать не могут. Может будут идеи, что можно сделать?

Comment by Sergii Volikov [ 2018-05-30 ]

Вроде, нашел причину!
В одном запросе был Insert и Select. Решил упростить себе работу, а получил ...
Это видно по логам pcap.
*6. COM_QUERY INSERT INTO as_menu_favorite (UserName,MenuId,CorrDate) VALUE ('CORP
xxx',217,NOW())ON DUPLICATE KEY UPDATE Cnt=Cnt+1,CorrDate=NOW();SELECT URL FROM as_menu WHERE id=217*
Локально это пофиксил, думал и на сервере изменил, но оказалось на сервере файл не переписался (остался старый).

Comment by Sergii Volikov [ 2018-05-30 ]

Ошибка не проявляется, значит причина найдена.
Спасибо за помощь!

Comment by Vladislav Vaintroub [ 2018-05-31 ]

pcap traces show iirregularity , probably something weird with semicolon batching, the MORE_RESULTS_EXIST flag is set on OK from ping, probably from previous multi-statement.
Will try to reproduce with C

Comment by Vladislav Vaintroub [ 2018-05-31 ]

could not reproduce the same with c++ so far. Here iis the program that emulates C/NET connect sequence and tries to emulate the queries/ping/change database as close as possible (note, that C/NET also sends a weird unparsable by wireshark connection attribute, but this program does not)

That passes with last 10.2, no problem, pcap trace does not show any irregularities

#include "stdafx.h"
#include <stdlib.h>
#include <mysql.h>
#include <stdio.h>
 
 
#define ERROR(x) {printf("error in " x ",mysql_error=%d(%s), on line %d\n", mysql_errno(mysql),mysql_error(mysql), __LINE__); goto end;}
int main()
{
	int ret = 1;
	MYSQL *mysql = mysql_init(0);
	MYSQL_RES *res;
	const char *init_queries[] = {
		"SHOW VARIABLES",
		"SELECT TIMEDIFF(NOW(), UTC_TIMESTAMP())",
		"SHOW COLLATION",
		"SET character_set_results = NULL"
	};
 
	mysql = mysql_real_connect(mysql, "127.0.0.1", "root", "", "mysql", 3306, 0, CLIENT_MULTI_STATEMENTS|CLIENT_MULTI_RESULTS);
	if (!mysql)
		ERROR("mysql_real_connect");
 
	
	for (auto q : init_queries) {
		if (mysql_query(mysql,q)) {
			printf("%s failed", q);
			ERROR("mysql_query");
		}
		res = mysql_store_result(mysql);
		
		if (!res) {
			printf("query %s, no result\n", q);
			//ERROR("mysql_use_result");
		}
		else {
			int cnt=0;
			while (mysql_fetch_row(res))
			{
				cnt++;
			}
			mysql_free_result(res);
		}
	}
 
	if (mysql_select_db(mysql, "test")) {
		ERROR("mysql_query");
	}
 
	if (mysql_query(mysql, "do 1;select 'menu' as menu, 'NZA/Lot' as URL;")) {
		ERROR("mysql_query");
	}
 
	while (mysql_more_results(mysql))
	{
		if (mysql_next_result(mysql))
			ERROR("mysql_next_result");
		res = mysql_store_result(mysql);
		if (!res) {
			ERROR("mysql_use_result");
		}
		else
			mysql_free_result(res);
	}
 
	if (mysql_ping(mysql)) {
		ERROR("mysql_ping");
	}
 
	if (mysql_select_db(mysql, "test")) {
		ERROR("mysql_select_db");
	}
	ret = 0;
end:
	if (mysql)
		mysql_close(mysql);
	exit(ret);
}

Comment by Vladislav Vaintroub [ 2018-06-01 ]

here is C# program tested with 6.9.12 C/NET, as well as 8.0.11 it does not show errors either

 
using MySql.Data.MySqlClient;
 
namespace connectortest
{
    class Program
    {
        static void Main(string[] args)
        {
            for (int i = 0; i < 100; i++)
            {
                using (var con = new MySqlConnection("user=root;host=127.0.0.1;SslMode=None;database=mysql"))
                {
                    con.Open();
 
                    MySqlCommand command = new MySqlCommand("do 1; select 1;", con);
                    using (var r = command.ExecuteReader())
                    {
                    }
                    con.Ping();
                    con.ChangeDatabase("mysql");
                }
            }
        }
    }
}

Comment by Vladislav Vaintroub [ 2018-06-01 ]

tested the above with community MySqlConnector, too. Works as well. So I guess the error is really of a sporadic nature, rather than systematic.

Comment by Sergii Volikov [ 2018-06-05 ]

Добрый день!
Владислав, это вопросы, сообщения мне?
Мне попробовать воспроизвести ошибку еще раз?

Кстати, сегодня ошибка проявилась два раза. До этого ее небыло.
MySql.Data.MySqlClient.MySqlException: Out of sync with server
Generated: Tue, 05 Jun 2018 07:06:03 GMT

System.Web.HttpUnhandledException (0x80004005): Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> MySql.Data.MySqlClient.MySqlException (0x80004005): Out of sync with server
at MySql.Data.MySqlClient.NativeDriver.ReadOk(Boolean read)
at MySql.Data.MySqlClient.NativeDriver.SetDatabase(String dbName)
at MySql.Data.MySqlClient.Driver.SetDatabase(String dbName)
at MySql.Data.MySqlClient.MySqlConnection.ChangeDatabase(String databaseName)
at MySql.Data.MySqlClient.MySqlConnection.Open()

Comment by Vladislav Vaintroub [ 2018-06-05 ]

Это я себе пишу, а также всем кто читает ( у нас не все в русском сильны). А вопросы есть, да У вас прокси нету между клиентом и сервером? Я долго смотрел на код, и решил что такого как в .pcap быть не может в обычном случае.

Comment by Sergii Volikov [ 2018-06-05 ]

Думаю прокси тут не причем (его и нет), так как сервер приложения и сервер БД это один физический (вернее виртуальный) сервер.
То что я эмулировал (.pcap), было с моего локального ПК на сервер БД, но ведь ошибка проявляется и в обычном случае.
У меня есть подозрение, что ошибка проявляется не сразу, а после некоторого количества (критического) запросов Insert/Select.

Comment by Vladislav Vaintroub [ 2018-06-05 ]

ну если нету , можно еще постарать повторить ошибку, с локальным сервером БД?

Comment by Sergii Volikov [ 2018-06-05 ]

Установить локальный сервер БД?
Или повторить ошибку при связи cервер WEB - сервер БД?
Но я не представляю как это отследить с помощью Wireshark? Ведь она отслеживает только сетевой интерфейс!? А этом случае сеть не будет использоваться.

Comment by Vladislav Vaintroub [ 2018-06-05 ]

главное ошибку повторить. .pcap можно собрать с помощью rawcap http://www.netresec.com/?page=RawCap

Comment by Sergii Volikov [ 2018-06-05 ]

ошибка легко воспроизводится на реальной базе. Но нужно несколько раз выполнить скрипт Inset и Select.

INSERT INTO as_menu_favorite (UserName,MenuId,CorrDate) VALUE (@UserName,@Id,NOW())ON DUPLICATE KEY UPDATE Cnt=Cnt+1,CorrDate=NOW();SELECT URL FROM as_menu WHERE id=@id;

Кроме того, другие клиенты этого приложения тоже в этот момент могут получить ошибку, даже не обращаясь к этим таблицам.
Если копировать эти (as_menu_favorite и as_menu) таблицы с данными в другую базу ошибку воспроизвести не получается.
То есть, структура таблиц не имеет значения!?
Что дальше делать, пока, не понимаю.

Comment by Vladislav Vaintroub [ 2018-06-05 ]

написать маленькое приложение, как мой пример вверху, чтобы это воспроизвести можно было с нуля.
Спасибо!

Comment by Vladislav Vaintroub [ 2018-06-05 ]

а, я вижу это не получается. Это гдето, кроме "реальной базы" воспроизводится?

Comment by Sergii Volikov [ 2018-06-05 ]

Написать без проблем, но почему думаете, что оно воспроизведет ошибку?
Ок. Делаю, по результатам опишусь.

Comment by Sergii Volikov [ 2018-06-05 ]

пробовал на другой схеме "test" той-же базы - не удалось воспроизвести. Даже с теми же данными.

Comment by Sergii Volikov [ 2018-06-05 ]

Программу сделал, но как и ожидалось - результат отличный, но нас не устраивает, потому, что ошибка не воспроизводиться.
Цикл делал до 1000.
Приложение выполняется за 21,8 сек.
На всякий случай привожу код программы

           Stopwatch sWatch = new Stopwatch();
            sWatch.Start();
            for (int i = 0; i < 1000; i++)
            {
                using (var con = new MySqlConnection("user=webuser;Password=****;host=ServerIP;SslMode=None;database=mysql"))
                {
                    con.Open();
 
                    MySqlCommand command = new MySqlCommand("do 1; select 1;", con);
                    using (var r = command.ExecuteReader())
                    {
                    }
                    con.Ping();
                    con.ChangeDatabase("mysql");
                }
            }
            sWatch.Stop();
            Console.WriteLine(sWatch.ElapsedMilliseconds);
            Console.ReadKey();

Comment by Wolfgang Krebs [ 2018-10-23 ]

we have the same problem at our site - using mariadb - server on centos 7 in version 10.2.8 and we already tried version 10.2.18 and on the client mysql-connector for .net 4.1 and mysql-connector for .net 4.5.
In addition to the tcpdump already posted - we did a strace on the server side. Here you can see, that the server really produces a wrong answer to the mysql_ping:
[pid 15838] recvfrom(422, "\1\0\0\0", 4, MSG_DONTWAIT, NULL, NULL) = 4
[pid 15838] recvfrom(422, "\16", 1, MSG_DONTWAIT, NULL, NULL) = 1
[pid 15838] clock_gettime(CLOCK_REALTIME,

{1539959333, 120847514}

) = 0
[pid 15838] clock_gettime(CLOCK_MONOTONIC,

{110494, 150948059}

) = 0
[pid 15838] clock_gettime(CLOCK_MONOTONIC,

{110494, 150973363}

) = 0
[pid 15838] sendto(422, "\16\0\0\0\0\0\0\n\0\0\0\7\0\0\1\0\0\0\2\0\0\0", 22, MSG_DONTWAIT, NULL, 0) = 22

we solved the problem by changing/recompiling the client SW with an odbc driver not changing the server versions. With the ODBC client version there are no problems at all.

Comment by Vladislav Vaintroub [ 2018-10-23 ]

wkrebs, do you have a reproducible test case for that? If you have, please share

Comment by Oleksandr Byelkin [ 2018-10-24 ]

Are/is there triggers/trigger on the table which is updating?

Comment by Wolfgang Krebs [ 2018-10-24 ]

there are no triggers on the table which is updating - especially the error occurs without updating any table

concerning a test case - I can support you with the sequence of commands, that are send to the database - and I want to mention some interesting thing - the application worked fine at the first connection to the database after a restart of the mariadb-server. When we closed the application and restarted it the error occurred.

here the sequence that is executed (i think some of the commands are executed within the mysql connector itself and must not be programmed especially - sorry, i have no access to the source code, so that is the maximum I can provide:
login to database
show variables
SELECT TIMEDIFF(NOW(), UTC_TIMESTAMP())
show collation
set names latin1
set character_set_results=NULL
use database
SET SESSION old_passwords = 0; SELECT * FROM tablename WHERE user='xxx' AND pwd=PASSWORD('userpasswd') AND status='A'
mysql_ping -> here we got the erronous response, that disturbs the further client server communication (\16\0\0\0\0\0\0\n\0\0\0\7\0\0\1\0\0\0\2\0\0\0)

Comment by Vladislav Vaintroub [ 2018-10-25 ]

Thanks wkrebs. Summarizing what we have seen so far, including yesterdays brainstorming session with sanja

0. it happens when there is a semicolon-separated "batch". Both cases where it was seen, there is a command that returns OK (SET/UPDATE), followed by semicolon, followed by a SELECT

1. for one case for which we have network trace, pcap, it manifests in a weird resultset already returned by select command in the batch (resultset rows end with an EOF with "more results exist" flag, which is directly followed by an EOF packet without this flag)

2. the following OK packet (response to ping) is malformed, and embeds part of another OK packet into message (which is normally reserved for readable string)

3. The following command (switch database) returns a malformed packet, which seemingly contains tail part of OK in 2.

4. It was reported that triggers are not involved.
How it can happen is still a mystery after inspection of the source code

Comment by Bradley Grainger [ 2019-06-13 ]

Issues filed on MySqlConnector (.NET driver) that appear to be caused by this bug: https://github.com/mysql-net/MySqlConnector/issues/612 https://github.com/mysql-net/MySqlConnector/issues/651

Comment by Moshe L [ 2019-06-13 ]

I can repro. the problem on 10.3.15@Windows 2016, 10.3.13@Linux.
It not failing on the first query, but a ~ 0.5-1%.

My Testcase (C# with MySqlConnector, but fail also with other error message with oracle MySql.Data):

{{
string sql = @" SET @hereami =1; select * from table limit 1; ";

// working: string sql = @"set @s=POINT(32.08373,34.8965); set@z=POINT(32.08373,34.8965);";
// also working: string sql= " select * from table limit 1; select * from table limit 1;";

for (int i = 0; i < 2200; i++) {

using (var Conn = new MySqlConnection(connstr))
{
Conn.Open();
var Cmd = new MySqlCommand(sql);
Cmd.Connection = Conn;
using (var oReader = Cmd.ExecuteReader())

{ oReader.Read(); }

}
}

Console.ReadKey();
}}

Comment by Vladislav Vaintroub [ 2019-06-13 ]

what data do you have in your table Moshe L ?
What is the DDL for it?

Comment by Moshe L [ 2019-06-13 ]

the data is useless; I can use any table for the select.
the problem is with the combination of "SET ...; SELECT ...;" or "UPDATE. .. ; SELECT". the table isn't relevant.

Comment by Vladislav Vaintroub [ 2019-06-13 ]

Ok, just to make sure, as an example for "any table", this will also fail for you

CREATE TABLE t(i int);
INSERT INTO t VALUES(1);

if you execute
SET @a=1;SELECT * FROM t;

given enough attempts?
Or even simpler, with no tables, but still same structure (OK packet, followed by result set)
like

DO 1; SELECT 1;

Can you confirm that this would be failing?

You do get the failure with a single user, or only with multiple ones?

Comment by Moshe L [ 2019-06-14 ]

Tes. Your first testcase was failing.
DO 1; SELECT 1;

did not crash

SET @hereami =1; SELECT 1;

also not crashed

DO 1; select * from news limit 1;

crashed

multiuser only. I was tested via "Pooling=false" and via batch file looping on mysql -e "..." - no problems.
tested also with a mysql < file.sql with a 30K of 'set...select' queries - no problems.

Comment by Vladislav Vaintroub [ 2019-06-14 ]

Moshe L, if you are using pooling, how often you open a new connection? I your previous example it was just a single time, which equates basically to no-pooling

Comment by Moshe L [ 2019-06-14 ]

@Bradley Grainger was wrote the Pooling machine.

As I know, it open a ~5 connections (in my configuration), and re-use them forever until the connection is broken.
If the app need more then 5 concurrent connections, the pool can open until 20 (in my configuration) connections and then, If I request one I will wait until one is free, or the timeout Exception will thrown.

Comment by Moshe L [ 2019-06-14 ]

My C# Testcase

 
	string conn = "server, db,user,password; pooling=true; Connection reset =false; Min Pool Size=5;Max Pool Size=40; Connect Timeout=10;default command timeout=30;UseAffectedRows=true;Allow User Variables=true; CharacterSet=utf8mb4";
 
		
 
			string sql = @" SET @hereami =1; select * from news limit 1; ";
			//string sql = @"set @s=POINT(32.08373,34.8965); set@z=POINT(32.08373,34.8965);"; // no problem
			//sql = " SET @hereami =1; SELECT 1,2,3;"; // no problem
			sql = @"DO 1; select * from news limit 1; ";
 
			var s2 = sql.Split(';'); // one of  the tests was splitting the queries and run them one-and-one - no problem but 50% mroe time.
			
				
			for (int i = 0; i < 3200; i++)
				{
 
				using (var Conn = new MySqlConnection(conn))
				{
					Conn.Open();
					//foreach (var current in s2)
					//{
						var Cmd = new MySqlCommand(sql);
						Cmd.Connection = Conn;
						using (var oReader = Cmd.ExecuteReader())
						{
							oReader.Read();
						}
					//}
				}
				}
 
			Console.ReadKey();

Comment by Bradley Grainger [ 2019-06-14 ]

pooling=true; Connection reset =false may be relevant to the repro here. With this setting, MySqlConnector will send a COM_PING packet to the server when MySqlConnection.Open() is called (which doesn't open a new connection, but retrieves one from the pool); this is done to check that the connection is still valid.

At least in one of the packet captures I reviewed, a corrupt packet was sent in response to the COM_PING; it's also been mentioned previously on this case.

Comment by Moshe L [ 2019-06-15 ]

other version of this bug:

sql = @"delete from news where n_id=1; select n_id from news limit 1; ";
			string sql2 = "select n_id from news limit 1;";
 
			var s2 = sql.Split(';');
			
				
			for (int i = 0; i < 3200; i++)
				{
 
				using (var Conn = new MySqlConnection(conn))
				{
					Conn.Open();
						var Cmd = new MySqlCommand(sql);
						Cmd.Connection = Conn;
						using (var oReader = Cmd.ExecuteReader())
						{
							oReader.Read();
						}
					Cmd.CommandText = sql2;
					Cmd.ExecuteScalar(); //sometimes  MySqlProtocolException: Packet received out-of-order. Expected 1; got 108.
				}
				}

Comment by Moshe L [ 2020-01-29 ]

something new with this problem?

Comment by Vladislav Vaintroub [ 2020-01-29 ]

We have not reproduced it this far. I tried my best , but there is not enough information. Maybe you can share the details of the server configuration (my.ini or my.cnf), so this gives an idea.

Comment by Moshe L [ 2020-01-30 ]

my.ini for one of the servers (Windows 2016). a ~same configuration was throws the same error on Debian.

 
[mysqld]
datadir=C:/Program Files/MariaDB 10.3/data
tmpdir=C:/Program Files/MariaDB 10.3/temp
port=3306
innodb_buffer_pool_size=4096M
tmp_table_size = 2677721611
innodb_change_buffer_max_size=40
skip_name_resolve=1
 
 
 
query_cache_size=24857600
query_cache_type=1
join_buffer_size=2621440
sort_buffer_size = 2048576
key_buffer_size= 234217721
 
ft_min_word_len=2
 
[client]
port=3306
default-character-set=utf8
plugin-dir=C:/Program Files/MariaDB 10.4/lib/plugin

I was added a testcase in C# you can see on the comments. if you want, I can test it for you with a server open to the world or to my static IP.

Comment by Vladislav Vaintroub [ 2020-01-30 ]

Moshe L , I tried you testcase , too . Of course I've no idea about your "news" table, so I had a table with single int row. I'm not getting the errors.
Would you like to test a patch that I'd implement "by suspicion" ? There are things that I suspect might affect server, but I did not figure out exactly how. I.e if I upload a server build (a ZIP or MSI), would you volunteer to test it, on your environment where everything fails. As of server access, that would need an access with RDP, and debugger, and deterministic test case. Alas, if you had deterministic test case, I would not need a remote server either.

Comment by Moshe L [ 2020-01-30 ]

Thank you for all work.

I want to do it. yes.
the problem is that the problem is not deterministic. on the same code it failed about 1/1000~ of the runs, so for repeat it I running a loop until it throwing the error.

the strage thing: I was saw the errors on my production (3 diffrent machines) but non on my development system.
I was upgraded the server to 10.4.10 some months ago, and after this upgrade (before it was 10.3.8) I see less error messages.

btw, I was saw a "better" error rate on this query, on a simple loop:

{{
/*CREATE TABLE `sites_addresses` (
`sa_id` int(11) NOT NULL AUTO_INCREMENT,
`sa_site` int(11) NOT NULL,
`sa_address` int(11) NOT NULL,
`sa_visible` tinyint(1) NOT NULL DEFAULT 1,
PRIMARY KEY (`sa_id`),
UNIQUE KEY `site_address` (`sa_site`,`sa_address`),
KEY `sad_visible` (`sa_visible`,`sa_id`,`sa_site`,`sa_address`),
KEY `filter_visible` (`sa_address`,`sa_site`,`sa_visible`)
) ENGINE=InnoDB AUTO_INCREMENT=897110 DEFAULT CHARSET=utf8mb4;
*/
string sql = @"
insert into sites_addresses set sa_site=1218006, sa_visible=1, sa_address=66968 on duplicate key update sa_site=1218006, sa_visible=1, sa_address=66968; select sa_id from sites_addresses where sa_address=66968 and sa_site=1218006";
}}

the specific error message is diffrent:

`Packet received out-of-order. Expected 1; got 115., /Company/PostSite`

on the old testcase it was `got 84`.

Comment by Vladislav Vaintroub [ 2020-01-30 ]

https://1drv.ms/u/s!AqT4tBcElQz_bgxYQBf6J2ykN_A?e=h6uH6N

I build a ZIP package for the "fix by suspicion" ( https://github.com/mariadb/server/commit/64437d040bfdb61c92efd33301a676ca02f342c8 ).
Moshe L, I would appreciate if you can give it a test? It is on top of current 10.4, with the patch I mention.

I tend to strongly suspect the COM_MULTI code that came in 10.2 for the breakage. that line that I removed was protocol-relevant addition that came with that code, and this is in semicolon batching. And it kinda rhymes well with "concatenated packets" that we have seen in the network trace

sanja, FYI.

Comment by Moshe L [ 2020-01-30 ]

my test:

extract your zip file
backup all
stop mysql service
run from commandline the exact data/my.ini/settings but on the exe from your zip, on production server

run the testcase

The testcase success. I will wait a day to see if the random problem disappears.

Comment by Vladislav Vaintroub [ 2020-01-30 ]

. Thank you Moshe L. Please keep us informed.

Comment by Moshe L [ 2020-02-03 ]

4 days of quiet.

you can mark this bug as fixed, I think.

Generated at Thu Feb 08 08:27:56 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.