Working on Wine Part 4 Debugging Wine

Andrew Eikum a CodeWeavers employee and Wine developer is writing a series of post to introduce people to Wine usage and development.

About This Guide

This is a series of guides intended to introduce software developers to the Wine ecosystem. It will cover what Wine is, how to use Wine, how to debug Wine, how to fix Wine, and what to do with your fix once you've made it.

The guide will be published throughout January.

• Part 1 describes what Wine is and provides a short description of various popular forks of Wine.
• Part 2 describes Wine's build process.
• Part 3 describes how to use Wine as a developer.
• Part 4 describes how to debug Wine in general.
• Part 5 describes Wine's source tree layout and how to edit the source.
• Part 6 describes how you can send your work upstream.

If you've made it this far, then you should have a functioning Wine build and an application installed that has some problem that you want to fix.

Debugging Wine is unlike debugging an application or even most open source libraries and software. As a Wine developer, you typically don't have access to the source of the application. So you have to be able to guess at what the application is trying to do, and then figure out why Wine is failing to meet its requirements.

Applications are often debugged with debuggers, but this is of limited use with Wine. A lot of time is spent in application code, which isn't useful to us, or in OS library or kernel code, which is also often not useful to us. Wine is just the go-between from application code to library or OS code, so debuggers tend to spend a lot more time out of Wine code than in it. Problems in Wine are also often less about bugs than they are missing features. Debuggers don't help here.

 

WINEDEBUG

Instead, most Wine debugging is done with printf-debugging. Wine developers have introduced copious logging into the libraries. When you run an application with these debug traces enabled, it will spit out large quantities of information about how the application is using the library.

You enable these logs with the WINEDEBUG environment variable. This variable takes a comma-separated list of debug channels. While it has a more complicated syntax than this, usually you just enable channels entirely. For example, to debug a networking issue, you might start with:

    $ WINEDEBUG=+seh,+winhttp,+winsock,+wininet ~/src/wine.win64/wine Steam.exe

This will emit a ton of output on stderr. Usually you redirect to a file:

    $ rm -f out.txt && WINEDEBUG=+seh,+winhttp,+winsock,+wininet 

~/src/wine.win64/wine Steam.exe &>> out.txt

Notice that the redirect is in append mode, to allow for more readable multi-threaded logging. This requires that we delete any old log file first.

This is the basic Wine debugging loop. Run the application with logging enabled, demonstrate the failure, examine the log, add more logging if necessary, and repeat until you understand the problem.

 

Debugging channels

Wine trace logs have four "severities," called TRACE, WARN, FIXME, and ERR. TRACE is just general debugging, and is silenced by default. WARN indicates some suspicious, but non-fatal condition and is also silenced by default. FIXME indicates some missing feature of Wine and will be printed by default. ERR indicates a serious problem and will also be printed by default.

Wine lets developers output logs on specific channels. These are declared in the C source files with WINE_DECLARE_DEBUG_CHANNEL and WINE_DEFAULT_DEBUG_CHANNEL. Grepping the C files for DEBUG_CHANNEL works great.

It's not always easy to determine which log channels are useful to trace. If you know what general area your problem is in, you can add channels from the relevant Wine libraries. If you don't have any idea, then a log with just +seh is a decent starting place to dig for fixmes and errs.
There are some special debugging channels.

tid and pid will prepend each log line with the Thread ID and Process ID that outputted the log line. tid is enabled by default in recent Wine.

relay will output every API entry point that the application, or other parts of Wine, make a call to. This is extremely verbose, but can be very valuable, especially if you don't know where the problem lies.

timestamp will prepend every log line with a millisecond-resolution timer. This is great if you can estimate when in the log the problem occurred, or are working with timing-sensitive code like audio.

 

Working with log files

Most WINEDEBUG logs will grow to hundreds of kB and MB of plaintext. Logs of multiple GB are not uncommon, especially relay logs. Many GUI text editors will not handle files of these sizes very well. An editor like vim is recommended.

You should also get familiar with tools like grep, head, and tail to pare log files down to manageable chunks. In particular, grep -v can get rid of uselessly repetitive log lines.
When encountering a new log, a good first step is to grep for err:, warn:, and fixme:. These can indicate problems. You'll likely get a lot of fixmes and probably some warns. If you're getting messages from areas unrelated to the problem you're examining, you can usually ignore them. For example, fixmes from the d3d channel are probably unrelated to a problem with audio.

 

Log file techniques

One generally useful technique is to find the problem and then search backwards. For example, bad pointer dereferences are a common failure. These can be found in a +seh log by searching for c0000005. Once you've found the failure in the log, you can start going backwards and if you're lucky, find some fixme or err indicating a missing feature. Or in a relay log, you might find some API that is returning a failure, like a bad HRESULT instead of S_OK.

If you don't have an obvious crash point, you can also try to find where in the log things start to go bad. For example, most applications follow a pattern of loading libraries, initializing stuff, normal application processing, then uninitializing stuff and unloading libraries. If you have an application that is quitting unexpectedly, you can search for when shutdown-related code is happening and then start going backwards to try to find the culprit.

If you have an application that fails on some specific input condition (say, clicking on some UI element), you can actually write to the log at the same time that Wine is. While Wine is debugging, run:

    $ echo '@@@@@@@@' >> out.txt

Then perform your action and observe the failure. Then run it again:

    $ echo '########' >> out.txt

Now you know the failure occurred between the at-symbols and the hashes.

Full Article

Run Microsoft Windows Applications and Games on Mac, Linux or ChromeOS save up to 20% off  CodeWeavers CrossOver+ today.