Cherrypick the WAL error logging from the pre-3.7.5 line into a branch

for version 3.7.2.  Include the sqlite3_vsnprintf() interface.  This
checkin is intended for debugging and not for release.

FossilOrigin-Name: 6549e7672bcbac0bca6cef96c4d4a42998ba3ba9

manifest

@@ -1,8 +1,8 @@
 -----BEGIN PGP SIGNED MESSAGE-----
 Hash: SHA1
 
-C Version\s3.7.2\srelease\scandidate\s1
-D 2010-08-23T18:52:01
+C Cherrypick\sthe\sWAL\serror\slogging\sfrom\sthe\spre-3.7.5\sline\sinto\sa\sbranch\nfor\sversion\s3.7.2.\s\sInclude\sthe\ssqlite3_vsnprintf()\sinterface.\s\sThis\ncheckin\sis\sintended\sfor\sdebugging\sand\snot\sfor\srelease.
+D 2011-01-05T13:07:19
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in 543f91f24cd7fee774ecc0a61c19704c0c3e78fd
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -94,7 +94,7 @@ F ext/rtree/rtree_perf.tcl 6c18c1f23cd48e0f948930c98dfdd37dfccb5195
 F ext/rtree/rtree_util.tcl 06aab2ed5b826545bf215fff90ecb9255a8647ea
 F ext/rtree/tkt3363.test 2bf324f7908084a5f463de3109db9c6e607feb1b
 F ext/rtree/viewrtree.tcl eea6224b3553599ae665b239bd827e182b466024
-F install-sh 9d4de14ab9fb0facae2f48780b874848cbf2f895 x
+F install-sh 9d4de14ab9fb0facae2f48780b874848cbf2f895
 F ltmain.sh 3ff0879076df340d2e23ae905484d8c15d5fdea8
 F main.mk 26ad86cf0689940f19b3d608bbfdb3956b2fb9a7
 F mkdll.sh 7d09b23c05d56532e9d44a50868eb4b12ff4f74a
@@ -167,13 +167,13 @@ F src/pcache.h c683390d50f856d4cd8e24342ae62027d1bb6050
 F src/pcache1.c e921e8a1d52c93abde63cb6dad1fa39770410c52
 F src/pragma.c 8b24ce00a93de345b6c3bd1e1e2cfba9f63d2325
 F src/prepare.c ce4c35a2b1d5fe916e4a46b70d24a6e997d7c4c6
-F src/printf.c 8ae5082dd38a1b5456030c3755ec3a392cd51506
+F src/printf.c 37e8bfd4c5a04eae4960adbe776b0f1fc4cad674
 F src/random.c cd4a67b3953b88019f8cd4ccd81394a8ddfaba50
 F src/resolve.c 1c0f32b64f8e3f555fe1f732f9d6f501a7f05706
 F src/rowset.c 69afa95a97c524ba6faf3805e717b5b7ae85a697
 F src/select.c 8add6cab889fc02e1492eda8dba462ccf11f51dd
 F src/shell.c 8517fc1f9c59ae4007e6cc8b9af91ab231ea2056
-F src/sqlite.h.in 2d72a6242df41c517e38eec8791abcf5484a36f1
+F src/sqlite.h.in 91939f10e63ec477d052c37c6d2b464c9ac2461e
 F src/sqlite3ext.h 69dfb8116af51b84a029cddb3b35062354270c89
 F src/sqliteInt.h e33b15e8176442bf7484f0e716edfd1ce03b2979
 F src/sqliteLimit.h a17dcd3fb775d63b64a43a55c54cb282f9726f44
@@ -230,7 +230,7 @@ F src/vdbeblob.c 258a6010ba7a82b72b327fb24c55790655689256
 F src/vdbemem.c e5673f81a2381b35c60e73ef0a8502be2ab1041e
 F src/vdbetrace.c 864cef96919323482ebd9986f2132435115e9cc2
 F src/vtab.c 0e8e0cb30dffb078367e843e84e37ef99236c7e4
-F src/wal.c 5ac2119e23ee4424599d4275b66dc88d612a0543
+F src/wal.c 1076d7d8a2ff6167207576f837e5d458fb8647ea
 F src/wal.h 96669b645e27cd5a111ba59f0cae7743a207bc3c
 F src/walker.c 3112bb3afe1d85dc52317cb1d752055e9a781f8f
 F src/where.c 7db3e41c2a846f9deeb24f1bbb75461b4010b7b5
@@ -556,7 +556,7 @@ F test/permutations.test 17498d1219f922d5a6da893a94c4dc7766fb2426
 F test/pragma.test ed78d200f65c6998df51196cb8c39d5300570f24
 F test/pragma2.test 5364893491b9231dd170e3459bfc2e2342658b47
 F test/printf.test 05970cde31b1a9f54bd75af60597be75a5c54fea
-F test/progress.test 5b075c3c790c7b2a61419bc199db87aaf48b8301
+F test/progress.test 5b075c3c790c7b2a61419bc199db87aaf48b8301 x
 F test/ptrchng.test ef1aa72d6cf35a2bbd0869a649b744e9d84977fc
 F test/quick.test 1681febc928d686362d50057c642f77a02c62e57
 F test/quote.test 215897dbe8de1a6f701265836d6601cc6ed103e6
@@ -824,7 +824,7 @@ F tool/genfkey.test 4196a8928b78f51d54ef58e99e99401ab2f0a7e5
 F tool/lemon.c fe890e2d8d2db1e3f57e2a22503dbb0f6843e517
 F tool/lempar.c 01ca97f87610d1dac6d8cd96ab109ab1130e76dc
 F tool/mkkeywordhash.c d2e6b4a5965e23afb80fbe74bb54648cd371f309
-F tool/mkopts.tcl 66ac10d240cc6e86abd37dc908d50382f84ff46e
+F tool/mkopts.tcl 66ac10d240cc6e86abd37dc908d50382f84ff46e x
 F tool/mkspeedsql.tcl a1a334d288f7adfe6e996f2e712becf076745c97
 F tool/mksqlite3c.tcl aff0d53f0e84cf919922c0d02e767bdf5eeafb90
 F tool/mksqlite3h.tcl eb100dce83f24b501b325b340f8b5eb8e5106b3b
@@ -849,14 +849,18 @@ F tool/speedtest2.tcl ee2149167303ba8e95af97873c575c3e0fab58ff
 F tool/speedtest8.c 2902c46588c40b55661e471d7a86e4dd71a18224
 F tool/speedtest8inst1.c 293327bc76823f473684d589a8160bde1f52c14e
 F tool/vdbe-compress.tcl d70ea6d8a19e3571d7ab8c9b75cba86d1173ff0f
-P 21a1e5961bba148fda50cc0b7d472ca74f90808a
-R aa9cc30f9dbcb7ea427137065cf4e4be
+P 42537b60566f288167f1b5864a5435986838e3a3
+R cc7deca34c58f9101094db42dd411f0a
+T *bgcolor * #8eb2a1
+T *branch * wal-trace-372
+T *sym-wal-trace-372 *
+T -sym-trunk *
 U drh
-Z e73ee740c6593b4458c2d23b6fa7b923
+Z 9ad7e0630e9e6a86b3e214d91cd95b64
 -----BEGIN PGP SIGNATURE-----
 Version: GnuPG v1.4.6 (GNU/Linux)
 
-iD8DBQFMcsNUoxKgR168RlERApyRAKCOHvk0Gn1uE2F8YVm3k/w13/3UugCeOh16
-bApiXjM1a7FP+Qr1HX5kWTQ=
-=L2Lf
+iD8DBQFNJG0KoxKgR168RlERAuS2AJ0UbkZkdqn/jcD8Da0NsE8Y8cYD3gCfWqgZ
+fjsNY2yMO+aT/mg2P1MbJCY=
+=Tppw
 -----END PGP SIGNATURE-----

manifest.uuid

@@ -1 +1 @@
-42537b60566f288167f1b5864a5435986838e3a3
+6549e7672bcbac0bca6cef96c4d4a42998ba3ba9

src/printf.c

@@ -934,21 +934,28 @@ 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.
+**
+** 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.
 */
+char *sqlite3_vsnprintf(int n, char *zBuf, const char *zFormat, va_list ap){
+  StrAccum acc;
+  if( n<=0 ) return zBuf;
+  sqlite3StrAccumInit(&acc, zBuf, n, 0);
+  acc.useMalloc = 0;
+  sqlite3VXPrintf(&acc, 0, zFormat, ap);
+  return sqlite3StrAccumFinish(&acc);
+}
 char *sqlite3_snprintf(int n, char *zBuf, const char *zFormat, ...){
   char *z;
   va_list ap;
-  StrAccum acc;
-
-  if( n<=0 ){
-    return zBuf;
-  }
-  sqlite3StrAccumInit(&acc, zBuf, n, 0);
-  acc.useMalloc = 0;
   va_start(ap,zFormat);
-  sqlite3VXPrintf(&acc, 0, zFormat, ap);
+  z = sqlite3_vsnprintf(n, zBuf, zFormat, ap);
   va_end(ap);
-  z = sqlite3StrAccumFinish(&acc);
   return z;
 }
 

src/sqlite.h.in

@@ -1829,6 +1829,8 @@ void sqlite3_free_table(char **result);
 ** the zero terminator.  So the longest string that can be completely
 ** written will be n-1 characters.
 **
+** ^The sqlite3_vsnprintf() routine is a varargs version of sqlite3_snprintf().
+**
 ** These routines all implement some additional formatting
 ** options that are useful for constructing SQL statements.
 ** All of the usual printf() formatting options apply.  In addition, there
@@ -1892,6 +1894,7 @@ void sqlite3_free_table(char **result);
 char *sqlite3_mprintf(const char*,...);
 char *sqlite3_vmprintf(const char*, va_list);
 char *sqlite3_snprintf(int,char*,const char*, ...);
+char *sqlite3_vsnprintf(int,char*,const char*, va_list);
 
 /*
 ** CAPI3REF: Memory Allocation Subsystem

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.
@@ -504,6 +519,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,
@@ -517,6 +533,7 @@ static int walIndexPage(Wal *pWal, int iPage, volatile u32 **ppPage){
     rc = sqlite3OsShmMap(pWal->pDbFd, iPage, WALINDEX_PGSZ, 
         pWal->writeLock, (void volatile **)&pWal->apWiData[iPage]
     );
+    if( rc ) walTrace("xShmMap():%d in walIndexPage(iPage=%d)",rc,iPage);
   }
 
   *ppPage = pWal->apWiData[iPage];
@@ -1795,6 +1812,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 ){
@@ -1802,13 +1820,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
@@ -1888,6 +1909,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);
   }
@@ -1946,12 +1968,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;
     }
   }
@@ -1981,8 +2005,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{
@@ -1995,6 +2021,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;
         }
       }
@@ -2002,6 +2029,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