はじめに

こんにちは、ラクス Advent Calendar 2019 13日目担当の@rs_tukkiです。
気が付けばもうこれで中間地点です。一ヶ月って早いですね。

ちなみに昨日はi476bさんの記事でした。私も来年こそはC#勉強したい！
今日は、スマホアプリの開発中にやらかした(というか気づけなかった)ささいなミスのお話です。

背景

現在私が携わっているプロダクトでは、大元となるWebアプリケーションに加えてスマホアプリを2つリリースしています。それぞれAndroidとiPhoneで出しているので開発するものは4つ。
今年の4月に開発を引き継ぎましたが、そのころには既に4つともリリース済みで、後はWeb側の改修に合わせてアップデートを繰り返していくだけなので~~慣れない言語にひいこら言いながら~~さほど大きな問題もなく進められていました。

発生した問題

二つのアプリのうち片方の改修作業をしていたときのことです。

とはいってもやるべきことは簡単で、スマホアプリのWebViewからサーバにリクエストを送って、あれこれ解析した後その結果を表示するだけの機能でした。アプリ側よりむしろサーバ側の方が改修範囲が大きい内容です。

ひとまず実装を終えて、検証しようとAndroidアプリからリクエストを送ってみました。

……読み込み中。

…………読み込み中。

………………まだ読み込み中。

そして最終的に、アプリは**「インターネットの接続を確認してください」**というエラーダイアログだけ吐いて元の画面に戻ってしまいました。
その一文だけでは何も分かりませんが多分どこかで実装間違えてるんでしょう。はい。

調査した内容

真っ先に疑ったのはサーバ側のエラー

今回はアプリ側よりサーバ側に多く手を入れていたので、真っ先にサーバ側でエラーが起こってるんじゃないか…という発想に至りました。
というわけでコードを確認。サーバ側のコードはJavaで記載しています。

                if (code != HttpStatus.SC_OK) {
                    // エラーログ出力
                    StringBuilder errorMessage = new StringBuilder();
                    errorMessage.append("解析中にエラーが発生しました。");
                    String responseBody = StringUtils.truncate(responseEntity, 500);
                    errorMessage.append("responseBody=" + responseBody);
                    throw new hogehogeException(errorMessage.toString());
                }
                return response;
            } finally {
                long elapsed = System.currentTimeMillis() - start;
                log.info("API elapsed {} ms", elapsed);
            }
        } catch (IOException e) {
            // エラーログ出力
            StringBuilder errorMessage = new StringBuilder();
            errorMessage.append("解析中に予期せぬエラーが発生しました。");
            throw new hogehogeException(errorMessage.toString());
        }

サーバ側では例外を吐いたらログに記録するようにしているはずなので、この実装なら何かしらエラーが起こっていればログにその内容が記載されているはず。

……が、少なくともログを見る限りサーバ側は多少負荷がかかっていたものの、正常にレスポンスを返しているように見えました。

違う？じゃあアプリ側のエラーかな

サーバ側が正常に稼働しているように見えるので、アプリ側に根本的な原因があるのはほぼ確定でしょう。
というわけで早速Androidの検証機をMacに繋ぎ、IDEからデバッグモードでアプリを動かしてみます。
どこで止まっているのかさえ分かれば原因もすぐ分かる！はず！

そして、問題だった処理は無事に成功し、解析の結果が画面に表示されました。

さっきは上手くエラーになってくれた(という言い方もどうかと思うが)のに。
もしかしてiPhoneだったらエラーになるんでしょうか。それじゃiPhoneのアプリをデバッグモードで起動して……

そしてやっぱり処理は成功しました。

そもそもどうしてそんなエラーが出てたんだろう

最初にエラーになったときは、「インターネットの接続を確認してください」というダイアログが出ていたはずです。
ということで、どんな操作をしたらそのダイアログに行き着くのか調べてみることにしました。アプリ側のコードはKotlinです。

    try {
        val result = handlingFunction() //リクエストの結果を取得
        if (result.isSuccessful.not()) { //リクエストが失敗ならtrue
            throw HttpException(result)
        }
        return resultSelector(result)
    } catch (e: SocketTimeoutException) {
        throw NotConnected(e) //「インターネットの接続を確認してください」
    } catch (e: UnknownHostException) {
        throw NotConnected(e) //「インターネットの接続を確認してください」
    } catch (e: HttpException) {

アプリの分岐処理を見る限り、「インターネットの接続を確認してください」のダイアログが出る条件は2つ。

アプリからの通信がタイムアウトした
接続先のホストが存在しないか、スマホが通信できない状態だった

流石に後者にはなり得ないはずなので、つまり原因は通信がタイムアウトしたことだと断定できます。
……サーバ側はちゃんとレスポンス返してましたけど……

そういえばアプリ側のタイムアウト値どう設定してたっけ

とりあえず、アプリ側でHTTP通信を生成している箇所を調べてみます。

private fun buildHttpClient(cookieJar: CookieJar, versionService: IVersionService): OkHttpClient {
    val dispatcher = Dispatcher()
    val builder = OkHttpClient.Builder()
        .dispatcher(dispatcher)
        .addInterceptor(UserAgentInterceptor(versionService))
        .cookieJar(cookieJar)

    return builder.build()
}

見る限り、アプリ側では明示的にタイムアウト値を設定しているわけではなさそうでした。
その場合処理はどうなるんでしょう？まさか無制限ってことはないと思いますが……

ありました

ということでリファレンスの確認。

https://square.github.io/okhttp/3.x/okhttp/index.html?okhttp3/OkHttpClient.html

The default is 10 seconds.

はい。そりゃちょっとでも通信遅れたらタイムアウトになりますね。

結局何がダメだったのか

今回のエラーが発生した原因は大きく分けて2つありました。

1つ。サーバ側が一時的に高負荷状態になり、解析処理に時間がかかったこと。

2つ。Androidアプリのタイムアウト値がデフォルト値(=10秒)のままで、その値を見直していなかったこと。

サーバ側は高負荷とはいえ更にタイムアウト値が長く設定されていたので、アプリ側から通信を切断した後も正常にレスポンスを返(そうと)してくれた、というわけでした。

iPhoneアプリでは起きなかったのか？

今回の事象はAndroidアプリだけでしたが、気になったのでiPhoneの方もタイムアウト値を調べてみました。
……実はこちらもデフォルト値のままだったのですが、Swiftで使われているURLRequestはデフォルトのタイムアウト値が60秒に設定されていたため、処理遅延はあったもののタイムアウトの難からは逃れた、というわけです。

打った対策

流石にAndroidのデフォルト値が10秒は短すぎたため、高負荷時の処理時間を確認した上でタイムアウトが起こりにくい秒数を明示的に設定しました。
そもそもサーバ側とアプリ側でタイムアウト値が違うというのも変な話ですが。

また、サーバの高負荷そのものは今回の実装とは別の原因だったらしく、そちらも対策中です。

まとめ

デフォルト、ダメ、ゼッタイ。…とまでは言いませんが。
今回実装した処理は元からある程度時間がかかることが分かっていたので、最初からタイムアウト値を調査して場合によっては引き延ばす対応をしておくべきでした。そこまで目を向けられなかったのは反省です…

というわけで、想定される影響を洗い出して確認しておかないと想定外の問題が起こるかもしれない、という話でした。

さて明日は@aizkoさんです！よろしくお願いします！