How to Track Memory or Pointers When Function Calls Are Possibly Asynchronous

All development related issues welcome

Moderator: Moderator Team

Post Reply
berylliumquestion
Posts: 10
Joined: Sun Sep 01, 2019 12:59 am

How to Track Memory or Pointers When Function Calls Are Possibly Asynchronous

Post by berylliumquestion »

This is related to the last topic I posted:
https://www.reactos.org/forum/viewtopic.php?f=2&t=19396

In it ThFabba talked about how IRPs are asynchronous.
ThFabba wrote:
Fri Dec 20, 2019 6:02 pm
...
  • IRPs are asynchronous in nature and sometimes they're processed in less-than-obvious ways. For example it's possible for the owner of an IRP to set a completion routine that re-uses the same structure for a completely different operation. In a case like this you may see an initial call to IoCallDriver followed by request completion via IoCompleteRequest -- which then calls the completion routine and initiates another operation by calling IoCallDriver again.
...
Now I'm not entirely sure if everything in this quote is relevant to this post, but I think the asynchronous part is very relevant.

I believe this may be the case for a specific thing I'm looking for. DeviceObject->Flags changes in a way that I think it shouldn't. However, I don't know for certain, because I'm unable to see where it is being modified. This is the bug I filed on Jira CORE-16362, but I want to know how I can find the source of the problem myself and I'm hitting a bit of a wall. A certain piece of memory seems to be being altered somewhere within the code in a way that completely halts progress, but the usually very helpful DPRINT1 statements have been less helpful at this point.

drivers/filesystem/cdfs/deviosup.c
in the function

Code: Select all

_Requires_lock_held_(_Global_critical_region_)
BOOLEAN
CdReadDirDataThroughCache (
    _In_ PIRP_CONTEXT IrpContext,
    _In_ PIO_RUN Run
    )
A little ways down into the function is where the problem starts:

Code: Select all

if (STATUS_PENDING == Status)  {

		DPRINT1("CdReadDirDataThroughCache Vcb->TargetDeviceObject->Flags before: %I64x\n", Vcb->TargetDeviceObject->Flags);
                (VOID)KeWaitForSingleObject( &Vcb->SectorCacheEvent,
                                       Executive,
                                       KernelMode,
                                       FALSE,
                                       NULL );
                DPRINT1("CdReadDirDataThroughCache Vcb->TargetDeviceObject->Flags after: %I64x\n", Vcb->TargetDeviceObject->Flags);
                
                if ((Vcb->TargetDeviceObject->Flags & DO_VERIFY_VOLUME) == 2)
                {
                    Vcb->TargetDeviceObject->Flags -= DO_VERIFY_VOLUME;
                }
            
                Status = Vcb->SectorCacheIrp->IoStatus.Status;
            }
I looked at that function in wait.c and it seems to suggest asynchronicity. There's only one problem that I'm having where I can't seem to track the change of the DeviceObject->Flags. Between those two DPRINT1 statements DeviceObject->Flags goes from being equal to 150 to 152. However, because it seems that it goes to different instances of IoCallDriver, it therefore shows different contents in DeviceObject->Flags.

This is when I run it on real hardware.

Here's the short version:

Code: Select all

(drivers/filesystems/cdfs/deviosup.c:2797) CdReadDirDataThroughCache DeviceObject->Flags before: b49c1d3800000150
(drivers/filesystems/cdfs/deviosup.c:2804) CdReadDirDataThroughCache DeviceObject->Flags after: 152
Here's the really long version:

Code: Select all

(drivers/filesystems/cdfs/deviosup.c:2797) 71 CdReadDirDataThroughCache DeviceObject->Flags: b49c1d3800000150
(ntoskrnl/io/iomgr/file.c:2595) FileName: \Device\MountPointManager
(ntoskrnl/io/iomgr/file.c:359) ParseObject: B4A6DBF8. RemainingName: 
(ntoskrnl/io/iomgr/file.c:999) Before IoCallDriver
(ntoskrnl/io/iomgr/irp.c:1265) irp.c start DeviceObject->Flags: f75fc84c00000840
(ntoskrnl/io/iomgr/irp.c:1271) irp.c 0 DeviceObject->Flags: f75fc84c00000840
(ntoskrnl/io/iomgr/irp.c:1275) irp.c 1 DeviceObject->Flags: f75fc84c00000840
(ntoskrnl/io/iomgr/irp.c:1279) irp.c 2 DeviceObject->Flags: f75fc84c00000840
(ntoskrnl/io/iomgr/irp.c:1288) irp.c 5 DeviceObject->Flags: f75fc84c00000840
(ntoskrnl/io/iomgr/irp.c:1291) irp.c 6 DeviceObject->Flags: f75fc84c00000840
(ntoskrnl/io/iomgr/irp.c:1293) irp.c 7 DeviceObject->Flags: f75fc84c00000840
(ntoskrnl/io/iomgr/irp.c:1299) irp.c end DeviceObject->Flags: f75fc84c00000840
(ntoskrnl/io/iomgr/irp.c:1300) DeviceObject: B4A6DBF8
(ntoskrnl/io/iomgr/irp.c:1301) Irp: B4CAE4E8
(ntoskrnl/io/iomgr/irp.c:1302) DriverObject->MajorFunction: b4cd11a0
(ntoskrnl/io/iomgr/irp.c:1303) StackPtr->MajorFunction: 0
(ntoskrnl/io/iomgr/irp.c:1348) IofCompleteRequest()
(ntoskrnl/io/iomgr/file.c:1002) After IoCallDriver
(ntoskrnl/io/iomgr/file.c:1067) file.c something something who knows
(ntoskrnl/io/iomgr/file.c:2205) ObjectBody: B4CB69C0
(ntoskrnl/io/iomgr/file.c:2333) 3 file
(ntoskrnl/io/iomgr/irp.c:1265) irp.c start DeviceObject->Flags: f75fca3800000840
(ntoskrnl/io/iomgr/irp.c:1271) irp.c 0 DeviceObject->Flags: f75fca3800000840
(ntoskrnl/io/iomgr/irp.c:1275) irp.c 1 DeviceObject->Flags: f75fca3800000840
(ntoskrnl/io/iomgr/irp.c:1279) irp.c 2 DeviceObject->Flags: f75fca3800000840
(ntoskrnl/io/iomgr/irp.c:1288) irp.c 5 DeviceObject->Flags: f75fca3800000840
(ntoskrnl/io/iomgr/irp.c:1291) irp.c 6 DeviceObject->Flags: f75fca3800000840
(ntoskrnl/io/iomgr/irp.c:1293) irp.c 7 DeviceObject->Flags: f75fca3800000840
(ntoskrnl/io/iomgr/irp.c:1299) irp.c end DeviceObject->Flags: f75fca3800000840
(ntoskrnl/io/iomgr/irp.c:1300) DeviceObject: B4A6DBF8
(ntoskrnl/io/iomgr/irp.c:1301) Irp: B4CAE4E8
(ntoskrnl/io/iomgr/irp.c:1302) DriverObject->MajorFunction: b4cd11a0
(ntoskrnl/io/iomgr/irp.c:1303) StackPtr->MajorFunction: 12
(ntoskrnl/io/iomgr/irp.c:1348) IofCompleteRequest()
(ntoskrnl/io/iomgr/irp.c:1265) irp.c start DeviceObject->Flags: f75fcca400000840
(ntoskrnl/io/iomgr/irp.c:1271) irp.c 0 DeviceObject->Flags: f75fcca400000840
(ntoskrnl/io/iomgr/irp.c:1275) irp.c 1 DeviceObject->Flags: f75fcca400000840
(ntoskrnl/io/iomgr/irp.c:1279) irp.c 2 DeviceObject->Flags: f75fcca400000840
(ntoskrnl/io/iomgr/irp.c:1288) irp.c 5 DeviceObject->Flags: f75fcca400000840
(ntoskrnl/io/iomgr/irp.c:1291) irp.c 6 DeviceObject->Flags: f75fcca400000840
(ntoskrnl/io/iomgr/irp.c:1293) irp.c 7 DeviceObject->Flags: f75fcca400000840
(ntoskrnl/io/iomgr/irp.c:1299) irp.c end DeviceObject->Flags: f75fcca400000840
(ntoskrnl/io/iomgr/irp.c:1300) DeviceObject: B4A6DBF8
(ntoskrnl/io/iomgr/irp.c:1301) Irp: B4CAE4E8
(ntoskrnl/io/iomgr/irp.c:1302) DriverObject->MajorFunction: b4cd11a0
(ntoskrnl/io/iomgr/irp.c:1303) StackPtr->MajorFunction: e
(ntoskrnl/io/iomgr/irp.c:1348) IofCompleteRequest()
(ntoskrnl/io/iomgr/irp.c:1265) irp.c start DeviceObject->Flags: 840
(ntoskrnl/io/iomgr/irp.c:1271) irp.c 0 DeviceObject->Flags: 840
(ntoskrnl/io/iomgr/irp.c:1275) irp.c 1 DeviceObject->Flags: 840
(ntoskrnl/io/iomgr/irp.c:1279) irp.c 2 DeviceObject->Flags: 840
(ntoskrnl/io/iomgr/irp.c:1288) irp.c 5 DeviceObject->Flags: 840
(ntoskrnl/io/iomgr/irp.c:1291) irp.c 6 DeviceObject->Flags: 840
(ntoskrnl/io/iomgr/irp.c:1293) irp.c 7 DeviceObject->Flags: 840
(ntoskrnl/io/iomgr/irp.c:1299) irp.c end DeviceObject->Flags: 840
(ntoskrnl/io/iomgr/irp.c:1300) DeviceObject: B4A6DBF8
(ntoskrnl/io/iomgr/irp.c:1301) Irp: B4CAE4E8
(ntoskrnl/io/iomgr/irp.c:1302) DriverObject->MajorFunction: b4cd11a0
(ntoskrnl/io/iomgr/irp.c:1303) StackPtr->MajorFunction: e
(ntoskrnl/io/iomgr/irp.c:1348) IofCompleteRequest()
(ntoskrnl/io/iomgr/irp.c:1265) irp.c start DeviceObject->Flags: 80a1206000000840
(ntoskrnl/io/iomgr/irp.c:1271) irp.c 0 DeviceObject->Flags: 80a1206000000840
(ntoskrnl/io/iomgr/irp.c:1275) irp.c 1 DeviceObject->Flags: 80a1206000000840
(ntoskrnl/io/iomgr/irp.c:1279) irp.c 2 DeviceObject->Flags: 80a1206000000840
(ntoskrnl/io/iomgr/irp.c:1288) irp.c 5 DeviceObject->Flags: 80a1206000000840
(ntoskrnl/io/iomgr/irp.c:1291) irp.c 6 DeviceObject->Flags: 80a1206000000840
(ntoskrnl/io/iomgr/irp.c:1293) irp.c 7 DeviceObject->Flags: 80a1206000000840
(ntoskrnl/io/iomgr/irp.c:1299) irp.c end DeviceObject->Flags: 80a1206000000840
(ntoskrnl/io/iomgr/irp.c:1300) DeviceObject: B4A6DBF8
(ntoskrnl/io/iomgr/irp.c:1301) Irp: B4CAE4E8
(ntoskrnl/io/iomgr/irp.c:1302) DriverObject->MajorFunction: b4cd11a0
(ntoskrnl/io/iomgr/irp.c:1303) StackPtr->MajorFunction: e
(ntoskrnl/io/iomgr/irp.c:1348) IofCompleteRequest()
(ntoskrnl/io/iomgr/irp.c:1265) irp.c start DeviceObject->Flags: b4cd080800000840
(ntoskrnl/io/iomgr/irp.c:1271) irp.c 0 DeviceObject->Flags: b4cd080800000840
(ntoskrnl/io/iomgr/irp.c:1275) irp.c 1 DeviceObject->Flags: b4cd080800000840
(ntoskrnl/io/iomgr/irp.c:1279) irp.c 2 DeviceObject->Flags: b4cd080800000840
(ntoskrnl/io/iomgr/irp.c:1288) irp.c 5 DeviceObject->Flags: b4cd080800000840
(ntoskrnl/io/iomgr/irp.c:1291) irp.c 6 DeviceObject->Flags: b4cd080800000840
(ntoskrnl/io/iomgr/irp.c:1293) irp.c 7 DeviceObject->Flags: b4cd080800000840
(ntoskrnl/io/iomgr/irp.c:1299) irp.c end DeviceObject->Flags: b4cd080800000840
(ntoskrnl/io/iomgr/irp.c:1300) DeviceObject: B4A6DBF8
(ntoskrnl/io/iomgr/irp.c:1301) Irp: B4CAE4E8
(ntoskrnl/io/iomgr/irp.c:1302) DriverObject->MajorFunction: b4cd11a0
(ntoskrnl/io/iomgr/irp.c:1303) StackPtr->MajorFunction: e
(ntoskrnl/io/iomgr/irp.c:1348) IofCompleteRequest()
(ntoskrnl/io/iomgr/irp.c:1265) irp.c start DeviceObject->Flags: 100000050
(ntoskrnl/io/iomgr/irp.c:1271) irp.c 0 DeviceObject->Flags: 100000050
(ntoskrnl/io/iomgr/irp.c:1275) irp.c 1 DeviceObject->Flags: 100000050
(ntoskrnl/io/iomgr/irp.c:1279) irp.c 2 DeviceObject->Flags: 100000050
(ntoskrnl/io/iomgr/irp.c:1288) irp.c 5 DeviceObject->Flags: 100000050
(ntoskrnl/io/iomgr/irp.c:1291) irp.c 6 DeviceObject->Flags: 100000050
(ntoskrnl/io/iomgr/irp.c:1293) irp.c 7 DeviceObject->Flags: 100000050
(ntoskrnl/io/iomgr/irp.c:1299) irp.c end DeviceObject->Flags: 100000050
(ntoskrnl/io/iomgr/irp.c:1300) DeviceObject: B4A48038
(ntoskrnl/io/iomgr/irp.c:1301) Irp: B49C21F0
(ntoskrnl/io/iomgr/irp.c:1302) DriverObject->MajorFunction: b4ccfd10
(ntoskrnl/io/iomgr/irp.c:1303) StackPtr->MajorFunction: f
(drivers/storage/port/scsiport/scsiport.c:2572) ScsiPortDispatchScsi(DeviceObject B4A48038  Irp B49C21F0)
(drivers/storage/port/scsiport/scsiport.c:2574) 0 DeviceObject->Flags: b49c21f000000050
(ntoskrnl/io/iomgr/irp.c:1348) IofCompleteRequest()
(drivers/storage/port/scsiport/scsiport.c:2825) 1 DeviceObject->Flags: b49c21f000000050
(drivers/filesystems/cdfs/deviosup.c:2804) 72 CdReadDirDataThroughCache DeviceObject->Flags: 152
I appreciate the time you've taken to read this post. Thank you. :)

ThFabba
Developer
Posts: 291
Joined: Sun Jul 11, 2010 11:39 am

Re: How to Track Memory or Pointers When Function Calls Are Possibly Asynchronous

Post by ThFabba »

So the "proper debugging" answer to "how do I track down when a value in memory changes" is to use a memory breakpoint (watchpoint). In ROS this generally means switching over to using an MSVC build and debugging with WinDbg, then using the "ba" command. In you particular instance you'd want to find the address of your device object's Flags member via "?? &DeviceObject->Flags" or similar, then do "ba w4 0x1234" with 0x1234 replaced by that address.

The alternative approach that doesn't require switching debuggers would be to find the places in the code that set this particular flag (0x2). Flags is an ULONG by the way, so the upper 32 bits in your prints are just noise (%lx would be enough to print it). Device object flags are called DO_xxx, so https://git.reactos.org/?p=reactos.git& ... efine%20DO_ tells us that the flag in question is DO_VERIFY_VOLUME. So we can search for places that use this flag: https://git.reactos.org/?p=reactos.git& ... IFY_VOLUME
The flag doesn't seem to get set by ntoskrnl, so it's likely to be cdfs's CdMarkRealDevForVerify: https://git.reactos.org/?p=reactos.git& ... vForVerify
So you might get lucky by adding some prints around those lines in fsctrl.c and verfysup.c. To deal with the asynchronicity it might also be useful to print out the DeviceObject pointer in the same print, so you can be sure that you're looking at the correct device object's flags.

All that said, it may be completely normal for a CD device to occasionally require verification, so perhaps also consider the possibility that it's not the flag that's the problem but the way that cdfs handles it is buggy (or triggering a bug in our kernel or SEH).

berylliumquestion
Posts: 10
Joined: Sun Sep 01, 2019 12:59 am

Re: How to Track Memory or Pointers When Function Calls Are Possibly Asynchronous

Post by berylliumquestion »

Do you have a recommendation on what versions to use? I tried installing MSVC 2013 with WDK 7.10, but I don't think I have them configured right. Would the next versions up work too? I mean, I tried 2019 first, but generating sln didn't work out too well. It might be too new.

I tried adding prints to both verfysup and fstctrl. Only fstctrl is called in the entire process, but it is not called during the time the Flags get changed.

I did something else before I got your reply. I actually copied the KiSwapThread function, changed it so that it has a third parameter, and renamed it so that I didn't have to change anything else in the code. Here's a new bit of info. Here's the new function:

ntoskrnl/ke/thrdschd.c:

Code: Select all

LONG_PTR
FASTCALL
KiSwapThreadDebug(IN PKTHREAD CurrentThread,
             IN PKPRCB Prcb,
             IN PDEVICE_OBJECT DeviceObject )
{
    BOOLEAN ApcState = FALSE;
    KIRQL WaitIrql;
    LONG_PTR WaitStatus;
    PKTHREAD NextThread;
    ASSERT(KeGetCurrentIrql() >= DISPATCH_LEVEL);
    DPRINT1("Flags thrdschd.c start: %I64x\n", DeviceObject->Flags);

    /* Acquire the PRCB lock */
    KiAcquirePrcbLock(Prcb);
    DPRINT1("Flags thrdschd.c #0: %I64x\n", DeviceObject->Flags);

    /* Get the next thread */
    NextThread = Prcb->NextThread;
    DPRINT1("Flags thrdschd.c #1: %I64x\n", DeviceObject->Flags);
    if (NextThread)
    {
        /* Already got a thread, set it up */
        Prcb->NextThread = NULL;
        DPRINT1("Flags thrdschd.c #2: %I64x\n", DeviceObject->Flags);
        Prcb->CurrentThread = NextThread;
        DPRINT1("Flags thrdschd.c #3: %I64x\n", DeviceObject->Flags);
        NextThread->State = Running;
        DPRINT1("Flags thrdschd.c #4: %I64x\n", DeviceObject->Flags);
    }
    else
    {
        /* Try to find a ready thread */
        NextThread = KiSelectReadyThread(0, Prcb);
        DPRINT1("Flags thrdschd.c #5: %I64x\n", DeviceObject->Flags);
        if (NextThread)
        {
            /* Switch to it */
            Prcb->CurrentThread = NextThread;
            DPRINT1("Flags thrdschd.c #6: %I64x\n", DeviceObject->Flags);
            NextThread->State = Running;
            DPRINT1("Flags thrdschd.c #7: %I64x\n", DeviceObject->Flags);
        }
        else
        {
            /* Set the idle summary */
            InterlockedOrSetMember(&KiIdleSummary, Prcb->SetMember);
            DPRINT1("Flags thrdschd.c #8: %I64x\n", DeviceObject->Flags);

            /* Schedule the idle thread */
            NextThread = Prcb->IdleThread;
            DPRINT1("Flags thrdschd.c #9: %I64x\n", DeviceObject->Flags);
            Prcb->CurrentThread = NextThread;
            DPRINT1("Flags thrdschd.c #10: %I64x\n", DeviceObject->Flags);
            NextThread->State = Running;
            DPRINT1("Flags thrdschd.c #11: %I64x\n", DeviceObject->Flags);
        }
    }

    /* Sanity check and release the PRCB */
    ASSERT(CurrentThread != Prcb->IdleThread);
    DPRINT1("Flags thrdschd.c #12: %I64x\n", DeviceObject->Flags);
    KiReleasePrcbLock(Prcb);
    DPRINT1("Flags thrdschd.c #13: %I64x\n", DeviceObject->Flags);

    /* Save the wait IRQL */
    WaitIrql = CurrentThread->WaitIrql;
    DPRINT1("Address of Flags thrdschd.c before: %lx\n", &DeviceObject->Flags);
    DPRINT1("Flags thrdschd.c before: %lx\n", DeviceObject->Flags);
    DPRINT1("KiSwapContext(%I64x, %I64x)\n", WaitIrql, CurrentThread);

    /* Swap contexts */
    ApcState = KiSwapContext(WaitIrql, CurrentThread);
    
    DPRINT1("Address of Flags thrdschd.c after: %lx\n", &DeviceObject->Flags);
    DPRINT1("Flags thrdschd.c after: %lx\n", DeviceObject->Flags);
    DPRINT1("KiSwapContext arguments after function is called (WaitIrql: %I64x, CurrentThread: %I64x)\n", WaitIrql, CurrentThread);
    

    /* Get the wait status */
    WaitStatus = CurrentThread->WaitStatus;
    DPRINT1("Flags thrdschd.c #16: %I64x\n", DeviceObject->Flags);

    /* Check if we need to deliver APCs */
    if (ApcState)
    {
        /* Lower to APC_LEVEL */
        KeLowerIrql(APC_LEVEL);
        DPRINT1("Flags thrdschd.c #17: %I64x\n", DeviceObject->Flags);

        /* Deliver APCs */
        KiDeliverApc(KernelMode, NULL, NULL);
        DPRINT1("Flags thrdschd.c #18: %I64x\n", DeviceObject->Flags);
        ASSERT(WaitIrql == 0);
        DPRINT1("Flags thrdschd.c #19: %I64x\n", DeviceObject->Flags);
    }

    DPRINT1("Flags thrdschd.c #20: %I64x\n", DeviceObject->Flags);
    /* Lower IRQL back to what it was and return the wait status */
    KeLowerIrql(WaitIrql);
    DPRINT1("Flags thrdschd.c end: %I64x\n", DeviceObject->Flags);
    return WaitStatus;
}
Shortened log:

Code: Select all

(ntoskrnl/ke/thrdschd.c:495) Address of Flags thrdschd.c before: b4cb2054
(ntoskrnl/ke/thrdschd.c:496) Flags thrdschd.c before: 150
(ntoskrnl/ke/thrdschd.c:497) KiSwapContext(b4cafae000000001, b49c0908b4cafae0)
(ntoskrnl/ke/thrdschd.c:502) Address of Flags thrdschd.c after: b4cb2054
(ntoskrnl/ke/thrdschd.c:503) Flags thrdschd.c after: 152
(ntoskrnl/ke/thrdschd.c:504) KiSwapContext arguments after function is called (WaitIrql: b4cafae000000001, CurrentThread: b49c0908b4cafae0)
Can't really use any sort of print statements within KiSwapContext function because it's in assembly. So, I think I might need to switch to WinDBG.

User avatar
binarymaster
Posts: 368
Joined: Sun Nov 16, 2014 7:05 pm
Location: Russia, Moscow
Contact:

Re: How to Track Memory or Pointers When Function Calls Are Possibly Asynchronous

Post by binarymaster »

berylliumquestion wrote:
Wed Dec 25, 2019 4:28 am
I tried 2019 first, but generating sln didn't work out too well. It might be too new.
Yes, sln doesn't work. But it will work with VS2019 and ninja.

Just open VS command prompt, change the directory to ReactOS source tree, and run it the same way as you do with RosBE:

Code: Select all

configure.cmd
cd output-VS-i386
ninja bootcd

berylliumquestion
Posts: 10
Joined: Sun Sep 01, 2019 12:59 am

Re: How to Track Memory or Pointers When Function Calls Are Possibly Asynchronous

Post by berylliumquestion »

Well, I had. I just that doing that would mean that it wouldn't have WinDBG, but then I thought about it again and realized I hadn't even checked if that were really true.

In any case, building it with MSVC makes it stop even sooner with a BSoD that says this at the bottom.

Code: Select all

*** STOP: 0x0000007F (0x00000008,0x80819000,0x00000000,0x00000000)
For some strange reason the serial output says it's calling kd64/kdio.c, but it should be calling kd/kdio.c since the system is 32 bit.

When I remove the hdd, it just becomes stuck in a loop.

However, it works just fine in QEMU.

Post Reply

Who is online

Users browsing this forum: No registered users and 2 guests