Rolled logs, old files deleted on process (app) restart

[driftwoodstudio]

Running app (iOS app) generates log files:

• some.log (lets call this "File A")
• some_timestamp1.log
• some_timestamp2.log

Then app is quit (force quit by user, or invisibly by iOS).

User returns to app (re-launching it).

File state is now:

• some.log (new, starts empty, is NOT "File A" !)
• some_timestamp3.log (this IS "File A", renamed to get it out of the way)

These files are gone:

• some_timestamp1.log
• some_timestamp2.log

Describing effect in words: "when you create a new instance of XCGLogger with same configuration, it loses the previous file set (old, rolled log files) and keeps only the most recent 'active' log file by rolling (renaming) it. Data is lost that should have been kept according to the config for max number of rolled log files to keep."

Swift code for setup:

let logger = XCGLogger(identifier: config.identifier, includeDefaultDestinations: true)

file.targetMaxFileSize = 1024 * 100

file.targetMaxLogFiles = 3

file.outputLevel = .debug

file.showThreadName = false

file.showLogIdentifier = false

file.showFileName = false

logger.add(destination: file)

[driftwoodstudio]

Additional info, after more testing: appears to be related to the .targetMaxLogFiles setting and how it gets applied. Sometimes rolling allows more files, sometimes not (deleting files, even though count is still well under target max).

I have a test run in front of me where the max files is set to 15, and after logging system init, there are 11 files. The app runs for a while, generating more data, then observe log directory and (a) it has generated 6 new rolled log files, but (b) there are only 13 files.

So started with 11, added 6 (11 + 6 = 17 files involved).

But when those 6 rolled files were added, 4 old files were dropped (11 + 6 added - 4 dropped = 13 left).

With my .targetMaxLogFiles = 15 I expected to see 15 files (11 + 6 new - 2 dropped = 15).

My guess is that dropping old files is (as the parameter name suggests) done in a fuzzy-batching kind of way where once the code sees the number of log files is getting "too many" it deletes "some" files. Not a predictable number. Just "some" to get the count back under the target maximum.

But... if that's what's happening, it's pretty severe as I found in an additional test case:

I initialized the autorotating file destination with:

    let file = AutoRotatingFileDestination(writeToFile: LogFactory.logsFileURL(named: config.filename), shouldAppend: true)
    file.targetMaxFileSize = config.suggestedMaxFileBytes // 300k
    file.targetMaxLogFiles = config.suggestedMaxFiles // 10 files

Since I set my values after the constructor, the constructor should initially have set things up with defaults, which (looking at the code) are 10 files each 1 mb (1024k).

BUT... that produced a VERY unexpected result:

At APP LAUNCH 
At: /var/mobile/Containers/Data/Application/23B87F74-3D06-4BE7-A270-FA188D03A9B8/Documents/logs: 
  backup.log                               | 48942 (49 KB)    2020-11-02 11:06:07 
  backup_2020-11-02_110607.log             | 16729 (17 KB)    2020-11-02 10:57:37 

At LOGS INIT start 
At: /var/mobile/Containers/Data/Application/23B87F74-3D06-4BE7-A270-FA188D03A9B8/Documents/logs: 
  backup.log                               | 48942 (49 KB)    2020-11-02 11:06:07 
  backup_2020-11-02_110607.log             | 16729 (17 KB)    2020-11-02 10:57:37 

At LOGS INIT end 
At: /var/mobile/Containers/Data/Application/23B87F74-3D06-4BE7-A270-FA188D03A9B8/Documents/logs: 
  backup.log                               | 762 (762 bytes)  2020-11-02 11:35:25 
  backup_2020-11-02_113525.log             | 48942 (49 KB)    2020-11-02 11:06:07 

Rather than keeping the two starting log files, it kept one and deleted the other. If the default params are to keep 10 1mb files, how could XCGLogger have decided this was right ??

[driftwoodstudio]

Added info:

1. there are multiple log streams going to the logs directory (a general.log, a backup.log, a database.log, etc... all creating their own rolled files). I'm not certain, given code read, that the AutoRotatingFileDestination.archivedFileURLs() function is handling this right. Might be counting too many files. Unclear. I may be wrong.

2. Possibly related to #1: I'm not specifying an identifier when creating the AutoRotatingFileDestination(). This may be causing issues as identifier appears to be stored in extended attributes of file in filesystem, and reading this back is the means of identifying which files are "part of the same set" in determining if there's too many files and deletes are needed. As I have multiple file sources all going to the same directory, and all with blank (default) .identifier property, I think this means all the files will get counted as part of every "rotate and archive" set, rather than being based on filename, which is what I'd expected.

3. I was not specifying a maxTimeInterval parameter in creating the AutoRotatingFileDestination. This caused the (somewhat odd) default of 10 minutes to be used. (Who needs to start a new log every 10 min??). So this was causing force-rotate-on-startup effect as it was often 10 minutes between one run and another, given me futzing with code and writing new test stuff in between.

[driftwoodstudio]

My problems were ultimately due to not using critical parameter values.

I have added code documentation that would have helped me, and created a pull requests from it (no changes other than code comments). Pull request: #311