Fixes to LLC and DAL to handle unreliable UART.

Use a 100ms timeout in uart_read() when reading LLC payload only.

Allow 200 retries on host.

Note that we use pn544 timeout retransmit instead of an explicit REJ
(do not use CRC_ERROR_REJ). The reason is that after a
dropped frame, a host timeout on read() is the only reliable way to recover
frame alignment, but if we send an immediate REJ then we are constantly reading
and can never regain frame alignment.

Also note that the pn544 timeout (200ms) is higher than the host (100ms). This
allows the host to abort a partial read and return to known state before the
pn544 re-transmits.

We have to turn off timeout for FW mode. Typical read time is ~100ms, but some
are 1 second+

Modify DAL & LLC layer to more reliably handle partial frames by searching for
a LLC length byte again, and log the various error paths.

Also introduce debugging tools:

debug.nfc.LOW_LEVEL_TRACES 2
Will enable LLC header decoding in the trace output.
Only read at NFC init time, use /data/local.prop to enable.

debug.nfc.UART_ERROR_RATE X
Will randomly inject errors at the uart transport, with a probability of X/1000
for every byte. 50% of those errors will be a dropped byte, 50% will be
corrupted. Recommend X=10. FW mode can't handle any errors. Can be enabled
after boot.

adb shell dumpsys nfc
Will now print the number of errors detected at the LLC layer.

Change-Id: I739ed193e3d4caa563a866b6a9d834c154917962

6 files changed, 178 insertions, 21 deletions

diff --git a/Linux_x86/phDal4Nfc.c b/Linux_x86/phDal4Nfc.c
index 9bedaf9..8b4f687 100644
--- a/Linux_x86/phDal4Nfc.c
+++ b/Linux_x86/phDal4Nfc.c
@@ -135,9 +135,9 @@ static void refresh_low_level_traces() {
         return;
     }
 
-    property_get("debug.nfc.LOW_LEVEL_TRACES", value, "");
+    property_get("debug.nfc.LOW_LEVEL_TRACES", value, "0");
     if (value[0]) {
-        low_level_traces = atoi(value) ? 1 : 0;
+        low_level_traces = atoi(value);
         return;
     }
 #endif
@@ -752,7 +752,8 @@ retry:
 
         if (low_level_traces)
         {
-             phOsalNfc_PrintData("RECV", (uint16_t)gReadWriteContext.nNbOfBytesRead, gReadWriteContext.pReadBuffer);
+             phOsalNfc_PrintData("RECV", (uint16_t)gReadWriteContext.nNbOfBytesRead,
+                    gReadWriteContext.pReadBuffer, low_level_traces);
         }
         DAL_DEBUG("RX Thread Read ok. nbToRead=%d\n", gReadWriteContext.nNbOfBytesToRead);
         DAL_DEBUG("RX Thread NbReallyRead=%d\n", gReadWriteContext.nNbOfBytesRead);
@@ -882,7 +883,11 @@ void phDal4Nfc_DeferredCb (void  *params)
             DAL_PRINT(" Dal deferred read called \n");
             TransactionInfo.buffer=gReadWriteContext.pReadBuffer;
             TransactionInfo.length=(uint16_t)gReadWriteContext.nNbOfBytesRead;
-            TransactionInfo.status=NFCSTATUS_SUCCESS;
+            if (gReadWriteContext.nNbOfBytesRead == gReadWriteContext.nNbOfBytesToRead) {
+                TransactionInfo.status=NFCSTATUS_SUCCESS;
+            } else {
+                TransactionInfo.status=NFCSTATUS_READ_FAILED;
+            }
             gReadWriteContext.nReadBusy = FALSE;
 
 
@@ -900,7 +905,8 @@ void phDal4Nfc_DeferredCb (void  *params)
 
             if(low_level_traces)
             {
-                phOsalNfc_PrintData("SEND", (uint16_t)gReadWriteContext.nNbOfBytesToWrite, gReadWriteContext.pWriteBuffer);
+                phOsalNfc_PrintData("SEND", (uint16_t)gReadWriteContext.nNbOfBytesToWrite,
+                        gReadWriteContext.pWriteBuffer, low_level_traces);
             }
 
             /* DAL_DEBUG("dalMsg->transactInfo.length : %d\n", dalMsg->transactInfo.length); */
diff --git a/Linux_x86/phDal4Nfc_uart.c b/Linux_x86/phDal4Nfc_uart.c
index bb891e3..7ff9c4c 100644
--- a/Linux_x86/phDal4Nfc_uart.c
+++ b/Linux_x86/phDal4Nfc_uart.c
@@ -29,6 +29,7 @@
 #define LOG_TAG "NFC_uart"
 #include <cutils/log.h>
 
+#include <stdlib.h>
 #include <unistd.h>
 #include <fcntl.h>
 #include <termios.h>
@@ -44,6 +45,7 @@
 #include <phNfcStatus.h>
 #if defined(ANDROID)
 #include <string.h>
+#include <cutils/properties.h> // for property_get
 #endif
 
 typedef struct
@@ -164,6 +166,8 @@ NFCSTATUS phDal4Nfc_uart_open_and_configure(pphDal4Nfc_sConfig_t pConfig, void *
 
    DAL_ASSERT_STR(gComPortContext.nOpened==0, "Trying to open but already done!");
 
+   srand(time(NULL));
+
    switch(pConfig->nLinkType)
    {
      case ENUM_DAL_LINK_TYPE_COM1:
@@ -260,6 +264,60 @@ NFCSTATUS phDal4Nfc_uart_open_and_configure(pphDal4Nfc_sConfig_t pConfig, void *
    return nfcret;
 }
 
+/*
+  adb shell setprop debug.nfc.UART_ERROR_RATE X
+  will corrupt and drop bytes in uart_read(), to test the error handling
+  of DAL & LLC errors.
+ */
+int property_error_rate = 0;
+static void read_property() {
+    char value[PROPERTY_VALUE_MAX];
+    property_get("debug.nfc.UART_ERROR_RATE", value, "0");
+    property_error_rate = atoi(value);
+}
+
+/* returns length of buffer after errors */
+static int apply_errors(uint8_t *buffer, int length) {
+    int i;
+    if (!property_error_rate) return length;
+
+    for (i = 0; i < length; i++) {
+        if (rand() % 1000 < property_error_rate) {
+            if (rand() % 2) {
+                // 50% chance of dropping byte
+                length--;
+                memcpy(&buffer[i], &buffer[i+1], length-i);
+                LOGW("dropped byte %d", i);
+            } else {
+                // 50% chance of corruption
+                buffer[i] = (uint8_t)rand();
+                LOGW("corrupted byte %d", i);
+            }
+        }
+    }
+    return length;
+}
+
+static struct timeval timeval_remaining(struct timespec timeout) {
+    struct timespec now;
+    struct timeval delta;
+    clock_gettime(CLOCK_MONOTONIC, &now);
+
+    delta.tv_sec = timeout.tv_sec - now.tv_sec;
+    delta.tv_usec = (timeout.tv_nsec - now.tv_nsec) / (long)1000;
+
+    if (delta.tv_usec < 0) {
+        delta.tv_usec += 1000000;
+        delta.tv_sec--;
+    }
+    if (delta.tv_sec < 0) {
+        delta.tv_sec = 0;
+        delta.tv_usec = 0;
+    }
+    return delta;
+}
+
+static int libnfc_firmware_mode = 0;
 
 /*-----------------------------------------------------------------------------
 
@@ -274,20 +332,41 @@ int phDal4Nfc_uart_read(uint8_t * pBuffer, int nNbBytesToRead)
     int ret;
     int numRead = 0;
     struct timeval tv;
+    struct timeval *ptv;
+    struct timespec timeout;
     fd_set rfds;
 
     DAL_ASSERT_STR(gComPortContext.nOpened == 1, "read called but not opened!");
     DAL_DEBUG("_uart_read() called to read %d bytes", nNbBytesToRead);
 
-    // Read with 2 second timeout, so that the read thread can be aborted
-    // when the pn544 does not respond and we need to switch to FW download
-    // mode. This should be done via a control socket instead.
+    read_property();
+
+    // Read timeout:
+    // FW mode: no timeout
+    // 1 byte read: steady-state LLC length read, allowed to block forever
+    // >1 byte read: LLC payload, 100ms timeout (before pn544 re-transmit)
+    if (nNbBytesToRead > 1 && !libnfc_firmware_mode) {
+        clock_gettime(CLOCK_MONOTONIC, &timeout);
+        timeout.tv_nsec += 100000000;
+        if (timeout.tv_nsec > 1000000000) {
+            timeout.tv_sec++;
+            timeout.tv_nsec -= 1000000000;
+        }
+        ptv = &tv;
+    } else {
+        ptv = NULL;
+    }
+
     while (numRead < nNbBytesToRead) {
        FD_ZERO(&rfds);
        FD_SET(gComPortContext.nHandle, &rfds);
-       tv.tv_sec = 2;
-       tv.tv_usec = 0;
-       ret = select(gComPortContext.nHandle + 1, &rfds, NULL, NULL, NULL);
+
+       if (ptv) {
+          tv = timeval_remaining(timeout);
+          ptv = &tv;
+       }
+
+       ret = select(gComPortContext.nHandle + 1, &rfds, NULL, NULL, ptv);
        if (ret < 0) {
            DAL_DEBUG("select() errno=%d", errno);
            if (errno == EINTR || errno == EAGAIN) {
@@ -295,11 +374,13 @@ int phDal4Nfc_uart_read(uint8_t * pBuffer, int nNbBytesToRead)
            }
            return -1;
        } else if (ret == 0) {
-           DAL_PRINT("timeout!");
+           LOGW("timeout!");
            break;  // return partial response
        }
        ret = read(gComPortContext.nHandle, pBuffer + numRead, nNbBytesToRead - numRead);
        if (ret > 0) {
+           ret = apply_errors(pBuffer + numRead, ret);
+
            DAL_DEBUG("read %d bytes", ret);
            numRead += ret;
        } else if (ret == 0) {
@@ -313,6 +394,7 @@ int phDal4Nfc_uart_read(uint8_t * pBuffer, int nNbBytesToRead)
            return -1;
        }
     }
+
     return numRead;
 }
 
@@ -388,6 +470,11 @@ int phDal4Nfc_uart_reset(long level)
         goto out;
     }
     ret = NFCSTATUS_SUCCESS;
+    if (level == 2) {
+        libnfc_firmware_mode = 1;
+    } else {
+        libnfc_firmware_mode = 0;
+    }
 
 out:
     if (fd >= 0) {
diff --git a/Linux_x86/phOsalNfc.c b/Linux_x86/phOsalNfc.c
index 0544309..cbca1ac 100644
--- a/Linux_x86/phOsalNfc.c
+++ b/Linux_x86/phOsalNfc.c
@@ -158,10 +158,11 @@ void phOsalNfc_RaiseException(phOsalNfc_ExceptionType_t eExceptionType, uint16_t
  * \param[in] pBuffer pointer to data bytes to be displayed.
  *
  */
-void phOsalNfc_PrintData(const char *pString, uint32_t length, uint8_t *pBuffer)
+void phOsalNfc_PrintData(const char *pString, uint32_t length, uint8_t *pBuffer,
+        int verbosity)
 {
     char print_buffer[length * 3 + 1];
-    int i;
+    unsigned int i;
 
     if (pString == NULL) {
         pString = "";
@@ -170,5 +171,42 @@ void phOsalNfc_PrintData(const char *pString, uint32_t length, uint8_t *pBuffer)
     for (i = 0; i < length; i++) {
         snprintf(&print_buffer[i*3], 4, " %02X", pBuffer[i]);
     }
-    LOGD("> %s:%s", pString, print_buffer);
+
+    char llc[40] = "";
+
+    if (verbosity >= 2) {
+        uint8_t llc_header = 0;
+        if (!strcmp(pString, "SEND") && length >= 2) {
+            llc_header = pBuffer[1];
+        } else if (!strcmp(pString, "RECV") && length >= 2) {
+            llc_header = pBuffer[0];
+        }
+
+        if ((llc_header & 0xC0) == 0x80) {
+            // I
+            uint8_t ns = (llc_header & 0x38) >> 3;
+            uint8_t nr = llc_header & 0x07;
+            snprintf(&llc[0], sizeof(llc), "I %d (%d)", ns, nr);
+        } else if ((llc_header & 0xE0) == 0xC0) {
+            // S
+            uint8_t t = (llc_header & 0x18) >> 3;
+            uint8_t nr = llc_header & 0x07;
+            char *type;
+            switch (t) {
+            case 0x00: type = "RR "; break;
+            case 0x01: type = "REJ"; break;
+            case 0x02: type = "RNR"; break;
+            case 0x03: type = "SREJ"; break;
+            default: type = "???"; break;
+            }
+            snprintf(&llc[0], sizeof(llc), "S %s (%d)", type, nr);
+        } else if ((llc_header & 0xE0) == 0xE0) {
+            // U
+            snprintf(&llc[0], sizeof(llc), "U");
+        } else if (length > 1) {
+            snprintf(&llc[0], sizeof(llc), "???");
+        }
+    }
+
+    LOGD("> %s:%s\t%s", pString, print_buffer, llc);
 }
diff --git a/src/phLlcNfc_DataTypes.h b/src/phLlcNfc_DataTypes.h
index 9d5b588..b84cd3e 100644
--- a/src/phLlcNfc_DataTypes.h
+++ b/src/phLlcNfc_DataTypes.h
@@ -132,7 +132,7 @@ DEFINED : then if the received NS = (expected NR - 1) then instead of REJ
         RR frame is sent
 COMMENTED : then REJ frame is sent
 */
-#define LLC_RR_INSTEAD_OF_REJ
+// #define LLC_RR_INSTEAD_OF_REJ
 
 #define SEND_UFRAME
 
@@ -205,7 +205,7 @@ COMMENTED : then exception is raised
 #define PH_LLCNFC_READPEND_REMAIN_BYTE              (0x02U)
 /** Read pending not done */
 #define PH_LLCNFC_READPEND_FLAG_OFF                 FALSE
-#define PH_LLCNFC_MAX_REJ_RETRY_COUNT               (10)
+#define PH_LLCNFC_MAX_REJ_RETRY_COUNT               (200)
 
 
 /**** Macros for state machine ****/
diff --git a/src/phLlcNfc_Interface.c b/src/phLlcNfc_Interface.c
index a1e9938..175462d 100644
--- a/src/phLlcNfc_Interface.c
+++ b/src/phLlcNfc_Interface.c
@@ -43,6 +43,9 @@
 #ifdef PH_LLCNFC_DALINT
 #include <phDal4Nfc.h>
 #endif
+#define LOG_TAG "NFC-LLC"
+
+#include <utils/Log.h>
 /*********************** End of includes ****************************/
 
 /***************************** Macros *******************************/
@@ -70,6 +73,7 @@ phLlcNfc_RdResp_Cb(
 /******************** End of Local functions ************************/
 
 /********************** Global variables ****************************/
+int libnfc_llc_error_count = 0;
 
 /******************** End of Global Variables ***********************/
 
@@ -666,7 +670,7 @@ phLlcNfc_RdResp_Cb(
     PH_LLCNFC_PRINT("\n\nLLC : READ RESP CB CALLED\n\n");
     
     if ((NULL != ps_llc_ctxt) && (NULL != pCompInfo) && (NULL != pHwInfo)
-       && (pCompInfo->length != 0) && (NULL != pCompInfo->buffer))
+       && (NULL != pCompInfo->buffer))
     {
         ps_frame_info = &(ps_llc_ctxt->s_frameinfo);
         ps_recv_pkt = &(ps_frame_info->s_recvpacket);
@@ -782,19 +786,19 @@ phLlcNfc_RdResp_Cb(
                 else if (ps_frame_info->recv_error_count < 
                     PH_LLCNFC_MAX_REJ_RETRY_COUNT)
                 {
+                    LOGW("LLC bad crc");
                     PH_LLCNFC_PRINT("CRC ERROR RECVD \n");
                     PH_LLCNFC_DEBUG("RECV ERROR COUNT : 0x%02X\n", ps_frame_info->recv_error_count);
 
                     ps_frame_info->recv_error_count = (uint8_t)
                                     (ps_frame_info->recv_error_count + 1);
+                    libnfc_llc_error_count++;
 
                     result = phLlcNfc_Interface_Read(ps_llc_ctxt, 
                         PH_LLCNFC_READWAIT_OFF, 
                         (uint8_t *)&(ps_recv_pkt->s_llcbuf.llc_length_byte), 
                         PH_LLCNFC_BYTES_INIT_READ);
-
 #ifdef CRC_ERROR_REJ
-
                     /* Send REJ (S frame), as the CRC received has error  */
                     result = phLlcNfc_H_SendRejectFrame (ps_llc_ctxt);
 
@@ -803,6 +807,7 @@ phLlcNfc_RdResp_Cb(
                 }
                 else
                 {
+                    LOGE("max LLC retries exceeded, stack restart");
                     result = phLlcNfc_Interface_Read (ps_llc_ctxt, 
                                 PH_LLCNFC_READWAIT_OFF, 
                                 (uint8_t *)&(ps_recv_pkt->s_llcbuf.llc_length_byte), 
@@ -827,6 +832,7 @@ phLlcNfc_RdResp_Cb(
             else if (ps_frame_info->recv_error_count >= 
                     PH_LLCNFC_MAX_REJ_RETRY_COUNT)
             {
+                LOGE("max LLC retries exceeded, stack restart");
                 result = phLlcNfc_Interface_Read (ps_llc_ctxt, 
                         PH_LLCNFC_READWAIT_OFF, 
                         (uint8_t *)&(ps_recv_pkt->s_llcbuf.llc_length_byte), 
@@ -849,8 +855,10 @@ phLlcNfc_RdResp_Cb(
                 (PH_LLCNFC_MAX_BUFLEN_RECV_SEND > pCompInfo->length) && 
                 (pCompInfo->length != ps_recv_pkt->s_llcbuf.llc_length_byte))
             {
+                LOGE("bad LLC length1 %d", pCompInfo->length);
                 ps_frame_info->recv_error_count = (uint8_t)
                                     (ps_frame_info->recv_error_count + 1);
+                libnfc_llc_error_count++;
 
                 result = phLlcNfc_Interface_Read(ps_llc_ctxt, 
                         PH_LLCNFC_READWAIT_OFF, 
@@ -875,8 +883,10 @@ phLlcNfc_RdResp_Cb(
                     value is greater than (0x21 - 1), then pend a read to 
                     get 1 byte again
                 */
+                LOGW("bad LLC length byte %x\n", *(pCompInfo->buffer));
                 ps_frame_info->recv_error_count = (uint8_t)
                                     (ps_frame_info->recv_error_count + 1);
+                libnfc_llc_error_count++;
 
                 result = phLlcNfc_Interface_Read(ps_llc_ctxt, 
                         PH_LLCNFC_READWAIT_OFF, 
@@ -885,8 +895,10 @@ phLlcNfc_RdResp_Cb(
             }
             else
             {
+                LOGW("unknown LLC error1");
                 ps_frame_info->recv_error_count = (uint8_t)
                                     (ps_frame_info->recv_error_count + 1);
+                libnfc_llc_error_count++;
 
                 phLlcNfc_StopTimers(PH_LLCNFC_GUARDTIMER, 
                                     ps_llc_ctxt->s_timerinfo.guard_to_count);
@@ -905,11 +917,24 @@ phLlcNfc_RdResp_Cb(
                                         pHwInfo, pCompInfo);
                 }
             }
+        } else if (NFCSTATUS_READ_FAILED == pCompInfo->status) {
+            // partial read - try reading the length byte again
+            LOGW("LLC length mis-match\n");
+            ps_frame_info->recv_error_count = (uint8_t)
+                                (ps_frame_info->recv_error_count + 1);
+            libnfc_llc_error_count++;
+
+            result = phLlcNfc_Interface_Read(ps_llc_ctxt,
+                    PH_LLCNFC_READWAIT_OFF,
+                    (uint8_t *)&(ps_recv_pkt->s_llcbuf.llc_length_byte),
+                    PH_LLCNFC_BYTES_INIT_READ);
         }
         else
         {
+            LOGW("unknown LLC error2");
             ps_frame_info->recv_error_count = (uint8_t)
                                     (ps_frame_info->recv_error_count + 1);
+            libnfc_llc_error_count++;
 
             phLlcNfc_StopTimers(PH_LLCNFC_GUARDTIMER, 
                                 ps_llc_ctxt->s_timerinfo.guard_to_count);
diff --git a/src/phOsalNfc.h b/src/phOsalNfc.h
index 246c2e6..e522263 100644
--- a/src/phOsalNfc.h
+++ b/src/phOsalNfc.h
@@ -166,7 +166,8 @@ void phOsalNfc_DbgString(const char *pString);
  *
  * \retval None
  */
-void phOsalNfc_PrintData(const char *pString, uint32_t length, uint8_t *pBuffer);
+void phOsalNfc_PrintData(const char *pString, uint32_t length, uint8_t *pBuffer,
+        int verbosity);
 
 /*!
  * \ingroup grp_osal_nfc