7 Feb
2013
7 Feb
'13
3:23 p.m.
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(a)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(a)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(a)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(a)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(a)dr.vm
[FAIL_TWO] Rerouted gw returned 486 0(5890) INFO: <script>: XLOG:
38e422e10af08b2e34d58e5b765e81d3(a)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(a)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(a)dr.vm
[dialog:failed] Deleting 38e422e10af08b2e34d58e5b765e81d3(a)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(a)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(a)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(a)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