один из пользователей не может подключиться

[madf]

...

 

иль может автодисконнект не до конца сработавший прерыватся новой попыткой коннекта?

Если в процессе отключения приходит запрос на подключение - такой запрос считается ошибочным и не обрабатывается. Пользователь зависает в фазе отключения некоторое время, после чего снова считается подключенным.

Если в подключенном состоянии пользователь не отвечает на Alive-запросы сервера в течении некоторого времени - он считается отключенным. При этом очищается индекс ip-адресов.

Если пользователь "зависает" в процессе подключения - через определенное время он сбрасывается в состояние "отключен".

 

Да, еще. В этом контексте слово "подключен" следует читать как "авторизован", а "отключен" - "не авторизован".

[napTu]

спасибо за комментарии.

я тут подкрутил таймеры alive и timeout, вернул на дефолтные значения. Жду... %)

[napTu]

снова я

 

теперь так:

пользователь переустановил винду, поставил новый авторизатор, долго (весь день) пытался ввести логин, пароль, но всё время вписывал вместо q - g , при этом менял большие на меленькие в имени, перед этим еще подключался не со своего ип адреса...

 

в итоге ситуация по топику повторилась.

 

клиент периодически шлет пакеты с верными логином и паролем. стг никак не отвечает - ни одного пакета.

на неверный логин шлет ответ с ошибкой.

 

вот дамп пакетов:

 

tcpdump: listening on fxp0

19:42:07.906199 192.168.10.87 > hst.icenet: icmp: echo reply (ttl 128, id 300, len 84)

4500 0054 012c 0000 8001 a3d0 c0a8 0a57

c0a8 0a05 0000 e9ed f46a 0000 ef89 cd47

6cd2 0d00 0809 0a0b 0c0d 0e0f 1011 1213

1415 1617 1819 1a1b 1c1d 1e1f 2021 2223

2425 2627 2829 2a2b 2c2d 2e2f 3031 3233

3435

19:42:10.298870 192.168.10.87.rplay > hst.icenet.rplay: udp 64 (ttl 128, id 301, len 92)

4500 005c 012d 0000 8011 a3b7 c0a8 0a57

c0a8 0a05 15b3 15b3 0048 b6b6 3030 3130

3000 0007 d8c2 1f49 c867 0f48 cd2a 2f49

b1e4 0a91 cd2a 2f49 b1e4 0a91 cd2a 2f49

b1e4 0a91 2c40 fc7c 4836 e380 31f5 dd8f

6114

19:42:16.391930 192.168.10.87.rplay > hst.icenet.rplay: udp 64 (ttl 128, id 302, len 92)

4500 005c 012e 0000 8011 a3b6 c0a8 0a57

c0a8 0a05 15b3 15b3 0048 b6b6 3030 3130

3000 0007 d8c2 1f49 c867 0f48 cd2a 2f49

b1e4 0a91 cd2a 2f49 b1e4 0a91 cd2a 2f49

b1e4 0a91 2c40 fc7c 4836 e380 31f5 dd8f

6114

^C

53505 packets received by filter

 

хотя врядли они помогут, инфа то в них верна.

 

чего еще можно посмотреть?

[madf]

Точный ответ дал бы консольный лог...

Ответа на пакет может не быть в 3 случаях:

1. Пришел пакет 0 длины или ошибка приема данных из сокета.

2. Длина пакета больше 256 байт.

3. Неправильный заголовок пакета:

3.1. Неправильный MAGIC (IA_ID).

3.2. Неверная версия протокола в заголовке.

 

Если все эти 3 пункта пройдены нормально - пакет уходит на обработку. Дальнейшие ошибки должны попадать в /var/log/stargazer.log

[napTu]

в дебаг режиме запустил. 5суток. лог уже перевалил за гиг.

А полёт нормальный - испугалося наверное.

 

Грядёт дата снятия АП и перехода на след.месяц.

Имеет ли смысл перезапустить в нормальном режиме на этот период?

[madf]

в дебаг режиме запустил. 5суток. лог уже перевалил за гиг.

А полёт нормальный - испугалося наверное.

 

Грядёт дата снятия АП и перехода на след.месяц.

Имеет ли смысл перезапустить в нормальном режиме на этот период?

Разве что в качестве меры предупреждения черезмерного роста лога

[napTu]

таки вылез глюк. что фильтровать из лога? Пользователь 192.168.11.112

 

Здесь он не может подключиться:

 

inetaccess.cpp > 13:50:35 > User Ksusha1230 FOUND!

inetaccess.cpp > 13:50:35 > ======================> InitEncrypt dont needed

inetaccess.cpp > 13:50:35 > ALIVE_ACK_6(7) - OK

inetaccess.cpp > 13:50:35 > Monitor time 1207564408 1207997495

inetaccess.cpp > 13:50:35 > recv from 192.168.11.112 5555 len=64

inetaccess.cpp > 13:50:35 > User Barhan FOUND!

inetaccess.cpp > 13:50:35 > ======================> InitEncrypt dont needed

inetaccess.cpp > 13:50:35 > Monitor time 1207564408 1207997495

user.cpp > 13:50:36 > USER::WriteStat user=Larisa

 

Здесь он вводит заведомо неверный логи:

 

inetaccess.cpp > 13:51:00 > recv from 192.168.10.179 5555 len=64

inetaccess.cpp > 13:51:00 > User Dima179 FOUND!

inetaccess.cpp > 13:51:00 > ======================> InitEncrypt dont needed

inetaccess.cpp > 13:51:00 > ALIVE_ACK_6(7) - OK

inetaccess.cpp > 13:51:00 > Monitor time 1207564408 1207997520

inetaccess.cpp > 13:51:00 > recv from 192.168.11.112 5555 len=64

inetaccess.cpp > 13:51:00 > User 1 NOT found!

inetaccess.cpp > 13:51:00 > SendError 256 bytes sent

inetaccess.cpp > 13:51:00 > Monitor time 1207564408 1207997520

inetaccess.cpp > 13:51:00 > Min8(sizeof(ALIVE_SYN)) = 368

inetaccess.cpp > 13:51:00 > 1207997699.124701 368 bytes sent to 192.168.11.15:5555 len=368

inetaccess.cpp > 13:51:00 > Send_ALIVE_SYN_7

inetaccess.cpp > 13:51:00 > recv from 192.168.11.15 5555 len=64

inetaccess.cpp > 13:51:00 > User Makar FOUND!

inetaccess.cpp > 13:51:00 > ======================> InitEncrypt dont needed

 

По его ип адресу только такие сообщения.

[madf]

Нужен кусок лога побольше. Там где он не может подключиться.

[napTu]

Вот лог его подключений за сегодня (в обратном порядке):

C 2008.04.12-14.54.34 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-14.54.21 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-14.09.14 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-12.11.35 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-12.10.15 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-12.09.42 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-12.08.37 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-12.08.04 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-12.02.28 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-12.00.35 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-11.53.15 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-11.52.09 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-11.45.19 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-11.43.41 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-11.41.06 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-11.40.49 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-09.58.34 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.12-09.57.32 192.168.11.112 Barhan 367 10.000000

C 2008.04.12-06.26.15 192.168.11.112 Barhan 367 10.000000

 

D 2008.04.11-22.16.50 192.168.11.112 Barhan 367 10.000000

 

до 12:11 его смыкало, потом он не мог подключится, потом я рестартанул в 14:07 старгейзер.

 

 

последние 50 мегабайт лога (c 10утра) тут http://icenet.net.ua/sel.log.gz (архив 3,3 мегабайта)

[napTu]

опять же, обнаружилось что в районе этого абонента проблемы со свичем (подвис). Еще один пожаловался на периодические отключения, а другой на такую же траблу, что описана в этом топике.

[telo]

У меня подобная проблема! когда пользователь просто со своими данными в ключе пытается зайти но при этом путает любую буковку в логине, говорит неверный лог и пасс, все пока не перегружу стг его пускать не будет. особо не вычислял эту проблему, т.к. просто по утрам перегружаю стг если ктото позвонит в последние сутки с такой проблемой. Говорю просто что это как бы система от взломов чтобы никто ни у кого не воровал инет, и почти все понимают )))

На счет потерь по свитчу это бред, я лично на себе эту проблему проверял, на отдельном компе подключался на прямую к серваку, просто в логине делаю ошибку и все вуаля )))

[napTu]

telo, ну это немного не то. С таким же успехом я могу назвать твои слова бредом, ибо у меня можно вводить сколь угодно много неверных логин-пароль вариантов, но после ввода правильного всё работает. В моем случае абоненты перестают работать в местах где наблюдаются потери на свичах.

[napTu]

блин, время в дебаге смещено, тяжело ориентироваться...

 

по логам ситуация следующая:

 

- периодически теряются алив пакеты.

inetaccess.cpp > 11:35:33 > Min8(sizeof(ALIVE_SYN)) = 368

inetaccess.cpp > 11:35:33 > 1207989569.340008 368 bytes sent to 192.168.11.112:5555 len=368

inetaccess.cpp > 11:35:33 > Send_ALIVE_SYN_7

inetaccess.cpp > 11:35:33 > recv from 192.168.11.112 5555 len=64

inetaccess.cpp > 11:35:33 > User Barhan FOUND!

inetaccess.cpp > 11:35:33 > ======================> InitEncrypt dont needed

inetaccess.cpp > 11:35:33 > ALIVE_ACK_6(7) - OK

...

inetaccess.cpp > 11:36:18 > Min8(sizeof(ALIVE_SYN)) = 368

inetaccess.cpp > 11:36:18 > ========= ALIVE_ACK_6(7) TIMEOUT !!! Barhan =========

inetaccess.cpp > 11:36:18 > 1207989614.356267 368 bytes sent to 192.168.11.112:5555 len=368

inetaccess.cpp > 11:36:18 > Send_ALIVE_SYN_7

 

три теряются, на четвертый обнаруживается и заново авторизируется,

но инфы об отключении нет, хотя он реально отключается:

 

inetaccess.cpp > 11:36:54 > recv from 192.168.11.112 5555 len=64

inetaccess.cpp > 11:36:54 > User Barhan FOUND!

inetaccess.cpp > 11:36:54 > Add new user

inetaccess.cpp > 11:36:54 > ========> InitEncrypt 'NO PASSWORD' '********'

inetaccess.cpp > 11:36:54 > User Barhan phase changed from 1 to 2

inetaccess.cpp > 11:36:54 > Phase changed from 1 to 2

inetaccess.cpp > 11:36:54 > 1207989650.429457 192 bytes sent to 192.168.11.112:5555 len=192

 

- далее идет множество раз переход в фазу 2

 

inetaccess.cpp > 11:37:10 > recv from 192.168.11.112 5555 len=64

inetaccess.cpp > 11:37:10 > User Barhan FOUND!

inetaccess.cpp > 11:37:10 > ======================> InitEncrypt dont needed

inetaccess.cpp > 11:37:10 > User Barhan phase changed from 1 to 2

inetaccess.cpp > 11:37:10 > Phase changed from 1 to 2

inetaccess.cpp > 11:37:10 > 1207989666.486143 192 bytes sent to 192.168.11.112:5555 len=192

 

- тут мы вдруг переподключились:

 

inetaccess.cpp > 11:37:10 > recv from 192.168.11.112 5555 len=64

inetaccess.cpp > 11:37:10 > User Barhan FOUND!

inetaccess.cpp > 11:37:10 > ======================> InitEncrypt dont needed

inetaccess.cpp > 11:37:10 > CONN_ACK

inetaccess.cpp > 11:37:10 > rnd = 995745997 connAck->rnd=995745998

inetaccess.cpp > 11:37:10 > User Barhan phase changed from 2 to 3

users.cpp > 11:37:10 > Del IP Idx

traffcounter.cpp > 11:37:10 > DelUser: Barhan

user.cpp > 11:37:10 > Disconnect. User name 'Barhan' ip=192.168.11.112

users.cpp > 11:37:10 > Add IP Idx

traffcounter.cpp > 11:37:10 > AddUser: Barhan

inetaccess.cpp > 11:37:10 > Phase changed from 2 to 3

inetaccess.cpp > 11:37:10 > Min8(sizeof(ALIVE_SYN)) = 368

inetaccess.cpp > 11:37:10 > 1207989666.539364 368 bytes sent to 192.168.11.112:5555 len=368

 

...

- многократные переходы из фазы 1 в 2 дают в конечном итоге дисконнект,

или это по таймауту отвалилось:

 

users.cpp > 12:09:19 > Del IP Idx

traffcounter.cpp > 12:09:19 > DelUser: Barhan

user.cpp > 12:09:19 > Disconnect. User name 'Barhan' ip=192.168.11.112

 

- далее снова можество попыток с переходом из фазы 1 в 2

 

И ВОТ КУЛЬМИНАЦИЯ:

 

inetaccess.cpp > 12:13:17 > recv from 192.168.11.112 5555 len=64

inetaccess.cpp > 12:13:17 > User Barhan FOUND!

inetaccess.cpp > 12:13:17 > ======================> InitEncrypt dont needed

 

C этого момента записи о переходе из фазы 1 в 2 отсутствуют, идут только эти три строки

 

Ну и пользователь соответственно более не может подключиться.

[napTu]

по коду следующее:

 

вариант 1)

в AUTH_IA::Process_CONN_SYN_6

имеем фазу залипшую 2, тогда

if (!(iaUser->phase == 1 || iaUser->phase == 3))

return -1;

 

Тогда гдето теряется условие обнуления фазы по таймауту, или для неподключенного пользователя. Я этого условия в коде вообще не нашел.

 

 

 

вариант 2)

не доходим до AUTH_IA::Process_CONN_SYN_6

причин этого не наблюдаю.

[tvpKS]

Наблюдаю точь в точь описанную в топике проблему с авторизацией. Примерно, раз в три-четыре дня появляется жалоба о невозможности подключиться. Решается проблема только перезагрузкой сервера.

[napTu]

я знаю причину! это происки заводов-империалистов производителей оптического оборудования.

купуйте оптику и всё будет пучком. нет потерь - нет проблем с авторизацией.

[madf]

по коду следующее:

 

вариант 1)

в AUTH_IA::Process_CONN_SYN_6

имеем фазу залипшую 2, тогда

if (!(iaUser->phase == 1 || iaUser->phase == 3))

return -1;

 

Тогда гдето теряется условие обнуления фазы по таймауту, или для неподключенного пользователя. Я этого условия в коде вообще не нашел.

 

 

 

вариант 2)

не доходим до AUTH_IA::Process_CONN_SYN_6

причин этого не наблюдаю.

Фазы не залипают. Таймаутер сбрасывает фазы 2 и 3 в 1, а 4 - в 3.

Судя по вот этому кусочку лога

   inetaccess.cpp > 12:12:07 > User Plotnikova FOUND!
   inetaccess.cpp > 12:12:07 > ======================>   InitEncrypt dont needed
   inetaccess.cpp > 12:12:07 > ALIVE_ACK_6(7) - OK
   inetaccess.cpp > 12:12:07 > Monitor time 1207564408 1207991587
 traffcounter.cpp > 12:12:09 > FlushAndRemove() packets: 2705(rem 352) ip2packets: 5410(rem 704)
   inetaccess.cpp > 12:12:10 > recv from 192.168.10.65 5554 len=64
   inetaccess.cpp > 12:12:10 > User Nadya FOUND!
   inetaccess.cpp > 12:12:10 > ======================>   InitEncrypt dont needed
   inetaccess.cpp > 12:12:10 > Monitor time 1207564408 1207991590

это известная проблема с дедлоком. После элайв-пакета в 12:12:07 дальнейшие просто не определяются.

Сейчас эта проблема уже, вроде-бы, решена. Ждите релиза...

[napTu]

вроде-бы и Ждите не обнадеживает нисколечко.

 

Дедлок как я понимаю кратковременное зависание на некоторое время, которое неизвестно где происходит и теряется часть данных?

 

надо бы в inetaccess.cpp напихать побольше дебаг месседжей и глянуть подробнее ситуацию.

[napTu]

да и фиг с ним с дедлоком, главное чтобы продолжалась корректная обработка после него.

[madf]

Сейчас в inetaccess пофикшен точно 1 дедлок и добавлен функционал для более детального мониторинга переходов между фазами юзеров.

[napTu]

где взять?

[madf]

Пока нигде. В процессе тестирования, документирования и написания ченджлога

[nallien]

та же проблема, с нетерпением жду релиза, так как мучаемся уже с месяца три этой бедой.

[napTu]

таки я был прав - теряется информация в базе таймаутера.

вот сейчас курю лог юзера. добавил одну единствнную дебаг строчку:

 

int AUTH_IA::Process_CONN_SYN_6(CONN_SYN_6 * connSyn, IA_USER * iaUser, user_iter * user, uint32_t s

{

if (!(iaUser->phase == 1 || iaUser->phase == 3))

{

printfd(__FILE__, "User %s phase not1 and not3 - return from CONN_SYN_6 \n",

iaUser->user->GetLogin().c_str() );

 

return -1;

}

 

когда пользователь не может подключится, то она и срабатывает:

 

inetaccess.cpp > 21:58:42 > Send_ALIVE_SYN_7

inetaccess.cpp > 21:58:42 > recv from 192.168.8.60 5555 len=64

inetaccess.cpp > 21:58:42 > User Gudvin FOUND!

inetaccess.cpp > 21:58:42 > ======================> InitEncrypt dont needed

inetaccess.cpp > 21:58:42 > User Gudvin phase not1 and not3 - return from CONN_SYN_6

inetaccess.cpp > 21:58:42 > Monitor time 1215722161 1215802782

 

 

 

Вопросы следующие:

1.как изменить таймаутер или что то еще чтобы сбрасывались данные таких юзеров? типа сделать временную заплатку...

 

2.как более полно протрассировать почему теряется инфа?

[napTu]

смотрю далее по коду таймаутера из расчета что пользователь застряет в фазе 2 :

 

static UTIME currTime;

gettimeofday(&currTime, NULL);

 

if ((it->second.phase == 2)

&& (currTime - it->second.phaseTime) > iaSettings.GetUserDelay())

{

it->second.phase = 1;

gettimeofday(&it->second.phaseTime, NULL);

//it->second.phaseTime = stgTime;

//#ifdef IA_DEBUG

printfd(__FILE__, "Phase changed from 2 to 1. Reason: timeout $s \n" , sip );

//#endif

}

 

следовательно по какой то причине не выполняется второе условие :

&& (currTime - it->second.phaseTime) > iaSettings.GetUserDelay

 

возможно что в дедлоке сбивается it->second.phaseTime и тогда условие никогда не выполняется...

 

вставлю сюда дебаг...