I have a problem with the SSTP VPN client dial on demand.
When dial on demand is switched off, it works normally but when I enable dial on demand and it should connect (dial), it connects and disconnects and so on…
Tested on RB2011 and RB532 ROS 6.30.4
Config (RB532):
/interface sstp-client
add authentication=mschap2 connect-to=a.b.c.d dial-on-demand=yes \
disabled=no keepalive-timeout=disabled name=VPN password=yyy pfs=yes \
profile=encryption-limit user=xxx \
verify-server-address-from-certificate=no
/ppp profile
add idle-timeout=1m name=encryption-limit session-timeout=1d use-compression=\
no use-encryption=required
Log with dial on demand enabled:
12:22:12 sstp,ppp,info VPN: initializing...
12:22:12 sstp,ppp,debug VPN: IPCP demandUp
12:22:12 sstp,ppp,debug VPN: MPLSCP demandUp
12:22:12 sstp,ppp,info VPN: waiting for packets...
12:24:37 sstp,ppp,info VPN: connecting...
12:24:40 sstp,packet VPN sending
12:24:40 sstp,packet SSTP_DUPLEX_POST /sra_{BA195980-CD49-458b-9E23-C84EE0ADCD75}/ HTTP/1.1\r
12:24:40 sstp,packet Content-Length: 18446744073709551615\r
12:24:40 sstp,packet Host: 0.0.0.0\r
12:24:40 sstp,packet \r
12:24:40 sstp,packet
12:24:40 sstp,packet VPN recv
12:24:40 sstp,packet HTTP/1.1 200 OK\r
12:24:40 sstp,packet Content-Length: 18446744073709551615\r
12:24:40 sstp,packet Date: Fri, 04 Sep 2015 10:24:40 GMT\r
12:24:40 sstp,packet Server: Microsoft-HTTPAPI/2.0\r
12:24:40 sstp,packet \r
12:24:40 sstp,packet
12:24:40 sstp,packet VPN sent control packet type: connect request
12:24:40 sstp,packet 10 01 00 0e 00 01 00 01 00 01 00 06 00 01
12:24:40 sstp,packet VPN recv control packet type: connect ack
12:24:40 sstp,packet 10 01 00 30 00 02 00 01 00 04 00 28 00 00 00 02
12:24:40 sstp,packet 6e 69 29 30 6f d0 9e e4 dc 85 c7 a4 e5 55 03 24
12:24:40 sstp,packet 31 98 ef 55 da f2 9b 35 6d b9 63 02 04 65 35 2d
12:24:40 sstp,ppp,debug VPN: LCP lowerup
12:24:40 sstp,ppp,debug VPN: LCP open
12:24:40 sstp,ppp,debug,packet VPN: sent LCP ConfReq id=0x1
12:24:40 sstp,ppp,debug,packet <magic 0x20fa3f76>
12:24:40 sstp,ppp,debug,packet VPN: rcvd LCP ConfReq id=0x0
12:24:40 sstp,ppp,debug,packet <auth pap>
12:24:40 sstp,ppp,debug,packet VPN: sent LCP ConfRej id=0x0
12:24:40 sstp,ppp,debug,packet <auth pap>
12:24:40 sstp,ppp,debug,packet VPN: rcvd LCP ConfRej id=0x1
12:24:40 sstp,ppp,debug,packet <magic 0x20fa3f76>
12:24:40 sstp,ppp,debug,packet VPN: sent LCP ConfReq id=0x2
12:24:40 sstp,ppp,debug,packet VPN: rcvd LCP ConfReq id=0x1
12:24:40 sstp,ppp,debug,packet <auth mschap2>
12:24:40 sstp,ppp,debug,packet VPN: sent LCP ConfAck id=0x1
12:24:40 sstp,ppp,debug,packet <auth mschap2>
12:24:40 sstp,ppp,debug,packet VPN: rcvd LCP TermReq id=0x2
12:24:40 sstp,ppp,debug,packet VPN: sent LCP TermAck id=0x2
12:24:40 sstp,ppp,debug VPN: LCP lowerdown
12:24:40 sstp,ppp,info VPN: terminating...
12:24:40 sstp,ppp,debug VPN: LCP lowerdown
12:24:40 sstp,ppp,debug VPN: LCP down event in starting state
12:24:40 sstp,ppp,info VPN: disconnected
12:24:40 sstp,ppp,info VPN: initializing...
12:24:40 sstp,ppp,debug VPN: IPCP demandUp
12:24:40 sstp,ppp,debug VPN: MPLSCP demandUp
12:24:40 sstp,ppp,info VPN: waiting for packets...
12:24:47 sstp,ppp,info VPN: connecting...
12:24:48 sstp,packet VPN sending
12:24:48 sstp,packet SSTP_DUPLEX_POST /sra_{BA195980-CD49-458b-9E23-C84EE0ADCD75}/ HTTP/1.1\r
12:24:48 sstp,packet Content-Length: 18446744073709551615\r
12:24:48 sstp,packet Host: 0.0.0.0\r
12:24:48 sstp,packet \r
12:24:48 sstp,packet
12:24:48 sstp,packet VPN recv
12:24:48 sstp,packet HTTP/1.1 200 OK\r
12:24:48 sstp,packet Content-Length: 18446744073709551615\r
12:24:48 sstp,packet Date: Fri, 04 Sep 2015 10:24:48 GMT\r
12:24:48 sstp,packet Server: Microsoft-HTTPAPI/2.0\r
12:24:48 sstp,packet \r
12:24:48 sstp,packet
12:24:48 sstp,packet VPN sent control packet type: connect request
12:24:48 sstp,packet 10 01 00 0e 00 01 00 01 00 01 00 06 00 01
12:24:48 sstp,packet VPN recv control packet type: connect ack
12:24:48 sstp,packet 10 01 00 30 00 02 00 01 00 04 00 28 00 00 00 02
12:24:48 sstp,packet 2e 42 2a a4 25 08 e6 9f 14 5a 3d a4 8f 81 7d 5e
12:24:48 sstp,packet a2 8b 23 6f 09 82 7a 3a 6c 4e 3a d0 94 7b 1d e2
12:24:48 sstp,ppp,debug VPN: LCP lowerup
12:24:48 sstp,ppp,debug,packet VPN: sent LCP ConfReq id=0x3
12:24:48 sstp,ppp,debug,packet <magic 0xb9388c5>
12:24:48 sstp,ppp,debug VPN: LCP open
12:24:48 sstp,ppp,debug,packet VPN: rcvd LCP ConfReq id=0x0
12:24:48 sstp,ppp,debug,packet <auth pap>
12:24:48 sstp,ppp,debug,packet VPN: sent LCP ConfRej id=0x0
12:24:48 sstp,ppp,debug,packet <auth pap>
12:24:48 sstp,ppp,debug,packet VPN: rcvd LCP ConfRej id=0x3
12:24:48 sstp,ppp,debug,packet <magic 0xb9388c5>
12:24:48 sstp,ppp,debug,packet VPN: sent LCP ConfReq id=0x4
12:24:48 sstp,ppp,debug,packet VPN: rcvd LCP ConfReq id=0x1
12:24:48 sstp,ppp,debug,packet <auth mschap2>
12:24:48 sstp,ppp,debug,packet VPN: sent LCP ConfAck id=0x1
12:24:48 sstp,ppp,debug,packet <auth mschap2>
12:24:48 sstp,ppp,debug,packet VPN: rcvd LCP TermReq id=0x2
12:24:48 sstp,ppp,debug,packet VPN: sent LCP TermAck id=0x2
12:24:48 sstp,ppp,debug VPN: LCP lowerdown
12:24:48 sstp,ppp,info VPN: terminating...
12:24:48 sstp,ppp,debug VPN: LCP lowerdown
12:24:48 sstp,ppp,debug VPN: LCP down event in starting state
12:24:48 sstp,ppp,info VPN: disconnected
12:24:48 sstp,ppp,info VPN: initializing...
12:24:48 sstp,ppp,debug VPN: IPCP demandUp
12:24:48 sstp,ppp,debug VPN: MPLSCP demandUp
12:24:48 sstp,ppp,info VPN: waiting for packets...
12:24:58 sstp,ppp,info VPN: connecting...
12:24:58 sstp,packet VPN sending
12:24:58 sstp,packet SSTP_DUPLEX_POST /sra_{BA195980-CD49-458b-9E23-C84EE0ADCD75}/ HTTP/1.1\r
12:24:58 sstp,packet Content-Length: 18446744073709551615\r
12:24:58 sstp,packet Host: 0.0.0.0\r
12:24:58 sstp,packet \r
12:24:58 sstp,packet
12:24:58 sstp,packet VPN recv
12:24:58 sstp,packet HTTP/1.1 200 OK\r
12:24:58 sstp,packet Content-Length: 18446744073709551615\r
12:24:58 sstp,packet Date: Fri, 04 Sep 2015 10:24:58 GMT\r
12:24:58 sstp,packet Server: Microsoft-HTTPAPI/2.0\r
12:24:58 sstp,packet \r
12:24:58 sstp,packet
12:24:58 sstp,packet VPN sent control packet type: connect request
12:24:58 sstp,packet 10 01 00 0e 00 01 00 01 00 01 00 06 00 01
12:24:58 sstp,packet VPN recv control packet type: connect ack
12:24:58 sstp,packet 10 01 00 30 00 02 00 01 00 04 00 28 00 00 00 02
12:24:58 sstp,packet 24 09 13 47 fe af 61 9f f5 70 71 79 cb b6 c3 2d
12:24:58 sstp,packet 2b a6 18 2b 27 54 af 66 0c 62 81 81 74 6d 9e 7e
12:24:58 sstp,ppp,debug VPN: LCP lowerup
12:24:58 sstp,ppp,debug,packet VPN: sent LCP ConfReq id=0x5
12:24:58 sstp,ppp,debug,packet <magic 0x308838bd>
12:24:58 sstp,ppp,debug VPN: LCP open
12:24:58 sstp,ppp,debug,packet VPN: rcvd LCP ConfReq id=0x0
12:24:58 sstp,ppp,debug,packet <auth pap>
12:24:58 sstp,ppp,debug,packet VPN: sent LCP ConfRej id=0x0
12:24:58 sstp,ppp,debug,packet <auth pap>
12:24:58 sstp,ppp,debug,packet VPN: rcvd LCP ConfRej id=0x5
12:24:58 sstp,ppp,debug,packet <magic 0x308838bd>
12:24:58 sstp,ppp,debug,packet VPN: sent LCP ConfReq id=0x6
12:24:58 sstp,ppp,debug,packet VPN: rcvd LCP ConfReq id=0x1
12:24:58 sstp,ppp,debug,packet <auth mschap2>
12:24:58 sstp,ppp,debug,packet VPN: sent LCP ConfAck id=0x1
12:24:58 sstp,ppp,debug,packet <auth mschap2>
12:24:58 sstp,ppp,debug,packet VPN: rcvd LCP TermReq id=0x2
12:24:58 sstp,ppp,debug,packet VPN: sent LCP TermAck id=0x2
12:24:58 sstp,ppp,debug VPN: LCP lowerdown
12:24:58 sstp,ppp,info VPN: terminating...
12:24:58 sstp,ppp,debug VPN: LCP lowerdown
12:24:58 sstp,ppp,debug VPN: LCP down event in starting state
12:24:58 sstp,ppp,info VPN: disconnected
12:24:59 sstp,ppp,info VPN: initializing...
12:24:59 sstp,ppp,debug VPN: IPCP demandUp
12:24:59 sstp,ppp,debug VPN: MPLSCP demandUp
12:24:59 sstp,ppp,info VPN: waiting for packets...
Log with dial on demand disabled for comparison:
12:28:12 sstp,ppp,info VPN: initializing...
12:28:12 sstp,ppp,info VPN: connecting...
12:28:14 sstp,packet VPN sending
12:28:14 sstp,packet SSTP_DUPLEX_POST /sra_{BA195980-CD49-458b-9E23-C84EE0ADCD75}/ HTTP/1.1\r
12:28:14 sstp,packet Content-Length: 18446744073709551615\r
12:28:14 sstp,packet Host: 0.0.0.0\r
12:28:14 sstp,packet \r
12:28:14 sstp,packet
12:28:14 sstp,packet VPN recv
12:28:14 sstp,packet HTTP/1.1 200 OK\r
12:28:14 sstp,packet Content-Length: 18446744073709551615\r
12:28:14 sstp,packet Date: Fri, 04 Sep 2015 10:28:43 GMT\r
12:28:14 sstp,packet Server: Microsoft-HTTPAPI/2.0\r
12:28:14 sstp,packet \r
12:28:14 sstp,packet
12:28:14 sstp,packet VPN sent control packet type: connect request
12:28:14 sstp,packet 10 01 00 0e 00 01 00 01 00 01 00 06 00 01
12:28:14 sstp,packet VPN recv control packet type: connect ack
12:28:14 sstp,packet 10 01 00 30 00 02 00 01 00 04 00 28 00 00 00 02
12:28:14 sstp,packet f3 1a b6 58 5f 3a 2e 9f 2c d2 21 82 bc f4 ca 52
12:28:14 sstp,packet 51 fa 1f ea 7d 65 e3 a4 d9 cd 92 70 09 bf d7 a0
12:28:14 sstp,ppp,debug VPN: LCP lowerup
12:28:14 sstp,ppp,debug VPN: LCP open
12:28:14 sstp,ppp,debug,packet VPN: sent LCP ConfReq id=0x1
12:28:14 sstp,ppp,debug,packet <magic 0x985e8c1>
12:28:15 sstp,ppp,debug,packet VPN: rcvd LCP ConfReq id=0x0
12:28:15 sstp,ppp,debug,packet <auth pap>
12:28:15 sstp,ppp,debug,packet VPN: sent LCP ConfRej id=0x0
12:28:15 sstp,ppp,debug,packet <auth pap>
12:28:15 sstp,ppp,debug,packet VPN: rcvd LCP ConfRej id=0x1
12:28:15 sstp,ppp,debug,packet <magic 0x985e8c1>
12:28:15 sstp,ppp,debug,packet VPN: sent LCP ConfReq id=0x2
12:28:15 sstp,ppp,debug,packet VPN: rcvd LCP ConfReq id=0x1
12:28:15 sstp,ppp,debug,packet <auth mschap2>
12:28:15 sstp,ppp,debug,packet VPN: sent LCP ConfAck id=0x1
12:28:15 sstp,ppp,debug,packet <auth mschap2>
12:28:15 sstp,ppp,debug,packet VPN: rcvd LCP ConfAck id=0x2
12:28:15 sstp,ppp,debug VPN: LCP opened
12:28:15 sstp,ppp,debug,packet VPN: rcvd CHAP Challenge id=0x0
12:28:15 sstp,ppp,debug,packet <challenge len=16>
12:28:15 sstp,ppp,debug,packet <name abcd>
12:28:15 sstp,ppp,debug,packet VPN: sent CHAP Response id=0x0
12:28:15 sstp,ppp,debug,packet <response len=49>
12:28:15 sstp,ppp,debug,packet <name xxx>
12:28:15 sstp,ppp,debug,packet VPN: rcvd CHAP Success id=0x0
12:28:15 sstp,ppp,debug,packet S=DD5DB5EF7CC1D61E9D636862A68FF6D9370A9601
12:28:15 sstp,ppp,info VPN: authenticated
12:28:15 sstp,packet VPN sent control packet type: connected
12:28:15 sstp,packet 10 01 00 70 00 04 00 01 00 03 00 68 00 00 00 02
12:28:15 sstp,packet f3 1a b6 58 5f 3a 2e 9f 2c d2 21 82 bc f4 ca 52
12:28:15 sstp,packet 51 fa 1f ea 7d 65 e3 a4 d9 cd 92 70 09 bf d7 a0
12:28:15 sstp,packet 23 e6 c1 99 ca f4 d6 e0 65 f9 3c cb 54 12 5c 16
12:28:15 sstp,packet cb ae 77 9e 09 95 fe cd 65 b3 96 b4 c9 a7 f5 a6
12:28:15 sstp,packet 2f f3 49 a5 71 d6 48 2c 32 7c 4b 09 62 1c 0a 13
12:28:15 sstp,packet 43 c9 fe 8a 16 e4 72 b2 94 9d 56 30 f2 82 da 7f
12:28:15 sstp,ppp,debug VPN: IPCP lowerup
12:28:15 sstp,ppp,debug VPN: IPCP open
12:28:15 sstp,ppp,debug,packet VPN: sent IPCP ConfReq id=0x1
12:28:15 sstp,ppp,debug,packet <addr 0.0.0.0>
12:28:15 sstp,ppp,debug VPN: IPV6CP open
12:28:15 sstp,ppp,debug VPN: MPLSCP lowerup
12:28:15 sstp,ppp,debug VPN: MPLSCP open
12:28:15 sstp,ppp,debug,packet VPN: sent MPLSCP ConfReq id=0x1
12:28:15 sstp,ppp,debug VPN: BCP open
12:28:15 sstp,ppp,debug VPN: CCP lowerup
12:28:15 sstp,ppp,debug VPN: CCP open
12:28:15 sstp,packet VPN recv control packet type: echo request
12:28:15 sstp,packet 10 01 00 08 00 08 00 00
12:28:15 sstp,packet VPN sent control packet type: echo response
12:28:15 sstp,packet 10 01 00 08 00 09 00 00
Any ideas what is wrong with my config?
Or is it a ROS bug?