# SPD-records for L2TP IPSec client behind NAT



## yurybx (Dec 4, 2018)

Hello!
I am trying to set up an L2TP IPSec client on FreeBSD, which is located behind NAT. The connection is established, the interface receives an IP-address, but the traffic through the tunnel does not pass, and the connection is broken for a minute ("peer not responding to echo requests"). Firewall on my FreeBSD is disabled. I suspect that I have incorrectly specified the SPD records.
L2TP server is not mine, but everything is fine with it, since the connection from Windows has been working properly. I ask for help!
My current configuration is:
FreeBSD 10.4 amd64, ipsec-tools-0.8.2_5, mpd5-5.8.
10.1.1.99 - my FreeBSD's IP address, 195.195.195.195 - L2TP-server's IP address.

```
# /usr/local/sbin/setkey -D
10.1.1.99[4500] 195.195.195.195[4500]
        esp-udp mode=transport spi=2500708219(0x950dc77b) reqid=0(0x00000000)
        E: 3des-cbc  cc241dfe 151fdb7b 0227e341 bef53d6a 7cdd3310 563f285e
        A: hmac-md5  ea372c20 05d8a139 a1d374a0 2809c7ab
        seq=0x0000000a replay=4 flags=0x00000000 state=mature
        created: Dec  4 12:29:24 2018   current: Dec  4 12:29:27 2018
        diff: 3(s)      hard: 3600(s)   soft: 2880(s)
        last: Dec  4 12:29:26 2018      hard: 0(s)      soft: 0(s)
        current: 1096(bytes)    hard: 0(bytes)  soft: 0(bytes)
        allocated: 10   hard: 0 soft: 0
        sadb_seq=1 pid=1964 refcnt=2
195.195.195.195[4500] 10.1.1.99[4500]
        esp-udp mode=transport spi=84968259(0x05108343) reqid=0(0x00000000)
        E: 3des-cbc  dff05279 74648a8e 5543ab0d a036e756 705d41af 7b7acfb0
        A: hmac-md5  453adf6a 27bef5d1 bf2aa0a0 f66e40b1
        seq=0x0000000b replay=4 flags=0x00000000 state=mature
        created: Dec  4 12:29:24 2018   current: Dec  4 12:29:27 2018
        diff: 3(s)      hard: 3600(s)   soft: 2880(s)
        last: Dec  4 12:29:26 2018      hard: 0(s)      soft: 0(s)
        current: 682(bytes)     hard: 0(bytes)  soft: 0(bytes)
        allocated: 11   hard: 0 soft: 0
        sadb_seq=0 pid=1964 refcnt=1

# cat setkey.conf
flush;
spdflush;
spdadd 10.1.1.99[0] 195.195.195.195[1701] udp -P out ipsec esp/transport//require;
spdadd 195.195.195.195[1701] 10.1.1.99[0] udp -P in ipsec esp/transport//require;

# cat racoon.conf:
path include "/usr/local/etc/racoon";
path pre_shared_key "/usr/local/etc/racoon/psk.txt";
log info;
padding
{
        maximum_length 20;      
        randomize off;        
        strict_check off;     
        exclusive_tail off;   
}
listen {
        isakmp                  10.1.1.99 [7001];
        isakmp                  10.1.1.99 [500];
        isakmp_natt             10.1.1.99 [4500];
}
timer {
        counter 5;
        interval 20 sec;
        persend 1;
        phase1 30 sec;
        phase2 15 sec;
}
remote 195.195.195.195 {
        exchange_mode main,aggressive;
        lifetime time 24 hour;
        my_identifier address;
        peers_identifier address;
        passive off;
        generate_policy off;
        nat_traversal on;
        proposal {
                encryption_algorithm 3des;
                hash_algorithm sha1;
                authentication_method pre_shared_key;
                dh_group 2;
        }
}
sainfo anonymous {
        encryption_algorithm 3des;
        authentication_algorithm hmac_md5, hmac_sha1;
        lifetime time 1 hour ;
        compression_algorithm deflate;
}

# cat mpd.conf
startup:
log +ALL +EVENTS -FRAME -ECHO
default:
      load L2TP_client
L2TP_client:
        create bundle static B1
        create link static L1 l2tp
        set link action bundle B1
        set auth authname "mylogin"
        set auth password "mypassword"
        set link max-redial 0
        set link mtu 1460
        set link keep-alive 20 75
        set l2tp peer 195.195.195.195
        open
```


----------



## SirDice (Dec 4, 2018)

yurybx said:


> FreeBSD 10.4 amd64


FreeBSD 10.4 is End-of-Life and not supported anymore. In fact, the whole 10 branch is End-of-Life. 

Topics about unsupported FreeBSD versions
https://www.freebsd.org/security/unsupported.html


----------



## obsigna (Dec 4, 2018)

The FreeBSD-10 branch and security/ipsec-tools need kernel patches in order to get NAT-T completely  working.

You definitely want to upgrade to 11.2 or go right to the latest 12-RC. All IPsec-NAT-T problems are resolved and even better, all you need for IPsec is enabled by default in the GENERIC kernel, that means you won’t need to compile a custom one.

In addition, forget ipsec-tools, use security/strongswan instead.  With only a few reasonable settings, strongSwan works out of the box together with net/mpd5 for setting up L2TP/IPsec peers.


----------



## yurybx (Dec 6, 2018)

I can not find an example of configuring StrongSwan as a client behind nat. All links offered by Google relate to setting up an L2TP IPSec server. Could you suggest a link?
And I also began to doubt that racoon was to blame for my problem. After all, if the ng0 interface receives an ip address, then IPSec works well in both directions. Right? Maybe the problem is at the level of MPD5?


----------



## obsigna (Dec 6, 2018)

There is no big difference between an IPsec client and an IPsec server. You want to think more about one peer being the initiator of the link and the other peer opens its door once it hears someone's knocking.

On the initiator (client) you would simply leave out the directive auto = add. You also need to keep in mind that L2TP/IPsec is a two phase connection, so on the L2TP/IPsec client you would need to first initiate the IPsec transport link and then, once it is established, open the L2TP connection, and make sure, that the traffic goes through the IPsec link. nixlike wrote a script for this, see: https://forums.freebsd.org/threads/strongswan-mpd5-to-meraki-mx100-client-vpn.67006/#post-397204

You want to read the whole thread.


----------



## yurybx (Dec 6, 2018)

I configured the program, as in the example that you suggested. Unfortunately, I can’t set up an IPsec connection: "received NO_PROPOSAL_CHOSEN error notify". I tried to change the parameter ESP to "aes256-sha1!" and it does not help. Tell me, please, how to understand what's the matter?


```
conn %default
      ikelifetime=60m
      keylife=20m
      rekeymargin=3m
      keyingtries=1
      keyexchange=ikev1
      authby=secret
      ike=aes128-sha1-modp1024,3des-sha1-modp1024!
      esp=aes128-sha1-modp1024,3des-sha1-modp1024!

conn ivpn
      keyexchange=ikev1
      left=%defaultroute
      auto=add
      authby=secret
      type=transport
      leftprotoport=17/%any
      rightprotoport=17/1701
      right=195.195.195.195
```


```
# ipsec up ivpn
initiating Main Mode IKE_SA ivpn[2] to 195.195.195.195
generating ID_PROT request 0 [ SA V V V V V ]
sending packet: from 10.1.1.99[500] to 195.195.195.195[500] (212 bytes)
received packet: from 195.195.195.195[500] to 10.1.1.99[500] (128 bytes)
parsed ID_PROT response 0 [ SA V V ]
received NAT-T (RFC 3947) vendor ID
received FRAGMENTATION vendor ID
generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
sending packet: from 10.1.1.99[500] to 195.195.195.195[500] (244 bytes)
received packet: from 195.195.195.195[500] to 10.1.1.99[500] (304 bytes)
parsed ID_PROT response 0 [ KE No V V V V NAT-D NAT-D ]
received Cisco Unity vendor ID
received XAuth vendor ID
received unknown vendor ID: fa:6f:8c:02:08:5a:f8:4d:a3:d0:7b:ab:96:0e:13:5b
received unknown vendor ID: 1f:07:f7:0e:aa:65:14:d3:b0:fa:96:54:2a:50:01:00
local host is behind NAT, sending keep alives
generating ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ]
sending packet: from 10.1.1.99[4500] to 195.195.195.195[4500] (108 bytes)
received packet: from 195.195.195.195[4500] to 10.1.1.99[4500] (92 bytes)
parsed ID_PROT response 0 [ ID HASH V ]
received DPD vendor ID
IKE_SA ivpn[2] established between 10.1.1.99[10.1.1.99]...195.195.195.195[195.195.195.195]
scheduling reauthentication in 3336s
maximum IKE_SA lifetime 3516s
generating QUICK_MODE request 3710640694 [ HASH SA No KE ID ID NAT-OA NAT-OA ]
sending packet: from 10.1.1.99[4500] to 195.195.195.195[4500] (364 bytes)
received packet: from 195.195.195.195[4500] to 10.1.1.99[4500] (92 bytes)
parsed INFORMATIONAL_V1 request 4226070514 [ HASH N(NO_PROP) ]
received NO_PROPOSAL_CHOSEN error notify
establishing connection 'ivpn' failed
```


----------



## obsigna (Dec 6, 2018)

Try again after removing the ike and the esp directives. strongSwan comes with a reasonable set of default ciphers enabled. On one of my servers, which need to serve older clients, I have ike = aes256-sha1-modp1024 in my ipsec.conf. For modern peers we don’t want to support sha1 anymore. If this doesn't help, you need to find out, which ciphers the IPsec server supports, then choose the best one and add it to the ike and/or esp directives.


----------



## yurybx (Dec 7, 2018)

When I try to establish connection without that directives, I get the error at an earlier stage.

```
# ipsec up ivpn
initiating Main Mode IKE_SA ivpn[1] to 195.195.195.195
generating ID_PROT request 0 [ SA V V V V V ]
sending packet: from 10.1.1.99[500] to 195.195.195.195[500] (204 bytes)
received packet: from 195.195.195.195[500] to 10.1.1.99[500] (120 bytes)
parsed INFORMATIONAL_V1 request 0 [ N(NO_PROP) ]
received NO_PROPOSAL_CHOSEN error notify
establishing connection 'ivpn' failed
```
I also tried "ike=aes256-sha1-modp1024" and "ike=3des-sha1-modp1024" - got the same error.
How can I find out the ciphers supported by the IPSec server? The problem is that the server is not mine. I tried to analize racoon's log (it establishes IPSec-connection successfully), but it did not help. Here is the log of successful connection by racoon:

```
Dec  7 11:56:00 TEST racoon: INFO: @(#)ipsec-tools 0.8.2 (http://ipsec-tools.sourceforge.net)
Dec  7 11:56:00 TEST racoon: INFO: @(#)This product linked OpenSSL 1.0.1u-freebsd  22 Sep 2016 (http://www.openssl.org/)
Dec  7 11:56:00 TEST racoon: INFO: Reading configuration from "/usr/local/etc/racoon/racoon.conf"
Dec  7 11:56:00 TEST racoon: DEBUG2: lifetime = 86400
Dec  7 11:56:00 TEST racoon: DEBUG2: lifebyte = 0
Dec  7 11:56:00 TEST racoon: DEBUG2: encklen=0
Dec  7 11:56:00 TEST racoon: DEBUG2: p:1 t:1
Dec  7 11:56:00 TEST racoon: DEBUG2: 3DES-CBC(5)
Dec  7 11:56:00 TEST racoon: DEBUG2: SHA(2)
Dec  7 11:56:00 TEST racoon: DEBUG2: 1024-bit MODP group(2)
Dec  7 11:56:00 TEST racoon: DEBUG2: pre-shared key(1)
Dec  7 11:56:00 TEST racoon: DEBUG2:
Dec  7 11:56:00 TEST racoon: DEBUG2: Etype mismatch: got 2, expected 4.
Dec  7 11:56:00 TEST racoon: DEBUG: hmac(modp1024)
Dec  7 11:56:00 TEST racoon: DEBUG: no check of compression algorithm; not supported in sadb message.
Dec  7 11:56:00 TEST racoon: DEBUG: getsainfo params: loc='ANONYMOUS' rmt='ANONYMOUS' peer='NULL' client='NULL' id=0
Dec  7 11:56:00 TEST racoon: DEBUG2: parse successed.
Dec  7 11:56:00 TEST racoon: INFO: 10.1.1.99[4500] used for NAT-T
Dec  7 11:56:00 TEST racoon: INFO: 10.1.1.99[4500] used as isakmp port (fd=6)
Dec  7 11:56:00 TEST racoon: INFO: 10.1.1.99[500] used as isakmp port (fd=7)
Dec  7 11:56:00 TEST racoon: INFO: 10.1.1.99[7001] used as isakmp port (fd=8)
Dec  7 11:56:00 TEST racoon: DEBUG: pk_recv: retry[0] recv()
Dec  7 11:56:00 TEST racoon: DEBUG: got pfkey X_SPDDUMP message
Dec  7 11:56:00 TEST racoon: DEBUG2:  02120000 0b000100 01000000 e3020000 03000500 11200000 100206a5 c3954646 00000000 00000000 03000600 11200000 10020000 0a010163 00000000 00000000 03001200 02000100 02000000 00000000 08003200 01020000
Dec  7 11:56:00 TEST racoon: DEBUG: pk_recv: retry[0] recv()
Dec  7 11:56:00 TEST racoon: DEBUG: got pfkey X_SPDDUMP message
Dec  7 11:56:00 TEST racoon: DEBUG2:  02120000 0b000100 00000000 e3020000 03000500 11200000 10020000 0a010163 00000000 00000000 03000600 11200000 100206a5 c3954646 00000000 00000000 03001200 02000200 01000000 00000000 08003200 01020000
Dec  7 11:56:00 TEST racoon: DEBUG: sub:0x7fffffffe610: 10.1.1.99/32[0] 195.195.195.195/32[1701] proto=udp dir=out reqid=0
Dec  7 11:56:00 TEST racoon: DEBUG: db :0x80205d490: 195.195.195.195/32[1701] 10.1.1.99/32[0] proto=udp dir=in reqid=0
Dec  7 11:56:25 TEST racoon: DEBUG: pk_recv: retry[0] recv()
Dec  7 11:56:25 TEST racoon: DEBUG: got pfkey ACQUIRE message
Dec  7 11:56:25 TEST racoon: DEBUG2:  02060003 2f000000 02000000 00000000 03000500 11200000 10020000 0a010163 00000000 00000000 03000600 11200000 100206a5 c3954646 00000000 00000000 02001200 02000200 01000000 00000000 25000d00 20000000 00070000 00000000 0001c001 00000000 01000000 01000000 00000000 00000000 00000000 00000000 00000000 00000000 80510100 00000000 80700000 00000000 00000000 00000000 000b0000 00000000 00010008 00000000 01000000 01000000 00000000 00000000 00000000 00000000 00000000 00000000 80510100 00000000 80700000 00000000 00000000 00000000 000c0000 00000000 00010001 00000000 01000000 01000000 00000000 00000000 00000000 00000000 00000000 00000000 80510100 00000000 80700000 00000000 00000000 00000000 00160000 00000000 00010001 00000000 01000000 01000000 00000000 00000000 00000000 00000000 00000000 00000000 80510100 00000000 80700000 00000000 00000000 00000000
Dec  7 11:56:25 TEST racoon: DEBUG: suitable outbound SP found: 10.1.1.99/32[0] 195.195.195.195/32[1701] proto=udp dir=out reqid=0.
Dec  7 11:56:25 TEST racoon: DEBUG: sub:0x7fffffffe610: 195.195.195.195/32[1701] 10.1.1.99/32[0] proto=udp dir=in reqid=0
Dec  7 11:56:25 TEST racoon: DEBUG: db :0x80205d490: 195.195.195.195/32[1701] 10.1.1.99/32[0] proto=udp dir=in reqid=0
Dec  7 11:56:25 TEST racoon: DEBUG: suitable inbound SP found: 195.195.195.195/32[1701] 10.1.1.99/32[0] proto=udp dir=in reqid=0.
Dec  7 11:56:25 TEST racoon: DEBUG: new acquire 10.1.1.99/32[0] 195.195.195.195/32[1701] proto=udp dir=out reqid=0
Dec  7 11:56:25 TEST racoon: [195.195.195.195] DEBUG2: Checking remote conf "195.195.195.195[500]" 195.195.195.195[500].
Dec  7 11:56:25 TEST racoon: DEBUG2: enumrmconf: "195.195.195.195[500]" matches.
Dec  7 11:56:25 TEST racoon: [195.195.195.195] DEBUG: configuration "195.195.195.195[500]" selected.
Dec  7 11:56:25 TEST racoon: DEBUG: getsainfo params: loc='10.1.1.99' rmt='195.195.195.195' peer='NULL' client='NULL' id=0
Dec  7 11:56:25 TEST racoon: DEBUG: evaluating sainfo: loc='ANONYMOUS', rmt='ANONYMOUS', peer='ANY', id=0, reqid=0
Dec  7 11:56:25 TEST racoon: DEBUG: check and compare ids : values matched (ANONYMOUS)
Dec  7 11:56:25 TEST racoon: DEBUG: check and compare ids : values matched (ANONYMOUS)
Dec  7 11:56:25 TEST racoon: DEBUG: selected sainfo: loc='ANONYMOUS', rmt='ANONYMOUS', peer='ANY', id=0, reqid=0
Dec  7 11:56:25 TEST racoon: DEBUG:  (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Transport reqid=0:0)
Dec  7 11:56:25 TEST racoon: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-md5)
Dec  7 11:56:25 TEST racoon: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-sha)
Dec  7 11:56:25 TEST racoon: DEBUG: in post_acquire
Dec  7 11:56:25 TEST racoon: [195.195.195.195] DEBUG2: Checking remote conf "195.195.195.195[500]" 195.195.195.195[500].
Dec  7 11:56:25 TEST racoon: DEBUG2: enumrmconf: "195.195.195.195[500]" matches.
Dec  7 11:56:25 TEST racoon: [195.195.195.195] DEBUG: configuration "195.195.195.195[500]" selected.
Dec  7 11:56:25 TEST racoon: DEBUG2: getph1: start
Dec  7 11:56:25 TEST racoon: DEBUG2: local: 10.1.1.99[0]
Dec  7 11:56:25 TEST racoon: DEBUG2: remote: 195.195.195.195[1701]
Dec  7 11:56:25 TEST racoon: DEBUG2: no match
Dec  7 11:56:25 TEST racoon: INFO: IPsec-SA request for 195.195.195.195 queued due to no phase1 found.
Dec  7 11:56:25 TEST racoon: DEBUG: ===
Dec  7 11:56:25 TEST racoon: INFO: initiate new phase 1 negotiation: 10.1.1.99[500]<=>195.195.195.195[500]
Dec  7 11:56:25 TEST racoon: INFO: begin Identity Protection mode.
Dec  7 11:56:25 TEST racoon: DEBUG: new cookie: 66a0d6f56c2082ef
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 52, next type 13
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 16, next type 13
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 16, next type 0
Dec  7 11:56:25 TEST racoon: DEBUG: 124 bytes from 10.1.1.99[500] to 195.195.195.195[500]
Dec  7 11:56:25 TEST racoon: DEBUG: sockname 10.1.1.99[500]
Dec  7 11:56:25 TEST racoon: DEBUG: send packet from 10.1.1.99[500]
Dec  7 11:56:25 TEST racoon: DEBUG: send packet to 195.195.195.195[500]
Dec  7 11:56:25 TEST racoon: DEBUG: 1 times of 124 bytes message will be sent to 195.195.195.195[500]
Dec  7 11:56:25 TEST racoon: DEBUG:  66a0d6f5 6c2082ef 00000000 00000000 01100200 00000000 0000007c 0d000038 00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 000c0004 00015180 80010005 80030001 80020002 80040002 0d000014 4a131c81 07035845 5c5728f2 0e95452f 00000014 afcad713 68a1f1c9 6b8696fc 77570100
Dec  7 11:56:25 TEST racoon: DEBUG: resend phase1 packet 66a0d6f56c2082ef:0000000000000000
Dec  7 11:56:25 TEST racoon: DEBUG: ===
Dec  7 11:56:25 TEST racoon: DEBUG: 128 bytes message received from 195.195.195.195[500] to 10.1.1.99[500]
Dec  7 11:56:25 TEST racoon: DEBUG:  66a0d6f5 6c2082ef 43283910 6a57a86f 01100200 00000000 00000080 0d000038 00000001 00000001 0000002c 01010001 00000024 01010000 80010005 80020002 80040002 80030001 800b0001 000c0004 00015180 0d000014 4a131c81 07035845 5c5728f2 0e95452f 00000018 4048b7d5 6ebce885 25e7de7f 00d6c2d3 c0000000
Dec  7 11:56:25 TEST racoon: DEBUG: begin.
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=1(sa)
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=13(vid)
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=13(vid)
Dec  7 11:56:25 TEST racoon: DEBUG: succeed.
Dec  7 11:56:25 TEST racoon: INFO: received Vendor ID: RFC 3947
Dec  7 11:56:25 TEST racoon: INFO: received broken Microsoft ID: FRAGMENTATION
Dec  7 11:56:25 TEST racoon: [195.195.195.195] INFO: Selected NAT-T version: RFC 3947
Dec  7 11:56:25 TEST racoon: DEBUG: total SA len=52
Dec  7 11:56:25 TEST racoon: DEBUG:  00000001 00000001 0000002c 01010001 00000024 01010000 80010005 80020002 80040002 80030001 800b0001 000c0004 00015180
Dec  7 11:56:25 TEST racoon: DEBUG: begin.
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=2(prop)
Dec  7 11:56:25 TEST racoon: DEBUG: succeed.
Dec  7 11:56:25 TEST racoon: DEBUG: proposal #1 len=44
Dec  7 11:56:25 TEST racoon: DEBUG: begin.
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=3(trns)
Dec  7 11:56:25 TEST racoon: DEBUG: succeed.
Dec  7 11:56:25 TEST racoon: DEBUG: transform #1 len=36
Dec  7 11:56:25 TEST racoon: DEBUG: type=Encryption Algorithm, flag=0x8000, lorv=3DES-CBC
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: type=Hash Algorithm, flag=0x8000, lorv=SHA
Dec  7 11:56:25 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: type=Group Description, flag=0x8000, lorv=1024-bit MODP group
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(modp1024)
Dec  7 11:56:25 TEST racoon: DEBUG: type=Authentication Method, flag=0x8000, lorv=pre-shared key
Dec  7 11:56:25 TEST racoon: DEBUG: type=Life Type, flag=0x8000, lorv=seconds
Dec  7 11:56:25 TEST racoon: DEBUG: type=Life Duration, flag=0x0000, lorv=4
Dec  7 11:56:25 TEST racoon: DEBUG: pair 1:
Dec  7 11:56:25 TEST racoon: DEBUG:  0x802024c80: next=0x0 tnext=0x0
Dec  7 11:56:25 TEST racoon: DEBUG: proposal #1: 1 transform
Dec  7 11:56:25 TEST racoon: DEBUG: type=Encryption Algorithm, flag=0x8000, lorv=3DES-CBC
Dec  7 11:56:25 TEST racoon: DEBUG: type=Hash Algorithm, flag=0x8000, lorv=SHA
Dec  7 11:56:25 TEST racoon: DEBUG: type=Group Description, flag=0x8000, lorv=1024-bit MODP group
Dec  7 11:56:25 TEST racoon: DEBUG: type=Authentication Method, flag=0x8000, lorv=pre-shared key
Dec  7 11:56:25 TEST racoon: DEBUG: type=Life Type, flag=0x8000, lorv=seconds
Dec  7 11:56:25 TEST racoon: DEBUG: type=Life Duration, flag=0x0000, lorv=4
Dec  7 11:56:25 TEST racoon: DEBUG: prop#=1, prot-id=ISAKMP, spi-size=0, #trns=1
Dec  7 11:56:25 TEST racoon: DEBUG: trns#=1, trns-id=IKE
Dec  7 11:56:25 TEST racoon: DEBUG:   lifetime = 86400
Dec  7 11:56:25 TEST racoon: DEBUG:   lifebyte = 0
Dec  7 11:56:25 TEST racoon: DEBUG:   enctype = 3DES-CBC
Dec  7 11:56:25 TEST racoon: DEBUG:   encklen = 0
Dec  7 11:56:25 TEST racoon: DEBUG:   hashtype = SHA
Dec  7 11:56:25 TEST racoon: DEBUG:   authmethod = pre-shared key
Dec  7 11:56:25 TEST racoon: DEBUG:   dh_group = 1024-bit MODP group
Dec  7 11:56:25 TEST racoon: DEBUG2: checkisakmpsa: authmethod: 1 / 1
Dec  7 11:56:25 TEST racoon: DEBUG: an acceptable proposal found.
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(modp1024)
Dec  7 11:56:25 TEST racoon: DEBUG: agreed on pre-shared key auth.
Dec  7 11:56:25 TEST racoon: DEBUG: ===
Dec  7 11:56:25 TEST racoon: DEBUG: compute DH's private.
Dec  7 11:56:25 TEST racoon: DEBUG:  7e833060 4ba1995e 8880a4aa 46f46948 460b2607 3338d315 4600d0b6 d411bf75 d64cf786 d6c2edda 91643af6 de8196f2 66a697c3 5f1fa9ff 10ee6bd8 5bed0f87 19363893 679ff1a4 b7fce14b 8e3ba7f5 f36dc7f5 72f823fd f7c3d7ee 14cf0ef3 cc76b0ad 9a5eeed8 94b2bb04 f59eb9f1 461daa03 0b54d33f d690c5c2 ceaa422a
Dec  7 11:56:25 TEST racoon: DEBUG: compute DH's public.
Dec  7 11:56:25 TEST racoon: DEBUG:  e9184f2d b4981706 5aa96cee 335bb2b5 f4fae353 7c5f3c53 43ede4d9 95e65b62 33bc95db 8e849470 de82c54a 7d9e4348 b9252661 10f1580f 2342d97d ae753aa2 b937691c 0b2333d7 bb1628d5 80209263 77a22e8e 0f5a4032 3479753f a0c78ce5 f94a213a 72cbe115 d5f22c7f 4364985c 922863c8 e24ca3e7 80a3c35f 56080782
Dec  7 11:56:25 TEST racoon: [195.195.195.195] INFO: Hashing 195.195.195.195[500] with algo #2
Dec  7 11:56:25 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:25 TEST racoon: [10.1.1.99] INFO: Hashing 10.1.1.99[500] with algo #2
Dec  7 11:56:25 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:25 TEST racoon: INFO: Adding remote and local NAT-D payloads.
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 128, next type 10
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 16, next type 20
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 20, next type 20
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 20, next type 0
Dec  7 11:56:25 TEST racoon: DEBUG: 228 bytes from 10.1.1.99[500] to 195.195.195.195[500]
Dec  7 11:56:25 TEST racoon: DEBUG: sockname 10.1.1.99[500]
Dec  7 11:56:25 TEST racoon: DEBUG: send packet from 10.1.1.99[500]
Dec  7 11:56:25 TEST racoon: DEBUG: send packet to 195.195.195.195[500]
Dec  7 11:56:25 TEST racoon: DEBUG: 1 times of 228 bytes message will be sent to 195.195.195.195[500]
Dec  7 11:56:25 TEST racoon: DEBUG:  66a0d6f5 6c2082ef 43283910 6a57a86f 04100200 00000000 000000e4 0a000084 e9184f2d b4981706 5aa96cee 335bb2b5 f4fae353 7c5f3c53 43ede4d9 95e65b62 33bc95db 8e849470 de82c54a 7d9e4348 b9252661 10f1580f 2342d97d ae753aa2 b937691c 0b2333d7 bb1628d5 80209263 77a22e8e 0f5a4032 3479753f a0c78ce5 f94a213a 72cbe115 d5f22c7f 4364985c 922863c8 e24ca3e7 80a3c35f 56080782 14000014 b6d967cc ce38f972 3454d6f3 519b5c91 14000018 501f19da e02f8274 a1e5e24c 13167b81 4483aa45 00000018 8eae0e35 6b1a0d84 3101f4c0 7dd26788 8b5013b0
Dec  7 11:56:25 TEST racoon: DEBUG: resend phase1 packet 66a0d6f56c2082ef:432839106a57a86f
Dec  7 11:56:25 TEST racoon: DEBUG: ===
Dec  7 11:56:25 TEST racoon: DEBUG: 304 bytes message received from 195.195.195.195[500] to 10.1.1.99[500]
Dec  7 11:56:25 TEST racoon: DEBUG:  66a0d6f5 6c2082ef 43283910 6a57a86f 04100200 00000000 00000130 0a000084 0697fd65 ce264b84 8cb6048c c516bbb1 948ffdac ef4af5ec 3e7883c5 eab9c8b2 b12e0b22 3c150d20 0d828fa3 51f489e2 31e53b9c 24165699 678e5239 21738492 4131fc6e edf2a0ef 8e1e402c af22e5c2 f1d1b5a7 f34a0ef0 cd1504b1 0bbf0fe3 53b15f52 6b580443 b8d26365 a15b88e2 c5b6eb8b fa4df061 610ec4bb 2ea60dc2 0d000018 34062827 a24df96a 4355f65e 39ee441a f756c9d0 0d000014 12f5f28c 457168a9 702d9fe2 74cc0100 0d00000c 09002689 dfd6b712 0d000014 b6ef9e0d 6a56a86f c2999911 d809b519 14000014 1f07f70e aa6514d3 b0fa9654 2a500100 14000018 ec1c2e12 e6e19871 b00dde08 8a01c1cc 97d7a755 00000018 501f19da e02f8274 a1e5e24c 13167b81 4483aa45
Dec  7 11:56:25 TEST racoon: DEBUG: begin.
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=4(ke)
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=10(nonce)
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=13(vid)
Dec  7 11:56:25 TEST last message repeated 3 times
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=20(nat-d)
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=20(nat-d)
Dec  7 11:56:25 TEST racoon: DEBUG: succeed.
Dec  7 11:56:25 TEST racoon: INFO: received Vendor ID: CISCO-UNITY
Dec  7 11:56:25 TEST racoon: INFO: received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt
Dec  7 11:56:25 TEST racoon: DEBUG: received unknown Vendor ID
Dec  7 11:56:25 TEST racoon: DEBUG:  b6ef9e0d 6a56a86f c2999911 d809b519
Dec  7 11:56:25 TEST racoon: DEBUG: received unknown Vendor ID
Dec  7 11:56:25 TEST racoon: DEBUG:  1f07f70e aa6514d3 b0fa9654 2a500100
Dec  7 11:56:25 TEST racoon: [10.1.1.99] INFO: Hashing 10.1.1.99[500] with algo #2
Dec  7 11:56:25 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:25 TEST racoon: INFO: NAT-D payload #0 doesn't match
Dec  7 11:56:25 TEST racoon: [195.195.195.195] INFO: Hashing 195.195.195.195[500] with algo #2
Dec  7 11:56:25 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:25 TEST racoon: INFO: NAT-D payload #1 verified
Dec  7 11:56:25 TEST racoon: INFO: NAT detected: ME
Dec  7 11:56:25 TEST racoon: INFO: KA list add: 10.1.1.99[4500]->195.195.195.195[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: ===
Dec  7 11:56:25 TEST racoon: DEBUG: compute DH's shared.
Dec  7 11:56:25 TEST racoon: DEBUG:  9f41feb5 e0b5290a fab77914 d15ddec5 014c1470 df6180bc 4117d239 1c5d2e47 49d58c02 15fd7f6c b51690fb 9e1d5bb4 9a112ba3 8a8ab929 5e555355 d02c3633 3bcad860 bea160e4 1e637a09 1df53e38 26629074 b6170e2a 8fd73b8e 28716835 750af95e 3447ef52 a3708187 4df7d19f 566ed023 f9dbf90a fe949b1d 9af9e6ce
Dec  7 11:56:25 TEST racoon: DEBUG: the psk found.
Dec  7 11:56:25 TEST racoon: DEBUG2: psk:
Dec  7 11:56:25 TEST racoon: DEBUG2:  47746864 73715f59 467b
Dec  7 11:56:25 TEST racoon: DEBUG: nonce 1:
Dec  7 11:56:25 TEST racoon: DEBUG:  b6d967cc ce38f972 3454d6f3 519b5c91
Dec  7 11:56:25 TEST racoon: DEBUG: nonce 2:
Dec  7 11:56:25 TEST racoon: DEBUG:  34062827 a24df96a 4355f65e 39ee441a f756c9d0
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: SKEYID computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  bac88b95 787a4d50 3fafc78c 0df0a7fc b58da95b
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: SKEYID_d computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  af37d5ec e31e482d 9d8fa9dc 057df2e6 4a8ad62c
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: SKEYID_a computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  46a03274 6dd820b6 d923cdfe edb6be17 58af3f6e
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: SKEYID_e computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  ebc534db bcc9810e c256a283 1efa5489 e688f8bb
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: len(SKEYID_e) < len(Ka) (20 < 24), generating long key (Ka = K1 | K2 | ...)
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: compute intermediate encryption key K1
Dec  7 11:56:25 TEST racoon: DEBUG:  00
Dec  7 11:56:25 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: compute intermediate encryption key K2
Dec  7 11:56:25 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb
Dec  7 11:56:25 TEST racoon: DEBUG:  523c8d61 7dc238a9 190e03dc ec61273c 517960a9
Dec  7 11:56:25 TEST racoon: DEBUG: final encryption key computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb 523c8d61
Dec  7 11:56:25 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: IV computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  4b7fa81a 57f28564
Dec  7 11:56:25 TEST racoon: DEBUG: use ID type of IPv4_address
Dec  7 11:56:25 TEST racoon: DEBUG: HASH with:
Dec  7 11:56:25 TEST racoon: DEBUG:  e9184f2d b4981706 5aa96cee 335bb2b5 f4fae353 7c5f3c53 43ede4d9 95e65b62 33bc95db 8e849470 de82c54a 7d9e4348 b9252661 10f1580f 2342d97d ae753aa2 b937691c 0b2333d7 bb1628d5 80209263 77a22e8e 0f5a4032 3479753f a0c78ce5 f94a213a 72cbe115 d5f22c7f 4364985c 922863c8 e24ca3e7 80a3c35f 56080782 0697fd65 ce264b84 8cb6048c c516bbb1 948ffdac ef4af5ec 3e7883c5 eab9c8b2 b12e0b22 3c150d20 0d828fa3 51f489e2 31e53b9c 24165699 678e5239 21738492 4131fc6e edf2a0ef 8e1e402c af22e5c2 f1d1b5a7 f34a0ef0 cd1504b1 0bbf0fe3 53b15f52 6b580443 b8d26365 a15b88e2 c5b6eb8b fa4df061 610ec4bb 2ea60dc2 66a0d6f5 6c2082ef 43283910 6a57a86f 00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 000c0004 00015180 80010005 80030001 80020002 80040002 011101f4 0a010163
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: HASH (init) computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  d30781ba 6fdf851a dc3c6c46 4c8d3116 2b6613bd
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 8, next type 8
Dec  7 11:56:25 TEST racoon: DEBUG: add payload of len 20, next type 0
Dec  7 11:56:25 TEST racoon: DEBUG: begin encryption.
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: pad length = 4
Dec  7 11:56:25 TEST racoon: DEBUG:  0800000c 011101f4 0a010163 00000018 d30781ba 6fdf851a dc3c6c46 4c8d3116 2b6613bd 00000004
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: with key:
Dec  7 11:56:25 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb 523c8d61
Dec  7 11:56:25 TEST racoon: DEBUG: encrypted payload by IV:
Dec  7 11:56:25 TEST racoon: DEBUG:  4b7fa81a 57f28564
Dec  7 11:56:25 TEST racoon: DEBUG: save IV for next:
Dec  7 11:56:25 TEST racoon: DEBUG:  aa67e249 97c7eab4
Dec  7 11:56:25 TEST racoon: DEBUG: encrypted.
Dec  7 11:56:25 TEST racoon: DEBUG: Adding NON-ESP marker
Dec  7 11:56:25 TEST racoon: DEBUG: 72 bytes from 10.1.1.99[4500] to 195.195.195.195[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: sockname 10.1.1.99[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: send packet from 10.1.1.99[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: send packet to 195.195.195.195[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: 1 times of 72 bytes message will be sent to 195.195.195.195[4500]
Dec  7 11:56:25 TEST racoon: DEBUG:  00000000 66a0d6f5 6c2082ef 43283910 6a57a86f 05100201 00000000 00000044 71c1106d d9490a4f f73aa5e3 741e1ef4 f30d3576 1a842e10 25a89743 6dafbbbc aa67e249 97c7eab4
Dec  7 11:56:25 TEST racoon: DEBUG: resend phase1 packet 66a0d6f56c2082ef:432839106a57a86f
Dec  7 11:56:25 TEST racoon: DEBUG: ===
Dec  7 11:56:25 TEST racoon: DEBUG: 84 bytes message received from 195.195.195.195[4500] to 10.1.1.99[4500]
Dec  7 11:56:25 TEST racoon: DEBUG:  66a0d6f5 6c2082ef 43283910 6a57a86f 05100201 00000000 00000054 bc73a297 9daf7ef9 d463323f a1b7cdbf 2b02ebac a9579c87 6efd0cd8 8b1a3e8b 9ed2da5c 9430dc67 afb3fe1a 929918c0 a9bf12cc fee1ec4d
Dec  7 11:56:25 TEST racoon: DEBUG: begin decryption.
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: IV was saved for next processing:
Dec  7 11:56:25 TEST racoon: DEBUG:  a9bf12cc fee1ec4d
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: with key:
Dec  7 11:56:25 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb 523c8d61
Dec  7 11:56:25 TEST racoon: DEBUG: decrypted payload by IV:
Dec  7 11:56:25 TEST racoon: DEBUG:  aa67e249 97c7eab4
Dec  7 11:56:25 TEST racoon: DEBUG: decrypted payload, but not trimed.
Dec  7 11:56:25 TEST racoon: DEBUG:  0800000c 01110000 c3954646 0d000018 3cec26d3 a8b6316a ae978b24 1e7d7f22 0c460ab0 00000014 afcad713 68a1f1c9 6b8696fc 77570100
Dec  7 11:56:25 TEST racoon: DEBUG: padding len=0
Dec  7 11:56:25 TEST racoon: DEBUG: skip to trim padding.
Dec  7 11:56:25 TEST racoon: DEBUG: decrypted.
Dec  7 11:56:25 TEST racoon: DEBUG:  66a0d6f5 6c2082ef 43283910 6a57a86f 05100201 00000000 00000054 0800000c 01110000 c3954646 0d000018 3cec26d3 a8b6316a ae978b24 1e7d7f22 0c460ab0 00000014 afcad713 68a1f1c9 6b8696fc 77570100
Dec  7 11:56:25 TEST racoon: DEBUG: begin.
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=5(id)
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=8(hash)
Dec  7 11:56:25 TEST racoon: DEBUG: seen nptype=13(vid)
Dec  7 11:56:25 TEST racoon: DEBUG: succeed.
Dec  7 11:56:25 TEST racoon: INFO: received Vendor ID: DPD
Dec  7 11:56:25 TEST racoon: DEBUG: remote supports DPD
Dec  7 11:56:25 TEST racoon: WARNING: port 4500 expected, but 0
Dec  7 11:56:25 TEST racoon: DEBUG: HASH received:
Dec  7 11:56:25 TEST racoon: DEBUG:  3cec26d3 a8b6316a ae978b24 1e7d7f22 0c460ab0
Dec  7 11:56:25 TEST racoon: DEBUG: HASH with:
Dec  7 11:56:25 TEST racoon: DEBUG:  0697fd65 ce264b84 8cb6048c c516bbb1 948ffdac ef4af5ec 3e7883c5 eab9c8b2 b12e0b22 3c150d20 0d828fa3 51f489e2 31e53b9c 24165699 678e5239 21738492 4131fc6e edf2a0ef 8e1e402c af22e5c2 f1d1b5a7 f34a0ef0 cd1504b1 0bbf0fe3 53b15f52 6b580443 b8d26365 a15b88e2 c5b6eb8b fa4df061 610ec4bb 2ea60dc2 e9184f2d b4981706 5aa96cee 335bb2b5 f4fae353 7c5f3c53 43ede4d9 95e65b62 33bc95db 8e849470 de82c54a 7d9e4348 b9252661 10f1580f 2342d97d ae753aa2 b937691c 0b2333d7 bb1628d5 80209263 77a22e8e 0f5a4032 3479753f a0c78ce5 f94a213a 72cbe115 d5f22c7f 4364985c 922863c8 e24ca3e7 80a3c35f 56080782 43283910 6a57a86f 66a0d6f5 6c2082ef 00000001 00000001 0000002c 01010001 00000024 01010000 800b0001 000c0004 00015180 80010005 80030001 80020002 80040002 01110000 c3954646[CODE]
```


----------



## yurybx (Dec 7, 2018)

Continued log below:

```
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: HASH (init) computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  3cec26d3 a8b6316a ae978b24 1e7d7f22 0c460ab0
Dec  7 11:56:25 TEST racoon: DEBUG: HASH for PSK validated.
Dec  7 11:56:25 TEST racoon: [195.195.195.195] DEBUG: peer's ID:
Dec  7 11:56:25 TEST racoon: DEBUG:  01110000 c3954646
Dec  7 11:56:25 TEST racoon: DEBUG: ===
Dec  7 11:56:25 TEST racoon: DEBUG: compute IV for phase2
Dec  7 11:56:25 TEST racoon: DEBUG: phase1 last IV:
Dec  7 11:56:25 TEST racoon: DEBUG:  a9bf12cc fee1ec4d a56a4a71
Dec  7 11:56:25 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: phase2 IV computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  9855a169 807eae23
Dec  7 11:56:25 TEST racoon: DEBUG: HASH with:
Dec  7 11:56:25 TEST racoon: DEBUG:  a56a4a71 0000001c 00000001 01106002 66a0d6f5 6c2082ef 43283910 6a57a86f
Dec  7 11:56:25 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:25 TEST racoon: DEBUG: HASH computed:
Dec  7 11:56:25 TEST racoon: DEBUG:  ee476fe3 71fc6042 29857dc4 3b4e706f b1f6e6bf
Dec  7 11:56:25 TEST racoon: DEBUG: begin encryption.
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: pad length = 4
Dec  7 11:56:25 TEST racoon: DEBUG:  0b000018 ee476fe3 71fc6042 29857dc4 3b4e706f b1f6e6bf 0000001c 00000001 01106002 66a0d6f5 6c2082ef 43283910 6a57a86f 00000004
Dec  7 11:56:25 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:25 TEST racoon: DEBUG: with key:
Dec  7 11:56:25 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb 523c8d61
Dec  7 11:56:25 TEST racoon: DEBUG: encrypted payload by IV:
Dec  7 11:56:25 TEST racoon: DEBUG:  9855a169 807eae23
Dec  7 11:56:25 TEST racoon: DEBUG: save IV for next:
Dec  7 11:56:25 TEST racoon: DEBUG:  ab70857f 4f2e5841
Dec  7 11:56:25 TEST racoon: DEBUG: encrypted.
Dec  7 11:56:25 TEST racoon: DEBUG: Adding NON-ESP marker
Dec  7 11:56:25 TEST racoon: DEBUG: 88 bytes from 10.1.1.99[4500] to 195.195.195.195[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: sockname 10.1.1.99[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: send packet from 10.1.1.99[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: send packet to 195.195.195.195[4500]
Dec  7 11:56:25 TEST racoon: DEBUG: 1 times of 88 bytes message will be sent to 195.195.195.195[4500]
Dec  7 11:56:25 TEST racoon: DEBUG:  00000000 66a0d6f5 6c2082ef 43283910 6a57a86f 08100501 a56a4a71 00000054 ca83e8c5 0a88ba34 242e21ec 3645f311 596f13ab 90775797 5d7df361 50164373 7b361436 3995bba3 c2feab40 afb49268 ab70857f 4f2e5841
Dec  7 11:56:25 TEST racoon: DEBUG: sendto Information notify.
Dec  7 11:56:25 TEST racoon: DEBUG: IV freed
Dec  7 11:56:25 TEST racoon: INFO: ISAKMP-SA established 10.1.1.99[4500]-195.195.195.195[4500] spi:66a0d6f56c2082ef:432839106a57a86f
Dec  7 11:56:25 TEST racoon: DEBUG: ===
Dec  7 11:56:26 TEST racoon: DEBUG2: getph1: start
Dec  7 11:56:26 TEST racoon: DEBUG2: local: 10.1.1.99[0]
Dec  7 11:56:26 TEST racoon: DEBUG2: remote: 195.195.195.195[1701]
Dec  7 11:56:26 TEST racoon: DEBUG2: p->local: 10.1.1.99[4500]
Dec  7 11:56:26 TEST racoon: DEBUG2: p->remote: 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG2: matched
Dec  7 11:56:26 TEST racoon: DEBUG2: CHKPH1THERE: got a ph1 handler, setting ports.
Dec  7 11:56:26 TEST racoon: DEBUG2: iph1->local: 10.1.1.99[4500]
Dec  7 11:56:26 TEST racoon: DEBUG2: iph1->remote: 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG2: before:
Dec  7 11:56:26 TEST racoon: DEBUG2: src: 10.1.1.99[0]
Dec  7 11:56:26 TEST racoon: DEBUG2: dst: 195.195.195.195[1701]
Dec  7 11:56:26 TEST racoon: DEBUG2: After:
Dec  7 11:56:26 TEST racoon: DEBUG2: src: 10.1.1.99[4500]
Dec  7 11:56:26 TEST racoon: DEBUG2: dst: 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: ===
Dec  7 11:56:26 TEST racoon: DEBUG: begin QUICK mode.
Dec  7 11:56:26 TEST racoon: INFO: initiate new phase 2 negotiation: 10.1.1.99[4500]<=>195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: compute IV for phase2
Dec  7 11:56:26 TEST racoon: DEBUG: phase1 last IV:
Dec  7 11:56:26 TEST racoon: DEBUG:  a9bf12cc fee1ec4d ad087870
Dec  7 11:56:26 TEST racoon: DEBUG: hash(sha1)
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: phase2 IV computed:
Dec  7 11:56:26 TEST racoon: DEBUG:  50119056 8a6810ae
Dec  7 11:56:26 TEST racoon: DEBUG: call pfkey_send_getspi
Dec  7 11:56:26 TEST racoon: DEBUG: pfkey GETSPI sent: ESP/Transport 195.195.195.195[1701]->10.1.1.99[0]
Dec  7 11:56:26 TEST racoon: DEBUG: pfkey getspi sent.
Dec  7 11:56:26 TEST racoon: DEBUG: pk_recv: retry[0] recv()
Dec  7 11:56:26 TEST racoon: DEBUG: got pfkey GETSPI message
Dec  7 11:56:26 TEST racoon: DEBUG2:  02010003 0a000000 02000000 e3020000 02000100 069ed33d 00000000 00000000 03000500 ff200000 10020000 c3954646 00000000 00000000 03000600 ff200000 10020000 0a010163 00000000 00000000
Dec  7 11:56:26 TEST racoon: DEBUG: pfkey GETSPI succeeded: ESP/Transport 195.195.195.195[500]->10.1.1.99[500] spi=111072061(0x69ed33d)
Dec  7 11:56:26 TEST racoon: INFO: NAT detected -> UDP encapsulation (ENC_MODE 2->4).
Dec  7 11:56:26 TEST racoon: DEBUG: use local ID type IPv4_address
Dec  7 11:56:26 TEST racoon: DEBUG: use remote ID type IPv4_address
Dec  7 11:56:26 TEST racoon: DEBUG: IDci:
Dec  7 11:56:26 TEST racoon: DEBUG:  01110000 0a010163
Dec  7 11:56:26 TEST racoon: DEBUG: IDcr:
Dec  7 11:56:26 TEST racoon: DEBUG:  011106a5 c3954646
Dec  7 11:56:26 TEST racoon: DEBUG: NAT-OAi:
Dec  7 11:56:26 TEST racoon: DEBUG:  01001194 0a010163
Dec  7 11:56:26 TEST racoon: DEBUG: NAT-OAr:
Dec  7 11:56:26 TEST racoon: DEBUG:  01001194 c3954646
Dec  7 11:56:26 TEST racoon: DEBUG: add payload of len 68, next type 10
Dec  7 11:56:26 TEST racoon: DEBUG: add payload of len 16, next type 5
Dec  7 11:56:26 TEST racoon: DEBUG: add payload of len 8, next type 5
Dec  7 11:56:26 TEST racoon: DEBUG: add payload of len 8, next type 21
Dec  7 11:56:26 TEST racoon: DEBUG: add payload of len 8, next type 21
Dec  7 11:56:26 TEST racoon: DEBUG: add payload of len 8, next type 0
Dec  7 11:56:26 TEST racoon: DEBUG: HASH with:
Dec  7 11:56:26 TEST racoon: DEBUG:  ad087870 0a000048 00000001 00000001 0000003c 01030402 069ed33d 03000018 01030000 80010001 80020e10 80040004 80050001 00000018 02030000 80010001 80020e10 80040004 80050002 05000014 f1efcd01 dc986ec6 a38945ea 95c18e7d 0500000c 01110000 0a010163 1500000c 011106a5 c3954646 1500000c 01001194 0a010163 0000000c 01001194 c3954646
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:26 TEST racoon: DEBUG: HASH computed:
Dec  7 11:56:26 TEST racoon: DEBUG:  fedff7c0 327279dd a4b762b3 c554a3df ff68cc78
Dec  7 11:56:26 TEST racoon: DEBUG: add payload of len 20, next type 1
Dec  7 11:56:26 TEST racoon: DEBUG: begin encryption.
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: pad length = 4
Dec  7 11:56:26 TEST racoon: DEBUG:  01000018 fedff7c0 327279dd a4b762b3 c554a3df ff68cc78 0a000048 00000001 00000001 0000003c 01030402 069ed33d 03000018 01030000 80010001 80020e10 80040004 80050001 00000018 02030000 80010001 80020e10 80040004 80050002 05000014 f1efcd01 dc986ec6 a38945ea 95c18e7d 0500000c 01110000 0a010163 1500000c 011106a5 c3954646 1500000c 01001194 0a010163 0000000c 01001194 c3954646 00000004
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: with key:
Dec  7 11:56:26 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb 523c8d61
Dec  7 11:56:26 TEST racoon: DEBUG: encrypted payload by IV:
Dec  7 11:56:26 TEST racoon: DEBUG:  50119056 8a6810ae
Dec  7 11:56:26 TEST racoon: DEBUG: save IV for next:
Dec  7 11:56:26 TEST racoon: DEBUG:  442cb78f 7dc088bc
Dec  7 11:56:26 TEST racoon: DEBUG: encrypted.
Dec  7 11:56:26 TEST racoon: DEBUG: Adding NON-ESP marker
Dec  7 11:56:26 TEST racoon: DEBUG: 200 bytes from 10.1.1.99[4500] to 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: sockname 10.1.1.99[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: send packet from 10.1.1.99[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: send packet to 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: 1 times of 200 bytes message will be sent to 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG:  00000000 66a0d6f5 6c2082ef 43283910 6a57a86f 08102001 ad087870 000000c4 416ad346 e44bbf3b 355b28c7 3eb6e21a e3173727 2d7ec71b 1457ddf8 157a5a2a 6415fdb1 4ac6c2b6 6fac8876 0ca7c384 d0cf549c db77a9bb 1744ab0d abe9c664 b80bd6dd 59aa6597 3ae1a19c 6cdfd4d6 fab2003e fa3dc51f adfbdfd2 c4cd1133 44f5ea6f 52230203 5bb6fdea 240cd64b 5f13b1fe ab20ce59 73eaeea2 5ee9c66f 2556b949 25d2f839 61a4bc73 02f6f091 86164358 ffc0dd9c 54247feb 9c94c361 442cb78f 7dc088bc
Dec  7 11:56:26 TEST racoon: DEBUG: resend phase2 packet 66a0d6f56c2082ef:432839106a57a86f:0000ad08
Dec  7 11:56:26 TEST racoon: DEBUG: ===
Dec  7 11:56:26 TEST racoon: DEBUG: 172 bytes message received from 195.195.195.195[4500] to 10.1.1.99[4500]
Dec  7 11:56:26 TEST racoon: DEBUG:  66a0d6f5 6c2082ef 43283910 6a57a86f 08102001 ad087870 000000ac f1c0791e 6f3b6ed6 2cb34ee4 a902ca65 c5d1e81c 59a7ca50 1dd39f3f 88ad1dca 515edf17 fd3156a4 0da00de9 eb62861b cb75b544 1064325b c6db98ad 075e581d 64af9098 601e6599 a57765b6 447b336f e801d7e9 735bb9f6 436f74c3 e89e7c2a 27f094a2 c740b118 78ddea96 3d1b32e8 19dfb133 858a62f4 cda4a092 878b5ad5 367f38e2 128523b0 c69d5d05 4fdf1461
Dec  7 11:56:26 TEST racoon: DEBUG: begin decryption.
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: IV was saved for next processing:
Dec  7 11:56:26 TEST racoon: DEBUG:  c69d5d05 4fdf1461
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: with key:
Dec  7 11:56:26 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb 523c8d61
Dec  7 11:56:26 TEST racoon: DEBUG: decrypted payload by IV:
Dec  7 11:56:26 TEST racoon: DEBUG:  442cb78f 7dc088bc
Dec  7 11:56:26 TEST racoon: DEBUG: decrypted payload, but not trimed.
Dec  7 11:56:26 TEST racoon: DEBUG:  01000018 df3a62f7 2ae8434e d3bc9f40 c6178dc8 07762504 0a000030 00000001 00000001 00000024 01030401 529acb9c 00000018 01030000 80010001 80020e10 80040004 80050001 05000018 b216bb93 ab0d0d93 38ec3843 26a8079c 85806d9a 0500000c 01110000 5b8ea122 1500000c 011106a5 c3954646 1500000c 01000000 5b8ea122 0000000c 01000000 c3954646
Dec  7 11:56:26 TEST racoon: DEBUG: padding len=70
Dec  7 11:56:26 TEST racoon: DEBUG: skip to trim padding.
Dec  7 11:56:26 TEST racoon: DEBUG: decrypted.
Dec  7 11:56:26 TEST racoon: DEBUG:  66a0d6f5 6c2082ef 43283910 6a57a86f 08102001 ad087870 000000ac 01000018 df3a62f7 2ae8434e d3bc9f40 c6178dc8 07762504 0a000030 00000001 00000001 00000024 01030401 529acb9c 00000018 01030000 80010001 80020e10 80040004 80050001 05000018 b216bb93 ab0d0d93 38ec3843 26a8079c 85806d9a 0500000c 01110000 5b8ea122 1500000c 011106a5 c3954646 1500000c 01000000 5b8ea122 0000000c 01000000 c3954646
Dec  7 11:56:26 TEST racoon: DEBUG: begin.
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=8(hash)
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=1(sa)
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=10(nonce)
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=5(id)
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=5(id)
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=21(nat-oa)
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=21(nat-oa)
Dec  7 11:56:26 TEST racoon: DEBUG: succeed.
Dec  7 11:56:26 TEST racoon: DEBUG: IDci matches NAT-OAi.
Dec  7 11:56:26 TEST racoon: DEBUG: IDcr matches proposal.
Dec  7 11:56:26 TEST racoon: DEBUG: HASH allocated:hbuf->l=160 actual:tlen=136
Dec  7 11:56:26 TEST racoon: DEBUG: HASH(2) received:
Dec  7 11:56:26 TEST racoon: DEBUG:  df3a62f7 2ae8434e d3bc9f40 c6178dc8 07762504
Dec  7 11:56:26 TEST racoon: DEBUG: HASH with:
Dec  7 11:56:26 TEST racoon: DEBUG:  ad087870 f1efcd01 dc986ec6 a38945ea 95c18e7d 0a000030 00000001 00000001 00000024 01030401 529acb9c 00000018 01030000 80010001 80020e10 80040004 80050001 05000018 b216bb93 ab0d0d93 38ec3843 26a8079c 85806d9a 0500000c 01110000 5b8ea122 1500000c 011106a5 c3954646 1500000c 01000000 5b8ea122 0000000c 01000000 c3954646
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:26 TEST racoon: DEBUG: HASH computed:
Dec  7 11:56:26 TEST racoon: DEBUG:  df3a62f7 2ae8434e d3bc9f40 c6178dc8 07762504
Dec  7 11:56:26 TEST racoon: DEBUG: total SA len=68
Dec  7 11:56:26 TEST racoon: DEBUG:  00000001 00000001 0000003c 01030402 069ed33d 03000018 01030000 80010001 80020e10 80040004 80050001 00000018 02030000 80010001 80020e10 80040004 80050002
Dec  7 11:56:26 TEST racoon: DEBUG: begin.
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=2(prop)
Dec  7 11:56:26 TEST racoon: DEBUG: succeed.
Dec  7 11:56:26 TEST racoon: DEBUG: proposal #1 len=60
Dec  7 11:56:26 TEST racoon: DEBUG: begin.
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=3(trns)
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=3(trns)
Dec  7 11:56:26 TEST racoon: DEBUG: succeed.
Dec  7 11:56:26 TEST racoon: DEBUG: transform #1 len=24
Dec  7 11:56:26 TEST racoon: DEBUG: type=SA Life Type, flag=0x8000, lorv=seconds
Dec  7 11:56:26 TEST racoon: DEBUG: type=SA Life Duration, flag=0x8000, lorv=3600
Dec  7 11:56:26 TEST racoon: DEBUG: life duration was in TLV.
Dec  7 11:56:26 TEST racoon: DEBUG: type=Encryption Mode, flag=0x8000, lorv=UDP-Transport
Dec  7 11:56:26 TEST racoon: DEBUG: UDP encapsulation requested
Dec  7 11:56:26 TEST racoon: DEBUG: type=Authentication Algorithm, flag=0x8000, lorv=hmac-md5
Dec  7 11:56:26 TEST racoon: DEBUG: transform #2 len=24
Dec  7 11:56:26 TEST racoon: DEBUG: type=SA Life Type, flag=0x8000, lorv=seconds
Dec  7 11:56:26 TEST racoon: DEBUG: type=SA Life Duration, flag=0x8000, lorv=3600
Dec  7 11:56:26 TEST racoon: DEBUG: life duration was in TLV.
Dec  7 11:56:26 TEST racoon: DEBUG: type=Encryption Mode, flag=0x8000, lorv=UDP-Transport
Dec  7 11:56:26 TEST racoon: DEBUG: UDP encapsulation requested
Dec  7 11:56:26 TEST racoon: DEBUG: type=Authentication Algorithm, flag=0x8000, lorv=hmac-sha
Dec  7 11:56:26 TEST racoon: DEBUG: pair 1:
Dec  7 11:56:26 TEST racoon: DEBUG:  0x802024e60: next=0x0 tnext=0x802024e80
Dec  7 11:56:26 TEST racoon: DEBUG:   0x802024e80: next=0x0 tnext=0x0
Dec  7 11:56:26 TEST racoon: DEBUG: proposal #1: 2 transform
Dec  7 11:56:26 TEST racoon: DEBUG: total SA len=44
Dec  7 11:56:26 TEST racoon: DEBUG:  00000001 00000001 00000024 01030401 529acb9c 00000018 01030000 80010001 80020e10 80040004 80050001
Dec  7 11:56:26 TEST racoon: DEBUG: begin.
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=2(prop)
Dec  7 11:56:26 TEST racoon: DEBUG: succeed.
Dec  7 11:56:26 TEST racoon: DEBUG: proposal #1 len=36
Dec  7 11:56:26 TEST racoon: DEBUG: begin.
Dec  7 11:56:26 TEST racoon: DEBUG: seen nptype=3(trns)
Dec  7 11:56:26 TEST racoon: DEBUG: succeed.
Dec  7 11:56:26 TEST racoon: DEBUG: transform #1 len=24
Dec  7 11:56:26 TEST racoon: DEBUG: type=SA Life Type, flag=0x8000, lorv=seconds
Dec  7 11:56:26 TEST racoon: DEBUG: type=SA Life Duration, flag=0x8000, lorv=3600
Dec  7 11:56:26 TEST racoon: DEBUG: life duration was in TLV.
Dec  7 11:56:26 TEST racoon: DEBUG: type=Encryption Mode, flag=0x8000, lorv=UDP-Transport
Dec  7 11:56:26 TEST racoon: DEBUG: UDP encapsulation requested
Dec  7 11:56:26 TEST racoon: DEBUG: type=Authentication Algorithm, flag=0x8000, lorv=hmac-md5
Dec  7 11:56:26 TEST racoon: DEBUG: pair 1:
Dec  7 11:56:26 TEST racoon: DEBUG:  0x802024ea0: next=0x0 tnext=0x0
Dec  7 11:56:26 TEST racoon: DEBUG: proposal #1: 1 transform
Dec  7 11:56:26 TEST racoon: DEBUG: begin compare proposals.
Dec  7 11:56:26 TEST racoon: DEBUG: pair[1]: 0x802024ea0
Dec  7 11:56:26 TEST racoon: DEBUG:  0x802024ea0: next=0x0 tnext=0x0
Dec  7 11:56:26 TEST racoon: DEBUG: prop#=1 prot-id=ESP spi-size=4 #trns=1 trns#=1 trns-id=3DES
Dec  7 11:56:26 TEST racoon: DEBUG: type=SA Life Type, flag=0x8000, lorv=seconds
Dec  7 11:56:26 TEST racoon: DEBUG: type=SA Life Duration, flag=0x8000, lorv=3600
Dec  7 11:56:26 TEST racoon: DEBUG: type=Encryption Mode, flag=0x8000, lorv=UDP-Transport
Dec  7 11:56:26 TEST racoon: DEBUG: type=Authentication Algorithm, flag=0x8000, lorv=hmac-md5
Dec  7 11:56:26 TEST racoon: DEBUG: peer's single bundle:
Dec  7 11:56:26 TEST racoon: DEBUG:  (proto_id=ESP spisize=4 spi=529acb9c spi_p=00000000 encmode=UDP-Transport reqid=0:0)
Dec  7 11:56:26 TEST racoon: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-md5)
Dec  7 11:56:26 TEST racoon: DEBUG: my single bundle:
Dec  7 11:56:26 TEST racoon: DEBUG:  (proto_id=ESP spisize=4 spi=069ed33d spi_p=00000000 encmode=UDP-Transport reqid=0:0)
Dec  7 11:56:26 TEST racoon: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-md5)
Dec  7 11:56:26 TEST racoon: DEBUG:   (trns_id=3DES encklen=0 authtype=hmac-sha)
Dec  7 11:56:26 TEST racoon: INFO: Adjusting my encmode UDP-Transport->Transport
Dec  7 11:56:26 TEST racoon: INFO: Adjusting peer's encmode UDP-Transport(4)->Transport(2)
Dec  7 11:56:26 TEST racoon: DEBUG: matched
Dec  7 11:56:26 TEST racoon: DEBUG: ===
Dec  7 11:56:26 TEST racoon: DEBUG: HASH(3) generate
Dec  7 11:56:26 TEST racoon: DEBUG: HASH with:
Dec  7 11:56:26 TEST racoon: DEBUG:  00ad0878 70f1efcd 01dc986e c6a38945 ea95c18e 7db216bb 93ab0d0d 9338ec38 4326a807 9c85806d 9a
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:26 TEST racoon: DEBUG: HASH computed:
Dec  7 11:56:26 TEST racoon: DEBUG:  a9698dc7 b2e3c64f c5fe4142 8468e14f dd524166
Dec  7 11:56:26 TEST racoon: DEBUG: add payload of len 20, next type 0
Dec  7 11:56:26 TEST racoon: DEBUG: begin encryption.
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: pad length = 8
Dec  7 11:56:26 TEST racoon: DEBUG:  00000018 a9698dc7 b2e3c64f c5fe4142 8468e14f dd524166 00000000 00000008
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: with key:
Dec  7 11:56:26 TEST racoon: DEBUG:  48377391 0973c37c d4555ce2 0b903861 4bea38fb 523c8d61
Dec  7 11:56:26 TEST racoon: DEBUG: encrypted payload by IV:
Dec  7 11:56:26 TEST racoon: DEBUG:  c69d5d05 4fdf1461
Dec  7 11:56:26 TEST racoon: DEBUG: save IV for next:
Dec  7 11:56:26 TEST racoon: DEBUG:  275d6a62 bb370fc0
Dec  7 11:56:26 TEST racoon: DEBUG: encrypted.
Dec  7 11:56:26 TEST racoon: DEBUG: Adding NON-ESP marker
Dec  7 11:56:26 TEST racoon: DEBUG: 64 bytes from 10.1.1.99[4500] to 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: sockname 10.1.1.99[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: send packet from 10.1.1.99[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: send packet to 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG: 1 times of 64 bytes message will be sent to 195.195.195.195[4500]
Dec  7 11:56:26 TEST racoon: DEBUG:  00000000 66a0d6f5 6c2082ef 43283910 6a57a86f 08102001 ad087870 0000003c 320340b9 c90e4c8f 942997b8 d18ce012 91bd8228 efeb943d 275d6a62 bb370fc0
Dec  7 11:56:26 TEST racoon: DEBUG: KEYMAT compute with
Dec  7 11:56:26 TEST racoon: DEBUG:  03069ed3 3df1efcd 01dc986e c6a38945 ea95c18e 7db216bb 93ab0d0d 9338ec38 4326a807 9c85806d 9a
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(md5)
Dec  7 11:56:26 TEST racoon: DEBUG: encklen=192 authklen=128
Dec  7 11:56:26 TEST racoon: DEBUG: generating 640 bits of key (dupkeymat=4)
Dec  7 11:56:26 TEST racoon: DEBUG: generating K1...K4 for KEYMAT.
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:26 TEST last message repeated 2 times
Dec  7 11:56:26 TEST racoon: DEBUG:  ae3b0e40 58333956 46216eb7 93a933c7 b6bd3e7b 8e65f680 1003741b 776ba84b aa920285 4a96627e c0e397b3 daab24b3 d2955da7 83f8f8bb b673b1b3 b0b00bb9 f1c97350 7f6b4965 362ec790 ad924318
Dec  7 11:56:26 TEST racoon: DEBUG: KEYMAT compute with
Dec  7 11:56:26 TEST racoon: DEBUG:  03529acb 9cf1efcd 01dc986e c6a38945 ea95c18e 7db216bb 93ab0d0d 9338ec38 4326a807 9c85806d 9a
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(md5)
Dec  7 11:56:26 TEST racoon: DEBUG: encklen=192 authklen=128
Dec  7 11:56:26 TEST racoon: DEBUG: generating 640 bits of key (dupkeymat=4)
Dec  7 11:56:26 TEST racoon: DEBUG: generating K1...K4 for KEYMAT.
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(hmac_sha1)
Dec  7 11:56:26 TEST last message repeated 2 times
Dec  7 11:56:26 TEST racoon: DEBUG:  cdc36fa3 f04efaaa 86a8ae8c f2c74edb e4b474eb 0a5966db 282c0b73 af4748bf a127357c 1a53c731 4b197262 5601d61a b548bcd4 d83e6655 05a78a20 8f2a2595 7c24127f 046b3d47 85d97741 8a80ea65
Dec  7 11:56:26 TEST racoon: DEBUG: KEYMAT computed.
Dec  7 11:56:26 TEST racoon: DEBUG: call pk_sendupdate
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(md5)
Dec  7 11:56:26 TEST racoon: DEBUG: call pfkey_send_update2
Dec  7 11:56:26 TEST racoon: DEBUG: pfkey update sent.
Dec  7 11:56:26 TEST racoon: DEBUG: encryption(3des)
Dec  7 11:56:26 TEST racoon: DEBUG: hmac(md5)
Dec  7 11:56:26 TEST racoon: DEBUG: call pfkey_send_add2 (NAT flavor)
Dec  7 11:56:26 TEST racoon: DEBUG: call pfkey_send_add2
Dec  7 11:56:26 TEST racoon: DEBUG: pfkey add sent.
Dec  7 11:56:26 TEST racoon: DEBUG: pk_recv: retry[0] recv()
Dec  7 11:56:26 TEST racoon: DEBUG: got pfkey UPDATE message
Dec  7 11:56:26 TEST racoon: DEBUG2:  02020003 14000000 02000000 e3020000 02000100 069ed33d 04000203 00000000 02001300 01000000 00000000 00000000 03000500 ff200000 100206a5 c3954646 00000000 00000000 03000600 ff200000 10020000 0a010163 00000000 00000000 04000300 00000000 00000000 00000000 100e0000 00000000 00000000 00000000 04000400 00000000 00000000 00000000 400b0000 00000000 00000000 00000000
Dec  7 11:56:26 TEST racoon: DEBUG: pfkey UPDATE succeeded: ESP/Transport 10.1.1.99[500]->195.195.195.195[500] spi=111072061(0x69ed33d)
Dec  7 11:56:26 TEST racoon: INFO: IPsec-SA established: ESP/Transport 10.1.1.99[500]->195.195.195.195[500] spi=111072061(0x69ed33d)
Dec  7 11:56:26 TEST racoon: DEBUG: ===
Dec  7 11:56:26 TEST racoon: DEBUG: pk_recv: retry[0] recv()
Dec  7 11:56:26 TEST racoon: DEBUG: got pfkey ADD message
Dec  7 11:56:26 TEST racoon: DEBUG2:  02030003 14000000 02000000 e3020000 02000100 529acb9c 04000203 00000000 02001300 01000000 00000000 00000000 03000500 ff200000 10020000 0a010163 00000000 00000000 03000600 ff200000 100206a5 c3954646 00000000 00000000 04000300 00000000 00000000 00000000 100e0000 00000000 00000000 00000000 04000400 00000000 00000000 00000000 400b0000 00000000 00000000 00000000
Dec  7 11:56:26 TEST racoon: INFO: IPsec-SA established: ESP/Transport 10.1.1.99[500]->195.195.195.195[500] spi=1385876380(0x529acb9c)
Dec  7 11:56:26 TEST racoon: DEBUG: ===
Dec  7 11:56:40 TEST racoon: DEBUG: KA: 10.1.1.99[4500]->195.195.195.195[4500]
Dec  7 11:56:40 TEST racoon: DEBUG: sockname 10.1.1.99[4500]
Dec  7 11:56:40 TEST racoon: DEBUG: send packet from 10.1.1.99[4500]
Dec  7 11:56:40 TEST racoon: DEBUG: send packet to 195.195.195.195[4500]
Dec  7 11:56:40 TEST racoon: DEBUG: 1 times of 1 bytes message will be sent to 195.195.195.195[4500]
Dec  7 11:56:40 TEST racoon: DEBUG:  ff
```


----------



## obsigna (Dec 7, 2018)

Seems that racoon the successful ESP cipher utilizes MD5 as the hash algorithm. Please try again with the following directives in ipsec.conf(5):
ike = 3des-sha1-modp1024
esp = 3des-md5-modp1024

The man file says that in the case of IKEv1 we may place only 1 cipher per directive. Also don’t use the exclamation mark because this prevents strongSwan to agree on another proposal than the configured one.


----------



## yurybx (Dec 8, 2018)

It's funny! In fact, it was enough to enter "ipsec.conf" cisco into Google (in the strongswan logs we can see that the IPSec server is a Cisco) and follow the first link! Here I am noodle!
In short, my connection is now established successfully with the following parameters:

```
ike=aes128-sha1-modp1024
esp=aes128-sha1
```
But! I return to where I came from: the L2TP connection still breaks immediately after it is established. At least I now know that racoon is not to blame. How to understand the reason? Let me remind you that the connection works properly in Windows.
Here is the MPD's log:

```
Dec  8 19:00:12 TEST mpd: [B1] Bundle: Interface ng0 created
Dec  8 19:00:12 TEST mpd: [L1] Link: OPEN event
Dec  8 19:00:12 TEST mpd: [L1] LCP: Open event
Dec  8 19:00:12 TEST mpd: [L1] LCP: state change Initial --> Starting
Dec  8 19:00:12 TEST mpd: [L1] LCP: LayerStart
Dec  8 19:00:12 TEST mpd: L2TP: Initiating control connection 0x803073610 0.0.0.0 0 <-> 195.195.195.195 1701
Dec  8 19:00:12 TEST mpd: L2TP: Control connection 0x803073610 10.1.1.99 13812 <-> 195.195.195.195 1701 connected
Dec  8 19:00:12 TEST mpd: [L1] L2TP: Incoming call #6990000 via control connection 0x803073610 initiated
Dec  8 19:00:12 TEST mpd: [L1] L2TP: Call #6990000 connected
Dec  8 19:00:12 TEST mpd: [L1] Link: UP event
Dec  8 19:00:12 TEST mpd: [L1] LCP: Up event
Dec  8 19:00:12 TEST mpd: [L1] LCP: state change Starting --> Req-Sent
Dec  8 19:00:12 TEST mpd: [L1] LCP: SendConfigReq #1
Dec  8 19:00:12 TEST mpd: [L1]   ACFCOMP
Dec  8 19:00:12 TEST mpd: [L1]   PROTOCOMP
Dec  8 19:00:12 TEST mpd: [L1]   MRU 1500
Dec  8 19:00:12 TEST mpd: [L1]   MAGICNUM 0xc99f7a37
Dec  8 19:00:12 TEST mpd: [L1] LCP: rec'd Configure Request #1 (Req-Sent)
Dec  8 19:00:12 TEST mpd: [L1]   AUTHPROTO CHAP MSOFTv2
Dec  8 19:00:12 TEST mpd: [L1]   MAGICNUM 0x2e156187
Dec  8 19:00:12 TEST mpd: [L1] LCP: SendConfigAck #1
Dec  8 19:00:12 TEST mpd: [L1]   AUTHPROTO CHAP MSOFTv2
Dec  8 19:00:12 TEST mpd: [L1]   MAGICNUM 0x2e156187
Dec  8 19:00:12 TEST mpd: [L1] LCP: state change Req-Sent --> Ack-Sent
Dec  8 19:00:12 TEST mpd: [L1] LCP: rec'd Configure Reject #1 (Ack-Sent)
Dec  8 19:00:12 TEST mpd: [L1]   ACFCOMP
Dec  8 19:00:12 TEST mpd: [L1]   PROTOCOMP
Dec  8 19:00:12 TEST mpd: [L1]   MRU 1500
Dec  8 19:00:12 TEST mpd: [L1] LCP: SendConfigReq #2
Dec  8 19:00:12 TEST mpd: [L1]   MAGICNUM 0xc99f7a37
Dec  8 19:00:12 TEST mpd: [L1] LCP: rec'd Configure Ack #2 (Ack-Sent)
Dec  8 19:00:12 TEST mpd: [L1]   MAGICNUM 0xc99f7a37
Dec  8 19:00:12 TEST mpd: [L1] LCP: state change Ack-Sent --> Opened
Dec  8 19:00:12 TEST mpd: [L1] LCP: auth: peer wants CHAP, I want nothing
Dec  8 19:00:12 TEST mpd: [L1] LCP: LayerUp
Dec  8 19:00:12 TEST mpd: [L1] CHAP: rec'd CHALLENGE #1 len: 21
Dec  8 19:00:12 TEST mpd: [L1]   Name: ""
Dec  8 19:00:12 TEST mpd: [L1] CHAP: Using authname "mylogin"
Dec  8 19:00:12 TEST mpd: [L1] CHAP: sending RESPONSE #1 len: 61
Dec  8 19:00:12 TEST mpd: [L1] CHAP: rec'd SUCCESS #1 len: 46
Dec  8 19:00:12 TEST mpd: [L1]   MESG: S=3D47260EC1C1A7ECD65D4D984782100A76C23C64
Dec  8 19:00:12 TEST mpd: [L1] LCP: authorization successful
Dec  8 19:00:12 TEST mpd: [L1] Link: Matched action 'bundle "B1" ""'
Dec  8 19:00:12 TEST mpd: [L1] Link: Join bundle "B1"
Dec  8 19:00:12 TEST mpd: [B1] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Dec  8 19:00:12 TEST mpd: [B1] IPCP: Open event
Dec  8 19:00:12 TEST mpd: [B1] IPCP: state change Initial --> Starting
Dec  8 19:00:12 TEST mpd: [B1] IPCP: LayerStart
Dec  8 19:00:12 TEST mpd: [B1] IPCP: Up event
Dec  8 19:00:12 TEST mpd: [B1] IPCP: state change Starting --> Req-Sent
Dec  8 19:00:12 TEST mpd: [B1] IPCP: SendConfigReq #1
Dec  8 19:00:12 TEST mpd: [B1]   IPADDR 10.1.1.99
Dec  8 19:00:12 TEST mpd: [B1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Dec  8 19:00:12 TEST mpd: [B1] IPCP: rec'd Configure Request #1 (Req-Sent)
Dec  8 19:00:12 TEST mpd: [B1]   IPADDR 195.195.195.195
Dec  8 19:00:12 TEST mpd: [B1]     195.195.195.195 is OK
Dec  8 19:00:12 TEST mpd: [B1] IPCP: SendConfigAck #1
Dec  8 19:00:12 TEST mpd: [B1]   IPADDR 195.195.195.195
Dec  8 19:00:12 TEST mpd: [B1] IPCP: state change Req-Sent --> Ack-Sent
Dec  8 19:00:12 TEST mpd: [B1] IPCP: rec'd Configure Reject #1 (Ack-Sent)
Dec  8 19:00:12 TEST mpd: [B1]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Dec  8 19:00:12 TEST mpd: [B1] IPCP: SendConfigReq #2
Dec  8 19:00:12 TEST mpd: [B1]   IPADDR 10.1.1.99
Dec  8 19:00:12 TEST mpd: [B1] IPCP: rec'd Configure Nak #2 (Ack-Sent)
Dec  8 19:00:12 TEST mpd: [B1]   IPADDR 10.10.181.222
Dec  8 19:00:12 TEST mpd: [B1]     10.10.181.222 is OK
Dec  8 19:00:12 TEST mpd: [B1] IPCP: SendConfigReq #3
Dec  8 19:00:12 TEST mpd: [B1]   IPADDR 10.10.181.222
Dec  8 19:00:12 TEST mpd: [B1] IPCP: rec'd Configure Ack #3 (Ack-Sent)
Dec  8 19:00:12 TEST mpd: [B1]   IPADDR 10.10.181.222
Dec  8 19:00:12 TEST mpd: [B1] IPCP: state change Ack-Sent --> Opened
Dec  8 19:00:12 TEST mpd: [B1] IPCP: LayerUp
Dec  8 19:00:12 TEST mpd: [B1]   10.10.181.222 -> 195.195.195.195
Dec  8 19:00:12 TEST mpd: [B1] IFACE: Up event
Dec  8 19:01:12 TEST mpd: [L1] LCP: no reply to 1 echo request(s)
Dec  8 19:01:32 TEST mpd: [L1] LCP: no reply to 2 echo request(s)
Dec  8 19:01:52 TEST mpd: [L1] LCP: no reply to 3 echo request(s)
Dec  8 19:01:52 TEST mpd: [L1] LCP: peer not responding to echo requests
Dec  8 19:01:52 TEST mpd: [L1] LCP: state change Opened --> Stopping
Dec  8 19:01:52 TEST mpd: [L1] Link: Leave bundle "B1"
Dec  8 19:01:52 TEST mpd: [B1] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Dec  8 19:01:52 TEST mpd: [B1] IPCP: Close event
Dec  8 19:01:52 TEST mpd: [B1] IPCP: state change Opened --> Closing
Dec  8 19:01:52 TEST mpd: [B1] IPCP: SendTerminateReq #4
Dec  8 19:01:52 TEST mpd: [B1] IPCP: LayerDown
Dec  8 19:01:52 TEST mpd: [B1] IFACE: Down event
Dec  8 19:01:52 TEST mpd: [B1] IPCP: Down event
Dec  8 19:01:52 TEST mpd: [B1] IPCP: LayerFinish
Dec  8 19:01:52 TEST mpd: [B1] Bundle: No NCPs left. Closing links...
Dec  8 19:01:52 TEST mpd: [B1] IPCP: state change Closing --> Initial
Dec  8 19:01:52 TEST mpd: [L1] LCP: SendTerminateReq #3
Dec  8 19:01:52 TEST mpd: [L1] LCP: LayerDown
Dec  8 19:01:54 TEST mpd: [L1] LCP: SendTerminateReq #4
Dec  8 19:01:56 TEST mpd: [L1] LCP: state change Stopping --> Stopped
Dec  8 19:01:56 TEST mpd: [L1] LCP: LayerFinish
Dec  8 19:01:56 TEST mpd: [L1] L2TP: Call #6990000 terminated locally
Dec  8 19:01:56 TEST mpd: [L1] Link: DOWN event
Dec  8 19:01:56 TEST mpd: [L1] LCP: Down event
Dec  8 19:01:56 TEST mpd: [L1] LCP: state change Stopped --> Starting
Dec  8 19:01:56 TEST mpd: [L1] LCP: LayerStart
Dec  8 19:01:56 TEST mpd: [L1] Link: reconnection attempt 1 in 1 seconds
Dec  8 19:01:57 TEST mpd: [L1] Link: reconnection attempt 1
Dec  8 19:01:57 TEST mpd: [L1] L2TP: Incoming call #6990001 via control connection 0x803073610 initiated
Dec  8 19:02:37 TEST mpd: [L1] L2TP: call #6990001 terminated: result=2 error=6 errmsg="control connection closing"
Dec  8 19:02:37 TEST mpd: [L1] Link: DOWN event
Dec  8 19:02:37 TEST mpd: [L1] LCP: Down event
Dec  8 19:02:37 TEST mpd: [L1] Link: reconnection attempt 2 in 3 seconds
Dec  8 19:02:37 TEST mpd: L2TP: Control connection 0x803073610 terminated: 0 ()
Dec  8 19:02:40 TEST mpd: [L1] Link: reconnection attempt 2
Dec  8 19:02:40 TEST mpd: L2TP: Initiating control connection 0x803073910 0.0.0.0 0 <-> 195.195.195.195 1701
Dec  8 19:02:48 TEST mpd: L2TP: Control connection 0x803073610 destroyed
```
And my mpd.conf:

```
startup:
log +ALL +EVENTS -FRAME -ECHO
default:
      load L2TP_client

L2TP_client:
        create bundle static B1
        create link static L1 l2tp
        set link action bundle B1
        set auth authname "mylogin"
        set auth password "mypassword"
        set link max-redial 0
        set link mtu 1460
        set link keep-alive 20 75

        set l2tp peer 195.195.195.195
        open
```


----------



## obsigna (Dec 8, 2018)

My /usr/local/etc/ipsec.conf is:

```
conn L2TP/IPsec-Client
   keyexchange = ikev1
   type = transport

   leftauth = psk
   left = %defaultroute
   leftprotoport=17/%any

   rightauth = psk
   rightid = %any
   right = example.com
   rightprotoport=17/1701

   auto = start
```

My /usr/local/etc/mpd5/mpd.conf is:

```
startup:

default:
    load l2tp_client

l2tp_client:
# Create a static bundle named B_l2tp
    create bundle static B_l2tp
    set bundle enable compression
    set ipcp ranges 0.0.0.0/0 0.0.0.0/0

# Create a static link named L_l2tp
    create link static L_l2tp l2tp
    set link action bundle B_l2tp
    set link max-redial 0
    set link mtu 1230
    set link keep-alive 20 75
    set l2tp peer example.com
    set l2tp disable dataseq
    set auth authname <my_username>
    set auth password <my_password>
    open
```

I run a L2TP/IPsec dialin server on an AWS-EC2 instance composed of mpd5/strongSwan on FreeBSD 11.2-RELEASE.

I can connect to said server from a FreeBSD 11.2-RELEASE client from behind NAT having mpd5/strongSwan configured as shown above using the following two commands:
`service strongswan onestart`
`service mpd5 onestart`

In order to take the connection down, I do:
`service mpd5 onestop`
`service strongswan onestop`


----------



## yurybx (Dec 10, 2018)

I tried your configuration, and nothing has changed. As before, the IPSec-connection is established normally, but L2TP does not work: "peer not responding to echo requests". I do not know what to do.


----------



## obsigna (Dec 10, 2018)

Check the firewalls.
If a firewall is active on the local machine, it need to allow all traffic via ng* interfaces. In ipfw(8) terms:
allow ip from any to any via ng*

In addition check that UDP ports 500 and 4500 are open on every involved firewall, and in case of a NAT’ing stateful ipfw firewall you need also take care for the fragments. On my FreeBSD 11.2-RELEASE gateway machine I got:

allow udp from any to me 500,4500 in recv $WAN keep-state
allow udp from any to me in recv $WAN frag

Did you update to FreeBSD 11.2? In case not, good luck!


----------



## yurybx (Dec 11, 2018)

Today I installed the bare FreeBSD 11.2 from scratch. I configured StrongSwan and MPD5 on it and received an identical situation: the IPSec connection is established, the NG0 interface receives an IP address, but L2TP packets do not go and the connection is broken with the error "peer not responding to echo requests". Maybe there is some specific configuration of the MPD client for Cisco? Unfortunately, this time, Google did not help me to find it.


----------



## obsigna (Dec 11, 2018)

Please can you send the complete MPD5 session log when connecting with a similar configuration like mine. I would like to compare this line by line with my log of a successful connection. Do you let the server propose the local IP of the ng0 interface, don’t you? I ask this because in the MPD5 log in a previous message, it seems that you used a predefined local ng0 address.


----------



## yurybx (Dec 12, 2018)

Thank you for trying to help me!
Yes, I get the ip address from the server. My FreeBSD has static IP-address 10.1.1.99, and my NG0 interface gets 10.10.181.222 as proposed by L2TP-server.
Your IPSec's configuration works for me only with the lines:
ike=aes128-sha1-modp1024
esp=aes128-sha1
As for MPD, here is my MPD's log with your configuration:

```
Dec 12 11:33:45 TEST mpd: process 833 started, version 5.8 (root@TEST 14:21 11-Dec-2018)
Dec 12 11:33:45 TEST mpd: [B_l2tp] Bundle: Interface ng0 created
Dec 12 11:33:45 TEST mpd: [L_l2tp] Link: OPEN event
Dec 12 11:33:45 TEST mpd: [L_l2tp] LCP: Open event
Dec 12 11:33:45 TEST mpd: [L_l2tp] LCP: state change Initial --> Starting
Dec 12 11:33:45 TEST mpd: [L_l2tp] LCP: LayerStart
Dec 12 11:33:45 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:33:48 TEST mpd: L2TP: Control connection 0x803077310 10.1.1.99 18800 <-> 195.195.195.195 1701 connected
Dec 12 11:33:48 TEST mpd: [L_l2tp] L2TP: Incoming call #4740000 via control connection 0x803077310 initiated
Dec 12 11:33:48 TEST mpd: [L_l2tp] L2TP: Call #4740000 connected
Dec 12 11:33:48 TEST mpd: [L_l2tp] Link: UP event
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: Up event
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: state change Starting --> Req-Sent
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: SendConfigReq #1
Dec 12 11:33:48 TEST mpd: [L_l2tp]   ACFCOMP
Dec 12 11:33:48 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 12 11:33:48 TEST mpd: [L_l2tp]   MRU 1500
Dec 12 11:33:48 TEST mpd: [L_l2tp]   MAGICNUM 0x2c02292d
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #1 (Req-Sent)
Dec 12 11:33:48 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 12 11:33:48 TEST mpd: [L_l2tp]   MAGICNUM 0x201496d4
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: SendConfigAck #1
Dec 12 11:33:48 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 12 11:33:48 TEST mpd: [L_l2tp]   MAGICNUM 0x201496d4
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: state change Req-Sent --> Ack-Sent
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: rec'd Configure Reject #1 (Ack-Sent)
Dec 12 11:33:48 TEST mpd: [L_l2tp]   ACFCOMP
Dec 12 11:33:48 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 12 11:33:48 TEST mpd: [L_l2tp]   MRU 1500
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: SendConfigReq #2
Dec 12 11:33:48 TEST mpd: [L_l2tp]   MAGICNUM 0x2c02292d
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: rec'd Configure Ack #2 (Ack-Sent)
Dec 12 11:33:48 TEST mpd: [L_l2tp]   MAGICNUM 0x2c02292d
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: state change Ack-Sent --> Opened
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: auth: peer wants CHAP, I want nothing
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: LayerUp
Dec 12 11:33:48 TEST mpd: [L_l2tp] CHAP: rec'd CHALLENGE #1 len: 21
Dec 12 11:33:48 TEST mpd: [L_l2tp]   Name: ""
Dec 12 11:33:48 TEST mpd: [L_l2tp] CHAP: Using authname "mylogin"
Dec 12 11:33:48 TEST mpd: [L_l2tp] CHAP: sending RESPONSE #1 len: 61
Dec 12 11:33:48 TEST mpd: [L_l2tp] CHAP: rec'd SUCCESS #1 len: 46
Dec 12 11:33:48 TEST mpd: [L_l2tp]   MESG: S=438FCCA7F3A74539C9032CBCCD66AE499DAB5B1C
Dec 12 11:33:48 TEST mpd: [L_l2tp] LCP: authorization successful
Dec 12 11:33:48 TEST mpd: [L_l2tp] Link: Matched action 'bundle "B_l2tp" ""'
Dec 12 11:33:48 TEST mpd: [L_l2tp] Link: Join bundle "B_l2tp"
Dec 12 11:33:48 TEST mpd: [B_l2tp] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Dec 12 11:33:48 TEST mpd: [B_l2tp] IPCP: Open event
Dec 12 11:33:48 TEST mpd: [B_l2tp] IPCP: state change Initial --> Starting
Dec 12 11:33:48 TEST mpd: [B_l2tp] IPCP: LayerStart
Dec 12 11:33:48 TEST mpd: [B_l2tp] CCP: Open event
Dec 12 11:33:48 TEST mpd: [B_l2tp] CCP: state change Initial --> Starting
Dec 12 11:33:48 TEST mpd: [B_l2tp] CCP: LayerStart
Dec 12 11:33:48 TEST mpd: [B_l2tp] IPCP: Up event
Dec 12 11:33:48 TEST mpd: [B_l2tp] IPCP: state change Starting --> Req-Sent
Dec 12 11:33:48 TEST mpd: [B_l2tp] IPCP: SendConfigReq #1
Dec 12 11:33:48 TEST mpd: [B_l2tp]   IPADDR 0.0.0.0
Dec 12 11:33:48 TEST mpd: [B_l2tp]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Dec 12 11:33:48 TEST mpd: [B_l2tp] CCP: Up event
Dec 12 11:33:48 TEST mpd: [B_l2tp] CCP: state change Starting --> Req-Sent
Dec 12 11:33:48 TEST mpd: [B_l2tp] CCP: SendConfigReq #1
Dec 12 11:33:48 TEST mpd: [B_l2tp] IPCP: rec'd Terminate Ack #1 (Req-Sent)
Dec 12 11:33:48 TEST mpd: [B_l2tp] CCP: rec'd Terminate Ack #1 (Req-Sent)
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: SendConfigReq #2
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: SendConfigReq #2
Dec 12 11:33:50 TEST mpd: [B_l2tp]   IPADDR 0.0.0.0
Dec 12 11:33:50 TEST mpd: [B_l2tp]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: rec'd Configure Request #1 (Req-Sent)
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: SendConfigAck #1
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: state change Req-Sent --> Ack-Sent
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: rec'd Configure Ack #2 (Ack-Sent)
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: state change Ack-Sent --> Opened
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: LayerUp
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: No compression negotiated
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: parameter negotiation failed
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: state change Opened --> Stopping
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: SendTerminateReq #3
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: LayerDown
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: rec'd Configure Request #1 (Req-Sent)
Dec 12 11:33:50 TEST mpd: [B_l2tp]   IPADDR 195.195.195.195
Dec 12 11:33:50 TEST mpd: [B_l2tp]     195.195.195.195 is OK
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: SendConfigAck #1
Dec 12 11:33:50 TEST mpd: [B_l2tp]   IPADDR 195.195.195.195
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: state change Req-Sent --> Ack-Sent
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: rec'd Configure Reject #2 (Ack-Sent)
Dec 12 11:33:50 TEST mpd: [B_l2tp]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: SendConfigReq #3
Dec 12 11:33:50 TEST mpd: [B_l2tp]   IPADDR 0.0.0.0
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: rec'd Terminate Ack #3 (Stopping)
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: state change Stopping --> Stopped
Dec 12 11:33:50 TEST mpd: [B_l2tp] CCP: LayerFinish
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: rec'd Configure Nak #3 (Ack-Sent)
Dec 12 11:33:50 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 12 11:33:50 TEST mpd: [B_l2tp]     10.10.181.222 is OK
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: SendConfigReq #4
Dec 12 11:33:50 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: rec'd Configure Ack #4 (Ack-Sent)
Dec 12 11:33:50 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: state change Ack-Sent --> Opened
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: LayerUp
Dec 12 11:33:50 TEST mpd: [B_l2tp]   10.10.181.222 -> 195.195.195.195
Dec 12 11:33:50 TEST mpd: [B_l2tp] IFACE: Up event
Dec 12 11:34:48 TEST mpd: [L_l2tp] LCP: no reply to 1 echo request(s)
Dec 12 11:35:08 TEST mpd: [L_l2tp] LCP: no reply to 2 echo request(s)
Dec 12 11:35:28 TEST mpd: [L_l2tp] LCP: no reply to 3 echo request(s)
Dec 12 11:35:28 TEST mpd: [L_l2tp] LCP: peer not responding to echo requests
Dec 12 11:35:28 TEST mpd: [L_l2tp] LCP: state change Opened --> Stopping
Dec 12 11:35:28 TEST mpd: [L_l2tp] Link: Leave bundle "B_l2tp"
Dec 12 11:35:28 TEST mpd: [B_l2tp] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Dec 12 11:35:28 TEST mpd: [B_l2tp] IPCP: Close event
Dec 12 11:35:28 TEST mpd: [B_l2tp] IPCP: state change Opened --> Closing
Dec 12 11:35:28 TEST mpd: [B_l2tp] IPCP: SendTerminateReq #5
Dec 12 11:35:28 TEST mpd: [B_l2tp] IPCP: LayerDown
Dec 12 11:35:28 TEST mpd: [B_l2tp] IFACE: Down event
Dec 12 11:35:28 TEST mpd: [B_l2tp] CCP: Close event
Dec 12 11:35:28 TEST mpd: [B_l2tp] CCP: state change Stopped --> Closed
Dec 12 11:35:28 TEST mpd: [B_l2tp] IPCP: Down event
Dec 12 11:35:28 TEST mpd: [B_l2tp] IPCP: LayerFinish
Dec 12 11:35:28 TEST mpd: [B_l2tp] Bundle: No NCPs left. Closing links...
Dec 12 11:35:28 TEST mpd: [B_l2tp] IPCP: state change Closing --> Initial
Dec 12 11:35:28 TEST mpd: [B_l2tp] CCP: Down event
Dec 12 11:35:28 TEST mpd: [B_l2tp] CCP: state change Closed --> Initial
Dec 12 11:35:28 TEST mpd: [L_l2tp] LCP: SendTerminateReq #3
Dec 12 11:35:28 TEST mpd: [L_l2tp] LCP: LayerDown
Dec 12 11:35:30 TEST mpd: [L_l2tp] LCP: SendTerminateReq #4
Dec 12 11:35:32 TEST mpd: [L_l2tp] LCP: state change Stopping --> Stopped
Dec 12 11:35:32 TEST mpd: [L_l2tp] LCP: LayerFinish
Dec 12 11:35:32 TEST mpd: [L_l2tp] L2TP: Call #4740000 terminated locally
Dec 12 11:35:32 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:35:32 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:35:32 TEST mpd: [L_l2tp] LCP: state change Stopped --> Starting
Dec 12 11:35:32 TEST mpd: [L_l2tp] LCP: LayerStart
Dec 12 11:35:32 TEST mpd: [L_l2tp] Link: reconnection attempt 1 in 1 seconds
Dec 12 11:35:33 TEST mpd: [L_l2tp] Link: reconnection attempt 1
Dec 12 11:35:33 TEST mpd: [L_l2tp] L2TP: Incoming call #4740001 via control connection 0x803077310 initiated
Dec 12 11:36:10 TEST mpd: [L_l2tp] L2TP: call #4740001 terminated: result=2 error=6 errmsg="control connection closing"
Dec 12 11:36:10 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:36:10 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:36:10 TEST mpd: [L_l2tp] Link: reconnection attempt 2 in 3 seconds
Dec 12 11:36:10 TEST mpd: L2TP: Control connection 0x803077310 terminated: 0 ()
Dec 12 11:36:13 TEST mpd: [L_l2tp] Link: reconnection attempt 2
Dec 12 11:36:13 TEST mpd: L2TP: Initiating control connection 0x803077610 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:36:21 TEST mpd: L2TP: Control connection 0x803077310 destroyed
Dec 12 11:37:13 TEST mpd: L2TP: Control connection 0x803077610 terminated: 6 (expecting reply; none received)
Dec 12 11:37:13 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:37:13 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:37:13 TEST mpd: [L_l2tp] Link: reconnection attempt 3 in 2 seconds
Dec 12 11:37:15 TEST mpd: [L_l2tp] Link: reconnection attempt 3
Dec 12 11:37:15 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:37:24 TEST mpd: L2TP: Control connection 0x803077610 destroyed
Dec 12 11:38:15 TEST mpd: L2TP: Control connection 0x803077310 terminated: 6 (expecting reply; none received)
Dec 12 11:38:15 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:38:15 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:38:15 TEST mpd: [L_l2tp] Link: reconnection attempt 4 in 3 seconds
Dec 12 11:38:18 TEST mpd: [L_l2tp] Link: reconnection attempt 4
Dec 12 11:38:18 TEST mpd: L2TP: Initiating control connection 0x803077610 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:38:26 TEST mpd: L2TP: Control connection 0x803077310 destroyed
Dec 12 11:39:18 TEST mpd: L2TP: Control connection 0x803077610 terminated: 6 (expecting reply; none received)
Dec 12 11:39:18 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:39:18 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:39:18 TEST mpd: [L_l2tp] Link: reconnection attempt 5 in 4 seconds
Dec 12 11:39:22 TEST mpd: [L_l2tp] Link: reconnection attempt 5
Dec 12 11:39:22 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:39:29 TEST mpd: L2TP: Control connection 0x803077610 destroyed
Dec 12 11:40:22 TEST mpd: L2TP: Control connection 0x803077310 terminated: 6 (expecting reply; none received)
Dec 12 11:40:22 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:40:22 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:40:22 TEST mpd: [L_l2tp] Link: reconnection attempt 6 in 4 seconds
Dec 12 11:40:26 TEST mpd: [L_l2tp] Link: reconnection attempt 6
Dec 12 11:40:26 TEST mpd: L2TP: Initiating control connection 0x803077610 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:40:33 TEST mpd: L2TP: Control connection 0x803077310 destroyed
Dec 12 11:41:26 TEST mpd: L2TP: Control connection 0x803077610 terminated: 6 (expecting reply; none received)
Dec 12 11:41:26 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:41:26 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:41:26 TEST mpd: [L_l2tp] Link: reconnection attempt 7 in 2 seconds
Dec 12 11:41:29 TEST mpd: [L_l2tp] Link: reconnection attempt 7
Dec 12 11:41:29 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:41:37 TEST mpd: L2TP: Control connection 0x803077610 destroyed
Dec 12 11:42:29 TEST mpd: L2TP: Control connection 0x803077310 terminated: 6 (expecting reply; none received)
Dec 12 11:42:29 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:42:29 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:42:29 TEST mpd: [L_l2tp] Link: reconnection attempt 8 in 3 seconds
Dec 12 11:42:32 TEST mpd: [L_l2tp] Link: reconnection attempt 8
Dec 12 11:42:32 TEST mpd: L2TP: Initiating control connection 0x803077610 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:42:40 TEST mpd: L2TP: Control connection 0x803077310 destroyed
Dec 12 11:43:32 TEST mpd: L2TP: Control connection 0x803077610 terminated: 6 (expecting reply; none received)
Dec 12 11:43:32 TEST mpd: [L_l2tp] Link: DOWN event
Dec 12 11:43:32 TEST mpd: [L_l2tp] LCP: Down event
Dec 12 11:43:32 TEST mpd: [L_l2tp] Link: reconnection attempt 9 in 4 seconds
Dec 12 11:43:36 TEST mpd: [L_l2tp] Link: reconnection attempt 9
Dec 12 11:43:36 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 12 11:43:43 TEST mpd: L2TP: Control connection 0x803077610 destroyed
```


----------



## obsigna (Dec 12, 2018)

Yes, I anticipated that you specify the ciphers for the IPsec connection, and from what I see, the IPsec part is working.

Comparing the L2TP connection logs, I notice something is going wrong in the IPCP negotiation.


```
Dec 12 11:33:50 TEST mpd: [B_l2tp] IPCP: rec'd Configure Reject #2 (Ack-Sent)
Dec 12 11:33:50 TEST mpd: [B_l2tp]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
```

Try disabling Van Jacobson TCP header compression. In addition for troubleshooting it is best to strip down the mpd configuration to the mere basics:


```
startup:

default:
        load l2tp_client

l2tp_client:
        create bundle static B_l2tp
        create link static L_l2tp l2tp
        set link action bundle B_l2tp

        set l2tp peer example.com
        set l2tp enable outcall
       
        set ipcp no vjcomp
       
        set auth authname <username>
        set auth password <password>

        open
```


----------



## yurybx (Dec 13, 2018)

I tried your new configuration and got an error at an earlier stage of connection:

```
Dec 13 11:32:23 TEST mpd: process 1211 started, version 5.8 (root@TEST 14:21 11-Dec-2018)
Dec 13 11:32:23 TEST mpd: [B_l2tp] Bundle: Interface ng0 created
Dec 13 11:32:23 TEST mpd: [L_l2tp] Link: OPEN event
Dec 13 11:32:23 TEST mpd: [L_l2tp] LCP: Open event
Dec 13 11:32:23 TEST mpd: [L_l2tp] LCP: state change Initial --> Starting
Dec 13 11:32:23 TEST mpd: [L_l2tp] LCP: LayerStart
Dec 13 11:32:23 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 13 11:32:26 TEST mpd: L2TP: Control connection 0x803077310 10.1.1.99 22912 <-> 195.195.195.195 1701 connected
Dec 13 11:32:26 TEST mpd: [L_l2tp] L2TP: Outgoing call #2020000 via control connection 0x803077310 initiated
Dec 13 11:33:27 TEST mpd: [L_l2tp] L2TP: call #2020000 terminated: result=2 error=6 errmsg="control connection closing"
Dec 13 11:33:27 TEST mpd: [L_l2tp] Link: DOWN event
Dec 13 11:33:27 TEST mpd: [L_l2tp] LCP: Close event
Dec 13 11:33:27 TEST mpd: [L_l2tp] LCP: state change Starting --> Initial
Dec 13 11:33:27 TEST mpd: [L_l2tp] LCP: LayerFinish
Dec 13 11:33:27 TEST mpd: [L_l2tp] LCP: Down event
Dec 13 11:33:27 TEST mpd: L2TP: Control connection 0x803077310 terminated: 6 (expecting reply; none received)
Dec 13 11:33:38 TEST mpd: L2TP: Control connection 0x803077310 destroyed
```
After that, I removed the line "set l2tp enable outcall" from the configuration and got rid of the VJComp reject but got the same error as before (peer not responding to echo requests):

```
Dec 13 11:35:15 TEST mpd: process 1398 started, version 5.8 (root@TEST 14:21 11-Dec-2018)
Dec 13 11:35:15 TEST mpd: [B_l2tp] Bundle: Interface ng0 created
Dec 13 11:35:15 TEST mpd: [L_l2tp] Link: OPEN event
Dec 13 11:35:15 TEST mpd: [L_l2tp] LCP: Open event
Dec 13 11:35:15 TEST mpd: [L_l2tp] LCP: state change Initial --> Starting
Dec 13 11:35:15 TEST mpd: [L_l2tp] LCP: LayerStart
Dec 13 11:35:15 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 13 11:35:18 TEST mpd: L2TP: Control connection 0x803077310 10.1.1.99 19073 <-> 195.195.195.195 1701 connected
Dec 13 11:35:18 TEST mpd: [L_l2tp] L2TP: Incoming call #760000 via control connection 0x803077310 initiated
Dec 13 11:35:18 TEST mpd: [L_l2tp] L2TP: Call #760000 connected
Dec 13 11:35:18 TEST mpd: [L_l2tp] Link: UP event
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: Up event
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: state change Starting --> Req-Sent
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: SendConfigReq #1
Dec 13 11:35:18 TEST mpd: [L_l2tp]   ACFCOMP
Dec 13 11:35:18 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MRU 1500
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MAGICNUM 0xc4cb95e8
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #1 (Req-Sent)
Dec 13 11:35:18 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MAGICNUM 0x7c3950aa
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: SendConfigAck #1
Dec 13 11:35:18 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MAGICNUM 0x7c3950aa
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: state change Req-Sent --> Ack-Sent
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: rec'd Configure Reject #1 (Ack-Sent)
Dec 13 11:35:18 TEST mpd: [L_l2tp]   ACFCOMP
Dec 13 11:35:18 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MRU 1500
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: SendConfigReq #2
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MAGICNUM 0xc4cb95e8
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: rec'd Configure Ack #2 (Ack-Sent)
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MAGICNUM 0xc4cb95e8
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: state change Ack-Sent --> Opened
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: auth: peer wants CHAP, I want nothing
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: LayerUp
Dec 13 11:35:18 TEST mpd: [L_l2tp] CHAP: rec'd CHALLENGE #1 len: 21
Dec 13 11:35:18 TEST mpd: [L_l2tp]   Name: ""
Dec 13 11:35:18 TEST mpd: [L_l2tp] CHAP: Using authname "mylogin"
Dec 13 11:35:18 TEST mpd: [L_l2tp] CHAP: sending RESPONSE #1 len: 61
Dec 13 11:35:18 TEST mpd: [L_l2tp] CHAP: rec'd SUCCESS #1 len: 46
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MESG: S=FE6A078F09E25793BDB35B9A05F8CB59ED3F9267
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: authorization successful
Dec 13 11:35:18 TEST mpd: [L_l2tp] Link: Matched action 'bundle "B_l2tp" ""'
Dec 13 11:35:18 TEST mpd: [L_l2tp] Link: Join bundle "B_l2tp"
Dec 13 11:35:18 TEST mpd: [B_l2tp] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Dec 13 11:35:18 TEST mpd: [B_l2tp] IPCP: Open event
Dec 13 11:35:18 TEST mpd: [B_l2tp] IPCP: state change Initial --> Starting
Dec 13 11:35:18 TEST mpd: [B_l2tp] IPCP: LayerStart
Dec 13 11:35:18 TEST mpd: [B_l2tp] IPCP: Up event
Dec 13 11:35:18 TEST mpd: [B_l2tp] IPCP: state change Starting --> Req-Sent
Dec 13 11:35:18 TEST mpd: [B_l2tp] IPCP: SendConfigReq #1
Dec 13 11:35:18 TEST mpd: [B_l2tp]   IPADDR 10.1.1.99
Dec 13 11:35:18 TEST mpd: [B_l2tp] IPCP: rec'd Terminate Ack #1 (Req-Sent)
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: SendConfigReq #2
Dec 13 11:35:20 TEST mpd: [B_l2tp]   IPADDR 10.1.1.99
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: rec'd Configure Request #1 (Req-Sent)
Dec 13 11:35:20 TEST mpd: [B_l2tp]   IPADDR 195.195.195.195
Dec 13 11:35:20 TEST mpd: [B_l2tp]     195.195.195.195 is OK
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: SendConfigAck #1
Dec 13 11:35:20 TEST mpd: [B_l2tp]   IPADDR 195.195.195.195
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: state change Req-Sent --> Ack-Sent
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: rec'd Configure Nak #2 (Ack-Sent)
Dec 13 11:35:20 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 13 11:35:20 TEST mpd: [B_l2tp]     10.10.181.222 is OK
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: SendConfigReq #3
Dec 13 11:35:20 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: rec'd Configure Ack #3 (Ack-Sent)
Dec 13 11:35:20 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: state change Ack-Sent --> Opened
Dec 13 11:35:20 TEST mpd: [B_l2tp] IPCP: LayerUp
Dec 13 11:35:20 TEST mpd: [B_l2tp]   10.10.181.222 -> 195.195.195.195
Dec 13 11:35:20 TEST mpd: [B_l2tp] IFACE: Up event
Dec 13 11:35:33 TEST mpd: [L_l2tp] LCP: no reply to 1 echo request(s)
Dec 13 11:35:38 TEST mpd: [L_l2tp] LCP: no reply to 2 echo request(s)
Dec 13 11:35:43 TEST mpd: [L_l2tp] LCP: no reply to 3 echo request(s)
Dec 13 11:35:48 TEST mpd: [L_l2tp] LCP: no reply to 4 echo request(s)
Dec 13 11:35:53 TEST mpd: [L_l2tp] LCP: no reply to 5 echo request(s)
Dec 13 11:35:59 TEST mpd: [L_l2tp] LCP: no reply to 6 echo request(s)
Dec 13 11:36:04 TEST mpd: [L_l2tp] LCP: no reply to 7 echo request(s)
Dec 13 11:36:04 TEST mpd: [L_l2tp] LCP: peer not responding to echo requests
Dec 13 11:36:04 TEST mpd: [L_l2tp] LCP: state change Opened --> Stopping
Dec 13 11:36:04 TEST mpd: [L_l2tp] Link: Leave bundle "B_l2tp"
Dec 13 11:36:04 TEST mpd: [B_l2tp] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Dec 13 11:36:04 TEST mpd: [B_l2tp] IPCP: Close event
Dec 13 11:36:04 TEST mpd: [B_l2tp] IPCP: state change Opened --> Closing
Dec 13 11:36:04 TEST mpd: [B_l2tp] IPCP: SendTerminateReq #4
Dec 13 11:36:04 TEST mpd: [B_l2tp] IPCP: LayerDown
Dec 13 11:36:04 TEST mpd: [B_l2tp] IFACE: Down event
Dec 13 11:36:04 TEST mpd: [B_l2tp] IPCP: Down event
Dec 13 11:36:04 TEST mpd: [B_l2tp] IPCP: LayerFinish
Dec 13 11:36:04 TEST mpd: [B_l2tp] Bundle: No NCPs left. Closing links...
Dec 13 11:36:04 TEST mpd: [B_l2tp] IPCP: state change Closing --> Initial
Dec 13 11:36:04 TEST mpd: [L_l2tp] LCP: SendTerminateReq #3
Dec 13 11:36:04 TEST mpd: [L_l2tp] LCP: LayerDown
Dec 13 11:36:06 TEST mpd: [L_l2tp] LCP: SendTerminateReq #4
Dec 13 11:36:08 TEST mpd: [L_l2tp] LCP: state change Stopping --> Stopped
Dec 13 11:36:08 TEST mpd: [L_l2tp] LCP: LayerFinish
Dec 13 11:36:08 TEST mpd: [L_l2tp] L2TP: Call #760000 terminated locally
Dec 13 11:36:08 TEST mpd: [L_l2tp] Link: DOWN event
Dec 13 11:36:08 TEST mpd: [L_l2tp] LCP: Close event
Dec 13 11:36:08 TEST mpd: [L_l2tp] LCP: state change Stopped --> Closed
Dec 13 11:36:08 TEST mpd: [L_l2tp] LCP: Down event
Dec 13 11:36:08 TEST mpd: [L_l2tp] LCP: state change Closed --> Initial
Dec 13 11:36:18 TEST mpd: L2TP: Control connection 0x803077310 terminated: 0 (no more sessions exist in this tunnel)
Dec 13 11:36:29 TEST mpd: L2TP: Control connection 0x803077310 destroyed
```


----------



## obsigna (Dec 13, 2018)

```
Dec 13 11:35:18 TEST mpd: [L_l2tp] LCP: rec'd Configure Reject #1 (Ack-Sent)
Dec 13 11:35:18 TEST mpd: [L_l2tp]   ACFCOMP
Dec 13 11:35:18 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 13 11:35:18 TEST mpd: [L_l2tp]   MRU 1500
```

Let’s disable all other compression facilities as well and reduce the MTU/MRU, in addition we do not send keep alive (= do not ask for echo) packets and hence we don’t wait for it:


```
startup:

default:
        load l2tp_client

l2tp_client:
        create bundle static B_l2tp
        create link static L_l2tp l2tp
        set link action bundle B_l2tp
        set link mtu 1460
        set link mru 1460
        set link no acfcomp
        set link no protocomp
        set link keep-alive 0 0
        set l2tp peer example.com
        set ipcp no vjcomp
        set auth authname <username>
        set auth password <password>

        open
```


----------



## yurybx (Dec 14, 2018)

Now the connection breaks not after one but two and a half minutes. I understand, I can not do without logs from the server?

```
Dec 14 14:10:07 TEST mpd: process 4736 started, version 5.8 (root@TEST 14:21 11-Dec-2018)
Dec 14 14:10:07 TEST mpd: [B_l2tp] Bundle: Interface ng0 created
Dec 14 14:10:07 TEST mpd: [L_l2tp] Link: OPEN event
Dec 14 14:10:07 TEST mpd: [L_l2tp] LCP: Open event
Dec 14 14:10:07 TEST mpd: [L_l2tp] LCP: state change Initial --> Starting
Dec 14 14:10:07 TEST mpd: [L_l2tp] LCP: LayerStart
Dec 14 14:10:07 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.195.195.195 1701
Dec 14 14:10:10 TEST mpd: L2TP: Control connection 0x803077310 10.1.1.99 53575 <-> 195.195.195.195 1701 connected
Dec 14 14:10:10 TEST mpd: [L_l2tp] L2TP: Incoming call #8420000 via control connection 0x803077310 initiated
Dec 14 14:10:10 TEST mpd: [L_l2tp] L2TP: Call #8420000 connected
Dec 14 14:10:10 TEST mpd: [L_l2tp] Link: UP event
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: Up event
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: state change Starting --> Req-Sent
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: SendConfigReq #1
Dec 14 14:10:10 TEST mpd: [L_l2tp]   MRU 1460
Dec 14 14:10:10 TEST mpd: [L_l2tp]   MAGICNUM 0x586f1d00
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #1 (Req-Sent)
Dec 14 14:10:10 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 14:10:10 TEST mpd: [L_l2tp]   MAGICNUM 0x75b0f9ba
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: SendConfigAck #1
Dec 14 14:10:10 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 14:10:10 TEST mpd: [L_l2tp]   MAGICNUM 0x75b0f9ba
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: state change Req-Sent --> Ack-Sent
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: rec'd Configure Reject #1 (Ack-Sent)
Dec 14 14:10:10 TEST mpd: [L_l2tp]   MRU 1460
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: SendConfigReq #2
Dec 14 14:10:10 TEST mpd: [L_l2tp]   MAGICNUM 0x586f1d00
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: rec'd Configure Ack #2 (Ack-Sent)
Dec 14 14:10:10 TEST mpd: [L_l2tp]   MAGICNUM 0x586f1d00
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: state change Ack-Sent --> Opened
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: auth: peer wants CHAP, I want nothing
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: LayerUp
Dec 14 14:10:10 TEST mpd: [L_l2tp] CHAP: rec'd CHALLENGE #1 len: 21
Dec 14 14:10:10 TEST mpd: [L_l2tp]   Name: ""
Dec 14 14:10:10 TEST mpd: [L_l2tp] CHAP: Using authname "mylogin"
Dec 14 14:10:10 TEST mpd: [L_l2tp] CHAP: sending RESPONSE #1 len: 61
Dec 14 14:10:10 TEST mpd: [L_l2tp] CHAP: rec'd SUCCESS #1 len: 46
Dec 14 14:10:10 TEST mpd: [L_l2tp]   MESG: S=0A6BD04BE73829C132DA42C0314288E7420BBD8C
Dec 14 14:10:10 TEST mpd: [L_l2tp] LCP: authorization successful
Dec 14 14:10:10 TEST mpd: [L_l2tp] Link: Matched action 'bundle "B_l2tp" ""'
Dec 14 14:10:10 TEST mpd: [L_l2tp] Link: Join bundle "B_l2tp"
Dec 14 14:10:10 TEST mpd: [B_l2tp] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Dec 14 14:10:10 TEST mpd: [B_l2tp] IPCP: Open event
Dec 14 14:10:10 TEST mpd: [B_l2tp] IPCP: state change Initial --> Starting
Dec 14 14:10:10 TEST mpd: [B_l2tp] IPCP: LayerStart
Dec 14 14:10:10 TEST mpd: [B_l2tp] IPCP: Up event
Dec 14 14:10:10 TEST mpd: [B_l2tp] IPCP: state change Starting --> Req-Sent
Dec 14 14:10:10 TEST mpd: [B_l2tp] IPCP: SendConfigReq #1
Dec 14 14:10:10 TEST mpd: [B_l2tp]   IPADDR 10.1.1.99
Dec 14 14:10:10 TEST mpd: [B_l2tp] IPCP: rec'd Terminate Ack #1 (Req-Sent)
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: SendConfigReq #2
Dec 14 14:10:12 TEST mpd: [B_l2tp]   IPADDR 10.1.1.99
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: rec'd Configure Request #1 (Req-Sent)
Dec 14 14:10:12 TEST mpd: [B_l2tp]   IPADDR 195.195.195.195
Dec 14 14:10:12 TEST mpd: [B_l2tp]     195.195.195.195 is OK
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: SendConfigAck #1
Dec 14 14:10:12 TEST mpd: [B_l2tp]   IPADDR 195.195.195.195
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: state change Req-Sent --> Ack-Sent
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: rec'd Configure Nak #2 (Ack-Sent)
Dec 14 14:10:12 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 14 14:10:12 TEST mpd: [B_l2tp]     10.10.181.222 is OK
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: SendConfigReq #3
Dec 14 14:10:12 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: rec'd Configure Ack #3 (Ack-Sent)
Dec 14 14:10:12 TEST mpd: [B_l2tp]   IPADDR 10.10.181.222
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: state change Ack-Sent --> Opened
Dec 14 14:10:12 TEST mpd: [B_l2tp] IPCP: LayerUp
Dec 14 14:10:12 TEST mpd: [B_l2tp]   10.10.181.222 -> 195.195.195.195
Dec 14 14:10:12 TEST mpd: [B_l2tp] IFACE: Up event
Dec 14 14:12:32 TEST mpd: [L_l2tp] L2TP: call #8420000 terminated: result=2 error=6 errmsg="control connection closing"
Dec 14 14:12:32 TEST mpd: [L_l2tp] Link: DOWN event
Dec 14 14:12:32 TEST mpd: [L_l2tp] LCP: Close event
Dec 14 14:12:32 TEST mpd: [L_l2tp] LCP: state change Opened --> Closing
Dec 14 14:12:32 TEST mpd: [L_l2tp] Link: Leave bundle "B_l2tp"
Dec 14 14:12:32 TEST mpd: [B_l2tp] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Dec 14 14:12:32 TEST mpd: [B_l2tp] IPCP: Close event
Dec 14 14:12:32 TEST mpd: [B_l2tp] IPCP: state change Opened --> Closing
Dec 14 14:12:32 TEST mpd: [B_l2tp] IPCP: SendTerminateReq #4
Dec 14 14:12:32 TEST mpd: [B_l2tp] IPCP: LayerDown
Dec 14 14:12:32 TEST mpd: [B_l2tp] IFACE: Down event
Dec 14 14:12:32 TEST mpd: [B_l2tp] IPCP: Down event
Dec 14 14:12:32 TEST mpd: [B_l2tp] IPCP: LayerFinish
Dec 14 14:12:32 TEST mpd: [B_l2tp] Bundle: No NCPs left. Closing links...
Dec 14 14:12:32 TEST mpd: [B_l2tp] IPCP: state change Closing --> Initial
Dec 14 14:12:32 TEST mpd: [L_l2tp] LCP: SendTerminateReq #3
Dec 14 14:12:32 TEST mpd: [L_l2tp] LCP: LayerDown
Dec 14 14:12:32 TEST mpd: [L_l2tp] LCP: Down event
Dec 14 14:12:32 TEST mpd: [L_l2tp] LCP: LayerFinish
Dec 14 14:12:32 TEST mpd: [L_l2tp] LCP: state change Closing --> Initial
Dec 14 14:12:32 TEST mpd: L2TP: Control connection 0x803077310 terminated: 0 ()
Dec 14 14:12:43 TEST mpd: L2TP: Control connection 0x803077310 destroyed
```


----------



## obsigna (Dec 14, 2018)

During this 150 s of lifetime, do you see the interface ng0?

In case yes, does ifconfig ng0 inform the peer's address in the other LAN (not the WAN address)? Something like the following:

```
ng0: flags=88d1<UP,POINTOPOINT,RUNNING,NOARP,SIMPLEX,MULTICAST> metric 0 mtu 1500
    inet 10.1.1.99 --> 10.1.1.1 netmask 0xffffffff
    inet6 fe80::7285:c2ff:fe5d:e86d%ng0 prefixlen 64 scopeid 0x3
    nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
```

Can you ping the peer´s local address, in the above example 10.1.1.1?


----------



## yurybx (Dec 14, 2018)

Yes, I see the interface ng0, but can't ping other side. (From now on, I stop masking the server's IP address, and the former 195.195.195.195 is now 195.149.70.70.)

```
# ifconfig ng0
ng0: flags=88d1<UP,POINTOPOINT,RUNNING,NOARP,SIMPLEX,MULTICAST> metric 0 mtu 1460
        inet 10.10.181.222 --> 195.149.70.70 netmask 0xffffffff
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
root@TEST:/usr/local/etc # ping 195.149.70.70
PING 195.149.70.70 (195.149.70.70): 56 data bytes
^C
--- 195.149.70.70 ping statistics ---
42 packets transmitted, 0 packets received, 100.0% packet loss
```
Today I turned to tech support on that side, and I was prompted by necessary settings. But they are designed for
xl2tpd that cannot be installed into FreeBSD from ports. I tried to adjust my configuration based on that example, but I didn’t succeed.

```
# cat mpd.conf
startup:

default:
        load l2tp_client

l2tp_client:
        create bundle static B_l2tp
        set ipcp no vjcomp

        set ccp no
        create link static L_l2tp l2tp
        set link action bundle B_l2tp
        set link no pap chap eap
        set link enable chap
        set link mtu 1410
        set link mru 1410

        set l2tp peer 195.149.70.70

        set auth authname "mylogin"
        set auth password "mypassword"

        open
```


```
cat /var/log/mpd.log
Dec 14 16:04:38 TEST mpd: process 1279 started, version 5.8 (root@TEST 14:21 11-Dec-2018)
Dec 14 16:04:39 TEST mpd: [B_l2tp] Bundle: Interface ng0 created
Dec 14 16:04:39 TEST mpd: mpd.conf:10: Error in 'set ccp no'
Dec 14 16:04:39 TEST mpd: [L_l2tp] Link: OPEN event
Dec 14 16:04:39 TEST mpd: [L_l2tp] LCP: Open event
Dec 14 16:04:39 TEST mpd: [L_l2tp] LCP: state change Initial --> Starting
Dec 14 16:04:39 TEST mpd: [L_l2tp] LCP: LayerStart
Dec 14 16:04:39 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.149.70.70 1701
Dec 14 16:04:42 TEST mpd: L2TP: Control connection 0x803077310 10.1.1.99 46630 <-> 195.149.70.70 1701 connected
Dec 14 16:04:42 TEST mpd: [L_l2tp] L2TP: Incoming call #1340000 via control connection 0x803077310 initiated
Dec 14 16:04:42 TEST mpd: [L_l2tp] L2TP: Call #1340000 connected
Dec 14 16:04:42 TEST mpd: [L_l2tp] Link: UP event
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: Up event
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: state change Starting --> Req-Sent
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigReq #1
Dec 14 16:04:42 TEST mpd: [L_l2tp]   ACFCOMP
Dec 14 16:04:42 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MRU 1410
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x0a13e374
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #1 (Req-Sent)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x7167d30f
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigRej #1
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Reject #1 (Req-Sent)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   ACFCOMP
Dec 14 16:04:42 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MRU 1410
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigReq #2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x0a13e374
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #2 (Req-Sent)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x7167d30f
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigRej #2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Ack #2 (Req-Sent)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x0a13e374
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: state change Req-Sent --> Ack-Rcvd
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #3 (Ack-Rcvd)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x7167d30f
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigRej #3
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #4 (Ack-Rcvd)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x7167d30f
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigRej #4
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #5 (Ack-Rcvd)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x7167d30f
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigRej #5
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #6 (Ack-Rcvd)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x7167d30f
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigRej #6
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #7 (Ack-Rcvd)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x7167d30f
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: SendConfigRej #7
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #8 (Ack-Rcvd)
Dec 14 16:04:42 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:04:42 TEST mpd: [L_l2tp]   MAGICNUM 0x7167d30f
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: not converging
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: parameter negotiation failed
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: state change Ack-Rcvd --> Stopped
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: LayerFinish
Dec 14 16:04:42 TEST mpd: [L_l2tp] L2TP: Call #1340000 terminated locally
Dec 14 16:04:42 TEST mpd: [L_l2tp] Link: DOWN event
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: Close event
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: state change Stopped --> Closed
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: Down event
Dec 14 16:04:42 TEST mpd: [L_l2tp] LCP: state change Closed --> Initial
Dec 14 16:04:42 TEST mpd: L2TP: Control connection 0x803077310 terminated: 0 (No Error)
Dec 14 16:04:53 TEST mpd: L2TP: Control connection 0x803077310 destroyed
```
Is it possible by that example to determine what my problem is? Also there is configuration for Mikrotic router: http://vpninfo.uz.gov.ua/instructions/mikrotik/6.10/


----------



## yurybx (Dec 14, 2018)

Also I tried next options:

```
set link no pap
set link no chap
set link no chap-md5
set link no chap-msv1
set link yes chap-msv2
```
And got error:

```
Dec 14 16:34:45 TEST mpd: process 881 started, version 5.8 (root@TEST 14:21 11-Dec-2018)
Dec 14 16:34:45 TEST mpd: [B_l2tp] Bundle: Interface ng0 created
Dec 14 16:34:45 TEST mpd: mpd.conf:10: Error in 'set ccp no'
Dec 14 16:34:45 TEST mpd: [L_l2tp] Link: OPEN event
Dec 14 16:34:45 TEST mpd: [L_l2tp] LCP: Open event
Dec 14 16:34:45 TEST mpd: [L_l2tp] LCP: state change Initial --> Starting
Dec 14 16:34:45 TEST mpd: [L_l2tp] LCP: LayerStart
Dec 14 16:34:45 TEST mpd: L2TP: Initiating control connection 0x803077310 0.0.0.0 0 <-> 195.149.70.70 1701
Dec 14 16:34:48 TEST mpd: L2TP: Control connection 0x803077310 10.1.1.99 12125 <-> 195.149.70.70 1701 connected
Dec 14 16:34:48 TEST mpd: [L_l2tp] L2TP: Incoming call #4250000 via control connection 0x803077310 initiated
Dec 14 16:34:48 TEST mpd: [L_l2tp] L2TP: Call #4250000 connected
Dec 14 16:34:48 TEST mpd: [L_l2tp] Link: UP event
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: Up event
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: state change Starting --> Req-Sent
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: SendConfigReq #1
Dec 14 16:34:48 TEST mpd: [L_l2tp]   ACFCOMP
Dec 14 16:34:48 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 14 16:34:48 TEST mpd: [L_l2tp]   MRU 1410
Dec 14 16:34:48 TEST mpd: [L_l2tp]   MAGICNUM 0xc1160ca7
Dec 14 16:34:48 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: rec'd Configure Request #1 (Req-Sent)
Dec 14 16:34:48 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:34:48 TEST mpd: [L_l2tp]   MAGICNUM 0x537a1de7
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: SendConfigAck #1
Dec 14 16:34:48 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:34:48 TEST mpd: [L_l2tp]   MAGICNUM 0x537a1de7
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: state change Req-Sent --> Ack-Sent
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: rec'd Configure Reject #1 (Ack-Sent)
Dec 14 16:34:48 TEST mpd: [L_l2tp]   ACFCOMP
Dec 14 16:34:48 TEST mpd: [L_l2tp]   PROTOCOMP
Dec 14 16:34:48 TEST mpd: [L_l2tp]   MRU 1410
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: SendConfigReq #2
Dec 14 16:34:48 TEST mpd: [L_l2tp]   MAGICNUM 0xc1160ca7
Dec 14 16:34:48 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: rec'd Configure Ack #2 (Ack-Sent)
Dec 14 16:34:48 TEST mpd: [L_l2tp]   MAGICNUM 0xc1160ca7
Dec 14 16:34:48 TEST mpd: [L_l2tp]   AUTHPROTO CHAP MSOFTv2
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: state change Ack-Sent --> Opened
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: auth: peer wants CHAP, I want CHAP
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: sending CHALLENGE #1 len: 28
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: LayerUp
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: rec'd CHALLENGE #1 len: 21
Dec 14 16:34:48 TEST mpd: [L_l2tp]   Name: ""
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: Using authname "mylogin"
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: sending RESPONSE #1 len: 61
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: rec'd RESPONSE #1 len: 5
Dec 14 16:34:48 TEST mpd: [L_l2tp]   Bogus packet
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: Auth return status: undefined
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: Invalid response
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: Reply message: E=691 R=0 M=Login incorrect
Dec 14 16:34:48 TEST mpd: [L_l2tp] CHAP: sending FAILURE #1 len: 31
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: authorization failed
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: parameter negotiation failed
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: state change Opened --> Stopping
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: SendTerminateReq #3
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: LayerDown
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: rec'd Terminate Ack #3 (Stopping)
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: state change Stopping --> Stopped
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: LayerFinish
Dec 14 16:34:48 TEST mpd: [L_l2tp] L2TP: Call #4250000 terminated locally
Dec 14 16:34:48 TEST mpd: [L_l2tp] Link: DOWN event
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: Close event
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: state change Stopped --> Closed
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: Down event
Dec 14 16:34:48 TEST mpd: [L_l2tp] LCP: state change Closed --> Initial
Dec 14 16:34:48 TEST mpd: L2TP: Control connection 0x803077310 terminated: 0 (No Error)
Dec 14 16:34:59 TEST mpd: L2TP: Control connection 0x803077310 destroyed
```


----------



## obsigna (Dec 15, 2018)

Xl2tpd is a fork of net/l2tpd, see https://github.com/xelerance/xl2tpd#readme

So chances are that the original l2tpd(8) which is in the ports would work.


----------



## yurybx (Dec 18, 2018)

I configured the l2tpd as instructed, but the connection is not established: "No more free pseudo-tty's".
Here is the l2tpd's log:

```
This binary does not support kernel L2TP.
l2tpd version 0.69 started on TEST.local PID:860
Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
Forked by Scott Balmos and David Stipp, (C) 2001
Inhereted by Jeff McAdams, (C) 2002
FreeBSD version 11.2-RELEASE on a amd64, addr 0.0.0.0, port 1701
do_control: Got message c vpn-uz (8 bytes long)
ourtid = 49146, entropy_buf = bffa
l2tp_call:Connecting to host 195.149.70.70, port 1701
check_control: control, cid = 0, Ns = 0, Nr = 1
handle_avps: handling avp's for tunnel 49146, call 0
message_type_avp: message type 2 (Start-Control-Connection-Reply)
protocol_version_avp: peer is using version 1, revision 0.
framing_caps_avp: supported peer frames: async sync
bearer_caps_avp: supported peer bearers: analog digital
firmware_rev_avp: peer reports firmware version 4384 (0x1120)
hostname_avp: peer reports hostname 'ASA'
vendor_avp: peer reports vendor 'Cisco Systems, Inc.'
assigned_tunnel_avp: using peer's tunnel 51097
receive_window_size_avp: peer wants RWS of 16.  Will use flow control.
control_finish: Connection established to 195.149.70.70, 1701.  Local: 49146, Remote: 51097.
ourcid = 33308, entropy_buf = 821c
lac_call: Calling on tunnel 49146
check_control: control, cid = 0, Ns = 1, Nr = 2
check_control: control, cid = 0, Ns = 1, Nr = 3
handle_avps: handling avp's for tunnel 49146, call 33308
message_type_avp: message type 11 (Incoming-Call-Reply)
assigned_call_avp: using peer's call 40031
control_finish: Call established with 195.149.70.70, Local: 33308, Remote: 40031, Serial: 1
getPtyMaster: No more free pseudo-tty's
start_pppd: unable to allocate pty, abandoning!
check_control: control, cid = 40031, Ns = 2, Nr = 4
check_control: control, cid = 40031, Ns = 2, Nr = 4
handle_avps: handling avp's for tunnel 49146, call 33308
message_type_avp: message type 16 (Set-Link-Info)
ignore_avp : Ignoring AVP
check_control: control, cid = 0, Ns = 3, Nr = 4
handle_avps: handling avp's for tunnel 49146, call 0
message_type_avp: message type 6 (Hello)
check_control: control, cid = 0, Ns = 4, Nr = 4
handle_avps: handling avp's for tunnel 49146, call 0
message_type_avp: message type 6 (Hello)
check_control: control, cid = 0, Ns = 5, Nr = 4
handle_avps: handling avp's for tunnel 49146, call 0
message_type_avp: message type 6 (Hello)
...
```
And the StrongSwan's log at the moment of l2tpd trying to connect:

```
Dec 18 09:18:50 14[KNL] creating acquire job for policy 10.1.1.99/32[udp] === 195.149.70.70/32[udp/l2f] with reqid {1}
Dec 18 09:18:50 13[IKE] initiating Main Mode IKE_SA vpn-uz[1] to 195.149.70.70
Dec 18 09:18:50 13[ENC] generating ID_PROT request 0 [ SA V V V V V ]
Dec 18 09:18:50 13[NET] sending packet: from 10.1.1.99[500] to 195.149.70.70[500] (240 bytes)
Dec 18 09:18:50 14[NET] received packet: from 195.149.70.70[500] to 10.1.1.99[500] (128 bytes)
Dec 18 09:18:50 14[ENC] parsed ID_PROT response 0 [ SA V V ]
Dec 18 09:18:50 14[IKE] received NAT-T (RFC 3947) vendor ID
Dec 18 09:18:50 14[IKE] received FRAGMENTATION vendor ID
Dec 18 09:18:50 14[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
Dec 18 09:18:50 14[NET] sending packet: from 10.1.1.99[500] to 195.149.70.70[500] (244 bytes)
Dec 18 09:18:50 14[NET] received packet: from 195.149.70.70[500] to 10.1.1.99[500] (304 bytes)
Dec 18 09:18:50 14[ENC] parsed ID_PROT response 0 [ KE No V V V V NAT-D NAT-D ]
Dec 18 09:18:50 14[IKE] received Cisco Unity vendor ID
Dec 18 09:18:50 14[IKE] received XAuth vendor ID
Dec 18 09:18:50 14[ENC] received unknown vendor ID: d3:fd:75:e4:51:5a:08:26:b4:d6:10:2c:92:6f:6e:34
Dec 18 09:18:50 14[ENC] received unknown vendor ID: 1f:07:f7:0e:aa:65:14:d3:b0:fa:96:54:2a:50:01:00
Dec 18 09:18:50 14[IKE] local host is behind NAT, sending keep alives
Dec 18 09:18:50 14[ENC] generating ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ]
Dec 18 09:18:50 14[NET] sending packet: from 10.1.1.99[4500] to 195.149.70.70[4500] (108 bytes)
Dec 18 09:18:50 14[NET] received packet: from 195.149.70.70[4500] to 10.1.1.99[4500] (92 bytes)
Dec 18 09:18:50 14[ENC] parsed ID_PROT response 0 [ ID HASH V ]
Dec 18 09:18:50 14[IKE] received DPD vendor ID
Dec 18 09:18:50 14[IKE] IKE_SA vpn-uz[1] established between 10.1.1.99[10.1.1.99]...195.149.70.70[195.149.70.70]
Dec 18 09:18:50 14[IKE] scheduling reauthentication in 10227s
Dec 18 09:18:50 14[IKE] maximum IKE_SA lifetime 10767s
Dec 18 09:18:50 14[ENC] generating QUICK_MODE request 723898552 [ HASH SA No ID ID NAT-OA NAT-OA ]
Dec 18 09:18:50 14[NET] sending packet: from 10.1.1.99[4500] to 195.149.70.70[45
00] (220 bytes)
Dec 18 09:18:50 14[NET] received packet: from 195.149.70.70[4500] to 10.1.1.99[4500] (188 bytes)
Dec 18 09:18:50 14[ENC] parsed QUICK_MODE response 723898552 [ HASH SA No ID ID NAT-OA NAT-OA ]
Dec 18 09:18:50 14[IKE] CHILD_SA vpn-uz{3} established with SPIs cc43a242_i 97bc78cf_o and TS 10.1.1.99/32[udp] === 195.149.70.70/32[udp/l2f]
Dec 18 09:18:50 14[ENC] generating QUICK_MODE request 723898552 [ HASH ]
Dec 18 09:18:50 14[NET] sending packet: from 10.1.1.99[4500] to 195.149.70.70[4500] (60 bytes)
Dec 18 09:19:22 16[NET] received packet: from 195.149.70.70[4500] to 10.1.1.99[4500] (76 bytes)
Dec 18 09:19:22 16[ENC] parsed INFORMATIONAL_V1 request 705272029 [ HASH D ]
Dec 18 09:19:22 16[IKE] received DELETE for ESP CHILD_SA with SPI 97bc78cf
Dec 18 09:19:22 16[IKE] closing CHILD_SA vpn-uz{3} with SPIs cc43a242_i (592 bytes) 97bc78cf_o (968 bytes) and TS 10.1.1.99/32[udp] === 195.149.70.70/32[udp/l2f]
Dec 18 09:19:22 16[NET] received packet: from 195.149.70.70[4500] to 10.1.1.99[4500] (92 bytes)
Dec 18 09:19:22 16[ENC] parsed INFORMATIONAL_V1 request 1270181315 [ HASH D ]
Dec 18 09:19:22 16[IKE] received DELETE for IKE_SA vpn-uz[1]
Dec 18 09:19:22 16[IKE] deleting IKE_SA vpn-uz[1] between 10.1.1.99[10.1.1.99]...195.149.70.70[195.149.70.70]
```


----------



## obsigna (Dec 18, 2018)

Seems that you did not configure the ppp daemon. Something alike:

/usr/local/etc/l2tpd.conf:

```
...
pppoptfile = /etc/ppp/ppp-l2tp.opts
...
```

/etc/ppp/ppp-l2tp.opts

```
nodetach
usepeerdns
noipdefault
nodefaultroute
noauth
noccp
refuse-eap
refuse-chap
refuse-mschap
refuse-mschap-v2
lcp-echo-failure 0
lcp-echo-interval 0
mru 1410
mtu 1410
user LOGIN
password PASSWORD
```

I have no experience with net/l2tpd and ppp(8). At least the above should configure ppp to create an endpoint for the l2tpd connection.

See also: https://forums.freebsd.org/threads/l2tpd-troubleshooting-on-freebsd-11-1.64119/


----------



## lycosa32 (Jan 31, 2019)

yurybx said:


> I configured the l2tpd as instructed, but the connection is not established: "No more free pseudo-tty's".


Guys, have you managed to connect the BSD client to the ipsec/l2tp server yet? Regarding "no more pseudo-tty's", most likely you have to load pty.ko module by executing "kldload pty". I am pulling my hair out trying to connect to my corporate VPN server. It seems a trivial task for Windows, Linux and even Android clients. I have almost the same settings in ipsec.conf and mpd.conf and in my case StrongSwan establishes the connection, MPD5 establishes the connection too, I can even ping the host inside the corporate network. But as soon as I try to get a file via FTP or to launch RDP session I see exactly the same picture with "LCP: no reply to 1 echo request(s)" and I have to restart MPD5.


----------



## yurybx (Mar 5, 2019)

No, I never managed to get the L2TP / IPSeс connection to work. I even installed CentOS and did everything according to the instructions from the service provider, but my connection still breaks immediately after the establishment. I am at a dead end, I do not know what to do.


----------

