After the upgrade to 5.2, I’ve noticed two issues:
PUT requests are not logged in CsvRequestLogger anymore. I do have several ExcludeRequestDtoTypes specified, but this particular request I watch for is not one of them.
This exception occurred that caused the PUT to 500:
System.Text.DecoderFallbackException
Unable to translate bytes [8B] at index 0 from specified code page to Unicode.
at System.Text.DecoderExceptionFallbackBuffer.Throw(Byte bytesUnknown, Int32 index)
at System.Text.DecoderExceptionFallbackBuffer.Fallback(Byte bytesUnknown, Int32 index)
at System.Text.DecoderFallbackBuffer.InternalFallback(Byte bytes, Byte* pBytes)
at System.Text.UTF8Encoding.GetCharCount(Byte* bytes, Int32 count, DecoderNLS baseDecoder)
at System.String.CreateStringFromEncoding(Byte* bytes, Int32 byteLength, Encoding encoding)
at System.Text.UTF8Encoding.GetString(Byte bytes, Int32 index, Int32 count)
at ServiceStack.StreamExtensions.ReadToEnd(MemoryStream ms, Encoding encoding)
at ServiceStack.Host.AspNet.AspNetRequest.GetRawBody()
at ServiceStack.Host.InMemoryRollingRequestLogger.CreateEntry(IRequest request, Object requestDto, Object response, TimeSpan requestDuration, Type requestType)
at ServiceStack.CsvRequestLogger.Log(IRequest request, Object requestDto, Object response, TimeSpan requestDuration)
at ServiceStack.HttpExtensions.EndHttpHandlerRequest(IResponse httpRes, Boolean skipHeaders, Boolean skipClose, Action`1 afterHeaders)
at MyAPI.AppHost.<b__1_8>d.MoveNext() in AppHost.cs:line 148
— End of stack trace from previous location where exception was thrown —
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at ServiceStack.ServiceStackHost.d__322.MoveNext()
— End of stack trace from previous location where exception was thrown —
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at ServiceStack.ServiceStackHost.d__321.MoveNext()
— End of stack trace from previous location where exception was thrown —
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at ServiceStack.Host.RestHandler.d__14.MoveNext()
The PUT request went through after a third try. I looked at my code and couldn’t find anything wrong. Any idea what happened here? It seems like a new logging bug, especially since PUT requests don’t show up anymore.
I may have gotten this exception because of this setting:
JsConfig.UTF8Encoding = new UTF8Encoding(false, true);
The exception occurred when trying to read the Request Body which sounds like it is because of your custom UTF8Encoding where the 2nd parameter tells it to throwOnInvalidBytes.
I’m assuming it works without overriding the default JsConfig.UTF8Encoding right?
Hi @mythz, my thoughts exactly, but it doesn’t make sense since the same request sent a third time ended up working. If there was an invalid character, I’d think it would error all the time.
This appears to be an intermittent bug that happens rarely (only happened twice within a short period between requests), so it’s not really easy to test that.
Also doesn’t explain why the request doesn’t even get logged, may be related. Even the successful ones using the same DTO aren’t logging like they were before.
I’m assuming it’s due to enabling MemoryStream pooling in .NET v4.5 which uses an optimized ReadStream function that’s now making use of the global JsConfig.UTF8Encoding setting, where as previously it didn’t.
Note that none of these returned HTTP 500.
My guess is that SS code is suppressing the invalid bytes exception, which results in the request not being logged. SS code is apparently trying to process bad UTF8 bytes.
However, it’s interesting how the exception in my first post managed to bubble out and 500 that particular request.
So it’s always logged when not overriding JsConfig.UTF8Encoding? and that trying to read a compressed request body with an overridden UTF8Encoding is causing the Exception?
Isn’t that what I said? The compressed stream can’t be read when the JsConfig.UTF8Encoding is configured to throw on invalid bytes. The solution is then to not override UTF8Encoding as there’s nothing ServiceStack can do here except ignore the global setting.
Ok, I think I understand what is happening here.
The logger logs both compressed request and decompressed request as a string.
Compressed request logging worked in 5.1 because it was using your UTF8 encoding that wasn’t configured to throw an exception.
5.2 switched that to use my encoding, which is why the exception is being thrown now.
When sending compressed requests, RequestBody in the log is all the compressed bytes and looks like this: https://i.imgur.com/6QnF6GU.png
When sending a request without compression, RequestBody is raw JSON.
I always found it odd that it was logging the compressed body, so maybe that’s the real bug here?
RequestDto is correctly logged for both compressed/not compressed requests.
Yeah wasn’t uncompressing Buffered Requests for Hosts that don’t automatically decompress request streams which should be resolved from this commit which is available from v5.2.1 that’s now available on MyGet.
BTW you can force this Exception to be thrown in StrictMode:
SetConfig(new HostConfig { StrictMode = true })
What AppHost are you using? i.e. HttpListener or .NET Core?
I assume it would as the test suggests, have you tried it?
It is enabled by default on Debug and disabled on Release as it would cause runtime Exceptions to existing systems when there weren’t any. E.g. in this case an Exception with the Request Logger shouldn’t break requests. This commit made it so the Exception is rethrown instead of swallowed and logged. See logging for how to enable Debug Logging.
But are you using self-hosting HttpListener or ASP.NET? i.e. what’s your AppHost base class called?
I couldn’t reproduce that error. I could only reproduce the issue where the logging was silently failing. Since that error was logging related too, I imagine it’s fixed, but I’ll let you know if it happens again. It’s still unclear to me how that particular exception bubbled up in that one request.
@mythz I did a final review and I just wanted to confirm one thing.
For the stack trace in the first post, you can see that it happened in AspNetRequest.GetRawBody() and then into StreamExtensions.ReadToEnd. The changes you made have to do with BufferedStream and ReadBufferedStreamToEnd, which is what was apparently silently crashing the logging, but is not what 500’d my one request.
I have a suspicion that the error in the first post was caused by a rare case of the BufferedStream being null, and therefore went down to return InputStream.ReadToEnd() to complete the method instead, which somehow bubbled up and crashed.
Does that still need to be fixed? I’m not sure how your BufferedStream stuff works, but it seems possible that the reason for the error in the first post may have been a rare case of BufferedStream being null.
