Решил поднять резервный сервер шейпинга.
в dynashape.cfg прописал необходимые параметры,
запихал в крон команду, чтобы utm5_dynashape
забирал с ядра необходимые данные. Запустил, проверил, что
все срабатывает нормально и ушел домой.
Сегодня утром обнаружил у себя в ящике около сотни писем со
следующим содержанием: utm5_core process exited ... Check it
Причем без какой-либо периодичности.
В main.log никакой информации об ошибках не было.
verificator.log не создавался, зато в debug.log было, предположительно, найдено откуда ноги растут:
Видим, как два модуля шейпинга подключаются, шлют свои запросы, и после этого ядро, не вернув ответа, перезагружается.Info : Sep 01 16:04:01 RPCConn[SSL]<init@82.179.90.226>: Access granted to [SSL]<init@82.179.90.226> (UID: -1)
?Debug : Sep 01 16:04:01 RPCConn[SSL]<init@82.179.90.226>: SSL type requested: SSLv3(2)
Info : Sep 01 16:04:01 RPCServer@0.0.0.0: Client connecting: 82.179.90.227:57887
Info : Sep 01 16:04:01 RPCConn: Connection from: 82.179.90.227:57887
?Debug : Sep 01 16:04:01 DBA Groups: Group: -1 from 1
-Stats : Sep 01 16:04:01 DBA Groups: Stats: Uptime: 00:00:00. Events: 0; Errors: 0
Info : Sep 01 16:04:01 RPCConn[SSL]<init@82.179.90.227>: Access granted to [SSL]<init@82.179.90.227> (UID: -1)
?Debug : Sep 01 16:04:01 RPCConn[SSL]<init@82.179.90.227>: SSL type requested: SSLv3(2)
?Debug : Sep 01 16:04:01 RPCConn[SSL]<init@82.179.90.226>: Call: 0x12001 (get_shape_param)
?Debug : Sep 01 16:04:01 RPCConn[SSL]<init@82.179.90.226>: Real Call: 0x12001 (get_shape_param)
?Debug : Sep 01 16:04:01 UTM5 DBA: DBAccess instance created
?Debug : Sep 01 16:04:01 DBA:Ctx: Looking for free context
?Debug : Sep 01 16:04:01 DBCtx: <149330904> SQL SELECT query: SELECT distinct ig.ip as ip,us.value, a.id as accountid,a.int_status,ig.mask,sl.id FROM accounts a,iptraffic_service_links il,service_links sl,services_data sd,ip_groups ig,utm
5_settings us WHERE a.id=sl.account_id AND a.is_deleted=0 AND sl.service_id=sd.id AND sd.tariff_id = us.variable AND sl.id=il.id AND ig.ip_group_id=il.ip_group_id AND sl.is_deleted=0 AND sd.is_deleted=0 AND ig.is_deleted=0 AND sd.servic
e_type=3 AND sd.tariff_id!=0 AND ig.ip_type=1 GROUP BY ig.ip,us.value,a.id,a.int_status,ig.mask,sl.id ORDER BY a.id
?Debug : Sep 01 16:04:01 RPCConn[SSL]<init@82.179.90.227>: Call: 0x12001 (get_shape_param)
?Debug : Sep 01 16:04:01 RPCConn[SSL]<init@82.179.90.227>: Real Call: 0x12001 (get_shape_param)
?Debug : Sep 01 16:04:01 UTM5 DBA: DBAccess instance created
?Debug : Sep 01 16:04:01 DBA:Ctx: Looking for free context
?Debug : Sep 01 16:04:01 DBCtx: <149018536> SQL SELECT query: SELECT distinct ig.ip as ip,us.value, a.id as accountid,a.int_status,ig.mask,sl.id FROM accounts a,iptraffic_service_links il,service_links sl,services_data sd,ip_groups ig,utm
5_settings us WHERE a.id=sl.account_id AND a.is_deleted=0 AND sl.service_id=sd.id AND sd.tariff_id = us.variable AND sl.id=il.id AND ig.ip_group_id=il.ip_group_id AND sl.is_deleted=0 AND sd.is_deleted=0 AND ig.is_deleted=0 AND sd.servic
e_type=3 AND sd.tariff_id!=0 AND ig.ip_type=1 GROUP BY ig.ip,us.value,a.id,a.int_status,ig.mask,sl.id ORDER BY a.id
?Debug : Sep 01 16:04:02 BusClassif: aggregation interval reached for slink <817> ip <1387485715> tclass <10>
?Debug : Sep 01 16:04:02 UTM5 DBA: DBAccess instance created
?Debug : Sep 01 16:04:02 DBA:Ctx: Looking for free context
?Debug : Sep 01 16:04:02 DBCtx: <148992536> SQL query: BEGIN
?Debug : Sep 01 16:04:02 DBCtx: DB transaction begin
?Debug : Sep 01 16:04:02 DBCtx: <148992536> SQL SELECT query: SELECT discounted,qnt,downed_as_prepaid FROM downloaded WHERE is_deleted=0 AND downloaded_id='470' AND tclass_id='10'
?Debug : Sep 01 16:04:02 DBCtx: <148992536> SQL query: UPDATE downloaded SET qnt='28855090', discounted='0', downed_as_prepaid='0' WHERE downloaded_id='470' AND tclass_id='10'
?Debug : Sep 01 16:04:02 DBCtx: <148992536> SQL query: UPDATE dtagg_iptraffic SET discounted='0.000000', discounted_without_tax='0.000000', bytes='28855090' WHERE id='347306'
?Debug : Sep 01 16:04:02 UTM5 DBA: Charge:0.000000 p.u. for link:817 account 449
?Debug : Sep 01 16:04:02 DBCtx: <148992536> SQL query: UPDATE accounts SET balance='0' WHERE id = '449'
?Debug : Sep 01 16:04:02 DBCtx: <148992536> SQL query: INSERT INTO discount_transactions_all(account_id,incoming_rest,outgoing_rest,discount,discount_with_tax,service_id,service_type,slink_id,discount_date,charge_type,discount_period_id)
VALUES('449','0','0','0','0','29','3','817','1314878642','3','31599')
?Debug : Sep 01 16:04:02 UTM5 DBA: Checking for rehash: flags 3, balance 0.000 (old 0.000), credit 0.000
?Debug : Sep 01 16:04:02 DBAGiga: Rehash: Target: 10; Action: 1; Ptr: f7285e58
?Debug : Sep 01 16:04:02 Radius: Account '449': 0.000/0.000 send...
?Debug : Sep 01 16:04:02 BusLogic: BLM(37) pushed (comment: ruh block)
?Debug : Sep 01 16:04:02 DBCtx: <148992536> SQL query: INSERT INTO discount_transactions_iptraffic_all(id,account_id,discount,discount_with_tax,service_id,slink_id,discount_date,discount_date_hour,discount_date_day,discount_date_month,t_c
lass,base_cost,ipid,bytes,discount_period_id) VALUES('1484','449','0','0','29','817','1314878642','1314878400','1314820800','1314820800','10','0','1387485715','174773','31599')
?Debug : Sep 01 16:04:02 BusLogic: try to execute 37
?Debug : Sep 01 16:04:02 BusLogic: hw_block_handler with code 37
?Debug : Sep 01 16:04:02 BusLogic: finished unknown
?Debug : Sep 01 16:04:02 DBCtx: <148992536> SQL query: COMMIT
?Debug : Sep 01 16:04:02 DBCtx: DB transaction commit
?Debug : Sep 01 16:04:02 DBA:Ctx: Pushing back free context
-Stats : Sep 01 16:04:02 UTM5 DBA: Stats: Uptime: 00:00:00. Events: 0; Errors: 0
?Debug : Sep 01 16:04:02 FW@82.179.90.1: Ping reply received
Info : Sep 01 16:04:32 UTM5 Logger: New `?Debug : ' stream: /var/log/utm5/debug.log
Info : Sep 01 16:04:32 UTM5 Logger: New ` Info : ' stream: /var/log/utm5/main.log
?Debug : Sep 01 16:04:32 ModMap: Module <config> exist
?Debug : Sep 01 16:04:32 ModMap: Module <logger> exist
?Debug : Sep 01 16:04:32 ModMap: Module <rehash> exist
Info : Sep 01 16:04:32 DBA:Ctx: Creating 16 DB connections
?Debug : Sep 01 16:04:32 DBCtx: Connecting to MySQL database
Причем
в большинстве случаев ядро все-таки возвращает шейперу необходимые данные и в логе это отображается следующим сообщением:
RPCConn[SSL]<init@82.179.90.22(6|7)>: Call 0x12001 (get_shape_param) finished...
и перезапуск самого ядра не происходит.
После отключения резервного шейпера падения ядра прекратились.
Судя по показаниям системы мониторинга, потребление проца и памяти
во время падений увеличивалось незначительно и связано, скорее всего, с перезапуском utm5_core.
Возникает два вопроса:
Это особенность самого ядра, то что он не может работать с двумя шейперами или в чем-то другом?
Как можно Это исправить/обойти?
Биллинг: 5.2.1-006-update7
ОС: Centos 5.6 x86-64
Все это работает под VMware ESX на виртуальной машине с характеристиками: 4-ядра Xeon E5345, 4Gb оперативы