Add detailed error logging to WAL in an effort to track down an obscure

SQLITE_PROTOCOL problem.  This code is intended for debugging and not
for release.

FossilOrigin-Name: 2c2afdd0adad7d364915ac200c71603deddf148e

diff --git a/manifest b/manifest
index c7260b994de87489d6fb1cfbe1a14d8f2a923c77..207aa11dad0cfb28401715feb77ad689ce7a0c3e 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,8 +1,8 @@
 -----BEGIN PGP SIGNED MESSAGE-----
 Hash: SHA1
 
-C Add\sthe\ssqlite3_vsnprintf()\sinterface.
-D 2011-01-05T12:20:09
+C Add\sdetailed\serror\slogging\sto\sWAL\sin\san\seffort\sto\strack\sdown\san\sobscure\nSQLITE_PROTOCOL\sproblem.\s\sThis\scode\sis\sintended\sfor\sdebugging\sand\snot\nfor\srelease.
+D 2011-01-05T12:50:18
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in de6498556d536ae60bb8bb10e8c1ba011448658c
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -240,7 +240,7 @@ F src/vdbeblob.c 18955f0ee6b133cd08e1592010cb9a6b11e9984c
 F src/vdbemem.c 411649a35686f54268ccabeda175322c4697f5a6
 F src/vdbetrace.c 864cef96919323482ebd9986f2132435115e9cc2
 F src/vtab.c b297e8fa656ab5e66244ab15680d68db0adbec30
-F src/wal.c dbca424f71678f663a286ab2a98f947af1d412a7
+F src/wal.c 2db71704aad93c8af510b9d03db7ff83cb72d262
 F src/wal.h c1aac6593a0b02b15dc625987e619edeab39292e
 F src/walker.c 3112bb3afe1d85dc52317cb1d752055e9a781f8f
 F src/where.c af069e6b53234118014dabfece96a9515b69d76b
@@ -898,14 +898,18 @@ F tool/speedtest2.tcl ee2149167303ba8e95af97873c575c3e0fab58ff
 F tool/speedtest8.c 2902c46588c40b55661e471d7a86e4dd71a18224
 F tool/speedtest8inst1.c 293327bc76823f473684d589a8160bde1f52c14e
 F tool/vdbe-compress.tcl d70ea6d8a19e3571d7ab8c9b75cba86d1173ff0f
-P 73128d4ef5d7703bf7af0553c307b55dc1b783f6
-R 22f3c024ddce8fb34edcc7b2ba2f47cc
+P fc67adea414320e0c0b24054f76070cfaeebb401
+R 9a70d0db3cd018c7ffadd937acab66a6
+T *bgcolor * #8eb2a1
+T *branch * wal-trace-375
+T *sym-wal-trace-375 *
+T -sym-trunk *
 U drh
-Z 7a7101ec3b07503edbe1e87dcccedd8b
+Z deca480426022b743682a4741edf3ac7
 -----BEGIN PGP SIGNATURE-----
 Version: GnuPG v1.4.6 (GNU/Linux)
 
-iD8DBQFNJGH9oxKgR168RlERApc5AJ0YgtPklZ+P441lEcNlotS284XXhwCdF7KS
-vpLjG17hnHrqRDNqDYunPRg=
-=hyLY
+iD8DBQFNJGkNoxKgR168RlERAlszAJ4xSpT0v27OigWR5jRHbwMOdSMMawCgh9Ef
+iJiFD8SkEPDoPW+dVg/AXgU=
+=RGug
 -----END PGP SIGNATURE-----

diff --git a/manifest.uuid b/manifest.uuid
index adfaf67b0fc6f6567f1da769426d2a5e60cb04dc..fbb877e17dc5040c2ee01889da1809d74167d08b 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-fc67adea414320e0c0b24054f76070cfaeebb401
\ No newline at end of file
+2c2afdd0adad7d364915ac200c71603deddf148e
\ No newline at end of file

diff --git a/src/wal.c b/src/wal.c
index ff327bf6bb5a30147beab40fa3aa81f765b05f3d..a2e2a39ba4445072a527b6c4e11f2db3f4bf2aec 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -253,6 +253,21 @@ 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.
@@ -511,6 +526,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,
@@ -529,6 +545,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];
@@ -1860,6 +1877,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 ){
@@ -1867,13 +1885,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
@@ -1953,6 +1974,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);
   }
@@ -2011,12 +2033,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;
     }
   }
@@ -2046,8 +2070,10 @@ 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;
+      walTrace("aReadMark[1] <- %d", pWal->hdr.mxFrame);
     }else if( rc==SQLITE_BUSY ){
       rc = WAL_RETRY;
+      walTrace("aReadMark[1] is busy");
     }
     return rc;
   }else{
@@ -2060,6 +2086,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;
         }
       }
@@ -2067,6 +2094,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