Windows Azure あるある:
せっかくデプロイしたのに「何かがおかしくて」BusyとAbortedを繰り返す
とまぁこういう状況を何とかデバッグするための小ネタです。
厳密ではないですが、ある程度の切り分けはできるんじゃないかな~的な。
さてWindows AzureでデプロイしたロールがBusy・Abortedを繰り返したりするときはどんな場合でしょうか。
十中八九、StartupTasksでこけてるケースだと思われますキリッ(経験談
どんなプロセスで起動してるかはこちらのWindows Azure Roleアーキテクチャ(蒼の王座)を参照して頂くとして、だいたいInitializeが終わった後Busyで止まるのはStartupTasksですね。
それ以外は決まりきった処理(カスタムな処理がない)のでこけるケースはマレなはず。(OnStartでこけたりするのはあるか)
で、一般的にStartup TasksはCMDファイルだったりでデバッグ面倒ですね。あとローカルではテストしにくいケースが大半だと思います。(たとえばWebPIを使ったインストールや、Azure上でしか使えない環境変数などを利用したりとか)
動作を見たくても、PaaSであるWindows Azure上のインスタンス起動時は見れません。
RDPを設定してもRDPが起動してなければ意味がないですね。(※指定したタスクがBackground等で動作する場合はこけてもRDPが起動して接続できたりする可能性はありますが)
じゃぁどうするのか?
RDPが起動してればOKなわけですから、Upgradeが出来るように同じエンドポイントで構成されたダミーの空っぽなサービスパッケージをデプロイして、RDPにつないでおいてから調べたい対象のサービスパッケージをUpgradeでデプロイしましょう。
基本的にRDPが切断されるのは一瞬だけ(RoleRootの切り替わり時だけ)なので、うまく行けばRDP接続を継続したまま起動時の処理を追うことができると思います。UpgradeなのでちゃんとStartupTasksも処理されますしね。
あとはWindows Azureデプロイ失敗時にSysinternalのDebugViewで調査等を参考にデバッグください。
え、ログファイルを追いたい?Tailすればいいんじゃないですかね。
あとUpgrade時にRDPが切断されて結局つながらないってケースもあるのでその場合は諦めましょう。一度ログオンした状態になってるし厳密には初期起動時と同じじゃないので万能じゃないですけどね(
おまけ
エントリポイント内のログとか見る場合、AzureらしくDiagnostics設定してもいいんですが転送されなかったり、そこが失敗してると意味ないですね。。
直接Azure Storageに出力してもいいんですが System.Diagnostics.DefaultTraceListener 使ってOutputDebugString APIで出力するようにしておけば上述の方法でDBMon.exeやDebugViewerで拾えますね。
まぁ適材適所ということで…
ちなみにDebugViewで取れたUpgrade時の情報のサンプルです。(※StartupTasksを仕込み忘れたのであまり深い意味はない)
00000536 249.87687683 [1044] [00000009] [05/28/2011 14:52:56.82] Goal state 2 received. 00000537 249.87701416 [1044] [00000009] [05/28/2011 14:52:56.82] Goal state being updated. 00000538 249.92436218 [1044] [00000009] [05/28/2011 14:52:56.87] Deleting all user accounts. 00000539 249.92620850 [1044] [00000009] [05/28/2011 14:52:56.87] Role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0 is being updated. 00000540 249.92637634 [1044] [00000009] [05/28/2011 14:52:56.87] Role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0 has goal state Started. 00000541 250.03047180 [1044] [00000003] [05/28/2011 14:52:56.96] Goal state execution started for role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0. 00000542 250.03065491 [1044] [00000003] [05/28/2011 14:52:56.96] Driving role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0 to goal state Started from current state Started. 00000543 250.03482056 [1044] [00000003] [05/28/2011 14:52:56.97] New source package detected for role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0. Role will be restarted. 00000544 250.03492737 [1044] [00000003] [05/28/2011 14:52:56.97] Role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0 could not be updated. It will be restarted. 00000545 250.03778076 [1044] [00000003] [05/28/2011 14:52:56.97] Using default role stop timeout of 300000 milliseconds. 00000546 250.40103149 [2740] Microsoft.WindowsAzure.ServiceRuntime Information: 205 : 00000547 250.40112305 [2740] Role entrypoint . CALLING OnStop() 00000548 250.40139771 [2740] Microsoft.WindowsAzure.ServiceRuntime Information: 206 : 00000549 250.40147400 [2740] Role entrypoint . COMPLETED OnStop() 00000550 252.01646423 [1044] [00000003] [05/28/2011 14:52:58.96] Sending new config file: 9bb8199d1d2f40e59c19fe84767fd9db.9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0.2.xml. 00000551 252.05427551 [1044] Invalid parameter passed to C runtime function. 00000552 252.05436707 [1044] Invalid parameter passed to C runtime function. 00000553 253.57112122 [1044] Invalid parameter passed to C runtime function. 00000554 253.57127380 [1044] Invalid parameter passed to C runtime function. 00000555 254.92184448 [1044] [00000009] [05/28/2011 14:53:01.86] WaAppAgent Heartbeat. 00000556 259.29455566 [1044] [00000009] [05/28/2011 14:53:06.22] Role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0 is reporting state NotReady with sub-status Starting and details Initializing role.... 00000557 259.37777710 [2096] Invalid parameter passed to C runtime function. 00000558 259.37780762 [2096] Invalid parameter passed to C runtime function. 00000559 260.99954224 [2940] Invalid parameter passed to C runtime function. 00000560 260.99960327 [2940] Invalid parameter passed to C runtime function. 00000561 261.00262451 [1928] Invalid parameter passed to C runtime function. 00000562 261.00265503 [1928] Invalid parameter passed to C runtime function. 00000563 271.35952759 [2180] Invalid parameter passed to C runtime function. 00000564 271.36846924 [2180] Invalid parameter passed to C runtime function. 00000565 271.37487793 [1044] [00000003] [05/28/2011 14:53:11.32] Role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0 has current state Busy, desired state Started, and goal state execution status StartInProgress. 00000566 271.37899780 [2256] Invalid parameter passed to C runtime function. 00000567 271.37930298 [2256] Invalid parameter passed to C runtime function. 00000568 271.38226318 [1044] [00000009] [05/28/2011 14:53:12.08] WaAppAgent Heartbeat. 00000569 271.38275146 [1044] [00000009] [05/28/2011 14:53:18.30] Role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0 is reporting state NotReady with sub-status Starting and details Waiting for role to start.... 00000570 272.89532471 [1852] Invalid parameter passed to C runtime function. 00000571 272.89538574 [1852] Invalid parameter passed to C runtime function. 00000572 273.45935059 [2640] Invalid parameter passed to C runtime function. 00000573 273.45938110 [2640] Invalid parameter passed to C runtime function. 00000574 273.63766479 [2344] 00000575 273.63766479 [2344] *** HR originated: -2147024774 00000576 273.63766479 [2344] *** Source File: d:\iso_whid\amd64fre\base\isolation\com\copyout.cpp, line 1302 00000577 273.63766479 [2344] ~中略~ 00001015 274.04110718 [2344] *** HR propagated: -2147024774 00001016 274.04110718 [2344] *** Source File: d:\iso_whid\amd64fre\base\isolation\com\enumidentityattribute.cpp, line 144 00001017 274.04110718 [2344] 00001018 275.54354858 [2344] Invalid parameter passed to C runtime function. 00001019 275.54360962 [2344] Invalid parameter passed to C runtime function. 00001020 275.84848022 [2344] Microsoft.WindowsAzure.ServiceRuntime Information: 200 : 00001021 275.85186768 [2344] Role entrypoint . CALLING OnStart() 00001022 275.85708618 [2344] Microsoft.WindowsAzure.ServiceRuntime Information: 202 : 00001023 275.85714722 [2344] Role entrypoint . COMPLETED OnStart() 00001024 275.86169434 [2344] Microsoft.WindowsAzure.ServiceRuntime Information: 203 : 00001025 275.86172485 [2344] Role entrypoint . CALLING Run() 00001026 276.37518311 [1044] [00000003] [05/28/2011 14:53:23.30] Role 9bb8199d1d2f40e59c19fe84767fd9db.Mvc3ApplicationSample_IN_0 has current state Starting, desired state Started, and goal state execution status StartInProgress. 00001027 276.70333862 [1044] [00000009] [05/28/2011 14:53:23.63] WaAppAgent Heartbeat.