printf in kernel extension

Is there any limit on the message length in the kernel?

Yes. The kernel’s

printf

If you’re serious about logging from the kernel, you should use the

<os/log.h>

Share and Enjoy
—
Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

I try to use os_log instead of printf in my code, but no log can be shown in the Console.app.

os_log(OS_LOG_DEFAULT, "some message";

When I use the %s specifier, another problem occurs.

os_log(OS_LOG_DEFAULT, "some message %s", cstringVar);

I got this warning from Xcode:

Invalid conversion specifier 's'

Changing %s to %{public}s also doesn't work.

So what is the correct way to use unified logging in a pure c environment? Thanks!

So what is the correct way to use unified logging in a pure c environment?

To be clear, we’re talking about a pure C environment within a KEXT, right?

I got this warning from Xcode:

Hmm, that’s strange. I did something similar here and it worked as expected. Specifically:

1. Using Xcode 11.1 on macOS 10.14.6, I created a new project using the Generic Kernel Extension template.

2. In

   ***.c

   (where

   ***

   is the name of the KEXT), I added an include to the top, just under the existing include:

   #include <os/log.h>

   .

3. I then added the following to

   ***_start

   :

   const char * cStringVar = "Hello Cruel World!";
   os_log(OS_LOG_DEFAULT, "%s", cStringVar);

   .

It compiles just fine.

Share and Enjoy
—
Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

I'm using Xcode 10.3 with macOS 10.12 SDK on 10.14.6. The os_log* functions is available in the SDK, but my kext cannot print any log on my own computer, even if I just print a literal C string. I've not yet tried it on 10.12 & 10.13.

I'm using Xcode 10.3 … on 10.14.6.

FYI, I repeated the test above with Xcode 10.3 and it works as expected.

with macOS 10.12 SDK

Huh? Xcode 10.3 ships with the 10.14 SDK. Using it with any other SDK is unsupported and will result in weird bugs.

Note that

os_log

Share and Enjoy
—
Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

Hey eksimo,

thanks for looking into this. I ran across this same issue today, while working on a fun kext project. Specifically, the code compiles, but I haven't been able to confirm that the log message ends up somewhere retrievable.

I'm on:

* macOS: 10.14.6 (18G1012)

* XCode: Version 11.2.1 (11B500)

* kext's macOS Deployment Target: 10.14

I compiled a kext that contains:

kern_return_t mydemo_start(kmod_info_t * ki, void *d)
{
    const char * cStringVar = "Hello Cruel World!";
    os_log(OS_LOG_DEFAULT, "%s", cStringVar);
    return KERN_SUCCESS;
}

kext seems to load fine, and it's displayed in kextstat, however log show --predicate 'eventMessage contains "Hello Cruel"' --info doesn't return any messages 😟.

Any ideas?

Restarting macOS actually made this work. I suspect I had previously send pointer to bad data, which may have messed up some kext-related logging until restart. I haven't achieved clarity on when it stops working but sometimes, os_log from a kext reliably stops working.

os_log_create also seems to reliably not work from a kext -- no subsystem or cateogry is passed with the associate message:

os_log_t general_log = os_log_create("io.myname.test", "general");
os_log(general_log, "hi there");
IOLog("hello from cland v5");

but

$ log show --predicate 'senderImagePath contains "myname"' --last 5m --info --debug --style json
Filtering the log data using "senderImagePath CONTAINS "happy""
[{
  "traceID" : 17081085460484,
  "eventMessage" : "hi there",
  "eventType" : "logEvent",
  "source" : null,
  "formatString" : "hi there",
  "activityIdentifier" : 0,
  "subsystem" : "",              # <<<<<<< should not be empty
  "category" : "",               # <<<<<<< should not be empty
  "threadID" : 89482,
  "senderImageUUID" : "6CE18218-3F80-3215-A933-3F824337FC45",
  "backtrace" : {
    "frames" : [
      {
        "imageOffset" : 3883,
        "imageUUID" : "6CE18218-3F80-3215-A933-3F824337FC45"
      }
    ]
  },
  "processImagePath" : "\/kernel",
  "senderImagePath" : "\/Users\/myname\/kext\/sample.kext\/Contents\/MacOS\/happymeowmeow",
  "timestamp" : "2019-12-09 20:58:10.361445-0800",
  "machTimestamp" : 2232376941776,
  "messageType" : "Default",
  "processImageUUID" : "DFB5D0E2-3B41-3647-A48B-D704AFCC06B4",
  "processID" : 0,
  "senderProgramCounter" : 3883,
  "parentActivityIdentifier" : 0,
  "timezoneName" : ""

Thanks for the update. Most interesting.

Restarting macOS actually made this work.

Weird.

I haven't achieved clarity on when it stops working but sometimes,

os_log

from a kext reliably stops working.

I got nothing )-:

If you can come up with even a vague theory about reproducing this, please file a bug about it, posting your bug number, just for the record.

os_log_create

also seems to reliably not work from a kext

That is expected (alas).

Share and Enjoy
—
Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

> That is expected (alas).

Why? Where is this documented?

I don't see how it's acceptable that stuff just "doesn't work", without further explanation.

> Note that

os_log

Again, where is this documented?

Some of us are using older SDKs because it's the recommended practice when supporting older macOS versions (see e.g. https://stackoverflow.com/a/15092753/3688293). I don't understand how a simple logging function can have bugs because of this.

Some of us are using older SDKs

Are you working in the kernel? Because the post you referenced is very much focused on user-space code (it has no mention of kernel, kext, or KPI).

Share and Enjoy
—
Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

having the same problem on 10.13.6

from what phil dennis-jordan has told me:

"There is a bug in IOSharedDataQueue which could cause it to stall in macOS 10.13 which was only fixed in 10.14.2 IIRC after I tracked it down and reported it to Apple (and got a high-profile client of ours to lean on Apple to take it seriously). I think this also affects the kernel logging mechanism, and is likely what's causing your logging drop-out. The most reliable logging from kexts on all OS versions is to use kprintf() and connect to the target Mac using a Firewire cable and log using the fwkpfv command on your dev Mac."

this is nothing short of a disaster. expecting others to upgrade to 10.14.2++ when:

1. mojave doesn't support nvidia graphics

2. mojave doesn't support HFS+

3. mojave doesn't support raidboot (10.13.6 does with a dosdude patcher, but updates are still a nuisance to apply!)

is an absolutely unreasonable recommendation and/or course of action.

i am just astounded and floored at how destructive APPULL (say "PULL" with the cheeks FULL, rhyme not intended but v welcome) has been. like, this problem would be apparent to any NEWBIE who is STARTING development.

just unreal...