SQLAlchemyのquery実行時に出力されるログ

INFO 2020-12-01 00:00:00 SELECT table.col1, table.col2
FROM table
WHERE table.pk1 = %(primary_1)s AS anon_1 [in 略/sqlalchemy/engine/base.py:1151]
INFO 2020-12-01 00:00:00 {'primary_1': 'value'} [in 略/sqlalchemy/engine/base.py:1154]

この出力って凄く見づらいんですよね。
どうにかならんものかなぁと思って調べてみたんです。

地道に頑張るパターン

class Session(object):
    def __exit__(self, exc_type, exc_value, traceback):
        # 略
        for st in self._profiler.statements_with_parameters:
            query = st[0] % st[1]
            logger.info("[SQL] %s" % query)

SQLAlchemyの発行する見づらいSQLをそのまま当て込んで使うパターンですね。
これだと文字列が””とかで囲われないので型が分かりにくい問題点があります。

正しいパターン

def find_by_pk():
    query = session.query(table).filter(table.pk1 = "value")
    logger.info(query.statement.compile(dialect=mysql.dialect(),
                               compile_kwargs={"literal_binds": True}))

INFO 2020-12-01 00:00:00 SELECT table.col1, table.col2
FROM table
WHERE table.pk1 = 'value' AS anon_1 [in loggerが呼ばれた場所]

どうやらsession.queryに発行されたSQLが保持されているようで、それを使うことできれいに出力することができました。
ただ、検証したバージョン(1.2.0)はバグが含まれているようで、'value'の部分にdatetime型が入るとエラーになります。
チケットが発行されていたので最新版では修正されているとは思います。(未確認)

参考

SQLAlchemyが生成するクエリを確認する
 NotImplementedError: Don't know how to literal-quote value date time.datetime
String compiler can now literal compile date time objects