Debugging Experience using WinDbg

Poonam Bajaj

Sharing a debugging experience using WinDbg.

This issue was a crash on Windows platform showing jvm!jio_fprintf as the topmost JVM frame on the call stack of the crashing thread. I debugged this crash using WinDbg Debugger.

I received a Crash Dump file from customer, opened it in WinDbg and got the following stack trace from it:

This stack shows that the top frame is ntdll!RtlEnterCriticalSection+0xb which was called from jvm!jio_fprintf(), which seemed unlikely. To confirm this, I checked the symbols on the stack of the crashing thread.

Note: To get the stack address in Windbg, click View->Registers, take the value of 'ebp'; this register contains the address of the current frame on the stack.

In this case, ebp was 0x2245f698

Note: To see the symbols on the stack, click View->Memory and paste 'ebp' value. Select "Pointer and Symbol" in the 'Debug Format' drop down in the memory window.

I got the following symbols on the stack:

The symbols on the stack show that the returm address of jvm!jio_vfprintf was also put on the stack and that means that the last JVM function that got called was actually jvm!jio_vfprintf and the crash might have happened somewhere in this function.

After that I looked at the disassembly of this function. For seeing disassembly we need to copy the value corresponding to the symbol of this function on the stack (6d4545dc) and paste it in the Disassembly window.

Note: To open the disassembly window, click View->Disassembly.

This disassembly shows that it is reading value in jvm!Arguments::_vfprintf_hook and is calling a function present at that address. This brought one important fact into light that customer was setting the 'vfprintf' option while creating the embedded jvm. So jvm function jvm!jio_vfprintf was invoking customer's jio_vfprintf() which was set as the _vfprintf_hook by customer code.

Here's some part of the customer's code where they create Java VM:

JavaVMInitArgs vm_args; 
JavaVMOption options[2]; 
options[0].optionString = "-Djava.class.path=" USER_CLASSPATH; 
vm_args.version = 0x00010002; 
options[1].optionString = "vfprintf"; 
options[1].extraInfo = (void*)jio_vfprintf; 
vm_args.version = JNI_VERSION_1_2; 
vm_args.ignoreUnrecognized = JNI_TRUE; 
/* Create the Java VM */ 
res = JNI_CreateJavaVM(&jvm,(void**) &env,&vm_args); 

Customer's jio_vfprintf() was implemented in a dll called JavaInvoker. Here's part of the function:

Then I asked for the pdb file for JavaInvoker so that I could see the disassembly of this function in WinDbg. The diassembly of JavaInvoker!jio_vfprintf() showed that the FILE* file was NULL and fprintf was being called with null file handle.

The customer had also reported that the log file they were opening in jio_vfprintf was growing beyond 4gb size. On Windows, fopen() for large files of size more than 4gb fails and returns Null. So in this case, when the jvm.log file grew more than 4gb, fopen failed and was setting the 'file' to Null. The subsequent fprintf tried to access this Null file handle and crashed.

I suggested Customer to add a null check for 'file' after opening the file and before writing to it.

if (file == 0) {
    file = fopen("log\\JVM.log", "a+");
    if (file != 0) {
        ------
    }
}