Enable sqlite wal logging

This will help us track down bug: 3353077

Change-Id: I394a86908e8a534fbba1bbe21c6a450d95dbce9e

dist/sqlite3.c

@@ -19167,21 +19167,27 @@ SQLITE_API char *sqlite3_mprintf(const char *zFormat, ...){
 ** current locale settings.  This is important for SQLite because we
 ** are not able to use a "," as the decimal point in place of "." as
 ** specified by some locales.
-*/
-SQLITE_API char *sqlite3_snprintf(int n, char *zBuf, const char *zFormat, ...){
-  char *z;
-  va_list ap;
+**
+** Oops:  The first two arguments of sqlite3_snprintf() are backwards
+** from the snprintf() standard.  Unfortunately, it is too late to change
+** this without breaking compatibility, so we just have to live with the
+** mistake.
+**
+** sqlite3_vsnprintf() is the varargs version.*/
+SQLITE_API char *sqlite3_vsnprintf(int n, char *zBuf, const char *zFormat, va_list ap){
   StrAccum acc;
-
-  if( n<=0 ){
-    return zBuf;
-  }
+  if( n<=0 ) return zBuf;
   sqlite3StrAccumInit(&acc, zBuf, n, 0);
   acc.useMalloc = 0;
-  va_start(ap,zFormat);
   sqlite3VXPrintf(&acc, 0, zFormat, ap);
+  return sqlite3StrAccumFinish(&acc);
+}
+SQLITE_API char *sqlite3_snprintf(int n, char *zBuf, const char *zFormat, ...){
+  char *z;
+  va_list ap;
+  va_start(ap,zFormat);
+  z = sqlite3_vsnprintf(n, zBuf, zFormat, ap);
   va_end(ap);
-  z = sqlite3StrAccumFinish(&acc);
   return z;
 }
@@ -41700,6 +41706,21 @@ SQLITE_PRIVATE int sqlite3WalTrace = 0;
 # define WALTRACE(X)
 #endif
+/*
+** WAL tracing logic added to search for an SQLITE_PROTOCOL error.
+*/
+static void walTrace(const char *zFormat, ...){
+  va_list ap;
+  char zMsg[100];
+  va_start(ap, zFormat);
+  sqlite3_vsnprintf(sizeof(zMsg), zMsg, zFormat, ap);
+  va_end(ap);
+#ifdef SQLITE_WAL_TRACE
+  fprintf(stdout, "WALTRACE: [%s]\n", zMsg); fflush(stdout);
+#endif
+  sqlite3_log(99, "%s", zMsg);
+}
+
 /*
 ** The maximum (and only) versions of the wal and wal-index formats
 ** that may be interpreted by this version of SQLite.
@@ -41958,6 +41979,7 @@ static int walIndexPage(Wal *pWal, int iPage, volatile u32 **ppPage){
     apNew = (volatile u32 **)sqlite3_realloc((void *)pWal->apWiData, nByte);
     if( !apNew ){
       *ppPage = 0;
+      walTrace("realloc(%d) in walIndexPage()", nByte);
       return SQLITE_NOMEM;
     }
     memset((void*)&apNew[pWal->nWiData], 0,
@@ -41976,6 +41998,7 @@ static int walIndexPage(Wal *pWal, int iPage, volatile u32 **ppPage){
           pWal->writeLock, (void volatile **)&pWal->apWiData[iPage]
       );
     }
+    if( rc ) walTrace("xShmMap():%d in walIndexPage(iPage=%d)",rc,iPage);
   }
   *ppPage = pWal->apWiData[iPage];
@@ -43272,6 +43295,7 @@ static int walIndexReadHdr(Wal *pWal, int *pChanged){
   assert( badHdr==0 || pWal->writeLock==0 );
   if( badHdr && SQLITE_OK==(rc = walLockExclusive(pWal, WAL_WRITE_LOCK, 1)) ){
     pWal->writeLock = 1;
+    walTrace("trying walIndexTryHdr w/lock");
     if( SQLITE_OK==(rc = walIndexPage(pWal, 0, &page0)) ){
       badHdr = walIndexTryHdr(pWal, pChanged);
       if( badHdr ){
@@ -43279,13 +43303,16 @@ static int walIndexReadHdr(Wal *pWal, int *pChanged){
         ** a WRITE lock, it can only mean that the header is corrupted and
         ** needs to be reconstructed.  So run recovery to do exactly that.
         */
+        walTrace("walIndexTryHdr() failed w/lock");
         rc = walIndexRecover(pWal);
+        if( rc ) walTrace("walIndexRecover():%d", rc);
         *pChanged = 1;
       }
     }
     pWal->writeLock = 0;
     walUnlockExclusive(pWal, WAL_WRITE_LOCK, 1);
   }
+  else if(badHdr) walTrace("walLockExcl():%d in walIndexReadHdr()", rc);
   /* If the header is read successfully, check the version number to make
   ** sure the wal-index was not constructed with some future format that
@@ -43365,6 +43392,7 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){
   /* Take steps to avoid spinning forever if there is a protocol error. */
   if( cnt>5 ){
+    walTrace("cnt=%d",cnt);
     if( cnt>100 ) return SQLITE_PROTOCOL;
     sqlite3OsSleep(pWal->pVfs, 1);
   }
@@ -43423,12 +43451,14 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){
         ** have started to backfill the appended frames but crashed before
         ** it finished. Leaving a corrupt image in the database file.
         */
+        walTrace("wal read/write race - writer won");
         walUnlockShared(pWal, WAL_READ_LOCK(0));
         return WAL_RETRY;
       }
       pWal->readLock = 0;
       return SQLITE_OK;
     }else if( rc!=SQLITE_BUSY ){
+      walTrace("walLockShared(0):%d in walTryBeginRead", rc);
       return rc;
     }
   }
@@ -43458,8 +43488,12 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){
       pInfo->aReadMark[1] = pWal->hdr.mxFrame;
       walUnlockExclusive(pWal, WAL_READ_LOCK(1), 1);
       rc = WAL_RETRY;
+      if( cnt>5 ){
+        walTrace("aReadMark[1] <- %d", pWal->hdr.mxFrame);
+      }
     }else if( rc==SQLITE_BUSY ){
       rc = WAL_RETRY;
+      walTrace("aReadMark[1] is busy");
     }
     return rc;
   }else{
@@ -43472,6 +43506,7 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){
           walUnlockExclusive(pWal, WAL_READ_LOCK(i), 1);
           break;
         }else if( rc!=SQLITE_BUSY ){
+          walTrace("walLockExclusive(%d):%d", i, rc);
           return rc;
         }
       }
@@ -43479,6 +43514,7 @@ static int walTryBeginRead(Wal *pWal, int *pChanged, int useWal, int cnt){
     rc = walLockShared(pWal, WAL_READ_LOCK(mxI));
     if( rc ){
+      walTrace("walLockShared(mxI=%d):%d", mxI, rc);
       return rc==SQLITE_BUSY ? WAL_RETRY : rc;
     }
     /* Now that the read-lock has been obtained, check that neither the