[Kamailio-Users] "Failed" acc log when 183 Session Progress - sr-users

24 Dec 2008

Hello all,

I just have a little question about this thing :

when I start a call, my Radius receives before the session is established a
"failed" in its accounting log.
If I move the setflag() for rad acc and rad failed acc (or one of each, then
the other one), the "Start" disappear - but I get the Stop.

How to not take acc in charge when there is a 183 Session Progress ?

here is the radius acc log :

Code:       Accounting-Request
Identifier: 102
Authentic: 
Z3z<16>^<230><251>i<233>[6Q<196><12><140><25>
Attributes:
    Acct-Status-Type = Failed
    Service-Type = Sip-Session
    Sip-Response-Code = 183
    Sip-Method = "<1>"
    Event-Timestamp = 1230128211
    Sip-From-Tag = "a3addce43738cc27o0"
    Sip-To-Tag = "1c782477072"
    Acct-Session-Id = &quot;10bdf568-2821ed73(a)192.168.1.7&quot;
    Sip-Method = "INVITE"
    SER-From = "0170645745"
    SER-To = "0663128505"
    Sip-User-Digest-URI =
"sip:0663128505@sip.720.fr<sip%3A0663128505@sip.720.fr>
"
    Sip-Req-URI = "sip:0663128505@77.246.81.136:5060;transport=udp"
    Sip-Source-IP-Address = "87.90.4.63"
    Sip-Source-Port = "5060"
    NAS-Port = 5060
    Acct-Delay-Time = 0
    NAS-IP-Address = 192.168.60.9

the setflag() are here :

if (is_method("INVITE"))
        {
                setflag(4);    # flag "radius acc"
                setflag(5);    # flag "radius failed acc"
                setflag(8);     # flag "dialog"
                setflag(9);     # flag "session timer"
                route(13);
        }

the only place I found the related "183" taken in charge in the kamailio.cfg
is here :

onreply_route[2]
{
    if (nat_uac_test("1"))
    { fix_nated_contact(); }

    if (isbflagset(14) && status =~ "(180|183|2[0-9][0-9])")        #?
branch flag nat
    {
                if (!search("^Content-Length:[ ]*0"))
                { force_rtp_proxy(); }
    }
    exit;
}

in the kamailio log for this same call :

Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_msg: SIP Reply
(status):
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_msg:  version: <SIP/2.0>

Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_msg:  status:  <100>
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_msg:  reason:  <Trying>
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_headers: flags=2
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_via_param: found param
type 232, <branch> = <z9hG4bKbe63.1eddc1f3.0>; state=16
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_via: end of header
reached, state=5
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_headers: via found,
flags=2
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_headers: this is the
first via
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:receive_msg: After
parse_msg...
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:grep_sock_info: checking if
host==us: 13==13 &&  [77.246.81.132] == [77.246.81.132]
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:grep_sock_info: checking if
port 5060 matches port 5060
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:forward_reply: found module
tm, passing reply to it
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:t_check:
start=0xffffffffffffffff
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_headers: flags=22
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_via_param: found param
type 235, <rport> = <5060>; state=6
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_via_param: found param
type 234, <received> = <87.90.4.63>; state=6
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_via_param: found param
type 232, <branch> = <z9hG4bK-8aeb8bb>; state=16
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_via: end of header
reached, state=5
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_headers: via found,
flags=22
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_headers: parse_headers:
this is the second via
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_to_param:
tag=1c782477072
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_to: end of header
reached, state=29
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_to:
display={"0663128505"},
ruri={sip:0663128505@sip.720.fr<sip%3A0663128505@sip.720.fr>}

Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:get_hdr_field: <To> [58];
uri=[sip:0663128505@sip.720.fr &lt;sip%3A0663128505(a)sip.720.fr&gt;]
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:get_hdr_field: to body
["0663128505" <sip:0663128505@sip.720.fr
&lt;sip%3A0663128505(a)sip.720.fr&gt;&gt;]
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:get_hdr_field: cseq <CSeq>:
<102> <INVITE>
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_headers: flags=8
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:t_reply_matching: hash 14059
label 1058856417 branch 0
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:t_reply_matching: REF_UNSAFE:
after is 1
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:t_reply_matching: reply matched
(T=0x7fcc45ebb090)!
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:run_trans_callbacks:
trans=0x7fcc45ebb090, callback type 2, id 1 entered
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:t_check: end=0x7fcc45ebb090
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:reply_received: org. status
uas=0, uac[0]=0 local=0 is_invite=1)
Dec 24 15:16:51 ser0 kamailio[7748]:
-NAT-ONREPLY-----------------------------
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:parse_headers: flags=80
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:get_hdr_field:
content_length=0
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:get_hdr_field: found end of
header
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:t_should_relay_response:
T_code=0, new_code=100
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:relay_reply: branch=0, save=0,
relay=-1
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:set_timer: relative timeout is
60
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:insert_timer_unsafe: [1]:
0x7fcc45ebb2e0 (95)
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:tm:t_unref: UNREF_UNSAFE: after is
0
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:destroy_avp_list: destroying
list (nil)
Dec 24 15:16:51 ser0 kamailio[7748]: DBG:core:receive_msg: cleaning up
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_msg: SIP Reply
(status):
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_msg:  version: <SIP/2.0>

Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_msg:  status:  <183>
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_msg:  reason:  <Session
Progress>
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: flags=2
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_via_param: found param
type 232, <branch> = <z9hG4bKbe63.1eddc1f3.0>; state=16
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_via: end of header
reached, state=5
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: via found,
flags=2
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: this is the
first via
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:receive_msg: After
parse_msg...
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:grep_sock_info: checking if
host==us: 13==13 &&  [77.246.81.132] == [77.246.81.132]
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:grep_sock_info: checking if
port 5060 matches port 5060
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:forward_reply: found module
tm, passing reply to it
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:t_check:
start=0xffffffffffffffff
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: flags=22
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_via_param: found param
type 235, <rport> = <5060>; state=6
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_via_param: found param
type 234, <received> = <87.90.4.63>; state=6
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_via_param: found param
type 232, <branch> = <z9hG4bK-8aeb8bb>; state=16
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_via: end of header
reached, state=5
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: via found,
flags=22
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: parse_headers:
this is the second via
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_to_param:
tag=1c782477072
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_to: end of header
reached, state=29
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_to:
display={"0663128505"},
ruri={sip:0663128505@sip.720.fr<sip%3A0663128505@sip.720.fr>}

Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:get_hdr_field: <To> [58];
uri=[sip:0663128505@sip.720.fr &lt;sip%3A0663128505(a)sip.720.fr&gt;]
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:get_hdr_field: to body
["0663128505" <sip:0663128505@sip.720.fr
&lt;sip%3A0663128505(a)sip.720.fr&gt;&gt;]
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:get_hdr_field: cseq <CSeq>:
<102> <INVITE>
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: flags=8
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:t_reply_matching: hash 14059
label 1058856417 branch 0
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:t_reply_matching: REF_UNSAFE:
after is 1
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:t_reply_matching: reply matched
(T=0x7fcc45ebb090)!
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:run_trans_callbacks:
trans=0x7fcc45ebb090, callback type 2, id 1 entered
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: flags=8
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:t_check: end=0x7fcc45ebb090
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:reply_received: org. status
uas=0, uac[0]=100 local=0 is_invite=1)
Dec 24 15:16:51 ser0 kamailio[7747]:
-NAT-ONREPLY-----------------------------
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: flags=80
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers:
flags=ffffffffffffffff
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:get_hdr_field:
content_length=293
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:get_hdr_field: found end of
header
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:nathelper:check_content_type: type
<application/sdp> found valid
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: flags=40
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_to_param:
tag=a3addce43738cc27o0
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_to: end of header
reached, state=29
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_to:
display={"0170645745"},
ruri={sip:0170645745@sip.720.fr<sip%3A0170645745@sip.720.fr>}

Dec 24 15:16:51 ser0 kamailio[7747]: DBG:nathelper:force_rtp_proxy2_f: proxy
reply: 35934 77.246.81.133
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:t_should_relay_response:
T_code=0, new_code=183
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:relay_reply: branch=0, save=0,
relay=0
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:run_trans_callbacks:
trans=0x7fcc45ebb090, callback type 16, id 0 entered
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:dialog:run_dlg_callbacks:
dialog=0x7fcc45ebc7c0, type=256
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:sst:sst_dialog_response_fwded_CB:
Dialog seen REPLY 183 Session Progress
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: flags=2000
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers:
flags=ffffffffffffffff
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:clen_builder: content-length:
311 (311)
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:build_res_buf_from_sip_res:
old size: 1027, new size: 983
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:build_res_buf_from_sip_res:
copied size: orig:1025, new: 981, rest: 2 msg= SIP/2.0 183 Session
Progress^M Via: SIP/2.0/UDP
192.168.1.7:5060;rport=5060;received=87.90.4.63;branch=z9hG4bK-8aeb8bb^M
From: "0170645745" <sip:0170645745@sip.720.fr
&lt;sip%3A0170645745(a)sip.720.fr&gt;&gt;;tag=a3addce43738cc27o0^M
To: "0663128505" <sip:0663128505@sip.720.fr
&lt;sip%3A0663128505(a)sip.720.fr&gt;&gt;;tag=1c782477072^M
Call-ID: 10bdf568-2821ed73(a)192.168.1.7^M CSeq: 102 INVITE^M Contact: <
sip:61@77.246.81.136 &lt;sip%3A61(a)77.246.81.136&gt;&gt;^M Record-Route:
<sip:77.246.81.132;lr=on;ftag=a3addce43738cc27o0;nat=yes;did=17a.36b075d2>^M
Supported: em,timer,replaces,path,resource-priority^M Allow:
REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE^M
Server: 720 DEGRES PSTN GW/v.5.40A.030.002^M Content-Type: application/sdp^M
Content-Length: 311^M ^M v=0^M o=AudiocodesGW 782585440 782585110 IN IP4
77.246.81.136^M s=Phone-Call^M c=IN IP4 77.246.81.133^M t=0 0^M m=audio
35934 RTP/AVP 18 101^M a=rtpmap:18 G729/8000^M a=fmtp:18 annexb=yes^M
a=rtpmap:101 telephone-event/
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:_shm_resize: resize(0) called
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:relay_reply: sent buf=0x7936d8:
SIP/2.0 1..., shmem=0x7fcc45ebef00: SIP/2.0 1
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:run_trans_callbacks:
trans=0x7fcc45ebb090, callback type 128, id 1 entered
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:parse_headers: flags=14000
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:run_trans_callbacks:
trans=0x7fcc45ebb090, callback type 128, id 0 entered
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:dialog:next_state_dlg: dialog
0x7fcc45ebc7c0 changed from state 1 to state 2, due event 2
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:set_timer: relative timeout is
60
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:insert_timer_unsafe: [1]:
0x7fcc45ebb2e0 (96)
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:tm:t_unref: UNREF_UNSAFE: after is
0
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:destroy_avp_list: destroying
list (nil)
Dec 24 15:16:51 ser0 kamailio[7747]: DBG:core:receive_msg: cleaning up
Dec 24 15:16:51 ser0 kamailio[7753]: DBG:tm:utimer_routine: timer
routine:4,tl=0x7fcc45ebb2b0 next=(nil), timeout=36400000

-- 
Samuel MULLER
sml(a)720.fr