opentelemetry-autoinstrumentation causes pymsql connection erros

[alexandraBara]

Describe your environment Describe any aspect of your environment relevant to the problem, including your Python version, platform, version numbers of installed dependencies, information about your cloud hosting provider, etc. If you're reporting a problem with a specific version of a library in this repo, please check whether the problem has been fixed on main.

• Python 3.9
• pymysql 0.10.0
• opentelemetry-distro==0.32b0
• opentelemetry-exporter-otlp-proto-http==1.11.1
• opentelemetry-propagator-jaeger==1.12.0rc2
• opentelemetry-instrumentation-pymysql==0.32b0

and I have these env vars set:

•     env.OTEL_METRICS_EXPORTER="none"
  

•     env.OTEL_TRACES_EXPORTER="console"
  

•     env.OTEL_LOG_LEVEL="debug"
  

Steps to reproduce
Describe exactly how to reproduce the error. Include a code sample if applicable.
I run my application like this:
opentelemetry-instrument python3 ./<mypyscript.py>

What is the expected behavior?
What did you expect to see?
This runs just fine if i dont add opentelemetry-instrument

What is the actual behavior?
What did you see instead?

Stack trace

opentelemetry-instrument python3 ./tuna/import_configs.py -t recurrent_alex_opentelemetry_22_nchw --mark_recurrent -f utils/configs/conv_configs_NCHW.txt

Invalid key value resource attribute pair null: not enough values to unpack (expected 2, got 1)

Invalid key value resource attribute pair null: not enough values to unpack (expected 2, got 1)

Invalid key value resource attribute pair null: not enough values to unpack (expected 2, got 1)

Invalid key value resource attribute pair null: not enough values to unpack (expected 2, got 1)

Invalid key value resource attribute pair null: not enough values to unpack (expected 2, got 1)

Invalid key value resource attribute pair null: not enough values to unpack (expected 2, got 1)

Invalid key value resource attribute pair null: not enough values to unpack (expected 2, got 1)

Traceback (most recent call last):

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/engine/base.py", line 2336, in _wrap_pool_connect

return fn()

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 364, in connect

return _ConnectionFairy._checkout(self)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 778, in _checkout

fairy = _ConnectionRecord.checkout(pool)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 495, in checkout

rec = pool._do_get()

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/impl.py", line 140, in _do_get

self._dec_overflow()

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/util/langhelpers.py", line 68, in exit

compat.raise_(

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/util/compat.py", line 182, in raise_

raise exception

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/impl.py", line 137, in _do_get

return self._create_connection()

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 309, in _create_connection

return _ConnectionRecord(self)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 440, in init

self.__connect(first_connect_check=True)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 664, in __connect

pool.dispatch.first_connect.for_modify(

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/event/attr.py", line 314, in exec_once_unless_exception

self._exec_once_impl(True, *args, **kw)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/event/attr.py", line 285, in _exec_once_impl

self(*args, **kw)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/event/attr.py", line 322, in call

fn(*args, **kw)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/util/langhelpers.py", line 1406, in go

return once_fn(*arg, **kw)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/engine/strategies.py", line 200, in first_connect

dialect.do_rollback(c.connection)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/dialects/mysql/base.py", line 2509, in do_rollback

dbapi_connection.rollback()

File "/usr/local/lib/python3.9/dist-packages/pymysql/connections.py", line 431, in rollback

self._execute_command(COMMAND.COM_QUERY, "ROLLBACK")

File "/usr/local/lib/python3.9/dist-packages/pymysql/connections.py", line 742, in _execute_command

raise err.InterfaceError(0, '')

pymysql.err.InterfaceError: (0, '')

The above exception was the direct cause of the following exception:

Traceback (most recent call last):

File "/home/miopenpdb/workspace/Test_mb_alex_opentelemetry/./tuna/import_configs.py", line 239, in

main()

File "/home/miopenpdb/workspace/Test_mb_alex_opentelemetry/./tuna/import_configs.py", line 231, in main

counts = import_cfgs(args, dbt)

File "/home/miopenpdb/workspace/Test_mb_alex_opentelemetry/./tuna/import_configs.py", line 208, in import_cfgs

connect_db()

File "/home/miopenpdb/workspace/Test_mb_alex_opentelemetry/tuna/db_tables.py", line 56, in connect_db

ENGINE.execute('Use {}'.format(db_name))

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/engine/base.py", line 2234, in execute

connection = self._contextual_connect(close_with_result=True)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/engine/base.py", line 2302, in _contextual_connect

self._wrap_pool_connect(self.pool.connect, None),

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/engine/base.py", line 2339, in _wrap_pool_connect

Connection._handle_dbapi_exception_noconnection(

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/engine/base.py", line 1583, in _handle_dbapi_exception_noconnection

util.raise_(

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/util/compat.py", line 182, in raise_

raise exception

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/engine/base.py", line 2336, in _wrap_pool_connect

return fn()

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 364, in connect

return _ConnectionFairy._checkout(self)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 778, in _checkout

fairy = _ConnectionRecord.checkout(pool)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 495, in checkout

rec = pool._do_get()

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/impl.py", line 140, in _do_get

self._dec_overflow()

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/util/langhelpers.py", line 68, in exit

compat.raise_(

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/util/compat.py", line 182, in raise_

raise exception

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/impl.py", line 137, in _do_get

return self._create_connection()

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 309, in _create_connection

return _ConnectionRecord(self)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 440, in init

self.__connect(first_connect_check=True)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/pool/base.py", line 664, in __connect

pool.dispatch.first_connect.for_modify(

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/event/attr.py", line 314, in exec_once_unless_exception

self._exec_once_impl(True, *args, **kw)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/event/attr.py", line 285, in _exec_once_impl

self(*args, **kw)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/event/attr.py", line 322, in call

fn(*args, **kw)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/util/langhelpers.py", line 1406, in go

return once_fn(*arg, **kw)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/engine/strategies.py", line 200, in first_connect

dialect.do_rollback(c.connection)

File "/usr/local/lib/python3.9/dist-packages/sqlalchemy/dialects/mysql/base.py", line 2509, in do_rollback

dbapi_connection.rollback()

File "/usr/local/lib/python3.9/dist-packages/pymysql/connections.py", line 431, in rollback

self._execute_command(COMMAND.COM_QUERY, "ROLLBACK")

File "/usr/local/lib/python3.9/dist-packages/pymysql/connections.py", line 742, in _execute_command

raise err.InterfaceError(0, '')

sqlalchemy.exc.InterfaceError: (pymysql.err.InterfaceError) (0, '')

(Background on this error at: http://sqlalche.me/e/13/rvf5)

{

"name": "SET",

"context": {

    "trace_id": "0xc89e5d71a915e3112d7c1abfe8868b2c",

    "span_id": "0xd2e6fb6fb1d03fda",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.474928Z",

"end_time": "2022-08-04T18:00:23.476814Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SET NAMES utf8mb4",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "SHOW",

"context": {

    "trace_id": "0xef88b04165aa155041ac6cfbf1655f91",

    "span_id": "0x804f7db19ba1098e",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.478194Z",

"end_time": "2022-08-04T18:00:23.508391Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SHOW VARIABLES LIKE 'sql_mode'",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "SHOW",

"context": {

    "trace_id": "0x75975cbe1e1e2f56e536579bd8edaab7",

    "span_id": "0x9de6ae2fa5fbe756",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.508824Z",

"end_time": "2022-08-04T18:00:23.512078Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SHOW VARIABLES LIKE 'lower_case_table_names'",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "SELECT",

"context": {

    "trace_id": "0x89d57044548da505ebed6924d15c0059",

    "span_id": "0x35d1e14502c096cb",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.512519Z",

"end_time": "2022-08-04T18:00:23.514217Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SELECT VERSION()",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "SELECT",

"context": {

    "trace_id": "0x619446a8ba99021a17f6151f6fa5e00d",

    "span_id": "0x5beea9b6b1b00aaa",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.514807Z",

"end_time": "2022-08-04T18:00:23.516615Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SELECT DATABASE()",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "SELECT",

"context": {

    "trace_id": "0x9e243e519b1329e5ebcdf4575fc989c8",

    "span_id": "0x1093a09e63ec8b4b",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.517020Z",

"end_time": "2022-08-04T18:00:23.518827Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SELECT @@transaction_isolation",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "show",

"context": {

    "trace_id": "0xaf8a2a01cee1416e093c8968f9180baf",

    "span_id": "0xfcfa9a672098e81a",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.519226Z",

"end_time": "2022-08-04T18:00:23.522371Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "show collation where `Charset` = 'utf8mb4' and `Collation` = 'utf8mb4_bin'",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "SELECT",

"context": {

    "trace_id": "0xe4b9cbb4b315c3a5e89d7ff7fadbd819",

    "span_id": "0x027be519b6e31d39",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.523790Z",

"end_time": "2022-08-04T18:00:23.525888Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SELECT CAST('test plain returns' AS CHAR(60)) AS anon_1",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "SELECT",

"context": {

    "trace_id": "0x85a6e30224bff9004f4b5184f1914854",

    "span_id": "0x539eab4b3d877d5a",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.526648Z",

"end_time": "2022-08-04T18:00:23.528560Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SELECT CAST('test unicode returns' AS CHAR(60)) AS anon_1",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

{

"name": "SELECT",

"context": {

    "trace_id": "0x3f99e02d82163c91a7b8896315e25ea0",

    "span_id": "0x5cc4779fade82474",

    "trace_state": "[]"

},

"kind": "SpanKind.CLIENT",

"parent_id": null,

"start_time": "2022-08-04T18:00:23.529406Z",

"end_time": "2022-08-04T18:00:23.531096Z",

"status": {

    "status_code": "UNSET"

},

"attributes": {

    "db.system": "mysql",

    "db.name": "tuna_scales_alex_opentelemetry_22",

    "db.statement": "SELECT CAST('test collated returns' AS CHAR CHARACTER SET utf8mb4) COLLATE utf8mb4_bin AS anon_1",

    "db.user": "root",

    "net.peer.name": "localhost",

    "net.peer.port": 3306

},

"events": [],

"links": [],

"resource": {

    "telemetry.sdk.language": "python",

    "telemetry.sdk.name": "opentelemetry",

    "telemetry.sdk.version": "1.12.0rc2",

    "service.name": "MITunaX.miopen_find_compile",

    "telemetry.auto.version": "0.32b0"

}

}

script returned exit code 1

Additional context
This is my first go at adding instrumentation to our project, so please bare with me as i navigate this.
It seems like adding the instrumentation to any scripts that launch db connections fail in the same way.
Any help would be appreciated.

[rogersd]

@srikanthccv Was this fixed by #1346? I'm still seeing the same error with the 0.34b0 release.

[srikanthccv]

No, I don't think they are related. I think this was referenced mistakenly.

[rogersd]

This should be fixed in #1424

[srikanthccv]

Please re-open if it's not fixed in #1424

[TheNomet]

Hi @rogersd and @srikanthccv,
I tried to test opentelemetry-lambda with pymysql and I still see the error when having connection.autocommit(True).

How to reproduce

• Clone opentelemetry-lambda and ensure that the latest version of opentelemetry is used
• add PyMySQL==0.10.1 to python/sample-apps/function/requirements.txt
• modify python/sample-apps/function/lambda_function.py as follows

import os
import pymysql
import boto3
import json

s3 = boto3.resource("s3")


def lambda_handler(event, context):
    print(pymysql.__version__)
    
    host = os.getenv("DB_HOST")
    port = int(os.getenv("DB_PORT"))
    # MODIFY THE FOLLOWING
    user = ""
    passwd = ""
    query = ""
    # MODIFY THE ABOVE
    
    conn = pymysql.connect(
        host=host,
        port=port,
        user=user,
        passwd=passwd,
        connect_timeout=50,
        charset="utf8mb4",
    )
    # Remove this line for the lambda to work
    conn.autocommit(True)
    
    with conn.cursor(pymysql.cursors.DictCursor) as cursor:
        cursor.execute(query)
        res = cursor.fetchall()

    return {"statusCode": 200, "body": json.dumps(os.environ.get("_X_AMZN_TRACE_ID")), "res": str(res)}

• run cd python/sample-apps && ./run.sh to deploy.

Notes

• a database is needed for the setup to work
• comment conn.autocommit(True) to check that the lambda works

Logs

[ERROR] InterfaceError: (0, '')
Traceback (most recent call last):
  File "/opt/python/wrapt/wrappers.py", line 578, in __call__
    return self._self_wrapper(self.__wrapped__, self._self_instance,
  File "/opt/python/opentelemetry/instrumentation/aws_lambda/__init__.py", line 315, in _instrumented_lambda_handler_call
    result = call_wrapped(*args, **kwargs)
  File "/var/task/lambda_function.py", line 28, in lambda_handler
    conn.autocommit(True)
  File "/var/task/pymysql/connections.py", line 389, in autocommit
    self._send_autocommit_mode()
  File "/var/task/pymysql/connections.py", line 405, in _send_autocommit_mode
    self._execute_command(COMMAND.COM_QUERY, "SET AUTOCOMMIT = %s" %
  File "/var/task/pymysql/connections.py", line 742, in _execute_command
    raise err.InterfaceError(0, '')

Interesting facts

If I add conn.ping() before calling conn.autocommit() the error disappears.

[rogersd]

Looking at https://github.com/vasireddy99/opentelemetry-lambda/blob/main/python/src/otel/otel_sdk/requirements-nodeps.txt it looks like they're still using 0.35b0 for everything. Are you modifying that to use the fixed version for these packages?

opentelemetry-instrumentation-dbapi==0.35b2
opentelemetry-instrumentation-pymysql==0.35b2
opentelemetry-instrumentation-sqlite3==0.35b2