Skip to content

H/2 stress many failure in content posting methods  #55261

Closed
#58442
Closed
H/2 stress many failure in content posting methods #55261
#58442
Assignees
ManickaP
Labels
area-System.Net.Httpdisabled-testThe test is disabled in source code against the issuein-prThere is an active PR which will close this issue when it is merged
Milestone
6.0.0

Description

@ManickaP
ManickaP
opened on Jul 7, 2021

Reproduces in and out of Docker. Started happening between 6.0 Preview 4 and 6.0 Preview 6 (on 4 it ran, on 6 started failing) - tested locally.
Error:

System.Exception: Expected status code OK, got InternalServerError
   at HttpStress.ClientOperations.ValidateStatusCode(HttpResponseMessage m, HttpStatusCode expectedStatus) in /home/manicka/repositories/runtime/src/libraries/System.Net.Http/tests/StressTests/HttpStress/ClientOperations.cs:line 487
   at HttpStress.ClientOperations.<>c.<<get_Operations>b__1_12>d.MoveNext() in /home/manicka/repositories/runtime/src/libraries/System.Net.Http/tests/StressTests/HttpStress/ClientOperations.cs:line 451
--- End of stack trace from previous location ---
   at HttpStress.StressClient.<>c__DisplayClass17_0.<<StartCore>g__RunWorker|0>d.MoveNext() in /home/manicka/repositories/runtime/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressClient.cs:line 204

Potentially kestrel error, cc: @JamesNK @Tratcher @halter73

Discovered in #55098

Activity

  1. ghost added
    area-System.Net.Http
    on Jul 7, 2021
  2. ghost added
    untriagedNew issue has not been triaged by the area owner
    on Jul 7, 2021

  4. ManickaP commented on Jul 7, 2021

    @ManickaP
    ManickaP
    on Jul 7, 2021
    MemberAuthor

    Some more digging:
    kestrel log:

    [15:25:43 ERR] Connection id "0HMA19AMUPRVO", Request id "0HMA19AMUPRVO:00003227": An unhandled exception was thrown by the application.
System.IO.IOException: The client reset the request stream.
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestPipeReader.ReadAsync(CancellationToken cancellationToken) in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000db2+0x7
   at System.IO.Pipelines.PipeReader.CopyToAsyncCore[TStream](TStream destination, Func`4 writeAsync, CancellationToken cancellationToken) in System.IO.Pipelines.dll:token 0x60000b8+0x236
   at HttpStress.StressServer.<>c.<<MapRoutes>b__6_6>d.MoveNext() in /home/manicka/repositories/runtime/src/libraries/System.Net.Http/tests/StressTests/HttpStress/StressServer.cs:line 254
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger) in Microsoft.AspNetCore.Routing.dll:token 0x60000ab+0xa9
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application) in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000d28+0x54c

    Happens with slow content sending operation much more:
    NO cancellation:

    [7/7/2021 3:32:53 PM] Total: 7,076 Runtime: 00:00:06
	 0: GET                       Success: 469	Canceled: 0	Fail: 0
	 1: GET Partial               Success: 470	Canceled: 0	Fail: 0
	 2: GET Headers               Success: 471	Canceled: 0	Fail: 0
	 3: GET Parameters            Success: 472	Canceled: 0	Fail: 0
	 4: GET Aborted               Success: 472	Canceled: 0	Fail: 0
	 5: POST                      Success: 456	Canceled: 0	Fail: 16
	 6: POST Multipart Data       Success: 452	Canceled: 0	Fail: 21
	 7: POST Duplex               Success: 465	Canceled: 0	Fail: 9
	 8: POST Duplex Slow          Success: 459	Canceled: 2	Fail: 13
	 9: POST Duplex Dispose       Success: 456	Canceled: 0	Fail: 16
	10: POST ExpectContinue       Success: 458	Canceled: 0	Fail: 14
	11: HEAD                      Success: 472	Canceled: 0	Fail: 0
	12: PUT                       Success: 450	Canceled: 0	Fail: 22
	13: PUT Slow                  Success: 453	Canceled: 3	Fail: 16
	14: GET Slow                  Success: 468	Canceled: 1	Fail: 0
	    TOTAL                     Success: 6,943	Canceled: 6	Fail: 127

    Cancellation:

    [7/7/2021 3:32:18 PM] Total: 6,540 Runtime: 00:00:06
	 0: GET                       Success: 407	Canceled: 27	Fail: 0
	 1: GET Partial               Success: 403	Canceled: 32	Fail: 0
	 2: GET Headers               Success: 398	Canceled: 38	Fail: 0
	 3: GET Parameters            Success: 406	Canceled: 30	Fail: 0
	 4: GET Aborted               Success: 404	Canceled: 32	Fail: 0
	 5: POST                      Success: 409	Canceled: 20	Fail: 8
	 6: POST Multipart Data       Success: 413	Canceled: 20	Fail: 5
	 7: POST Duplex               Success: 397	Canceled: 33	Fail: 8
	 8: POST Duplex Slow          Success: 405	Canceled: 28	Fail: 5
	 9: POST Duplex Dispose       Success: 403	Canceled: 28	Fail: 5
	10: POST ExpectContinue       Success: 391	Canceled: 37	Fail: 8
	11: HEAD                      Success: 412	Canceled: 24	Fail: 0
	12: PUT                       Success: 404	Canceled: 25	Fail: 7
	13: PUT Slow                  Success: 402	Canceled: 29	Fail: 3
	14: GET Slow                  Success: 405	Canceled: 29	Fail: 0
	    TOTAL                     Success: 6,059	Canceled: 432	Fail: 49
  5. ManickaP
    added
    disabled-testThe test is disabled in source code against the issue
    on Jul 8, 2021

  6. karelz commented on Jul 13, 2021

    @karelz
    karelz
    on Jul 13, 2021
    Member

    @JamesNK @Tratcher @halter73 is it something you could help us with please? It seems like Kestrel regression and it blocks our stress runs :(
    Should we create issue in aspnet repo?

  7. halter73 commented on Jul 13, 2021

    @halter73
    halter73
    on Jul 13, 2021
    Member

    System.IO.IOException: The client reset the request stream.

    @karelz What makes this seem like a Kestrel regression? The above exception is only thrown if Kestrel received a RST_STREAM frame from the client.

    System.Exception: Expected status code OK, got InternalServerError

    I'm assuming this means the client received a 500 response. This could be caused by an uncaught exception on the server, but not an exception caused by RST_STREAM since that closes the stream.

    Can you collect more verbose server logs and/or collect a network trace?

  8. karelz
    added this to the 6.0.0 milestone on Jul 15, 2021
  9. karelz
    removed
    untriagedNew issue has not been triaged by the area owner
    on Jul 15, 2021
  10. alnikola
    self-assigned this
    on Jul 21, 2021

  11. alnikola commented on Jul 21, 2021

    @alnikola
    alnikola
    on Jul 21, 2021
    Contributor

    Client logs show that these HTTP/2 POST tests are failing only on Windows and only with timeout in one of the following 2 places:

    1. Http2Stream.WaitForDataAsync
    2. Http2Stream.WaitFor100ContinueAsync

    The timeout exception message is

    System.Threading.Tasks.TaskCanceledException: The request was canceled due to the configured HttpClient.Timeout of 60 seconds elapsing.

  12. alnikola commented on Jul 21, 2021

    @alnikola
    alnikola
    on Jul 21, 2021
    Contributor

    My first guess would be that the server hasn't responded in the given time.

  13. alnikola commented on Jul 23, 2021

    @alnikola
    alnikola
    on Jul 23, 2021
    Contributor

    My comment above might not be related to this issue because here the server responds with 500 to client whereas I observed timeouts. I'll continue the investigation.

  14. alnikola commented on Jul 26, 2021

    @alnikola
    alnikola
    on Jul 26, 2021
    Contributor

    It seems the issue is caused by the client sending EndOfStream without sending a RST_STREAM first when it has set the Content-Length and the server is still reading the request body when EndOfStream arrives. It's a protocol violation so the server throws the following exception and responds with 500.

    [DBG] Connection id "0HMAGA52UA8E0": HTTP/2 stream error.
Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2StreamErrorException: HTTP/2 stream ID 695 error (PROTOCOL_ERROR): Less data received than specified in the Content-Length header.
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Stream.OnEndStreamReceived() in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000da7+0x39
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Stream.OnDataAsync(Http2Frame dataFrame, ReadOnlySequence`1& payload) in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000da6+0x141
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessDataFrameAsync(ReadOnlySequence`1& payload) in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000cff+0x12b
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessFrameAsync[TContext](IHttpApplication`1 application, ReadOnlySequence`1& payload) in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000cfe+0xc0
   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2.Http2Connection.ProcessRequestsAsync[TContext](IHttpApplication`1 application) in Microsoft.AspNetCore.Server.Kestrel.Core.dll:token 0x6000cfa+0x9df

  15. alnikola commented on Jul 26, 2021

    @alnikola
    alnikola
    on Jul 26, 2021
    Contributor

    It might indicate there is a bug with how Http2Stream sends EndOfStream in SendRequestBodyAsync.

  16. 21 remaining items

  17. alnikola
    added a commit that references this issue on Aug 25, 2021

    [Stress] Enable POST by disabling InternalServerError suppression

    cda0b74
  18. ghost added
    in-prThere is an active PR which will close this issue when it is merged
    on Aug 25, 2021
  19. ghost removed
    in-prThere is an active PR which will close this issue when it is merged
    on Aug 27, 2021
  20. ghost added
    in-prThere is an active PR which will close this issue when it is merged
    on Aug 31, 2021
  21. ManickaP
    closed this as completedin #58442on Aug 31, 2021
  22. ghost removed
    in-prThere is an active PR which will close this issue when it is merged
    on Aug 31, 2021

  23. karelz commented on Sep 1, 2021

    @karelz
    karelz
    on Sep 1, 2021
    Member

    Reopening to track backport to 6.0.

  24. karelz
    reopened this on Sep 1, 2021
  25. karelz
    modified the milestones: 7.0.0, 6.0.0 on Sep 1, 2021
  26. ghost added
    in-prThere is an active PR which will close this issue when it is merged
    on Sep 2, 2021
  27. karelz
    assigned
    ManickaP
    on Sep 2, 2021

  28. karelz commented on Sep 9, 2021

    @karelz
    karelz
    on Sep 9, 2021
    Member

    Fixed in 6.0 RC2 in PR #58541.
    Fixed in 7.0 in PR #58442.

  29. karelz
    closed this as completedon Sep 9, 2021
  30. ghost locked as resolved and limited conversation to collaborators on Oct 9, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

area-System.Net.Httpdisabled-testThe test is disabled in source code against the issuein-prThere is an active PR which will close this issue when it is merged

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions