create more unused udp session when we do stress testing

[rudinyu]

acl-pppd create a lot of udp session to radius server,but we check radius server, these sessions should be finished.

We use netstat to check it show "ESTABLISHED"

Like

udp 0 0 10.1.250.55:29053 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:24957 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:45437 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:24958 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:41342 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:16766 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:53630 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:45438 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:37246 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:20862 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:57726 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:33150 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:49534 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:12670 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:29054 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:61822 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:37247 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:33151 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:16767 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:24959 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:12671 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd udp 0 0 10.1.250.55:49535 10.1.25.2:1813 ESTABLISHED 14206/accel-pppd

Do you have any idea about it?

[DmitriyEshenko]

What accel-ppp version do you use?

[rudinyu]

I have 3 machines to run different version, but they have the same issues.

This is my accelpppd

net@250-50-accelpppd:~$ accel-cmd --version accel-cmd 7bcac049264393cf06c8be7743d96c66a7ad701c

net@250-51-accelpppd:~$ accel-cmd --version accel-cmd 1.11.2

net@250-55-accelpppd:~$ accel-cmd --version accel-cmd 2910add2238d419ad82e43f3ebf1fb8d5708e13b

[DmitriyEshenko]

Do you see in accel-cmd show stat acct lost or interim lost? How can I check this on my test server?

[rudinyu]

acct lost(total/5m/1m): 3713/0/0 acct avg query time(5m/1m): 0/0 ms interim sent: 0 interim lost(total/5m/1m): 0/0/0 interim avg query time(5m/1m): 0/0 ms

We use netstat -u netstat -u Active Internet connections (w/o servers) Proto Recv-Q Send-Q Local Address Foreign Address State udp 0 0 250-55-accelpppd:33883 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:64981 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:40809 10.1.25.2:radius-acct ESTABLISHED

When we stop dial-up testing program, the UDP sessions still be here.

Our stress testing is

1. we create more PPP users to dial up to accel-ppp
2. We just create dial-up traffic only.

[DmitriyEshenko]

I think it's possible if sessions have state "finish", do you may check this? After stress test run command accel-cmd show sessions match state finish then wait closing sessions and see netstat -u

[DmitriyEshenko]

If radius server not reply onAcct-Status-Type Start accel-ppp trying send again several times ([radius]max-try=3 by default and [radius]timeout=3 by defaults) and then close sessions. I think that's normal for this situation.

[rudinyu]

When we stop stress testing session, we use netstat -u to check. We get a more ESTABLISHED session. Even we wait for one day, these sessions still are on ESTABLISHED. We need to stop accel-ppp.

It looks like sock handle leak.

Thanks -Rudin

[DmitriyEshenko]

Do you may show me part of log with one of sessions which has state "start" or "finish" and has session long time. And part of accel-ppp.conf [ppp] and [pppoe]. Before log capture, you must set [log]level=5 [ppp]verbose=1 [ipoe]verbose=1 and run accel-cmd reload. I think this problem not radius

[rudinyu]

hinet@250-55-accelpppd:~$ netstat -tun | more Active Internet connections (w/o servers) Proto Recv-Q Send-Q Local Address Foreign Address State
tcp 0 0 127.0.0.1:54336 127.0.0.1:6379 TIME_WAIT
tcp 0 52 10.1.250.55:22 10.1.25.204:60493 ESTABLISHED udp 0 0 10.1.250.55:33084 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:37180 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:28988 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:49468 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:20796 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:45372 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:16700 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:53564 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:12604 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:41276 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:24892 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:61756 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:57660 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:33085 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:37181 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:45373 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:41277 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:28989 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:61757 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:20797 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:53565 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:49469 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:57661 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:24893 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:12605 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:16701 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:37182 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:61758 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:24894 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:20798 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:33086 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:12606 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:16702 10.1.25.2:1813 ESTABLISHED udp 0 0 10.1.250.55:28990 10.1.25.2:1813 ESTABLISHED hinet@250-55-accelpppd:~$ hinet@250-55-accelpppd:~$ hinet@250-55-accelpppd:~$ hinet@250-55-accelpppd:~$ netstat -u | more Active Internet connections (w/o servers) Proto Recv-Q Send-Q Local Address Foreign Address State
udp 0 0 250-55-accelpppd:33084 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:37180 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:28988 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:49468 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:20796 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:45372 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:16700 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:53564 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:12604 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:41276 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:24892 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:61756 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:57660 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:33085 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:37181 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:45373 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:41277 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:28989 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:61757 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:20797 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:53565 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:49469 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:57661 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:24893 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:12605 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:16701 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:37182 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:61758 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:24894 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:20798 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:33086 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:12606 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:16702 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:28990 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:45374 10.1.25.2:radius-acct ESTABLISHED udp 0 0 250-55-accelpppd:49470 10.1.25.2:radius-acct ESTABLISHED hinet@250-55-accelpppd:~$ netstat -u | wc -l 50899 hinet@250-55-accelpppd:~$ accel-cmd --version accel-cmd 2910add2238d419ad82e43f3ebf1fb8d5708e13b hinet@250-55-accelpppd:~$ hinet@250-55-accelpppd:~$ accel-cmd show sessions ifname | username | calling-sid | ip | type | comp | state | uptime --------+----------+-------------+----+------+------+-------+-------- hinet@250-55-accelpppd:~$ accel-cmd show stat uptime: 10.23:59:18 cpu: 0% mem(rss/virt): 398520/670772 kB core: mempool_allocated: 365603652 mempool_available: 856492 thread_count: 6 thread_active: 1 context_count: 684 context_sleeping: 0 context_pending: 0 md_handler_count: 50988 md_handler_pending: 0 timer_count: 51175 timer_pending: 0 sessions: starting: 0 active: 0 finishing: 0 pppoe: starting: 0 active: 0 delayed PADO: 0 recv PADI: 16030278 drop PADI: 17 sent PADO: 16030261 recv PADR(dup): 3997399(35476) sent PADS: 3950769 filtered: 0 radius(1, 10.1.25.2): state: active fail count: 180956 request count: 0 queue length: 0 auth sent: 3679793 auth lost(total/5m/1m): 240/0/0 auth avg query time(5m/1m): 4/6 ms acct sent: 7365211 acct lost(total/5m/1m): 186169/6/3 acct avg query time(5m/1m): 0/0 ms interim sent: 0 interim lost(total/5m/1m): 0/0/0 interim avg query time(5m/1m): 0/0 ms hinet@250-55-accelpppd:~$ accel-cmd show stat uptime: 10.23:59:21 cpu: 0% mem(rss/virt): 398520/670772 kB core: mempool_allocated: 365603652 mempool_available: 856620 thread_count: 6 thread_active: 1 context_count: 684 context_sleeping: 0 context_pending: 0 md_handler_count: 50988 md_handler_pending: 0 timer_count: 51175 timer_pending: 0 sessions: starting: 0 active: 0 finishing: 0 pppoe: starting: 0 active: 0 delayed PADO: 0 recv PADI: 16030278 drop PADI: 17 sent PADO: 16030261 recv PADR(dup): 3997399(35476) sent PADS: 3950769 filtered: 0 radius(1, 10.1.25.2): state: active fail count: 180956 request count: 0 queue length: 0 auth sent: 3679793 auth lost(total/5m/1m): 240/0/0 auth avg query time(5m/1m): 4/6 ms acct sent: 7365211 acct lost(total/5m/1m): 186169/6/3 acct avg query time(5m/1m): 0/0 ms interim sent: 0 interim lost(total/5m/1m): 0/0/0 interim avg query time(5m/1m): 0/0 ms hinet@250-55-accelpppd:~$

accel-ppp log [2019-05-14 09:52:49]: info: ens9.3601: recv [PPPoE PADI 00:00:77:0b:01:02 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 000a0000>] [2019-05-14 09:52:49]: info: ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 09:52:50]: debug: connlimit: check entry 2203510571008 [2019-05-14 09:52:50]: debug: connlimit: accept 2203510571008 [2019-05-14 09:52:50]: info: ens9.3601: recv [PPPoE PADI 00:00:77:0b:01:02 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 000a0000>] [2019-05-14 09:52:50]: info: ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 09:52:50]: info: ens9.3601: recv [PPPoE PADR 00:00:77:0b:01:02 => 52:54:00:61:9c:32 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 09:52:50]: info: ens9.3601: send [PPPoE PADS 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=4540 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 09:52:50]: debug: ens9.3601: lcp_layer_init [2019-05-14 09:52:50]: debug: ens9.3601: auth_layer_init [2019-05-14 09:52:50]: debug: ens9.3601: ccp_layer_init [2019-05-14 09:52:50]: debug: ens9.3601: ipcp_layer_init [2019-05-14 09:52:50]: debug: ens9.3601: ipv6cp_layer_init [2019-05-14 09:52:50]: debug: ens9.3601: ppp establishing [2019-05-14 09:52:50]: debug: ens9.3601: lcp_layer_start [2019-05-14 09:52:50]: info: ens9.3601: send [LCP ConfReq id=68 <mru 1440> <magic 50fe4b07>] [2019-05-14 09:52:50]: info: ens9.3601: recv [LCP ConfReq id=1 <magic 0506c320> <mru 65531>] [2019-05-14 09:52:50]: info: ens9.3601: send [LCP ConfNak id=1 <mru 1440>] [2019-05-14 09:52:50]: info: ens9.3601: recv [LCP ConfAck id=68 <mru 1440> <magic 50fe4b07>] [2019-05-14 09:52:50]: info: ens9.3601: recv [LCP ConfReq id=2 <magic 0506c320> <mru 1440>] [2019-05-14 09:52:50]: info: ens9.3601: send [LCP ConfAck id=2 ] [2019-05-14 09:52:50]: debug: ens9.3601: lcp_layer_started [2019-05-14 09:52:50]: debug: ens9.3601: auth_layer_start [2019-05-14 09:52:50]: info: ens9.3601: recv [PAP AuthReq id=1] [2019-05-14 09:52:50]: debug: ens9.3601: radius(1): req_enter 1 [2019-05-14 09:52:50]: info: ens9.3601: send [RADIUS(1) Access-Request id=1 <User-Name "test1"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <User-Password 0xe55ba0cbef33aa3e4da45e32ba2f3dcb>] [2019-05-14 09:52:50]: debug: ens9.3601: radius(1): req_exit 0 [2019-05-14 09:52:50]: info: ens9.3601: recv [RADIUS(1) Access-Accept id=1 <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daa8> ] [2019-05-14 09:52:50]: info: ppp0: connect: ppp0 <--> pppoe(00:00:77:0b:01:02) [2019-05-14 09:52:50]: debug: ppp0: ppp connected [2019-05-14 09:52:50]: info: ppp0: send [PAP AuthAck id=1 "Authentication succeeded"] [2019-05-14 09:52:50]: debug: ppp0: auth_layer_started [2019-05-14 09:52:50]: debug: ppp0: ccp_layer_start [2019-05-14 09:52:50]: debug: ppp0: ipcp_layer_start [2019-05-14 09:52:50]: info: ppp0: send [IPCP ConfReq id=62 <addr 10.1.250.199>] [2019-05-14 09:52:50]: debug: ppp0: ipv6cp_layer_start [2019-05-14 09:52:50]: info: ppp0: test1: authentication succeeded [2019-05-14 09:52:50]: info: ppp0: recv [IPCP ConfReq id=1 <addr 0.0.0.0>] [2019-05-14 09:52:50]: info: ppp0: send [IPCP ConfNak id=1 <addr 10.172.0.98>] [2019-05-14 09:52:50]: info: ppp0: recv [IPCP ConfAck id=62 <addr 10.1.250.199>] [2019-05-14 09:52:50]: info: ppp0: recv [IPCP ConfReq id=2 <addr 10.172.0.98>] [2019-05-14 09:52:50]: info: ppp0: send [IPCP ConfAck id=2] [2019-05-14 09:52:50]: debug: ppp0: ipcp_layer_started [2019-05-14 09:52:50]: debug: ppp0: radius(1): req_enter 1 [2019-05-14 09:52:50]: info: ppp0: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daa8> <Acct-Session-Id "0000000002f70b0d"> <Acct-Session-Time 0> <Acct-Input-Octets 0> <Acct-Output-Octets 0> <Acct-Input-Packets 0> <Acct-Output-Packets 0> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.98>] [2019-05-14 09:52:50]: debug: ppp0: radius(1): req_exit 0 [2019-05-14 09:52:50]: info: ppp0: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 09:52:50]: debug: ppp0: pppoe: ppp started [2019-05-14 09:53:15]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:53:15]: debug: cli: disconnect [2019-05-14 09:53:15]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:53:15]: debug: cli: disconnect [2019-05-14 09:53:20]: debug: ppp0: recv [LCP EchoReq id=3 <magic 0506c320>] [2019-05-14 09:53:20]: debug: ppp0: send [LCP EchoRep id=3 <magic 50fe4b07>] [2019-05-14 09:53:50]: debug: ppp0: recv [LCP EchoReq id=4 <magic 0506c320>] [2019-05-14 09:53:50]: debug: ppp0: send [LCP EchoRep id=4 <magic 50fe4b07>] [2019-05-14 09:54:16]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:54:16]: debug: cli: disconnect [2019-05-14 09:54:16]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:54:16]: debug: cli: disconnect [2019-05-14 09:54:20]: debug: ppp0: recv [LCP EchoReq id=5 <magic 0506c320>] [2019-05-14 09:54:20]: debug: ppp0: send [LCP EchoRep id=5 <magic 50fe4b07>] [2019-05-14 09:54:50]: debug: ppp0: recv [LCP EchoReq id=6 <magic 0506c320>] [2019-05-14 09:54:50]: debug: ppp0: send [LCP EchoRep id=6 <magic 50fe4b07>] [2019-05-14 09:54:50]: debug: ppp0: send [LCP EchoReq id=69 <magic 50fe4b07>] [2019-05-14 09:54:50]: debug: ppp0: recv [LCP EchoRep id=69 <magic 0506c320>] [2019-05-14 09:55:17]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:55:17]: debug: cli: disconnect [2019-05-14 09:55:17]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:55:17]: debug: cli: disconnect [2019-05-14 09:55:20]: debug: ppp0: recv [LCP EchoReq id=7 <magic 0506c320>] [2019-05-14 09:55:20]: debug: ppp0: send [LCP EchoRep id=7 <magic 50fe4b07>] [2019-05-14 09:55:50]: debug: ppp0: recv [LCP EchoReq id=8 <magic 0506c320>] [2019-05-14 09:55:50]: debug: ppp0: send [LCP EchoRep id=8 <magic 50fe4b07>] [2019-05-14 09:56:18]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:56:18]: debug: cli: disconnect [2019-05-14 09:56:18]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:56:18]: debug: cli: disconnect [2019-05-14 09:56:20]: debug: ppp0: recv [LCP EchoReq id=9 <magic 0506c320>] [2019-05-14 09:56:20]: debug: ppp0: send [LCP EchoRep id=9 <magic 50fe4b07>] [2019-05-14 09:56:50]: debug: ppp0: recv [LCP EchoReq id=a <magic 0506c320>] [2019-05-14 09:56:50]: debug: ppp0: send [LCP EchoRep id=a <magic 50fe4b07>] [2019-05-14 09:56:50]: debug: ppp0: send [LCP EchoReq id=6a <magic 50fe4b07>] [2019-05-14 09:56:50]: debug: ppp0: recv [LCP EchoRep id=6a <magic 0506c320>] [2019-05-14 09:57:19]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:57:19]: debug: cli: disconnect [2019-05-14 09:57:19]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:57:19]: debug: cli: disconnect [2019-05-14 09:57:20]: debug: ppp0: recv [LCP EchoReq id=b <magic 0506c320>] [2019-05-14 09:57:20]: debug: ppp0: send [LCP EchoRep id=b <magic 50fe4b07>] [2019-05-14 09:57:50]: debug: ppp0: recv [LCP EchoReq id=c <magic 0506c320>] [2019-05-14 09:57:50]: debug: ppp0: send [LCP EchoRep id=c <magic 50fe4b07>] [2019-05-14 09:58:20]: debug: ppp0: recv [LCP EchoReq id=d <magic 0506c320>] [2019-05-14 09:58:20]: debug: ppp0: send [LCP EchoRep id=d <magic 50fe4b07>] [2019-05-14 09:58:20]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:58:20]: debug: cli: disconnect [2019-05-14 09:58:20]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:58:20]: debug: cli: disconnect [2019-05-14 09:58:50]: debug: ppp0: recv [LCP EchoReq id=e <magic 0506c320>] [2019-05-14 09:58:50]: debug: ppp0: send [LCP EchoRep id=e <magic 50fe4b07>] [2019-05-14 09:58:50]: debug: ppp0: send [LCP EchoReq id=6b <magic 50fe4b07>] [2019-05-14 09:58:50]: debug: ppp0: recv [LCP EchoRep id=6b <magic 0506c320>] [2019-05-14 09:59:20]: debug: ppp0: recv [LCP EchoReq id=f <magic 0506c320>] [2019-05-14 09:59:20]: debug: ppp0: send [LCP EchoRep id=f <magic 50fe4b07>] [2019-05-14 09:59:21]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:59:21]: debug: cli: disconnect [2019-05-14 09:59:21]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:59:21]: debug: cli: disconnect [2019-05-14 09:59:50]: debug: ppp0: recv [LCP EchoReq id=10 <magic 0506c320>] [2019-05-14 09:59:50]: debug: ppp0: send [LCP EchoRep id=10 <magic 50fe4b07>] [2019-05-14 10:00:20]: debug: ppp0: recv [LCP EchoReq id=11 <magic 0506c320>] [2019-05-14 10:00:20]: debug: ppp0: send [LCP EchoRep id=11 <magic 50fe4b07>] [2019-05-14 10:00:22]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:00:22]: debug: cli: disconnect [2019-05-14 10:00:22]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:00:22]: debug: cli: disconnect [2019-05-14 10:00:50]: debug: ppp0: recv [LCP EchoReq id=12 <magic 0506c320>] [2019-05-14 10:00:50]: debug: ppp0: send [LCP EchoRep id=12 <magic 50fe4b07>] [2019-05-14 10:00:50]: debug: ppp0: send [LCP EchoReq id=6c <magic 50fe4b07>] [2019-05-14 10:00:50]: debug: ppp0: recv [LCP EchoRep id=6c <magic 0506c320>] [2019-05-14 10:01:20]: debug: ppp0: recv [LCP EchoReq id=13 <magic 0506c320>] [2019-05-14 10:01:20]: debug: ppp0: send [LCP EchoRep id=13 <magic 50fe4b07>] [2019-05-14 10:01:23]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:01:23]: debug: cli: disconnect [2019-05-14 10:01:23]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:01:23]: debug: cli: disconnect [2019-05-14 10:01:50]: debug: ppp0: recv [LCP EchoReq id=14 <magic 0506c320>] [2019-05-14 10:01:50]: debug: ppp0: send [LCP EchoRep id=14 <magic 50fe4b07>] [2019-05-14 10:02:20]: debug: ppp0: recv [LCP EchoReq id=15 <magic 0506c320>] [2019-05-14 10:02:20]: debug: ppp0: send [LCP EchoRep id=15 <magic 50fe4b07>] [2019-05-14 10:02:24]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:02:24]: debug: cli: disconnect [2019-05-14 10:02:24]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:02:24]: debug: cli: disconnect [2019-05-14 10:02:50]: debug: ppp0: recv [LCP EchoReq id=16 <magic 0506c320>] [2019-05-14 10:02:50]: debug: ppp0: send [LCP EchoRep id=16 <magic 50fe4b07>] [2019-05-14 10:02:50]: debug: ppp0: send [LCP EchoReq id=6d <magic 50fe4b07>] [2019-05-14 10:02:50]: debug: ppp0: recv [LCP EchoRep id=6d <magic 0506c320>] [2019-05-14 10:03:20]: debug: ppp0: recv [LCP EchoReq id=17 <magic 0506c320>] [2019-05-14 10:03:20]: debug: ppp0: send [LCP EchoRep id=17 <magic 50fe4b07>] [2019-05-14 10:03:25]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:03:25]: debug: cli: disconnect [2019-05-14 10:03:25]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:03:25]: debug: cli: disconnect [2019-05-14 10:03:50]: debug: ppp0: recv [LCP EchoReq id=18 <magic 0506c320>] [2019-05-14 10:03:50]: debug: ppp0: send [LCP EchoRep id=18 <magic 50fe4b07>] [2019-05-14 10:04:20]: debug: ppp0: recv [LCP EchoReq id=19 <magic 0506c320>] [2019-05-14 10:04:20]: debug: ppp0: send [LCP EchoRep id=19 <magic 50fe4b07>] [2019-05-14 10:04:26]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:04:26]: debug: cli: disconnect [2019-05-14 10:04:26]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:04:26]: debug: cli: disconnect [2019-05-14 10:04:50]: debug: ppp0: recv [LCP EchoReq id=1a <magic 0506c320>] [2019-05-14 10:04:50]: debug: ppp0: send [LCP EchoRep id=1a <magic 50fe4b07>] [2019-05-14 10:04:50]: debug: ppp0: send [LCP EchoReq id=6e <magic 50fe4b07>] [2019-05-14 10:04:50]: debug: ppp0: recv [LCP EchoRep id=6e <magic 0506c320>] [2019-05-14 10:05:20]: debug: ppp0: recv [LCP EchoReq id=1b <magic 0506c320>] [2019-05-14 10:05:20]: debug: ppp0: send [LCP EchoRep id=1b <magic 50fe4b07>] [2019-05-14 10:05:27]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:05:27]: debug: cli: disconnect [2019-05-14 10:05:27]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:05:27]: debug: cli: disconnect [2019-05-14 10:05:50]: debug: ppp0: recv [LCP EchoReq id=1c <magic 0506c320>] [2019-05-14 10:05:50]: debug: ppp0: send [LCP EchoRep id=1c <magic 50fe4b07>] [2019-05-14 10:06:20]: debug: ppp0: recv [LCP EchoReq id=1d <magic 0506c320>] [2019-05-14 10:06:20]: debug: ppp0: send [LCP EchoRep id=1d <magic 50fe4b07>] [2019-05-14 10:06:28]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:06:28]: debug: cli: disconnect [2019-05-14 10:06:28]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:06:28]: debug: cli: disconnect [2019-05-14 10:06:50]: debug: ppp0: recv [LCP EchoReq id=1e <magic 0506c320>] [2019-05-14 10:06:50]: debug: ppp0: send [LCP EchoRep id=1e <magic 50fe4b07>] [2019-05-14 10:06:50]: debug: ppp0: send [LCP EchoReq id=6f <magic 50fe4b07>] [2019-05-14 10:06:50]: debug: ppp0: recv [LCP EchoRep id=6f <magic 0506c320>] [2019-05-14 10:07:20]: debug: ppp0: recv [LCP EchoReq id=1f <magic 0506c320>] [2019-05-14 10:07:20]: debug: ppp0: send [LCP EchoRep id=1f <magic 50fe4b07>] [2019-05-14 10:07:29]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:07:29]: debug: cli: disconnect [2019-05-14 10:07:29]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:07:29]: debug: cli: disconnect [2019-05-14 10:07:50]: debug: ppp0: recv [LCP EchoReq id=20 <magic 0506c320>] [2019-05-14 10:07:50]: debug: ppp0: send [LCP EchoRep id=20 <magic 50fe4b07>] [2019-05-14 10:08:20]: debug: ppp0: recv [LCP EchoReq id=21 <magic 0506c320>] [2019-05-14 10:08:20]: debug: ppp0: send [LCP EchoRep id=21 <magic 50fe4b07>] [2019-05-14 10:08:30]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:08:30]: debug: cli: disconnect [2019-05-14 10:08:31]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:08:31]: debug: cli: disconnect [2019-05-14 10:08:50]: debug: ppp0: recv [LCP EchoReq id=22 <magic 0506c320>] [2019-05-14 10:08:50]: debug: ppp0: send [LCP EchoRep id=22 <magic 50fe4b07>] [2019-05-14 10:08:50]: debug: ppp0: send [LCP EchoReq id=70 <magic 50fe4b07>] [2019-05-14 10:08:50]: debug: ppp0: recv [LCP EchoRep id=70 <magic 0506c320>] [2019-05-14 10:09:20]: debug: ppp0: recv [LCP EchoReq id=23 <magic 0506c320>] [2019-05-14 10:09:20]: debug: ppp0: send [LCP EchoRep id=23 <magic 50fe4b07>] [2019-05-14 10:09:31]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:09:31]: debug: cli: disconnect [2019-05-14 10:09:31]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:09:31]: debug: cli: disconnect [2019-05-14 10:09:50]: debug: ppp0: recv [LCP EchoReq id=24 <magic 0506c320>] [2019-05-14 10:09:50]: debug: ppp0: send [LCP EchoRep id=24 <magic 50fe4b07>] [2019-05-14 10:10:20]: debug: ppp0: recv [LCP EchoReq id=25 <magic 0506c320>] [2019-05-14 10:10:20]: debug: ppp0: send [LCP EchoRep id=25 <magic 50fe4b07>] [2019-05-14 10:10:33]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:10:33]: debug: cli: disconnect [2019-05-14 10:10:33]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:10:33]: debug: cli: disconnect [2019-05-14 10:10:50]: debug: ppp0: recv [LCP EchoReq id=26 <magic 0506c320>] [2019-05-14 10:10:50]: debug: ppp0: send [LCP EchoRep id=26 <magic 50fe4b07>] [2019-05-14 10:10:50]: debug: ppp0: send [LCP EchoReq id=71 <magic 50fe4b07>] [2019-05-14 10:10:50]: debug: ppp0: recv [LCP EchoRep id=71 <magic 0506c320>] [2019-05-14 10:11:20]: debug: ppp0: recv [LCP EchoReq id=27 <magic 0506c320>] [2019-05-14 10:11:20]: debug: ppp0: send [LCP EchoRep id=27 <magic 50fe4b07>] [2019-05-14 10:11:33]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:11:33]: debug: cli: disconnect [2019-05-14 10:11:33]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:11:33]: debug: cli: disconnect [2019-05-14 10:11:50]: debug: ppp0: recv [LCP EchoReq id=28 <magic 0506c320>] [2019-05-14 10:11:50]: debug: ppp0: send [LCP EchoRep id=28 <magic 50fe4b07>] [2019-05-14 10:12:20]: debug: ppp0: recv [LCP EchoReq id=29 <magic 0506c320>] [2019-05-14 10:12:20]: debug: ppp0: send [LCP EchoRep id=29 <magic 50fe4b07>] [2019-05-14 10:12:35]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:12:35]: debug: cli: disconnect [2019-05-14 10:12:35]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:12:35]: debug: cli: disconnect [2019-05-14 10:12:50]: debug: ppp0: recv [LCP EchoReq id=2a <magic 0506c320>] [2019-05-14 10:12:50]: debug: ppp0: send [LCP EchoRep id=2a <magic 50fe4b07>] [2019-05-14 10:12:50]: debug: ppp0: send [LCP EchoReq id=72 <magic 50fe4b07>] [2019-05-14 10:12:50]: debug: ppp0: recv [LCP EchoRep id=72 <magic 0506c320>] [2019-05-14 10:12:50]: info: ens9.3601: recv [PPPoE PADT 00:00:77:0b:01:02 => 52:54:00:61:9c:32 sid=4540] [2019-05-14 10:12:50]: debug: ppp0: terminate [2019-05-14 10:12:50]: debug: ppp0: radius(1): req_enter 1 [2019-05-14 10:12:50]: info: ppp0: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daa8> <Acct-Session-Id "0000000002f70b0d"> <Acct-Session-Time 1200> <Acct-Input-Octets 30> <Acct-Output-Octets 30> <Acct-Input-Packets 3> <Acct-Output-Packets 3> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.98> ] [2019-05-14 10:12:50]: debug: ppp0: radius(1): req_exit 0 [2019-05-14 10:12:50]: debug: ppp0: pppoe: ppp finished [2019-05-14 10:12:50]: debug: ppp0: lcp_layer_free [2019-05-14 10:12:50]: debug: ppp0: auth_layer_free [2019-05-14 10:12:50]: debug: ppp0: ccp_layer_free [2019-05-14 10:12:50]: debug: ppp0: ipcp_layer_free [2019-05-14 10:12:50]: debug: ppp0: ipv6cp_layer_free [2019-05-14 10:12:50]: debug: ppp0: ppp destablished [2019-05-14 10:12:50]: info: ens9.3601: send [PPPoE PADT 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=4540 <AC-Name 250.55> ] [2019-05-14 10:12:50]: info: ppp0: disconnected [2019-05-14 10:12:50]: info: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:12:50]: debug: connlimit: check entry 2203510571008 [2019-05-14 10:12:50]: debug: connlimit: accept 2203510571008 [2019-05-14 10:12:50]: info: ens9.3601: recv [PPPoE PADI 00:00:77:0b:01:02 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 000a0000>] [2019-05-14 10:12:50]: info: ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 10:12:51]: debug: connlimit: check entry 2203510571008 [2019-05-14 10:12:51]: debug: connlimit: accept 2203510571008 [2019-05-14 10:12:51]: info: ens9.3601: recv [PPPoE PADI 00:00:77:0b:01:02 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 000a0000>] [2019-05-14 10:12:51]: info: ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 10:12:51]: info: ens9.3601: recv [PPPoE PADR 00:00:77:0b:01:02 => 52:54:00:61:9c:32 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 10:12:51]: info: ens9.3601: send [PPPoE PADS 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=4580 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 10:12:51]: debug: ens9.3601: lcp_layer_init [2019-05-14 10:12:51]: debug: ens9.3601: auth_layer_init [2019-05-14 10:12:51]: debug: ens9.3601: ccp_layer_init [2019-05-14 10:12:51]: debug: ens9.3601: ipcp_layer_init [2019-05-14 10:12:51]: debug: ens9.3601: ipv6cp_layer_init [2019-05-14 10:12:51]: debug: ens9.3601: ppp establishing [2019-05-14 10:12:51]: debug: ens9.3601: lcp_layer_start [2019-05-14 10:12:51]: info: ens9.3601: send [LCP ConfReq id=28 <mru 1440> <magic 554198fa>] [2019-05-14 10:12:51]: info: ens9.3601: recv [LCP ConfReq id=1 <magic 0506c320> <mru 65531>] [2019-05-14 10:12:51]: info: ens9.3601: send [LCP ConfNak id=1 <mru 1440>] [2019-05-14 10:12:51]: info: ens9.3601: recv [LCP ConfAck id=28 <mru 1440> <magic 554198fa>] [2019-05-14 10:12:51]: info: ens9.3601: recv [LCP ConfReq id=2 <magic 0506c320> <mru 1440>] [2019-05-14 10:12:51]: info: ens9.3601: send [LCP ConfAck id=2 ] [2019-05-14 10:12:51]: debug: ens9.3601: lcp_layer_started [2019-05-14 10:12:51]: debug: ens9.3601: auth_layer_start [2019-05-14 10:12:51]: info: ens9.3601: recv [PAP AuthReq id=1] [2019-05-14 10:12:51]: debug: ens9.3601: radius(1): req_enter 1 [2019-05-14 10:12:51]: info: ens9.3601: send [RADIUS(1) Access-Request id=1 <User-Name "test1"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <User-Password 0x7502e922c06cd9ea9c15e5680e4a44d6>] [2019-05-14 10:12:51]: debug: ens9.3601: radius(1): req_exit 0 [2019-05-14 10:12:51]: info: ens9.3601: recv [RADIUS(1) Access-Accept id=1 <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daac> ] [2019-05-14 10:12:51]: info: ppp0: connect: ppp0 <--> pppoe(00:00:77:0b:01:02) [2019-05-14 10:12:51]: debug: ppp0: ppp connected [2019-05-14 10:12:51]: info: ppp0: send [PAP AuthAck id=1 "Authentication succeeded"] [2019-05-14 10:12:51]: debug: ppp0: auth_layer_started [2019-05-14 10:12:51]: debug: ppp0: ccp_layer_start [2019-05-14 10:12:51]: debug: ppp0: ipcp_layer_start [2019-05-14 10:12:51]: info: ppp0: send [IPCP ConfReq id=8c <addr 10.1.250.199>] [2019-05-14 10:12:51]: debug: ppp0: ipv6cp_layer_start [2019-05-14 10:12:51]: info: ppp0: test1: authentication succeeded [2019-05-14 10:12:51]: info: ppp0: recv [IPCP ConfReq id=1 <addr 0.0.0.0>] [2019-05-14 10:12:51]: info: ppp0: send [IPCP ConfNak id=1 <addr 10.172.0.99>] [2019-05-14 10:12:51]: info: ppp0: recv [IPCP ConfAck id=8c <addr 10.1.250.199>] [2019-05-14 10:12:51]: info: ppp0: recv [IPCP ConfReq id=2 <addr 10.172.0.99>] [2019-05-14 10:12:51]: info: ppp0: send [IPCP ConfAck id=2] [2019-05-14 10:12:51]: debug: ppp0: ipcp_layer_started [2019-05-14 10:12:51]: debug: ppp0: radius(1): req_enter 1 [2019-05-14 10:12:51]: info: ppp0: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daac> <Acct-Session-Id "0000000002f70b0e"> <Acct-Session-Time 0> <Acct-Input-Octets 0> <Acct-Output-Octets 0> <Acct-Input-Packets 0> <Acct-Output-Packets 0> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.99>] [2019-05-14 10:12:51]: debug: ppp0: radius(1): req_exit 0 [2019-05-14 10:12:51]: info: ppp0: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:12:51]: debug: ppp0: pppoe: ppp started [2019-05-14 10:13:21]: debug: ppp0: recv [LCP EchoReq id=3 <magic 0506c320>] [2019-05-14 10:13:21]: debug: ppp0: send [LCP EchoRep id=3 <magic 554198fa>] [2019-05-14 10:13:35]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:13:35]: debug: cli: disconnect [2019-05-14 10:13:35]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:13:35]: debug: cli: disconnect [2019-05-14 10:13:51]: debug: ppp0: recv [LCP EchoReq id=4 <magic 0506c320>] [2019-05-14 10:13:51]: debug: ppp0: send [LCP EchoRep id=4 <magic 554198fa>] [2019-05-14 10:14:21]: debug: ppp0: recv [LCP EchoReq id=5 <magic 0506c320>] [2019-05-14 10:14:21]: debug: ppp0: send [LCP EchoRep id=5 <magic 554198fa>] [2019-05-14 10:14:37]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:14:37]: debug: cli: disconnect [2019-05-14 10:14:37]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:14:37]: debug: cli: disconnect [2019-05-14 10:14:51]: debug: ppp0: recv [LCP EchoReq id=6 <magic 0506c320>] [2019-05-14 10:14:51]: debug: ppp0: send [LCP EchoRep id=6 <magic 554198fa>] [2019-05-14 10:14:51]: debug: ppp0: send [LCP EchoReq id=29 <magic 554198fa>] [2019-05-14 10:14:51]: debug: ppp0: recv [LCP EchoRep id=29 <magic 0506c320>] [2019-05-14 10:15:21]: debug: ppp0: recv [LCP EchoReq id=7 <magic 0506c320>] [2019-05-14 10:15:21]: debug: ppp0: send [LCP EchoRep id=7 <magic 554198fa>] [2019-05-14 10:15:37]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:15:37]: debug: cli: disconnect [2019-05-14 10:15:37]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:15:37]: debug: cli: disconnect [2019-05-14 10:15:51]: debug: ppp0: recv [LCP EchoReq id=8 <magic 0506c320>] [2019-05-14 10:15:51]: debug: ppp0: send [LCP EchoRep id=8 <magic 554198fa>] [2019-05-14 10:16:21]: debug: ppp0: recv [LCP EchoReq id=9 <magic 0506c320>] [2019-05-14 10:16:21]: debug: ppp0: send [LCP EchoRep id=9 <magic 554198fa>] [2019-05-14 10:16:39]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:16:39]: debug: cli: disconnect [2019-05-14 10:16:39]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:16:39]: debug: cli: disconnect [2019-05-14 10:16:51]: debug: ppp0: recv [LCP EchoReq id=a <magic 0506c320>] [2019-05-14 10:16:51]: debug: ppp0: send [LCP EchoRep id=a <magic 554198fa>] [2019-05-14 10:16:51]: debug: ppp0: send [LCP EchoReq id=2a <magic 554198fa>] [2019-05-14 10:16:51]: debug: ppp0: recv [LCP EchoRep id=2a <magic 0506c320>] [2019-05-14 10:17:21]: info: ppp0: recv [LCP TermReq id=b] [2019-05-14 10:17:21]: info: ppp0: send [LCP TermAck id=11] [2019-05-14 10:17:21]: debug: ppp0: terminate [2019-05-14 10:17:21]: debug: ppp0: lcp_layer_finish [2019-05-14 10:17:21]: debug: ppp0: auth_layer_finish [2019-05-14 10:17:21]: debug: ppp0: auth_layer_finished [2019-05-14 10:17:21]: debug: ppp0: ccp_layer_finish [2019-05-14 10:17:21]: debug: ppp0: ccp_layer_finished [2019-05-14 10:17:21]: debug: ppp0: ipcp_layer_finish [2019-05-14 10:17:21]: debug: ppp0: ipcp_layer_finished [2019-05-14 10:17:21]: debug: ppp0: ipv6cp_layer_finish [2019-05-14 10:17:21]: debug: ppp0: ipv6cp_layer_finished [2019-05-14 10:17:21]: info: ens9.3601: recv [PPPoE PADT 00:00:77:0b:01:02 => 52:54:00:61:9c:32 sid=4580] [2019-05-14 10:17:21]: debug: ppp0: radius(1): req_enter 1 [2019-05-14 10:17:21]: info: ppp0: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daac> <Acct-Session-Id "0000000002f70b0e"> <Acct-Session-Time 270> <Acct-Input-Octets 30> <Acct-Output-Octets 30> <Acct-Input-Packets 3> <Acct-Output-Packets 3> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.99> ] [2019-05-14 10:17:21]: debug: ppp0: radius(1): req_exit 0 [2019-05-14 10:17:21]: debug: ppp0: pppoe: ppp finished [2019-05-14 10:17:21]: debug: ppp0: lcp_layer_free [2019-05-14 10:17:21]: debug: ppp0: auth_layer_free [2019-05-14 10:17:21]: debug: ppp0: ccp_layer_free [2019-05-14 10:17:21]: debug: ppp0: ipcp_layer_free [2019-05-14 10:17:21]: debug: ppp0: ipv6cp_layer_free [2019-05-14 10:17:21]: debug: ppp0: ppp destablished [2019-05-14 10:17:21]: info: ens9.3601: send [PPPoE PADT 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=4580 <AC-Name 250.55> ] [2019-05-14 10:17:21]: info: ppp0: disconnected [2019-05-14 10:17:21]: info: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:17:39]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:17:39]: debug: cli: disconnect [2019-05-14 10:17:39]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:17:39]: debug: cli: disconnect [2019-05-14 10:18:41]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:18:41]: debug: cli: disconnect [2019-05-14 10:18:41]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:18:41]: debug: cli: disconnect [2019-05-14 10:18:50]: debug: connlimit: check entry 270303448028242 [2019-05-14 10:18:50]: debug: connlimit: remove 2203510571008 [2019-05-14 10:18:50]: debug: connlimit: add entry 270303448028242 [2019-05-14 10:18:50]: debug: connlimit: accept 270303448028242 [2019-05-14 10:18:50]: info: ens9.3601: recv [PPPoE PADI 52:54:00:ed:d6:f5 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 61590000>] [2019-05-14 10:18:50]: info: ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=0000 <AC-Name 250.55> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b15ba0f45e3d01272> <Host-Uniq 61590000>] [2019-05-14 10:18:55]: debug: connlimit: check entry 270303448028242 [2019-05-14 10:18:55]: debug: connlimit: accept 270303448028242 [2019-05-14 10:18:55]: info: ens9.3601: recv [PPPoE PADI 52:54:00:ed:d6:f5 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 61590000>] [2019-05-14 10:18:55]: info: ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=0000 <AC-Name 250.55> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b21f30c58c4af9f80> <Host-Uniq 61590000>] [2019-05-14 10:18:55]: info: ens9.3601: recv [PPPoE PADR 52:54:00:ed:d6:f5 => 52:54:00:61:9c:32 sid=0000 <Host-Uniq 61590000> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b21f30c58c4af9f80>] [2019-05-14 10:18:55]: info: ens9.3601: send [PPPoE PADS 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=45c0 <AC-Name 250.55> <Host-Uniq 61590000>] [2019-05-14 10:18:55]: debug: ens9.3601: lcp_layer_init [2019-05-14 10:18:55]: debug: ens9.3601: auth_layer_init [2019-05-14 10:18:55]: debug: ens9.3601: ccp_layer_init [2019-05-14 10:18:55]: debug: ens9.3601: ipcp_layer_init [2019-05-14 10:18:55]: debug: ens9.3601: ipv6cp_layer_init [2019-05-14 10:18:55]: debug: ens9.3601: ppp establishing [2019-05-14 10:18:55]: debug: ens9.3601: lcp_layer_start [2019-05-14 10:18:55]: info: ens9.3601: send [LCP ConfReq id=27 <mru 1440> <magic 4a2bb9ea>] [2019-05-14 10:18:55]: info: ens9.3601: recv [LCP ConfReq id=1 <mru 1492> <magic 38e53b5a>] [2019-05-14 10:18:55]: info: ens9.3601: send [LCP ConfAck id=1 ] [2019-05-14 10:18:55]: info: ens9.3601: recv [LCP ConfAck id=27 <mru 1440> <magic 4a2bb9ea>] [2019-05-14 10:18:55]: debug: ens9.3601: lcp_layer_started [2019-05-14 10:18:55]: debug: ens9.3601: auth_layer_start [2019-05-14 10:18:55]: debug: ens9.3601: recv [LCP EchoReq id=0 <magic 38e53b5a>] [2019-05-14 10:18:55]: debug: ens9.3601: send [LCP EchoRep id=0 <magic 4a2bb9ea>] [2019-05-14 10:18:55]: info: ens9.3601: recv [PAP AuthReq id=1] [2019-05-14 10:18:55]: debug: ens9.3601: radius(1): req_enter 1 [2019-05-14 10:18:55]: info: ens9.3601: send [RADIUS(1) Access-Request id=1 <User-Name "test1"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <User-Password 0x21b9a44f7cec58535b62f3b0f1767c58>] [2019-05-14 10:18:55]: debug: ens9.3601: radius(1): req_exit 0 [2019-05-14 10:18:55]: info: ens9.3601: recv [RADIUS(1) Access-Accept id=1 <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dab0> ] [2019-05-14 10:18:55]: info: ppp0: connect: ppp0 <--> pppoe(52:54:00:ed:d6:f5) [2019-05-14 10:18:55]: debug: ppp0: ppp connected [2019-05-14 10:18:55]: info: ppp0: send [PAP AuthAck id=1 "Authentication succeeded"] [2019-05-14 10:18:55]: debug: ppp0: auth_layer_started [2019-05-14 10:18:55]: debug: ppp0: ccp_layer_start [2019-05-14 10:18:55]: debug: ppp0: ipcp_layer_start [2019-05-14 10:18:55]: info: ppp0: send [IPCP ConfReq id=16 <addr 10.1.250.199>] [2019-05-14 10:18:55]: debug: ppp0: ipv6cp_layer_start [2019-05-14 10:18:55]: info: ppp0: test1: authentication succeeded [2019-05-14 10:18:55]: info: ppp0: recv [IPCP ConfReq id=1 <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>] [2019-05-14 10:18:55]: info: ppp0: send [IPCP ConfNak id=1 <addr 10.172.0.100> <dns1 168.95.1.1> <dns2 168.95.192.1>] [2019-05-14 10:18:55]: info: ppp0: recv [IPCP ConfAck id=16 <addr 10.1.250.199>] [2019-05-14 10:18:55]: info: ppp0: recv [IPCP ConfReq id=2 <addr 10.172.0.100> <dns1 168.95.1.1> <dns2 168.95.192.1>] [2019-05-14 10:18:55]: info: ppp0: send [IPCP ConfAck id=2] [2019-05-14 10:18:55]: debug: ppp0: ipcp_layer_started [2019-05-14 10:18:55]: debug: ppp0: radius(1): req_enter 1 [2019-05-14 10:18:55]: info: ppp0: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dab0> <Acct-Session-Id "0000000002f70b0f"> <Acct-Session-Time 0> <Acct-Input-Octets 0> <Acct-Output-Octets 0> <Acct-Input-Packets 0> <Acct-Output-Packets 0> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.100>] [2019-05-14 10:18:55]: debug: ppp0: radius(1): req_exit 0 [2019-05-14 10:18:55]: info: ppp0: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:18:55]: debug: ppp0: pppoe: ppp started [2019-05-14 10:19:25]: debug: ppp0: recv [LCP EchoReq id=1 <magic 38e53b5a>] [2019-05-14 10:19:25]: debug: ppp0: send [LCP EchoRep id=1 <magic 4a2bb9ea>] [2019-05-14 10:19:41]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:19:41]: debug: cli: disconnect [2019-05-14 10:19:41]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:19:41]: debug: cli: disconnect [2019-05-14 10:19:55]: debug: ppp0: recv [LCP EchoReq id=2 <magic 38e53b5a>] [2019-05-14 10:19:55]: debug: ppp0: send [LCP EchoRep id=2 <magic 4a2bb9ea>] [2019-05-14 10:20:25]: debug: ppp0: recv [LCP EchoReq id=3 <magic 38e53b5a>] [2019-05-14 10:20:25]: debug: ppp0: send [LCP EchoRep id=3 <magic 4a2bb9ea>] [2019-05-14 10:20:43]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:20:43]: debug: cli: disconnect [2019-05-14 10:20:43]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:20:43]: debug: cli: disconnect [2019-05-14 10:20:55]: debug: ppp0: send [LCP EchoReq id=28 <magic 4a2bb9ea>] [2019-05-14 10:20:55]: debug: ppp0: recv [LCP EchoRep id=28 <magic 38e53b5a>] [2019-05-14 10:20:55]: debug: ppp0: recv [LCP EchoReq id=4 <magic 38e53b5a>] [2019-05-14 10:20:55]: debug: ppp0: send [LCP EchoRep id=4 <magic 4a2bb9ea>] [2019-05-14 10:21:25]: debug: ppp0: recv [LCP EchoReq id=5 <magic 38e53b5a>] [2019-05-14 10:21:25]: debug: ppp0: send [LCP EchoRep id=5 <magic 4a2bb9ea>] [2019-05-14 10:21:43]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:21:43]: debug: cli: disconnect [2019-05-14 10:21:43]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:21:43]: debug: cli: disconnect [2019-05-14 10:21:55]: debug: ppp0: recv [LCP EchoReq id=6 <magic 38e53b5a>] [2019-05-14 10:21:55]: debug: ppp0: send [LCP EchoRep id=6 <magic 4a2bb9ea>] [2019-05-14 10:22:25]: debug: ppp0: recv [LCP EchoReq id=7 <magic 38e53b5a>] [2019-05-14 10:22:25]: debug: ppp0: send [LCP EchoRep id=7 <magic 4a2bb9ea>] [2019-05-14 10:22:44]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:22:44]: debug: cli: disconnect [2019-05-14 10:22:44]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:22:44]: debug: cli: disconnect [2019-05-14 10:22:55]: debug: ppp0: send [LCP EchoReq id=29 <magic 4a2bb9ea>] [2019-05-14 10:22:55]: debug: ppp0: recv [LCP EchoRep id=29 <magic 38e53b5a>] [2019-05-14 10:22:55]: debug: ppp0: recv [LCP EchoReq id=8 <magic 38e53b5a>] [2019-05-14 10:22:55]: debug: ppp0: send [LCP EchoRep id=8 <magic 4a2bb9ea>] [2019-05-14 10:23:26]: debug: ppp0: recv [LCP EchoReq id=9 <magic 38e53b5a>] [2019-05-14 10:23:26]: debug: ppp0: send [LCP EchoRep id=9 <magic 4a2bb9ea>] [2019-05-14 10:23:45]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:23:45]: debug: cli: disconnect [2019-05-14 10:23:45]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:23:45]: debug: cli: disconnect [2019-05-14 10:23:56]: debug: ppp0: recv [LCP EchoReq id=a <magic 38e53b5a>] [2019-05-14 10:23:56]: debug: ppp0: send [LCP EchoRep id=a <magic 4a2bb9ea>] [2019-05-14 10:24:26]: debug: ppp0: recv [LCP EchoReq id=b <magic 38e53b5a>] [2019-05-14 10:24:26]: debug: ppp0: send [LCP EchoRep id=b <magic 4a2bb9ea>] [2019-05-14 10:24:46]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:24:46]: debug: cli: disconnect [2019-05-14 10:24:46]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:24:46]: debug: cli: disconnect [2019-05-14 10:24:55]: debug: ppp0: send [LCP EchoReq id=2a <magic 4a2bb9ea>] [2019-05-14 10:24:55]: debug: ppp0: recv [LCP EchoRep id=2a <magic 38e53b5a>] [2019-05-14 10:24:56]: debug: ppp0: recv [LCP EchoReq id=c <magic 38e53b5a>] [2019-05-14 10:24:56]: debug: ppp0: send [LCP EchoRep id=c <magic 4a2bb9ea>] [2019-05-14 10:25:26]: debug: ppp0: recv [LCP EchoReq id=d <magic 38e53b5a>] [2019-05-14 10:25:26]: debug: ppp0: send [LCP EchoRep id=d <magic 4a2bb9ea>] [2019-05-14 10:25:47]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:25:47]: debug: cli: disconnect [2019-05-14 10:25:47]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:25:47]: debug: cli: disconnect [2019-05-14 10:25:56]: debug: ppp0: recv [LCP EchoReq id=e <magic 38e53b5a>] [2019-05-14 10:25:56]: debug: ppp0: send [LCP EchoRep id=e <magic 4a2bb9ea>] [2019-05-14 10:26:48]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:26:48]: debug: cli: disconnect [2019-05-14 10:26:48]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:26:48]: debug: cli: disconnect [2019-05-14 10:26:55]: debug: ppp0: send [LCP EchoReq id=2b <magic 4a2bb9ea>] [2019-05-14 10:27:49]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:27:49]: debug: cli: disconnect [2019-05-14 10:27:49]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:27:49]: debug: cli: disconnect [2019-05-14 10:28:50]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:28:50]: debug: cli: disconnect [2019-05-14 10:28:50]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:28:50]: debug: cli: disconnect [2019-05-14 10:28:55]: debug: ppp0: send [LCP EchoReq id=2c <magic 4a2bb9ea>] [2019-05-14 10:29:51]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:29:51]: debug: cli: disconnect [2019-05-14 10:29:51]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:29:51]: debug: cli: disconnect [2019-05-14 10:30:52]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:30:52]: debug: cli: disconnect [2019-05-14 10:30:52]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:30:52]: debug: cli: disconnect [2019-05-14 10:30:55]: warn: ppp0: lcp: no echo reply [2019-05-14 10:30:55]: debug: ppp0: terminate [2019-05-14 10:30:55]: debug: ppp0: radius(1): req_enter 1 [2019-05-14 10:30:55]: info: ppp0: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dab0> <Acct-Session-Id "0000000002f70b0f"> <Acct-Session-Time 720> <Acct-Input-Octets 54> <Acct-Output-Octets 54> <Acct-Input-Packets 3> <Acct-Output-Packets 3> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.100> ] [2019-05-14 10:30:55]: debug: ppp0: radius(1): req_exit 0 [2019-05-14 10:30:55]: debug: ppp0: pppoe: ppp finished [2019-05-14 10:30:55]: debug: ppp0: lcp_layer_free [2019-05-14 10:30:55]: debug: ppp0: auth_layer_free [2019-05-14 10:30:55]: debug: ppp0: ccp_layer_free [2019-05-14 10:30:55]: debug: ppp0: ipcp_layer_free [2019-05-14 10:30:55]: debug: ppp0: ipv6cp_layer_free [2019-05-14 10:30:55]: debug: ppp0: ppp destablished [2019-05-14 10:30:55]: info: ens9.3601: send [PPPoE PADT 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=45c0 <AC-Name 250.55> ] [2019-05-14 10:30:55]: info: ppp0: disconnected [2019-05-14 10:30:55]: info: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:31:53]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:31:53]: debug: cli: disconnect [2019-05-14 10:31:53]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:31:53]: debug: cli: disconnect [2019-05-14 10:32:54]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:32:54]: debug: cli: disconnect [2019-05-14 10:32:54]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:32:54]: debug: cli: disconnect [2019-05-14 10:33:55]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:33:55]: debug: cli: disconnect [2019-05-14 10:33:55]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:33:55]: debug: cli: disconnect [2019-05-14 10:34:02]: debug: connlimit: check entry 270303448028242 [2019-05-14 10:34:02]: debug: connlimit: accept 270303448028242 [2019-05-14 10:34:02]: info: ens9.3601: recv [PPPoE PADI 52:54:00:ed:d6:f5 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 71050000>] [2019-05-14 10:34:02]: info: ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=0000 <AC-Name 250.55> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1bbcbea228c3c7f469> <Host-Uniq 71050000>] [2019-05-14 10:34:07]: debug: connlimit: check entry 270303448028242 [2019-05-14 10:34:07]: debug: connlimit: accept 270303448028242 [2019-05-14 10:34:07]: info: ens9.3601: recv [PPPoE PADI 52:54:00:ed:d6:f5 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 71050000>] [2019-05-14 10:34:07]: info: ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=0000 <AC-Name 250.55> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b9b92f8b93fa67cbd> <Host-Uniq 71050000>] [2019-05-14 10:34:07]: info: ens9.3601: recv [PPPoE PADR 52:54:00:ed:d6:f5 => 52:54:00:61:9c:32 sid=0000 <Host-Uniq 71050000> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b9b92f8b93fa67cbd>] [2019-05-14 10:34:07]: info: ens9.3601: send [PPPoE PADS 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=4600 <AC-Name 250.55> <Host-Uniq 71050000>] [2019-05-14 10:34:07]: debug: ens9.3601: lcp_layer_init [2019-05-14 10:34:07]: debug: ens9.3601: auth_layer_init [2019-05-14 10:34:07]: debug: ens9.3601: ccp_layer_init [2019-05-14 10:34:07]: debug: ens9.3601: ipcp_layer_init [2019-05-14 10:34:07]: debug: ens9.3601: ipv6cp_layer_init [2019-05-14 10:34:07]: debug: ens9.3601: ppp establishing [2019-05-14 10:34:07]: debug: ens9.3601: lcp_layer_start [2019-05-14 10:34:07]: info: ens9.3601: send [LCP ConfReq id=c <mru 1440> <magic 3de2c055>] [2019-05-14 10:34:07]: info: ens9.3601: recv [LCP ConfReq id=1 <mru 1492> <magic 54d38a72>] [2019-05-14 10:34:07]: info: ens9.3601: send [LCP ConfAck id=1 ] [2019-05-14 10:34:10]: debug: ens9.3601: fsm timeout 9 [2019-05-14 10:34:10]: info: ens9.3601: send [LCP ConfReq id=c <mru 1440> <magic 3de2c055>] [2019-05-14 10:34:10]: info: ens9.3601: recv [LCP ConfAck id=c <mru 1440> <magic 3de2c055>] [2019-05-14 10:34:10]: debug: ens9.3601: lcp_layer_started [2019-05-14 10:34:10]: debug: ens9.3601: auth_layer_start [2019-05-14 10:34:10]: debug: ens9.3601: recv [LCP EchoReq id=0 <magic 54d38a72>] [2019-05-14 10:34:10]: debug: ens9.3601: send [LCP EchoRep id=0 <magic 3de2c055>] [2019-05-14 10:34:10]: info: ens9.3601: recv [PAP AuthReq id=1] [2019-05-14 10:34:10]: debug: ens9.3601: radius(1): req_enter 1 [2019-05-14 10:34:10]: info: ens9.3601: send [RADIUS(1) Access-Request id=1 <User-Name "test1"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <User-Password 0x3a371143e53b38ca73a8dc3bfeeeb69a>] [2019-05-14 10:34:10]: debug: ens9.3601: radius(1): req_exit 0 [2019-05-14 10:34:10]: info: ens9.3601: recv [RADIUS(1) Access-Accept id=1 <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dabc> ] [2019-05-14 10:34:10]: info: ppp0: connect: ppp0 <--> pppoe(52:54:00:ed:d6:f5) [2019-05-14 10:34:10]: debug: ppp0: ppp connected [2019-05-14 10:34:10]: info: ppp0: send [PAP AuthAck id=1 "Authentication succeeded"] [2019-05-14 10:34:10]: debug: ppp0: auth_layer_started [2019-05-14 10:34:10]: debug: ppp0: ccp_layer_start [2019-05-14 10:34:10]: debug: ppp0: ipcp_layer_start [2019-05-14 10:34:10]: info: ppp0: send [IPCP ConfReq id=fc <addr 10.1.250.199>] [2019-05-14 10:34:10]: debug: ppp0: ipv6cp_layer_start [2019-05-14 10:34:10]: info: ppp0: test1: authentication succeeded [2019-05-14 10:34:10]: info: ppp0: recv [IPCP ConfReq id=1 <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>] [2019-05-14 10:34:10]: info: ppp0: send [IPCP ConfNak id=1 <addr 10.172.0.101> <dns1 168.95.1.1> <dns2 168.95.192.1>] [2019-05-14 10:34:10]: info: ppp0: recv [IPCP ConfAck id=fc <addr 10.1.250.199>] [2019-05-14 10:34:10]: info: ppp0: recv [IPCP ConfReq id=2 <addr 10.172.0.101> <dns1 168.95.1.1> <dns2 168.95.192.1>] [2019-05-14 10:34:10]: info: ppp0: send [IPCP ConfAck id=2] [2019-05-14 10:34:10]: debug: ppp0: ipcp_layer_started [2019-05-14 10:34:10]: debug: ppp0: radius(1): req_enter 1 [2019-05-14 10:34:10]: info: ppp0: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dabc> <Acct-Session-Id "0000000002f70b10"> <Acct-Session-Time 0> <Acct-Input-Octets 0> <Acct-Output-Octets 0> <Acct-Input-Packets 0> <Acct-Output-Packets 0> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.101>] [2019-05-14 10:34:10]: debug: ppp0: radius(1): req_exit 0 [2019-05-14 10:34:10]: info: ppp0: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:34:10]: debug: ppp0: pppoe: ppp started [2019-05-14 10:34:40]: debug: ppp0: recv [LCP EchoReq id=1 <magic 54d38a72>] [2019-05-14 10:34:40]: debug: ppp0: send [LCP EchoRep id=1 <magic 3de2c055>] [2019-05-14 10:34:56]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:34:56]: debug: cli: disconnect [2019-05-14 10:34:56]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:34:56]: debug: cli: disconnect [2019-05-14 10:35:10]: debug: ppp0: recv [LCP EchoReq id=2 <magic 54d38a72>] [2019-05-14 10:35:10]: debug: ppp0: send [LCP EchoRep id=2 <magic 3de2c055>] [2019-05-14 10:35:40]: debug: ppp0: recv [LCP EchoReq id=3 <magic 54d38a72>] [2019-05-14 10:35:40]: debug: ppp0: send [LCP EchoRep id=3 <magic 3de2c055>] [2019-05-14 10:35:57]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:35:57]: debug: cli: disconnect [2019-05-14 10:35:57]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:35:57]: debug: cli: disconnect [2019-05-14 10:36:10]: debug: ppp0: send [LCP EchoReq id=d <magic 3de2c055>] [2019-05-14 10:36:10]: debug: ppp0: recv [LCP EchoRep id=d <magic 54d38a72>] [2019-05-14 10:36:10]: debug: ppp0: recv [LCP EchoReq id=4 <magic 54d38a72>] [2019-05-14 10:36:10]: debug: ppp0: send [LCP EchoRep id=4 <magic 3de2c055>] [2019-05-14 10:36:40]: debug: ppp0: recv [LCP EchoReq id=5 <magic 54d38a72>] [2019-05-14 10:36:40]: debug: ppp0: send [LCP EchoRep id=5 <magic 3de2c055>] [2019-05-14 10:36:58]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:36:58]: debug: cli: disconnect [2019-05-14 10:36:58]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:36:58]: debug: cli: disconnect [2019-05-14 10:37:10]: debug: ppp0: recv [LCP EchoReq id=6 <magic 54d38a72>] [2019-05-14 10:37:10]: debug: ppp0: send [LCP EchoRep id=6 <magic 3de2c055>] [2019-05-14 10:37:40]: debug: ppp0: recv [LCP EchoReq id=7 <magic 54d38a72>] [2019-05-14 10:37:40]: debug: ppp0: send [LCP EchoRep id=7 <magic 3de2c055>] [2019-05-14 10:37:59]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:37:59]: debug: cli: disconnect [2019-05-14 10:37:59]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:37:59]: debug: cli: disconnect [2019-05-14 10:38:10]: debug: ppp0: send [LCP EchoReq id=e <magic 3de2c055>] [2019-05-14 10:38:10]: debug: ppp0: recv [LCP EchoRep id=e <magic 54d38a72>] [2019-05-14 10:38:10]: debug: ppp0: recv [LCP EchoReq id=8 <magic 54d38a72>] [2019-05-14 10:38:10]: debug: ppp0: send [LCP EchoRep id=8 <magic 3de2c055>] [2019-05-14 10:38:40]: debug: ppp0: recv [LCP EchoReq id=9 <magic 54d38a72>] [2019-05-14 10:38:40]: debug: ppp0: send [LCP EchoRep id=9 <magic 3de2c055>] [2019-05-14 10:39:00]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:39:00]: debug: cli: disconnect [2019-05-14 10:39:00]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:39:00]: debug: cli: disconnect [2019-05-14 10:39:10]: debug: ppp0: recv [LCP EchoReq id=a <magic 54d38a72>] [2019-05-14 10:39:10]: debug: ppp0: send [LCP EchoRep id=a <magic 3de2c055>] [2019-05-14 10:39:40]: debug: ppp0: recv [LCP EchoReq id=b <magic 54d38a72>] [2019-05-14 10:39:40]: debug: ppp0: send [LCP EchoRep id=b <magic 3de2c055>] [2019-05-14 10:40:01]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:40:01]: debug: cli: disconnect [2019-05-14 10:40:01]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:40:01]: debug: cli: disconnect [2019-05-14 10:40:10]: debug: ppp0: send [LCP EchoReq id=f <magic 3de2c055>] [2019-05-14 10:40:10]: debug: ppp0: recv [LCP EchoRep id=f <magic 54d38a72>] [2019-05-14 10:40:10]: debug: ppp0: recv [LCP EchoReq id=c <magic 54d38a72>] [2019-05-14 10:40:10]: debug: ppp0: send [LCP EchoRep id=c <magic 3de2c055>] [2019-05-14 10:40:40]: debug: ppp0: recv [LCP EchoReq id=d <magic 54d38a72>] [2019-05-14 10:40:40]: debug: ppp0: send [LCP EchoRep id=d <magic 3de2c055>] [2019-05-14 10:41:02]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:41:02]: debug: cli: disconnect [2019-05-14 10:41:02]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:41:02]: debug: cli: disconnect [2019-05-14 10:41:10]: debug: ppp0: recv [LCP EchoReq id=e <magic 54d38a72>] [2019-05-14 10:41:10]: debug: ppp0: send [LCP EchoRep id=e <magic 3de2c055>] [2019-05-14 10:41:40]: debug: ppp0: recv [LCP EchoReq id=f <magic 54d38a72>] [2019-05-14 10:41:40]: debug: ppp0: send [LCP EchoRep id=f <magic 3de2c055>] [2019-05-14 10:42:03]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:42:03]: debug: cli: disconnect [2019-05-14 10:42:03]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:42:03]: debug: cli: disconnect [2019-05-14 10:42:10]: debug: ppp0: send [LCP EchoReq id=10 <magic 3de2c055>] [2019-05-14 10:42:10]: debug: ppp0: recv [LCP EchoRep id=10 <magic 54d38a72>] [2019-05-14 10:42:10]: debug: ppp0: recv [LCP EchoReq id=10 <magic 54d38a72>] [2019-05-14 10:42:10]: debug: ppp0: send [LCP EchoRep id=10 <magic 3de2c055>] [2019-05-14 10:42:40]: debug: ppp0: recv [LCP EchoReq id=11 <magic 54d38a72>] [2019-05-14 10:42:40]: debug: ppp0: send [LCP EchoRep id=11 <magic 3de2c055>] [2019-05-14 10:43:04]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:43:04]: debug: cli: disconnect [2019-05-14 10:43:04]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:43:04]: debug: cli: disconnect [2019-05-14 10:43:10]: debug: ppp0: recv [LCP EchoReq id=12 <magic 54d38a72>] [2019-05-14 10:43:10]: debug: ppp0: send [LCP EchoRep id=12 <magic 3de2c055>] [2019-05-14 10:43:40]: debug: ppp0: recv [LCP EchoReq id=13 <magic 54d38a72>] [2019-05-14 10:43:40]: debug: ppp0: send [LCP EchoRep id=13 <magic 3de2c055>] [2019-05-14 10:44:05]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:44:05]: debug: cli: disconnect [2019-05-14 10:44:05]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:44:05]: debug: cli: disconnect [2019-05-14 10:44:10]: debug: ppp0: send [LCP EchoReq id=11 <magic 3de2c055>] [2019-05-14 10:44:10]: debug: ppp0: recv [LCP EchoRep id=11 <magic 54d38a72>] [2019-05-14 10:44:10]: debug: ppp0: recv [LCP EchoReq id=14 <magic 54d38a72>] [2019-05-14 10:44:10]: debug: ppp0: send [LCP EchoRep id=14 <magic 3de2c055>] [2019-05-14 10:44:40]: debug: ppp0: recv [LCP EchoReq id=15 <magic 54d38a72>] [2019-05-14 10:44:40]: debug: ppp0: send [LCP EchoRep id=15 <magic 3de2c055>] [2019-05-14 10:45:06]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:45:06]: debug: cli: disconnect [2019-05-14 10:45:06]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:45:06]: debug: cli: disconnect [2019-05-14 10:45:10]: debug: ppp0: recv [LCP EchoReq id=16 <magic 54d38a72>] [2019-05-14 10:45:10]: debug: ppp0: send [LCP EchoRep id=16 <magic 3de2c055>] [2019-05-14 10:45:40]: debug: ppp0: recv [LCP EchoReq id=17 <magic 54d38a72>] [2019-05-14 10:45:40]: debug: ppp0: send [LCP EchoRep id=17 <magic 3de2c055>] [2019-05-14 10:46:07]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:46:07]: debug: cli: disconnect [2019-05-14 10:46:07]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:46:07]: debug: cli: disconnect [2019-05-14 10:46:10]: debug: ppp0: send [LCP EchoReq id=12 <magic 3de2c055>] [2019-05-14 10:46:10]: debug: ppp0: recv [LCP EchoRep id=12 <magic 54d38a72>] [2019-05-14 10:46:10]: debug: ppp0: recv [LCP EchoReq id=18 <magic 54d38a72>] [2019-05-14 10:46:10]: debug: ppp0: send [LCP EchoRep id=18 <magic 3de2c055>] [2019-05-14 10:46:40]: debug: ppp0: recv [LCP EchoReq id=19 <magic 54d38a72>] [2019-05-14 10:46:40]: debug: ppp0: send [LCP EchoRep id=19 <magic 3de2c055>] [2019-05-14 10:47:08]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:47:08]: debug: cli: disconnect [2019-05-14 10:47:08]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:47:08]: debug: cli: disconnect [2019-05-14 10:47:10]: debug: ppp0: recv [LCP EchoReq id=1a <magic 54d38a72>] [2019-05-14 10:47:10]: debug: ppp0: send [LCP EchoRep id=1a <magic 3de2c055>] [2019-05-14 10:47:41]: debug: ppp0: recv [LCP EchoReq id=1b <magic 54d38a72>] [2019-05-14 10:47:41]: debug: ppp0: send [LCP EchoRep id=1b <magic 3de2c055>] [2019-05-14 10:48:09]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:48:09]: debug: cli: disconnect [2019-05-14 10:48:09]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:48:09]: debug: cli: disconnect [2019-05-14 10:48:10]: debug: ppp0: send [LCP EchoReq id=13 <magic 3de2c055>] [2019-05-14 10:48:10]: debug: ppp0: recv [LCP EchoRep id=13 <magic 54d38a72>] [2019-05-14 10:48:11]: debug: ppp0: recv [LCP EchoReq id=1c <magic 54d38a72>] [2019-05-14 10:48:11]: debug: ppp0: send [LCP EchoRep id=1c <magic 3de2c055>] [2019-05-14 10:48:41]: debug: ppp0: recv [LCP EchoReq id=1d <magic 54d38a72>] [2019-05-14 10:48:41]: debug: ppp0: send [LCP EchoRep id=1d <magic 3de2c055>] [2019-05-14 10:49:10]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:49:10]: debug: cli: disconnect [2019-05-14 10:49:10]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:49:10]: debug: cli: disconnect [2019-05-14 10:49:11]: debug: ppp0: recv [LCP EchoReq id=1e <magic 54d38a72>] [2019-05-14 10:49:11]: debug: ppp0: send [LCP EchoRep id=1e <magic 3de2c055>] [2019-05-14 10:49:41]: debug: ppp0: recv [LCP EchoReq id=1f <magic 54d38a72>] [2019-05-14 10:49:41]: debug: ppp0: send [LCP EchoRep id=1f <magic 3de2c055>] [2019-05-14 10:50:10]: debug: ppp0: send [LCP EchoReq id=14 <magic 3de2c055>] [2019-05-14 10:50:10]: debug: ppp0: recv [LCP EchoRep id=14 <magic 54d38a72>] [2019-05-14 10:50:11]: debug: ppp0: recv [LCP EchoReq id=20 <magic 54d38a72>] [2019-05-14 10:50:11]: debug: ppp0: send [LCP EchoRep id=20 <magic 3de2c055>] [2019-05-14 10:50:11]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:50:11]: debug: cli: disconnect [2019-05-14 10:50:11]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:50:11]: debug: cli: disconnect [2019-05-14 10:50:41]: debug: ppp0: recv [LCP EchoReq id=21 <magic 54d38a72>] [2019-05-14 10:50:41]: debug: ppp0: send [LCP EchoRep id=21 <magic 3de2c055>] [2019-05-14 10:51:11]: debug: ppp0: recv [LCP EchoReq id=22 <magic 54d38a72>] [2019-05-14 10:51:11]: debug: ppp0: send [LCP EchoRep id=22 <magic 3de2c055>] [2019-05-14 10:51:12]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:51:12]: debug: cli: disconnect [2019-05-14 10:51:12]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:51:12]: debug: cli: disconnect [2019-05-14 10:51:41]: debug: ppp0: recv [LCP EchoReq id=23 <magic 54d38a72>] [2019-05-14 10:51:41]: debug: ppp0: send [LCP EchoRep id=23 <magic 3de2c055>] [2019-05-14 10:52:10]: debug: ppp0: send [LCP EchoReq id=15 <magic 3de2c055>] [2019-05-14 10:52:10]: debug: ppp0: recv [LCP EchoRep id=15 <magic 54d38a72>] [2019-05-14 10:52:11]: debug: ppp0: recv [LCP EchoReq id=24 <magic 54d38a72>] [2019-05-14 10:52:11]: debug: ppp0: send [LCP EchoRep id=24 <magic 3de2c055>] [2019-05-14 10:52:13]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:52:13]: debug: cli: disconnect [2019-05-14 10:52:13]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:52:13]: debug: cli: disconnect [2019-05-14 10:52:41]: debug: ppp0: recv [LCP EchoReq id=25 <magic 54d38a72>] [2019-05-14 10:52:41]: debug: ppp0: send [LCP EchoRep id=25 <magic 3de2c055>] [2019-05-14 10:53:11]: debug: ppp0: recv [LCP EchoReq id=26 <magic 54d38a72>] [2019-05-14 10:53:11]: debug: ppp0: send [LCP EchoRep id=26 <magic 3de2c055>] [2019-05-14 10:53:14]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:53:14]: debug: cli: disconnect [2019-05-14 10:53:14]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:53:14]: debug: cli: disconnect [2019-05-14 10:53:41]: debug: ppp0: recv [LCP EchoReq id=27 <magic 54d38a72>] [2019-05-14 10:53:41]: debug: ppp0: send [LCP EchoRep id=27 <magic 3de2c055>] [2019-05-14 10:53:54]: info: ppp0: recv [LCP TermReq id=2] [2019-05-14 10:53:54]: info: ppp0: send [LCP TermAck id=2] [2019-05-14 10:53:54]: debug: ppp0: terminate [2019-05-14 10:53:54]: debug: ppp0: lcp_layer_finish [2019-05-14 10:53:54]: debug: ppp0: auth_layer_finish [2019-05-14 10:53:54]: debug: ppp0: auth_layer_finished [2019-05-14 10:53:54]: debug: ppp0: ccp_layer_finish [2019-05-14 10:53:54]: debug: ppp0: ccp_layer_finished [2019-05-14 10:53:54]: debug: ppp0: ipcp_layer_finish [2019-05-14 10:53:54]: debug: ppp0: ipcp_layer_finished [2019-05-14 10:53:54]: debug: ppp0: ipv6cp_layer_finish [2019-05-14 10:53:54]: debug: ppp0: ipv6cp_layer_finished [2019-05-14 10:53:54]: debug: ppp0: radius(1): req_enter 1 [2019-05-14 10:53:54]: info: ppp0: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dabc> <Acct-Session-Id "0000000002f70b10"> <Acct-Session-Time 1187> <Acct-Input-Octets 54> <Acct-Output-Octets 54> <Acct-Input-Packets 3> <Acct-Output-Packets 3> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.101> ] [2019-05-14 10:53:54]: debug: ppp0: radius(1): req_exit 0 [2019-05-14 10:53:54]: info: ppp0: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:53:57]: debug: ppp0: fsm timeout 0 [2019-05-14 10:53:57]: debug: ppp0: lcp_layer_finished [2019-05-14 10:53:57]: debug: ppp0: pppoe: ppp finished [2019-05-14 10:53:57]: debug: ppp0: lcp_layer_free [2019-05-14 10:53:57]: debug: ppp0: auth_layer_free [2019-05-14 10:53:57]: debug: ppp0: ccp_layer_free [2019-05-14 10:53:57]: debug: ppp0: ipcp_layer_free [2019-05-14 10:53:57]: debug: ppp0: ipv6cp_layer_free [2019-05-14 10:53:57]: debug: ppp0: ppp destablished [2019-05-14 10:53:57]: info: ens9.3601: send [PPPoE PADT 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=4600 <AC-Name 250.55> ] [2019-05-14 10:53:57]: info: ppp0: disconnected [2019-05-14 10:54:15]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:54:15]: debug: cli: disconnect [2019-05-14 10:54:15]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:54:15]: debug: cli: disconnect [2019-05-14 10:55:16]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:55:16]: debug: cli: disconnect [2019-05-14 10:55:16]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:55:16]: debug: cli: disconnect [2019-05-14 10:56:17]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:56:17]: debug: cli: disconnect [2019-05-14 10:56:17]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:56:17]: debug: cli: disconnect [2019-05-14 10:57:18]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:57:18]: debug: cli: disconnect [2019-05-14 10:57:18]: info: cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:57:18]: debug: cli: disconnect

debug log [2019-05-14 09:52:49.219] ens9.3601: recv [PPPoE PADI 00:00:77:0b:01:02 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 000a0000>] [2019-05-14 09:52:49.219] ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 09:52:50.219] connlimit: check entry 2203510571008 [2019-05-14 09:52:50.219] connlimit: accept 2203510571008 [2019-05-14 09:52:50.219] ens9.3601: recv [PPPoE PADI 00:00:77:0b:01:02 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 000a0000>] [2019-05-14 09:52:50.219] ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 09:52:50.221] ens9.3601: recv [PPPoE PADR 00:00:77:0b:01:02 => 52:54:00:61:9c:32 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 09:52:50.221] ens9.3601: send [PPPoE PADS 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=4540 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 09:52:50.221] ens9.3601: : lcp_layer_init [2019-05-14 09:52:50.221] ens9.3601: : auth_layer_init [2019-05-14 09:52:50.221] ens9.3601: : ccp_layer_init [2019-05-14 09:52:50.221] ens9.3601: : ipcp_layer_init [2019-05-14 09:52:50.221] ens9.3601: : ipv6cp_layer_init [2019-05-14 09:52:50.221] ens9.3601: : ppp establishing [2019-05-14 09:52:50.221] ens9.3601: 0000000002f70b0d: lcp_layer_start [2019-05-14 09:52:50.221] ens9.3601: 0000000002f70b0d: send [LCP ConfReq id=68 <mru 1440> <magic 50fe4b07>] [2019-05-14 09:52:50.227] ens9.3601: 0000000002f70b0d: recv [LCP ConfReq id=1 <magic 0506c320> <mru 65531>] [2019-05-14 09:52:50.227] ens9.3601: 0000000002f70b0d: send [LCP ConfNak id=1 <mru 1440>] [2019-05-14 09:52:50.229] ens9.3601: 0000000002f70b0d: recv [LCP ConfAck id=68 <mru 1440> <magic 50fe4b07>] [2019-05-14 09:52:50.229] ens9.3601: 0000000002f70b0d: recv [LCP ConfReq id=2 <magic 0506c320> <mru 1440>] [2019-05-14 09:52:50.229] ens9.3601: 0000000002f70b0d: send [LCP ConfAck id=2 ] [2019-05-14 09:52:50.230] ens9.3601: 0000000002f70b0d: lcp_layer_started [2019-05-14 09:52:50.230] ens9.3601: 0000000002f70b0d: auth_layer_start [2019-05-14 09:52:50.231] ens9.3601: 0000000002f70b0d: recv [PAP AuthReq id=1] [2019-05-14 09:52:50.231] ens9.3601: 0000000002f70b0d: radius(1): req_enter 1 [2019-05-14 09:52:50.231] ens9.3601: 0000000002f70b0d: send [RADIUS(1) Access-Request id=1 <User-Name "test1"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <User-Password 0xe55ba0cbef33aa3e4da45e32ba2f3dcb>] [2019-05-14 09:52:50.235] ens9.3601: 0000000002f70b0d: radius(1): req_exit 0 [2019-05-14 09:52:50.235] ens9.3601: 0000000002f70b0d: recv [RADIUS(1) Access-Accept id=1 <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daa8> ] [2019-05-14 09:52:50.235] ppp0: 0000000002f70b0d: connect: ppp0 <--> pppoe(00:00:77:0b:01:02) [2019-05-14 09:52:50.235] ppp0: 0000000002f70b0d: ppp connected [2019-05-14 09:52:50.235] ppp0: 0000000002f70b0d: send [PAP AuthAck id=1 "Authentication succeeded"] [2019-05-14 09:52:50.235] ppp0: 0000000002f70b0d: auth_layer_started [2019-05-14 09:52:50.235] ppp0: 0000000002f70b0d: ccp_layer_start [2019-05-14 09:52:50.235] ppp0: 0000000002f70b0d: ipcp_layer_start [2019-05-14 09:52:50.236] ppp0: 0000000002f70b0d: send [IPCP ConfReq id=62 <addr 10.1.250.199>] [2019-05-14 09:52:50.236] ppp0: 0000000002f70b0d: ipv6cp_layer_start [2019-05-14 09:52:50.236] ppp0: 0000000002f70b0d: test1: authentication succeeded [2019-05-14 09:52:50.237] ppp0: 0000000002f70b0d: recv [IPCP ConfReq id=1 <addr 0.0.0.0>] [2019-05-14 09:52:50.237] ppp0: 0000000002f70b0d: send [IPCP ConfNak id=1 <addr 10.172.0.98>] [2019-05-14 09:52:50.238] ppp0: 0000000002f70b0d: recv [IPCP ConfAck id=62 <addr 10.1.250.199>] [2019-05-14 09:52:50.239] ppp0: 0000000002f70b0d: recv [IPCP ConfReq id=2 <addr 10.172.0.98>] [2019-05-14 09:52:50.239] ppp0: 0000000002f70b0d: send [IPCP ConfAck id=2] [2019-05-14 09:52:50.239] ppp0: 0000000002f70b0d: ipcp_layer_started [2019-05-14 09:52:50.239] ppp0: 0000000002f70b0d: radius(1): req_enter 1 [2019-05-14 09:52:50.239] ppp0: 0000000002f70b0d: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daa8> <Acct-Session-Id "0000000002f70b0d"> <Acct-Session-Time 0> <Acct-Input-Octets 0> <Acct-Output-Octets 0> <Acct-Input-Packets 0> <Acct-Output-Packets 0> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.98>] [2019-05-14 09:52:50.250] ppp0: 0000000002f70b0d: radius(1): req_exit 0 [2019-05-14 09:52:50.250] ppp0: 0000000002f70b0d: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 09:52:50.250] ppp0: 0000000002f70b0d: pppoe: ppp started [2019-05-14 09:53:15.300] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:53:15.301] cli: disconnect [2019-05-14 09:53:15.304] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:53:15.304] cli: disconnect [2019-05-14 09:53:20.228] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=3 <magic 0506c320>] [2019-05-14 09:53:20.228] ppp0: 0000000002f70b0d: send [LCP EchoRep id=3 <magic 50fe4b07>] [2019-05-14 09:53:50.226] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=4 <magic 0506c320>] [2019-05-14 09:53:50.226] ppp0: 0000000002f70b0d: send [LCP EchoRep id=4 <magic 50fe4b07>] [2019-05-14 09:54:16.832] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:54:16.832] cli: disconnect [2019-05-14 09:54:16.835] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:54:16.835] cli: disconnect [2019-05-14 09:54:20.225] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=5 <magic 0506c320>] [2019-05-14 09:54:20.226] ppp0: 0000000002f70b0d: send [LCP EchoRep id=5 <magic 50fe4b07>] [2019-05-14 09:54:50.224] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=6 <magic 0506c320>] [2019-05-14 09:54:50.224] ppp0: 0000000002f70b0d: send [LCP EchoRep id=6 <magic 50fe4b07>] [2019-05-14 09:54:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=69 <magic 50fe4b07>] [2019-05-14 09:54:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=69 <magic 0506c320>] [2019-05-14 09:55:17.365] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:55:17.365] cli: disconnect [2019-05-14 09:55:17.368] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:55:17.369] cli: disconnect [2019-05-14 09:55:20.223] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=7 <magic 0506c320>] [2019-05-14 09:55:20.223] ppp0: 0000000002f70b0d: send [LCP EchoRep id=7 <magic 50fe4b07>] [2019-05-14 09:55:50.222] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=8 <magic 0506c320>] [2019-05-14 09:55:50.222] ppp0: 0000000002f70b0d: send [LCP EchoRep id=8 <magic 50fe4b07>] [2019-05-14 09:56:18.914] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:56:18.915] cli: disconnect [2019-05-14 09:56:18.918] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:56:18.919] cli: disconnect [2019-05-14 09:56:20.220] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=9 <magic 0506c320>] [2019-05-14 09:56:20.221] ppp0: 0000000002f70b0d: send [LCP EchoRep id=9 <magic 50fe4b07>] [2019-05-14 09:56:50.219] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=a <magic 0506c320>] [2019-05-14 09:56:50.219] ppp0: 0000000002f70b0d: send [LCP EchoRep id=a <magic 50fe4b07>] [2019-05-14 09:56:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=6a <magic 50fe4b07>] [2019-05-14 09:56:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=6a <magic 0506c320>] [2019-05-14 09:57:19.423] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:57:19.423] cli: disconnect [2019-05-14 09:57:19.426] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:57:19.427] cli: disconnect [2019-05-14 09:57:20.218] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=b <magic 0506c320>] [2019-05-14 09:57:20.218] ppp0: 0000000002f70b0d: send [LCP EchoRep id=b <magic 50fe4b07>] [2019-05-14 09:57:50.217] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=c <magic 0506c320>] [2019-05-14 09:57:50.217] ppp0: 0000000002f70b0d: send [LCP EchoRep id=c <magic 50fe4b07>] [2019-05-14 09:58:20.216] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=d <magic 0506c320>] [2019-05-14 09:58:20.216] ppp0: 0000000002f70b0d: send [LCP EchoRep id=d <magic 50fe4b07>] [2019-05-14 09:58:20.933] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:58:20.933] cli: disconnect [2019-05-14 09:58:20.936] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:58:20.937] cli: disconnect [2019-05-14 09:58:50.214] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=e <magic 0506c320>] [2019-05-14 09:58:50.215] ppp0: 0000000002f70b0d: send [LCP EchoRep id=e <magic 50fe4b07>] [2019-05-14 09:58:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=6b <magic 50fe4b07>] [2019-05-14 09:58:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=6b <magic 0506c320>] [2019-05-14 09:59:20.213] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=f <magic 0506c320>] [2019-05-14 09:59:20.213] ppp0: 0000000002f70b0d: send [LCP EchoRep id=f <magic 50fe4b07>] [2019-05-14 09:59:21.442] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:59:21.442] cli: disconnect [2019-05-14 09:59:21.445] cli: tcp: new connection from 127.0.0.1 [2019-05-14 09:59:21.446] cli: disconnect [2019-05-14 09:59:50.212] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=10 <magic 0506c320>] [2019-05-14 09:59:50.212] ppp0: 0000000002f70b0d: send [LCP EchoRep id=10 <magic 50fe4b07>] [2019-05-14 10:00:20.211] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=11 <magic 0506c320>] [2019-05-14 10:00:20.211] ppp0: 0000000002f70b0d: send [LCP EchoRep id=11 <magic 50fe4b07>] [2019-05-14 10:00:22.949] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:00:22.950] cli: disconnect [2019-05-14 10:00:22.953] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:00:22.953] cli: disconnect [2019-05-14 10:00:50.209] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=12 <magic 0506c320>] [2019-05-14 10:00:50.210] ppp0: 0000000002f70b0d: send [LCP EchoRep id=12 <magic 50fe4b07>] [2019-05-14 10:00:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=6c <magic 50fe4b07>] [2019-05-14 10:00:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=6c <magic 0506c320>] [2019-05-14 10:01:20.208] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=13 <magic 0506c320>] [2019-05-14 10:01:20.208] ppp0: 0000000002f70b0d: send [LCP EchoRep id=13 <magic 50fe4b07>] [2019-05-14 10:01:23.449] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:01:23.449] cli: disconnect [2019-05-14 10:01:23.452] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:01:23.453] cli: disconnect [2019-05-14 10:01:50.207] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=14 <magic 0506c320>] [2019-05-14 10:01:50.207] ppp0: 0000000002f70b0d: send [LCP EchoRep id=14 <magic 50fe4b07>] [2019-05-14 10:02:20.206] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=15 <magic 0506c320>] [2019-05-14 10:02:20.206] ppp0: 0000000002f70b0d: send [LCP EchoRep id=15 <magic 50fe4b07>] [2019-05-14 10:02:24.960] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:02:24.960] cli: disconnect [2019-05-14 10:02:24.963] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:02:24.963] cli: disconnect [2019-05-14 10:02:50.204] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=16 <magic 0506c320>] [2019-05-14 10:02:50.205] ppp0: 0000000002f70b0d: send [LCP EchoRep id=16 <magic 50fe4b07>] [2019-05-14 10:02:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=6d <magic 50fe4b07>] [2019-05-14 10:02:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=6d <magic 0506c320>] [2019-05-14 10:03:20.203] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=17 <magic 0506c320>] [2019-05-14 10:03:20.203] ppp0: 0000000002f70b0d: send [LCP EchoRep id=17 <magic 50fe4b07>] [2019-05-14 10:03:25.462] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:03:25.462] cli: disconnect [2019-05-14 10:03:25.465] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:03:25.465] cli: disconnect [2019-05-14 10:03:50.202] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=18 <magic 0506c320>] [2019-05-14 10:03:50.202] ppp0: 0000000002f70b0d: send [LCP EchoRep id=18 <magic 50fe4b07>] [2019-05-14 10:04:20.201] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=19 <magic 0506c320>] [2019-05-14 10:04:20.201] ppp0: 0000000002f70b0d: send [LCP EchoRep id=19 <magic 50fe4b07>] [2019-05-14 10:04:26.972] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:04:26.972] cli: disconnect [2019-05-14 10:04:26.976] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:04:26.976] cli: disconnect [2019-05-14 10:04:50.200] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=1a <magic 0506c320>] [2019-05-14 10:04:50.200] ppp0: 0000000002f70b0d: send [LCP EchoRep id=1a <magic 50fe4b07>] [2019-05-14 10:04:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=6e <magic 50fe4b07>] [2019-05-14 10:04:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=6e <magic 0506c320>] [2019-05-14 10:05:20.198] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=1b <magic 0506c320>] [2019-05-14 10:05:20.198] ppp0: 0000000002f70b0d: send [LCP EchoRep id=1b <magic 50fe4b07>] [2019-05-14 10:05:27.472] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:05:27.473] cli: disconnect [2019-05-14 10:05:27.476] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:05:27.476] cli: disconnect [2019-05-14 10:05:50.197] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=1c <magic 0506c320>] [2019-05-14 10:05:50.197] ppp0: 0000000002f70b0d: send [LCP EchoRep id=1c <magic 50fe4b07>] [2019-05-14 10:06:20.196] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=1d <magic 0506c320>] [2019-05-14 10:06:20.196] ppp0: 0000000002f70b0d: send [LCP EchoRep id=1d <magic 50fe4b07>] [2019-05-14 10:06:28.981] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:06:28.981] cli: disconnect [2019-05-14 10:06:28.984] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:06:28.985] cli: disconnect [2019-05-14 10:06:50.195] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=1e <magic 0506c320>] [2019-05-14 10:06:50.195] ppp0: 0000000002f70b0d: send [LCP EchoRep id=1e <magic 50fe4b07>] [2019-05-14 10:06:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=6f <magic 50fe4b07>] [2019-05-14 10:06:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=6f <magic 0506c320>] [2019-05-14 10:07:20.194] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=1f <magic 0506c320>] [2019-05-14 10:07:20.194] ppp0: 0000000002f70b0d: send [LCP EchoRep id=1f <magic 50fe4b07>] [2019-05-14 10:07:29.485] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:07:29.486] cli: disconnect [2019-05-14 10:07:29.489] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:07:29.489] cli: disconnect [2019-05-14 10:07:50.192] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=20 <magic 0506c320>] [2019-05-14 10:07:50.192] ppp0: 0000000002f70b0d: send [LCP EchoRep id=20 <magic 50fe4b07>] [2019-05-14 10:08:20.191] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=21 <magic 0506c320>] [2019-05-14 10:08:20.191] ppp0: 0000000002f70b0d: send [LCP EchoRep id=21 <magic 50fe4b07>] [2019-05-14 10:08:30.997] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:08:30.997] cli: disconnect [2019-05-14 10:08:31.000] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:08:31.000] cli: disconnect [2019-05-14 10:08:50.190] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=22 <magic 0506c320>] [2019-05-14 10:08:50.190] ppp0: 0000000002f70b0d: send [LCP EchoRep id=22 <magic 50fe4b07>] [2019-05-14 10:08:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=70 <magic 50fe4b07>] [2019-05-14 10:08:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=70 <magic 0506c320>] [2019-05-14 10:09:20.188] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=23 <magic 0506c320>] [2019-05-14 10:09:20.189] ppp0: 0000000002f70b0d: send [LCP EchoRep id=23 <magic 50fe4b07>] [2019-05-14 10:09:31.500] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:09:31.500] cli: disconnect [2019-05-14 10:09:31.503] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:09:31.503] cli: disconnect [2019-05-14 10:09:50.187] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=24 <magic 0506c320>] [2019-05-14 10:09:50.187] ppp0: 0000000002f70b0d: send [LCP EchoRep id=24 <magic 50fe4b07>] [2019-05-14 10:10:20.186] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=25 <magic 0506c320>] [2019-05-14 10:10:20.186] ppp0: 0000000002f70b0d: send [LCP EchoRep id=25 <magic 50fe4b07>] [2019-05-14 10:10:33.002] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:10:33.002] cli: disconnect [2019-05-14 10:10:33.006] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:10:33.006] cli: disconnect [2019-05-14 10:10:50.185] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=26 <magic 0506c320>] [2019-05-14 10:10:50.185] ppp0: 0000000002f70b0d: send [LCP EchoRep id=26 <magic 50fe4b07>] [2019-05-14 10:10:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=71 <magic 50fe4b07>] [2019-05-14 10:10:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=71 <magic 0506c320>] [2019-05-14 10:11:20.184] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=27 <magic 0506c320>] [2019-05-14 10:11:20.184] ppp0: 0000000002f70b0d: send [LCP EchoRep id=27 <magic 50fe4b07>] [2019-05-14 10:11:33.502] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:11:33.502] cli: disconnect [2019-05-14 10:11:33.505] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:11:33.505] cli: disconnect [2019-05-14 10:11:50.182] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=28 <magic 0506c320>] [2019-05-14 10:11:50.182] ppp0: 0000000002f70b0d: send [LCP EchoRep id=28 <magic 50fe4b07>] [2019-05-14 10:12:20.181] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=29 <magic 0506c320>] [2019-05-14 10:12:20.181] ppp0: 0000000002f70b0d: send [LCP EchoRep id=29 <magic 50fe4b07>] [2019-05-14 10:12:35.013] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:12:35.014] cli: disconnect [2019-05-14 10:12:35.017] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:12:35.017] cli: disconnect [2019-05-14 10:12:50.180] ppp0: 0000000002f70b0d: recv [LCP EchoReq id=2a <magic 0506c320>] [2019-05-14 10:12:50.180] ppp0: 0000000002f70b0d: send [LCP EchoRep id=2a <magic 50fe4b07>] [2019-05-14 10:12:50.230] ppp0: 0000000002f70b0d: send [LCP EchoReq id=72 <magic 50fe4b07>] [2019-05-14 10:12:50.231] ppp0: 0000000002f70b0d: recv [LCP EchoRep id=72 <magic 0506c320>] [2019-05-14 10:12:50.361] ens9.3601: recv [PPPoE PADT 00:00:77:0b:01:02 => 52:54:00:61:9c:32 sid=4540] [2019-05-14 10:12:50.361] ppp0: 0000000002f70b0d: terminate [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: radius(1): req_enter 1 [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daa8> <Acct-Session-Id "0000000002f70b0d"> <Acct-Session-Time 1200> <Acct-Input-Octets 30> <Acct-Output-Octets 30> <Acct-Input-Packets 3> <Acct-Output-Packets 3> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.98> ] [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: radius(1): req_exit 0 [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: pppoe: ppp finished [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: lcp_layer_free [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: auth_layer_free [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: ccp_layer_free [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: ipcp_layer_free [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: ipv6cp_layer_free [2019-05-14 10:12:50.362] ppp0: 0000000002f70b0d: ppp destablished [2019-05-14 10:12:50.363] ens9.3601: send [PPPoE PADT 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=4540 <AC-Name 250.55> ] [2019-05-14 10:12:50.363] ppp0: 0000000002f70b0d: disconnected [2019-05-14 10:12:50.420] recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:12:50.560] connlimit: check entry 2203510571008 [2019-05-14 10:12:50.560] connlimit: accept 2203510571008 [2019-05-14 10:12:50.560] ens9.3601: recv [PPPoE PADI 00:00:77:0b:01:02 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 000a0000>] [2019-05-14 10:12:50.560] ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 10:12:51.658] connlimit: check entry 2203510571008 [2019-05-14 10:12:51.659] connlimit: accept 2203510571008 [2019-05-14 10:12:51.659] ens9.3601: recv [PPPoE PADI 00:00:77:0b:01:02 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 000a0000>] [2019-05-14 10:12:51.659] ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 10:12:51.661] ens9.3601: recv [PPPoE PADR 00:00:77:0b:01:02 => 52:54:00:61:9c:32 sid=0000 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 10:12:51.661] ens9.3601: send [PPPoE PADS 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=4580 <AC-Name 250.55> <Host-Uniq 000a0000>] [2019-05-14 10:12:51.661] ens9.3601: : lcp_layer_init [2019-05-14 10:12:51.661] ens9.3601: : auth_layer_init [2019-05-14 10:12:51.661] ens9.3601: : ccp_layer_init [2019-05-14 10:12:51.661] ens9.3601: : ipcp_layer_init [2019-05-14 10:12:51.661] ens9.3601: : ipv6cp_layer_init [2019-05-14 10:12:51.661] ens9.3601: : ppp establishing [2019-05-14 10:12:51.661] ens9.3601: 0000000002f70b0e: lcp_layer_start [2019-05-14 10:12:51.661] ens9.3601: 0000000002f70b0e: send [LCP ConfReq id=28 <mru 1440> <magic 554198fa>] [2019-05-14 10:12:51.668] ens9.3601: 0000000002f70b0e: recv [LCP ConfReq id=1 <magic 0506c320> <mru 65531>] [2019-05-14 10:12:51.668] ens9.3601: 0000000002f70b0e: send [LCP ConfNak id=1 <mru 1440>] [2019-05-14 10:12:51.669] ens9.3601: 0000000002f70b0e: recv [LCP ConfAck id=28 <mru 1440> <magic 554198fa>] [2019-05-14 10:12:51.670] ens9.3601: 0000000002f70b0e: recv [LCP ConfReq id=2 <magic 0506c320> <mru 1440>] [2019-05-14 10:12:51.670] ens9.3601: 0000000002f70b0e: send [LCP ConfAck id=2 ] [2019-05-14 10:12:51.670] ens9.3601: 0000000002f70b0e: lcp_layer_started [2019-05-14 10:12:51.670] ens9.3601: 0000000002f70b0e: auth_layer_start [2019-05-14 10:12:51.671] ens9.3601: 0000000002f70b0e: recv [PAP AuthReq id=1] [2019-05-14 10:12:51.671] ens9.3601: 0000000002f70b0e: radius(1): req_enter 1 [2019-05-14 10:12:51.671] ens9.3601: 0000000002f70b0e: send [RADIUS(1) Access-Request id=1 <User-Name "test1"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <User-Password 0x7502e922c06cd9ea9c15e5680e4a44d6>] [2019-05-14 10:12:51.673] ens9.3601: 0000000002f70b0e: radius(1): req_exit 0 [2019-05-14 10:12:51.673] ens9.3601: 0000000002f70b0e: recv [RADIUS(1) Access-Accept id=1 <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daac> ] [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: connect: ppp0 <--> pppoe(00:00:77:0b:01:02) [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: ppp connected [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: send [PAP AuthAck id=1 "Authentication succeeded"] [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: auth_layer_started [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: ccp_layer_start [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: ipcp_layer_start [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: send [IPCP ConfReq id=8c <addr 10.1.250.199>] [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: ipv6cp_layer_start [2019-05-14 10:12:51.673] ppp0: 0000000002f70b0e: test1: authentication succeeded [2019-05-14 10:12:51.675] ppp0: 0000000002f70b0e: recv [IPCP ConfReq id=1 <addr 0.0.0.0>] [2019-05-14 10:12:51.675] ppp0: 0000000002f70b0e: send [IPCP ConfNak id=1 <addr 10.172.0.99>] [2019-05-14 10:12:51.676] ppp0: 0000000002f70b0e: recv [IPCP ConfAck id=8c <addr 10.1.250.199>] [2019-05-14 10:12:51.677] ppp0: 0000000002f70b0e: recv [IPCP ConfReq id=2 <addr 10.172.0.99>] [2019-05-14 10:12:51.677] ppp0: 0000000002f70b0e: send [IPCP ConfAck id=2] [2019-05-14 10:12:51.677] ppp0: 0000000002f70b0e: ipcp_layer_started [2019-05-14 10:12:51.677] ppp0: 0000000002f70b0e: radius(1): req_enter 1 [2019-05-14 10:12:51.677] ppp0: 0000000002f70b0e: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daac> <Acct-Session-Id "0000000002f70b0e"> <Acct-Session-Time 0> <Acct-Input-Octets 0> <Acct-Output-Octets 0> <Acct-Input-Packets 0> <Acct-Output-Packets 0> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.99>] [2019-05-14 10:12:51.687] ppp0: 0000000002f70b0e: radius(1): req_exit 0 [2019-05-14 10:12:51.687] ppp0: 0000000002f70b0e: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:12:51.687] ppp0: 0000000002f70b0e: pppoe: ppp started [2019-05-14 10:13:21.669] ppp0: 0000000002f70b0e: recv [LCP EchoReq id=3 <magic 0506c320>] [2019-05-14 10:13:21.669] ppp0: 0000000002f70b0e: send [LCP EchoRep id=3 <magic 554198fa>] [2019-05-14 10:13:35.513] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:13:35.514] cli: disconnect [2019-05-14 10:13:35.517] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:13:35.518] cli: disconnect [2019-05-14 10:13:51.667] ppp0: 0000000002f70b0e: recv [LCP EchoReq id=4 <magic 0506c320>] [2019-05-14 10:13:51.667] ppp0: 0000000002f70b0e: send [LCP EchoRep id=4 <magic 554198fa>] [2019-05-14 10:14:21.666] ppp0: 0000000002f70b0e: recv [LCP EchoReq id=5 <magic 0506c320>] [2019-05-14 10:14:21.666] ppp0: 0000000002f70b0e: send [LCP EchoRep id=5 <magic 554198fa>] [2019-05-14 10:14:37.021] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:14:37.022] cli: disconnect [2019-05-14 10:14:37.025] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:14:37.025] cli: disconnect [2019-05-14 10:14:51.665] ppp0: 0000000002f70b0e: recv [LCP EchoReq id=6 <magic 0506c320>] [2019-05-14 10:14:51.665] ppp0: 0000000002f70b0e: send [LCP EchoRep id=6 <magic 554198fa>] [2019-05-14 10:14:51.670] ppp0: 0000000002f70b0e: send [LCP EchoReq id=29 <magic 554198fa>] [2019-05-14 10:14:51.672] ppp0: 0000000002f70b0e: recv [LCP EchoRep id=29 <magic 0506c320>] [2019-05-14 10:15:21.664] ppp0: 0000000002f70b0e: recv [LCP EchoReq id=7 <magic 0506c320>] [2019-05-14 10:15:21.664] ppp0: 0000000002f70b0e: send [LCP EchoRep id=7 <magic 554198fa>] [2019-05-14 10:15:37.526] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:15:37.526] cli: disconnect [2019-05-14 10:15:37.530] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:15:37.530] cli: disconnect [2019-05-14 10:15:51.662] ppp0: 0000000002f70b0e: recv [LCP EchoReq id=8 <magic 0506c320>] [2019-05-14 10:15:51.663] ppp0: 0000000002f70b0e: send [LCP EchoRep id=8 <magic 554198fa>] [2019-05-14 10:16:21.661] ppp0: 0000000002f70b0e: recv [LCP EchoReq id=9 <magic 0506c320>] [2019-05-14 10:16:21.661] ppp0: 0000000002f70b0e: send [LCP EchoRep id=9 <magic 554198fa>] [2019-05-14 10:16:39.034] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:16:39.034] cli: disconnect [2019-05-14 10:16:39.037] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:16:39.037] cli: disconnect [2019-05-14 10:16:51.660] ppp0: 0000000002f70b0e: recv [LCP EchoReq id=a <magic 0506c320>] [2019-05-14 10:16:51.660] ppp0: 0000000002f70b0e: send [LCP EchoRep id=a <magic 554198fa>] [2019-05-14 10:16:51.670] ppp0: 0000000002f70b0e: send [LCP EchoReq id=2a <magic 554198fa>] [2019-05-14 10:16:51.672] ppp0: 0000000002f70b0e: recv [LCP EchoRep id=2a <magic 0506c320>] [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: recv [LCP TermReq id=b] [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: send [LCP TermAck id=11] [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: terminate [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: lcp_layer_finish [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: auth_layer_finish [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: auth_layer_finished [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: ccp_layer_finish [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: ccp_layer_finished [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: ipcp_layer_finish [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: ipcp_layer_finished [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: ipv6cp_layer_finish [2019-05-14 10:17:21.019] ppp0: 0000000002f70b0e: ipv6cp_layer_finished [2019-05-14 10:17:21.021] ens9.3601: recv [PPPoE PADT 00:00:77:0b:01:02 => 52:54:00:61:9c:32 sid=4580] [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: radius(1): req_enter 1 [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "00:00:77:0b:01:02"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2daac> <Acct-Session-Id "0000000002f70b0e"> <Acct-Session-Time 270> <Acct-Input-Octets 30> <Acct-Output-Octets 30> <Acct-Input-Packets 3> <Acct-Output-Packets 3> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.99> ] [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: radius(1): req_exit 0 [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: pppoe: ppp finished [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: lcp_layer_free [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: auth_layer_free [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: ccp_layer_free [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: ipcp_layer_free [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: ipv6cp_layer_free [2019-05-14 10:17:21.021] ppp0: 0000000002f70b0e: ppp destablished [2019-05-14 10:17:21.022] ens9.3601: send [PPPoE PADT 52:54:00:61:9c:32 => 00:00:77:0b:01:02 sid=4580 <AC-Name 250.55> ] [2019-05-14 10:17:21.022] ppp0: 0000000002f70b0e: disconnected [2019-05-14 10:17:21.032] recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:17:39.529] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:17:39.529] cli: disconnect [2019-05-14 10:17:39.533] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:17:39.533] cli: disconnect [2019-05-14 10:18:41.031] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:18:41.031] cli: disconnect [2019-05-14 10:18:41.034] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:18:41.035] cli: disconnect [2019-05-14 10:18:50.819] connlimit: check entry 270303448028242 [2019-05-14 10:18:50.819] connlimit: remove 2203510571008 [2019-05-14 10:18:50.819] connlimit: add entry 270303448028242 [2019-05-14 10:18:50.819] connlimit: accept 270303448028242 [2019-05-14 10:18:50.819] ens9.3601: recv [PPPoE PADI 52:54:00:ed:d6:f5 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 61590000>] [2019-05-14 10:18:50.819] ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=0000 <AC-Name 250.55> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b15ba0f45e3d01272> <Host-Uniq 61590000>] [2019-05-14 10:18:55.824] connlimit: check entry 270303448028242 [2019-05-14 10:18:55.824] connlimit: accept 270303448028242 [2019-05-14 10:18:55.824] ens9.3601: recv [PPPoE PADI 52:54:00:ed:d6:f5 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 61590000>] [2019-05-14 10:18:55.824] ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=0000 <AC-Name 250.55> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b21f30c58c4af9f80> <Host-Uniq 61590000>] [2019-05-14 10:18:55.825] ens9.3601: recv [PPPoE PADR 52:54:00:ed:d6:f5 => 52:54:00:61:9c:32 sid=0000 <Host-Uniq 61590000> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b21f30c58c4af9f80>] [2019-05-14 10:18:55.825] ens9.3601: send [PPPoE PADS 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=45c0 <AC-Name 250.55> <Host-Uniq 61590000>] [2019-05-14 10:18:55.825] ens9.3601: : lcp_layer_init [2019-05-14 10:18:55.825] ens9.3601: : auth_layer_init [2019-05-14 10:18:55.825] ens9.3601: : ccp_layer_init [2019-05-14 10:18:55.825] ens9.3601: : ipcp_layer_init [2019-05-14 10:18:55.825] ens9.3601: : ipv6cp_layer_init [2019-05-14 10:18:55.825] ens9.3601: : ppp establishing [2019-05-14 10:18:55.826] ens9.3601: 0000000002f70b0f: lcp_layer_start [2019-05-14 10:18:55.826] ens9.3601: 0000000002f70b0f: send [LCP ConfReq id=27 <mru 1440> <magic 4a2bb9ea>] [2019-05-14 10:18:55.826] ens9.3601: 0000000002f70b0f: recv [LCP ConfReq id=1 <mru 1492> <magic 38e53b5a>] [2019-05-14 10:18:55.826] ens9.3601: 0000000002f70b0f: send [LCP ConfAck id=1 ] [2019-05-14 10:18:55.826] ens9.3601: 0000000002f70b0f: recv [LCP ConfAck id=27 <mru 1440> <magic 4a2bb9ea>] [2019-05-14 10:18:55.826] ens9.3601: 0000000002f70b0f: lcp_layer_started [2019-05-14 10:18:55.826] ens9.3601: 0000000002f70b0f: auth_layer_start [2019-05-14 10:18:55.827] ens9.3601: 0000000002f70b0f: recv [LCP EchoReq id=0 <magic 38e53b5a>] [2019-05-14 10:18:55.827] ens9.3601: 0000000002f70b0f: send [LCP EchoRep id=0 <magic 4a2bb9ea>] [2019-05-14 10:18:55.827] ens9.3601: 0000000002f70b0f: recv [PAP AuthReq id=1] [2019-05-14 10:18:55.827] ens9.3601: 0000000002f70b0f: radius(1): req_enter 1 [2019-05-14 10:18:55.827] ens9.3601: 0000000002f70b0f: send [RADIUS(1) Access-Request id=1 <User-Name "test1"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <User-Password 0x21b9a44f7cec58535b62f3b0f1767c58>] [2019-05-14 10:18:55.828] ens9.3601: 0000000002f70b0f: radius(1): req_exit 0 [2019-05-14 10:18:55.828] ens9.3601: 0000000002f70b0f: recv [RADIUS(1) Access-Accept id=1 <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dab0> ] [2019-05-14 10:18:55.828] ppp0: 0000000002f70b0f: connect: ppp0 <--> pppoe(52:54:00:ed:d6:f5) [2019-05-14 10:18:55.829] ppp0: 0000000002f70b0f: ppp connected [2019-05-14 10:18:55.829] ppp0: 0000000002f70b0f: send [PAP AuthAck id=1 "Authentication succeeded"] [2019-05-14 10:18:55.829] ppp0: 0000000002f70b0f: auth_layer_started [2019-05-14 10:18:55.829] ppp0: 0000000002f70b0f: ccp_layer_start [2019-05-14 10:18:55.829] ppp0: 0000000002f70b0f: ipcp_layer_start [2019-05-14 10:18:55.829] ppp0: 0000000002f70b0f: send [IPCP ConfReq id=16 <addr 10.1.250.199>] [2019-05-14 10:18:55.829] ppp0: 0000000002f70b0f: ipv6cp_layer_start [2019-05-14 10:18:55.829] ppp0: 0000000002f70b0f: test1: authentication succeeded [2019-05-14 10:18:55.830] ppp0: 0000000002f70b0f: recv [IPCP ConfReq id=1 <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>] [2019-05-14 10:18:55.830] ppp0: 0000000002f70b0f: send [IPCP ConfNak id=1 <addr 10.172.0.100> <dns1 168.95.1.1> <dns2 168.95.192.1>] [2019-05-14 10:18:55.830] ppp0: 0000000002f70b0f: recv [IPCP ConfAck id=16 <addr 10.1.250.199>] [2019-05-14 10:18:55.830] ppp0: 0000000002f70b0f: recv [IPCP ConfReq id=2 <addr 10.172.0.100> <dns1 168.95.1.1> <dns2 168.95.192.1>] [2019-05-14 10:18:55.830] ppp0: 0000000002f70b0f: send [IPCP ConfAck id=2] [2019-05-14 10:18:55.830] ppp0: 0000000002f70b0f: ipcp_layer_started [2019-05-14 10:18:55.830] ppp0: 0000000002f70b0f: radius(1): req_enter 1 [2019-05-14 10:18:55.830] ppp0: 0000000002f70b0f: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dab0> <Acct-Session-Id "0000000002f70b0f"> <Acct-Session-Time 0> <Acct-Input-Octets 0> <Acct-Output-Octets 0> <Acct-Input-Packets 0> <Acct-Output-Packets 0> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.100>] [2019-05-14 10:18:55.843] ppp0: 0000000002f70b0f: radius(1): req_exit 0 [2019-05-14 10:18:55.843] ppp0: 0000000002f70b0f: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:18:55.843] ppp0: 0000000002f70b0f: pppoe: ppp started [2019-05-14 10:19:25.853] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=1 <magic 38e53b5a>] [2019-05-14 10:19:25.854] ppp0: 0000000002f70b0f: send [LCP EchoRep id=1 <magic 4a2bb9ea>] [2019-05-14 10:19:41.519] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:19:41.519] cli: disconnect [2019-05-14 10:19:41.522] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:19:41.522] cli: disconnect [2019-05-14 10:19:55.869] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=2 <magic 38e53b5a>] [2019-05-14 10:19:55.869] ppp0: 0000000002f70b0f: send [LCP EchoRep id=2 <magic 4a2bb9ea>] [2019-05-14 10:20:25.898] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=3 <magic 38e53b5a>] [2019-05-14 10:20:25.899] ppp0: 0000000002f70b0f: send [LCP EchoRep id=3 <magic 4a2bb9ea>] [2019-05-14 10:20:43.014] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:20:43.014] cli: disconnect [2019-05-14 10:20:43.017] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:20:43.018] cli: disconnect [2019-05-14 10:20:55.826] ppp0: 0000000002f70b0f: send [LCP EchoReq id=28 <magic 4a2bb9ea>] [2019-05-14 10:20:55.827] ppp0: 0000000002f70b0f: recv [LCP EchoRep id=28 <magic 38e53b5a>] [2019-05-14 10:20:55.898] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=4 <magic 38e53b5a>] [2019-05-14 10:20:55.898] ppp0: 0000000002f70b0f: send [LCP EchoRep id=4 <magic 4a2bb9ea>] [2019-05-14 10:21:25.928] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=5 <magic 38e53b5a>] [2019-05-14 10:21:25.928] ppp0: 0000000002f70b0f: send [LCP EchoRep id=5 <magic 4a2bb9ea>] [2019-05-14 10:21:43.500] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:21:43.500] cli: disconnect [2019-05-14 10:21:43.503] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:21:43.503] cli: disconnect [2019-05-14 10:21:55.958] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=6 <magic 38e53b5a>] [2019-05-14 10:21:55.958] ppp0: 0000000002f70b0f: send [LCP EchoRep id=6 <magic 4a2bb9ea>] [2019-05-14 10:22:25.984] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=7 <magic 38e53b5a>] [2019-05-14 10:22:25.984] ppp0: 0000000002f70b0f: send [LCP EchoRep id=7 <magic 4a2bb9ea>] [2019-05-14 10:22:44.989] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:22:44.989] cli: disconnect [2019-05-14 10:22:44.992] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:22:44.992] cli: disconnect [2019-05-14 10:22:55.826] ppp0: 0000000002f70b0f: send [LCP EchoReq id=29 <magic 4a2bb9ea>] [2019-05-14 10:22:55.827] ppp0: 0000000002f70b0f: recv [LCP EchoRep id=29 <magic 38e53b5a>] [2019-05-14 10:22:55.984] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=8 <magic 38e53b5a>] [2019-05-14 10:22:55.984] ppp0: 0000000002f70b0f: send [LCP EchoRep id=8 <magic 4a2bb9ea>] [2019-05-14 10:23:26.014] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=9 <magic 38e53b5a>] [2019-05-14 10:23:26.014] ppp0: 0000000002f70b0f: send [LCP EchoRep id=9 <magic 4a2bb9ea>] [2019-05-14 10:23:45.465] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:23:45.466] cli: disconnect [2019-05-14 10:23:45.469] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:23:45.469] cli: disconnect [2019-05-14 10:23:56.044] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=a <magic 38e53b5a>] [2019-05-14 10:23:56.044] ppp0: 0000000002f70b0f: send [LCP EchoRep id=a <magic 4a2bb9ea>] [2019-05-14 10:24:26.073] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=b <magic 38e53b5a>] [2019-05-14 10:24:26.074] ppp0: 0000000002f70b0f: send [LCP EchoRep id=b <magic 4a2bb9ea>] [2019-05-14 10:24:46.949] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:24:46.949] cli: disconnect [2019-05-14 10:24:46.953] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:24:46.953] cli: disconnect [2019-05-14 10:24:55.826] ppp0: 0000000002f70b0f: send [LCP EchoReq id=2a <magic 4a2bb9ea>] [2019-05-14 10:24:55.827] ppp0: 0000000002f70b0f: recv [LCP EchoRep id=2a <magic 38e53b5a>] [2019-05-14 10:24:56.073] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=c <magic 38e53b5a>] [2019-05-14 10:24:56.073] ppp0: 0000000002f70b0f: send [LCP EchoRep id=c <magic 4a2bb9ea>] [2019-05-14 10:25:26.103] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=d <magic 38e53b5a>] [2019-05-14 10:25:26.104] ppp0: 0000000002f70b0f: send [LCP EchoRep id=d <magic 4a2bb9ea>] [2019-05-14 10:25:47.432] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:25:47.432] cli: disconnect [2019-05-14 10:25:47.436] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:25:47.436] cli: disconnect [2019-05-14 10:25:56.133] ppp0: 0000000002f70b0f: recv [LCP EchoReq id=e <magic 38e53b5a>] [2019-05-14 10:25:56.133] ppp0: 0000000002f70b0f: send [LCP EchoRep id=e <magic 4a2bb9ea>] [2019-05-14 10:26:48.920] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:26:48.920] cli: disconnect [2019-05-14 10:26:48.924] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:26:48.924] cli: disconnect [2019-05-14 10:26:55.826] ppp0: 0000000002f70b0f: send [LCP EchoReq id=2b <magic 4a2bb9ea>] [2019-05-14 10:27:49.402] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:27:49.402] cli: disconnect [2019-05-14 10:27:49.406] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:27:49.406] cli: disconnect [2019-05-14 10:28:50.886] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:28:50.887] cli: disconnect [2019-05-14 10:28:50.890] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:28:50.890] cli: disconnect [2019-05-14 10:28:55.826] ppp0: 0000000002f70b0f: send [LCP EchoReq id=2c <magic 4a2bb9ea>] [2019-05-14 10:29:51.374] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:29:51.374] cli: disconnect [2019-05-14 10:29:51.377] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:29:51.377] cli: disconnect [2019-05-14 10:30:52.860] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:30:52.860] cli: disconnect [2019-05-14 10:30:52.863] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:30:52.863] cli: disconnect [2019-05-14 10:30:55.826] ppp0: 0000000002f70b0f: lcp: no echo reply [2019-05-14 10:30:55.826] ppp0: 0000000002f70b0f: terminate [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: radius(1): req_enter 1 [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dab0> <Acct-Session-Id "0000000002f70b0f"> <Acct-Session-Time 720> <Acct-Input-Octets 54> <Acct-Output-Octets 54> <Acct-Input-Packets 3> <Acct-Output-Packets 3> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.100> ] [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: radius(1): req_exit 0 [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: pppoe: ppp finished [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: lcp_layer_free [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: auth_layer_free [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: ccp_layer_free [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: ipcp_layer_free [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: ipv6cp_layer_free [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: ppp destablished [2019-05-14 10:30:55.827] ens9.3601: send [PPPoE PADT 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=45c0 <AC-Name 250.55> ] [2019-05-14 10:30:55.827] ppp0: 0000000002f70b0f: disconnected [2019-05-14 10:30:55.838] recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:31:53.354] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:31:53.354] cli: disconnect [2019-05-14 10:31:53.357] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:31:53.358] cli: disconnect [2019-05-14 10:32:54.851] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:32:54.852] cli: disconnect [2019-05-14 10:32:54.855] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:32:54.855] cli: disconnect [2019-05-14 10:33:55.345] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:33:55.346] cli: disconnect [2019-05-14 10:33:55.349] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:33:55.349] cli: disconnect [2019-05-14 10:34:02.427] connlimit: check entry 270303448028242 [2019-05-14 10:34:02.427] connlimit: accept 270303448028242 [2019-05-14 10:34:02.427] ens9.3601: recv [PPPoE PADI 52:54:00:ed:d6:f5 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 71050000>] [2019-05-14 10:34:02.427] ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=0000 <AC-Name 250.55> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1bbcbea228c3c7f469> <Host-Uniq 71050000>] [2019-05-14 10:34:07.432] connlimit: check entry 270303448028242 [2019-05-14 10:34:07.432] connlimit: accept 270303448028242 [2019-05-14 10:34:07.432] ens9.3601: recv [PPPoE PADI 52:54:00:ed:d6:f5 => ff:ff:ff:ff:ff:ff sid=0000 <Host-Uniq 71050000>] [2019-05-14 10:34:07.433] ens9.3601: send [PPPoE PADO 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=0000 <AC-Name 250.55> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b9b92f8b93fa67cbd> <Host-Uniq 71050000>] [2019-05-14 10:34:07.433] ens9.3601: recv [PPPoE PADR 52:54:00:ed:d6:f5 => 52:54:00:61:9c:32 sid=0000 <Host-Uniq 71050000> <AC-Cookie 843ae0a8b326e6eaccdfb0e3fe5d6c1b9b92f8b93fa67cbd>] [2019-05-14 10:34:07.433] ens9.3601: send [PPPoE PADS 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=4600 <AC-Name 250.55> <Host-Uniq 71050000>] [2019-05-14 10:34:07.434] ens9.3601: : lcp_layer_init [2019-05-14 10:34:07.434] ens9.3601: : auth_layer_init [2019-05-14 10:34:07.434] ens9.3601: : ccp_layer_init [2019-05-14 10:34:07.434] ens9.3601: : ipcp_layer_init [2019-05-14 10:34:07.434] ens9.3601: : ipv6cp_layer_init [2019-05-14 10:34:07.434] ens9.3601: : ppp establishing [2019-05-14 10:34:07.434] ens9.3601: 0000000002f70b10: lcp_layer_start [2019-05-14 10:34:07.434] ens9.3601: 0000000002f70b10: send [LCP ConfReq id=c <mru 1440> <magic 3de2c055>] [2019-05-14 10:34:07.462] ens9.3601: 0000000002f70b10: recv [LCP ConfReq id=1 <mru 1492> <magic 54d38a72>] [2019-05-14 10:34:07.463] ens9.3601: 0000000002f70b10: send [LCP ConfAck id=1 ] [2019-05-14 10:34:10.434] ens9.3601: 0000000002f70b10: fsm timeout 9 [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: send [LCP ConfReq id=c <mru 1440> <magic 3de2c055>] [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: recv [LCP ConfAck id=c <mru 1440> <magic 3de2c055>] [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: lcp_layer_started [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: auth_layer_start [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: recv [LCP EchoReq id=0 <magic 54d38a72>] [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: send [LCP EchoRep id=0 <magic 3de2c055>] [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: recv [PAP AuthReq id=1] [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: radius(1): req_enter 1 [2019-05-14 10:34:10.435] ens9.3601: 0000000002f70b10: send [RADIUS(1) Access-Request id=1 <User-Name "test1"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <User-Password 0x3a371143e53b38ca73a8dc3bfeeeb69a>] [2019-05-14 10:34:10.438] ens9.3601: 0000000002f70b10: radius(1): req_exit 0 [2019-05-14 10:34:10.438] ens9.3601: 0000000002f70b10: recv [RADIUS(1) Access-Accept id=1 <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dabc> ] [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: connect: ppp0 <--> pppoe(52:54:00:ed:d6:f5) [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: ppp connected [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: send [PAP AuthAck id=1 "Authentication succeeded"] [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: auth_layer_started [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: ccp_layer_start [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: ipcp_layer_start [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: send [IPCP ConfReq id=fc <addr 10.1.250.199>] [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: ipv6cp_layer_start [2019-05-14 10:34:10.438] ppp0: 0000000002f70b10: test1: authentication succeeded [2019-05-14 10:34:10.440] ppp0: 0000000002f70b10: recv [IPCP ConfReq id=1 <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>] [2019-05-14 10:34:10.440] ppp0: 0000000002f70b10: send [IPCP ConfNak id=1 <addr 10.172.0.101> <dns1 168.95.1.1> <dns2 168.95.192.1>] [2019-05-14 10:34:10.440] ppp0: 0000000002f70b10: recv [IPCP ConfAck id=fc <addr 10.1.250.199>] [2019-05-14 10:34:10.440] ppp0: 0000000002f70b10: recv [IPCP ConfReq id=2 <addr 10.172.0.101> <dns1 168.95.1.1> <dns2 168.95.192.1>] [2019-05-14 10:34:10.440] ppp0: 0000000002f70b10: send [IPCP ConfAck id=2] [2019-05-14 10:34:10.440] ppp0: 0000000002f70b10: ipcp_layer_started [2019-05-14 10:34:10.440] ppp0: 0000000002f70b10: radius(1): req_enter 1 [2019-05-14 10:34:10.440] ppp0: 0000000002f70b10: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dabc> <Acct-Session-Id "0000000002f70b10"> <Acct-Session-Time 0> <Acct-Input-Octets 0> <Acct-Output-Octets 0> <Acct-Input-Packets 0> <Acct-Output-Packets 0> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.101>] [2019-05-14 10:34:10.488] ppp0: 0000000002f70b10: radius(1): req_exit 0 [2019-05-14 10:34:10.488] ppp0: 0000000002f70b10: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:34:10.489] ppp0: 0000000002f70b10: pppoe: ppp started [2019-05-14 10:34:40.462] ppp0: 0000000002f70b10: recv [LCP EchoReq id=1 <magic 54d38a72>] [2019-05-14 10:34:40.462] ppp0: 0000000002f70b10: send [LCP EchoRep id=1 <magic 3de2c055>] [2019-05-14 10:34:56.836] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:34:56.836] cli: disconnect [2019-05-14 10:34:56.839] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:34:56.839] cli: disconnect [2019-05-14 10:35:10.492] ppp0: 0000000002f70b10: recv [LCP EchoReq id=2 <magic 54d38a72>] [2019-05-14 10:35:10.492] ppp0: 0000000002f70b10: send [LCP EchoRep id=2 <magic 3de2c055>] [2019-05-14 10:35:40.521] ppp0: 0000000002f70b10: recv [LCP EchoReq id=3 <magic 54d38a72>] [2019-05-14 10:35:40.522] ppp0: 0000000002f70b10: send [LCP EchoRep id=3 <magic 3de2c055>] [2019-05-14 10:35:57.317] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:35:57.317] cli: disconnect [2019-05-14 10:35:57.320] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:35:57.320] cli: disconnect [2019-05-14 10:36:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=d <magic 3de2c055>] [2019-05-14 10:36:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=d <magic 54d38a72>] [2019-05-14 10:36:10.521] ppp0: 0000000002f70b10: recv [LCP EchoReq id=4 <magic 54d38a72>] [2019-05-14 10:36:10.521] ppp0: 0000000002f70b10: send [LCP EchoRep id=4 <magic 3de2c055>] [2019-05-14 10:36:40.551] ppp0: 0000000002f70b10: recv [LCP EchoReq id=5 <magic 54d38a72>] [2019-05-14 10:36:40.551] ppp0: 0000000002f70b10: send [LCP EchoRep id=5 <magic 3de2c055>] [2019-05-14 10:36:58.805] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:36:58.805] cli: disconnect [2019-05-14 10:36:58.808] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:36:58.809] cli: disconnect [2019-05-14 10:37:10.581] ppp0: 0000000002f70b10: recv [LCP EchoReq id=6 <magic 54d38a72>] [2019-05-14 10:37:10.581] ppp0: 0000000002f70b10: send [LCP EchoRep id=6 <magic 3de2c055>] [2019-05-14 10:37:40.610] ppp0: 0000000002f70b10: recv [LCP EchoReq id=7 <magic 54d38a72>] [2019-05-14 10:37:40.610] ppp0: 0000000002f70b10: send [LCP EchoRep id=7 <magic 3de2c055>] [2019-05-14 10:37:59.288] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:37:59.288] cli: disconnect [2019-05-14 10:37:59.292] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:37:59.292] cli: disconnect [2019-05-14 10:38:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=e <magic 3de2c055>] [2019-05-14 10:38:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=e <magic 54d38a72>] [2019-05-14 10:38:10.610] ppp0: 0000000002f70b10: recv [LCP EchoReq id=8 <magic 54d38a72>] [2019-05-14 10:38:10.610] ppp0: 0000000002f70b10: send [LCP EchoRep id=8 <magic 3de2c055>] [2019-05-14 10:38:40.640] ppp0: 0000000002f70b10: recv [LCP EchoReq id=9 <magic 54d38a72>] [2019-05-14 10:38:40.640] ppp0: 0000000002f70b10: send [LCP EchoRep id=9 <magic 3de2c055>] [2019-05-14 10:39:00.777] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:39:00.777] cli: disconnect [2019-05-14 10:39:00.781] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:39:00.781] cli: disconnect [2019-05-14 10:39:10.670] ppp0: 0000000002f70b10: recv [LCP EchoReq id=a <magic 54d38a72>] [2019-05-14 10:39:10.670] ppp0: 0000000002f70b10: send [LCP EchoRep id=a <magic 3de2c055>] [2019-05-14 10:39:40.700] ppp0: 0000000002f70b10: recv [LCP EchoReq id=b <magic 54d38a72>] [2019-05-14 10:39:40.700] ppp0: 0000000002f70b10: send [LCP EchoRep id=b <magic 3de2c055>] [2019-05-14 10:40:01.261] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:40:01.261] cli: disconnect [2019-05-14 10:40:01.264] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:40:01.264] cli: disconnect [2019-05-14 10:40:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=f <magic 3de2c055>] [2019-05-14 10:40:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=f <magic 54d38a72>] [2019-05-14 10:40:10.699] ppp0: 0000000002f70b10: recv [LCP EchoReq id=c <magic 54d38a72>] [2019-05-14 10:40:10.699] ppp0: 0000000002f70b10: send [LCP EchoRep id=c <magic 3de2c055>] [2019-05-14 10:40:40.729] ppp0: 0000000002f70b10: recv [LCP EchoReq id=d <magic 54d38a72>] [2019-05-14 10:40:40.729] ppp0: 0000000002f70b10: send [LCP EchoRep id=d <magic 3de2c055>] [2019-05-14 10:41:02.762] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:41:02.763] cli: disconnect [2019-05-14 10:41:02.766] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:41:02.766] cli: disconnect [2019-05-14 10:41:10.759] ppp0: 0000000002f70b10: recv [LCP EchoReq id=e <magic 54d38a72>] [2019-05-14 10:41:10.759] ppp0: 0000000002f70b10: send [LCP EchoRep id=e <magic 3de2c055>] [2019-05-14 10:41:40.789] ppp0: 0000000002f70b10: recv [LCP EchoReq id=f <magic 54d38a72>] [2019-05-14 10:41:40.789] ppp0: 0000000002f70b10: send [LCP EchoRep id=f <magic 3de2c055>] [2019-05-14 10:42:03.253] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:42:03.253] cli: disconnect [2019-05-14 10:42:03.256] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:42:03.257] cli: disconnect [2019-05-14 10:42:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=10 <magic 3de2c055>] [2019-05-14 10:42:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=10 <magic 54d38a72>] [2019-05-14 10:42:10.789] ppp0: 0000000002f70b10: recv [LCP EchoReq id=10 <magic 54d38a72>] [2019-05-14 10:42:10.789] ppp0: 0000000002f70b10: send [LCP EchoRep id=10 <magic 3de2c055>] [2019-05-14 10:42:40.818] ppp0: 0000000002f70b10: recv [LCP EchoReq id=11 <magic 54d38a72>] [2019-05-14 10:42:40.818] ppp0: 0000000002f70b10: send [LCP EchoRep id=11 <magic 3de2c055>] [2019-05-14 10:43:04.750] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:43:04.750] cli: disconnect [2019-05-14 10:43:04.753] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:43:04.753] cli: disconnect [2019-05-14 10:43:10.848] ppp0: 0000000002f70b10: recv [LCP EchoReq id=12 <magic 54d38a72>] [2019-05-14 10:43:10.848] ppp0: 0000000002f70b10: send [LCP EchoRep id=12 <magic 3de2c055>] [2019-05-14 10:43:40.855] ppp0: 0000000002f70b10: recv [LCP EchoReq id=13 <magic 54d38a72>] [2019-05-14 10:43:40.856] ppp0: 0000000002f70b10: send [LCP EchoRep id=13 <magic 3de2c055>] [2019-05-14 10:44:05.244] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:44:05.244] cli: disconnect [2019-05-14 10:44:05.247] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:44:05.247] cli: disconnect [2019-05-14 10:44:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=11 <magic 3de2c055>] [2019-05-14 10:44:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=11 <magic 54d38a72>] [2019-05-14 10:44:10.855] ppp0: 0000000002f70b10: recv [LCP EchoReq id=14 <magic 54d38a72>] [2019-05-14 10:44:10.855] ppp0: 0000000002f70b10: send [LCP EchoRep id=14 <magic 3de2c055>] [2019-05-14 10:44:40.885] ppp0: 0000000002f70b10: recv [LCP EchoReq id=15 <magic 54d38a72>] [2019-05-14 10:44:40.885] ppp0: 0000000002f70b10: send [LCP EchoRep id=15 <magic 3de2c055>] [2019-05-14 10:45:06.733] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:45:06.734] cli: disconnect [2019-05-14 10:45:06.737] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:45:06.737] cli: disconnect [2019-05-14 10:45:10.915] ppp0: 0000000002f70b10: recv [LCP EchoReq id=16 <magic 54d38a72>] [2019-05-14 10:45:10.915] ppp0: 0000000002f70b10: send [LCP EchoRep id=16 <magic 3de2c055>] [2019-05-14 10:45:40.945] ppp0: 0000000002f70b10: recv [LCP EchoReq id=17 <magic 54d38a72>] [2019-05-14 10:45:40.945] ppp0: 0000000002f70b10: send [LCP EchoRep id=17 <magic 3de2c055>] [2019-05-14 10:46:07.226] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:46:07.227] cli: disconnect [2019-05-14 10:46:07.230] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:46:07.230] cli: disconnect [2019-05-14 10:46:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=12 <magic 3de2c055>] [2019-05-14 10:46:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=12 <magic 54d38a72>] [2019-05-14 10:46:10.945] ppp0: 0000000002f70b10: recv [LCP EchoReq id=18 <magic 54d38a72>] [2019-05-14 10:46:10.945] ppp0: 0000000002f70b10: send [LCP EchoRep id=18 <magic 3de2c055>] [2019-05-14 10:46:40.974] ppp0: 0000000002f70b10: recv [LCP EchoReq id=19 <magic 54d38a72>] [2019-05-14 10:46:40.975] ppp0: 0000000002f70b10: send [LCP EchoRep id=19 <magic 3de2c055>] [2019-05-14 10:47:08.722] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:47:08.722] cli: disconnect [2019-05-14 10:47:08.725] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:47:08.726] cli: disconnect [2019-05-14 10:47:10.990] ppp0: 0000000002f70b10: recv [LCP EchoReq id=1a <magic 54d38a72>] [2019-05-14 10:47:10.990] ppp0: 0000000002f70b10: send [LCP EchoRep id=1a <magic 3de2c055>] [2019-05-14 10:47:41.019] ppp0: 0000000002f70b10: recv [LCP EchoReq id=1b <magic 54d38a72>] [2019-05-14 10:47:41.020] ppp0: 0000000002f70b10: send [LCP EchoRep id=1b <magic 3de2c055>] [2019-05-14 10:48:09.210] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:48:09.210] cli: disconnect [2019-05-14 10:48:09.213] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:48:09.213] cli: disconnect [2019-05-14 10:48:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=13 <magic 3de2c055>] [2019-05-14 10:48:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=13 <magic 54d38a72>] [2019-05-14 10:48:11.020] ppp0: 0000000002f70b10: recv [LCP EchoReq id=1c <magic 54d38a72>] [2019-05-14 10:48:11.020] ppp0: 0000000002f70b10: send [LCP EchoRep id=1c <magic 3de2c055>] [2019-05-14 10:48:41.049] ppp0: 0000000002f70b10: recv [LCP EchoReq id=1d <magic 54d38a72>] [2019-05-14 10:48:41.050] ppp0: 0000000002f70b10: send [LCP EchoRep id=1d <magic 3de2c055>] [2019-05-14 10:49:10.719] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:49:10.719] cli: disconnect [2019-05-14 10:49:10.722] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:49:10.723] cli: disconnect [2019-05-14 10:49:11.079] ppp0: 0000000002f70b10: recv [LCP EchoReq id=1e <magic 54d38a72>] [2019-05-14 10:49:11.079] ppp0: 0000000002f70b10: send [LCP EchoRep id=1e <magic 3de2c055>] [2019-05-14 10:49:41.109] ppp0: 0000000002f70b10: recv [LCP EchoReq id=1f <magic 54d38a72>] [2019-05-14 10:49:41.109] ppp0: 0000000002f70b10: send [LCP EchoRep id=1f <magic 3de2c055>] [2019-05-14 10:50:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=14 <magic 3de2c055>] [2019-05-14 10:50:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=14 <magic 54d38a72>] [2019-05-14 10:50:11.109] ppp0: 0000000002f70b10: recv [LCP EchoReq id=20 <magic 54d38a72>] [2019-05-14 10:50:11.109] ppp0: 0000000002f70b10: send [LCP EchoRep id=20 <magic 3de2c055>] [2019-05-14 10:50:11.205] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:50:11.205] cli: disconnect [2019-05-14 10:50:11.208] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:50:11.208] cli: disconnect [2019-05-14 10:50:41.139] ppp0: 0000000002f70b10: recv [LCP EchoReq id=21 <magic 54d38a72>] [2019-05-14 10:50:41.139] ppp0: 0000000002f70b10: send [LCP EchoRep id=21 <magic 3de2c055>] [2019-05-14 10:51:11.169] ppp0: 0000000002f70b10: recv [LCP EchoReq id=22 <magic 54d38a72>] [2019-05-14 10:51:11.169] ppp0: 0000000002f70b10: send [LCP EchoRep id=22 <magic 3de2c055>] [2019-05-14 10:51:12.695] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:51:12.695] cli: disconnect [2019-05-14 10:51:12.698] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:51:12.698] cli: disconnect [2019-05-14 10:51:41.199] ppp0: 0000000002f70b10: recv [LCP EchoReq id=23 <magic 54d38a72>] [2019-05-14 10:51:41.199] ppp0: 0000000002f70b10: send [LCP EchoRep id=23 <magic 3de2c055>] [2019-05-14 10:52:10.435] ppp0: 0000000002f70b10: send [LCP EchoReq id=15 <magic 3de2c055>] [2019-05-14 10:52:10.436] ppp0: 0000000002f70b10: recv [LCP EchoRep id=15 <magic 54d38a72>] [2019-05-14 10:52:11.199] ppp0: 0000000002f70b10: recv [LCP EchoReq id=24 <magic 54d38a72>] [2019-05-14 10:52:11.199] ppp0: 0000000002f70b10: send [LCP EchoRep id=24 <magic 3de2c055>] [2019-05-14 10:52:13.180] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:52:13.181] cli: disconnect [2019-05-14 10:52:13.184] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:52:13.184] cli: disconnect [2019-05-14 10:52:41.229] ppp0: 0000000002f70b10: recv [LCP EchoReq id=25 <magic 54d38a72>] [2019-05-14 10:52:41.229] ppp0: 0000000002f70b10: send [LCP EchoRep id=25 <magic 3de2c055>] [2019-05-14 10:53:11.258] ppp0: 0000000002f70b10: recv [LCP EchoReq id=26 <magic 54d38a72>] [2019-05-14 10:53:11.259] ppp0: 0000000002f70b10: send [LCP EchoRep id=26 <magic 3de2c055>] [2019-05-14 10:53:14.666] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:53:14.666] cli: disconnect [2019-05-14 10:53:14.669] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:53:14.669] cli: disconnect [2019-05-14 10:53:41.288] ppp0: 0000000002f70b10: recv [LCP EchoReq id=27 <magic 54d38a72>] [2019-05-14 10:53:41.288] ppp0: 0000000002f70b10: send [LCP EchoRep id=27 <magic 3de2c055>] [2019-05-14 10:53:54.014] ppp0: 0000000002f70b10: recv [LCP TermReq id=2] [2019-05-14 10:53:54.014] ppp0: 0000000002f70b10: send [LCP TermAck id=2] [2019-05-14 10:53:54.014] ppp0: 0000000002f70b10: terminate [2019-05-14 10:53:54.014] ppp0: 0000000002f70b10: lcp_layer_finish [2019-05-14 10:53:54.015] ppp0: 0000000002f70b10: auth_layer_finish [2019-05-14 10:53:54.015] ppp0: 0000000002f70b10: auth_layer_finished [2019-05-14 10:53:54.015] ppp0: 0000000002f70b10: ccp_layer_finish [2019-05-14 10:53:54.015] ppp0: 0000000002f70b10: ccp_layer_finished [2019-05-14 10:53:54.015] ppp0: 0000000002f70b10: ipcp_layer_finish [2019-05-14 10:53:54.015] ppp0: 0000000002f70b10: ipcp_layer_finished [2019-05-14 10:53:54.015] ppp0: 0000000002f70b10: ipv6cp_layer_finish [2019-05-14 10:53:54.015] ppp0: 0000000002f70b10: ipv6cp_layer_finished [2019-05-14 10:53:54.017] ppp0: 0000000002f70b10: radius(1): req_enter 1 [2019-05-14 10:53:54.017] ppp0: 0000000002f70b10: send [RADIUS(1) Accounting-Request id=1 <User-Name "test1"> <NAS-Port 0> <NAS-Port-Id "ppp0"> <Calling-Station-Id "52:54:00:ed:d6:f5"> <Called-Station-Id "ens9.3601:52:54:00:61:9c:32"> <Class 0x53425232434cd8b2e79f87fe8fcc9dc011802201800281988002800681aa91aab5a1c412800e81d8b2e79f87fe8fcc9dc686d2dabc> <Acct-Session-Id "0000000002f70b10"> <Acct-Session-Time 1187> <Acct-Input-Octets 54> <Acct-Output-Octets 54> <Acct-Input-Packets 3> <Acct-Output-Packets 3> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Acct-Delay-Time 0> <Framed-IP-Address 10.172.0.101> ] [2019-05-14 10:53:54.034] ppp0: 0000000002f70b10: radius(1): req_exit 0 [2019-05-14 10:53:54.034] ppp0: 0000000002f70b10: recv [RADIUS(1) Accounting-Response id=1] [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: fsm timeout 0 [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: lcp_layer_finished [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: pppoe: ppp finished [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: lcp_layer_free [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: auth_layer_free [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: ccp_layer_free [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: ipcp_layer_free [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: ipv6cp_layer_free [2019-05-14 10:53:57.015] ppp0: 0000000002f70b10: ppp destablished [2019-05-14 10:53:57.015] ens9.3601: send [PPPoE PADT 52:54:00:61:9c:32 => 52:54:00:ed:d6:f5 sid=4600 <AC-Name 250.55> ] [2019-05-14 10:53:57.016] ppp0: 0000000002f70b10: disconnected [2019-05-14 10:54:15.138] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:54:15.138] cli: disconnect [2019-05-14 10:54:15.141] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:54:15.141] cli: disconnect [2019-05-14 10:55:16.628] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:55:16.628] cli: disconnect [2019-05-14 10:55:16.631] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:55:16.631] cli: disconnect [2019-05-14 10:56:17.110] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:56:17.110] cli: disconnect [2019-05-14 10:56:17.113] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:56:17.113] cli: disconnect [2019-05-14 10:57:18.599] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:57:18.599] cli: disconnect [2019-05-14 10:57:18.602] cli: tcp: new connection from 127.0.0.1 [2019-05-14 10:57:18.602] cli: disconnect

[DmitriyEshenko]

Sorry for long answer time. Did you use module pppd_compat? Can you provide whole accel-ppp.conf

[rudinyu]

We don't enable pppd_compat.

It is our config #file

[modules] log_file

log_syslog

log_tcp

log_pgsql

pptp

l2tp

pppoe

ipoe

auth_mschap_v2

auth_mschap_v1

auth_chap_md5

auth_pap radius chap-secrets ippool

pppd_compat

shaper

net-snmp

logwtmp

connlimit

ipv6_nd

ipv6_dhcp

ipv6pool

net-accel-dp

[auth] any-login=0 noauth=0

noauth=1

timeout=9

[core] log-error=/var/log/accel-ppp/core.log thread-count=6

[common]

single-session=replace

sid-case=upper

sid-source=seq

max-sessions=32100

[ppp] verbose=1 min-mtu=1280 mtu=1440 mru=1440 # accomp=deny

pcomp=deny ccp=0 check-ip=0

check-ip=1

mppe=require

mppe=deny ipv4=require ipv6=deny

ipv6-intf-id=0:0:0:1

ipv6-peer-intf-id=0:0:0:2

ipv6-accept-peer-intf-id=1

ipv6-intf-id=random

ipv6-peer-intf-id=random

lcp-echo-interval=120 lcp-echo-failure=1 lcp-echo-timeout=0 unit-cache=2000

unit-preallocate=1

single-session=replace

[lcp]

echo-interval=5

echo-failure=1

[pptp]

verbose=1

echo-interval=30

[vlan-mon]

verbose=10

autoclean = 1

[pppoe] verbose=1 ac-name=250.50

service-name=250.50

pado-delay=0

pado-delay=0,100:100,200:200,-1:500

called-sid=ifname:mac

tr101=1

padi-limit=1 overall limit of PADI packets to reply in 1 second period(default=0 unlimited)

Rate of per-mac PADI packets is limited to no more than 1 packet per second.

padi-limit=100

ip-pool=pool1

sid-uppercase=0

vlan-mon=ens9.1,1-1000

vlan-timeout=60

vlan-name=%I.%N

mac-filter=/etc/mac-blacklist,deny

mac-filter=/etc/mac-blacklist,deny

interface=eth1,padi-limit=1000,net=accel-dp

,padi-limit=3 limit of PADI packets to reply on this interface in 1 second period.

interface=re:eth1.,padi-limit=8

interface=re:eth5.([1-9]|[1-9][0-9]|[1-9][0-9][0-9]|[1-4][0-9][0-9][0-9])

interface=re:ens9.

interface=ens9

interface=eth2

[l2tp]

verbose=1

dictionary=/usr/local/share/accel-ppp/l2tp/dictionary

hello-interval=60

timeout=60

rtimeout=1

rtimeout-cap=16

retransmit=5

recv-window=16

host-name=accel-ppp

dir300_quirk=0

secret=

dataseq=allow

reorder-timeout=0

ip-pool=l2tp

[ipoe]

verbose=1

username=ifname

password=username

lease-time=600

renew-time=600

max-lease-time=3600

unit-cache=1000

l4-redirect-table=4

l4-redirect-ipset=l4

l4-redirect-on-reject=300

l4-redirect-ip-pool=pool1

shared=0

ifcfg=1

mode=L2

start=dhcpv4

start=UP

ip-unnumbered=1

proxy-arp=0

nat=0

proto=100

relay=10.10.10.10

vendor=Custom

attr-dhcp-client-ip=DHCP-Client-IP-Address

attr-dhcp-router-ip=DHCP-Router-IP-Address

attr-dhcp-mask=DHCP-Mask

attr-dhcp-lease-time=DHCP-Lease-Time

attr-dhcp-opt82=DHCP-Option82

attr-dhcp-opt82-remote-id=DHCP-Agent-Remote-Id

attr-dhcp-opt82-circuit-id=DHCP-Agent-Circuit-Id

attr-l4-redirect=L4-Redirect

attr-l4-redirect-table=4

attr-l4-redirect-ipset=l4-redirect

lua-file=/etc/accel-ppp.lua

offer-delay=0,100:100,200:200,-1:1000

vlan-mon=eth0,10-200

vlan-timeout=60

vlan-name=%I.%N

ip-pool=ipoe

idle-timeout=0

session-timeout=0

soft-terminate=0

check-mac-change=1

calling-sid=mac

local-net=192.168.0.0/16

interface=eth0

[dns] dns1=168.95.1.1 dns2=168.95.192.1

[wins]

wins1=172.16.0.1

wins2=172.16.1.1

[radius] dictionary=/usr/local/share/accel-ppp/radius/dictionary

dm_coa_secret=xflow

nas-identifier=accel-ppp

nas-ip-address=127.0.0.1

gw-ip-address=10.1.250.199 server=10.1.25.2,jalee123,auth-port=1812,acct-port=1813,max-lease-time=540,renew-time=180,lease-time=360,req-limit=400,fail-timeout=3,max-fail=2,weight=1

weight=100 is controller who is primary server, 100 > 1

dae-server=127.0.0.1:3799,testing123

dae-server=172.30.222.85:3799,xflow

verbose=1 timeout=3 max-try=2

acct-interim-interval=60

acct-timeout=3 acct-delay-time=1

acct-on=0

attr-tunnel-type=My-Tunnel-Type

[client-ip-range]

10.0.0.0/8

[ip-pool] gw-ip-address=10.1.250.199

vendor=Cisco

attr=Cisco-AVPair

attr=Framed-Pool

192.160.0.2-255

192.168.1.1-255,name=pool1

=======ip:4000

10.167.0.0/21,name=pool1

10.167.8.0/22,name=pool1

10.167.12.0/24,name=pool1

10.167.13.0/24,name=pool2,next=pool1

10.167.14.0/24,name=pool1

10.167.15.0-231,name=pool1

10.180.0.0-100,name=pool10

10.167.15.0-159,name=pool1

======ip:24000

10.167.0.0/18,name=pool1 10.167.64.0/20,name=pool1 10.167.80.0/21,name=pool1 10.167.88.0/22,name=pool1 10.167.92.0/24,name=pool1 10.167.93.0-192,name=pool1

======ip:12000

10.167.0.0/19,name=pool1

10.167.32.0/21,name=pool1

10.167.40.0/22,name=pool1

10.167.44.0/24,name=pool1

10.167.45.0/24,name=pool1

10.167.46.0-223,name=pool1

10.168.0.0/23,name=pool1

10.169.3.1-255,name=pool1

10.170.0.0/16,name=pool1

[log] log-file=/var/log/accel-ppp/accel-ppp.log log-emerg=/var/log/accel-ppp/emerg.log log-fail-file=/var/log/accel-ppp/auth-fail.log log-debug=/var/log/accel-ppp/debug.log

log-debug=/dev/stdout

syslog=accel-pppd,daemon

log-tcp=127.0.0.1:3000

copy=1

color=1

per-user-dir=per_user

per-session-dir=per_session

per-session=1

level=5 <--debug mode, 3 is normal

level=3

[log-pgsql] conninfo=user=log log-table=log

[pppd-compat]

ip-pre-up=/etc/ppp/ip-pre-up

ip-up=/etc/ppp/ip-up

ip-down=/etc/ppp/ip-down

ip-change=/etc/ppp/ip-change

radattr-prefix=/var/run/radattr

verbose=1

[chap-secrets]

gw-ip-address=192.168.100.1

chap-secrets=/etc/ppp/chap-secrets

encrypted=0

username-hash=md5

[pap-secrets] pap-secrets=/etc/ppp/pap-secrets

[shaper]

attr=Filter-Id

down-burst-factor=0.1

up-burst-factor=1.0

latency=50

mpu=0

mtu=0

r2q=10

quantum=1500

moderate-quantum=1

cburst=1534

ifb=ifb0

up-limiter=police

down-limiter=tbf

leaf-qdisc=sfq perturb 10

leaf-qdisc=fq_codel [limit PACKETS] [flows NUMBER] [target TIME] [interval TIME] [quantum BYTES] [[no]ecn]

rate-multiplier=1

fwmark=1

verbose=1

[cli] verbose=1 telnet=127.0.0.1:2000 tcp=127.0.0.1:2001

password=123

[snmp] master=0 agent-name=accel-ppp

[connlimit]

limit=5/min

limit=150/s burst=3 timeout=30

[ipv6-pool]

fc00:0:1::/48,64

delegate=fc00:1::/36,48

[ipv6-dns]

2001::8888

fc00:1::1

fc00:1::2

fc00:1::3

dnssl=suffix1.local.net

dnssl=suffix2.local.net.

[ipv6-dhcp]

verbose=1

pref-lifetime=604800

valid-lifetime=2592000

route-via-gw=1

[accel-dp] socket=/var/run/accel-dp.sock

[DmitriyEshenko]

Cannot reproduce with your config. Why Accounting-Request without Acct-Status-Type? You are modified code or log output?

[rudinyu]

1. We use N2X to do stress testing.
2. We don't modify code, do you have any suggestions about the value of Acct-Status-Type.

Thanks

[rudinyu]

We found if radius request more this setting (req-limit=400), it will happen session leak.

[rudinyu]

In rad_server_req_exit function, I have a question if serv->req_cnt big than serv->req_limit, why we don't do anything.