diff --git a/logback-android/src/main/java/ch/qos/logback/classic/android/Clock.java b/logback-android/src/main/java/ch/qos/logback/classic/android/Clock.java new file mode 100644 index 0000000000..77cb023c94 --- /dev/null +++ b/logback-android/src/main/java/ch/qos/logback/classic/android/Clock.java @@ -0,0 +1,5 @@ +package ch.qos.logback.classic.android; + +interface Clock { + long currentTimeMillis(); +} diff --git a/logback-android/src/main/java/ch/qos/logback/classic/android/SQLiteAppender.java b/logback-android/src/main/java/ch/qos/logback/classic/android/SQLiteAppender.java index 7e24ac7266..596422704c 100644 --- a/logback-android/src/main/java/ch/qos/logback/classic/android/SQLiteAppender.java +++ b/logback-android/src/main/java/ch/qos/logback/classic/android/SQLiteAppender.java @@ -52,6 +52,11 @@ public class SQLiteAppender extends UnsynchronizedAppenderBase { private Duration maxHistory; private long lastCleanupTime = 0; private SQLiteLogCleaner logCleaner; + private Clock clock = new SystemClock(); + + void setClock(Clock clock) { + this.clock = clock; + } /** * Sets the database name resolver, used to customize the names of the table names @@ -183,7 +188,7 @@ public void start() { */ private void clearExpiredLogs(SQLiteDatabase db) { if (lastCheckExpired(this.maxHistory, this.lastCleanupTime)) { - this.lastCleanupTime = System.currentTimeMillis(); + this.lastCleanupTime = this.clock.currentTimeMillis(); this.getLogCleaner().performLogCleanup(db, this.maxHistory); } } @@ -197,7 +202,7 @@ private void clearExpiredLogs(SQLiteDatabase db) { private boolean lastCheckExpired(Duration expiry, long lastCleanupTime) { boolean isExpired = false; if (expiry != null && expiry.getMilliseconds() > 0) { - final long now = System.currentTimeMillis(); + final long now = this.clock.currentTimeMillis(); final long timeDiff = now - lastCleanupTime; isExpired = (lastCleanupTime <= 0) || (timeDiff >= expiry.getMilliseconds()); } @@ -209,10 +214,11 @@ private boolean lastCheckExpired(Duration expiry, long lastCleanupTime) { */ public SQLiteLogCleaner getLogCleaner() { if (this.logCleaner == null) { + final Clock thisClock = this.clock; this.logCleaner = new SQLiteLogCleaner() { @Override public void performLogCleanup(SQLiteDatabase db, Duration expiry) { - final long expiryMs = System.currentTimeMillis() - expiry.getMilliseconds(); + final long expiryMs = thisClock.currentTimeMillis() - expiry.getMilliseconds(); final String deleteExpiredLogsSQL = SQLBuilder.buildDeleteExpiredLogsSQL(dbNameResolver, expiryMs); db.execSQL(deleteExpiredLogsSQL); } diff --git a/logback-android/src/main/java/ch/qos/logback/classic/android/SystemClock.java b/logback-android/src/main/java/ch/qos/logback/classic/android/SystemClock.java new file mode 100644 index 0000000000..c9b990a594 --- /dev/null +++ b/logback-android/src/main/java/ch/qos/logback/classic/android/SystemClock.java @@ -0,0 +1,7 @@ +package ch.qos.logback.classic.android; + +final class SystemClock implements Clock { + public long currentTimeMillis() { + return System.currentTimeMillis(); + } +} diff --git a/logback-android/src/test/java/ch/qos/logback/classic/android/SQLiteAppenderTest.java b/logback-android/src/test/java/ch/qos/logback/classic/android/SQLiteAppenderTest.java index 7e97343fbe..4434dad0c1 100644 --- a/logback-android/src/test/java/ch/qos/logback/classic/android/SQLiteAppenderTest.java +++ b/logback-android/src/test/java/ch/qos/logback/classic/android/SQLiteAppenderTest.java @@ -13,7 +13,6 @@ */ package ch.qos.logback.classic.android; -import android.database.Cursor; import android.database.sqlite.SQLiteDatabase; import org.junit.After; @@ -25,27 +24,18 @@ import org.robolectric.RobolectricTestRunner; import org.slf4j.Logger; -import java.io.ByteArrayInputStream; import java.io.File; import java.io.IOException; -import java.io.InputStream; import ch.qos.logback.classic.LoggerContext; -import ch.qos.logback.classic.joran.JoranConfigurator; import ch.qos.logback.core.CoreConstants; -import ch.qos.logback.core.joran.spi.JoranException; -import ch.qos.logback.core.status.ErrorStatus; -import ch.qos.logback.core.status.StatusUtil; import ch.qos.logback.core.util.CoreTestConstants; import ch.qos.logback.core.util.Duration; import static org.hamcrest.Matchers.containsString; -import static org.hamcrest.Matchers.greaterThan; import static org.hamcrest.Matchers.is; -import static org.hamcrest.Matchers.lessThan; import static org.hamcrest.Matchers.notNullValue; import static org.junit.Assert.assertThat; -import static org.junit.Assert.fail; import static org.mockito.ArgumentMatchers.any; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.times; @@ -58,40 +48,25 @@ public class SQLiteAppenderTest { private static final long EXPIRY_MS = 500; private static final long NO_EXPIRY = 0; - private static final String SQLITE_APPENDER_WITHOUT_MAX_HISTORY_XML = - "" + - "" + - "" + TEST_SQLITE_FILENAME + "" + - "" + - "" + - "" + - "" + - ""; - - private static final String SQLITE_APPENDER_WITH_MAX_HISTORY_XML = - "" + - "" + - "" + TEST_SQLITE_FILENAME + "" + - "500 milli" + - "" + - "" + - "" + - "" + - ""; - @Rule public TemporaryFolder tmp = new TemporaryFolder(); private SQLiteLogCleaner logCleaner; - private long startTimeMs; private LoggerContext context; private SQLiteAppender appender; + private Long mockTimeMs; @Before public void setup() throws Exception { context = new LoggerContext(); context.putProperty(CoreConstants.PACKAGE_NAME_KEY, "com.example"); appender = new SQLiteAppender(); + mockTimeMs = System.currentTimeMillis(); + appender.setClock(new Clock() { + public long currentTimeMillis() { + return mockTimeMs; + } + }); appender.setFilename(TEST_SQLITE_FILENAME); appender.setContext(context); logCleaner = mock(SQLiteLogCleaner.class); @@ -103,38 +78,13 @@ public void teardown() { } @Test - public void maxHistoryRemovesExpiredLogs() throws InterruptedException, JoranException { - configureLogbackByString(SQLITE_APPENDER_WITH_MAX_HISTORY_XML); - final int count = 12; - addLogEvents(count, EXPIRY_MS / 2); - - Cursor c = getCursor(); - assertRowCount(c, 0, count); - - final int colIndex = c.getColumnIndex("timestmp"); - while (c.moveToNext()) { - final long timestamp = c.getLong(colIndex); - assertThat(timestamp, is(greaterThan(startTimeMs - EXPIRY_MS))); - } - } - - @Test - public void maxHistoryIsDisabledByDefault() throws InterruptedException, JoranException { - configureLogbackByString(SQLITE_APPENDER_WITHOUT_MAX_HISTORY_XML); - final int count = 1000; - addLogEvents(count, NO_EXPIRY); - - assertThat(getCursor().getCount(), is(count)); - } - - @Test - public void cleanuOccursAtAppenderStartup() throws InterruptedException { + public void cleanuOccursAtAppenderStartup() { addAppenderToContext("1 hour"); verify(logCleaner, times(1)).performLogCleanup(any(SQLiteDatabase.class), any(Duration.class)); } @Test - public void cleanupDoesNotOccurBeforeExpiration() throws InterruptedException { + public void cleanupDoesNotOccurBeforeExpiration() { addAppenderToContext("1 hour"); addLogEvents(3, NO_EXPIRY); @@ -145,7 +95,7 @@ public void cleanupDoesNotOccurBeforeExpiration() throws InterruptedException { } @Test - public void cleanupOccursAfterEveryExpiration() throws InterruptedException { + public void cleanupOccursAfterEveryExpiration() { addAppenderToContext(EXPIRY_MS + " milli"); final int count = 7; @@ -232,29 +182,21 @@ public void getMaxHistoryMsZeroByDefault() { assertThat(appender.getMaxHistoryMs(), is(0L)); } - private void configureLogbackByString(String xml) throws JoranException { - JoranConfigurator config = new JoranConfigurator(); - config.setContext(context); - - InputStream stream = new ByteArrayInputStream(xml.getBytes()); - config.doConfigure(stream); - - StatusUtil statusUtil = new StatusUtil(context); - if (statusUtil.getHighestLevel(0) == ErrorStatus.ERROR) { - fail("Configuration error found"); - } - } - - private void addLogEvents(int count, long delayMs) throws InterruptedException { + private long addLogEvents(int count, long delayMs) { Logger log = context.getLogger(SQLiteAppenderTest.class); - startTimeMs = System.currentTimeMillis(); + final long startTimeMs = mockTimeMs; + long currTimeMs = startTimeMs; + System.out.println("start=" + startTimeMs); for (int i = 0; i < count; i++) { log.info("i={}", i); if (delayMs > 0) { - Thread.sleep(delayMs); + currTimeMs += delayMs; + mockTimeMs = currTimeMs; + System.out.println("mockTime=" + mockTimeMs + " actual="+ System.currentTimeMillis()); } } + return startTimeMs; } /** Gets a SQLiteAppender with a no-op log-cleaner mock */ @@ -265,14 +207,4 @@ private void addAppenderToContext(String maxHistory) { ch.qos.logback.classic.Logger testRoot = context.getLogger(SQLiteAppenderTest.class); testRoot.addAppender(appender); } - - private Cursor getCursor() { - SQLiteDatabase db = SQLiteDatabase.openDatabase(TEST_SQLITE_FILENAME, null, SQLiteDatabase.OPEN_READONLY); - return db.rawQuery("SELECT timestmp FROM logging_event;", null); - } - - private void assertRowCount(Cursor c, int min, int max) { - assertThat(c.getCount(), is(greaterThan(min))); - assertThat(c.getCount(), is(lessThan(max))); - } }