Refactor file logging logic

app/build.gradle

@@ -221,10 +221,10 @@ dependencies {
     implementation "com.google.code.gson:gson:2.8.6"
 
     implementation "no.nordicsemi.android:dfu:1.11.1"
-    implementation("com.github.tony19:logback-android-classic:1.1.1-6") {
+    implementation("com.github.tony19:logback-android:2.0.0") {
         exclude group: "com.google.android", module: "android"
     }
-    implementation "org.slf4j:slf4j-api:1.7.24"
+    implementation "org.slf4j:slf4j-api:1.7.36"
     implementation "com.github.PhilJay:MPAndroidChart:v3.1.0"
     implementation "com.github.pfichtner:durationformatter:0.1.1"
     implementation "de.cketti.library.changelog:ckchangelog:1.2.2"

app/src/main/assets/logback.xml

@@ -8,32 +8,8 @@
         </encoder>
     </appender>
 
-    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
-        <file>${GB_LOGFILES_DIR}/gadgetbridge.log</file>
-
-        <lazy>true</lazy>
-        <!-- encoders are  by default assigned the type
-             ch.qos.logback.classic.encoder.PatternLayoutEncoder -->
-        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
-            <fileNamePattern>${GB_LOGFILES_DIR}/gadgetbridge-%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
-            <maxHistory>10</maxHistory>
-            <timeBasedFileNamingAndTriggeringPolicy
-                class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
-                <!-- or whenever the file size reaches 50MB -->
-                <maxFileSize>2MB</maxFileSize>
-            </timeBasedFileNamingAndTriggeringPolicy>
-        </rollingPolicy>
-        <encoder>
-            <!--<pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>-->
-            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{1} - %msg%n</pattern>
-            <!-- to debug crashes, set immediateFlush to true, otherwise keep it false to improve throughput -->
-            <immediateFlush>false</immediateFlush>
-            <!--<pattern>%date [%thread] %-5level %logger{25} - %msg%n</pattern>-->
-        </encoder>
-    </appender>
-
     <root level="DEBUG">
         <appender-ref ref="STDOUT" />
-        <appender-ref ref="FILE" />
+        <!-- The FILE appender is added programmatically by nodomain.freeyourgadget.gadgetbridge.Logging -->
     </root>
 </configuration>

app/src/main/java/nodomain/freeyourgadget/gadgetbridge/Logging.java

@@ -24,22 +24,29 @@ import org.slf4j.LoggerFactory;
 import java.io.IOException;
 
 import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
 import ch.qos.logback.classic.spi.ILoggingEvent;
 import ch.qos.logback.core.Appender;
 import ch.qos.logback.core.FileAppender;
 import ch.qos.logback.core.encoder.Encoder;
 import ch.qos.logback.core.encoder.LayoutWrappingEncoder;
+import ch.qos.logback.core.rolling.RollingFileAppender;
+import ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy;
+import ch.qos.logback.core.rolling.TimeBasedRollingPolicy;
+import ch.qos.logback.core.util.FileSize;
 import ch.qos.logback.core.util.StatusPrinter;
 import nodomain.freeyourgadget.gadgetbridge.util.GB;
 
 public abstract class Logging {
+    // Only used for tests
     public static final String PROP_LOGFILES_DIR = "GB_LOGFILES_DIR";
 
+    private String logDirectory;
     private FileAppender<ILoggingEvent> fileLogger;
 
     public void setupLogging(boolean enable) {
         try {
-            if (fileLogger == null) {
+            if (!isFileLoggerInitialized()) {
                 init();
             }
             if (enable) {
@@ -47,8 +54,8 @@ public abstract class Logging {
             } else {
                 stopFileLogger();
             }
-            getLogger().info("Gadgetbridge version: " + BuildConfig.VERSION_NAME);
+            getLogger().info("Gadgetbridge version: {}", BuildConfig.VERSION_NAME);
-        } catch (IOException ex) {
+        } catch (Exception ex) {
             Log.e("GBApplication", "External files dir not available, cannot log to file", ex);
             stopFileLogger();
         }
@@ -62,7 +69,7 @@ public abstract class Logging {
     }
 
     public boolean isFileLoggerInitialized() {
-        return fileLogger != null;
+        return logDirectory != null;
     }
 
     public void debugLoggingConfiguration() {
@@ -76,17 +83,11 @@ public abstract class Logging {
     protected abstract String createLogDirectory() throws IOException;
 
     protected void init() throws IOException {
-        rememberFileLogger();
+        Log.i("GBApplication", "Initializing logging");
-        String dir = createLogDirectory();
+        logDirectory = createLogDirectory();
-        if (dir == null) {
+        if (logDirectory == null) {
             throw new IllegalArgumentException("log directory must not be null");
         }
-        // used by assets/logback.xml since the location cannot be statically determined
-        System.setProperty(PROP_LOGFILES_DIR, dir);
-    }
-
-    public boolean isInitialized() {
-        return System.getProperty(PROP_LOGFILES_DIR) != null;
     }
 
     private Logger getLogger() {
@@ -94,49 +95,55 @@ public abstract class Logging {
     }
 
     private void startFileLogger() {
-        if (fileLogger != null && !fileLogger.isStarted()) {
+        if (fileLogger != null) {
-            addFileLogger(fileLogger);
+            Log.w("GBApplication", "Logger already started");
-            fileLogger.setLazy(false); // hack to make sure that start() actually opens the file
+            return;
-            fileLogger.start();
         }
+
+        if (logDirectory == null) {
+            Log.e("GBApplication", "Can't start file logging without a log directory");
+            return;
+        }
+
+        final FileAppender fileAppender = createFileAppender(logDirectory);
+        fileAppender.start();
+        attachLogger(fileAppender);
+        fileLogger = fileAppender;
     }
 
     private void stopFileLogger() {
-        if (fileLogger != null && fileLogger.isStarted()) {
+        if (fileLogger == null) {
+            return;
+        }
+
+        if (fileLogger.isStarted()) {
             fileLogger.stop();
         }
-        // We still need to remove the logger from the root appender, otherwise slf4j will log to
+
-        // a GB_LOGFILES_DIR_IS_UNDEFINED directory (especially if something failed before we got
+        detachLogger(fileLogger);
-        // the fileLogger
+
-        removeFileLogger();
+        fileLogger = null;
     }
 
-    private void rememberFileLogger() {
+    private void attachLogger(Appender<ILoggingEvent> logger) {
-        if (fileLogger == null) {
+        try {
             ch.qos.logback.classic.Logger root = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
-            fileLogger = (FileAppender<ILoggingEvent>) root.getAppender("FILE");
+            if (!root.isAttached(logger)) {
+                root.addAppender(logger);
+            }
+        } catch (Throwable ex) {
+            Log.e("GBApplication", "Error attaching logger appender", ex);
         }
     }
 
-    private void addFileLogger(Appender<ILoggingEvent> fileLogger) {
+    private void detachLogger(Appender<ILoggingEvent> logger) {
         try {
             ch.qos.logback.classic.Logger root = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
-            if (!root.isAttached(fileLogger)) {
+            if (logger != null && root.isAttached(logger)) {
-                root.addAppender(fileLogger);
+                root.detachAppender(logger);
             }
         } catch (Throwable ex) {
-            Log.e("GBApplication", "Error adding logger FILE appender", ex);
+            Log.e("GBApplication", "Error detaching logger appender", ex);
-        }
-    }
-
-    private void removeFileLogger() {
-        try {
-            ch.qos.logback.classic.Logger root = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
-            if (fileLogger != null && root.isAttached(fileLogger)) {
-                root.detachAppender(fileLogger);
-            }
-        } catch (Throwable ex) {
-            Log.e("GBApplication", "Error removing logger FILE appender", ex);
         }
     }
 
@@ -144,25 +151,6 @@ public abstract class Logging {
         return fileLogger;
     }
 
-    public boolean setImmediateFlush(boolean enable) {
-        FileAppender<ILoggingEvent> fileLogger = getFileLogger();
-        Encoder<ILoggingEvent> encoder = fileLogger.getEncoder();
-        if (encoder instanceof LayoutWrappingEncoder) {
-            ((LayoutWrappingEncoder) encoder).setImmediateFlush(enable);
-            return true;
-        }
-        return false;
-    }
-
-    public boolean isImmediateFlush() {
-        FileAppender<ILoggingEvent> fileLogger = getFileLogger();
-        Encoder<ILoggingEvent> encoder = fileLogger.getEncoder();
-        if (encoder instanceof LayoutWrappingEncoder) {
-            return ((LayoutWrappingEncoder) encoder).isImmediateFlush();
-        }
-        return false;
-    }
-
     public static String formatBytes(byte[] bytes) {
         if (bytes == null) {
             return "(null)";
@@ -180,4 +168,36 @@ public abstract class Logging {
             logger.warn("DATA: " + GB.hexdump(value, 0, value.length));
         }
     }
+
+    public static FileAppender createFileAppender(final String logDirectory) {
+        final LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
+
+        final PatternLayoutEncoder ple = new PatternLayoutEncoder();
+        //ple.setPattern("%date %level [%thread] %logger{10} [%file:%line] %msg%n");
+        ple.setPattern("%d{HH:mm:ss.SSS} [%thread] %-5level %logger{1} - %msg%n");
+        ple.setContext(lc);
+        ple.start();
+
+        final SizeAndTimeBasedRollingPolicy rollingPolicy = new SizeAndTimeBasedRollingPolicy();
+        final RollingFileAppender<ILoggingEvent> fileAppender = new RollingFileAppender<ILoggingEvent>();
+
+        rollingPolicy.setContext(lc);
+        rollingPolicy.setFileNamePattern(logDirectory + "/gadgetbridge-%d{yyyy-MM-dd}.%i.log.zip");
+        rollingPolicy.setParent(fileAppender);
+        rollingPolicy.setMaxFileSize(FileSize.valueOf("2MB"));
+        rollingPolicy.setMaxHistory(10);
+        rollingPolicy.setTotalSizeCap(FileSize.valueOf("100MB"));
+        rollingPolicy.start();
+
+        fileAppender.setContext(lc);
+        fileAppender.setName("FILE");
+        fileAppender.setLazy(true);
+        fileAppender.setFile(logDirectory + "/gadgetbridge.log");
+        fileAppender.setEncoder(ple);
+        // to debug crashes, set immediateFlush to true, otherwise keep it false to improve throughput
+        fileAppender.setImmediateFlush(false);
+        fileAppender.setRollingPolicy(rollingPolicy);
+
+        return fileAppender;
+    }
 }

app/src/main/java/nodomain/freeyourgadget/gadgetbridge/activities/SettingsActivity.java

@@ -185,7 +185,7 @@ public class SettingsActivity extends AbstractSettingsActivity {
         });
 
         // If we didn't manage to initialize file logging, disable the preference
-        if (!GBApplication.getLogging().isInitialized()) {
+        if (!GBApplication.getLogging().isFileLoggerInitialized()) {
             pref.setEnabled(false);
             pref.setSummary(R.string.pref_write_logfiles_not_available);
         }

app/src/main/java/nodomain/freeyourgadget/gadgetbridge/util/FileUtils.java

@@ -265,7 +265,16 @@ public class FileUtils {
             }
 
             if (!GBEnvironment.env().isLocalTest()) { // don't do this with robolectric
-                final String storageState = Environment.getExternalStorageState(dir);
+                final String storageState;
+                if (android.os.Build.VERSION.SDK_INT >= android.os.Build.VERSION_CODES.LOLLIPOP) {
+                    storageState = Environment.getExternalStorageState(dir);
+                } else if(i == 0) {
+                    // the first directory is also the primary external storage, i.e. the same as Environment.getExternalFilesDir()
+                    storageState = Environment.getExternalStorageState();
+                } else {
+                    // Assume it is mounted on older android versions - we test writing later
+                    storageState = Environment.MEDIA_MOUNTED;
+                }
                 if (!Environment.MEDIA_MOUNTED.equals(storageState)) {
                     GB.log("ignoring '" +  storageState + "' external storage dir: " + dir, GB.INFO, null);
                     continue;

app/src/main/java/nodomain/freeyourgadget/gadgetbridge/util/GB.java

@@ -462,18 +462,6 @@ public class GB {
     }
 
     public static void log(String message, int severity, Throwable ex) {
-
-        // Handle if slf4j is not setup yet as this causes this issue:
-        // https://codeberg.org/Freeyourgadget/Gadgetbridge/issues/2394
-        // and similar, as reported by users via matrix chat, because
-        // under some conditions the FileUtils.getWritableExternalFilesDirs
-        // can break the slf4j rule again, but this method is used while bootstrapping
-        // slf4j, so catch22... and it is useful to have proper logging when slf4f is ready.
-        if (!GBApplication.getLogging().isFileLoggerInitialized()) {
-            Log.i(TAG, message);
-            return;
-        }
-
         switch (severity) {
             case INFO:
                 LOG.info(message, ex);

app/src/test/java/nodomain/freeyourgadget/gadgetbridge/test/LoggingTest.java

@@ -11,8 +11,8 @@ import nodomain.freeyourgadget.gadgetbridge.Logging;
 import nodomain.freeyourgadget.gadgetbridge.util.FileUtils;
 
 import static org.junit.Assert.assertEquals;
-import static org.junit.Assert.assertFalse;
 import static org.junit.Assert.assertNotNull;
+import static org.junit.Assert.assertNull;
 import static org.junit.Assert.assertTrue;
 import static org.junit.Assert.fail;
 
@@ -59,8 +59,7 @@ public class LoggingTest extends TestBase {
             assertTrue(logging.getFileLogger().isStarted());
 
             logging.setupLogging(false);
-            assertNotNull(logging.getFileLogger());
+            assertNull(logging.getFileLogger());
-            assertFalse(logging.getFileLogger().isStarted());
 
             logging.setupLogging(true);
             assertNotNull(logging.getFileLogger());

app/src/test/java/nodomain/freeyourgadget/gadgetbridge/test/TestBase.java

@@ -24,6 +24,7 @@ import nodomain.freeyourgadget.gadgetbridge.model.DeviceType;
 import nodomain.freeyourgadget.gadgetbridge.util.FileUtils;
 
 import static org.junit.Assert.assertNotNull;
+import static nodomain.freeyourgadget.gadgetbridge.Logging.PROP_LOGFILES_DIR;
 
 /**
  * Base class for all testcases in Gadgetbridge that are supposed to run locally
@@ -51,12 +52,12 @@ public abstract class TestBase {
         System.setProperty("robolectric.logging", "stdout");
 
         // properties might be preconfigured in build.gradle because of test ordering problems
-        String logDir = System.getProperty(Logging.PROP_LOGFILES_DIR);
+        String logDir = System.getProperty(PROP_LOGFILES_DIR);
         if (logDir != null) {
             logFilesDir = new File(logDir);
         } else {
             logFilesDir = FileUtils.createTempDir("logfiles");
-            System.setProperty(Logging.PROP_LOGFILES_DIR, logFilesDir.getAbsolutePath());
+            System.setProperty(PROP_LOGFILES_DIR, logFilesDir.getAbsolutePath());
         }
 
         if (System.getProperty(ContextInitializer.CONFIG_FILE_PROPERTY) == null) {