[SR-Users] Multiple radius responses on a missed call
Efelin Novak
efelin.novak at gmail.com
Thu Feb 7 21:23:14 CET 2013
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 at dr.vm]
0(5890) DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: to body
[<sip:5556003900000 at 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 at 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 at 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 at dr.vm
0(5890) DEBUG: exec [exec_hf.c:267]:
SIP_HF_CONTACT=<sip:0221028400 at 192.168.21.106>
0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_TO=<sip:5556003900000 at dr.vm>
0(5890) DEBUG: exec [exec_hf.c:267]: SIP_HF_FROM="Janko"
<sip:0221028400 at 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 at ast-car.vm sip:0221028400 at dr.vm
38e422e10af08b2e34d58e5b765e81d3 at 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 at dr.vm
[FAIL_TWO] Rerouted gw returned 486 0(5890) INFO: <script>: XLOG:
38e422e10af08b2e34d58e5b765e81d3 at 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 at dr.vm>;tag=as5c1d222e
To: <sip:5556003900000 at dr.vm>;tag=as493d6134
Call-ID: 38e422e10af08b2e34d58e5b765e81d3 at 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 at dr.vm
[dialog:failed] Deleting 38e422e10af08b2e34d58e5b765e81d3 at 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 at 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 at 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 at 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 at 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
More information about the sr-users
mailing list