Why is my PsSetCreateThreadNotifyRoutine callback called at APC_LEVEL?

Hi,

I’ve inherited a file system driver and am doing some testing with driver verifier enabled. I am testing on an up-to-date Windows 8 system. In summary, my drivers cause a driver verifier violation, however based on the MSDN documentation they are behaving correctly.

The violation occurs during OS shutdown, in the driver’s thread create notify callback (set using PsSetCreateThreadNotifyRoutine). My driver calls ZwClose on a thread handle, and the call is made at APC_LEVEL. Bad move driver!

DRIVER_VERIFIER_DETECTED_VIOLATION (c4)
A device driver attempting to corrupt the system has been caught. This is
because the driver was specified in the registry as being suspect (by the
administrator) and the kernel has enabled substantial checking of this driver.
If the driver attempts to corrupt the system, bugchecks 0xC4, 0xC1 and 0xA will
be among the most commonly seen crashes.
Arguments:
Arg1: 0002001f, ID of the ‘IrqlZwPassive’ rule that was violated.
Arg2: 85809fd6, A pointer to the string describing the violated rule condition.
Arg3: 00000000, An optional pointer to the rule state variable(s).
Arg4: 00000000, Reserved (unused)

Debugging Details:

DV_VIOLATED_CONDITION: ZwClose should only be called at IRQL = PASSIVE_LEVEL.
DV_MSDN_LINK: !url http://go.microsoft.com/fwlink/?LinkId=216048
DV_RULE_INFO: !ruleinfo 0x2001f
BUGCHECK_STR: 0xc4_IrqlZwPassive_XDV
DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT
PROCESS_NAME: wininit.exe
CURRENT_IRQL: 1
LAST_CONTROL_TRANSFER: from 81109fc7 to 810e1ca4

Here’s the stack:

ChildEBP RetAddr
9157f534 8126306c MyDriver!create_thread_notify_routine+0x15
9157f620 812934cc nt!PspInsertThread+0x5db
9157f7d4 812a8a7b nt!PspCreateThread+0x1db
9157f92c 812a8965 nt!PsCreateSystemThreadEx+0x104
9157f95c 81231069 nt!PsCreateSystemThread+0x26
9157f9dc 8123262c nt!PopFlushVolumes+0x217
9157faa0 81156978 nt!NtSetSystemPowerState+0x424
9157faa0 810de87d nt!KiSystemServicePostCall
9157fb24 81243c00 nt!ZwSetSystemPowerState+0x11
9157fbf4 813fd0a9 nt! ?? ::OKHAJAOM::`string’+0x34fc
9157fc08 81156978 nt!NtShutdownSystem+0x32
9157fc08 77627174 nt!KiSystemServicePostCall
00adf6b8 77624dae ntdll!KiFastSystemCallRet
00adf6bc 008fda38 ntdll!NtShutdownSystem+0xa
00adf6e8 008f8b81 wininit!WinInitShutdown+0x379
00adf76c 008f5f08 wininit!WinMain+0xe93
00adf7fc 76bb173e wininit!_initterm_e+0x169
00adf808 77666911 KERNEL32!BaseThreadInitThunk+0xe
00adf84c 776668bd ntdll!__RtlUserThreadStart+0x4a
00adf85c 00000000 ntdll!_RtlUserThreadStart+0x1c

Okay, so clearly my driver is doing something bad. BUT… it should never reach this point. An excerpt from the MSDN documentation for PsSetCreateThreadNotifyRoutine:

“The driver’s thread-notify routine runs at IRQL = PASSIVE_LEVEL. When a thread is created, the thread-notify routine runs in the context of the thread that created the new thread. When a thread is deleted, the thread-notify routine runs in the context of this thread when the thread exits.”

Unfortunately, in this case we are running at IRQL = APC_LEVEL, and things go bad.

So, is this a bug in Windows or a bug in the documentation? Either way, I’ll have to fix it in my code but I’d like to know a bit more about what is going wrong.

Thanks,
Alnoor

That’s certainly a bug somewhere. Are you actually running at APC_LEVEL
(KeGetCurrentIrql() == APC_LEVEL) or are you in a guarded region
(KTHREAD.SpecialApcDisable < 0)?

My suspicion is that you’re in a guarded region, which points to someone
having a lock acquired around this call. This means that you ARE running at
IRQL PASSIVE_LEVEL but with APC_LEVEL semantics. This makes it a bit tricky
to point the finger, but if that is the case I would blame whoever is
calling PsCreateSystemThread from the guarded region.

-scott
OSR

wrote in message news:xxxxx@ntdev…

Hi,

I’ve inherited a file system driver and am doing some testing with driver
verifier enabled. I am testing on an up-to-date Windows 8 system. In
summary, my drivers cause a driver verifier violation, however based on the
MSDN documentation they are behaving correctly.

The violation occurs during OS shutdown, in the driver’s thread create
notify callback (set using PsSetCreateThreadNotifyRoutine). My driver calls
ZwClose on a thread handle, and the call is made at APC_LEVEL. Bad move
driver!

DRIVER_VERIFIER_DETECTED_VIOLATION (c4)
A device driver attempting to corrupt the system has been caught. This is
because the driver was specified in the registry as being suspect (by the
administrator) and the kernel has enabled substantial checking of this
driver.
If the driver attempts to corrupt the system, bugchecks 0xC4, 0xC1 and 0xA
will
be among the most commonly seen crashes.
Arguments:
Arg1: 0002001f, ID of the ‘IrqlZwPassive’ rule that was violated.
Arg2: 85809fd6, A pointer to the string describing the violated rule
condition.
Arg3: 00000000, An optional pointer to the rule state variable(s).
Arg4: 00000000, Reserved (unused)

Debugging Details:

DV_VIOLATED_CONDITION: ZwClose should only be called at IRQL =
PASSIVE_LEVEL.
DV_MSDN_LINK: !url http://go.microsoft.com/fwlink/?LinkId=216048
DV_RULE_INFO: !ruleinfo 0x2001f
BUGCHECK_STR: 0xc4_IrqlZwPassive_XDV
DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT
PROCESS_NAME: wininit.exe
CURRENT_IRQL: 1
LAST_CONTROL_TRANSFER: from 81109fc7 to 810e1ca4

Here’s the stack:

ChildEBP RetAddr
9157f534 8126306c MyDriver!create_thread_notify_routine+0x15
9157f620 812934cc nt!PspInsertThread+0x5db
9157f7d4 812a8a7b nt!PspCreateThread+0x1db
9157f92c 812a8965 nt!PsCreateSystemThreadEx+0x104
9157f95c 81231069 nt!PsCreateSystemThread+0x26
9157f9dc 8123262c nt!PopFlushVolumes+0x217
9157faa0 81156978 nt!NtSetSystemPowerState+0x424
9157faa0 810de87d nt!KiSystemServicePostCall
9157fb24 81243c00 nt!ZwSetSystemPowerState+0x11
9157fbf4 813fd0a9 nt! ?? ::OKHAJAOM::`string’+0x34fc
9157fc08 81156978 nt!NtShutdownSystem+0x32
9157fc08 77627174 nt!KiSystemServicePostCall
00adf6b8 77624dae ntdll!KiFastSystemCallRet
00adf6bc 008fda38 ntdll!NtShutdownSystem+0xa
00adf6e8 008f8b81 wininit!WinInitShutdown+0x379
00adf76c 008f5f08 wininit!WinMain+0xe93
00adf7fc 76bb173e wininit!_initterm_e+0x169
00adf808 77666911 KERNEL32!BaseThreadInitThunk+0xe
00adf84c 776668bd ntdll!__RtlUserThreadStart+0x4a
00adf85c 00000000 ntdll!_RtlUserThreadStart+0x1c

Okay, so clearly my driver is doing something bad. BUT… it should never
reach this point. An excerpt from the MSDN documentation for
PsSetCreateThreadNotifyRoutine:

“The driver’s thread-notify routine runs at IRQL = PASSIVE_LEVEL. When a
thread is created, the thread-notify routine runs in the context of the
thread that created the new thread. When a thread is deleted, the
thread-notify routine runs in the context of this thread when the thread
exits.”

Unfortunately, in this case we are running at IRQL = APC_LEVEL, and things
go bad.

So, is this a bug in Windows or a bug in the documentation? Either way, I’ll
have to fix it in my code but I’d like to know a bit more about what is
going wrong.

Thanks,
Alnoor

Hi Scott,

I’m actually running at APC_LEVEL. To test this, I’ve modified my notify routine as such:

create_thread_notify_routine(
__in HANDLE process_id,
__in HANDLE thread_id,
__in BOOLEAN create
) {
// AA: The docs say that this routine is called at PASSIVE_LEVEL, but during Win8 shutdown, I have
// observed it being called at APC level.
if (PASSIVE_LEVEL != KeGetCurrentIrql())
{
return;
}

If I set a breakpoint on the ‘return;’ line, it invariably gets hit during shutdown. The stack trace is the same each time.

Technically this code change only proves that I’m not running at PASSIVE_LEVEL, but that still breaks the contract specified in the docs.

I’m sensing you feel like this is a Windows bug? I’m not sure if I’m missing some sort of subtlety here.

Thanks,
Alnoor

Is there also a way to query if it isa guarded region? Given the OP’s
example of testing the IRQL level, there seems to be no issue with adding
a guarded-region test.

OP: if there is a guarded-region test, save the current IRQL and the
guarded-region values in variables and print them out.

It sounds like this passive-level-with-APC-semantics issue is not clear.
The docs should say “PASSIVE_LEVEL” only if the KeGetCurrentIrql ==
PASSIVE_LEVEL, and otherwise it should say “or APC_LEVEL in a guarded
context”; this may need to be a pervasive change. It also suggests that
Driver Verifier should recognize a guarded APC as, as you put it,
“PASSIVE_LEVEL with APC_LEVEL semantics”.

Or, of course, it might actually be a bug.
joe

That’s certainly a bug somewhere. Are you actually running at APC_LEVEL
(KeGetCurrentIrql() == APC_LEVEL) or are you in a guarded region
(KTHREAD.SpecialApcDisable < 0)?

My suspicion is that you’re in a guarded region, which points to someone
having a lock acquired around this call. This means that you ARE running
at
IRQL PASSIVE_LEVEL but with APC_LEVEL semantics. This makes it a bit
tricky
to point the finger, but if that is the case I would blame whoever is
calling PsCreateSystemThread from the guarded region.

-scott
OSR

wrote in message news:xxxxx@ntdev…

Hi,

I’ve inherited a file system driver and am doing some testing with driver
verifier enabled. I am testing on an up-to-date Windows 8 system. In
summary, my drivers cause a driver verifier violation, however based on
the
MSDN documentation they are behaving correctly.

The violation occurs during OS shutdown, in the driver’s thread create
notify callback (set using PsSetCreateThreadNotifyRoutine). My driver
calls
ZwClose on a thread handle, and the call is made at APC_LEVEL. Bad move
driver!

DRIVER_VERIFIER_DETECTED_VIOLATION (c4)
A device driver attempting to corrupt the system has been caught. This is
because the driver was specified in the registry as being suspect (by the
administrator) and the kernel has enabled substantial checking of this
driver.
If the driver attempts to corrupt the system, bugchecks 0xC4, 0xC1 and 0xA
will
be among the most commonly seen crashes.
Arguments:
Arg1: 0002001f, ID of the ‘IrqlZwPassive’ rule that was violated.
Arg2: 85809fd6, A pointer to the string describing the violated rule
condition.
Arg3: 00000000, An optional pointer to the rule state variable(s).
Arg4: 00000000, Reserved (unused)

Debugging Details:

DV_VIOLATED_CONDITION: ZwClose should only be called at IRQL =
PASSIVE_LEVEL.
DV_MSDN_LINK: !url http://go.microsoft.com/fwlink/?LinkId=216048
DV_RULE_INFO: !ruleinfo 0x2001f
BUGCHECK_STR: 0xc4_IrqlZwPassive_XDV
DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT
PROCESS_NAME: wininit.exe
CURRENT_IRQL: 1
LAST_CONTROL_TRANSFER: from 81109fc7 to 810e1ca4

Here’s the stack:

ChildEBP RetAddr
9157f534 8126306c MyDriver!create_thread_notify_routine+0x15
9157f620 812934cc nt!PspInsertThread+0x5db
9157f7d4 812a8a7b nt!PspCreateThread+0x1db
9157f92c 812a8965 nt!PsCreateSystemThreadEx+0x104
9157f95c 81231069 nt!PsCreateSystemThread+0x26
9157f9dc 8123262c nt!PopFlushVolumes+0x217
9157faa0 81156978 nt!NtSetSystemPowerState+0x424
9157faa0 810de87d nt!KiSystemServicePostCall
9157fb24 81243c00 nt!ZwSetSystemPowerState+0x11
9157fbf4 813fd0a9 nt! ?? ::OKHAJAOM::`string’+0x34fc
9157fc08 81156978 nt!NtShutdownSystem+0x32
9157fc08 77627174 nt!KiSystemServicePostCall
00adf6b8 77624dae ntdll!KiFastSystemCallRet
00adf6bc 008fda38 ntdll!NtShutdownSystem+0xa
00adf6e8 008f8b81 wininit!WinInitShutdown+0x379
00adf76c 008f5f08 wininit!WinMain+0xe93
00adf7fc 76bb173e wininit!_initterm_e+0x169
00adf808 77666911 KERNEL32!BaseThreadInitThunk+0xe
00adf84c 776668bd ntdll!__RtlUserThreadStart+0x4a
00adf85c 00000000 ntdll!_RtlUserThreadStart+0x1c

Okay, so clearly my driver is doing something bad. BUT… it should never
reach this point. An excerpt from the MSDN documentation for
PsSetCreateThreadNotifyRoutine:

“The driver’s thread-notify routine runs at IRQL = PASSIVE_LEVEL. When a
thread is created, the thread-notify routine runs in the context of the
thread that created the new thread. When a thread is deleted, the
thread-notify routine runs in the context of this thread when the thread
exits.”

Unfortunately, in this case we are running at IRQL = APC_LEVEL, and things
go bad.

So, is this a bug in Windows or a bug in the documentation? Either way,
I’ll
have to fix it in my code but I’d like to know a bit more about what is
going wrong.

Thanks,
Alnoor


NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

Isn’t this enough that the debugger shows
the current IRQL as 1? Can the captured IRQL be wrong?

On 26-Sep-2013 21:47, alnoor.allidina@ wrote:
> Debugging Details:
> ------------------
>
> DV_VIOLATED_CONDITION: ZwClose should only be called at IRQL =
PASSIVE_LEVEL.

> PROCESS_NAME: wininit.exe
> CURRENT_IRQL: 1

Regards,
– pa

>Isn’t this enough that the debugger shows the current IRQL as 1? Can the captured IRQL be wrong?

When you get a bugcheck, the IRQL in the debugger is meaningless (always at least 2).

Interesting, many of the uses of APC_LEVEL (and APC_LEVEL serialization
primitives) are gone from the O/S so that’s why I assumed the guarded
region.

I’m sensing you feel like this is a Windows bug? I’m not sure if I’m
missing some sort of subtlety here.

Yes, I suspect it’s a bug. Here the create thread notify routine is called
as a result of the call to PsCreateSystemThread. PsCreateSystemThread has an
IRQL restriction of PASSIVE_LEVEL, so your callback should run at
PASSIVE_LEVEL. In this case, the call to PsCreateSystemThread is being
called by PopFlushVolumes:

nt!PsCreateSystemThread+0x26
nt!PopFlushVolumes+0x217

So my guess is that PopFlushVolumes is raising the IRQL either directly or
indirectly (it’s also possible that NtSetSystemPowerState is doing it, but
I’d start at PopFlushVolumes). It should be easy to confirm, just set a
breakpoint at nt!PopFlushVolumes and run !irql. If the IRQL is
PASSIVE_LEVEL, you can step and run !irql periodically to see where the IRQL
is raised.

-scott
OSR

wrote in message news:xxxxx@ntdev…

Hi Scott,

I’m actually running at APC_LEVEL. To test this, I’ve modified my notify
routine as such:

create_thread_notify_routine(
__in HANDLE process_id,
__in HANDLE thread_id,
__in BOOLEAN create
) {
// AA: The docs say that this routine is called at PASSIVE_LEVEL, but during
Win8 shutdown, I have
// observed it being called at APC level.
if (PASSIVE_LEVEL != KeGetCurrentIrql())
{
return;
}

If I set a breakpoint on the ‘return;’ line, it invariably gets hit during
shutdown. The stack trace is the same each time.

Technically this code change only proves that I’m not running at
PASSIVE_LEVEL, but that still breaks the contract specified in the docs.

I’m sensing you feel like this is a Windows bug? I’m not sure if I’m missing
some sort of subtlety here.

Thanks,
Alnoor

>Is there also a way to query if it isa guarded region?

KeAreAllApcsDisabled lets you know if you are in a guarded region OR if the
IRQL >= APC_LEVEL. There is no way to check specifically for a guarded
region.

-scott
OSR

wrote in message news:xxxxx@ntdev…

Is there also a way to query if it isa guarded region? Given the OP’s
example of testing the IRQL level, there seems to be no issue with adding
a guarded-region test.

OP: if there is a guarded-region test, save the current IRQL and the
guarded-region values in variables and print them out.

It sounds like this passive-level-with-APC-semantics issue is not clear.
The docs should say “PASSIVE_LEVEL” only if the KeGetCurrentIrql ==
PASSIVE_LEVEL, and otherwise it should say “or APC_LEVEL in a guarded
context”; this may need to be a pervasive change. It also suggests that
Driver Verifier should recognize a guarded APC as, as you put it,
“PASSIVE_LEVEL with APC_LEVEL semantics”.

Or, of course, it might actually be a bug.
joe

That’s certainly a bug somewhere. Are you actually running at APC_LEVEL
(KeGetCurrentIrql() == APC_LEVEL) or are you in a guarded region
(KTHREAD.SpecialApcDisable < 0)?

My suspicion is that you’re in a guarded region, which points to someone
having a lock acquired around this call. This means that you ARE running
at
IRQL PASSIVE_LEVEL but with APC_LEVEL semantics. This makes it a bit
tricky
to point the finger, but if that is the case I would blame whoever is
calling PsCreateSystemThread from the guarded region.

-scott
OSR

wrote in message news:xxxxx@ntdev…

Hi,

I’ve inherited a file system driver and am doing some testing with driver
verifier enabled. I am testing on an up-to-date Windows 8 system. In
summary, my drivers cause a driver verifier violation, however based on
the
MSDN documentation they are behaving correctly.

The violation occurs during OS shutdown, in the driver’s thread create
notify callback (set using PsSetCreateThreadNotifyRoutine). My driver
calls
ZwClose on a thread handle, and the call is made at APC_LEVEL. Bad move
driver!

DRIVER_VERIFIER_DETECTED_VIOLATION (c4)
A device driver attempting to corrupt the system has been caught. This is
because the driver was specified in the registry as being suspect (by the
administrator) and the kernel has enabled substantial checking of this
driver.
If the driver attempts to corrupt the system, bugchecks 0xC4, 0xC1 and 0xA
will
be among the most commonly seen crashes.
Arguments:
Arg1: 0002001f, ID of the ‘IrqlZwPassive’ rule that was violated.
Arg2: 85809fd6, A pointer to the string describing the violated rule
condition.
Arg3: 00000000, An optional pointer to the rule state variable(s).
Arg4: 00000000, Reserved (unused)

Debugging Details:

DV_VIOLATED_CONDITION: ZwClose should only be called at IRQL =
PASSIVE_LEVEL.
DV_MSDN_LINK: !url http://go.microsoft.com/fwlink/?LinkId=216048
DV_RULE_INFO: !ruleinfo 0x2001f
BUGCHECK_STR: 0xc4_IrqlZwPassive_XDV
DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT
PROCESS_NAME: wininit.exe
CURRENT_IRQL: 1
LAST_CONTROL_TRANSFER: from 81109fc7 to 810e1ca4

Here’s the stack:

ChildEBP RetAddr
9157f534 8126306c MyDriver!create_thread_notify_routine+0x15
9157f620 812934cc nt!PspInsertThread+0x5db
9157f7d4 812a8a7b nt!PspCreateThread+0x1db
9157f92c 812a8965 nt!PsCreateSystemThreadEx+0x104
9157f95c 81231069 nt!PsCreateSystemThread+0x26
9157f9dc 8123262c nt!PopFlushVolumes+0x217
9157faa0 81156978 nt!NtSetSystemPowerState+0x424
9157faa0 810de87d nt!KiSystemServicePostCall
9157fb24 81243c00 nt!ZwSetSystemPowerState+0x11
9157fbf4 813fd0a9 nt! ?? ::OKHAJAOM::`string’+0x34fc
9157fc08 81156978 nt!NtShutdownSystem+0x32
9157fc08 77627174 nt!KiSystemServicePostCall
00adf6b8 77624dae ntdll!KiFastSystemCallRet
00adf6bc 008fda38 ntdll!NtShutdownSystem+0xa
00adf6e8 008f8b81 wininit!WinInitShutdown+0x379
00adf76c 008f5f08 wininit!WinMain+0xe93
00adf7fc 76bb173e wininit!_initterm_e+0x169
00adf808 77666911 KERNEL32!BaseThreadInitThunk+0xe
00adf84c 776668bd ntdll!__RtlUserThreadStart+0x4a
00adf85c 00000000 ntdll!_RtlUserThreadStart+0x1c

Okay, so clearly my driver is doing something bad. BUT… it should never
reach this point. An excerpt from the MSDN documentation for
PsSetCreateThreadNotifyRoutine:

“The driver’s thread-notify routine runs at IRQL = PASSIVE_LEVEL. When a
thread is created, the thread-notify routine runs in the context of the
thread that created the new thread. When a thread is deleted, the
thread-notify routine runs in the context of this thread when the thread
exits.”

Unfortunately, in this case we are running at IRQL = APC_LEVEL, and things
go bad.

So, is this a bug in Windows or a bug in the documentation? Either way,
I’ll
have to fix it in my code but I’d like to know a bit more about what is
going wrong.

Thanks,
Alnoor


NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

If the target is >= Server 2003 then yes, this should be correct (the IRQL
is saved prior to entering the bugcheck code). I simply missed this in the
scanning of the output.

-scott
OSR

“Pavel A.” wrote in message news:xxxxx@ntdev…

Isn’t this enough that the debugger shows
the current IRQL as 1? Can the captured IRQL be wrong?

On 26-Sep-2013 21:47, alnoor.allidina@ wrote:

Debugging Details:

DV_VIOLATED_CONDITION: ZwClose should only be called at IRQL =
PASSIVE_LEVEL.

PROCESS_NAME: wininit.exe
CURRENT_IRQL: 1

Regards,
– pa