JUnit tests for writing to file pass locally but fail on Travis CI

Question

The problem

Me and my group members have been instructed by our teacher to implement a logger for our game. This logger should be well tested with JUnit and so we did. One problem we are dealing with for a while now is that all these tests pass locally but are failing every now and then on Travis CI.

Our analysis

We suspect that there is not enough time for these tests to actually create and remove the logging file before the assertion is executed. However, we aren't really sure if this is what causing our tests to fail on Travis.

Our code

Logger.java

package logging;

import java.io.BufferedReader;
import java.io.BufferedWriter;
import java.io.File;
import java.io.FileReader;
import java.io.FileWriter;
import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.StandardCopyOption;
import java.sql.Timestamp;
import java.util.Calendar;

public final class Logger extends Thread {
    private static volatile boolean debug = false;
    private static volatile StringBuilder queue = new StringBuilder();
    private static volatile File file = new File("log.log");
    private static volatile int logLength = 10000;
    private static Logger logger;

    /**
     * supported logging types.
     *
     */
    public enum LogType {
        INFO, WARNING, ERROR
    }

    private Logger() {
    } // unreachable because static

    /**
     * The logger runs in his own thread to prevent concurrent writing
     * exceptions on the log file if multiple threads are logging.
     */
    public void run() {
        while (debug) {
            try {
                sleep(10000);
                if (queue.length() > 0) {
                    try {
                        writeToFile();
                    } catch (IOException exception) {
                        exception.printStackTrace();
                    }
                }
            } catch (InterruptedException exception) {
                exception.printStackTrace();
            }
        }
    }

    private void writeToFile() throws IOException {
        if (!file.exists()) {
            file.createNewFile();
        }
        FileWriter writer = new FileWriter(file, true);
        writer.write(queue.toString());
        writer.close();
        capFileSize();
    }

    private void capFileSize() throws IOException {
        int fileLength = countLines();
        if (fileLength > logLength) {
            String line;
            File tempFile = File.createTempFile("TETRIS_LOG_", ".log");
            BufferedWriter writer = new BufferedWriter(new FileWriter(tempFile));
            try {
                BufferedReader reader = new BufferedReader(new FileReader(file));
                try {
                    skipLines(fileLength - logLength, reader);
                    while ((line = reader.readLine()) != null) {
                        writer.write(line);
                        writer.newLine();
                    }
                } finally {
                    reader.close();
                }
            } finally {
                writer.close();
            }
            Files.move(tempFile.toPath(), file.toPath(), StandardCopyOption.REPLACE_EXISTING);
        }
    }

    private void skipLines(int lines, BufferedReader file) throws IOException {
        for (int i = 0; i < lines; i++) {
            file.readLine();
        }
    }

    private int countLines() throws IOException {
        char[] buffer = new char[1024];
        int count = 0;
        int readChars = 0;
        boolean empty = true;
        BufferedReader reader = new BufferedReader(new FileReader(file));
        try {
            while ((readChars = reader.read(buffer)) != -1) {
                empty = false;
                for (int i = 0; i < readChars; ++i) {
                    if (buffer[i] == '\n') {
                        ++count;
                    }
                }
            }
            return (count == 0 && !empty) ? 1 : count;
        } finally {
            reader.close();
        }
    }

    /**
     * Log lets you log a line in the log file, conditional on the debug mode
     * being on.
     * 
     * @param sender
     *            the object invoking the log statement
     * @param logtype
     *            the log type, for homogeneity constrained in the LogType enum
     * @param message
     *            the message that is logged
     */
    public static void log(Object sender, LogType logtype, String message) {
        if (debug) {
            String msg = String.format("[%s] message @[%s] from object %s: %s\r\n",
                logtype.toString(),
                new Timestamp(Calendar.getInstance().getTimeInMillis()).toString(),
                sender.toString(), message);
            queue.append(msg);
        }
    }

    public static void info(Object sender, String message) {
        Logger.log(sender, LogType.INFO, message);
    }

    public static void error(Object sender, String message) {
        Logger.log(sender, LogType.ERROR, message);
    }

    public static void warning(Object sender, String message) {
        Logger.log(sender, LogType.WARNING, message);
    }

    /**
     * clearLog truncates the log, in case you accidentally logged a nude
     * picture or something.
     */
    public static void clearLog() {
        try {
            Files.deleteIfExists(file.toPath());
        } catch (IOException exception) {
            exception.printStackTrace();
        }
    }

    /* getters / setters */
    public static int getLogLength() {
        return logLength;
    }

    public static void setLogLength(int length) {
        logLength = length;
    }

    public static void setLogDir(String path) {
        file = new File(path);
    }

    public static String getLogDir() {
        return file.toString();
    }

    /**
     * switch debug on.
     */
    public static synchronized void setDebugOn() {
        if (!debug) {
            debug = true;
            logger = new Logger();
            logger.start();
        }
    }

    /**
     * switch debug off.
     */
    public static void setDebugOff() {
        if (debug) {
            debug = false;
            try {
                logger.join();
            } catch (InterruptedException exception) {
                exception.printStackTrace();
            }
        }
        logger = null;
    }
}

LoggerTest.java

package logging;

import java.io.BufferedReader;
import java.io.File;
import java.io.FileReader;
import java.io.IOException;

import org.junit.Test;

import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertFalse;
import static org.junit.Assert.assertTrue;

public class LoggerTest {
    @Test
    public void test_logcreate() {
        String testloc = "test.log";
        Logger.setLogDir(testloc);
        Logger.clearLog();
        Logger.setDebugOn();
        Logger.log(this, Logger.LogType.ERROR, "test 1");
        Logger.setDebugOff();
        assertTrue(new File(testloc).exists());
    }

    @Test
    public void test_logdelete() {
        String testloc = "test.log";
        Logger.setLogDir(testloc);
        Logger.setDebugOn();
        Logger.log(this, Logger.LogType.ERROR, "test 1");
        assertTrue(new File(testloc).exists());
        Logger.setDebugOff();
        Logger.clearLog();
        assertFalse(new File(testloc).exists());
    }

    @Test
    public void test_debugMode() {
        String testloc = "test.log";
        Logger.setLogDir(testloc);
        Logger.setDebugOff();
        Logger.clearLog();
        Logger.log(this, Logger.LogType.ERROR, "test 1");

        assertFalse(new File(testloc).exists());
    }

    @Test
    public void test_capLog() throws IOException, InterruptedException {
        String testloc = "test.log";
        Logger.setLogDir(testloc);
        Logger.setLogLength(10);
        Logger.clearLog();
        Logger.setDebugOn();
        for (int i = 0; i < 100; i++) {
            Logger.log(this, Logger.LogType.ERROR, "test 1");
        }
        Logger.setDebugOff();
        Thread.sleep(1000);
        assertTrue(new File(testloc).exists());

        int count = 0;
        File file = new File(testloc);
        FileReader fileReader = new FileReader(file);
        BufferedReader reader = new BufferedReader(fileReader);
        while (reader.readLine() != null) {
            ++count;
        }
        reader.close();
        assertEquals(10, count);

    }
}

Travis job log

[...]

:test
Download https://jcenter.bintray.com/org/jacoco/org.jacoco.agent/0.7.7.201606060606/org.jacoco.agent-0.7.7.201606060606.pom
Download https://jcenter.bintray.com/org/jacoco/org.jacoco.build/0.7.7.201606060606/org.jacoco.build-0.7.7.201606060606.pom
Download https://jcenter.bintray.com/org/jacoco/org.jacoco.agent/0.7.7.201606060606/org.jacoco.agent-0.7.7.201606060606.jar
tetris.LoggerTest > test_logcreate FAILED
    java.lang.AssertionError at LoggerTest.java:26
tetris.LoggerTest > test_logdelete FAILED
    java.lang.AssertionError at LoggerTest.java:35
47 tests completed, 2 failed
:test FAILED
FAILURE: Build failed with an exception.
* What went wrong:
Execution failed for task ':test'.

[...]

EDIT #1

I have used Awaitility but Travis is still struggling with file creation/deletion. Even with one minute timeout.

LoggerTest.java

package tetris;

import java.io.BufferedReader;
import java.io.File;
import java.io.FileReader;
import java.util.concurrent.Callable;

import org.junit.Test;

import static com.jayway.awaitility.Awaitility.with;
import static com.jayway.awaitility.Duration.*;
import static org.hamcrest.Matchers.equalTo;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertFalse;
import static org.junit.Assert.assertTrue;

import logging.Logger;

public class LoggerTest {

    @Test
    public void test_logcreate() throws Exception {
        String testloc = "test.log";
        Logger.setLogDir(testloc);
        Logger.clearLog();
        Logger.setDebugOn();
        Logger.log(this, Logger.LogType.ERROR, "test 1");
        Logger.setDebugOff();

        asyncWaitForFileCreation(testloc);
        assertTrue(new File(testloc).exists());
    }

    @Test
    public void test_logdelete() throws Exception {
        String testloc = "test.log";
        Logger.setLogDir(testloc);
        Logger.setDebugOn();
        Logger.log(this, Logger.LogType.ERROR, "test 1");

        asyncWaitForFileCreation(testloc);
        assertTrue(new File(testloc).exists());

        Logger.setDebugOff();
        Logger.clearLog();

        asyncWaitForFileRemoval(testloc);
        assertFalse(new File(testloc).exists());
    }

    @Test
    public void test_debugMode() throws Exception {
        String testloc = "test.log";
        Logger.setLogDir(testloc);
        Logger.setDebugOff();
        Logger.clearLog();
        Logger.log(this, Logger.LogType.ERROR, "test 1");

        asyncWaitForFileRemoval(testloc);
        assertFalse(new File(testloc).exists());
    }

    @Test
    public void test_capLog() throws Exception {
        String testloc = "test.log";
        Logger.setLogDir(testloc);
        Logger.setLogLength(10);
        Logger.clearLog();
        Logger.setDebugOn();
        for (int i = 0; i < 100; i++) {
            Logger.log(this, Logger.LogType.ERROR, "test 1");
            Logger.info(this, "test 1");
            Logger.warning(this, "test 1");
            Logger.error(this, "test 1");
        }
        Logger.setDebugOff();

        File testlocFile = new File(testloc);

        asyncWaitForFileCreation(testloc);
        assertTrue(testlocFile.exists());

        int count = 0;
        File file = new File(testloc);
        FileReader fileReader = new FileReader(file);
        BufferedReader reader = new BufferedReader(fileReader);
        while (reader.readLine() != null) {
            ++count;
        }
        reader.close();

        assertEquals(10, count);
    }
    @Test
    public void test_getters() throws ClassCastException {
        assertTrue(Logger.getLogDir() instanceof String);
        assertTrue(Logger.getLogLength() == Logger.getLogLength());
    }

    private void asyncWaitForFileCreation(String testloc) throws Exception {
        with().pollDelay(ONE_HUNDRED_MILLISECONDS)
                .and().with().pollInterval(TWO_HUNDRED_MILLISECONDS)
                .and().with().timeout(ONE_MINUTE)
                .await("file creation")
                .until(fileIsCreatedOnDisk(testloc), equalTo(true));
    }

    private void asyncWaitForFileRemoval(String testloc) throws Exception {
        with().pollDelay(ONE_HUNDRED_MILLISECONDS)
                .and().with().pollInterval(TWO_HUNDRED_MILLISECONDS)
                .and().with().timeout(ONE_MINUTE)
                .await("file removal")
                .until(fileIsRemovedFromDisk(testloc), equalTo(true));
    }

    private Callable<Boolean> fileIsCreatedOnDisk(final String filename) {
        return () -> {
            File file = new File(filename);
            return file.exists();
        };
    }

    private Callable<Boolean> fileIsRemovedFromDisk(final String filename) {
        return () -> {
            File file = new File(filename);
            return !file.exists();
        };
    }
}

Travis job log

:test
Download https://jcenter.bintray.com/org/jacoco/org.jacoco.agent/0.7.7.201606060606/org.jacoco.agent-0.7.7.201606060606.pom
Download https://jcenter.bintray.com/org/jacoco/org.jacoco.build/0.7.7.201606060606/org.jacoco.build-0.7.7.201606060606.pom
Download https://jcenter.bintray.com/org/jacoco/org.jacoco.agent/0.7.7.201606060606/org.jacoco.agent-0.7.7.201606060606.jar
tetris.LoggerTest > test_logcreate FAILED
    java.util.concurrent.TimeoutException at LoggerTest.java:36
tetris.LoggerTest > test_capLog FAILED
    java.util.concurrent.TimeoutException at LoggerTest.java:94
47 tests completed, 2 failed
:test FAILED
FAILURE: Build failed with an exception.
* What went wrong:
Execution failed for task ':test'.

score 1 · Answer 1 · answered Oct 11 '16 at 12:33

1

In your first test case, you give your Logger Thread not enough time to create the file. This may work on some OSes, but Travis CI is sloooow. Recommendation: Create a method which polls for a condition (in this case, file exists) for some time (at least five seconds) with some interval (e.g. 100ms).

private static boolean pollForCondition(Callable<Boolean> condition) {
  while (/* ... */) {
    if (condition.call().booleanValue()) {
      return true;
    }
    // ...
  }
  return false;
}

This method should be used from all your test cases (from within an assertTrue()).

Also, consider that the execution order of your test cases is not determined (starting with Java 6 or 7, AFAIK). Do you delete created files somewhere before the next test case is starting?

answered Oct 11 '16 at 12:33

Florian Albrecht

2,266
1
20
25

I tried to apply your suggestion but without luck. Could you please have another look at my edit? – Pascal Oct 12 '16 at 19:48
Did you check my last point? The execution order on Travis could differ from your local execution order. Try executing your tests locally one by one without cleaning in between, and check if they work when executed in e.g. reverse order. – Florian Albrecht Oct 13 '16 at 08:17
The order test_logcreate, test_logdelete, test_capLog, test_getters, test_debugMode seems to work locally. But... the order test_capLog, test_debugMode, test_getters, test_logcreate, test_logdelete fails. – Pascal Oct 13 '16 at 13:57
Well, this is your problem. Read something about Before and After methods in JUnit. You must set up a "clean" environment with a Before method, which is suitable for each single test method. – Florian Albrecht Oct 13 '16 at 14:18

JUnit tests for writing to file pass locally but fail on Travis CI

1 Answers1