Setting IoStatus.Information

I spent a couple hours yesterday investigating a bug that turned out to be a pretty silly mistake on my part, but I wanted to share some of the analysis with you. The problem was that an application was failing with a message of "There is not enough space on the disk", according to its logs.

Naturally the first step was to run procmon with and without my filter and compare the logs. After some filtering and searching and looking at timestamps (as an aside, any decent logging solution should have timestamps for the events, it makes it so much easier to find things) I managed to narrow things down to this:

And this is what the log looked like when the application worked:

The thing that I found most puzzling just by looking at these to screenshots was the fact that when the application was failing, the IRP_MJ_QUERY_INFORMATION call for the FilePositionInformation class was successful but still ProcMon didn't print the position like it did when the application was working. Anyway, the problem was obviously that the application was trying to set the EndOfFilte to a very large offset and it failed because the disk wasn't that large. I was curious to see how that file size was calculated and so I spent some time looking at the number, in the hope that maybe some high bit is set somewhere, messing up the number. But to no avail, the value looked positively random: 1,288,524,915,353 bytes is 0x12C0211E299…

Anyway, with that investigation leading nowhere (the next step was to debug the application to figure out how that value came about, something I wasn't very eager to do), I decided that I should take a break and instead investigate the other puzzling aspect, ProcMon not displaying the FilePositionInformation even thought the call was successful. So I spent a bit of time trying to figure it out and in my filter everything looked fine, I was setting the size properly:

            case FilePositionInformation:
                {
                    PFILE_POSITION_INFORMATION positionInfo = Data->Iopb->Parameters.QueryFileInformation.InfoBuffer;

                    // retrieve the current position from the file object

                    positionInfo->CurrentByteOffset = FltObjects->FileObject->CurrentByteOffset;

                    // then complete the operation

                    Data->IoStatus.Status = STATUS_SUCCESS;
                    callbackStatus = FLT_PREOP_COMPLETE;
                }
                break;

Compare this with the FastFat implementation:

VOID
FatQueryPositionInfo (
    IN PIRP_CONTEXT IrpContext,
    IN PFILE_OBJECT FileObject,
    IN OUT PFILE_POSITION_INFORMATION Buffer,
    IN OUT PLONG Length
    )

/*++

Routine Description:

    This routine performs the query position information function for fat.

Arguments:

    FileObject - Supplies the File object being queried

    Buffer - Supplies a pointer to the buffer where the information is to
        be returned

    Length - Supplies the length of the buffer in bytes, and receives the
        remaining bytes free in the buffer upon return.

Return Value:

    None

--*/

{
    PAGED_CODE();

    DebugTrace(+1, Dbg, "FatQueryPositionInfo...\n", 0);

    //
    //  Get the current position found in the file object.
    //

    Buffer->CurrentByteOffset = FileObject->CurrentByteOffset;

    //
    //  Update the length and status output variables
    //

    *Length -= sizeof( FILE_POSITION_INFORMATION );

    DebugTrace( 0, Dbg, "*Length = %08lx\n", *Length);

    DebugTrace(-1, Dbg, "FatQueryPositionInfo -> VOID\n", 0);

    UNREFERENCED_PARAMETER( IrpContext );

    return;
}

Not at all that different, right ? Anyway, I figured I should set an on-access breakpoint to see where the information that I set in the buffer was read:

1: kd> ba r 4 937dd744  
1: kd> g
Breakpoint 0 hit
nt!ExDeferredFreePool+0x2e3:
82931943 894604          mov     dword ptr [esi+4],eax

So as you can see the buffer wasn't access until the memory got freed. I then decided to compare it with what happens when my filter is not in the picture:

1: kd> ba r 4 94b6c874  
1: kd> g
Breakpoint 0 hit
nt!memcpy+0x134:
8284f8f4 89448ffc        mov     dword ptr [edi+ecx*4-4],eax
1: kd> kn
 # ChildEBP RetAddr  
00 9a037bf8 828b31c3 nt!memcpy+0x134
01 9a037c48 82a6e017 nt!IopCompleteRequest+0xa0
02 9a037d18 8285444a nt!NtQueryInformationFile+0x86c
03 9a037d18 779c64f4 nt!KiFastCallEntry+0x12a
...

And this was where it hit me. Since this was BUFFERED_IO, the IO manager was supposed to copy the data I provided back into the user's buffer. But as we can clearly see, with my filter there was no access to the buffer at all. This is because I didn’t set the IoStatus.Information properly. I did set it to 0 somewhere up the in the beginning of the function but forgot to set it to reflect the size of the data that I filled in when completing the request. The net result was that ProcMon was smart enough not to display anything because it got no data back, but the application had no idea this was going on and so it used whatever happened to be in the buffer as the actual position, and then proceeded to set that position as the EndOfFile. After setting the IoStatus.Information properly the application started working. For completeness, this is the code that worked:

            case FilePositionInformation:
                {
                    PFILE_POSITION_INFORMATION positionInfo = Data->Iopb->Parameters.QueryFileInformation.InfoBuffer;

                    // retrieve the current position from the file object

                    positionInfo->CurrentByteOffset = FltObjects->FileObject->CurrentByteOffset;

                    // then complete the operation

                    Data->IoStatus.Status = STATUS_SUCCESS;
                    Data->IoStatus.Information = sizeof(positionInfo->CurrentByteOffset);
                    callbackStatus = FLT_PREOP_COMPLETE;
                }
                break;

In closing I'd like to point to Doron's blog on How to return the number of bytes required for a subsequent operation that explains some more of the inner workings on IoStatus.Information and how the IO manager uses it.