Howdy,
I'm playing with OPENSER 0.9.5 with sipp as the workload generator on a bunch of linux boxes. When the transport is UDP, openser adds a via header like it is supposed to as a proxy. But when I use TCP no via header is added. This is a UAC->proxy->UAS scenario. Here's the header as seen at the UAS:
| UDP message received [633] bytes : | | INVITE sip:service@10.0.1.41:5060 SIP/2.0 | Record-Route: sip:10.0.1.42;ftag=1;lr=on | Via: SIP/2.0/UDP 10.0.1.42;branch=z9hG4bKe9cc.cc24a79.0 | Via: SIP/2.0/UDP bronxville1:5060;received=10.0.1.40;branch=z9hG4bK-1-0 | From: sipp sip:sipp@bronxville1:5060;tag=1 | To: sut sip:service@10.0.1.41:5060 | Call-ID: 1-31891@bronxville1 | CSeq: 1 INVITE | Contact: sip:sipp@bronxville1:5060 | Max-Forwards: 16 | Subject: Performance Test | Content-Type: application/sdp | Content-Length: 132 | P-hint: outbound
And the corresponding message received at the UAS when using TCP:
| TCP message received [495] bytes : | | INVITE sip:service@10.0.1.41:5060 SIP/2.0 | Via: SIP/2.0/TCP bronxville1:5060;branch=z9hG4bK-1-0 | From: sipp sip:sipp@bronxville1:5060;tag=1 | To: sut sip:service@10.0.1.41:5060 | Call-ID: 1-31865@bronxville1 | CSeq: 1 INVITE | Contact: sip:sipp@bronxville1:5060 | Max-Forwards: 70 | Subject: Performance Test | Content-Type: application/sdp | Content-Length: 132
Note the absence of the 2nd Via header. Openser complains about this on the way back to the UAC.
Any suggestions appreciated.
Thanks,
-Erich
Hi Erich,
do you get any errors in the log when OpenSER forwards the request over TCP? why is the RR header missing when using TCP? can you post for the TCP case, the full network capture -incoming and outgoing message with addresses and ports?
thanks for report and regards, bogdan
Erich Nahum wrote:
Howdy,
I'm playing with OPENSER 0.9.5 with sipp as the workload generator on a bunch of linux boxes. When the transport is UDP, openser adds a via header like it is supposed to as a proxy. But when I use TCP no via header is added. This is a UAC->proxy->UAS scenario. Here's the header as seen at the UAS:
| UDP message received [633] bytes : | | INVITE sip:service@10.0.1.41:5060 SIP/2.0 | Record-Route: sip:10.0.1.42;ftag=1;lr=on | Via: SIP/2.0/UDP 10.0.1.42;branch=z9hG4bKe9cc.cc24a79.0 | Via: SIP/2.0/UDP bronxville1:5060;received=10.0.1.40;branch=z9hG4bK-1-0 | From: sipp sip:sipp@bronxville1:5060;tag=1 | To: sut sip:service@10.0.1.41:5060 | Call-ID: 1-31891@bronxville1 | CSeq: 1 INVITE | Contact: sip:sipp@bronxville1:5060 | Max-Forwards: 16 | Subject: Performance Test | Content-Type: application/sdp | Content-Length: 132 | P-hint: outbound
And the corresponding message received at the UAS when using TCP:
| TCP message received [495] bytes : | | INVITE sip:service@10.0.1.41:5060 SIP/2.0 | Via: SIP/2.0/TCP bronxville1:5060;branch=z9hG4bK-1-0 | From: sipp sip:sipp@bronxville1:5060;tag=1 | To: sut sip:service@10.0.1.41:5060 | Call-ID: 1-31865@bronxville1 | CSeq: 1 INVITE | Contact: sip:sipp@bronxville1:5060 | Max-Forwards: 70 | Subject: Performance Test | Content-Type: application/sdp | Content-Length: 132
Note the absence of the 2nd Via header. Openser complains about this on the way back to the UAC.
Any suggestions appreciated.
Thanks,
-Erich
On Mon, Jul 25, 2005 at 03:05:23PM +0300, Bogdan-Andrei Iancu wrote:
do you get any errors in the log when OpenSER forwards the request over TCP? why is the RR header missing when using TCP? can you post for the TCP case, the full network capture -incoming and outgoing message with addresses and ports?
Looking at the dumps in ethereal, it seems that it is in fact sipp that is not including both the via headers in the UAS response under TCP.
Sorry for the false alarm, but thanks for the response.
PS: Love the "your call is important to us" message.
-Erich
On Mon, Jul 25, 2005 at 03:05:23PM +0300, Bogdan-Andrei Iancu wrote:
do you get any errors in the log when OpenSER forwards the request over TCP? why is the RR header missing when using TCP? can you post for the TCP case, the full network capture -incoming and outgoing message with addresses and ports?
Sorry, I was mistaken before when I said I was mistaken. The fault does seem to be from openser. I was looking at the wrong dumps. I'm attaching the following items in the hopes that they illustrate the problem:
ethereal text dump of UAC TCP ethereal text dump of UAC UDP ethereal text dump of UAS TCP ethereal text dump of UAS UDP logs from /var/log/messages with debug=5
To cut to the chase, here's a diff of the UAS TCP packet with the UDP. bronxville == UAC == 10.0.1.40 crestwood == proxy == 10.0.1.42 tuckahoe == UAS == 10.0.1.41
< Via: SIP/2.0/TCP bronxville1:5060;branch=z9hG4bK-1-0 ---
Record-Route: <sip:10.0.1.42;ftag=1;lr=on> Via: SIP/2.0/UDP 10.0.1.42;branch=z9hG4bKcf89.f46403c6.0 Via: SIP/2.0/UDP bronxville1:5060;received=10.0.1.40;branch=z9hG4bK-1-0
15c17 < Call-ID: 1-26885@bronxville1 ---
Call-ID: 1-26914@bronxville1
18c20 < Max-Forwards: 70 ---
Max-Forwards: 16
21a24
P-hint: outbound
Thanks,
-Erich
Hi Erich,
thanks for the log - I will look into them and try to find the problem asap.
regards, bogdan
Erich Nahum wrote:
On Mon, Jul 25, 2005 at 03:05:23PM +0300, Bogdan-Andrei Iancu wrote:
do you get any errors in the log when OpenSER forwards the request over TCP? why is the RR header missing when using TCP? can you post for the TCP case, the full network capture -incoming and outgoing message with addresses and ports?
Sorry, I was mistaken before when I said I was mistaken. The fault does seem to be from openser. I was looking at the wrong dumps. I'm attaching the following items in the hopes that they illustrate the problem:
ethereal text dump of UAC TCP ethereal text dump of UAC UDP ethereal text dump of UAS TCP ethereal text dump of UAS UDP logs from /var/log/messages with debug=5
To cut to the chase, here's a diff of the UAS TCP packet with the UDP. bronxville == UAC == 10.0.1.40 crestwood == proxy == 10.0.1.42 tuckahoe == UAS == 10.0.1.41
< Via: SIP/2.0/TCP bronxville1:5060;branch=z9hG4bK-1-0
Hi Erich,
I analysed a little bit the dumps and logs you sent and I would say there is nothing wrong with OpenSER here - it seams more like the result of strange SIP UAs:
The second TCP message is from .40 -> .41 which is UAC -> UAS. For the first message the IP/TCP headers are missing. So, the SIP requests over TCP does not hit the proxy at all!! For UDP, the net dump shows two requests, 40 -> 42 and 42->41, which is the normal path.
In same idea, you can notice in OpenSER logs that there is no log regarding the request, but only some replies processing. And this is very, very strange!!! The UAS receives the request via TCP directly from UAC, but sends back the reply to proxy, ignoring the VIA stack.....that's broken...
I will strongly advice to re-try the scenario using different SIP UAs.
regards, bogdan
Erich Nahum wrote:
On Mon, Jul 25, 2005 at 03:05:23PM +0300, Bogdan-Andrei Iancu wrote:
do you get any errors in the log when OpenSER forwards the request over TCP? why is the RR header missing when using TCP? can you post for the TCP case, the full network capture -incoming and outgoing message with addresses and ports?
Sorry, I was mistaken before when I said I was mistaken. The fault does seem to be from openser. I was looking at the wrong dumps. I'm attaching the following items in the hopes that they illustrate the problem:
ethereal text dump of UAC TCP ethereal text dump of UAC UDP ethereal text dump of UAS TCP ethereal text dump of UAS UDP logs from /var/log/messages with debug=5
To cut to the chase, here's a diff of the UAS TCP packet with the UDP. bronxville == UAC == 10.0.1.40 crestwood == proxy == 10.0.1.42 tuckahoe == UAS == 10.0.1.41
< Via: SIP/2.0/TCP bronxville1:5060;branch=z9hG4bK-1-0
Record-Route: <sip:10.0.1.42;ftag=1;lr=on> Via: SIP/2.0/UDP 10.0.1.42;branch=z9hG4bKcf89.f46403c6.0 Via: SIP/2.0/UDP bronxville1:5060;received=10.0.1.40;branch=z9hG4bK-1-015c17
< Call-ID: 1-26885@bronxville1
Call-ID: 1-26914@bronxville118c20
< Max-Forwards: 70
Max-Forwards: 1621a24
P-hint: outboundThanks,
-Erich
Session Initiation Protocol Request-Line: INVITE sip:service@10.0.1.41:5060 SIP/2.0 Method: INVITE Resent Packet: False Message Header Via: SIP/2.0/TCP bronxville1:5060;branch=z9hG4bK-1-0 From: sipp sip:sipp@bronxville1:5060;tag=1 SIP from address: sipp sip:sipp@bronxville1:5060 SIP tag: 1 To: sut sip:service@10.0.1.41:5060 Call-ID: 1-27019@bronxville1 CSeq: 1 INVITE Contact: sip:sipp@bronxville1:5060 Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 132 Message body
Frame 7 (537 bytes on wire, 537 bytes captured) Ethernet II, Src: 00:11:25:29:11:5d, Dst: 00:0d:60:9d:30:3f Internet Protocol, Src Addr: 10.0.1.40 (10.0.1.40), Dst Addr: 10.0.1.42 (10.0.1.42) User Datagram Protocol, Src Port: 5060 (5060), Dst Port: 5060 (5060) Session Initiation Protocol Request-Line: INVITE sip:service@10.0.1.41:5060 SIP/2.0 Method: INVITE Resent Packet: False Message Header Via: SIP/2.0/UDP bronxville1:5060;branch=z9hG4bK-1-0 From: sipp sip:sipp@bronxville1:5060;tag=1 SIP from address: sipp sip:sipp@bronxville1:5060 SIP tag: 1 To: sut sip:service@10.0.1.41:5060 Call-ID: 1-28105@bronxville1 CSeq: 1 INVITE Contact: sip:sipp@bronxville1:5060 Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 132 Message body
Frame 16 (561 bytes on wire, 561 bytes captured) Ethernet II, Src: 00:11:25:29:11:5d, Dst: 00:0d:60:9d:73:db Internet Protocol, Src Addr: 10.0.1.40 (10.0.1.40), Dst Addr: 10.0.1.41 (10.0.1.41) Transmission Control Protocol, Src Port: 56280 (56280), Dst Port: 5060 (5060), Seq: 1, Ack: 1, Len: 495 Session Initiation Protocol Request-Line: INVITE sip:service@10.0.1.41:5060 SIP/2.0 Method: INVITE Resent Packet: False Message Header Via: SIP/2.0/TCP bronxville1:5060;branch=z9hG4bK-1-0 From: sipp sip:sipp@bronxville1:5060;tag=1 SIP from address: sipp sip:sipp@bronxville1:5060 SIP tag: 1 To: sut sip:service@10.0.1.41:5060 Call-ID: 1-26885@bronxville1 CSeq: 1 INVITE Contact: sip:sipp@bronxville1:5060 Max-Forwards: 70 Subject: Performance Test Content-Type: application/sdp Content-Length: 132 Message body
Frame 10 (676 bytes on wire, 676 bytes captured) Ethernet II, Src: 00:0d:60:9d:30:3f, Dst: 00:0d:60:9d:73:db Internet Protocol, Src Addr: 10.0.1.42 (10.0.1.42), Dst Addr: 10.0.1.41 (10.0.1.41) User Datagram Protocol, Src Port: 5060 (5060), Dst Port: 5060 (5060) Session Initiation Protocol Request-Line: INVITE sip:service@10.0.1.41:5060 SIP/2.0 Method: INVITE Resent Packet: False Message Header Record-Route: sip:10.0.1.42;ftag=1;lr=on Via: SIP/2.0/UDP 10.0.1.42;branch=z9hG4bKcf89.f46403c6.0 Via: SIP/2.0/UDP bronxville1:5060;received=10.0.1.40;branch=z9hG4bK-1-0 From: sipp sip:sipp@bronxville1:5060;tag=1 SIP from address: sipp sip:sipp@bronxville1:5060 SIP tag: 1 To: sut sip:service@10.0.1.41:5060 Call-ID: 1-26914@bronxville1 CSeq: 1 INVITE Contact: sip:sipp@bronxville1:5060 Max-Forwards: 16 Subject: Performance Test Content-Type: application/sdp Content-Length: 132 P-hint: outbound Message body
Jul 26 19:21:06 crestwood ./openser[27474]: tcpconn_new: new tcp connection: 10.0.1.41 Jul 26 19:21:06 crestwood ./openser[27474]: tcpconn_new: on port 47197, type 2 Jul 26 19:21:06 crestwood ./openser[27474]: tcpconn_add: hashes: 87, 9 Jul 26 19:21:06 crestwood ./openser[27474]: tcp_main_loop: new connection: 0x403b6e10 64 Jul 26 19:21:06 crestwood ./openser[27474]: send2child: to tcp child 0 35(27466), 0x403b6e10 Jul 26 19:21:06 crestwood ./openser[27466]: received n=4 con=0x403b6e10, fd=49 Jul 26 19:21:06 crestwood ./openser[27466]: tcp_read_req: content-length= 0 Jul 26 19:21:06 crestwood ./openser[27466]: SIP Reply (status): Jul 26 19:21:06 crestwood ./openser[27466]: version: <SIP/2.0> Jul 26 19:21:06 crestwood ./openser[27466]: status: <180> Jul 26 19:21:06 crestwood ./openser[27466]: reason: <Ringing> Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: flags=1 Jul 26 19:21:06 crestwood ./openser[27466]: Found param type 232, <branch> = <z9hG4bK-1-0>; state=16 Jul 26 19:21:06 crestwood ./openser[27466]: end of header reached, state=5 Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: Via found, flags=1 Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: this is the first via Jul 26 19:21:06 crestwood ./openser[27466]: After parse_msg... Jul 26 19:21:06 crestwood ./openser[27466]: forward_reply: found module tm, passing reply to it Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: t_check: msg id=7 global id=6 T start=(nil) Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: flags=17 Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: add_param: tag=1 Jul 26 19:21:06 crestwood ./openser[27466]: end of header reached, state=29 Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: get_hdr_field: <To> [40]; uri=[sip:service@10.0.1.41:5060] Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: to body [sut sip:service@10.0.1.41:5060] Jul 26 19:21:06 crestwood ./openser[27466]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: flags=4 Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: t_reply_matching: failure to match a transaction Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: t_check: msg id=7 global id=7 T end=(nil) Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: flags=2 Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: get_hdr_body : content_length=0 Jul 26 19:21:06 crestwood ./openser[27466]: found end of header Jul 26 19:21:06 crestwood ./openser[27466]: ERROR: forward_reply: no 2nd via found in reply Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG:destroy_avp_list: destroying list (nil) Jul 26 19:21:06 crestwood ./openser[27466]: receive_msg: cleaning up Jul 26 19:21:06 crestwood ./openser[27466]: tcp_read_req: content-length= 130 Jul 26 19:21:06 crestwood ./openser[27466]: SIP Reply (status): Jul 26 19:21:06 crestwood ./openser[27466]: version: <SIP/2.0> Jul 26 19:21:06 crestwood ./openser[27466]: status: <200> Jul 26 19:21:06 crestwood ./openser[27466]: reason: <OK> Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: flags=1 Jul 26 19:21:06 crestwood ./openser[27466]: Found param type 232, <branch> = <z9hG4bK-1-0>; state=16 Jul 26 19:21:06 crestwood ./openser[27466]: end of header reached, state=5 Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: Via found, flags=1 Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: this is the first via Jul 26 19:21:06 crestwood ./openser[27466]: After parse_msg... Jul 26 19:21:06 crestwood ./openser[27466]: forward_reply: found module tm, passing reply to it Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: t_check: msg id=8 global id=7 T start=(nil) Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: flags=17 Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: add_param: tag=1 Jul 26 19:21:06 crestwood ./openser[27466]: end of header reached, state=29 Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: get_hdr_field: <To> [40]; uri=[sip:service@10.0.1.41:5060] Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: to body [sut sip:service@10.0.1.41:5060] Jul 26 19:21:06 crestwood ./openser[27466]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: flags=4 Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: t_reply_matching: failure to match a transaction Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: t_check: msg id=8 global id=8 T end=(nil) Jul 26 19:21:06 crestwood ./openser[27466]: parse_headers: flags=2 Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG: get_hdr_body : content_length=130 Jul 26 19:21:06 crestwood ./openser[27466]: found end of header Jul 26 19:21:06 crestwood ./openser[27466]: ERROR: forward_reply: no 2nd via found in reply Jul 26 19:21:06 crestwood ./openser[27466]: DEBUG:destroy_avp_list: destroying list (nil) Jul 26 19:21:06 crestwood ./openser[27466]: receive_msg: cleaning up Jul 26 19:21:07 crestwood ./openser[27474]: tcpconn_new: new tcp connection: 10.0.1.41 Jul 26 19:21:07 crestwood ./openser[27474]: tcpconn_new: on port 47198, type 2 Jul 26 19:21:07 crestwood ./openser[27474]: tcpconn_add: hashes: 84, 10 Jul 26 19:21:07 crestwood ./openser[27474]: tcp_main_loop: new connection: 0x403a6cf8 66 Jul 26 19:21:07 crestwood ./openser[27474]: send2child: to tcp child 1 36(27467), 0x403a6cf8 Jul 26 19:21:07 crestwood ./openser[27467]: received n=4 con=0x403a6cf8, fd=50 Jul 26 19:21:07 crestwood ./openser[27467]: tcp_read_req: content-length= 0 Jul 26 19:21:07 crestwood ./openser[27467]: SIP Reply (status): Jul 26 19:21:07 crestwood ./openser[27467]: version: <SIP/2.0> Jul 26 19:21:07 crestwood ./openser[27467]: status: <180> Jul 26 19:21:07 crestwood ./openser[27467]: reason: <Ringing> Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: flags=1 Jul 26 19:21:07 crestwood ./openser[27467]: Found param type 232, <branch> = <z9hG4bK-2-0>; state=16 Jul 26 19:21:07 crestwood ./openser[27467]: end of header reached, state=5 Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: Via found, flags=1 Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: this is the first via Jul 26 19:21:07 crestwood ./openser[27467]: After parse_msg... Jul 26 19:21:07 crestwood ./openser[27467]: forward_reply: found module tm, passing reply to it Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: t_check: msg id=7 global id=6 T start=(nil) Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: flags=17 Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: add_param: tag=2 Jul 26 19:21:07 crestwood ./openser[27467]: end of header reached, state=29 Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: get_hdr_field: <To> [40]; uri=[sip:service@10.0.1.41:5060] Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: to body [sut sip:service@10.0.1.41:5060] Jul 26 19:21:07 crestwood ./openser[27467]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: flags=4 Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: t_reply_matching: failure to match a transaction Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: t_check: msg id=7 global id=7 T end=(nil) Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: flags=2 Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: get_hdr_body : content_length=0 Jul 26 19:21:07 crestwood ./openser[27467]: found end of header Jul 26 19:21:07 crestwood ./openser[27467]: ERROR: forward_reply: no 2nd via found in reply Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG:destroy_avp_list: destroying list (nil) Jul 26 19:21:07 crestwood ./openser[27467]: receive_msg: cleaning up Jul 26 19:21:07 crestwood ./openser[27467]: tcp_read_req: content-length= 130 Jul 26 19:21:07 crestwood ./openser[27467]: SIP Reply (status): Jul 26 19:21:07 crestwood ./openser[27467]: version: <SIP/2.0> Jul 26 19:21:07 crestwood ./openser[27467]: status: <200> Jul 26 19:21:07 crestwood ./openser[27467]: reason: <OK> Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: flags=1 Jul 26 19:21:07 crestwood ./openser[27467]: Found param type 232, <branch> = <z9hG4bK-2-0>; state=16 Jul 26 19:21:07 crestwood ./openser[27467]: end of header reached, state=5 Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: Via found, flags=1 Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: this is the first via Jul 26 19:21:07 crestwood ./openser[27467]: After parse_msg... Jul 26 19:21:07 crestwood ./openser[27467]: forward_reply: found module tm, passing reply to it Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: t_check: msg id=8 global id=7 T start=(nil) Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: flags=17 Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: add_param: tag=2 Jul 26 19:21:07 crestwood ./openser[27467]: end of header reached, state=29 Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: get_hdr_field: <To> [40]; uri=[sip:service@10.0.1.41:5060] Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: to body [sut sip:service@10.0.1.41:5060] Jul 26 19:21:07 crestwood ./openser[27467]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: flags=4 Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: t_reply_matching: failure to match a transaction Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: t_check: msg id=8 global id=8 T end=(nil) Jul 26 19:21:07 crestwood ./openser[27467]: parse_headers: flags=2 Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG: get_hdr_body : content_length=130 Jul 26 19:21:07 crestwood ./openser[27467]: found end of header Jul 26 19:21:07 crestwood ./openser[27467]: ERROR: forward_reply: no 2nd via found in reply Jul 26 19:21:07 crestwood ./openser[27467]: DEBUG:destroy_avp_list: destroying list (nil) Jul 26 19:21:07 crestwood ./openser[27467]: receive_msg: cleaning up Jul 26 19:21:08 crestwood ./openser[27474]: tcpconn_new: new tcp connection: 10.0.1.41 Jul 26 19:21:08 crestwood ./openser[27474]: tcpconn_new: on port 47199, type 2 Jul 26 19:21:08 crestwood ./openser[27474]: tcpconn_add: hashes: 85, 11 Jul 26 19:21:08 crestwood ./openser[27474]: tcp_main_loop: new connection: 0x403c6f28 67 Jul 26 19:21:08 crestwood ./openser[27474]: send2child: to tcp child 2 37(27468), 0x403c6f28 Jul 26 19:21:08 crestwood ./openser[27468]: received n=4 con=0x403c6f28, fd=52 Jul 26 19:21:08 crestwood ./openser[27468]: tcp_read_req: content-length= 0 Jul 26 19:21:08 crestwood ./openser[27468]: SIP Reply (status): Jul 26 19:21:08 crestwood ./openser[27468]: version: <SIP/2.0> Jul 26 19:21:08 crestwood ./openser[27468]: status: <180> Jul 26 19:21:08 crestwood ./openser[27468]: reason: <Ringing> Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: flags=1 Jul 26 19:21:08 crestwood ./openser[27468]: Found param type 232, <branch> = <z9hG4bK-3-0>; state=16 Jul 26 19:21:08 crestwood ./openser[27468]: end of header reached, state=5 Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: Via found, flags=1 Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: this is the first via Jul 26 19:21:08 crestwood ./openser[27468]: After parse_msg... Jul 26 19:21:08 crestwood ./openser[27468]: forward_reply: found module tm, passing reply to it Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: t_check: msg id=5 global id=4 T start=(nil) Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: flags=17 Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: add_param: tag=3 Jul 26 19:21:08 crestwood ./openser[27468]: end of header reached, state=29 Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: get_hdr_field: <To> [40]; uri=[sip:service@10.0.1.41:5060] Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: to body [sut sip:service@10.0.1.41:5060] Jul 26 19:21:08 crestwood ./openser[27468]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: flags=4 Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: t_reply_matching: failure to match a transaction Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: t_check: msg id=5 global id=5 T end=(nil) Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: flags=2 Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: get_hdr_body : content_length=0 Jul 26 19:21:08 crestwood ./openser[27468]: found end of header Jul 26 19:21:08 crestwood ./openser[27468]: ERROR: forward_reply: no 2nd via found in reply Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG:destroy_avp_list: destroying list (nil) Jul 26 19:21:08 crestwood ./openser[27468]: receive_msg: cleaning up Jul 26 19:21:08 crestwood ./openser[27468]: tcp_read_req: content-length= 130 Jul 26 19:21:08 crestwood ./openser[27468]: SIP Reply (status): Jul 26 19:21:08 crestwood ./openser[27468]: version: <SIP/2.0> Jul 26 19:21:08 crestwood ./openser[27468]: status: <200> Jul 26 19:21:08 crestwood ./openser[27468]: reason: <OK> Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: flags=1 Jul 26 19:21:08 crestwood ./openser[27468]: Found param type 232, <branch> = <z9hG4bK-3-0>; state=16 Jul 26 19:21:08 crestwood ./openser[27468]: end of header reached, state=5 Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: Via found, flags=1 Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: this is the first via Jul 26 19:21:08 crestwood ./openser[27468]: After parse_msg... Jul 26 19:21:08 crestwood ./openser[27468]: forward_reply: found module tm, passing reply to it Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: t_check: msg id=6 global id=5 T start=(nil) Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: flags=17 Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: add_param: tag=3 Jul 26 19:21:08 crestwood ./openser[27468]: end of header reached, state=29 Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: get_hdr_field: <To> [40]; uri=[sip:service@10.0.1.41:5060] Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: to body [sut sip:service@10.0.1.41:5060] Jul 26 19:21:08 crestwood ./openser[27468]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: flags=4 Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: t_reply_matching: failure to match a transaction Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: t_check: msg id=6 global id=6 T end=(nil) Jul 26 19:21:08 crestwood ./openser[27468]: parse_headers: flags=2 Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG: get_hdr_body : content_length=130 Jul 26 19:21:08 crestwood ./openser[27468]: found end of header Jul 26 19:21:08 crestwood ./openser[27468]: ERROR: forward_reply: no 2nd via found in reply Jul 26 19:21:08 crestwood ./openser[27468]: DEBUG:destroy_avp_list: destroying list (nil) Jul 26 19:21:08 crestwood ./openser[27468]: receive_msg: cleaning up Jul 26 19:21:10 crestwood ./openser[27466]: tcp_read: EOF on 0x403b6e10, FD 49 Jul 26 19:21:10 crestwood ./openser[27466]: tcp_read_req: EOF Jul 26 19:21:10 crestwood ./openser[27466]: releasing con 0x403b6e10, state -1, fd=49, id=9 Jul 26 19:21:10 crestwood ./openser[27466]: extra_data (nil) Jul 26 19:21:10 crestwood ./openser[27467]: tcp_read: EOF on 0x403a6cf8, FD 50 Jul 26 19:21:10 crestwood ./openser[27467]: tcp_read_req: EOF Jul 26 19:21:10 crestwood ./openser[27467]: releasing con 0x403a6cf8, state -1, fd=50, id=10 Jul 26 19:21:10 crestwood ./openser[27467]: extra_data (nil) Jul 26 19:21:10 crestwood ./openser[27468]: tcp_read: EOF on 0x403c6f28, FD 52 Jul 26 19:21:10 crestwood ./openser[27468]: tcp_read_req: EOF Jul 26 19:21:10 crestwood ./openser[27468]: releasing con 0x403c6f28, state -1, fd=52, id=11 Jul 26 19:21:10 crestwood ./openser[27474]: tcp_main_loop: reader response= 403b6e10, -1 from 0 Jul 26 19:21:10 crestwood ./openser[27474]: tcp_main_loop: destroying connection Jul 26 19:21:10 crestwood ./openser[27474]: tcp_main_loop: reader response= 403a6cf8, -1 from 1 Jul 26 19:21:10 crestwood ./openser[27474]: tcp_main_loop: destroying connection Jul 26 19:21:10 crestwood ./openser[27468]: extra_data (nil) Jul 26 19:21:10 crestwood ./openser[27474]: tcp_main_loop: reader response= 403c6f28, -1 from 2 Jul 26 19:21:10 crestwood ./openser[27474]: tcp_main_loop: destroying connection
-
Bogdan-Andrei Iancu -
Erich Nahum