日々の破片

_ 今日のエニグマ

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

次のような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のスタックを壊す？ いや、そんなばかな。

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

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