#341 closed баг (fixed)
R422: разрывы соединений при больших значениях таймаута передачи
| Reported by: | san | Owned by: | alx |
|---|---|---|---|
| Priority: | средний | Milestone: | 1 очередь |
| Component: | VE-02 | Keywords: | |
| Cc: |
Description
При тестировании настройки "Таймаут передачи" модуля R422 обнаружил некоторую странность: Если на блоке VIP установить модуль в режим сервер и настройку "Таймаут передачи" сделать довольно большой, например 5000 мс., то соединение периодически(очень часто) разрывается, без видимой причины.
Если настройку установить в 0 или 10 мс., всё работает при тех же условиях.
Глубже пока не смотрел, описанное воспроизводится в блоке 192.168.0.1
(с противоположной стороны блок 3U 192.168.1.52)
Attachments (1)
Change History (19)
comment:1 by , 5 years ago
comment:2 by , 5 years ago
Replying to san:
соединение ... разрывается, без видимой причины.
Это странно, так как (я только что проверил в исходном коде) любой вроде бы переход в состояние Error сопровождается выводом в лог сообщения об ошибке... Может быть у тебя в настройках установлен приоритет журналирования выше чем ERR?
follow-up: 5 comment:4 by , 5 years ago
Без видимой причины, это до залезания в лог, надеюсь что в логе будет записана причина)
посмотрю его завтра
comment:5 by , 5 years ago
Replying to san:
Без видимой причины, это до залезания в лог
В таком случае, вывод о наличии бага - преждевременен...
follow-up: 8 comment:6 by , 5 years ago
Фрагмент лога со стороны cервера VIP
Mar 13 05:02:02 comcerto daemon.err sip_ua[437]: r232.cpp:216: module 1: read() error: Mar 13 05:02:02 comcerto daemon.info sip_ua[437]: r232.cpp:204: module 1: connection closed by remote host Mar 13 05:02:02 comcerto daemon.info sip_ua[437]: r232.cpp:594: module 1: waiting for incoming connection...
Фрагмент лога со стороны клиента VE-02
Mar 13 05:20:58 comcerto daemon.err sip_ua[448]: r232.cpp:241: module 1: cannot connect: Connection refused Mar 13 05:20:58 comcerto daemon.err sip_ua[448]: r232.cpp:241: module 1: cannot connect: Connection refused
з.ы. На VE-02 часы спешат на 20 минут
comment:7 by , 5 years ago
Ещё отмечу, что разрыв происходит только после того, как я включаю передачу данных.
Пока данных нет, соединение не разрывается.
comment:8 by , 5 years ago
Replying to san:
Mar 13 05:02:02 comcerto daemon.err sip_ua[437]: r232.cpp:216: module 1: read() error:
Хм... Действительно, без видимой причины. :) Текста ошибки нет!
follow-up: 11 comment:10 by , 5 years ago
Ну вообще в этой ситуации мне не нравится что соединение неожиданно для меня "разрывается", хотя "внешних" причин для разрыва нет. то что разорвалось из-за какой то внутренней ошибки я и так догадывался))
comment:11 by , 5 years ago
Replying to san:
соединение ... "разрывается", хотя "внешних" причин для разрыва нет. то что разорвалось из-за какой то внутренней ошибки я и так догадывался))
Не вижу оснований для таких догадок. Согласно приведенному фрагменту лога, ошибка возникла при попытке читать данные из сокета. Так как текст ошибки в лог не вывелся, мы не знаем, какая именно ошибка произошла, но наиболее вероятной причиной мне кажется получение чего-то из сети, то есть извне. Сами мы по факту этой ошибки соединение не закрываем (что, возможно, неправильно). Чисто теоретически можно предположить возможность ошибки read() по внутренним причинам, если, например, дескриптор сокета "испорчен", и в read() передали мусор вместо дескриптора, или, например, сокет почему-то (по ошибке) закрыли раньше, и вызвали read() для уже закрытого сокета. Оба варианта мне кажутся неправдоподобными, так как каждое закрытие соединения сопровождается соответствующей записью в лог, а причин для "порчи" одной отдельной переменной я тоже не вижу...
В любом случае предлагаю не гадать, а повторить эксперимент с исправленным sip_ua - теперь в логе будет указан конкретный текст ошибки read().
follow-up: 13 comment:12 by , 5 years ago
Повторил
Mar 13 06:38:25 comcerto daemon.err sip_ua[437]: r232.cpp:216: module 1: read() error: Connection reset by peer Mar 13 06:38:25 comcerto daemon.info sip_ua[437]: r232.cpp:204: module 1: connection closed by remote host Mar 13 06:38:25 comcerto daemon.info sip_ua[437]: r232.cpp:594: module 1: waiting for incoming connection... Mar 13 06:38:25 comcerto daemon.info sip_ua[437]: r232.cpp:96: module 1: connect from ::ffff:192.168.0.117:39382
comment:13 by , 5 years ago
Replying to san:
read() error: Connection reset by peer
Ну вот. Как я и предполагал, причина внешняя.
comment:14 by , 5 years ago
Повторил эксперимент, теперь время на обоих блоках правильное, детализацию лога повысил до INFO
Сервер VIP:
root@comcerto:~# logread -f Mar 13 06:50:53 comcerto daemon.err sip_ua[437]: r232.cpp:216: module 1: read() error: Connection reset by peer Mar 13 06:50:53 comcerto daemon.info sip_ua[437]: r232.cpp:204: module 1: connection closed by remote host Mar 13 06:50:53 comcerto daemon.info sip_ua[437]: r232.cpp:594: module 1: waiting for incoming connection... Mar 13 06:50:53 comcerto daemon.info sip_ua[437]: r232.cpp:96: module 1: connect from ::ffff:192.168.0.117:59714 Mar 13 06:50:54 comcerto daemon.err sip_ua[437]: r232.cpp:216: module 1: read() error: Connection reset by peer Mar 13 06:50:54 comcerto daemon.info sip_ua[437]: r232.cpp:204: module 1: connection closed by remote host Mar 13 06:50:54 comcerto daemon.info sip_ua[437]: r232.cpp:594: module 1: waiting for incoming connection... Mar 13 06:50:54 comcerto daemon.info sip_ua[437]: r232.cpp:96: module 1: connect from ::ffff:192.168.0.117:59716
Клиент VE-02
root@comcerto:~# logread -f Mar 13 06:50:53 comcerto daemon.info sip_ua[448]: r232.cpp:204: module 1: connection closed by remote host Mar 13 06:50:53 comcerto daemon.info sip_ua[448]: r232.cpp:372: module 1: looking up 192.168.0.1... Mar 13 06:50:53 comcerto daemon.info sip_ua[448]: r232.cpp:428: module 1: connecting to 192.168.0.1 port 12912... Mar 13 06:50:53 comcerto daemon.err sip_ua[448]: r232.cpp:241: module 1: cannot connect: Connection refused Mar 13 06:50:53 comcerto daemon.info sip_ua[448]: r232.cpp:428: module 1: connecting to 192.168.0.1 port 12912... Mar 13 06:50:53 comcerto daemon.err sip_ua[448]: r232.cpp:254: module 1: connected to server Mar 13 06:50:54 comcerto daemon.info sip_ua[448]: r232.cpp:204: module 1: connection closed by remote host Mar 13 06:50:54 comcerto daemon.info sip_ua[448]: r232.cpp:372: module 1: looking up 192.168.0.1... Mar 13 06:50:54 comcerto daemon.info sip_ua[448]: r232.cpp:428: module 1: connecting to 192.168.0.1 port 12912... Mar 13 06:50:54 comcerto daemon.err sip_ua[448]: r232.cpp:241: module 1: cannot connect: Connection refused Mar 13 06:50:54 comcerto daemon.info sip_ua[448]: r232.cpp:428: module 1: connecting to 192.168.0.1 port 12912... Mar 13 06:50:54 comcerto daemon.err sip_ua[448]: r232.cpp:254: module 1: connected to server
comment:15 by , 5 years ago
Приложи, пожалуйста, еще и вывод tcpdump'а. Хочется посмотреть, что происходит в действительности...
comment:16 by , 5 years ago
Вот вроде бы похожий тикет в 3G
https://trac.adc-line.ru/MC04-3G/ticket/32
by , 5 years ago
comment:17 by , 5 years ago
Логи последнего эксперимента, чей дамп выше.
Сервер VIP
root@comcerto:~# logread -f Mar 13 09:22:17 comcerto daemon.err sip_ua[437]: r232.cpp:216: module 1: read() error: Connection reset by peer Mar 13 09:22:17 comcerto daemon.info sip_ua[437]: r232.cpp:204: module 1: connection closed by remote host Mar 13 09:22:17 comcerto daemon.info sip_ua[437]: r232.cpp:594: module 1: waiting for incoming connection... Mar 13 09:22:17 comcerto daemon.info sip_ua[437]: r232.cpp:96: module 1: connect from ::ffff:192.168.0.117:43285 Mar 13 09:22:19 comcerto daemon.err sip_ua[437]: r232.cpp:216: module 1: read() error: Connection reset by peer Mar 13 09:22:19 comcerto daemon.info sip_ua[437]: r232.cpp:204: module 1: connection closed by remote host Mar 13 09:22:19 comcerto daemon.info sip_ua[437]: r232.cpp:594: module 1: waiting for incoming connection... Mar 13 09:22:19 comcerto daemon.info sip_ua[437]: r232.cpp:96: module 1: connect from ::ffff:192.168.0.117:43287
клиент VE-02
root@comcerto:~# logread -f Mar 13 09:22:17 comcerto daemon.info sip_ua[448]: r232.cpp:204: module 1: connection closed by remote host Mar 13 09:22:17 comcerto daemon.info sip_ua[448]: r232.cpp:372: module 1: looking up 192.168.0.1... Mar 13 09:22:17 comcerto daemon.info sip_ua[448]: r232.cpp:428: module 1: connecting to 192.168.0.1 port 12912... Mar 13 09:22:17 comcerto daemon.err sip_ua[448]: r232.cpp:241: module 1: cannot connect: Connection refused Mar 13 09:22:17 comcerto daemon.info sip_ua[448]: r232.cpp:428: module 1: connecting to 192.168.0.1 port 12912... Mar 13 09:22:17 comcerto daemon.err sip_ua[448]: r232.cpp:254: module 1: connected to server Mar 13 09:22:19 comcerto daemon.info sip_ua[448]: r232.cpp:204: module 1: connection closed by remote host Mar 13 09:22:19 comcerto daemon.info sip_ua[448]: r232.cpp:372: module 1: looking up 192.168.0.1... Mar 13 09:22:19 comcerto daemon.info sip_ua[448]: r232.cpp:428: module 1: connecting to 192.168.0.1 port 12912... Mar 13 09:22:19 comcerto daemon.err sip_ua[448]: r232.cpp:241: module 1: cannot connect: Connection refused Mar 13 09:22:19 comcerto daemon.info sip_ua[448]: r232.cpp:428: module 1: connecting to 192.168.0.1 port 12912... Mar 13 09:22:19 comcerto daemon.err sip_ua[448]: r232.cpp:254: module 1: connected to server
Добавлю ещё, что в эксперименте я передаю в обе стороны поток данных на скорости 800 байт/с.