0

Recently, I've tested my kext on 10.14 and it seem to run smoothly for a while. But after some random time(can take few minutes), It produces the following panic : 

thread_invoke: preemption_level -1, possible cause: unlocking an
unlocked mutex or spinlock"

This I've ran my code several times and have noticed that the panic may be triggered by either my user-space daemon while calling psynch_cvwait sys call or directly from the kernel extension while triggering context switch after calling msleep function.

Here's a trace from the kernel :

frame #4: 0xffffff800afe24a3 kernel`panic(str=<unavailable>) at debug.c:620 [opt]
frame #5: 0xffffff800affef06 kernel`thread_invoke(self=0xffffff801b7a4030, thread=0xffffff801afe4540, reason=0) at sched_prim.c:2261 [opt]
frame #6: 0xffffff800affdaff kernel`thread_block_reason(continuation=<unavailable>, parameter=<unavailable>, reason=<unavailable>) at sched_prim.c:3088 [opt]
frame #7: 0xffffff800b4fcfe1 kernel`_sleep [inlined] thread_block(continuation=<unavailable>) at sched_prim.c:3104 [opt]
frame #8: 0xffffff800b4fcfd6 kernel`_sleep(chan=<unavailable>, pri=0, wmsg=<unavailable>, abstime=1299691844730, continuation=0x0000000000000000, mtx=0x0000000000000000) at kern_synch.c:251 [opt]
frame #9: 0xffffff800b4fd352 kernel`msleep(chan=0x01000004001ddd89, mtx=0x0000000000000000, pri=0, wmsg="", ts=<unavailable>) at kern_synch.c:346 [opt]

And next is a stack trace triggered from the user-space daemon sys call:

frame #4: 0xffffff800afe24a3 kernel`panic(str=<unavailable>) at debug.c:620 [opt]
frame #5: 0xffffff800affef06 kernel`thread_invoke(self=0xffffff80176f5a50, thread=0xffffff8019a5de60, reason=0) at sched_prim.c:2261 [opt]
frame #6: 0xffffff800affdaff kernel`thread_block_reason(continuation=<unavailable>, parameter=<unavailable>, reason=<unavailable>) at sched_prim.c:3088 [opt]
frame #7: 0xffffff7f8cbf5080
frame #8: 0xffffff7f8cbf6dcf
frame #9: 0xffffff800b499c3c kernel`psynch_cvwait(p=<unavailable>, uap=<unavailable>, retval=<unavailable>) at pthread_shims.c:397 [opt]

where the missing frames belongs to extension com.apple.kec.pthread(1.0)[C69B97C1-505D-3629-9D64-7B7BC6D780A8]@0xffffff7f8cbf3000->0xffffff7f8cbfafff

At first I thought it might be caused from random memory corruption, but it looks that after all my reproductions, no other entity besides the 2 I just mentioned triggered the panic.

If I look at the panic message, it connected to value that may be found in %gs register per processor, where the preemption level is kept. However, in lldb I don't have any access to this register and I doubt if it's mapped to my driver memory.

So what I left is to comments parts of my driver and see if the problem persists.. Perhaps any of you have more insights about how to address this problem ?

thanks

Zohar81
  • 4,554
  • 5
  • 29
  • 82

1 Answers1

1

I believe the following lldb command should print the gs register along with all the others:

register read

I've previously only encountered this panic when dealing with spinlocks, as they disable preemption. If your kext does not use spinlocks, and does not explicitly disable preemption via inline assembly, this is probably a bug in macOS, and I would report it to Apple ASAP.

pmdj
  • 22,018
  • 3
  • 52
  • 103
  • I actually using spin locks for very basic tasks in my code. but I would assume that if spinlock trigger the negative preemption level, I should have seen exactly one thread in `showallstacks` whose backtrace contain the `spinlock` function. However, so far I haven't trace such thread. – Zohar81 Jun 14 '18 at 05:58
  • Also, regarding the `%gs` register, I could read it using `register read` and it showed that `gs = 0x000000009da40000`. From the source Code it looks like the gs register is used as the base of `cpu_data_t` region, each CPU using a different address as the base... However, I couldn't read it from lldb using `memory read` (got error 4) – Zohar81 Jun 14 '18 at 06:17