Hi folks,
I'd like to ask you how can I solve an issue when I'm receiving three RADIUS requests on one missed call. My scenario is as follows:
A calls to B. B returns 503 error message, INIVITE is then sent to C and C sends 486.
After first 503 I receive a first RADIUS request. This is correct.
However after 486 I receive three RADIUS requests with different IDs. As you can see in a DEBUG one RADIUS is send after the SIP reply message is received and second and third RADIUS messages are sent after the SIP reply message is forwarded.
I'd like to receive only two RADIUS messages. One after 503 and second after 486.
FLT_ACC is defined as 1. My config is as follows: modparam("acc", "failed_transaction_flag", FLT_ACC) modparam("acc", "report_cancels", 1) modparam("acc", "report_ack", 0) modparam("acc", "detect_direction", 0) modparam("acc", "early_media", 0) modparam("acc", "log_level", 5) modparam("acc", "log_flag", 1) modparam("acc", "log_missed_flag", 1) modparam("acc_radius", "radius_config", "/etc/radiusclient-ng/radiusclient.conf") # This is the location of the configuration file of radius client modparam("acc_radius", "radius_flag", FLT_ACC) modparam("acc_radius", "radius_missed_flag", FLT_ACC)
In a route I set setflag("FLT_ACC") only once per call.
Here is the debug for debug level 7: 0(5890) DEBUG: <core> [parser/msg_parser.c:634]: SIP Reply (status): 0(5890) DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0> 0(5890) DEBUG: <core> [parser/msg_parser.c:638]: status: <486> 0(5890) DEBUG: <core> [parser/msg_parser.c:640]: reason: <Busy here> 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.4438d232.1>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 234, <received> = <192.168.21.101>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=2 0(5890) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: this is the first via 0(5890) DEBUG: <core> [receive.c:149]: After parse_msg... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=5 T start=0xffffffff 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.e7b650e1.0>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/msg_parser.c:524]: parse_headers: this is the second via 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK463ae086>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 235, <rport> = <5060>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as493d6134 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: <core> [parser/msg_parser.c:188]: DEBUG: get_hdr_field: <To> [42]; uri=[sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body [sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:168]: get_hdr_field: cseq <CSeq>: <102> <INVITE> 0(5890) DEBUG: tm [t_lookup.c:965]: DEBUG: t_reply_matching: hash 51672 label 590185284 branch 1 0(5890) DEBUG: tm [t_lookup.c:1016]: DEBUG: t_reply_matching: reply matched (T=0x871afc98)! 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 2, reply code 486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as5c1d222e 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1148]: DEBUG: t_check_msg: msg id=6 global id=6 T end=0x871afc98 0(5890) DEBUG: tm [t_reply.c:2081]: DEBUG: reply_received: org. status uas=180, uac[1]=180 local=0 is_invite=1) 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 4194304, id 0 entered 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=6 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [REPLY_TWO] Incoming reply code: 486 0(5890) DEBUG: tm [t_reply.c:1204]: ->>>>>>>>> T_code=180, new_code=486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 128, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 128, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed: timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) DEBUG: <core> [md5utils.c:67]: DEBUG: MD5 calculated: 6e1b9f35a8b3e65859e29aefc1c26fc3 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_LENGTH=262 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_TYPE=application/sdp 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_SUPPORTED=replaces 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_DATE=Thu, 07 Feb 2013 19:35:53 GMT 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_MAX_FORWARDS=68 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_USER_AGENT=Asterisk PBX 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CSEQ=102 INVITE 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CALLID=38e422e10af08b2e34d58e5b765e81d3@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTACT=sip:0221028400@192.168.21.106 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=sip:5556003900000@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="Janko" sip:0221028400@dr.vm;tag=as5c1d222e 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_VIA=SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0,SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 0(5890) DEBUG: exec [exec_mod.c:175]: executing [/opt/kamrouter/scripts/notify_reroute.sh 503 sip:3333003900000@ast-car.vm sip:0221028400@dr.vm 38e422e10af08b2e34d58e5b765e81d3@dr.vm] sh: /opt/kamrouter/scripts/notify_reroute.sh: not found 0(5890) INFO: <core> [main.c:797]: INFO: dont_fork turned on, living on 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=0 global id=0 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [FAIL_TWO] Rerouted gw returned 486 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [aaa] VYMAZAVAM3 0(5890) DEBUG: tm [t_reply.c:1702]: DEBUG: relay_reply: branch=1, save=0, relay=1 0(5890) DEBUG: <core> [msg_translator.c:1933]: old size: 572, new size: 485 0(5890) DEBUG: <core> [msg_translator.c:1951]: build_res_from_sip_res: copied size: orig:110, new: 23, rest: 462 msg= SIP/2.0 486 Busy here Via: SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0 Via: SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 From: "Janko" sip:0221028400@dr.vm;tag=as5c1d222e To: sip:5556003900000@dr.vm;tag=as493d6134 Call-ID: 38e422e10af08b2e34d58e5b765e81d3@dr.vm CSeq: 102 INVITE Server: Asterisk PBX 11.0.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0
0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 1048576, id 0 entered 0(5890) DEBUG: dialog [dlg_hash.c:588]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:590]: dialog id=3894 found on entry 2825 0(5890) DEBUG: dialog [dlg_hash.c:940]: dialog 0x871af3f0 changed from state 2 to state 5, due event 4 (ref 2) 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_handlers.c:1469]: executing event_route 4 on state 5 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [dialog:failed] Deleting 38e422e10af08b2e34d58e5b765e81d3@dr.vm from dialogs and dstprefix_limit 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_handlers.c:543]: dialog 0x871af3f0 failed (negative reply) 0(5890) DEBUG: dialog [dlg_cb.c:256]: dialog=0x871af3f0, type=4 0(5890) DEBUG: dialog [dlg_hash.c:643]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_hash.c:646]: dialog callid='38e422e10af08b2e34d58e5b765e81d3@dr.vm' found on entry 2825, dir=1 0(5890) DEBUG: dialog [dlg_var.c:203]: Internal var-list ((nil)): 0(5890) DEBUG: dialog [dlg_var.c:213]: Dialog var-list (0x871af6f8): 0(5890) DEBUG: dialog [dlg_var.c:218]: "ru"=sip:003900000@cr1.vm:5060 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: d=0 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: et=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: st=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) acc [acc_cdr.c:192]: st=1360265682.889; et=1360265682.889; d=0; c1= 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: dialog [dlg_handlers.c:937]: registering TMCB to wait for negative ACK 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 512, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 512, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed: timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) acc [acc.c:275]: ACC: transaction answered: timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:867]: acc event for engine: radius 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 8388608, id 0 entered
Thanks for a help.
Efelin
Hello,
there are different event logged for accounting: - missed call event which is sent from the point of view of callee - transaction answered which is sent from the point of view of caller
In db (eg mysql) accounting, each event in stored in a different table. I don't know how they are in radius. You probably get two missed call events and one transaction answered.
If you want only one, do not set the flag for missed calls.
Cheers, Daniel
On 2/7/13 9:23 PM, Efelin Novak wrote:
Hi folks,
I'd like to ask you how can I solve an issue when I'm receiving three RADIUS requests on one missed call. My scenario is as follows:
A calls to B. B returns 503 error message, INIVITE is then sent to C and C sends 486.
After first 503 I receive a first RADIUS request. This is correct.
However after 486 I receive three RADIUS requests with different IDs. As you can see in a DEBUG one RADIUS is send after the SIP reply message is received and second and third RADIUS messages are sent after the SIP reply message is forwarded.
I'd like to receive only two RADIUS messages. One after 503 and second after 486.
FLT_ACC is defined as 1. My config is as follows: modparam("acc", "failed_transaction_flag", FLT_ACC) modparam("acc", "report_cancels", 1) modparam("acc", "report_ack", 0) modparam("acc", "detect_direction", 0) modparam("acc", "early_media", 0) modparam("acc", "log_level", 5) modparam("acc", "log_flag", 1) modparam("acc", "log_missed_flag", 1) modparam("acc_radius", "radius_config", "/etc/radiusclient-ng/radiusclient.conf") # This is the location of the configuration file of radius client modparam("acc_radius", "radius_flag", FLT_ACC) modparam("acc_radius", "radius_missed_flag", FLT_ACC)
In a route I set setflag("FLT_ACC") only once per call.
Here is the debug for debug level 7: 0(5890) DEBUG: <core> [parser/msg_parser.c:634]: SIP Reply (status): 0(5890) DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0> 0(5890) DEBUG: <core> [parser/msg_parser.c:638]: status: <486> 0(5890) DEBUG: <core> [parser/msg_parser.c:640]: reason: <Busy here> 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.4438d232.1>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 234, <received> = <192.168.21.101>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=2 0(5890) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: this is the first via 0(5890) DEBUG: <core> [receive.c:149]: After parse_msg... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=5 T start=0xffffffff 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.e7b650e1.0>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/msg_parser.c:524]: parse_headers: this is the second via 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK463ae086>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 235, <rport> = <5060>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as493d6134 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: <core> [parser/msg_parser.c:188]: DEBUG: get_hdr_field: <To> [42]; uri=[sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body [sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:168]: get_hdr_field: cseq <CSeq>: <102> <INVITE> 0(5890) DEBUG: tm [t_lookup.c:965]: DEBUG: t_reply_matching: hash 51672 label 590185284 branch 1 0(5890) DEBUG: tm [t_lookup.c:1016]: DEBUG: t_reply_matching: reply matched (T=0x871afc98)! 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 2, reply code 486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as5c1d222e 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1148]: DEBUG: t_check_msg: msg id=6 global id=6 T end=0x871afc98 0(5890) DEBUG: tm [t_reply.c:2081]: DEBUG: reply_received: org. status uas=180, uac[1]=180 local=0 is_invite=1) 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 4194304, id 0 entered 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=6 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [REPLY_TWO] Incoming reply code: 486 0(5890) DEBUG: tm [t_reply.c:1204]: ->>>>>>>>> T_code=180, new_code=486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 128, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 128, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed: timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) DEBUG: <core> [md5utils.c:67]: DEBUG: MD5 calculated: 6e1b9f35a8b3e65859e29aefc1c26fc3 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_LENGTH=262 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_TYPE=application/sdp 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_SUPPORTED=replaces 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_DATE=Thu, 07 Feb 2013 19:35:53 GMT 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_MAX_FORWARDS=68 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_USER_AGENT=Asterisk PBX 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CSEQ=102 INVITE 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CALLID=38e422e10af08b2e34d58e5b765e81d3@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTACT=sip:0221028400@192.168.21.106 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=sip:5556003900000@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="Janko" sip:0221028400@dr.vm;tag=as5c1d222e 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_VIA=SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0,SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 0(5890) DEBUG: exec [exec_mod.c:175]: executing [/opt/kamrouter/scripts/notify_reroute.sh 503 sip:3333003900000@ast-car.vm sip:0221028400@dr.vm 38e422e10af08b2e34d58e5b765e81d3@dr.vm] sh: /opt/kamrouter/scripts/notify_reroute.sh: not found 0(5890) INFO: <core> [main.c:797]: INFO: dont_fork turned on, living on 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=0 global id=0 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [FAIL_TWO] Rerouted gw returned 486 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [aaa] VYMAZAVAM3 0(5890) DEBUG: tm [t_reply.c:1702]: DEBUG: relay_reply: branch=1, save=0, relay=1 0(5890) DEBUG: <core> [msg_translator.c:1933]: old size: 572, new size: 485 0(5890) DEBUG: <core> [msg_translator.c:1951]: build_res_from_sip_res: copied size: orig:110, new: 23, rest: 462 msg= SIP/2.0 486 Busy here Via: SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0 Via: SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 From: "Janko" sip:0221028400@dr.vm;tag=as5c1d222e To: sip:5556003900000@dr.vm;tag=as493d6134 Call-ID: 38e422e10af08b2e34d58e5b765e81d3@dr.vm CSeq: 102 INVITE Server: Asterisk PBX 11.0.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0
0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 1048576, id 0 entered 0(5890) DEBUG: dialog [dlg_hash.c:588]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:590]: dialog id=3894 found on entry 2825 0(5890) DEBUG: dialog [dlg_hash.c:940]: dialog 0x871af3f0 changed from state 2 to state 5, due event 4 (ref 2) 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_handlers.c:1469]: executing event_route 4 on state 5 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [dialog:failed] Deleting 38e422e10af08b2e34d58e5b765e81d3@dr.vm from dialogs and dstprefix_limit 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_handlers.c:543]: dialog 0x871af3f0 failed (negative reply) 0(5890) DEBUG: dialog [dlg_cb.c:256]: dialog=0x871af3f0, type=4 0(5890) DEBUG: dialog [dlg_hash.c:643]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_hash.c:646]: dialog callid='38e422e10af08b2e34d58e5b765e81d3@dr.vm' found on entry 2825, dir=1 0(5890) DEBUG: dialog [dlg_var.c:203]: Internal var-list ((nil)): 0(5890) DEBUG: dialog [dlg_var.c:213]: Dialog var-list (0x871af6f8): 0(5890) DEBUG: dialog [dlg_var.c:218]: "ru"=sip:003900000@cr1.vm:5060 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: d=0 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: et=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: st=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) acc [acc_cdr.c:192]: st=1360265682.889; et=1360265682.889; d=0; c1= 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: dialog [dlg_handlers.c:937]: registering TMCB to wait for negative ACK 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 512, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 512, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed: timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) acc [acc.c:275]: ACC: transaction answered: timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:867]: acc event for engine: radius 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 8388608, id 0 entered
Thanks for a help.
Efelin
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
Thanks Daniel,
I'll check it and post results here.
Efelin
2013/2/8 Daniel-Constantin Mierla miconda@gmail.com:
Hello,
there are different event logged for accounting:
- missed call event which is sent from the point of view of callee
- transaction answered which is sent from the point of view of caller
In db (eg mysql) accounting, each event in stored in a different table. I don't know how they are in radius. You probably get two missed call events and one transaction answered.
If you want only one, do not set the flag for missed calls.
Cheers, Daniel
On 2/7/13 9:23 PM, Efelin Novak wrote:
Hi folks,
I'd like to ask you how can I solve an issue when I'm receiving three RADIUS requests on one missed call. My scenario is as follows:
A calls to B. B returns 503 error message, INIVITE is then sent to C and C sends 486.
After first 503 I receive a first RADIUS request. This is correct.
However after 486 I receive three RADIUS requests with different IDs. As you can see in a DEBUG one RADIUS is send after the SIP reply message is received and second and third RADIUS messages are sent after the SIP reply message is forwarded.
I'd like to receive only two RADIUS messages. One after 503 and second after 486.
FLT_ACC is defined as 1. My config is as follows: modparam("acc", "failed_transaction_flag", FLT_ACC) modparam("acc", "report_cancels", 1) modparam("acc", "report_ack", 0) modparam("acc", "detect_direction", 0) modparam("acc", "early_media", 0) modparam("acc", "log_level", 5) modparam("acc", "log_flag", 1) modparam("acc", "log_missed_flag", 1) modparam("acc_radius", "radius_config", "/etc/radiusclient-ng/radiusclient.conf") # This is the location of the configuration file of radius client modparam("acc_radius", "radius_flag", FLT_ACC) modparam("acc_radius", "radius_missed_flag", FLT_ACC)
In a route I set setflag("FLT_ACC") only once per call.
Here is the debug for debug level 7: 0(5890) DEBUG: <core> [parser/msg_parser.c:634]: SIP Reply (status): 0(5890) DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0> 0(5890) DEBUG: <core> [parser/msg_parser.c:638]: status: <486> 0(5890) DEBUG: <core> [parser/msg_parser.c:640]: reason: <Busy here> 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.4438d232.1>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 234, <received> = <192.168.21.101>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=2 0(5890) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: this is the first via 0(5890) DEBUG: <core> [receive.c:149]: After parse_msg... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=5 T start=0xffffffff 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.e7b650e1.0>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/msg_parser.c:524]: parse_headers: this is the second via 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK463ae086>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 235, <rport> = <5060>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as493d6134 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: <core> [parser/msg_parser.c:188]: DEBUG: get_hdr_field: <To> [42]; uri=[sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body [sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:168]: get_hdr_field: cseq <CSeq>: <102> <INVITE> 0(5890) DEBUG: tm [t_lookup.c:965]: DEBUG: t_reply_matching: hash 51672 label 590185284 branch 1 0(5890) DEBUG: tm [t_lookup.c:1016]: DEBUG: t_reply_matching: reply matched (T=0x871afc98)! 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 2, reply code 486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as5c1d222e 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1148]: DEBUG: t_check_msg: msg id=6 global id=6 T end=0x871afc98 0(5890) DEBUG: tm [t_reply.c:2081]: DEBUG: reply_received: org. status uas=180, uac[1]=180 local=0 is_invite=1) 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 4194304, id 0 entered 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=6 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [REPLY_TWO] Incoming reply code: 486 0(5890) DEBUG: tm [t_reply.c:1204]: ->>>>>>>>> T_code=180, new_code=486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 128, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 128, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) DEBUG: <core> [md5utils.c:67]: DEBUG: MD5 calculated: 6e1b9f35a8b3e65859e29aefc1c26fc3 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_LENGTH=262 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_TYPE=application/sdp 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_SUPPORTED=replaces 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_DATE=Thu, 07 Feb 2013 19:35:53 GMT 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_MAX_FORWARDS=68 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_USER_AGENT=Asterisk PBX 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CSEQ=102 INVITE 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CALLID=38e422e10af08b2e34d58e5b765e81d3@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTACT=sip:0221028400@192.168.21.106 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=sip:5556003900000@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="Janko" sip:0221028400@dr.vm;tag=as5c1d222e 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_VIA=SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0,SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 0(5890) DEBUG: exec [exec_mod.c:175]: executing [/opt/kamrouter/scripts/notify_reroute.sh 503 sip:3333003900000@ast-car.vm sip:0221028400@dr.vm 38e422e10af08b2e34d58e5b765e81d3@dr.vm] sh: /opt/kamrouter/scripts/notify_reroute.sh: not found 0(5890) INFO: <core> [main.c:797]: INFO: dont_fork turned on, living on 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=0 global id=0 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [FAIL_TWO] Rerouted gw returned 486 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [aaa] VYMAZAVAM3 0(5890) DEBUG: tm [t_reply.c:1702]: DEBUG: relay_reply: branch=1, save=0, relay=1 0(5890) DEBUG: <core> [msg_translator.c:1933]: old size: 572, new size: 485 0(5890) DEBUG: <core> [msg_translator.c:1951]: build_res_from_sip_res: copied size: orig:110, new: 23, rest: 462 msg= SIP/2.0 486 Busy here Via: SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0 Via: SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 From: "Janko" sip:0221028400@dr.vm;tag=as5c1d222e To: sip:5556003900000@dr.vm;tag=as493d6134 Call-ID: 38e422e10af08b2e34d58e5b765e81d3@dr.vm CSeq: 102 INVITE Server: Asterisk PBX 11.0.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0
0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 1048576, id 0 entered 0(5890) DEBUG: dialog [dlg_hash.c:588]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:590]: dialog id=3894 found on entry 2825 0(5890) DEBUG: dialog [dlg_hash.c:940]: dialog 0x871af3f0 changed from state 2 to state 5, due event 4 (ref 2) 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_handlers.c:1469]: executing event_route 4 on state 5 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [dialog:failed] Deleting 38e422e10af08b2e34d58e5b765e81d3@dr.vm from dialogs and dstprefix_limit 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_handlers.c:543]: dialog 0x871af3f0 failed (negative reply) 0(5890) DEBUG: dialog [dlg_cb.c:256]: dialog=0x871af3f0, type=4 0(5890) DEBUG: dialog [dlg_hash.c:643]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_hash.c:646]: dialog callid='38e422e10af08b2e34d58e5b765e81d3@dr.vm' found on entry 2825, dir=1 0(5890) DEBUG: dialog [dlg_var.c:203]: Internal var-list ((nil)): 0(5890) DEBUG: dialog [dlg_var.c:213]: Dialog var-list (0x871af6f8): 0(5890) DEBUG: dialog [dlg_var.c:218]: "ru"=sip:003900000@cr1.vm:5060 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: d=0 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: et=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: st=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) acc [acc_cdr.c:192]: st=1360265682.889; et=1360265682.889; d=0; c1= 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: dialog [dlg_handlers.c:937]: registering TMCB to wait for negative ACK 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 512, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 512, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) acc [acc.c:275]: ACC: transaction answered:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:867]: acc event for engine: radius 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 8388608, id 0 entered
Thanks for a help.
Efelin
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
-- Daniel-Constantin Mierla - http://www.asipto.com http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda Kamailio World Conference, April 16-17, 2013, Berlin
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
I'm little bit confused about a usage of radius acc_radius module. Parameters from acc_radius module can also be found in acc module after recompiling it with ENABLE_RADIUS_ACC=true.
Which one should I use? Which one is more up to date? What is the difference?
Cheers,
Efelin 2013/2/8 Efelin Novak efelin.novak@gmail.com:
Thanks Daniel,
I'll check it and post results here.
Efelin
2013/2/8 Daniel-Constantin Mierla miconda@gmail.com:
Hello,
there are different event logged for accounting:
- missed call event which is sent from the point of view of callee
- transaction answered which is sent from the point of view of caller
In db (eg mysql) accounting, each event in stored in a different table. I don't know how they are in radius. You probably get two missed call events and one transaction answered.
If you want only one, do not set the flag for missed calls.
Cheers, Daniel
On 2/7/13 9:23 PM, Efelin Novak wrote:
Hi folks,
I'd like to ask you how can I solve an issue when I'm receiving three RADIUS requests on one missed call. My scenario is as follows:
A calls to B. B returns 503 error message, INIVITE is then sent to C and C sends 486.
After first 503 I receive a first RADIUS request. This is correct.
However after 486 I receive three RADIUS requests with different IDs. As you can see in a DEBUG one RADIUS is send after the SIP reply message is received and second and third RADIUS messages are sent after the SIP reply message is forwarded.
I'd like to receive only two RADIUS messages. One after 503 and second after 486.
FLT_ACC is defined as 1. My config is as follows: modparam("acc", "failed_transaction_flag", FLT_ACC) modparam("acc", "report_cancels", 1) modparam("acc", "report_ack", 0) modparam("acc", "detect_direction", 0) modparam("acc", "early_media", 0) modparam("acc", "log_level", 5) modparam("acc", "log_flag", 1) modparam("acc", "log_missed_flag", 1) modparam("acc_radius", "radius_config", "/etc/radiusclient-ng/radiusclient.conf") # This is the location of the configuration file of radius client modparam("acc_radius", "radius_flag", FLT_ACC) modparam("acc_radius", "radius_missed_flag", FLT_ACC)
In a route I set setflag("FLT_ACC") only once per call.
Here is the debug for debug level 7: 0(5890) DEBUG: <core> [parser/msg_parser.c:634]: SIP Reply (status): 0(5890) DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0> 0(5890) DEBUG: <core> [parser/msg_parser.c:638]: status: <486> 0(5890) DEBUG: <core> [parser/msg_parser.c:640]: reason: <Busy here> 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.4438d232.1>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 234, <received> = <192.168.21.101>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=2 0(5890) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: this is the first via 0(5890) DEBUG: <core> [receive.c:149]: After parse_msg... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=5 T start=0xffffffff 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.e7b650e1.0>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/msg_parser.c:524]: parse_headers: this is the second via 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK463ae086>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 235, <rport> = <5060>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as493d6134 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: <core> [parser/msg_parser.c:188]: DEBUG: get_hdr_field: <To> [42]; uri=[sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body [sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:168]: get_hdr_field: cseq <CSeq>: <102> <INVITE> 0(5890) DEBUG: tm [t_lookup.c:965]: DEBUG: t_reply_matching: hash 51672 label 590185284 branch 1 0(5890) DEBUG: tm [t_lookup.c:1016]: DEBUG: t_reply_matching: reply matched (T=0x871afc98)! 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 2, reply code 486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as5c1d222e 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1148]: DEBUG: t_check_msg: msg id=6 global id=6 T end=0x871afc98 0(5890) DEBUG: tm [t_reply.c:2081]: DEBUG: reply_received: org. status uas=180, uac[1]=180 local=0 is_invite=1) 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 4194304, id 0 entered 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=6 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [REPLY_TWO] Incoming reply code: 486 0(5890) DEBUG: tm [t_reply.c:1204]: ->>>>>>>>> T_code=180, new_code=486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 128, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 128, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) DEBUG: <core> [md5utils.c:67]: DEBUG: MD5 calculated: 6e1b9f35a8b3e65859e29aefc1c26fc3 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_LENGTH=262 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_TYPE=application/sdp 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_SUPPORTED=replaces 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_DATE=Thu, 07 Feb 2013 19:35:53 GMT 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_MAX_FORWARDS=68 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_USER_AGENT=Asterisk PBX 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CSEQ=102 INVITE 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CALLID=38e422e10af08b2e34d58e5b765e81d3@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTACT=sip:0221028400@192.168.21.106 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=sip:5556003900000@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="Janko" sip:0221028400@dr.vm;tag=as5c1d222e 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_VIA=SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0,SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 0(5890) DEBUG: exec [exec_mod.c:175]: executing [/opt/kamrouter/scripts/notify_reroute.sh 503 sip:3333003900000@ast-car.vm sip:0221028400@dr.vm 38e422e10af08b2e34d58e5b765e81d3@dr.vm] sh: /opt/kamrouter/scripts/notify_reroute.sh: not found 0(5890) INFO: <core> [main.c:797]: INFO: dont_fork turned on, living on 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=0 global id=0 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [FAIL_TWO] Rerouted gw returned 486 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [aaa] VYMAZAVAM3 0(5890) DEBUG: tm [t_reply.c:1702]: DEBUG: relay_reply: branch=1, save=0, relay=1 0(5890) DEBUG: <core> [msg_translator.c:1933]: old size: 572, new size: 485 0(5890) DEBUG: <core> [msg_translator.c:1951]: build_res_from_sip_res: copied size: orig:110, new: 23, rest: 462 msg= SIP/2.0 486 Busy here Via: SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0 Via: SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 From: "Janko" sip:0221028400@dr.vm;tag=as5c1d222e To: sip:5556003900000@dr.vm;tag=as493d6134 Call-ID: 38e422e10af08b2e34d58e5b765e81d3@dr.vm CSeq: 102 INVITE Server: Asterisk PBX 11.0.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0
0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 1048576, id 0 entered 0(5890) DEBUG: dialog [dlg_hash.c:588]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:590]: dialog id=3894 found on entry 2825 0(5890) DEBUG: dialog [dlg_hash.c:940]: dialog 0x871af3f0 changed from state 2 to state 5, due event 4 (ref 2) 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_handlers.c:1469]: executing event_route 4 on state 5 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [dialog:failed] Deleting 38e422e10af08b2e34d58e5b765e81d3@dr.vm from dialogs and dstprefix_limit 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_handlers.c:543]: dialog 0x871af3f0 failed (negative reply) 0(5890) DEBUG: dialog [dlg_cb.c:256]: dialog=0x871af3f0, type=4 0(5890) DEBUG: dialog [dlg_hash.c:643]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_hash.c:646]: dialog callid='38e422e10af08b2e34d58e5b765e81d3@dr.vm' found on entry 2825, dir=1 0(5890) DEBUG: dialog [dlg_var.c:203]: Internal var-list ((nil)): 0(5890) DEBUG: dialog [dlg_var.c:213]: Dialog var-list (0x871af6f8): 0(5890) DEBUG: dialog [dlg_var.c:218]: "ru"=sip:003900000@cr1.vm:5060 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: d=0 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: et=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: st=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) acc [acc_cdr.c:192]: st=1360265682.889; et=1360265682.889; d=0; c1= 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: dialog [dlg_handlers.c:937]: registering TMCB to wait for negative ACK 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 512, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 512, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) acc [acc.c:275]: ACC: transaction answered:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:867]: acc event for engine: radius 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 8388608, id 0 entered
Thanks for a help.
Efelin
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
-- Daniel-Constantin Mierla - http://www.asipto.com http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda Kamailio World Conference, April 16-17, 2013, Berlin
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
On 2/8/13 11:07 AM, Efelin Novak wrote:
I'm little bit confused about a usage of radius acc_radius module. Parameters from acc_radius module can also be found in acc module after recompiling it with ENABLE_RADIUS_ACC=true.
Which one should I use? Which one is more up to date? What is the difference?
The functionality should be the same. I created acc_radius to make possible packaging radius accounting separate of acc module, otherwise the acc module (when installed from packages) will require always radius libraries, although is common to use it with database backend.
Perhaps acc module can be updated to get rid of radius code. Because I don't use radius accounting, I was reluctant to remove the old code from acc module, just to be in safe side if acc_radius had some missing features.
So I recommend using acc_radius, that is the way to go if you want to install from packages. If there would be any issue, it will be fixed.
Cheers, Daniel
Cheers,
Efelin 2013/2/8 Efelin Novak efelin.novak@gmail.com:
Thanks Daniel,
I'll check it and post results here.
Efelin
2013/2/8 Daniel-Constantin Mierla miconda@gmail.com:
Hello,
there are different event logged for accounting:
- missed call event which is sent from the point of view of callee
- transaction answered which is sent from the point of view of caller
In db (eg mysql) accounting, each event in stored in a different table. I don't know how they are in radius. You probably get two missed call events and one transaction answered.
If you want only one, do not set the flag for missed calls.
Cheers, Daniel
On 2/7/13 9:23 PM, Efelin Novak wrote:
Hi folks,
I'd like to ask you how can I solve an issue when I'm receiving three RADIUS requests on one missed call. My scenario is as follows:
A calls to B. B returns 503 error message, INIVITE is then sent to C and C sends 486.
After first 503 I receive a first RADIUS request. This is correct.
However after 486 I receive three RADIUS requests with different IDs. As you can see in a DEBUG one RADIUS is send after the SIP reply message is received and second and third RADIUS messages are sent after the SIP reply message is forwarded.
I'd like to receive only two RADIUS messages. One after 503 and second after 486.
FLT_ACC is defined as 1. My config is as follows: modparam("acc", "failed_transaction_flag", FLT_ACC) modparam("acc", "report_cancels", 1) modparam("acc", "report_ack", 0) modparam("acc", "detect_direction", 0) modparam("acc", "early_media", 0) modparam("acc", "log_level", 5) modparam("acc", "log_flag", 1) modparam("acc", "log_missed_flag", 1) modparam("acc_radius", "radius_config", "/etc/radiusclient-ng/radiusclient.conf") # This is the location of the configuration file of radius client modparam("acc_radius", "radius_flag", FLT_ACC) modparam("acc_radius", "radius_missed_flag", FLT_ACC)
In a route I set setflag("FLT_ACC") only once per call.
Here is the debug for debug level 7: 0(5890) DEBUG: <core> [parser/msg_parser.c:634]: SIP Reply (status): 0(5890) DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0> 0(5890) DEBUG: <core> [parser/msg_parser.c:638]: status: <486> 0(5890) DEBUG: <core> [parser/msg_parser.c:640]: reason: <Busy here> 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.4438d232.1>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 234, <received> = <192.168.21.101>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=2 0(5890) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: this is the first via 0(5890) DEBUG: <core> [receive.c:149]: After parse_msg... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=5 T start=0xffffffff 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK8d9c.e7b650e1.0>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/msg_parser.c:524]: parse_headers: this is the second via 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 232, <branch> = <z9hG4bK463ae086>; state=6 0(5890) DEBUG: <core> [parser/parse_via.c:1286]: Found param type 235, <rport> = <5060>; state=16 0(5890) DEBUG: <core> [parser/parse_via.c:2561]: end of header reached, state=5 0(5890) DEBUG: <core> [parser/msg_parser.c:511]: parse_headers: Via found, flags=22 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as493d6134 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: <core> [parser/msg_parser.c:188]: DEBUG: get_hdr_field: <To> [42]; uri=[sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body [sip:5556003900000@dr.vm] 0(5890) DEBUG: <core> [parser/msg_parser.c:168]: get_hdr_field: cseq <CSeq>: <102> <INVITE> 0(5890) DEBUG: tm [t_lookup.c:965]: DEBUG: t_reply_matching: hash 51672 label 590185284 branch 1 0(5890) DEBUG: tm [t_lookup.c:1016]: DEBUG: t_reply_matching: reply matched (T=0x871afc98)! 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 2, reply code 486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 2, id 0 entered 0(5890) DEBUG: <core> [parser/parse_to.c:178]: DEBUG: add_param: tag=as5c1d222e 0(5890) DEBUG: <core> [parser/parse_to.c:802]: end of header reached, state=29 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1148]: DEBUG: t_check_msg: msg id=6 global id=6 T end=0x871afc98 0(5890) DEBUG: tm [t_reply.c:2081]: DEBUG: reply_received: org. status uas=180, uac[1]=180 local=0 is_invite=1) 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 4194304, id 0 entered 0(5890) DEBUG: siptrace [siptrace.c:794]: storing info... 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=6 global id=6 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [REPLY_TWO] Incoming reply code: 486 0(5890) DEBUG: tm [t_reply.c:1204]: ->>>>>>>>> T_code=180, new_code=486 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 128, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 128, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) DEBUG: <core> [md5utils.c:67]: DEBUG: MD5 calculated: 6e1b9f35a8b3e65859e29aefc1c26fc3 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_LENGTH=262 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTENT_TYPE=application/sdp 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_SUPPORTED=replaces 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_ALLOW=INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_DATE=Thu, 07 Feb 2013 19:35:53 GMT 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_MAX_FORWARDS=68 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_USER_AGENT=Asterisk PBX 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CSEQ=102 INVITE 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CALLID=38e422e10af08b2e34d58e5b765e81d3@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_CONTACT=sip:0221028400@192.168.21.106 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=sip:5556003900000@dr.vm 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="Janko" sip:0221028400@dr.vm;tag=as5c1d222e 0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_VIA=SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0,SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 0(5890) DEBUG: exec [exec_mod.c:175]: executing [/opt/kamrouter/scripts/notify_reroute.sh 503 sip:3333003900000@ast-car.vm sip:0221028400@dr.vm 38e422e10af08b2e34d58e5b765e81d3@dr.vm] sh: /opt/kamrouter/scripts/notify_reroute.sh: not found 0(5890) INFO: <core> [main.c:797]: INFO: dont_fork turned on, living on 0(5890) DEBUG: tm [t_lookup.c:1079]: DEBUG: t_check_msg: msg id=0 global id=0 T start=0x871afc98 0(5890) DEBUG: tm [t_lookup.c:1151]: DEBUG: t_check_msg: T already found! 0(5890) DEBUG: tmx [t_var.c:438]: reply code is <486> 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [FAIL_TWO] Rerouted gw returned 486 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [aaa] VYMAZAVAM3 0(5890) DEBUG: tm [t_reply.c:1702]: DEBUG: relay_reply: branch=1, save=0, relay=1 0(5890) DEBUG: <core> [msg_translator.c:1933]: old size: 572, new size: 485 0(5890) DEBUG: <core> [msg_translator.c:1951]: build_res_from_sip_res: copied size: orig:110, new: 23, rest: 462 msg= SIP/2.0 486 Busy here Via: SIP/2.0/UDP 192.168.21.100;branch=z9hG4bK8d9c.e7b650e1.0 Via: SIP/2.0/UDP 192.168.21.106:5060;branch=z9hG4bK463ae086;rport=5060 From: "Janko" sip:0221028400@dr.vm;tag=as5c1d222e To: sip:5556003900000@dr.vm;tag=as493d6134 Call-ID: 38e422e10af08b2e34d58e5b765e81d3@dr.vm CSeq: 102 INVITE Server: Asterisk PBX 11.0.2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0
0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 1048576, id 0 entered 0(5890) DEBUG: dialog [dlg_hash.c:588]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:590]: dialog id=3894 found on entry 2825 0(5890) DEBUG: dialog [dlg_hash.c:940]: dialog 0x871af3f0 changed from state 2 to state 5, due event 4 (ref 2) 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_handlers.c:1469]: executing event_route 4 on state 5 0(5890) INFO: <script>: XLOG: 38e422e10af08b2e34d58e5b765e81d3@dr.vm [dialog:failed] Deleting 38e422e10af08b2e34d58e5b765e81d3@dr.vm from dialogs and dstprefix_limit 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_handlers.c:543]: dialog 0x871af3f0 failed (negative reply) 0(5890) DEBUG: dialog [dlg_cb.c:256]: dialog=0x871af3f0, type=4 0(5890) DEBUG: dialog [dlg_hash.c:643]: ref dlg 0x871af3f0 with 1 -> 3 0(5890) DEBUG: dialog [dlg_hash.c:646]: dialog callid='38e422e10af08b2e34d58e5b765e81d3@dr.vm' found on entry 2825, dir=1 0(5890) DEBUG: dialog [dlg_var.c:203]: Internal var-list ((nil)): 0(5890) DEBUG: dialog [dlg_var.c:213]: Dialog var-list (0x871af6f8): 0(5890) DEBUG: dialog [dlg_var.c:218]: "ru"=sip:003900000@cr1.vm:5060 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: d=0 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: et=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_var.c:218]: st=1360265682.889 (flags 1) 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 2 0(5890) acc [acc_cdr.c:192]: st=1360265682.889; et=1360265682.889; d=0; c1= 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: dialog [dlg_handlers.c:937]: registering TMCB to wait for negative ACK 0(5890) DEBUG: dialog [dlg_hash.c:735]: ref dlg 0x871af3f0 with 1 -> 2 0(5890) DEBUG: dialog [dlg_hash.c:753]: unref dlg 0x871af3f0 with 1 -> 1 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 512, id 0 entered 0(5890) DEBUG: acc [acc_logic.c:537]: acc callback called for t(0x871afc98) event type 512, reply code 486 0(5890) acc [acc.c:275]: ACC: call missed:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:872]: missed event for engine: radius 0(5890) acc [acc.c:275]: ACC: transaction answered:
timestamp=1360265692;method=INVITE;from_tag=as5c1d222e;to_tag=as493d6134;call_id=38e422e10af08b2e34d58e5b765e81d3@dr.vm;code=486;reason=Busy here 0(5890) DEBUG: acc [acc.c:867]: acc event for engine: radius 0(5890) DEBUG: tm [t_hooks.c:288]: DBG: trans=0x871afc98, callback type 8388608, id 0 entered
Thanks for a help.
Efelin
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
-- Daniel-Constantin Mierla - http://www.asipto.com http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda Kamailio World Conference, April 16-17, 2013, Berlin
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
-
Daniel-Constantin Mierla -
Efelin Novak