[PATCH] ntdll: Truncate and ellipsize debug output if it's too long.
Signed-off-by: Esme Povirk <esme(a)codeweavers.com> --- It turns out that, in addition to Mono's debug output being too long sometimes, one can trigger an overrun by passing too many arguments to a managed exe while the +mscoree debug channel is enabled. To guarantee that this won't happen in mscoree, we would either have to limit the number of arguments traced to 2 (since debug output for the filename and each argument could be up to 300 characters, and it needs to fit in a 1020 character buffer) or keep track of the lengths from each call to debugstr_w. I don't think there's any reasonable way for callers to ensure that in general we won't overrun this buffer, and losing some debug output on occasion is much better than crashing. dlls/ntdll/thread.c | 10 +++++----- dlls/ntdll/unix/debug.c | 8 +++++--- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/dlls/ntdll/thread.c b/dlls/ntdll/thread.c index 37dc7c8ab37..17e9cc0bf98 100644 --- a/dlls/ntdll/thread.c +++ b/dlls/ntdll/thread.c @@ -74,11 +74,11 @@ static int append_output( struct debug_info *info, const char *str, size_t len ) { if (len >= sizeof(info->output) - info->out_pos) { - __wine_dbg_write( info->output, info->out_pos ); - info->out_pos = 0; - ERR_(thread)( "debug buffer overflow:\n" ); - __wine_dbg_write( str, len ); - RtlRaiseStatus( STATUS_BUFFER_OVERFLOW ); + len = sizeof(info->output) - info->out_pos; + memcpy( info->output + info->out_pos, str, len ); + memcpy( info->output + sizeof(info->output) - 4, "...\n", 4 ); + info->out_pos = sizeof(info->output); + return len; } memcpy( info->output + info->out_pos, str, len ); info->out_pos += len; diff --git a/dlls/ntdll/unix/debug.c b/dlls/ntdll/unix/debug.c index d43cdaeb917..e435a58aa12 100644 --- a/dlls/ntdll/unix/debug.c +++ b/dlls/ntdll/unix/debug.c @@ -78,9 +78,11 @@ static int append_output( struct debug_info *info, const char *str, size_t len ) { if (len >= sizeof(info->output) - info->out_pos) { - fprintf( stderr, "wine_dbg_output: debugstr buffer overflow (contents: '%s')\n", info->output ); - info->out_pos = 0; - abort(); + len = sizeof(info->output) - info->out_pos; + memcpy( info->output + info->out_pos, str, len ); + memcpy( info->output + sizeof(info->output) - 4, "...\n", 4 ); + info->out_pos = sizeof(info->output); + return len; } memcpy( info->output + info->out_pos, str, len ); info->out_pos += len; -- 2.25.1
Is there anything I can do to help move this along? append_output only interacts with one other function, and this doesn't change the interface to it, so from a correctness perspective, I think this should be easy to verify.
From a design perspective, I don't know if this is right, but I couldn't think of a better approach. Exposing the buffer size to callers seems not ideal to me. Is there an alternative I'm missing?
"Esme Povirk (she/they)" <esme(a)codeweavers.com> writes:
Is there anything I can do to help move this along?
append_output only interacts with one other function, and this doesn't change the interface to it, so from a correctness perspective, I think this should be easy to verify.
It doesn't look quite correct, you'd need to flush the buffer otherwise you'll potentially lose even more output.
From a design perspective, I don't know if this is right, but I couldn't think of a better approach. Exposing the buffer size to callers seems not ideal to me. Is there an alternative I'm missing?
I'd suggest using debugstr_a/w like everywhere else. If you have to print an unbounded number of arguments, you can print them one per line. -- Alexandre Julliard julliard(a)winehq.org
On Fri, Aug 27, 2021 at 2:29 PM Alexandre Julliard <julliard(a)winehq.org> wrote:
It doesn't look quite correct, you'd need to flush the buffer otherwise you'll potentially lose even more output.
The intent was to discard all output past the end of the buffer until the next line starts and __wine_dbg_output flushes it. If the buffer is full, it'll do a 0-size memcpy and overwrite the end. Is that what you mean?
From a design perspective, I don't know if this is right, but I couldn't think of a better approach. Exposing the buffer size to callers seems not ideal to me. Is there an alternative I'm missing?
I'd suggest using debugstr_a/w like everywhere else. If you have to print an unbounded number of arguments, you can print them one per line.
Now that I think about it, I have no idea why I added those traces. Maybe I should just get rid of those. I would still like to figure this out for the occasions when Mono produces really long trace outputs.
If it's OK for append_output to write output and flush the buffer, would it be better to ensure we don't lose any output, at the cost of potentially writing a line non-atomically when it's too long?
"Esme Povirk (she/they)" <esme(a)codeweavers.com> writes:
On Fri, Aug 27, 2021 at 2:29 PM Alexandre Julliard <julliard(a)winehq.org> wrote:
It doesn't look quite correct, you'd need to flush the buffer otherwise you'll potentially lose even more output.
The intent was to discard all output past the end of the buffer until the next line starts and __wine_dbg_output flushes it. If the buffer is full, it'll do a 0-size memcpy and overwrite the end. Is that what you mean?
If the caller sends multiple lines at once these will be discarded too, because of the strrchr('\n'). I'd argue that printing the data in multiple writes is better than discarding, but I still feel that this can be handled in the callers.
From a design perspective, I don't know if this is right, but I couldn't think of a better approach. Exposing the buffer size to callers seems not ideal to me. Is there an alternative I'm missing?
I'd suggest using debugstr_a/w like everywhere else. If you have to print an unbounded number of arguments, you can print them one per line.
Now that I think about it, I have no idea why I added those traces. Maybe I should just get rid of those.
I would still like to figure this out for the occasions when Mono produces really long trace outputs.
The best is to send them through debugstr_a/w, but you can also truncate or wrap them manually as seems appropriate. You don't need to know the exact buffer length, you can use say 600 chars (two debugstr's worth). -- Alexandre Julliard julliard(a)winehq.org
On Tue, Aug 31, 2021 at 5:03 AM Alexandre Julliard <julliard(a)winehq.org> wrote:
I would still like to figure this out for the occasions when Mono produces really long trace outputs.
The best is to send them through debugstr_a/w, but you can also truncate or wrap them manually as seems appropriate. You don't need to know the exact buffer length, you can use say 600 chars (two debugstr's worth).
The trouble is that Mono likes to send debug output in pieces, especially the trace functionality where each argument is a single call to mono_print_handler_fn. To illustrate, I tried modifying it to print just one line with debugstr_a and got call traces like this: 00fc:fixme:mscoree:mono_print_handler_fn "ENTER:c (wrapper managed-to-native) System.IO.MonoIO:Write (intptr,byte[],int,int,System.IO.MonoIOError&)(" 00fc:fixme:mscoree:mono_print_handler_fn "0000000000000014" 00fc:fixme:mscoree:mono_print_handler_fn ", " 00fc:fixme:mscoree:mono_print_handler_fn "[System.Byte[]:[1024]0000000001457a40]" 00fc:fixme:mscoree:mono_print_handler_fn ", " 00fc:fixme:mscoree:mono_print_handler_fn "0" 00fc:fixme:mscoree:mono_print_handler_fn ", " 00fc:fixme:mscoree:mono_print_handler_fn "15" 00fc:fixme:mscoree:mono_print_handler_fn ", " 00fc:fixme:mscoree:mono_print_handler_fn "[BYREF:000000000011f140]" 00fc:fixme:mscoree:mono_print_handler_fn ")\n" We could keep track of the total line length in some sort of TLS, but it feels like it'd be better to do that in the common debug code where we already have a TLS structure than in mscoree. There's also a possibility that the length stored by mscoree will be off if other Wine traces occur in the same thread between these calls (which would, of course, garble the output, so maybe that's an argument for having a string buffer in mscoree, but it doesn't feel very clean to me as we'd have to hard-code the maximum length). On the Mono side, that line is printed by a single method, mono_trace_enter_method (https://github.com/madewokherd/mono/blob/develop/mono/mini/trace.c#L147), but I'd rather not modify Mono code any more than I have to because it makes merges more difficult, and it's not obvious to me how to improve it anyway. At the moment, Mono doesn't have access to debugstr_a, but I guess I could throw in another copy of debug.c. I've had one case where a single method name and its argument types was enough to overflow the buffer on its own.
"Esme Povirk (she/they)" <esme(a)codeweavers.com> writes:
On Tue, Aug 31, 2021 at 5:03 AM Alexandre Julliard <julliard(a)winehq.org> wrote:
I would still like to figure this out for the occasions when Mono produces really long trace outputs.
The best is to send them through debugstr_a/w, but you can also truncate or wrap them manually as seems appropriate. You don't need to know the exact buffer length, you can use say 600 chars (two debugstr's worth).
The trouble is that Mono likes to send debug output in pieces, especially the trace functionality where each argument is a single call to mono_print_handler_fn. To illustrate, I tried modifying it to print just one line with debugstr_a and got call traces like this:
00fc:fixme:mscoree:mono_print_handler_fn "ENTER:c (wrapper managed-to-native) System.IO.MonoIO:Write (intptr,byte[],int,int,System.IO.MonoIOError&)(" 00fc:fixme:mscoree:mono_print_handler_fn "0000000000000014" 00fc:fixme:mscoree:mono_print_handler_fn ", " 00fc:fixme:mscoree:mono_print_handler_fn "[System.Byte[]:[1024]0000000001457a40]" 00fc:fixme:mscoree:mono_print_handler_fn ", " 00fc:fixme:mscoree:mono_print_handler_fn "0" 00fc:fixme:mscoree:mono_print_handler_fn ", " 00fc:fixme:mscoree:mono_print_handler_fn "15" 00fc:fixme:mscoree:mono_print_handler_fn ", " 00fc:fixme:mscoree:mono_print_handler_fn "[BYREF:000000000011f140]" 00fc:fixme:mscoree:mono_print_handler_fn ")\n"
We could keep track of the total line length in some sort of TLS, but it feels like it'd be better to do that in the common debug code where we already have a TLS structure than in mscoree. There's also a possibility that the length stored by mscoree will be off if other Wine traces occur in the same thread between these calls (which would, of course, garble the output, so maybe that's an argument for having a string buffer in mscoree, but it doesn't feel very clean to me as we'd have to hard-code the maximum length).
It sounds very much like you want a buffer for mono_print_handler_fn separate from the other debug functions. I don't see any issue with hard-coding a maximum length. -- Alexandre Julliard julliard(a)winehq.org
participants (3)
-
Alexandre Julliard -
Esme Povirk -
Esme Povirk (she/they)