トップ «前の日記(2011-01-26) 最新 次の日記(2011-01-29)» 編集

日々の破片

著作一覧

2011-01-28

_ NET FrameworkのException.StackTrace

追記:間違ってるところを修正yfakariyaさんのコメントも参照

昨日、同僚と例外を出しまくるテストをしていて恐ろしいことに気付いた。

次のようなメソッドをクラスライブラリで用意したのだった。

public int Foo(string s) 
{
   // たとえば
   try 
   {
       var m = KEYWORDS.match(s);
       if (m.Success) 
       {
           return int.Parse(m.Group[1]);
       }
   }
   catch (Exception e)
   {
       var b = new StringBuilder("argment is ok ?\r\n");
       b.Append("value=").Append(s);
       Logger.Write(e, b.ToString());  // LoggerはeのStackTraceプロパティをログする。
       throw new ArgumentException(b.ToString(), e);
   }
}
....
public void Write(Exception e, string s)
{
    ...
    logWriter.WriteLine(e.StackTrace);
    ...
}

おれの作ったクラスライブラリは、Java流儀というか、引数のnullチェックみたいなくだらないことはしない。そういうものは下位のクラスライブラリに任せる。したがってnullが与えられるとRegex.MatchがスローするArugmentNullExceptionを取る。(さすがにこれは例が単純過ぎるが、本来はいろいろな例外が引数によって発生する可能性がある)

しかし、ライブラリのユーザがまじめに例外を処理することはあまり期待しない。すればOKだがしなくてもそれはその時だ。そこで、後で原因がわかるようにこちらで例外を受けたらログをするわけだ。

で、そうやってnullを与えたりその他の(上の例だとちょっと他の例は考えにくいが)エラーになるパターンを与えたりしてログにさんざん書き込んだ。

で、ログを見てびっくり。

スタックトレースのボトムが、Foo(String s)になっているからだ。

このトレースみたら、悪いのはFooメソッド以外に存在しないことになってしまう。

そこでいろいろ試すと、どうも、アセンブリ境界(.NET Frameworkのアセンブリの直前のアセンブリの最初のメソッド)でスタックトレースが切られてしまうようだと気付いた。

いや、これはクラスライブラリを提供する側にとっては致命的だよ。誰が呼び出したかを調べるためにトレースを残そうとしているのに、それが残らないわけだから。

で、気づいて良かった良かったということで、ロガークラスのほうで

var st = new System.Diagnostics.StackTrace(1); // 0にするとロガーのこのメソッドになってしまう
logFile.WriteLine(st.ToString());

と書き出すようにして決着。

が、今、追試してみて、確かにアセンブリ境界で切れるようだと確信したが、どうしてこんな愚かな仕組みになっているんだ?(追記:メソッドの位置の問題で、アセンブリの境界ではなく、スロー元からキャッチしたメソッドまでを取り出すようになっているため、そのように見えていたということで、誤り) と疑問は拭えない。おれの設定とかがおかしいんんじゃないかという気がするわけだ。

追記:さらにいろいろ試すと、System.Diagnostics.StackTraceはフレームの位置を決められるというメリットはあるけれど、行番号をまったく残してくれないことに気付く。とすると、Environment.StackTraceのほうが行番号が付くから良いかも(しかし先頭2つがEnvironmentになってしまうのがいやな感じだ。というか、PDBファイルを置かなければいずれにしても行番号は無いはずだから、Diagnosticsのやつでも同じかなぁ。

本日のツッコミ(全3件) [ツッコミを入れる]
_ yfakariya (2011-01-29 00:33)

アセンブリ境界でスタックトレースが切れるって事象は出たことないです(今試しましたが再現せず)。再スローする際に throw; ではなく throw e; と書くと切れますが……(ここは Java などと仕様が異なります)<br>あと、StackTrace クラスは fNeeFileInfo 引数に true を渡して、*.pdb ファイルがアセンブリの隣にあれば行番号出ます。

_ yfakariya (2011-01-29 00:41)

あ、すみません、勘違いしていました。catch の呼び出し元を取りたいのですね。それでしたら StackTrace クラスで Main まで取れます。StackTrace プロパティはアプリケーションのルートなんかでログを出すときを想定しているので、throw ~ catch までのスタックトレースが出ます。

_ arton (2011-01-29 01:13)

どうもありがとうございます。いやー、結構知らないことがたくさん。<br>>再スローする際に throw; ではなく throw e; と書くと切れますが……(ここは Java などと仕様が異なります) <br>これは全く頭になかったです。(上の例とは関係ないですが、切れたらまずい場合でもうかつに書いてしまいそうですね)<br>>throw ~ catch までのスタックトレースが出ます<br>おお、なるほど。それならば意味付けが明らかなので納得です。


2003|06|07|08|09|10|11|12|
2004|01|02|03|04|05|06|07|08|09|10|11|12|
2005|01|02|03|04|05|06|07|08|09|10|11|12|
2006|01|02|03|04|05|06|07|08|09|10|11|12|
2007|01|02|03|04|05|06|07|08|09|10|11|12|
2008|01|02|03|04|05|06|07|08|09|10|11|12|
2009|01|02|03|04|05|06|07|08|09|10|11|12|
2010|01|02|03|04|05|06|07|08|09|10|11|12|
2011|01|02|03|04|05|06|07|08|09|10|11|12|
2012|01|02|03|04|05|06|07|08|09|10|11|12|
2013|01|02|03|04|05|06|07|08|09|10|11|12|
2014|01|02|03|04|05|06|07|08|09|10|11|12|
2015|01|02|03|04|05|06|07|08|09|10|11|12|
2016|01|02|03|04|05|06|07|08|09|10|11|12|
2017|01|02|03|04|05|06|07|08|09|10|11|12|
2018|01|02|03|04|05|06|07|08|09|10|11|12|
2019|01|02|03|04|05|06|07|08|09|10|11|12|
2020|01|02|03|04|05|06|07|08|09|10|11|12|
2021|01|02|03|04|05|06|07|08|09|10|11|12|
2022|01|02|03|04|05|06|07|08|09|10|11|12|
2023|01|02|03|04|05|06|07|08|09|10|11|12|
2024|01|02|03|

ジェズイットを見習え