/ Check-in [01076528]
Login

Many hyperlinks are disabled.
Use anonymous login to enable hyperlinks.

Overview
Comment:Have os_unix.c call sqlite3_log() following errors in certain system calls.
Downloads: Tarball | ZIP archive | SQL archive
Timelines: family | ancestors | descendants | both | trunk
Files: files | file ages | folders
SHA1: 01076528a43b61ae20ef6969b7d326de9b5313e4
User & Date: dan 2011-02-21 11:46:24
References
2011-02-23
14:05
Backport the os_unix.c error logging enhancements from check-in [01076528a43b61a]. check-in: a4333b15 user: drh tags: branch-3.7.4
Context
2011-02-21
17:49
Fix a problem with "EXPLAIN QUERY PLAN SELECT count(*) FROM tbl". check-in: 9f9f3288 user: dan tags: trunk
11:46
Have os_unix.c call sqlite3_log() following errors in certain system calls. check-in: 01076528 user: dan tags: trunk
2011-02-19
23:18
An SQLITE_PROTOCOL error counts as a locking error for verification purposes. check-in: e87d499a user: drh tags: trunk
Changes
Hide Diffs Side-by-Side Diffs Ignore Whitespace Patch

Changes to src/os_unix.c.

   733    733   #endif
   734    734   };
   735    735   
   736    736   /*
   737    737   ** A lists of all unixInodeInfo objects.
   738    738   */
   739    739   static unixInodeInfo *inodeList = 0;
          740  +
          741  +/*
          742  +**
          743  +** This function - unixLogError_x(), is only ever called via the macro
          744  +** unixLogError().
          745  +**
          746  +** It is invoked after an error occurs in an OS function and errno has been
          747  +** set. It logs a message using sqlite3_log() containing the current value of
          748  +** errno and, if possible, the human-readable equivalent from strerror() or
          749  +** strerror_r().
          750  +**
          751  +** The first argument passed to the macro should be the error code that
          752  +** will be returned to SQLite (e.g. SQLITE_IOERR_DELETE, SQLITE_CANTOPEN). 
          753  +** The two subsequent arguments should be the name of the OS function that
          754  +** failed (e.g. "unlink", "open") and the the associated file-system path,
          755  +** if any.
          756  +*/
          757  +#define unixLogError(a,b,c)     unixLogError_x(a,b,c,__LINE__)
          758  +static int unixLogError_x(
          759  +  int errcode,                    /* SQLite error code */
          760  +  const char *zFunc,              /* Name of OS function that failed */
          761  +  const char *zPath,              /* File path associated with error */
          762  +  int iLine                       /* Source line number where error occurred */
          763  +){
          764  +  char *zErr;                     /* Message from strerror() or equivalent */
          765  +
          766  +  /* If this is not a threadsafe build (SQLITE_THREADSAFE==0), then use
          767  +  ** the strerror() function to obtain the human-readable error message
          768  +  ** equivalent to errno. Otherwise, use strerror_r().
          769  +  */ 
          770  +#if SQLITE_THREADSAFE && defined(HAVE_STRERROR_R)
          771  +  char aErr[80];
          772  +  memset(aErr, 0, sizeof(aErr));
          773  +  zErr = aErr;
          774  +
          775  +  /* If STRERROR_R_CHAR_P (set by autoconf scripts) or __USE_GNU is defined,
          776  +  ** assume that the system provides the the GNU version of strerror_r() that 
          777  +  ** returns a pointer to a buffer containing the error message. That pointer 
          778  +  ** may point to aErr[], or it may point to some static storage somewhere. 
          779  +  ** Otherwise, assume that the system provides the POSIX version of 
          780  +  ** strerror_r(), which always writes an error message into aErr[].
          781  +  **
          782  +  ** If the code incorrectly assumes that it is the POSIX version that is
          783  +  ** available, the error message will often be an empty string. Not a
          784  +  ** huge problem. Incorrectly concluding that the GNU version is available 
          785  +  ** could lead to a segfault though.
          786  +  */
          787  +#if defined(STRERROR_R_CHAR_P) || defined(__USE_GNU)
          788  +  zErr = 
          789  +# endif
          790  +  strerror_r(errno, aErr, sizeof(aErr)-1);
          791  +
          792  +#elif SQLITE_THREADSAFE
          793  +  /* This is a threadsafe build, but strerror_r() is not available. */
          794  +  zErr = "";
          795  +#else
          796  +  /* Non-threadsafe build, use strerror(). */
          797  +  zErr = strerror(errno);
          798  +#endif
          799  +
          800  +  assert( errcode!=SQLITE_OK );
          801  +  sqlite3_log(errcode,
          802  +      "os_unix.c: %s() at line %d - \"%s\" errno=%d path=%s",
          803  +      zFunc, iLine, zErr, errno, (zPath ? zPath : "n/a")
          804  +  );
          805  +
          806  +  return errcode;
          807  +}
          808  +
   740    809   
   741    810   /*
   742    811   ** Close all file descriptors accumuated in the unixInodeInfo->pUnused list.
   743    812   ** If all such file descriptors are closed without error, the list is
   744    813   ** cleared and SQLITE_OK returned.
   745    814   **
   746    815   ** Otherwise, if an error occurs, then successfully closed file descriptor
................................................................................
   753    822     UnixUnusedFd *pError = 0;
   754    823     UnixUnusedFd *p;
   755    824     UnixUnusedFd *pNext;
   756    825     for(p=pInode->pUnused; p; p=pNext){
   757    826       pNext = p->pNext;
   758    827       if( close(p->fd) ){
   759    828         pFile->lastErrno = errno;
   760         -      rc = SQLITE_IOERR_CLOSE;
          829  +      rc = unixLogError(SQLITE_IOERR_CLOSE, "close", pFile->zPath);
   761    830         p->pNext = pError;
   762    831         pError = p;
   763    832       }else{
   764    833         sqlite3_free(p);
   765    834       }
   766    835     }
   767    836     pInode->pUnused = pError;
................................................................................
  1406   1475   static int closeUnixFile(sqlite3_file *id){
  1407   1476     unixFile *pFile = (unixFile*)id;
  1408   1477     if( pFile ){
  1409   1478       if( pFile->dirfd>=0 ){
  1410   1479         int err = close(pFile->dirfd);
  1411   1480         if( err ){
  1412   1481           pFile->lastErrno = errno;
  1413         -        return SQLITE_IOERR_DIR_CLOSE;
         1482  +        return unixLogError(SQLITE_IOERR_DIR_CLOSE, "close", pFile->zPath);
  1414   1483         }else{
  1415   1484           pFile->dirfd=-1;
  1416   1485         }
  1417   1486       }
  1418   1487       if( pFile->h>=0 ){
  1419   1488         int err = close(pFile->h);
  1420   1489         if( err ){
  1421   1490           pFile->lastErrno = errno;
  1422         -        return SQLITE_IOERR_CLOSE;
         1491  +        return unixLogError(SQLITE_IOERR_CLOSE, "close", pFile->zPath);
  1423   1492         }
  1424   1493       }
  1425   1494   #if OS_VXWORKS
  1426   1495       if( pFile->pId ){
  1427   1496         if( pFile->isDelete ){
  1428   1497           unlink(pFile->pId->zCanonicalName);
  1429   1498         }
................................................................................
  2937   3006   
  2938   3007     assert( pFile );
  2939   3008     OSTRACE(("SYNC    %-3d\n", pFile->h));
  2940   3009     rc = full_fsync(pFile->h, isFullsync, isDataOnly);
  2941   3010     SimulateIOError( rc=1 );
  2942   3011     if( rc ){
  2943   3012       pFile->lastErrno = errno;
  2944         -    return SQLITE_IOERR_FSYNC;
         3013  +    return unixLogError(SQLITE_IOERR_FSYNC, "full_fsync", pFile->zPath);
  2945   3014     }
  2946   3015     if( pFile->dirfd>=0 ){
  2947   3016       int err;
  2948   3017       OSTRACE(("DIRSYNC %-3d (have_fullfsync=%d fullsync=%d)\n", pFile->dirfd,
  2949   3018               HAVE_FULLFSYNC, isFullsync));
  2950   3019   #ifndef SQLITE_DISABLE_DIRSYNC
  2951   3020       /* The directory sync is only attempted if full_fsync is
................................................................................
  2964   3033       }
  2965   3034   #endif
  2966   3035       err = close(pFile->dirfd); /* Only need to sync once, so close the */
  2967   3036       if( err==0 ){              /* directory when we are done */
  2968   3037         pFile->dirfd = -1;
  2969   3038       }else{
  2970   3039         pFile->lastErrno = errno;
  2971         -      rc = SQLITE_IOERR_DIR_CLOSE;
         3040  +      rc = unixLogError(SQLITE_IOERR_DIR_CLOSE, "close", pFile->zPath);
  2972   3041       }
  2973   3042     }
  2974   3043     return rc;
  2975   3044   }
  2976   3045   
  2977   3046   /*
  2978   3047   ** Truncate an open file to a specified size
................................................................................
  2991   3060     if( pFile->szChunk ){
  2992   3061       nByte = ((nByte + pFile->szChunk - 1)/pFile->szChunk) * pFile->szChunk;
  2993   3062     }
  2994   3063   
  2995   3064     rc = ftruncate(pFile->h, (off_t)nByte);
  2996   3065     if( rc ){
  2997   3066       pFile->lastErrno = errno;
  2998         -    return SQLITE_IOERR_TRUNCATE;
         3067  +    return unixLogError(SQLITE_IOERR_TRUNCATE, "ftruncate", pFile->zPath);
  2999   3068     }else{
  3000   3069   #ifndef NDEBUG
  3001   3070       /* If we are doing a normal write to a database file (as opposed to
  3002   3071       ** doing a hot-journal rollback or a write to some file other than a
  3003   3072       ** normal database file) and we truncate the file to zero length,
  3004   3073       ** that effectively updates the change counter.  This might happen
  3005   3074       ** when restoring a database using the backup API from a zero-length
................................................................................
  3079   3148         */
  3080   3149         int nBlk = buf.st_blksize;  /* File-system block size */
  3081   3150         i64 iWrite;                 /* Next offset to write to */
  3082   3151         int nWrite;                 /* Return value from seekAndWrite() */
  3083   3152   
  3084   3153         if( ftruncate(pFile->h, nSize) ){
  3085   3154           pFile->lastErrno = errno;
  3086         -        return SQLITE_IOERR_TRUNCATE;
         3155  +        return unixLogError(SQLITE_IOERR_TRUNCATE, "ftruncate", pFile->zPath);
  3087   3156         }
  3088   3157         iWrite = ((buf.st_size + 2*nBlk - 1)/nBlk)*nBlk-1;
  3089   3158         do {
  3090   3159           nWrite = seekAndWrite(pFile, iWrite, "", 1);
  3091   3160           iWrite += nBlk;
  3092   3161         } while( nWrite==1 && iWrite<nSize );
  3093   3162         if( nWrite!=1 ) return SQLITE_IOERR_WRITE;
................................................................................
  3428   3497       if( pShmNode->mutex==0 ){
  3429   3498         rc = SQLITE_NOMEM;
  3430   3499         goto shm_open_err;
  3431   3500       }
  3432   3501   
  3433   3502       pShmNode->h = open(zShmFilename, O_RDWR|O_CREAT, (sStat.st_mode & 0777));
  3434   3503       if( pShmNode->h<0 ){
  3435         -      rc = SQLITE_CANTOPEN_BKPT;
         3504  +      rc = unixLogError(SQLITE_CANTOPEN_BKPT, "open", zShmFilename);
  3436   3505         goto shm_open_err;
  3437   3506       }
  3438   3507   
  3439   3508       /* Check to see if another process is holding the dead-man switch.
  3440   3509       ** If not, truncate the file to zero length. 
  3441   3510       */
  3442   3511       rc = SQLITE_OK;
  3443   3512       if( unixShmSystemLock(pShmNode, F_WRLCK, UNIX_SHM_DMS, 1)==SQLITE_OK ){
  3444   3513         if( ftruncate(pShmNode->h, 0) ){
  3445         -        rc = SQLITE_IOERR_SHMOPEN;
         3514  +        rc = unixLogError(SQLITE_IOERR_SHMOPEN, "ftruncate", zShmFilename);
  3446   3515         }
  3447   3516       }
  3448   3517       if( rc==SQLITE_OK ){
  3449   3518         rc = unixShmSystemLock(pShmNode, F_RDLCK, UNIX_SHM_DMS, 1);
  3450   3519       }
  3451   3520       if( rc ) goto shm_open_err;
  3452   3521     }
................................................................................
  3544   3613         ** false, exit early. *pp will be set to NULL and SQLITE_OK returned.
  3545   3614         **
  3546   3615         ** Alternatively, if bExtend is true, use ftruncate() to allocate
  3547   3616         ** the requested memory region.
  3548   3617         */
  3549   3618         if( !bExtend ) goto shmpage_out;
  3550   3619         if( ftruncate(pShmNode->h, nByte) ){
  3551         -        rc = SQLITE_IOERR_SHMSIZE;
         3620  +        rc = unixLogError(SQLITE_IOERR_SHMSIZE,"ftruncate",pShmNode->zFilename);
  3552   3621           goto shmpage_out;
  3553   3622         }
  3554   3623       }
  3555   3624   
  3556   3625       /* Map the requested memory region into this processes address space. */
  3557   3626       apNew = (char **)sqlite3_realloc(
  3558   3627           pShmNode->apRegion, (iRegion+1)*sizeof(char *)
................................................................................
  4263   4332   #ifdef FD_CLOEXEC
  4264   4333         fcntl(fd, F_SETFD, fcntl(fd, F_GETFD, 0) | FD_CLOEXEC);
  4265   4334   #endif
  4266   4335         OSTRACE(("OPENDIR %-3d %s\n", fd, zDirname));
  4267   4336       }
  4268   4337     }
  4269   4338     *pFd = fd;
  4270         -  return (fd>=0?SQLITE_OK:SQLITE_CANTOPEN_BKPT);
         4339  +  return (fd>=0?SQLITE_OK:unixLogError(SQLITE_CANTOPEN_BKPT, "open", zDirname));
  4271   4340   }
  4272   4341   
  4273   4342   /*
  4274   4343   ** Return the name of a directory in which to put temporary files.
  4275   4344   ** If no suitable temporary file directory can be found, return NULL.
  4276   4345   */
  4277   4346   static const char *unixTempFileDir(void){
................................................................................
  4604   4673         flags &= ~(SQLITE_OPEN_READWRITE|SQLITE_OPEN_CREATE);
  4605   4674         openFlags &= ~(O_RDWR|O_CREAT);
  4606   4675         flags |= SQLITE_OPEN_READONLY;
  4607   4676         openFlags |= O_RDONLY;
  4608   4677         fd = open(zName, openFlags, openMode);
  4609   4678       }
  4610   4679       if( fd<0 ){
  4611         -      rc = SQLITE_CANTOPEN_BKPT;
         4680  +      rc = unixLogError(SQLITE_CANTOPEN_BKPT, "open", zName);
  4612   4681         goto open_finished;
  4613   4682       }
  4614   4683     }
  4615   4684     assert( fd>=0 );
  4616   4685     if( pOutFlags ){
  4617   4686       *pOutFlags = flags;
  4618   4687     }
................................................................................
  4736   4805     const char *zPath,        /* Name of file to be deleted */
  4737   4806     int dirSync               /* If true, fsync() directory after deleting file */
  4738   4807   ){
  4739   4808     int rc = SQLITE_OK;
  4740   4809     UNUSED_PARAMETER(NotUsed);
  4741   4810     SimulateIOError(return SQLITE_IOERR_DELETE);
  4742   4811     if( unlink(zPath)==(-1) && errno!=ENOENT ){
  4743         -    return SQLITE_IOERR_DELETE;
         4812  +    return unixLogError(SQLITE_IOERR_DELETE, "unlink", zPath);
  4744   4813     }
  4745   4814   #ifndef SQLITE_DISABLE_DIRSYNC
  4746   4815     if( dirSync ){
  4747   4816       int fd;
  4748   4817       rc = openDirectory(zPath, &fd);
  4749   4818       if( rc==SQLITE_OK ){
  4750   4819   #if OS_VXWORKS
  4751   4820         if( fsync(fd)==-1 )
  4752   4821   #else
  4753   4822         if( fsync(fd) )
  4754   4823   #endif
  4755   4824         {
  4756         -        rc = SQLITE_IOERR_DIR_FSYNC;
         4825  +        rc = unixLogError(SQLITE_IOERR_DIR_FSYNC, "fsync", zPath);
  4757   4826         }
  4758   4827         if( close(fd)&&!rc ){
  4759         -        rc = SQLITE_IOERR_DIR_CLOSE;
         4828  +        rc = unixLogError(SQLITE_IOERR_DIR_CLOSE, "close", zPath);
  4760   4829         }
  4761   4830       }
  4762   4831     }
  4763   4832   #endif
  4764   4833     return rc;
  4765   4834   }
  4766   4835   
................................................................................
  4836   4905   
  4837   4906     zOut[nOut-1] = '\0';
  4838   4907     if( zPath[0]=='/' ){
  4839   4908       sqlite3_snprintf(nOut, zOut, "%s", zPath);
  4840   4909     }else{
  4841   4910       int nCwd;
  4842   4911       if( getcwd(zOut, nOut-1)==0 ){
  4843         -      return SQLITE_CANTOPEN_BKPT;
         4912  +      return unixLogError(SQLITE_CANTOPEN_BKPT, "getcwd", zPath);
  4844   4913       }
  4845   4914       nCwd = (int)strlen(zOut);
  4846   4915       sqlite3_snprintf(nOut-nCwd, &zOut[nCwd], "/%s", zPath);
  4847   4916     }
  4848   4917     return SQLITE_OK;
  4849   4918   }
  4850   4919   

Added test/oserror.test.

            1  +# 2011 February 19
            2  +#
            3  +# The author disclaims copyright to this source code.  In place of
            4  +# a legal notice, here is a blessing:
            5  +#
            6  +#    May you do good and not evil.
            7  +#    May you find forgiveness for yourself and forgive others.
            8  +#    May you share freely, never taking more than you give.
            9  +#
           10  +#***********************************************************************
           11  +# This file implements regression tests for SQLite library.  The
           12  +# focus of this file is testing that error messages are logged via the
           13  +# sqlite3_log() mechanism when certain errors are encountered in the
           14  +# default unix or windows VFS modules.
           15  +#
           16  +
           17  +set testdir [file dirname $argv0]
           18  +source $testdir/tester.tcl
           19  +if {$::tcl_platform(platform)!="unix"} { finish_test ; return }
           20  +set ::testprefix oserror
           21  +
           22  +db close
           23  +sqlite3_shutdown
           24  +test_sqlite3_log xLog
           25  +proc xLog {error_code msg} {
           26  +  if {[string match os_* $msg]} {
           27  +    lappend ::log $msg 
           28  +  }
           29  +}
           30  +
           31  +proc do_re_test {tn script expression} {
           32  +  uplevel do_test $tn [list [subst -nocommands {
           33  +    set res [eval { $script }]
           34  +    if {[regexp {$expression} [set res]]} {
           35  +      set {} {$expression}
           36  +    } else {
           37  +      set res
           38  +    }
           39  +  }]] [list $expression]
           40  +  
           41  +}
           42  +
           43  +#--------------------------------------------------------------------------
           44  +# Tests oserror-1.* test failures in the open() system call.
           45  +#
           46  +
           47  +# Test a failure in open() due to too many files.
           48  +#
           49  +do_test 1.1.1 {
           50  +  set ::log [list]
           51  +  list [catch {
           52  +    for {set i 0} {$i < 2000} {incr i} { sqlite3 dbh_$i test.db -readonly 1 }
           53  +  } msg] $msg
           54  +} {1 {unable to open database file}}
           55  +do_test 1.1.2 {
           56  +  catch { for {set i 0} {$i < 2000} {incr i} { dbh_$i close } }
           57  +} {1}
           58  +
           59  +do_re_test 1.1.3 { lindex $::log 0 } {^os_unix.c: open.*test.db$}
           60  +
           61  +
           62  +# Test a failure in open() due to the path being a directory.
           63  +#
           64  +do_test 1.2.1 {
           65  +  file mkdir dir.db
           66  +  set ::log [list]
           67  +  list [catch { sqlite3 dbh dir.db } msg] $msg
           68  +} {1 {unable to open database file}}
           69  +
           70  +do_re_test 1.2.2 { lindex $::log 0 } {^os_unix.c: open.*dir.db$}
           71  +
           72  +# Test a failure in open() due to the path not existing.
           73  +#
           74  +do_test 1.3.1 {
           75  +  set ::log [list]
           76  +  list [catch { sqlite3 dbh /x/y/z/test.db } msg] $msg
           77  +} {1 {unable to open database file}}
           78  +
           79  +do_re_test 1.3.2 { lindex $::log 0 } {^os_unix.c: open.*test.db$}
           80  +
           81  +# Test a failure in open() due to the path not existing.
           82  +#
           83  +do_test 1.4.1 {
           84  +  set ::log [list]
           85  +  list [catch { sqlite3 dbh /root/test.db } msg] $msg
           86  +} {1 {unable to open database file}}
           87  +
           88  +do_re_test 1.4.2 { lindex $::log 0 } {^os_unix.c: open.*test.db$}
           89  +
           90  +#--------------------------------------------------------------------------
           91  +# Tests oserror-1.* test failures in the unlink() system call.
           92  +#
           93  +do_test 2.1.1 {
           94  +  set ::log [list]
           95  +  file mkdir test.db-wal
           96  +  forcedelete test.db
           97  +  sqlite3 dbh test.db
           98  +  catchsql { SELECT * FROM sqlite_master } dbh
           99  +} {1 {disk I/O error}}
          100  +
          101  +do_re_test 2.1.2 { lindex $::log 0 } {^os_unix.c: unlink.*test.db-wal$}
          102  +do_test 2.1.3 { 
          103  +  dbh close
          104  +  forcedelete test.db-wal
          105  +} {}
          106  +  
          107  +
          108  +sqlite3_shutdown
          109  +test_sqlite3_log 
          110  +sqlite3_initialize
          111  +finish_test
          112  +