From bcd94e416b8a5ea3df2e341b7ffec2825d6a5a4c Mon Sep 17 00:00:00 2001 From: Joshua Stiefer Date: Sun, 25 Apr 2021 20:32:20 -0700 Subject: [PATCH 1/2] Add SQLAlchemy multithreading test I was able to get the test to fail reliably for PostgreSQL by reverting back the behavior before #315. When going back to the current behavior, the test passes fine. Should more be done to try to trigger the others to also log the warning? --- .../tests/sqlalchemy_tests/mixins.py | 50 ++++++++++++++++++- .../tests/sqlalchemy_tests/test_sqlite.py | 4 ++ 2 files changed, 52 insertions(+), 2 deletions(-) diff --git a/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/mixins.py b/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/mixins.py index ccf37ae425..d97710003c 100644 --- a/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/mixins.py +++ b/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/mixins.py @@ -13,10 +13,12 @@ # limitations under the License. import contextlib +import logging +import threading -from sqlalchemy import Column, Integer, String, create_engine +from sqlalchemy import Column, Integer, String, create_engine, insert from sqlalchemy.ext.declarative import declarative_base -from sqlalchemy.orm import sessionmaker +from sqlalchemy.orm import close_all_sessions, scoped_session, sessionmaker from opentelemetry import trace from opentelemetry.instrumentation.sqlalchemy import SQLAlchemyInstrumentor @@ -199,3 +201,47 @@ def test_parent(self): self.assertEqual(parent_span.instrumentation_info.name, "sqlalch_svc") self.assertEqual(child_span.name, "SELECT " + self.SQL_DB) + + def test_multithreading(self): + """Ensure spans are captured correctly in a multithreading scenario + + We also expect no logged warnings about calling end() on an ended span. + """ + + def insert_player(session): + _session = session() + player = Player(name="Player") + _session.add(player) + _session.commit() + _session.query(Player).all() + + def insert_players(session): + _session = session() + players = [] + for player_number in range(3): + players.append(Player(name=f"Player {player_number}")) + _session.add_all(players) + _session.commit() + + session_factory = sessionmaker(bind=self.engine) + # pylint: disable=invalid-name + Session = scoped_session(session_factory) + thread_one = threading.Thread(target=insert_player, args=(Session,)) + thread_two = threading.Thread(target=insert_players, args=(Session,)) + + logger = logging.getLogger("opentelemetry.sdk.trace") + with self.assertLogs(logger, level="WARNING") as cm: + # Dummy warning so test doesn't fail on no logs + logger.warning("Dummy warning") + thread_one.start() + thread_two.start() + thread_one.join() + thread_two.join() + close_all_sessions() + + self.assertEqual( + cm.output, ["WARNING:opentelemetry.sdk.trace:Dummy warning"] + ) + + spans = self.memory_exporter.get_finished_spans() + self.assertEqual(len(spans), 5) diff --git a/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/test_sqlite.py b/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/test_sqlite.py index 0acba0fec2..bec0f5b04c 100644 --- a/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/test_sqlite.py +++ b/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/test_sqlite.py @@ -59,3 +59,7 @@ def test_engine_execute_errors(self): self.assertEqual( span.status.description, "no such table: a_wrong_table" ) + + def test_multithreading(self): + # Overriding instead of skipping based on DB name in mixin + pass From 14c4cc55be0bc8dd8331e43ae39307ac55ede5f3 Mon Sep 17 00:00:00 2001 From: Joshua Stiefer Date: Tue, 1 Jun 2021 15:04:08 -0700 Subject: [PATCH 2/2] Update tests based on feedback --- .../tests/sqlalchemy_tests/mixins.py | 22 +++++++++---------- .../tests/sqlalchemy_tests/test_sqlite.py | 4 ---- 2 files changed, 10 insertions(+), 16 deletions(-) diff --git a/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/mixins.py b/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/mixins.py index d97710003c..c2e5548ab1 100644 --- a/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/mixins.py +++ b/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/mixins.py @@ -208,6 +208,9 @@ def test_multithreading(self): We also expect no logged warnings about calling end() on an ended span. """ + if self.VENDOR == "sqlite": + return + def insert_player(session): _session = session() player = Player(name="Player") @@ -230,18 +233,13 @@ def insert_players(session): thread_two = threading.Thread(target=insert_players, args=(Session,)) logger = logging.getLogger("opentelemetry.sdk.trace") - with self.assertLogs(logger, level="WARNING") as cm: - # Dummy warning so test doesn't fail on no logs - logger.warning("Dummy warning") - thread_one.start() - thread_two.start() - thread_one.join() - thread_two.join() - close_all_sessions() - - self.assertEqual( - cm.output, ["WARNING:opentelemetry.sdk.trace:Dummy warning"] - ) + with self.assertRaises(AssertionError): + with self.assertLogs(logger, level="WARNING"): + thread_one.start() + thread_two.start() + thread_one.join() + thread_two.join() + close_all_sessions() spans = self.memory_exporter.get_finished_spans() self.assertEqual(len(spans), 5) diff --git a/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/test_sqlite.py b/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/test_sqlite.py index bec0f5b04c..0acba0fec2 100644 --- a/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/test_sqlite.py +++ b/tests/opentelemetry-docker-tests/tests/sqlalchemy_tests/test_sqlite.py @@ -59,7 +59,3 @@ def test_engine_execute_errors(self): self.assertEqual( span.status.description, "no such table: a_wrong_table" ) - - def test_multithreading(self): - # Overriding instead of skipping based on DB name in mixin - pass