この記事はエムスリー Advent Calendar 2018 4日目の記事です。
こんにちは、Androidエンジニアでバグの原因探しが趣味の星川（id:oboenikui）です。
根の深い問題というのはどうしても発見されにくいものであり、弊社ではアプリ含め全てのサービスでUTやQAにより品質担保に万全を期しておりますが、いくつかバグを発生させてしまいました。
本記事では、今年中に発生させてしまったバグ（開発中に発生したものも含む）の中で根の深かったもの、風変わりなものを3つをピックアップして懺悔していきます。
Androidを知らない方でも読めるように、少し余談多めで紹介しますがお付き合いください。
OkHttpのPublicSuffixDatabaseでクラッシュ
概要
Unable to load publicsuffixes.gz resource from the classpath. というメッセージでIllegalStateExceptionが投げられクラッシュしました。
これは、エラーログとしてはかなりの量が上がってくるにも関わらず、手元では一切確認ができず、調査が難航した問題でした。
PublicSuffixDatabaseについて
余談になりますが、Public Suffixというのは、.comや.co.jpのような、ドメインの中でインターネットユーザーが直接登録できる部分の後の部分を網羅したものです。
Cookieの仕様上親ドメインのCookieを変えることができますが、その際例えばco.jpを親ドメインと認識しクッキーが設定されるとセキュリティ上まずいので、それを除外するために網羅したのがPublic Suffix Listというわけです。本記事とは外れてしまうので、詳しくは以下のドキュメントやCookie Monster Bugなどをお調べください。
原因究明
OkHttp 3.7頃にPublicSuffixDatabaseというクラスが追加されました。
3.8.0時点での実装はこちらです。
if (!listRead.get() && listRead.compareAndSet(false, true)) { readTheListUninterruptibly(); } else { try { readCompleteLatch.await(); } catch (InterruptedException ignored) { } } synchronized (this) { if (publicSuffixListBytes == null) { throw new IllegalStateException("Unable to load " + PUBLIC_SUFFIX_RESOURCE + " resource " + "from the classpath."); } }
簡単に述べると、1度だけpublicsuffixes.gzというファイルを読み、その後は結果をキャッシュする処理です。読み込み中の場合は待機するようになっています。
このとき、readCompleteLatch.await()がInterruptedExceptionを投げてしまった場合、読み込み処理を待つことなく下のsynchronized以降に進んでしまうことがわかると思います。その場合はまだpublicSuffixListBytesがnullのことがあり、IllegalStateExceptionを投げます。
さて、クラッシュする箇所はわかったのですが、肝心の発生する理由がわからないという次の問題にぶち当たります。
発生する機種を見る限りは、機種依存でもない、Androidバージョン依存でもない、ユーザー依存でもないことが判明します。
さて、ここでAndroidエンジニアが疑うべきは何でしょうか？
もう一度ログが送られてくる機種を確認し、それらをAndroid OSバージョンと対応付けてみることにしました。すると最新機種からもたまに送られてくるものの、圧倒的に古い機種から送られてくることが多かったのです。 そこで目をつけたのが、端末のスペックでした。
その前に、Androidアプリにはライフサイクルというものがあります。スマートフォンはRAMが少ない上にSwapしづらい関係上、裏側に回ったアプリのプロセスがkillされることがあります。（以下の図の赤く囲った部分がそれです。）
https://developer.android.com/guide/components/activities?hl=ja より
当然この処理はRAMが少ない端末ほど発生します。機種の偏りはこれではないかと疑い、無事発見に至りました。
具体的な発生の流れの解説
さて、弊社アプリでは実装上アプリプロセスがkillされた後にこの問題が発生することがありましたが、実際にはOkHttpでCookieを使う場合どのアプリでも発生しうる問題でした。
幸いにもこの問題は恐らくこのIssueの修正と同時に発生しなくなっていると思われますが、一応旧バージョンを使う必要のあるケースのために、流れを解説します。
この問題はアプリ起動（アプリプロセス生成）後、2回以上のリクエストを最初に行った際に発生する可能性があります。 ただしそれらのリクエストに対するレスポンスが返ってくる前にスレッドの割り込みがされている必要があります。
弊社アプリの場合、OkHttp3 + RxJava 2 + AutoDisposeという構成なのですが、上記条件の下でAPIコールを行った際、直後にActivityをfinish()してしまうような実装になっていました。
（AutoDisposeはライフサイクルの状態変更を検知して、不要になったRxJavaのDisposableをdisposeするライブラリです。）
このdispose操作によりレスポンスが返ってくる前にスレッドを割り込みしてしまうため、クラッシュしていました。
デバッグ実行できなくなった
概要
自分の環境では特に問題なかったのですが、他のメンバーから「デバッグ実行だけができなくなった」とヘルプが。
調べてみるとInstant Runが実行できなくなっていました。ログは以下の通りです。
Caused by: java.lang.IllegalStateException: java.lang.IllegalStateException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at java.util.concurrent.ForkJoinTask.getThrowableException(ForkJoinTask.java:593)
at java.util.concurrent.ForkJoinTask.reportException(ForkJoinTask.java:677)
at java.util.concurrent.ForkJoinTask.join(ForkJoinTask.java:720)
at com.android.ide.common.internal.WaitableExecutor.waitForTasksWithQuickFail(WaitableExecutor.java:146)
at com.android.build.gradle.internal.transforms.InstantRunTransform.doTransform(InstantRunTransform.java:307)
... 53 more
Caused by: java.lang.IllegalStateException
at org.objectweb.asm.tree.analysis.BasicInterpreter.<init>(BasicInterpreter.java:67)
at com.android.build.gradle.internal.incremental.ConstructorBuilder$1.<init>(ConstructorBuilder.java:127)
at com.android.build.gradle.internal.incremental.ConstructorBuilder.build(ConstructorBuilder.java:127)
at com.android.build.gradle.internal.incremental.IncrementalSupportVisitor.visitMethod(IncrementalSupportVisitor.java:224)
at org.objectweb.asm.ClassVisitor.visitMethod(ClassVisitor.java:327)
at org.objectweb.asm.commons.SerialVersionUIDAdder.visitMethod(SerialVersionUIDAdder.java:236)
at org.objectweb.asm.tree.MethodNode.accept(MethodNode.java:685)
at org.objectweb.asm.tree.ClassNode.accept(ClassNode.java:436)
at com.android.build.gradle.internal.incremental.IncrementalVisitor.instrumentClass(IncrementalVisitor.java:370)
at com.android.build.gradle.internal.transforms.InstantRunTransform.transformToClasses2Format(InstantRunTransform.java:406)
at com.android.build.gradle.internal.transforms.InstantRunTransform.lambda$doTransform$3(InstantRunTransform.java:268)
at com.android.build.gradle.internal.transforms.InstantRunTransform.lambda$null$4(InstantRunTransform.java:297)
at java.util.concurrent.ForkJoinTask$AdaptedCallable.exec(ForkJoinTask.java:1424)
at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)
Twitter見てもInstant Runのネガティブな話しか見ないし、みんなOFFにしようぜ！と言いたいところでしたが、動かなくなったのは私のPRが原因なのは明らかだったので、ちゃんとした原因を調べました。
原因
動かなくなったきっかけは、FindBugsをSpotBugsに移行したことでした。Instant RunとSpotBugsはどちらもasmというライブラリを利用しています。そしてInstant Runはこの5系、SpotBugsは6系に依存しているのです。
通常このような依存関係の競合が発生した場合エラーメッセージで気付くと思いますが、ビルドスクリプトではそうではないようで（ここは詳しく調べてません）、Instant Runの方でも6系が使われるようになっていました。
ここで、BasicInterpreterというクラスは、6系以降、継承したクラスを使う場合はちゃんとAPIバージョンを指定してあげないとIllegalStateExceptionを投げるようになっています。
public BasicInterpreter() {
- super(ASM5);
+ super(ASM6);
+ if (getClass() != BasicInterpreter.class) {
+ throw new IllegalStateException();
+ }
}
しかしInstant Runの方は5系を使っており、当然そういう実装は意識していません。そのため以下のように継承したクラスを作成してしまっており、ビルドが通らなくなっているのでした。
BasicInterpreter interpreter = new BasicInterpreter() { boolean done = false; @Override // newValue is called first to initialize the frame values of all the local variables // we intercept the first one to create our own special value. public BasicValue newValue(Type type) { if (type == null) { return BasicValue.UNINITIALIZED_VALUE; } else if (type.getSort() == Type.VOID) { return null; } else { // If this is the first value created (i.e. the first local variable) // we use a special marker. BasicValue ret = done ? super.newValue(type) : new LocalValue(type); done = true; return ret; } } };
修正
spotbugsのタスクのときだけ6系を使うようにgradleを書き換えました。
- classpath 'gradle.plugin.com.github.spotbugs:spotbugs-gradle-plugin:1.6.5' + classpath('gradle.plugin.com.github.spotbugs:spotbugs-gradle-plugin:1.6.5') { + /* + asmのバージョン間の挙動の差異によりInstant Runが動かなくなるため、SpotBugs以外のタスクではexclude + 以下の実装でBasicInterpreterの使用方法が変更されたらここの設定は不要 + https://android.googlesource.com/platform/tools/base/+/studio-master-dev/build-system/instant-run-instrumentation/src/main/java/com/android/build/gradle/internal/incremental/ConstructorBuilder.java#127 + */ + if (project.gradle.startParameter.taskNames.find { it !=~ /spotbugs/ }) { + exclude group: 'org.ow2.asm' + } + }
色が微妙に透過される
概要
SwipeRefreshLayoutのローディングの色がよくよく見ると設定した色と異なっていました。
| 正 | 誤 |
|---|---|
 |
 |
原因
- setColorSchemeColors(R.color.primary) + setColorSchemeResources(R.color.primary)
カラーコードの整数値を渡すべき箇所でColor Resource IDを渡していました。Androidあるあるですね。
（Androidでは、色やテキストのように、多くの場所で使用することのあるリソースや環境によって変えることがあるリソースはXMLに定義し、自動的にIDが付与されます。）
しかしなんと偶然にも、自動生成されたColor Resource IDをカラーコードとして見ても割と似た色になっていたのです！
なお、このアプリは2016年初頭からFull Kotlinで実装されてきたものでした。そのため、通常IDEでワーニングが出るところですが、実装当時はワーニング表示がKotlinに対応していなかったのではないかと思います。
現在では問題なくワーニング表示されていたため発見に至りました。
Resource IDの振られ方
Resource IDの振られ方というのは実はシンプルで、かつ頻繁に値が大きく変わるものでもないのです。
- まず各リソース種別ごとにアルファベット順にソートされます。
- 次に、種別もアルファベット順にソートされ、種別ごとに最初のIDが割り振られます。
R.anim.*だったら0x7f010000から、R.animator.*だったら0x7f020000から、……という具合です。 - 最後に、同種のリソースごとアルファベット順にIDが付与されていきます。
R.anim.aが0x7f010000、R.anim.bが0x7f010001……という具合です。
R.color.primaryはcolorリソースの中では後の方に出てきます。実際に数字にすると0x7f050053で、カラーコードとして見ると青系統でした。カラーリソースの数を大幅に増やしたり、名前を辞書順で頭の方に近づけない限りは、大体青系統の色になります。弊社のイメージカラーも青系統ですので、似てしまったというわけです。
まとめ
2019年版の記事のネタが生まれないよう努力いたします。
エンジニア募集中
エムスリーでは、共に医療 × テクノロジーの未来を切り拓いてくれる仲間を募集中です。 「私が見つけたバグの方が根が深い」「我こそがバグ調査の達人だ」という方はぜひカジュアル面談やTech Talkにお越しください！
なんと直近では12/6にイベントがあります！こちらもぜひお越しください！！
