summary refs log tree commit diff
path: root/synapse/storage/_base.py
diff options
context:
space:
mode:
authorPaul "LeoNerd" Evans <paul@matrix.org>2014-09-12 14:37:55 +0100
committerPaul "LeoNerd" Evans <paul@matrix.org>2014-09-12 14:37:55 +0100
commit1c2024988457c5cdb9c0137a99e687e56e74e14b (patch)
tree1e08cfe1a6cfe1fcdf29f1223648ad47babb2efd /synapse/storage/_base.py
parentAdd a .runInteraction() method on SQLBaseStore itself to wrap the .db_pool (diff)
downloadsynapse-1c2024988457c5cdb9c0137a99e687e56e74e14b.tar.xz
Logging of all SQL queries via the 'synapse.storage.SQL' logger
Diffstat (limited to 'synapse/storage/_base.py')
-rw-r--r--synapse/storage/_base.py45
1 files changed, 43 insertions, 2 deletions
diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py
index 8a36f0bc6a..a46f2c6601 100644
--- a/synapse/storage/_base.py
+++ b/synapse/storage/_base.py
@@ -25,6 +25,44 @@ import json
 
 logger = logging.getLogger(__name__)
 
+sql_logger = logging.getLogger("synapse.storage.SQL")
+
+
+class LoggingTransaction(object):
+    """An object that almost-transparently proxies for the 'txn' object
+    passed to the constructor. Adds logging to the .execute() method."""
+    __slots__ = ["txn"]
+
+    def __init__(self, txn):
+        object.__setattr__(self, "txn", txn)
+
+    def __getattribute__(self, name):
+        if name == "execute":
+            return object.__getattribute__(self, "execute")
+
+        return getattr(object.__getattribute__(self, "txn"), name)
+
+    def __setattr__(self, name, value):
+        setattr(object.__getattribute__(self, "txn"), name, value)
+
+    def execute(self, sql, *args, **kwargs):
+        # TODO(paul): Maybe use 'info' and 'debug' for values?
+        sql_logger.debug("[SQL] %s", sql)
+        try:
+            if args and args[0]:
+                values = args[0]
+                sql_logger.debug("[SQL values] " +
+                    ", ".join(("<%s>",) * len(values)), *values)
+        except:
+            # Don't let logging failures stop SQL from working
+            pass
+
+        # TODO(paul): Here would be an excellent place to put some timing
+        #   measurements, and log (warning?) slow queries.
+        return object.__getattribute__(self, "txn").execute(
+            sql, *args, **kwargs
+        )
+
 
 class SQLBaseStore(object):
 
@@ -34,9 +72,12 @@ class SQLBaseStore(object):
         self.event_factory = hs.get_event_factory()
         self._clock = hs.get_clock()
 
-    def runInteraction(self, txn, *args, **kwargs):
+    def runInteraction(self, func, *args, **kwargs):
         """Wraps the .runInteraction() method on the underlying db_pool."""
-        return self._db_pool.runInteraction(txn, *args, **kwargs)
+        def inner_func(txn, *args, **kwargs):
+            return func(LoggingTransaction(txn), *args, **kwargs)
+
+        return self._db_pool.runInteraction(inner_func, *args, **kwargs)
 
     def cursor_to_dict(self, cursor):
         """Converts a SQL cursor into an list of dicts.