Hello, I've installed OpenSwan with xl2tpd on my server, and set it up for roadwarriors connecting using certificates.
My server is Debian 5.0.8, I am running xl2tpd 1.2.0, and Openswan IPsec 2.4.12, my clients are all Windows, and I am testing my setup on a Windows 7 client.
I have no problem connecting to the server, but after some time the connection drops. I removed the idle option from the ppp config but it does not make any difference.
Even when I create constant traffic with ping -t the connection drops also.
I have no problems reconnecting right away.
I have been hacking at this for a couple of days, reading every post I can find, but I have not found a solution to my problem.
Here are my configs and logs:
CONFIG FILES:
/etc/ppp/option.l2tpd
-----------------------------
ms-dns 10.248.75.4
ms-wins 10.248.75.4
asyncmap 0
auth
crtscts
lock
show-password
mru 1200
kdebug 2
dump
mtu 1200
proxyarp
lcp-echo-interval 30
lcp-echo-failure 2000
ipcp-accept-local
ipcp-accept-remote
noipx
connect-delay 5000
nodefaultroute
nologfd
logfile /var/log/ppp.log
-------------------------------
/etc/xl2tpd/xl2tpd.conf
-------------------------------
[global]
listen-addr=216.218.16.124
auth file = /etc/xl2tpd/l2tp-secrets
debug avp=yes
debug state=yes
debug tunnel=yes
[lns default]
ip range = 10.248.75.230-10.248.75.239
local ip = 10.248.75.254
length bit = yes
require chap = yes
refuse pap = yes
require authentication = yes
name = sds.educexpert.com
ppp debug = yes
pppoptfile = /etc/ppp/options.l2tpd
-------------------------------
/etc/ipsec.conf
-------------------------------
version 2.0
config setup
nat_traversal=yes
virtual_private=%v4:10.0.0.0/8,%v4:192.168.0.0/16,%v4:172.16.0.0/12
nhelpers=2
plutodebug="all"
conn l2tp-X.509
authby=rsasig
pfs=no
auto=add
rekey=no
left=216.218.16.124
leftrsasigkey=%cert
leftcert=/etc/ipsec.d/certs/sds.educexpert.com.pem
leftsubnet=10.248.75.0/24
leftprotoport=17/1701
# The remote user.
right=%any
rightca=%same
rightrsasigkey=%cert
rightprotoport=17/%any
rightsubnet=vhost:%priv,%no
conn block
auto=ignore
conn private
auto=ignore
conn private-or-clear
auto=ignore
conn clear-or-private
auto=ignore
conn clear
auto=ignore
conn packetdefault
auto=ignore
-------------------------------
LOGS:
/var/log/syslog
-------------------------------
Feb 17 11:58:25 sds xl2tpd[7698]: get_call: allocating new tunnel for host 72.14.204.99, port 1701.
Feb 17 11:58:25 sds xl2tpd[7698]: handle_avps: handling avp's for tunnel 14774, call 33326
Feb 17 11:58:25 sds xl2tpd[7698]: message_type_avp: message type 1 (Start-Control-Connection-Request)
Feb 17 11:58:25 sds xl2tpd[7698]: protocol_version_avp: peer is using version 1, revision 0.
Feb 17 11:58:25 sds xl2tpd[7698]: framing_caps_avp: supported peer frames: sync
Feb 17 11:58:25 sds xl2tpd[7698]: bearer_caps_avp: supported peer bearers:
Feb 17 11:58:25 sds xl2tpd[7698]: firmware_rev_avp: peer reports firmware version 1537 (0x0601)
Feb 17 11:58:25 sds xl2tpd[7698]: hostname_avp: peer reports hostname 'some-PC'
Feb 17 11:58:25 sds xl2tpd[7698]: vendor_avp: peer reports vendor 'Microsoft'
Feb 17 11:58:25 sds xl2tpd[7698]: assigned_tunnel_avp: using peer's tunnel 56
Feb 17 11:58:25 sds xl2tpd[7698]: receive_window_size_avp: peer wants RWS of 8. Will use flow control.
Feb 17 11:58:25 sds xl2tpd[7698]: control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 56, call is 0.
Feb 17 11:58:25 sds xl2tpd[7698]: control_finish: sending SCCRP
Feb 17 11:58:27 sds xl2tpd[7698]: get_call: allocating new tunnel for host 72.14.204.99, port 1701.
Feb 17 11:58:27 sds xl2tpd[7698]: handle_avps: handling avp's for tunnel 44570, call 3058
Feb 17 11:58:27 sds xl2tpd[7698]: message_type_avp: message type 1 (Start-Control-Connection-Request)
Feb 17 11:58:27 sds xl2tpd[7698]: protocol_version_avp: peer is using version 1, revision 0.
Feb 17 11:58:27 sds xl2tpd[7698]: framing_caps_avp: supported peer frames: sync
Feb 17 11:58:27 sds xl2tpd[7698]: bearer_caps_avp: supported peer bearers:
Feb 17 11:58:27 sds xl2tpd[7698]: firmware_rev_avp: peer reports firmware version 1537 (0x0601)
Feb 17 11:58:27 sds xl2tpd[7698]: hostname_avp: peer reports hostname 'some-PC'
Feb 17 11:58:27 sds xl2tpd[7698]: vendor_avp: peer reports vendor 'Microsoft'
Feb 17 11:58:27 sds xl2tpd[7698]: assigned_tunnel_avp: using peer's tunnel 56
Feb 17 11:58:27 sds xl2tpd[7698]: receive_window_size_avp: peer wants RWS of 8. Will use flow control.
Feb 17 11:58:27 sds xl2tpd[7698]: control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 56, call is 0.
Feb 17 11:58:27 sds xl2tpd[7698]: control_finish: Peer requested tunnel 56 twice, ignoring second one.
Feb 17 11:58:27 sds xl2tpd[7698]: build_fdset: closing down tunnel 44570
Feb 17 11:58:27 sds xl2tpd[7698]: handle_avps: handling avp's for tunnel 14774, call 33326
Feb 17 11:58:27 sds xl2tpd[7698]: message_type_avp: message type 3 (Start-Control-Connection-Connected)
Feb 17 11:58:27 sds xl2tpd[7698]: control_finish: message type is Start-Control-Connection-Connected(3). Tunnel is 56, call is 0.
Feb 17 11:58:27 sds xl2tpd[7698]: Connection established to 72.14.204.99, 1701. Local: 14774, Remote: 56 (ref=0/0). LNS session is 'default'
Feb 17 11:58:27 sds xl2tpd[7698]: check_control: Received out of order control packet on tunnel 56 (got 3, expected 2)
Feb 17 11:58:27 sds xl2tpd[7698]: handle_packet: bad control packet!
Feb 17 11:58:27 sds xl2tpd[7698]: network_thread: bad packet
Feb 17 11:58:27 sds xl2tpd[7698]: handle_avps: handling avp's for tunnel 14774, call 33326
Feb 17 11:58:27 sds xl2tpd[7698]: message_type_avp: message type 10 (Incoming-Call-Request)
Feb 17 11:58:27 sds xl2tpd[7698]: message_type_avp: new incoming call
Feb 17 11:58:27 sds xl2tpd[7698]: assigned_call_avp: using peer's call 1
Feb 17 11:58:27 sds xl2tpd[7698]: call_serno_avp: serial number is 0
Feb 17 11:58:27 sds xl2tpd[7698]: bearer_type_avp: peer bears: analog
Feb 17 11:58:27 sds xl2tpd[7698]: result_code_avp: result code not appropriate for Incoming-Call-Request. Ignoring.
Feb 17 11:58:27 sds xl2tpd[7698]: control_finish: message type is Incoming-Call-Request(10). Tunnel is 56, call is 0.
Feb 17 11:58:27 sds xl2tpd[7698]: control_finish: Sending ICRP
Feb 17 11:58:27 sds xl2tpd[7698]: handle_avps: handling avp's for tunnel 14774, call 53782
Feb 17 11:58:27 sds xl2tpd[7698]: message_type_avp: message type 12 (Incoming-Call-Connected)
Feb 17 11:58:27 sds xl2tpd[7698]: tx_speed_avp: transmit baud rate is 100000000
Feb 17 11:58:27 sds xl2tpd[7698]: frame_type_avp: peer uses:sync frames
Feb 17 11:58:27 sds xl2tpd[7698]: ignore_avp : Ignoring AVP
Feb 17 11:58:27 sds xl2tpd[7698]: control_finish: message type is Incoming-Call-Connected(12). Tunnel is 56, call is 1.
Feb 17 11:58:27 sds xl2tpd[7698]: start_pppd: I'm running:
Feb 17 11:58:27 sds xl2tpd[7698]: "/usr/sbin/pppd"
Feb 17 11:58:27 sds xl2tpd[7698]: "passive"
Feb 17 11:58:27 sds xl2tpd[7698]: "-detach"
Feb 17 11:58:27 sds xl2tpd[7698]: "10.248.75.254:10.248.75.230"
Feb 17 11:58:27 sds xl2tpd[7698]: "refuse-pap"
Feb 17 11:58:27 sds xl2tpd[7698]: "auth"
Feb 17 11:58:27 sds xl2tpd[7698]: "require-chap"
Feb 17 11:58:27 sds xl2tpd[7698]: "name"
Feb 17 11:58:27 sds xl2tpd[7698]: "sds.educexpert.com"
Feb 17 11:58:27 sds xl2tpd[7698]: "debug"
Feb 17 11:58:27 sds xl2tpd[7698]: "file"
Feb 17 11:58:27 sds xl2tpd[7698]: "/etc/ppp/options.l2tpd"
Feb 17 11:58:27 sds xl2tpd[7698]: "/dev/pts/1"
Feb 17 11:58:27 sds xl2tpd[7698]: Call established with 72.14.204.99, Local: 53782, Remote: 1, Serial: 0
Feb 17 11:58:27 sds pppd[8141]: pppd options in effect:
Feb 17 11:58:27 sds pppd[8141]: debug #011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: kdebug 2#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: -detach#011#011# (from command line)
Feb 17 11:58:27 sds pppd[8141]: logfile /var/log/ppp.log#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: connect-delay 5000#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: dump#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: auth#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: refuse-pap#011#011# (from command line)
Feb 17 11:58:27 sds pppd[8141]: name sds.educexpert.com#011#011# (from command line)
Feb 17 11:58:27 sds pppd[8141]: /dev/pts/1#011#011# (from command line)
Feb 17 11:58:27 sds pppd[8141]: lock#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: crtscts#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: modem#011#011# (from /etc/ppp/options)
Feb 17 11:58:27 sds pppd[8141]: asyncmap 0#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: mru 1200#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: mtu 1200#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: passive#011#011# (from command line)
Feb 17 11:58:27 sds pppd[8141]: lcp-echo-failure 2000#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: lcp-echo-interval 30#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: show-password#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: ipcp-accept-local#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: ipcp-accept-remote#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: ms-dns xxx # [don't know how to print value]#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: ms-wins xxx # [don't know how to print value]#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: nodefaultroute#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: proxyarp#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: 10.248.75.254:10.248.75.230#011#011# (from command line)
Feb 17 11:58:27 sds pppd[8141]: noipx#011#011# (from /etc/ppp/options.l2tpd)
Feb 17 11:58:27 sds pppd[8141]: pppd 2.4.4 started by root, uid 0
Feb 17 11:58:27 sds pppd[8141]: using channel 16
Feb 17 11:58:27 sds pppd[8141]: Using interface ppp0
Feb 17 11:58:27 sds pppd[8141]: Connect: ppp0 <--> /dev/pts/1
Feb 17 11:58:27 sds pppd[8141]: sent [LCP ConfReq id=0x1 <mru 1200> <asyncmap 0x0> <auth chap MD5> <magic 0xe07db3f9> <pcomp> <accomp>]
Feb 17 11:58:27 sds pppd[8141]: rcvd [LCP ConfReq id=0x0 <mru 1400> <magic 0x17ea6c4d> <pcomp> <accomp> <callback CBCP>]
Feb 17 11:58:27 sds pppd[8141]: sent [LCP ConfRej id=0x0 <callback CBCP>]
Feb 17 11:58:27 sds pppd[8141]: rcvd [LCP ConfAck id=0x1 <mru 1200> <asyncmap 0x0> <auth chap MD5> <magic 0xe07db3f9> <pcomp> <accomp>]
Feb 17 11:58:27 sds pppd[8141]: rcvd [LCP ConfReq id=0x1 <mru 1400> <magic 0x17ea6c4d> <pcomp> <accomp>]
Feb 17 11:58:27 sds pppd[8141]: sent [LCP ConfAck id=0x1 <mru 1400> <magic 0x17ea6c4d> <pcomp> <accomp>]
Feb 17 11:58:27 sds pppd[8141]: sent [LCP EchoReq id=0x0 magic=0xe07db3f9]
Feb 17 11:58:27 sds pppd[8141]: sent [CHAP Challenge id=0xa5 <96563d3aa83972355630358ec59348b894a8cb112a4aee>, name = "sds.educexpert.com"]
Feb 17 11:58:27 sds pppd[8141]: rcvd [LCP Ident id=0x2 magic=0x17ea6c4d "MSRASV5.20"]
Feb 17 11:58:27 sds pppd[8141]: rcvd [LCP Ident id=0x3 magic=0x17ea6c4d "MSRAS-0-SOME-PC"]
Feb 17 11:58:27 sds pppd[8141]: rcvd [LCP Ident id=0x4 magic=0x17ea6c4d "\001\014\\\37777777600\37777777747\37777777675-D\37777777657\377777776459\004\37777777620\37777777712\37777777652-"]
Feb 17 11:58:27 sds pppd[8141]: rcvd [LCP EchoRep id=0x0 magic=0x17ea6c4d]
Feb 17 11:58:27 sds pppd[8141]: rcvd [CHAP Response id=0xa5 <03463e9bd02b8cce14ea1ca4c31f536e>, name = "rlanteigne"]
Feb 17 11:58:27 sds pppd[8141]: sent [CHAP Success id=0xa5 "Access granted"]
Feb 17 11:58:27 sds pppd[8141]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Feb 17 11:58:27 sds pppd[8141]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 10.248.75.254>]
Feb 17 11:58:27 sds pppd[8141]: rcvd [IPCP ConfReq id=0x5 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-wins 0.0.0.0> <ms-dns3 0.0.0.0> <ms-wins 0.0.0.0>]
Feb 17 11:58:27 sds pppd[8141]: sent [IPCP ConfNak id=0x5 <addr 10.248.75.230> <ms-dns1 10.248.75.4> <ms-wins 10.248.75.4> <ms-dns3 10.248.75.4> <ms-wins 10.248.75.4>]
Feb 17 11:58:27 sds pppd[8141]: rcvd [LCP ProtRej id=0x6 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Feb 17 11:58:27 sds pppd[8141]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
Feb 17 11:58:27 sds pppd[8141]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Feb 17 11:58:27 sds pppd[8141]: sent [IPCP ConfReq id=0x2 <addr 10.248.75.254>]
Feb 17 11:58:27 sds pppd[8141]: rcvd [IPCP ConfReq id=0x7 <addr 10.248.75.230> <ms-dns1 10.248.75.4> <ms-wins 10.248.75.4> <ms-dns3 10.248.75.4> <ms-wins 10.248.75.4>]
Feb 17 11:58:27 sds pppd[8141]: sent [IPCP ConfAck id=0x7 <addr 10.248.75.230> <ms-dns1 10.248.75.4> <ms-wins 10.248.75.4> <ms-dns3 10.248.75.4> <ms-wins 10.248.75.4>]
Feb 17 11:58:27 sds pppd[8141]: rcvd [IPCP ConfAck id=0x2 <addr 10.248.75.254>]
Feb 17 11:58:27 sds pppd[8141]: found interface eth2 for proxy arp
Feb 17 11:58:27 sds pppd[8141]: local IP address 10.248.75.254
Feb 17 11:58:27 sds pppd[8141]: remote IP address 10.248.75.230
Feb 17 11:58:27 sds pppd[8141]: Script /etc/ppp/ip-up started (pid 8145)
Feb 17 11:58:27 sds pppd[8141]: Script /etc/ppp/ip-up finished (pid 8145), status = 0x0
Feb 17 11:58:57 sds pppd[8141]: sent [LCP EchoReq id=0x1 magic=0xe07db3f9]
Feb 17 11:58:57 sds pppd[8141]: rcvd [LCP EchoRep id=0x1 magic=0x17ea6c4d]
Feb 17 11:59:27 sds pppd[8141]: sent [LCP EchoReq id=0x2 magic=0xe07db3f9]
Feb 17 11:59:27 sds pppd[8141]: rcvd [LCP EchoRep id=0x2 magic=0x17ea6c4d]
Feb 17 11:59:57 sds pppd[8141]: sent [LCP EchoReq id=0x3 magic=0xe07db3f9]
Feb 17 11:59:57 sds pppd[8141]: rcvd [LCP EchoRep id=0x3 magic=0x17ea6c4d]
(...)
Feb 17 12:04:57 sds pppd[8141]: sent [LCP EchoReq id=0xd magic=0xe07db3f9]
Feb 17 12:04:57 sds pppd[8141]: rcvd [LCP EchoRep id=0xd magic=0x17ea6c4d]
Feb 17 12:05:27 sds pppd[8141]: sent [LCP EchoReq id=0xe magic=0xe07db3f9]
Feb 17 12:05:27 sds pppd[8141]: rcvd [LCP EchoRep id=0xe magic=0x17ea6c4d]
Feb 17 12:05:57 sds pppd[8141]: sent [LCP EchoReq id=0xf magic=0xe07db3f9]
Feb 17 12:06:16 sds xl2tpd[7698]: handle_avps: handling avp's for tunnel 14774, call 33326
Feb 17 12:06:16 sds xl2tpd[7698]: message_type_avp: message type 6 (Hello)
Feb 17 12:06:16 sds xl2tpd[7698]: control_finish: message type is Hello(6). Tunnel is 56, call is 0.
Feb 17 12:06:26 sds xl2tpd[7698]: check_control: Received out of order control packet on tunnel 56 (got 4, expected 5)
Feb 17 12:06:26 sds xl2tpd[7698]: handle_packet: bad control packet!
Feb 17 12:06:26 sds xl2tpd[7698]: network_thread: bad packet
Feb 17 12:06:27 sds pppd[8141]: sent [LCP EchoReq id=0x10 magic=0xe07db3f9]
Feb 17 12:06:32 sds xl2tpd[7698]: Maximum retries exceeded for tunnel 14774. Closing.
Feb 17 12:06:32 sds xl2tpd[7698]: build_fdset: closing down tunnel 14774
Feb 17 12:06:32 sds xl2tpd[7698]: Trustingly terminating pppd: sending TERM signal to pid 8141
Feb 17 12:06:32 sds pppd[8141]: Modem hangup
Feb 17 12:06:32 sds pppd[8141]: Connect time 8.1 minutes.
Feb 17 12:06:32 sds pppd[8141]: Sent 5378 bytes, received 12110 bytes.
Feb 17 12:06:32 sds pppd[8141]: Script /etc/ppp/ip-down started (pid 8174)
Feb 17 12:06:32 sds pppd[8141]: Connection terminated.
Feb 17 12:06:32 sds pppd[8141]: Waiting for 1 child processes...
Feb 17 12:06:32 sds pppd[8141]: script /etc/ppp/ip-down, pid 8174
Feb 17 12:06:32 sds pppd[8141]: Terminating on signal 15
Feb 17 12:06:32 sds pppd[8141]: sending SIGTERM to process 8174
Feb 17 12:06:32 sds pppd[8141]: Exit.
Feb 17 12:06:32 sds xl2tpd[7698]: pppd 8141 successfully terminated
Feb 17 12:06:32 sds xl2tpd[7698]: Connection 56 closed to 72.14.204.99, port 1701 (Timeout)
Feb 17 12:06:33 sds xl2tpd[7698]: get_call: can't find call 53782 in tunnel 14774#012 (ref=0/0)
Feb 17 12:06:33 sds xl2tpd[7698]: network_thread: no such call 42246 on tunnel 0. Sending special ZLB
Feb 17 12:06:36 sds xl2tpd[7698]: check_control: Received out of order control packet on tunnel 56 (got 4, expected 5)
Feb 17 12:06:36 sds xl2tpd[7698]: handle_packet: bad control packet!
Feb 17 12:06:36 sds xl2tpd[7698]: network_thread: bad packet
Feb 17 12:06:37 sds xl2tpd[7698]: Unable to deliver closing message for tunnel 14774. Destroying anyway.
Feb 17 12:06:37 sds xl2tpd[7698]: build_fdset: closing down tunnel 14774
Feb 17 12:06:37 sds xl2tpd[7698]: Can not find tunnel 14774 (refhim=0)
Feb 17 12:06:37 sds xl2tpd[7698]: network_thread: unable to find call or tunnel to handle packet. call = 53782, tunnel = 14774 Dumping.
-------------------------------
Window 7 Diagnostic
-------------------------------------------------------------------------------
C:\Windows\tracing\NDPTSP.LOG
-------------------------------------------------------------------------------
[3340] 12:00:11:743: lineGetDevCaps(62): deviceID(3), TSPIV(30000), ExtV(0)
[3340] 12:00:11:744: lineOpen(62): deviceID(3), htLine(000000000001005A)
[3340] 12:00:11:744: ! SyncDriverRequest: oid(Open), devID(3), reqID(2d9), deviceID(3)
[3340] 12:00:11:744: ! lineOpen: obj(0000000000EC0000)
[3340] 12:00:11:744: ! Guid: e43d242b-9eab-4626a9-5246649fbb939a
[3340] 12:00:11:744: ! MediaType(9)
[3340] 12:00:11:744: CommitNegotiatedTSPIVersion: deviceID(3)
[3340] 12:00:11:744: lineGetNumAddressIDs(62): line(0000000000EC0000)
[3340] 12:00:11:744: ! lineGetNumAddressIDs: numAddressIDs(1)
[3340] 12:00:11:744: lineSetDefaultMediaDetection(56): line(0000000000EC0000), mode(102)
[3340] 12:00:11:744: ! SyncDriverRequest: oid(StDefaultMediaDetection), devID(3), reqID(2da), hdLine(0000000000000003)
[3340] 12:00:11:745: lineSetStatusMessages(57): line(0000000000EC0000)
[3340] 12:00:11:745: ! SyncDriverRequest: oid(SetStatusMessagesGatherDigits), devID(3), reqID(2db), hdLine(0000000000000003)
[3340] 12:00:11:746: !! SyncDriverRequest: (Oid SetStatusMessagesGatherDigits) returns with NDIS status (c0012016)
[3340] 12:00:12:970: lineMakeCall(57): reqID(10049), line(0000000000EC0000)
[3340] 12:00:12:970: ! AsyncDriverRequest: oid(MakeCall), devID(3), ReqID(10049), reqID(2dc), hdCall(0)
[3600] 12:00:12:970: ! AsyncEventsThread: got a line event
[3600] 12:00:12:970: ! ProcessEvent: event(0000000000362288), msg(2), ht_line(0000000000EC0000), ht_call(0000000000EE0002), p1(0000000000000200), p2(0000000000000000), p3(0000000000000100)
[3600] 12:00:12:970: ! ProcessEvent: incomplete outbound call, saving state
[3600] 12:00:12:971: ! AsyncEventsThread: got a completed req
[3600] 12:00:12:971: ! AsyncEventsThread: req(000000000177BF68) with reqID(10049) returned lRes(0)
[3600] 12:00:12:971: lineMakeCall_post: lRes(0)
[3600] 12:00:12:971: AsyncEventsThread: call compproc with ReqID(10049), lRes(0)
[3600] 12:00:12:971: ! AsyncEventsThread: report back the saved call state
[3600] 12:00:12:971: ! AET::fnLineEvent(CALLSTATE): htline(000000000001005A), htcall(000000000001039F), p1(0000000000000200), p2(0000000000000000), p3(0000000000000100)
[3096] 12:00:12:971: lineGetCallInfo(151): call(0000000000EE0002)
[3096] 12:00:12:971: ! SyncDriverRequest: oid(GetCallInfo), devID(3), reqID(2dd), hdCall(0000000000000038)
[3096] 12:00:12:971: ! lineGetCallInfo: dwCalledIDFlags contained LINECALLPARTYID_UNAVAIL
[3600] 12:00:15:084: ! AsyncEventsThread: got a line event
[3600] 12:00:15:085: ! ProcessEvent: event(0000000000362288), msg(2), ht_line(0000000000EC0000), ht_call(0000000000EE0002), p1(0000000000000100), p2(0000000000000000), p3(0000000000000100)
[3600] 12:00:15:085: ProcessEvent: using MSP
[3600] 12:00:15:085: ProcessEvent: acquired MSP Mutex
[3600] 12:00:15:085: ProcessEvent: released MSP Mutex
[3600] 12:00:15:085: ! PE::fnLineEvent(CALLSTATE): htline(000000000001005A), htcall(000000000001039F), p1(0000000000000100), p2(0000000000000000), p3(0000000000000100)
[3924] 12:00:15:086: lineGetCallInfo(152): call(0000000000EE0002)
[3924] 12:00:15:086: ! SyncDriverRequest: oid(GetCallInfo), devID(3), reqID(2de), hdCall(0000000000000038)
[3924] 12:00:15:086: ! lineGetCallInfo: dwCalledIDFlags contained LINECALLPARTYID_UNAVAIL
[3924] 12:00:15:088: lineGetCallStatus(82): call(0000000000EE0002)
[3924] 12:00:15:088: ! SyncDriverRequest: oid(GetCallStatus), devID(3), reqID(2df), hdCall(0000000000000038)
[3924] 12:00:15:098: lineGetCallInfo(153): call(0000000000EE0002)
[3924] 12:00:15:098: ! SyncDriverRequest: oid(GetCallInfo), devID(3), reqID(2e0), hdCall(0000000000000038)
[3924] 12:00:15:098: ! lineGetCallInfo: dwCalledIDFlags contained LINECALLPARTYID_UNAVAIL
[3924] 12:00:15:098: lineGetID(53): line(0000000000000000), call(0000000000EE0002), addressID(0), select(4)
[3924] 12:00:15:098: ! SyncDriverRequest: oid(GetID), devID(3), reqID(2e1), hdLine(0000000000000000)
[3600] 12:09:05:029: ! AsyncEventsThread: got a line event
[3600] 12:09:05:029: ! ProcessEvent: event(0000000000362288), msg(2), ht_line(0000000000EC0000), ht_call(0000000000EE0002), p1(0000000000004000), p2(0000000000000000), p3(0000000000000100)
[3600] 12:09:05:029: ProcessEvent: using MSP
[3600] 12:09:05:029: ProcessEvent: acquired MSP Mutex
[3600] 12:09:05:029: ProcessEvent: released MSP Mutex
[3600] 12:09:05:029: ! PE::fnLineEvent(CALLSTATE): htline(000000000001005A), htcall(000000000001039F), p1(0000000000004000), p2(0000000000000000), p3(0000000000000100)
[3600] 12:09:05:029: ! PE::fnLineEvent(CALLSTATE_IDLE): htline(000000000001005A), htcall(000000000001039F), p3(0000000000000100)
[2256] 12:09:05:031: lineGetCallStatus(83): call(0000000000EE0002)
[2256] 12:09:05:031: ! SyncDriverRequest: oid(GetCallStatus), devID(3), reqID(2e2), hdCall(0000000000000038)
[2256] 12:09:05:032: lineDrop(75): reqID(103a0), call(0000000000EE0002)
[2256] 12:09:05:032: ! AsyncDriverRequest: oid(Drop), devID(3), ReqID(103a0), reqID(2e3), hdCall(0)
[3600] 12:09:05:032: ! AsyncEventsThread: got a completed req
[3600] 12:09:05:032: ! AsyncEventsThread: req(00000000002A0DE8) with reqID(103a0) returned lRes(0)
[3600] 12:09:05:032: AsyncEventsThread: call compproc with ReqID(103a0), lRes(0)
[2256] 12:09:05:033: lineCloseCall(57): call(0000000000EE0002)
[2256] 12:09:05:033: ! SyncDriverRequest: oid(CloseCall), devID(3), reqID(2e4), hdCall(0000000000000038)
[2256] 12:09:05:035: lineClose(62): line(0000000000EC0000)
[2256] 12:09:05:035: ! SyncDriverRequest: oid(Close), devID(3), reqID(2e5), hdLine(0000000000000003)
[2256] 12:09:05:036: DecommitNegotiatedTSPIVersion: deviceID(3)
-------------------------------------------------------------------------------
C:\Windows\tracing\PPP.LOG
-------------------------------------------------------------------------------
[1936] 02-17 12:00:15:111: PROTOCOL_MSG_Start recvd, d=, hPort=2,flags=8,mask=820208,IfType=-1
[2752] 02-17 12:00:15:113: Line up event occurred on port 2
[2752] 02-17 12:00:15:113: Local identification = MSRAS-0-SOME-PC
[2752] 02-17 12:00:15:113: PortName: VPN2-1
[2752] 02-17 12:00:15:113: Starting PPP on link with IfType=0xffffffff,IPIf=0xffffffff,IPv6If=0xffffffff
(...)
[2752] 02-17 12:00:15:258: LCP Local Options-------------
[2752] 02-17 12:00:15:258: MRU=1400,ACCM=-1,Auth=0,MagicNumber=401239117,PFC=ON,ACFC=ON
[2752] 02-17 12:00:15:258: Recv Framing = PPP,SSHF=OFF,MRRU=1500,LinkDiscrim=0
[2752] 02-17 12:00:15:258: LCP Remote Options-------------
[2752] 02-17 12:00:15:258: MRU=1200,ACCM=0,Auth=c223,MagicNumber=-528632839,PFC=ON,ACFC=ON
[2752] 02-17 12:00:15:258: Send Framing = PPP,SSHF=OFF,MRRU=1500,LinkDiscrim=0
[2752] 02-17 12:00:15:258: LCP Configured successfully
(...)
[2752] 02-17 12:00:15:259: Client: LCP Configured successfully for Guid {805C0C01-BDE7-442D-AFA5-390490CAAA2D}
(...)
[2752] 02-17 12:00:15:877: Inserting autodisconnect in timer q for port=2, sec=-1
[2752] 02-17 12:00:15:877: InsertInTimerQ called portid=90,Id=0,Protocol=0,EventType=1,fAuth=0,Timeout=-1
[2752] 02-17 12:00:45:313: >PPP packet received at 02/17/2011 17:00:45:313
[2752] 02-17 12:00:45:313: >Protocol = LCP, Type = Echo-Request, Length = 0xa, Id = 0x1, Port = 2
[2752] 02-17 12:00:45:313:
[2752] 02-17 12:00:45:313: <PPP packet sent at 02/17/2011 17:00:45:313
[2752] 02-17 12:00:45:313: <Protocol = LCP, Type = Echo-Reply, Length = 0xa, Id = 0x1, Port = 2
(...)
[3132] 02-17 12:09:05:035: PROTOCOL_MSG_LineDown recvd, hPort=2
[2752] 02-17 12:09:05:035: Line down event occurred on port 2
[2752] 02-17 12:09:05:094: FsmDown event received for protocol c021 on port 2
(...)
[2752] 02-17 12:09:05:245: LcpEnd
[2752] 02-17 12:09:05:245: Post line down event occurred on port 2
-------------------------------------------------------------------------------
C:\Windows\tracing\RASMAN.LOG
-------------------------------------------------------------------------------
[2388] 02-17 12:00:16:085: SignalConnection
[2388] 02-17 12:00:16:085: SendSensNotification(_RAS_CONNECT) for 0x00390000 returns 0x00000000
[2388] 02-17 12:00:16:610: DwSendNotificationInternal(ENTRY_CONNECTED), rC=0x00000000
[2388] 02-17 12:00:16:610: SetSystemIdleTimer: fDisable=1
(...)
[3132] 02-17 12:09:05:033: WorkerThread: Disconnect event signaled on port: VPN2-1
[3132] 02-17 12:09:05:033: OVEVT_DEV_STATECHANGE. pOverlapped = 0x398b350
[3132] 02-17 12:09:05:033: d:\w7rtm\net\rras\ras\rasman\rasman\worker.c, 2027: Disconnecting port 2, connection 0x1d5e8f0, reason 1
[3132] 02-17 12:09:05:033: Disconnecting Port 0xVPN2-1, reason 1
[3132] 02-17 12:09:05:033: DisconnectPort: Saving Bundle stats for port VPN2-1
[3132] 02-17 12:09:05:033: RevertPostConnectionActions
[3132] 02-17 12:09:05:034: RasImpersonateUser. 0x0
[3132] 02-17 12:09:05:034: DeleteCredentialsFromCredMan
[3132] 02-17 12:09:05:034: DeleteCredentialsFromCredMan Done: 0
[3132] 02-17 12:09:05:034: RasRevertToSelf. 0x0
[3132] 02-17 12:09:05:034: QueueCloseConnections: no dependent connections
[3132] 02-17 12:09:05:034: 10. Throwing away handle 0x0!
[3132] 02-17 12:09:05:034: d:\w7rtm\net\rras\ras\rasman\rasman\util.c, 2202:Setting port 2 for autoclosure...
[3132] 02-17 12:09:05:034: d:\w7rtm\net\rras\ras\rasman\rasman\util.c 2214: Disconnected Port 2, reason 1. rc=0x0
[3132] 02-17 12:09:05:034: d:\w7rtm\net\rras\ras\rasman\rasman\util.c: 2324: port 2 state chg: prev=2, new=3
[3132] 02-17 12:09:05:034: d:\w7rtm\net\rras\ras\rasman\rasman\util.c: 2340: port 2 state chg: prev=3, new=4
[3132] 02-17 12:09:05:035: 5. Notifying of disconnect on port 2
[3132] 02-17 12:09:05:035: d:\w7rtm\net\rras\ras\rasman\rasman\util.c: 2454: port 2 async reqtype chg: prev=0, new=0
[3132] 02-17 12:09:05:035: ***** DisconnectType=1,DisconnectReason=4,pConn=0x1d5e8f0,cbports=1,signaled=1,hEvent=0xffffffff,fRedial=0
[3132] 02-17 12:09:05:035: Calling DwQueueRedial
[3132] 02-17 12:09:05:035: DwQueueRedial
[3132] 02-17 12:09:05:035: DwQueueRedial returned 0x0
[3132] 02-17 12:09:05:035: d:\w7rtm\net\rras\ras\rasman\rasman\util.c, 2515: Autoclosing port 2
[3132] 02-17 12:09:05:035: PortClose: port (2). OpenInstances = 1
[3132] 02-17 12:09:05:035: Freeing the notifier list for port 2
[3132] 02-17 12:09:05:035: DwInitializeIpSec: fOnFailure set to 0
[3132] 02-17 12:09:05:035: Deleting client ipsec filter on 2
[3132] 02-17 12:09:05:035: DwDeleteIpSecFilter for VPN2-1 returned 0x57
[3132] 02-17 12:09:05:035: PortClose (2). OpenInstances = 0
[3132] 02-17 12:09:05:036: d:\w7rtm\net\rras\ras\rasman\rasman\request.c: 3594: port 2 async reqtype chg: prev=0, new=0
[3132] 02-17 12:09:05:036: d:\w7rtm\net\rras\ras\rasman\rasman\request.c: 3597: port 2 state chg: prev=4, new=4
[3132] 02-17 12:09:05:036: RemoveConnectionPort: port 2, fOwnerClose=0, pConn=0x1d5e8f0, pConn->CB_Ports=0
[3132] 02-17 12:09:05:037: Completely disconnected connection: Reason: ERROR_LINK_FAILURE (829)
[932] 02-17 12:09:05:037: RedialDroppedLink
[932] 02-17 12:09:05:037: RedialDroppedLink: szCmdLine=C:\Windows\system32\rasautou -r -f "C:\Users\some\AppData\Roaming\Microsoft\Network\Connections\Pbk\rasphone.pbk" -e "VPN EE-inc"
[932] 02-17 12:09:05:037: RasImpersonateUser. 0x0
[932] 02-17 12:09:05:045: RedialDroppedLink: started pid 3568
[932] 02-17 12:09:05:045: RasRevertToSelf. 0x0
[932] 02-17 12:09:05:045: RedialDroppedLink done. 0x0
[3132] 02-17 12:09:05:065: SendSensNotification(_RAS_DISCONNECT) for 0x00390000 returns 0x00000000
[3132] 02-17 12:09:05:085: DwSendNotificationInternal(ENTRY_DISCONNECTED) rc=0x0
(I have stripted some log entries to reduce the size of the message)
If you see anything that could point to the source of the problem, and maybe to a solution I would apreciate it.
Thank you in advance.
Remi
