logback-android FileAppender not creating files

Question

I'm using logback-android in a Kotlin project to generate logs in a file. I previously tested this solution in different Android versions without any issue, but I discovered an issue in Android 5.1: the parent directories to the log file are created but not the log files. How do I fix this?

build.gradle:

implementation 'io.github.microutils:kotlin-logging:1.6.24'
implementation 'com.github.tony19:logback-android:2.0.0'

logback.xml:

<configuration>
    <property name="LOG_DIR" value="${EXT_DIR:-${DATA_DIR}}/log.log" />
    <timestamp key="datetime" datePattern="yyyy'-'MMdd'-'HH':'mm':'ss"/>
    <appender name="logcat" class="ch.qos.logback.classic.android.LogcatAppender">
        <encoder>
            <pattern>[%d{yyyyMMdd-HH:mm:ss}][%thread][%-5level][%logger{36}][%msg]%n</pattern>
        </encoder>
    </appender>
    <appender name="filelog" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/${datetime}.log</file>
        <encoder>
            <pattern>[%d{yyyyMMdd-HH:mm:ss}][%thread][%-5level][%logger{36}][%msg]%n</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${LOG_DIR}/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>5</maxHistory>
            <totalSizeCap>500MB</totalSizeCap>
        </rollingPolicy>
    </appender>
    <root level="DEBUG">
        <appender-ref ref="logcat" />
    </root>
    <root level="DEBUG">
        <appender-ref ref="filelog" />
    </root>
</configuration>

Answer 1

I recommend using logback's debug (e.g., <configuration debug="true"> in logback.xml) to see helpful messages in logcat for troubleshooting.

Android 5.1

logcat messages show that the filename is invalid. Specifically, Android 5.1 disallows : in filenames (not an issue in later versions of Android):

<timestamp key="datetime" datePattern="yyyy-MM-dd-HH:mm:ss"/> <!-- DON'T USE COLONS IN ANDROID 5.1 -->
<file>${LOG_DIR}/${datetime}.log</file>

The problem would appear in logcat as a FileNotFoundException, as a result of FileOutputStream failing to create the file:

|-INFO in ch.qos.logback.core.rolling.RollingFileAppender[filelog] - File property is set to [/storage/sdcard/logfolder/2019-09-07-05:22:42.log]
    java.io.FileNotFoundException: /storage/sdcard/logfolder/2019-09-07-05:22:42.log: open failed: EINVAL (Invalid argument)

...

|-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[filelog] - openFile(/storage/sdcard/logfolder/2019-09-07-05:22:42.log,true) failed
    java.io.FileNotFoundException: /storage/sdcard/logfolder/2019-09-07-05:22:42.log: open failed: EINVAL (Invalid argument)

...

|-WARN in ch.qos.logback.core.rolling.RollingFileAppender[filelog] - Attempted to append to non started appender [filelog].

The workaround is to remove the colons from the RollingFileAppender's file property, while taking care to avoid any possible filename collisions with fileNamePattern. For example:

<timestamp key="datetime" datePattern="yyyy-MM-dd--HHmmss"/>
<file>${LOG_DIR}/${datetime}.log</file>
...
<fileNamePattern>${LOG_DIR}/%d{yyyy-MM-dd}.%i.log</fileNamePattern>

Android 6+

Since : is allowed in filenames in Android 6+, we don't need to worry about filename collisions mentioned above. The config could stay the same.

Also, make sure to request user permission to write to external storage, or else logback-android will fail to create any parent directories to the destination file (and be missing write-access to the file itself). If debug is enabled, you'd see logcat messages like this:

|-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[filelog] - Failed to create parent directories for [/storage/emulated/0/logfolder/2019-09-07-02:27:04.log]
|-ERROR in ch.qos.logback.core.rolling.RollingFileAppender[filelog] - openFile(/storage/emulated/0/logfolder/2019-09-07-02:27:04.log,true) failed
    java.io.FileNotFoundException: /storage/emulated/0/logfolder/2019-09-07-02:27:04.log: open failed: ENOENT (No such file or directory)

In your case, the permission requesting code should be in onCreate() of MainActivity.kt before logging anything that would cause writing to external storage:

import android.Manifest
import android.content.pm.PackageManager
import android.support.v4.app.ActivityCompat
import android.support.v4.content.ContextCompat

...

override fun onCreate(savedInstanceState: Bundle?) {
    super.onCreate(savedInstanceState)
    setContentView(R.layout.activity_main)

    if (ContextCompat.checkSelfPermission(this, Manifest.permission.WRITE_EXTERNAL_STORAGE) != PackageManager.PERMISSION_GRANTED) {
        ActivityCompat.requestPermissions(this, arrayOf(Manifest.permission.WRITE_EXTERNAL_STORAGE), 1)
    }

    logger.info { "hello world" }
}