Post not yet marked as solved
I think the solution is to make console_write (called by printf and IOLog indirectly) also call kprintf. It seems to work and it's much faster than serial port which one would expect from a 800Mbps connection compared to a 115.2Kbps.
One problem with this solution is that they both call os_log_with_args(OS_LOG_DEFAULT, OS_LOG_TYPE_DEFAULT, ...). That makes each message appear doubled in the output of dmesg. Maybe I should try making console_write call _doprnt(..., PE_kputc, ...) or make console_printbuf_putc call PE_kputc.
I don't see the IOLog messages in the output of log stream. Is that to be expected, or do I need special arguments for log stream to show IOLog messages? Are IOLog messages stored to a /var/log file? They are not in system.log.
Maybe the oslog documentation should mention some of this non-oslog stuff to show how they relate. I see a bunch of trees but can't see the forest.
Post not yet marked as solved
See my issue at https://forums.developer.apple.com/thread/133313It seems to me that log is not for development purpose (code, compile, repeat). It's for after the product is released to the user. If you want real logging, then maybe kprintf is needed or output information to an IO registry property...There should be a method to invalidate whatever cache the log is using.
Post not yet marked as solved
I can make a change to the text in my code (use probex24), build, install, then make another change (use probex25) in my code, build, install. Now "log show" shows both occurences as probex25 (the first 6 should show probex24).2020-05-22 23:50:25.209 Db kernel[0:d3154] (MyAIC) MyAIC::probex25#1
2020-05-22 23:50:25.209 Db kernel[0:d3153] (MyAIC) MyAIC::probex25#2
2020-05-22 23:50:25.212 Db kernel[0:d315c] (MyAIC) MyAIC::probex25#3
2020-05-22 23:50:25.212 Db kernel[0:d315d] (MyAIC) MyAIC::probex25#4
2020-05-22 23:50:25.213 Db kernel[0:d315a] (MyAIC) MyAIC::probex25#5
2020-05-22 23:50:25.213 Db kernel[0:d3157] (MyAIC) MyAIC::probex25#6
2020-05-22 23:50:38.679 Db kernel[0:d322a] (MyAIC) MyAIC::probex25#1
2020-05-22 23:50:38.679 Db kernel[0:d322b] (MyAIC) MyAIC::probex25#2
2020-05-22 23:50:38.682 Db kernel[0:d3234] (MyAIC) MyAIC::probex25#3
2020-05-22 23:50:38.682 Db kernel[0:d3233] (MyAIC) MyAIC::probex25#4
2020-05-22 23:50:38.682 Db kernel[0:d3231] (MyAIC) MyAIC::probex25#5
2020-05-22 23:50:38.682 Db kernel[0:d322e] (MyAIC) MyAIC::probex25#6Here is what happens when I change the code and the text. First is "count *= 2" with "probex27", Second is "count *= 3" with "probex27".2020-05-22 23:59:05.186 Db kernel[0:d40a6] (MyAIC) MyAIC::probex25#0
2020-05-22 23:59:05.186 Db kernel[0:d409f] (MyAIC) MyAIC::probex25#2
2020-05-22 23:59:05.187 Db kernel[0:d40a2] (MyAIC) MyAIC::probex25#4
2020-05-22 23:59:05.187 Db kernel[0:d40a0] (MyAIC) MyAIC::probex25#6
2020-05-22 23:59:05.187 Db kernel[0:d40a8] (MyAIC) MyAIC::probex25#8
2020-05-22 23:59:05.190 Db kernel[0:d40a9] (MyAIC) MyAIC::probex25#10
2020-05-22 23:59:25.742 Db kernel[0:d41b2] (MyAIC) MyAIC::probex25#0
2020-05-22 23:59:25.742 Db kernel[0:d41b0] (MyAIC) MyAIC::probex25#3
2020-05-22 23:59:25.742 Db kernel[0:d41b3] (MyAIC) MyAIC::probex25#6
2020-05-22 23:59:25.742 Db kernel[0:d41a9] (MyAIC) MyAIC::probex27#9
2020-05-22 23:59:25.742 Db kernel[0:d41ad] (MyAIC) MyAIC::probex27#12
2020-05-22 23:59:25.742 Db kernel[0:d41aa] (MyAIC) MyAIC::probex27#15My install script installs the kext from a random directory each time (mktemp), so the location of the file cannot be the thing that is being cached improperly.
Post not yet marked as solved
More testing: My kext attaches 6 times (changed from previous versions). "log stream" shows results for the last 4 successful probes with text "probex20". "log show" shows all 6 successful probes "probex20" for the first 5 and "probex21" for the last one. My probe also adds a string property (snprintf followed by setProperty) - all 6 have the correct text of "21". So it seems that only os_log text is broken.joevt@Joes-Mac-mini ~ % log stream --style compact --debug --predicate "message contains 'MyAIC::probex'"
Filtering the log data using "composedMessage CONTAINS "MyAIC::probex""
=== Messages dropped during live streaming (use `log show` to see what they were)
...
=== Messages dropped during live streaming (use `log show` to see what they were)
2020-05-22 23:16:57.274 Db kernel[0:ce715] (MyAIC) MyAIC::probex20#3
2020-05-22 23:16:57.274 Db kernel[0:ce71c] (MyAIC) MyAIC::probex20#4
2020-05-22 23:16:57.274 Db kernel[0:ce71b] (MyAIC) MyAIC::probex20#5
2020-05-22 23:16:57.274 Db kernel[0:ce712] (MyAIC) MyAIC::probex20#6joevt@Joes-Mac-mini ~ % log show --debug -last 2m --style compact --info --predicate "message contains 'MyAIC::probex'"
Filtering the log data using "composedMessage CONTAINS "MyAIC::probex""
Timestamp Ty Process[PID:TID]
2020-05-22 23:16:57.276 Db kernel[0:ce719] (MyAIC) MyAIC::probex20#1
2020-05-22 23:16:57.276 Db kernel[0:ce716] (MyAIC) MyAIC::probex20#2
2020-05-22 23:16:57.276 Db kernel[0:ce715] (MyAIC) MyAIC::probex20#3
2020-05-22 23:16:57.276 Db kernel[0:ce71c] (MyAIC) MyAIC::probex20#4
2020-05-22 23:16:57.276 Db kernel[0:ce71b] (MyAIC) MyAIC::probex20#5
2020-05-22 23:16:57.276 Db kernel[0:ce712] (MyAIC) MyAIC::probex21#6joevt@Joes-Mac-mini ~ % ioreg -filw0 | grep '"Info"'
| | | | | "Info" = "21"
| | | "Info" = "21"
| | | | | | | "Info" = "21"
| | | | | | "Info" = "21"
| | | | | "Info" = "21"
| | | "Info" = "21"
Post not yet marked as solved
I replaced os_log with os_log_debug. I didn't see much of a difference in behavior.I have my probe function like this (it counts the probes):static volatile SInt32 gCount = 0;
IOService * MyAIC::probe(IOService *provider, SInt32 *score)
{
SInt32 count = OSIncrementAtomic(&gCount);
setProperty("ProbeNum", count, 32);
os_log_debug(OS_LOG_DEFAULT, "MyAIC::probe12#%d\n", count);
return this;
}I use the following for logging:log stream --style compact --debug --predicate "message contains 'MyAIC::probe'"My IOService probes approx 27 times but log stream only shows the the last 8 occurances.I am using the same install script as in my previous post.Using log show instead of log stream like this:log show --debug -last 2m --style compact --info --predicate "message contains 'MyAIC::probe'"returns all 27 probe occurances but there is some strange behavior again with the message text. It shows the old text of probe11 for awhile, then it switches to probe12:2020-05-21 21:03:42.306 Db kernel[0:5f0d7] (MyAIC) MyAIC::probe11#0
2020-05-21 21:03:42.309 Db kernel[0:5f0d4] (MyAIC) MyAIC::probe11#1
2020-05-21 21:03:42.309 Db kernel[0:5f0d1] (MyAIC) MyAIC::probe11#2
2020-05-21 21:03:42.309 Db kernel[0:5f0d5] (MyAIC) MyAIC::probe11#3
2020-05-21 21:03:42.309 Db kernel[0:5f0c3] (MyAIC) MyAIC::probe11#4
2020-05-21 21:03:42.309 Db kernel[0:5f0c0] (MyAIC) MyAIC::probe11#5
2020-05-21 21:03:42.309 Db kernel[0:5f0bd] (MyAIC) MyAIC::probe11#6
2020-05-21 21:03:42.309 Db kernel[0:5f0be] (MyAIC) MyAIC::probe11#7
2020-05-21 21:03:42.309 Db kernel[0:5f0c2] (MyAIC) MyAIC::probe11#8
2020-05-21 21:03:42.309 Db kernel[0:5f0cb] (MyAIC) MyAIC::probe11#9
2020-05-21 21:03:42.309 Db kernel[0:5f0ce] (MyAIC) MyAIC::probe11#10
2020-05-21 21:03:42.309 Db kernel[0:5f0c8] (MyAIC) MyAIC::probe11#11
2020-05-21 21:03:42.309 Db kernel[0:5f0d6] (MyAIC) MyAIC::probe11#12
2020-05-21 21:03:42.309 Db kernel[0:5f0c6] (MyAIC) MyAIC::probe11#13
2020-05-21 21:03:42.309 Db kernel[0:5f0c7] (MyAIC) MyAIC::probe11#14
2020-05-21 21:03:42.309 Db kernel[0:5f0c5] (MyAIC) MyAIC::probe11#15
2020-05-21 21:03:42.309 Db kernel[0:5f0bf] (MyAIC) MyAIC::probe11#16
2020-05-21 21:03:42.309 Db kernel[0:5f0c1] (MyAIC) MyAIC::probe11#17
2020-05-21 21:03:42.309 Db kernel[0:5f0cf] (MyAIC) MyAIC::probe12#18
2020-05-21 21:03:42.309 Db kernel[0:5f0ca] (MyAIC) MyAIC::probe12#19
2020-05-21 21:03:42.309 Db kernel[0:5f0c4] (MyAIC) MyAIC::probe12#20
2020-05-21 21:03:42.309 Db kernel[0:5f0d0] (MyAIC) MyAIC::probe12#21
2020-05-21 21:03:42.309 Db kernel[0:5f0d2] (MyAIC) MyAIC::probe12#22
2020-05-21 21:03:42.309 Db kernel[0:5f0cd] (MyAIC) MyAIC::probe12#23
2020-05-21 21:03:42.309 Db kernel[0:5f0d3] (MyAIC) MyAIC::probe12#24
2020-05-21 21:03:42.309 Db kernel[0:5f0cc] (MyAIC) MyAIC::probe12#25
2020-05-21 21:03:42.310 Db kernel[0:5f0c9] (MyAIC) MyAIC::probe12#26With log stream running, I change the text to probe13, build, and install. log stream shows this (shows probe12 instead of the expected probe13 and only shows the last 8 probes):2020-05-21 21:23:20.959 Db kernel[0:61334] (MyAIC) MyAIC::probe12#19
2020-05-21 21:23:20.959 Db kernel[0:61339] (MyAIC) MyAIC::probe12#20
2020-05-21 21:23:20.959 Db kernel[0:61328] (MyAIC) MyAIC::probe12#21
2020-05-21 21:23:20.959 Db kernel[0:61327] (MyAIC) MyAIC::probe12#22
2020-05-21 21:23:20.959 Db kernel[0:61329] (MyAIC) MyAIC::probe12#23
2020-05-21 21:23:20.959 Db kernel[0:6133d] (MyAIC) MyAIC::probe12#25
2020-05-21 21:23:20.959 Db kernel[0:6132c] (MyAIC) MyAIC::probe12#24
2020-05-21 21:23:20.959 Db kernel[0:6132a] (MyAIC) MyAIC::probe12#26I guess log stream dropping messages is expected behavior (is there a way to change that?) but showing the wrong message text must be wrong.log show shows this (you see it switched from probe12 to probe13 at the end which is really strange since the probe count is increasing normally):2020-05-21 21:23:20.978 Db kernel[0:6133a] (MyAIC) MyAIC::probe12#0
2020-05-21 21:23:20.982 Db kernel[0:61338] (MyAIC) MyAIC::probe12#1
2020-05-21 21:23:20.982 Db kernel[0:61325] (MyAIC) MyAIC::probe12#3
2020-05-21 21:23:20.982 Db kernel[0:61337] (MyAIC) MyAIC::probe12#2
2020-05-21 21:23:20.982 Db kernel[0:6133c] (MyAIC) MyAIC::probe12#4
2020-05-21 21:23:20.982 Db kernel[0:6132e] (MyAIC) MyAIC::probe12#5
2020-05-21 21:23:20.982 Db kernel[0:61326] (MyAIC) MyAIC::probe12#6
2020-05-21 21:23:20.982 Db kernel[0:61330] (MyAIC) MyAIC::probe12#7
2020-05-21 21:23:20.982 Db kernel[0:6133e] (MyAIC) MyAIC::probe12#8
2020-05-21 21:23:20.982 Db kernel[0:61335] (MyAIC) MyAIC::probe12#9
2020-05-21 21:23:20.982 Db kernel[0:61333] (MyAIC) MyAIC::probe12#10
2020-05-21 21:23:20.982 Db kernel[0:6133f] (MyAIC) MyAIC::probe12#11
2020-05-21 21:23:20.982 Db kernel[0:61331] (MyAIC) MyAIC::probe12#12
2020-05-21 21:23:20.982 Db kernel[0:61332] (MyAIC) MyAIC::probe12#13
2020-05-21 21:23:20.982 Db kernel[0:6132f] (MyAIC) MyAIC::probe12#14
2020-05-21 21:23:20.982 Db kernel[0:6132d] (MyAIC) MyAIC::probe12#15
2020-05-21 21:23:20.982 Db kernel[0:61336] (MyAIC) MyAIC::probe12#16
2020-05-21 21:23:20.982 Db kernel[0:6133b] (MyAIC) MyAIC::probe12#17
2020-05-21 21:23:20.982 Db kernel[0:6132b] (MyAIC) MyAIC::probe12#18
2020-05-21 21:23:20.982 Db kernel[0:61334] (MyAIC) MyAIC::probe12#19
2020-05-21 21:23:20.982 Db kernel[0:61339] (MyAIC) MyAIC::probe12#20
2020-05-21 21:23:20.982 Db kernel[0:61328] (MyAIC) MyAIC::probe12#21
2020-05-21 21:23:20.982 Db kernel[0:61327] (MyAIC) MyAIC::probe12#22
2020-05-21 21:23:20.982 Db kernel[0:61329] (MyAIC) MyAIC::probe12#23
2020-05-21 21:23:20.982 Db kernel[0:6133d] (MyAIC) MyAIC::probe12#25
2020-05-21 21:23:20.982 Db kernel[0:6132c] (MyAIC) MyAIC::probe12#24
2020-05-21 21:23:20.982 Db kernel[0:6132a] (MyAIC) MyAIC::probe13#26Also strange is that the log stream and log show have different time stamps.
