2019年1月30日に発生したシステム障害の解析

投稿日: 2019年2月1日 2020年6月18日
カテゴリー: プレイ日記
タグ: 雑記

現在の状態 2019/2/1 15:30

システム障害は解消されました。
対応お疲れ様でした ( ^^) _旦~~

現象(解消済み)

・新規装備の獲得はできるが、プレゼントボックスに強制退避される。
・この装備はプレゼントボックスから取り出すことはできない。（アプリ改修待ち）
・ガチャの装備品の獲得時の画像は表示されない。

上記は新たなバグではなく、暫定対応中の現象です。

10連ガチャがx連になっていた！
との書き込みが多いですが、それは、装備品は表示されず、プレゼントボックスに入っているので安心しましょう (*‘ω‘ *)。

10連のマナガチャを回した時の例です。
この場合、4つしか玉が表示されていませんが、キャラが4つ、装備が6つということです。

獲得表示も、キャラのみが表示されます。
装備の6つは表示されていないだけで、実際にはプレゼントボックスに入っています。

このようにプレゼントボックスに入っています。
受け取りは現在できませんが、アプリの改修後に受け取れます。

何が起きているのか

月雲はソフトウェアエンジニアをやっております。
iOSアプリの開発も長いので、やって良い範囲で適当に解析してみようと思います。

クラッシュログ

iOSのクラッシュログは誰でも参照可能です。
一部を整形して抜粋します。

Exception Type:  EXC_CRASH (SIGKILL)
Exception Codes: 0x0000000000000000, 0x0000000000000000
Exception Note:  EXC_CORPSE_NOTIFY
Termination Reason: Namespace SPRINGBOARD, Code 0x8badf00d
Termination Description: SPRINGBOARD, process-exit watchdog transgression:
 jp.co.atm.vcon.jp exhausted real (wall clock) time allowance of 5.00 seconds | 
 ProcessVisibility: Foreground |
 ProcessState: Running |
 WatchdogEvent: process-exit |
 WatchdogVisibility: Foreground |
 WatchdogCPUStatistics: ( | 
  "Elapsed total CPU time (seconds): 2.270 (user 2.270, system 0.000), 8% CPU", |
  "Elapsed application CPU time (seconds): 0.439, 1% CPU" |
 )
Triggered by Thread:  0

0x8badf00d (;´･ω･)
あぁ、出てますね。有名な “ate bad food” です。

iOSには番犬 (Watchdog) がおりまして、メインスレッドを常に監視しています。
時間がかかりすぎる処理があると、噛みついて、そのプロセスを落とします (SIGKILL)
怖いですね (；ﾟДﾟ)

今度、このようなWorkerを作るときは、名前は Garm にして、プロセスを殺す命令には GARURU と名前つけよう (*‘ω‘ *)

ガル、ガルル！ (ヘル様、あのプロセス殺しておきました！）

application CPU time (seconds): 0.439
CPU時間はそれほど消費していません。
よって、何らかの処理で待ち時間が発生していると考えられます。（推測）

このログの下に、クラッシュしたスレッドのコールスタックがロギングされているのですが、これは、dSYMファイルをリンクして、シンボル化(symbolicate)しないと読めません。


Thread 0 name:  Dispatch queue: com.apple.main-thread
Thread 0 Crashed:
0   libsystem_kernel.dylib        	0x00000001e7e42f0c 0x1e7e20000 + 143116
...

よって、ログの解析はここまでですね。

運営の発表

運営による、暫定対応の内容です。

ログと運営の発表から、以下の事が推測されます。

キーワードは「入手順」ということで、これをどのように実装するかはいくつか方法があります。
1. 入手時刻を保持し、それを使ってソートする。
2. 入手順そのものを数値で表現し、それを使ってソートする。

データの解析等の観点から、1は必ず持っていると思います。
ただし、処理の最適化の観点から、2も付随して保持し、ソート時にはこれを使うということも考えられます。

ここでは、1という前提で推測してみます。
(2なら、単なる表現のオーバーフローかな。）

現象の推測

・装備品には入手時刻のプロパティがある。
・入手時刻を利用した処理を実行すると、何らかの処理待ちが発生し閾値を超え、システムによって強制終了される。

原因の推測

・ある一定時刻以降の全ての装備品が対象ということは、それ以降の時刻表現に問題がある。
・この”問題”は、いくつか考えられる。
　・時刻表現としては問題がないが、それを受け取って処理をするアプリ側に問題がある（パースできない表現になっていたなど）
　・時刻表現そのものに問題がある。（エポックからの数値表現がオーバーフローした, サーバが不正な時刻表現を生成した…etc)

色々と推測できますが、装備がプレゼントボックスに退避され、アプリの改修で対応ができるとなると…
原因にある2つの合わせ技かもしれない。入手時刻データは変えずに処理できるようにするということなので。
（時刻表現に問題があるけど、アプリの改修で対応。）

まあ、実際にはわからないですけどね。
全然違う原因かもしれない。

運営さん、修正頑張ってくださいﾌｧ━(ゝω･o)9━ｨﾄｫ♪