[SR-Users] Multiple radius responses on a missed call

Daniel-Constantin Mierla miconda at gmail.com
Fri Feb 8 09:27:07 CET 2013


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 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
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users at 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
  - http://conference.kamailio.com -




More information about the sr-users mailing list