8 Feb
2013
8 Feb
'13
7:23 a.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
8 Feb
8 Feb
7:27 p.m.
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(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
_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users(a)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 -
8:21 p.m.
Thanks Daniel,
I'll check it and post results here.
Efelin
2013/2/8 Daniel-Constantin Mierla <miconda(a)gmail.com>om>:
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(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
_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users(a)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 -
_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
9:07 p.m.
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(a)gmail.com>om>:
Thanks Daniel,
I'll check it and post results here.
Efelin
2013/2/8 Daniel-Constantin Mierla <miconda(a)gmail.com>om>:
> 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(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
>>
>> _______________________________________________
>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
>> sr-users(a)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 -
>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users(a)lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
9 Feb
9 Feb
10:33 a.m.
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(a)gmail.com>om>:
> Thanks Daniel,
>
> I'll check it and post results here.
>
> Efelin
>
> 2013/2/8 Daniel-Constantin Mierla <miconda(a)gmail.com>om>:
>> 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(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
>>>
>>> _______________________________________________
>>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
>>> sr-users(a)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 -
>>
>>
>> _______________________________________________
>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
>> sr-users(a)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 -
4385
days inactive
4386
days old
4 comments
2 participants
participants (2)
-
Daniel-Constantin Mierla -
Efelin Novak