Crash when logging a debug level event via Logger

[fddecc]

It appears that in all cases, this occurs shortly after launch / after Logger is created.

Crash details:

Thread 7 Crashed:
0   libswiftCore.dylib            	0x000000020b96f7ec swift_isUniquelyReferenced_nonNull_native + 0
1   Datadog                       	0x000000010969d7d0 specialized Dictionary.merging(_:uniquingKeysWith:) + 64 (<compiler-generated>:0)
2   Datadog                       	0x000000010969a024 Logger.debug(_:attributes:) + 152
3   InstaShopper                  	0x0000000103cc40c8 DatadogWriter.writeMessage(_:logLevel:) + 992

Redacted crash report included in zip file:

2020-03-11_21-34-05.9183_-0400-d9f8257d00b30d86bce2bfac00812dcd649fff30.crash.zip

Last commit in version we are currently using is 5eb1ecc

[ncreated]

@00FA9A Thank you for the stack trace! As far as I see, this is related to the Logger invocation from your code: DatadogWriter.writeMessage(). Could you share details on what sort of message and (especially) kind of attributes that you send?

[fddecc]

@ncreated we only pass message string and no attributes, which is what puzzles me considering that it appears to fail when merging dicts

[ncreated]

@00FA9A Thanks for details. I looked closer into the crash and Logger's code and I feel we need a wider context of your usage to push it further. All the tests of immediate logging right after startup do not issue any crash on our side (both when logging from the main thread and dispatching on queue).

The crashing signal you're receiving suggests an unowned memory access:

Exception Type:  EXC_BAD_ACCESS (SIGSEGV)
Exception Subtype: KERN_INVALID_ADDRESS at 0x8000000000000008

I can see from the Thread 7th stack trace (instructions 7 to 2) that you dispatch logging asynchronously to separate queue by wrapping it in DatadogWriter.

2   Datadog                       	0x000000010969a024 Logger.debug(_:attributes:) + 152
3   InstaShopper                  	0x0000000103cc40c8 DatadogWriter.writeMessage(_:logLevel:) + 992
4   InstaShopper                  	0x0000000103cc4178 protocol witness for LogWriter.writeMessage(_:logLevel:) in conformance DatadogWriter + 20
5   Willow                        	0x0000000109809c04 closure #1 in Logger.logMessage(_:with:) + 208 (Logger.swift:274)
6   Willow                        	0x000000010980967c thunk for @escaping @callee_guaranteed () -> () + 28 (<compiler-generated>:0)
7   libdispatch.dylib             	0x00000001dd690a38 _dispatch_call_block_and_release + 24 (init.c:1372)
8   libdispatch.dylib             	0x00000001dd6917d4 _dispatch_client_callout + 16 (object.m:511)
9   libdispatch.dylib             	0x00000001dd66cdec _dispatch_lane_serial_drain$VARIANT$armv81 + 548 (inline_internal.h:2441)

Is it possible for you to post the relevant parts of the code, so we can see how the wider context of logger configuration and try to reproduce the crash?

Also, two diagnostic questions:

• Are you able to reproduce this crash locally with debugger? If yes, could you enable zombie objects and share the results?
• Does this crash occur every time? As I understand from your first comment: yes, but just want to confirm.
• Are you sure the Datadog.initialize(...) is called synchronously before dispatching logging to separate thread? It is important to have Datadog.initialize(...) complete before accessing Logger.builder, which might be not true if both things happen in parallel with use of dispatch queues.

If it's relevant for you, you can reach me on Datadog public Slack so we can iterate on this faster.

[fddecc]

@ncreated

Datadog is initialized on app launch. Logger is build immediately following that.

typealias DatadogCore = Datadog
typealias DatadogLogger = Logger
...
// Setup Datadog
DatadogCore.initialize(appContext: .init(),configuration: Datadog.Configuration.builderUsing(clientToken: datadogToken).build())
DatadogCore.verbosityLevel = .none

// Setup Datadog Logger
self.datadogLogger = DatadogLogger.builder
    .set(serviceName: "...")
    .printLogsToConsole(false)
    .build() 

After this is complete, and we have updated user objet with latest from our backend, we will set user attributes with:

DatadogCore.setUserInfo(id: userID)
userTraits.forEach { datadogLogger.addAttribute(forKey: $0.key, value: $0.value) }

This happens every time user object is updated, and that could happen multiple times during a session

We later use datadogLogger as needed to log any events through our wrapper (DatadogWriter, that conforms to LogModifierWriter from Willow - we use this to support multiple destinations for our logs).

[ncreated]

Thanks @00FA9A 🏅. I managed to catch the crash with stack trace very similar to your. This crash is the highest priority now and we will ship the fix soon.

A workaround is to avoid adding / removing Logger tags and attributes from different threads.