JDBC setReadOnly呼び出しの問題を解決した話

こんにちは。Inflabのバックエンド開発者のINTとJayです。

InflabのバックエンドサーバーはほとんどがNode.jsで構成されていますが、一部JVMのサーバーも運用しています。
JVMサーバーでは、モニタリングにPinpointを活用しています。
最近、原因の特定が難しいエラーのアラートがPinpointから断続的に届きました。この記事では、その問題を解決するまでの経験を共有します。

問題が発生した環境

• Spring Boot 3.2.5
• Spring JDBC 6.1.6
• PostgreSQL Driver 42.6.2
• AWS Advanced JDBC Wrapper 2.2.3
• Amazon Aurora PostgreSQL 14.9.6

問題の状況

Pinpointでは、次のようなエラーメッセージを確認できました。
今回のエラーは、特定のAPIだけで発生するのではなく、不特定の参照系APIで断続的に発生していました。

エラーメッセージは次のとおりです。

Cannot change transaction read-only property in the middle of a transaction

Pinpointのログを見ると、エラーはトランザクションの最後にcommitとcloseを行う際に発生していました。

ここで、気になる点が見つかりました。

• コネクションを返却する際に、謎のクエリリクエストが発生している
• エラーが発生したにもかかわらず、その後ほかのトランザクションは正常に処理されている（APIは正常にレスポンスを返している）

エラーの発生箇所

まず、エラーメッセージからどのコードでエラーが発生したのかを特定しようとしました。
エラーメッセージは、「トランザクションの途中で読み取り専用プロパティは変更できない」という意味です。

Pinpointを見ると、エラー発生箇所の付近では PgConnection、ProxyConnection、PgStatement といったクラスが使われていました。
そこで、PostgreSQL JDBCドライバーの内部でエラーが起きているのではないかと考えました。

実際に、ドライバーの PgConnection クラス内部のsetReadOnlyメソッドに、同じエラーメッセージを出力するコードが見つかりました。

メソッドの最初の分岐に該当するとエラーが発生します。これは queryExecutor のトランザクション状態が IDLE ではない場合です。

queryExecutor.getTransactionState() は TransactionState 列挙型を返し、次の3つの状態を持ちます。

public enum TransactionState {
  IDLE,
  OPEN,
  FAILED
}

名前から予想できるとおり、トランザクション開始前は IDLE、トランザクションが開始されると OPEN になります。

PgConnection はJDBCの Connection インターフェースを実装しており、そのインターフェースの setReadOnly メソッドの説明は次のとおりです。

setReadOnly は、ドライバーにデータベース最適化のためのヒントを提供するメソッドであり、トランザクション中には呼び出せないと明記されています。

謎のクエリ

次に、トランザクション終了時に呼び出された謎のクエリを調べました。
Pinpointで確認できた実行クエリは次のとおりです。

SELECT SERVER_ID,
       CASE WHEN SESSION_ID = 'MASTER_SESSION_ID' THEN TRUE ELSE FALSE END,
       CPU,
       COALESCE(REPLICA_LAG_IN_MSEC, 0),
       LAST_UPDATE_TIMESTAMP
FROM aurora_replica_status()
WHERE EXTRACT(EPOCH FROM (NOW() - LAST_UPDATE_TIMESTAMP)) <= 300
   OR SESSION_ID = 'MASTER_SESSION_ID'

このクエリは、バックエンドサーバーのコード上には存在しませんでした。

ただ、FROM 句で aurora_replica_status() という関数を呼び出していることから、私たちが使っている Aurora PostgreSQL に関連するコードが発行したクエリだと推測しました。

AWS JDBCラッパードライバー

Amazon Aurora には、書き込みインスタンスがダウンしたときに、読み取りインスタンスの1つが書き込みインスタンスに昇格する failover 機能があります。
AWSでは、failover によって発生するダウンタイムを最小限に抑えるために、既存のJDBCドライバーをラップしたラッパードライバーを提供しています。

Inflabはメインデータベースとして Amazon Aurora PostgreSQL クラスターを使っており、1台の書き込みインスタンスと複数の読み取りインスタンスで構成されています。

JVMのバックエンドサーバーは講座ドメインを担当しており、決済や精算など、サービスの重要なドメインを扱っています。
そのため高い可用性が求められ、書き込みインスタンスが入れ替わる状況で素早いフェイルオーバー（fast failover）を実現するために、ラッパードライバーを使っています。

Failover Plugin

AWSのラッパードライバーは、fast failoverだけでなく、ほかにもさまざまな機能を提供しています。
ドライバーはそれらをプラグインの形で提供しており、ドライバーの設定で使いたいプラグインを有効にできます。
GitHubにある公式ドキュメントを見ると、failoverがどのように行われるのかが分かります。

アプリケーションでJDBCメソッドを実行すると、元のConnection（PgConnection）の代わりに、ドライバーがラップしたコネクションのメソッドが先に呼び出されます。
もし書き込みインスタンスに障害が発生した場合、ドライバーは内部のtopologyキャッシュを使って新しい書き込みインスタンスを探します。その後、物理コネクションを入れ替えることで、新たに昇格したインスタンスをより早く使えるようにします。

謎のクエリを実行しているのはこのラッパードライバーではないかと考え、ドライバーのリポジトリを調べたところ、謎のクエリと同じコードが見つかりました。
クエリを組み立てるメソッドの名前は getTopologyQuery で、クラスターの状態を確認して、書き込みインスタンスが入れ替わったかどうかを把握します。

以降、このクエリをtopologyクエリと呼びます。

原因の推論

ここまでの分析をまとめると、次のようになります。

• トランザクション終了時に、断続的にtopologyクエリが実行される
• このクエリは、AWSが提供するJDBCラッパードライバーの内部で実行される
• JDBCの setReadOnly メソッドは、トランザクション中には呼び出せない

これらから、次のようなシナリオでエラーが発生したと推論しました。

• (1) トランザクションの終了
• (2)TransactionState が IDLE に変わる
• (3) 特定の条件でtopologyクエリが実行される
• (4)TransactionState が再び OPEN に変わる
• (5)setReadOnly メソッドの呼び出し
• (6) エラーの発生

簡単な解決策

ここまでの分析から、このエラーを解決する最も簡単な方法は、AWSのラッパードライバーを使わないことです。
この問題は、ラッパードライバーがトランザクション終了時にtopologyクエリを実行することで起きているからです。

このドライバーを使っていたのは、前述のとおり書き込みインスタンスの障害によるダウンタイムを最小限にするためでした。
しかし、こうした障害が起きる頻度は高くありません。また、バックエンドサーバーの大部分を占めるNode.jsにはラッパードライバーがありません。そのため、一部のJVMサーバーだけに適用しても得られるメリットは大きくないと考えています。

それでも、次のような理由から、この方法は採用しませんでした。

• 前述の高い可用性を諦める選択肢は、できる限り避けたい
• 問題の根本的な原因を把握せずに、単にその原因を取り除くことが適切なのか疑問がある
• ドライバーの設定が正しくなかったことで発生した問題かもしれず、それを突き止めるほうが重要だと判断した
• 断続的に発生するエラーは原因の特定が難しいものの、解決に取り組む中で多くのことを学べると考えた

エラーの再現

デバッグ環境：IntelliJ IDEA 2024.2.3

根本的な原因を把握するには、ここまでの分析が正しいかを検証する必要があります。
また、次のような疑問を解消しなければなりません。

• topologyクエリがトランザクションの終了処理の中で実行されるのはなぜか？
• AWSドライバーは、どのような状況でtopologyクエリを実行するのか？
• トランザクションの終了処理の中で setReadOnly メソッドが呼び出されるのはなぜか？

そこで、ローカルでデバッグしてエラーを再現してみることにしました。
エラーは不特定の参照系APIで断続的に発生していたため、次のような方法を取りました。

• 任意の参照系APIを選ぶ
• エラー発生箇所にブレークポイントを設定し、デバッグモードでサーバーを起動する
• 負荷テストスクリプトを使って、選んだ参照系APIを繰り返し呼び出す

スクリプトを実行してしばらくすると、ブレークポイントで停止しました。

上の画面から分かる情報は、次のとおりです。

• (A) CourseApiRepository の findBySlug メソッドの実行時にエラーが発生
• (B) readOnly の状態を true に変えようとしている
• (C) TransactionStatus の状態は OPEN
• (D) 現在のコネクションの readOnly の値は true

推測どおり、TransactionStatus の状態が OPEN の状況で setReadOnly メソッドが呼び出されていました。
findBySlug メソッドは getCourseWithVoucher メソッドの中で実行されており、このメソッドで最初に呼び出されるクエリです。getCourseWithVoucher には @Transactional(readOnly = true) アノテーションが適用されています（アノテーションはクラスに付与）。

ここで、さらにいくつか疑問が出てきます。

• Pinpointではトランザクションをcommitする際にエラーが発生したと表示されているが、ローカルではトランザクションの最初のクエリで発生している
• PgConnection のreadOnlyの状態はすでに true になっている

内部ライブラリのコードを読み解く

Pinpointで確認した流れとは異なりますが、同じエラーが発生するよう再現した状況で、さらに詳しい情報が必要でした。

IntelliJ IDEAは、デフォルトでは内部ライブラリのコールスタックを1つにまとめてデバッグ画面に表示します。
私たちは内部ドライバーの動作を確認する必要があったので、スタック画面を右クリックし、Hide Frames from Libraries オプションのチェックを外します。

スタックの中身を見ると、次のとおりです。

ここで注目すべき点は次のとおりです。

• (A)、(B)、(C) setReadOnly メソッドはさまざまな Connection 実装で使われている
• HikariProxyConnection → ProxyConnection → ConnectionWrapper → PgConnection の順に呼び出されている
• (D) 最も外側で setReadOnly を呼び出しているクラスは、LazyConnectionDataSourceProxy の getTargetConnection

前述のラッパードライバーの説明どおり、実際のコネクションよりも先にラッパーのコネクションが使われています（B）。

次に、getTargetConnection を選択して、(D) setReadOnly メソッドの最初の呼び出し箇所を確認します。

このメソッドは名前のとおり（getTargetConnection）、トランザクションで使うためのコネクションをコネクションプールから取得します。
実行中の既存トランザクションがなければ this.target が null で、このときDataSourceからコネクションを取得して割り当てます。
その後このメソッドが再び呼び出されると、初回とは異なり、すでに割り当てられている this.target を返します。

このメソッドは、次の2つの条件をどちらも満たすときに、targetのsetReadOnlyを呼び出します。

• this.readOnly がtrue
• readOnlyDataSource がnull

デバッグメニューの式（下部のボックス）を見ると、this.readOnly はtrueで、readOnlyDataSource の値も null です。条件をすべて満たしているので、setReadOnly が呼び出されます。

this.readOnly はデフォルト値がfalseで、@Transactional(readOnly = true) アノテーションを使うとtrueに変わります。

Topologyキャッシュ

残っている疑問の1つである、AWSラッパードライバーがどのような状況でtopologyクエリを実行するのかを見ていきます。

先ほどお見せしたコネクション間のスタックトレースには、topologyクエリの呼び出し箇所は見当たりませんでした。
これは、すでにtopologyクエリを実行した後のスタックを表示しているためです。

そこで、topologyクエリを組み立てる getTopologyQuery メソッドを呼び出している箇所にブレークポイントを設定し、負荷テストを行いました。
getTopologyQuery メソッドを呼び出しているのは、ラッパードライバーの AuroraHostListProvider クラスの queryForTopology メソッドです。

queryForTopology メソッドは getTopology メソッドから呼び出されています。ここのブレークポイントで止まったときのスタックは次のとおりです。

ここから多くの情報が読み取れます。

• (A) AWSラッパードライバーの setReadOnly メソッドを呼び出す
• (B) FailoverConnectionPlugin の updateTopology メソッドが呼び出される
• (C) AuroraHostListProvider の getTopology メソッドを呼び出す
• (D) getTopology メソッドは topologyCache からホスト情報を取得する
• (E) ホスト情報が存在しなければtopologyクエリを実行する
• (F) 取得したクエリ結果をキャッシュに保存する
• (G) キャッシュの有効期限は30000000000ナノ秒（30秒）

ラッパードライバーは、JDBCの特定のメソッドが実行されると、topologyクエリを実行するかどうかを確認します。
topologyクエリを実行した場合は結果をキャッシュに保存し、キャッシュの有効期限が切れると再びtopologyクエリを実行します。

これで、次のシナリオが起きたときにエラーが発生することが分かりました。

• LazyConnectionDataSourceProxy の getTargetConnection メソッドが呼び出される
• this.target の setReadOnly メソッドが呼び出される
• AWSラッパードライバーの setReadOnly メソッドが呼び出される
• ちょうどtopologyキャッシュの有効期限が切れていて、topology クエリが実行される
• PgConnection の TransactionStatus の状態が OPEN に変わる
• PgConnection の setReadOnly メソッドが呼び出される
• エラーが発生する

通常は、LazyConnectionDataSourceProxy の getTargetConnection メソッドが取得したコネクションの setReadOnly メソッドを呼び出す時点では、まだクエリを1つも実行していません。そのため TransactionStatus の状態は IDLE で、setReadOnly メソッドを呼び出してもエラーは発生しません。

しかし、AWSラッパードライバーを使うと、PgConnection の setReadOnly を呼び出す前にtopologyキャッシュの有効期限を確認します。
もしキャッシュの有効期限が切れていれば、新たにtopologyクエリを実行することになり、setReadOnly の呼び出しより先に TransactionStatus の状態が OPEN に変わります。
その結果、エラーが発生してしまいます。

つまり、これらの条件がすべてそろったときにだけエラーが発生するため、不特定の参照系APIで断続的に発生していたのです。

最後の疑問の解消

まだ解消できていない疑問が1つあります。

それは、Pinpointで確認したエラーの発生タイミングと、ローカルでの発生タイミングが異なることです。
Pinpointではcommitメソッド、つまりトランザクションが終わるタイミングでエラーが発生していましたが、ローカルではトランザクションの開始時（最初のクエリを実行する部分）に発生しました。

ローカルでもcommitのタイミングで問題を再現するために、IntelliJ IDEAの条件付きブレークポイント機能を活用しました。

この機能を使うと、ブレークポイントを設定する際に、特定のブレークポイントに先にヒットした後でのみ、そのブレークポイントで停止するようにできます。
つまり、ブレークポイント間の前後関係を設定できます。

今回は、PgConnection の commit の後で setReadOnly のエラーが発生する瞬間を捉える必要があります。そこで、それぞれのメソッドにブレークポイントを設定し、setReadOnly メソッドのほうは条件付きブレークポイントにして、commit の後でのみ停止するようにしました。

これで負荷テストを実行したところ、狙いどおりの状況を再現できました。

次は、ブレークポイントで止まったときのスタックです。

ここからも、次のような情報が読み取れます。

• (A) commit が実行される
  • スタックトレースには表示されていないが、PgConnection の commit メソッドが呼び出される
  • そのため、TransactionStatus の状態が OPEN から IDLE に変わる
• (B) DataSourceUtils の resetConnectionAfterTransaction が実行される
• (C) このメソッドは、resetReadOnly の値が true の場合に setReadOnly を呼び出し、引数で false に変更する
  • resetReadOnly の値は、@Transactional アノテーションのreadOnlyオプションと同じ
• (D) ラッパードライバーの setReadOnly メソッドが呼び出される

これにより、トランザクションの終了時にも setReadOnly メソッドが呼び出されることが確認できました。

setReadOnly を実行しているメソッドの名前は resetConnectionAfterTransaction で、名前のとおりトランザクション終了時にコネクションをリセットするメソッドです。
このメソッドは、参照用に使われたコネクションだったかを確認し、書き込み用にも使えるよう setReadOnly を呼び出して false に変更します。

これは自然な動作ですが、ラッパードライバーを使う環境では、最初のクエリのときと同じ理由でエラーが発生する可能性があります。
ちょうどtopologyキャッシュの有効期限が切れてクエリが実行されると、TransactionStatus の状態が再び OPEN に変わったうえで setReadOnly メソッドが呼び出されるからです。

解決方法

ここまでで、トランザクションの開始時と終了時に setReadOnly メソッドが呼び出される状況と、それによるエラーの原因を把握しました。
では、これを解決する方法を共有します。

setReadOnlyDataSource

ラッパードライバーは、JDBCのメソッドを実行する前にtopologyキャッシュを確認し、有効期限が切れていれば新たにクエリを実行します。
しかし、setReadOnly メソッドは TransactionStatus の状態がIDLEのときに呼び出す必要があります。その直前にtopologyクエリが実行されてしまうと、エラーが発生します。

ラッパードライバーのコードを修正する方法もありますが、私たちは先ほど見た LazyConnectionDataSourceProxy のコードから別の方法を見つけました。

それは、getTargetConnection メソッドで setReadOnly メソッドが呼び出されないよう、黄色の分岐を false にすることです。

this.readOnly は @Transactional の readOnly オプションによって決まる値なので、この値を false に変えることはできません。
しかし、readOnlyDataSource の値は setReadOnlyDataSource メソッドで設定できます。

このメソッドはSpring 6.1.2で追加されたもので、読み取り専用のDataSourceを設定します。

Javadocを読むと、読み取り専用のDataSourceは readOnly のデフォルト値があらかじめ true に設定されていることを前提としているので、トランザクションの開始時と終了時に毎回 readOnly の値を切り替えることはしない、という一文が目に留まりました。

その前に、「読み取り専用のDataSourceは readOnly のデフォルト値が true に設定されていることを前提とする」とはどういうことかを確認しておきます。

私たちは1つの書き込みインスタンスと複数の読み取りインスタンスを使っているため、DataSourceも書き込み用と読み取り用に分けて使っています。
そして、読み取り専用のDataSourceは readOnly のデフォルト値を true に設定していました。

spring:
  datasource:
    writer:
      driverClassName: 'software.amazon.jdbc.Driver'
      jdbcUrl: '書き込みインスタンスのURL'
    reader:
      driverClassName: 'software.amazon.jdbc.Driver'
      jdbcUrl: '読み取りインスタンスのURL'
      read-only: true

このオプションによって、コネクションプールでコネクションを作成する際に readOnly の値を true に設定します。
これが、前のエラーの再現のセクションで、PgConnection の setReadOnly メソッドが呼び出される時点で readOnly の値がすでに true に設定されていた理由でした。

LazyConnectionDataSourceProxyの追加機能

setReadOnlyDataSource メソッドによって、新たに得られた機能があります。
それは、@Transactional の readOnly オプションに応じてDataSourceを振り分けられることです。

LazyConnectionDataSourceProxy は、実際にクエリの呼び出しが必要になる時点まで、JDBCコネクションの作成を遅延させます。
このクラスの getTargetConnection メソッドが呼び出される時点こそが、コネクションが作成される時点です。

このメソッドは内部で getDataSourceToUse メソッドを呼び出しています。getDataSourceToUse は、readOnly オプションに応じて適切なDataSourceを返します。

this.readOnly の値が true で、かつ readOnlyDataSource が設定されていれば readOnlyDataSource を返し、そうでなければ targetDataSource を返します。
これにより、targetDataSource には書き込み用のDataSourceを、readOnlyDataSource には読み取り専用のDataSourceを設定すれば、トランザクションのreadOnlyオプションに応じてDataSourceを振り分けられます。

最終的な設定

私たちは、もともとDataSourceの振り分けに RoutingDataSource を使っていました。

現在は、次のように修正して使っています。

まとめ

• AWSラッパードライバーを使う環境で、トランザクション終了時に setReadOnly を呼び出すと、断続的にエラーが発生する
• PgConnection の setReadOnly メソッドは、トランザクション中には呼び出せない
• ラッパードライバーのFailoverプラグインは、クラスターの状態を確認するためにtopologyクエリを実行する
• IDEのデバッグ機能を活用して、原因の再現と分析を行った
• トランザクションの開始時と終了時の setReadOnly 呼び出しの際にtopologyクエリが実行されると、エラーが発生することを確認した
• LazyConnectionDataSourceProxy の setReadOnlyDataSource メソッドで読み取り専用のDataSourceを設定して解決した

おわりに

ここまで、JDBCのsetReadOnlyに関する問題の原因の説明と、解決までの流れを共有しました。

簡単に解決する方法もある問題でしたが、粘り強くデバッグを続けたことで、Springがトランザクションをどのように管理しているのかを理解できました。
また、これまで何気なく使ってきたドライバーの内部動作も理解できました。

次回も、より役立つ記事をお届けします。
長文を最後まで読んでいただき、ありがとうございました。

※この記事は2024年9月1日に執筆されたものです。