Analisi del verbose della VPN IPSEC

In questo articolo andremo a vedere come analizzare il verbose e per fare questo vedremo alcuni esempi pratici.

La fase 1 non sale

1. Sul log l_vpn quando cerco di instaurare la vpn dal mio client Stormshield ottengo questo:
   id=firewall time="2012-01-04 11:58:52" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 11:58:52" error=2 phase=1 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0x58366c90026e0250 cookie_r=0x0000000000000000 user=francesco.redaelli@stormshield.com msg="Could not get a valid proposal"
   id=firewall time="2012-01-04 11:58:52" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 11:58:52" error=2 phase=1 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 msg="Negociation failed"
   Come potete vedere l'errore si trova sulla fase1, andiamo quindi ad analizzare il verbose per identificare quale parametro della fase1 abbiamo sbagliato.
   All'inizio del file di verbose troviamo tutti i parametri relativi alla fase 1 configurati sul nostro FW:
   2012-01-04 11:57:34: DEBUG: reading config file /var/tmp/racoon.conf
   

   ---

   2012-01-04 11:57:34: DEBUG2: lifetime = 21600
   2012-01-04 11:57:34: DEBUG2: lifebyte = 0
   2012-01-04 11:57:34: DEBUG2: encklen=128
   2012-01-04 11:57:34: DEBUG2: p:1 t:1
   2012-01-04 11:57:34: DEBUG2: AES-CBC(7)
   2012-01-04 11:57:34: DEBUG2: SHA(2)
   2012-01-04 11:57:34: DEBUG2: 1024-bit MODP group(2)
   2012-01-04 11:57:34: DEBUG2: pre-shared key(1)
   

   ---

   2012-01-04 11:57:34: DEBUG2: 
   2012-01-04 11:57:34: DEBUG2: lifetime = 21600
   2012-01-04 11:57:34: DEBUG2: lifebyte = 0
   2012-01-04 11:57:34: DEBUG2: encklen=128
   2012-01-04 11:57:34: DEBUG2: p:1 t:2
   2012-01-04 11:57:34: DEBUG2: Blowfish-CBC(3)
   2012-01-04 11:57:34: DEBUG2: SHA(2)
   2012-01-04 11:57:34: DEBUG2: 1024-bit MODP group(2)
   2012-01-04 11:57:34: DEBUG2: pre-shared key(1)
   

   ---

   2012-01-04 11:57:34: DEBUG2: 
   2012-01-04 11:57:34: DEBUG2: lifetime = 21600
   2012-01-04 11:57:34: DEBUG2: lifebyte = 0
   2012-01-04 11:57:34: DEBUG2: encklen=0
   2012-01-04 11:57:34: DEBUG2: p:1 t:3
   2012-01-04 11:57:34: DEBUG2: 3DES-CBC(5)
   2012-01-04 11:57:34: DEBUG2: SHA(2)
   2012-01-04 11:57:34: DEBUG2: 1024-bit MODP group(2)
   2012-01-04 11:57:34: DEBUG2: pre-shared key(1)
   
2. Come potete vedere ci sono 3 set di parametri(la linea tratteggiata è stata aggiunta da me per renderli più visibili) che il FW accetta
   Proseguendo nella lettura del verbose possiamo trovare i parametri che vengono inviati dal client e troviamo anche l'errore:
   2012-01-04 11:58:52: DEBUG: lifetime = 21600
   2012-01-04 11:58:52: DEBUG: lifebyte = 0
   2012-01-04 11:58:52: DEBUG: :enctype = DES-CBC
   2012-01-04 11:58:52: DEBUG: encklen = 0
   2012-01-04 11:58:52: DEBUG: hashtype = SHA
   2012-01-04 11:58:52: DEBUG: authmethod = pre-shared key
   2012-01-04 11:58:52: DEBUG: dh_group = 1024-bit MODP group
   2012-01-04 11:58:52: DEBUG2: checkisakmpsa:
   authmethod: 1 / 1
   2012-01-04 11:58:52: DEBUG2: checkisakmpsa
   authmethod: 1 / 1
   2012-01-04 11:58:52: DEBUG2: checkisakmpsa:
   authmethod: 1 / 1
   2012-01-04 11:58:52: ERROR: no suitable proposal found.
3. Il problema sta nel parametro realtivo all'encryption che sul client è stato settato a DES quando invece il FW si aspetta AES, Blowfish oppure 3DES come potete vedere al punto 1
4. Se volete prendere visione del file di verbose completo usato per scrivere questo articolo cliccate qui

La fase 2 non sale, primo caso:

1. Sul log l_vpn quando cerco di instaurare la vpn dal mio client Stormshield ottengo questo:
   id=firewall time="2012-01-04 12:05:08" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:05:08" error=0 phase=1 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xf4d79dd42aa1c3ce cookie_r=0x0000000000000000 msg="DPD support detected"
   id=firewall time="2012-01-04 12:05:08" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:05:08" error=0 phase=1 user=francesco.redaelli msg="User allowed"
   id=firewall time="2012-01-04 12:05:08" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:05:08" error=0 phase=1 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xf4d79dd42aa1c3ce cookie_r=0x14039978e83915c1 user=francesco.redaelli msg="INITIAL-CONTACT sent"
   id=firewall time="2012-01-04 12:05:08" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:05:08" error=0 phase=1 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xf4d79dd42aa1c3ce cookie_r=0x14039978e83915c1 user=francesco.redaelli msg="Phase established"
   id=firewall time="2012-01-04 12:05:08" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:05:08" error=2 phase=2 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xf4d79dd42aa1c3ce cookie_r=0x14039978e83915c1 user=francesco.redaelli msg="Could not get a valid proposal"
   id=firewall time="2012-01-04 12:05:08" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:05:08" error=2 phase=2 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xf4d79dd42aa1c3ce cookie_r=0x14039978e83915c1 localnet=192.168.85.0/24 remotenet=192.168.2.103 user=francesco.redaelli msg="Could not get a valid proposal"
   id=firewall time="2012-01-04 12:05:08" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:05:08" error=2 phase=2 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xf4d79dd42aa1c3ce cookie_r=0x14039978e83915c1 user=francesco.redaelli msg="Negociation failed"
   Come potete vedere l'errore si trova sulla fase2, andiamo quindi ad analizzare il verbose per identificare quale parametro della fase2 abbiamo sbagliato.
2. Se cerchiamo la parola WARNING troviamo queste righe all'interno delle quali troviamo subito il problema:
   2012-01-04 12:05:08: WARNING: trns_id mismatched: my:AES peer:DES
   2012-01-04 12:05:08: WARNING: trns_id mismatched: my:AES peer:DES
   2012-01-04 12:05:08: WARNING: trns_id mismatched: my:BLOWFISH peer:DES
   2012-01-04 12:05:08: WARNING: trns_id mismatched: my:BLOWFISH peer:DES
   2012-01-04 12:05:08: WARNING: trns_id mismatched: my:3DES peer:DES
   2012-01-04 12:05:08: WARNING: trns_id mismatched: my:3DES peer:DES
   Come potete vedere il peer(che sarebbe il mio client invia come encryption DES mentre il FW(my) si aspetta altri valori.
3. Se volete prendere visione del file di verbose completo usato per scrivere questo articolo cliccate qui

La fase 2 non sale, secondo caso:

1. Sul log l_vpn quando cerco di instaurare la vpn dal mio client Stormshield ottengo questo:
   id=firewall time="2012-01-04 12:23:42" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:23:42" error=0 phase=1 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xa8b1fb3e994282b3 cookie_r=0x0000000000000000 msg="DPD support detected"
   id=firewall time="2012-01-04 12:23:42" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:23:42" error=0 phase=1 user=francesco.redaelli msg="User allowed"
   id=firewall time="2012-01-04 12:23:42" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:23:42" error=0 phase=1 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xa8b1fb3e994282b3 cookie_r=0xcd39adca3223024a user=francesco.redaelli msg="INITIAL-CONTACT sent"
   id=firewall time="2012-01-04 12:23:42" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:23:42" error=0 phase=1 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xa8b1fb3e994282b3 cookie_r=0xcd39adca3223024a user=francesco.redaelli msg="Phase established"
   id=firewall time="2012-01-04 12:23:42" fw="V50XXA0E0000011" tz=+0100 startime="2012-01-04 12:23:42" error=2 phase=2 src=192.168.2.106 srcname=Firewall_out dst=192.168.2.103 side=responder cookie_i=0xa8b1fb3e994282b3 cookie_r=0xcd39adca3223024a localnet=192.168.85.0/22 remotenet=192.168.2.103 user=francesco.redaelli msg="Negociation failed"
   Come potete vedere l'errore si trova sulla fase2, andiamo quindi ad analizzare il verbose per identificare quale parametro della fase2 abbiamo sbagliato.
2. Analizzando il verbose ad un certo punto troviamo queste informazioni:
   2012-01-04 12:23:42: DEBUG: getsainfo params: loc='192.168.85.0/22' rmt='192.168.2.103' peer='francesco.redaelli@stormshield.com' client='192.168.2.103' id=4294967295
   2012-01-04 12:23:42: DEBUG: evaluating sainfo: loc='192.168.85.0/24', rmt='ANONYMOUS', peer='ANY', id=4294967295
   2012-01-04 12:23:42: DEBUG: check and compare ids : value mismatch (IPv4_subnet)
   2012-01-04 12:23:42: DEBUG: cmpid target: '192.168.85.0/22'
   2012-01-04 12:23:42: DEBUG: cmpid source: '192.168.85.0/24'
   2012-01-04 12:23:42: ERROR: failed to get sainfo.
   2012-01-04 12:23:42: ERROR: failed to get sainfo.
   2012-01-04 12:23:42: [192.168.2.103] ERROR: failed to pre-process ph2 packet (side: 1, status: 1).
3. Nelle prime due righe getsainfo params e evaluating sainfo troviamo prima i parametri che invia il client(getsainfo params) poi i parametri che si aspetta il nostro FW(evaluating sainfo).
   Come potete vedere nelle righe successive vengono paragonati i cmpid target (parametro inviato dal client) con il cmpid source parametro configurato nel FW e come potete vedere le network sono diverse quindi il tunnel non sale.
4. Per risolvere il problema quindi basta modificare la network sul nostro client facendola diventare una /24
5. Se volete prendere visione del file di verbose completo usato per scrivere questo articolo cliccate qui