Bug 171221

Summary:	ppp and serial gprs modem
Product:	Base System	Reporter:	hsu <hsu>
Component:	bin	Assignee:	freebsd-bugs (Nobody) <bugs>
Status:	Open ---
Severity:	Affects Only Me	CC:	c.taube
Priority:	Normal
Version:	9.0-RELEASE
Hardware:	Any
OS:	Any

Description hsu 2012-08-31 21:00:24 UTC

	
ppp does not seem to handshake with the modem, tried number of
different options, defaults, and trying to disable all options.

In FreeBSD 7.x this was the pppd command

------------------------------
route delete default
/usr/sbin/pppd -detach noauth nobsdcomp nodeflate local novj novjccomp debug connect "/usr/bin/chat -t 65 -v -f /usr/local/etc/ppp/gprs-connect" crtscts defaultroute /dev/cuad1 115200 
------------------------------

/usr/local/etc/ppp/grps-connect scripts is as follows:
--------------------------------
TIMEOUT         60
ABORT           'BUSY'
ABORT           'ERROR'
ABORT           'NO CARRIER'
''              'AT'
OK		AT\^SGAUTH=0
OK              AT\\Q3
OK		AT+CGDCONT=1,"IP","internet"
OK              ATD*99***1#
CONNECT         ''
--------------------------------

The script seem to work with ppp as it gets CONNECT and starts ppp
handshake, but the connection is always broken.  

Tried:

- changing timeout value (zero, default, various others).  Unlikely to be a timeout as the connection is terminated quickly.

- disabling various options like compresion options.

- denying those as well as disabling them.

- playing around with authentication.  The provider does not require
authentication, and authentication is disabled in the pppd command
line.  They seem to accept empty chap password and username if I try,
and that does not seem to have effect.

- several ppp configurations found by googling.

-----------------------------

One version of /etc/ppp/ppp.conf tried (out of tens of various ones):

-------------------------------------------
#################################################################
# PPP  Sample Configuration File
# Originally written by Toshiharu OHNO
# Simplified 5/14/1999 by wself@cdrom.com
#
# See /usr/share/examples/ppp/ for some examples
#
# $FreeBSD: release/9.0.0/etc/ppp/ppp.conf 203943 2010-02-16 01:07:06Z jkim $
#################################################################

default:
 # set log Phase Chat LCP IPCP CCP tun command
 set log All
 ident user-ppp VERSION

 # Ensure that "device" references the correct serial port
 # for your modem. (cuau0 = COM1, cuau1 = COM2)
 #
 set device /dev/cuau0
 set speed 115200

 set dial "ABORT BUSY ABORT NO\\sCARRIER TIMEOUT 5 \"\" AT OK-AT-OK ATE1Q0 OK AT\\^SGAUTH=0 OK AT\\\\Q3 OK AT+CGDCONT=1,\"IP\",\"internet\" OK \\dATDT\\T TIMEOUT 40 CONNECT"
 set timeout 0 
 enable dns				# request DNS info (for resolv.conf)
 set crtscts on
 # set mtu maximum 512
 # set mru maximum 512
 
 set phone "*99***1#"

 # disable vjcomp
 # disable acfcomp
 # disable deflate
 # disable deflate24
 # disable pred1
 # disable protocomp
 disable mppe
 disable ipv6cp
 disable ccp
 # disable lqr
 # disable echo

 # deny vjcomp
 # deny acfcomp
 # deny deflate
 # deny deflate24
 # deny pred1
 # deny protocomp
 # deny mppe
 # deny ipv6cp
 # deny lqr

 # set authname ""
 # set authkey ""

 delete all
 add 0 0 HISADDR			# Add a (sticky) default route

papchap:
 #
 # edit the next three lines and replace the items in caps with
 # the values which have been assigned by your ISP.
 #
------------------------

The following is a longish log with debug options on. For the above
ppp.conf, go to end and reverse search CONNECT.  The tries before that may have been done with differing ppp.conf options (spent some 4 hours trying different combinations, examples from various people, etc).

------------------------------
Aug 27 20:39:42 joutsenoranta ppp[8741]: Phase: Using interface: tun0
Aug 27 20:39:42 joutsenoranta ppp[8741]: Phase: deflink: Created in closed state
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Command: default: ident user-ppp VERSION
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Command: default: set device /dev/cuau0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Command: default: set speed 115200
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Command: default: set dial ABORT BUSY ABORT NO\sCARRIER TIMEOUT 5 "" AT OK-AT-OK ATE1Q0 OK AT\^SGAUTH=0 OK AT\\Q3 OK AT+CGDCONT=1,"IP","internet" OK \dATDT\T TIMEOUT 40 CONNECT
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Command: default: set timeout 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Command: default: enable dns
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Command: default: set crtscts on
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Command: default: set phone *99***1#
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Phase: PPP Started (foreground mode).
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Phase: bundle: Establish
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Phase: deflink: closed -> opening
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: ID0: 0 = uu_lock("cuau0")
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: ID0: 0 = open("/dev/cuau0", 6)
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Debug: deflink: Opened /dev/cuau0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Debug: deflink: tty_Create: physical (get): fd = 0, iflag = 2b02, oflag = 3, cflag = cb00
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Debug: deflink: physical (put): iflag = a01, oflag = 2, cflag = 3cb00
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: ID0: 0x283e03e0 = fopen("/var/run/cuau0.if", "w")
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting physical throughput timer[0x28507068]
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Phase: deflink: Connected!
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Phase: deflink: opening -> dial
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Phone: *99***1#
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: deflink: Dial attempt 1 of 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Send: AT^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 0d                                         AT.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Expect(5): OK
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting chat timeout timer[0x284c02b4]
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 0d 0d 0a 4f 4b 0d                          AT...OK.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: AT^M^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: OK
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Send: ATE1Q0^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 45 31 51 30 0d                             ATE1Q0.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Expect(5): OK
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting chat timeout timer[0x284c02b4]
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  0a                                               .
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: ^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 45 31 51 30 0d                             ATE1Q0.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  0d 0a 4f 4b 0d 0a                                ..OK..
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: ATE1Q0^M^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: OK^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Send: AT^SGAUTH=0^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 5e 53 47 41 55 54 48 3d 30 0d              AT^SGAUTH=0.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Expect(5): OK
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting chat timeout timer[0x284c02b4]
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 5e 53 47 41                                AT^SGA
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  55 54 48 3d 30 0d                                UTH=0.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  0d 0a 4f 4b 0d 0a                                ..OK..
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: AT^SGAUTH=0^M^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: OK^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Send: AT\Q3^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 5c 51 33 0d                                AT\Q3.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Expect(5): OK
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting chat timeout timer[0x284c02b4]
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 5c 51 33 0d                                AT\Q3.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  0d 0a 4f 4b 0d 0a                                ..OK..
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: AT\Q3^M^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: OK^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Send: AT+CGDCONT=1,IP,internet^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 2b 43 47 44 43 4f 4e 54 3d 31 2c 49 50 2c  AT+CGDCONT=1,IP,
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  69 6e 74 65 72 6e 65 74 0d                       internet.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Expect(5): OK
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting chat timeout timer[0x284c02b4]
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 2b 43 47 44 43 4f                          AT+CGDCO
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  4e 54                                            NT
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  3d 31 2c 49 50 2c 69 6e                          =1,IP,in
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  74 65 72 6e 65 74 0d                             ternet.
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  0d 0a 4f 4b 0d 0a                                ..OK..
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: AT+CGDCONT=1,IP,internet^M^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Received: OK^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting chat pause timer[0x284c0294]
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Chat: Send: ATDT*99***1#^M
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:42 joutsenoranta ppp[8741]: tun0: Physical:  41 54 44 54 2a 39 39 2a 2a 2a 31 23 0d           ATDT*99***1#.
Aug 27 20:39:43 joutsenoranta ppp[8741]: tun0: Timer: Select returns -1
Aug 27 20:39:43 joutsenoranta ppp[8741]: tun0: Timer: ---- Begin of Timer Service List---
Aug 27 20:39:43 joutsenoranta ppp[8741]: tun0: Timer: physical throughput timer[0x28507068]: freq = 1.00s, next = 0.00s, state = running
Aug 27 20:39:43 joutsenoranta ppp[8741]: tun0: Timer: chat pause timer[0x284c0294]: freq = 2.00s, next = 1.30s, state = running
Aug 27 20:39:43 joutsenoranta ppp[8741]: tun0: Timer: ---- End of Timer Service List ---
Aug 27 20:39:43 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting physical throughput timer[0x28507068] before chat pause timer[0x284c0294], delta = 10
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: Select returns -1
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: ---- Begin of Timer Service List---
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: physical throughput timer[0x28507068]: freq = 1.00s, next = 0.00s, state = running
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: chat pause timer[0x284c0294]: freq = 2.00s, next = 0.30s, state = running
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: ---- End of Timer Service List ---
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting physical throughput timer[0x28507068]
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: Select returns -1
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Chat: Expect(40): CONNECT
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting chat timeout timer[0x284c02b4]
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  41 54 44 54 2a 39 39 2a 2a 2a 31 23 0d 0d 0a 43  ATDT*99***1#...C
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  4f 4e 4e 45 43 54 0d 0a 7e ff 7d 23 c0 21 7d 21  ONNECT..~.}#.!}!
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  7d 22 7d 20 7d 38 7d 21 7d 24 7d 26 40 7d 25 7d  }"} }8}!}$}&@}%}
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  26 69 37 89 45 7d 22 7d 26 7d 20 7d 20 7d 20 7d  &i7.E}"}&} } } }
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  20 7d 27 7d 22 7d 28 7d 22 a5 7d 22 7e 7e ff 7d   }'}"}(}".}"~~.}
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  23 c0 21 7d 21 7d 23 7d 20 7d 38 7d 21 7d 24 7d  #.!}!}#} }8}!}$}
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  26 40 7d 25 7d 26 69 37 89 45 7d 22 7d 26 7d 20  &@}%}&i7.E}"}&} 
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  7d 20 7d 20 7d 20 7d 27 7d 22 7d 28 7d 22 6c 8b  } } } }'}"}(}"l.
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  7e 7e ff 7d 23 c0 21 7d 21 7d 24 7d 20 7d 38 7d  ~~.}#.!}!}$} }8}
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  21 7d 24 7d 26 40 7d 25 7d 26 69 37 89 45 7d 22  !}$}&@}%}&i7.E}"
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  7d 26 7d 20 7d 20 7d 20 7d 20 7d 27 7d 22 7d 28  }&} } } } }'}"}(
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Physical:  7d 22 20 2e 7e                                   }" .~
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Chat: Received: ATDT*99***1#^M^M
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Chat: Received: CONNECT^M
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Phase: deflink: dial -> carrier
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Debug: deflink: Using tty_Timeout [0x8087b60]
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting tty CD timer[0x2846510c]
Aug 27 20:39:44 joutsenoranta ppp[8741]: tun0: Debug: Waiting for carrier
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns -1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: ---- Begin of Timer Service List---
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: physical throughput timer[0x28507068]: freq = 1.00s, next = 0.00s, state = running
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tty CD timer[0x2846510c]: freq = 1.00s, next = 0.30s, state = running
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: ---- End of Timer Service List ---
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting physical throughput timer[0x28507068]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: Waiting for carrier
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns -1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting tty CD timer[0x2846510c]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Phase: deflink: /dev/cuau0: CD detected
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Phase: deflink: carrier -> login
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: Entering tty_Raw
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Phase: deflink: login -> lcp
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: FSM: Using "deflink" as a transport
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: State change Initial --> Closed
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: State change Closed --> Stopped
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting LCP openmode timer[0x2850715c] before tty CD timer[0x2846510c], delta = 3
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e ff 7d 23 c0 21 7d 21 7d 25 7d 20 7d 38 7d 21  ~.}#.!}!}%} }8}!
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7d 24 7d 26 40 7d 25 7d 26 69 37 89 45 7d 22 7d  }$}&@}%}&i7.E}"}
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  26 7d 20 7d 20 7d 20 7d 20 7d 27 7d 22 7d 28 7d  &} } } } }'}"}(}
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  22 e9 a7 7e                                      "..~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 52/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e ff 7d 23 c0 21 7d 21 7d 25 7d 20 7d 38 7d 21  ~.}#.!}!}%} }8}!
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7d 24 7d 26 40 7d 25 7d 26 69 37 89 45 7d 22 7d  }$}&@}%}&i7.E}"}
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  26 7d 20 7d 20 7d 20 7d 20 7d 27 7d 22 7d 28 7d  &} } } } }'}"}(}
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  22 e9 a7 7e                                      "..~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_LayerPull:
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 01 05 00 18 01 04 06 40 05 06 69 37  ...!.......@..i7
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  89 45 02 06 00 00 00 00 07 02 08 02 e9 a7        .E............
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: hdlc_LayerPull: fcs = f0b8 (good)
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPull: unknown -> 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PullPacket: Despatch proto 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: RecvConfigReq(5) state = Stopped
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MRU[4] 1600
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MAGICNUM[6] 0x69378945
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  ACCMAP[6] 0x00000000
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  PROTOCOMP[2]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  ACFCOMP[2]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: SendConfigReq(1) state = Stopped
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  ACFCOMP[2]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  PROTOCOMP[2]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  ACCMAP[6] 0x00000000
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MRU[4] 1500
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MAGICNUM[6] 0xdaca4bc6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: fsm_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  01 01 00 18 08 02 07 02 02 06 00 00 00 00 01 04  ................
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  05 dc 05 06 da ca 4b c6                          ......K.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPush: Using 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 01 01 00 18 08 02 07 02 02 06 00 00  ...!............
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  00 00 01 04 05 dc 05 06 da ca 4b c6 2a 99        ..........K.*.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e ff 7d 23 c0 21 7d 21 7d 21 7d 20 7d 38 7d 28  ~.}#.!}!}!} }8}(
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7d 22 7d 27 7d 22 7d 22 7d 26 7d 20 7d 20 7d 20  }"}'}"}"}&} } } 
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7d 20 7d 21 7d 24 7d 25 dc 7d 25 7d 26 da ca 4b  } }!}$}%.}%}&..K
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  c6 2a 99 7e                                      .*.~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PushPacket: Transmit proto 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_enqueue: len = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting LCP restart timer[0x2850713c]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: SendConfigAck(5) state = Stopped
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MRU[4] 1600
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MAGICNUM[6] 0x69378945
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  ACCMAP[6] 0x00000000
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  PROTOCOMP[2]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  ACFCOMP[2]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: fsm_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  02 05 00 18 01 04 06 40 05 06 69 37 89 45 02 06  .......@..i7.E..
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  00 00 00 00 07 02 08 02                          ........
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPush: Using 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 02 05 00 18 01 04 06 40 05 06 69 37  ...!.......@..i7
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  89 45 02 06 00 00 00 00 07 02 08 02 25 4a        .E..........%J
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e ff 7d 23 c0 21 7d 22 7d 25 7d 20 7d 38 7d 21  ~.}#.!}"}%} }8}!
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7d 24 7d 26 40 7d 25 7d 26 69 37 89 45 7d 22 7d  }$}&@}%}&i7.E}"}
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  26 7d 20 7d 20 7d 20 7d 20 7d 27 7d 22 7d 28 7d  &} } } } }'}"}(}
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  22 25 4a 7e                                      "%J~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PushPacket: Transmit proto 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_enqueue: len = 2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: LayerStart
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: State change Stopped --> Ack-Sent
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_dequeue: queue len = 2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_Dequeue: Dequeued from queue 1, containing 1 more packets
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e ff 7d 23 c0 21 7d 21 7d 21 7d 20 7d 38 7d 28  ~.}#.!}!}!} }8}(
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7d 22 7d 27 7d 22 7d 22 7d 26 7d 20 7d 20 7d 20  }"}'}"}"}&} } } 
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7d 20 7d 21 7d 24 7d 25 dc 7d 25 7d 26 da ca 4b  } }!}$}%.}%}&..K
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  c6 2a 99 7e                                      .*.~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorWrite: wrote 52(52) to 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_dequeue: queue len = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_Dequeue: Dequeued from queue 1, containing 0 more packets
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e ff 7d 23 c0 21 7d 22 7d 25 7d 20 7d 38 7d 21  ~.}#.!}"}%} }8}!
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7d 24 7d 26 40 7d 25 7d 26 69 37 89 45 7d 22 7d  }$}&@}%}&i7.E}"}
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  26 7d 20 7d 20 7d 20 7d 20 7d 27 7d 22 7d 28 7d  &} } } } }'}"}(}
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  22 25 4a 7e                                      "%J~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorWrite: wrote 52(52) to 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e ff 7d 23 c0 21 7d 22                          ~.}#.!}"
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e ff 7d 23 c0 21 7d 22                          ~.}#.!}"
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7d 21 7d 20 7d 38 7d 28                          }!} }8}(
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7d 21 7d 20 7d 38 7d 28                          }!} }8}(
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7d 22 7d 27 7d 22 7d 22                          }"}'}"}"
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7d 22 7d 27 7d 22 7d 22                          }"}'}"}"
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7d 26 7d 20 7d 20 7d 20 7d 20 7d 21 7d 24 7d 25  }&} } } } }!}$}%
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 16/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7d 26 7d 20 7d 20 7d 20 7d 20 7d 21 7d 24 7d 25  }&} } } } }!}$}%
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  dc 7d 25 7d 26 da ca 4b                          .}%}&..K
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  dc 7d 25 7d 26 da ca 4b                          .}%}&..K
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  c6 e6 74 7e                                      ..t~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 4/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  c6 e6 74 7e                                      ..t~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_LayerPull:
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 02 01 00 18 08 02 07 02 02 06 00 00  ...!............
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  00 00 01 04 05 dc 05 06 da ca 4b c6 e6 74        ..........K..t
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: hdlc_LayerPull: fcs = f0b8 (good)
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPull: unknown -> 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PullPacket: Despatch proto 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: RecvConfigAck(1) state = Ack-Sent
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  ACFCOMP[2]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  PROTOCOMP[2]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  ACCMAP[6] 0x00000000
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MRU[4] 1500
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MAGICNUM[6] 0xdaca4bc6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: State change Ack-Sent --> Opened
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: LayerUp
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LQM: deflink: LQR/LCP ECHO not negotiated
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting hdlc timer[0x28509db0]
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: SendIdent(0) state = Opened
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: fsm_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  0c 00 00 16 da ca 4b c6 75 73 65 72 2d 70 70 70  ......K.user-ppp
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  20 33 2e 34 2e 32                                 3.4.2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPush: Using 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 0c 00 00 16 da ca 4b c6 75 73 65 72  ...!......K.user
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  2d 70 70 70 20 33 2e 34 2e 32 11 7e              -ppp 3.4.2.~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e ff 7d 23 c0 21 7d 2c 7d 20 7d 20 7d 36 da ca  ~.}#.!},} } }6..
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  4b c6 75 73 65 72 2d 70 70 70 20 33 2e 34 2e 32  K.user-ppp 3.4.2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7d 31 7d 5e 7e                                   }1}^~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PushPacket: Transmit proto 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_enqueue: len = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  MAGICNUM daca4bc6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP:  TEXT user-ppp 3.4.2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP: FSM: Using "deflink" as a transport
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP: deflink: State change Initial --> Closed
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP: deflink: LayerStart.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP: MPPE: Not usable without CHAP81
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP: deflink: SendConfigReq(1) state = Closed
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP:  DEFLATE[4] win 15
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP:  PRED1[2] 
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: fsm_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  01 01 00 0a 1a 04 78 00 01 02                    ......x...
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPush: Using 0x80fd
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  80 fd 01 01 00 0a 1a 04 78 00 01 02 d5 fe        ........x.....
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e 80 fd 01 01 00 0a 1a 04 78 00 01 02 d5 fe 7e  ~........x.....~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PushPacket: Transmit proto 0x80fd
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_enqueue: len = 2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting CCP restart timer[0x28507c18] before hdlc timer[0x28509db0], delta = 21
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP: deflink: State change Closed --> Req-Sent
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Phase: deflink: lcp -> open
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Phase: bundle: Network
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP: FSM: Using "deflink" as a transport
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP: deflink: State change Initial --> Closed
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP: deflink: LayerStart.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting IPCP throughput timer[0x80b5368] before CCP restart timer[0x28507c18], delta = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP: deflink: SendConfigReq(1) state = Closed
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP:  IPADDR[6] 127.0.0.1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP:  COMPPROTO[6] 16 VJ slots with slot compression
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP:  PRIDNS[6] 192.168.1.1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP:  SECDNS[6] 255.255.255.255
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: fsm_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  01 01 00 1c 03 06 7f 00 00 01 02 06 00 2d 0f 01  .............-..
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  81 06 c0 a8 01 01 83 06 ff ff ff ff              ............
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPush: Using 0x8021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  80 21 01 01 00 1c 03 06 7f 00 00 01 02 06 00 2d  .!.............-
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  0f 01 81 06 c0 a8 01 01 83 06 ff ff ff ff 3d 97  ..............=.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e 80 21 01 01 00 1c 03 06 7f 00 00 01 02 06 00  ~.!.............
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  2d 0f 01 81 06 c0 a8 01 01 83 06 ff ff ff ff 3d  -..............=
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  97 7e                                            .~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PushPacket: Transmit proto 0x8021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_enqueue: len = 3
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting IPCP restart timer[0x80a40d0] before CCP restart timer[0x28507c18], delta = 20
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPCP: deflink: State change Closed --> Req-Sent
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPV6CP: FSM: Using "deflink" as a transport
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPV6CP: deflink: State change Initial --> Closed
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPV6CP: deflink: LayerStart.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting IPV6CP throughput timer[0x80b54f8] before IPCP throughput timer[0x80b5368], delta = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPV6CP: deflink: SendConfigReq(1) state = Closed
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPV6CP:  IFACEID[10] 0x021bebfffe62a7e1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: fsm_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  01 01 00 0e 01 0a 02 1b eb ff fe 62 a7 e1        ...........b..
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPush: Using 0x8057
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  80 57 01 01 00 0e 01 0a 02 1b eb ff fe 62 a7 e1  .W...........b..
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  04 57                                            .W
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e 80 57 01 01 00 0e 01 0a 02 1b eb ff fe 62 a7  ~.W...........b.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  e1 04 57 7e                                      ..W~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PushPacket: Transmit proto 0x8057
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_enqueue: len = 4
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting IPV6CP restart timer[0x80b53dc] before IPCP restart timer[0x80a40d0], delta = 20
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPV6CP: deflink: State change Closed --> Req-Sent
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: TCP/IP: OUT ICMP: :::135 ---> ff02::1:ff62:a7e1 (16/64)
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_enqueue: len = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_dequeue: queue len = 4
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_Dequeue: Dequeued from queue 1, containing 3 more packets
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e ff 7d 23 c0 21 7d 2c 7d 20 7d 20 7d 36 da ca  ~.}#.!},} } }6..
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  4b c6 75 73 65 72 2d 70 70 70 20 33 2e 34 2e 32  K.user-ppp 3.4.2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7d 31 7d 5e 7e                                   }1}^~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorWrite: wrote 37(37) to 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_dequeue: queue len = 3
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_Dequeue: Dequeued from queue 1, containing 2 more packets
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e 80 fd 01 01 00 0a 1a 04 78 00 01 02 d5 fe 7e  ~........x.....~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorWrite: wrote 16(16) to 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_dequeue: queue len = 2
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_Dequeue: Dequeued from queue 1, containing 1 more packets
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e 80 21 01 01 00 1c 03 06 7f 00 00 01 02 06 00  ~.!.............
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  2d 0f 01 81 06 c0 a8 01 01 83 06 ff ff ff ff 3d  -..............=
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  97 7e                                            .~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorWrite: wrote 34(34) to 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_dequeue: queue len = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_Dequeue: Dequeued from queue 1, containing 0 more packets
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e 80 57 01 01 00 0e 01 0a 02 1b eb ff fe 62 a7  ~.W...........b.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  e1 04 57 7e                                      ..W~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorWrite: wrote 20(20) to 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e ff 03 c0 21 08 00 00                          ~...!...
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e ff 03 c0 21 08 00 00                          ~...!...
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  11 80 fd 01 01 00 0a 1a 04 78 00 01 02 d5 60 5f  .........x....`_
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 16/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  11 80 fd 01 01 00 0a 1a 04 78 00 01 02 d5 60 5f  .........x....`_
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e 7e ff 03 c0 21 08 01                          ~~...!..
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e 7e ff 03 c0 21 08 01                          ~~...!..
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_LayerPull:
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 08 00 00 11 80 fd 01 01 00 0a 1a 04  ...!............
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  78 00 01 02 d5 60 5f                             x....`_
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: hdlc_LayerPull: fcs = f0b8 (good)
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPull: unknown -> 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PullPacket: Despatch proto 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: RecvProtocolRej(0) state = Opened
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: -- Protocol 0x80fd (Compression Control Protocol) was rejected!
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: CCP: deflink: State change Req-Sent --> Stopped
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  00 15 80 57 01 01 00 0e 01 0a 02 1b eb ff fe 62  ...W...........b
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 16/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  00 15 80 57 01 01 00 0e 01 0a 02 1b eb ff fe 62  ...W...........b
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  a7 e1 04 d6 6e 7e                                ....n~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 6/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  a7 e1 04 d6 6e 7e                                ....n~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_LayerPull:
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 08 01 00 15 80 57 01 01 00 0e 01 0a  ...!.....W......
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  02 1b eb ff fe 62 a7 e1 04 d6 6e                 .....b....n
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: hdlc_LayerPull: fcs = f0b8 (good)
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPull: unknown -> 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PullPacket: Despatch proto 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: RecvProtocolRej(1) state = Opened
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: -- Protocol 0x8057 (Internet Protocol V6 Control Protocol) was rejected!
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Phase: deflink: IPV6CP protocol reject closes IPV6CP !
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPV6CP: deflink: SendTerminateReq(1) state = Req-Sent
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: fsm_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug:  05 01 00 04                                      ....
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPush: Using 0x8057
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_Output
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  80 57 05 01 00 04 3c c5                          .W....<.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e 80 57 05 01 00 04 3c c5 7e                    ~.W....<.~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PushPacket: Transmit proto 0x8057
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_enqueue: len = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting IPV6CP restart timer[0x80b53dc] before IPCP restart timer[0x80a40d0], delta = 20
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: IPV6CP: deflink: State change Req-Sent --> Closing
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(w) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: m_dequeue: queue len = 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_Dequeue: Dequeued from queue 1, containing 0 more packets
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: write
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e 80 57 05 01 00 04 3c c5 7e                    ~.W....<.~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorWrite: wrote 10(10) to 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  7e ff 03 c0 21 08 02 00                          ~...!...
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  7e ff 03 c0 21 08 02 00                          ~...!...
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  0b 80 57 05 01 00 04 3c                          ..W....<
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  0b 80 57 05 01 00 04 3c                          ..W....<
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Physical:  af 61 7e                                         .a~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 3/2048 from 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Async:  af 61 7e                                         .a~
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_LayerPull:
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 08 02 00 0b 80 57 05 01 00 04 3c af  ...!.....W....<.
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: HDLC:  61                                               a
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: deflink: hdlc_LayerPull: fcs = f0b8 (good)
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPull: unknown -> 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Debug: link_PullPacket: Despatch proto 0xc021
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: RecvProtocolRej(2) state = Opened
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: LCP: deflink: -- Protocol 0x8057 (Internet Protocol V6 Control Protocol) was rejected!
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Phase: deflink: IPV6CP protocol reject closes IPV6CP !
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:45 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: Select returns -1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: ---- Begin of Timer Service List---
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: physical throughput timer[0x28507068]: freq = 1.00s, next = 0.00s, state = running
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: LCP openmode timer[0x2850715c]: freq = 1.00s, next = 0.30s, state = running
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: tty CD timer[0x2846510c]: freq = 1.00s, next = 0.30s, state = running
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: IPV6CP throughput timer[0x80b54f8]: freq = 1.00s, next = 0.40s, state = running
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: IPCP throughput timer[0x80b5368]: freq = 1.00s, next = 0.40s, state = running
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: IPV6CP restart timer[0x80b53dc]: freq = 3.00s, next = 2.40s, state = running
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: IPCP restart timer[0x80a40d0]: freq = 3.00s, next = 2.40s, state = running
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: hdlc timer[0x28509db0]: freq = 60.00s, next = 59.40s, state = running
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: ---- End of Timer Service List ---
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting physical throughput timer[0x28507068] before IPV6CP restart timer[0x80b53dc], delta = 6
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: Select returns -1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting tty CD timer[0x2846510c] before IPV6CP restart timer[0x80b53dc], delta = 3
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: deflink: Still online
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: Select returns -1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting IPCP throughput timer[0x80b5368] before IPV6CP restart timer[0x80b53dc], delta = 1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: timer_Start: Inserting IPV6CP throughput timer[0x80b54f8] before IPCP throughput timer[0x80b5368], delta = 1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical:  7e ff 03 c0 21 05 00 00                          ~...!...
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async:  7e ff 03 c0 21 05 00 00                          ~...!...
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical:  1d 4e 6f 72 6d 61 6c 20                          .Normal 
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async:  1d 4e 6f 72 6d 61 6c 20                          .Normal 
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical:  54 65 72 6d 69 6e 61 74                          Terminat
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async:  54 65 72 6d 69 6e 61 74                          Terminat
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical:  69 6f 6e 20 62 79 20 4e                          ion by N
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 8/2048 from 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async:  69 6f 6e 20 62 79 20 4e                          ion by N
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: tun: fdset(r) 6
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(r) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: deflink: fdset(e) 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Timer: Select returns 1
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical: read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Physical:  43 50 21 54 7e                                   CP!T~
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: deflink: DescriptorRead: read 5/2048 from 0
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async: Read
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async:  43 50 21 54 7e                                   CP!T~
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_LayerPull:
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 05 00 00 1d 4e 6f 72 6d 61 6c 20 54  ...!....Normal T
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: HDLC:  65 72 6d 69 6e 61 74 69 6f 6e 20 62 79 20 4e 43  ermination by NC
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: HDLC:  50 21 54                                         P!T
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: deflink: hdlc_LayerPull: fcs = f0b8 (good)
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPull: unknown -> 0xc021
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: link_PullPacket: Despatch proto 0xc021
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: LCP: deflink: RecvTerminateReq(0) state = Opened
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: LCP: deflink: LayerDown
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: LCP: deflink: SendTerminateAck(0) state = Opened
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: fsm_Output
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug:  06 00 00 04                                      ....
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Debug: proto_LayerPush: Using 0xc021
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: HDLC: hdlc_Output
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: HDLC:  ff 03 c0 21 06 00 00 04 2c b8                    ...!....,.
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async: Write
Aug 27 20:39:46 joutsenoranta ppp[8741]: tun0: Async:  7e ff 7d 2

Comment 1 Eitan Adler freebsd_committer

2018-05-20 23:50:56 UTC

For bugs matching the following conditions:
- Status == In Progress
- Assignee == "bugs@FreeBSD.org"
- Last Modified Year <= 2017

Do
- Set Status to "Open"