[Serusers] [Serdev] [Tracker] Created: (SER-332) tcp branching error
Tomasz Zieleniewski
tzieleniewski at gmail.com
Fri Nov 23 11:47:48 CET 2007
Hi,
Some more debug information:
User contacts:
ser at sen:~/ser/ser-2.0/ssp$ ./serctl/ser_ctl usrloc show touk at voip.rd.touk.pl
sip:touk at 192.168.0.164:1338;rinstance=191d670c84591ea3;transport=TCP 3330 -1.0
sip:touk at 192.168.0.164:1348;rinstance=e51fd20db73fc732;transport=TCP 3405 -1.0
Contents of the location table:
mysql> select * from location where uid like 'touk@%';
+----------------------+--------------------------+----------------------------------------------------------------------+----------+---------------------+----+----------------------------------------------+------+-------+----------------------------------+----------+
| uid | aor | contact
| received | expires
| q | callid | cseq
| flags | user_agent | instance |
+----------------------+--------------------------+----------------------------------------------------------------------+----------+---------------------+----+----------------------------------------------+------+-------+----------------------------------+----------+
| touk at voip.rd.touk.pl | sip:touk at voip.rd.touk.pl |
sip:touk at 192.168.0.164:1338;rinstance=191d670c84591ea3;transport=TCP |
NULL | 2007-11-23 11:17:03 | -1 |
MTQ1ZWZmZWE2MWIxZjViYmVkNzZlNmU0YTEwNjRmMTA. | 4 | 0 | X-Lite
release 1011s stamp 41150 | NULL |
| touk at voip.rd.touk.pl | sip:touk at voip.rd.touk.pl |
sip:touk at 192.168.0.164:1348;rinstance=e51fd20db73fc732;transport=TCP |
NULL | 2007-11-23 11:18:18 | -1 |
NDk0ZDA3ZmU5NmFlZmYyMjA5Mjc2ZTZiYTFmMTMxODY. | 4 | 0 | X-Lite
release 1011s stamp 41150 | NULL |
+----------------------+--------------------------+----------------------------------------------------------------------+----------+---------------------+----+----------------------------------------------+------+-------+----------------------------------+----------+
2 rows in set (0.00 sec)
Here is what does the internal proxy (192.168.0.165:7160) which is
registrar and perform location service,
the destination set contains both contacts and the first contact used
is the one which is unavailable.
this proxy sends first invite with this contact to boundary sip proxy
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: xlset_attr(bsp_route,
<$global_addr_bsp;lr=on>)
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: attr_destination($bsp_route)
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: ($fr_inv_timer)
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: t_on_reply(ONREPLY_ROUTE)
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: t_on_failure(FAILURE_ROUTE)
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: t_on_branch(BRANCH_ROUTE)
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: destination set:
Contact: sip:touk at 192.168.0.164:1338;rinstance=191d670c84591ea3;transport=TCP,
sip:touk at 192.168.0.164:1348;rinstance=e51fd20db73fc732;transpo
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: next route: <null>
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: message's next hop:
sip:voip.rd.touk.pl:7060;lr=on
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: (!t_relay())
Nov 23 11:20:27 sen ser[28434]: branch_route[BRANCH_ROUTE]: <INVITE>
ruri:<sip:touk at 192.168.0.164:1338;rinstance=191d670c84591ea3;transport=TCP>
t:<sip:touk at voip.rd.touk.pl> f:<sip:hellboy at voip.rd.touk.pl> c
Nov 23 11:20:27 sen ser[28434]: branch_route[BRANCH_ROUTE]:
append_hf(P-Warn: forked branch)
Nov 23 11:20:27 sen ser[28434]: branch_route[BRANCH_ROUTE]: <INVITE>
ruri:<sip:touk at 192.168.0.164:1348;rinstance=e51fd20db73fc732;transport=TCP>
t:<sip:touk at voip.rd.touk.pl> f:<sip:hellboy at voip.rd.touk.pl> c
Nov 23 11:20:27 sen ser[28434]: branch_route[BRANCH_ROUTE]:
append_hf(P-Warn: forked branch)
Nov 23 11:20:27 sen ser[28434]: ERROR: tcp_blocking_connect: poll
error: flags 18
Nov 23 11:20:27 sen ser[28434]: ERROR: tcp_blocking_connect: SO_ERROR
(111) Connection refused
Nov 23 11:20:27 sen ser[28434]: ERROR: tcpconn_connect:
tcp_blocking_connect failed
Nov 23 11:20:27 sen ser[28434]: ERROR: tcp_send: connect failed
Nov 23 11:20:27 sen ser[28434]: msg_send: ERROR: tcp_send failed
Nov 23 11:20:27 sen ser[28434]: ERROR: t_send_branch: sending request
on branch 1 failed
Nov 23 11:20:27 sen ser[28434]: route[FORWARD]: drop
here is what happens in boundary sip proxy:
is receives the invite tries to do the t_rqlay but there is the tcp error.
t_relay() fails and it sends the sl_reply_error to internal sip proxy:
Nov 23 11:31:38 sen ser[31861]: route[FORWARD]: destination set: <null>
Nov 23 11:31:38 sen ser[31861]: route[FORWARD]: next route: <null>
Nov 23 11:31:38 sen ser[31861]: route[FORWARD]: message's next hop:
sip:touk at 192.168.0.164:1338;rinstance=191d670c84591ea3;transport=TCP
Nov 23 11:31:38 sen ser[31861]: route[FORWARD]: (!t_relay())
Nov 23 11:31:38 sen ser[31861]: ERROR: tcp_blocking_connect: poll
error: flags 18
Nov 23 11:31:38 sen ser[31861]: ERROR: tcp_blocking_connect: SO_ERROR
(111) Connection refused
Nov 23 11:31:38 sen ser[31861]: ERROR: tcpconn_connect:
tcp_blocking_connect failed
Nov 23 11:31:38 sen ser[31861]: ERROR: tcp_send: connect failed
Nov 23 11:31:38 sen ser[31861]: msg_send: ERROR: tcp_send failed
Nov 23 11:31:38 sen ser[31861]: ERROR: t_send_branch: sending request
on branch 0 failed
Nov 23 11:31:38 sen ser[31861]: route[FORWARD]: (!t_relay()) -> TRUE
Nov 23 11:31:38 sen ser[31861]: route[FORWARD]: sl_reply_error()
Nov 23 11:31:38 sen ser[31861]: ERROR: sl_reply_error used: I'm
terribly sorry, server error occurred (1/SL)
in the attachment there are ngrep and wireshark log from the same situation
if you need more info please let me know
waiting for your feedback
Cheers
tomasz
On Nov 22, 2007 8:40 PM, Andrei Pelinescu-Onciul <andrei at iptel.org> wrote:
> On Nov 16, 2007 at 14:43, Tomasz Zieleniewski (JIRA) <tracker at iptel.org> wrote:
> > tcp branching error
> > -------------------
> >
> > Key: SER-332
> > URL: http://tracker.iptel.org/browse/SER-332
> > Project: SER
> > Issue Type: Bug
> > Components: core
> > Affects Versions: 2.0
> > Environment: Linux sen 2.6.18-5-amd64 #1 SMP Tue Oct 2 20:37:02 UTC 2007 x86_64 GNU/Linux
> > Reporter: Tomasz Zieleniewski
> > Priority: Critical
> >
> >
> > Hi,
> >
> > I have the following situation.
> > I have two ser rel_2_0_0 instances one acting as a boundary proxy the
> > other on as internal proxy (registrar, location).
> >
> > I have the following situation I have a user which has registered two
> > contacs one woth tcp transport the other one with udp.
> >
> > All messages coming to and outgoing from my network travels through
> > boundary sip proxy.
> >
> > When internal ser perform lookup_location it get to contacts and the
> > destination set contains two records:
> > Nov 15 11:03:13 sen ser[3673]: route[FORWARD]: destination set:
> > Contact: sip:xlite at 192.168.0.164:1221;rinstance=d35f9cda6bd79b0a;transport=TCP,
> > sip:xlite at 192.168.0.164:7060
> >
> > Then internal ser forward message to boundary SIP proxy by changing
> > the destination of the message and with the usage of t_relay().
> > I see from log that there are two branches involved:
> > Nov 15 11:03:13 sen ser[3673]: branch_route[BRANCH_ROUTE]: <INVITE>
> > ruri:<sip:xlite at 192.168.0.164:1221;rinstance=d35f9cda6bd79b0a;transport=TCP>
> > t:<sip:00 at voip.rd.touk.pl> f:<sip:lkl at voip.rd.touk.pl>
> > Nov 15 11:03:13 sen ser[3673]: branch_route[BRANCH_ROUTE]:
> > append_hf(P-Warn: forked branch)
> > Nov 15 11:03:13 sen ser[3673]: branch_route[BRANCH_ROUTE]: <INVITE>
> > ruri:<sip:xlite at 192.168.0.164:7060;rinstance=cfca8523e3747cb0>
> > t:<sip:00 at voip.rd.touk.pl> f:<sip:lkl at voip.rd.touk.pl>
> > Nov 15 11:03:13 sen ser[3673]: branch_route[BRANCH_ROUTE]:
> > append_hf(P-Warn: forked branch)
> >
> > both INVITES reaches boudary SIP proxy.
> >
> > Because first contact was unreachable there was an tcp error:
> > ser[3516]: ERROR: tcp_blocking_connect: poll error: flags 18
> > Nov 15 11:03:13 sen ser[3516]: ERROR: tcp_blocking_connect: SO_ERROR
> > (111) Connection refused
> > Nov 15 11:03:13 sen ser[3516]: ERROR: tcpconn_connect:
> > tcp_blocking_connect failed
> > Nov 15 11:03:13 sen ser[3516]: ERROR: tcp_send: connect failed
> > Nov 15 11:03:13 sen ser[3516]: msg_send: ERROR: tcp_send failed
> > Nov 15 11:03:13 sen ser[3516]: ERROR: t_send_branch: sending request
> > on branch 0 failed
> >
> > after which ser invokes sl_reply_error() which results in 477 next hop
> > error reponse message sent to internal ser instance.
> > The problem arises when boudary sip proxy processes second INVITE
> > which correspond to second destination.
> > when boundary SIP proxy receives it doesn't send it to user agent but
> > instead reponses to internal ser with
> > 500 I'm terribly sorry, server error occurred (1/SL)
> > the only thing I see in the boundary SIP proxy log is:
> > ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL)
> >
> > Did I miss something here or this is an error?
> > Waiting for Your feedback
> >
>
> Could you make some traffic dump between the 2 proxies and send it to me
> (andrei at iptel.org)?
> It's sounds quite strange (it should work without any problems) and a
> look at the packets might help.
>
>
> Thanks,
> Andrei
> _______________________________________________
> Serdev mailing list
> Serdev at lists.iptel.org
> http://lists.iptel.org/mailman/listinfo/serdev
>
More information about the sr-users
mailing list