Coveragepy: SQLite error: "Error binding parameter 0 - probably unsupported type" (PyPy related?)

[blueyed]

The following error happened with Python 3.6.9[pypy-7.3.1-final].

If I remember correctly I've seen this before (likely also with PyPy so it
might be a (compatibility) issue there), but it is not reproducible easily
(i.e. depends on some randomness somewhere, but e.g. pytest-xdist / parallel
execution is not involved here).

Traceback (most recent call last):
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/bin/coverage", line 8, in <module>
    sys.exit(main())
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/cmdline.py", line 865, in main
    status = CoverageScript().command_line(argv)
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/cmdline.py", line 582, in command_line
    return self.do_run(options, args)
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/cmdline.py", line 747, in do_run
    self.coverage.save()
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/control.py", line 651, in save
    data = self.get_data()
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/control.py", line 705, in get_data
    if self._collector and self._collector.flush_data():
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/collector.py", line 423, in flush_data
    self.covdata.add_arcs(self.mapped_file_dict(self.data))
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/sqldata.py", line 480, in add_arcs
    data,
  File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/sqldata.py", line 1089, in executemany
    return self.con.executemany(sql, data)
  File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 423, in executemany
    return cur.executemany(*args)
  File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 773, in wrapper
    return func(self, *args, **kwargs)
  File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 938, in executemany
    return self.__execute(True, sql, many_params)
  File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 889, in __execute
    self.__statement._set_params(params)
  File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 1180, in _set_params
    "probably unsupported type." % i)
_sqlite3.InterfaceError: Error binding parameter 0 - probably unsupported type.

(Relevant) build log snippet:

2020-07-10T12:02:21.1241557Z ##[group]Run tox -e pypy3-coverage
2020-07-10T12:02:21.1241784Z  tox -e pypy3-coverage
2020-07-10T12:02:21.1283065Z shell: /bin/bash -e {0}
2020-07-10T12:02:21.1283288Z env:
2020-07-10T12:02:21.1283409Z   pythonLocation: /opt/hostedtoolcache/PyPy/3.6.9/x64/bin
2020-07-10T12:02:21.1283544Z   PY_CACHE_KEY: a7b50a511a2559972db1d08dcdfb271afef80b32fea9877f227b24b0046b1cbc
2020-07-10T12:02:21.1283683Z   PYTEST_ADDOPTS: -ra --durations=50 -m 'pypy_specific or acceptance_tests'
2020-07-10T12:02:21.1283790Z   COLUMNS: 120
2020-07-10T12:02:21.1283899Z ##[endgroup]
2020-07-10T12:02:23.2514091Z Using /home/runner/work/pytest/pytest/.tox/.package/bin/python (3.6.9 (2ad108f17bdb, Apr 07 2020, 02:59:05)).
2020-07-10T12:02:26.4351047Z Using /home/runner/work/pytest/pytest/.tox/pypy3-coverage/bin/python (3.6.9 (2ad108f17bdb, Apr 07 2020, 02:59:05)).
2020-07-10T12:02:26.4411333Z pypy3-coverage inst-nodeps: /home/runner/work/pytest/pytest/.tox/.tmp/package/1/pytest-5.2.3.dev1473+gebe4a61e1.tar.gz
2020-07-10T12:03:05.2452703Z pypy3-coverage installed: argcomplete==1.11.1,attrs==19.3.0,certifi==2020.6.20,cffi==1.14.0,chardet==3.0.4,coverage==5.2,coverage-enable-subprocess==1.0,elementpath==1.4.6,greenlet==0.4.13,idna==2.10,importlib-metadata==1.7.0,mock==4.0.2,more-itertools==8.4.0,nose==1.3.7,packaging==20.4,pluggy==0.13.1,py==1.8.1,pyparsing==2.4.7,pytest @ file:///home/runner/work/pytest/pytest/.tox/.tmp/package/1/pytest-5.2.3.dev1473%2Bgebe4a61e1.tar.gz,readline==6.2.4.1,requests==2.24.0,six==1.15.0,urllib3==1.25.9,wcwidth==0.2.5,xmlschema==1.2.2,zipp==3.1.0
2020-07-10T12:03:05.2462774Z pypy3-coverage run-test-pre: PYTHONHASHSEED='4253141730'
2020-07-10T12:03:05.2465149Z pypy3-coverage run-test: commands[0] | coverage run -m pytest
2020-07-10T12:03:09.4893852Z ================================================= test session starts ==================================================
2020-07-10T12:03:09.4913368Z platform linux -- Python 3.6.9[pypy-7.3.1-final], pytest-5.2.3.dev1473+gebe4a61e1, py-1.8.1, pluggy-0.13.1
2020-07-10T12:03:09.4968578Z rootdir: ~/work/pytest/pytest, inifile: tox.ini, testpaths: testing
2020-07-10T12:03:09.4975308Z implicit args: '-ra -p pytester --strict-markers -l' (addopts config), "-ra --durations=50 -m 'pypy_specific or acceptance_tests'" (PYTEST_ADDOPTS)
2020-07-10T12:03:09.4978821Z cachedir: .tox/pypy3-coverage/.pytest_cache
2020-07-10T12:03:59.1194338Z collected 2777 items / 2694 deselected / 83 selected
…
2020-07-10T12:05:40.9196933Z ============================== 82 passed, 2694 deselected, 1 xfailed in 151.41s (0:02:31) ==============================
2020-07-10T12:05:41.7220437Z Traceback (most recent call last):
2020-07-10T12:05:41.7222504Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/cmdline.py", line 740, in do_run
2020-07-10T12:05:41.7222740Z     runner.run()
2020-07-10T12:05:41.7223301Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/execfile.py", line 247, in run
2020-07-10T12:05:41.7223466Z     exec(code, main_mod.__dict__)
2020-07-10T12:05:41.7223885Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/pytest/__main__.py", line 8, in <module>
2020-07-10T12:05:41.7224061Z     raise SystemExit(pytest.main())
2020-07-10T12:05:41.7224178Z SystemExit: ExitCode.OK
2020-07-10T12:05:41.7224240Z 
2020-07-10T12:05:41.7224361Z During handling of the above exception, another exception occurred:
2020-07-10T12:05:41.7224447Z 
2020-07-10T12:05:41.7224542Z Traceback (most recent call last):
2020-07-10T12:05:41.7224913Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/bin/coverage", line 8, in <module>
2020-07-10T12:05:41.7225065Z     sys.exit(main())
2020-07-10T12:05:41.7225452Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/cmdline.py", line 865, in main
2020-07-10T12:05:41.7225605Z     status = CoverageScript().command_line(argv)
2020-07-10T12:05:41.7226012Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/cmdline.py", line 582, in command_line
2020-07-10T12:05:41.7226166Z     return self.do_run(options, args)
2020-07-10T12:05:41.7226558Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/cmdline.py", line 747, in do_run
2020-07-10T12:05:41.7226706Z     self.coverage.save()
2020-07-10T12:05:41.7227090Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/control.py", line 651, in save
2020-07-10T12:05:41.7227236Z     data = self.get_data()
2020-07-10T12:05:41.7227754Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/control.py", line 705, in get_data
2020-07-10T12:05:41.7228150Z     if self._collector and self._collector.flush_data():
2020-07-10T12:05:41.7228735Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/collector.py", line 423, in flush_data
2020-07-10T12:05:41.7229015Z     self.covdata.add_arcs(self.mapped_file_dict(self.data))
2020-07-10T12:05:41.7229490Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/sqldata.py", line 480, in add_arcs
2020-07-10T12:05:41.7229648Z     data,
2020-07-10T12:05:41.7230071Z   File "/home/runner/work/pytest/pytest/.tox/pypy3-coverage/site-packages/coverage/sqldata.py", line 1089, in executemany
2020-07-10T12:05:41.7230235Z     return self.con.executemany(sql, data)
2020-07-10T12:05:41.7230420Z   File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 423, in executemany
2020-07-10T12:05:41.7230559Z     return cur.executemany(*args)
2020-07-10T12:05:41.7230736Z   File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 773, in wrapper
2020-07-10T12:05:41.7230896Z     return func(self, *args, **kwargs)
2020-07-10T12:05:41.7231075Z   File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 938, in executemany
2020-07-10T12:05:41.7231231Z     return self.__execute(True, sql, many_params)
2020-07-10T12:05:41.7231417Z   File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 889, in __execute
2020-07-10T12:05:41.7231695Z     self.__statement._set_params(params)
2020-07-10T12:05:41.7231873Z   File "/opt/hostedtoolcache/PyPy/3.6.9/x64/lib_pypy/_sqlite3.py", line 1180, in _set_params
2020-07-10T12:05:41.7232140Z     "probably unsupported type." % i)
2020-07-10T12:05:41.7232499Z _sqlite3.InterfaceError: Error binding parameter 0 - probably unsupported type.
2020-07-10T12:05:41.7345535Z ERROR: InvocationError for command /home/runner/work/pytest/pytest/.tox/pypy3-coverage/bin/coverage run -m pytest (exited with code 1)
2020-07-10T12:05:41.7345922Z pypy3-coverage run-test: commands[1] | coverage combine
2020-07-10T12:05:45.0303244Z pypy3-coverage run-test: commands[2] | coverage report -m
2020-07-10T12:05:57.9769748Z Name                                Stmts   Miss Branch BrPart     Cover   Missing
2020-07-10T12:05:57.9771268Z ----------------------------------------------------------------------------------
…
2020-07-10T12:05:57.9822381Z ----------------------------------------------------------------------------------
2020-07-10T12:05:57.9822586Z TOTAL                               11444   5065   4270    685    49.94%

(full: https://github.com/blueyed/pytest/runs/857827442)

[ttaoluo]

FYI: I can handle this error by sleeping and re-executing sql.

try:
    db.execute(sql_query)
except:
    time.sleep(0.1)
    db.execute(sql_query)

[blueyed]

@taolluo
Thanks for the info already.
Can you provide more information for when it happens for you? (PyPy also? Is the traceback the same/similar?)

[nedbat]

@taolluo without that except clause, how often does this happen?

[ttaoluo]

Yes, this error is very elusive, probably only once per hundreds and thousands of insertion.

This error raises here in my code when running with PyPy, https://github.com/taolluo/desmod/blob/261b17abe7b9611e9f9cd43ceeae60b65e14fa92/docs/examples/DP_allocation/DP_simulator.py#L1480

[pquentin]

For what it's worth we are seeing this maybe once in ten urllib3 PyPy tests, see https://github.com/urllib3/urllib3/pull/2086/checks?check_run_id=1446391457 for an example. Not sure how to get a traceback or reproducing it.

[nedbat]

@pquentin can you enable COVERAGE_DEBUG=sql environment variable for your coverage run? It will write all the SQL access to stderr, or you can define COVERAGE_DEBUG_FILE to be the file to write to. The last statement executed before the exception might give us a clue.

[nedbat]

I can also put in the sleep/retry that @taolluo suggested, though it's a little distasteful.

[pquentin]

I'm happy to help find the root cause, I agree that the sleep sounds like the wrong fix

[pquentin]

You can see a few failures here: https://github.com/pquentin/urllib3/runs/1449097388?check_suite_focus=true (there are multiple PyPy runs on the left, you may have to scroll a bit)

[nedbat]

Thanks, though the output is not encouraging. Here is one snippet:

Executing 'select numbits from line_bits where file_id = ? and context_id = ?' with (10, 1)
Executing 'insert or replace into line_bits  (file_id, context_id, numbits) values (?, ?, ?)' with (10, 1, b'\x96\x80\\\x97K\x00`\x9b\x1d\x00\x1e\x13 ')
Executing 'insert or replace into file (path) values (?)' with ('/home/runner/work/urllib3/urllib3/.nox/test-pypy/site-packages/urllib3/util/retry.py',)
Executing 'select numbits from line_bits where file_id = ? and context_id = ?' with (11, 1)
EXCEPTION from execute: Error binding parameter 0 - probably unsupported type.
Couldn't use data file '/home/runner/work/urllib3/urllib3/.coverage.fv-az176-372.2721.716992': Error binding parameter 0 - probably unsupported type.

Notice the first query here succeeded, and the last was the same query, with the same parameter types, but it failed.

[nedbat]

@pquentin Thanks so much for the repo, it's a great test case.
This change makes all the tests in that repo pass:

diff --git a/coverage/sqldata.py b/coverage/sqldata.py
index 702bd42b..0b058585 100644
--- a/coverage/sqldata.py
+++ b/coverage/sqldata.py
@@ -1056,7 +1056,10 @@ def execute(self, sql, parameters=()):
             tail = " with {!r}".format(parameters) if parameters else ""
             self.debug.write("Executing {!r}{}".format(sql, tail))
         try:
-            return self.con.execute(sql, parameters)
+            try:
+                return self.con.execute(sql, parameters)
+            except Exception:
+                return self.con.execute(sql, parameters)
         except sqlite3.Error as exc:
             msg = str(exc)
             try:

An immediate retry, with no sleep. It seems like there's a race condition somewhere in PyPy's SQLite support?

[pquentin]

@nedbat Thank you for this! We'll use that branch and report the bug to PyPy to see if they can do something with it. Is this involving threads?

[nedbat]

I don't see at the moment how threads are involved, but they could be. That branch will not exist for long. I can add this code to a real release soon.

[nedbat]

I've reported a PyPy issue: https://foss.heptapod.net/pypy/pypy/-/issues/3351

[pquentin]

Would you be open to include the distateful fix in coverage? We're unlikely to see a PyPy fix soon and the bug continues to affect us.

[nedbat]

Yes, I intend to do that. I got distracted by completely re-vamping the CI for this repo :)

[nedbat]

This is now released as part of coverage 5.3.1.

[sethmlarson]

Thanks so much @nedbat, hope you're doing well :)

[adiroiban]

FWIW I can still observer this issue here with coverage 5.5 https://github.com/twisted/twisted/pull/1577/checks?check_run_id=2274177993#step:9:751

The error is triggered by executemany , while I see that in #1071 the retry is on execute

This error was only observed on GitHub Actions.
I tried to re-run the same set of tests on my local system and I was not able to reproduce it.

[nedbat]

Is this reproducible on GitHub Actions? Can you try the nedbat/another-1010 branch of coverage.py? It applies the original 1010 fix to the executemany call.

[adiroiban]

Thanks Ned for the branch and your support. Much appreciated.

I have only experience this issue with PYPY. .. and only on GitHub Actions.

I tried to re-run pypy with coverage on my laptop in power

The same tests are executed with py 3.6, 3.7, 3.8. 3.9. 3.10(alpha) and coverage run never fails.

The main difference is that on CPython coverage is using the C Extension, while on PYPY it is not using it.

BTW, on PYPY with coverage the tests are 10 times slower.

On PYPY it used to fail about 30%.
With twisted/twisted, we were executing the whole test suite and observe that the test run itself was ok, but coverage run ended with exit code 1... after 30 minutes... without any extra output

To speed up the tests, we are now running coverage test with PYPY only for a subset of tests.. and this time we got the sqlite error.

The SQLite error is observed maybe 10% of the test runs.

I have create a PR using your new branch. I am giving it a few more spins and will see if after 20 runs I still get a failure.
I am also running the full tests on CPython to check for unexpected regressions... so far all is ok.

Will report back after a few more retries.

[adiroiban]

This was merged into twisted/twisted trunk. We will give it a spin for a few weeks and see how it goes.
I will report how it goes.
Thanks!