Bug #915: Please help

This doesn&#x27;t quite get all the way there, but the failure is being caused by the closure of a _io.FileIO due to GC, which happens to have the same fd as the sqlite database. The closure happens in the middle of a SQLite operation, which causes a subsequent flock() call to fail.<p>strace log from the failure:<p><pre><code> open(&quot;&#x2F;home&#x2F;travis&#x2F;apprise-api&#x2F;.coverage&quot;, O_RDWR|O_CREAT|O_CLOEXEC, 0644) = 31 fstat(31, {st_mode=S_IFREG|0644, st_size=192512, ...}) = 0 fstat(31, {st_mode=S_IFREG|0644, st_size=192512, ...}) = 0 lseek(31, 0, SEEK_SET) = 0 read(31, &quot;SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274&quot;..., 100) = 100 write(3, &quot;00001299 0001 6169 execute(&#x27;prag&quot;..., 54) = 54 write(3, &quot;Executing &#x27;pragma journal_mode=o&quot;..., 36) = 36 write(3, &quot;self: &lt;SqliteDb @0x7fa0feef9fd0 &quot;..., 86) = 86 fcntl(31, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=1073741824, l_len=1}) = 0 fcntl(31, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=1073741826, l_len=510}) = 0 fcntl(31, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=1073741824, l_len=1}) = 0 fstat(31, {st_mode=S_IFREG|0644, st_size=192512, ...}) = 0 fstat(31, {st_mode=S_IFREG|0644, st_size=192512, ...}) = 0 lseek(31, 0, SEEK_SET) = 0 read(31, &quot;SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274&quot;..., 1024) = 1024 lseek(31, 8192, SEEK_SET) = 8192 read(31, &quot;\r\3-\0\4\0\316\0\3^\1X\0035\0\316\0\245\0v\0v\0\0\0\0\0\0\0\0\0\0&quot;..., 1024) = 1024 lseek(31, 9216, SEEK_SET) = 9216 read(31, &quot;\r\0\0\0\4\0\370\0\0\370\3d\0035\1!\0\277\0\277\2\36\0\0\0\0\0\0\0\0\0\0&quot;..., 1024) = 1024 lseek(31, 14336, SEEK_SET) = 14336 read(31, &quot;\r\0\0\0\4\0\320\0\3\315\1\313\1\244\0\320\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0&quot;..., 1024) = 1024 fcntl(31, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 write(3, &quot;00001299 0001 6169 execute retur&quot;..., 76) = 76 write(3, &quot;00001299 0001 6170 execute(&#x27;prag&quot;..., 53) = 53 write(3, &quot;Executing &#x27;pragma synchronous=of&quot;..., 35) = 35 lseek(31, 0, SEEK_CUR) = 15360 close(31) = 0 write(3, &quot;self: &lt;SqliteDb @0x7fa0feef9fd0 &quot;..., 86) = 86 write(3, &quot;00001299 0001 6170 execute retur&quot;..., 76) = 76 write(3, &quot;00001299 0001 6168 _connect retu&quot;..., 40) = 40 write(3, &quot;00001299 0001 6167 __enter__ ret&quot;..., 116) = 116 write(3, &quot;00001299 0001 6171 execute(&#x27;sele&quot;..., 82) = 82 write(3, &quot;Executing &#x27;select tracer from tr&quot;..., 68) = 68 write(3, &quot;self: &lt;SqliteDb @0x7fa0feef9fd0 &quot;..., 86) = 86 fcntl(31, F_SETLK, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=1073741824, l_len=1}) = -1 EBADF (Bad file descriptor) open(&quot;&#x2F;home&#x2F;travis&#x2F;apprise-api&#x2F;.coverage&quot;, O_RDONLY|O_CLOEXEC) = 31 fstat(31, {st_mode=S_IFREG|0644, st_size=192512, ...}) = 0 ioctl(31, TCGETS, 0x7fff3bfa4920) = -1 ENOTTY (Inappropriate ioctl for device) lseek(31, 0, SEEK_CUR) = 0 read(31, &quot;SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274&quot;..., 4096) = 4096 close(31) = 0 write(3, &quot;EXCEPTION from execute: disk I&#x2F;O&quot;..., 39) = 39 write(3, &quot;self: &lt;SqliteDb @0x7fa0feef9fd0 &quot;..., 86) = 86 write(3, &quot;00001299 0001 6172 __exit__(&lt;cla&quot;..., 208) = 208 write(3, &quot;00001299 0001 6173 close()\n&quot;, 27) = 27 fstat(31, 0x7fff3bfa4220) = -1 EBADF (Bad file descriptor) close(31) = -1 EBADF (Bad file descriptor) </code></pre> Notice the close(31) right after the lseek. This close(31) is not generated by SQLite; rather, it&#x27;s being generated by the GC finalization of an unrelated file object:<p><pre><code> #0 internal_close (self=&lt;optimized out&gt;) at .&#x2F;Modules&#x2F;_io&#x2F;fileio.c:126 #1 _io_FileIO_close_impl (self=&lt;optimized out&gt;) at .&#x2F;Modules&#x2F;_io&#x2F;fileio.c:171 #2 _io_FileIO_close (self=&lt;optimized out&gt;, _unused_ignored=&lt;optimized out&gt;) at .&#x2F;Modules&#x2F;_io&#x2F;clinic&#x2F;fileio.c.h:23 #3 0x00007ffff7975be7 in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7fffeefaee58, args=args@entry=0x7fffffff7590, nargs=0, kwargs=kwargs@entry=0x0) at Objects&#x2F;methodobject.c:192 #4 0x00007ffff791b89e in _PyObject_FastCallDict (func=func@entry=0x7fffeefaee58, args=args@entry=0x7fffffff7590, nargs=&lt;optimized out&gt;, kwargs=kwargs@entry=0x0) at Objects&#x2F;abstract.c:2313 #5 0x00007ffff791c8a4 in PyObject_CallMethodObjArgs (callable=0x7fffeefaee58, name=&lt;optimized out&gt;) at Objects&#x2F;abstract.c:2759 #6 0x00007ffff7a976b4 in buffered_close (self=0x7fffee02ae08, args=&lt;optimized out&gt;) at .&#x2F;Modules&#x2F;_io&#x2F;bufferedio.c:538 #7 0x00007ffff7975be7 in _PyCFunction_FastCallDict (func_obj=func_obj@entry=0x7fffedf7eab0, args=args@entry=0x7fffffff77c0, nargs=0, kwargs=kwargs@entry=0x0) at Objects&#x2F;methodobject.c:192 #8 0x00007ffff791b89e in _PyObject_FastCallDict (func=func@entry=0x7fffedf7eab0, args=args@entry=0x7fffffff77c0, nargs=&lt;optimized out&gt;, kwargs=kwargs@entry=0x0) at Objects&#x2F;abstract.c:2313 #9 0x00007ffff791c8a4 in PyObject_CallMethodObjArgs (callable=0x7fffedf7eab0, callable@entry=0x7fffee02ae08, name=&lt;optimized out&gt;) at Objects&#x2F;abstract.c:2759 #10 0x00007ffff7a90def in iobase_finalize (self=0x7fffee02ae08) at .&#x2F;Modules&#x2F;_io&#x2F;iobase.c:266 #11 0x00007ffff7a59e4f in finalize_garbage (collectable=0x7fffffff7950) at Modules&#x2F;gcmodule.c:806 #12 collect (generation=generation@entry=1, n_collected=n_collected@entry=0x7fffffff79f0, n_uncollectable=n_uncollectable@entry=0x7fffffff79f8, nofail=nofail@entry=0) at Modules&#x2F;gcmodule.c:1005 #13 0x00007ffff7a5a63b in collect_with_callback (generation=1) at Modules&#x2F;gcmodule.c:1128 #14 0x00007ffff7a5ae8b in collect_generations () at Modules&#x2F;gcmodule.c:1151 #15 _PyObject_GC_Alloc (basicsize=&lt;optimized out&gt;, use_calloc=0) at Modules&#x2F;gcmodule.c:1729 #16 _PyObject_GC_Malloc (basicsize=&lt;optimized out&gt;) at Modules&#x2F;gcmodule.c:1739 #17 0x00007ffff7a5afdd in _PyObject_GC_New (tp=tp@entry=0x7ffff7d53ea0 &lt;PyGen_Type&gt;) at Modules&#x2F;gcmodule.c:1751 #18 0x00007ffff794766f in gen_new_with_qualname (qualname=0x7ffff4c1b450, name=0x7ffff4c218f0, f=0x7ffff292daf8, type=0x7ffff7d53ea0 &lt;PyGen_Type&gt;) at Objects&#x2F;genobject.c:802 #19 PyGen_NewWithQualName (f=0x7ffff292daf8, name=0x7ffff4c218f0, qualname=0x7ffff4c1b450) at Objects&#x2F;genobject.c:830 #20 0x00007ffff7a07f31 in _PyEval_EvalCodeWithName (_co=0x7ffff4c23270, globals=globals@entry=0x7ffff4cdd9d8, locals=locals@entry=0x0, args=&lt;optimized out&gt;, argcount=1, kwnames=kwnames@entry=0x0, kwargs=0x7ffff4c32930, kwcount=0, kwstep=1, defs=0x0, defcount=0, kwdefs=0x0, closure=0x7fffede2cfd0, name=0x7ffff4c218f0, qualname=0x7ffff4c1b450) at Python&#x2F;ceval.c:4150 #21 0x00007ffff7a081d7 in fast_function (kwnames=0x0, nargs=&lt;optimized out&gt;, stack=&lt;optimized out&gt;, func=0x7fffedc03f28) at Python&#x2F;ceval.c:4978 #22 call_function (pp_stack=pp_stack@entry=0x7fffffff7c60, oparg=oparg@entry=1, kwnames=kwnames@entry=0x0) at Python&#x2F;ceval.c:4858 #23 0x00007ffff7a0a633 in _PyEval_EvalFrameDefault (f=&lt;optimized out&gt;, throwflag=&lt;optimized out&gt;) at Python&#x2F;ceval.c:3335 </code></pre> Note that normal SQLite3 closes look like this:<p><pre><code> #0 0x00007ffff769b560 in __close_nocancel () from &#x2F;lib&#x2F;x86_64-linux-gnu&#x2F;libpthread.so.0 #1 0x00007ffff3a23d8c in robust_close (lineno=29378, h=&lt;optimized out&gt;, pFile=0x113cfd8) at sqlite3.c:28631 #2 closeUnixFile (id=id@entry=0x113cfd8) at sqlite3.c:29378 #3 0x00007ffff3a24f43 in unixClose (id=0x113cfd8) at sqlite3.c:29427 #4 0x00007ffff3a4858b in sqlite3OsClose (pId=0x113cfd8) at sqlite3.c:17944 #5 sqlite3PagerClose (pPager=0x113ce68) at sqlite3.c:47961 #6 0x00007ffff3a5930b in sqlite3BtreeClose (p=0xfb8088) at sqlite3.c:58266 #7 0x00007ffff3a59501 in sqlite3LeaveMutexAndCloseZombie (db=0x1260598) at sqlite3.c:134102 #8 0x00007ffff3a59ae2 in sqlite3Close (db=0x1260598, forceZombie=0) at sqlite3.c:134045 #9 0x00007ffff3cc8fe2 in pysqlite_connection_close (self=0x7fffedf5fd50, args=&lt;optimized out&gt;) at &#x2F;tmp&#x2F;python-build.20181021062245.3423&#x2F;Python-3.6.7&#x2F;Modules&#x2F;_sqlite&#x2F;connection.c:337 #10 0x00007ffff7975be7 in _PyCFunction_FastCallDict (func_obj=0x7fffedf7eab0, args=0x7fffede2e890, nargs=0, kwargs=kwargs@entry=0x0) at Objects&#x2F;methodobject.c:192 #11 0x00007ffff7975eb7 in _PyCFunction_FastCallKeywords (func=func@entry=0x7fffedf7eab0, stack=stack@entry=0x7fffede2e890, nargs=&lt;optimized out&gt;, kwnames=kwnames@entry=0x0) at Objects&#x2F;methodobject.c:294 #12 0x00007ffff7a082c1 in call_function (pp_stack=pp_stack@entry=0x7fffffff9640, oparg=oparg@entry=0, kwnames=kwnames@entry=0x0) at Python&#x2F;ceval.c:4837 </code></pre> EDIT 1: OK, I found the line of code that allocates this file, at line 398 in apprise_api&#x2F;api&#x2F;views.py:<p><pre><code> with NamedTemporaryFile() as f: # Write our content to disk f.write(config.encode()) f.flush() </code></pre> If you disable this block of code everything runs fine (although the tests fail). It&#x27;s kinda creepy that the NamedTemporaryFile is leaking - it really shouldn&#x27;t...

There was a similar bug in unraid that they ended up fixing in 6.8.0 where it turned out that SQLite wasn&#x27;t handling some sort of error condition in read-ahead I&#x2F;O? I wonder if this is related.<p><a href="https:&#x2F;&#x2F;forums.unraid.net&#x2F;bug-reports&#x2F;prereleases&#x2F;sqlite-data-corruption-testing-r664&#x2F;?do=findComment&amp;comment=6882" rel="nofollow">https:&#x2F;&#x2F;forums.unraid.net&#x2F;bug-reports&#x2F;prereleases&#x2F;sqlite-dat...</a><p>From that report:<p>====== 8&lt; ======<p>&gt; In the Linux block layer each READ or WRITE can have various modifier bits set. In the case of a read-ahead you get READ|REQ_RAHEAD which tells I&#x2F;O driver this is a read-ahead. In this case, if there are insufficient resources at the time this request is received, the driver is permitted to terminate the operation with BLK_STS_IOERR status. Here is an example in Linux md&#x2F;raid5 driver.<p>&gt; In case of Unraid it can definitely happen under heavy load that a read-ahead comes along and there are no &#x27;stripe buffers&#x27; immediately available. In this case, instead of making calling process wait, it terminated the I&#x2F;O. This has worked this way for years.<p>[...]<p>&gt; What I suspect is that this is a bug in SQLite - I think SQLite is using direct-I&#x2F;O (bypassing page cache) and issuing it&#x27;s own read-aheads and their logic to handle failing read-ahead is broken. But I did not follow that rabbit hole - too many other problems to work on :&#x2F;<p>====== 8&lt; ======<p>Some related bugs they brought up:<p><a href="https:&#x2F;&#x2F;bugzilla.kernel.org&#x2F;show_bug.cgi?id=201685" rel="nofollow">https:&#x2F;&#x2F;bugzilla.kernel.org&#x2F;show_bug.cgi?id=201685</a><p><a href="https:&#x2F;&#x2F;patchwork.kernel.org&#x2F;patch&#x2F;10712695&#x2F;" rel="nofollow">https:&#x2F;&#x2F;patchwork.kernel.org&#x2F;patch&#x2F;10712695&#x2F;</a><p>Edit: it appears that there&#x27;s _something_ causing corruption when drivers fail read-ahead I&#x2F;O. Whether it&#x27;s SQLite or something else in Linux is another question.

Unfortunately, the sqlite3 python interface doesn&#x27;t expose Sqlite&#x27;s extended error info so that you could see what&#x27;s happening.<p><a href="https:&#x2F;&#x2F;bugs.python.org&#x2F;issue16379" rel="nofollow">https:&#x2F;&#x2F;bugs.python.org&#x2F;issue16379</a><p>There an uncommitted patch to get the extended error in this other, related issue: <a href="https:&#x2F;&#x2F;bugs.python.org&#x2F;issue24139" rel="nofollow">https:&#x2F;&#x2F;bugs.python.org&#x2F;issue24139</a><p>Or maybe just try cffi or ctypes in python to call sqlite3_errcode(), sqlite3_extended_errcode() and sqlite3_errmsg(). The incantation to find an already linked sqlite3 lib:<p>import ctypes<p>import ctypes.util<p>sqlite = ctypes.CDLL(ctypes.util.find_library(&#x27;sqlite3&#x27;))

As mentioned on the Github issue [1], I&#x27;d suspect their SQLite optimizations:<p><pre><code> self.execute(&quot;pragma journal_mode=off&quot;).close() # This pragma makes writing faster. self.execute(&quot;pragma synchronous=off&quot;).close() </code></pre> I&#x27;ve always used WAL journaling mode, and NORMAL synchronous mode.<p>[1] <a href="https:&#x2F;&#x2F;github.com&#x2F;nedbat&#x2F;coveragepy&#x2F;issues&#x2F;915" rel="nofollow">https:&#x2F;&#x2F;github.com&#x2F;nedbat&#x2F;coveragepy&#x2F;issues&#x2F;915</a>

Can we please have an informative title?<p><i>Bug #915: Please help</i> tells me nothing.

Can someone suggest what the admins can turn this title into so it&#x27;s not mystery meat (e.g. no idea what we&#x27;re clicking through to, no idea whether the domain in question is ad-laden, etc).

Had an I&#x2F;O issue in SQLite yesterday: the cause was a full disk, due to years of SQLite backups!

The fix was to undo a seemingly safe performance tweak...<p>From <a href="https:&#x2F;&#x2F;github.com&#x2F;nedbat&#x2F;coveragepy&#x2F;commit&#x2F;e4b8389b27ce4e7681788b8a28dc875ff4991739" rel="nofollow">https:&#x2F;&#x2F;github.com&#x2F;nedbat&#x2F;coveragepy&#x2F;commit&#x2F;e4b8389b27ce4e76...</a><p>&quot;Put the filename calc back in _connect. Fixes #916<p>It was moved to __init__ to avoid recalculating, but the directory could have changed, so we need to wait to do the work. Instead, only do the relpath on systems that need it (Windows Py 2).&quot;

This is an editorialized title and as far as I know it&#x27;s not even accurate. The author maintains, but did not create coverage.py.<p>(Edit: Original title has been changed, so this comment is no longer necessary.)

hey, are you using docker on mac?

(Not helpful as such, but this reminds me of Mickens&#x27; &quot;The Night Watch&quot;.<p>&gt; HAVE NO TOOLS BECAUSE I’VE DESTROYED MY TOOLS WITH MY TOOLS<p><a href="https:&#x2F;&#x2F;www.usenix.org&#x2F;system&#x2F;files&#x2F;1311_05-08_mickens.pdf" rel="nofollow">https:&#x2F;&#x2F;www.usenix.org&#x2F;system&#x2F;files&#x2F;1311_05-08_mickens.pdf</a> )

The fix is described at &lt;a href=&quot;<a href="https:&#x2F;&#x2F;github.com&#x2F;nedbat&#x2F;coveragepy&#x2F;commit&#x2F;e4b8389b27ce4e7681788b8a28dc875ff4991739&quot;&gt;.." rel="nofollow">https:&#x2F;&#x2F;github.com&#x2F;nedbat&#x2F;coveragepy&#x2F;commit&#x2F;e4b8389b27ce4e76...</a>. it was simple, but elusive because of unsafe assumptions made in the name of performance.<p>&quot;Put the filename calc back in _connect. Fixes #916<p>It was moved to __init__ to avoid recalculating, but the directory could have changed, so we need to wait to do the work. Instead, only do the relpath on systems that need it (Windows Py 2).&quot;

OT: After the lamentation of the &quot;Github Monoculture&quot;, why was development of coveragepy moved from bitbucket to github?<p><a href="https:&#x2F;&#x2F;bitbucket.org&#x2F;ned&#x2F;coveragepy&#x2F;src&#x2F;default&#x2F;" rel="nofollow">https:&#x2F;&#x2F;bitbucket.org&#x2F;ned&#x2F;coveragepy&#x2F;src&#x2F;default&#x2F;</a> original project <a href="https:&#x2F;&#x2F;nedbatchelder.com&#x2F;blog&#x2F;201405&#x2F;github_monoculture.html" rel="nofollow">https:&#x2F;&#x2F;nedbatchelder.com&#x2F;blog&#x2F;201405&#x2F;github_monoculture.htm...</a> original post <a href="https:&#x2F;&#x2F;news.ycombinator.com&#x2F;item?id=7690897" rel="nofollow">https:&#x2F;&#x2F;news.ycombinator.com&#x2F;item?id=7690897</a> HN comments