Why don't my os_log entries show up until the second time my driver loads?

Question

Created 1w

Replies 3

Boosts 0

Participants 2

I'm in the process of writing a DriverKit USBHostInterface driver, and while I'm finally starting to get there, I've run into a bit of a frustration with logging.

Naturally I have a liberal amount of os_log calls that I'm using to troubleshoot my driver. However I've noticed that they don't show up until after the first time my driver has loaded.

Meaning, for example, suppose I make a new build of my driver and it's bundled user-mode app, install the bundle to /Applications, run the installer, verify it took with systemextensionsctl list, fire up Console and start streaming log entries, then plug in my device.

I can see the log entries that show that my driver is loaded, etc., then a bunch of kernel -> <private> log entries, but none of my Start method log entries.

If I unplug my device and plug it in again, my log entries show up as expected.

Why is this and, more importantly, how can I fix it? I'd like to see those log entries the first time the driver loads, if I could.

Answered by DTS Engineer in 881676022

Why is this and

To be perfectly honest, I have no idea.

There's a thread about logging in DriverKit logging here that might be worth reviewing, but that's primarily about issues with IOLog redaction, which is different than you're describing. I can't think of any reason why we'd redact the first run but not later runs. I suspect there is some kind of bug involved, but I'm going to run this by Quinn to see what he thinks.

Bonus Thought:
How are you signing your DEXT? Are you using automatic signing with the Development Only profiles (modern/good) or disabling SIP (old/bad)? This a blind guess, but it's possible the old (SIP disabled) approach might cause something weird like this, depending on exactly how the build was signed. See this post for more information on how to sign DEXT.

However, I do have two ideas for this:

more importantly, how can I fix it?

The post above mentions this in passing, but Quinn's "Recording Private Data in the System Log" post describes how you can manually control how redaction works and the "Sysdiagnose (Unredacted)" profile applies that approach to "everything". Theoretically, either approach should get you around whatever is going on.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Boost

Answer 1

DTS Engineer OP

Apple

6d

Recommended

Why is this and

To be perfectly honest, I have no idea.

There's a thread about logging in DriverKit logging here that might be worth reviewing, but that's primarily about issues with IOLog redaction, which is different than you're describing. I can't think of any reason why we'd redact the first run but not later runs. I suspect there is some kind of bug involved, but I'm going to run this by Quinn to see what he thinks.

Bonus Thought:
How are you signing your DEXT? Are you using automatic signing with the Development Only profiles (modern/good) or disabling SIP (old/bad)? This a blind guess, but it's possible the old (SIP disabled) approach might cause something weird like this, depending on exactly how the build was signed. See this post for more information on how to sign DEXT.

However, I do have two ideas for this:

more importantly, how can I fix it?

The post above mentions this in passing, but Quinn's "Recording Private Data in the System Log" post describes how you can manually control how redaction works and the "Sysdiagnose (Unredacted)" profile applies that approach to "everything". Theoretically, either approach should get you around whatever is going on.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

0

Answer 2

DTS Engineer OP

Apple

6d

I'm in the process of writing a DriverKit USBHostInterface driver, and while I'm finally starting to get there, I've run into a bit of a frustration with logging.

One unrelated question— what are you actually trying to do? More specifically, are you just doing vendor-specific communication or are you actually trying to integrate a USB device into the general system?

It's gotten a bit lost by the introduction of DriverKit, but if you're only doing vendor-specific communication, you don't actually need a DEXT at all. The IOUSBHost Framework will do exactly what you need with a LOT less effort than DriverKit. Even if the system has a class driver that's getting in the way, a codeless DEXT will get that out of the way with minimal work.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

0

Answer 3

DTS Engineer OP

Apple

5d

...and Quinn's answer is...

but I'm going to run this by Quinn to see what he thinks.

...no idea. If you have a moment, please file a bug on this and post the bug number back here. As part of the bug, please reproduce the issue, noting the times you:

Initially install the driver
First load (when logging fails)
Unload
Second load (when logging succeeds)
Unload
Third load (when logging succeeds)

...then collect a sysdiagnose and upload it to the bug. As you go through that process, try to go relatively slowly, pausing between each step, and then wait a minute or two before triggering the sysdiagnose. That helps disperse the logging data over time, which makes it easier to understand follow the process.

__
Kevin Elliott
DST Engineer, CoreOS/Hardware

0