после сбоя на сервере - ошибка 718 у всех

rusamg · Сообщение **rusamg** » Вт июн 29, 2010 10:46

Добрый день

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

после этого ни один пользователь не смог авторизоваться, у всех вылезает 718 ошибка, плюс обратил внимание - процесс utm5_core занимает до 99% в топе

никакие конфиги, ничего не правилось и не менялось,

с чего начинать поиски ?
логи внизу, сбой произошел почти в 18 часов
----------------
localhost# uname -a
FreeBSD localhost 6.2-RELEASE FreeBSD

----------------
last pid: 15751; load averages: 1.00, 1.00, 0.83 up 0+00:25:35 11:28:48
79 processes: 2 running, 77 sleeping
CPU states: 100% user, 0.0% nice, 0.0% system, 0.0% interrupt, 0.0% idle
Mem: 54M Active, 19M Inact, 46M Wired, 48K Cache, 30M Buf, 2826M Free
Swap: 4096M Total, 4096M Free

PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND
9133 root 2 124 0 10500K 9100K RUN 24:38 98.97% utm5_core
9761 root 2 20 0 5236K 3260K kserel 0:05 0.00% utm5_radius
918 root 23 20 0 12076K 6880K kserel 0:04 0.00% mpd4
786 root 1 96 0 1380K 1036K select 0:01 0.00% syslogd

-----------------

Notice: Jun 28 17:55:08 AuthServer: Authorization failed for user <inet658124>
ERROR : Jun 28 17:55:38 RADIUS DBA: Can't find login <inet863998>
ERROR : Jun 28 17:55:38 RADIUS DBA: Card login <inet863998> contains not digit symbol with code <105> ! Can't find card login
ERROR : Jun 28 17:55:38 AuthServer: No data for User <inet863998> found.
Notice: Jun 28 17:55:43 AuthServer: Login incorrect <inet658124> from NAS <10.128.1.137> CLID <> Calling-station <10.1.81.78>
Notice: Jun 28 17:55:43 AuthServer: Authorization failed for user <inet658124>
Notice: Jun 28 17:55:47 AuthServer: Login incorrect <inet2901910> from NAS <10.128.1.137> CLID <> Calling-station <10.1.41.53>
Notice: Jun 28 17:55:47 AuthServer: Authorization failed for user <inet2901910>
Notice: Jun 28 17:55:54 AuthServer: Login incorrect <inet111> from NAS <10.128.1.137> CLID <> Calling-station <10.1.102.10>
Notice: Jun 28 17:55:54 AuthServer: Authorization failed for user <inet111>
Notice: Jun 28 17:56:00 AuthServer: Login incorrect <inet503921> from NAS <10.128.1.137> CLID <> Calling-station <10.1.94.54>
Notice: Jun 28 17:56:00 AuthServer: Authorization failed for user <inet503921>
Notice: Jun 28 17:56:19 AuthServer: Login incorrect <inet658124> from NAS <10.128.1.137> CLID <> Calling-station <10.1.81.78>
Notice: Jun 28 17:56:19 AuthServer: Authorization failed for user <inet658124>
Info : Jun 28 17:58:15 UTM5 Logger: New ` Info : ' stream: /netup/utm5/log/radius_main.log
Notice: Jun 28 17:58:15 RADIUS Config: interim_update_interval less than 60 sec! Setting it to 60 sec ...
Info : Jun 28 17:58:15 StreamManager: Registering message handlers..
Info : Jun 28 17:58:15 StreamManager: ID <0x2001> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2002> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2003> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2004> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2005> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2006> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2007> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2008> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2030> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2031> handler <0x0810f680>
ERROR : Jun 28 17:58:15 StreamManager: connect failed: Connection refused
Info : Jun 28 17:58:15 RadiusSocket: Listening on 0.0.0.0:1812
Info : Jun 28 17:58:15 RadiusSocket: Listening on 0.0.0.0:1813
ERROR : Jun 28 17:58:45 StreamManager: connect failed: Connection refused
ERROR : Jun 28 17:59:15 StreamManager: connect failed: Connection refused
ERROR : Jun 28 17:59:45 StreamManager: connect failed: Connection refused
ERROR : Jun 28 18:00:15 StreamManager: connect failed: Connection refused
ERROR : Jun 28 18:00:45 StreamManager: connect failed: Connection refused
ERROR : Jun 28 18:01:15 StreamManager: connect failed: Connection refused
ERROR : Jun 28 18:01:45 StreamManager: connect failed: Connection refused
ERROR : Jun 28 18:02:15 StreamManager: connect failed: Connection refused
ERROR : Jun 28 18:02:45 StreamManager: connect failed: Connection refused

--------------------

%
ERROR : Jun 28 23:24:11 StreamManager: connect failed: Connection refused
?Debug : Jun 28 23:24:11 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 23:24:41 StreamManager: connect failed: Connection refused
?Debug : Jun 28 23:24:41 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 23:25:11 StreamManager: connect failed: Connection refused
?Debug : Jun 28 23:25:11 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 23:25:41 StreamManager: connect failed: Connection refused
?Debug : Jun 28 23:25:41 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 23:26:11 StreamManager: connect failed: Connection refused
?Debug : Jun 28 23:26:11 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 23:26:41 StreamManager: connect failed: Connection refused
?Debug : Jun 28 23:26:41 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 23:27:11 StreamManager: connect failed: Connection refused
?Debug : Jun 28 23:27:11 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 23:27:41 StreamManager: connect failed: Connection refused
?Debug : Jun 28 23:27:41 RADIUS Config: Unable to connect, waiting for 30 sec..

-------------------------------

?Debug : Jun 28 17:56:24 RADIUS DBA: No interim update enabled session <67> found. Setting to default (if enabled).
?Debug : Jun 28 17:56:24 RADIUS DBA: No interim update enabled session <68> found. Setting to default (if enabled).
?Debug : Jun 28 17:56:24 RADIUS DBA: No interim update enabled session <69> found. Se.............................................
Info : Jun 28 17:58:15 UTM5 Logger: New ` Info : ' stream: /netup/utm5/log/radius_main.log
Notice: Jun 28 17:58:15 RADIUS Config: interim_update_interval less than 60 sec! Setting it to 60 sec ...
?Debug : Jun 28 17:58:15 RADIUS Config: Using classic BaseTelephony
?Trace : Jun 28 17:58:15 RADIUS DBA: New state: ds_failed
Info : Jun 28 17:58:15 StreamManager: Registering message handlers..
Info : Jun 28 17:58:15 StreamManager: ID <0x2001> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2002> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2003> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2004> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2005> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2006> handler <0x0810f680>

Info : Jun 28 17:58:15 StreamManager: ID <0x202e> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x202f> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2030> handler <0x0810f680>
Info : Jun 28 17:58:15 StreamManager: ID <0x2031> handler <0x0810f680>
ERROR : Jun 28 17:58:15 StreamManager: connect failed: Connection refused
Info : Jun 28 17:58:15 RadiusSocket: Listening on 0.0.0.0:1812
?Trace : Jun 28 17:58:15 AuthServer: Entering process loop
Info : Jun 28 17:58:15 RadiusSocket: Listening on 0.0.0.0:1813
?Debug : Jun 28 17:58:15 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 17:58:45 StreamManager: connect failed: Connection refused
?Debug : Jun 28 17:58:45 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 17:59:15 StreamManager: connect failed: Connection refused
?Debug : Jun 28 17:59:15 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 17:59:45 StreamManager: connect failed: Connection refused
?Debug : Jun 28 17:59:45 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 18:00:15 StreamManager: connect failed: Connection refused
?Debug : Jun 28 18:00:15 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 18:00:45 StreamManager: connect failed: Connection refused
?Debug : Jun 28 18:00:45 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 18:01:15 StreamManager: connect failed: Connection refused
?Debug : Jun 28 18:01:15 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 18:01:45 StreamManager: connect failed: Connection refused
?Debug : Jun 28 18:01:45 RADIUS Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 18:02:15 StreamManager: connect failed: Connection refused
?Debug : Jun 28 18:02:15 RADIUS Config: Unable to connect, waiting for 30 sec..

--------------------------

?Debug : Jun 28 17:53:15 StreamFirewall: Got ping from core. Sending reply...
?Debug : Jun 28 17:53:45 StreamFirewall: Got ping from core. Sending reply...
?Debug : Jun 28 17:54:15 StreamFirewall: Got ping from core. Sending reply...
?Debug : Jun 28 17:54:45 StreamFirewall: Got ping from core. Sending reply...
?Debug : Jun 28 17:55:15 StreamFirewall: Got ping from core. Sending reply...
?Debug : Jun 28 17:55:45 StreamFirewall: Got ping from core. Sending reply...
?Debug : Jun 28 17:56:15 StreamFirewall: Got ping from core. Sending reply...
Info : Jun 28 17:58:15 UTM5 Logger: New ` Info : ' stream: /netup/utm5/log/rfw.log
Info : Jun 28 17:58:15 UTM5 Logger: New `?Debug : ' stream: /netup/utm5/log/rfw.log
Info : Jun 28 17:58:15 UTM5 Logger: New `?Debug : ' stream: /netup/utm5/log/rfw.log
ERROR : Jun 28 17:58:15 StreamManager: connect failed: Connection refused
ERROR : Jun 28 17:58:15 StreamManager: connect failed: Connection refused
?Debug : Jun 28 17:58:15 RFW Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 17:58:45 StreamManager: connect failed: Connection refused
ERROR : Jun 28 17:58:45 StreamManager: connect failed: Connection refused
?Debug : Jun 28 17:58:45 RFW Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 17:59:15 StreamManager: connect failed: Connection refused
ERROR : Jun 28 17:59:15 StreamManager: connect failed: Connection refused
?Debug : Jun 28 17:59:15 RFW Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 17:59:45 StreamManager: connect failed: Connection refused
ERROR : Jun 28 17:59:45 StreamManager: connect failed: Connection refused
?Debug : Jun 28 17:59:45 RFW Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 18:00:15 StreamManager: connect failed: Connection refused
ERROR : Jun 28 18:00:15 StreamManager: connect failed: Connection refused
?Debug : Jun 28 18:00:15 RFW Config: Unable to connect, waiting for 30 sec..
ERROR : Jun 28 18:00:45 StreamManager: connect failed: Connection refused
ERROR : Jun 28 18:00:45 StreamManager: connect failed: Connection refused
----------------------

погибаю, помогите ! )

Anton · Сообщение **Anton** » Вт июн 29, 2010 10:49

смотри вертификатор лог
у тебя походу ядро не стартануло

а радиус не может к нему подключится

если мпд
выдирай все записи
и сделай mpd.secure

чтобы народ авторизовался
а так у тебя что то с ядром

rusamg · Сообщение **rusamg** » Вт июн 29, 2010 11:03

Anton писал(а):смотри вертификатор лог
у тебя походу ядро не стартануло

а радиус не может к нему подключится

если мпд
выдирай все записи
и сделай mpd.secure

чтобы народ авторизовался
а так у тебя что то с ядром

куда смотреть, я дуб дубом в этом, а компетентный человек в отпуске

вот кусок верификатор.лог

-------------------

%
-- UPDATE service_links SET is_deleted=1 WHERE id='2352';
-- UPDATE periodic_service_links SET is_deleted=1 WHERE id='2352';

-- ERROR Periodic link 2353 linked to deleted discount period 6194
-- SQL DESC undelete discount period
UPDATE discount_periods SET is_expired=0 WHERE id='6194';

-- ERROR link 2353, wrong tariff id
-- SQL DESC delete broken link (NOT RECOMMENDED)
-- UPDATE service_links SET is_deleted=1 WHERE id='2353';
-- UPDATE periodic_service_links SET is_deleted=1 WHERE id='2353';
-- UPDATE iptraffic_service_links SET is_deleted=1 WHERE id='2353';

-- ERROR link 2353, account tariff link id 996, not equal discount period ids
-- SQL DESC delete broken link (NOT RECOMMENDED)
-- UPDATE service_links SET is_deleted=1 WHERE id='2353';
-- UPDATE periodic_service_links SET is_deleted=1 WHERE id='2353';
-- UPDATE iptraffic_service_links SET is_deleted=1 WHERE id='2353';

-- WARNING lost IP group 0
-- SQL DESC delete ip group
UPDATE ip_groups SET is_deleted=1 WHERE ip_group_id='0';

-- WARNING lost IP group 851
-- SQL DESC delete ip group
UPDATE ip_groups SET is_deleted=1 WHERE ip_group_id='851';
---------------

а про мпд я вообще не понял, что с ним делать

xxxupg · Сообщение **xxxupg** » Вт июн 29, 2010 11:10

проще удалить старые логи... потом стоп коре и старт коре... и смотреть что в логах сразу после старта пишется.

rusamg · Сообщение **rusamg** » Вт июн 29, 2010 12:16

xxxupg писал(а):проще удалить старые логи... потом стоп коре и старт коре... и смотреть что в логах сразу после старта пишется.

localhost# /netup/utm5/bin/safe_utm5_core stop
Stopping utm5_core
localhost# /netup/utm5/bin/safe_utm5_core start
Starting utm5_core
?Debug : Jun 29 13:09:24 Rehash: Rehash manager started
Notice: Jun 29 13:09:24 ModMap: Sub-Module 'rehash' inserted...
Notice: Jun 29 13:09:24 UTM5 Config: Processing config file: /netup/utm5/utm5.cfg
?Debug : Jun 29 13:09:24 ModMap: Module <rehash> exist
Notice: Jun 29 13:09:24 ModMap: Sub-Module 'config' inserted...
?Debug : Jun 29 13:09:24 ModMap: Module <config> exist
?Debug : Jun 29 13:09:24 ModMap: Module <rehash> exist
Notice: Jun 29 13:09:24 ModMap: Sub-Module 'logger' inserted...
*ALERT : Jun 29 13:09:25 UTM5 DBA: Service link <2254> from user_id <562> is broken and disabled. See verificator.log for details
*ALERT : Jun 29 13:09:25 UTM5 DBA: Service link <2255> from user_id <562> is broken and disabled. See verificator.log for details
*ALERT : Jun 29 13:09:25 UTM5 DBA: Service link <2352> from user_id <549> is broken and disabled. See verificator.log for details
*ALERT : Jun 29 13:09:25 UTM5 DBA: Service link <2353> from user_id <549> is broken and disabled. See verificator.log for details

rusamg · Сообщение **rusamg** » Вт июн 29, 2010 13:57

друзья
я правильно понимаю, что сбой на уровне mpd - utm5_core, то есть смотреть куда-то в их сторону

у меня уже голова квадратная, я нихрена в этом не понимаю, теоретически - что могло обсыпаться в результате сбоя файловой системы ?

rusamg · Сообщение **rusamg** » Вт июн 29, 2010 20:03

вот еще лог mpd

%
Jun 29 20:55:35 localhost mpd: PROTOCOMP
Jun 29 20:55:35 localhost mpd: MAGICNUM 39360e74
Jun 29 20:55:35 localhost mpd: MRU 1462
Jun 29 20:55:35 localhost mpd: [i20] LCP: SendConfigAck #1
Jun 29 20:55:35 localhost mpd: ACFCOMP
Jun 29 20:55:35 localhost mpd: PROTOCOMP
Jun 29 20:55:35 localhost mpd: MAGICNUM 39360e74
Jun 29 20:55:35 localhost mpd: MRU 1462
Jun 29 20:55:35 localhost mpd: PPTP: Incoming control connection from 10.1.91.11 4969 to 10.128.1.137 1723
Jun 29 20:55:35 localhost mpd: pptp18: attached to connection with 10.1.91.11 4969
Jun 29 20:55:36 localhost mpd: pptp24: no reply to StopCtrlConnRequest after 3 sec
Jun 29 20:55:36 localhost mpd: pptp24: killing connection with 10.1.92.41 65535
Jun 29 20:55:36 localhost mpd: [i20] LCP: SendConfigReq #17
Jun 29 20:55:36 localhost mpd: ACFCOMP
Jun 29 20:55:36 localhost mpd: PROTOCOMP
Jun 29 20:55:36 localhost mpd: MRU 1400
Jun 29 20:55:36 localhost mpd: MAGICNUM ef9a5a84
Jun 29 20:55:36 localhost mpd: AUTHPROTO CHAP MSOFTv2
Jun 29 20:55:36 localhost mpd: MP MRRU 1600
Jun 29 20:55:36 localhost mpd: MP SHORTSEQ
Jun 29 20:55:36 localhost mpd: ENDPOINTDISC [802.1] 00 02 55 53 e5 92
Jun 29 20:55:36 localhost mpd: [i20] LCP: rec'd Configure Reject #17 (Ack-Sent)
Jun 29 20:55:36 localhost mpd: MP MRRU 1600
Jun 29 20:55:36 localhost mpd: MP SHORTSEQ
Jun 29 20:55:36 localhost mpd: ENDPOINTDISC [802.1] 00 02 55 53 e5 92
Jun 29 20:55:36 localhost mpd: [i20] LCP: SendConfigReq #18
Jun 29 20:55:36 localhost mpd: ACFCOMP
Jun 29 20:55:36 localhost mpd: PROTOCOMP
Jun 29 20:55:36 localhost mpd: MRU 1400
Jun 29 20:55:36 localhost mpd: MAGICNUM ef9a5a84
Jun 29 20:55:36 localhost mpd: AUTHPROTO CHAP MSOFTv2
Jun 29 20:55:36 localhost mpd: [i20] LCP: rec'd Configure Request #1 (Ack-Sent)
Jun 29 20:55:36 localhost mpd: ACFCOMP
Jun 29 20:55:36 localhost mpd: PROTOCOMP
Jun 29 20:55:36 localhost mpd: MAGICNUM 39360e74
Jun 29 20:55:36 localhost mpd: MRU 1462
Jun 29 20:55:36 localhost mpd: [i20] LCP: SendConfigAck #1
Jun 29 20:55:36 localhost mpd: ACFCOMP
Jun 29 20:55:36 localhost mpd: PROTOCOMP
Jun 29 20:55:36 localhost mpd: MAGICNUM 39360e74
Jun 29 20:55:36 localhost mpd: MRU 1462
Jun 29 20:55:36 localhost mpd: [i20] LCP: rec'd Configure Nak #18 (Ack-Sent)
Jun 29 20:55:36 localhost mpd: AUTHPROTO CHAP MD5
Jun 29 20:55:36 localhost mpd: [i20] LCP: SendConfigReq #19
Jun 29 20:55:36 localhost mpd: ACFCOMP
Jun 29 20:55:36 localhost mpd: PROTOCOMP
Jun 29 20:55:36 localhost mpd: MRU 1400
Jun 29 20:55:36 localhost mpd: MAGICNUM ef9a5a84
Jun 29 20:55:36 localhost mpd: AUTHPROTO CHAP MD5

rusamg · Сообщение **rusamg** » Вт июн 29, 2010 20:56

починили

структура базы данных была нарушена

о так от

TiRider

Я писал целую статью здесь. Кто столкнулся. Нажмет поиск и найдет: Ошибка базы UTM5. Там подробно все по полочкам изложено, что чего и почем. Хотя проблема не совсем идентичная, но человек который понимает, устранит ее за 20 минут.

KSkostja

вырубило свет и теперь радиус ни кого не пускает что делать.

Info : Aug 24 15:49:37 RadiusSocket: Listening on 0.0.0.0:1812
Info : Aug 24 15:49:37 RadiusSocket: Listening on 0.0.0.0:1813
?Trace : Aug 24 15:49:37 AuthServer: Entering process loop
ERROR : Aug 24 15:49:38 StreamManager: connect failed: 10061
?Debug : Aug 24 15:49:38 RADIUS Config: Unable to connect, waiting for 30 sec..
Info : Aug 24 15:50:08 StreamConnection: Connection thread started. Peer 127.0.0.1:12758
?Debug : Aug 24 15:50:08 StreamConnection: Connection using TCP socket
?Debug : Aug 24 15:50:08 StreamConnection: System message recived
?Debug : Aug 24 15:50:08 StreamConnection: Challenge response sent
?Debug : Aug 24 15:50:08 StreamConnection: System message recived
Info : Aug 24 15:50:08 StreamConnection: Connection successfully authorized, user id <-2>
Info : Aug 24 15:50:13 StreamConnection: Connection from 127.0.0.1:12758 closed

Chris · Сообщение **Chris** » Вт авг 24, 2010 22:30

Что делать что делать, смотреть логи коры

KSkostja

как вылечить.

-- Verificator
-- You have to backup UTM5 database!
-- Affected tables list at the end of file

-- ERROR broken ip traffic link 76, ip group 76 not exist
-- SQL DESC delete slink (NOT RECOMMENDED)
-- UPDATE service_links SET is_deleted=1 WHERE id='76';
-- UPDATE periodic_service_links SET is_deleted=1 WHERE id='76';
-- UPDATE iptraffic_service_links SET is_deleted=1 WHERE id='76';

-- 1 errors
-- 0 warnings
-- affected tables: iptraffic_service_links periodic_service_links service_links
-- RESTART utm5_core!

mikkey finn

найти в админке сервисную связку с id=76, отредактировать ее или удалить.