После рестарта сервера rfw не коннектится к ядру

alex_pnz

Добрый день.

Краткое описание проблемы:
На сервере №1 стоят ядро и rfw на сервере №2 стоит rfw, который соединяется с ядром на сервере №1. Служба utm5_rfw прописана на автозапуске с помощью chkconfig. При остановке и запуске вручную (service utm5_rfw stop|start) на сервере №2 переподключение к ядру происходит нормально. При перезагрузке сервера №2 utm5_rfw запускается и через несколько секунд вылетает с ошибкой в логах, отказываясь подключаться к ядру (ядро дает отлуп). В панели администратора в разделе со списком брандмауеров он во время перезапуска является активным (подсвечивается зеленым).
Также заметил (netstat -anp), что висит соединение с уже выключенным rfw на стороне сервера с ядром, когда сервер с rfw выключен. Через некоторое время (минут через 10-13) это полумертвое соединение закрывается, и только тогда rfw может переподключиться к ядру.

Подскажите, пожалуйста, как это исправить? Крутить переменные на стороне ядра не хотелось бы - ибо костыль.

rfw.log на сервере №2 сразу после рестарта сервера:

Jan 22 17:03:28 ?Debug : 1cc377e0 ModTop: Socket connected to: host <Сервер №1> port <12758>
Jan 22 17:03:28 Info : 1cab3700 StreamConnection: Connection thread started. Peer [Сервер №1]:12758
Jan 22 17:03:28 ?Debug : 1cab3700 StreamConnection: Connection using SSLv3
Jan 22 17:03:28 ?Debug : 1cab3700 StreamConnection: System message <-31> recived
Jan 22 17:03:28 ?Debug : 1cab3700 StreamConnection: Challenge response sent
Jan 22 17:03:28 ?Debug : 1cab3700 StreamConnection: System message <-33> recived
Jan 22 17:03:28 Info : 1cab3700 StreamConnection: Connection successfully authorized, user id <-4>
Jan 22 17:03:28 ?Debug : 1cc377e0 StreamFirewall: Sending name: Сервер №2
Jan 22 17:03:28 ?Debug : 1cc377e0 StreamConnection: Sending message ID 0x3000
Jan 22 17:03:28 ?Debug : 1cab3700 StreamConnection: Got message ID 0x4000
Jan 22 17:03:28 ERROR : 1cab3700 StreamFirewall: Error occured: remote firewall is already connected
Jan 22 17:03:33 Info : 1cc377e0 UTM5 RFW: Terminating firewall: remote firewall is already connected

Писал в хотлайн - тикет еще не обработан, висит в новых уже четвертые сутки.

Версия и номер сборки: 5.3-001-update4-centos6_x64 Rev #13688
Полная версия дистрибутива операционной системы: CentOS 6.5 2.6.32-431.3.1.el6.x86_64
Версия СУБД: MariaDB 5.5.34, for Linux (x86_64)

alex_pnz

Почему ядро считает его "already connected"? Никто не сталкивался с подобным поведением? Или быть может я где-то ошибся и в упор не вижу ошибки?

psv · Сообщение **psv** » Чт янв 30, 2014 15:35

alex_pnz писал(а):Почему ядро считает его "already connected"? Никто не сталкивался с подобным поведением? Или быть может я где-то ошибся и в упор не вижу ошибки?

Возможно, стартует несколько процессов.
Что показывает
ps -H xa |grep utm
?

serjk · Сообщение **serjk** » Пт янв 31, 2014 10:07

Также заметил (netstat -anp), что висит соединение с уже выключенным rfw на стороне сервера с ядром, когда сервер с rfw выключен. Через некоторое время (минут через 10-13) это полумертвое соединение закрывается, и только тогда rfw может переподключиться к ядру.

Статус соединения какой при этом? Если можно, киньте вывод netstat

alex_pnz

Когда делаю остановку rfw на сервере №2 вручную

/etc/init.d/utm5_rfw stop

В логах utm5_core на сервере №1 появляются следующие записи:

Jan 31 15:34:23 ?Debug : 26beb700 StreamConnection: closing connection [37]
Jan 31 15:34:23 Info : 26beb700 StreamConnection: Connection from Сервер№2/57331 closed
Jan 31 15:34:23 ?Debug : 272f2700 StreamConnection: Sending message ID 0x2129
Jan 31 15:34:24 ERROR : 274f4700 RemoteFirewallManager: fw@Сервер№2: connection lost

и при ручном запуске происходит нормальное подключение.

Если делаю перезапуск сервера №2 (init 6). То после перезагрузки на нем:

ps -H xa | grep utm
2007 pts/3 S+ 0:00 grep utm

В rfw.log на сервере №2:

Jan 31 15:42:18 ?Debug : 9d0667e0 ModTop: Socket connected to: host <Сервер№1> port <12758>
Jan 31 15:42:18 Info : 9cee2700 StreamConnection: Connection thread started. Peer [Сервер№1]:12758
Jan 31 15:42:18 ?Debug : 9cee2700 StreamConnection: Connection using SSLv3
Jan 31 15:42:18 ?Debug : 9cee2700 StreamConnection: System message <-31> recived
Jan 31 15:42:18 ?Debug : 9cee2700 StreamConnection: Challenge response sent
Jan 31 15:42:18 ?Debug : 9cee2700 StreamConnection: System message <-33> recived
Jan 31 15:42:18 Info : 9cee2700 StreamConnection: Connection successfully authorized, user id <-4>
Jan 31 15:42:18 ?Debug : 9d0667e0 StreamFirewall: Sending name: Сервер№2
Jan 31 15:42:18 ?Debug : 9d0667e0 StreamConnection: Sending message ID 0x3000
Jan 31 15:42:18 ?Debug : 9cee2700 StreamConnection: Got message ID 0x4000
Jan 31 15:42:18 ERROR : 9cee2700 StreamFirewall: Error occured: remote firewall is already connected
Jan 31 15:42:23 Info : 9d0667e0 UTM5 RFW: Terminating firewall: remote firewall is already connected

В логе main.log на сервере №1:

Jan 31 15:42:18 Info : 26ded700 StreamConnection: Connection thread started. Peer [Сервер№2]:37973
Jan 31 15:42:18 Info : 26ded700 StreamConnection: Authorized user <rfw> from <Сервер№2>
Jan 31 15:42:18 ERROR : 26ded700 RemoteFirewallManager: remote firewall <Сервер№2> is already connected
Jan 31 15:42:23 Info : 26ded700 StreamConnection: Connection from Сервер№2/37973 closed

В логе debug.log на сервере №1:

Jan 31 15:42:18 Info : 26ded700 StreamConnection: Connection thread started. Peer [Сервер№2]:37973
Jan 31 15:42:18 ?Debug : 26ded700 StreamConnection: Connection using SSLv3
Jan 31 15:42:18 ?Debug : 26ded700 StreamConnection: System message <-30> recived
Jan 31 15:42:18 ?Debug : 26ded700 StreamConnection: Challenge key sent
Jan 31 15:42:18 ?Debug : 26ded700 StreamConnection: System message <-32> recived
Jan 31 15:42:18 Info : 26ded700 StreamConnection: Authorized user <rfw> from <Сервер№2>
Jan 31 15:42:18 ?Debug : 26ded700 StreamConnection: Got message ID 0x3000
Jan 31 15:42:18 ?Debug : 26ded700 DBConnectionPool: DBConnectioManager pool [Default]: connection is popped
Jan 31 15:42:18 ?Debug : 26ded700 DBConnection_mysql: <0x2bf3c40> SQL SELECT query: SELECT id,router_type,router_ip,login,password,router_comments,router
Jan 31 15:42:18 ?Debug : 26ded700 DBConnection_mysql: <0x2bf3c40> SQL SELECT query: 1 rows in 0.001 sec
Jan 31 15:42:18 ?Debug : 26ded700 DBConnectionPool: DBConnectionManager pool [Default]: connection is pushed back
Jan 31 15:42:18 ERROR : 26ded700 RemoteFirewallManager: remote firewall <Сервер№2> is already connected
Jan 31 15:42:18 ?Debug : 26ded700 StreamConnection: Sending message ID 0x4000
Jan 31 15:42:20 ?Debug : 270f0700 Scheduler: scheduled transaction Events [ 114, 136 ]
Jan 31 15:42:20 ?Debug : 270f0700 TransactionQueueManager: push: using default priority queue
Jan 31 15:42:20 ?Debug : 270f0700 TransactionQueueManager: push: transaction ptr [0x7ffbd80008c0] handler #1 ptr [0x2cc6530]
Jan 31 15:42:20 ?Debug : 270f0700 TransactionHandlerImpl: push: transaction ptr [d80008c0] (size 2, Events [ 114, 136 ])
Jan 31 15:42:20 ?Debug : 279f9700 TransactionHandlerImpl: current queue size: 1
Jan 31 15:42:20 ?Debug : 279f9700 TransactionHandlerImpl: incoming transaction ptr [d80008c0], outgoing transaction ptr [08000c90]
Jan 31 15:42:20 ?Debug : 279f9700 DBConnectionPool: DBConnectioManager pool [Default]: connection is popped
Jan 31 15:42:20 ?Debug : 279f9700 PluginManagerImpl: Got DynaShapePlugin plugin for event EventShapingCheckTimeranges/114
Jan 31 15:42:20 ?Debug : 279f9700 PluginManagerImpl: Got DynaShapePlugin plugin for event EventCheckTurboMode/136
Jan 31 15:42:20 ?Debug : 279f9700 TransactionFilter: transaction sent to the internal queue
Jan 31 15:42:20 ?Debug : 279f9700 TransactionQueueManager: push: using default priority queue
Jan 31 15:42:20 ?Debug : 279f9700 TransactionQueueManager: push: transaction ptr [0x7ffc08000c90] handler #0 ptr [0x2cc61e0]
Jan 31 15:42:20 ?Debug : 279f9700 TransactionHandlerImpl: push: empty transaction ptr [08000c90] dropped
Jan 31 15:42:20 ?Debug : 279f9700 DummyTransactionQueue: commit: 0 transactions
Jan 31 15:42:20 ?Debug : 279f9700 DBConnectionPool: DBConnectionManager pool [Default]: connection is pushed back
Jan 31 15:42:20 ?Debug : 279f9700 TransactionHandlerImpl: incoming transaction ptr [d80008c0] is done
Jan 31 15:42:20 ?Debug : 279f9700 DummyTransactionQueue: rollback: 0 transactions
Jan 31 15:42:23 ?Debug : 26ded700 StreamConnection: closing connection [39]
Jan 31 15:42:23 Info : 26ded700 StreamConnection: Connection from Сервер№2/37973 closed

И продолжается слаться безответное сообщение:

Jan 31 15:42:24 ?Debug : 274f4700 StreamConnection: Sending message ID 0x4004

Которое зависает в очереди на отправку полумертвого сокета:

[root@lambda:/home/alex_d/centos6]$ netstat -anp | grep Сервер№2
tcp 0 740 Сервер№1:12758 Сервер№2:57332 ESTABLISHED 15749/utm5_core

Как-то так....

psv · Сообщение **psv** » Пт янв 31, 2014 17:24

alex_pnz писал(а):Когда делаю остановку rfw на сервере №2 вручную
/etc/init.d/utm5_rfw stop
...

Кстати, заметил, что после выполнения такой команды всё равно rfw не останавливается.
Приходится ещё раз ёё выполнять ))).

alex_pnz

У меня тоже такое случается. Возможно, процесс некорректно убивается на сервере, поэтому не может сообщить ядру о своем выключении...
Проверка ядром процесса rfw выполняется странно: сообщения (типа пинга) посылаются ядром, но ответы на них не получает и на эту "тишину" от rfw не реагирует

alex_pnz

serjk писал(а): Статус соединения какой при этом? Если можно, киньте вывод netstat

[root@lambda:/home/alex_d/centos6]$ netstat -anp | grep Сервер№2
tcp 0 740 Сервер№1:12758 Сервер№2:57332 ESTABLISHED 15749/utm5_core

alex_pnz

Никаких вариантов в чем может быть дело?

serjk · Сообщение **serjk** » Чт фев 06, 2014 09:40

alex_pnz писал(а):Никаких вариантов в чем может быть дело?

Будем тестировать на centos6, может что всплывет. По имеющейся информации сложно сказать.

При перезагрузке сервера с RFW в логах ядра нет сообщений о разорванном соединении?

alex_pnz

serjk писал(а):
alex_pnz писал(а):Никаких вариантов в чем может быть дело?
Будем тестировать на centos6, может что всплывет. По имеющейся информации сложно сказать.

При перезагрузке сервера с RFW в логах ядра нет сообщений о разорванном соединении?

Таких сообщений нет