quill-finagle-mysqlでクエリログがINFOログとして出るのを抑える

問題

io.getquill.FinagleMysqlContext を使っていると、SQLが実行されるたびにINFOログにSQLが吐かれます。

SQLログの例

04:52:19.634 [finagle/netty3-4] INFO  io.getquill.FinagleMysqlContext - SELECT x3.id, x3.first_name, x3.last_name, x3.gender, x3.age, x3.created_at, x3.updated_at FROM user x3 WHERE x3.id = ?

デバッグ用途には便利ですが、本番運用を考えるとINFOログに全クエリが出るのは困る人も多いのではないでしょうか。

せめてDEBUGレベルで出るなら良いんだけど... と思っても、INFOレベルで出すようにハードコードされています。
https://github.com/getquill/quill/blob/19010f943d44908ead5a58c91304b41df86acb97/quill-finagle-mysql/src/main/scala/io/getquill/FinagleMysqlContext.scala#L71

解決策: io.getquill.FinagleMysqlContextの出すログをWARN以上にする

logback.xmlに少し書くだけです。

logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>

  <!-- Suppress INFO level log by quill-finagle-mysql -->
  <logger name="io.getquill.FinagleMysqlContext" level="WARN">
    <appender-ref ref="STDOUT" />
  </logger>

</configuration>

重要なのは <logger name="io.getquill.FinagleMysqlContext" level="WARN"> の行です。
LoggerFactory.getLogger()で作ったFinagleMysqlContext用のロガーに関しては、WARN以上のレベルのログしか出さないようにしています。

それ以外の出処のログは、ちゃんとINFO以下のログも出ます。

logback.xml 修正前のログ

```sql:logback.xml修正前

Server Started: verbose-service-server

AdminHttp -> http://127.0.0.1:45407/admin
ExternalThrift -> thrift://127.0.0.1:35583
04:52:19.389 [finagle/netty3-4] INFO ClockedDrainer - Drainer is disabled; bypassing
04:52:19.620 [finagle/netty3-4] INFO c.g.l.q.c.VerboseServiceController - info!
you said "hi :D"
04:52:19.634 [finagle/netty3-4] INFO io.getquill.FinagleMysqlContext - SELECT x3.id, x3.first_name, x3.last_name, x3.gender, x3.age, x3.created_at, x3.updated_at FROM user x3 WHERE x3.id = ?
04:52:19.754 [finagle/netty3-2] INFO c.t.f.t.filters.AccessLoggingFilter - EmbeddedVerboseServiceTest 12/Feb/2017:04:52:19 +0000 'echo' 139

### `logback.xml` 修正後のログ
```sql:`logback.xml`修正後
===========================================================================
Server Started: verbose-service-server
===========================================================================
AdminHttp      -> http://127.0.0.1:38567/admin
ExternalThrift -> thrift://127.0.0.1:38827
06:47:07.446 [finagle/netty3-4] INFO  ClockedDrainer - Drainer is disabled; bypassing
06:47:07.524 [finagle/netty3-4] INFO  c.g.l.q.c.VerboseServiceController - info!
	you said "hi :D"
06:47:07.563 [finagle/netty3-2] INFO  c.t.f.t.filters.AccessLoggingFilter - EmbeddedVerboseServiceTest 12/Feb/2017:06:47:07 +0000 'echo' 41

SQLに関するINFOログが1行だけ消えていることがわかります。

動くサンプル

$ sbt test

できるサンプルを https://github.com/laysakura/finatra-quill-suppress-query-log に置いています。
本記事の修正内容のPRも合わせて見ていただければと思います。

広告

株式会社FOLIOでは、ググって情報がなくてもソースを見て問題解決ができる、次世代オンライン証券を構築するエンジニアを募集中です。