Trouble using IOLog from a dext

Trying to use IOLog to print out a message from a dext. When I try to use IOLog, I get <private>, though I did not or thought I did not tag it as private. I have tried to update the info.plist file for the dext according to https://developer.apple.com/forums/thread/705810, but that has not helped, or perhaps I am not defining it correctly since it's a dext. Anyone else had this issue, and how did you fix it?

Answered by DTS Engineer in 825370022

Trying to figure out how to fix this. Any ideas out there?

So, the situation here is actually a bit more complicated than it really needs to be. As far as I can't tell, IOLog was basically written as a compatibility "shim" between DriverKit and the kernel's IOLog implementation. For historical reason, the kernel IOLog does not support the privacy annotations and blocking them in DriverKit ends up creating the situation you're seeing.

If you're looking for a quick "debug only" solution, you should be able to unredact the log data using the instructions in "Recording Private Data in the System Log" or with the "Sysdiagnose (Unredacted)" profile.

However, the correct solution is actually to just use os_log directly. The entire API is not imported, but os_log itself is and that should let you do what you want. Ironically, this is what our "basic" DriverKit sample actually does, it's just easy to over look because the code calls "Log" like this:

// MARK: Dext Lifecycle Management
bool NullDriver::init(void)
{
    bool result = false;

    Log("init()");

...but "Log" is actually a macro defined a the top of NullDriver.cpp:

#include <os/log.h>
...

// This log to makes it easier to parse out individual logs from the driver, since all logs will be prefixed with the same word/phrase.
// DriverKit logging has no logging levels; some developers might want to prefix errors differently than info messages.
// Another option is to #define a "debug" case where some log messages only exist when doing a debug build.
// To search for logs from this driver, use either: `sudo dmesg | grep NullDriver` or use Console.app search to find messages that start with "NullDriver -".
#define Log(fmt, ...) os_log(OS_LOG_DEFAULT, "NullDriver Base - " fmt "\n", ##__VA_ARGS__)

Finally, anticipating the question: "Is there any reason I would want use IOLog instead of os_log?"

"No. The only difference between them is that IOLog will create exactly the behavior above."

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

You need to change your string format specifier from "%s" to "%{public}s"

#include <os/log.h>

os_log(OS_LOG_DEFAULT, "Name: %{public}s", name);

Thank you for replying. That would be the right answer if I was using os_log. However using IOLog with a format string that is a dynamic string, that's the rub. By doing some additional testing, I note the following using a code snippet.

(const char *)e->fmt

LOG_INFO("%s \n", e->fmt);] // prints <private>

LOG_INFO("%{public}s \n", e->fmt); //prints the format string, like "port[%u] link up"

    IOLog((const char *)(e->fmt),
        be32_to_cpu(e->params[0]));

I use e->fmt for the format in IOLog, and because it is a dynamic string, the output from IOLog is <private>.

Trying to figure out how to fix this. Any ideas out there?

Trying to figure out how to fix this. Any ideas out there?

So, the situation here is actually a bit more complicated than it really needs to be. As far as I can't tell, IOLog was basically written as a compatibility "shim" between DriverKit and the kernel's IOLog implementation. For historical reason, the kernel IOLog does not support the privacy annotations and blocking them in DriverKit ends up creating the situation you're seeing.

If you're looking for a quick "debug only" solution, you should be able to unredact the log data using the instructions in "Recording Private Data in the System Log" or with the "Sysdiagnose (Unredacted)" profile.

However, the correct solution is actually to just use os_log directly. The entire API is not imported, but os_log itself is and that should let you do what you want. Ironically, this is what our "basic" DriverKit sample actually does, it's just easy to over look because the code calls "Log" like this:

// MARK: Dext Lifecycle Management
bool NullDriver::init(void)
{
    bool result = false;

    Log("init()");

...but "Log" is actually a macro defined a the top of NullDriver.cpp:

#include <os/log.h>
...

// This log to makes it easier to parse out individual logs from the driver, since all logs will be prefixed with the same word/phrase.
// DriverKit logging has no logging levels; some developers might want to prefix errors differently than info messages.
// Another option is to #define a "debug" case where some log messages only exist when doing a debug build.
// To search for logs from this driver, use either: `sudo dmesg | grep NullDriver` or use Console.app search to find messages that start with "NullDriver -".
#define Log(fmt, ...) os_log(OS_LOG_DEFAULT, "NullDriver Base - " fmt "\n", ##__VA_ARGS__)

Finally, anticipating the question: "Is there any reason I would want use IOLog instead of os_log?"

"No. The only difference between them is that IOLog will create exactly the behavior above."

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Thank you for responding. I am trying to use os_log, but run into an issue. The fmt I am using is a string and not a string literal. So for example if I use os_log(OS_LOG_DEFAULT, "%d %d", parm[0], parm [1]); . Xcode is totally OK with that. However if I use the (const char *) fmt_buffer, Xcode complains (Array initializer must be an initializer list or string literal). For example, os_log(OS_LOG_DEFAULT, fmt_buffer, parm[0], parm[1]); Doc says that os_log should accept a constant string, but I can't get it to work.

Thank you for responding. I am trying to use os_log, but run into an issue. The fmt I am using is a string and not a string literal. So for example if I use os_log(OS_LOG_DEFAULT, "%d %d", parm[0], parm [1]); . Xcode is totally OK with that. However if I use the (const char *) fmt_buffer, Xcode complains (Array initializer must be an initializer list or string literal). For example, os_log(OS_LOG_DEFAULT, fmt_buffer, parm[0], parm[1]); Doc says that os_log should accept a constant string, but I can't get it to work.

I'm not entirely sure how this was done in the implementation, but I believe the reason os_log was implemented as a macro (instead of a function) was to specifically force string literal specifiers, not just "const" strings. In any case, if you want to use dynamic specifiers then I would build the string yourself instead of directly trying to use os_log:

int kevin_log(const char *format, ...)
{
	va_list ap;
	va_start(ap, format);
	int result = kevin_logv(format, ap);
	va_end(ap);
	return result;
}

int kevin_logv(const char *format, va_list ap)
{
	char buf[1024];
	int result = vsnprintf(buf, sizeof(buf), format, ap);
	if (result>0) {
		os_log(OS_LOG_DEFAULT, "%{public}s", buf);
	} else {
	//You could also assert here
		os_log(OS_LOG_DEFAULT, "WARNING: INVALID STRING IN kevin_Logv!");
	}
	return result;
}

This gives you the same sort of safety that os_log is trying to provide by blocking dynamic formatters and is also the approach IOLog uses to wrap os_log.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Trouble using IOLog from a dext
 
 
Q