graphql-javaを使っていて、@deprecatedのdirectiveをつけているのに、ずっとアクセスがあるので、どのクエリがアクセスしてくんの？ってなりました。そこで、このクエリを見つけようと思います。
tl;dr
以下をコピペすればOK
@Component class LogDeprecatedQueryInstrumentation : SimpleInstrumentation() { private val log = LoggerFactory.getLogger(LogDeprecatedQueryInstrumentation::class.java) private val deprecatedFieldMap = mutableMapOf<String, MutableSet<String>>() override fun beginExecution(parameters: InstrumentationExecutionParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginExecution(parameters) val id = parameters.executionInput.executionId.toString() val query = parameters.query.takeIf { it.isNotBlank() } ?: return super.beginExecution(parameters) return whenCompleted { _, _ -> if (deprecatedFieldMap[id]?.isNotEmpty() == true) { log.warn( """ |Accessing deprecated field: ${deprecatedFieldMap[id]?.joinToString()} |Query: |$query """.trimMargin() ) } deprecatedFieldMap.remove(id) } } override fun beginField(parameters: InstrumentationFieldParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginField(parameters) val id = parameters.executionContext.executionId.toString() if (parameters.field.isDeprecated) { if (deprecatedFieldMap.containsKey(id)) { deprecatedFieldMap[id]?.add(parameters.field.name) } else { deprecatedFieldMap[id] = mutableSetOf(parameters.field.name) } } return super.beginField(parameters) } }
想定読者
- graphql-javaでの開発をしたい、している人
- graphql-spring-boot-starterを使ったことがある人
@deprecated
まず最初に@deprecated、これはgraphql-java自体がデフォルトでバンドルしているdirectiveの一つです。directiveに関しては様々なところでその存在含め議論されていますが、一旦ここでは忘れることにします。公式ドキュメントを見てもらえれば、わかりますが、@deprecatedはSDLのフィールドとEnumにつけることが可能で、これをつけることにより、そのフィールドやEnumは非推奨であるということをSDL上で宣言することが可能です。
type Drug {
# 医薬品名
name: String!
# 効能効果
description: String @deprecated(reason: "No longer supported")
}
type Query {
# 薬名から薬情報を取得する
drugsByName(name: String!) : [Drug!]
}
ちなみに余談ですが、この設定をして、GraphiQLを起動すると、deprecatedのワーニングが出ます。
新規クエリに関してはこれを見てもらえれば明確であるため、わかるのですが、問題はすでに動いているクエリです。@deprecatedを後でつけたとしても、利用側はそれに気づくことはできません。
クエリをログに吐く
どんなクエリがリクエストされているかはいくつかの方法でログにすることが可能です。今回はInstrumentationを使ってログを出力してみます。
Instrumentation
[Instrumentation] allows you to inject code that can observe the execution of a query and also change the runtime behaviour.
クエリ実行中に何が起こっているのか確認したり、実行時の挙動を変えたりするための仕組みです。
実装はInstrumentationやSimpleInstrumentationなどのクラスを継承するだけです。(instrumentationの登録方法はgraphql-java-kickstartを使っていると、@Componentなどにすれば、特に何もせずに登録されるため、ここでは一旦省略します。)
@Component class LogDeprecatedQueryInstrumentation : SimpleInstrumentation() { }
Instrumentationには様々なタイミングでコードをInjectする方法が提供されています。
/** * This is called right at the start of query execution and its the first step in the instrumentation chain. * * @param parameters the parameters to this step * * @return a non null {@link InstrumentationContext} object that will be called back when the step ends */ InstrumentationContext<ExecutionResult> beginExecution(InstrumentationExecutionParameters parameters);
beginExecutionはクエリの実行が始まる直前に呼ばれるメソッドです。引数は InstrumentationExecutionParameters でこのオブジェクトには実行前のクエリ情報やスキーマ情報が格納されています。
@Component class LogDeprecatedQueryInstrumentation : SimpleInstrumentation() { private val log = LoggerFactory.getLogger(LogDeprecatedQueryInstrumentation::class.java) override fun beginExecution(parameters: InstrumentationExecutionParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginExecution(parameters) log.info(parameters.query) return super.beginExecution(parameters) } }
これでクエリを実行してみると以下のようにクエリがログに出力されます。
INFO a.u.m.p.i.LogDeprecatedQueryInstrumentation - {
drugsByName(name: "ハチミツ") {
name
description
}
}
deprecatedフィールドをログに吐く
次にフィールドが @deprecated を判定したいです。各フィールドにアクセスする度に実行されるメソッドは beginField です。
/** * This is called just before a field is resolved into a value. * * @param parameters the parameters to this step * * @return a non null {@link InstrumentationContext} object that will be called back when the step ends */ InstrumentationContext<ExecutionResult> beginField(InstrumentationFieldParameters parameters);
引数は InstrumentationFieldParameters その取得しようとしているフィールドの情報が格納されています。そのフィールドに @deprecatedがついているかどうか？は parameters.field.isDeprecated で確認できます。
public boolean isDeprecated() { return deprecationReason != null; }
isDeprecatedの実装が若干本当にそれで判断するの！？って初見で驚きましたが、見なかったことにしましょう。
実際にそのフィールドが@deprecatedだった場合、フィールド名とそのパスをログ出力するようにしてみます。
@Component class LogDeprecatedQueryInstrumentation : SimpleInstrumentation() { private val log = LoggerFactory.getLogger(LogDeprecatedQueryInstrumentation::class.java) override fun beginField(parameters: InstrumentationFieldParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginField(parameters) if (parameters.field.isDeprecated) { log.info(parameters.field.name) } return super.beginField(parameters) } }
そうするとこんな感じのログが出ました。
INFO a.u.m.p.i.LogDeprecatedQueryInstrumentation - description INFO a.u.m.p.i.LogDeprecatedQueryInstrumentation - description INFO a.u.m.p.i.LogDeprecatedQueryInstrumentation - description INFO a.u.m.p.i.LogDeprecatedQueryInstrumentation - description INFO a.u.m.p.i.LogDeprecatedQueryInstrumentation - description INFO a.u.m.p.i.LogDeprecatedQueryInstrumentation - description
6回出力されているのは、"はちみつ"という名前のついている薬が6個あるためです。（はちみつは薬です。）
[余談] N+1問題で障害発生
6回出力されている時点で明確なのですが、beginFieldメソッドは出力するフィールド全てで出力されます。
要するにこのメソッドはN+1問題が確実に発生するメソッドであるので、注意が必要です。
当初、自分はinfoログではなく、errorログを出力するように実装していました。
override fun beginField(parameters: InstrumentationFieldParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginField(parameters) if (parameters.field.isDeprecated) { log.error(parameters.field.name) } return super.beginField(parameters) }
この処理を本番に出した結果、本番で障害を出しました (テヘペロ
理由として、これは完全に見落としだったのですが、errorログを出力するとSentryへのワーニングを出力するように設定されていました。 QA環境やステージング環境でもSentryへのワーニングが発生していたのですが、本番と違いそこまで負荷がかからず、通知も数件という感じで問題ない判定になっていました。 しかしそこは本番環境、アクセスが多く、Deprecatedフィールドへのアクセスもあり、Sentryへの通知をめちゃめちゃしてしまいました。 この通知処理があまりに多く、サーバがその負荷に耐えられずにダウンしてしまっていました。 infoログ(通知なし)に変えたら、問題なく動き出したときは、人生で初めてログ出力変えることによって動くようになるプログラム書いてしまったか・・・という衝撃を受けました。
deprecatedフィールドを一回だけ出力する(方針編)
話を戻して、deprecatedフィールドへのアクセスを検知したら、クエリ毎に一回だけ出力されれば十分であるため、一回のみ出力されるように修正します。
方針として以下となります。
- beginExecutionでクエリを取得
- beginFieldでdeprecatedフィールドの検知をする
- 全ての処理が終わった時に、deprecatedフィールドがある場合、クエリをログ出力する
こんな感じの方針で行こうと思います。
whenCompletedメソッド
InstrumentationやSimpleInstrumentationクラスは全て begin しか提供されていません。終わった時の処理はwhenCompletedメソッドを利用します。
/**
* Allows for the more fluent away to return an instrumentation context that runs the specified
* code on instrumentation step completion.
*
* @param codeToRun the code to run on completion
* @param <U> the generic type
*
* @return an instrumentation context
*/
public static <U> SimpleInstrumentationContext<U> whenCompleted(BiConsumer<U, Throwable> codeToRun) {
return new SimpleInstrumentationContext<>(null, codeToRun);
}
使い方は各種beginメソッド内で利用可能です。
class LogDeprecatedQueryInstrumentation : SimpleInstrumentation() { private val log = LoggerFactory.getLogger(LogDeprecatedQueryInstrumentation::class.java) override fun beginExecution(parameters: InstrumentationExecutionParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginExecution(parameters) log.info("beginExecution[${parameters.executionInput.executionId}]") return whenCompleted { _, _ -> log.info("beginExecution[${parameters.executionInput.executionId}] - whenCompleted") } } override fun beginField(parameters: InstrumentationFieldParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginField(parameters) log.info("beginField[${parameters.field.name}]") return whenCompleted { _, _ -> log.info("beginField[${parameters.field.name}] - whenCompleted") } } }
実際に使ってみるとこんな感じのログになります。
beginExecution[034a160a-4c3a-498f-a305-43f954445fb9] // -- (1) beginField[drugsByName] // -- (2) beginField[name] // -- (3) beginField[name] - whenCompleted // -- (4) beginField[description] // -- (5) beginField[description] - whenCompleted beginField[name] beginField[name] - whenCompleted beginField[description] beginField[description] - whenCompleted beginField[name] beginField[name] - whenCompleted beginField[description] beginField[description] - whenCompleted beginField[name] beginField[name] - whenCompleted beginField[description] beginField[description] - whenCompleted beginField[name] beginField[name] - whenCompleted beginField[description] beginField[description] - whenCompleted beginField[name] beginField[name] - whenCompleted beginField[description] beginField[description] - whenCompleted beginField[drugsByName] - whenCompleted // -- (6) beginExecution[034a160a-4c3a-498f-a305-43f954445fb9] - whenCompleted // -- (7)
- (1)でbeginExecutionの最初のログが出力されます。
- (2)でbeginFieldのdrugsByNameのログが出力されます。GraphQLではメソッド定義？もフィールド扱いです。
- (3)でnameフィールドのログ、(4)でそのフィールドへのアクセスが終わった時のログ
- (5)で次のdescriptionフィールドのログ
- (6)で(2)でアクセスしていたdrugsByNameへのアクセスが終わった時のログ
- (7)でクエリ実行全体が終わった時のログ
executionId
whenCompletedメソッドの実装時にしれっと使いましたが、executionIdというものがexecution毎に振られます。このIDはexecution毎にユニークで、どのexecutionの処理をしているのかを確認することが可能になります。
class LogDeprecatedQueryInstrumentation : SimpleInstrumentation() { private val log = LoggerFactory.getLogger(LogDeprecatedQueryInstrumentation::class.java) override fun beginExecution(parameters: InstrumentationExecutionParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginExecution(parameters) log.info("beginExecution[${parameters.executionInput.executionId}]") return whenCompleted { _, _ -> log.info("beginExecution[${parameters.executionInput.executionId}] - whenCompleted") } } override fun beginField(parameters: InstrumentationFieldParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginField(parameters) log.info("beginField[${parameters.executionContext.executionId}]") return whenCompleted { _, _ -> log.info("beginField[${parameters.executionContext.executionId}] - whenCompleted") } } }
例えばこんな感じの実装で確認してみます。ログ出力してみると
beginExecution[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginField[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted beginExecution[a83e77aa-8f51-4499-95af-75c4240ab0b7] - whenCompleted
一つのクエリ実行が完了するまで同じIDになります。ちなみにこんなクエリを実行してみます。
{
one: drugsByName(name: "ハチミツ") {
name
description
}
two: drugsByName(name: "ロキソプロフェン") {
name
description
}
}
複数のフィールドへのアクセスですが、クエリの実行としては同一であるため、同じIDで全て実行されています。
beginExecution[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted // 長いので省略 beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginField[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted beginExecution[60010edd-dd6c-4490-a3d9-fa92e167ce45] - whenCompleted
Exceptionが出た時もwhenCompletedは実行されてます。以下がRuntimeExceptionが出た時のログです。
beginExecution[9e729dab-5fbe-4611-b6db-22c0a1f78406] beginField[9e729dab-5fbe-4611-b6db-22c0a1f78406] Exception while fetching data (/drugsByName) : エラーだよ java.lang.RuntimeException: エラーだよ // stacktrace beginField[9e729dab-5fbe-4611-b6db-22c0a1f78406] - whenCompleted beginExecution[9e729dab-5fbe-4611-b6db-22c0a1f78406] - whenCompleted
deprecatedフィールドを一回だけ出力する(実装編)
方針をもう一度確認します。
- beginExecutionでクエリを取得
- beginFieldでdeprecatedフィールドの検知をする
- 全ての処理が終わった時に、deprecatedフィールドがある場合、クエリをログ出力する
こちらですが、whenCompletedメソッドを使うことにより、beginFieldでアクセスできるInstrumentationExecutionParametersにクエリ実行後にもアクセスできるため、クエリの取得とログ出力は同時に可能です。新しい方針としてはこんな感じに
- beginFieldでdeprecatedフィールドの検知をする
- beginExecutionのwhenCompletedでdeprecatedフィールドがある場合、クエリをログ出力する
deprecatedフィールドを検知した場合、先ほどのexecutionIdを何処かに格納して、beginExecutionのwhenCompletedでログ出力、不必要になったexecutionIdは削除という感じで実装していきます。 で、今回は簡単にフィールド変数に格納しましょう。
@Component class LogDeprecatedQueryInstrumentation : SimpleInstrumentation() { private val log = LoggerFactory.getLogger(LogDeprecatedQueryInstrumentation::class.java) private val deprecatedFieldMap = mutableMapOf<String, MutableSet<String>>() override fun beginExecution(parameters: InstrumentationExecutionParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginExecution(parameters) val id = parameters.executionInput.executionId.toString() val query = parameters.query.takeIf { it.isNotBlank() } ?: return super.beginExecution(parameters) return whenCompleted { _, _ -> if (deprecatedFieldMap[id]?.isNotEmpty() == true) { log.warn( """ |Accessing deprecated field: ${deprecatedFieldMap[id]?.joinToString()} |Query: |$query """.trimMargin() ) } deprecatedFieldMap.remove(id) } } override fun beginField(parameters: InstrumentationFieldParameters?): InstrumentationContext<ExecutionResult> { parameters ?: return super.beginField(parameters) val id = parameters.executionContext.executionId.toString() if (parameters.field.isDeprecated) { if (deprecatedFieldMap.containsKey(id)) { deprecatedFieldMap[id]?.add(parameters.field.name) } else { deprecatedFieldMap[id] = mutableSetOf(parameters.field.name) } } return super.beginField(parameters) } }
で、これを実行してみると
Accessing deprecated field: description
Query:
{
drugsByName(name: "ハチミツ") {
name
description
}
}
これで障害起こさず、悪いクエリを見つけることが出来ました。
まとめる
まとめると
- InstrumentationやSimpleInstrumentationなどのクラスで出力されるフィールドベースでアクセスすることが可能
- beginメソッドを使いのなしてね
- beginFieldはN+1になるので扱い注意！
- beginFieldはN+1になるので扱い注意！
- whenCompletedメソッドはそのアクセスが終わった後に呼ばれるよ
終わり。
