かんがるーさんの日記

最近自分が興味をもったものを調べた時の手順等を書いています。今は Spring Boot をいじっています。

Spring Boot 1.3.x の Web アプリを 1.4.x へバージョンアップする ( その12 )( RestTemplateBuilder を使用するように変更したらテストが失敗するようになった理由とは? )

概要

記事一覧はこちらです。

Spring Boot 1.3.x の Web アプリを 1.4.x へバージョンアップする ( その11 )( Error Prone を 2.0.15 → 2.0.18 へバージョンアップ。。。できませんでした ) の続きです。

  • 今回の手順で確認できるのは以下の内容です。
    • RestTemplate オブジェクトを生成するのに RestTemplateBuilder を使用するように変更したら、 ksbysample.webapp.lending.webapi.library.LibraryControllerTest#間違った都道府県を指定した場合にはエラーが返る のテストが時々失敗する ( 成功する時もある ) ようになったので、その原因を調べます。

参照したサイト・書籍

  1. Spring Boot 1.4+でRestTemplate(HTTPクライアント)を使う
    http://qiita.com/kazuki43zoo/items/7cf3c8ca4f6f2283cefb

  2. square/okhttp
    https://github.com/square/okhttp

目次

  1. どこで、どのようなエラーが発生しているのか?
  2. RestTemplate オブジェクトの生成処理を以前の処理に戻してみる
  3. 失敗するテストを単独で実行してみる
  4. テストが成功する SimpleClientHttpRequestFactory を使った RestTemplate オブジェクトの中身を見てみる
  5. テストが失敗する RestTemplateBuilder を使った RestTemplate オブジェクトの中身を見てみる
  6. 2つの RestTemplate オブジェクトの違いは?
  7. RestTemplateBuilder#detectRequestFactory で RestTemplateBuilder の自動検出を無効にして HttpURLConnection を使うようにしたらテストは成功するのか?
  8. OkHttp 3 だとテストは成功するのか?
  9. Apache HttpComponents HttpClient でもリトライ処理を入れればテストは成功するのか?
  10. ログのレベルを DEBUG に変更してみる
  11. 結局どうするか?

手順

どこで、どのようなエラーが発生しているのか?

clean タスク → Rebuild Project → build タスクを実行すると以下のエラーメッセージが出力されます。

f:id:ksby:20170307234243p:plain

失敗しているテストは以下のコードです。

    @Test
    public void 間違った都道府県を指定した場合にはエラーが返る() throws Exception {
        mvc.noauth.perform(get("/webapi/library/getLibraryList?pref=東a京都"))
                .andExpect(status().isOk())
                .andExpect(content().contentType("application/json;charset=UTF-8"))
                .andExpect(jsonPath("$.errcode", is(-2)))
                .andExpect(jsonPath("$.errmsg", is("都道府県名が正しくありません。")))
                .andExpect(jsonPath("$.content", hasSize(0)));
    }

コンソールの最後に There were failing tests. See the report at: file:///C:/project-springboot/ksbysample-webapp-lending/build/reports/tests/index.html と出力されていますので、このファイルを見てみます。

f:id:ksby:20170308000306p:plain f:id:ksby:20170308000444p:plain

-2 が返ってくるはずが -1 が返ってきたのでテスト失敗と判定されています。

リクエストを送信している /webapi/library/getLibraryList のソース  src/main/java/ksbysample/webapp/lending/webapi/library/LibraryController.java を見ると、ValueRequiredException ではなくそれ以外の例外が throw されたので errorcode が -1 になっているようです。

    @RequestMapping("/getLibraryList")
    public CommonWebApiResponse<List<Library>> getLibraryList(String pref) throws Exception {
        CommonWebApiResponse<List<Library>> response = new CommonWebApiResponse<>();
        response.setContent(Collections.emptyList());

        try {
            Libraries libraries = calilApiService.getLibraryList(pref);
            response.setContent(libraries.getLibraryList());
        } catch (ValueRequiredException e) {
            response.setErrcode(-2);
            response.setErrmsg("都道府県名が正しくありません。");
        } catch (Exception e) {
            logger.error("システムエラーが発生しました。", e);
            response.setErrcode(-1);
            response.setErrmsg("システムエラーが発生しました。");
        }

        return response;
    }

発生している例外を調べます。コンソールにログが出力されるようにするために src/main/resources/logback-unittest.xml を以下のように修正します。

<?xml version="1.0" encoding="UTF-8"?>
<included>
    <!--<root level="OFF"/>-->
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>
</included>

build タスクではコンソールに INFO ログは出力されないので、Project Tool Window の src/test から「Run ‘All Tests’ with Coverage」を実行します。

f:id:ksby:20170308002854p:plain

発生している例外は Caused by: java.net.SocketTimeoutException: Read timed out でした。タイムアウトの時間は以前とは変えていないのですが。。。

また他のテストを見ていて気づきましたが、src/main/test/ksbysample/webapp/lending/service/calilapi/CalilApiServiceTest.java で同じテストをしているはずなのに、こちらは ValueRequiredException が発生しています。

    @Test
    public void testGetLibraryList_都道府県名が間違っている場合() throws Exception {
        assertThatThrownBy(() -> {
            Libraries libraries = calilApiService.getLibraryList("東a京都");
        }).isInstanceOf(ValueRequiredException.class);
    }

RestTemplate オブジェクトの生成処理を以前の処理に戻してみる

src/main/java/ksbysample/webapp/lending/service/calilapi/CalilApiService.java で今回失敗している処理用の RestTemplate オブジェクトを生成している処理を以前の処理に戻してみます。

        @Bean
        public RestTemplate restTemplateForCalilApi() {
//            return this.restTemplateBuilder
//                    .setConnectTimeout(CONNECT_TIMEOUT)
//                    .setReadTimeout(READ_TIMEOUT)
//                    .rootUri(URL_CALILAPI_ROOT)
//                    .build();

            SimpleClientHttpRequestFactory factory = new SimpleClientHttpRequestFactory();
            factory.setConnectTimeout(CONNECT_TIMEOUT);
            factory.setReadTimeout(READ_TIMEOUT);
            RestTemplate restTemplate = new RestTemplate(factory);
            return restTemplate;
        }

Project Tool Window の src/test から「Run ‘All Tests’ with Coverage」を何度も実行してみましたが1度もエラーになりません。

f:id:ksby:20170308010357p:plain

RestTemplateBuilder を使うコードにしてみると、

        @Bean
        public RestTemplate restTemplateForCalilApi() {
            return this.restTemplateBuilder
                    .setConnectTimeout(CONNECT_TIMEOUT)
                    .setReadTimeout(READ_TIMEOUT)
                    .rootUri(URL_CALILAPI_ROOT)
                    .build();

//            SimpleClientHttpRequestFactory factory = new SimpleClientHttpRequestFactory();
//            factory.setConnectTimeout(CONNECT_TIMEOUT);
//            factory.setReadTimeout(READ_TIMEOUT);
//            RestTemplate restTemplate = new RestTemplate(factory);
//            return restTemplate;
        }

Project Tool Window の src/test から「Run ‘All Tests’ with Coverage」を実行してみますが、5回実行して5回全てテストが失敗しました。

f:id:ksby:20170308011618p:plain

同じ処理だと思っていたのですが、何が違うんでしょうか?

失敗するテストを単独で実行してみる

単独でテストを実行するとどうなるのか、確認してみます。

f:id:ksby:20170311125150p:plain

何回繰り返しても全て成功します。ということは単独では成功するが、全てのテストを通しで実行するとエラーになる現象のようです。

f:id:ksby:20170311125531p:plain

テストが成功する SimpleClientHttpRequestFactory を使った RestTemplate オブジェクトの中身を見てみる

breakpoint を設定した後、LibraryControllerTest#間違った都道府県を指定した場合にはエラーが返る テストメソッドを Debug 実行して生成された RestTemplate オブジェクトがどのような構成になっているのかを確認します。

f:id:ksby:20170308012306p:plain f:id:ksby:20170308013234p:plain

restTemplateForCalilApi の中身を見ていると以下の内容でした。

f:id:ksby:20170308210033p:plain f:id:ksby:20170308210159p:plain

テストが失敗する RestTemplateBuilder を使った RestTemplate オブジェクトの中身を見てみる

RestTemplateBuilder を使った場合の restTemplateForCalilApi の中身を見ていると以下の内容でした。

f:id:ksby:20170308210752p:plain f:id:ksby:20170308210951p:plain f:id:ksby:20170308211112p:plain

2つの RestTemplate オブジェクトの違いは?

  • messageConverters の数が違います。成功する方は size = 7 なのに対し、失敗する方は size = 10 でした。失敗する方は以下の点が違っていました。
    • StringHttpMessageConverter が2つありますが、片方は defaultCharset = “UTF-8” で、もう片方は defaultCharset = “ISO-8859-1” です。ちなみに成功する方にあるのは defaultCharset = “ISO-8859-1” の方です。
    • MappingJackson2HttpMessageConverter, MappingJackson2XmlHttpMessageConverter もそれぞれ2つずつありますが、こちらはどちらも defaultCharset = “UTF-8” で、インスタンスが異なるだけで内容は同じオブジェクトです。
  • uriTemplateHandler も DefaultUriTemplateHandler と RootUriTemplateHandler の違いがありますが、これは RestTemplateBuilder を使うように変更した時に RestTemplateBuilder#rootUri を追加したためと思われます。
  • requestFactory も異なっており、成功する方は SimpleClientHttpRequestFactory、失敗する方は HttpComponentsClientHttpRequestFactory でした。

タイムアウトしているという状況を考えると requestFactory の違いが影響しているように思えます。SimpleClientHttpRequestFactory と HttpComponentsClientHttpRequestFactory がそれぞれ何なのか調べてみたところ、

Apache HttpComponents HttpClient を build.gradle に記述していないので入れていないつもりでいたのですが、どうも classpath に存在して RestTemplateBuilder により検知されて使用するよう設定されているようです。

gradlew dependencies コマンドを実行して確認したところ、org.springframework.boot:spring-boot-starter-amqp を入れると依存関係で org.apache.httpcomponents:httpclient が入っていました ( この中に org.apache.http.client.HttpClient クラスがあります。 )。

compile - Dependencies for source set 'main'.
..........
+--- org.springframework.boot:spring-boot-starter-amqp: -> 1.4.4.RELEASE
|    +--- org.springframework.boot:spring-boot-starter:1.4.4.RELEASE (*)
|    +--- org.springframework:spring-messaging:4.3.6.RELEASE
|    |    +--- org.springframework:spring-beans:4.3.6.RELEASE (*)
|    |    +--- org.springframework:spring-context:4.3.6.RELEASE (*)
|    |    \--- org.springframework:spring-core:4.3.6.RELEASE
|    \--- org.springframework.amqp:spring-rabbit:1.6.7.RELEASE
|         +--- org.springframework:spring-web:4.2.9.RELEASE -> 4.3.6.RELEASE (*)
|         +--- org.springframework.retry:spring-retry:1.1.5.RELEASE
|         |    \--- org.springframework:spring-core:4.0.4.RELEASE -> 4.3.6.RELEASE
|         +--- org.springframework:spring-messaging:4.2.9.RELEASE -> 4.3.6.RELEASE (*)
|         +--- org.springframework:spring-context:4.2.9.RELEASE -> 4.3.6.RELEASE (*)
|         +--- org.springframework:spring-tx:4.2.9.RELEASE -> 4.3.6.RELEASE (*)
|         +--- com.rabbitmq:http-client:1.0.0.RELEASE
|         |    +--- org.apache.httpcomponents:httpclient:4.3.6 -> 4.5.2
|         |    |    +--- org.apache.httpcomponents:httpcore:4.4.4 -> 4.4.6
|         |    |    \--- commons-codec:commons-codec:1.9 -> 1.10
|         |    \--- com.fasterxml.jackson.core:jackson-databind:2.5.1 -> 2.8.6 (*)
|         +--- org.springframework.amqp:spring-amqp:1.6.7.RELEASE
|         |    \--- org.springframework:spring-core:4.2.9.RELEASE -> 4.3.6.RELEASE
|         \--- com.rabbitmq:amqp-client:3.6.5 -> 3.6.6
..........

RestTemplateBuilder#detectRequestFactory で RestTemplateBuilder の自動検出を無効にして HttpURLConnection を使うようにしたらテストは成功するのか?

Spring Boot 1.4+でRestTemplate(HTTPクライアント)を使う の記事によると、RestTemplateBuilder#detectRequestFactory(false) を呼べば RestTemplateBuilder の自動検出が無効になり HttpURLConnection が使われるようになるようです。HttpURLConnection にすれば RestTemplateBuilder を使用する場合でもテストが成功するのか確認してみます。

src/main/java/ksbysample/webapp/lending/service/calilapi/CalilApiService.java の CalilApiConfig.restTemplateForCalilApi メソッドを以下のように変更します。

        @Bean
        public RestTemplate restTemplateForCalilApi() {
            return this.restTemplateBuilder
                    .detectRequestFactory(false)
                    .setConnectTimeout(CONNECT_TIMEOUT)
                    .setReadTimeout(READ_TIMEOUT)
                    .rootUri(URL_CALILAPI_ROOT)
                    .build();

//            SimpleClientHttpRequestFactory factory = new SimpleClientHttpRequestFactory();
//            factory.setConnectTimeout(CONNECT_TIMEOUT);
//            factory.setReadTimeout(READ_TIMEOUT);
//            RestTemplate restTemplate = new RestTemplate(factory);
//            return restTemplate;
        }
  • .detectRequestFactory(false) を追加します。

Project Tool Window の src/test から「Run ‘All Tests’ with Coverage」を何度も実行してみましたが1度もエラーになりませんでした。

f:id:ksby:20170311130905p:plain

ここまでの確認結果をまとめてみると、

  • RestTemplateBuilder の問題ではなく Apache HttpComponents HttpClient の問題のようです。JDK 標準の HttpURLConnection だと発生しません。
  • テスト単独で実行すると発生しない。全てのテストを通しで実行した時だけ発生する問題のようです ( ただしたまに成功します )。

OkHttp 3 だとテストは成功するのか?

Apache HttpComponents HttpClient 以外のライブラリでも同じ現象が出るのか、OkHttp 3 で確認してみます。

build.gradle を以下のように変更します。変更後、Gradle Tool Window の左上にある「Refresh all Gradle projects」ボタンをクリックして更新します。

dependencies {
    ..........

    // dependency-management-plugin によりバージョン番号が自動で設定されるもの
    // Appendix A. Dependency versions ( http://docs.spring.io/platform/docs/current/reference/htmlsingle/#appendix-dependency-versions ) 参照
    ..........
    compile("org.codehaus.janino:janino")
    compile("com.squareup.okhttp3:okhttp")
    testCompile("org.springframework.boot:spring-boot-starter-test")
    ..........
  • compile("com.squareup.okhttp3:okhttp") を追加します。OkHttp 3 は Spring IO Platform の BOM に記載されているのでバージョン番号の記述は不要です。

src/main/java/ksbysample/webapp/lending/service/calilapi/CalilApiService.java の CalilApiConfig.restTemplateForCalilApi メソッドを以下のように変更します。

        @Bean
        public RestTemplate restTemplateForCalilApi() {
            return this.restTemplateBuilder
                    .setConnectTimeout(CONNECT_TIMEOUT)
                    .setReadTimeout(READ_TIMEOUT)
                    .rootUri(URL_CALILAPI_ROOT)
                    .requestFactory(new OkHttp3ClientHttpRequestFactory())
                    .build();

//            SimpleClientHttpRequestFactory factory = new SimpleClientHttpRequestFactory();
//            factory.setConnectTimeout(CONNECT_TIMEOUT);
//            factory.setReadTimeout(READ_TIMEOUT);
//            RestTemplate restTemplate = new RestTemplate(factory);
//            return restTemplate;
        }
  • .requestFactory(new OkHttp3ClientHttpRequestFactory()) を追加します。

clean タスク → Rebuild Project を実行します。

問題の出るテストを単独で実行すると、これは何度試しても成功します。

f:id:ksby:20170316004333p:plain

Project Tool Window の src/test から「Run ‘All Tests’ with Coverage」を実行してみると、5回実行して5回全てテストが失敗しました。エラーの原因も Caused by: java.net.SocketTimeoutException: Read timed out でした。

f:id:ksby:20170316005629p:plain

Apache HttpComponents HttpClient と変わりませんでした。変更したファイルは一旦元に戻します。

Apache HttpComponents HttpClient でもリトライ処理を入れればテストは成功するのか?

リトライを入れても失敗するのか確認してみます。簡単に試してみたいだけなので spring-retry ではなく for 文で実装します。

src/main/java/ksbysample/webapp/lending/service/calilapi/CalilApiService.java の getLibraryList メソッドを以下のように変更します。

    public Libraries getLibraryList(String pref) throws Exception {
        // 図書館データベースAPIを呼び出して XMLレスポンスを受信する
        ResponseEntity<String> response = null;
        for (int i = 1; i <= 5; i++) {
            try {
                response = this.restTemplateForCalilApi.getForEntity(URL_CALILAPI_LIBRALY
                        , String.class, this.calilApiKey, pref);
            } catch (Exception e) {
                if (i <= 4) {
                    logger.warn("★★★ リトライ = {} 回目: {}", i, e.getCause().getMessage());
                } else {
                    throw e;
                }
            }
        }

        // 受信した XMLレスポンスを Javaオブジェクトに変換する
        Serializer serializer = new Persister();
        Libraries libraries = serializer.read(Libraries.class, response.getBody());

        return libraries;
    }

Project Tool Window の src/test から「Run ‘All Tests’ with Coverage」を実行してみるとテストは常に成功するようになりました。ただし、ログを見ると常に1回リトライしていました。

f:id:ksby:20170316012319p:plain

ログのレベルを DEBUG に変更してみる

ログのレベルを DEBUG に変更して状況を見てみます。src/main/resources/logback-unittest.xml を以下のように修正します。

<?xml version="1.0" encoding="UTF-8"?>
<included>
    <!--<root level="OFF"/>-->
    <root level="DEBUG">
        <appender-ref ref="CONSOLE"/>
    </root>
</included>

Project Tool Window の src/test から「Run ‘All Tests’ with Coverage」を実行すると以下のログが出力されました。

2017-03-17 00:39:36.438  INFO : call : ksbysample.webapp.lending.service.calilapi.CalilApiService#getLibraryList({東a京都})
2017-03-17 00:39:36.438 DEBUG : Created GET request for "http://api.calil.jp/library?....."
2017-03-17 00:39:36.438 DEBUG : Setting request Accept header to [.....]
2017-03-17 00:39:36.438 DEBUG : CookieSpec selected: default
2017-03-17 00:39:36.438 DEBUG : Auth cache not set in the context
2017-03-17 00:39:36.438 DEBUG : Connection request: [route: {}->http://api.calil.jp:80][total kept alive: 1; route allocated: 1 of 5; total allocated: 1 of 10]
2017-03-17 00:39:36.470 DEBUG : http-outgoing-0 << "[read] I/O error: Read timed out"
2017-03-17 00:39:36.470 DEBUG : Connection leased: [id: 0][route: {}->http://api.calil.jp:80][total kept alive: 0; route allocated: 1 of 5; total allocated: 1 of 10]
2017-03-17 00:39:36.470 DEBUG : http-outgoing-0: set socket timeout to 5000
2017-03-17 00:39:36.470 DEBUG : Executing request GET /library?..... HTTP/1.1
2017-03-17 00:39:36.470 DEBUG : Target auth state: UNCHALLENGED
2017-03-17 00:39:36.470 DEBUG : Proxy auth state: UNCHALLENGED
2017-03-17 00:39:36.470 DEBUG : http-outgoing-0 >> GET /library?..... HTTP/1.1
..........
2017-03-17 00:39:41.482 DEBUG : http-outgoing-0 << "[read] I/O error: Read timed out"
2017-03-17 00:39:41.482 DEBUG : http-outgoing-0: Close connection
2017-03-17 00:39:41.482 DEBUG : http-outgoing-0: Shutdown connection
2017-03-17 00:39:41.482 DEBUG : Connection discarded
2017-03-17 00:39:41.482 DEBUG : Connection released: [id: 0][route: {}->http://api.calil.jp:80][total kept alive: 0; route allocated: 0 of 5; total allocated: 0 of 10]
2017-03-17 00:39:41.482  WARN : ★★★ リトライ = 1 回目: Read timed out
2017-03-17 00:39:41.482 DEBUG : Created GET request for "http://api.calil.jp/library?....."
2017-03-17 00:39:41.482 DEBUG : Setting request Accept header to [.....]
2017-03-17 00:39:41.482 DEBUG : CookieSpec selected: default
2017-03-17 00:39:41.482 DEBUG : Auth cache not set in the context
2017-03-17 00:39:41.482 DEBUG : Connection request: [route: {}->http://api.calil.jp:80][total kept alive: 0; route allocated: 0 of 5; total allocated: 0 of 10]
2017-03-17 00:39:41.482 DEBUG : Connection leased: [id: 2][route: {}->http://api.calil.jp:80][total kept alive: 0; route allocated: 1 of 5; total allocated: 1 of 10]
2017-03-17 00:39:41.482 DEBUG : Opening connection {}->http://api.calil.jp:80
2017-03-17 00:39:41.482 DEBUG : Connecting to api.calil.jp/160.16.122.86:80
2017-03-17 00:39:41.501 DEBUG : Connection established 192.168.2.100:58940<->160.16.122.86:80
2017-03-17 00:39:41.501 DEBUG : http-outgoing-2: set socket timeout to 5000
2017-03-17 00:39:41.502 DEBUG : Executing request GET /library?..... HTTP/1.1
2017-03-17 00:39:41.502 DEBUG : Target auth state: UNCHALLENGED
2017-03-17 00:39:41.502 DEBUG : Proxy auth state: UNCHALLENGED
2017-03-17 00:39:41.502 DEBUG : http-outgoing-2 >> GET /library?..... HTTP/1.1
..........
2017-03-17 00:39:41.866 DEBUG : http-outgoing-2 << "HTTP/1.1 200 OK[\r][\n]"

失敗時と成功時の違いを比較してみると、

  • 失敗時は total kept alive: 1 と出力されており、既存の接続済のコネクションを利用していますが、成功時は total kept alive: 0 と接続済のコネクションがないため、Connecting to api.calil.jp/160.16.122.86:80Connection established 192.168.2.100:58940<->160.16.122.86:80 と新規に接続しています。

結局どうするか?

ここまで調べた結果をまとめてみると、

  • 接続済のコネクションを再利用しようとすると失敗するときがある。失敗した時に発生している例外は java.net.SocketTimeoutException: Read timed out
  • リトライすれば2回目には成功する。3回目以降までリトライすることはない。
  • java.net.SocketTimeoutException: Read timed out の原因は分からず。デバッガで追ってもみたが、本当に単に time out しているだけだった。。。
  • JDK の HttpURLConnection で必ず成功するのは、おそらくコネクションプーリングの仕組みがないため。都度接続するので成功するのだろう。

という感じでしょうか。ライブラリの問題というより自分のところのネットワークの問題のような気がしてきました。WiFiiPhoneTwitter を見ていると、外では決して出ることがない「ツイートを読み込めません」というエラーメッセージがよく出ることがあり、同じように接続済のコネクションを再利用しようとして問題が発生しているものと思われます。RestTemplateBuilder や Apache HttpComponents HttpClient に問題がある訳ではないという結論です。

エラーが出ないようにするには JDK の HttpURLConnection を使うか、リトライ処理を入れるかするしかないようです。今回はリトライ処理を入れて対応します。

リトライ処理は上で入れた for 文の方式ではなく spring-retry で入れようと思います。長くなったのでリトライ処理は次回に入れます。またこれまで入れた修正は全て元に戻します。

ソースコード

履歴

2017/03/18
初版発行。