Не удаляется маршрут после завершении "быстрой" сессии

Bug reports
Post Reply
xlr
Posts: 4
Joined: 20 Feb 2018, 14:15

Не удаляется маршрут после завершении "быстрой" сессии

Post by xlr »

Доброго времени суток!

имеются сервера с NAT'ом и динамической маршрутизацией по ospf, клиенты подключаются по pppoe, на каждом сервере до 2000 клиентов, столкнулся с такой проблемой:

иногда клиент создаёт и разрывает сессию буквально за долю секунды, в следствии чего маршрут c ip адресом клиента успевает разойтись на остальные сервера, но, на сервере к которому клиент подключался маршрута нет, и дальше клиент не может подключиться так как исходя из маршрута, радиус думает что он уже подключён(проверка по маршруту для предотвращения подключений к нескольким серверам pppoe ). Лечится перезагрузкой ospf.

Версия accel-ppp: 1.11.2
система: CentOS Linux release 7.4.1708 (Core)
ядро: 3.10.0-693.17.1.el7.x86_64

лог подключения такого клиента:

Code: Select all


[2018-02-19 18:59:49]:  info: enp1s0f1.426: recv [PPPoE PADI 00:1d:92:ed:9c:05 => ff:ff:ff:ff:ff:ff sid=0000 <Service-Name > <Host-Uniq 020000000000000003000000>]
[2018-02-19 18:59:49]:  info: enp1s0f1.426: send [PPPoE PADO 00:1b:21:50:59:89 => 00:1d:92:ed:9c:05 sid=0000 <AC-Name pppoetest.osnova.tv> <Service-Name > <AC-Cookie 1ff5fd94e8477001d4da6c62873b20660c081ce7f86f96a2> <Host-Uniq 020000000000000003000000>]
[2018-02-19 18:59:49]:  info: enp1s0f1.426: recv [PPPoE PADR 00:1d:92:ed:9c:05 => 00:1b:21:50:59:89 sid=0000 <Service-Name > <Host-Uniq 020000000000000004000000> <AC-Cookie 1ff5fd94e8477001d4da6c62873b20660c081ce7f86f96a2>]
[2018-02-19 18:59:49]:  info: enp1s0f1.426: send [PPPoE PADS 00:1b:21:50:59:89 => 00:1d:92:ed:9c:05 sid=0a80 <AC-Name pppoetest.osnova.tv> <Service-Name > <Host-Uniq 020000000000000004000000>]
[2018-02-19 18:59:49]: debug: enp1s0f1.426: lcp_layer_init
[2018-02-19 18:59:49]: debug: enp1s0f1.426: auth_layer_init
[2018-02-19 18:59:49]: debug: enp1s0f1.426: ccp_layer_init
[2018-02-19 18:59:49]: debug: enp1s0f1.426: ipcp_layer_init
[2018-02-19 18:59:49]: debug: enp1s0f1.426: ipv6cp_layer_init
[2018-02-19 18:59:49]: debug: enp1s0f1.426: ppp establishing
[2018-02-19 18:59:49]: debug: enp1s0f1.426: lcp_layer_start
[2018-02-19 18:59:49]:  info: enp1s0f1.426: send [LCP ConfReq id=1 <auth MSCHAP-v2> <mru 1492> <magic 40cc078f>]
[2018-02-19 18:59:49]:  info: enp1s0f1.426: recv [LCP ConfReq id=0 <mru 1480> <magic 31d2397b> <pcomp> <accomp> < d 3 6 >]
[2018-02-19 18:59:49]:  info: enp1s0f1.426: send [LCP ConfRej id=0  <pcomp> <accomp> < d 3 6 >]
[2018-02-19 18:59:49]:  info: enp1s0f1.426: recv [LCP ConfReq id=1 <mru 1480> <magic 31d2397b>]
[2018-02-19 18:59:49]:  info: enp1s0f1.426: send [LCP ConfAck id=1 ]
[2018-02-19 18:59:52]: debug: enp1s0f1.426: fsm timeout 9
[2018-02-19 18:59:52]:  info: enp1s0f1.426: send [LCP ConfReq id=1 <auth MSCHAP-v2> <mru 1492> <magic 40cc078f>]
[2018-02-19 18:59:52]:  info: enp1s0f1.426: recv [LCP ConfAck id=1 <auth MSCHAP-v2> <mru 1492> <magic 40cc078f>]
[2018-02-19 18:59:52]: debug: enp1s0f1.426: lcp_layer_started
[2018-02-19 18:59:52]: debug: enp1s0f1.426: auth_layer_start
[2018-02-19 18:59:52]:  info: enp1s0f1.426: send [MSCHAP-v2 Challenge id=1 <421e85f8f458a4e9e1e545e9bae4f21>]
[2018-02-19 18:59:52]:  info: enp1s0f1.426: recv [LCP Ident id=2 <MSRASV5.20>]
[2018-02-19 18:59:52]:  info: enp1s0f1.426: recv [LCP Ident id=3 <MSRAS-0-JIAMEP-PC>]
[2018-02-19 18:59:52]:  info: enp1s0f1.426: recv [LCP Ident id=4 <3�����H��CzL��]
[2018-02-19 18:59:52]:  info: enp1s0f1.426: recv [MSCHAP-v2 Response id=1 <1b5d73fee728788d62a14621dcdf8849>, <c9d0aec95169306a79ed98d6314531e62bfe9dacf7cf4f2a>, F=0, name="home27711"]
[2018-02-19 18:59:52]:  info: enp1s0f1.426: send [RADIUS(3) Access-Request id=1 <User-Name "home27711"> <NAS-Identifier "172.16.1.115"> <NAS-IP-Address 172.16.1.115> <NAS-Port-Type Virtual> <Service-Type Framed-User> <Framed-Protocol PPP> <Calling-Station-Id "00:1d:92:ed:9c:05"> <Called-Station-Id "00:1b:21:50:59:89"><Microsoft MS-CHAP-Challenge ><Microsoft MS-CHAP2-Response >]
[2018-02-19 18:59:52]:  info: enp1s0f1.426: recv [RADIUS(3) Access-Accept id=1 <Filter-Id "pppoe 100000000 100000000"><Microsoft MS-CHAP2-Success > <Service-Type Framed-User> <Framed-IP-Address 172.16.64.214> <Framed-IP-Netmask 255.255.255.255>]
[2018-02-19 18:59:52]:  info: ppp494: connect: ppp494 <--> pppoe(00:1d:92:ed:9c:05)
[2018-02-19 18:59:52]: debug: ppp494: ppp connected
[2018-02-19 18:59:52]:  info: ppp494: send [MSCHAP-v2 Success id=1 "S=24D8C88DF3A210564C280CE63C92BBD31E70808F M=Authentication succeeded"]
[2018-02-19 18:59:52]: debug: ppp494: auth_layer_started
[2018-02-19 18:59:52]: debug: ppp494: ccp_layer_start
[2018-02-19 18:59:52]: debug: ppp494: ipcp_layer_start
[2018-02-19 18:59:52]:  info: ppp494: send [IPCP ConfReq id=1 <addr 172.20.1.254>]
[2018-02-19 18:59:52]: debug: ppp494: ipv6cp_layer_start
[2018-02-19 18:59:52]:  info: ppp494: home27711: authentication succeeded
[2018-02-19 18:59:52]:  warn: ppp494: IPV6CP: discarding packet
[2018-02-19 18:59:52]:  info: ppp494: send [LCP ProtoRej id=3 <8057>]
[2018-02-19 18:59:52]:  info: ppp494: recv [CCP ConfReq id=6 <mppe -H -M -S -L -D -C>]
[2018-02-19 18:59:52]:  info: ppp494: send [CCP ConfReq id=1]
[2018-02-19 18:59:52]:  info: ppp494: send [CCP ConfRej id=6 <mppe -H -M -S -L -D -C>]
[2018-02-19 18:59:52]:  info: ppp494: recv [IPCP ConfReq id=7 <addr 0.0.0.0> <dns1 0.0.0.0> <wins1 0.0.0.0> <dns2 0.0.0.0> <wins2 0.0.0.0>]
[2018-02-19 18:59:52]:  info: ppp494: send [IPCP ConfNak id=7 <addr 172.16.64.214> <dns1 193.151.107.98> <dns2 193.151.107.111>]
[2018-02-19 18:59:52]:  info: ppp494: recv [IPCP ConfAck id=1 <addr 172.20.1.254>]
[2018-02-19 18:59:52]:  info: ppp494: recv [CCP ConfAck id=1]
[2018-02-19 18:59:52]:  info: ppp494: recv [CCP TermReq id=8]
[2018-02-19 18:59:52]:  info: ppp494: send [CCP TermAck id=8]
[2018-02-19 18:59:52]:  info: ppp494: send [CCP TermReq id=3]
[2018-02-19 18:59:52]:  info: ppp494: recv [IPCP ConfReq id=9 <addr 172.16.64.214> <dns1 1.1.1.1> <wins1 0.0.0.0> <dns2 2.2.2.2> <wins2 0.0.0.0>]
[2018-02-19 18:59:52]:  info: ppp494: send [IPCP TermAck id=9]
[2018-02-19 18:59:52]:  info: ppp494: recv [CCP TermAck id=3]
[2018-02-19 18:59:52]: debug: ppp494: ccp_layer_finished
[2018-02-19 18:59:54]:  info: ppp494: recv [IPCP ConfReq id=a <addr 172.16.64.214> <dns1 1.1.1.1> <wins1 0.0.0.0> <dns2 2.2.2.2> <wins2 0.0.0.0>]
[2018-02-19 18:59:54]: debug: ppp494: ipcp_layer_started
[2018-02-19 18:59:54]:  info: ppp494: send [RADIUS(3) Accounting-Request id=1 <User-Name "home27711"> <NAS-Identifier "172.16.1.115"> <NAS-IP-Address 172.16.1.115> <NAS-Port 494> <NAS-Port-Id "ppp494"> <NAS-Port-Type Virtual> <Service-Type Framed-User> <Framed-Protocol PPP> <Calling-Station-Id "00:1d:92:ed:9c:05"> <Called-Station-Id "00:1b:21:50:59:89"> <Acct-Status-Type Start> <Acct-Authentic RADIUS> <Acct-Session-Id "9d934095df2bbb48"> <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> <Framed-IP-Address 172.16.64.214>]
[2018-02-19 18:59:54]:  info: ppp494: send [IPCP ConfAck id=a]
[2018-02-19 18:59:54]:  info: ppp494: recv [RADIUS(3) Accounting-Response id=1]
[2018-02-19 18:59:54]: debug: ppp494: pppoe: ppp started
[2018-02-19 18:59:54]:  info: ppp494: pppd_compat: ip-up started (pid 5520)
[2018-02-19 18:59:54]:  info: enp1s0f1.426: recv [PPPoE PADT 00:1d:92:ed:9c:05 => 00:1b:21:50:59:89 sid=0a80]
[2018-02-19 18:59:54]: debug: ppp494: terminate
[2018-02-19 18:59:54]:  info: ppp494: send [RADIUS(3) Accounting-Request id=1 <User-Name "home27711"> <NAS-Identifier "172.16.1.115"> <NAS-IP-Address 172.16.1.115> <NAS-Port 494> <NAS-Port-Id "ppp494"> <NAS-Port-Type Virtual> <Service-Type Framed-User> <Framed-Protocol PPP> <Calling-Station-Id "00:1d:92:ed:9c:05"> <Called-Station-Id "00:1b:21:50:59:89"> <Acct-Status-Type Stop> <Acct-Authentic RADIUS> <Acct-Session-Id "9d934095df2bbb48"> <Acct-Session-Time 6> <Acct-Input-Octets 322> <Acct-Output-Octets 207> <Acct-Input-Packets 12> <Acct-Output-Packets 9> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Framed-IP-Address 172.16.64.214> <Acct-Terminate-Cause User-Request>]
[2018-02-19 18:59:54]:  warn: ppp494: pppd_compat: ip-up is not yet finished, terminating it ...
[2018-02-19 18:59:54]:  info: ppp494: pppd_compat: ip-down started (pid 5538)
[2018-02-19 18:59:54]:  info: ppp494: pppd_compat: ip-up finished (0)
[2018-02-19 18:59:54]:  info: ppp494: pppd_compat: ip-down finished (0)
[2018-02-19 18:59:54]: debug: ppp494: pppoe: ppp finished
[2018-02-19 18:59:54]: debug: ppp494: lcp_layer_free
[2018-02-19 18:59:54]: debug: ppp494: auth_layer_free
[2018-02-19 18:59:54]: debug: ppp494: ccp_layer_free
[2018-02-19 18:59:54]: debug: ppp494: ipcp_layer_free
[2018-02-19 18:59:54]: debug: ppp494: ipv6cp_layer_free
[2018-02-19 18:59:54]: debug: ppp494: ppp destablished
[2018-02-19 18:59:54]:  info: enp1s0f1.426: send [PPPoE PADT 00:1b:21:50:59:89 => 00:1d:92:ed:9c:05 sid=0a80 <AC-Name pppoetest.osnova.tv> <Service-Name >]
[2018-02-19 18:59:54]:  info: ppp494: disconnected
пробовал на ядре 4.4.115 ситуация такая же, но более частая.

-------------------------------------------------------------------------------------------------------------------
Другая ситуация:
при попытке подключиться под пользователем который уже подключён, радиус выдаёт ошибку 7023, accel-ppp после версии 1.8.0(может и позже) перестал корректно передавать код ошибки:

accel-ppp v 1.8.0

Code: Select all

[2018-02-20 11:12:10]:  info: ppp14: recv [RADIUS(2) Access-Reject id=1 <Reply-Message "already connected to PPPoE25"><Microsoft MS-CHAP-Error "E=7023 R=0 V=3">]
[2018-02-20 11:12:10]:  info: ppp14: send [MSCHAP-v2 Failure id=1 "E=7023 R=0 V=3 M=already connected to PPPoE25"]

accel-ppp v 1.11.2

Code: Select all

[2018-02-16 21:50:54]:  info: enp1s0f1.432: recv [RADIUS(2) Access-Reject id=1 <Reply-Message "already connected to PPPoE29"><Microsoft MS-CHAP-Error "E=7023 R=0 V=3">]
[2018-02-16 21:50:54]:  info: enp1s0f1.432: send [MSCHAP-v2 Failure id=1 "E=691 R=0 V=3 M=Authentication failure"] 
в версии 1.11.2 accel отдаёт пользователю ошибку 691 вместо 7023.
Dmitry
Администратор
Posts: 954
Joined: 09 Oct 2014, 10:06

Re: Не удаляется маршрут после завершении "быстрой" сессии

Post by Dmitry »

привет
это баг ospf, средствами accel-ppp не лечится
или предлагаешь искусственно продлять сессию ?
xlr
Posts: 4
Joined: 20 Feb 2018, 14:15

Re: Не удаляется маршрут после завершении "быстрой" сессии

Post by xlr »

Привет!

к сожалению логов ospf не делал, по логам zebra видно что маршрут удалился

Code: Select all

2018/02/20 17:54:11 ZEBRA: MESSAGE: ZEBRA_INTERFACE_ADD ppp355
2018/02/20 17:54:11 ZEBRA: interface ppp355 index 8288 becomes active.
2018/02/20 17:54:11 ZEBRA: interface ppp355 index 8288 is now inactive.
2018/02/20 17:54:11 ZEBRA: MESSAGE: ZEBRA_INTERFACE_DELETE ppp355
2018/02/20 17:54:18 ZEBRA: MESSAGE: ZEBRA_INTERFACE_ADD ppp355
2018/02/20 17:54:18 ZEBRA: interface ppp355 index 8289 becomes active.
2018/02/20 17:54:18 ZEBRA: netlink_interface_addr RTM_NEWADDR ppp355:
2018/02/20 17:54:18 ZEBRA: warning: PtP interface ppp355 with addr 172.20.1.254/32 needs a peer address
2018/02/20 17:54:18 ZEBRA: MESSAGE: ZEBRA_INTERFACE_ADDRESS_ADD 172.20.1.254/32 on ppp355
2018/02/20 17:54:18 ZEBRA: netlink_interface_addr RTM_DELADDR ppp355:
2018/02/20 17:54:18 ZEBRA: MESSAGE: ZEBRA_INTERFACE_ADDRESS_DELETE 172.20.1.254/32 on ppp355
2018/02/20 17:54:18 ZEBRA: netlink_interface_addr RTM_NEWADDR ppp355:
2018/02/20 17:54:18 ZEBRA:   IFA_ADDRESS   172.16.167.244/32
2018/02/20 17:54:18 ZEBRA: MESSAGE: ZEBRA_INTERFACE_ADDRESS_ADD 172.20.1.254/32 on ppp355
2018/02/20 17:54:18 ZEBRA: MESSAGE: ZEBRA_INTERFACE_UP ppp355
2018/02/20 17:54:18 ZEBRA: rib_link: 172.16.167.244/32: rn 0x55c3a53839e0, rib 0x55c3a5383a40
2018/02/20 17:54:18 ZEBRA: rib_link: 172.16.167.244/32: adding dest to table
2018/02/20 17:54:18 ZEBRA: rib_link: 172.16.167.244/32: rn 0x55c3a5383bb0, rib 0x55c3a5383c10
2018/02/20 17:54:18 ZEBRA: rib_link: 172.16.167.244/32: adding dest to table
2018/02/20 17:54:18 ZEBRA: rib_process: 172.16.167.244/32: Adding route, select 0x55c3a5383a40
2018/02/20 17:54:18 ZEBRA: rib_process: 172.16.167.244/32: Adding route, select 0x55c3a5383c10
2018/02/20 17:54:18 ZEBRA: rib_process: 172.16.167.244/32: Updating existing route, select 0x55c3a5383a40, fib 0x55c3a5383a40
2018/02/20 17:54:18 ZEBRA: MESSAGE: ZEBRA_INTERFACE_DOWN ppp355
2018/02/20 17:54:18 ZEBRA: rib_delnode: 172.16.167.244/32: rn 0x55c3a53839e0, rib 0x55c3a5383a40, removing
2018/02/20 17:54:18 ZEBRA: rib_delnode: 172.16.167.244/32: rn 0x55c3a5383bb0, rib 0x55c3a5383c10, removing
2018/02/20 17:54:18 ZEBRA: netlink_interface_addr RTM_DELADDR ppp355:
2018/02/20 17:54:18 ZEBRA:   IFA_ADDRESS   172.16.167.244/32
2018/02/20 17:54:18 ZEBRA: MESSAGE: ZEBRA_INTERFACE_ADDRESS_DELETE 172.20.1.254/32 on ppp355
2018/02/20 17:54:18 ZEBRA: route 172.16.167.244/32 ifindex 8289 type 2 doesn't exist in rib
2018/02/20 17:54:18 ZEBRA: route 172.16.167.244/32 ifindex 8289 type 2 doesn't exist in rib
2018/02/20 17:54:18 ZEBRA: rib_process: 172.16.167.244/32: Removing existing route, fib 0x55c3a5383a40
2018/02/20 17:54:18 ZEBRA: rib_process: 172.16.167.244/32: Deleting fib 0x55c3a5383a40, rn 0x55c3a53839e0
2018/02/20 17:54:18 ZEBRA: rib_unlink: 172.16.167.244/32: rn 0x55c3a53839e0, rib 0x55c3a5383a40
2018/02/20 17:54:18 ZEBRA: rib_gc_dest: 172.16.167.244/32: removing dest from table
2018/02/20 17:54:18 ZEBRA: rib_process: 172.16.167.244/32: Removing existing route, fib 0x55c3a5383c10
2018/02/20 17:54:18 ZEBRA: rib_process: 172.16.167.244/32: Deleting fib 0x55c3a5383c10, rn 0x55c3a5383bb0
2018/02/20 17:54:18 ZEBRA: rib_unlink: 172.16.167.244/32: rn 0x55c3a5383bb0, rib 0x55c3a5383c10
2018/02/20 17:54:18 ZEBRA: rib_gc_dest: 172.16.167.244/32: removing dest from table
2018/02/20 17:54:18 ZEBRA: interface ppp355 index 8289 is now inactive.
2018/02/20 17:54:18 ZEBRA: MESSAGE: ZEBRA_INTERFACE_DELETE ppp355
настрою ospf на запись логов.

пока попробую искусственно продлить сессию на 1 секунду во время завершении сессии, но когда ip-up не успел завершиться, костыль конечно ...

возможно Вы слышали о подобной проблеме с ospf и вариантах её решения?

А что по поводу ошибки с кодом 691? проблема в радиусе или код ошибки 7023 устарел и больше не используется?
Dmitry
Администратор
Posts: 954
Joined: 09 Oct 2014, 10:06

Re: Не удаляется маршрут после завершении "быстрой" сессии

Post by Dmitry »

а что в ip-up/ip-down выполняется ?
xlr
Posts: 4
Joined: 20 Feb 2018, 14:15

Re: Не удаляется маршрут после завершении "быстрой" сессии

Post by xlr »

в ip-up, да
нарезка скорости при помощи tc,ifb с делением на локальный трафик и мир
в ip-down, пустой
xlr
Posts: 4
Joined: 20 Feb 2018, 14:15

Re: Не удаляется маршрут после завершении "быстрой" сессии

Post by xlr »

перешёл на ядро 4.4.115

логи подобного случая

Code: Select all

[2018-02-22 15:46:32.549] enp1s0f1.430: 9d934095df2c9c97: lcp_layer_start
[2018-02-22 15:46:32.549] enp1s0f1.430: 9d934095df2c9c97: send [LCP ConfReq id=1 <auth MSCHAP-v2> <mru 1492> <magic 05880837>]
[2018-02-22 15:46:32.589] enp1s0f1.430: 9d934095df2c9c97: recv [LCP ConfReq id=0 <mru 1480> <magic 04067dee> <pcomp> <accomp> < d 3 6 >]
[2018-02-22 15:46:32.589] enp1s0f1.430: 9d934095df2c9c97: send [LCP ConfRej id=0  <pcomp> <accomp> < d 3 6 >]
[2018-02-22 15:46:32.612] enp1s0f1.430: 9d934095df2c9c97: recv [LCP ConfAck id=1 <auth MSCHAP-v2> <mru 1492> <magic 05880837>]
[2018-02-22 15:46:32.613] enp1s0f1.430: 9d934095df2c9c97: recv [LCP ConfReq id=1 <mru 1480> <magic 04067dee>]
[2018-02-22 15:46:32.613] enp1s0f1.430: 9d934095df2c9c97: send [LCP ConfAck id=1 ]
[2018-02-22 15:46:32.613] enp1s0f1.430: 9d934095df2c9c97: lcp_layer_started
[2018-02-22 15:46:32.613] enp1s0f1.430: 9d934095df2c9c97: auth_layer_start
[2018-02-22 15:46:32.613] enp1s0f1.430: 9d934095df2c9c97: send [MSCHAP-v2 Challenge id=1 <d1355a9d8c1748eb9611d3f02bc0cb>]
[2018-02-22 15:46:32.614] enp1s0f1.430: 9d934095df2c9c97: recv [LCP Ident id=2 <MSRASV5.20>]
[2018-02-22 15:46:32.614] enp1s0f1.430: 9d934095df2c9c97: recv [LCP Ident id=3 <MSRAS-0-DESKTOP-MKG32QP>]
[2018-02-22 15:46:32.614] enp1s0f1.430: 9d934095df2c9c97: recv [LCP Ident id=4 <Q�=ǽB�O�����n��>]
[2018-02-22 15:46:32.632] enp1s0f1.430: 9d934095df2c9c97: recv [MSCHAP-v2 Response id=1 <86beb0afa4b39953a6ed70e79cd3c73d>, <30dfe0618fc9969a98461337db3ed15345eeedf8fb3b59>, F=0, name="home36001"]
[2018-02-22 15:46:32.632] enp1s0f1.430: 9d934095df2c9c97: send [RADIUS(3) Access-Request id=1 <User-Name "home36001"> <NAS-Identifier "172.16.1.115"> <NAS-IP-Address 172.16.1.115> <NAS-Port-Type Virtual> <Service-Type Framed-User> <Framed-Protocol PPP> <Calling-Station-Id "54:04:a6:71:17:cc"> <Called-Station-Id "00:1b:21:50:59:89"><Microsoft MS-CHAP-Challenge ><Microsoft MS-CHAP2-Response >]
[2018-02-22 15:46:32.638] enp1s0f1.430: 9d934095df2c9c97: recv [RADIUS(3) Access-Accept id=1 <Filter-Id "pppoe 25000000 25000000"><Microsoft MS-CHAP2-Success > <Service-Type Framed-User> <Framed-IP-Address 172.16.125.72> <Framed-IP-Netmask 255.255.255.255>]
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: connect: ppp235 <--> pppoe(54:04:a6:71:17:cc)
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: ppp connected
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: send [MSCHAP-v2 Success id=1 "S=E66E75BA1F0DB69C6584A77CC3B2261761ADCB3E M=Authentication succeeded"]
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: auth_layer_started
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: ccp_layer_start
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: ipcp_layer_start
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: send [IPCP ConfReq id=1 <addr 172.20.1.254>]
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: ipv6cp_layer_start
[2018-02-22 15:46:32.639] ppp235: 9d934095df2c9c97: home36001: authentication succeeded
[2018-02-22 15:46:32.646] ppp235: 9d934095df2c9c97: IPV6CP: discarding packet
[2018-02-22 15:46:32.646] ppp235: 9d934095df2c9c97: send [LCP ProtoRej id=3 <8057>]
[2018-02-22 15:46:32.646] ppp235: 9d934095df2c9c97: recv [CCP ConfReq id=6 <mppe -H -M -S -L -D -C>]
[2018-02-22 15:46:32.646] ppp235: 9d934095df2c9c97: send [CCP ConfReq id=1]
[2018-02-22 15:46:32.646] ppp235: 9d934095df2c9c97: send [CCP ConfRej id=6 <mppe -H -M -S -L -D -C>]
[2018-02-22 15:46:32.646] ppp235: 9d934095df2c9c97: recv [IPCP ConfReq id=7 <addr 0.0.0.0> <dns1 0.0.0.0> <wins1 0.0.0.0> <dns2 0.0.0.0> <wins2 0.0.0.0>]
[2018-02-22 15:46:32.646] ppp235: 9d934095df2c9c97: send [IPCP ConfNak id=7 <addr 172.16.125.72> <dns1 193.151.107.98> <dns2 193.151.107.111>]
[2018-02-22 15:46:32.646] ppp235: 9d934095df2c9c97: recv [IPCP ConfAck id=1 <addr 172.20.1.254>]
[2018-02-22 15:46:32.647] ppp235: 9d934095df2c9c97: recv [CCP ConfAck id=1]
[2018-02-22 15:46:32.647] ppp235: 9d934095df2c9c97: recv [CCP TermReq id=8]
[2018-02-22 15:46:32.647] ppp235: 9d934095df2c9c97: send [CCP TermAck id=8]
[2018-02-22 15:46:32.647] ppp235: 9d934095df2c9c97: send [CCP TermReq id=3]
[2018-02-22 15:46:32.648] ppp235: 9d934095df2c9c97: recv [IPCP ConfReq id=9 <addr 172.16.125.72> <dns1 193.151.107.98> <wins1 0.0.0.0> <dns2 193.151.107.111> <wins2 0.0.0.0>]
[2018-02-22 15:46:32.648] ppp235: 9d934095df2c9c97: send [IPCP TermAck id=9]
[2018-02-22 15:46:32.650] ppp235: 9d934095df2c9c97: recv [CCP TermAck id=3]
[2018-02-22 15:46:32.650] ppp235: 9d934095df2c9c97: ccp_layer_finished
[2018-02-22 15:46:34.579] ppp235: 9d934095df2c9c97: recv [IPCP ConfReq id=a <addr 172.16.125.72> <dns1 193.151.107.98> <wins1 0.0.0.0> <dns2 193.151.107.111> <wins2 0.0.0.0>]
[2018-02-22 15:46:34.579] ppp235: 9d934095df2c9c97: ipcp_layer_started
[2018-02-22 15:46:34.579] ppp235: 9d934095df2c9c97: send [RADIUS(2) Accounting-Request id=1 <User-Name "home36001"> <NAS-Identifier "172.16.1.115"> <NAS-IP-Address 172.16.1.115> <NAS-Port 235> <NAS-Port-Id "ppp235"> <NAS-Port-Type Virtual> <Service-Type Framed-User> <Framed-Protocol PPP> <Calling-Station-Id "54:04:a6:71:17:cc"> <Called-Station-Id "00:1b:21:50:59:89"> <Acct-Status-Type Start> <Acct-Authentic RADIUS> <Acct-Session-Id "9d934095df2c9c97"> <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> <Framed-IP-Address 172.16.125.72>]
[2018-02-22 15:46:34.579] ppp235: 9d934095df2c9c97: send [IPCP ConfAck id=a]
[2018-02-22 15:46:34.580] ppp235: 9d934095df2c9c97: recv [RADIUS(2) Accounting-Response id=1]
[2018-02-22 15:46:34.580] ppp235: 9d934095df2c9c97: pppoe: ppp started
[2018-02-22 15:46:34.581] ppp235: 9d934095df2c9c97: pppd_compat: ip-up started (pid 20313)
[2018-02-22 15:46:34.603] ppp235: 9d934095df2c9c97: recv [IPCP TermReq id=b]
[2018-02-22 15:46:34.604] ppp235: 9d934095df2c9c97: ipcp_layer_down
[2018-02-22 15:46:34.604] ppp235: 9d934095df2c9c97: ipcp_layer_down
[2018-02-22 15:46:34.604] ppp235: 9d934095df2c9c97: send [IPCP TermReq id=3]
[2018-02-22 15:46:34.604] ppp235: 9d934095df2c9c97: send [IPCP TermAck id=b]
[2018-02-22 15:46:35.319] ppp235: 9d934095df2c9c97: pppd_compat: ip-up finished (0)
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: terminate
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: lcp_layer_finish
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: send [LCP TermReq id=4]
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: auth_layer_finish
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: auth_layer_finished
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: ccp_layer_finish
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: ccp_layer_finished
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: ipcp_layer_finish
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: ipcp_layer_finished
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: ipv6cp_layer_finish
[2018-02-22 15:46:35.604] ppp235: 9d934095df2c9c97: ipv6cp_layer_finished
[2018-02-22 15:46:35.607] ppp235: 9d934095df2c9c97: send [RADIUS(2) Accounting-Request id=1 <User-Name "home36001"> <NAS-Identifier "172.16.1.115"> <NAS-IP-Address 172.16.1.115> <NAS-Port 235> <NAS-Port-Id "ppp235"> <NAS-Port-Type Virtual> <Service-Type Framed-User> <Framed-Protocol PPP> <Calling-Station-Id "54:04:a6:71:17:cc"> <Called-Station-Id "00:1b:21:50:59:89"> <Acct-Status-Type Stop> <Acct-Authentic RADIUS> <Acct-Session-Id "9d934095df2c9c97"> <Acct-Session-Time 3> <Acct-Input-Octets 180> <Acct-Output-Octets 100> <Acct-Input-Packets 11> <Acct-Output-Packets 10> <Acct-Input-Gigawords 0> <Acct-Output-Gigawords 0> <Framed-IP-Address 172.16.125.72> <Acct-Terminate-Cause User-Request>]
[2018-02-22 15:46:35.607] ppp235: 9d934095df2c9c97: IPCP: discarding packet
[2018-02-22 15:46:35.607] ppp235: 9d934095df2c9c97: recv [LCP TermReq id=c]
[2018-02-22 15:46:35.607] ppp235: 9d934095df2c9c97: send [LCP TermAck id=12]
[2018-02-22 15:46:36.607] ppp235: 9d934095df2c9c97: recv [RADIUS(2) Accounting-Response id=1]
[2018-02-22 15:46:37.608] ppp235: 9d934095df2c9c97: pppd_compat: ip-down started (pid 20379)
[2018-02-22 15:46:37.610] ppp235: 9d934095df2c9c97: pppd_compat: ip-down finished (255)
[2018-02-22 15:46:37.610] ppp235: 9d934095df2c9c97: pppoe: ppp finished
[2018-02-22 15:46:37.620] ppp235: 9d934095df2c9c97: lcp_layer_free
[2018-02-22 15:46:37.620] ppp235: 9d934095df2c9c97: auth_layer_free
[2018-02-22 15:46:37.620] ppp235: 9d934095df2c9c97: ccp_layer_free
[2018-02-22 15:46:37.620] ppp235: 9d934095df2c9c97: ipcp_layer_free
[2018-02-22 15:46:37.620] ppp235: 9d934095df2c9c97: ipv6cp_layer_free
[2018-02-22 15:46:37.620] ppp235: 9d934095df2c9c97: ppp destablished
[2018-02-22 15:46:37.620] ppp235: 9d934095df2c9c97: disconnected

при чём такие сообщения только в этом случае

Code: Select all

[2018-02-22 15:46:34.603] ppp235: 9d934095df2c9c97: recv [IPCP TermReq id=b]
[2018-02-22 15:46:34.604] ppp235: 9d934095df2c9c97: ipcp_layer_down
[2018-02-22 15:46:34.604] ppp235: 9d934095df2c9c97: ipcp_layer_down
[2018-02-22 15:46:34.604] ppp235: 9d934095df2c9c97: send [IPCP TermReq id=3]
[2018-02-22 15:46:34.604] ppp235: 9d934095df2c9c97: send [IPCP TermAck id=b]
[2018-02-22 15:46:35.607] ppp235: 9d934095df2c9c97: IPCP: discarding packet
на ~700 подключений таких сообщений не было.
Post Reply