本文書では、吉里吉里/KAGでエラーが発生した時に記録されるkrkr.console.logの、 エラー部分の読み方を詳細に説明する。
「エラーが出るけど原因が分からない」というのは、よほど難しいエラーなのか、 よほどアナタがエラーログを真面目に読んでいないのかのいずれかだ。 スクリプタを自負するなら、エラーログを見て原因追求くらいできてしかるべき。 この文書が、デバッグの一助となることを願って止まない。
今の今まで、なぜかこういう文書がないのが不思議。これ知っていれば、何をどう 直せばよいかが分かるようになるから、こういう文書こそ必要だと思うんだけど…。 あ、オフィシャルがないので、自前で「こう思ってる」のを書いているため、 決して正解ではないかもしれないので、もし間違いとか発見したら是非教えて 下さい。
エラーログは、コンソールから確認できる。具体的には、ゲーム画面上でShift+F4 (またはメニューバーから[デバッグ]→[コンソール])でコンソール画面が開き、 そこから確認できる。エラーが発生したら、その最後の方に 注目するとよい。…ということすら知らない人が居るのでこう書いてみた次第。 わかんない人は、まずは黙ってマニュアルを読むこと。
エラーが発生したら、なにはともあれまずはコンソールを開こう。話はそれからだ。 吉里吉里のエラーメッセージはかなり親切なので、ざっとメッセージを 読むことで、八割の問題は解決できる(…はず)。
以下のようなエラー出力された場合を考える。説明するために、左端に行番号を 付加している。実際のコンソール上ではこのような行番号は存在しないことに注意。
(snip) 01 02:56:57 first.ks : [rclick call=true storage="rclick_tjs20a.ks" target="*rclick" enabled=true name="メニュー(&S) ..."] 02 02:56:57 first.ks : 03 02:56:57 first.ks : [call storage=20100717Demo.ks] 04 02:56:57 first.ks : call stack depth before calling : 0 05 02:56:57 ================================================================================ 06 02:56:57 Scenario loaded : 20100717Demo.ks 07 02:56:57 20100717Demo.ks : 08 02:56:57 20100717Demo.ks : [nowait] 09 02:56:57 20100717Demo.ks : [select] 10 02:56:57 trace : 11 02:56:57 エラーが発生しました 12 ファイル : 20100717Demo.ks 行 : 4 13 タグ : select ( ← エラーの発生した前後のタグを示している場合もあります ) 14 タグ/マクロ "select" は存在しません |
エラーログは下から読んでいくのが基本。まず14行目、「タグ/マクロ "select" は 存在しません」と言われているのだから、きっと[select ....]というタグまたは マクロを、定義してないのに使ったのだろう、ということが分かる。その上、 11〜13行目を見れば、20100717Demo.ks中の4行目でエラーが発生していることが 分かる。
さらにその上を見てみよう。01〜09行目は、実行中だったKAGスクリプトが表示 されている。01〜04まではfirst.ks、04行目で[call storage=20100717Demo.ks]を 実行して、07行目でその先頭から実行しているようだ。で、09行目で[select]を 実行してエラーになっている。
ということで、このエラーログからは、 『first.ksから呼び出された20100717Demo.ks中の4行目で、 [select]を実行したんだけどそれがマクロとして定義されていなかった』ために エラーとなったことが分かった。ここまでは5秒くらで分かるようになろう。
あとは少々トンチを働かせてデバッグするだけだ。
次のエラーも、よく見るタイプ。
(snip) 01 03:58:46 eruby.ks : jumped to : *eruby_loop 02 03:58:46 eruby.ks : [return cond="mp.idx >= mp.str.length"] 03 03:58:46 eruby.ks : [emb exp="mp.str[mp.idx]"] 04 03:58:46 eruby.ks : [if mp.idx == 0] 05 03:58:46 ==== An exception occured at conductor.tjs(81)[(function) timerCallback], VM ip = 111 ==== 06 03:58:46 -- Disassembled VM code -- 07 03:58:46 #(81) obj = getNextTag(); // 次のタグを得る 08 03:58:46 00000111 calld %1, %-2.*12() // *12 = (string)"getNextTag" 09 03:58:46 -- Register dump -- 10 03:58:46 %-5=(void) %-4=(object)(object 0x05593A10:0x05593A10) %-3=(void) 11 03:58:46 %-2=(object)(object 0x0013FA24:0x00000000) %-1=(object)(object 0x018DB4CC:0x018DB4CC) 12 03:58:46 %0=(void) %1=(void) %2=(int)0 %3=(int)0 %4=(int)120459880 %5=(string)"onPaint" 13 03:58:46 %6=(string)"onKeyDown" %7=(int)0 %8=(void) %9=(object)(object 0x05593A10:0x05593A10) 14 03:58:46 ------------------------------------------------------------------------------------------ 15 03:58:46 trace : 16 03:58:46 エラーが発生しました 17 ファイル : eruby.ks 行 : 180 18 タグ : 不明 ( ← エラーの発生した前後のタグを示している場合もあります ) 19 タグの文法エラーです。'[' や ']' の対応、" と " の対応、スペースの入れ忘れ、余分な改行、macro 〜 endmacro の対応、必要な属性の不足などを確認してください |
例によって下から見ていく。19行目で「文法エラーです」と言われているので、多分 KAGかTJSの文法エラーしたのだろうなぁ、と思う。17行目で、その場所はeruby.ksの 180行目だということが分かる。もうこの瞬間にeruby.ksをエディタで開いて180行目を 確認してもよいが、その上、04行目がエラー発生行なので、ここをじーっと眺めて みよう。
…わかった？[if mp.idx == 0]と書いてあるが、本来は[if exp="mp.idx == 0"]で なければならなかったのだ。ちょっと他の言語やってると、すぐKAGの[if]タグの 書き方忘れるからイカンなぁ、と思う。ここまでもやっぱり30秒くらいで分かるように なろう。
なお、05〜14行目は、今回は見なくてよい。後に読み方を説明する。
以下は、「覚えとこう」的エラー。
(snip) 04:07:43 ==== An exception occured at conductor.tjs(81)[(function) timerCallback], VM ip = 111 ==== 04:07:43 -- Disassembled VM code -- 04:07:43 #(81) obj = getNextTag(); // 次のタグを得る 04:07:43 00000111 calld %1, %-2.*12() // *12 = (string)"getNextTag" 04:07:43 -- Register dump -- 04:07:43 %-5=(void) %-4=(object)(object 0x0197F39C:0x0197F39C) %-3=(void) 04:07:43 %-2=(object)(object 0x0013F780:0x00000000) %-1=(object)(object 0x018DB4CC:0x018DB4CC) 04:07:43 %0=(void) %1=(void) %2=(int)0 %3=(int)0 %4=(int)120997626 04:07:43 %5=(object)(object 0x0197F39C:0x0197F39C) %6=(void) 04:07:43 %7=(object)(object 0x0185AEFC:0x0185AEFC) %8=(void) %9=(int)1000 04:07:43 ------------------------------------------------------------------------------------------ 04:07:43 trace : 04:07:43 エラーが発生しました ファイル : 20100717Demo.ks 行 : 35 タグ : 不明 ( ← エラーの発生した前後のタグを示している場合もあります ) シナリオファイルに変更があったため return の戻り先位置を特定できません |
エラーメッセージ見てもわかんないと思う。結論だけ言えば、正にエラーメッセージ 通り、「シナリオファイルが変更されたため、return の戻り位置を特定できなかった」 のがエラー原因。
吉里吉里/KAGでは、[call]タグで呼び出して[return]タグで呼び出し元に戻ることが できる。この動作は以下のようなシーケンスで実行される。
ということで、こうなっちゃうともうどうしようもないので、特にパッチを作る 時には、[call]を使っている行の内容と、その行番号が変わらないように作成しよう、 というなんか「もやっ」とした助言しかできない。これは吉里吉里最大の弱点だが、 同時に他にどうしようもない問題ではある。
以下はTJSが絡むちょっと難しい例。
(snip) 01 04:42:33 first.ks : returned to : *main_loop line offset 21 02 04:42:33 first.ks : call stack depth after returning : 0 03 04:42:33 first.ks : [text_init] 04 04:42:33 ==== An exception occured at sakura.ks(452)[(function) resetVisibleState], VM ip = 4 ==== 05 04:42:33 -- Disassembled VM code -- 06 04:42:33 #(452) for (var n = sakuras.count-1; n >= 0; n--) 07 04:42:33 00000000 gpd %1, %-2.*0 // *0 = (string)"sakuras" 08 04:42:33 00000004 gpd %2, %1.*1 // *1 = (string)"count" 09 04:42:33 -- Register dump -- 10 04:42:33 %-4=(int)-1 %-3=(int)-1 %-2=(object)(object 0x0013DADC:0x00000000) 11 04:42:33 %-1=(object)(object 0x05520000:0x05520000) %0=(void) %1=(void) 12 04:42:33 %2=(object)(object 0x053602A4:0x053602A4) %3=(int)-1 %4=(int)1 13 04:42:33 ----------------------------------------------------------------------------------------- 14 04:42:33 trace : sakura.ks(504)[(function) onCopyLayer] <-- mainwindow.tjs(3191)[(function expression) (anonymous)] <-- mainwindow.tjs(598)[(function) forEachEventHook] <-- mainwindow.tjs(3190)[(function) backupLayer] <-- mainwindow.tjs(5416)[(function expression) (anonymous)] <-- conductor.tjs(440)[(function) onTag] <-- conductor.tjs(104)[(function) timerCallback] 15 04:42:33 エラーが発生しました 16 ファイル : first.ks 行 : 79 17 タグ : backlay ( ← エラーの発生した前後のタグを示している場合もあります ) 18 (void) から Object へ型を変換できません。Object 型が要求される文脈で Object 型以外の値が渡されるとこのエラーが発生します |
今までのエラー例を見た人なら、16行目、17行目から、first.ksの79行目にある [backlay]タグでエラーが出たのだななるほどなるほど、と思うだろう。実はそれは 誤りだ。17行目に書いてあるように、「エラーの発声した前後のタグを示している 場合がある」のであるよ。今回の正解は、first.ksの78行目(かどうかは このメッセージからは 分からないけれど)の、[text_init]タグの中のTJSスクリプトにエラーの原因があった。 この場合、どのファイルのどの部分にエラーがあるかは、04行目、 "An exception occured at..."に注目すればよい。
04 04:42:33 ==== An exception occured at sakura.ks(452)[(function) resetVisibleState], VM ip = 4 ==== |
これを日本語にすれば、「sakura.ksの452行目、resetVisibleState()関数内で例外が 発生した」…となる。
次に見るべきは14行目。ここでは、このTJS関数 resetVisibleState() が、 どのような経路で呼ばれたかが記録されている。横長に書かれてて分かりづらいので インデントと日本語補足付きで書き直してみよう。
trace :(resetVisibleState()は、) sakura.ks(504行目)：onCopyLayer()内から呼ばれ、これは、 mainwindow.tjs(3191行目)：function expression(その場に定義した関数)から呼ばれ、これは、 mainwindow.tjs(598行目)：forEachEventHook()内から呼ばれ、これは、 mainwindow.tjs(3190行目)：backupLayer()内から呼ばれ、これは、 mainwindow.tjs(5416行目)：function expressionから呼ばれ、これは、 conductor.tjs(440行目)：onTag()内から呼ばれ、これは、 conductor.tjs(104行目)：timerCallback()内から呼ばれた |
一番上が最後の、一番下が最初の呼び出し元を表している。resetVisibleState() 関数自体はこのトレースに出てこないので気をつけて。沢山あるが、 重要なのはトレースの一番上だけ、または二番目までだけだったりする。結局、 sakura.ks内で、onCopyLayer()→resetVisibleState()を呼び出した後に、 resetVisibleState()内でエラーになっていることがわかればいい。
そこまできたら今回の山場、VM(多分Virtual Machine...吉里吉里本体)コードの 解析、具体的には06行目〜12行目までの解析となる。まず06行目を見ることで、 エラーが発生した行がわかる。すなわち、今回エラーとなったのは、sakura.ksの 452行目、resetVisibleState()内の「for (var n = sakuras.count-1; n >= 0; n--)」 という行だということが分かる。
06 04:42:33 #(452) for (var n = sakuras.count-1; n >= 0; n--) 07 04:42:33 00000000 gpd %1, %-2.*0 // *0 = (string)"sakuras" 08 04:42:33 00000004 gpd %2, %1.*1 // *1 = (string)"count" 09 04:42:33 -- Register dump -- 10 04:42:33 %-4=(int)-1 %-3=(int)-1 %-2=(object)(object 0x0013DADC:0x00000000) 11 04:42:33 %-1=(object)(object 0x05520000:0x05520000) %0=(void) %1=(void) 12 04:42:33 %2=(object)(object 0x053602A4:0x053602A4) %3=(int)-1 %4=(int)1 |
さてそこからが問題。一体、何がどうエラーになったのだろうか。キモは07行と08行を しっかり読むことだ。
07行目は、「sakuras = SakuraPlugin(またはthis)["sakuras"]であり、 これを %1 = %-2.*0 で表す」ことを示している。このあたり、詳細は このあたりに紹介されているので是非一度チェックして欲しい。 のだが、これが「あーなるほど」と分かるには、一般的な VMの知識とか構文解析の知識とか、あるいは桜クラス(=SakuraPlugin(またはthis))が どう定義されているかが必要になるような気がして実に不親切だと思う。 思うけどそういうものらしいから仕方がない。とりあえずは07行目右の 「// *0 = (string)"sakuras"」という記述がヒントになろう。これと、452行の 中で表されているものを見比べて、"sakuras"が必要な部分を探せば、 なんとなく見えてくるのではあるまいか。すなわちここでは、
で、同じように08行目を解析すると、「sakuras.count = sakuras["count"]であり、 これを %2 = %1.*1 で表す」となる。ここでは以下が定義されている。 ただし、08行目で、%2に値を代入する前にエラーになっているので、レジスタダンプで 表示されている%2の値は信用できないことを忘れずに。
ここまできたらもう10〜12行目は分かったも同然。ちょっと横に長いから改行入れて 書き直して、上の定義をそのまま当てはめてみる。
%-4=(int)-1 %-3=(int)-1 %-2=(object)(object 0x0013DADC:0x00000000) ...... SakuraPlugin(クラス定義)、またはthis %-1=(object)(object 0x05520000:0x05520000) %0=(void) %1=(void) ................................. sakuras %2=(object)(object 0x053602A4:0x053602A4) %3=(int)-1 %4=(int)1 |
で、18行目のエラーメッセージを再確認する。「(void) から Object へ 型を変換できません」。だったら、オブジェクトがあるべきところに void が代入 されているのはどこか、という観点で見れば一目瞭然、%1がvoidになっている。 にも関わらず、sakuras.count を参照しようとしたのが、今回のエラーの原因だ。
で、ここからはトンチ。「なぜsakurasがvoidになったのか」を探していく。その 過程は「エラーメッセージを読む」ことの大筋から外れるので、ここでは述べない。 いずれにしても、 上のようなちょっとややこしいエラーメッセージが出ても、ちゃんと追いかければ 問題の直接原因はばっちり把握できることを忘れずに。
以下も、エラー例４と同じく、TJSが絡むちょっと難しい例。
(snip) 01 03:21:12 20100717Demo.ks : [text_mode mode=window] 02 03:21:12 20100717Demo.ks : ルビ機能を拡張して、均等割り振りを実現します。 03 03:21:13 20100717Demo.ks : [font size=48][eruby text=こんなカンジ 均等割りの例][resetfont]。 04 03:21:16 ==== An exception occured at ExtHistoryLayer.ks(1450)[(function) tag2dic], VM ip = 48 ==== 05 03:21:16 -- Disassembled VM code -- 06 03:21:16 #(1450) if (str[str.length-1] == ']') 07 03:21:16 00000038 gpd %1, %-3.*3 // *3 = (string)"length" 08 03:21:16 00000042 const %2, *2 // *2 = (int)1 09 03:21:16 00000045 sub %1, %2 10 03:21:16 00000048 gpi %3, %-3.%1 11 03:21:16 -- Register dump -- 12 03:21:16 %-9=(object)(object 0x0554FF64:0x0554FF64) %-8=(object)(object 0x0567BA68:0x0567BA68) 13 03:21:16 %-7=(void) %-6=(object)(object 0x0510B958:0x0510B958) %-5=(void) %-4=(int)1 14 03:21:16 %-3=(string)"" %-2=(object)(object 0x0013D1E0:0x00000000) 15 03:21:16 %-1=(object)(object 0x0510B958:0x0510B958) %0=(void) %1=(int)-1 %2=(int)1 %3=(int)1 16 03:21:16 %4=(string)"" %5=(int)1 %6=(string)"\"" %7=(string)"\"" 17 03:21:16 ------------------------------------------------------------------------------------------ 18 03:21:16 trace : ExtHistoryLayer.ks(1373)[(function) getTextWidth] <-- ExtHistoryLayer.ks(905)[(function) store] <-- ExtHistoryLayer.ks(895)[(function) store] <-- ExtHistoryLayer.ks(2134)[(function) store] <-- ExtHistoryLayer.ks(2433)[(function) storeTag] <-- anonymous@0x050AFBB0(1)[(top level script) global] <-- mainwindow.tjs(5777)[(function expression) (anonymous)] <-- conductor.tjs(440)[(function) onTag] <-- conductor.tjs(104)[(function) timerCallback] 19 03:21:16 エラーが発生しました 20 ファイル : 20100717Demo.ks 行 : 32 21 タグ : eval ( ← エラーの発生した前後のタグを示している場合もあります ) 22 値が範囲外です |
「あー、これはExtHistoryLayer.ksの1450行目、tag2dic()関数内の 『if (str[str.length-1] == ']')』って行でエラーになってるんだなー、それは ExtHistoryLayer.ksのgetTextWidth()関数の1373行目から呼ばれたんだなー」くらいは 10秒以内に分かるようになって欲しい。このための訓練は上のエラー例４で終了 していると信じる。
さて、では Disassembled VM code(06〜10行目)を見てみよう。ここでは、以下の ように定義している、らしい。
%-9=(object)(object 0x0554FF64:0x0554FF64) %-8=(object)(object 0x0567BA68:0x0567BA68) %-7=(void) %-6=(object)(object 0x0510B958:0x0510B958) %-5=(void) %-4=(int)1 %-3=(string)"" .................................. str %-2=(object)(object 0x0013D1E0:0x00000000) %-1=(object)(object 0x0510B958:0x0510B958) %0=(void) %1=(int)-1 ...................................... str.length-1 %2=(int)1 ....................................... (const int)1 %3=(int)1 %4=(string)"" %5=(int)1 %6=(string)"\"" %7=(string)"\"" |
10行目で%3に値を代入しようとしてエラーになっているので、%3の値は信用できないと 考えてよい。そうすると、str[str.length-1]を実行しようとして失敗していて、 このとき str = "" だから、str[-1]を実行しようとしていたわけだ。ここでやっと 22行目のエラーメッセージ「値が範囲外です」の意味が分かる。配列の添え字として -1 を指定したためだ。なるほど！
…というように見ていけば、エラーが発生した直接原因は非常にロジカルに判明 するのであった。あとは間接原因を一つ一つツブしていけばよい。ここでは、 ExtHistoryLayer中で、str=""の時に処理をスキップするように修正した。
…というカンジで、真面目にデバッグする方法について述べてみた、というところ。 我輩時折ボランティアで全然関係ない人のデバッグを手伝ったりするのであるが、 「それを我輩に聞くな！」みたいなお問い合わせも多くて多くて、それを少しでも 減らそう、と思ったのがこの文章を書くモチベーションだったりする。もちろん、 皆様がこれを読んで、自分のスクリプトのデバッグに役立ててくれるのであれば、 こんなに嬉しいことは無いんだけれども。
あとは、愚痴のようなもの。 あなたがスクリプタなら、あるいは他人のプラグインを使わせて頂いているなら、 「エラーが出た。どゆこと？」と人に聞く前に、以上の文章を一通り読もう。 そして、少なくとも「解析に必要なログがどこからどこまでであるか」を 学び、必要十分なエラーログを提供しよう。それが人にモノを尋ねる前の 最低限の礼儀だと思う。 エラーログなし・再現条件なし・再現環境無しの状態でこっちに投げられても、 どうしようもないっちぅねん。