On macOS Kernel/Kext Logging

I spent the better part of the last two days trying to figure out why I was seeing random / missing / corrupt log messages when trying to log from a kext on macOS Sierra. Sometimes the message was in the Console. Sometimes not. If I built a new copy of my kext and unloaded/reloaded, then the Console would just show random gibberish when logging.

The result of my suffering is that this specific combination works reliably:

#include < os/log.h >
* … *
os_log(OS_LOG_DEFAULT, “Your message with optional modifiers.\n”);

Then, from terminal:

log show –predicate ‘senderImagePath CONTAINS “MyKextName”’

(MyKextName is $(ProductName) in Xcode. not a com.whatever.thing. It is also case sensitive) That log command will show only Default messages and Fault messages. If you want to see Debug messages from ` os_log_debug( .. ) ` or Info messages from ` os_log_info( .. ) ` then include –debug and –info. But, these two types are not reliable in my experience.. Sometimes they log successfully, sometimes they don’t. I don’t see that issue with Default & Fault types.

Okay, so why log show, and not the Console.app or log stream? In particular, log stream cannot be used. stream cannot open the kernel process ID 0 for some reason. (I have SIP off, have sudo’d, and am running a development kernel, too), log stream will print some kernel messages, namely those generated by the OS itself. But stream will not show messages sent by my kext, at least. You can see some kind of error occur if you try to use ` log stream —process 0 ` or ` log stream —process kernel ` . Both error “PID not found for 0|kernel”.

I highly recommend playing around with Consolation if you have any trouble with the predicates - https://eclecticlight.co/tag/consolation/ .

Things I still don’t understand:

• Why did loading a new build of my kext corrupt printf and/or IOLog output in Console?
• Why, after a reboot, did the first load of my kext not printf anything in Console?
• Are any of: running a development or debug kernel, setting nvram boot-args, disabling SIP, or creating a custom OS log identifier with os_log_create important or relevant? Not sure, but they don’t appear to be tied to my working combination above.
• I read a lot about how tiny the in-memory log space is and how it gets overwritten if there is too much log printing. Is this relevant? I don’t think so, for my bugs here. I couldn’t print a single string reliably when no other activity was visible in the Console.
• Should you run ` log config –mode ‘level:debug’ ` ? What does ` log config –status ` printing, for me, ` System mode = DEBUG STREAM_LIVE PRIVATE_DATA DEVELOPMENT ` mean?
• Does checking Action -> Include Info Messages and/or Action -> Include Debug Messages change the apparent randomness in whether Console.app prints things? It didn’t for me..

Possibly helpful links to learn more about the system:

https://eclecticlight.co/2017/02/13/bugs-in-the-logs-sierras-new-logging-system-is-a-game-of-chance/
https://eclecticlight.co/2017/02/10/getting-more-out-of-sierras-logs/
https://eclecticlight.co/tag/consolation/
https://developer.apple.com/reference/os/logging
http://devstreaming.apple.com/videos/wwdc/2016/721wh2etddp4ghxhpcg/721/721_unified_logging_and_activity_tracing.pdf
https://forums.developer.apple.com/thread/66471
https://forums.developer.apple.com/thread/72834
https://forums.developer.apple.com/thread/66984
https://developer.apple.com/library/content/samplecode/Logging/Introduction/Intro.html

Last, for anyone searching…:

os_log
printf
IOLog
log stream
log show
Console
Consolation
Unified Logging
Activity Tracing
System_Library_Preferences_Logging/Subsystems
_System_Library_LogPreferences.plist missing kernel logs missing kext logs logs corrupt Console gibberish os x Sierra radar bug report 28948441 sysctl debug.kextlog debug.oslog