[Serusers] dealing with parallel forking ...

Cesc Santa cesc.santa at gmail.com
Fri Aug 3 13:43:02 CEST 2007


>From the answer below, Olaf and Samuel don't seem to agree much ...
Let me attach some debug info, maybe you can see better through it
than me. See attached files with debug corresponding to the first 200
OK and to the second ...
I would like to think that SER actually does as Samuel said ... after
the first 200 OK, all the other branches shall be automatically
cancelled, thus not giving the other callees the option of sending
more 200 OKs ...


On 8/3/07, samuel <samu60 at gmail.com> wrote:
> inline...
>
> 2007/8/3, Olaf Bergmann <Olaf.Bergmann at freenet-ag.de>:
> > Cesc Santa wrote:
> >
> >
> > > I am doing some tests and it is not really a problem ... but maybe
> > > someone has a better idea. In my configuration, the first 200 OK
> > > received is forwarded to the caller and the whole SIP session setup
> > > (caller + 1st callee).
> > > Next 200 OKs are also delivered to the caller,
> >
> > That is the correct behavior of a SIP proxy.
>
> I think the proper forking behaviour is to send a CANCEL to all branches
> upon receiving a 200 from one of them and I think that SER does this
> automatically... isn't it??
>
>
> > > who happily ignores them ...
> >
> > That is broken behavior of a SIP UA.
>
> I think it's not specified what to do when a UA receives a second  200
> OK.... it can safely ignore it, it can present a mesage to the user, it can
> try to mix the different audio streams, it can create a second dialog and
> put the first on hold, and more options.
>
> Try to look at HERP and "early media and forking" topics....
>
>
> > > it is the task of the 2nd (and 3rd, ... ) callee to at a
> > > certain point give up and send a BYE, to which the caller replies with
> > > 481 no call leg ...
> > > It all works ... but, I wonder if ser could send CANCELs after
> > > receiving the 1st 200 OK ... if yes, how? :)
> >
> > No, you cannot CANCEL an INVITE after having received a final
> > response. This must be done by the caller after having sent the ACK.
> > The UAC you have used is broken. The callee's UA tries to deal with
> > it and does the best it can. You should use a standards-compliant
> > SIP UA for your tests.
>
> Hope I'm right though I think it should work "as it is"  ;)
>
> sam.
>
-------------- next part --------------
FIRST 200 OK ... correctly sent to caller

 3(11813) receive_msg: cleaning up
 3(11813) SIP Reply  (status):
 3(11813)  version: <SIP/2.0>
 3(11813)  status:  <200>
 3(11813)  reason:  <OK>
 3(11813) parse_headers: flags=1
 3(11813) Found param type 232, <branch> = <z9hG4bK465c.183e978.1>; state=6
 3(11813) Found param type 234, <received> = <192.168.200.71>; state=16
 3(11813) end of header reached, state=5
 3(11813) parse_headers: Via found, flags=1
 3(11813) parse_headers: this is the first via
 3(11813) header field type 1, name=<Via>, body=<SIP/2.0/UDP 192.168.200.71;branch=z9hG4bK465c.183e978.1;received=192.168.200.71>
 3(11813)  first  via: <SIP/2.0/UDP> <192.168.200.71:(0)> 3(11813) ;<> 3(11813)
 3(11813) exiting parse_msg
 3(11813) After parse_msg...
 3(11813) TIC:tic_response_callback: starting
 3(11813) DEBUG : tic_response_callback : there's no transaction waiting binding
 3(11813) TIC:tic_response_callback:  No operation
 3(11813) forward_reply: found module tm, passing reply to it
 3(11813) DEBUG: t_check: msg id=12 global id=11 T start=0xffffffff
 3(11813) parse_headers: flags=17
 3(11813) Found param type 232, <branch> = <z9hG4bK0a0000960000002e46b3117f00006e8f0000000a>; state=6
 3(11813) Found param type 235, <rport> = <5060>; state=16
 3(11813) end of header reached, state=5
 3(11813) parse_headers: Via found, flags=17
 3(11813) parse_headers: this is the second via
 3(11813) header field type 1, name=<Via>, body=<SIP/2.0/UDP 192.168.200.141;branch=z9hG4bK0a0000960000002e46b3117f00006e8f0000000a;rport=5060>
 3(11813) header field type 512, name=<Record-Route>, body=<<sip:192.168.200.71;ftag=4cb08f2cfe0;lr=on>>
 3(11813) header field type 8, name=<From>, body=<"hp_cesc" <sip:7008 at 192.168.200.71>;tag=4cb08f2cfe0>
 3(11813) DEBUG: add_param: tag=as6f6964dd
 3(11813) end of header reached, state=29
 3(11813) DEBUG: get_hdr_field: <To> [51]; uri=[sip:grp.commander at 192.168.200.71]
 3(11813) DEBUG: to body [<sip:grp.commander at 192.168.200.71>]
 3(11813) header field type 4, name=<To>, body=<<sip:grp.commander at 192.168.200.71>;tag=as6f6964dd>
 3(11813) header field type 32, name=<Call-ID>, body=<982596E3E4D842A9B30F0F58934E96480x0a000096>
 3(11813) get_hdr_field: cseq <CSeq>: <1> <INVITE>
 3(11813) header field type 16, name=<CSeq>, body=<1 INVITE>
 3(11813) parse_headers: flags=4
 3(11813) DEBUG: t_reply_matching: hash 50532 label 142205825 branch 1
 3(11813) DEBUG: t_reply_matching: reply matched (T=0xb5eada38)!
 3(11813) parse_headers: flags=4
 3(11813) DEBUG: t_check: msg id=12 global id=12 T end=0xb5eada38
 3(11813) DEBUG: reply_received: org. status uas=0, uac[1]=100 local=0 is_invite=1)
 3(11813) DEBUG: reset_timer (group 3, tl=0xb5eadc40)
 3(11813) DEBUG: reset_timer (group 0, tl=0xb5eadc54)
 3(11813) XLOG: xl_print_log: final buffer length 91
 3(11813) ============================================================
 3(11813) [Fri Aug  3 07:29:10 2007]
 3(11813)
 3(11813) XLOG: xl_print_log: final buffer length 27
 3(11813) [192.168.200.71 ## 11813]
 3(11813)
 3(11813) XLOG: xl_print_log: final buffer length 855
 3(11813) SIP/2.0 200 OK
 3(11813) Via: SIP/2.0/UDP 192.168.200.71;branch=z9hG4bK465c.183e978.1;received=192.168.200.71
 3(11813) Via: SIP/2.0/UDP 192.168.200.141;branch=z9hG4bK0a0000960000002e46b3117f00006e8f0000000a;rport=5060
 3(11813) Record-Route: <sip:192.168.200.71;ftag=4cb08f2cfe0;lr=on>
 3(11813) From: "hp_cesc" <sip:7008 at 192.168.200.71>;tag=4cb08f2cfe0
 3(11813) To: <sip:grp.commander at 192.168.200.71>;tag=as6f6964dd
 3(11813) Call-ID: 982596E3E4D842A9B30F0F58934E96480x0a000096
 3(11813) CSeq: 1 INVITE
 3(11813) User-Agent: Asterisk PBX
 3(11813) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
 3(11813) Contact: <sip:600 at 192.168.200.71:6060>
 3(11813) Content-Type: application/sdp
 3(11813) Content-Length: 220
 3(11813) v=0
 3(11813) o=root 11821 11821 IN IP4 192.168.200.71
 3(11813) s=session
 3(11813) c=IN IP4 192.168.200.71
 3(11813) t=0 0
 3(11813) m=audio 24312 RTP/AVP 8 101
 3(11813) a=rtpmap:8 PCMA/8000
 3(11813) a=rtpmap:101 telephone-event/8000
 3(11813) a=fmtp:101 0-16
 3(11813) a=silenceSupp:off - - - -
 3(11813)
 3(11813)
 3(11813) XLOG: xl_print_log: final buffer length 45
 3(11813) RTP Proxy Handle: flagset: globally disabled
 3(11813)
 3(11813) XLOG: xl_print_log: final buffer length 42
 3(11813) LOG: Entering ROUTE RTPPROXY HANDLE BASIC
 3(11813)
 3(11813) XLOG: xl_print_log: final buffer length 48
 3(11813) LOG:  RTPPROXY disabled ... not using RTP Proxy
 3(11813)
 3(11813) ->>>>>>>>> T_code=0, new_code=200
 3(11813) DEBUG: relay_reply: branch=1, save=0, relay=1
 3(11813)  old size: 852, new size: 766
 3(11813) build_res_from_sip_res: copied size: orig:102, new: 16, rest: 750 msg=
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.200.141;branch=z9hG4bK0a0000960000002e46b3117f00006e8f0000000a;rport=5060
Record-Route: <sip:192.168.200.71;ftag=4cb08f2cfe0;lr=on>
From: "hp_cesc" <sip:7008 at 192.168.200.71>;tag=4cb08f2cfe0
To: <sip:grp.commander at 192.168.200.71>;tag=as6f6964dd
Call-ID: 982596E3E4D842A9B30F0F58934E96480x0a000096
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:600 at 192.168.200.71:6060>
Content-Type: application/sdp
Content-Length: 220

v=0
o=root 11821 11821 IN IP4 192.168.200.71
s=session
c=IN IP4 192.168.200.71
t=0 0
m=audio 24312 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

 3(11813) WARNING:vqm_resize: resize(0) called
 3(11813) DEBUG: update_totag_set: new totag
 3(11813) DEBUG: put on WAIT
 3(11813) DEBUG: add_to_tail_of_timer[2]: 0xb5eada80
 3(11813) DEBUG: reply relayed. buf=0x81e6348: SIP/2.0 2..., shmem=0xb5eb2008: SIP/2.0 2
 3(11813) DEBUG: reset_timer (group 3, tl=0xb5eadb60)
 3(11813) DEBUG: reset_timer (group 0, tl=0xb5eadb74)
 3(11813) DEBUG: reset_timer (group 3, tl=0xb5eadc40)
 3(11813) DEBUG: reset_timer (group 0, tl=0xb5eadc54)
 3(11813) DEBUG: cleanup_uac_timers: RETR/FR timers reset
 3(11813) DEBUG:destroy_avp_list: destroying list (nil)
-------------- next part --------------
SECOND 200 OK ... incorrectly fwd'd??


 3(11813)  version: <SIP/2.0>
 3(11813)  status:  <200>
 3(11813)  reason:  <OK>
 3(11813) parse_headers: flags=1
 3(11813) header field type 32, name=<Call-ID>, body=<982596E3E4D842A9B30F0F58934E96480x0a000096>
 3(11813) get_hdr_field: cseq <CSeq>: <1> <INVITE>
 3(11813) header field type 16, name=<CSeq>, body=<1 INVITE>
 3(11813) header field type 8, name=<From>, body=<"hp_cesc" <sip:7008 at 192.168.200.71>;tag=4cb08f2cfe0>
 3(11813) DEBUG: add_param: tag=467b94ac5d199bf
 3(11813) end of header reached, state=29
 3(11813) DEBUG: get_hdr_field: <To> [56]; uri=[sip:grp.commander at 192.168.200.71]
 3(11813) DEBUG: to body [<sip:grp.commander at 192.168.200.71>]
 3(11813) header field type 4, name=<To>, body=<<sip:grp.commander at 192.168.200.71>;tag=467b94ac5d199bf>
 3(11813) Found param type 232, <branch> = <z9hG4bK465c.183e978.0>; state=16
 3(11813) end of header reached, state=5
 3(11813) parse_headers: Via found, flags=1
 3(11813) parse_headers: this is the first via
 3(11813) header field type 1, name=<Via>, body=<SIP/2.0/UDP 192.168.200.71;branch=z9hG4bK465c.183e978.0>
 3(11813)  first  via: <SIP/2.0/UDP> <192.168.200.71:(0)> 3(11813) ;<> 3(11813)
 3(11813) exiting parse_msg
 3(11813) After parse_msg...
 3(11813) TIC:tic_response_callback: starting
 3(11813) DEBUG : tic_response_callback : there's no transaction waiting binding
 3(11813) TIC:tic_response_callback:  No operation
 3(11813) forward_reply: found module tm, passing reply to it
 3(11813) DEBUG: t_check: msg id=16 global id=15 T start=(nil)
 3(11813) parse_headers: flags=17
 3(11813) parse_headers: flags=4
 3(11813) DEBUG: t_reply_matching: hash 50532 label 142205825 branch 0
 3(11813) DEBUG: t_reply_matching: no matching transaction exists
 3(11813) DEBUG: t_reply_matching: failure to match a transaction
 3(11813) DEBUG: t_check: msg id=16 global id=16 T end=(nil)
 3(11813) parse_headers: flags=2
 3(11813) Found param type 232, <branch> = <z9hG4bK0a0000960000002e46b3117f00006e8f0000000a>; state=6
 3(11813) Found param type 235, <rport> = <5060>; state=16
 3(11813) end of header reached, state=5
 3(11813) parse_headers: Via found, flags=2
 3(11813) parse_headers: this is the second via
 3(11813) header field type 1, name=<Via>, body=<SIP/2.0/UDP 192.168.200.141;branch=z9hG4bK0a0000960000002e46b3117f00006e8f0000000a;rport=5060>
 3(11813)  old size: 963, new size: 901
 3(11813) build_res_from_sip_res: copied size: orig:266, new: 204, rest: 697 msg=
SIP/2.0 200 OK
Call-ID: 982596E3E4D842A9B30F0F58934E96480x0a000096
CSeq: 1 INVITE
From: "hp_cesc" <sip:7008 at 192.168.200.71>;tag=4cb08f2cfe0
To: <sip:grp.commander at 192.168.200.71>;tag=467b94ac5d199bf
Via: SIP/2.0/UDP 192.168.200.141;branch=z9hG4bK0a0000960000002e46b3117f00006e8f0000000a;rport=5060
Record-Route: <sip:192.168.200.71;ftag=4cb08f2cfe0;lr=on>
Content-Length: 259
Allow: NOTIFY
Allow: REFER
Allow: OPTIONS
Allow: INVITE
Allow: ACK
Allow: CANCEL
Allow: BYE
Content-Type: application/sdp
Supported: replaces
Contact: <sip:grp.commander at 192.168.200.33>
User-Agent: Elite 1.0 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26

v=0
o=MxSIP 0 1581884204 IN IP4 192.168.200.33
s=SIP Call
c=IN IP4 192.168.200.33
t=0 0
m=audio 16384 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=silenceSupp:off - - - -

 3(11813) update_sock_struct_from_via: using 'rport'
 3(11813) update_sock_struct_from_via: using via host
 3(11813) update_sock_struct_from_via: trying SRV lookup
 3(11813) DEBUG: get_out_socket: socket determined: 0x81b60f8
 3(11813)  reply forwarded to 192.168.200.141:0
 3(11813) DEBUG:destroy_avp_list: destroying list (nil)
 3(11813) receive_msg: cleaning up
 3(11813) SIP Reply  (status):
 3(11813)  version: <SIP/2.0>
 3(11813)  status:  <200>
 3(11813)  reason:  <OK>
 3(11813) parse_headers: flags=1
 3(11813) header field type 32, name=<Call-ID>, body=<982596E3E4D842A9B30F0F58934E96480x0a000096>
 3(11813) get_hdr_field: cseq <CSeq>: <1> <INVITE>
 3(11813) header field type 16, name=<CSeq>, body=<1 INVITE>
 3(11813) header field type 8, name=<From>, body=<"hp_cesc" <sip:7008 at 192.168.200.71>;tag=4cb08f2cfe0>
 3(11813) DEBUG: add_param: tag=467b94ac5d199bf
 3(11813) end of header reached, state=29
 3(11813) DEBUG: get_hdr_field: <To> [56]; uri=[sip:grp.commander at 192.168.200.71]
 3(11813) DEBUG: to body [<sip:grp.commander at 192.168.200.71>]
 3(11813) header field type 4, name=<To>, body=<<sip:grp.commander at 192.168.200.71>;tag=467b94ac5d199bf>
 3(11813) Found param type 232, <branch> = <z9hG4bK465c.183e978.0>; state=16
 3(11813) end of header reached, state=5
 3(11813) parse_headers: Via found, flags=1
 3(11813) parse_headers: this is the first via
 3(11813) header field type 1, name=<Via>, body=<SIP/2.0/UDP 192.168.200.71;branch=z9hG4bK465c.183e978.0>
 3(11813)  first  via: <SIP/2.0/UDP> <192.168.200.71:(0)> 3(11813) ;<> 3(11813)
 3(11813) exiting parse_msg
 3(11813) After parse_msg...
 3(11813) TIC:tic_response_callback: starting
 3(11813) DEBUG : tic_response_callback : there's no transaction waiting binding
 3(11813) TIC:tic_response_callback:  No operation
 3(11813) forward_reply: found module tm, passing reply to it
 3(11813) DEBUG: t_check: msg id=17 global id=16 T start=(nil)
 3(11813) parse_headers: flags=17
 3(11813) parse_headers: flags=4
 3(11813) DEBUG: t_reply_matching: hash 50532 label 142205825 branch 0
 3(11813) DEBUG: t_reply_matching: no matching transaction exists
 3(11813) DEBUG: t_reply_matching: failure to match a transaction
 3(11813) DEBUG: t_check: msg id=17 global id=17 T end=(nil)
 3(11813) parse_headers: flags=2
 3(11813) Found param type 232, <branch> = <z9hG4bK0a0000960000002e46b3117f00006e8f0000000a>; state=6
 3(11813) Found param type 235, <rport> = <5060>; state=16
 3(11813) end of header reached, state=5
 3(11813) parse_headers: Via found, flags=2
 3(11813) parse_headers: this is the second via
 3(11813) header field type 1, name=<Via>, body=<SIP/2.0/UDP 192.168.200.141;branch=z9hG4bK0a0000960000002e46b3117f00006e8f0000000a;rport=5060>
 3(11813)  old size: 963, new size: 901
 3(11813) build_res_from_sip_res: copied size: orig:266, new: 204, rest: 697 msg=
SIP/2.0 200 OK
Call-ID: 982596E3E4D842A9B30F0F58934E96480x0a000096
CSeq: 1 INVITE
From: "hp_cesc" <sip:7008 at 192.168.200.71>;tag=4cb08f2cfe0
To: <sip:grp.commander at 192.168.200.71>;tag=467b94ac5d199bf
Via: SIP/2.0/UDP 192.168.200.141;branch=z9hG4bK0a0000960000002e46b3117f00006e8f0000000a;rport=5060
Record-Route: <sip:192.168.200.71;ftag=4cb08f2cfe0;lr=on>
Content-Length: 259
Allow: NOTIFY
Allow: REFER
Allow: OPTIONS
Allow: INVITE
Allow: ACK
Allow: CANCEL
Allow: BYE
Content-Type: application/sdp
Supported: replaces
Contact: <sip:grp.commander at 192.168.200.33>
User-Agent: Elite 1.0 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26

v=0
o=MxSIP 0 1581884204 IN IP4 192.168.200.33
s=SIP Call
c=IN IP4 192.168.200.33
t=0 0
m=audio 16384 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=silenceSupp:off - - - -

 3(11813) update_sock_struct_from_via: using 'rport'
 3(11813) update_sock_struct_from_via: using via host
 3(11813) update_sock_struct_from_via: trying SRV lookup
 3(11813) DEBUG: get_out_socket: socket determined: 0x81b60f8
 3(11813)  reply forwarded to 192.168.200.141:0
 3(11813) DEBUG:destroy_avp_list: destroying list (nil)


More information about the sr-users mailing list