Cocoalumberjack: Fishy behavior using file logger - stops logging after clearing

[iamcam]

I'm using two separate file loggers for the purpose of a detailed, debug-level logging and a truncated version for easier on-device diagnostics.
The full debug-level log uses an out-of-box file logging experience. This is the one that seems to be exhibiting issues. When I clear the log files (I've tried both deletion and rewriting with empty NSData), the logger is unable to write to the file until the application is restarted.

The setup:

 DDFileLogger *fileLogger = [[DDFileLogger alloc] init];
    fileLogger.logFormatter = [[HPDDLogFormatter alloc] init];
    fileLogger.rollingFrequency = 60 * 60 * 24 * 7;
    fileLogger.logFileManager.maximumNumberOfLogFiles = 1;
    self.fileLogger = fileLogger;
    [DDLog addLogger:self.fileLogger withLogLevel:ddLogLevel];

The clear:

    NSArray *paths = [self.appDelegate.fileLogger.logFileManager unsortedLogFileInfos];
    for( DDLogFileInfo *logFileInfo in paths ){
        [[NSFileManager defaultManager] removeItemAtPath:logFileInfo.filePath error:nil];
        [logFileInfo reset];
        DDLogInfo(@"Deleting log file: %@", logFileInfo.filePath);
    }

I'm not sure why this doesn't work - there aren't any logs .
_[edit]_ Typically I see this after running my -clearLogs method twice in a row. The first time sometimes logging is still there if logged at the time of deletion. The second time is usually good to destroy the files completely. Either way, the truncated log repopulates just fine.

---

Performing a custom configuration seems to be immune to the above-stated problems:

 // Configure separate trunctaed log file location
    NSArray *paths = NSSearchPathForDirectoriesInDomains(NSCachesDirectory, NSUserDomainMask, YES);
    NSString *baseDir = ([paths count] > 0) ? [paths objectAtIndex:0] : nil;
    NSString *specialLogsDirectory = [baseDir stringByAppendingPathComponent:@"TruncatedLogs"];
    DDLogFileManagerDefault *specialLogFileManager = [[DDLogFileManagerDefault alloc] initWithLogsDirectory:specialLogsDirectory];

    // This is for truncated logging to file. See Live Link-Prefix.pch
    DDFileLogger *specialFileLogger = [[DDFileLogger alloc] initWithLogFileManager:specialLogFileManager];
    specialFileLogger.logFormatter = [[HPDDTruncatedLogFormatter alloc] init];
    specialFileLogger.rollingFrequency = 60 * 60 * 24 * 7; // 24 hour rolling
    specialFileLogger.logFileManager.maximumNumberOfLogFiles = 1;
    specialFileLogger.maximumFileSize = 1024.0f * 256.0f; // 256k max special log size
    self.specialFileLogger = specialFileLogger;
    [DDLog addLogger:self.specialFileLogger withLogLevel:LOG_FLAG_ERROR];

...logging behaves as expected after the log files are deleted.

Any ideas? Am I doing something wrong?

[rivera-ernesto]

Any idea @dvor ?

[dvor]

For some reason file deletion event handler isn't called on second deletion. I will try to debug it.

[rivera-ernesto]

Thanks!

[dvor]

There seems that there is a bug in iOS 8 Simulator. NSFileManager's method removeItemAtPath:error: goes crazy and breaks vnode's event handler.

I've tested it on iPhone 4s iOS 8.0.2, iOS 7.1 Simulator - everything works well.

@iamcam Can you test it on real devise and confirm that problem is with simulator?

[dvor]

So the basic flow is:

iOS 8 Device / iOS 7 Simulator:

• log to file
• removeItemAtPath:error:
• log to file
• removeItemAtPath:error:
• ...
• everything is ok

---

iOS 8 Simulator:

• log to file
• removeItemAtPath:error:
• log to file
• removeItemAtPath:error:
• NSFileLogger goes crazy and breaks fileLogger

---

In case if we'll remove logFile manually (from Finder or with rm), everything will be okay too.

iOS 8 Simulator:

• log to file
• rm file.log
• log to file
• rm file.log
• ...
• everything is ok

[iamcam]

I'll test it in both OSs, but I do know for certain on-device logs were showing this behavior - I believe on iOS7. My client had complained that out email log attachments weren't working properly. When I looked into it, I was seeing the behavior described earlier.

On Oct 17, 2014, at 3:42 AM, Dmitry Vorobyov [email protected] wrote:

So the basic flow is:

iOS 7 Simulator:

log to file
removeItemAtPath:error:
log to file
removeItemAtPath:error:
...
everything is ok
iOS 8 Simulator:

log to file
removeItemAtPath:error:
log to file
removeItemAtPath:error:
NSFileLogger goes crazy and breaks fileLogger
In case if we'll remove logFile manually (from Finder or with rm), everything will be okay too.

iOS 8 Simulator:

log to file
rm file.log
log to file
rm file.log
...
everything is ok
—
Reply to this email directly or view it on GitHub.

[iamcam]

Confirmed, I'm seeing this issue in iOS7.1 on device.

[dvor]

Ok, I'll try to investigate more.

Meantime, you can use workaround - archive logfile and then delete it:

[self.fileLogger rollLogFileWithCompletionBlock:^{
    NSArray *paths = [self.fileLogger.logFileManager unsortedLogFileInfos];

    for( DDLogFileInfo *logFileInfo in paths ){

        if (logFileInfo.isArchived) {
            [[NSFileManager defaultManager] removeItemAtPath:logFileInfo.filePath error:nil];
            [logFileInfo reset];
            DDLogInfo(@"Deleting log file: %@", logFileInfo.filePath);
        }
    }
}];

[rivera-ernesto]

Thanks for the support @dvor !

[bpoplauschi]

Guys, could someone patch this up?

[watershade-apps]

@dvor That was so helpful. I would like to clarify to others that it worked perfectly. while testing I let tester to send me log file using MFMailComposeViewController. then I cleared the log file using the code snippet you provided.

[Autoc0diq]

We're experiencing the same issue on iOS 8. We followed the solution dvor suggested with rolling files. Our app runs in the background. However we don't delete the files, we move them into a separate folder for upload. Somehow after a while, the logger stops writing to the file system and we have no idea why.

From the dispatch_source_cancel doc:
Note that it is invalid to close a file descriptor or deallocate a mach port currently being tracked by a dispatch source object before the cancellation handler is invoked.

It seems the file handle is closed before the source cancel handler is invoked. Could it be the reason?

[andmix]

how to get the rolled file,guys? I want to get the rolled file's content for uploading

[rivera-ernesto]

I think we need more maintainers for the file logger which is the part with more issues right now.

[dgutzeit]

Was there any progress on this issue ? We see similar behaviour when file is supposed to be rolled at the background.

[bengotow]

Hey folks - ran into this today and was originally trying to roll the log file and then delete the old one. That only works the first time (maybe because something deeper down is designed to ensure it's not needlessly rolling files?) I tried truncating the files using the code below and it's working fine even after many repeated rounds of log + truncate + log + truncate:

        appDelegate.fileLogger.logFileManager.unsortedLogFilePaths.forEach { (path) in
            FileHandle.init(forWritingAtPath: path)?.truncateFile(atOffset: 0)
        }

[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.

[ffried]

Is this still an issue? There were some changes to DDFileLogger, maybe one of them fixed it?

[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.