Repository: apache/fluo
Issue: Collision trace logging does not hex escape data

While trying to debug some unexpected collisions in webindex, I noticed that logging of collisions does not hex escape binary data like other transaction trace logging does.
```
17:48:45.466 [Fluo-0002-007-async-commits] TRACE fluo.tx.collisions - txid: 14580734 trigger: p:1prp:net.analystratings>.www>o>/stocks/NYSE/LCI/ page new  14536153
17:48:45.466 [Fluo-0002-007-async-commits] TRACE fluo.tx.collisions - txid: 14580734 class: webindex.data.fluo.PageObserver
17:48:45.466 [Fluo-0002-007-async-commits] TRACE fluo.tx.collisions - txid: 14580734 collisions: {um:u:679:^C^Acom.reuters>.www>o>/finance/stocks/companyProfile?symbol=LC�^@^@^@^@^@�{�=[u v ], um:u:366:^C^A�^Agov.sec>.www>o>/Archives/edgar/data/57725/000120919115012121/xslF345X03/doc4.xml^@^@^@^@^@�{�=[u v ]}
```

Changed files:
modules/integration/src/test/java/org/apache/fluo/integration/log/LogIT.java, modules/core/src/main/java/org/apache/fluo/core/log/TracingTransaction.java, modules/integration/src/test/java/org/apache/fluo/integration/TestUtil.java

diff --git a/modules/core/src/main/java/org/apache/fluo/core/log/TracingTransaction.java b/modules/core/src/main/java/org/apache/fluo/core/log/TracingTransaction.java
index 62f61a18..0753cd41 100644
--- a/modules/core/src/main/java/org/apache/fluo/core/log/TracingTransaction.java
+++ b/modules/core/src/main/java/org/apache/fluo/core/log/TracingTransaction.java
@@ -37,6 +37,8 @@ import org.apache.fluo.core.util.Hex;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
+import static org.apache.fluo.core.util.Hex.encNonAscii;
+
 public class TracingTransaction extends AbstractTransactionBase implements AsyncTransaction,
     Snapshot {
 
@@ -52,12 +54,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
   private Class<?> clazz;
   private boolean committed = false;
 
-  private static String enc(Bytes b) {
-    return Hex.encNonAscii(b);
-  }
-
-  private static String enc(Column c) {
-    return Hex.encNonAscii(c);
+  private static String toStringEncNonAscii(Column c) {
+    return encNonAscii(c);
   }
 
   public TracingTransaction(AsyncTransaction tx) {
@@ -68,32 +66,37 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
     this(tx, null, clazz, txExecId);
   }
 
-  private String encB(Collection<Bytes> columns) {
+  private String toStringEncNonAsciiCB(Collection<Bytes> columns) {
     return Iterators.toString(Iterators.transform(columns.iterator(), Hex::encNonAscii));
   }
 
-  private String encRC(Collection<RowColumn> ret) {
+  private String toStringEncNonAsciiCRC(Collection<RowColumn> ret) {
     return Iterators.toString(Iterators.transform(ret.iterator(), Hex::encNonAscii));
   }
 
-  private String encRC(Map<Bytes, Map<Column, Bytes>> ret) {
-    return Iterators.toString(Iterators.transform(ret.entrySet().iterator(), e -> enc(e.getKey())
-        + "=" + encC(e.getValue())));
+  private String toStringEncNonAsciiMBMCB(Map<Bytes, Map<Column, Bytes>> ret) {
+    return Iterators.toString(Iterators.transform(ret.entrySet().iterator(),
+        e -> encNonAscii(e.getKey()) + "=" + toStringEncNonAsciiMCB(e.getValue())));
   }
 
-  private String encRCM(Map<RowColumn, Bytes> ret) {
+  private String toStringEncNonAsciiMRCB(Map<RowColumn, Bytes> ret) {
     return Iterators.toString(Iterators.transform(ret.entrySet().iterator(),
-        e -> Hex.encNonAscii(e.getKey()) + "=" + enc(e.getValue())));
+        e -> encNonAscii(e.getKey()) + "=" + encNonAscii(e.getValue())));
   }
 
 
-  private String encC(Collection<Column> columns) {
+  private String toStringEncNonAsciiCC(Collection<Column> columns) {
     return Iterators.toString(Iterators.transform(columns.iterator(), Hex::encNonAscii));
   }
 
-  private String encC(Map<Column, Bytes> ret) {
-    return Iterators.toString(Iterators.transform(ret.entrySet().iterator(), e -> enc(e.getKey())
-        + "=" + enc(e.getValue())));
+  private String toStringEncNonAsciiMCB(Map<Column, Bytes> ret) {
+    return Iterators.toString(Iterators.transform(ret.entrySet().iterator(),
+        e -> toStringEncNonAscii(e.getKey()) + "=" + encNonAscii(e.getValue())));
+  }
+
+  private String toStringEncNonAsciiMBSC(Map<Bytes, Set<Column>> m) {
+    return Iterators.toString(Iterators.transform(m.entrySet().iterator(),
+        e -> encNonAscii(e.getKey()) + "=" + toStringEncNonAsciiCC(e.getValue())));
   }
 
   public TracingTransaction(AsyncTransaction tx, Notification notification, Class<?> clazz,
@@ -108,8 +111,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
       log.trace("txid: {} begin() thread: {}", txid, Thread.currentThread().getId());
 
       if (notification != null) {
-        log.trace("txid: {} trigger: {} {} {}", txid, enc(notification.getRow()),
-            enc(notification.getColumn()), notification.getTimestamp());
+        log.trace("txid: {} trigger: {} {} {}", txid, encNonAscii(notification.getRow()),
+            toStringEncNonAscii(notification.getColumn()), notification.getTimestamp());
       }
 
       if (clazz != null) {
@@ -127,7 +130,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
   public Bytes get(Bytes row, Column column) {
     Bytes ret = tx.get(row, column);
     if (log.isTraceEnabled()) {
-      log.trace("txid: {} get({}, {}) -> {}", txid, enc(row), enc(column), enc(ret));
+      log.trace("txid: {} get({}, {}) -> {}", txid, encNonAscii(row), toStringEncNonAscii(column),
+          encNonAscii(ret));
     }
     return ret;
   }
@@ -136,7 +140,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
   public Map<Column, Bytes> get(Bytes row, Set<Column> columns) {
     Map<Column, Bytes> ret = tx.get(row, columns);
     if (log.isTraceEnabled()) {
-      log.trace("txid: {} get({}, {}) -> {}", txid, enc(row), encC(columns), encC(ret));
+      log.trace("txid: {} get({}, {}) -> {}", txid, encNonAscii(row),
+          toStringEncNonAsciiCC(columns), toStringEncNonAsciiMCB(ret));
     }
     return ret;
   }
@@ -145,7 +150,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
   public Map<Bytes, Map<Column, Bytes>> get(Collection<Bytes> rows, Set<Column> columns) {
     Map<Bytes, Map<Column, Bytes>> ret = tx.get(rows, columns);
     if (log.isTraceEnabled()) {
-      log.trace("txid: {} get({}, {}) -> {}", txid, encB(rows), encC(columns), encRC(ret));
+      log.trace("txid: {} get({}, {}) -> {}", txid, toStringEncNonAsciiCB(rows),
+          toStringEncNonAsciiCC(columns), toStringEncNonAsciiMBMCB(ret));
     }
     return ret;
   }
@@ -154,7 +160,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
   public Map<RowColumn, Bytes> get(Collection<RowColumn> rowColumns) {
     Map<RowColumn, Bytes> ret = tx.get(rowColumns);
     if (log.isTraceEnabled()) {
-      log.trace("txid: {} get({}) -> {}", txid, encRC(rowColumns), encRCM(ret));
+      log.trace("txid: {} get({}) -> {}", txid, toStringEncNonAsciiCRC(rowColumns),
+          toStringEncNonAsciiMRCB(ret));
     }
     return ret;
   }
@@ -167,7 +174,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
   @Override
   public void setWeakNotification(Bytes row, Column col) {
     if (log.isTraceEnabled()) {
-      log.trace("txid: {} setWeakNotification({}, {})", txid, enc(row), enc(col));
+      log.trace("txid: {} setWeakNotification({}, {})", txid, encNonAscii(row),
+          toStringEncNonAscii(col));
     }
     tx.setWeakNotification(row, col);
   }
@@ -175,7 +183,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
   @Override
   public void set(Bytes row, Column col, Bytes value) throws AlreadySetException {
     if (log.isTraceEnabled()) {
-      log.trace("txid: {} set({}, {}, {})", txid, enc(row), enc(col), enc(value));
+      log.trace("txid: {} set({}, {}, {})", txid, encNonAscii(row), toStringEncNonAscii(col),
+          encNonAscii(value));
     }
     tx.set(row, col, value);
   }
@@ -183,7 +192,7 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
   @Override
   public void delete(Bytes row, Column col) throws AlreadySetException {
     if (log.isTraceEnabled()) {
-      log.trace("txid: {} delete({}, {})", txid, enc(row), enc(col));
+      log.trace("txid: {} delete({}, {})", txid, encNonAscii(row), toStringEncNonAscii(col));
     }
     tx.delete(row, col);
   }
@@ -212,7 +221,8 @@ public class TracingTransaction extends AbstractTransactionBase implements Async
       collisionLog.trace("txid: {} class: {}", txid, clazz.getName());
     }
 
-    collisionLog.trace("txid: {} collisions: {}", txid, tx.getStats().getRejected());
+    collisionLog.trace("txid: {} collisions: {}", txid, toStringEncNonAsciiMBSC(tx.getStats()
+        .getRejected()));
   }
 
   @Override
diff --git a/modules/integration/src/test/java/org/apache/fluo/integration/TestUtil.java b/modules/integration/src/test/java/org/apache/fluo/integration/TestUtil.java
index fe9ee27b..61ce45e1 100644
--- a/modules/integration/src/test/java/org/apache/fluo/integration/TestUtil.java
+++ b/modules/integration/src/test/java/org/apache/fluo/integration/TestUtil.java
@@ -17,18 +17,26 @@ package org.apache.fluo.integration;
 
 import org.apache.fluo.api.client.SnapshotBase;
 import org.apache.fluo.api.client.TransactionBase;
+import org.apache.fluo.api.data.Bytes;
 import org.apache.fluo.api.data.Column;
 
 public class TestUtil {
 
   private TestUtil() {}
 
+  private static final Bytes ZERO = Bytes.of("0");
+
+  public static void increment(TransactionBase tx, Bytes row, Column col, int val) {
+    int prev = 0;
+    String prevStr = tx.get(row, col, ZERO).toString();
+    prev = Integer.parseInt(prevStr);
+    tx.set(row, col, Bytes.of(prev + val + ""));
+  }
+
   public static void increment(TransactionBase tx, String row, Column col, int val) {
     int prev = 0;
-    String prevStr = tx.gets(row, col);
-    if (prevStr != null) {
-      prev = Integer.parseInt(prevStr);
-    }
+    String prevStr = tx.gets(row, col, "0");
+    prev = Integer.parseInt(prevStr);
     tx.set(row, col, prev + val + "");
   }
 
diff --git a/modules/integration/src/test/java/org/apache/fluo/integration/log/LogIT.java b/modules/integration/src/test/java/org/apache/fluo/integration/log/LogIT.java
index 7e1e2794..fe712fe1 100644
--- a/modules/integration/src/test/java/org/apache/fluo/integration/log/LogIT.java
+++ b/modules/integration/src/test/java/org/apache/fluo/integration/log/LogIT.java
@@ -56,12 +56,20 @@ public class LogIT extends ITBaseMini {
   private static final Column STAT_COUNT = new Column("stat", "count");
 
   static class SimpleLoader implements Loader {
-
     public void load(TransactionBase tx, Context context) throws Exception {
       TestUtil.increment(tx, "r1", new Column("a", "b"), 1);
     }
   }
 
+  static class SimpleBinaryLoader implements Loader {
+
+    private static final Bytes ROW = Bytes.of(new byte[] {'r', '1', 13});
+
+    public void load(TransactionBase tx, Context context) throws Exception {
+      TestUtil.increment(tx, ROW, new Column(Bytes.of("a"), Bytes.of(new byte[] {0, 9})), 1);
+    }
+  }
+
   static class TriggerLoader implements Loader {
 
     int r;
@@ -147,7 +155,7 @@ public class LogIT extends ITBaseMini {
 
       try (LoaderExecutor le = client.newLoaderExecutor()) {
         for (int i = 0; i < 20; i++) {
-          le.execute(new SimpleLoader());
+          le.execute(new SimpleBinaryLoader());
           le.execute(new TriggerLoader(i));
         }
       }
@@ -166,13 +174,13 @@ public class LogIT extends ITBaseMini {
 
     String pattern;
 
-    pattern = ".*txid: (\\\\d+) class: org.apache.fluo.integration.log.LogIT\\\\$SimpleLoader";
-    pattern += ".*txid: \\\\1 collisions: \\\\Q{r1=[a b ]}\\\\E.*";
+    pattern = ".*txid: (\\\\d+) class: org.apache.fluo.integration.log.LogIT\\\\$SimpleBinaryLoader";
+    pattern += ".*txid: \\\\1 collisions: \\\\Q[r1\\\\x0d=[a \\\\x00\\\\x09 ]]\\\\E.*";
     Assert.assertTrue(logMsgs.matches(pattern));
 
     pattern = ".*txid: (\\\\d+) trigger: \\\\d+ stat count  \\\\d+";
     pattern += ".*txid: \\\\1 class: org.apache.fluo.integration.log.LogIT\\\\$TestObserver";
-    pattern += ".*txid: \\\\1 collisions: \\\\Q{all=[stat count ]}\\\\E.*";
+    pattern += ".*txid: \\\\1 collisions: \\\\Q[all=[stat count ]]\\\\E.*";
     Assert.assertTrue(logMsgs.matches(pattern));
   }