Skip to content

Fail & log requests where ASP.NET model binding failed #22

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Feb 7, 2025

Conversation

bdach
Copy link
Contributor

@bdach bdach commented Feb 7, 2025

With this PR, model binding failures on any controller method will cause the resulting request handling to be immediately terminated with a 400 Bad Request, and the failure details to be logged to stdout and sentry:

fail: osu.Server.BeatmapSubmission.ModelStateValidationFilter[0]
      Failed to validate model state. Errors:
      { field: "versionId", message: "The value '999999999999999999999999999' is not valid.", exception: "" }

1738930780
1738930803

epic rant time

It is rant time!

So I've spent a significant chunk of the last two days trying to figure out why the staging deployment of this service was failing in a completely incomprehensible way. Specifically, the way it was failing was as follows:

For a given beatmap upload, there are two requests. The first assigns the new beatmap IDs by creating a couple of database rows, and the second is supposed to accept a beatmap package, parse it, and populate everything that is required and also notify everything that a new beatmap (or an update thereof) has arrived.

On staging, the first request would succeed no problem, and create the rows (verifiably so, which was checked several times manually via mysql), but the second request would return a 404. The only way it could feasibly return a 404 is if the first request never happened.

The 404 was not caused by anything of the following:

  • Any routing or cloudflare shenanigans; tested by exposing the service directly rather than via CF, and adding HTTP logging to .NET, which confirmed that the request was arriving.
  • Any database shenanigans.
  • Any containerisation shenanigans; locally the docker images as produced by github actions directly did not exhibit this behaviour.

Some ad-hoc logging nailed this down to an apparent ASP.NET model binding failure. "Model binding" refers to the magic glue that is supposed to let you controller actions like plain methods with a bunch of annotations and get all of the data from various sources (route, form, query string, what have you) into nice C# objects for perusal. It turned out that in this particular case the ID of the beatmap in the second request was ZERO, even though the request path (i.e. the place it was supposed to come from) was 100% correct.

Some more ad-hoc logging produced the following absolute stinker:

UploadFullPackageAsync: ModelState errors listed: {message: Failed to read the request form. Read-only file system : '/tmp/', exception: }

At this point I am restraining myself from saying some very unkind words. What is happening here is that file uploads will use /tmp for large enough files:

Any single buffered file exceeding 64 KB is moved from memory to a temp file on disk.

Temporary files for larger requests are written to the location named in the ASPNETCORE_TEMP environment variable. If ASPNETCORE_TEMP is not defined, the files are written to the current user's temporary folder.

(source: https://learn.microsoft.com/en-us/aspnet/core/mvc/models/file-uploads?view=aspnetcore-9.0#file-upload-scenarios)

Secondly, on staging the docker container was deployed with the filesystem set to readonly, as per OWASP recommendations (https://cheatsheetseries.owasp.org/cheatsheets/Docker_Security_Cheat_Sheet.html#rule-8-set-filesystem-and-volumes-to-read-only). Thus:

  • Because ASPNETCORE_TEMP was not explicitly set, ASP.NET internals attempted to buffer the file to /tmp.
  • This failed because /tmp was not writable.
  • This in turn caused model binding to completely, SILENTLY fail, but the controller method WOULD CONTINUE TO EXECUTE AS IF NOTHING HAPPENED.

As per
https://learn.microsoft.com/en-us/aspnet/core/mvc/models/model-binding?view=aspnetcore-9.0#example, it is apparently the consumer's sole responsibility to check that model binding succeeded and inspect any resulting errors:

In the preceding example, the model binding targets are method parameters that are simple types. Targets may also be the properties of a complex type. After each property is successfully bound, model validation occurs for that property. The record of what data is bound to the model, and any binding or validation errors, is stored in ControllerBase.ModelState or PageModel.ModelState. To find out if this process was successful, the app checks the ModelState.IsValid flag.

which is why this commit has to exist to avoid any such further stupidity happening ever again. Hopefully.

It is rant time!

So I've spent a significant chunk of the last two days trying to figure
out why the staging deployment of this service was failing in a
completely incomprehensible way. Specifically, the way it was failing
was as follows:

For a given beatmap upload, there are two requests. The first assigns
the new beatmap IDs by creating a couple of database rows, and the
second is supposed to accept a beatmap package, parse it, and populate
everything that is required and also notify everything that a new
beatmap (or an update thereof) has arrived.

On staging, the first request would succeed no problem, and create the
rows (verifiably so, which was checked several times manually via
mysql), but the second request would return a 404.

The 404 was *not* caused by anything of the following:

- Any routing or cloudflare shenanigans; tested by exposing the service
  directly rather than via CF, and adding HTTP logging to .NET, which
  confirmed that the request was arriving.
- Any database shenanigans.
- Any containerisation shenanigans; locally the docker images as
  produced by github actions directly did not exhibit this behaviour.

Some ad-hoc logging nailed this down to an apparent ASP.NET model
binding failure. "Model binding" refers to the magic glue that is
supposed to let you controller actions like plain methods with a bunch
of annotations and get all of the data from various sources (route,
form, query string, what have you) into nice C# objects for perusal. It
turned out that in this particular case the ID of the beatmap in the
second request was ***ZERO***, even though the request path was 100%
correct.

Some more ad-hoc logging produced the following absolute stinker:

```
UploadFullPackageAsync: ModelState errors listed: {message: Failed to read the request form. Read-only file system : '/tmp/', exception: }
```

At this point I am restraining myself from saying some very unkind
words. What is happening here is that file uploads will use `/tmp` for
large enough files:

> Any single buffered file exceeding 64 KB is moved from memory to a
> temp file on disk.
>
> Temporary files for larger requests are written to the location named
> in the `ASPNETCORE_TEMP` environment variable. If ASPNETCORE_TEMP is
> not defined, the files are written to the current user's temporary
> folder.

(source: https://learn.microsoft.com/en-us/aspnet/core/mvc/models/file-uploads?view=aspnetcore-9.0#file-upload-scenarios)

Secondly, on staging the docker container was deployed with the
filesystem set to readonly, as per OWASP recommendations
(https://cheatsheetseries.owasp.org/cheatsheets/Docker_Security_Cheat_Sheet.html#rule-8-set-filesystem-and-volumes-to-read-only).
Thus:

- Because `ASPNETCORE_TEMP` was not explicitly set, ASP.NET internals
  attempted to buffer the file to `/tmp`.
- This failed because `/tmp` was not writable.
- This in turn caused model binding to completely, ***SILENTLY*** fail.

As per
https://learn.microsoft.com/en-us/aspnet/core/mvc/models/model-binding?view=aspnetcore-9.0#example,
it is apparently the consumer's sole responsibility to check that model
binding succeeded and inspect any resulting errors:

> In the preceding example, the model binding targets are method
> parameters that are simple types. Targets may also be the properties
> of a complex type. After each property is successfully bound, model
> validation occurs for that property. The record of what data is bound
> to the model, and any binding or validation errors, is stored in
> `ControllerBase.ModelState` or `PageModel.ModelState`. To find out if
> this process was successful, the app checks the `ModelState.IsValid`
> flag.

which is why this commit has to exist to avoid any such further
stupidity happening ever again. Hopefully.
@bdach bdach self-assigned this Feb 7, 2025
@peppy peppy merged commit 577dbbb into ppy:master Feb 7, 2025
4 checks passed
@bdach bdach deleted the explicit-model-state-validation branch February 7, 2025 13:50
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants