9 ms·

Bug #915: Please help

591 points by supakeen 7y ago

TAForObvReasons 7y ago
OT: After the lamentation of the "Github Monoculture", why was development of coveragepy moved from bitbucket to github? https://bitbucket.org/ned/coveragepy/src/default/ https://bitbucket.org/ned/coveragepy/src/default/ original project https://nedbatchelder.com/blog/201405/github_monoculture.html https://nedbatchelder.com/blog/201405/github_monoculture.htm... original post https://news.ycombinator.com/item?id=7690897 https://news.ycombinator.com/item?id=7690897 HN comments
- nedbat 7y ago
  If the monoculture were easy to resist, it wouldn't need lamentation. :)
- jakeogh 7y ago
  My blocker with bitbucket is it requires JS to use the web interface. Otherwise, blank page.
dmead 7y ago
hey, are you using docker on mac?
- nedbat 7y ago
  In my reproduction, yes. But the original failure was on Travis, which I doubt is using docker on mac.
contingencies 7y ago
Had an I/O issue in SQLite yesterday: the cause was a full disk, due to years of SQLite backups!
- DominoTree 7y ago
  The solution is clearly to restore a full system backup from a time that it had fewer SQLite backups :P
  - phkahler 7y ago
    But first back it up in the present state in case anything goes wrong.
x1798DE 7y ago
This is an editorialized title and as far as I know it's not even accurate. The author maintains, but did not create coverage.py. (Edit: Original title has been changed, so this comment is no longer necessary.)
- supakeen 7y ago
  I was unaware of that and it seems people have fixed the title for me. Thanks!
- jp_sc 7y ago
  Looking at the commit history, he is the author of almost all the code written in the last ten years. Even if there was someone before him (who was it? I couldn't find any reference to them), how could we not consider him the author of the project by now?
  - x1798DE 7y ago
    The original title made reference to Ned as the "creator of coveragepy", which specifically means the person who created it. The original author was Gareth Rees, according to Contributors.txt [1], and Ned Batchelder took over in 2004. I don't mean it to suggest that Ned has a lessor role than creator, just that the post's title was changed to add inaccurate information. I figured that if the moderators saw this and decided that the context of the author's role in Coverage was important, they could update the title to reflect his actual role. [1] https://github.com/nedbat/coveragepy/blob/master/CONTRIBUTORS.txt#L1 https://github.com/nedbat/coveragepy/blob/master/CONTRIBUTOR...
    - jp_sc 7y ago
      Sorry, I missed the obvious place to look into it.
  - mjw1007 7y ago
    It was Gareth Rees. https://garethrees.org/2001/12/04/python-coverage/ https://garethrees.org/2001/12/04/python-coverage/
pdq 7y ago
As mentioned on the Github issue [1], I'd suspect their SQLite optimizations: self.execute("pragma journal_mode=off").close() # This pragma makes writing faster. self.execute("pragma synchronous=off").close() I've always used WAL journaling mode, and NORMAL synchronous mode. [1] https://github.com/nedbat/coveragepy/issues/915 https://github.com/nedbat/coveragepy/issues/915
- nedbat 7y ago
  I have tried removing the two pragmas, and the problem still happens.
  - slovenlyrobot 7y ago
    For some reason Docker is struggling to download the image right now (lots of interested parties? :), I just wanted to trap writes to the database file and look at what's actually getting written there. Is there any possibility e.g. of an FD reuse issue in the code somewhere? It might even be possible to spot it with strace (although you need to start the container with the right caps to try that). An example where this can happen is programs closing 'stderr' fd 2, only for e.g. SQLite to open its database reusing fd 2, then some library code calls fprintf(stderr, ..) etc. Would love a copy of the DB 'sometime before' and after to look at. There are tools around for inspecting SQLite databases on a page-by-page basis
  - jsmith45 7y ago
    Neither of those make much sense as the cause anyway. Both sacrifice database consistency if the hosting process crashes or os crashes or reboots due to power failure, but with something like a coverage database, neither is particularly worrying. Worst case the users nukes the db, and reruns the tests. Even if removing those pragmas fixed things, it feels likely that would just be hiding the issue instead of fixing it. Disk io errors are not supposed to happen in sqlite except in cases like: accessing a corrupted database, drives failing or running out of disk space, bad permissions on some folder sqlite needs to write to. So unless the test case involves a python process crashing or getting killed, I question if this is actually a bug in your your code. I feel like this being some bug in either sqlite, or in the file systems used by docker (specifically by behaving in some manner not anticipated by sqlite). With those optimizations, the only remaining sqlite disk IO should be the database itself, and the temp store. Since I stronly suspect the error you are getting is coming from sqlite, it would be helpful to know which of those two disk io cases it is. Perhaps you can try the pragma to force the temp store to be in memory? The results of that might help us know if the disk io error is in reading/writing the database file itself, or if it is in reading/writing temp files. Knowing that could narrow things down a bit.
mmastrac 7y ago
There was a similar bug in unraid that they ended up fixing in 6.8.0 where it turned out that SQLite wasn't handling some sort of error condition in read-ahead I/O? I wonder if this is related. https://forums.unraid.net/bug-reports/prereleases/sqlite-data-corruption-testing-r664/?do=findComment&comment=6882 https://forums.unraid.net/bug-reports/prereleases/sqlite-dat... From that report: ====== 8< ====== > 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/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/raid5 driver. > In case of Unraid it can definitely happen under heavy load that a read-ahead comes along and there are no 'stripe buffers' immediately available. In this case, instead of making calling process wait, it terminated the I/O. This has worked this way for years. [...] > What I suspect is that this is a bug in SQLite - I think SQLite is using direct-I/O (bypassing page cache) and issuing it'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 :/ ====== 8< ====== Some related bugs they brought up: https://bugzilla.kernel.org/show_bug.cgi?id=201685 https://bugzilla.kernel.org/show_bug.cgi?id=201685 https://patchwork.kernel.org/patch/10712695/ https://patchwork.kernel.org/patch/10712695/ Edit: it appears that there's _something_ causing corruption when drivers fail read-ahead I/O. Whether it's SQLite or something else in Linux is another question.
- geofft 7y ago
  > I think SQLite is using direct-I/O (bypassing page cache) Should be pretty easy to confirm/deny that suspicion and see if it's worth going down the rabbit hole, no? strace -e open -o >(grep O_DIRECT) ./myprogram
  - lelf 7y ago
    -o >(grep O_DIRECT) This is cool. Never seen it (but it makes sense.)
    - mmastrac 7y ago
tyingq 7y ago
Unfortunately, the sqlite3 python interface doesn't expose Sqlite's extended error info so that you could see what's happening. https://bugs.python.org/issue16379 https://bugs.python.org/issue16379 There an uncommitted patch to get the extended error in this other, related issue: https://bugs.python.org/issue24139 https://bugs.python.org/issue24139 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: import ctypes import ctypes.util sqlite = ctypes.CDLL(ctypes.util.find_library('sqlite3'))
MaxBarraclough 7y ago
Can we please have an informative title? Bug #915: Please help tells me nothing.
- TwoNineFive 7y ago
  Whenever I come across a mailing list bug or a reddit post or similar with a "PLEASE HELP ME!" title I just auto-downvote/remove/delete it. I refer to them as "help-me zombies". They have no brains and they want to eat yours. They don't know what they need help with, but they need help.
- emmelaich 7y ago
  I knew from the domain name that it would be interesting; Ned Batchelder is no dummy.
  - rahuldottech 7y ago
    Sure, but many of us have know idea who they are, and an informative title really helps, even if you're familiar with the source.
- segfaultbuserr 7y ago
  The original title was something like "Ned Batchelder, the author of coverage.py, was asking for help on Bug #915", but it was against the guidelines, so the title was restored.
TheRealPomax 7y ago
Can someone suggest what the admins can turn this title into so it's not mystery meat (e.g. no idea what we're clicking through to, no idea whether the domain in question is ad-laden, etc).
- tyingq 7y ago
  Help: Unresolved SQLite I/O Error in coverage.py
nneonneo 7y ago
This doesn'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. strace log from the failure: open("/home/travis/apprise-api/.coverage", 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, "SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274"..., 100) = 100 write(3, "00001299 0001 6169 execute('prag"..., 54) = 54 write(3, "Executing 'pragma journal_mode=o"..., 36) = 36 write(3, "self: <SqliteDb @0x7fa0feef9fd0 "..., 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, "SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274"..., 1024) = 1024 lseek(31, 8192, SEEK_SET) = 8192 read(31, "\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"..., 1024) = 1024 lseek(31, 9216, SEEK_SET) = 9216 read(31, "\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"..., 1024) = 1024 lseek(31, 14336, SEEK_SET) = 14336 read(31, "\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"..., 1024) = 1024 fcntl(31, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 write(3, "00001299 0001 6169 execute retur"..., 76) = 76 write(3, "00001299 0001 6170 execute('prag"..., 53) = 53 write(3, "Executing 'pragma synchronous=of"..., 35) = 35 lseek(31, 0, SEEK_CUR) = 15360 close(31) = 0 write(3, "self: <SqliteDb @0x7fa0feef9fd0 "..., 86) = 86 write(3, "00001299 0001 6170 execute retur"..., 76) = 76 write(3, "00001299 0001 6168 _connect retu"..., 40) = 40 write(3, "00001299 0001 6167 __enter__ ret"..., 116) = 116 write(3, "00001299 0001 6171 execute('sele"..., 82) = 82 write(3, "Executing 'select tracer from tr"..., 68) = 68 write(3, "self: <SqliteDb @0x7fa0feef9fd0 "..., 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("/home/travis/apprise-api/.coverage", 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, "SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274"..., 4096) = 4096 close(31) = 0 write(3, "EXCEPTION from execute: disk I/O"..., 39) = 39 write(3, "self: <SqliteDb @0x7fa0feef9fd0 "..., 86) = 86 write(3, "00001299 0001 6172 __exit__(<cla"..., 208) = 208 write(3, "00001299 0001 6173 close()\n", 27) = 27 fstat(31, 0x7fff3bfa4220) = -1 EBADF (Bad file descriptor) close(31) = -1 EBADF (Bad file descriptor) Notice the close(31) right after the lseek. This close(31) is not generated by SQLite; rather, it's being generated by the GC finalization of an unrelated file object: #0 internal_close (self=<optimized out>) at ./Modules/_io/fileio.c:126 #1 _io_FileIO_close_impl (self=<optimized out>) at ./Modules/_io/fileio.c:171 #2 _io_FileIO_close (self=<optimized out>, _unused_ignored=<optimized out>) at ./Modules/_io/clinic/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/methodobject.c:192 #4 0x00007ffff791b89e in _PyObject_FastCallDict (func=func@entry=0x7fffeefaee58, args=args@entry=0x7fffffff7590, nargs=<optimized out>, kwargs=kwargs@entry=0x0) at Objects/abstract.c:2313 #5 0x00007ffff791c8a4 in PyObject_CallMethodObjArgs (callable=0x7fffeefaee58, name=<optimized out>) at Objects/abstract.c:2759 #6 0x00007ffff7a976b4 in buffered_close (self=0x7fffee02ae08, args=<optimized out>) at ./Modules/_io/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/methodobject.c:192 #8 0x00007ffff791b89e in _PyObject_FastCallDict (func=func@entry=0x7fffedf7eab0, args=args@entry=0x7fffffff77c0, nargs=<optimized out>, kwargs=kwargs@entry=0x0) at Objects/abstract.c:2313 #9 0x00007ffff791c8a4 in PyObject_CallMethodObjArgs (callable=0x7fffedf7eab0, callable@entry=0x7fffee02ae08, name=<optimized out>) at Objects/abstract.c:2759 #10 0x00007ffff7a90def in iobase_finalize (self=0x7fffee02ae08) at ./Modules/_io/iobase.c:266 #11 0x00007ffff7a59e4f in finalize_garbage (collectable=0x7fffffff7950) at Modules/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/gcmodule.c:1005 #13 0x00007ffff7a5a63b in collect_with_callback (generation=1) at Modules/gcmodule.c:1128 #14 0x00007ffff7a5ae8b in collect_generations () at Modules/gcmodule.c:1151 #15 _PyObject_GC_Alloc (basicsize=<optimized out>, use_calloc=0) at Modules/gcmodule.c:1729 #16 _PyObject_GC_Malloc (basicsize=<optimized out>) at Modules/gcmodule.c:1739 #17 0x00007ffff7a5afdd in _PyObject_GC_New (tp=tp@entry=0x7ffff7d53ea0 <PyGen_Type>) at Modules/gcmodule.c:1751 #18 0x00007ffff794766f in gen_new_with_qualname (qualname=0x7ffff4c1b450, name=0x7ffff4c218f0, f=0x7ffff292daf8, type=0x7ffff7d53ea0 <PyGen_Type>) at Objects/genobject.c:802 #19 PyGen_NewWithQualName (f=0x7ffff292daf8, name=0x7ffff4c218f0, qualname=0x7ffff4c1b450) at Objects/genobject.c:830 #20 0x00007ffff7a07f31 in _PyEval_EvalCodeWithName (_co=0x7ffff4c23270, globals=globals@entry=0x7ffff4cdd9d8, locals=locals@entry=0x0, args=<optimized out>, 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/ceval.c:4150 #21 0x00007ffff7a081d7 in fast_function (kwnames=0x0, nargs=<optimized out>, stack=<optimized out>, func=0x7fffedc03f28) at Python/ceval.c:4978 #22 call_function (pp_stack=pp_stack@entry=0x7fffffff7c60, oparg=oparg@entry=1, kwnames=kwnames@entry=0x0) at Python/ceval.c:4858 #23 0x00007ffff7a0a633 in _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3335 Note that normal SQLite3 closes look like this: #0 0x00007ffff769b560 in __close_nocancel () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007ffff3a23d8c in robust_close (lineno=29378, h=<optimized out>, 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=<optimized out>) at /tmp/python-build.20181021062245.3423/Python-3.6.7/Modules/_sqlite/connection.c:337 #10 0x00007ffff7975be7 in _PyCFunction_FastCallDict (func_obj=0x7fffedf7eab0, args=0x7fffede2e890, nargs=0, kwargs=kwargs@entry=0x0) at Objects/methodobject.c:192 #11 0x00007ffff7975eb7 in _PyCFunction_FastCallKeywords (func=func@entry=0x7fffedf7eab0, stack=stack@entry=0x7fffede2e890, nargs=<optimized out>, kwnames=kwnames@entry=0x0) at Objects/methodobject.c:294 #12 0x00007ffff7a082c1 in call_function (pp_stack=pp_stack@entry=0x7fffffff9640, oparg=oparg@entry=0, kwnames=kwnames@entry=0x0) at Python/ceval.c:4837 EDIT 1: OK, I found the line of code that allocates this file, at line 398 in apprise_api/api/views.py: with NamedTemporaryFile() as f: # Write our content to disk f.write(config.encode()) f.flush() If you disable this block of code everything runs fine (although the tests fail). It's kinda creepy that the NamedTemporaryFile is leaking - it really shouldn't...
mikewarot 7y ago
The fix is described at <a href="https://github.com/nedbat/coveragepy/commit/e4b8389b27ce4e7681788b8a28dc875ff4991739">.. https://github.com/nedbat/coveragepy/commit/e4b8389b27ce4e76.... it was simple, but elusive because of unsafe assumptions made in the name of performance. "Put the filename calc back in _connect. Fixes #916 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)."
mikewarot 7y ago
The fix was to undo a seemingly safe performance tweak... From https://github.com/nedbat/coveragepy/commit/e4b8389b27ce4e7681788b8a28dc875ff4991739 https://github.com/nedbat/coveragepy/commit/e4b8389b27ce4e76... "Put the filename calc back in _connect. Fixes #916 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)."
- herman_toothrot 7y ago
  This post is about issue #915 which seems unrelated/still open
carapace 7y ago
(Not helpful as such, but this reminds me of Mickens' "The Night Watch". > HAVE NO TOOLS BECAUSE I’VE DESTROYED MY TOOLS WITH MY TOOLS https://www.usenix.org/system/files/1311_05-08_mickens.pdf https://www.usenix.org/system/files/1311_05-08_mickens.pdf )

591 points by supakeen 7y ago

OT: After the lamentation of the "Github Monoculture", why was development of coveragepy moved from bitbucket to github? https://bitbucket.org/ned/coveragepy/src/default/ https://bitbucket.org/ned/coveragepy/src/default/ original project https://nedbatchelder.com/blog/201405/github_monoculture.html https://nedbatchelder.com/blog/201405/github_monoculture.htm... original post https://news.ycombinator.com/item?id=7690897 https://news.ycombinator.com/item?id=7690897 HN comments

nedbat 7y ago
If the monoculture were easy to resist, it wouldn't need lamentation. :)
jakeogh 7y ago
My blocker with bitbucket is it requires JS to use the web interface. Otherwise, blank page.

dmead 7y ago

hey, are you using docker on mac?

nedbat 7y ago
In my reproduction, yes. But the original failure was on Travis, which I doubt is using docker on mac.

contingencies 7y ago

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

DominoTree 7y ago
The solution is clearly to restore a full system backup from a time that it had fewer SQLite backups :P
- phkahler 7y ago
  But first back it up in the present state in case anything goes wrong.

x1798DE 7y ago

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

supakeen 7y ago
I was unaware of that and it seems people have fixed the title for me. Thanks!
jp_sc 7y ago
Looking at the commit history, he is the author of almost all the code written in the last ten years. Even if there was someone before him (who was it? I couldn't find any reference to them), how could we not consider him the author of the project by now?
- x1798DE 7y ago
  The original title made reference to Ned as the "creator of coveragepy", which specifically means the person who created it. The original author was Gareth Rees, according to Contributors.txt [1], and Ned Batchelder took over in 2004. I don't mean it to suggest that Ned has a lessor role than creator, just that the post's title was changed to add inaccurate information. I figured that if the moderators saw this and decided that the context of the author's role in Coverage was important, they could update the title to reflect his actual role. [1] https://github.com/nedbat/coveragepy/blob/master/CONTRIBUTORS.txt#L1 https://github.com/nedbat/coveragepy/blob/master/CONTRIBUTOR...
  - jp_sc 7y ago
    Sorry, I missed the obvious place to look into it.
- mjw1007 7y ago
  It was Gareth Rees. https://garethrees.org/2001/12/04/python-coverage/ https://garethrees.org/2001/12/04/python-coverage/

pdq 7y ago

As mentioned on the Github issue [1], I'd suspect their SQLite optimizations: self.execute("pragma journal_mode=off").close() # This pragma makes writing faster. self.execute("pragma synchronous=off").close() I've always used WAL journaling mode, and NORMAL synchronous mode. [1] https://github.com/nedbat/coveragepy/issues/915 https://github.com/nedbat/coveragepy/issues/915

nedbat 7y ago
I have tried removing the two pragmas, and the problem still happens.
- slovenlyrobot 7y ago
  For some reason Docker is struggling to download the image right now (lots of interested parties? :), I just wanted to trap writes to the database file and look at what's actually getting written there. Is there any possibility e.g. of an FD reuse issue in the code somewhere? It might even be possible to spot it with strace (although you need to start the container with the right caps to try that). An example where this can happen is programs closing 'stderr' fd 2, only for e.g. SQLite to open its database reusing fd 2, then some library code calls fprintf(stderr, ..) etc. Would love a copy of the DB 'sometime before' and after to look at. There are tools around for inspecting SQLite databases on a page-by-page basis
- jsmith45 7y ago
  Neither of those make much sense as the cause anyway. Both sacrifice database consistency if the hosting process crashes or os crashes or reboots due to power failure, but with something like a coverage database, neither is particularly worrying. Worst case the users nukes the db, and reruns the tests. Even if removing those pragmas fixed things, it feels likely that would just be hiding the issue instead of fixing it. Disk io errors are not supposed to happen in sqlite except in cases like: accessing a corrupted database, drives failing or running out of disk space, bad permissions on some folder sqlite needs to write to. So unless the test case involves a python process crashing or getting killed, I question if this is actually a bug in your your code. I feel like this being some bug in either sqlite, or in the file systems used by docker (specifically by behaving in some manner not anticipated by sqlite). With those optimizations, the only remaining sqlite disk IO should be the database itself, and the temp store. Since I stronly suspect the error you are getting is coming from sqlite, it would be helpful to know which of those two disk io cases it is. Perhaps you can try the pragma to force the temp store to be in memory? The results of that might help us know if the disk io error is in reading/writing the database file itself, or if it is in reading/writing temp files. Knowing that could narrow things down a bit.

mmastrac 7y ago

There was a similar bug in unraid that they ended up fixing in 6.8.0 where it turned out that SQLite wasn't handling some sort of error condition in read-ahead I/O? I wonder if this is related. https://forums.unraid.net/bug-reports/prereleases/sqlite-data-corruption-testing-r664/?do=findComment&comment=6882 https://forums.unraid.net/bug-reports/prereleases/sqlite-dat... From that report: ====== 8< ====== > 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/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/raid5 driver. > In case of Unraid it can definitely happen under heavy load that a read-ahead comes along and there are no 'stripe buffers' immediately available. In this case, instead of making calling process wait, it terminated the I/O. This has worked this way for years. [...] > What I suspect is that this is a bug in SQLite - I think SQLite is using direct-I/O (bypassing page cache) and issuing it'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 :/ ====== 8< ====== Some related bugs they brought up: https://bugzilla.kernel.org/show_bug.cgi?id=201685 https://bugzilla.kernel.org/show_bug.cgi?id=201685 https://patchwork.kernel.org/patch/10712695/ https://patchwork.kernel.org/patch/10712695/ Edit: it appears that there's _something_ causing corruption when drivers fail read-ahead I/O. Whether it's SQLite or something else in Linux is another question.

geofft 7y ago
> I think SQLite is using direct-I/O (bypassing page cache) Should be pretty easy to confirm/deny that suspicion and see if it's worth going down the rabbit hole, no? strace -e open -o >(grep O_DIRECT) ./myprogram
- lelf 7y ago
  -o >(grep O_DIRECT) This is cool. Never seen it (but it makes sense.)
  - mmastrac 7y ago

tyingq 7y ago

Unfortunately, the sqlite3 python interface doesn't expose Sqlite's extended error info so that you could see what's happening. https://bugs.python.org/issue16379 https://bugs.python.org/issue16379 There an uncommitted patch to get the extended error in this other, related issue: https://bugs.python.org/issue24139 https://bugs.python.org/issue24139 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: import ctypes import ctypes.util sqlite = ctypes.CDLL(ctypes.util.find_library('sqlite3'))

MaxBarraclough 7y ago

Can we please have an informative title? Bug #915: Please help tells me nothing.

TwoNineFive 7y ago
Whenever I come across a mailing list bug or a reddit post or similar with a "PLEASE HELP ME!" title I just auto-downvote/remove/delete it. I refer to them as "help-me zombies". They have no brains and they want to eat yours. They don't know what they need help with, but they need help.
emmelaich 7y ago
I knew from the domain name that it would be interesting; Ned Batchelder is no dummy.
- rahuldottech 7y ago
  Sure, but many of us have know idea who they are, and an informative title really helps, even if you're familiar with the source.
segfaultbuserr 7y ago
The original title was something like "Ned Batchelder, the author of coverage.py, was asking for help on Bug #915", but it was against the guidelines, so the title was restored.

TheRealPomax 7y ago

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

tyingq 7y ago
Help: Unresolved SQLite I/O Error in coverage.py

nneonneo 7y ago

This doesn'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. strace log from the failure: open("/home/travis/apprise-api/.coverage", 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, "SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274"..., 100) = 100 write(3, "00001299 0001 6169 execute('prag"..., 54) = 54 write(3, "Executing 'pragma journal_mode=o"..., 36) = 36 write(3, "self: <SqliteDb @0x7fa0feef9fd0 "..., 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, "SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274"..., 1024) = 1024 lseek(31, 8192, SEEK_SET) = 8192 read(31, "\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"..., 1024) = 1024 lseek(31, 9216, SEEK_SET) = 9216 read(31, "\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"..., 1024) = 1024 lseek(31, 14336, SEEK_SET) = 14336 read(31, "\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"..., 1024) = 1024 fcntl(31, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 write(3, "00001299 0001 6169 execute retur"..., 76) = 76 write(3, "00001299 0001 6170 execute('prag"..., 53) = 53 write(3, "Executing 'pragma synchronous=of"..., 35) = 35 lseek(31, 0, SEEK_CUR) = 15360 close(31) = 0 write(3, "self: <SqliteDb @0x7fa0feef9fd0 "..., 86) = 86 write(3, "00001299 0001 6170 execute retur"..., 76) = 76 write(3, "00001299 0001 6168 _connect retu"..., 40) = 40 write(3, "00001299 0001 6167 __enter__ ret"..., 116) = 116 write(3, "00001299 0001 6171 execute('sele"..., 82) = 82 write(3, "Executing 'select tracer from tr"..., 68) = 68 write(3, "self: <SqliteDb @0x7fa0feef9fd0 "..., 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("/home/travis/apprise-api/.coverage", 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, "SQLite format 3\0\4\0\1\1\0@ \0\0\0\n\0\0\0\274"..., 4096) = 4096 close(31) = 0 write(3, "EXCEPTION from execute: disk I/O"..., 39) = 39 write(3, "self: <SqliteDb @0x7fa0feef9fd0 "..., 86) = 86 write(3, "00001299 0001 6172 __exit__(<cla"..., 208) = 208 write(3, "00001299 0001 6173 close()\n", 27) = 27 fstat(31, 0x7fff3bfa4220) = -1 EBADF (Bad file descriptor) close(31) = -1 EBADF (Bad file descriptor) Notice the close(31) right after the lseek. This close(31) is not generated by SQLite; rather, it's being generated by the GC finalization of an unrelated file object: #0 internal_close (self=<optimized out>) at ./Modules/_io/fileio.c:126 #1 _io_FileIO_close_impl (self=<optimized out>) at ./Modules/_io/fileio.c:171 #2 _io_FileIO_close (self=<optimized out>, _unused_ignored=<optimized out>) at ./Modules/_io/clinic/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/methodobject.c:192 #4 0x00007ffff791b89e in _PyObject_FastCallDict (func=func@entry=0x7fffeefaee58, args=args@entry=0x7fffffff7590, nargs=<optimized out>, kwargs=kwargs@entry=0x0) at Objects/abstract.c:2313 #5 0x00007ffff791c8a4 in PyObject_CallMethodObjArgs (callable=0x7fffeefaee58, name=<optimized out>) at Objects/abstract.c:2759 #6 0x00007ffff7a976b4 in buffered_close (self=0x7fffee02ae08, args=<optimized out>) at ./Modules/_io/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/methodobject.c:192 #8 0x00007ffff791b89e in _PyObject_FastCallDict (func=func@entry=0x7fffedf7eab0, args=args@entry=0x7fffffff77c0, nargs=<optimized out>, kwargs=kwargs@entry=0x0) at Objects/abstract.c:2313 #9 0x00007ffff791c8a4 in PyObject_CallMethodObjArgs (callable=0x7fffedf7eab0, callable@entry=0x7fffee02ae08, name=<optimized out>) at Objects/abstract.c:2759 #10 0x00007ffff7a90def in iobase_finalize (self=0x7fffee02ae08) at ./Modules/_io/iobase.c:266 #11 0x00007ffff7a59e4f in finalize_garbage (collectable=0x7fffffff7950) at Modules/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/gcmodule.c:1005 #13 0x00007ffff7a5a63b in collect_with_callback (generation=1) at Modules/gcmodule.c:1128 #14 0x00007ffff7a5ae8b in collect_generations () at Modules/gcmodule.c:1151 #15 _PyObject_GC_Alloc (basicsize=<optimized out>, use_calloc=0) at Modules/gcmodule.c:1729 #16 _PyObject_GC_Malloc (basicsize=<optimized out>) at Modules/gcmodule.c:1739 #17 0x00007ffff7a5afdd in _PyObject_GC_New (tp=tp@entry=0x7ffff7d53ea0 <PyGen_Type>) at Modules/gcmodule.c:1751 #18 0x00007ffff794766f in gen_new_with_qualname (qualname=0x7ffff4c1b450, name=0x7ffff4c218f0, f=0x7ffff292daf8, type=0x7ffff7d53ea0 <PyGen_Type>) at Objects/genobject.c:802 #19 PyGen_NewWithQualName (f=0x7ffff292daf8, name=0x7ffff4c218f0, qualname=0x7ffff4c1b450) at Objects/genobject.c:830 #20 0x00007ffff7a07f31 in _PyEval_EvalCodeWithName (_co=0x7ffff4c23270, globals=globals@entry=0x7ffff4cdd9d8, locals=locals@entry=0x0, args=<optimized out>, 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/ceval.c:4150 #21 0x00007ffff7a081d7 in fast_function (kwnames=0x0, nargs=<optimized out>, stack=<optimized out>, func=0x7fffedc03f28) at Python/ceval.c:4978 #22 call_function (pp_stack=pp_stack@entry=0x7fffffff7c60, oparg=oparg@entry=1, kwnames=kwnames@entry=0x0) at Python/ceval.c:4858 #23 0x00007ffff7a0a633 in _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized out>) at Python/ceval.c:3335 Note that normal SQLite3 closes look like this: #0 0x00007ffff769b560 in __close_nocancel () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007ffff3a23d8c in robust_close (lineno=29378, h=<optimized out>, 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=<optimized out>) at /tmp/python-build.20181021062245.3423/Python-3.6.7/Modules/_sqlite/connection.c:337 #10 0x00007ffff7975be7 in _PyCFunction_FastCallDict (func_obj=0x7fffedf7eab0, args=0x7fffede2e890, nargs=0, kwargs=kwargs@entry=0x0) at Objects/methodobject.c:192 #11 0x00007ffff7975eb7 in _PyCFunction_FastCallKeywords (func=func@entry=0x7fffedf7eab0, stack=stack@entry=0x7fffede2e890, nargs=<optimized out>, kwnames=kwnames@entry=0x0) at Objects/methodobject.c:294 #12 0x00007ffff7a082c1 in call_function (pp_stack=pp_stack@entry=0x7fffffff9640, oparg=oparg@entry=0, kwnames=kwnames@entry=0x0) at Python/ceval.c:4837 EDIT 1: OK, I found the line of code that allocates this file, at line 398 in apprise_api/api/views.py: with NamedTemporaryFile() as f: # Write our content to disk f.write(config.encode()) f.flush() If you disable this block of code everything runs fine (although the tests fail). It's kinda creepy that the NamedTemporaryFile is leaking - it really shouldn't...

mikewarot 7y ago

The fix is described at <a href="https://github.com/nedbat/coveragepy/commit/e4b8389b27ce4e7681788b8a28dc875ff4991739">.. https://github.com/nedbat/coveragepy/commit/e4b8389b27ce4e76.... it was simple, but elusive because of unsafe assumptions made in the name of performance. "Put the filename calc back in _connect. Fixes #916 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)."

mikewarot 7y ago

The fix was to undo a seemingly safe performance tweak... From https://github.com/nedbat/coveragepy/commit/e4b8389b27ce4e7681788b8a28dc875ff4991739 https://github.com/nedbat/coveragepy/commit/e4b8389b27ce4e76... "Put the filename calc back in _connect. Fixes #916 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)."

herman_toothrot 7y ago
This post is about issue #915 which seems unrelated/still open

carapace 7y ago

(Not helpful as such, but this reminds me of Mickens' "The Night Watch". > HAVE NO TOOLS BECAUSE I’VE DESTROYED MY TOOLS WITH MY TOOLS https://www.usenix.org/system/files/1311_05-08_mickens.pdf https://www.usenix.org/system/files/1311_05-08_mickens.pdf )