Instrumentation issues with coverage module and SQLite in latest 0.32b0 release

[phillipuniverse]

I utilize the automatic instrumentation for my projects during tests. When I run my tests with coverage I get an error in the last part when the coverage results are being written out:

Traceback (most recent call last):
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/bin/coverage", line 8, in <module>
    sys.exit(main())
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/cmdline.py", line 943, in main
    status = CoverageScript().command_line(argv)
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/cmdline.py", line 659, in command_line
    return self.do_run(options, args)
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/cmdline.py", line 837, in do_run
    self.coverage.save()
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/control.py", line 706, in save
    data = self.get_data()
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/control.py", line 775, in get_data
    if self._collector and self._collector.flush_data():
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/collector.py", line 471, in flush_data
    self.covdata.add_arcs(self.mapped_file_dict(data))
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/sqldata.py", line 238, in _wrapped
    return method(self, *args, **kwargs)
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/sqldata.py", line 499, in add_arcs
    self._choose_lines_or_arcs(arcs=True)
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/sqldata.py", line 528, in _choose_lines_or_arcs
    with self._connect() as con:
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/sqldata.py", line 315, in _connect
    self._open_db()
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/sqldata.py", line 266, in _open_db
    self._read_db()
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/sqldata.py", line 270, in _read_db
    with self._dbs[threading.get_ident()] as db:
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/sqldata.py", line 1084, in __enter__
    self._connect()
  File "/Users/phillip/Library/Caches/pypoetry/virtualenvs/shipwell-auth-oHcJ824x-py3.10/lib/python3.10/site-packages/coverage/sqldata.py", line 1067, in _connect
    self.con.create_function("REGEXP", 2, _regexp)
sqlite3.ProgrammingError: Base Connection.__init__ not called.

An example execution for e.g. a Django project is this:

coverage run --rcfile pyproject.toml manage.py test

The only changes I have in my venv is the change from 1.12.0rc1 to 1.12.0rc2, and the contrib module from 0.31b0 to 0.32b0.

I can also reproduce this in some projects with Pytest, and the pytest-cov module:

pytest --cov --cov-report=xml:tests/coverage.xml

The way I kick off my instrumentation is to:

1. Add the opentelemetry-contrib-instrumentations dependency to pull in all instrumentations
2. Include a manual import to start monkeypatching:

   # This import kicks off all of the autoinstrumentation of OpenTelemetry
   import opentelemetry.instrumentation.auto_instrumentation.sitecustomize as autotrace

Steps to reproduce

I'm working on a small example project that demonstrates the issue but wanted to get this open in the meantime to help others that might be googling for this issue. But basically:

0. Start instrumentation libraries
1. Run tests with coverage
2. At the end of the tests see the above error when attempting to write coverage data via sqlite

This causes the test process to get an error code and tests "fail". If I don't instrument then I don't get an error and everything works fine.

Python version - 3.10.4 (reproducible in Python 3.7-3.10)
OpenTelemetry/contrib Version - 1.12.0rc2/0.32b0
Coverage - 6.3.3 or 6.4.1
pytest-cov - 3.0.0

[phillipuniverse]

This problem appears to be a regression in the sqlite3 instrumentation. If I disable it:

import os
from opentelemetry.instrumentation.environment_variables import OTEL_PYTHON_DISABLED_INSTRUMENTATIONS

os.environ[OTEL_PYTHON_DISABLED_INSTRUMENTATIONS] = "sqlite3"

Then the coverage module works correctly and no exception is raised.

[philipcwhite]

I have this same issue in Flask. sqlite3.ProgrammingError: Base Connection.init not called. When I remove the sqlite3 instrumentation I have no errors (or sql monitoring). In earlier versions this worked.

[phillipuniverse]

@philipcwhite we had some ideas over in #1183 but nothing really conclusive, like which calls were no longer being propagated. You might have a better time reproducing the issue?

[philipcwhite]

Here is my test app.
https://github.com/philipcwhite/flask-auth/tree/main/sqlite3
I set my connections and queries up as a class and this previously worked. The new release it does not. Looks like it fails when init is called.

class Data:
def init(self):
self.con = sqlite3.connect('flask.db')
self.cursor = self.con.cursor()

[ocelotl]

I am back on investigating this one

[rogersd]

@ocelotl Looks like I'm hitting this too. Does your fix solve it, and can it make it in to the next release?

[bigon]

Any news on this? Because that completely breaks the instrumentation with sqlite

[philipcwhite]

I still have this issue. Nothing seems to have been fixed. I posted in the CNCF slack on this. It looks like they may be working on something here but nothing has been released. #1183

[aabmass]

According to #1179 (comment), this was a regression in the instrumentation. Has anyone experiencing the issue actually bisected this to find the root cause?

[phillipuniverse]

@aabmass yes see #1183

[ocelotl]

@phillipuniverse please take a look at #1659, we are trying to revert the bugfix that introduced this issue.

[phillipuniverse]

@ocelotl I saw you closed #1659 but FWIW it did resolve the issue.

There are a few other examples of SQLAlchemy usage for test cases too:

• the one I reported about instrumentation
• Small test app from @philipcwhite demonstrating the issue - Instrumentation issues with coverage module and SQLite in latest 0.32b0 release #1179 (comment). Should probably formalize this one into a test case

It also seemed like we're about there with #1183, any reason to not accept that PR?

[ocelotl]

@phillipuniverse sorry, I closed that PR to open a new one: #1660. Right now it is failing because an issue we have in main, I am investigating it.

AFAIK #1183 did not fix the issue completely and needs more investigation, I'd rather revert the original bugfix and start all over again. Sorry for the back and forth and for the long time it has taken to address this issue.

[phillipuniverse]

Fully fixed in 0.37b0 by #1660.