Rework log item caching, might work better or at least give a better understanding what goes wrong (closes #455)

6 files changed, 251 insertions, 58 deletions

diff --git a/main/build.gradle b/main/build.gradle
index 7312a126..bd296540 100644
--- a/main/build.gradle
+++ b/main/build.gradle
@@ -16,6 +16,8 @@ dependencies {
     compile 'com.android.support:cardview-v7:23.3.0'
     compile 'com.android.support:recyclerview-v7:23.3.0'
     //    compile 'ch.acra:acra:4.5.0'
+
+    testCompile 'junit:junit:4.12'
 }
 
 android {
diff --git a/main/src/main/java/de/blinkt/openvpn/core/LogFileHandler.java b/main/src/main/java/de/blinkt/openvpn/core/LogFileHandler.java
index d69fdfb0..dfa6c5fa 100644
--- a/main/src/main/java/de/blinkt/openvpn/core/LogFileHandler.java
+++ b/main/src/main/java/de/blinkt/openvpn/core/LogFileHandler.java
@@ -16,6 +16,8 @@ import java.io.FileInputStream;
 import java.io.FileNotFoundException;
 import java.io.FileOutputStream;
 import java.io.IOException;
+import java.io.InputStream;
+import java.io.OutputStream;
 import java.nio.ByteBuffer;
 import java.util.Locale;
 
@@ -29,7 +31,8 @@ class LogFileHandler extends Handler {
     static final int FLUSH_TO_DISK = 101;
     static final int LOG_INIT = 102;
     public static final int LOG_MESSAGE = 103;
-    private static FileOutputStream mLogFile;
+    public static final int MAGIC_BYTE = 0x55;
+    protected OutputStream mLogFile;
 
     public static final String LOGFILE_NAME = "logcache.dat";
 
@@ -72,10 +75,10 @@ class LogFileHandler extends Handler {
         mLogFile.flush();
     }
 
-    private static void trimLogFile() {
+    private void trimLogFile() {
         try {
             mLogFile.flush();
-            mLogFile.getChannel().truncate(0);
+            ((FileOutputStream) mLogFile).getChannel().truncate(0);
         } catch (IOException e) {
             e.printStackTrace();
         }
@@ -88,79 +91,147 @@ class LogFileHandler extends Handler {
         // write binary format to disc
         byte[] liBytes = p.marshall();
 
-        byte[] lenBytes = ByteBuffer.allocate(4).putInt(liBytes.length).array();
-        mLogFile.write(lenBytes);
-        mLogFile.write(liBytes);
+        writeEscapedBytes(liBytes);
         p.recycle();
     }
 
-    private void openLogFile (File cacheDir) throws FileNotFoundException {
+    public void writeEscapedBytes(byte[] bytes) throws IOException {
+        int magic = 0;
+        for (byte b : bytes)
+            if (b == MAGIC_BYTE || b == MAGIC_BYTE + 1)
+                magic++;
+
+        byte eBytes[] = new byte[bytes.length + magic];
+
+        int i = 0;
+        for (byte b : bytes) {
+            if (b == MAGIC_BYTE || b == MAGIC_BYTE + 1) {
+                eBytes[i++] = MAGIC_BYTE + 1;
+                eBytes[i++] = (byte) (b - MAGIC_BYTE);
+            } else {
+                eBytes[i++] = b;
+            }
+        }
+
+        byte[] lenBytes = ByteBuffer.allocate(4).putInt(bytes.length).array();
+        synchronized (mLogFile) {
+            mLogFile.write(MAGIC_BYTE);
+            mLogFile.write(lenBytes);
+            mLogFile.write(eBytes);
+        }
+    }
+
+    private void openLogFile(File cacheDir) throws FileNotFoundException {
         File logfile = new File(cacheDir, LOGFILE_NAME);
         mLogFile = new FileOutputStream(logfile);
     }
 
     private void readLogCache(File cacheDir) {
-        File logfile = new File(cacheDir, LOGFILE_NAME);
+        try {
+            File logfile = new File(cacheDir, LOGFILE_NAME);
 
 
-        if (!logfile.exists() || !logfile.canRead())
-            return;
+            if (!logfile.exists() || !logfile.canRead())
+                return;
 
+            readCacheContents(new FileInputStream(logfile));
 
+        } catch (java.io.IOException | java.lang.RuntimeException e) {
+            VpnStatus.logError("Reading cached logfile failed");
+            VpnStatus.logException(e);
+            e.printStackTrace();
+            // ignore reading file error
+        }
+    }
 
-        try {
 
-            BufferedInputStream logFile = new BufferedInputStream(new FileInputStream(logfile));
+    protected void readCacheContents(InputStream in) throws IOException {
 
-            byte[] buf = new byte[8192];
-            int read = logFile.read(buf, 0, 4);
-            int itemsRead=0;
 
-            while (read >= 4) {
-                int len = ByteBuffer.wrap(buf, 0, 4).asIntBuffer().get();
+        BufferedInputStream logFile = new BufferedInputStream(in);
 
-                // Marshalled LogItem
-                read = logFile.read(buf, 0, len);
+        byte[] buf = new byte[16384];
+        int read = logFile.read(buf, 0, 5);
+        int itemsRead = 0;
 
-                Parcel p = Parcel.obtain();
-                p.unmarshall(buf, 0, read);
-                p.setDataPosition(0);
-                VpnStatus.LogItem li = VpnStatus.LogItem.CREATOR.createFromParcel(p);
-                if (li.verify()) {
-                    VpnStatus.newLogItem(li, true);
-                } else {
-                    VpnStatus.logError(String.format(Locale.getDefault(),
-                            "Could not read log item from file: %d/%d: %s",
-                            read, len, bytesToHex(buf, Math.max(read,80))));
+
+        readloop:
+        while (read >= 5) {
+            int skipped = 0;
+            while (buf[skipped] != MAGIC_BYTE) {
+                skipped++;
+                if (!(logFile.read(buf, skipped + 4, 1) == 1) || skipped + 10 > buf.length) {
+                    VpnStatus.logDebug(String.format(Locale.US, "Skipped %d bytes and no a magic byte found", skipped));
+                    break readloop;
                 }
-                p.recycle();
-
-                //Next item
-                read = logFile.read(buf, 0, 4);
-                itemsRead++;
-                if (itemsRead > 2*VpnStatus.MAXLOGENTRIES) {
-                    VpnStatus.logError("Too many logentries read from cache, aborting.");
-                    read = 0;
+            }
+            if (skipped > 0)
+                VpnStatus.logDebug(String.format(Locale.US, "Skipped %d bytes before finding a magic byte", skipped));
+
+            int len = ByteBuffer.wrap(buf, skipped+1, 4).asIntBuffer().get();
+
+            // Marshalled LogItem
+            int pos = 0;
+            byte buf2[] = new byte[buf.length];
+
+            while (pos < len) {
+                byte b = (byte) logFile.read();
+                if (b == MAGIC_BYTE) {
+                    VpnStatus.logDebug(String.format(Locale.US, "Unexpected magic byte found at pos %d, abort current log item", pos));
+                    read = logFile.read(buf, 1, 4) + 1;
+                    continue readloop;
+                } else if (b == MAGIC_BYTE + 1) {
+                    b = (byte) logFile.read();
+                    if (b == 0)
+                        b = MAGIC_BYTE;
+                    else if (b == 1)
+                        b = MAGIC_BYTE + 1;
+                    else {
+                        VpnStatus.logDebug(String.format(Locale.US, "Escaped byte not 0 or 1: %d", b));
+                        read = logFile.read(buf, 1, 4) + 1;
+                        continue readloop;
+                    }
                 }
+                buf2[pos++] = b;
+            }
+
+            restoreLogItem(buf2, len);
 
+            //Next item
+            read = logFile.read(buf, 0, 5);
+            itemsRead++;
+            if (itemsRead > 2 * VpnStatus.MAXLOGENTRIES) {
+                VpnStatus.logError("Too many logentries read from cache, aborting.");
+                read = 0;
             }
-            VpnStatus.logDebug(R.string.reread_log, itemsRead);
 
+        }
+        VpnStatus.logDebug(R.string.reread_log, itemsRead);
 
 
-        } catch (java.io.IOException | java.lang.RuntimeException e) {
-            VpnStatus.logError("Reading cached logfile failed");
-            VpnStatus.logException(e);
-            e.printStackTrace();
-            // ignore reading file error
+    }
+
+    protected void restoreLogItem(byte[] buf, int len) {
+        Parcel p = Parcel.obtain();
+        p.unmarshall(buf, 0, len);
+        p.setDataPosition(0);
+        VpnStatus.LogItem li = VpnStatus.LogItem.CREATOR.createFromParcel(p);
+        if (li.verify()) {
+            VpnStatus.newLogItem(li, true);
+        } else {
+            VpnStatus.logError(String.format(Locale.getDefault(),
+                    "Could not read log item from file: %d: %s",
+                     len, bytesToHex(buf, Math.max(len, 80))));
         }
+        p.recycle();
     }
 
     final protected static char[] hexArray = "0123456789ABCDEF".toCharArray();
+
     public static String bytesToHex(byte[] bytes, int len) {
         len = Math.min(bytes.length, len);
         char[] hexChars = new char[len * 2];
-        for ( int j = 0; j < len; j++ ) {
+        for (int j = 0; j < len; j++) {
             int v = bytes[j] & 0xFF;
             hexChars[j * 2] = hexArray[v >>> 4];
             hexChars[j * 2 + 1] = hexArray[v & 0x0F];
diff --git a/main/src/main/java/de/blinkt/openvpn/core/VpnStatus.java b/main/src/main/java/de/blinkt/openvpn/core/VpnStatus.java
index 29bef6de..92ab5900 100644
--- a/main/src/main/java/de/blinkt/openvpn/core/VpnStatus.java
+++ b/main/src/main/java/de/blinkt/openvpn/core/VpnStatus.java
@@ -56,6 +56,7 @@ public class VpnStatus {
     private static int mLastStateresid = R.string.state_noprocess;
 
     private static long mlastByteCount[] = {0, 0, 0, 0};
+    private static HandlerThread mHandlerThread;
 
     public static void logException(LogLevel ll, String context, Exception e) {
         StringWriter sw = new StringWriter();
@@ -122,6 +123,11 @@ public class VpnStatus {
     }
 
     public static void initLogCache(File cacheDir) {
+        mHandlerThread = new HandlerThread("LogFileWriter", Thread.MIN_PRIORITY);
+        mHandlerThread.start();
+        mLogFileHandler = new LogFileHandler(mHandlerThread.getLooper());
+
+
         Message m = mLogFileHandler.obtainMessage(LogFileHandler.LOG_INIT, cacheDir);
         mLogFileHandler.sendMessage(m);
 
@@ -186,7 +192,7 @@ public class VpnStatus {
 
     private static ConnectionStatus mLastLevel = ConnectionStatus.LEVEL_NOTCONNECTED;
 
-    private static final LogFileHandler mLogFileHandler;
+    private static LogFileHandler mLogFileHandler;
 
     static {
         logbuffer = new LinkedList<>();
@@ -194,9 +200,6 @@ public class VpnStatus {
         stateListener = new Vector<>();
         byteCountListener = new Vector<>();
 
-        HandlerThread mHandlerThread = new HandlerThread("LogFileWriter", Thread.MIN_PRIORITY);
-        mHandlerThread.start();
-        mLogFileHandler = new LogFileHandler(mHandlerThread.getLooper());
 
         logInformation();
 
@@ -293,7 +296,7 @@ public class VpnStatus {
                     } else {
                         String str = String.format(Locale.ENGLISH, "Log (no context) resid %d", mRessourceId);
                         if (mArgs != null)
-                            str += TextUtils.join("|", mArgs);
+                            str += join("|", mArgs);
 
                         return str;
                     }
@@ -312,6 +315,24 @@ public class VpnStatus {
 
         }
 
+
+        // TextUtils.join will cause not macked exeception in tests ....
+        public static String join(CharSequence delimiter, Object[] tokens) {
+            StringBuilder sb = new StringBuilder();
+            boolean firstTime = true;
+            for (Object token: tokens) {
+                if (firstTime) {
+                    firstTime = false;
+                } else {
+                    sb.append(delimiter);
+                }
+                sb.append(token);
+            }
+            return sb.toString();
+        }
+
+
+
         public LogLevel getLogLevel() {
             return mLevel;
         }
@@ -404,12 +425,20 @@ public class VpnStatus {
     public synchronized static void clearLog() {
         logbuffer.clear();
         logInformation();
-        mLogFileHandler.sendEmptyMessage(LogFileHandler.TRIM_LOG_FILE);
+        if (mLogFileHandler!=null)
+            mLogFileHandler.sendEmptyMessage(LogFileHandler.TRIM_LOG_FILE);
     }
 
     private static void logInformation() {
+        String nativeAPI;
+        try {
+            nativeAPI = NativeUtils.getNativeAPI();
+        } catch (UnsatisfiedLinkError ignore) {
+            nativeAPI = "error";
+        }
+
         logInfo(R.string.mobile_info, Build.MODEL, Build.BOARD, Build.BRAND, Build.VERSION.SDK_INT,
-                NativeUtils.getNativeAPI(), Build.VERSION.RELEASE, Build.ID, Build.FINGERPRINT, "", "");
+                nativeAPI , Build.VERSION.RELEASE, Build.ID, Build.FINGERPRINT, "", "");
     }
 
     public synchronized static void addLogListener(LogListener ll) {
@@ -578,18 +607,21 @@ public class VpnStatus {
             logbuffer.addFirst(logItem);
         } else {
             logbuffer.addLast(logItem);
-            Message m = mLogFileHandler.obtainMessage(LogFileHandler.LOG_MESSAGE, logItem);
-            mLogFileHandler.sendMessage(m);
+            if (mLogFileHandler!=null) {
+                Message m = mLogFileHandler.obtainMessage(LogFileHandler.LOG_MESSAGE, logItem);
+                mLogFileHandler.sendMessage(m);
+            }
         }
 
         if (logbuffer.size() > MAXLOGENTRIES + MAXLOGENTRIES / 2) {
             while (logbuffer.size() > MAXLOGENTRIES)
                 logbuffer.removeFirst();
-            mLogFileHandler.sendMessage(mLogFileHandler.obtainMessage(LogFileHandler.TRIM_LOG_FILE));
+            if (mLogFileHandler!=null)
+                mLogFileHandler.sendMessage(mLogFileHandler.obtainMessage(LogFileHandler.TRIM_LOG_FILE));
         }
 
-        if (BuildConfig.DEBUG && !cachedLine)
-            Log.d("OpenVPN", logItem.getString(null));
+        //if (BuildConfig.DEBUG && !cachedLine && !BuildConfig.FLAVOR.equals("test"))
+        //    Log.d("OpenVPN", logItem.getString(null));
 
 
         for (LogListener ll : logListener) {
diff --git a/main/src/main/java/de/blinkt/openvpn/fragments/LogFragment.java b/main/src/main/java/de/blinkt/openvpn/fragments/LogFragment.java
index 3c68fd87..a620beb4 100644
--- a/main/src/main/java/de/blinkt/openvpn/fragments/LogFragment.java
+++ b/main/src/main/java/de/blinkt/openvpn/fragments/LogFragment.java
@@ -629,7 +629,14 @@ public class LogFragment extends ListFragment implements StateListener, SeekBar.
     }
 
     @Override
-    public void onAttach(Activity activity) {
+    public void onViewCreated(View view, Bundle savedInstanceState) {
+        super.onViewCreated(view, savedInstanceState);
+        // Scroll to the end of the list end
+        //getListView().setSelection(getListView().getAdapter().getCount()-1);
+    }
+
+    @Override
+    public void onAttach(Context activity) {
         super.onAttach(activity);
         if (getResources().getBoolean(R.bool.logSildersAlwaysVisible)) {
             mShowOptionsLayout = true;
diff --git a/main/src/main/res/values/strings.xml b/main/src/main/res/values/strings.xml
index 16262cde..ad905367 100755
--- a/main/src/main/res/values/strings.xml
+++ b/main/src/main/res/values/strings.xml
@@ -405,6 +405,6 @@
     <string name="missing_ca_certificate">Missing CA certificate</string>
     <string name="crl_title">Certifcate Revoke List (optional)</string>
     <string name="reread_log">Reread (%d) log items from log cache file</string>
-    <string name="samsung_broken">Even though Samsung phones are among the most selling Android phones, Samsung\'s firmware are also among the most buggy Android firmwares. The bugs are not limited to the VPN operation on these devices but many of them can be workarounded. In the following some of these bugs are described\n\nDNS does not work unless the DNS server in the VPN range.\nOn many Samsung 5.x devices the allowed/disallowed apps feature does not work.\nOn Samsung 6.x VPN is reported not to work unless the VPN app is excempted from Powersave features.</string>
+    <string name="samsung_broken">Even though Samsung phones are among the most selling Android phones, Samsung\'s firmware are also among the most buggy Android firmwares. The bugs are not limited to the VPN operation on these devices but many of them can be workarounded. In the following some of these bugs are described.\n\nDNS does not work unless the DNS server in the VPN range.\n\nOn many Samsung 5.x devices the allowed/disallowed apps feature does not work.\nOn Samsung 6.x VPN is reported not to work unless the VPN app is exempted from Powersave features.</string>
     <string name="samsung_broken_title">Samsung phones</string>
 </resources>
diff --git a/main/src/test/java/de/blinkt/openvpn/core/TestLogFileHandler.java b/main/src/test/java/de/blinkt/openvpn/core/TestLogFileHandler.java
new file mode 100644
index 00000000..f86dbcdc
--- /dev/null
+++ b/main/src/test/java/de/blinkt/openvpn/core/TestLogFileHandler.java
@@ -0,0 +1,81 @@
+package de.blinkt.openvpn.core;
+
+import android.annotation.SuppressLint;
+import android.os.Looper;
+import android.os.Message;
+import android.util.Log;
+
+import junit.framework.Assert;
+
+import org.junit.Before;
+import org.junit.Test;
+
+import java.io.ByteArrayInputStream;
+import java.io.ByteArrayOutputStream;
+import java.io.IOException;
+import java.io.InputStream;
+import java.io.OutputStream;
+import java.io.StringBufferInputStream;
+import java.util.Arrays;
+
+public class TestLogFileHandler {
+
+    byte[] testUnescaped = new byte[] {0x00, 0x55, -27, 0x00, 0x56, 0x10, -128, 0x55, 0x54};
+    byte[] expectedEscaped = new byte[] {0x55, 0x00, 0x00, 0x00, 0x09, 0x00, 0x56, 0x00, -27, 0x00, 0x56, 0x01, 0x10, -128, 0x56, 0x00, 0x54};
+    private TestingLogFileHandler lfh;
+
+
+    @Before
+    public void setup()
+    {
+        lfh = new TestingLogFileHandler();
+    }
+
+    @Test
+    public void testWriteByteArray() throws IOException {
+
+        ByteArrayOutputStream byteArrayOutputStream = new ByteArrayOutputStream();
+
+        lfh.setLogFile(byteArrayOutputStream);
+
+        lfh.writeEscapedBytes(testUnescaped);
+
+        byte[] result = byteArrayOutputStream.toByteArray();
+        Assert.assertTrue(Arrays.equals(expectedEscaped, result));
+    }
+
+    @Test
+    public void readByteArray() throws IOException {
+
+        ByteArrayInputStream in = new ByteArrayInputStream(expectedEscaped);
+
+        lfh.readCacheContents(in);
+
+        Assert.assertTrue(Arrays.equals(testUnescaped, lfh.mRestoredByteArray));
+
+    }
+
+    @SuppressLint("HandlerLeak")
+    static class TestingLogFileHandler extends LogFileHandler {
+
+        public byte[] mRestoredByteArray;
+
+        public TestingLogFileHandler() {
+            super(null);
+        }
+
+        public void setLogFile(OutputStream out) {
+            mLogFile = out;
+        }
+
+        @Override
+        public void readCacheContents(InputStream in) throws IOException {
+            super.readCacheContents(in);
+        }
+
+        @Override
+        protected void restoreLogItem(byte[] buf, int len) {
+            mRestoredByteArray = Arrays.copyOf(buf, len);
+        }
+    }
+}
\ No newline at end of file