tony19 / logback-android

📄The reliable, generic, fast and flexible logging framework for Android
Apache License 2.0
1.2k stars 172 forks source link

App death during rollover causes losing logs and malformed gz files #369

Open Ekalips opened 3 months ago

Ekalips commented 3 months ago

Describe the bug

Hi. We are using a conjunction of Timer and Logback Android to log into files in production environment for further inspection. For this we are using RollingFileAppender, SizeAndTimeBasedRollingPolicy configured to max 40mb log size and/or daily rollovers, the code for it is attached below. The issue we are facing is that we get malformed i.log.gz files once in a while, way more often that we would want. After thorough research the culprit seems to be the fact that those production devices have quite unexpected lifecycle and might (and oftentimes do) kill our app right at the midnight and restart the device, so what's happening is that app wakes up right after the midnight just to log that it's dying (from lifecycle callbacks), therefore triggering the rollover, but as soon as that happens app is killed and restarted, which seems to cause rollover to stop what it was doing and not recover properly afterwards. I've tried finding similar issues or any solutions for it but no luck really. The only few solutions (hacks) I can see is to reduce the max file size so it rolls over naturally more and the last log file is smaller so it may be able to compress it in time, or trying to not log anything if the app is closing (altho it'll slightly reduce the log usefulness). Are there any official solutions to this or maybe it's an open issue?

Reproduction

class FileLoggingTree(config: Config) : Timber.DebugTree() {

    private val logger = LoggerFactory.getLogger(FileLoggingTree::class.java)

    init {
        val loggerContext = LoggerFactory.getILoggerFactory() as LoggerContext
        loggerContext.reset()

        val rollingFileAppender = RollingFileAppender<ILoggingEvent>()
        rollingFileAppender.context = loggerContext
        rollingFileAppender.isAppend = true
        rollingFileAppender.file =
            "${config.logDirectory}${File.separator}${config.latestLogFileName}.log"

        val rollingPolicy = SizeAndTimeBasedRollingPolicy<ILoggingEvent>()
        rollingPolicy.context = loggerContext
        rollingPolicy.setMaxFileSize(FileSize.valueOf("40MB"))
        rollingPolicy.maxHistory = 120
        rollingPolicy.fileNamePattern =
            "${config.logDirectory}${File.separator}%d{${config.logDatePattern}}${File.separator}${config.logNamePattern}"
        rollingPolicy.setTotalSizeCap(FileSize.valueOf("1GB"))
        rollingPolicy.setParent(rollingFileAppender)
        rollingPolicy.start()

        val encoder = PatternLayoutEncoder()
        encoder.context = loggerContext
        encoder.charset = Charset.defaultCharset()
        encoder.pattern = "%d{HH:mm:ss.SSS} | %.-1level | %msg%n"
        encoder.start()

        rollingFileAppender.rollingPolicy = rollingPolicy
        rollingFileAppender.encoder = encoder
        rollingFileAppender.start()

        val root = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME) as Logger
        root.level = Level.DEBUG
        root.addAppender(rollingFileAppender)

        StatusPrinter.print(loggerContext)
    }

    override fun log(priority: Int, tag: String?, message: String, t: Throwable?) {
        val logMessage = tag.toString().trim().bringToLength(30) + " | " + message.trim()
        when (priority) {
            Log.VERBOSE, Log.DEBUG -> {
                if (t != null) logger.debug(logMessage, t) else logger.debug(logMessage)
            }

            Log.INFO -> {
                if (t != null) logger.info(logMessage, t) else logger.info(logMessage)
            }

            Log.WARN -> {
                if (t != null) logger.warn(logMessage, t) else logger.warn(logMessage)
            }

            Log.ERROR, Log.ASSERT -> {
                if (t != null) logger.error(logMessage, t) else logger.error(logMessage)
            }
        }
    }

    private fun String.bringToLength(requiredLength: Int): String {
        return if (length > requiredLength) this.take(requiredLength)
        else if (length == requiredLength) this
        else this.padEnd(requiredLength)
    }

    data class Config(
        val logDirectory: String,
        val latestLogFileName: String,
        val logDatePattern: String,
        val logNamePattern: String
    )
}
    val logConfig: FileLoggingTree.Config = FileLoggingTree.Config(
        context.filesDir.path + File.separator + "logs",
        "latest",
        "yyyy-MM-dd",
        "%i.log.gz"
    )

Logs

No response

logback-android version

3.0.0

OS Version

9

What logback configuration are you using? (logback.xml or Java/Kotlin code)

Kotlin code

Validations

Ekalips commented 3 months ago

Additional info: the library does "move" the latest log into the tmp file for further processing, so technically data isn't lost when app death happens. The issue is that tmp file is basically forgotten after restart, just left sitting there.