トップ «前の日記(2012-03-04) 最新 次の日記(2012-03-08)» 編集

日々の破片

Subscribe with livedoor Reader
著作一覧

2012-03-06

_ 今日のエニグマ

こちらのバグだとは思うのだが、どうにも釈然としないのでメモ。

次のようなC#のコードで動くASP.NETと統合されたWCF RESTサービス。

/// ユーティリティ群
internal class Logger { ... } // 独自のバックアップハンドリングとかあるので作り込み。
internal class TableMapper { // 軽いモデルが成長してしまったやつ
  delegate void UserCode(SqlConnection c);
  // せっかくコネクションを持っているから、アプリケーション独自
  // 処理にも開放してやるか。
  internal void UserTransactionProc(UserCode cb)
  {
     // コネクション関係のいろいろ
     try
     {
        cb(connection);
        connection.Commit();
     }
     catch (Exception e)
     {
         Logger.Log(e);
         connection.RollBack();
         throw; // 3/7 1:00追加。これがなきゃ外のcatchのコメントは合わないよね。
     }
     finally
     {
        // 後片付け。 
     }
  }
}
/// サービス
public string FooBar(string arga, string argb)
{
    try
    {
       bool success = false;
       // arga, argbの検証
       var t = TableMapper.CreateGeneral();
       t.UserTransactionProc((c) =>
       {
          var command = c.CreateCommand(); // とかなんとか
          command.Parameters.Add(new SqlParameter("@foo", arga));
          ....
          success = command.ExecuteNoQuery() == 1;
          if (success) 
          {
             callNextCommandChain(c);
          }
          else
          {
             Logger.Log("failed...argsa=" + arga);
           }
       });
    }
    catch
    {
       Logger.Log("foobar arga:" + arga); // Excepion was already Logged by TableMapper
       throw;
    }
    return CreateJson();
}

これがargaの特定パターンで、ログにfoobar arga: とだけ残して消失(クライアントへはRSTか500が返る)する。ログのメッセージパターンからは例外が起きているはずだが、その例外の大元となるSqlExceptionらしきものが何もない。そりゃ、TableMapperのtry節以外でArgumentExceptionとかもあり得るが、あくまでもあり得るというだけのことだし。

いくら考えてもわからない。

面倒になって、一番外側のcatchを次のようにした。

    catch (Exception e)
    {
       Logger.Log("foobar arga:" + arga, e); // maybe Exception logged twice
       throw;
    }
    return CreateJson();

すると、先ほどまでと同じargaの入力パターンに対して、ログが"failed...argsa=bad paramとなった。? 内側のログだよな。

まるで、printf入れると動きが変わるCのプログラムだ。

argaの腐れっぷりがILのスタックを壊す? いや、そんなばかな。

上のように簡略化した再現コードを作ったが、再現しない。まあ、しないほうが自然ではある。

というわけで、今日は疲れているので寝る。明日、再検討するか。

本日のツッコミ(全4件) [ツッコミを入れる]
_ 楓等 (2012-03-06 23:15)

UserTransactionProcの引数に渡すラムダ式が実行されるタイミングって同期でしょうか?

_ arton (2012-03-06 23:26)

同期です。(そこは上の簡略コードの通りに、スタックを確保して、UserTransactionProcを呼ぶと、スタックを確保してデリゲート(与えているのはラムダ記法ですが)を呼び出してまた、返ってくるという普通のコールバック。

_ 楓等 (2012-03-06 23:29)

ああいや、このコードでは同期ですが、その、簡略化されていないコードではどうかなと思って…。<br>非同期だとキャッチされないので…↓<br>using System;<br>using System.Diagnostics;<br>using System.ComponentModel;<br><br>namespace AsyncExceptionTest<br>{<br> class Program<br> {<br> static void Main(string[] args)<br> {<br> try<br> {<br> BackgroundWorker bw = new BackgroundWorker();<br> bw.RunWorkerCompleted += (s, e) =><br> {<br> throw new Exception("exception1");<br> };<br> bw.RunWorkerAsync();<br> }<br> catch(Exception e)<br> {<br> Debug.WriteLine("catch." + e.ToString());<br> }<br> Console.ReadLine();<br> }<br> }<br>}<br>ただ、catchとcatch(Exception e)で動きが変わるのはなんとも解せないですね。きもちわるいです。

_ 楓等 (2012-03-06 23:29)

あっと、時間差。失礼しました。同期なんですか。本当に謎ですねえ。


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|

ジェズイットを見習え