Вытащил лог биллинга - помогите разобрать
Копирую свой пост с другого форума.
Дальше возникла следующая заморочка:
Дозвонился, ввожу пинкод карты, мне отвечает, что пинкод неправильный. Лезу в админку, смотрю что карта добавилась. Смотрю в её свойствах - нет услуги.
Создал фиктивную услугу, скопировал в неё цены с основной. Поставил галочку "добавлять по умолчанию". В базовой услуге эта галочка не активна.
При вводе пинкода уже другой карты, она добавилась, услуга завелась, но в ответ всё же пишет, что "неправильно введен пинкод.
Да ещё карты при автодобавлени (автоактивации) в списке красными нарисованы, если изменить в них параметр "Интернет" на "включен", то карточные пользователи становятся зелеными. Тем не менее на результат ввода пинкода это не влияет.
Вот что нашёл Debug.log
Код: Выделить всё
?Debug : Nov 19 12:03:36 Radius: init_session_log id <2>
?Debug : Nov 19 12:03:36 DBCtx: <679506944> SQL query: INSERT INTO tel_sessions_log(account_id,slink_id,recv_date,last_update_date, NAS_Port,Acct_Delay_Time, Acct_Session_Id,NAS_Port_Type,User_Name,Service_Type,Framed_Protocol,NAS_IP_Address,NAS_Id,Acct_Status_Type, Acct_Input_Packets,Acct_Input_Octets,Acct_Input_Gigawords,Acct_Output_Packets,Acct_Output_Octets,Acct_Output_Gigawords, Acct_Session_Time,Acct_Terminate_Cause,Called_Station_Id,Calling_Station_Id,h323_remote_address,h323_conf_id, h323_setup_time,h323_call_origin, h323_call_type,h323_connect_time,h323_disconnect_time,h323_disconnect_cause, h323_gw_id,zone_id,did,session_start_date) VALUES('3','3','1258625016','1258625016','0','0','00000042','0','74012','1','0','50243776','192.168.254.2','1','0','0','0','0','0','0','0','0','570235','74012','','h323-conf-id=A348F4B4 D42911DE 803BAE22 418E4AC0','h323-setup-time=12\:03\:36.592 EET Thu Nov 19 2009','h323-call-origin=answer','h323-call-type=Telephony','','','','h323-gw-id=Router.','0','0','1258625016')
?Debug : Nov 19 12:03:36 Radius: Dynamic IP binding not called because ip or slink is null ! ip <0> slink <3>
?Debug : Nov 19 12:03:50 UTM5 DBA: DBAccess instance created
?Debug : Nov 19 12:03:50 DBA:Ctx: Looking for free context
?Debug : Nov 19 12:03:50 DBCtx: <679515136> SQL query: BEGIN
?Debug : Nov 19 12:03:50 DBCtx: DB transaction begin
?Debug : Nov 19 12:03:50 DBCtx: <679515136> SQL SELECT query: SELECT id,pool_id,secret,balance,currency,expiration,days,is_used,service_id,is_blocked FROM card_info WHERE secret='000397717964'
?Debug : Nov 19 12:03:50 DBCtx: <679515136> SQL SELECT query: SELECT value FROM utm5_settings WHERE variable='card_user_prefix'
?Debug : Nov 19 12:03:50 DBCtx: <679515136> SQL SELECT query: SELECT id,pool_id,secret,balance,currency,expiration,days,is_used,service_id,is_blocked FROM card_info WHERE id='3'
?Debug : Nov 19 12:03:50 DBCtx: <679515136> SQL SELECT query: SELECT pool_id,cards,cards_used,first_update,last_update FROM card_pool_info WHERE pool_id='1'
?Debug : Nov 19 12:03:50 DBCtx: <679515136> SQL SELECT query: SELECT user_id FROM card_pool_owners WHERE pool_id ='1' AND is_deleted = 0
?Debug : Nov 19 12:03:50 DBCtx: <679515136> SQL SELECT query: SELECT id,pool_id,secret,balance,currency,expiration,days,is_used,service_id,is_blocked FROM card_info WHERE id='3'
Warn : Nov 19 12:03:50 UTM5 DBA: add_user_card_priv: card <3> is already used
?Debug : Nov 19 12:03:50 DBCtx: <679515136> SQL query: COMMIT
?Debug : Nov 19 12:03:50 DBCtx: DB transaction commit
?Debug : Nov 19 12:03:50 DBA:Ctx: Pushing back free context
-Stats : Nov 19 12:03:50 UTM5 DBA: Stats: Uptime: 00:00:00. Events: 0; Errors: 0
?Debug : Nov 19 12:03:56 DBCtx: <679506944> SQL query: INSERT INTO tel_sessions_detail(dhs_sess_id,disc_per_id,slink_id,recv_date,account_id,trange_id,duration,base_cost,sum_cost) VALUES('10','3','3','1258625036','3','0','20','0','0')
?Debug : Nov 19 12:03:56 UTM5 DBA: DBAccess instance created
?Debug : Nov 19 12:03:56 DBA:Ctx: Looking for free context
?Debug : Nov 19 12:03:56 DBCtx: <679511040> SQL query: BEGIN
?Debug : Nov 19 12:03:56 DBCtx: DB transaction begin
?Debug : Nov 19 12:03:56 UTM5 DBA: discount_from_account tel zoneid <0> h.base_cost <0.000000>
?Debug : Nov 19 12:03:56 DBCtx: <679506944> SQL query: UPDATE dtagg_telephony SET discounted='0.000000',discounted_without_tax='0.000000', duration='68' WHERE id='1'
?Debug : Nov 19 12:03:56 UTM5 DBA: Charge:0.000000 p.u. for link:3 account 3
?Debug : Nov 19 12:03:56 DBCtx: <679511040> SQL query: UPDATE accounts SET balance='1' WHERE id = '3'
?Debug : Nov 19 12:03:56 DBCtx: <679511040> 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('3','1','1','0','0','1','6','3','1258625036','6','3')
?Debug : Nov 19 12:03:56 UTM5 DBA: Checking for rehash: flags 3, balance 1.000 (old 1.000), credit 0.000
?Debug : Nov 19 12:03:56 DBAGiga: Rehash: Target: 10; Action: 1; Ptr: bc7e8a0c
?Debug : Nov 19 12:03:56 Radius: Account '3': 1.000/0.000 send...
?Debug : Nov 19 12:03:56 HSPlugin: Rehash: Target: 10; Action: 1; Ptr: bc7e8a0c
?Debug : Nov 19 12:03:56 BusLogic: BLM(37) pushed (comment: ruh block)
?Debug : Nov 19 12:03:56 DBCtx: <679511040> SQL query: COMMIT
?Debug : Nov 19 12:03:56 BusLogic: try to execute 37
?Debug : Nov 19 12:03:56 BusLogic: hw_block_handler with code 37
?Debug : Nov 19 12:03:56 BusLogic: finished unknown
?Debug : Nov 19 12:03:56 DBCtx: DB transaction commit
?Debug : Nov 19 12:03:56 DBA:Ctx: Pushing back free context
-Stats : Nov 19 12:03:56 UTM5 DBA: Stats: Uptime: 00:00:00. Events: 0; Errors: 0
?Debug : Nov 19 12:03:56 Radius: edit_session_log id <2> input octets <0> output octet <60480>
?Debug : Nov 19 12:03:56 Radius: session log with id <2> found in the cache
?Debug : Nov 19 12:03:56 DBCtx: <679506944> SQL query: UPDATE tel_sessions_log SET account_id='3', slink_id='3', last_update_date='1258625036', Acct_Status_Type='2', Acct_Input_Packets ='0', Acct_Input_Octets ='0', Acct_Input_Gigawords ='0', Acct_Output_Packets ='252', Acct_Output_Octets ='60480', Acct_Output_Gigawords ='0', h323_connect_time='', Acct_Terminate_Cause='0', h323_disconnect_cause='h323-disconnect-cause=11', Acct_Session_Time ='20' WHERE id='10'
?Debug : Nov 19 12:03:56 Radius: id2core removing key <2>
А вот что сыпется в radius.log
Код: Выделить всё
?Debug : Nov 19 12:03:36 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 19 12:03:36 AcctServer: Acct packet with session ID: 00000042
?Debug : Nov 19 12:03:36 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 19 12:03:36 AcctServer: Acct-Start packet
?Debug : Nov 19 12:03:36 AcctServer: Acct-Start: User <74012>
?Debug : Nov 19 12:03:36 AcctServer: Acct-Session-Time (46) not present in accounting packet.
?Debug : Nov 19 12:03:36 RADIUS DBA: Info for login <74012> found. type <3>
?Debug : Nov 19 12:03:36 RADIUS DBA: Password found for tel login:74012
?Debug : Nov 19 12:03:36 RADIUS DBA: info for user found. type <3> info addr <677436416>
?Debug : Nov 19 12:03:36 RADIUS DBA: search_user_info return info <677436416>
?Debug : Nov 19 12:03:36 RADIUS DBA: search_user_info return valid info
?Debug : Nov 19 12:03:36 RADIUS DBA: Setting interim interval <0> for session id <00000042>
?Debug : Nov 19 12:03:36 RADIUS DBA: TELTARIFF: called number <570235> calling number <74012> direction id <0> zone id <0>
?Debug : Nov 19 12:03:36 RADIUS DBA: tel.session_count incremented. value <1>
?Debug : Nov 19 12:03:36 RADIUS DBA: Calling send_session_log_init_sync ...
?Debug : Nov 19 12:03:36 RADIUS Stream[plugin]: send_session_log_init_sync
?Debug : Nov 19 12:03:36 RADIUS Stream[plugin]: init log id <2>
?Debug : Nov 19 12:03:36 AcctServer: Reply packet dump: RPacket:
Code: 5; ID: 99
?Debug : Nov 19 12:03:36 RadiusSocket: Moving RADIUS packet into send queue
?Debug : Nov 19 12:03:36 RadiusSocket: RADIUS raw data sent
?Debug : Nov 19 12:03:36 AcctServer: Next...
?Debug : Nov 19 12:03:36 RadiusSocket: Waiting for RADIUS raw data
?Debug : Nov 19 12:03:49 RADIUS DBA: No interim update enabled session <2> found. Setting to default (if enabled).
?Debug : Nov 19 12:03:50 RadiusSocket: RADIUS packet successfully received
?Debug : Nov 19 12:03:50 RadiusSocket: RADIUS raw data obtained
?Debug : Nov 19 12:03:50 RADIUS Packet: Size <187>; HDR.Size <187>
?Debug : Nov 19 12:03:50 AuthServer: Recv...
?Debug : Nov 19 12:03:50 AuthServer: Packet from NAS <192.168.254.2>
?Debug : Nov 19 12:03:50 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 19 12:03:50 AuthServer: Packet from <192.168.254.2> packet dump: RPacket:
Code: 1; ID: 17
<Vendor: 0; Attr: 1>[4]: 30303033
<Vendor: 0; Attr: 2>[16]: 8c7317d63c44eb690655a9bd4819dc43
<Vendor: 0; Attr: 4>[4]: c0a8fe02
<Vendor: 0; Attr: 5>[4]: 00000000
<Vendor: 0; Attr: 6>[4]: 00000001
<Vendor: 0; Attr: 31>[5]: 3734303132
<Vendor: 0; Attr: 61>[4]: 00000000
<Vendor: 9; Attr: 1>[29]: 683332332d6976722d6f75743d7472616e73616374696f6e49443a3137
<Vendor: 9; Attr: 2>[11]: 4953444e20303a443a3238
<Vendor: 9; Attr: 24>[48]: 683332332d636f6e662d69643d4133343846344234204434323931314445203830334241453232203431384534414330
?Debug : Nov 19 12:03:50 AuthServer: User <0003> connecting
?Debug : Nov 19 12:03:50 AuthServer: Session for sessionid <0003> not found in <192.168.254.2> cache
ERROR : Nov 19 12:03:50 RADIUS DBA: Can't find login <0003>
?Debug : Nov 19 12:03:50 RADIUS DBA: Searching card login <000000003>
ERROR : Nov 19 12:03:50 RADIUS DBA: Can't find card login <000000003>
?Debug : Nov 19 12:03:50 AuthServer: Attempt to add new Card user: <0003>
?Debug : Nov 19 12:03:50 AuthServer: Skiping non-digit symbols
?Debug : Nov 19 12:03:50 RADIUS DBA: Sending Auto-Add Request for Card-ID: 0003
?Debug : Nov 19 12:03:50 RADIUS Stream[plugin]: Ping reply received
?Debug : Nov 19 12:03:50 RADIUS Stream[plugin]: Got User-Autoadd id <0>
?Debug : Nov 19 12:03:50 AuthServer: Got AutoAdd 0 UID from core.
Info : Nov 19 12:03:51 AuthServer: Retry:0 to find user <0003>
ERROR : Nov 19 12:03:51 RADIUS DBA: Can't find login <0003>
?Debug : Nov 19 12:03:51 RADIUS DBA: Searching card login <000000003>
ERROR : Nov 19 12:03:51 RADIUS DBA: Can't find card login <000000003>
Info : Nov 19 12:03:52 AuthServer: Retry:1 to find user <0003>
ERROR : Nov 19 12:03:52 RADIUS DBA: Can't find login <0003>
?Debug : Nov 19 12:03:52 RADIUS DBA: Searching card login <000000003>
ERROR : Nov 19 12:03:52 RADIUS DBA: Can't find card login <000000003>
Info : Nov 19 12:03:53 AuthServer: Retry:2 to find user <0003>
ERROR : Nov 19 12:03:53 RADIUS DBA: Can't find login <0003>
?Debug : Nov 19 12:03:53 RADIUS DBA: Searching card login <000000003>
ERROR : Nov 19 12:03:53 RADIUS DBA: Can't find card login <000000003>
Warn : Nov 19 12:03:53 AuthServer: Errors adding card <0003>. Rehash failed
ERROR : Nov 19 12:03:53 AuthServer: No data for User <0003> found.
?Debug : Nov 19 12:03:53 AuthServer: Auth reply: RPacket:
Code: 3; ID: 17
<Vendor: 0; Attr: 18>[21]: 417574686f72697a6174696f6e206661696c65642e
<Vendor: 9; Attr: 103>[19]: 683332332d72657475726e2d636f64653d2d31
?Debug : Nov 19 12:03:53 RADIUS Packet: raw data constructed! size <70>
?Debug : Nov 19 12:03:53 RadiusSocket: Moving RADIUS packet into send queue
?Debug : Nov 19 12:03:53 RadiusSocket: RADIUS raw data sent
?Debug : Nov 19 12:03:53 AuthServer: Next...
?Trace : Nov 19 12:03:53 AuthServer: Process loop step
?Debug : Nov 19 12:03:53 RadiusSocket: Waiting for RADIUS raw data
?Debug : Nov 19 12:03:56 RadiusSocket: RADIUS packet successfully received
?Debug : Nov 19 12:03:56 RadiusSocket: RADIUS raw data obtained
?Debug : Nov 19 12:03:56 RADIUS Packet: Size <1142>; HDR.Size <1142>
?Debug : Nov 19 12:03:56 AcctServer: Recv...
?Debug : Nov 19 12:03:56 AcctServer: Packet from <192.168.254.2> packet dump: RPacket:
Code: 4; ID: 100
<Vendor: 0; Attr: 1>[4]: 30303033
<Vendor: 0; Attr: 4>[4]: c0a8fe02
<Vendor: 0; Attr: 5>[4]: 00000000
<Vendor: 0; Attr: 6>[4]: 00000001
<Vendor: 0; Attr: 30>[6]: 353730323335
<Vendor: 0; Attr: 31>[5]: 3734303132
<Vendor: 0; Attr: 40>[4]: 00000002
<Vendor: 0; Attr: 41>[4]: 00000000
<Vendor: 0; Attr: 42>[4]: 00000000
<Vendor: 0; Attr: 43>[4]: 0000ec40
<Vendor: 0; Attr: 44>[8]: 3030303030303432
<Vendor: 0; Attr: 45>[4]: 00000001
<Vendor: 0; Attr: 46>[4]: 00000014
<Vendor: 0; Attr: 47>[4]: 00000000
<Vendor: 0; Attr: 48>[4]: 000000fc
<Vendor: 0; Attr: 61>[4]: 00000000
<Vendor: 9; Attr: 1>[57]: 683332332d696e636f6d696e672d636f6e662d69643d4133343846344234204434323931314445203830334241453232203431384534414330
<Vendor: 9(0); Attr: 1>[22]: 737562736372696265723d526567756c61724c696e65
<Vendor: 9(1); Attr: 1>[31]: 67772d7278642d63646e3d746f6e3a302c6e70693a302c233a353730323335
<Vendor: 9(2); Attr: 1>[24]: 63616c6c696e672d70617274792d63617465676f72793d39
<Vendor: 9(3); Attr: 1>[25]: 7472616e736d697373696f6e2d6d656469756d2d7265713d30
<Vendor: 9(4); Attr: 1>[27]: 683332332d6976722d6f75743d5461726966663a556e6b6e6f776e
<Vendor: 9(5); Attr: 1>[16]: 72656c656173652d736f757263653d31
<Vendor: 9(6); Attr: 1>[30]: 67772d7278642d63676e3d746f6e3a302c6e70693a302c233a3734303132
<Vendor: 9(7); Attr: 1>[15]: 636861726765642d756e6974733d30
<Vendor: 9(8); Attr: 1>[30]: 646973636f6e6e6563742d746578743d7573657220627573792028313729
<Vendor: 9(9); Attr: 1>[18]: 706565722d616464726573733d3734303132
<Vendor: 9(10); Attr: 1>[16]: 696e666f2d747970653d737065656368
<Vendor: 9(11); Attr: 1>[9]: 706565722d69643d31
<Vendor: 9(12); Attr: 1>[16]: 706565722d69662d696e6465783d3736
<Vendor: 9(13); Attr: 1>[19]: 6c6f676963616c2d69662d696e6465783d3430
<Vendor: 9(14); Attr: 1>[13]: 61636f6d2d6c6576656c3d3231
<Vendor: 9(15); Attr: 1>[24]: 636f6465722d747970652d726174653d67373131756c6177
<Vendor: 9(16); Attr: 1>[22]: 6e6f6973652d6c6576656c3d34323934393637323132
<Vendor: 9(17); Attr: 1>[26]: 766f6963652d74782d6475726174696f6e3d3131363730206d73
<Vendor: 9(18); Attr: 1>[20]: 74782d6475726174696f6e3d3131363730206d73
<Vendor: 9; Attr: 2>[11]: 4953444e20303a443a3238
<Vendor: 9; Attr: 24>[48]: 683332332d636f6e662d69643d4133343846344234204434323931314445203830334241453232203431384534414330
<Vendor: 9; Attr: 25>[48]: 683332332d73657475702d74696d653d31323a30333a33362e3539322045455420546875204e6f762031392032303039
<Vendor: 9; Attr: 26>[23]: 683332332d63616c6c2d6f726967696e3d616e73776572
<Vendor: 9; Attr: 27>[24]: 683332332d63616c6c2d747970653d54656c6570686f6e79
<Vendor: 9; Attr: 28>[50]: 683332332d636f6e6e6563742d74696d653d31323a30333a33362e3630362045455420546875204e6f762031392032303039
<Vendor: 9; Attr: 29>[53]: 683332332d646973636f6e6e6563742d74696d653d31323a30333a35362e3133372045455420546875204e6f762031392032303039
<Vendor: 9; Attr: 30>[24]: 683332332d646973636f6e6e6563742d63617573653d3131
<Vendor: 9; Attr: 31>[20]: 683332332d766f6963652d7175616c6974793d30
<Vendor: 9; Attr: 33>[18]: 683332332d67772d69643d526f757465722e
?Debug : Nov 19 12:03:56 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 19 12:03:56 AcctServer: Acct packet with session ID: 00000042
?Debug : Nov 19 12:03:56 RADIUS DBA: NAS found. Data size <0>
?Debug : Nov 19 12:03:56 AcctServer: Acct-Stop packet
?Debug : Nov 19 12:03:56 RADIUS DBA: Session erase ... login type <3>
?Debug : Nov 19 12:03:56 RADIUS DBA: login type login_tel
?Debug : Nov 19 12:03:56 RADIUS DBA: Calling tel_calculate cost. session_time_not_present <0> NOW <1258625036>
?Debug : Nov 19 12:03:56 RADIUS Tarif: UT for telephony called. tkey:0 start:1258625016 stop:1258625036
?Debug : Nov 19 12:03:56 RADIUS Tarif: Telephony service <1> free time <5>
?Debug : Nov 19 12:03:56 RADIUS Tarif: UT cost_info sum:0.0000 setup_time <1258625016>
?Debug : Nov 19 12:03:56 RADIUS DBA: VoIP Discount: TR ID 0: 0.000 for 20 sec setup_time <1258625016>
?Debug : Nov 19 12:03:56 RADIUS Tarif: UT tkey <0> downloaded <46>
?Debug : Nov 19 12:03:56 RADIUS DBA: VoIP calculated cost: 0.000
?Debug : Nov 19 12:03:56 RADIUS Stream[plugin]: finish log id <2>
?Debug : Nov 19 12:03:56 AcctServer: Reply packet dump: RPacket:
Code: 5; ID: 100
т.е. в логе радиуса видно, что карточку № 0003 не видит в БД
про других пользователей:
для регистрации шлюза заведены 2 пользователя
1 - cisco - для регистрации его на ГейтКипере
2 - 74012 - для регистрации при звонке - иначе сыпятся ошибки, мол неизвестный логин/пароль в логах
Им обоим добавлена услуга телефонии.
Возможно у меня где то в этом косяк, но понять пока не могу. Может кто сможет подсказать более точно?