From dcdb96bcb123f2095c89eff639b66b5b980f1f99 Mon Sep 17 00:00:00 2001 From: Peter Giacomo Lombardo Date: Wed, 10 Oct 2018 21:02:06 +0200 Subject: [PATCH 1/7] Initial instrumentation, tests and infra. --- instana/__init__.py | 5 +- instana/instrumentation/sqlalchemy.py | 50 +++++++++++++++++ instana/recorder.py | 5 +- setup.py | 5 +- tests/test_sqlalchemy.py | 78 +++++++++++++++++++++++++++ 5 files changed, 137 insertions(+), 6 deletions(-) create mode 100644 instana/instrumentation/sqlalchemy.py create mode 100644 tests/test_sqlalchemy.py diff --git a/instana/__init__.py b/instana/__init__.py index c17c0284..335b345c 100644 --- a/instana/__init__.py +++ b/instana/__init__.py @@ -60,9 +60,10 @@ def load_instrumentation(): if "INSTANA_DISABLE_AUTO_INSTR" not in os.environ: # Import & initialize instrumentation from .instrumentation import asynqp # noqa - from .instrumentation import urllib3 # noqa - from .instrumentation import sudsjurko # noqa from .instrumentation import mysqlpython # noqa + from .instrumentation import sqlalchemy # noqa + from .instrumentation import sudsjurko # noqa + from .instrumentation import urllib3 # noqa from .instrumentation.django import middleware # noqa diff --git a/instana/instrumentation/sqlalchemy.py b/instana/instrumentation/sqlalchemy.py new file mode 100644 index 00000000..9a10c404 --- /dev/null +++ b/instana/instrumentation/sqlalchemy.py @@ -0,0 +1,50 @@ +from __future__ import absolute_import + +import opentracing +import opentracing.ext.tags as ext +import wrapt + +from ..log import logger +from ..singletons import tracer + +try: + import sqlalchemy + from sqlalchemy import event + from sqlalchemy.engine import Engine + + @event.listens_for(Engine, 'before_cursor_execute', named=True) + def receive_before_cursor_execute(**kw): + parent_span = tracer.active_span + + # If we're not tracing, just return + if parent_span is None: + return + + scope = tracer.start_active_span("sqlalchemy", child_of=parent_span) + context = kw['context'] + context._stan_scope = scope + return + + @event.listens_for(Engine, 'after_cursor_execute', named=True) + def receive_after_cursor_execute(**kw): + context = kw['context'] + + if context is not None and hasattr(context, '_stan_scope'): + this_scope = context._stan_scope + if this_scope is not None: + this_scope.close() + + @event.listens_for(Engine, 'dbapi_error', named=True) + def receive_dbapi_error(**kw): + context = kw['context'] + if context is not None and hasattr(context, '_stan_scope'): + this_scope = context._stan_scope + this_scope.span.log_kv({'message': e}) + this_scope.span.set_tag("error", True) + ec = this_scope.span.tags.get('ec', 0) + this_scope.span.set_tag("ec", ec+1) + + + logger.debug("Instrumenting SQLAlchemy") +except ImportError: + pass diff --git a/instana/recorder.py b/instana/recorder.py index cb411f9c..79a7c91e 100644 --- a/instana/recorder.py +++ b/instana/recorder.py @@ -23,10 +23,11 @@ class InstanaRecorder(SpanRecorder): registered_spans = ("django", "memcache", "mysql", "rabbitmq", "rpc-client", - "rpc-server", "soap", "urllib3", "wsgi") + "rpc-server", "sqlalchemy", "soap", "urllib3", "wsgi") http_spans = ("django", "wsgi", "urllib3", "soap") - exit_spans = ("memcache", "mysql", "rabbitmq", "rpc-client", "soap", "urllib3") + exit_spans = ("memcache", "mysql", "rabbitmq", "rpc-client", "sqlalchemy", + "soap", "urllib3") entry_spans = ("django", "wsgi", "rabbitmq", "rpc-server") entry_kind = ["entry", "server", "consumer"] diff --git a/setup.py b/setup.py index 378845c9..ec163cc0 100644 --- a/setup.py +++ b/setup.py @@ -57,9 +57,10 @@ def check_setuptools(): 'pyOpenSSL>=16.1.0;python_version<="2.7"', 'pytest>=3.0.1', 'requests>=2.17.1', - 'urllib3[secure]>=1.15', + 'sqlalchemy>=1.1.15', 'spyne>=2.9', - 'suds-jurko>=0.6' + 'suds-jurko>=0.6', + 'urllib3[secure]>=1.15' ], }, test_suite='nose.collector', diff --git a/tests/test_sqlalchemy.py b/tests/test_sqlalchemy.py new file mode 100644 index 00000000..94761cc0 --- /dev/null +++ b/tests/test_sqlalchemy.py @@ -0,0 +1,78 @@ +from __future__ import absolute_import + +import os +import sys +import unittest + +from sqlalchemy import Column, Integer, String, create_engine +from sqlalchemy.ext.declarative import declarative_base +from sqlalchemy.orm import sessionmaker + +from instana.singletons import tracer + +engine = create_engine('sqlite:///:memory:', echo=False) +Base = declarative_base() + +class StanUser(Base): + __tablename__ = 'churchofstan' + + id = Column(Integer, primary_key=True) + name = Column(String) + fullname = Column(String) + password = Column(String) + + def __repr__(self): + return "" % ( + self.name, self.fullname, self.password) + +Base.metadata.create_all(engine) + +stan_user = StanUser(name='IAmStan', fullname='Stan Robot', password='3X}vP66ADoCFT2g?HPvoem2eJh,zWXgd36Rb/{aRq/>7EYy6@EEH4BP(oeXac@mR') + +Session = sessionmaker(bind=engine) +Session.configure(bind=engine) +session = Session() + + +class TestSQLAlchemy(unittest.TestCase): + # def connect(self): + + def setUp(self): + """ Clear all spans before a test run """ + self.recorder = tracer.recorder + self.recorder.clear_spans() + + def tearDown(self): + pass + + def test_execute(self): + with tracer.start_active_span('test'): + session.add(stan_user) + session.commit() + + spans = self.recorder.queued_spans() + self.assertEqual(2, len(spans)) + + sql_span = spans[0] + test_span = spans[1] + + self.assertIsNone(tracer.active_span) + + # Same traceId + self.assertEqual(test_span.t, sql_span.t) + + # Parent relationships + self.assertEqual(sql_span.p, test_span.s) + + # Error logging + self.assertFalse(test_span.error) + self.assertIsNone(test_span.ec) + self.assertFalse(sql_span.error) + self.assertIsNone(sql_span.ec) + + # SQLAlchemy span + self.assertEqual("sqlalchemy", sql_span.n) + + self.assertIsNotNone(sql_span.stack) + self.assertTrue(type(sql_span.stack) is list) + self.assertGreater(len(sql_span.stack), 0) From 449272b429f6962330c0b4dfc397b3c603bcfe0c Mon Sep 17 00:00:00 2001 From: Peter Giacomo Lombardo Date: Thu, 11 Oct 2018 12:27:09 +0200 Subject: [PATCH 2/7] Centralize test env configuration --- tests/helpers.py | 45 ++++++++++++++++++++++ tests/test_mysql-python.py | 78 ++++++++++++-------------------------- 2 files changed, 70 insertions(+), 53 deletions(-) create mode 100644 tests/helpers.py diff --git a/tests/helpers.py b/tests/helpers.py new file mode 100644 index 00000000..af98f4b3 --- /dev/null +++ b/tests/helpers.py @@ -0,0 +1,45 @@ +import os + +testenv = {} + +""" +MySQL Environment +""" +if 'MYSQL_HOST' in os.environ: + testenv['mysql_host']= os.environ['MYSQL_HOST'] +elif 'TRAVIS_MYSQL_HOST' in os.environ: + testenv['mysql_host'] = os.environ['TRAVIS_MYSQL_HOST'] +else: + testenv['mysql_host'] = '127.0.0.1' + +testenv['mysql_port'] = int(os.environ.get('MYSQL_PORT', '3306')) +testenv['mysql_db'] = os.environ.get('MYSQL_DB', 'travis_ci_test') +testenv['mysql_user'] = os.environ.get('MYSQL_USER', 'root') + +if 'MYSQL_PW' in os.environ: + testenv['mysql_pw'] = os.environ['MYSQL_PW'] +elif 'TRAVIS_MYSQL_PASS' in os.environ: + testenv['mysql_pw'] = os.environ['TRAVIS_MYSQL_PASS'] +else: + testenv['mysql_pw'] = '' + +""" +PostgreSQL Environment +""" +if 'POSTGRESQL_HOST' in os.environ: + testenv['postgresql_host ']= os.environ['POSTGRESQL_HOST'] +elif 'TRAVIS_POSTGRESQL_HOST' in os.environ: + testenv['postgresql_host'] = os.environ['TRAVIS_POSTGRESQL_HOST'] +else: + testenv['postgresql_host'] = '127.0.0.1' + +testenv['postgresql_port'] = int(os.environ.get('POSTGRESQL_PORT', '3306')) +testenv['postgresql_db'] = os.environ.get('POSTGRESQL_DB', 'travis_ci_test') +testenv['postgresql_user'] = os.environ.get('POSTGRESQL_USER', 'root') + +if 'POSTGRESQL_PW' in os.environ: + testenv['postgresql_pw'] = os.environ['POSTGRESQL_PW'] +elif 'TRAVIS_POSTGRESQL_PASS' in os.environ: + testenv['postgresql_pw'] = os.environ['TRAVIS_POSTGRESQL_PASS'] +else: + testenv['postgresql_pw'] = '' diff --git a/tests/test_mysql-python.py b/tests/test_mysql-python.py index ff69efa2..b0b03f5b 100644 --- a/tests/test_mysql-python.py +++ b/tests/test_mysql-python.py @@ -9,6 +9,8 @@ from instana.singletons import tracer +from .helpers import testenv + if sys.version_info < (3, 0): import MySQLdb else: @@ -17,36 +19,6 @@ logger = logging.getLogger(__name__) - -if 'MYSQL_HOST' in os.environ: - mysql_host = os.environ['MYSQL_HOST'] -elif 'TRAVIS_MYSQL_HOST' in os.environ: - mysql_host = os.environ['TRAVIS_MYSQL_HOST'] -else: - mysql_host = '127.0.0.1' - -if 'MYSQL_PORT' in os.environ: - mysql_port = int(os.environ['MYSQL_PORT']) -else: - mysql_port = 3306 - -if 'MYSQL_DB' in os.environ: - mysql_db = os.environ['MYSQL_DB'] -else: - mysql_db = "travis_ci_test" - -if 'MYSQL_USER' in os.environ: - mysql_user = os.environ['MYSQL_USER'] -else: - mysql_user = "root" - -if 'MYSQL_PW' in os.environ: - mysql_pw = os.environ['MYSQL_PW'] -elif 'TRAVIS_MYSQL_PASS' in os.environ: - mysql_pw = os.environ['TRAVIS_MYSQL_PASS'] -else: - mysql_pw = '' - create_table_query = 'CREATE TABLE IF NOT EXISTS users(id serial primary key, \ name varchar(40) NOT NULL, email varchar(40) NOT NULL)' @@ -57,9 +29,9 @@ END """ -db = MySQLdb.connect(host=mysql_host, port=mysql_port, - user=mysql_user, passwd=mysql_pw, - db=mysql_db) +db = MySQLdb.connect(host=testenv['mysql_host'], port=testenv['mysql_port'], + user=testenv['mysql_user'], passwd=testenv['mysql_pw'], + db=testenv['mysql_db']) cursor = db.cursor() cursor.execute(create_table_query) @@ -83,10 +55,10 @@ class TestMySQLPython: def setUp(self): - logger.warn("MySQL connecting: %s:@%s:3306/%s", mysql_user, mysql_host, mysql_db) - self.db = MySQLdb.connect(host=mysql_host, port=mysql_port, - user=mysql_user, passwd=mysql_pw, - db=mysql_db) + logger.warn("MySQL connecting: %s:@%s:3306/%s", testenv['mysql_user'], testenv['mysql_host'], testenv['mysql_db']) + self.db = MySQLdb.connect(host=testenv['mysql_host'], port=testenv['mysql_port'], + user=testenv['mysql_user'], passwd=testenv['mysql_pw'], + db=testenv['mysql_db']) self.cursor = self.db.cursor() self.recorder = tracer.recorder self.recorder.clear_spans() @@ -126,10 +98,10 @@ def test_basic_query(self): assert_equals(None, db_span.ec) assert_equals(db_span.n, "mysql") - assert_equals(db_span.data.mysql.db, mysql_db) - assert_equals(db_span.data.mysql.user, mysql_user) + assert_equals(db_span.data.mysql.db, testenv['mysql_db']) + assert_equals(db_span.data.mysql.user, testenv['mysql_user']) assert_equals(db_span.data.mysql.stmt, 'SELECT * from users') - assert_equals(db_span.data.mysql.host, "%s:3306" % mysql_host) + assert_equals(db_span.data.mysql.host, "%s:3306" % testenv['mysql_host']) def test_basic_insert(self): result = None @@ -154,10 +126,10 @@ def test_basic_insert(self): assert_equals(None, db_span.ec) assert_equals(db_span.n, "mysql") - assert_equals(db_span.data.mysql.db, mysql_db) - assert_equals(db_span.data.mysql.user, mysql_user) + assert_equals(db_span.data.mysql.db, testenv['mysql_db']) + assert_equals(db_span.data.mysql.user, testenv['mysql_user']) assert_equals(db_span.data.mysql.stmt, 'INSERT INTO users(name, email) VALUES(%s, %s)') - assert_equals(db_span.data.mysql.host, "%s:3306" % mysql_host) + assert_equals(db_span.data.mysql.host, "%s:3306" % testenv['mysql_host']) def test_executemany(self): result = None @@ -182,10 +154,10 @@ def test_executemany(self): assert_equals(None, db_span.ec) assert_equals(db_span.n, "mysql") - assert_equals(db_span.data.mysql.db, mysql_db) - assert_equals(db_span.data.mysql.user, mysql_user) + assert_equals(db_span.data.mysql.db, testenv['mysql_db']) + assert_equals(db_span.data.mysql.user, testenv['mysql_user']) assert_equals(db_span.data.mysql.stmt, 'INSERT INTO users(name, email) VALUES(%s, %s)') - assert_equals(db_span.data.mysql.host, "%s:3306" % mysql_host) + assert_equals(db_span.data.mysql.host, "%s:3306" % testenv['mysql_host']) def test_call_proc(self): result = None @@ -208,10 +180,10 @@ def test_call_proc(self): assert_equals(None, db_span.ec) assert_equals(db_span.n, "mysql") - assert_equals(db_span.data.mysql.db, mysql_db) - assert_equals(db_span.data.mysql.user, mysql_user) + assert_equals(db_span.data.mysql.db, testenv['mysql_db']) + assert_equals(db_span.data.mysql.user, testenv['mysql_user']) assert_equals(db_span.data.mysql.stmt, 'test_proc') - assert_equals(db_span.data.mysql.host, "%s:3306" % mysql_host) + assert_equals(db_span.data.mysql.host, "%s:3306" % testenv['mysql_host']) def test_error_capture(self): result = None @@ -240,10 +212,10 @@ def test_error_capture(self): assert_equals(True, db_span.error) assert_equals(1, db_span.ec) - assert_equals(db_span.data.mysql.error, '(1146, "Table \'%s.blah\' doesn\'t exist")' % mysql_db) + assert_equals(db_span.data.mysql.error, '(1146, "Table \'%s.blah\' doesn\'t exist")' % testenv['mysql_db']) assert_equals(db_span.n, "mysql") - assert_equals(db_span.data.mysql.db, mysql_db) - assert_equals(db_span.data.mysql.user, mysql_user) + assert_equals(db_span.data.mysql.db, testenv['mysql_db']) + assert_equals(db_span.data.mysql.user, testenv['mysql_user']) assert_equals(db_span.data.mysql.stmt, 'SELECT * from blah') - assert_equals(db_span.data.mysql.host, "%s:3306" % mysql_host) + assert_equals(db_span.data.mysql.host, "%s:3306" % testenv['mysql_host']) From 0576abb04e47bb833cba9f95cd471c5e1e6b04a5 Mon Sep 17 00:00:00 2001 From: Peter Giacomo Lombardo Date: Thu, 11 Oct 2018 17:36:29 +0200 Subject: [PATCH 3/7] Fix whitespace --- tests/helpers.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/helpers.py b/tests/helpers.py index af98f4b3..59aa7cb7 100644 --- a/tests/helpers.py +++ b/tests/helpers.py @@ -27,7 +27,7 @@ PostgreSQL Environment """ if 'POSTGRESQL_HOST' in os.environ: - testenv['postgresql_host ']= os.environ['POSTGRESQL_HOST'] + testenv['postgresql_host']= os.environ['POSTGRESQL_HOST'] elif 'TRAVIS_POSTGRESQL_HOST' in os.environ: testenv['postgresql_host'] = os.environ['TRAVIS_POSTGRESQL_HOST'] else: From 71934b1171155176eac8fab6a08ec8516c907ee8 Mon Sep 17 00:00:00 2001 From: Peter Giacomo Lombardo Date: Thu, 11 Oct 2018 17:38:12 +0200 Subject: [PATCH 4/7] SQLAlchemy KVs, span conversion --- instana/instrumentation/sqlalchemy.py | 32 +++++++++++++++++++-------- instana/json_span.py | 16 +++++++++++--- instana/recorder.py | 9 +++++++- setup.py | 1 + tests/test_sqlalchemy.py | 17 +++++++++++--- 5 files changed, 59 insertions(+), 16 deletions(-) diff --git a/instana/instrumentation/sqlalchemy.py b/instana/instrumentation/sqlalchemy.py index 9a10c404..633717d5 100644 --- a/instana/instrumentation/sqlalchemy.py +++ b/instana/instrumentation/sqlalchemy.py @@ -3,6 +3,7 @@ import opentracing import opentracing.ext.tags as ext import wrapt +import re from ..log import logger from ..singletons import tracer @@ -12,18 +13,30 @@ from sqlalchemy import event from sqlalchemy.engine import Engine + url_regexp = re.compile(':@') + @event.listens_for(Engine, 'before_cursor_execute', named=True) def receive_before_cursor_execute(**kw): - parent_span = tracer.active_span + try: + parent_span = tracer.active_span - # If we're not tracing, just return - if parent_span is None: - return + # If we're not tracing, just return + if parent_span is None: + return - scope = tracer.start_active_span("sqlalchemy", child_of=parent_span) - context = kw['context'] - context._stan_scope = scope - return + scope = tracer.start_active_span("sqlalchemy", child_of=parent_span) + context = kw['context'] + context._stan_scope = scope + + conn = kw['conn'] + url = str(conn.engine.url) + scope.span.set_tag('sql', kw['statement']) + scope.span.set_tag('eng', conn.engine.name) + scope.span.set_tag('url', url_regexp.sub('@', url)) + except Exception as e: + logger.debug(e) + finally: + return @event.listens_for(Engine, 'after_cursor_execute', named=True) def receive_after_cursor_execute(**kw): @@ -37,6 +50,7 @@ def receive_after_cursor_execute(**kw): @event.listens_for(Engine, 'dbapi_error', named=True) def receive_dbapi_error(**kw): context = kw['context'] + if context is not None and hasattr(context, '_stan_scope'): this_scope = context._stan_scope this_scope.span.log_kv({'message': e}) @@ -45,6 +59,6 @@ def receive_dbapi_error(**kw): this_scope.span.set_tag("ec", ec+1) - logger.debug("Instrumenting SQLAlchemy") + logger.debug("Instrumenting sqlalchemy") except ImportError: pass diff --git a/instana/json_span.py b/instana/json_span.py index 15350662..f0a55516 100644 --- a/instana/json_span.py +++ b/instana/json_span.py @@ -26,13 +26,14 @@ def __init__(self, **kwds): class Data(object): - service = None - http = None baggage = None custom = None + http = None + rabbitmq = None sdk = None + service = None + sqlalchemy = None soap = None - rabbitmq = None def __init__(self, **kwds): self.__dict__.update(kwds) @@ -70,6 +71,15 @@ class RabbitmqData(object): def __init__(self, **kwds): self.__dict__.update(kwds) +class SQLAlchemyData(object): + sql = None + url = None + eng = None + error = None + + def __init__(self, **kwds): + self.__dict__.update(kwds) + class SoapData(object): action = None diff --git a/instana/recorder.py b/instana/recorder.py index 79a7c91e..b8757bbd 100644 --- a/instana/recorder.py +++ b/instana/recorder.py @@ -12,7 +12,7 @@ import instana.singletons from .json_span import (CustomData, Data, HttpData, JsonSpan, MySQLData, - RabbitmqData, SDKData, SoapData) + RabbitmqData, SDKData, SoapData, SQLAlchemyData) from .log import logger if sys.version_info.major is 2: @@ -114,6 +114,13 @@ def build_registered_span(self, span): address=span.tags.pop('address', None), key=span.tags.pop('key', None)) + if span.operation_name == "sqlalchemy": + data.sqlalchemy = SQLAlchemyData(sql=span.tags.pop('sql', None), + eng=span.tags.pop('eng', None), + url=span.tags.pop('url', None), + err=span.tags.pop('err', None)) + + if span.operation_name == "soap": data.soap = SoapData(action=span.tags.pop('soap.action', None)) diff --git a/setup.py b/setup.py index ec163cc0..044bc0b0 100644 --- a/setup.py +++ b/setup.py @@ -54,6 +54,7 @@ def check_setuptools(): 'lxml>=3.4', 'mock>=2.0.0', 'MySQL-python>=1.2.5;python_version<="2.7"', + 'psycopg2>=2.7.1', 'pyOpenSSL>=16.1.0;python_version<="2.7"', 'pytest>=3.0.1', 'requests>=2.17.1', diff --git a/tests/test_sqlalchemy.py b/tests/test_sqlalchemy.py index 94761cc0..4405a9aa 100644 --- a/tests/test_sqlalchemy.py +++ b/tests/test_sqlalchemy.py @@ -8,9 +8,13 @@ from sqlalchemy.ext.declarative import declarative_base from sqlalchemy.orm import sessionmaker +from .helpers import testenv + from instana.singletons import tracer -engine = create_engine('sqlite:///:memory:', echo=False) +# engine = create_engine('sqlite:///:memory:', echo=False) +engine = create_engine("postgresql://%s:%s@%s/%s" % (testenv['postgresql_user'], testenv['postgresql_pw'], + testenv['postgresql_host'], testenv['postgresql_db'])) Base = declarative_base() class StanUser(Base): @@ -45,7 +49,7 @@ def setUp(self): def tearDown(self): pass - def test_execute(self): + def test_session_add(self): with tracer.start_active_span('test'): session.add(stan_user) session.commit() @@ -71,7 +75,14 @@ def test_execute(self): self.assertIsNone(sql_span.ec) # SQLAlchemy span - self.assertEqual("sqlalchemy", sql_span.n) + self.assertEqual('sqlalchemy', sql_span.n) + self.assertFalse('custom' in sql_span.data.__dict__) + self.assertTrue('sqlalchemy' in sql_span.data.__dict__) + + self.assertEqual('postgresql', sql_span.data.sqlalchemy.eng) + self.assertEqual('postgresql://tester@mazzo/rails5_stack', sql_span.data.sqlalchemy.url) + self.assertEqual('INSERT INTO churchofstan (name, fullname, password) VALUES (%(name)s, %(fullname)s, %(password)s) RETURNING churchofstan.id', sql_span.data.sqlalchemy.sql) + self.assertIsNone(sql_span.data.sqlalchemy.err) self.assertIsNotNone(sql_span.stack) self.assertTrue(type(sql_span.stack) is list) From 1d1c18e1f67b4eb5e24422043e73b7df9ae73e97 Mon Sep 17 00:00:00 2001 From: Peter Giacomo Lombardo Date: Fri, 12 Oct 2018 09:48:15 +0200 Subject: [PATCH 5/7] Moar tests; Add error logging --- instana/instrumentation/sqlalchemy.py | 21 +++++++---- instana/recorder.py | 18 +++++----- tests/test_sqlalchemy.py | 50 +++++++++++++++++++++++++-- 3 files changed, 70 insertions(+), 19 deletions(-) diff --git a/instana/instrumentation/sqlalchemy.py b/instana/instrumentation/sqlalchemy.py index 633717d5..86315126 100644 --- a/instana/instrumentation/sqlalchemy.py +++ b/instana/instrumentation/sqlalchemy.py @@ -30,9 +30,9 @@ def receive_before_cursor_execute(**kw): conn = kw['conn'] url = str(conn.engine.url) - scope.span.set_tag('sql', kw['statement']) - scope.span.set_tag('eng', conn.engine.name) - scope.span.set_tag('url', url_regexp.sub('@', url)) + scope.span.set_tag('sqlalchemy.sql', kw['statement']) + scope.span.set_tag('sqlalchemy.eng', conn.engine.name) + scope.span.set_tag('sqlalchemy.url', url_regexp.sub('@', url)) except Exception as e: logger.debug(e) finally: @@ -53,10 +53,17 @@ def receive_dbapi_error(**kw): if context is not None and hasattr(context, '_stan_scope'): this_scope = context._stan_scope - this_scope.span.log_kv({'message': e}) - this_scope.span.set_tag("error", True) - ec = this_scope.span.tags.get('ec', 0) - this_scope.span.set_tag("ec", ec+1) + if this_scope is not None: + this_scope.span.set_tag("error", True) + ec = this_scope.span.tags.get('ec', 0) + this_scope.span.set_tag("ec", ec+1) + + if 'exception' in kw: + e = kw['exception'] + this_scope.span.set_tag('sqlalchemy.err', str(e)) + else: + this_scope.span.set_tag('sqlalchemy.err', "No dbapi error specified.") + this_scope.close() logger.debug("Instrumenting sqlalchemy") diff --git a/instana/recorder.py b/instana/recorder.py index b8757bbd..57d0e657 100644 --- a/instana/recorder.py +++ b/instana/recorder.py @@ -115,10 +115,10 @@ def build_registered_span(self, span): key=span.tags.pop('key', None)) if span.operation_name == "sqlalchemy": - data.sqlalchemy = SQLAlchemyData(sql=span.tags.pop('sql', None), - eng=span.tags.pop('eng', None), - url=span.tags.pop('url', None), - err=span.tags.pop('err', None)) + data.sqlalchemy = SQLAlchemyData(sql=span.tags.pop('sqlalchemy.sql', None), + eng=span.tags.pop('sqlalchemy.eng', None), + url=span.tags.pop('sqlalchemy.url', None), + err=span.tags.pop('sqlalchemy.err', None)) if span.operation_name == "soap": @@ -133,11 +133,6 @@ def build_registered_span(self, span): tskey = list(data.custom.logs.keys())[0] data.mysql.error = data.custom.logs[tskey]['message'] - if len(span.tags) > 0: - if data.custom is None: - data.custom = CustomData() - data.custom.tags = span.tags - entityFrom = {'e': instana.singletons.agent.from_.pid, 'h': instana.singletons.agent.from_.agentUuid} @@ -160,6 +155,11 @@ def build_registered_span(self, span): json_span.error = error json_span.ec = ec + if len(span.tags) > 0: + if data.custom is None: + data.custom = CustomData() + data.custom.tags = span.tags + return json_span def build_sdk_span(self, span): diff --git a/tests/test_sqlalchemy.py b/tests/test_sqlalchemy.py index 4405a9aa..223c0192 100644 --- a/tests/test_sqlalchemy.py +++ b/tests/test_sqlalchemy.py @@ -35,7 +35,6 @@ def __repr__(self): Session = sessionmaker(bind=engine) Session.configure(bind=engine) -session = Session() class TestSQLAlchemy(unittest.TestCase): @@ -45,14 +44,15 @@ def setUp(self): """ Clear all spans before a test run """ self.recorder = tracer.recorder self.recorder.clear_spans() + self.session = Session() def tearDown(self): pass def test_session_add(self): with tracer.start_active_span('test'): - session.add(stan_user) - session.commit() + self.session.add(stan_user) + self.session.commit() spans = self.recorder.queued_spans() self.assertEqual(2, len(spans)) @@ -87,3 +87,47 @@ def test_session_add(self): self.assertIsNotNone(sql_span.stack) self.assertTrue(type(sql_span.stack) is list) self.assertGreater(len(sql_span.stack), 0) + + def test_error_logging(self): + try: + with tracer.start_active_span('test'): + self.session.execute("htVwGrCwVThisIsInvalidSQLaw4ijXd88") + self.session.commit() + except: + pass + + spans = self.recorder.queued_spans() + self.assertEqual(2, len(spans)) + + sql_span = spans[0] + test_span = spans[1] + + self.assertIsNone(tracer.active_span) + + # Same traceId + self.assertEqual(test_span.t, sql_span.t) + + # Parent relationships + self.assertEqual(sql_span.p, test_span.s) + + # Error logging + self.assertFalse(test_span.error) + self.assertIsNone(test_span.ec) + self.assertTrue(sql_span.error) + self.assertIs(sql_span.ec, 1) + + # SQLAlchemy span + self.assertEqual('sqlalchemy', sql_span.n) + # import ipdb; ipdb.set_trace() + + self.assertFalse('custom' in sql_span.data.__dict__) + self.assertTrue('sqlalchemy' in sql_span.data.__dict__) + + self.assertEqual('postgresql', sql_span.data.sqlalchemy.eng) + self.assertEqual('postgresql://tester@mazzo/rails5_stack', sql_span.data.sqlalchemy.url) + self.assertEqual('htVwGrCwVThisIsInvalidSQLaw4ijXd88', sql_span.data.sqlalchemy.sql) + self.assertEqual('syntax error at or near "htVwGrCwVThisIsInvalidSQLaw4ijXd88"\nLINE 1: htVwGrCwVThisIsInvalidSQLaw4ijXd88\n ^\n', sql_span.data.sqlalchemy.err) + + self.assertIsNotNone(sql_span.stack) + self.assertTrue(type(sql_span.stack) is list) + self.assertGreater(len(sql_span.stack), 0) From d6c4705fc475c67ff2a50fbc91da89505b2fe75a Mon Sep 17 00:00:00 2001 From: Peter Giacomo Lombardo Date: Fri, 12 Oct 2018 13:46:48 +0200 Subject: [PATCH 6/7] Add test for transactions --- tests/test_sqlalchemy.py | 62 ++++++++++++++++++++++++++++++++++++++-- 1 file changed, 60 insertions(+), 2 deletions(-) diff --git a/tests/test_sqlalchemy.py b/tests/test_sqlalchemy.py index 223c0192..38393e79 100644 --- a/tests/test_sqlalchemy.py +++ b/tests/test_sqlalchemy.py @@ -38,8 +38,6 @@ def __repr__(self): class TestSQLAlchemy(unittest.TestCase): - # def connect(self): - def setUp(self): """ Clear all spans before a test run """ self.recorder = tracer.recorder @@ -88,6 +86,66 @@ def test_session_add(self): self.assertTrue(type(sql_span.stack) is list) self.assertGreater(len(sql_span.stack), 0) + def test_transaction(self): + result = None + with tracer.start_active_span('test'): + with engine.begin() as connection: + result = connection.execute("select 1") + result = connection.execute("select (name, fullname, password) from churchofstan where name='doesntexist'") + + spans = self.recorder.queued_spans() + self.assertEqual(3, len(spans)) + + sql_span0 = spans[0] + sql_span1 = spans[1] + test_span = spans[2] + + self.assertIsNone(tracer.active_span) + + # Same traceId + self.assertEqual(test_span.t, sql_span0.t) + self.assertEqual(test_span.t, sql_span1.t) + + # Parent relationships + self.assertEqual(sql_span0.p, test_span.s) + self.assertEqual(sql_span1.p, test_span.s) + + # Error logging + self.assertFalse(test_span.error) + self.assertIsNone(test_span.ec) + self.assertFalse(sql_span0.error) + self.assertIsNone(sql_span0.ec) + self.assertFalse(sql_span1.error) + self.assertIsNone(sql_span1.ec) + + # SQLAlchemy span0 + self.assertEqual('sqlalchemy', sql_span0.n) + self.assertFalse('custom' in sql_span0.data.__dict__) + self.assertTrue('sqlalchemy' in sql_span0.data.__dict__) + + self.assertEqual('postgresql', sql_span0.data.sqlalchemy.eng) + self.assertEqual('postgresql://tester@mazzo/rails5_stack', sql_span0.data.sqlalchemy.url) + self.assertEqual('select 1', sql_span0.data.sqlalchemy.sql) + self.assertIsNone(sql_span0.data.sqlalchemy.err) + + self.assertIsNotNone(sql_span0.stack) + self.assertTrue(type(sql_span0.stack) is list) + self.assertGreater(len(sql_span0.stack), 0) + + # SQLAlchemy span1 + self.assertEqual('sqlalchemy', sql_span1.n) + self.assertFalse('custom' in sql_span1.data.__dict__) + self.assertTrue('sqlalchemy' in sql_span1.data.__dict__) + + self.assertEqual('postgresql', sql_span1.data.sqlalchemy.eng) + self.assertEqual('postgresql://tester@mazzo/rails5_stack', sql_span1.data.sqlalchemy.url) + self.assertEqual("select (name, fullname, password) from churchofstan where name='doesntexist'", sql_span1.data.sqlalchemy.sql) + self.assertIsNone(sql_span1.data.sqlalchemy.err) + + self.assertIsNotNone(sql_span1.stack) + self.assertTrue(type(sql_span1.stack) is list) + self.assertGreater(len(sql_span1.stack), 0) + def test_error_logging(self): try: with tracer.start_active_span('test'): From c5144c9fbaa5b21052916090872ad7326e40cf1f Mon Sep 17 00:00:00 2001 From: Peter Giacomo Lombardo Date: Fri, 12 Oct 2018 14:28:42 +0200 Subject: [PATCH 7/7] Remove auth from connect strings --- instana/instrumentation/sqlalchemy.py | 4 ++-- tests/test_sqlalchemy.py | 8 ++++---- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/instana/instrumentation/sqlalchemy.py b/instana/instrumentation/sqlalchemy.py index 86315126..80d79f10 100644 --- a/instana/instrumentation/sqlalchemy.py +++ b/instana/instrumentation/sqlalchemy.py @@ -13,7 +13,7 @@ from sqlalchemy import event from sqlalchemy.engine import Engine - url_regexp = re.compile(':@') + url_regexp = re.compile('\/\/(\S+@)') @event.listens_for(Engine, 'before_cursor_execute', named=True) def receive_before_cursor_execute(**kw): @@ -32,7 +32,7 @@ def receive_before_cursor_execute(**kw): url = str(conn.engine.url) scope.span.set_tag('sqlalchemy.sql', kw['statement']) scope.span.set_tag('sqlalchemy.eng', conn.engine.name) - scope.span.set_tag('sqlalchemy.url', url_regexp.sub('@', url)) + scope.span.set_tag('sqlalchemy.url', url_regexp.sub('//', url)) except Exception as e: logger.debug(e) finally: diff --git a/tests/test_sqlalchemy.py b/tests/test_sqlalchemy.py index 38393e79..9b9e8dfc 100644 --- a/tests/test_sqlalchemy.py +++ b/tests/test_sqlalchemy.py @@ -78,7 +78,7 @@ def test_session_add(self): self.assertTrue('sqlalchemy' in sql_span.data.__dict__) self.assertEqual('postgresql', sql_span.data.sqlalchemy.eng) - self.assertEqual('postgresql://tester@mazzo/rails5_stack', sql_span.data.sqlalchemy.url) + self.assertEqual('postgresql://mazzo/rails5_stack', sql_span.data.sqlalchemy.url) self.assertEqual('INSERT INTO churchofstan (name, fullname, password) VALUES (%(name)s, %(fullname)s, %(password)s) RETURNING churchofstan.id', sql_span.data.sqlalchemy.sql) self.assertIsNone(sql_span.data.sqlalchemy.err) @@ -124,7 +124,7 @@ def test_transaction(self): self.assertTrue('sqlalchemy' in sql_span0.data.__dict__) self.assertEqual('postgresql', sql_span0.data.sqlalchemy.eng) - self.assertEqual('postgresql://tester@mazzo/rails5_stack', sql_span0.data.sqlalchemy.url) + self.assertEqual('postgresql://mazzo/rails5_stack', sql_span0.data.sqlalchemy.url) self.assertEqual('select 1', sql_span0.data.sqlalchemy.sql) self.assertIsNone(sql_span0.data.sqlalchemy.err) @@ -138,7 +138,7 @@ def test_transaction(self): self.assertTrue('sqlalchemy' in sql_span1.data.__dict__) self.assertEqual('postgresql', sql_span1.data.sqlalchemy.eng) - self.assertEqual('postgresql://tester@mazzo/rails5_stack', sql_span1.data.sqlalchemy.url) + self.assertEqual('postgresql://mazzo/rails5_stack', sql_span1.data.sqlalchemy.url) self.assertEqual("select (name, fullname, password) from churchofstan where name='doesntexist'", sql_span1.data.sqlalchemy.sql) self.assertIsNone(sql_span1.data.sqlalchemy.err) @@ -182,7 +182,7 @@ def test_error_logging(self): self.assertTrue('sqlalchemy' in sql_span.data.__dict__) self.assertEqual('postgresql', sql_span.data.sqlalchemy.eng) - self.assertEqual('postgresql://tester@mazzo/rails5_stack', sql_span.data.sqlalchemy.url) + self.assertEqual('postgresql://mazzo/rails5_stack', sql_span.data.sqlalchemy.url) self.assertEqual('htVwGrCwVThisIsInvalidSQLaw4ijXd88', sql_span.data.sqlalchemy.sql) self.assertEqual('syntax error at or near "htVwGrCwVThisIsInvalidSQLaw4ijXd88"\nLINE 1: htVwGrCwVThisIsInvalidSQLaw4ijXd88\n ^\n', sql_span.data.sqlalchemy.err)