Hello everyone,
I've encountered a very strange and persistent logging issue with my DriverKit DEXT and would appreciate any insights from the community.
[Problem Summary]
My DriverKit DEXT, along with its companion Swift app, is functionally working perfectly.
I can repeatedly call methods in the DEXT from the app (e.g., a Ping-Pong test and a StaticProcessInbandTask call) and receive the correct response every time.
However, the os_log messages within my IOUserClient subclass are only successfully recorded for the very first set of interactions. After that, all subsequent logs are completely missing.
What's even stranger is that all successfully recorded logs are attributed to the kernel: process, even for purely user-space methods like ExternalMethod.
[Development Environment]
- macOS: 15.7.1
- Xcode: 16.4
- Hardware: MacBook Pro M1
DEXT Logging Macro (Log.h):
#include <os/log.h>
#define Log(fmt, ...) \
do { \
os_log(OS_LOG_DEFAULT, "[%{public}s] " fmt, __FUNCTION__, ##__VA_ARGS__); \
} while (0)
[Steps to Reproduce & Observed Behavior]
- The DEXT is successfully loaded via the companion app.
- I click the "Ping-Pong" button, then the "Process InBand" button in the app. The app's UI log correctly shows that the request was sent and a successful response was received from the DEXT.
- I repeat step 2 multiple times. Each interaction works flawlessly from the app's perspective.
- I then use the log show command to export the logs from this period, for example:
log show --last 5m | grep "com.accusys.Acxxx.driver" > dext_logs.txt
- Observed Result (Log Content):
In the dext_logs.txt file, I can only see the logs from the very first Ping-Pong and the very first Process InBand call. All subsequent, successful operations leave no trace in the logs.
kernel: (com.accusys.Acxxx.driver.dext) [ExternalMethod] // { ---
kernel: (com.accusys.Acxxx.driver.dext) [ExternalMethod] // --- }
kernel: (com.accusys.Acxxx.driver.dext) [StaticPingPong] // { ---
kernel: (com.accusys.Acxxx.driver.dext) [StaticPingPong] // --- }
kernel: (com.accusys.Acxxx.driver.dext) [ExternalMethod] // { ---
kernel: (com.accusys.Acxxx.driver.dext) [ExternalMethod] // --- }
kernel: (com.accusys.Acxxx.driver.dext) [StaticProcessInbandTask] // { ---
kernel: (com.accusys.Acxxx.driver.dext) [StaticProcessInbandTask] // --- }
<--- END OF FILE (No new logs appear after this point) --->
[Core Questions]
- Why are logs in IOUserClient subclass only recorded once? Given the DEXT is clearly still running and processing requests, why would os_log calls only succeed in writing to the system log database on the first interaction?
- Why are all logs attributed to the kernel? Why would logs from 100% user-space code like ExternalMethod and StaticPingPong be attributed to the kernel process?
[Solutions Attempted That Did Not Work]
- I have verified with
ps auxthat the DEXT process (com.accusys.Acxxx.driver) is running continuously in the background and has not crashed. - Attempted to force-restart the logging service with
sudo killall logd,but the issue persists. - Performed the most thorough reset possible using
systemextensionsctl resetfollowed by a full reboot, then reinstalled the DEXT. The issue remains exactly the same.
Thank you for any possible help or suggestions
Best, Charles
So, let me start here:
Why are all logs attributed to the kernel?
Because that's where the logs came from. More specifically, the "os_log" function you are calling in DriverKit is not the same "os_log" function that exists in userspace. It actually does IPC into the kernel, which then logs out through the kernel’s logging infrastructure.
Why would logs from 100% user-space code like ExternalMethod and StaticPingPong be attributed to the kernel process?
I think the term "user-space" is deeply misleading when it comes to DriverKit. While it’s true in the basic technical sense, it is DEEPLY misleading when it comes to the "practical" relationship a DEXT has with the rest of the system. Practically speaking, your DEXT has very little "connection" to the larger system. It talks the kernel through the underlying DEXT infrastructure and it talks to user space through IOUserClient. That's ALL that exists, so the "direct" answer is that it's logging through the kernel because that's the only way it can log.
WHY it works that way... is for exactly the same reason the kernel doesn't log its own data*. It's basically impossible for the kernel to "know" exactly what it's interacting with and how those interactions will affect the larger system, so the simplest solution is to route all I/O "out" of the kernel so that the kernel’s own writes go through the standard I/O channel.
*The kernel sends log data out to user space, which then writes the data to disk.
Moving to the issue here:
Why are logs in IOUserClient subclass only recorded once? Given the DEXT is clearly still running and processing requests, why would os_log calls only succeed in writing to the system log database on the first interaction?
I don't know, but my first guess would be that it IS in fact logging, but the messages are being missed for some other reason. The first thing I would do is replicate the issue, trigger a sysdiagnose, then go look at the full console archive to see exactly what's in the log. I'd use your log command to get the last working message, find that message in the console archive, then trace the kernel "forward" from there to see what you find. I'm not sure what you will find, but I suspect you'll find that the messages are actually "there" and that the problem is that "log" isn't giving you what you expect or grep isn't filtering correctly.
Finally, I'm not entire confident that your logging macro actually works, at least not reliably. See this forum post for the details and alternative implementation.
__
Kevin Elliott
DTS Engineer, CoreOS/Hardware
