[Users] loose_route goes strict - Stray colon in Record-Route

G.Jacobsen g_jacobsen at yahoo.co.uk
Thu Jun 29 09:06:55 CEST 2006 

Further to below problem regarding BYEs not loose_routed.

I see now that openser sends the invite with a wierd colon at the end of
"127.0.0.1:" in record route. The same colon is of course also present in
the BYEs which loop.

Is it possible that OS gets confused by this when receiving the BYE ? What
causes this - How can I work around this ?

Thanks a lot for your help in the matter. I am using openser 1.0.1

Gerry

Inivite sent by OS:

INVITE sip:7336058 at 127.0.0.1:5061 SIP/2.0
Max-Forwards: 10
Record-Route: <sip:127.0.0.1:;r2=on;ftag=as58f53672;lr=on>
Record-Route: <sip:101.101.101.101;r2=on;ftag=as58f53672;lr=on>
Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK39c3.dcf37ad6.0
Via: SIP/2.0/UDP 202.202.202.202:5060;branch=z9hG4bK2955936f
From: "7654321" <sip:7654321 at XXXXXXXXXXXX>;tag=as58f53672
To: <sip:7654321 at XXXXXXXXXXXX>
Contact: <sip:7654321 at 202.202.202.202>
Call-ID: 5cdc877611378bf05dc78ef3035be7fb at xxxxxxxxxxxxxx
CSeq: 103 INVITE
User-Agent: Asterisk PBX
Date: Thu, 29 Jun 2006 07:23:52 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Content-Type: application/sdp
Content-Length: 240




-----Original Message-----
From: G.Jacobsen [mailto:g_jacobsen at yahoo.co.uk]
Sent: Donnerstag, 29. Juni 2006 01:04
To: Devel at Openser. Org
Subject: loose_route goes strict with BYEs


Gentlemen,

I have openser sitting on the same machine as another UA - openser is on
port 5060 the other on 5061. BYEs by the UA are not loose_routed to the
originating client - causing the BYEs to loop on openser with 513 message
too big.

I am not sure whether this is related - but a similar problem seems to have
been touched here before - still cant find the solution.
http://openser.org/pipermail/devel/2006-April/002540.html

I have put all aliases with the port 5060 now - still doesnt help.

If I read the debug correctly openser does strict routing on this line - why
?
"rewrite_uri: Rewriting Request-URI with
'sip:111.111.111.111;r2=on;ftag=109880961431220;lr=on' "

I would be most grateful if someone could explain which parameter causes the
BYE to go strict.

TIA Gerry

Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: SIP Request:
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:  method:  <BYE>
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:  uri:
<sip:1234567 at sip.somedomain.com:5060>
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:  version: <SIP/2.0>
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=2
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG: add_param:
tag=109880961431220
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG:parse_to:end
of header reached, state=29
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG:
get_hdr_field: <To> [55]; uri=[sip:1234567 at sip.somedomain.com:5060]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG: to body
[<sip:1234567 at sip.somedomain.com:5060>]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: Found param type
235, <rport> = <n/a>; state=6
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: Found param type
232, <branch> = <z9hG4bK719885386>; state=16
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: end of header
reached, state=5
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers: Via
found, flags=2
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers: this
is the first via
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: After parse_msg...
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: preparing to run
routing scripts...
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=100
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: get_hdr_field: cseq
<CSeq>: <2> <BYE>
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:
DEBUG:maxfwd:is_maxfwd_present: value = 70
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG: add_param:
tag=1957747793
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG:parse_to:end
of header reached, state=29
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=200
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: is_preloaded: No
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if host==us: 14==9 &&  [sip.somedomain.com] == [127.0.0.1]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if port 5060 matches port 5060
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if host==us: 14==13 &&  [sip.somedomain.com] == [111.111.111.111]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if port 5060 matches port 5060
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if host==us: 14==9 &&  [sip.somedomain.com] == [127.0.0.1]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if port 5060 matches port 5060
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if host==us: 14==13 &&  [sip.somedomain.com] == [111.111.111.111]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if port 5060 matches port 5060
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if host==us: 9==9 &&  [127.0.0.1] == [127.0.0.1]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if port 5060 matches port 5060
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: grep_sock_info -
checking if host==us: 9==9 &&  [127.0.0.1] == [127.0.0.1]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:
DBG:rr:run_rr_callbacks: callback id 0 entered
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:
DEBUG:uac:restore_from: getting 'vsf' Route param
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:
DEBUG:uac:restore_from: Route param 'vsf' not found
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: after_strict: Next
hop: 'sip:111.111.111.111;r2=on;ftag=109880961431220;lr=on' is loose router
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=ffffffffffffffff
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG: get_hdr_body
: content_length=0
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: found end of header
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: rewrite_uri:
Rewriting Request-URI with
'sip:111.111.111.111;r2=on;ftag=109880961431220;lr=on'
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: after_strict: The
last route URI: 'sip:111.111.111.111;r2=on;ftag=109880961431220;lr=on'
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=ffffffffffffffff
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=58
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: rc_get_seqnbr:
couldn't open sequence file /var/run/radius.seq: Permission denied
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=58
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: ACC: request
accounted: method=BYE, i-uri=sip:1234567 at sip.somedomain.com:5060,
o-uri=sip:111.111.111.111;r2=on;ftag=109880961431220;lr=on,
call_id=2BCF5051-F28C-4CCA-AE6B-D895607B668E at 81.198.36.24,
from=<sip:7654321 at sip.somedomain.com:5060>;tag=1957747793, code=200 ok
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG: t_newtran:
msg id=2 , global msg id=1 , T on entrance=0xffffffff
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=ffffffffffffffff
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: parse_headers:
flags=78
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: t_lookup_request:
start searching: hash=51354, isACK=0
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG: RFC3261
transaction matching failed
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG:
t_lookup_request: no transaction found
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DBG:
trans=0x405797d8, callback type 1, id 0 entered
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG: mk_proxy:
doing DNS lookup...
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:
check_via_address(127.0.0.1, 127.0.0.1, 0)
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG:
add_to_tail_of_timer[4]: 0x405798f4
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: SIP Request:
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: DEBUG:
add_to_tail_of_timer[0]: 0x40579904
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]:  method:  <BYE>
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: SER: new
transaction fwd'ed
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]:  uri:
<sip:111.111.111.111;r2=on;ftag=109880961431220;lr=on>
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]:
DEBUG:destroy_avp_list: destroying list (nil)
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]:  version: <SIP/2.0>
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19818]: receive_msg:
cleaning up
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: parse_headers:
flags=2
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: DEBUG: add_param:
tag=109880961431220
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: DEBUG:parse_to:end
of header reached, state=29
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: DEBUG:
get_hdr_field: <To> [55]; uri=[sip:1234567 at sip.somedomain.com:5060]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: DEBUG: to body
[<sip:1234567 at sip.somedomain.com:5060>]
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: Found param type
232, <branch> = <z9hG4bKa98c.f4c21e03.0>; state=16
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: end of header
reached, state=5
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: parse_headers: Via
found, flags=2
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: parse_headers: this
is the first via
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: After parse_msg...
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: preparing to run
routing scripts...
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: parse_headers:
flags=100
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: Found param type
235, <rport> = <5061>; state=6
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: Found param type
232, <branch> = <z9hG4bK719885386>; state=16
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: end of header
reached, state=5
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: parse_headers: Via
found, flags=100
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: parse_headers: this
is the second via
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: get_hdr_field: cseq
<CSeq>: <2> <BYE>
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]:
DEBUG:maxfwd:is_maxfwd_present: value = 69
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: DEBUG: add_param:
tag=1957747793
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: DEBUG:parse_to:end
of header reached, state=29
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: parse_headers:
flags=200
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: DEBUG: get_hdr_body
: content_length=0
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: found end of header
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: find_first_route:
No Route headers found
Jun 29 00:32:16 gatesip1 /usr/local/sbin/openser[19830]: loose_route: There
is no Route HF


	
	
		
___________________________________________________________ 
All new Yahoo! Mail "The new Interface is stunning in its simplicity and ease of use." - PC Magazine 
http://uk.docs.yahoo.com/nowyoucan.html

More information about the sr-users mailing list