Exception due to thread race condition

[ehmjaysee]

My application uses xcglogger with a FileDestination() which is configured to use a background queue for performance reasons. The key to this crash is the way xcglogger implements background queues. The problem does not happen when background queues are not used.

My application is designed to create a new output file every minute or so. I want to create a new log file each time the application creates a new output file. The code looks like this:

        // close current log file
        if let destination = appLog.destination(withIdentifier: name) as? FileDestination {
            destination.closeFile()
            appLog.remove(destination: destination)
        }
        // Create a new log file
        let fileDestination = FileDestination(writeToFile: "newLogFileName", identifier: name)
        fileDestination.logQueue = XCGLogger.logQueue
        appLog.add(destination: fileDestination)

Sometimes this causes the app to crash when background queues are used. The background thread is busy writing to the file at the same the the main thread is removing the old FileDestination and adding the new one. To work around the problem I override FileDestination:closeFile() like this

    open func closeFile() {
        if let handle = logFileHandle {
            if let logQueue = logQueue {
                let group = DispatchGroup()
                group.enter()
                logQueue.async {
                    handle.synchronizeFile()
                    handle.closeFile()
                    group.leave()
                }
                group.wait()
            } else {
                handle.synchronizeFile()
                handle.closeFile()
            }
        }
        logFileHandle = nil
    }

[ehmjaysee]

Correction: The 'crash' is actually an exception thrown by objective-C from inside the write() function. The error message is:

Objective-C Exception occurred: *** -[NSConcreteFileHandle writeData:]: No such file or directory

The exception is thrown because the log file is getting closed before the logQueue has a chance to process all pending messages. Looking at the code it seems the log file is closed too early. The log file is closed when destination.owner is set to nil. The exception does not occur if this line of code is commented out and you allow the file to be closed later when the FileDestination instance is destroyed. I am not an expert on the DispatchQueue class, but it seems likely the class is designed to allow the queue to empty prior to destroying itself. When FileDestination is destroyed it will first need to destroy the DispatchQueue instance before it can destroy itself, so this approach would guarantee that all messages in the queue get written to disk before the file is closed.

Just to summarize what leads up to the exception:

Prior to the crash the logQueue is non-empty with pending log messages to process. The application main thread calls log.remove() which sets destination.owner=nil thus triggering the property observer which calls closeFile(). At this point in time the logQueue is in the middle of a write() operation which will throw an exception when it discovers the file is closed.

open class FileDestination: BaseQueuedDestination {
    // MARK: - Properties
    /// Logger that owns the destination object
    open override var owner: XCGLogger? {
        didSet {
            if owner != nil {
                openFile()
            }
            else {
//debug                closeFile()
            }
        }
    }

[DaveWoodCom]

This sounds like an unsupported way of using the logger. Would it make more sense to use the AutoRotatingFileDestination instead? You can even force a rotation if the auto options don't meet your needs. Just call the rotateFile() method directly.

[ehmjaysee]

Thanks for the suggestion. I ran a test where I called rotateFile() instead of log.remove() and I get the same result with the same exception and backtrace. Both functions (rotate and remove) close the log file without flushing the logQueue so if the queue is non-empty those message will get dropped and there is a possibility of hitting the exception. Again this is not 100% reproducible as it depends on timing between two threads.

Fixing the timing problem when using rotateFile() cannot be solved the same way as I suggested for the remove() case. I think a small change to closeFile() may resolve the timing issue for both cases. Consider the code change below. The code change forces the system to drain the dispatch queue before closing the file. I ran 10 iterations with remove() and 10 more with rotateFile() and I did not get the exception using this code change. Prior to this I did not get more than 3 iterations without an exception.

    private func closeFile() {
//      logFileHandle?.synchronizeFile()    <-- remove this
        flush()                                                <-- add this
        logFileHandle?.closeFile()
        logFileHandle = nil
    }

    open func flush(closure: (() -> Void)? = nil) {
        if let logQueue = logQueue {
            let group = DispatchGroup()       <-- add this
            group.enter()
            logQueue.async {
                self.logFileHandle?.synchronizeFile()
                closure?()
                group.leave()
            }
            group.wait()
        }
        else {
            logFileHandle?.synchronizeFile()
            closure?()
        }
    }

Update: Looking further into the XCGlogger code I can say the code sample above would NOT properly handle all use cases, mainly because closeFile() is called from many places and potentially from many different threads.

[ehmjaysee]

I simplified the problem description and provided some sample code.