いつの間にか Azure VPN Gateway の診断ログが取れるようになってました。
これがあればユーザー側でのデバッグが大分やりやすくなるので、周知の意味も込めてメモ程度に残しておきます。
診断ログの設定方法
まず、診断ログは [診断設定] のブレードから、個別に有効化します。
![](https://blob.syuheiuda.com/wp-content/2019/01/VPN_Diag1-1024x956.png)
適当な名前とストレージ等の出力先を指定し、有効化したいログの種類にチェックします。VPN 接続時のネゴシエーション周りは IKEDiagnosticLogs だけで十分なはず。(他のログについても順次確認中)
![](https://blob.syuheiuda.com/wp-content/2019/01/VPN_Diag2.png)
しばらく待つと指定したストレージに insights-logs-ikediagnosticlog という名前でコンテナが作成され、その中を掘っていくと毎時 PT1H.json というファイルが吐き出されていることが確認できます。
![](https://blob.syuheiuda.com/wp-content/2019/01/VPN_Diag3-1024x560.png)
ログ解析のポイント
PT1H.json を開いてみると、ログは JSON Lines (各行が JSON 形式) のフォーマットで出力されていることがわかります。適当に JSON が見やすいエディタを使いましょう。
![](https://blob.syuheiuda.com/wp-content/2019/01/VPN_Diag4-1024x560.png)
ここからは Azure 固有の話ではなく IPsec VPN のネゴシエーション周りの一般的なお話ですが、接続を確立しようとする際は、SA INIT の通信が行われます。
(SA: Security Association, INIT : Initialize のことです)
Azure とオンプレ側の VPN デバイスのどちらから接続を始めても問題ありませんが、先に接続要求を送ったほうを Initiator、接続要求を受け取ったほうを Responder と呼びます。で、SA INIT のフェーズでは Initiator 側が initiator cookie (iCookie) だけセットした状態で、responder cookie (rCookie) が空 (0x0) のパケットを送付してネゴシエーションを始めます。(受け取った Responder 側が rCookie をセットして返します)
なので、ログの中で “iCookie : 0x0” とか “rCookie : 0x0” の行を探しましょう。(闇雲にログを見るのではなく、SA INIT を始めた行から見ていくことをオススメします。)
以下の例では、Azure 側としては [RECV Network Packet] ということで、パケットを受け取ったと書かれているので、オンプレミス側 (FortiGate) が Initiator で、Azure VPN Gateway は Responder 担っていることがわかります。(図では、549-552 行目が受け取った SA INIT のデバッグ ログで、それに対しての応答が 553-555 行目になっています。)
あ、毎度のことながら IP アドレスは FortiGate 側を ff.ff.ff.ff、Azure 側を aa.aa.aa.aa でマスクしてますのでご容赦を。
![](https://blob.syuheiuda.com/wp-content/2019/01/VPN_Diag5-1024x560.png)
この例では、iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd となっていますが、同じタイミングの VPN デバイスのログをみても同一の Cookie でログが見つかるはずです。(以下はあくまでも FortiGate のデバッグ ログの例なので、機種によって出力されるログは異なります。FortiGate の場合は 16 進数を意味する 0x なしでログが出るみたいなので、 1df26d566a7f45fa とかで検索しています。)
![](https://blob.syuheiuda.com/wp-content/2019/01/VPN_Diag6-1024x98.png)
ということで、あとは何の処理で失敗しているのかをゴリゴリ見ていきましょう。(確認ポイントは状況によって違うのと、そもそも VPN の接続時のフローとかを把握していないとダメなので、 細かい話は Cisco のドキュメントとか見て頑張ってください。 )
正常時のログサンプル (抜粋)
{ "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4236930Z", "level": "Informational", "properties": {"message":"[RECV Network Packet] Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Packet : IKEVersion : IKEv2 ; iCookie : 0x1df26d566a7f45fa ; rCookie : 0x0 ; Exchange type : IKEv2 SA Init Mode ; Length : 396 ; NextPayload : SA ; Flags : 0x8(INITIATOR,REQUEST) ; Messid : 0x00000000","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4236930Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Received SA INIT","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4236930Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Received Ike payload: Policy1:AES-CBC-256 SHA1 SHA1 DhGroup2 Policy2:3DES SHA1 SHA1 DhGroup2 Policy3:AES-CBC-256 SHA256 SHA256 DhGroup2 ","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4236930Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Receiving MM Packet for tunnel Id 0x0 iCookie 0x1DF26D566A7F45FA and rCookie 0x29D6549E71D8FADD: Receiving MM Nonce","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4236930Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Sending IKE SA_INIT response packet with tunnelId 0x0, iCookie 0x1DF26D566A7F45FA and rCookie 0x29D6549E71D8FADD","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4236930Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Sending Ike payload for tunnel Id 0x0: Auth:PreShared Key- Responder Policy:AES-CBC-256 SHA1 DhGroup2 ","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4236930Z", "level": "Informational", "properties": {"message":"[SEND Network Packet] Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Packet : IKEVersion : IKEv2 ; iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd ; Exchange type : IKEv2 SA Init Mode ; Length : 364 ; NextPayload : SA ; Flags : 0x20(RESPONDER,RESPONSE) ; Messid : 0x00000000","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"[RECV Network Packet] Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Packet : IKEVersion : IKEv2 ; iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd ; Exchange type : IKEv2 Auth Mode ; Length : 284 ; NextPayload : ENCR ; Flags : 0x8(INITIATOR,REQUEST) ; Messid : 0x00000001","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Received IKE AUTH message","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Received Traffic Selector payload - Number of TSIs 1: StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0 Number of TSRs 1:StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Proposed Traffic Selector payload will be - Number of TSIs 1: StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0 Number of TSRs 1:StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Received IPSec payload: Policy1:AES-CBC-256 SHA1 Policy2:3DES SHA1 Policy3:AES-CBC-256 SHA256 ","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Sending SA AUTH response message for tunnelId 0x5 and tsId 0x13","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Sending IPSec policy Payload for tunnel Id 0x5, tsId 0x13: Policy1:AES-CBC-256 SHA1 ","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: IKE Tunnel created for tunnelId 0x5","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"[SEND Network Packet] Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Packet : IKEVersion : IKEv2 ; iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd ; Exchange type : IKEv2 Auth Mode ; Length : 204 ; NextPayload : ENCR ; Flags : 0x20(RESPONDER,RESPONSE) ; Messid : 0x00000001","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: IKE Tunnel closed for tunnelId 0x3 with status Deleted via RPC call","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:06.4440063Z", "level": "Informational", "properties": {"message":"Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Sending IPSEC SA delete for tunnelId 0x3 and tsId 0x12","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:08.4569360Z", "level": "Informational", "properties": {"message":"[SEND Network Packet] Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Packet : IKEVersion : IKEv2 ; iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd ; Exchange type : IKEv2 Informational Mode ; Length : 76 ; NextPayload : ENCR ; Flags : 0x0(RESPONDER,REQUEST) ; Messid : 0x00000000","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:08.4575869Z", "level": "Informational", "properties": {"message":"[RECV Network Packet] Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Packet : IKEVersion : IKEv2 ; iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd ; Exchange type : IKEv2 Informational Mode ; Length : 76 ; NextPayload : ENCR ; Flags : 0x28(INITIATOR,RESPONSE) ; Messid : 0x00000000","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:10.4754992Z", "level": "Informational", "properties": {"message":"[SEND Network Packet] Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Packet : IKEVersion : IKEv2 ; iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd ; Exchange type : IKEv2 Informational Mode ; Length : 76 ; NextPayload : ENCR ; Flags : 0x0(RESPONDER,REQUEST) ; Messid : 0x00000001","instance":"GatewayTenantWorker_IN_0"}} { "resourceid": "/SUBSCRIPTIONS/49DDE45F-5712-44B2-B0AB-296BDE83AF6B/RESOURCEGROUPS/CALEDFWLCH/PROVIDERS/MICROSOFT.NETWORK/VIRTUALNETWORKGATEWAYS/CALEDFWLCH-VPNGW-JW", "category": "IKEDiagnosticLog", "operationName": "IKELogEvent", "time": "2019-01-28T15:19:10.4754992Z", "level": "Informational", "properties": {"message":"[RECV Network Packet] Remote ff.ff.ff.ff:500: Local aa.aa.aa.aa:500: Packet : IKEVersion : IKEv2 ; iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd ; Exchange type : IKEv2 Informational Mode ; Length : 76 ; NextPayload : ENCR ; Flags : 0x28(INITIATOR,RESPONSE) ; Messid : 0x00000001","instance":"GatewayTenantWorker_IN_0"}}
気が向いたら何パターンかありがちな設定ミス時のログの例でも追記します。
VPN 切断時のチェックポイント
VPN の切断・再接続時のログは、insights-logs-tunneldiagnosticlog コンテナー内に同じく PT1H.json ファイルとして出力されています。中を見ると、status が Disconnected (切断された) もしくは Connected (接続された) ということと、 stateChangeReason として理由が明記されているので、ざっくりとした切断理由が分かります。
以下の例だと DPD timed out で Disconnected になっているので、Azure VPN Gateway からの DPD (Dead Peer Detection) の通信にオンプレミス側の FortiGate が応答を返さなかったので切断されたことが分かります。(これは、当然 FortiGate 自身が無応答だった可能性もありますが、Internet の経路上で問題があった可能性もゼロではありません) オンプレミス側のデバッグログ等とも見比べて、どこで何が起きていたかを調査しましょう。
また、Connected に変わった際は RemotelyTriggered で発生したと書かれています。したがって、FortiGate 側が Initiator となって接続要求を送ってきたので、Azure VPN Gateway としてはそれを受け入れて接続が完了したという事になります。(メンテナンス等で Azure 側から切断、再接続をした際は LocalTriggered とかになるはずです)
![](https://blob.syuheiuda.com/wp-content/2019/01/VPN_Diag7-1024x543.png)
ルーティング観点のチェックポイント
VPN で BGP を使っている場合など、トンネルは張れているのにルーティングの問題で通信出来ない場合もあります。そうした際は insights-logs-routediagnosticlog 内の PT1H.json ファイルでルーティング情報を確認しましょう。以下の例では、 VPN の切断・再接続に伴って発生した、経路の消失、BGP の Peer Down、BGP の Peer Up、経路の学習が確認できます。また、一部マスクをしていますが、学習した経路も確認できるので、オンプレミス側から BGP で正しく経路を出せていない場合なども一目で分かるはずです。
![](https://blob.syuheiuda.com/wp-content/2019/01/VPN_Diag8-1024x543.png)
その他
Azure との VPN できない場合の VPN デバイス側のトラシューは以下なども併せてどうぞ。
あと、Jazug Night で登壇した際に更に詳しい話をしたので、以下のスライド P.64 – 73 や YouTube の録画 (1:03:36 – 1:18:50) もご確認ください。
1 comment for “Azure との VPN 接続がうまくいかない場合のデバッグ方法”