60.3. Protokollierung bei strongSwan Version 6

60.3.1. Das Protokollformat des Intra2net Systems

Ein Beispiel für eine Zeile aus einer System-Logdatei:

May 13 11:50:03 intra charon: 12[IKE1] <C1|3> authentication of 
        'CN=intra.net.lan' with RSA_EMSA_PKCS1_NULL successful
      

May 13 11:50:03

Datum und Uhrzeit des Ereignisses

intra

Rechnername des Intra2net Systems

charon:

Kennung des IPSec-Dienstes (strongSwan Version 6)

12[IKE1]

Thread-ID, Modulname und Loglevel der Meldung

<C1|3>

Verbindungskennung (mit Präfix "C") und interne ID der IKE-SA.

Wurde noch keine Verbindungskennung eindeutig zugeordnet, wird nur die ID der IKE-SA ausgegeben. Die Verbindungskennungen können über das Menü "Information > System > VPN" den Verbindungsnamen zugeordnet werden.

authentication...

Nachricht

60.3.2. Fehler in Phase 1

Fehler in Phase 1 bedeuten meistens eine falsche Konfiguration der Authentifizierung (z.B. falsche Zertifikate konfiguriert oder eine andere IPSec-ID verwendet) oder auch falsch konfigurierte Verschlüsselungsalgorithmen.

Am Anfang jeder Verbindung tauschen die Gegenstellen typischerweise Informationen über ihre Fähigkeiten aus und erkennen, ob die Verbindung durch NAT läuft:

received packet: from 192.168.1.200[500] to 192.168.1.254[500] (416 bytes)
parsed ID_PROT request 0 [ SA V V V V V ]
received XAuth vendor ID
received DPD vendor ID
received FRAGMENTATION vendor ID
received NAT-T (RFC 3947) vendor ID

Danach sieht man die eigentliche Funktion des Pakets:

192.168.1.200 is initiating a Main Mode IKE_SA

Jetzt findet die Auswahl eines passenden Verschlüsselungsprofils statt. Im Erfolgsfall sieht dies z.B. so aus:

selected proposal: IKE:AES_CBC_192/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_1536

Sollte das von der Gegenseite angefragte und das lokal konfigurierte Verschlüsselungsprofil nicht zusammenpassen, wird dies detailliert protokolliert:

received proposals: IKE:CAMELLIA_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
configured proposals: IKE:AES_CBC_192/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256...
no proposal found
generating INFORMATIONAL_V1 request 3626487893 [ N(NO_PROP) ]

Das Kürzel "N(NO_PROP)" steht dabei für die Nachricht NO_PROPOSAL_CHOSEN.

Danach fordert das Intra2net System die Gegenseite auf ihr Zertifikat zu senden:

sending cert request for "CN=vpntest.net.lan"

Die Gegenstelle antwortet mit ihrem Zertifikat und fordert das Zertifikat des Intra2net Systems an:

parsed ID_PROT request 0 [ ID CERT SIG CERTREQ N(INITIAL_CONTACT) ]
received cert request for 'CN=intra.net.lan'
received end entity cert "CN=vpntest.net.lan"

Jetzt kann die Verbindung eindeutig einem konfigurierten VPN zugeordnet werden:

looking for RSA signature peer configs matching 192.168.1.254...
   192.168.1.200[CN=vpntest.net.lan(ID_DER_ASN1_DN)]
selected peer config "C1"

Es liegen jetzt alle nötigen Informationen vor, um Phase 1 erfolgreich abschließen zu können:

  using trusted certificate "CN=vpntest.net.lan"
authentication of 'CN=vpntest.net.lan' with RSA_EMSA_PKCS1_NULL successful
authentication of 'CN=intra.net.lan' (myself) successful
IKE_SA C1[1] established between 192.168.1.254[CN=intra.net.lan]...
   192.168.1.200[CN=vpntest.net.lan]

Ist auf der Gegenseite dagegen das falsche eigene Zertifikat konfiguriert, kann die Verbindung nicht zugeordnet werden:

received cert request for 'CN=intra.net.lan'
received end entity cert "CN=wrongcert.net.lan"
looking for RSA signature peer configs matching 192.168.1.254...
   192.168.1.200[CN=wrongcert.net.lan(ID_DER_ASN1_DN)]
no peer config found
generating INFORMATIONAL_V1 request 2748090117 [ HASH N(AUTH_FAILED) ]

Hat die Gegenseite zwar das richtige eigene Zertifikat, erwartet aber vom Intra2net System ein anderes, kommt die Verbindung auf der Seite des Intra2net Systems zuerst zustande. Die Gegenseite beendet dann allerdings direkt danach die Verbindung:

parsed INFORMATIONAL_V1 request 1539580505 [ HASH D ]
received DELETE for IKE_SA C1[1]
deleting IKE_SA C1[1] between 192.168.1.254[CN=intra.net.lan]...
  192.168.1.200[CN=vpntest.net.lan]

Ist die Gegenstelle gar nicht erreichbar oder verwirft alle Verbindungsanfragen ohne Antwort, ist im Log folgendes Muster zu sehen:

vici initiate CHILD_SA 'C1'
initiating Main Mode IKE_SA C1[2] to 192.168.1.200
generating ID_PROT request 0 [ SA V V V V V ]
sending packet: from 192.168.1.254[500] to 192.168.1.200[500] (416 bytes)
sending retransmit 1 of request message ID 0, seq 1
sending retransmit 2 of request message ID 0, seq 1
giving up after 2 retransmits
peer not responding, trying again (2/3)
peer not responding, trying again (3/3)
establishing IKE_SA failed, peer not responding

Der Verbindungsaufbau wird auf den verschiedenen Ebenen mehrfach wiederholt und nach etwa 40 Sekunden aufgegeben. Ist die Verbindung so konfiguriert, dass sie immer aufgebaut werden soll, beginnt kurz danach ein neuer Aufbauversuch von vorn.

60.3.3. Fehler in Phase 2

In Phase 2 werden die Daten für die IP-Tunnel ausgehandelt. Tritt hier ein Fehler auf, so sind meistens falsche IP-Adressen für den Tunnel hinterlegt. Allerdings kann es auch hier nicht passende Verschlüsselungsalgorithmen geben.

Ein erfolgreiches Abschließen von Phase 2 sieht z.B. so aus:

parsed QUICK_MODE request 3970744905 [ HASH ]
CHILD_SA C1{12} established with SPIs cbf076da_i c112327b_o and TS 192.168.101.0/24 
   === 192.168.100.0/24

In der Meldung wird auf der linken Seite das Netz auf der lokalen Seite und auf der rechten Seite das Netz hinter der Gegenseite angegeben.

Sind auf der Gegenseite nicht übereinstimmende Daten für den Tunnel konfiguriert, kommt es zu einem Fehler:

no matching CHILD_SA config found for 192.168.100.0/24 === 192.168.103.0/24
generating INFORMATIONAL_V1 request 4234879466 [ HASH N(INVAL_ID) ]

Ist die Gegenseite mit der eigenen Tunnelkonfiguration nicht einverstanden, wird dies wie folgt protokolliert:

received INVALID_ID_INFORMATION error notify

Ist auf der Gegenseite das falsche Verschlüsselungsprofil konfiguriert, äußert sich das sehr ähnlich wie in Phase 1:

received proposals: ESP:CAMELLIA_CBC_256/HMAC_SHA1_96/MODP_1536/NO_EXT_SEQ
configured proposals: ESP:AES_CBC_192/HMAC_SHA2_256_128/MODP_1536/NO_EXT_SEQ,...
no matching proposal found, sending NO_PROPOSAL_CHOSEN
generating INFORMATIONAL_V1 request 1561624858 [ HASH N(NO_PROP) ]

Ist die Gegenseite mit dem eigenen Verschlüsselungsprofil nicht einverstanden, wird dies wie folgt protokolliert:

received NO_PROPOSAL_CHOSEN error notify

Ist die VPN-Verbindung erfolgreich aufgebaut und die Funktion Offline-Erkennung aktiv, wird die Offline-Erkennung (Dead Peer Detection (DPD)) regelmäßig durchgeführt und protokolliert:

sending DPD request
generating INFORMATIONAL_V1 request 2386962670 [ HASH N(DPD) ]
sending packet: from 192.168.1.254[500] to 192.168.1.200[500] (108 bytes)
received packet: from 192.168.1.200[500] to 192.168.1.254[500] (108 bytes)
parsed INFORMATIONAL_V1 request 2215444627 [ HASH N(DPD) ]
generating INFORMATIONAL_V1 request 4233730633 [ HASH N(DPD_ACK) ]
sending packet: from 192.168.1.254[500] to 192.168.1.200[500] (108 bytes)
received packet: from 192.168.1.200[500] to 192.168.1.254[500] (108 bytes)
parsed INFORMATIONAL_V1 request 2351292760 [ HASH N(DPD_ACK) ]