latestタグのままdocker imageを本番運用してどうなったか

latestタグや書き換えるためのタグ(develop, stagingなど)を使って、本番で運用するのはやめましょう。 コンテナイメージのキャッシュ状況やリリースフローによっては予期しない形で 予期しないバージョンが本番で起動する可能性があります。

本記事では、どのプラットフォームやツールで発生したかについては記載しません。 本題はそこではないのと、そもそも運用が間違っているので 記述しても余計な枝葉になるからです。

この記事ではどういうことが起きたか、について書きます。

どういうことが起きたか

サービスで、dockerイメージのlatestタグを使って本番運用していた。 全コンテナをgraceful restartしたようだ。(つもりだったが・・・)

別の作業中、管理画面の表示がおかしくなっているという話が出てきた。 そこで調べてもらったところ、なぜかリリースしたはずの機能が正常に機能していない、という連絡を受けた。 また、影響範囲としてはデータの欠損が発生しているようだということも分かった。

そこで、用意してあったビルド時のgitのコミットハッシュを調べるエンドポイントを何回かリロードしたところ 二種類のハッシュが帰ってくることを確認した、

このことから、ロードバランサーの下に複数のバージョンのコンテナが紐づいていることが分かったので コミットハッシュからどういう状態のアプリケーションがデプロイされているかを確認したところ とある機能が実装されているバージョンとされていないバージョンがデプロイされていることが分かった。 データの欠損もこれが原因だと分かった。 また、プラットフォームの画面からコンテナを見ると、実行開始時間が直近の物とちょっと古いものが混ざっているのも確認できた。

ここで幸運だったのが、元々latest運用されていたが どういう対応でバージョンを固定するかを考えていたので、以下の状態にしていったのが幸運だった。

  • latestではなく書き換えしない前提のgitのコミットハッシュでタグ付けしたdocker imageがある状態
  • 本番で運用しているバージョンをすぐに変更できる状態

だが、まず本番で運用しているバージョンを変更する前にトリアージをする必要があると考え 問題を対処している時間はサービスのピークタイムを過ぎていたので、データ欠損の影響を少なくするために、古いコンテナをぶつり落とした。 落としたタイミングでリロードをしてみたところ、何件かロードバランサーから502が帰ってきたようだ。 その後、新しいコンテナが立ち上がってきたのを確認した。

が、しかし、今度は新しすぎるコンテナが立ち上がってきたのを観測した(本番に影響のある差分がなかったのが幸運だった)

ここで、本来あるべきバージョンで固定するために 本番で運用しているバージョンをlatestからgitのコミットハッシュのバージョンに固定化して 難を逃れた。

まとめ

今回は、latestイメージを運用していてどうなったか、という話を書いた。

少し振り返ると、 幸運だったのは

  • 動いているアプリケーションがどういう状態で動いているか外から調べられるように作っていたこと
  • latestイメージでの運用がダメということが分かっていた
  • 本番で動作するバージョンをすぐに変更できるようにしていたこと
  • データの欠損が直接サービスに影響するものでなかったこと(リアルタイム性が必要のないデータだったこと)
  • latestイメージで運用することがどういうことかを分かってもらえたこと
  • サービスに大きい影響は出ず、サービスの利用に問題がなかったこと

不幸だったのは

  • latestイメージで運用していたこと
  • latestイメージで運用していてバージョン違いのコンテナが混ざったこと
  • データの欠損が発生してしまったこと
  • 利用中にエラーが発生せず、気づくのが遅れてしまったこと
    • 実装の方向性を直しておけば回避できたように思う(requiredなカラムがnullableだった)

こんな感じだったように思う。 サービスに大きい影響は出ず、利用に問題がなかったのは良かったことだが、発見が遅れてしまった原因でもある。 全体的に見ると、幸運だったように思う。

最後に僕から言いたいことは「latestタグや書き換える前提のタグで運用をするのはやめましょう」です。

僕はデータの欠損を直すタスクを新たに積みました。

JUnit JupiterのAutomatic Extension Detectionを使って簡単にテストのログにコンテキストを付与する

今回使った実装を使えば、どういうテストで実行された処理なのかが明確に分かるようになります。

使い方です。

class MdcExtensionTest {

  @Test
  public void test() {
    assertThat(MDC.get("test.displayName")).isNotNull();
    assertThat(MDC.get("test.id")).isNotNull();
  }

}

使い方は、テストを書くだけです。(この表現には誇張があります。)

冗談はさておき、今回の記事では、JUnit JupiterのAutomatic Extension Detectionを使ってテストのログにコンテキストを付与してみます。

また、今回の記事は以下の流れで説明します

  • はじめに
  • どう見やすくするか
  • 今回実装したExtensionの実装
  • 最初のサンプルはどうやって動いていたのか
  • JUnit JupiterのAutomatic Extension Detectionを有効にする
  • ログを追加して試してみる

はじめに

まず初めに、Gradleから吐き出される以下のようなテストのレポートを見たことをある方はいますか?

f:id:reteria:20200122095950p:plain

見たことない人もいるかもしれないので 改めて注意して見て欲しい部分があります。 それは、Standard Outputの部分です。

f:id:reteria:20200122100049p:plain

これ、1つのテストクラス(!= テスト)で発生した標準出力をまとめてくれています。 しかし、この状態では、どのテストでログが出力されたのかは、テストとログを眺めながら調べることでしか分かりません。

そこで、この記事では、よりテストのログを活用するために、MDCにテストのコンテキストを注入することで よりテストのログを見やすくしてみます。

MDCはslf4jのAPIにありますが、Mapped Diagnostic Contextの略です。 MDCについての詳しい説明は slf4jの実装であるlogbackのドキュメントを読むと良いでしょう。

第8章 診断コンテキスト

どう見やすくするか

以下のステップを踏むことでよりテストのログがどのテストから出力されたのか分かりやすくなるはずです。

  • JUnit JupiterのExtensionを使ってMDCに値を設定する
  • ログに MDCの値を出力するようにする

また、どんな値をMDCに設定していると見やすいかと考えると以下のようなものが考えられます。

  • テストクラス名
  • テスト名
  • テストのID

他にもあるかもしれませんが、ここでは上記の値をMDCに設定して試してみます。

今回実装したExtensionの実装

今回実装したExtensionの実装は以下のようなシンプルなコードです。

@AutoService(Extension.class)
public class MdcExtension implements BeforeEachCallback, AfterEachCallback {

  @Override
  public void beforeEach(ExtensionContext context) throws Exception {
    final Optional<String> classNameOpt = context.getTestClass()
      .map(Class::getName);
    classNameOpt.ifPresent(className -> MDC.put("test.class", className));
    if (!classNameOpt.isPresent()) {
      context.getTestInstance()
        .ifPresent(instance -> MDC.put("test.class", instance.getClass()
          .getName()));
    }
    MDC.put("test.displayName", context.getDisplayName());
     // context.getUniqueId()もあるが、uuidのような文字列ではないのでここではUUIDを使っている
    MDC.put("test.id", UUID.randomUUID().toString());
  }

  @Override
  public void afterEach(ExtensionContext context) throws Exception {
    MDC.remove("test.displayName");
    MDC.remove("test.class");
    MDC.remove("test.id");
  }
}

beforeEachでMDCに値を設定して afterEachでクリーンアップしているだけですね。

感の良い方はここで気づくと思うんですが JUnit JupiterのAutomatic Extension DetectionはServiceLoaderの仕組みを使っています。

最初のサンプルはどうやって動いていたのか

まず。最初のサンプルはどうやって動いていたのか説明すると 以下のようなステップを踏むことで、個別のテストにExtensionの記述をすることなく Extensionを暗黙的に使うことができます。

  • JUnit JupiterのAutomatic Extension Detectionを有効にする
  • ServiceLoaderの設定を含むライブラリを依存関係に含める

では、次はJUnit JupiterのAutomatic Extension Detectionの有効の仕方を見ていきます。

JUnit JupiterのAutomatic Extension Detectionを有効にする方法

まず、JUnit JupiterのAutomatic Extension Detectionはデフォルトでは有効になっていません。 そのため、このAutomatic Extension Detectionを有効にする方法を見ていきます。

公式のリファレンスとしては以下の箇所に説明がありますが この記事にも書いておきます。 JUnit 5 User Guide

まず、テストの起動方法によって変わる方法として、以下のような設定方法があります。

  • Console Launcherを使っている人は --config オプション
  • Gradleを使っている人は systemPropertysystemProperties から
  • Mavenを使っている人は Maven Surefire Pluginの configurationParametersから

また、テストの起動方法によらない設定方法として以下があります。

  • JVMシステムプロパティ
  • クラスパスのルートに置かれた、junit-platform.properties

今回は、junit-platform.propertiesを使って説明します。 他の設定方法については、ドキュメントを参照してください。

Automatic Extension Detectionを有効にするには、以下のように junit-platform.properties に記述を加えれば良いです。

junit.jupiter.extensions.autodetection.enabled=true

また、Automatic Extension DetectionではServiceLoader経由でExtensionを探索します。 ServiceLoaderの利用方法等については他の記事に任せるのでググってください。

ログを追加して試してみる

では、最初のサンプルにログを追加して試してみます。

雑な感じで用意したlogback-test.xmlを以下に示します。

<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                %d{yyyy-MM-dd HH:mm:ss} %-5level class: %X{test.class} id: %X{test.id} test: %X{test.displayName} %logger{36} - %msg%n
            </Pattern>
        </layout>
    </appender>


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

</configuration>

また、最初のテストにログを追加しました。

class MdcExtensionTest {

  Logger log = LoggerFactory.getLogger(MdcExtensionTest.class);

  @Test
  public void test() {
    assertThat(MDC.get("test.displayName")).isNotNull();
    assertThat(MDC.get("test.id")).isNotNull();
    log.info("MDCExtension test is end.");
  }

}

以下のようなログが出力されました。

2020-01-22 09:46:59 INFO  class: com.github.wreulicke.bricks.junit.jupiter.MdcExtensionTest id: 5ead17d4-b107-4541-b6a5-9c4cd5c05f7a test: test() c.g.w.b.j.jupiter.MdcExtensionTest - MDCExtension test is end.

まとめ

今回の記事では、JUnit JupiterのAutomatic Extension Detectionを使って Extensionを自動的に適用することで、個別のテストにExtensionの設定を記述することなく テストのログにMDCを介してコンテキストを付与してみました。 これで、テストのログが少し追いかけやすくなるのではないでしょうか。

また、今回はやらなかったんですが、JUnit5のExtensionの様々なCallbackでログを出力すれば どのステップで失敗したのか、みたいな情報も調べられるかもしれません。

終わり。

追記:

記事書いて思ったけど、テストのレポートで出力がクラス毎に分かれてるなら MDCにクラス名入れなくても良かったかも?

Quarkusに入っているQuteというテンプレートエンジン単体で使ってみる

QuarkusにはQuteというテンプレートエンジンが入っています。 今回は、これをQuarkusじゃないプロジェクトで使ってみます。 使ったバージョンは1.1.1.Final です。

quarkus.io

今回のコードは以下のリポジトリにおいてあります。 github.com

quarkus-sandboxと言いつつ、quarkusを動かしているフォルダは一つもない・・・

とりあえず動かしてみる

JUnitのテストでQuteを動かしてみます。(実はこのままでは動かないんですが)

public class QuteTest {

    @Test
    public void test() { // 後述するが、このままでは動かない
        final Engine engine = Engine.builder()
                .addDefaults()
                .build();
        final String content = engine.parse("{name} は {price} 円です")
                .data(new Item(BigDecimal.TEN, "スイカ"))
                .render();

        assertThat(content).isEqualTo("スイカ は 10 円です");
    }
}

特に難しいところはないですが、解説をしていきます。

まずテンプレートエンジンの初期化です。

       final Engine engine = Engine.builder()
                .addDefaults() // addDefaultSectionHelpers()とaddDefaultValueResolvers()を呼び出している
                .build();

addDefaultsはaddDefaultValueResolversとaddDefaultSectionHelpersを中で呼び出しています。 まず、ValueResovlerというのは、名前の通りなんですが 下のようなインターフェースです。(正確には下のインターフェースを継承したインターフェース)

public interface Resolver {

    /**
     * 
     * @param context
     * @return the result
     * @see Results#NOT_FOUND
     */
    CompletionStage<Object> resolve(EvalContext context);

}

contextから値をresolveするのがVallueResolverの役割になります。

次にSectionHelpersなんですが実装を見てみましょう。 下のようなコードが書かれています。

    public EngineBuilder addDefaultSectionHelpers() {
        return addSectionHelpers(new IfSectionHelper.Factory(), new LoopSectionHelper.Factory(),
                new WithSectionHelper.Factory(), new IncludeSectionHelper.Factory(), new InsertSectionHelper.Factory(),
                new SetSectionHelper.Factory());
    }

下のリファレンスガイドにある、section tagに対応するHelperのようです。 quarkus.io

エンジンの初期化の次はtemplateのレンダリングです。 これはそんな難しくないですね。

       final String content = engine.parse("{name} は {price} 円です") // テンプレートをparse
                .data(new Item(BigDecimal.TEN, "スイカ")) // データを提供して
                .render(); // レンダリング

dataというメソッドで、テンプレートに使うパラメータを渡しています。

ちなみに、最初に書いた通り、上にあげたテストは失敗します。

何がダメだったのか

リファレンスガイドにある、以下の記述を見てください。

A value resolver is automatically generated for a type annotated with @TemplateData. This allows Quarkus to avoid using reflection to access the data at runtime.

quarkus.io

value resolverは @TemplateData アノテーションをつけておくと自動で生成されるよと書いてあり これによりランタイムにリフレクションを避けることができる、と書かれています。

じゃあ、アノテーションを書いたらすぐうまくいくのかというと また別の話になってきます。

Quarkusがアノテーションを見てValueResolverを生成するのはコンパイルより後のようです。 gradleで普通にできるjarと中身を見て比べてみます。

$ ./gradlew clean quarkusBuild
$ jar tf build/qute-only-1.0-SNAPSHOT-runner.jar # quarkusが生成したjar
# 一部省略しています。
META-INF/
META-INF/MANIFEST.MF
org/
org/acme/
org/acme/qute/
org/acme/qute/Item_ValueResolver.class # なんか出来てる
META-INF/services/
org/acme/qute/Item.class
templates/
templates/hello.html
templates/items.html
META-INF/services/io.quarkus.arc.ComponentsProvider
$ jar tf build/libs/qute-only-1.0-SNAPSHOT.jar # gradleで普通にできるjar
# ValueResolverは見当らない
META-INF/
META-INF/MANIFEST.MF
org/
org/acme/
org/acme/qute/
org/acme/qute/Item.class
templates/
templates/hello.html
templates/items.html

ValueResolverは普通のjarにないのでアノテーションをつけても動かないのは当然です。

ValueResolverを実装して動かしてみる

Quarkus抜きで動かそうとしているので、アノテーションをつけても動かないのは仕方ないので ValueResolverを自分で実装して動かしてみます。

public class QuteTest {

    @Test
    public void test() {
        final ValueResolver valueResolver = context -> { // 増えた
            if (context.getName().equals("name")) {
                final Item item = (Item) context.getBase();
                return CompletableFuture.completedFuture(item.name);
            }
            if (context.getName().equals("price")) {
                final Item item = (Item) context.getBase();
                return CompletableFuture.completedFuture(item.price);
            }
            return Results.NOT_FOUND;
        };
        final Engine engine = Engine.builder()
                .addDefaults()
                .addValueResolver(valueResolver) // 増えた
                .build();
        final String content = engine.parse("{name} は {price} 円です")
                .data(new Item(BigDecimal.TEN, "スイカ"))
                .render();

        assertThat(content).isEqualTo("スイカ は 10 円です");
    }
}

という訳で、こんな感じで動きました。

まとめ

Quarkusの中にあるQuteというテンプレートエンジンをQuarkusの外で使ってみましたが、シンプルで簡単に使えそうです。 @TemplateData は、Quarkusでテストしたらちゃんと動くのかな?また今度試してみます。 Quarkusのビルドライフサイクル周りの知識がないのでハマった感じでした。

終わり。

少し疑問になったんだけど、Quarkusのテストってどんな感じで動くんだろう? quteを使ったサンプルだと、RestAssuredでレンダリングされたレスポンスの検証をしているので テンプレートエンジンが正しく動いているはずなんだけど どのタイミングでValueResolverが提供されるんだろう・・・

今回のコードは以下のリポジトリにおいてあります。 github.com

追記: QuarkusTestの中の話

QuarkusTestの中で使われているQuarkusTestExtensionのコードを読んでみたところ ValueResolverに限らず、テスト時にクラスファイルを生成しているようです。 github.com

なるほど・・・

追記: Quarkusのgradle projectで ./gradlew clean test をすると QuarkusTestが失敗する

Quteを使っている時だけ起きる問題なのかな?他にもありそうだけどここにメモしておく。

src/main/resources/templatesにあるtemplateを./gradlew quarkusBuildした際に build/classes/java/templatesにコピーしている挙動になっている。 そのため、単にclean testすると、QuarkusTestを使ったテストで以下のエラーが発生する

org.junit.jupiter.api.extension.TestInstantiationException: TestInstanceFactory [io.quarkus.test.junit.QuarkusTestExtension] failed to instantiate test class [org.acme.qute.ItemsResourceTest]: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
    [error]: Build step io.quarkus.arc.deployment.ArcProcessor#generateResources threw an exception: javax.enterprise.inject.spi.DeploymentException: Found 2 deployment problems: 
[1] No template found for org.acme.qute.HelloResource#hello
[2] No template found for org.acme.qute.ItemResource#items
    at io.quarkus.arc.processor.BeanDeployment.processErrors(BeanDeployment.java:873)
    at io.quarkus.arc.processor.BeanProcessor.processValidationErrors(BeanProcessor.java:116)
    at io.quarkus.arc.deployment.ArcProcessor.generateResources(ArcProcessor.java:301)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

templateがコピーされてなくてtemplateが見つからない、というエラーが出ている。 ./gradlew quarkusBuild test とすれば動く。

参考