[Bug 16941] New: interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

Summary: interrupts cause nested trace output
           Product: Wine
           Version: 1.1.12
          Platform: PC
        OS/Version: Linux
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: -unknown
        AssignedTo: [e-mail]
        ReportedBy: [e-mail]

The winmm periodic timer interrupt (used e.g. by the dsound PCM player) causes
confusion in wine's debug log. I believe every line in the log should be output
atomically. This is not the case and makes the log harder to analyse.

Please search your traces using the following regexp
.[0-9]{4}:[a-zCR]
to find sections where one thread manages to interrupt another one amid a log
line.

In my case, all such occurrences are caused by one thread, identified as
follows:
0019:trace:mmtime:TIME_MMSysTimeThread Starting main winmm thread

Here's a sample where the main thread's (0009) logline is interrupted by the
timer's thread (0019) trace output:

0009: get_handle_fd(0019:Call KERNEL32.GetTickCount()
0019:Ret  KERNEL32.GetTickCount()
0019:trace:dsound:DSOUND_timer (1,0,0x1fbbb0,0x0,0x0)
0019:[many lines omitted]
 handle=00a4 ) <- This is the remains of the trace output
                  from the interrupted thread (0009)
0009: *fd* 00a4 -> 83

Here's another example, involving a redispatch to thread 0018:

001e0019:Call KERNEL32.GetTickCount() 
0019:Ret  KERNEL32.GetTickCount() ...
0019: [many lines omitted]
: create_key() = 0 { hkey=0020, created=0 }
^^^^  remains from thread 001e
0018: get_new_process_info( info=0038 )
0018: select() = PENDING { timeout=infinite, ...
001e:trace:reg:NtCreateKey <- 0x20

The interruptor's pattern is always the same:
- 2x GetTickCount()
- trace:dsound:DSOUND_timer
- dsound perform mix etc.

Looking at libs/wine/debug.c:default_dbg_vlog() I see no obvious mechanism to
ensure atomic output, while and dlls/ntdll/debugtools.c:NTDLL_dbg_vlog() might
have the machinery given a temporary output buffer and a single call to
write().

[Bug 16941] interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

--- Comment #1 from Alexandre Julliard   2009-01-15 13:02:25 ---
The version from debugtools.c is the one that is used, so it is a single call
to write. There isn't really anything more we can do. You can put the output
file in append mode with a >> redirection, this may help.

[Bug 16941] interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

Vitaliy Margolen  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
           Severity|normal                      |enhancement

[Bug 16941] interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

Jörg Höhle  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
          Component|-unknown                    |tools

--- Comment #2 from Jörg Höhle   2009-01-16 04:35:21 ---
Looking more closely at the log, I found that all (but one) interrupted traces
are of the form
nnnn: close_handle, get_handle_fd, get|enum|set_key_value etc.
(NOT the typical nnnn:class:component:function ...)
I.e. they emanate from server/trace.c which is full of fprintf(stderr,...)
snippets, making output interruptible, whereas all the others indeed go through
the one atomic write(2) call in dbg_vlog().

So Vitaliy is right to change this issue to an enhancement request:
server/trace.c and tools/make_requests need be rewritten not to use several
fprintf(stderr), but a single one for all the dump_*() helpers, via a temporary
buffer.

Hence I'm changing component to tools ("server" is not a selectable component).

[Bug 16941] interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

--- Comment #3 from Alexandre Julliard   2009-01-16 08:12:32 ---
stderr is put in line-buffered mode in the server so this shouldn't happen.
I've moved the setvbuf call a little, maybe that will help.

[Bug 16941] interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

Austin English  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
          Component|tools                       |wineserver

--- Comment #4 from Austin English   2009-01-16 10:46:58 ---
(In reply to comment #2)
> Hence I'm changing component to tools ("server" is not a selectable component).

But 'wineserver' is ;-)

[Bug 16941] interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

Jörg Höhle  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|UNCONFIRMED                 |RESOLVED
         Resolution|                            |FIXED

--- Comment #5 from Jörg Höhle   2009-03-24 05:16:58 ---
When I wrote the bug report, I was convinced that it would show up in every
application so I did not write down where I observed it. Now I've scanned
gigabytes of logs from various applications and could not find its trace
anymore, even in releases older than Alexandre's patch. I'm sorry for that ;-)
So I hope this patch plugs any remaining holes and close this issue.
I agree with Alexandre that line buffered mode should prevent this bug from
showing up, even though the log file is written to using 2 different API layers
-- fprintf(stderr) and write(2) -- from all threads.

[Bug 16941] interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

Alexandre Julliard  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |CLOSED

--- Comment #6 from Alexandre Julliard   2009-03-27 13:55:59 ---
Closing bugs fixed in 1.1.18.

[Bug 16941] interrupts cause nested trace output

http://bugs.winehq.org/show_bug.cgi?id=16941

--- Comment #7 from Jörg Höhle   2009-06-12 03:54:19 ---
Created an attachment (id=21749)
 --> (http://bugs.winehq.org/attachment.cgi?id=21749)
3 log samples from around raise_exception

When "The Westerner" crashes after the intro, there's a slight variation of
nested logs. Looking closely, it seems a part of a former log line is
duplicated.

The normal exception log header line is:
trace:seh:raise_exception code=c000013a flags=0 addr=0x7ef9400d ip=7ef9400d
tid=0009

A weird one looks like follows, with the code=... part lacking the
raise_exception prefix, and attached to another line instead:
Ret  msadp32.acm.DriverProc() retval=00000001 ret=7e4569b6
 get_console_input_info( handle=0000 )
 get_console_input_info() = INVALID_PARAMETER { history_mode=0, history_size=0,
history_index=0, edition_mode=0, input_cp=0, output_cp=0, win=00000000,
title=L"" }
Ret  msadp32.acm.DriverProc()code=c000013a flags=0 addr=0xb8053430 ip=b8053430
tid=0009
trace:seh:raise_exception  eax=00000040 ebx=00000002 ecx=7efff0c8 edx=00000040
esi=0000001e edi=0000001e

Do you see how the prefix "Ret  msadp32.acm.DriverProc()" seems duplicated and
replacing the raise_exception part?

Attached are 2-3 larger samples of this, all from The Westerner. This is not
yet enough material to open another issue, so I'm just leaving a note here.

BTW, where does get_console_input come from? Is that the exception handling
code already kicking in?

This was produced using wine-1.1.22, compiled by me on Ubuntu 8.04 (or 8.10?).