Opened 5 years ago

Closed 5 years ago

#32 closed баг (fixed)

Соединение TLS разрывается из-за ошибки

Reported by: san Owned by: alx
Priority: critical Milestone: 1 очередь
Keywords: Cc:

Description (last modified by san)

  1. Jun 4 04:51 Соединение TLS между устройствами было разорвано видимо по причине TCP inactivity timeout
  1. Ожидалось что после разрыва соединение будет установлено заново, и устройства продолжат передачу данных, однако после установки соединения оно закрывается с ошибкой:

    Jun 4 04:54:49 3gd[4866]: tls_tty.cpp:89: TlsTty::read(): TLS error: e=5: error:00000000:lib(0):func(0):reason(0)

Attachments (6)

messages​ (189.1 KB ) - added by san 5 years ago.
server_messages​ (117.2 KB ) - added by san 5 years ago.
3gd_client​ (1.0 KB ) - added by san 5 years ago.
3gd_server​ (1.0 KB ) - added by san 5 years ago.
client_messages2​ (91.7 KB ) - added by san 5 years ago.
server_messages2​ (180.6 KB ) - added by san 5 years ago.

Download all attachments as: .zip

Change History (26)

by san, 5 years ago

Attachment: messages​ added

comment:2 by san, 5 years ago

Через некоторое время соединение таки установилось, вот продолжение​ лога.

in reply to:  description comment:3 by alx, 5 years ago

Replying to san:

  1. Ожидалось что после разрыва соединение будет установлено заново, и устройства продолжат передачу данных, однако после установки соединения...

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

comment:4 by alx, 5 years ago

Resolution: → invalid
Status: new → closed

Согласно логу, в 04:46:17 соединение было разорвано. В 04:46:47, как и ожидалось, соединение было установлено заново:

Jun  4 04:46:17 3gd[4866]: link.cpp:192: --> Link::error(): connection closed
Jun  4 04:46:47 3gd[4866]: tcp_tty.cpp:181: connecting to 176.118.12.58 port 1001...
Jun  4 04:46:47 3gd[4866]: tls_tty.cpp:168: TLS connection established: TLSv1.2 GOST2012-GOST8912-GOST8912

Таким образом, клиент ведет себя в точном соответствии с задуманным алгоритмом. Бага не вижу.

comment:5 by san, 5 years ago

Description: modified (diff)
Resolution: invalid
Status: closed → reopened
Summary: Соединение TLS не устанавливается после разрыва → Соединение TLS разрывается из-за ошибки

Прошу прощения, ошибся с указанием времени происшествия в описании, исправил.
Вот само происшествие

  • разрыв по таймауту
  • установление соединения
  • какая-то ошибка
  • соединение закрывается 
    Jun  4 04:51:47 3gd[4866]: tcp_tty.cpp:355: TCP inactivity timeout
Jun  4 04:51:47 3gd[4866]: link.cpp:192: --> Link::error(): connection closed
Jun  4 04:52:17 3gd[4866]: tcp_tty.cpp:181: connecting to 176.118.12.58 port 1001...
Jun  4 04:52:17 3gd[4866]: tls_tty.cpp:168: TLS connection established: TLSv1.2 GOST2012-GOST8912-GOST8912
Jun  4 04:52:17 3gd[4866]: tls_tty.cpp:89: TlsTty::read(): TLS error: e=5: error:00000000:lib(0):func(0):reason(0)
Jun  4 04:52:17 3gd[4866]: link.cpp:192: --> Link::error(): connection closed

Такие попытки с ошибкой повторяются много раз и только в 05:03 соединение устанавливается.(смотри лог из comment:2)

comment:6 by alx, 5 years ago

Приложи, пожалуйста, также лог сервера.

by san, 5 years ago

Attachment: server_messages​ added

comment:7 by san, 5 years ago

Приложил

comment:8 by alx, 5 years ago

Также приложи, пожалуйста, конфиги клиента и сервера.

comment:9 by alx, 5 years ago

А почему в 05:02:13 перезапустился 3gd?

Version 0, edited 5 years ago by alx (next)

by san, 5 years ago

Attachment: 3gd_client​ added

by san, 5 years ago

Attachment: 3gd_server​ added

comment:10 by san, 5 years ago

Добавил конфиги

А почему в 05:02:13 перезапустился 3gd на сервере?

Не имею понятия. Я его не трогал, просто продолжал наблюдение.

comment:11 by alx, 5 years ago

Предполагаю, что проблема в настройках сервера: судя по приложенному attachment:3gd_server​, сразу два последовательных порта включены в режим "сервер" и им назначен один и тот же номер порта - 1001.

Предлагаю изменить настройки одного из последовательных портов - например изменить номер TCP порта или перевести его в режим клиента и повторить эксперимент.

comment:12 by san, 5 years ago

Хм.. действительно. Эти настройки остались после экспериментов заказчика.
Пробую...

in reply to:  12 comment:13 by alx, 5 years ago

Replying to san:

Эти настройки остались после экспериментов заказчика.

Откуда у заказчика интерфейс RS-485? Насколько я помню, мы поставляли для экспериментов тестирования устройство только с интерфейсом RS-232. В первоначальном варианте интерфейса панель порта RS-485 была даже скрыта...

Last edited 5 years ago by alx (previous) (diff)

comment:14 by san, 5 years ago

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

Last edited 5 years ago by san (previous) (diff)

in reply to:  14 comment:15 by alx, 5 years ago

Replying to san:

Интерфейса то не было, а настройки были)

??? По умолчанию последовательный порт включен в режим "клиент", а номер порта имеет значение 0 (в режиме "клиент" оно не используется).

comment:16 by san, 5 years ago

Может мы им так отправили, а может после обновления они перенастроили.

in reply to:  16 comment:17 by alx, 5 years ago

Replying to san:

Может мы им так отправили, а может после обновления они перенастроили.

Не понимаю, какой мог быть смысл настраивать отсутствующий интерфейс...

Если только по ошибке...

Last edited 5 years ago by alx (previous) (diff)

comment:18 by san, 5 years ago

Изменил номер порта сервера для rs-485 на 1002, ситуация повторилась Jun 4 11:19:26
сейчас приложу логи...

by san, 5 years ago

Attachment: client_messages2​ added

by san, 5 years ago

Attachment: server_messages2​ added

comment:19 by alx, 5 years ago

В результате тестов установлено, что ошибка возникает из-за того что TlsTty::want_read становится не равной нулю. В результате при поллинге сокета выполняется ветка под if(want_read), в которой всегда генерируется ошибка. Переменная TlsTty::want_read инициализируется нулем, и ей нигде не присваивается никакого другого значения. Предположительно где-то по неизвестной пока причине происходит порча памяти.

По той же причине (ненулевое значение TlsTty::want_read) происходит эффект, описанный в #33.

comment:20 by alx, 5 years ago

Resolution: → fixed
Status: reopened → closed

In 139/smartCrypto:

Исправлена ошибка: не инициализировались две переменные в конструкторе,
используемом в режиме "сервер". Closes #32, #33.

Note: See TracTickets for help on using tickets.