SE の雑記

SQL Server の情報をメインに Microsoft 製品の勉強内容を日々投稿

複数 NIC を使用した仮想マシンで「実行中(プロビジョニング)」の状態が続いたので調査した際のメモ

one comment

複数 NIC を使用した仮想マシンの状態が「実行中 (プロビジョニング)」の状態のまま、デプロイが完了しない現象について、調査する必要があったので調べてみたメモを。
2015/2/10 時点の内容ですのでどこかのタイミングで解消しているかもしれません。

image

以下のような仮想ネットワークを構築しています。
image

  • 「Subnet-1」は「172.0.0.0/26」
  • 「Subnet-2」は「172.0.0.64/26」

を使用しています。

この状態で、

  • MultiNICVM は「Subnet-2」を「Set-AzureSubnet」に指定、「Subnet-1」を「Add-AzureNetworkInterfaceConfig」に指定
  • MultiNICVM2は「Subnet-1」を「Add-AzureNetworkInterfaceConfig」に指定、「Subnet-2」を「Set-AzureSubnet」に指定

して仮想マシンを作成します。

以下はポータルから確認した内容となります。

image

この設定で作成した仮想マシンですが、「MultiNICVM2」 はプロビジョニングが完了するのですが、「MultiNICVM」はプロビジョニングが完了しないという現象が発生しました。

プロビジョニングが完了しない「MultiNICVM」は数時間放っておくと「プロビジョニングのタイムアウト」となります。
image

この現象の原因を調査したというのが今回のお話です。

原因ですが、仮想マシンにリモートデスクトップで接続をして、「C:WindowsAzureLogsWaAppAgent.log」から確認することができました。
今回の仮想マシンは VM エージェントをインストールする設定にしているのですが、エージェントのログが上記のファイルになるのかなと思います。
プロビジョニングが完了しない仮想マシンでは、以下のようなログが出力されていました。

[00000006] [02/10/2015 04:32:21.83] [INFO]  Initializing ControlSystem.
[00000006] [02/10/2015 04:32:21.89] [INFO]  Attempting to discover fabric address on interface Ethernet 2.
[00000006] [02/10/2015 04:32:21.91] [INFO]  Discovered fabric address on interface Ethernet 2.
[00000006] [02/10/2015 04:32:21.91] [INFO]  Using fabric address 168.63.129.16 from DHCP.
[00000006] [02/10/2015 04:32:21.91] [INFO]  Using fabric URI http://168.63.129.16/.
[00000006] [02/10/2015 04:32:45.80] [ERROR] GetVersions() failed with exception: System.ServiceModel.EndpointNotFoundException: There was no endpoint listening at http://168.63.129.16/?comp=versions that could accept the message. This is often caused by an incorrect address or SOAP action. See InnerException, if present, for more details. ---> System.Net.WebException: Unable to connect to the remote server ---> System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 168.63.129.16:80
   at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress)
   at System.Net.ServicePoint.ConnectSocketInternal(Boolean connectFailure, Socket s4, Socket s6, Socket& socket, IPAddress& address, ConnectSocketState state, IAsyncResult asyncResult, Exception& exception)
   --- End of inner exception stack trace ---
   at System.Net.HttpWebRequest.GetResponse()
   at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)
   --- End of inner exception stack trace ---
Server stack trace:
   at System.ServiceModel.Channels.HttpChannelUtilities.ProcessGetResponseWebException(WebException webException, HttpWebRequest request, HttpAbortReason abortReason)
   at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)
   at System.ServiceModel.Channels.RequestChannel.Request(Message message, TimeSpan timeout)
   at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
   at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
   at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)
Exception rethrown at [0]:
   at Microsoft.ServiceModel.Web.WebHttpChannelProxy`1.Invoke(IMessage msg)
   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
   at Microsoft.WindowsAzure.RoleContainer.Protocol.IControlSystem.GetVersions()
   at Microsoft.WindowsAzure.RoleContainer.Protocol.ControlSystem.SelectProtocolVersion().
[00000006] [02/10/2015 04:32:45.85] [ERROR] There was no match for protocol version. ControlSystem not initialized.

 

こちらが正常にプロブジョニングが実行できた仮想マシンのログです。

[00000006] [02/10/2015 04:28:36.86] [INFO]  Initializing ControlSystem.
[00000006] [02/10/2015 04:28:36.94] [INFO]  Attempting to discover fabric address on interface Ethernet 2.
[00000006] [02/10/2015 04:28:36.94] [INFO]  Discovered fabric address on interface Ethernet 2.
[00000006] [02/10/2015 04:28:36.94] [INFO]  Using fabric address 168.63.129.16 from DHCP.
[00000006] [02/10/2015 04:28:36.95] [INFO]  Using fabric URI http://168.63.129.16/.
[00000006] [02/10/2015 04:28:39.09] [INFO]  ControlSystem initialized with version 2012-11-30.
[00000006] [02/10/2015 04:28:39.31] [INFO]  Initializing StateExecutorForIaaS.
[00000006] [02/10/2015 04:28:39.32] [INFO]  StateExecutorForIaaS initialization completed.
[00000005] [02/10/2015 04:28:39.32] [HEART] WindowsAzureGuestAgent Heartbeat.
[00000005] [02/10/2015 04:28:39.40] [INFO]  Driving to new goal state (V:2012-11-30 I:1 M:(ES:Started) C:(ID:50d27247-0ad4-4de6-a3ce-7237e071c060 R:[(ID:c2f0f9f4d1024eaf9b7215c1cc19d717.MultiNICVM2 S:Started),])). Retrying plugin install due to previous failure: False
[00000005] [02/10/2015 04:28:40.14] [INFO]  Extension Plugins Found.
[00000005] [02/10/2015 04:28:40.23] [INFO]  Extension GuestAgentExtension Found.
[00000005] [02/10/2015 04:28:40.28] [INFO]  Extension StatusUploadBlob Found
[00000005] [02/10/2015 04:28:40.28] [INFO]  Extension StatusUploadBlob value is https://ozawavmstoragejapanwest.blob.core.windows.net/vhds/OzawaMultiNICTest2.OzawaMultiNICTest2.MultiNICVM2.status?sr=b&sp=rw&se=9999-01-01&sk=key1&sv=2014-02-14&sig=RjeTBxkcJLF8a6H7PmMjay1aRtAFYutCMqmTDHAgf5c%3D.
[00000005] [02/10/2015 04:28:55.70] [INFO]  StatusUploadBlobUrl is pointed to the following Blob type: BlockBlob.
[00000005] [02/10/2015 04:28:55.70] [INFO]  C:WindowsAzureConfig is created.
[00000005] [02/10/2015 04:28:56.38] [INFO]  Successfully retrieved transport certificate.
[00000005] [02/10/2015 04:28:56.97] [INFO]  Successfully imported cert Cert0My into the store My
[00000005] [02/10/2015 04:28:56.98] [INFO]  Starting installation of plugins. Incarnation: 1 Plugin size: 1
[00000005] [02/10/2015 04:28:57.01] [INFO]  Downloading version manifest for plugin Microsoft.Compute.BGInfo from http://rdfepirv2os1prdstr01.blob.core.windows.net/bfd5c281a7dc4e4b84381eb0b47e3aaf/Microsoft.Compute_BGInfo_japanwest_manifest.xml.
[00000005] [02/10/2015 04:28:57.08] [INFO]  Getting plugin locations for plugin 'Microsoft.Compute.BGInfo'. Current Version: '1.1', Requested Version: '1.1'
[00000005] [02/10/2015 04:28:57.08] [INFO]  Auto-Upgrade mode. Highest public version for plugin 'Microsoft.Compute.BGInfo' with requested version: '1.1', is: '1.1'
[00000005] [02/10/2015 04:28:57.08] [INFO]  Updating plugin 'Microsoft.Compute.BGInfo' to version '1.1'
[00000005] [02/10/2015 04:28:57.09] [INFO]  No plugin settings received. Setting nothing for plugin: Microsoft.Compute.BGInfo version: 1.1
[00000005] [02/10/2015 04:28:57.12] [INFO]  C:WindowsAzureLogsAggregateStatus is created.
[00000006] [02/10/2015 04:28:57.19] [INFO]  Processing plugin Microsoft.Compute.BGInfo version 1.1, state: enabled, autoupgrade: True, isJson: False
[00000006] [02/10/2015 04:28:57.19] [INFO]  Plugin Microsoft.Compute.BGInfo 1.1 not found in cache.
[00000006] [02/10/2015 04:28:57.22] [INFO]  Starting download of plugin Microsoft.Compute.BGInfo from location: http://rdfepirv2os1prdstr01.blob.core.windows.net/bfd5c281a7dc4e4b84381eb0b47e3aaf/Microsoft.Compute__BGInfo__1.1.
[00000006] [02/10/2015 04:28:57.24] [INFO]  Download finished for plugin Microsoft.Compute.BGInfo.
[00000006] [02/10/2015 04:28:57.24] [INFO]  Extracting plug-in zip file to folder. Zip file: C:PackagesPluginsMicrosoft.Compute.BGInfo1.1Microsoft.Compute.BGInfo_1.1.zip
[00000006] [02/10/2015 04:28:57.28] [INFO]  Xml manifest file C:PackagesPluginsMicrosoft.Compute.BGInfo1.1PluginManifest.xml found corresponding to the plugin Microsoft.Compute.BGInfo
[00000006] [02/10/2015 04:28:57.39] [INFO]  Successfully created folder C:PackagesPluginsMicrosoft.Compute.BGInfo1.1RuntimeSettings
[00000006] [02/10/2015 04:28:57.39] [INFO]  Successfully created folder C:PackagesPluginsMicrosoft.Compute.BGInfo1.1Status
[00000006] [02/10/2015 04:28:57.39] [INFO]  Successfully created folder C:WindowsAzureLogsPluginsMicrosoft.Compute.BGInfo1.1
[00000006] [02/10/2015 04:28:57.42] [INFO]  Install command of plugin Microsoft.Compute.BGInfo: C:PackagesPluginsMicrosoft.Compute.BGInfo1.1BGInfoLauncher.exe
[00000006] [02/10/2015 04:28:57.42] [INFO]  Beginning installation of plugin Microsoft.Compute.BGInfo 1.1.
[00000006] [02/10/2015 04:28:57.47] [INFO]  Waiting for command of plugin Microsoft.Compute.BGInfo to finish...
[00000006] [02/10/2015 04:29:00.54] [INFO]  Successfully installed plugin Microsoft.Compute.BGInfo 1.1.
[00000006] [02/10/2015 04:29:00.54] [INFO]  Plugin enabled (name: Microsoft.Compute.BGInfo, version: 1.1)., Code: 0
[00000008] [02/10/2015 04:43:48.22] [HEART] WindowsAzureGuestAgent Heartbeat.

「http://168.63.129.16/?comp=versions」 にアクセスができなくて、エージェントの処理が完了できていないようですね。

プロビジョニングが完了した環境の IE では上記の URL にアクセスができるのですが、プロビジョニングが完了しない仮想マシンではアクセスができませんでした。

image

上記の IP に対して pathping を実行してみます。

上がプロビジョニングが完了していないもの (MultiNICVM)、下がプロビジョニングが完了しているもの (MultiNICVM2)  になります。

image

image

両方とも「Subnet-1」の IP からアクセスに行っていますね。

次に両環境のルーティングテーブルを確認してみます。

上が「MultiNICVM」、下が「MultiNICVM2」となります。

両方とも等価のルーティングテーブルですね。

image

image

違いは、NICに追加したサブネットの順序ですね。

  • MultiNICVM : Subnet-2 を設定して、Subnet-1 の NIC を追加
  • MultiNICVM2 : Subnet-1 を設定して、Subnet-2 の NIC を追加


それでは、プロビジョニングが終わらない仮想マシンで、以下のような静的経路を追加してみます。

route add 168.63.129.16 MASK 255.255.255.255 172.0.0.65 IF 12

静的経路を追加してから、「WaAppAgent.log」を確認すると、URL にアクセスすることができ、後続の処理が実行されていることが確認できます。

エージェントの処理で問題が発生していたのかなと思い、「-DisableGuestAgent」で仮想マシンを作成しても、現象変わらずでしたので、根幹の問題はここではなかったようです。。。

使用するネットワークの問題のような感じなのでルーティングを整えればよさそうだとは思うのですが、この辺の修正方法が分からないのですよね。。。

 

  • 1 枚目の NIC : 172.0.1.0/24
  • 2 枚目の NIC : 172.0.0.0/24

では現象が発生し、

  • 1 枚目の NIC : 172.0.0.0/24
  • 2 枚目の NIC : 10.0.0.0/24

の場合は現象が発生しなかったりと。

Share

Written by Masayuki.Ozawa

2月 10th, 2015 at 2:51 pm

Posted in Microsoft Azure,Windows Azure

Tagged with ,

«
»

One Response to '複数 NIC を使用した仮想マシンで「実行中(プロビジョニング)」の状態が続いたので調査した際のメモ'

Subscribe to comments with RSS or TrackBack to '複数 NIC を使用した仮想マシンで「実行中(プロビジョニング)」の状態が続いたので調査した際のメモ'.

  1. 「168.63.129.16」はDNSでもあるようです(ADのDNSフォワーダーに追加されてました)。
    この現象が起きると、このサーバーはインターネットに接続できなかったり、Windows Updateにつながらなかったり、おかげで.NET Framework 3.5 がインストールできなかったりと大変です。
    結果、SQL Server入りませんし、ASP .NET 3.5も使えません。 こまったものです。
    うちの環境ではシングルNICでもこの168.63.129.16との疎通がいまいちうまくいかず、日本語化言語パックのダウンロードに何度も失敗したりしていました。ipfonfig /flushdns とsleep、再試行を何度かやるとうまくいくようですが。
    仮想ネットワークの最初のネットワークにDNSが属していないといけないとかあるんでしょうか。

    yaki

    12 2月 15 at 21:39

Leave a Reply