Move some log lines from default logger to sql/transaction loggers (#7952)

Idea from matrix-org/synapse-dinsic#49
This commit is contained in:
Andrew Morgan 2020-07-28 10:52:13 -07:00 committed by GitHub
parent 2c1e1b153d
commit 8a25332d94
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
2 changed files with 11 additions and 8 deletions

1
changelog.d/7952.misc Normal file
View file

@ -0,0 +1 @@
Move some database-related log lines from the default logger to the database/transaction loggers.

View file

@ -49,11 +49,11 @@ from synapse.storage.engines import BaseDatabaseEngine, PostgresEngine, Sqlite3E
from synapse.storage.types import Connection, Cursor from synapse.storage.types import Connection, Cursor
from synapse.types import Collection from synapse.types import Collection
logger = logging.getLogger(__name__)
# python 3 does not have a maximum int value # python 3 does not have a maximum int value
MAX_TXN_ID = 2 ** 63 - 1 MAX_TXN_ID = 2 ** 63 - 1
logger = logging.getLogger(__name__)
sql_logger = logging.getLogger("synapse.storage.SQL") sql_logger = logging.getLogger("synapse.storage.SQL")
transaction_logger = logging.getLogger("synapse.storage.txn") transaction_logger = logging.getLogger("synapse.storage.txn")
perf_logger = logging.getLogger("synapse.storage.TIME") perf_logger = logging.getLogger("synapse.storage.TIME")
@ -233,7 +233,7 @@ class LoggingTransaction:
try: try:
return func(sql, *args) return func(sql, *args)
except Exception as e: except Exception as e:
logger.debug("[SQL FAIL] {%s} %s", self.name, e) sql_logger.debug("[SQL FAIL] {%s} %s", self.name, e)
raise raise
finally: finally:
secs = time.time() - start secs = time.time() - start
@ -419,7 +419,7 @@ class Database(object):
except self.engine.module.OperationalError as e: except self.engine.module.OperationalError as e:
# This can happen if the database disappears mid # This can happen if the database disappears mid
# transaction. # transaction.
logger.warning( transaction_logger.warning(
"[TXN OPERROR] {%s} %s %d/%d", name, e, i, N, "[TXN OPERROR] {%s} %s %d/%d", name, e, i, N,
) )
if i < N: if i < N:
@ -427,18 +427,20 @@ class Database(object):
try: try:
conn.rollback() conn.rollback()
except self.engine.module.Error as e1: except self.engine.module.Error as e1:
logger.warning("[TXN EROLL] {%s} %s", name, e1) transaction_logger.warning("[TXN EROLL] {%s} %s", name, e1)
continue continue
raise raise
except self.engine.module.DatabaseError as e: except self.engine.module.DatabaseError as e:
if self.engine.is_deadlock(e): if self.engine.is_deadlock(e):
logger.warning("[TXN DEADLOCK] {%s} %d/%d", name, i, N) transaction_logger.warning(
"[TXN DEADLOCK] {%s} %d/%d", name, i, N
)
if i < N: if i < N:
i += 1 i += 1
try: try:
conn.rollback() conn.rollback()
except self.engine.module.Error as e1: except self.engine.module.Error as e1:
logger.warning( transaction_logger.warning(
"[TXN EROLL] {%s} %s", name, e1, "[TXN EROLL] {%s} %s", name, e1,
) )
continue continue
@ -478,7 +480,7 @@ class Database(object):
# [2]: https://github.com/python/cpython/blob/v3.8.0/Modules/_sqlite/cursor.c#L236 # [2]: https://github.com/python/cpython/blob/v3.8.0/Modules/_sqlite/cursor.c#L236
cursor.close() cursor.close()
except Exception as e: except Exception as e:
logger.debug("[TXN FAIL] {%s} %s", name, e) transaction_logger.debug("[TXN FAIL] {%s} %s", name, e)
raise raise
finally: finally:
end = monotonic_time() end = monotonic_time()