Entity Framework 6 で Azure の SQL データベースにアクセスするとセマフォがうんたら言われる問題への対処

13867 ワード
EntityFramework EntityFramework テキストリンク

問題

Azure の SQL データベースに定期的にアクセスする Windows サービスを作っていたのですが、何日か連続で動かしているとたまにこんなエラーがでます。

System.Data.Entity.Core.EntityCommandExecutionException: An error occurred while executing the command definition. See the inner exception for details. ---> System.Data.SqlClient.SqlException: サーバーから結果を受信しているときに、トランスポート レベルのエラーが発生しました。 (provider: TCP Provider, error: 0 - セマフォがタイムアウトしました。) ---> System.ComponentModel.Win32Exception: セマフォがタイムアウトしました。

原因

で、いろいろ調べて原因はわかった。
http://tech.exceedone.co.jp/asp-net-mvc/cloud-sql-azure-connection-retry/

クラウドのデータベース(SQL Azure)は可溶性を保つために、ロードバランサーがデータベースの間にはいっており、適時切り替えられます。

ということは、プログラムから接続したセッション（コネクションプール）が無効になっており、再度セッションを張る必要があります。

対処

うまくいかない。。

Entity Framework 6 だと
http://qiita.com/mocha/items/f56b477630f9e4481aa2
とかで簡単に再接続処理を組み込めるみたいなのですが、どうにも再接続が効いていない気がする。
デバッグ実行したらやっぱりリトライすることなく catch ブロックに飛んでいく。

test.cs
try
{
  using (var context = new ApplicationDbContext())
  {
    // カウントを取得するだけ（この処理を行うまえにネットワークを切断する）
    var count = context.Hoges.Count(); // ☆ここで失敗するとリトライしてくれるんじゃないの？？
  }
}
catch (Exception e)
{
  Console.WriteLine(e);
}

うまくいった

海外のサイトも漁って、やっとここにたどり着く。
http://msdn.microsoft.com/en-us/data/dn469464.aspx

SqlAzureExecutionStrategyを派生したApplicationStrategyで、ShoudRetryOn メソッドをオーバーライドすることによってリトライ時の挙動をカスタマイズすることができるらしい。
こうしてみた。

ApplicationStrategy.cs
    public class ApplicationStrategy : SqlAzureExecutionStrategy
    {
        /// <summary>
        /// カウント用
        /// </summary>
        private int _count = 0;

        public ApplicationStrategy() : base()
        {
            Debug.WriteLine("コンストラクタ <" + GetHashCode() + ">");
        }

        public ApplicationStrategy(int maxRetryCount, TimeSpan maxDelay)
            : base(maxRetryCount, maxDelay)
        {
            Debug.WriteLine("コンストラクタ2 <" + GetHashCode() + ">");
        }

        protected override bool ShouldRetryOn(Exception exception)
        {
            SqlException sqlException = exception as SqlException;
            if (sqlException != null)
            {
                Debug.WriteLine("{0} [{1}]失敗{2}回目です。。",
                    DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss(fff)"),
                    GetHashCode(),
                    ++_count);
                return true;
            }
            return base.ShouldRetryOn(exception);
        }
    }

意図的にネットワークを切断してみたときのログはこんな感じ（リトライ回数は5、リトライ間隔は30秒）。

コンストラクタ2 <42387602>
コンストラクタ2 <34449534>
コンストラクタ2 <61826280>
コンストラクタ2 <21803985>
コンストラクタ2 <21548186>
コンストラクタ2 <11060407>
コンストラクタ2 <4757004>
コンストラクタ2 <43989438>
コンストラクタ2 <58736510>
コンストラクタ2 <45655991>
コンストラクタ2 <59956320>
コンストラクタ2 <42290028>
コンストラクタ2 <21251484>
コンストラクタ2 <50052055>
コンストラクタ2 <38868335>
コンストラクタ2 <65654745>
コンストラクタ2 <7490004>
コンストラクタ2 <38654717>
コンストラクタ2 <41339550>
コンストラクタ2 <12551388>
コンストラクタ2 <44844895>
コンストラクタ2 <51558565> <-- ☆
コンストラクタ2 <33526412>
コンストラクタ2 <32405628>
コンストラクタ2 <48573094>
コンストラクタ2 <51650977>
2014/10/23 13:29:24(182) [51558565]失敗1回目です。。 <-- ☆
2014/10/23 13:29:25(119) [60884226]失敗1回目です。。
2014/10/23 13:29:25(151) [60884226]失敗2回目です。。
2014/10/23 13:29:26(260) [60884226]失敗3回目です。。
2014/10/23 13:29:29(505) [60884226]失敗4回目です。。
2014/10/23 13:29:37(935) [60884226]失敗5回目です。。
2014/10/23 13:29:53(955) [60884226]失敗6回目です。。
2014/10/23 13:29:53(970) [51558565]失敗2回目です。。 <-- ☆
2014/10/23 13:29:55(065) [5367331]失敗1回目です。。
2014/10/23 13:29:55(097) [5367331]失敗2回目です。。
2014/10/23 13:29:56(239) [5367331]失敗3回目です。。
2014/10/23 13:29:59(369) [5367331]失敗4回目です。。
2014/10/23 13:30:06(549) [5367331]失敗5回目です。。
2014/10/23 13:30:23(547) [5367331]失敗6回目です。。
2014/10/23 13:30:23(563) [51558565]失敗3回目です。。 <-- ☆
2014/10/23 13:30:26(878) [29895661]失敗1回目です。。
2014/10/23 13:30:26(911) [29895661]失敗2回目です。。
2014/10/23 13:30:28(059) [29895661]失敗3回目です。。
2014/10/23 13:30:31(287) [29895661]失敗4回目です。。
2014/10/23 13:30:38(801) [29895661]失敗5回目です。。
2014/10/23 13:30:54(767) [29895661]失敗6回目です。。
2014/10/23 13:30:54(788) [51558565]失敗4回目です。。 <-- ☆
2014/10/23 13:31:02(374) [57177419]失敗1回目です。。
2014/10/23 13:31:02(421) [57177419]失敗2回目です。。
2014/10/23 13:31:03(516) [57177419]失敗3回目です。。
2014/10/23 13:31:07(677) [57177419]失敗4回目です。。
2014/10/23 13:31:15(323) [57177419]失敗5回目です。。
2014/10/23 13:31:30(532) [57177419]失敗6回目です。。
2014/10/23 13:31:30(541) [51558565]失敗5回目です。。 <-- ☆
コンストラクタ2 <62572816>
コンストラクタ2 <15348643>
2014/10/23 13:31:46(750) [15348643]失敗1回目です。。
2014/10/23 13:31:46(774) [15348643]失敗2回目です。。
2014/10/23 13:31:47(847) [15348643]失敗3回目です。。
2014/10/23 13:31:51(138) [15348643]失敗4回目です。。
2014/10/23 13:31:58(345) [15348643]失敗5回目です。。
2014/10/23 13:32:14(629) [15348643]失敗6回目です。。
2014/10/23 13:32:14(629) [51558565]失敗6回目です。。 <-- ☆
型 'System.Data.Entity.Infrastructure.RetryLimitExceededException' の初回例外が EntityFramework.dll で発生しました
System.Data.Entity.Infrastructure.RetryLimitExceededException: Maximum number of retries (5) exceeded while executing database operations with 'ApplicationStrategy'. See inner exception for the most recent failure. ---> System.Data.Entity.Core.EntityException: The underlying provider failed on Open. ---> System.Data.Entity.Infrastructure.RetryLimitExceededException: Maximum number of retries (5) exceeded while executing database operations with 'ApplicationStrategy'. See inner exception for the most recent failure. ---> System.Data.SqlClient.SqlException: SQL Server への接続を確立しているときにネットワーク関連またはインスタンス固有のエラーが発生しました。サーバーが見つからないかアクセスできません。インスタンス名が正しいこと、および SQL Server がリモート接続を許可するように構成されていることを確認してください。 (provider: TCP Provider, error: 0 - そのようなホストは不明です。) ---> System.ComponentModel.Win32Exception: そのようなホストは不明です。

☆だけに注目するとそれっぽくリトライできていますね。間に挟まっているのはなんなんだろう。コネクションをプーリングしているからかと思って接続文字列にpooling=false;を入れてみたけど結果変わらず。

トランザクションを使った処理もちゃんと動きました（リトライ回数は5、リトライ間隔は30秒）。

型 'System.Data.Entity.Core.EntityCommandExecutionException' の初回例外が EntityFramework.dll で発生しました
2014/10/23 13:41:52(003) [29135544]失敗1回目です。。
型 'System.Data.Entity.Core.EntityException' の初回例外が EntityFramework.dll で発生しました
2014/10/23 13:41:55(428) [29135544]失敗2回目です。。
型 'System.Data.Entity.Core.EntityException' の初回例外が EntityFramework.dll で発生しました
2014/10/23 13:41:57(182) [29135544]失敗3回目です。。
型 'System.Data.Entity.Core.EntityException' の初回例外が EntityFramework.dll で発生しました
2014/10/23 13:42:02(454) [29135544]失敗4回目です。。
スレッド 0x1690 はコード 259 (0x103) で終了しました。
型 'System.Data.Entity.Core.EntityException' の初回例外が EntityFramework.dll で発生しました
2014/10/23 13:42:11(136) [29135544]失敗5回目です。。
型 'System.Data.Entity.Core.EntityException' の初回例外が EntityFramework.dll で発生しました
2014/10/23 13:42:29(838) [29135544]失敗6回目です。。
型 'System.Data.Entity.Infrastructure.RetryLimitExceededException' の初回例外が EntityFramework.dll で発生しました
System.Data.Entity.Infrastructure.RetryLimitExceededException: Maximum number of retries (5) exceeded while executing database operations with 'ApplicationStrategy'. See inner exception for the most recent failure. ---> System.Data.Entity.Core.EntityException: The underlying provider failed on Open. ---> System.Data.SqlClient.SqlException: SQL Server への接続を確立しているときにネットワーク関連またはインスタンス固有のエラーが発生しました。サーバーが見つからないかアクセスできません。インスタンス名が正しいこと、および SQL Server がリモート接続を許可するように構成されていることを確認してください。 (provider: TCP Provider, error: 0 - そのようなホストは不明です。) ---> System.ComponentModel.Win32Exception: そのようなホストは不明です。

でも、リトライ間隔（30秒）は無視されてますね。なんなんだろう。。

納得いかないこと（メモ）

  • そもそも、DBConfiguration の拡張だけでなぜリトライが効かないのか。
  • ApplicationStrategyでselectのリトライ処理を行ったときの内部処理が意味不明。なんでApplicationStrategyのインスタンスがいっぱい使われてるの？
  • ApplicationStrategyでupdate（トランザクション）のリトライ処理を行ったとき、リトライ間隔の設定が無視されていた。なんで？

ローカルDB（MDFファイル）へのアタッチに失敗する問題への対処

MSTestではローカルDBにアタッチしてConfiguration.Seed()を流し込むようにしているのですが、ファイルにアタッチできないとか言われます。
しょうがないので、無理やりSqlAzure用のストラテジを無効化して回避しました。泥臭い。
```COnfiguration.cs

public sealed class Configuration : DbMigrationsConfiguration<ApplicationDbContext>
{
    public Configuration()
    {
        // ☆ローカルDBにアクセスするときにSqlAzureExecutionStrategyを使うとエラーになるための苦肉の策。
        ApplicationConfiguration.SuspendExecutionStrategy = true;

        // いろいろ
    }

    protected override void Seed(ApplicationDbContext context)
    {
        // いろいろ

        // ☆戻しておく
        ApplicationConfiguration.SuspendExecutionStrategy = false;
    }
}