"InvalidOperationException: End of body before form was fully parsed" on Linux on OpenIdConnect POST callback

[LaurensAdema]

While updating to nightly builds I found that the POST callback on OpenIdConnect (to Azure) does not work on Linux, while it does on Windows. I can confirm it worked on preview 7 on Linux. I don't have confirmation on preview 8 but it is definitely broken on 3.0.0-preview9-19419-03. I have tried both Framework-Dependent as Self-Contained on linux-x64.

The exception:

System.Exception: An error was encountered while handling the remote login.
 ---> System.InvalidOperationException: End of body before form was fully parsed.
   at Microsoft.AspNetCore.WebUtilities.FormPipeReader.ReadFormAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Http.Features.FormFeature.InnerReadFormAsync(CancellationToken cancellationToken)
   at Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler.HandleRemoteAuthenticateAsync()
   at Microsoft.AspNetCore.Authentication.RemoteAuthenticationHandler`1.HandleRequestAsync()
   --- End of inner exception stack trace ---
   at Microsoft.AspNetCore.Authentication.RemoteAuthenticationHandler`1.HandleRequestAsync()
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Localization.RequestLocalizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)

Broken 3.0.0-preview9-19419-03 Linux Webserver log (on Linux Azure App Service)

2019-08-23T11:30:04.579919328Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Hosting.Diagnostics[1]
2019-08-23T11:30:04.579955828Z       Request starting HTTP/1.1 GET http://<URL>/
2019-08-23T11:30:04.591865577Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
2019-08-23T11:30:04.592863281Z       Route matched with {action = "Index", controller = "Home", area = "", page = ""}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] Index(System.Nullable`1[System.Guid], System.Threading.CancellationToken) on controller <CONTROLLER> (<APPLICATION>).
2019-08-23T11:30:04.597492899Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[2]
2019-08-23T11:30:04.597538299Z       Authorization failed.
2019-08-23T11:30:04.598950305Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
2019-08-23T11:30:04.598966405Z       Authorization failed for the request at filter 'Microsoft.AspNetCore.Mvc.Authorization.AuthorizeFilter'.
2019-08-23T11:30:04.600335111Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Mvc.ChallengeResult[1]
2019-08-23T11:30:04.600351711Z       Executing ChallengeResult with authentication schemes ().
2019-08-23T11:30:04.603109022Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler[12]
2019-08-23T11:30:04.603126622Z       AuthenticationScheme: AzureADOpenID was challenged.
2019-08-23T11:30:04.604531128Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
2019-08-23T11:30:04.604546928Z       Executed action <APPLICATION>.HomeController.Index (<APPLICATION>) in 9.3335ms
2019-08-23T11:30:04.648410305Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Hosting.Diagnostics[2]
2019-08-23T11:30:04.648439505Z       Request finished in 68.8234ms 302
2019-08-23T11:30:05.765627726Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Hosting.Diagnostics[1]
2019-08-23T11:30:05.765667026Z       Request starting HTTP/1.1 POST http://<URL>/signin-oidc application/x-www-form-urlencoded 2843
2019-08-23T11:30:05.767299633Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler[4]
2019-08-23T11:30:05.767316533Z       Error from RemoteAuthentication: End of body before form was fully parsed..

Working 3.0.0-preview7 Linux Webserver log (on Linux Azure App Service)

2019-08-23T11:26:42.059969048Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Hosting.Diagnostics[1]
2019-08-23T11:26:42.060014648Z       Request starting HTTP/1.1 GET http://<URL>/
2019-08-23T11:26:42.070989681Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
2019-08-23T11:26:42.071921784Z       Route matched with {action = "Index", controller = "Home", area = "", page = ""}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] Index(System.Nullable`1[System.Guid], System.Threading.CancellationToken) on controller <APPLICATION>.Controllers.HomeController (<APPLICATION>).
2019-08-23T11:26:42.076781098Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[2]
2019-08-23T11:26:42.076798898Z       Authorization failed.
2019-08-23T11:26:42.078008102Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
2019-08-23T11:26:42.078024302Z       Authorization failed for the request at filter 'Microsoft.AspNetCore.Mvc.Authorization.AuthorizeFilter'.
2019-08-23T11:26:42.079306606Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Mvc.ChallengeResult[1]
2019-08-23T11:26:42.079321806Z       Executing ChallengeResult with authentication schemes ().
2019-08-23T11:26:42.086277027Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler[12]
2019-08-23T11:26:42.086295427Z       AuthenticationScheme: AzureADOpenID was challenged.
2019-08-23T11:26:42.087936931Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
2019-08-23T11:26:42.087953031Z       Executed action <APPLICATION>.Controllers.HomeController.Index (<APPLICATION>) in 15.596300000000001ms
2019-08-23T11:26:42.095005852Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Hosting.Diagnostics[2]
2019-08-23T11:26:42.095022752Z       Request finished in 36.2522ms 302
2019-08-23T11:26:42.687498313Z �[40m�[32minfo�[39m�[22m�[49m: Microsoft.AspNetCore.Hosting.Diagnostics[1]
2019-08-23T11:26:42.687541213Z       Request starting HTTP/1.1 POST http://<URL>/signin-oidc application/x-www-form-urlencoded 2843
2019-08-23T11:26:42.696907941Z �[40m�[32minfo�[39m�[22m�[49m: System.Net.Http.HttpClient.<CONTROLLER>, <APPLICATION>, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.LogicalHandler[100]
2019-08-23T11:26:42.697466942Z       Start processing HTTP request POST https://<URL>/configuration/isvalidissuer

Working 3.0.0-preview9-19419-03 Windows Webserver log (on Windows localhost, Windows App Service logs are more difficult to obtain)

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 GET https://localhost:44333/
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {action = "Index", controller = "Home", area = "", page = ""}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] Index(System.Nullable`1[System.Guid], System.Threading.CancellationToken) on controller <APPLICATION>.Controllers.HomeController (<APPLICATION>).
info: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[2]
      Authorization failed.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Authorization failed for the request at filter 'Microsoft.AspNetCore.Mvc.Authorization.AuthorizeFilter'.
info: Microsoft.AspNetCore.Mvc.ChallengeResult[1]
      Executing ChallengeResult with authentication schemes ().
info: Microsoft.AspNetCore.Authentication.OpenIdConnect.OpenIdConnectHandler[12]
      AuthenticationScheme: AzureADOpenID was challenged.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action <APPLICATION>.Controllers.HomeController.Index (<APPLICATION>) in 18.822ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 35.4657ms 302
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/2 POST https://localhost:44333/signin-oidc application/x-www-form-urlencoded 2843
info: System.Net.Http.HttpClient.<CONTROLLER>, <APPLICATION>, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.LogicalHandler[100]
      Start processing HTTP request POST https://localhost:5001/v4/configuration/isvalidissuer

[Tratcher]

Your second and third log are cut off before the /sigin-oidc request finishes. Is there more to those log?

Can you capture a client side wireshark trace for the successes and failures? How about a Fiddler trace?

Side question: Why do you have two SessionMiddleware in the pipeline?

[Tratcher]

FYI there was a fix to the parser in preview9:
#12749
You can try decompiling your bits to make sure you have these changes.

[LaurensAdema]

The remainder of the request isn't really relevant to the scope of the issue since the request cuts out before processing the request. This is why I cut off the log after the first sign of processing. The two working ones both end in:

 info: Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler[10]
      AuthenticationScheme: AzureADCookie signed in.

Regarding Fiddler/Wireshark, I have included the (redacted) working and not working requests. I omitted them because I didn't see any differences but maybe I'm missing something. Also the initial requests are both responded to with a 302 to https://login.microsoftonline.com/organizations/oauth2/v2.0/authorize? etc. both with the Set-Cookies for OpenIdConnect and Correlation. These requests result in the following POST requests.

Broken Linux

POST https://<REDACTED>/signin-oidc HTTP/1.1
Host: <REDACTED>
Connection: keep-alive
Content-Length: 2843
Cache-Control: max-age=0
Origin: https://login.microsoftonline.com
Upgrade-Insecure-Requests: 1
Content-Type: application/x-www-form-urlencoded
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36
Sec-Fetch-Mode: navigate
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3
Sec-Fetch-Site: cross-site
Referer: https://login.microsoftonline.com/
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9,nl;q=0.8
Cookie: .AspNetCore.OpenIdConnect.Nonce.<REDACTED>=N; .AspNetCore.Correlation.AzureADOpenID.<REDACTED>=N

code=<REDACTED>&state=<REDACTED>&session_state=<REDACTED>

Working Windows

POST https://<REDACTED>/signin-oidc HTTP/1.1
Host: <REDACTED>
Connection: keep-alive
Content-Length: 2843
Cache-Control: max-age=0
Origin: https://login.microsoftonline.com
Upgrade-Insecure-Requests: 1
Content-Type: application/x-www-form-urlencoded
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.100 Safari/537.36
Sec-Fetch-Mode: navigate
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3
Sec-Fetch-Site: cross-site
Referer: https://login.microsoftonline.com/
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9,nl;q=0.8
Cookie: .AspNetCore.OpenIdConnect.Nonce.<REDACTED>=N; .AspNetCore.Correlation.AzureADOpenID.<REDACTED>=N

code=<REDACTED>&state=<REDACTED>&session_state=<REDACTED>

Regarding the fix; I used the latest build (downloaded today) from this link https://github.com/dotnet/core-sdk/blob/master/README.md#installers-and-binaries so I figure I must have it included since the merge was done quite a long time ago.

Why I have two SessionMiddleware's I actually don't know. As far as I can there are only two mentions of it in the Startup. Once in the app configuration and once in the service configuration. And I also add a Redis cache.

[Tratcher]

I hit the same exception on Windows with WsFederation, master branch. This may be a preview9 regression from #12749, investigating. @Pilchie

[Tratcher]

@LaurensAdema can you give lengths for the redacted values in
code=<REDACTED>&state=<REDACTED>&session_state=<REDACTED>?

I see an issue in the form parser that's sensitive to relative length of values.

[LaurensAdema]

Code is 2478 chars, state is 306 chars and session state is 36 chars

[Tratcher]

@LaurensAdema thanks, that matches my repro case. I've submitted a PR to fix this.

You should be fine if you roll back to preview8, this was only regressed in preview9.

[LaurensAdema]

Okay thanks!