Monitoring OutputDebugString on Windows systems from an OSGi component using JNA

Recently I needed to create a small DLL to call some functions on a Windows Mobile device attached to the desktop Windows PC. Inside my DLL I made heavy use of the kernel32.dll OutputDebugString Win32 API to send text to an attached debugger or Debug View. Since I was programming in Java, I would have liked to have all the log messages appear in the Java console and end up in the log file created by slf4j.

How does OutputDebugString work?

Basically it writes its data to a shared memory section of kernel32.dll. Everybody can try to read this memory out at any time. You just need to know how the name of this memory block is and can get a direct memory pointer to it. I will not go into the details of that now, you can lookup the required methods in the MSDN yourself. So at first we need to open the existing filemapping with the name "DBWIN_BUFFER" using CreateFileMapping. Windows allocates 4096 bytes for the shared buffer. We then just map this shared buffer to a real memory location using MapViewOfFile. Using JNA thats pretty easy to do:

HANDLE sharedFile = Kernel32.INSTANCE.CreateFileMapping(W32API.INVALID_HANDLE_VALUE, null, Kernel32.PAGE_READWRITE, 0, 4096, DBWIN_BUFFER_SHARED_FILE);
HANDLE sharedMemory = Kernel32.INSTANCE.MapViewOfFile(this.sharedFile, Kernel32.SECTION_MAP_READ, 0, 0, 4096);

I added those prototypes to the already existing JNA Kernel32 package:

int PAGE_READONLY = 0x02;
int PAGE_READWRITE = 0x04;
int PAGE_WRITECOPY = 0x08;
int PAGE_EXECUTE = 0x10;
int PAGE_EXECUTE_READ = 0x20;
int PAGE_EXECUTE_READWRITE = 0x40;

HANDLE CreateFileMapping(HANDLE hFile, SECURITY_ATTRIBUTES lpAttributes, int flProtect, int dwMaximumSizeHigh, int dwMaximumSizeLow, String lpName);

int SECTION_QUERY = 0x0001;
int SECTION_MAP_WRITE = 0x0002;
int SECTION_MAP_READ = 0x0004;
int SECTION_MAP_EXECUTE = 0x0008;
int SECTION_EXTEND_SIZE = 0x0010;

Pointer MapViewOfFile(HANDLE hFileMappingObject, int dwDesiredAccess, int dwFileOffsetHigh, int dwFileOffsetLow, int dwNumberOfBytesToMap);

boolean UnmapViewOfFile(Pointer lpBaseAddress);

Now we basically have everything ready to start reading from that buffer. The first 4 bytes (32-bit DWORD) is the process ID of the process that wrote the text using OutputDebugString. The following bytes are the actual debug message as an ANSI string. Now, to tell kernel32 that we are interested in reading out this memory, we should inform it. Otherwise kernel32 would not write anything to this memory, if nobody is about to read it. For that purpose there is a named Win32 event that we need to signal. Its name is "DBWIN_BUFFER_READY". We create it using those new Kernel32 JNA mappings:

HANDLE CreateEvent(SECURITY_ATTRIBUTES lpEventAttributes, boolean bManualReset, boolean bInitialState, String lpName);

boolean SetEvent(HANDLE hEvent);

boolean PulseEvent(HANDLE hEvent);

Now lets create the mentioned event:

bufferReadyEvent = Kernel32.INSTANCE.CreateEvent(null, false, false, DBWIN_BUFFER_READY_EVENT);

When we signal this event, kernel32 will start to write data into the shared memory if some process calls OutputDebugString. In an infinite loop would could now read the memory out but that would read always the last written text that might not have changed since the last time we checked. Windows helps us to get informed when new text has been written to the shared memory. It signals this with the named event "DBWIN_DATA_READY". Now we can be a very good citizen and use the Win32 WaitForSingleObject to wait for this event to be signaled.

while (run) {
 // Say that we are interested in receiving data ready events
 Kernel32.INSTANCE.SetEvent(this.bufferReadyEvent);

 final int ret = Kernel32.INSTANCE.WaitForSingleObject(this.dataReadyEvent, Kernel32.INFINITE);
 if (!run) {
   break;
 }
 if (ret == 0) { // WAIT_OBJECT_0
   final int pid = this.sharedMemory.getInt(0);
   final String text = this.sharedMemory.getString(4, false);
 }
}

Creating a monitor thread

We can implement this whole functionality as a Thread and hand it in an OSGi LogService to log the catched debug message with the OSGi environment.

package outputdebugstring.monitor.internal;

import org.osgi.service.log.LogService;

import com.sun.jna.Pointer;
import com.sun.jna.examples.win32.Kernel32;
import com.sun.jna.examples.win32.W32API;
import com.sun.jna.examples.win32.W32API.HANDLE;

class OutputDebugStringThread extends Thread {
private static final String DBWIN_BUFFER_SHARED_FILE = "DBWIN_BUFFER"; //$NON-NLS-1$
private static final String DBWIN_DATA_READY_EVENT = "DBWIN_DATA_READY"; //$NON-NLS-1$
private static final String DBWIN_BUFFER_READY_EVENT = "DBWIN_BUFFER_READY"; //$NON-NLS-1$

private final HANDLE bufferReadyEvent;
private final HANDLE dataReadyEvent;
private final HANDLE sharedFile;
private final Pointer sharedMemory;
private final LogService log;
private volatile boolean run = true;

public OutputDebugStringThread(final LogService log) {
 super("OutputDebugString monitor"); //$NON-NLS-1$

 setDaemon(true);

 this.log = log;

 this.bufferReadyEvent = Kernel32.INSTANCE.CreateEvent(null, false, false, DBWIN_BUFFER_READY_EVENT);
 this.dataReadyEvent = Kernel32.INSTANCE.CreateEvent(null, false, false, DBWIN_DATA_READY_EVENT);
 this.sharedFile = Kernel32.INSTANCE.CreateFileMapping(W32API.INVALID_HANDLE_VALUE, null,
     Kernel32.PAGE_READWRITE, 0, 4096, DBWIN_BUFFER_SHARED_FILE);
 this.sharedMemory = Kernel32.INSTANCE.MapViewOfFile(this.sharedFile, Kernel32.SECTION_MAP_READ, 0, 0, 4096);
}

@Override
public void run() {
 try {
   while (this.run) {
     // Say that we are interested in receiving data ready events
     Kernel32.INSTANCE.SetEvent(this.bufferReadyEvent);

     final int ret = Kernel32.INSTANCE.WaitForSingleObject(this.dataReadyEvent, Kernel32.INFINITE);
     if (!this.run) {
       break;
     }
     if (ret == 0) { // WAIT_OBJECT_0
       final int pid = this.sharedMemory.getInt(0);
       final String text = this.sharedMemory.getString(4, false);
       this.log.log(LogService.LOG_DEBUG, String.format("[%d] %s", pid, text)); //$NON-NLS-1$
     }
   }
 } finally {
   if (this.sharedMemory != null) {
     Kernel32.INSTANCE.UnmapViewOfFile(this.sharedMemory);
   }
   if (!W32API.INVALID_HANDLE_VALUE.equals(this.sharedFile)) {
     Kernel32.INSTANCE.CloseHandle(this.sharedFile);
   }
   if (!W32API.INVALID_HANDLE_VALUE.equals(this.bufferReadyEvent)) {
     Kernel32.INSTANCE.CloseHandle(this.bufferReadyEvent);
   }
   if (!W32API.INVALID_HANDLE_VALUE.equals(this.dataReadyEvent)) {
     Kernel32.INSTANCE.CloseHandle(this.dataReadyEvent);
   }
 }
}

/**
* Our very own implementation that simply notifies the thread to stop by sending an event it is waiting for.
*/
@Override
public void interrupt() {
 this.run = false;
 Kernel32.INSTANCE.PulseEvent(this.dataReadyEvent);
}
}

As you can see I have overwritten the interrupt() method of Thread to implement a custom interruption using the volatile variable "run". We then pulse the dataReadyEvent to make the WaitForSingleObject wake up and immediately check the run variable to stop running.

Creating an OSGi component

Now that we have the (almost OGSi independent) thread to catch Windows debug messages we can wrap it in a simple OSGi component that will also give the thread the LogService it needs. A better solution would be however to have the Thread just call a simple Listener method to report the debug message event. That way it would have no dependency on OSGi.

The service component would be as simple as this:

public class MonitorComponent {
private OutputDebugStringThread thread;

protected void deactivate() {
  if (this.thread != null) {
    this.thread.interrupt();
  }
}

protected void bind(final LogService log) {
  this.thread = new OutputDebugStringThread(log);
  this.thread.start();
}
}

And the corresponding DS component XML file

<?xml version="1.0" encoding="UTF-8"?>
<scr:component xmlns:scr="http://www.osgi.org/xmlns/scr/v1.1.0" name="outputdebugstring.MonitorComponent">
 <implementation class="outputdebugstring.monitor.internal.MonitorComponent"/>
 <reference bind="bind" cardinality="1..1" interface="org.osgi.service.log.LogService" name="LogService" policy="static"/>
</scr:component>

As you can see we dynamically bind to the OSGi LogService and our component will be only activated when there is at least one LogService available. This saves our component from instantiating itself if there is nothing to log to.

Extensions

The component could also facilitate the OSGi EventAdmin and send an event: event.topic = win32/OutputDebugString ods.pid = the process ID ods.text = the text

Note: It seems that inside the mapped file all texts are stored in the ANSI character set and not in Unicode (UTF-16) even when a process called OutputDebugStringW.

Sourcecode is up at github now.