いつの間にか Azure VPN Gateway の診断ログが取れるようになってました。
診断ログの設定方法
まず、診断ログは [診断設定] のブレードから、個別に有効化します。
適当な名前とストレージ等の出力先を指定し、有効化したいログの種類にチェックします。VPN 接続時のネゴシエーション周りは IKEDiagnosticLogs だけで十分なはず。(他のログについても順次確認中)
しばらく待つと指定したストレージに insights-logs-ikediagnosticlog という名前でコンテナが作成され、その中を掘っていくと毎時 PT1H.json というファイルが吐き出されていることが確認できます。
ログ解析のポイント
PT1H.json を開いてみると、ログは JSON Lines (各行が JSON 形式) のフォーマットで出力されていることがわかります。適当に JSON が見やすいエディタを使いましょう。
ここからは Azure 固有の話ではなく IPsec VPN のネゴシエーション周りの一般的なお話ですが、接続を確立しようとする際は、SA INIT の通信が行われます。
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 でマスクしてますのでご容赦を。
この例では、iCookie : 0x1df26d566a7f45fa ; rCookie : 0x29d6549e71d8fadd となっていますが、同じタイミングの VPN デバイスのログをみても同一の Cookie でログが見つかるはずです。(以下はあくまでも FortiGate のデバッグ ログの例なので、機種によって出力されるログは異なります。FortiGate の場合は 16 進数を意味する 0x なしでログが出るみたいなので、 1df26d566a7f45fa とかで検索しています。)
ということで、あとは何の処理で失敗しているのかをゴリゴリ見ていきましょう。(確認ポイントは状況によって違うのと、そもそも 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 とかになるはずです)
ルーティング観点のチェックポイント
VPN で BGP を使っている場合など、トンネルは張れているのにルーティングの問題で通信出来ない場合もあります。そうした際は insights-logs-routediagnosticlog 内の PT1H.json ファイルでルーティング情報を確認しましょう。以下の例では、 VPN の切断・再接続に伴って発生した、経路の消失、BGP の Peer Down、BGP の Peer Up、経路の学習が確認できます。また、一部マスクをしていますが、学習した経路も確認できるので、オンプレミス側から BGP で正しく経路を出せていない場合なども一目で分かるはずです。
その他
Azure との VPN できない場合の VPN デバイス側のトラシューは以下なども併せてどうぞ。
あと、Jazug Night で登壇した際に更に詳しい話をしたので、以下のスライド P.64 – 73 や YouTube の録画 (1:03:36 – 1:18:50) もご確認ください。
VIDEO
