Трассировка процесса соединения
Успех процесса поиска неисправности практически всегда основывается на знании процесса установки соединения и умении использовать инструменты отладки. Далее рассмотрим процесс установки соединения с использованием команды debug с различными опциями. Первым этапом в установке соединения идет установка pppoe сессии. Ниже приведен процесс установки сессии с вырезками из вывода debug-команд:
debug pppoe events
Nov 2 07:38:12.495: PPPoE 0: I PADI R:0800.27da.d2e0 L:ffff.ffff.ffff Fa0/0
*Nov 2 07:38:12.495: Service tag: NULL Tag
*Nov 2 07:38:12.495: PPPoE 0: O PADO, R:0019.56d6.d5f4 L:0800.27da.d2e0 Fa0/0
*Nov 2 07:38:12.495: Service tag: NULL Tag
*Nov 2 07:38:12.495: PPPoE 0: I PADR R:0800.27da.d2e0 L:0019.56d6.d5f4 Fa0/0
*Nov 2 07:38:12.495: Service tag: NULL Tag
*Nov 2 07:38:12.495: PPPoE : encap string prepared
*Nov 2 07:38:12.495: [5]PPPoE 5: Access IE handle allocated
*Nov 2 07:38:12.495: [5]PPPoE 5: pppoe SSS switch updated
*Nov 2 07:38:12.495: [5]PPPoE 5: AAA get retrieved attrs
*Nov 2 07:38:12.495: [5]PPPoE 5: AAA get nas port details
*Nov 2 07:38:12.495: [5]PPPoE 5: AAA get dynamic attrs
*Nov 2 07:38:12.495: [5]PPPoE 5: AAA get dynamic attrs
*Nov 2 07:38:12.495: [5]PPPoE 5: AAA unique ID allocated
*Nov 2 07:38:12.499: [5]PPPoE 5: No AAA accounting method list
*Nov 2 07:38:12.499: [5]PPPoE 5: Service request sent to SSS
*Nov 2 07:38:12.499: [5]PPPoE 5: Created, Service: None R:0019.56d6.d5f4 L:0800.27da.d2e00
*Nov 2 07:38:12.499: [5]PPPoE 5: State NAS_PORT_POLICY_INQUIRY Event SSS_LOCAL
*Nov 2 07:38:12.499: [5]PPPoE 5: O PADS R:0800.27da.d2e0 L:0019.56d6.d5f4 Fa0/0
*Nov 2 07:38:12.499: [5]PPPoE 5: State PPP_START Event DYN_BIND
*Nov 2 07:38:12.499: [5]PPPoE 5: data path set to PPP
*Nov 2 07:38:12.571: [5]PPPoE 5: State LCP_NEGOTIATION Event PPP_LOCAL
*Nov 2 07:38:12.571: PPPoE 5/SB: Sent vtemplate request on base Vi1
*Nov 2 07:38:12.575: [5]PPPoE 5: State VACCESS_REQUESTED Event VA_RESP
*Nov 2 07:38:12.575: [5]PPPoE 5: Vi1.1 interface obtained
*Nov 2 07:38:12.575: [5]PPPoE 5: State PTA_BINDING Event STAT_BIND
*Nov 2 07:38:12.575: [5]PPPoE 5: data path set to Virtual Acess
*Nov 2 07:38:12.575: [5]PPPoE 5: Connected PTA
*Nov 2 07:38:12.579: [5]PPPoE 5: AAA get dynamic attrs
*Nov 2 07:38:12.579: [5]PPPoE 5: AAA get dynamic attrs
debug pppoe packets:
*Nov 2 07:39:46.999: PPPoE 0: I PADI R:0800.27da.d2e0 L:ffff.ffff.ffff Fa0/0
FF FF FF FF FF FF 08 00 27 DA D2 E0 88 63 11 09
00 00 00 10 01 01 00 00 01 03 00 08 02 00 00 00 …
*Nov 2 07:39:46.999: PPPoE 0: O PADO, R:0019.56d6.d5f4 L:0800.27da.d2e0 Fa0/0
*Nov 2 07:39:46.999: Service tag: NULL Tag
08 00 27 DA D2 E0 00 19 56 D6 D5 F4 88 63 11 07
00 00 00 31 01 01 00 00 01 03 00 08 02 00 00 00 …
*Nov 2 07:39:47.003: PPPoE 0: I PADR R:0800.27da.d2e0 L:0019.56d6.d5f4 Fa0/0
00 19 56 D6 D5 F4 08 00 27 DA D2 E0 88 63 11 19
00 00 00 24 01 01 00 00 01 03 00 08 02 00 00 00 …
*Nov 2 07:39:47.003: [6]PPPoE 6: O PADS R:0800.27da.d2e0 L:0019.56d6.d5f4 Fa0/0
08 00 27 DA D2 E0 00 19 56 D6 D5 F4 88 63 11 65
00 06 00 24 01 01 00 00 01 03 00 08 02 00 00 00 …
Теперь подробнее о debug pppoe events:
*Nov 2 07:39:46.999: PPPoE 0: I PADI R:0800.27da.d2e0 L:ffff.ffff.ffff Fa0/0
Говорит на что-то откуда-то приходит на интерфейс FastEthernet0/0. Теперь разберемся что, куда и зачем.
debug pppoe pack
Первым шагом PPPoE клиент рассылает PADI(PPPoE Active Discovery Initiation) пакеты целью обнаружения PPPoE серверов (очень схоже с работой DHCP). Пакет посылается клиентом на широковещательный адрес: FF FF FF FF FF FF. Так же здесь же можно видеть mac адрес клиента, который подключается — 0800.27da.d2e0. После того как PPPoE сервер получает запрос PADI, который он может обслуживать, сервер посылает PADO (PPPoE Active Discovery Offer) пакет, так сказать, предлагая свои услуги. В результате чего сервере доступа видно следующее:
debug pppoe packets:
*Nov 2 07:39:46.999: PPPoE 0: O PADO, R:0019.56d6.d5f4 L:0800.27da.d2e0 Fa0/0
*Nov 2 07:39:46.999: Service tag: NULL Tag
08 00 27 DA D2 E0 00 19 56 D6 D5 F4 88 63 11 07
00 00 00 31 01 01 00 00 01 03 00 08 02 00 00 00 …
О PADO – говорит о том что пакет PADO был исходящий (О=Output). R:0019.56d6.d5f4 L:0800.27da.d2e0 – указывает mac удаленного сервера(R=remote) и локального интерфейса, через который был получен пакет. При получении PADO пакета, клиент выбирает сервер с которым будет работать (так как PADI был отправлен широковещательно, то может придти несколько PADO), и отправляет PADR (PPPoE Active Discovery Request). Данный пакет уже отправляется на unicast адрес, взятый из PADO:
*Nov 2 07:39:47.003: PPPoE 0: I PADR R:0800.27da.d2e0 L:0019.56d6.d5f4 Fa0/0
00 19 56 D6 D5 F4 08 00 27 DA D2 E0 88 63 11 19
00 00 00 24 01 01 00 00 01 03 00 08 02 00 00 00 …
Когда сервер PPPoE получает PADR, он генерирует уникальный ключ PPPoE сессии и отвечает клиенту путем передачи PADS (PPPoE Active Discovery Session-confirmation):
*Nov 2 07:39:47.003: [6]PPPoE 6: O PADS R:0800.27da.d2e0 L:0019.56d6.d5f4 Fa0/0
08 00 27 DA D2 E0 00 19 56 D6 D5 F4 88 63 11 65
00 06 00 24 01 01 00 00 01 03 00 08 02 00 00 00 …
Из вышеприведенной строки, видно, что сессии был присвоен номер 6, этот номер и будет далее вставляться во все пакеты до тех пор, пока PPPoE сессия не будет терминирована. Этот же ID будет показан в выводе команды show pppoe session:
pppoe-nas#sh pppoe session
1 session in LOCALLY_TERMINATED (PTA) State
1 session total
Uniq ID PPPoE RemMAC Port Source VA State
SID LocMAC VA-st
6 6 0800.27da.d2e0 Fa0/0 Vt1 Vi1.1 PTA
0019.56d6.d5f4 UP
В колонке VA-St можно увидеть значение UP – это означает, что PPPoE сессия установлена. После того как, будет поднята PPPoE сессия, начнется процесс установки PPP соединения, который будет проходить в стандартном режиме.
Отладка
Перед началом настройки PPPoE рекомендуется проверить версию IOS, проверить физическое соединение модема с сетью.
Шаг 1: Если после того, как маршрутизатор был полностью сконфигурирован, и соединение не поднялось, в первую очередь необходимо проверить физическое соединение маршрутизатора и физическое соединение с модемом, работает ли модем, индикацию на СРЕ устройстве со стороны клиента. Только после проверки наличия физической связи следует приступать к проверке правильности настроек маршрутизатора.
Шаг 2: Проверили физическое соединение, проверили настройки, теперь можно приступать к проверке 2-го уровня. Здесь уже понадобится умение разбираться в выводе debug и show команд. Первое с чего следует начать – это проверка, есть ли связь между сервером PPPoE и клиентским устройством. При работе с сервером доступа рекомендуется использовать команду debug pppoe events, так как она имеет более дружественный вывод.
Предположим первую ситуацию, когда debug выдает повторяющиеся через некоторое время строки типа:
debug pppoe events
*Nov 2 07:38:12.495: PPPoE 0: I PADI R:0800.27da.d2e0 L:ffff.ffff.ffff Fa0/0
*Nov 2 07:38:12.495: Service tag: NULL Tag
или
debug pppoe packets
pppoe-nas#
*Nov 2 07:39:46.999: PPPoE 0: I PADI R:0800.27da.d2e0 L:ffff.ffff.ffff Fa0/0
FF FF FF FF FF FF 08 00 27 DA D2 E0 88 63 11 09
00 00 00 10 01 01 00 00 01 03 00 08 02 00 00 00 …
Это означает, что PADI пакеты не доходят до PPPoE сервера. В данном случае рекомендуется ещё раз проверить соединение на физическом уровне, и если не выявлено никаких проблем, то проверить настройки vlan.
Шаг 3: Наиболее часто встречаемые проблемы при установке PPP соединения лежат в несоответствии типа аутентификации или неправильно заданных имени пользователя или пароля.
Первым примером рассмотрим ситуацию, когда произошла ошибка в выборе метода аутентификации CHAP или PAP (согласование метода происходит в 1 фазе установки соединения). Предположим, что с клиентской стороны настроен на метод PAP. При данной ошибке, в отличие от ошибки в пароле или пользователе, можно на основании вывода debug команд произвести нужные изменения в настройках клиентского устройства. Рассмотрим вывод команды debug ppp negotiation:
pppoe-nas#
*Nov 2 08:01:04.643: ppp15 PPP: Send Message[Dynamic Bind Response]
*Nov 2 08:01:04.643: ppp15 PPP: Using vpn set call direction
*Nov 2 08:01:04.643: ppp15 PPP: Treating connection as a callin
*Nov 2 08:01:04.643: ppp15 PPP: Session handle[57000011] Session id[15]
*Nov 2 08:01:04.643: ppp15 PPP: Phase is ESTABLISHING, Passive Open
*Nov 2 08:01:04.643: ppp15 LCP: State is Listen
*Nov 2 08:01:04.659: ppp15 LCP: I CONFREQ [Listen] id 0 len 17
*Nov 2 08:01:04.659: ppp15 LCP: MRU 1480 (0x010405C8)
*Nov 2 08:01:04.659: ppp15 LCP: MagicNumber 0x010A4CCA (0x0506010A4CCA)
*Nov 2 08:01:04.659: ppp15 LCP: Callback 6 (0x0D0306)
*Nov 2 08:01:04.659: ppp15 LCP: O CONFREQ [Listen] id 1 len 19
*Nov 2 08:01:04.659: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.659: ppp15 LCP: AuthProto CHAP (0x0305C22305)
*Nov 2 08:01:04.659: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.659: ppp15 LCP: O CONFREJ [Listen] id 0 len 7
*Nov 2 08:01:04.659: ppp15 LCP: Callback 6 (0x0D0306)
*Nov 2 08:01:04.659: ppp15 LCP: I CONFNAK [REQsent] id 1 len 8
*Nov 2 08:01:04.659: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.659: ppp15 LCP: O CONFREQ [REQsent] id 2 len 19
*Nov 2 08:01:04.659: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.659: ppp15 LCP: AuthProto MS-CHAP (0x0305C22380)
*Nov 2 08:01:04.659: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.663: ppp15 LCP: I CONFREQ [REQsent] id 1 len 14
*Nov 2 08:01:04.663: ppp15 LCP: MRU 1480 (0x010405C8)
*Nov 2 08:01:04.663: ppp15 LCP: MagicNumber 0x010A4CCA (0x0506010A4CCA)
*Nov 2 08:01:04.663: ppp15 LCP: O CONFNAK [REQsent] id 1 len 8
*Nov 2 08:01:04.663: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.671: ppp15 LCP: I CONFNAK [REQsent] id 2 len 8
*Nov 2 08:01:04.671: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.671: ppp15 LCP: O CONFREQ [REQsent] id 3 len 19
*Nov 2 08:01:04.671: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.671: ppp15 LCP: AuthProto CHAP (0x0305C22305)
*Nov 2 08:01:04.671: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.671: ppp15 LCP: I CONFREQ [REQsent] id 2 len 14
*Nov 2 08:01:04.671: ppp15 LCP: MRU 1480 (0x010405C8)
*Nov 2 08:01:04.671: ppp15 LCP: MagicNumber 0x010A4CCA (0x0506010A4CCA)
*Nov 2 08:01:04.671: ppp15 LCP: O CONFNAK [REQsent] id 2 len 8
*Nov 2 08:01:04.671: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.679: ppp15 LCP: I CONFNAK [REQsent] id 3 len 8
*Nov 2 08:01:04.679: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.679: ppp15 LCP: O CONFREQ [REQsent] id 4 len 19
*Nov 2 08:01:04.679: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.679: ppp15 LCP: AuthProto MS-CHAP (0x0305C22380)
*Nov 2 08:01:04.679: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.711: ppp15 LCP: I CONFREQ [REQsent] id 3 len 14
*Nov 2 08:01:04.711: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.711: ppp15 LCP: MagicNumber 0x010A4CCA (0x0506010A4CCA)
*Nov 2 08:01:04.711: ppp15 LCP: O CONFACK [REQsent] id 3 len 14
*Nov 2 08:01:04.711: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.711: ppp15 LCP: MagicNumber 0x010A4CCA (0x0506010A4CCA)
*Nov 2 08:01:04.723: ppp15 LCP: I CONFNAK [ACKsent] id 4 len 8
*Nov 2 08:01:04.723: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.723: ppp15 LCP: O CONFREQ [ACKsent] id 5 len 19
*Nov 2 08:01:04.723: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.723: ppp15 LCP: AuthProto CHAP (0x0305C22305)
*Nov 2 08:01:04.723: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.731: ppp15 LCP: I CONFNAK [ACKsent] id 5 len 8
*Nov 2 08:01:04.731: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.731: ppp15 LCP: O CONFREQ [ACKsent] id 6 len 19
*Nov 2 08:01:04.731: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.731: ppp15 LCP: AuthProto MS-CHAP (0x0305C22380)
*Nov 2 08:01:04.731: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.739: ppp15 LCP: I CONFNAK [ACKsent] id 6 len 8
*Nov 2 08:01:04.739: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.739: ppp15 LCP: O CONFREQ [ACKsent] id 7 len 19
*Nov 2 08:01:04.739: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.739: ppp15 LCP: AuthProto CHAP (0x0305C22305)
*Nov 2 08:01:04.739: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.751: ppp15 LCP: I CONFNAK [ACKsent] id 7 len 8
*Nov 2 08:01:04.751: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.751: ppp15 LCP: O CONFREQ [ACKsent] id 8 len 19
*Nov 2 08:01:04.751: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.751: ppp15 LCP: AuthProto MS-CHAP (0x0305C22380)
*Nov 2 08:01:04.751: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.759: ppp15 LCP: I CONFNAK [ACKsent] id 8 len 8
*Nov 2 08:01:04.759: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.759: ppp15 LCP: O CONFREQ [ACKsent] id 9 len 19
*Nov 2 08:01:04.759: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.759: ppp15 LCP: AuthProto CHAP (0x0305C22305)
*Nov 2 08:01:04.759: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.771: ppp15 LCP: I CONFNAK [ACKsent] id 9 len 8
*Nov 2 08:01:04.771: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.771: ppp15 LCP: O CONFREQ [ACKsent] id 10 len 19
*Nov 2 08:01:04.771: ppp15 LCP: MRU 1492 (0x010405D4)
*Nov 2 08:01:04.771: ppp15 LCP: AuthProto MS-CHAP (0x0305C22380)
*Nov 2 08:01:04.771: ppp15 LCP: MagicNumber 0x1D33F9D9 (0x05061D33F9D9)
*Nov 2 08:01:04.779: ppp15 LCP: I CONFNAK [ACKsent] id 10 len 8
*Nov 2 08:01:04.779: ppp15 LCP: AuthProto PAP (0x0304C023)
*Nov 2 08:01:04.779: ppp15 LCP: Failed to negotiate with peer
*Nov 2 08:01:04.779: ppp15 PPP: Sending Acct Event[Down] id[15]
*Nov 2 08:01:04.779: ppp15 LCP: O TERMREQ [ACKsent] id 11 len 4
*Nov 2 08:01:04.779: ppp15 PPP: Phase is TERMINATING
*Nov 2 08:01:04.791: ppp15 LCP: I TERMACK [TERMsent] id 11 len 4
*Nov 2 08:01:04.791: ppp15 LCP: State is Closed
*Nov 2 08:01:04.791: ppp15 PPP: Phase is DOWN
*Nov 2 08:01:04.791: ppp15 PPP: Send Message[Disconnect]
*Nov 2 08:01:04.771: ppp15 LCP: AuthProto PAP (0x0304C023) – означает что поступил запрос содержащий в себе параметры соединения, которые предлагает предлагает клиент. В этих параметрах значится, что метод аутентификации предлагается – PAP.
Теперь рассмотрим пример, когда PPP соединение не устанавливается из-за несоответствия типа имени пользователя или пароля. Дело в том, что вывод debug команд при неправильно заданном имени пользователя или пароля одинаковы, поэтому не имеет смысла рассматривать эти случаи по отдельности.
debug ppp negotiation
pppoe-nas#
*Nov 2 07:58:59.987: ppp12 PPP: Send Message[Dynamic Bind Response]
*Nov 2 07:58:59.987: ppp12 PPP: Using vpn set call direction
*Nov 2 07:58:59.987: ppp12 PPP: Treating connection as a callin
*Nov 2 07:58:59.987: ppp12 PPP: Session handle[F400000E] Session id[12]
*Nov 2 07:58:59.987: ppp12 PPP: Phase is ESTABLISHING, Passive Open
*Nov 2 07:58:59.987: ppp12 LCP: State is Listen
*Nov 2 07:58:59.999: ppp12 LCP: I CONFREQ [Listen] id 0 len 17
*Nov 2 07:58:59.999: ppp12 LCP: MRU 1480 (0x010405C8)
*Nov 2 07:58:59.999: ppp12 LCP: MagicNumber 0x4AFF688E (0x05064AFF688E)
*Nov 2 07:58:59.999: ppp12 LCP: Callback 6 (0x0D0306)
*Nov 2 07:58:59.999: ppp12 LCP: O CONFREQ [Listen] id 1 len 19
*Nov 2 07:58:59.999: ppp12 LCP: MRU 1492 (0x010405D4)
*Nov 2 07:58:59.999: ppp12 LCP: AuthProto CHAP (0x0305C22305)
*Nov 2 07:58:59.999: ppp12 LCP: MagicNumber 0x1D3212E1 (0x05061D3212E1)
*Nov 2 07:58:59.999: ppp12 LCP: O CONFREJ [Listen] id 0 len 7
*Nov 2 07:58:59.999: ppp12 LCP: Callback 6 (0x0D0306)
*Nov 2 07:59:00.003: ppp12 LCP: I CONFACK [REQsent] id 1 len 19
*Nov 2 07:59:00.003: ppp12 LCP: MRU 1492 (0x010405D4)
*Nov 2 07:59:00.003: ppp12 LCP: AuthProto CHAP (0x0305C22305)
*Nov 2 07:59:00.007: ppp12 LCP: MagicNumber 0x1D3212E1 (0x05061D3212E1)
*Nov 2 07:59:00.007: ppp12 LCP: I CONFREQ [ACKrcvd] id 1 len 14
*Nov 2 07:59:00.007: ppp12 LCP: MRU 1480 (0x010405C8)
*Nov 2 07:59:00.007: ppp12 LCP: MagicNumber 0x4AFF688E (0x05064AFF688E)
*Nov 2 07:59:00.007: ppp12 LCP: O CONFNAK [ACKrcvd] id 1 len 8
*Nov 2 07:59:00.007: ppp12 LCP: MRU 1492 (0x010405D4)
*Nov 2 07:59:00.015: ppp12 LCP: I CONFREQ [ACKrcvd] id 2 len 14
*Nov 2 07:59:00.015: ppp12 LCP: MRU 1480 (0x010405C8)
*Nov 2 07:59:00.015: ppp12 LCP: MagicNumber 0x4AFF688E (0x05064AFF688E)
*Nov 2 07:59:00.015: ppp12 LCP: O CONFNAK [ACKrcvd] id 2 len 8
*Nov 2 07:59:00.015: ppp12 LCP: MRU 1492 (0x010405D4)
*Nov 2 07:59:00.023: ppp12 LCP: I CONFREQ [ACKrcvd] id 3 len 14
*Nov 2 07:59:00.023: ppp12 LCP: MRU 1492 (0x010405D4)
*Nov 2 07:59:00.023: ppp12 LCP: MagicNumber 0x4AFF688E (0x05064AFF688E)
*Nov 2 07:59:00.023: ppp12 LCP: O CONFACK [ACKrcvd] id 3 len 14
*Nov 2 07:59:00.027: ppp12 LCP: MRU 1492 (0x010405D4)
*Nov 2 07:59:00.027: ppp12 LCP: MagicNumber 0x4AFF688E (0x05064AFF688E)
*Nov 2 07:59:00.027: ppp12 LCP: State is Open
*Nov 2 07:59:00.027: ppp12 PPP: Phase is AUTHENTICATING, by this end
*Nov 2 07:59:00.027: ppp12 CHAP: O CHALLENGE id 1 len 30 from «pppoe-nas»
*Nov 2 07:59:00.035: ppp12 LCP: I IDENTIFY [Open] id 4 len 18 magic 0x4AFF688E MSRASV5.10
*Nov 2 07:59:00.035: ppp12 LCP: I IDENTIFY [Open] id 5 len 31 magic 0x4AFF688E MSRAS-0-2-4
*Nov 2 07:59:00.035: ppp12 CHAP: I RESPONSE id 1 len 30 from «pppoeuser»
*Nov 2 07:59:00.035: ppp12 PPP: Phase is FORWARDING, Attempting Forward
*Nov 2 07:59:00.035: ppp12 PPP: Phase is AUTHENTICATING, Unauthenticated User
*Nov 2 07:59:00.039: ppp12 CHAP: O FAILURE id 1 len 25 msg is «Authentication failed»
*Nov 2 07:59:00.039: ppp12 PPP: Sending Acct Event[Down] id[12]
*Nov 2 07:59:00.039: ppp12 PPP: Phase is TERMINATING
*Nov 2 07:59:00.039: ppp12 LCP: O TERMREQ [Open] id 2 len 4
*Nov 2 07:59:00.139: ppp12 LCP: I TERMACK [TERMsent] id 2 len 4
*Nov 2 07:59:00.139: ppp12 LCP: State is Closed
*Nov 2 07:59:00.139: ppp12 PPP: Phase is DOWN
*Nov 2 07:59:00.139: ppp12 PPP: Send Message[Disconnect]
Видим, что только что закончилась 1 фазы установки PPP соединения(LCP). Начиная со второй строки мы можем отследить процесс аутентификации.
*Nov 2 07:59:00.027: ppp12 CHAP: O CHALLENGE id 1 len 30 from «pppoe-nas» – данное сообщение означает, что сервер доступа получил входящий запрос содержащий в себе запрос, который клиент должен захешировать совместно с соответствующем паролем алгоритмом MD5 и отправить в ответ на challenge запрос, что мы и видим в следующих 3-ех строках:
*Nov 2 07:59:00.035: ppp12 LCP: I IDENTIFY [Open] id 4 len 18 magic 0x4AFF688E MSRASV5.10
*Nov 2 07:59:00.035: ppp12 LCP: I IDENTIFY [Open] id 5 len 31 magic 0x4AFF688E MSRAS-0-2-4
*Nov 2 07:59:00.035: ppp12 CHAP: I RESPONSE id 1 len 30 from «pppoeuser»
Следует заметить, что в сообщении об отправке ответа в кавычках стоит имя пользователя, которое указанно в настройках chap.
*Nov 2 07:59:00.039: ppp12 CHAP: O FAILURE id 1 len 25 msg is «Authentication failed» – это сообщение уже говорит, что сервер доступа признал ответ неправильным и начинает процедуру разрыва соединения.
В случае же когда аутентификация прошла успешно, в debug ppp negotiation появится следующее сообщение:
*Nov 2 08:08:04.383: ppp22 PPP: Phase is FORWARDING, Attempting Forward
*Nov 2 08:08:04.383: ppp22 PPP: Phase is AUTHENTICATING, Unauthenticated User
*Nov 2 08:08:04.387: ppp22 PPP: Phase is FORWARDING, Attempting Forward
*Nov 2 08:08:04.387: ppp22 PPP: Send Message[Connect Local]
*Nov 2 08:08:04.391: ppp22 PPP: Bind to [Virtual-Access1.1]