Wrong (different) thread id in logs depending on XcodeLogConfiguration init options

[shyswork]

Hey, I have encountered a pretty interesting bug.
This is my setup:
Empty new project from single view template. Code added in AppDelegate.swift

This code:

func application(_ application: UIApplication, didFinishLaunchingWithOptions launchOptions: [UIApplicationLaunchOptionsKey: Any]?) -> Bool {

//        let config = XcodeLogConfiguration(minimumSeverity: .verbose, stdStreamsMode: .useExclusively)
        let config = XcodeLogConfiguration()
        Log.enable(configuration: [config])
        NSLog("NSLog")
        Log.error?.message("ERROR cleanroom logger - message")
        Log.debug?.trace("DEBUG cleanroom logger - trace")
        Log.error?.trace("ERROR cleanroom logger - trace")

        DispatchQueue.global().async {
            NSLog("NSLog - dispatched")
            Log.error?.message("ERROR cleanroom logger - message - dispatched")
            Log.error?.trace("ERROR cleanroom logger - trace - dispatched")
            Log.debug?.trace("DEBUG cleanroom logger - trace - dispatched")
        }
        return true
    }

produces this output:

2017-02-09 13:45:34.217448 logtest[590:416043] NSLog
2017-02-09 13:45:34.220634 logtest[590:416109] NSLog - dispatched
2017-02-09 13:45:34.239134 logtest[590:416107] [CleanroomLogger] ❌ ERROR cleanroom logger - message (AppDelegate.swift:25)
2017-02-09 13:45:34.240717 logtest[590:416107] [CleanroomLogger] ❌ —> AppDelegate.swift:27 - ERROR cleanroom logger - trace
2017-02-09 13:45:34.242348 logtest[590:416107] [CleanroomLogger] ❌ ERROR cleanroom logger - message - dispatched (AppDelegate.swift:31)
2017-02-09 13:45:34.243071 logtest[590:416107] [CleanroomLogger] ❌ —> AppDelegate.swift:32 - ERROR cleanroom logger - trace - dispatched

This code:

func application(_ application: UIApplication, didFinishLaunchingWithOptions launchOptions: [UIApplicationLaunchOptionsKey: Any]?) -> Bool {

        let config = XcodeLogConfiguration(minimumSeverity: .verbose, stdStreamsMode: .useExclusively)
//        let config = XcodeLogConfiguration()
        Log.enable(configuration: [config])
        NSLog("NSLog")
        Log.error?.message("ERROR cleanroom logger - message")
        Log.debug?.trace("DEBUG cleanroom logger - trace")
        Log.error?.trace("ERROR cleanroom logger - trace")

        DispatchQueue.global().async {
            NSLog("NSLog - dispatched")
            Log.error?.message("ERROR cleanroom logger - message - dispatched")
            Log.error?.trace("ERROR cleanroom logger - trace - dispatched")
            Log.debug?.trace("DEBUG cleanroom logger - trace - dispatched")
        }
        return true
    }

produces this output:

2017-02-09 13:47:15.471444 logtest[596:416670] NSLog
2017-02-09 13:47:15.476065 logtest[596:416728] NSLog - dispatched
2017-02-09 13:47:15.474000 logtest[596:416670] [CleanroomLogger] ❌ ERROR cleanroom logger - message (AppDelegate.swift:25)
2017-02-09 13:47:15.475000 logtest[596:416670] [CleanroomLogger] ◾️ —> AppDelegate.swift:26 - DEBUG cleanroom logger - trace
2017-02-09 13:47:15.475000 logtest[596:416670] [CleanroomLogger] ❌ —> AppDelegate.swift:27 - ERROR cleanroom logger - trace
2017-02-09 13:47:15.476000 logtest[596:416728] [CleanroomLogger] ❌ ERROR cleanroom logger - message - dispatched (AppDelegate.swift:31)
2017-02-09 13:47:15.478000 logtest[596:416728] [CleanroomLogger] ❌ —> AppDelegate.swift:32 - ERROR cleanroom logger - trace - dispatched
2017-02-09 13:47:15.479000 logtest[596:416728] [CleanroomLogger] ◾️ —> AppDelegate.swift:33 - DEBUG cleanroom logger - trace - dispatched

Please note the thread IDs in both cases.
In the first case NSLog in main thread, NSLog in global queue and CleanroomLogger logs show different IDs.
In the second case dispatched and non dispatched logs (both CleanroomLogger and NSLog) show similar (correct if you ask me) thread IDs.

Apparently there is a bug somewhere which causes incorrect threadID printing or capturing behaviour.

On a side note there is a good question: which threadID should log show?

1. the ID of the thread in which Log.error?.message() is called
2. the ID of the thread in which entry was processed

I would say the first.

[emaloney]

Thanks a lot for detailed report. To answer your question, the thread ID should show the ID of the thread that issues the call to Log.error?.message().

How the thread ID is constructed when using the XcodeLogConfiguration, however, depends on several factors:

1. Whether or not you're running an OS version with the new os_log() function available.
2. The value of the mimicOSLogOutput parameter passed to the XcodeLogConfiguration constructor
3. The value of the stdStreamsMode parameter passed to the XcodeLogConfiguration constructor
4. The setting of the OS_ACTIVITY_MODE environment variable of the running executable

The reason for this is that the XcodeLogConfiguration is designed to show consistent output regardless of whether it is running on a platform with os_log() available.

When os_log() is used, the thread ID you see is generated by os_log(), which is built into the operating system. If os_log() is not used because it is unavailable or being bypassed, CleanroomLogger will attempt to mimic the same output using its own OSLogMimicFormatter implementation.

It is possible that this accounts for the discrepancy. Are the thread IDs consistent if you pass mimicOSLogOutput: false to the XcodeLogConfiguration constructor?

[shyswork]

I haven't tried to pass mimicOSLogOutput to XcodeLogConfiguration .

Like I said I have made a minimal app, there is no other custom code in the template app beside the one I have provided.

I have tried it on iPhone 5 on iOS 10, OS_ACTIVITY_MODE was not touched.

I will try to play around with it a bit more, but so far it seems that the output of the default configuration is not correct. As you see NSLog's main thread has ID 416043 and global queue has id 416109 but all output from logger seems to show the ID 416107 which I guess is the ID of logger queue.

[emaloney]

If that's the case then it's a bug / oversight on my part.

[emaloney]

I've looked into it further and, the interesting thing is, the correct thread ID is rendered by CleanroomLogger.

In your first case, the (incorrect) thread ID is generated by Apple's os_log() implementation.

In your second case, the (correct) thread ID is created by CleanroomLogger.

I'm not sure if that means Apple's os_log() has a bug, or if they're just getting a thread ID some other way. FYI, the (correct) code CleanroomLogger uses to determine the thread ID is:

var threadID: UInt64 = 0
pthread_threadid_np(nil, &threadID)

This is definitely a head-scratcher.

[shyswork]

Well, I have dug into code a little bit more.
It seems everything is working as expected. And this is a framework issue (bug or feature).

What causes it is this:
let config = XcodeLogConfiguration(stdStreamsMode: .useExclusively)

Minimum severity as in my initial report doesn't matter.
If I understand code correctly if stdStreamsMode: .useExclusively is used then you generate the whole message yourself because if you print message in func record(message ... of StandardStreamsLogRecorder you would get
"2017-02-20 14:15:23.679000 logtest[1134:1446702] [CleanroomLogger] ❌ ERROR cleanroom logger - message (AppDelegate.swift:26)"

but if you do the same in func record(message ... of OSLogRecorder you would get only
"❌ ERROR cleanroom logger - message (AppDelegate.swift:26)"

which means that the os_log would generate the 'header' with date and app details. Thus it will use the CleanroomLogger serial queue id to print the message. This is the queue to which all messages are dispatched and it differs from main queue and global queue in which log message was dispatch by the application's code.

I would say that the correct way to log messages is to generate the message for OSLogRecorder from the saved of LogEntry which would include the correct thread ID. In the end of the day I would want to know the thread ID of the thread in which I called log function not the thread ID of the logger process.