Packet received out-of-order. Expected 1; got 84. #651

MosheL · 2019-06-13T08:24:15Z

Packet received out-of-order. Expected 1; got 84

at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() 
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
at System.Threading.Tasks.ValueTask`1.get_Result() 
at MySqlConnector.Protocol.Serialization.ProtocolUtility.DoReadPayloadAsync(BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 previousPayloads, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) 
at MySqlConnector.Protocol.Serialization.ProtocolUtility.ReadPayloadAsync(BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 cache, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) 
at MySqlConnector.Protocol.Serialization.StandardPayloadHandler.ReadPayloadAsync(ArraySegmentHolder`1 cache, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) 
at MySqlConnector.Core.ServerSession.ReceiveReplyAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) 
--- End of stack trace from previous location where exception was thrown --- 
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() 
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task) 
at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult() 
at MySqlConnector.Core.ServerSession.TryAsyncContinuation(Task`1 task) 
at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke() 
at System.Threading.Tasks.Task.Execute() 
--- End of stack trace from previous location where exception was thrown --- 
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() 
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task) 
at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1.ConfiguredValueTaskAwaiter.GetResult() 

[Failed to read the result set.]
at MySql.Data.MySqlClient.MySqlDataReader.ActivateResultSet(ResultSet resultSet) 
at MySql.Data.MySqlClient.MySqlDataReader.<ReadFirstResultSetAsync>d__96.MoveNext() 
--- End of stack trace from previous location where exception was thrown --- 
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() 
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
at System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult() 
at MySql.Data.MySqlClient.MySqlDataReader.<CreateAsync>d__95.MoveNext() 
--- End of stack trace from previous location where exception was thrown --- 
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() 
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult() 
at MySqlConnector.Core.TextCommandExecutor.<ExecuteReaderAsync>d__1.MoveNext() 
--- End of stack trace from previous location where exception was thrown --- 
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() 
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult() 
at MySql.Data.MySqlClient.MySqlCommand.ExecuteDbDataReader(CommandBehavior behavior) 
at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader()

MySqlConnector 0.56, MariaDB 10.3.15 @ Windows 2016.

I tried with 10.3.13 - no problems.

how to start debug it ?

The text was updated successfully, but these errors were encountered:

bgrainger · 2019-06-13T13:35:09Z

Do you have a SQL statement (and database structure) that reproduces the problem?

Otherwise, if you're not using SSL, a packet capture (with Wireshark or similar) will show the network traffic that's causing the problem.

MosheL · 2019-06-13T15:14:10Z

yes. there are many, but these all is versions of the same code:

SET @hereami = POINT(0,0); SELECT types.id , concat( min(types.name) ,' ‏(', count(st_site) ,')') as name, min(parent.name) parent, min(parent.id) parent_id , min(parent.display_order) display_order1, min(types.display_order) display_order FROM types ,types as parent , sites_types where st_type=types.id and parent.id=types.parent_id and types.id > 0 and st_site in ( SELECT /*0, 0, 0 */ search_sites.id FROM search_sites WHERE 
1=1 
and search_sites.id in (select st_site from sites_types where st_site_visible=1 and st_speciality=2199) and city in(1397)) and types.parent_id=2199 group by types.id ORDER BY display_order1 desc, display_order desc, min(types.name) asc;

I was tried to debug the problem, the problem is in the specific query (or similar), in a ~ 1/30 factor.
Tried to build a testcase with only the problematic SELECTs but can't see the problem.

I have a PCAP with the problem (and also the 0,1 problem). I can send it by mail but not upload it to public.

MosheL · 2019-06-13T15:18:02Z

I was sent a mail with a PCAP file with the problem.

bgrainger · 2019-06-13T15:57:18Z

Thanks; I have it.

MosheL · 2019-06-13T16:59:50Z

Update: I was removed the usage of the Allow User Variables=true and the variable from the SQL

the error was removed.

testcase :

static void Main(string[] args)
 {


  var logger = new MySqlConnector.Logging.ConsoleLoggerProvider(MySqlConnector.Logging.MySqlConnectorLogLevel.Debug);
  MySqlConnector.Logging.MySqlConnectorLogManager.Provider = logger;



  var Conn = new MySqlConnection("server=........; pooling=true;Connection reset =false; Min Pool Size=5;Max Pool Size=20; Connect Timeout=10;default command timeout=30;UseAffectedRows=true;Allow User Variables=true;CharacterSet=utf8mb4");
  Conn.Open();

  


  string sql = @"
SET @hereami = POINT(32.08373,34.8965); SELECT types.id , concat( min(types.name) ,' ‏(', count(st_site) ,')') as name, min(parent.name) parent, min(parent.id) parent_id , min(parent.display_order) display_order1, min(types.display_order) display_order FROM types ,types as parent , sites_types where st_type=types.id and parent.id=types.parent_id and types.id > 0 and st_site in ( SELECT /*0, 32.08373, 34.8965 */ search_sites.id FROM search_sites WHERE 
1=1 
and search_sites.id in (select st_site from sites_types where st_site_visible=1 and st_speciality=1686) and city in(1792)) and types.parent_id=1686 group by types.id ORDER BY display_order1 desc, display_order desc, min(types.name) asc";



// without parameters and Allow User Variables=true it working
  string sql2 = @"
SELECT types.id , concat( min(types.name) ,' ‏(', count(st_site) ,')') as name, min(parent.name) parent, min(parent.id) parent_id , min(parent.display_order) display_order1, min(types.display_order) display_order FROM types ,types as parent , sites_types where st_type=types.id and parent.id=types.parent_id and types.id > 0 and st_site in ( SELECT /*0, 32.08373, 34.8965 */ search_sites.id FROM search_sites WHERE 
1=1 
and search_sites.id in (select st_site from sites_types where st_site_visible=1 and st_speciality=1686) and city in(1792)) and types.parent_id=1686 group by types.id ORDER BY display_order1 desc, display_order desc, min(types.name) asc";


  var Cmd = new MySqlCommand(sql);
  Cmd.Connection = Conn;
  for (int i = 0; i < 2200; i++)
  {
   using (var oReader =Cmd.ExecuteReader()) {
    oReader.Read();
   }
  }


  Console.ReadKey();



 }

bgrainger · 2019-06-13T17:08:37Z

The cause of this is just like #612 (comment).

Here's the end of a query followed by the server response. There are 11 bytes of garbage at the beginning, which contain part of the query the client submitted. The 0x54 is being (mis)interpreted as packet sequence number 84. Then there is the expected OK packet (green) followed by the column count packet (purple).

CC @vaintroub are you aware of any MariaDB-specific bugs that could cause a server response to be prefixed with 11 bytes of random memory possibly initialised with the client's query? This is on MariaDB 10.3.15 (running on Windows Server AFAIK).

bgrainger · 2019-06-13T17:19:51Z

I haven't Google translated all the Russian in this case, but this appears to be the same issue: https://jira.mariadb.org/browse/MDEV-16308

vaintroub · 2019-06-13T17:21:24Z

Yes, you found that as I was writing. This is an unsolved mystery case. We tried hard to understand what's going on and how is that possible, did not have any idea so far.

bgrainger · 2019-06-13T17:34:35Z

Closing this as an external (MariaDB) issue.

MosheL · 2019-06-13T19:18:35Z

Workaround: use SELECT and not SET.

SELECT @hereami = POINT(1,2); SELECT ... is valid

bgrainger mentioned this issue Jun 13, 2019

"Packet received out-of-order. Expected 1; got 0." happening infrequently #612

Closed

bgrainger closed this as completed Jun 13, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Packet received out-of-order. Expected 1; got 84. #651

Packet received out-of-order. Expected 1; got 84. #651

MosheL commented Jun 13, 2019 •

edited

Loading

bgrainger commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019

Uh oh!

bgrainger commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019

Uh oh!

bgrainger commented Jun 13, 2019 •

edited

Loading

Uh oh!

bgrainger commented Jun 13, 2019

Uh oh!

vaintroub commented Jun 13, 2019

Uh oh!

bgrainger commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019

Uh oh!

Packet received out-of-order. Expected 1; got 84. #651

Packet received out-of-order. Expected 1; got 84. #651

Comments

MosheL commented Jun 13, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

bgrainger commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019

Uh oh!

bgrainger commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019

Uh oh!

bgrainger commented Jun 13, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

bgrainger commented Jun 13, 2019

Uh oh!

vaintroub commented Jun 13, 2019

Uh oh!

bgrainger commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019

Uh oh!

MosheL commented Jun 13, 2019 •

edited

Loading

bgrainger commented Jun 13, 2019 •

edited

Loading