Cocoalumberjack: Crash in logMessage

[gtimmy]

New Issue Checklist

• [x] I have read and understood the CONTRIBUTING guide
• [x] I have read the Documentation or CocoaDocs
• [x] I have searched for a similar issue in the project and found none

Issue Info

Info | Value |
-------------------------|-------------------------------------|
Platform Name | osx
Platform Version | 10.12.4
CocoaLumberjack Version | 3.0.0
Integration Method | cocoapods
Xcode Version | Xcode 8.2.1
Repro rate | sometimes

Issue Description and Steps

Possible exception in currentLogFileHandle is not handled.

[_currentLogFileHandle seekToEndOfFile] may raise NSFileHandleOperationException which is not NSException and can't be catched in logMessage by @catch (NSException *exception)

Crash log:

Thread 12 Crashed:: Dispatch queue: NSOperationQueue 0x608000038120 :: NSOperation 0x60000025fe60 (QOS: USER_INITIATED)
0 libobjc.A.dylib 0x00007fffc3a04081 objc_class::demangledName(bool) + 33
1 com.apple.Foundation 0x00007fffb00dbbb2 _NSMethodExceptionProem + 61
2 com.apple.Foundation 0x00007fffb0073f5c _NSFileHandleRaiseOperationException + 92
3 com.apple.Foundation 0x00007fffaffe93b1 -[NSConcreteFileHandle seekToEndOfFile] + 74
4 org.cocoapods.CocoaLumberjack 0x000000010cda4f2a -[DDFileLogger currentLogFileHandle] + 172
5 org.cocoapods.CocoaLumberjack 0x000000010cda51a9 -[DDFileLogger logMessage:] + 272

[gtimmy]

Another crash log:

Thread 18 Crashed:: Dispatch queue: NSOperationQueue 0x600000227460 (QOS: DEFAULT)
0 libobjc.A.dylib 0x00007fffbd240e9b objc_release + 11
1 org.cocoapods.CocoaLumberjack 0x000000010ff444a7 -[DDLogFileInfo fileAttributes] + 117
2 org.cocoapods.CocoaLumberjack 0x000000010ff445ca -[DDLogFileInfo creationDate] + 50
3 org.cocoapods.CocoaLumberjack 0x000000010ff43592 -[DDFileLogger scheduleTimerToRollLogFileDueToAge] + 109
4 org.cocoapods.CocoaLumberjack 0x000000010ff43f42 -[DDFileLogger currentLogFileHandle] + 196
5 org.cocoapods.CocoaLumberjack 0x000000010ff441a9 -[DDFileLogger logMessage:] + 272

[bpoplauschi]

@gtimmy those are 2 different cases.
Can you reproduce both? It would help if you could create a demo project where they both appear.

[gtimmy]

@bpoplauschi to be honest we got it only 1 or 2 times, but we don't want to have a time bomb in production. I will try to create a demo project, but I think @catch block should be updated, in any case, as I see, this code may throw not only NSException.

[mpogra]

I also got similar crash today -

Crashed Thread: 6 Dispatch queue: cocoa.lumberjack.fileLogger

Exception Type: EXC_CRASH (SIGABRT)
Exception Codes: 0x0000000000000000, 0x0000000000000000
Exception Note: EXC_CORPSE_NOTIFY

Application Specific Information:
* Terminating app due to uncaught exception 'NSFileHandleOperationException', reason: '* -[NSConcreteFileHandle writeData:]: Permission denied'
terminating with uncaught exception of type NSException
abort() called

Application Specific Backtrace 1:
0 CoreFoundation 0x00007fffa52030db __exceptionPreprocess + 171
1 libobjc.A.dylib 0x00007fffb9e90a2a objc_exception_throw + 48
2 CoreFoundation 0x00007fffa52809c5 +[NSException raise:format:] + 197
3 Foundation 0x00007fffa6c40f7c -[NSConcreteFileHandle writeData:] + 202
4 WFS Agent 0x0000000100af9e3e -[DDFileLogger logMessage:] + 281
5 WFS Agent 0x0000000100acc543 __16+[DDLog lt_log:]_block_invoke + 50
6 libdispatch.dylib 0x00007fffba744ef7 _dispatch_call_block_and_release + 12
7 libdispatch.dylib 0x00007fffba73c0b8 _dispatch_client_callout + 8
8 libdispatch.dylib 0x00007fffba752836 _dispatch_queue_serial_drain + 209
9 libdispatch.dylib 0x00007fffba744cd9 _dispatch_queue_invoke + 1046
10 libdispatch.dylib 0x00007fffba73de70 _dispatch_root_queue_drain + 476
11 libdispatch.dylib 0x00007fffba73dc47 _dispatch_worker_thread3 + 99
12 libsystem_pthread.dylib 0x00007fffba989712 _pthread_wqthread + 1299
13 libsystem_pthread.dylib 0x00007fffba9891ed start_wqthread + 13

[gtimmy]

@bpoplauschi I'm unable to reproduce these crash and create a test project. Looks like, a race condition is there in these crashes, but at least block @catch (NSException *exception) should be changed to @catch (id exception)

[rist]

We had some crashes in currentLogFileHandle which could be related

Hardware Model:      iPhone9,3
Process:         XXX
Path:            XXX
Identifier:      XXX
Version:         1.7.4 (2017-03-02T05:23)
Code Type:       ARM-64
Parent Process:  ??? [1]

Date/Time:       2017-03-02T09:51:17Z
Launch Time:     2017-03-02T09:49:06Z
OS Version:      iPhone OS 10.2.1 (14D27)
Report Version:  104

Exception Type:  SIGSEGV
Exception Codes: SEGV_ACCERR at 0x7c
Crashed Thread:  0

Thread 0 Crashed:
0   libdispatch.dylib                    0x0000000189680944 dispatch_source_set_timer + 20
1   CocoaLumberjack                      0x0000000101219c18 -[DDFileLogger scheduleTimerToRollLogFileDueToAge] (DDFileLogger.m:774)
2   CocoaLumberjack                      0x000000010121a58c -[DDFileLogger currentLogFileHandle] (DDFileLogger.m:956)
3   CocoaLumberjack                      0x000000010121a808 -[DDFileLogger logMessage:] (DDFileLogger.m:1011)

[adubovkin]

I have the same problem:

SIGSEGV: SEGV_ACCERR
libdispatch.dylib.dispatch_source_set_timer$VARIANT$mp + 40
AppModule.-[DDFileLogger scheduleTimerToRollLogFileDueToAge] ( DDFileLogger .m :768)
AppModule.-[DDFileLogger currentLogFileHandle] ( DDFileLogger .m :949)
AppModule.-[DDFileLogger logMessage:] ( DDFileLogger .m :0)

It looks like a race condition while clearing _rollingTimer from other places - there are a bunch of _rollingTimer = NULL in the code

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If this is still an issue, please make sure it is up to date and if so, add a comment that this is still an issue to keep it open. Thank you for your contributions.

[bpoplauschi]

It's hard to refresh this thread discussion, but I did try in a demo project and NSFileHandleOperationException is caught by @catch (NSException *exception).

Code used

- (NSError *)updateFileAtURL:(NSURL *)fileUrl {
    NSError *error = nil;
    NSFileHandle *file = [NSFileHandle fileHandleForUpdatingURL:fileUrl error:&error];
    [file closeFile];  // important - this generates the exception since the file handler is closed
    @try {
        [file seekToFileOffset:12323];        // Debugger stops at this line throwing an expected exception in test
    } @catch (NSException *exception) {
        error = [NSError errorWithDomain:@"FileUpdateErrorDomain"
                                    code:-1
                                userInfo:@{@"exception" : exception}];
    }
    return error;
}

- (void)testOtherExc {
    NSError *error = [self updateFileAtURL:[NSURL fileURLWithPath:@"/Users/bogdanp/GitHub/CocoaLumberjack/xxx"]];
    expect(error).toNot.beNil();
    NSException *illegalSeek = error.userInfo[@"exception"];
    expect(illegalSeek.name).to.equal(NSFileHandleOperationException);
    expect(illegalSeek.reason).to.equal(@"*** -[NSConcreteFileHandle seekToFileOffset:]: No such file or directory");
}

Inspired from https://dzone.com/articles/testing-code-that-catches-exceptions

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If this is still an issue, please make sure it is up to date and if so, add a comment that this is still an issue to keep it open. Thank you for your contributions.

[sumitjagdev]

Crash DDFileLogger.m line 1104
-[DDLogFileInfo fileAttributes]

[sumitjagdev]

Crash DDFileLogger.m line 1128
-[DDLogFileInfo creationDate]

[sumitjagdev]

Crash DDFileLogger.m line 739
-[DDFileLogger scheduleTimerToRollLogFileDueToAge]

[bpoplauschi]

@sumitjagdev those are different crashes than the one at the top of this issue.
Feel free to open issues for each crash with the proper info for each one (see the issue template and fill out that info).