.net core 2.1 The WriteAsync method cannot be called when another write operation is pending

[cschotte]

When I upgraded my project from .net core 2.0 to 2.1 I (sometimes) get this

System.NotSupportedException:
System.NotSupportedException:  The WriteAsync method cannot be called when another write operation is pending.
   at System.Net.Security.SslStreamInternal.WriteAsyncInternal[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStreamInternal.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at MySqlConnector.Protocol.Serialization.StreamByteHandler.WriteBytesAsync(ArraySegment`1 data, IOBehavior ioBehavior) in C:\projects\mysqlconnector\src\MySqlConnector\Protocol\Serialization\StreamByteHandler.cs:line 87
--- End of stack trace from previous location where exception was thrown ---
   at MySqlConnector.Utilities.ValueTaskExtensions.ContinueWith[T,TResult](ValueTask`1 valueTask, Func`2 continuation) in C:\projects\mysqlconnector\src\MySqlConnector\Utilities\ValueTaskExtensions.cs:line 8
   at MySqlConnector.Core.ServerSession.DisposeAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in C:\projects\mysqlconnector\src\MySqlConnector\Core\ServerSession.cs:line 200
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, IOBehavior ioBehavior, CancellationToken cancellationToken) in C:\projects\mysqlconnector\src\MySqlConnector\Core\ConnectionPool.cs:line 89
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, IOBehavior ioBehavior, CancellationToken cancellationToken) in C:\projects\mysqlconnector\src\MySqlConnector\Core\ConnectionPool.cs:line 141
   at MySql.Data.MySqlClient.MySqlConnection.CreateSessionAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in C:\projects\mysqlconnector\src\MySqlConnector\MySql.Data.MySqlClient\MySqlConnection.cs:line 399
   at MySql.Data.MySqlClient.MySqlConnection.OpenAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in C:\projects\mysqlconnector\src\MySqlConnector\MySql.Data.MySqlClient\MySqlConnection.cs:line 170
   at MySql.Data.MySqlClient.MySqlConnection.Open() in C:\projects\mysqlconnector\src\MySqlConnector\MySql.Data.MySqlClient\MySqlConnection.cs:line 156
   at BackOffice.Controllers.ApiController.GetCustomerList(Nullable`1 id) in C:\Dev\New Line Mobile\NewLineBilling\BackOffice\Controllers\ApiController.cs:line 43
   at lambda_method(Closure , Object , Object[] )
   at Microsoft.Extensions.Internal.ObjectMethodExecutor.Execute(Object target, Object[] parameters)
   at Microsoft.AspNetCore.Mvc.Internal.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.InvokeActionMethodAsync()
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.InvokeNextActionFilterAsync()
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.Rethrow(ActionExecutedContext context)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.InvokeInnerFilterAsync()
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeNextResourceFilter()
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Rethrow(ResourceExecutedContext context)
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeFilterPipelineAsync()
   at Microsoft.AspNetCore.Mvc.Internal.ResourceInvoker.InvokeAsync()
   at Microsoft.AspNetCore.Builder.RouterMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Localization.RequestLocalizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.Invoke(HttpContext context)

[bgrainger]

What version of MySqlConnector are you using?

[cschotte]

v0.40.4 the exception is happening (sometimes) in the Connection.Open(); (i'm using SSL)
MySQL Server version 5.7.21 (Azure)
.NET Core 2.1.0

[bgrainger]

I wonder if SslStream in an earlier .NET Core version was throwing a different exception and it just happened to be caught here: https://github.com/mysql-net/MySqlConnector/blob/0.40.4/src/MySqlConnector/Core/ServerSession.cs#L196-L210

It seems like a previous Write operation must have failed somehow, which is why the session is being cleaned up (after being retrieved from the pool), but I don't yet know exactly how this error is being triggered.

[bgrainger]

Are you able to collect logs (with ConsoleLoggerProvider or one of these options) of the failure and post them here?

[cschotte]

ConnectionPool:Debug: Pool1 waiting for an available session
ConnectionPool:Debug: Pool1 receiving Session1.2 back
ConnectionPool:Debug: Pool1 found an existing session; checking it for validity
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 1263.5836ms 200 application/json; charset=utf-8
ServerSession:Debug: Session1.1 ServerVersion=5.6.39.0 doesn't support reset connection; sending change user request
ConnectionPool:Debug: Pool1 found an existing session; checking it for validity
ServerSession:Debug: Session1.4 ServerVersion=5.6.39.0 doesn't support reset connection; sending change user request
ServerSession:Debug: Session1.1 optimistic reauthentication failed; logging in again
ServerSession:Debug: Session1.1 switching to AuthenticationMethod 'mysql_native_password'
ServerSession:Debug: Session1.4 optimistic reauthentication failed; logging in again
ServerSession:Debug: Session1.4 switching to AuthenticationMethod 'mysql_native_password'
ConnectionPool:Debug: Pool1 returning pooled Session1.1 to caller; LeasedSessionsCount=1
TextCommandExecutor:Debug: Session1.1 ExecuteBehavior Synchronous CommandText: SELECT *************
ConnectionPool:Debug: Pool1 returning pooled Session1.4 to caller; LeasedSessionsCount=2
TextCommandExecutor:Debug: Session1.4 ExecuteBehavior Synchronous CommandText: SELECT *************
ServerSession:Debug: Session1.1 entering FinishQuerying; SessionState=Querying
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action method BackOffice.Controllers.ApiController.GetDeviceListForContract (BackOffice), returned result Microsoft.AspNetCore.Mvc.JsonResult in 93.1543ms.
Microsoft.AspNetCore.Mvc.Formatters.Json.Internal.JsonResultExecutor:Information: Executing JsonResult, writing value of type '<>f__AnonymousType1`2[[System.Collections.Generic.List`1[[System.Object, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]], System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[System.Int32, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.
ServerSession:Debug: Session1.4 entering FinishQuerying; SessionState=Querying
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action BackOffice.Controllers.ApiController.GetDeviceListForContract (BackOffice) in 245.8154ms
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action method BackOffice.Controllers.ApiController.GetDeviceListForContract (BackOffice), returned result Microsoft.AspNetCore.Mvc.JsonResult in 263.1115ms.
ServerSession:Debug: Session1.1 returning to Pool1
Microsoft.AspNetCore.Mvc.Formatters.Json.Internal.JsonResultExecutor:Information: Executing JsonResult, writing value of type '<>f__AnonymousType1`2[[System.Collections.Generic.List`1[[System.Object, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]], System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[System.Int32, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.
ConnectionPool:Debug: Pool1 receiving Session1.1 back
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action BackOffice.Controllers.ApiController.GetDeviceListForContract (BackOffice) in 1509.4531ms
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 1403.9836ms 200 application/json; charset=utf-8
ServerSession:Debug: Session1.4 returning to Pool1
ConnectionPool:Debug: Pool1 receiving Session1.4 back
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 1683.3681ms 200 application/json; charset=utf-8
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request starting HTTP/1.1 GET http://localhost:10836/Customer/  
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Route matched with {action = "Index", controller = "Customer"}. Executing action BackOffice.Controllers.CustomerController.Index (BackOffice)
Microsoft.AspNetCore.Authorization.DefaultAuthorizationService:Information: Authorization was successful.
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executing action method BackOffice.Controllers.CustomerController.Index (BackOffice) - Validation state: Valid
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action method BackOffice.Controllers.CustomerController.Index (BackOffice), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0263ms.
Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor:Information: Executing ViewResult, running view Index.
The program '' has exited with code -1 (0xffffffff).
Microsoft.AspNetCore.Mvc.ViewFeatures.ViewResultExecutor:Information: Executed ViewResult - view Index executed in 5.7508ms.
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action BackOffice.Controllers.CustomerController.Index (BackOffice) in 223.05ms
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 272.4622ms 200 text/html; charset=utf-8
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request starting HTTP/1.1 GET http://localhost:10836/Api/GetCustomerList?_=1528451143686  
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Route matched with {action = "GetCustomerList", controller = "Api"}. Executing action BackOffice.Controllers.ApiController.GetCustomerList (BackOffice)
Microsoft.AspNetCore.Authorization.DefaultAuthorizationService:Information: Authorization was successful.
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executing action method BackOffice.Controllers.ApiController.GetCustomerList (BackOffice) with arguments () - Validation state: Valid
ConnectionPool:Debug: Pool1 waiting for an available session
ConnectionPool:Debug: Pool1 found an existing session; checking it for validity
ServerSession:Debug: Session1.4 ServerVersion=5.6.39.0 doesn't support reset connection; sending change user request
ServerSession:Debug: Session1.4 optimistic reauthentication failed; logging in again
ServerSession:Debug: Session1.4 switching to AuthenticationMethod 'mysql_native_password'
ConnectionPool:Debug: Pool1 returning pooled Session1.4 to caller; LeasedSessionsCount=1
TextCommandExecutor:Debug: Session1.4 ExecuteBehavior Synchronous CommandText: SELECT *************
ServerSession:Debug: Session1.4 entering FinishQuerying; SessionState=Querying
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action method BackOffice.Controllers.ApiController.GetCustomerList (BackOffice), returned result Microsoft.AspNetCore.Mvc.JsonResult in 126.1668ms.
Microsoft.AspNetCore.Mvc.Formatters.Json.Internal.JsonResultExecutor:Information: Executing JsonResult, writing value of type '<>f__AnonymousType1`2[[System.Collections.Generic.List`1[[System.Object, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]], System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[System.Int32, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.
Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action BackOffice.Controllers.ApiController.GetCustomerList (BackOffice) in 199.4792ms
ServerSession:Debug: Session1.4 returning to Pool1
ConnectionPool:Debug: Pool1 receiving Session1.4 back
Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 280.5857ms 200 application/json; charset=utf-8
The program '[692] dotnet.exe: Program Trace' has exited with code 0 (0x0).
The program '[692] dotnet.exe' has exited with code -1 (0xffffffff).

[cschotte]

The MySQL Server version is 5.7.21 (Azure), only the Logger is reporting ServerVersion=5.6.39.0 (if this is a MySQL version number)

[bgrainger]

The MySQL Server version is 5.7.21 (Azure), only the Logger is reporting ServerVersion=5.6.39.0 (if this is a MySQL version number)

This is a known issue with Azure Database for MySQL (due to the proxy that's used): https://social.msdn.microsoft.com/Forums/security/en-US/795cb2be-dce7-4805-b324-a67e83697580/azure-database-for-mysql-reports-incorrect-version?forum=AzureDatabaseforMySQL

[bgrainger]

Just to confirm: the WriteAsync exception did happen during the period of time that log was collected? (Unfortunately, I don't think I see anything relevant yet.)

[bgrainger]

Just got this same error when targeting Azure:

Failed   SideBySide.DataTypes.InsertLargeBlobSync(column: "LongBlob", size: 67108864)
Error Message:
 System.NotSupportedException :  The WriteAsync method cannot be called when another write operation is pending.
Stack Trace:
   at System.Net.Security.SslStreamInternal.WriteAsyncInternal[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStreamInternal.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at MySqlConnector.Protocol.Serialization.StreamByteHandler.WriteBytesAsync(ArraySegment`1 data, IOBehavior ioBehavior) in /home/travis/build/mysql-net/MySqlConnector/src/MySqlConnector/Protocol/Serialization/StreamByteHandler.cs:line 100
--- End of stack trace from previous location where exception was thrown ---
   at MySqlConnector.Utilities.ValueTaskExtensions.ContinueWith[T,TResult](ValueTask`1 valueTask, Func`2 continuation) in /home/travis/build/mysql-net/MySqlConnector/src/MySqlConnector/Utilities/ValueTaskExtensions.cs:line 8
   at MySqlConnector.Core.ServerSession.DisposeAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /home/travis/build/mysql-net/MySqlConnector/src/MySqlConnector/Core/ServerSession.cs:line 204
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, IOBehavior ioBehavior, CancellationToken cancellationToken) in /home/travis/build/mysql-net/MySqlConnector/src/MySqlConnector/Core/ConnectionPool.cs:line 89
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, IOBehavior ioBehavior, CancellationToken cancellationToken) in /home/travis/build/mysql-net/MySqlConnector/src/MySqlConnector/Core/ConnectionPool.cs:line 141
   at MySql.Data.MySqlClient.MySqlConnection.CreateSessionAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in /home/travis/build/mysql-net/MySqlConnector/src/MySqlConnector/MySql.Data.MySqlClient/MySqlConnection.cs:line 399
   at MySql.Data.MySqlClient.MySqlConnection.OpenAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in /home/travis/build/mysql-net/MySqlConnector/src/MySqlConnector/MySql.Data.MySqlClient/MySqlConnection.cs:line 171
   at MySql.Data.MySqlClient.MySqlConnection.Open() in /home/travis/build/mysql-net/MySqlConnector/src/MySqlConnector/MySql.Data.MySqlClient/MySqlConnection.cs:line 157

Since the exception is in GetSessionAsync, it may be related to a previous unit test.

This occurred in the netcoreapp2.0 tests, so it may not strictly be related to netcoreapp2.1.

[cschotte]

Next week I try to create a small test project, so we can easier trigger this event. Now I it looks random.

[cschotte]

https://stackoverflow.com/questions/12611861/sslstream-writeasync-the-beginwrite-method-cannot-be-called-when-another-write

[cschotte]

The following solution is (for now) working for me, needs more testing.

public class Database : IDisposable
    {
        private readonly MySqlConnection db;

        public Database(string connectionString)
        {
            db = new MySqlConnection(connectionString);

            db.OpenAsync().GetAwaiter().GetResult();
        }

        public void Dispose()
        {
            db.Close();
        } 

[bgrainger]

Were you previously calling OpenAsync() without awaiting it? What was your previous code?