Проблема с опросом по GSM/CSD после перехода на Linux/Postgres

[mxl (Максим)]

После перехода на Linux/PostgreSQL возникла проблема с опросом приборов по GSM/CSD.
Система выдает сообщение “Ошибка опроса. Истек таймаут на установку соединения.”

Ошибка из интерфейса ЛЭРС:

Лог:
tail -f /var/LERS/Logs/PollService/dump.mc35i.2023-06-18.log

2023-06-18 04:39:30.3122 ---- Порт открыт
2023-06-18 04:39:30.3137 >> ATZ
2023-06-18 04:39:30.3875 <<
OK
2023-06-18 04:39:30.3896 >> ATD89640847763
2023-06-18 04:40:05.3945 <<
CONNECT 9600/RLP
2023-06-18 04:40:06.0143 ---- Порт закрыт

Система Debian 11.7, Docker 24.0.2, ЛЭРС 3.51.3, COM порт в сервере без переходников. Модем Siemens MC35i.

Запустил в контейнере отладку процесса опроса командой strace -f -p номер_процесса_службы_опроса -t -o /trace.log.

Заметил, что коннект в лог файле отображается позже, чем он реально произошел (в трассировке в 11:39:49, а в логе отобразилось только после таймаута 35 сек. в 04:40:05, разница в часах из-за таймзоны в логе). То есть, CONNECT был до истечения таймаута. Также прилагаю видео, где видно задержку в логе.
Видео отладки:

lers.mp4

Трассировка с помощью strace:
root@d04ce181e884:/# tail -f /trace.log | grep CONNE
14584 11:39:49 <… read resumed>“\r\nCONNEC”, 8) = 8

в логе при этом сообщение отобразилось позже (ровно в момент завершения таймаута, часовой пояс только неверный в логе):
2023-06-18 04:40:05.3945 <<
CONNECT 9600/RLP

Перехват strace и данные лога:

То есть CONNECT был до истечения timeout, но служба опроса или не увидела его или не нашла в БД, какой запрос послать. Еще заметил, что нет последей буквы “T” в ответе “\r\nCONNEC”. Но это вроде нормально.

Такую же проблему описывали в теме Проблемы с опросом приборов после миграции на Postgres - #6 от пользователя slavniy и там как я понял только базу перенесли на Postgres, а сам сервер остался под Windows и не переставлялся (в логе также коннект после таймаута и дальше закрытие порта). Поэтому думаю, может при переносе БД, например, не скопировались данные по моделям приборов учета или еще что-то (я как пользователь с ЛЭРС мало работаю, не знаю предметную область учета).

Пробовал на разных серверах: первый запуск был на виртуальной машине KVM и с использованием переходника USB->COM ,думал проблема в чем-то из этой более сложной схемы и перешел на bare metal сервер без виртуалок и без COM-переходников, этот вариант и описал в теме.

Что можно еще проверить? В чем может быть проблема?

[slavniy (Иван Славный)]

@mxl

Еще заметил, что нет последей буквы “T” в ответе “\r\nCONNEC”. Но это вроде нормально.

Нет, это явно не нормальная ситуация. Остальная часть ответа есть в журнале трассировки? Если да, во сколько она была зарегистрирована в нем? Почему вообще ответ приходит в таком виде?

[mxl (Максим)]

1. Прикладываю ссылку на полный лог трассировки. Событие коннект происходит в 09:31:18.
   trace.log — Яндекс Диск
2. Попробовал сейчас в качестве диспетчерского модема Teleofis RX100, проблема не решилась и сообщение тоже без последней буквы “T”.
   В инструкции (http://marrginal.ru/files/modem/Siemens_mc35i_atc_0103.pdf) в пункте 2.5.1 Verbose and numeric result codes приведены следующие ответы:
   Verbose format Numeric format Meaning
   CONNECT 1 Link established
   CONNECT 9600/RLP 49 Link with 9600 bps and Radio Link Protocol
   Думаю, что модем шлет цифру, а текстовая интерпретация уже происходит в программе.

Можете прислать аналогичную трассировку с вашей системы для анализа?

Также попробовал через minicom сделать звонок (через модем Teleofis), сообщение полное - CONNECT 9600:

Добро пожаловать в minicom 2.8
ПАРАМЕТРЫ: I18n
Port /dev/ttyS0, 09:15:47
Нажмите CTRL-A Z для получения подсказки по клавишам
OK
ATD
ATZ
OK
ATD89640847761

CONNECT 9600

[mxl (Максим)]

Сейчас создал новую БД, завел туда тестовый прибор и все заработало без проблем.
Поэтому, как я и предполагал, что ошибка в БД (что-то не так перенеслось, хотя ошибок скрипт не выдавал).
Скорее всего и в соседней теме (Проблемы с опросом приборов после миграции на Postgres - #6 от пользователя slavniy), где перенесли только БД на Postgres, а не сам сервер, проблема была в этом же.

Лог:
2023-06-19 05:03:13.2257 ---- Порт открыт
2023-06-19 05:03:13.2257 >> ATZ
2023-06-19 05:03:13.3116 <<
OK

2023-06-19 05:03:13.3116 >> ATD89293966449
2023-06-19 05:03:39.0509 <<
CONNECT 9600

2023-06-19 05:03:39.2239 >> 01 11 C0 2C
2023-06-19 05:03:40.7106 << 01 11 0A
2023-06-19 05:03:40.7171 << 54 4D 4B 30 32 30 01 01 01 03 17 72
2023-06-19 05:03:40.7515 >> 01 04 00 47 00 10 41 D3
2023-06-19 05:03:42.2264 << 01 04 20
2023-06-19 05:03:42.2748 << 00 05 06 3F 05 3C 04 FC 02 FF 02 86 02 66 00 5F 00 38 00 18 08 FF 00 00 08 5E 08 FF 00 00 00 46 7D AA
2023-06-19 05:03:42.2924 >> 01 03 00 00 00 0A C5 CD
2023-06-19 05:03:43.7673 << 01 03 14
2023-06-19 05:03:43.7899 << 00 00 0A F7 00 17 00 06 00 13 00 0B 00 32 00 06 00 00 00 00 9B 00
2023-06-19 05:03:44.5287 ---- Порт закрыт

Что именно проверить в БД? И как исправить?

[slavniy (Иван Славный)]

1. В приложенном вами журнале трассировки после “CONNEC” немного позже приходит “6319 09:31:18 <… read resumed>“T 9600\r\n”, 8) = 8”. Но почему ответ приходит за два захода?.
2. Нет, ваше предложение неверно. Должно приходить именно строковое значение.

@mxl

Сейчас создал новую БД, завел туда тестовый прибор и все заработало без проблем.

Уточните после переноса вы меняли COM-порт в настройках порта опроса? Также уточните в журнале трассировки службы опроса после создания пустой БД ответ также разбит на две части?

[mxl (Максим)]

1. Да, после переноса БД в Postgres менял настройки COM порта, вместо COM1 выставлял нужное, а именно /dev/ttyS0. Также пробовал выставлять как стандартный модем, там и конкретные модели. В Общих настройках GSM модема пробовал выставлять программный и аппаратные контроль потока итд. Без этого мы бы вообще не получили реакции в логах (не было бы ответов OK на ATZ).
   Также через интерфейс ЛЭРС успешно отправлялась тестовая SMS.
   После очистки БД заново добавил порт опроса и в общих настройках завел GMS модем.

2. Да, даже при успешном опросе сообщение разбито на два:

tail -f /trace.log | grep CONNEC
1033 12:40:01 <… read resumed>“\r\nCONNEC”, 8) = 8
^C
root@1a1ca315a453:/# cat /trace.log | grep “T 9600”
1033 12:40:01 <… read resumed>“T 9600\r\n”, 8) = 8

Сам файл трассировки: trace.log — Яндекс Диск

Скрин успешного опроса:

[slavniy (Иван Славный)]

Ситуация очень странная. Она вряд ли как то связана с БД, так как Служба опроса не работает с БД. С ней работает только Сервер, который передает Службе опроса информацию о относящихся к ней порта опроса. Возможно есть какие то проблемы с перенесенными портами опроса диспетчерских модемов. Попробуйте штатным способом удалить порт опроса и создать его заново в перенесенной БД, после повторите опрос.

[mxl (Максим)]

В разделе Опрос → Службы и порты опроса в блоке Локальная служба опроса удалил модем и создал его заново.
Не помогло((

Настройки.

Хотел еще попробовать включить “Программный контроль установки и заверешения связи”, но через web не получается, выдает ошибку “Порт /dev/ttyS0 используется для вызова GPRS-устройств.”, а windows нет под рукой. Но это скорее всего не поможет, я вроде, ранее это уже пробовал.

[slavniy (Иван Славный)]

Сервер ЛЭРС УЧЕТ из Docker с пустой БД Postgres был развернут на том же компьютере, что и перенесенная ранее? Вы создавали новый образ docker или просто отвязали перенесенную БД и привязали пустую?

[mxl (Максим)]

Я в LERS_SERVER_DATABASE__ConnectionString заменил имя базы и сделать docker compose up -d. Сервер и модем тот же, версию контейнера тоже не менял.

version: “3.9”
services:
lers:
image: lersamr/full:3.51.3
restart: always
ports:
- 10000:10000 # Порт для подключения к серверу ЛЭРС УЧЁТ
volumes:
- /var/LERS:/var/LERS
- /etc/LERS:/etc/LERS
devices:
- “/dev/ttyS0:/dev/ttyS0” # COM-порт, к которому подключен модем
environment:
LERS_SERVER_DATABASE__ConnectionString: “Host=ХОСТ;Database=lers;Username=lers;Password=ПАРОЛЬ”
LERS_SERVER_DATABASE__Provider: “Postgres”

[slavniy (Иван Славный)]

Данный COM-порт не задействован в настройках вызывного модема в Системных параметрах?

[mxl (Максим)]

В Администрировании GSM-модем указан тот же порт. Но так сделано и в версии с чистой базой, где все работает…
Попробовать убрать его из системных параметров?

[slavniy (Иван Славный)]

Да, попробуйте убрать его из Системных параметров и отключить там использование GSM-модема. После всех изменений на всякий случай перезагрузите Службу опроса и Сервер.

[mxl (Максим)]

Выключил, перезагрузил контейнер. Не помогло.

[slavniy (Иван Славный)]

Приложите журнал работы Службы опроса и Сервера из docker за сегодня 19.06.2023.

[mxl (Максим)]

Выслал логи на support@lers.ru.

[slavniy (Иван Славный)]

Вы прислали только журнал работы Службы опроса за запрошенную дату и дампы обмена с ним. Приложите также запрошенный журнал работы Сервера ЛЭРС УЧЕТ.

[mxl (Максим)]

Закачал сейчас в эту же папку на ya диске: server.2023-06-19.log и server_error.2023-06-19.log.

[slavniy (Иван Славный)]

@mxl

Заметил, что коннект в лог файле отображается позже, чем он реально произошел (в трассировке в 11:39:49, а в логе отобразилось только после таймаута 35 сек. в 04:40:05, разница в часах из-за таймзоны в логе)

А почему у вас локальная Служба опроса и Сервер имеют разные часовые пояса? Или это разница между docker и ОС?

[mxl (Максим)]

Да, скорее всего из-за этого. Пока еще не разобрался с этим (на форуме писали, что время в docker не критично).
Если подскажите, как поправить, сделаю сегодня.