Merge "WifiNative: add wallclock timestamps for packet fate" into nyc-dev

3 files changed, 124 insertions, 75 deletions

diff --git a/service/java/com/android/server/wifi/WifiNative.java b/service/java/com/android/server/wifi/WifiNative.java
index 0e0f08f7a..9e1c49204 100644
--- a/service/java/com/android/server/wifi/WifiNative.java
+++ b/service/java/com/android/server/wifi/WifiNative.java
@@ -68,14 +68,17 @@ import java.nio.CharBuffer;
 import java.nio.charset.CharacterCodingException;
 import java.nio.charset.CharsetDecoder;
 import java.nio.charset.StandardCharsets;
+import java.text.SimpleDateFormat;
 import java.util.ArrayList;
 import java.util.BitSet;
+import java.util.Date;
 import java.util.HashMap;
 import java.util.Iterator;
 import java.util.List;
 import java.util.Locale;
 import java.util.Map;
 import java.util.Set;
+import java.util.TimeZone;
 
 
 /**
@@ -2627,14 +2630,23 @@ public class WifiNative {
 
     @Immutable
     abstract static class FateReport {
+        final static int USEC_PER_MSEC = 1000;
+        // The driver timestamp is a 32-bit counter, in microseconds. This field holds the
+        // maximal value of a driver timestamp in milliseconds.
+        final static int MAX_DRIVER_TIMESTAMP_MSEC = (int) (0xffffffffL / 1000);
+        final static SimpleDateFormat dateFormatter = new SimpleDateFormat("HH:mm:ss.SSS");
+
         final byte mFate;
         final long mDriverTimestampUSec;
         final byte mFrameType;
         final byte[] mFrameBytes;
+        final long mEstimatedWallclockMSec;
 
         FateReport(byte fate, long driverTimestampUSec, byte frameType, byte[] frameBytes) {
             mFate = fate;
             mDriverTimestampUSec = driverTimestampUSec;
+            mEstimatedWallclockMSec =
+                    convertDriverTimestampUSecToWallclockMSec(mDriverTimestampUSec);
             mFrameType = frameType;
             mFrameBytes = frameBytes;
         }
@@ -2643,9 +2655,12 @@ public class WifiNative {
             StringWriter sw = new StringWriter();
             PrintWriter pw = new PrintWriter(sw);
             FrameParser parser = new FrameParser(mFrameType, mFrameBytes);
-            pw.format("%-15s  %-9s  %-32s  %-12s  %-23s  %s\n",
-                    mDriverTimestampUSec, directionToString(), fateToString(),
-                    parser.mMostSpecificProtocolString, parser.mTypeString, parser.mResultString);
+            dateFormatter.setTimeZone(TimeZone.getDefault());
+            pw.format("%-15s  %12s  %-9s  %-32s  %-12s  %-23s  %s\n",
+                    mDriverTimestampUSec,
+                    dateFormatter.format(new Date(mEstimatedWallclockMSec)),
+                    directionToString(), fateToString(), parser.mMostSpecificProtocolString,
+                    parser.mTypeString, parser.mResultString);
             return sw.toString();
         }
 
@@ -2670,10 +2685,10 @@ public class WifiNative {
         public static String getTableHeader() {
             StringWriter sw = new StringWriter();
             PrintWriter pw = new PrintWriter(sw);
-            pw.format("\n%-15s  %-9s  %-32s  %-12s  %-23s  %s\n",
-                    "Timestamp", "Direction", "Fate", "Protocol", "Type", "Result");
-            pw.format("%-15s  %-9s  %-32s  %-12s  %-23s  %s\n",
-                    "---------", "---------", "----", "--------", "----", "------");
+            pw.format("\n%-15s  %-12s  %-9s  %-32s  %-12s  %-23s  %s\n",
+                    "Time usec", "Walltime", "Direction", "Fate", "Protocol", "Type", "Result");
+            pw.format("%-15s  %-12s  %-9s  %-32s  %-12s  %-23s  %s\n",
+                    "---------", "--------", "---------", "----", "--------", "----", "------");
             return sw.toString();
         }
 
@@ -2693,6 +2708,34 @@ public class WifiNative {
                     return Byte.toString(frameType);
             }
         }
+
+        /**
+         * Converts a driver timestamp to a wallclock time, based on the current
+         * BOOTTIME to wallclock mapping. The driver timestamp is a 32-bit counter of
+         * microseconds, with the same base as BOOTTIME.
+         */
+        private static long convertDriverTimestampUSecToWallclockMSec(long driverTimestampUSec) {
+            final long wallclockMillisNow = System.currentTimeMillis();
+            final long boottimeMillisNow = SystemClock.elapsedRealtime();
+            final long driverTimestampMillis = driverTimestampUSec / USEC_PER_MSEC;
+
+            long boottimeTimestampMillis = boottimeMillisNow % MAX_DRIVER_TIMESTAMP_MSEC;
+            if (boottimeTimestampMillis < driverTimestampMillis) {
+                // The 32-bit microsecond count has wrapped between the time that the driver
+                // recorded the packet, and the call to this function. Adjust the BOOTTIME
+                // timestamp, to compensate.
+                //
+                // Note that overflow is not a concern here, since the result is less than
+                // 2 * MAX_DRIVER_TIMESTAMP_MSEC. (Given the modulus operation above,
+                // boottimeTimestampMillis must be less than MAX_DRIVER_TIMESTAMP_MSEC.) And, since
+                // MAX_DRIVER_TIMESTAMP_MSEC is an int, 2 * MAX_DRIVER_TIMESTAMP_MSEC must fit
+                // within a long.
+                boottimeTimestampMillis += MAX_DRIVER_TIMESTAMP_MSEC;
+            }
+
+            final long millisSincePacketTimestamp = boottimeTimestampMillis - driverTimestampMillis;
+            return wallclockMillisNow - millisSincePacketTimestamp;
+        }
     }
 
     /**
diff --git a/tests/wifitests/src/com/android/server/wifi/WifiLoggerTest.java b/tests/wifitests/src/com/android/server/wifi/WifiLoggerTest.java
index 76851882e..e07c4b80b 100644
--- a/tests/wifitests/src/com/android/server/wifi/WifiLoggerTest.java
+++ b/tests/wifitests/src/com/android/server/wifi/WifiLoggerTest.java
@@ -40,6 +40,7 @@ import org.mockito.MockitoAnnotations;
 import java.io.FileDescriptor;
 import java.io.PrintWriter;
 import java.io.StringWriter;
+import java.util.regex.Pattern;
 
 /**
  * Unit tests for {@link com.android.server.wifi.WifiLogger}.
@@ -399,10 +400,10 @@ public class WifiLoggerTest {
         final boolean verbosityToggle = false;
         String dumpString = getDumpString(verbosityToggle);
         assertTrue(dumpString.contains(WifiNative.FateReport.getTableHeader()));
-        assertTrue(dumpString.contains("0                TX"));
-        assertTrue(dumpString.contains("1                RX"));
-        assertTrue(dumpString.contains("2                TX"));
-        assertTrue(dumpString.contains("3                RX"));
+        assertTrue(Pattern.compile("0 .* TX ").matcher(dumpString).find());
+        assertTrue(Pattern.compile("1 .* RX ").matcher(dumpString).find());
+        assertTrue(Pattern.compile("2 .* TX ").matcher(dumpString).find());
+        assertTrue(Pattern.compile("3 .* RX ").matcher(dumpString).find());
         assertFalse(dumpString.contains("VERBOSE PACKET FATE DUMP"));
         assertFalse(dumpString.contains("Frame bytes"));
     }
@@ -416,34 +417,29 @@ public class WifiLoggerTest {
         final boolean verbosityToggle = true;
         String dumpString = getDumpString(verbosityToggle);
         assertTrue(dumpString.contains(WifiNative.FateReport.getTableHeader()));
-        assertTrue(dumpString.contains("0                TX"));
-        assertTrue(dumpString.contains("1                RX"));
-        assertTrue(dumpString.contains("2                TX"));
-        assertTrue(dumpString.contains("3                RX"));
+        assertTrue(Pattern.compile("0 .* TX ").matcher(dumpString).find());
+        assertTrue(Pattern.compile("1 .* RX ").matcher(dumpString).find());
+        assertTrue(Pattern.compile("2 .* TX ").matcher(dumpString).find());
+        assertTrue(Pattern.compile("3 .* RX ").matcher(dumpString).find());
         assertTrue(dumpString.contains("VERBOSE PACKET FATE DUMP"));
         assertTrue(dumpString.contains("Frame bytes"));
     }
 
     /**
-     * Verifies that dump() outputs frames in timestamp order, even if the HAL provided the
-     * data out-of-order.
+     * Verifies that dump() outputs frames in timestamp order, even though the HAL provided the
+     * data out-of-order (order is specified in getDumpString()).
      */
     @Test
     public void dumpIsSortedByTimestamp() {
         final boolean verbosityToggle = true;
         String dumpString = getDumpString(verbosityToggle);
         assertTrue(dumpString.contains(WifiNative.FateReport.getTableHeader()));
-        int expected_index_of_frame_0 = dumpString.indexOf("0                TX");
-        int expected_index_of_frame_1 = dumpString.indexOf("1                RX");
-        int expected_index_of_frame_2 = dumpString.indexOf("2                TX");
-        int expected_index_of_frame_3 = dumpString.indexOf("3                RX");
-        assertFalse(-1 == expected_index_of_frame_0);
-        assertFalse(-1 == expected_index_of_frame_1);
-        assertFalse(-1 == expected_index_of_frame_2);
-        assertFalse(-1 == expected_index_of_frame_3);
-        assertTrue(expected_index_of_frame_0 < expected_index_of_frame_1);
-        assertTrue(expected_index_of_frame_1 < expected_index_of_frame_2);
-        assertTrue(expected_index_of_frame_2 < expected_index_of_frame_3);
+        assertTrue(Pattern.compile(
+                "0 .* TX .*\n" +
+                "1 .* RX .*\n" +
+                "2 .* TX .*\n" +
+                "3 .* RX "
+        ).matcher(dumpString).find());
 
         int expected_index_of_verbose_frame_0 = dumpString.indexOf(
                 "Frame direction: TX\nFrame timestamp: 0\n");
diff --git a/tests/wifitests/src/com/android/server/wifi/WifiNativeTest.java b/tests/wifitests/src/com/android/server/wifi/WifiNativeTest.java
index cb938ba0e..7013fe38c 100644
--- a/tests/wifitests/src/com/android/server/wifi/WifiNativeTest.java
+++ b/tests/wifitests/src/com/android/server/wifi/WifiNativeTest.java
@@ -34,6 +34,7 @@ import org.junit.Test;
 import java.lang.reflect.Constructor;
 import java.util.HashMap;
 import java.util.Map;
+import java.util.regex.Pattern;
 
 /**
  * Unit tests for {@link com.android.server.wifi.WifiNative}.
@@ -205,13 +206,12 @@ public class WifiNativeTest {
      */
     @Test
     public void testFateReportTableHeader() {
-        String header = WifiNative.FateReport.getTableHeader();
-        assertTrue(header.contains(
-                "Timestamp        Direction  Fate                              "
-                        + "Protocol      Type                     Result\n"));
-        assertTrue(header.contains(
-                "---------        ---------  ----                              "
-                        + "--------      ----                     ------\n"));
+        final String header = WifiNative.FateReport.getTableHeader();
+        assertEquals(
+                "\nTime usec        Walltime      Direction  Fate                              "
+                + "Protocol      Type                     Result\n"
+                + "---------        --------      ---------  ----                              "
+                + "--------      ----                     ------\n", header);
     }
 
     /**
@@ -220,14 +220,16 @@ public class WifiNativeTest {
     @Test
     public void testTxFateReportToTableRowString() {
         WifiNative.TxFateReport fateReport = TX_FATE_REPORT;
-        assertEquals(
-                FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
-                        + "TX "  // direction
-                        + "sent "  // fate
-                        + "Ethernet "  // type
-                        + "N/A "  // protocol
-                        + "N/A",  // result
-                fateReport.toTableRowString().replaceAll("\\s+", " ").trim()
+        assertTrue(
+                fateReport.toTableRowString().replaceAll("\\s+", " ").trim().matches(
+                    FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
+                            + "\\d{2}:\\d{2}:\\d{2}\\.\\d{3} "  // walltime
+                            + "TX "  // direction
+                            + "sent "  // fate
+                            + "Ethernet "  // type
+                            + "N/A "  // protocol
+                            + "N/A"  // result
+                )
         );
 
         for (FrameTypeMapping frameTypeMapping : FRAME_TYPE_MAPPINGS) {
@@ -237,14 +239,16 @@ public class WifiNativeTest {
                     frameTypeMapping.mTypeNumber,
                     FATE_REPORT_FRAME_BYTES
             );
-            assertEquals(
-                    FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
-                            + "TX "  // direction
-                            + "sent "  // fate
-                            + frameTypeMapping.mExpectedProtocolText + " "  // type
-                            + "N/A "  // protocol
-                            + "N/A",  // result
-                    fateReport.toTableRowString().replaceAll("\\s+", " ").trim()
+            assertTrue(
+                    fateReport.toTableRowString().replaceAll("\\s+", " ").trim().matches(
+                            FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
+                                    + "\\d{2}:\\d{2}:\\d{2}\\.\\d{3} "  // walltime
+                                    + "TX "  // direction
+                                    + "sent "  // fate
+                                    + frameTypeMapping.mExpectedProtocolText + " "  // type
+                                    + "N/A "  // protocol
+                                    + "N/A"  // result
+                    )
             );
         }
 
@@ -255,14 +259,16 @@ public class WifiNativeTest {
                     WifiLoggerHal.FRAME_TYPE_80211_MGMT,
                     FATE_REPORT_FRAME_BYTES
             );
-            assertEquals(
-                    FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
-                            + "TX "  // direction
-                            + fateMapping.mExpectedText + " "  // fate
-                            + "802.11 Mgmt "  // type
-                            + "N/A "  // protocol
-                            + "N/A",  // result
-                    fateReport.toTableRowString().replaceAll("\\s+", " ").trim()
+            assertTrue(
+                    fateReport.toTableRowString().replaceAll("\\s+", " ").trim().matches(
+                            FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
+                                    + "\\d{2}:\\d{2}:\\d{2}\\.\\d{3} "  // walltime
+                                    + "TX "  // direction
+                                    + Pattern.quote(fateMapping.mExpectedText) + " "  // fate
+                                    + "802.11 Mgmt "  // type
+                                    + "N/A "  // protocol
+                                    + "N/A"  // result
+                    )
             );
         }
     }
@@ -318,14 +324,16 @@ public class WifiNativeTest {
     @Test
     public void testRxFateReportToTableRowString() {
         WifiNative.RxFateReport fateReport = RX_FATE_REPORT;
-        assertEquals(
-                FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
-                        + "RX "  // direction
-                        + "firmware dropped (invalid frame) "  // fate
-                        + "Ethernet "  // type
-                        + "N/A "  // protocol
-                        + "N/A", // result
-                fateReport.toTableRowString().replaceAll("\\s+", " ").trim()
+        assertTrue(
+                fateReport.toTableRowString().replaceAll("\\s+", " ").trim().matches(
+                        FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
+                                + "\\d{2}:\\d{2}:\\d{2}\\.\\d{3} "  // walltime
+                                + "RX "  // direction
+                                + Pattern.quote("firmware dropped (invalid frame) ")  // fate
+                                + "Ethernet "  // type
+                                + "N/A "  // protocol
+                                + "N/A"  // result
+                )
         );
 
         // FrameTypeMappings omitted, as they're the same as for TX.
@@ -337,14 +345,16 @@ public class WifiNativeTest {
                     WifiLoggerHal.FRAME_TYPE_80211_MGMT,
                     FATE_REPORT_FRAME_BYTES
             );
-            assertEquals(
-                    FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
-                            + "RX "  // direction
-                            + fateMapping.mExpectedText + " " // fate
-                            + "802.11 Mgmt "  // type
-                            + "N/A " // protocol
-                            + "N/A",  // result,
-                    fateReport.toTableRowString().replaceAll("\\s+", " ").trim()
+            assertTrue(
+                    fateReport.toTableRowString().replaceAll("\\s+", " ").trim().matches(
+                            FATE_REPORT_DRIVER_TIMESTAMP_USEC + " "  // timestamp
+                                    + "\\d{2}:\\d{2}:\\d{2}\\.\\d{3} "  // walltime
+                                    + "RX "  // direction
+                                    + Pattern.quote(fateMapping.mExpectedText) + " " // fate
+                                    + "802.11 Mgmt "  // type
+                                    + "N/A " // protocol
+                                    + "N/A"  // result
+                    )
             );
         }
     }