Marten TimeOut first write using IDocumentSession

Question

I have an app Service in Azure running in Linux that uses Marten in an Azure Database for PostgreSQL.

I have a Release Pipeline that deploys directly to the production slot and every time that it is deployed a new version I have the same issue.

If I try to query data from DB using IQuerySession first request is a bit slow, but it gets data OK and subsequent queries are faster.

But if I try to write data to DB, in this case we are using IDocumentSession, then we have this Exception after 4 minutes waiting response.

 ---> System.IO.IOException: Unable to write data to the transport connection: Connection reset by peer.
 ---> System.Net.Sockets.SocketException (104): Connection reset by peer
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.CreateException(SocketError error, Boolean forAsyncThrow)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.SendAsyncForNetworkStream(Socket socket, CancellationToken cancellationToken)
   at System.Net.Sockets.NetworkStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at System.Net.Security.SslStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at Npgsql.NpgsqlWriteBuffer.Flush(Boolean async, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at Npgsql.NpgsqlWriteBuffer.Flush(Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlConnector.Flush(Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlConnector.Open(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult()
   at Npgsql.NpgsqlConnector.RawOpen(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult()
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
   at System.Net.Security.SslStream.ReceiveBlobAsync[TIOAdapter](TIOAdapter adapter)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Runtime.CompilerServices.AsyncValueTaskMethodBuilder`1.SetResult(TResult result)
   at System.Net.Security.SslStream.<FillHandshakeBufferAsync>g__InternalFillHandshakeBufferAsync|187_0[TIOAdapter](TIOAdapter adap, ValueTask`1 task, Int32 minSize)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.InvokeContinuation(Action`1 continuation, Object state, Boolean forceAsync, Boolean requiresExecutionContextFlow)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.OnCompleted(SocketAsyncEventArgs _)
   at System.Net.Sockets.SocketAsyncEngine.System.Threading.IThreadPoolWorkItem.Execute()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
   at System.Threading.Thread.StartCallback()
--- End of stack trace from previous location ---

   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.<WriteSingleChunk>g__CompleteWriteAsync|180_1[TIOAdapter](ValueTask writeTask, Byte[] bufferToReturn)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at Npgsql.NpgsqlWriteBuffer.Flush(Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlWriteBuffer.Flush(Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlConnector.Open(NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at Npgsql.ConnectorPool.OpenNewConnector(NpgsqlConnection conn, NpgsqlTimeout timeout, Boolean async, CancellationToken cancellationToken)
   at Npgsql.ConnectorPool.<>c__DisplayClass38_0.<<Rent>g__RentAsync|0>d.MoveNext()
--- End of stack trace from previous location ---
   at Npgsql.NpgsqlConnection.<>c__DisplayClass41_0.<<Open>g__OpenAsync|0>d.MoveNext()
--- End of stack trace from previous location ---
   at Marten.Storage.Tenant.executeMigration(ISchemaObject[] schemaObjects, CancellationToken token)
   at Marten.Storage.Tenant.generateOrUpdateFeature(Type featureType, IFeatureSchema feature, CancellationToken token)
   at Marten.Storage.Tenant.ensureStorageExists(IList`1 types, Type featureType, CancellationToken token)
   at Marten.Storage.Tenant.EnsureStorageExists(Type featureType)
   at Marten.Events.Aggregation.AggregateProjection`1.Build(DocumentStore store)
   at Marten.Events.Projections.ProjectionOptions.<>c__DisplayClass11_0.<BuildInlineProjections>b__1(ProjectionSource x)
   at System.Linq.Enumerable.SelectArrayIterator`2.ToArray()
   at Marten.Events.Projections.ProjectionOptions.BuildInlineProjections(DocumentStore store)
   at Marten.Events.EventGraph.<>c__DisplayClass14_0.<.ctor>b__2()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
--- End of stack trace from previous location ---
   at System.Lazy`1.CreateValue()
   at Marten.Events.EventGraph.ProcessEventsAsync(DocumentSessionBase session, CancellationToken token)
   at Marten.Internal.Sessions.DocumentSessionBase.SaveChangesAsync(CancellationToken token)
   at Enel.TaskTracker.BuildingBlocks.Infrastructure.AggregateStore.MartenAggregateRepository`1.Store(T aggregate, CancellationToken cancellationToken) in /home/vsts/work/1/s/src/BuildingBlocks/Enel.TaskTracker.BuildingBlocks.Infrastructure/AggregateStore/MartenAggregateRepository.cs:line 35
   at Enel.TaskTracker.Administracion.Proveedores.Api.Proveedores.EditarProveedor.EditarProveedorCommandHandler.Handle(EditarProveedorCommand command, CancellationToken cancellationToken) in /home/vsts/work/1/s/src/Administracion/Proveedores/Api/Proveedores/EditarProveedor/EditarProveedorCommandHandler.cs:line 66
   at MediatR.Pipeline.RequestExceptionProcessorBehavior`2.Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate`1 next)
   at MediatR.Pipeline.RequestExceptionProcessorBehavior`2.Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate`1 next)
   at MediatR.Pipeline.RequestExceptionActionProcessorBehavior`2.Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate`1 next)
   at MediatR.Pipeline.RequestExceptionActionProcessorBehavior`2.Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate`1 next)
   at MediatR.Pipeline.RequestPostProcessorBehavior`2.Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate`1 next)
   at MediatR.Pipeline.RequestPreProcessorBehavior`2.Handle(TRequest request, CancellationToken cancellationToken, RequestHandlerDelegate`1 next)
   at Enel.TaskTracker.Administracion.Proveedores.Api.Proveedores.EditarProveedor.EditarProveedor.Handle(EditarProveedorRequest request, IMediator mediator) in /home/vsts/work/1/s/src/Administracion/Proveedores/Api/Proveedores/EditarProveedor/EditarProveedor.cs:line 10
   at Microsoft.AspNetCore.Http.RequestDelegateFactory.ExecuteTaskResult[T](Task`1 task, HttpContext httpContext)
   at Microsoft.AspNetCore.Http.RequestDelegateFactory.<>c__DisplayClass46_3.<<HandleRequestBodyAndCompileRequestDelegate>b__2>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
   at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
   at Hellang.Middleware.ProblemDetails.ProblemDetailsMiddleware.Invoke(HttpContext context) ```

If we retry this same request, after no less than 3 minutes, we have our write done. Subsequent requests works as expected, in a reasonable amount of time

What can I see in Azure Database for PostgreSQL logs is this:

``` 2022-03-09 14:14:20 UTC-6228b468.b38c-LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.

    
2022-03-09 14:14:20 UTC-6228b409.b338-LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.

    
2022-03-09 14:14:20 UTC-6228b404.b330-LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.

    
2022-03-09 14:14:37 UTC-6228b64d.b490-LOG:  connection received: host=40.74.8.88 port=26306 pid=46224
2022-03-09 14:14:37 UTC-6228b64d.b490-LOG:  connection authorized: user=postgresdatabase=tasktracker SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, compression=off)
2022-03-09 14:14:42 UTC-6228b652.b4e4-LOG:  connection received: host=40.74.8.88 port=1025 pid=46308
2022-03-09 14:14:42 UTC-6228b652.b4e4-LOG:  connection authorized: user=postgresdatabase=tasktracker SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, compression=off)
2022-03-09 14:15:42 UTC-6228b68e.b4e8-LOG:  connection received: host=40.74.8.88 port=28545 pid=46312
2022-03-09 14:15:42 UTC-6228b68e.b4e8-LOG:  connection authorized: user=postgresdatabase=tasktracker SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, compression=off)
2022-03-09 14:15:45 UTC-6228b691.b540-LOG:  connection received: host=40.74.8.88 port=15297 pid=46400
2022-03-09 14:15:46 UTC-6228b691.b540-LOG:  connection authorized: user=postgresdatabase=tasktracker SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, compression=off)
2022-03-09 14:18:07 UTC-6228b71f.b544-LOG:  connection received: host=127.0.0.1 port=38706 pid=46404
2022-03-09 14:18:07 UTC-6228b71f.b544-LOG:  connection authorized: user=azure_superuserdatabase=postgres SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, compression=off)
2022-03-09 14:18:08 UTC-6228b720.b594-LOG:  connection received: host=127.0.0.1 port=38714 pid=46484
2022-03-09 14:18:08 UTC-6228b720.b594-LOG:  connection authorized: user=azure_superuserdatabase=azure_sys SSL enabled (protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, compression=off)
2022-03-09 14:19:17 UTC-62262d77.98-LOG:  checkpoint starting: time
2022-03-09 14:19:19 UTC-62262d77.98-LOG:  checkpoint complete (152): wrote 15 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=1.688 s, sync=0.016 s, total=2.188 s; sync files=10, longest=0.007 s, average=0.003 s; distance=67 kB, estimate=14343 kB

I have tried different parameters in connection string, now we have something like this:

"ConnectionString": "Server=***;Database='***';Port=5432;User Id=***;Password='***';Ssl Mode=Require;Trust Server Certificate=true;KeepAlive = 300;Pooling=false;Timeout=300;CommandTimeout=300",

I have tried with and without Pooling, and I have played with different configurations, but this behaviour is ocurring every time a new release is deployed.

What else can I do?