< Previous by Date Date Index Next by Date >
< Previous in Thread Thread Index Next in Thread >

Re: [reSIProcate-users] [recon-devel] TLS and SRTP and recon bug report


There are repro log, the user1 is bria pro, the user2 is my UA, this log shows
TLS handshake faild, but why when I try to call user1 from user2 is working ?

Thanks


INFO | 20090228-003415.852 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
41 | Creating TLS connection for domain 192.168.1.198 [ V4 192.168.1.101:6920 TL
S target domain=unspecified mFlowKey=0 ] on 1284
INFO | 20090228-003415.868 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
177 | TLS handshake starting (Server mode)
INFO | 20090228-003415.868 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
188 | TLS connected
INFO | 20090228-003415.883 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
269 | TLS connected
INFO | 20090228-003415.899 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
617 | TLS sessions set up with TLSv1 TLSv1/SSLv3 AES256-SHA
INFO | 20090228-003415.899 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
313 | TLS handshake done for peer
INFO | 20090228-003415.914 | repro | REPRO:APP | 1792 | AclStore.cxx:525 | AclSt
ore - source address NOT trusted: 192.168.1.101:6920 TLS
INFO | 20090228-003415.914 | repro | RESIP:DUM | 1792 | ServerAuthManager.cxx:39
4 | Sending challenge to SipReq:  REGISTER 192.168.1.198:5061 tid=c7371f618a6a47
51 cseq=REGISTER contact=user2@xxxxxxxxxxxxx:7796 / 1 from(wire) tlsd=192.168.1.
198
INFO | 20090228-003415.930 | repro | RESIP:DUM | 1792 | ServerAuthManager.cxx:45
 | ServerAuth challenged request SipReq:  REGISTER 192.168.1.198:5061 tid=c7371f
618a6a4751 cseq=REGISTER contact=user2@xxxxxxxxxxxxx:7796 / 1 from(wire) tlsd=19
2.168.1.198
INFO | 20090228-003415.993 | repro | RESIP:DUM | 1792 | ServerAuthManager.cxx:33
7 | Requesting credential for user2 @ 192.168.1.198
INFO | 20090228-003416.008 | repro | RESIP:DUM | 1792 | ServerAuthManager.cxx:51
 | ServerAuth requested credentials SipReq:  REGISTER 192.168.1.198:5061 tid=571
ef541ee63605f cseq=REGISTER contact=user2@xxxxxxxxxxxxx:7796 / 2 from(wire) tlsd
=192.168.1.198
INFO | 20090228-003416.024 | repro | RESIP:DUM | 1792 | ServerAuthManager.cxx:12
9 | Checking for auth result in realm=192.168.1.198 A1=0f4b317a47256c1f5735f2fdd
cf99dd4
INFO | 20090228-003416.024 | repro | RESIP:DUM | 1792 | ServerAuthManager.cxx:21
4 | Authorized request for 192.168.1.198
INFO | 20090228-003416.039 | repro | RESIP:DUM | 1792 | DialogUsageManager.cxx:1
333 | Got: SipReq:  REGISTER 192.168.1.198:5061 tid=571ef541ee63605f cseq=REGIST
ER contact=user2@xxxxxxxxxxxxx:7796 / 2 from(wire) tlsd=192.168.1.198
INFO | 20090228-003416.055 | repro | RESIP:DUM | 1792 | ServerRegistration.cxx:3
28 | Adding sip:user2@xxxxxxxxxxxxx:5061 -> <sip:user2@xxxxxxxxxxxxx:7796;rinsta
nce=7029b88f210f1ae0;transport=TLS>
INFO | 20090228-003416.071 | repro | RESIP:DUM | 1792 | ServerRegistration.cxx:4
5 | accepted a registration sip:user2@xxxxxxxxxxxxx:5061
INFO | 20090228-003416.149 | repro | REPRO:APP | 3760 | Proxy.cxx:249 | New Requ
estContext tid=b905616c801ce331 : SipReq:  SUBSCRIBE user2@xxxxxxxxxxxxx:5061 ti
d=b905616c801ce331 cseq=SUBSCRIBE contact=user2@xxxxxxxxxxxxx:7796 / 1 from(wire
) tlsd=192.168.1.198
INFO | 20090228-003416.180 | repro | REPRO:APP | 3760 | Proxy.cxx:258 | Insertin
g new RequestContext tid=b905616c801ce331 -> RequestContext:  identity= count=1
final=0
INFO | 20090228-003416.180 | repro | REPRO:APP | 3760 | AclStore.cxx:525 | AclSt
ore - source address NOT trusted: 192.168.1.101:6920 TLS
INFO | 20090228-003416.211 | repro | REPRO:APP | 3760 | RequestContext.cxx:70 |
RequestContext::process(TransactionTerminated) b905616c801ce331 : RequestContext
:  identity= count=1 final=1 orig requri=SipReq:  SUBSCRIBE user2@xxxxxxxxxxxxx:
5061 tid=b905616c801ce331 cseq=SUBSCRIBE contact=user2@xxxxxxxxxxxxx:7796 / 1 fr
om(wire) tlsd=192.168.1.198
INFO | 20090228-003416.243 | repro | REPRO:APP | 3760 | Proxy.cxx:249 | New Requ
estContext tid=2a174d48e37e3534 : SipReq:  SUBSCRIBE user2@xxxxxxxxxxxxx:5061 ti
d=2a174d48e37e3534 cseq=SUBSCRIBE contact=user2@xxxxxxxxxxxxx:7796 / 2 from(wire
) tlsd=192.168.1.198
INFO | 20090228-003416.258 | repro | REPRO:APP | 3760 | Proxy.cxx:258 | Insertin
g new RequestContext tid=2a174d48e37e3534 -> RequestContext:  identity= count=1
final=0
INFO | 20090228-003416.274 | repro | REPRO:APP | 3760 | AclStore.cxx:525 | AclSt
ore - source address NOT trusted: 192.168.1.101:6920 TLS
INFO | 20090228-003416.274 | repro | REPRO:APP | 3760 | DigestAuthenticator.cxx:
330 | Request user auth info for user2 at realm 192.168.1.198
INFO | 20090228-003416.289 | repro | REPRO:APP | 3760 | DigestAuthenticator.cxx:
114 | Received user auth info for user2 at realm 192.168.1.198 a1 is 0f4b317a472
56c1f5735f2fddcf99dd4
INFO | 20090228-003416.305 | repro | REPRO:APP | 3760 | DigestAuthenticator.cxx:
134 | Authentication ok for user2
INFO | 20090228-003416.305 | repro | REPRO:APP | 3760 | DigestAuthenticator.cxx:
240 | Identity-Info=http://TESTSERVER:5080/cert?domain=192.168.1.198
INFO | 20090228-003416.321 | repro | REPRO:APP | 3760 | LocationServer.cxx:52 |
LocationServer monkey
 adding target <sip:user2@xxxxxxxxxxxxx:7796;rinstance=7029b88f210f1ae0;transpor
t=TLS> with tuple [ V4 0.0.0.0:0 UNKNOWN_TRANSPORT target domain=unspecified mFl
owKey=0 ]
INFO | 20090228-003416.336 | repro | REPRO:APP | 3760 | RequestContext.cxx:471 |
 RequestContext:  identity=user2 count=1 final=0 orig requri=SipReq:  SUBSCRIBE
user2@xxxxxxxxxxxxx:5061 tid=2a174d48e37e3534 cseq=SUBSCRIBE contact=user2@xxxxx
68.1.101:7796 / 2 from(wire) tlsd=192.168.1.198 there are 1 candidates -> contin
ue
INFO | 20090228-003416.352 | repro | REPRO:APP | 3760 | RequestContext.cxx:621 |
 Updating timer C.
INFO | 20090228-003416.352 | repro | REPRO:APP | 3760 | Proxy.cxx:424 | Posting
timer C
INFO | 20090228-003416.352 | repro | REPRO:APP | 3760 | Proxy.cxx:410 | add clie
nt transaction tid=9e10eb3c2a37bd23 00CB1BD8
INFO | 20090228-003416.368 | repro | REPRO:APP | 3760 | ResponseContext.cxx:279
| Creating new client transaction 9e10eb3c2a37bd23 -> sip:user2@xxxxxxxxxxxxx:77
96;rinstance=7029b88f210f1ae0;transport=TLS
INFO | 20090228-003416.399 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
41 | Creating TLS connection for domain 192.168.1.198 [ V4 192.168.1.101:7796 TL
S target domain=192.168.1.101 mFlowKey=0 ] on 1272
INFO | 20090228-003416.414 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
183 | TLS handshake starting (client mode)
INFO | 20090228-003416.414 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
188 | TLS connected
ERR | 20090228-003416.430 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:2
38 | socket error 0
ERR | 20090228-003416.430 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:2
44 | TLS handshake failed
INFO | 20090228-003416.430 | repro | RESIP:TRANSPORT | 4084 | Connection.cxx:122
 | Write failed on socket: 1272, closing connection
INFO | 20090228-003416.446 | repro | RESIP:TRANSACTION | 4084 | TuSelector.cxx:8
5 | Sending ConnectionTerminated [ V4 192.168.1.101:7796 TLS target domain=192.1
68.1.101 mFlowKey=1272 ] to TUs
INFO | 20090228-003416.461 | repro | RESIP:TRANSACTION | 4084 | TransactionState
.cxx:1738 | Try sending request to a different dns result
INFO | 20090228-003416.461 | repro | RESIP:TRANSACTION | 4084 | TransactionState
.cxx:1633 | Ran out of dns entries for 192.168.1.101. Send 503
INFO | 20090228-003416.477 | repro | RESIP:DNS | 4084 | DnsUtil.cxx:145 | local
hostname does not contain a domain part TESTSERVER
INFO | 20090228-003416.493 | repro | REPRO:APP | 3760 | Proxy.cxx:292 | Looking
up RequestContext tid=9e10eb3c2a37bd23
INFO | 20090228-003416.493 | repro | REPRO:APP | 3760 | ResponseContext.cxx:814
| processResponse:
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/TLS 192.168.1.198:5061;branch=z9hG4bK-d8754z-9e10eb3c2a37bd23-1---d
8754z-;rport
Via: SIP/2.0/TLS 192.168.1.101:7796;branch=z9hG4bK-d8754z-2a174d48e37e3534-1---d
8754z-;rport=6920
To: <sip:user2@xxxxxxxxxxxxx:5061>;tag=1626df2e
From: <sip:user2@xxxxxxxxxxxxx:5061>;tag=b066b760
Call-ID: MDhlZjlmYzQyM2M0M2RmOGMxODc5ZGNjZWMxOWUwOWI.
CSeq: 2 SUBSCRIBE
Warning: 499 TESTSERVER ""
Content-Length: 0


INFO | 20090228-003416.539 | repro | REPRO:APP | 3760 | ResponseContext.cxx:867
| Search for 9e10eb3c2a37bd23 in [9e10eb3c2a37bd23 -> Target: sip:user2@xxxxxxxx
1.101:7796;rinstance=7029b88f210f1ae0;transport=TLS  status=1]
INFO | 20090228-003416.555 | repro | REPRO:APP | 3760 | ResponseContext.cxx:1065
 | Terminating client transaction: 9e10eb3c2a37bd23 all = 0
INFO | 20090228-003416.555 | repro | REPRO:APP | 3760 | ResponseContext.cxx:1070
 | client transactions: [9e10eb3c2a37bd23 -> Target: sip:user2@xxxxxxxxxxxxx:779
6;rinstance=7029b88f210f1ae0;transport=TLS  status=1]
INFO | 20090228-003416.571 | repro | REPRO:APP | 3760 | ResponseContext.cxx:1244
 | Forwarding best response: SipResp: 503 tid=2a174d48e37e3534 cseq=SUBSCRIBE /
2 from(wire)
INFO | 20090228-003416.586 | repro | REPRO:APP | 3760 | RequestContext.cxx:70 |
RequestContext::process(TransactionTerminated) 9e10eb3c2a37bd23 : RequestContext
:  identity=user2 count=2 final=1 orig requri=SipReq:  SUBSCRIBE user2@xxxxxxxxx
.198:5061 tid=2a174d48e37e3534 cseq=SUBSCRIBE contact=user2@xxxxxxxxxxxxx:7796 /
 2 from(wire) tlsd=192.168.1.198
INFO | 20090228-003416.602 | repro | REPRO:APP | 3760 | RequestContext.cxx:70 |
RequestContext::process(TransactionTerminated) 2a174d48e37e3534 : RequestContext
:  identity=user2 count=1 final=1 orig requri=SipReq:  SUBSCRIBE user2@xxxxxxxxx
.198:5061 tid=2a174d48e37e3534 cseq=SUBSCRIBE contact=user2@xxxxxxxxxxxxx:7796 /
 2 from(wire) tlsd=192.168.1.198
INFO | 20090228-003427.493 | repro | REPRO:APP | 3760 | Proxy.cxx:249 | New Requ
estContext tid=f84e9a3f4c7bbb03 : SipReq:  INVITE user2@xxxxxxxxxxxxx:5061 tid=f
84e9a3f4c7bbb03 cseq=INVITE contact=user1@xxxxxxxxxxxxx:6918 / 1 from(wire) tlsd
=192.168.1.198
INFO | 20090228-003427.508 | repro | REPRO:APP | 3760 | Proxy.cxx:258 | Insertin
g new RequestContext tid=f84e9a3f4c7bbb03 -> RequestContext:  identity= count=1
final=0
INFO | 20090228-003427.508 | repro | REPRO:APP | 3760 | AclStore.cxx:525 | AclSt
ore - source address NOT trusted: 192.168.1.101:6918 TLS
INFO | 20090228-003427.649 | repro | REPRO:APP | 3760 | RequestContext.cxx:70 |
RequestContext::process(TransactionTerminated) f84e9a3f4c7bbb03 : RequestContext
:  identity= count=1 final=1 orig requri=SipReq:  INVITE user2@xxxxxxxxxxxxx:506
1 tid=f84e9a3f4c7bbb03 cseq=INVITE contact=user1@xxxxxxxxxxxxx:6918 / 1 from(wir
e) tlsd=192.168.1.198
INFO | 20090228-003427.774 | repro | REPRO:APP | 3760 | Proxy.cxx:249 | New Requ
estContext tid=c164d1343026f75d : SipReq:  INVITE user2@xxxxxxxxxxxxx:5061 tid=c
164d1343026f75d cseq=INVITE contact=user1@xxxxxxxxxxxxx:6918 / 2 from(wire) tlsd
=192.168.1.198
INFO | 20090228-003427.789 | repro | REPRO:APP | 3760 | Proxy.cxx:258 | Insertin
g new RequestContext tid=c164d1343026f75d -> RequestContext:  identity= count=1
final=0
INFO | 20090228-003427.805 | repro | REPRO:APP | 3760 | AclStore.cxx:525 | AclSt
ore - source address NOT trusted: 192.168.1.101:6918 TLS
INFO | 20090228-003427.821 | repro | REPRO:APP | 3760 | DigestAuthenticator.cxx:
330 | Request user auth info for user1 at realm 192.168.1.198
INFO | 20090228-003427.821 | repro | REPRO:APP | 3760 | DigestAuthenticator.cxx:
114 | Received user auth info for user1 at realm 192.168.1.198 a1 is 0ce205184a5
3708194ac416a8bf94c5a
INFO | 20090228-003427.836 | repro | REPRO:APP | 3760 | DigestAuthenticator.cxx:
134 | Authentication ok for user1
INFO | 20090228-003427.836 | repro | REPRO:APP | 3760 | DigestAuthenticator.cxx:
240 | Identity-Info=http://TESTSERVER:5080/cert?domain=192.168.1.198
INFO | 20090228-003427.852 | repro | REPRO:APP | 3760 | LocationServer.cxx:52 |
LocationServer monkey
 adding target <sip:user2@xxxxxxxxxxxxx:7796;rinstance=7029b88f210f1ae0;transpor
t=TLS> with tuple [ V4 0.0.0.0:0 UNKNOWN_TRANSPORT target domain=unspecified mFl
owKey=0 ]
INFO | 20090228-003427.868 | repro | REPRO:APP | 3760 | RequestContext.cxx:471 |
 RequestContext:  identity=user1 count=1 final=0 orig requri=SipReq:  INVITE use
r2@xxxxxxxxxxxxx:5061 tid=c164d1343026f75d cseq=INVITE contact=user1@xxxxxxxxxxx
01:6918 / 2 from(wire) tlsd=192.168.1.198 there are 1 candidates -> continue
INFO | 20090228-003427.899 | repro | REPRO:APP | 3760 | RequestContext.cxx:621 |
 Updating timer C.
INFO | 20090228-003427.899 | repro | REPRO:APP | 3760 | Proxy.cxx:424 | Posting
timer C
INFO | 20090228-003427.914 | repro | REPRO:APP | 3760 | Proxy.cxx:410 | add clie
nt transaction tid=c96ea83033067633 00CB3550
INFO | 20090228-003427.914 | repro | REPRO:APP | 3760 | ResponseContext.cxx:279
| Creating new client transaction c96ea83033067633 -> sip:user2@xxxxxxxxxxxxx:77
96;rinstance=7029b88f210f1ae0;transport=TLS
INFO | 20090228-003427.946 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
41 | Creating TLS connection for domain 192.168.1.198 [ V4 192.168.1.101:7796 TL
S target domain=192.168.1.101 mFlowKey=0 ] on 1268
INFO | 20090228-003427.961 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
183 | TLS handshake starting (client mode)
INFO | 20090228-003427.961 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:
188 | TLS connected
ERR | 20090228-003427.961 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:2
38 | socket error 0
ERR | 20090228-003427.977 | repro | RESIP:TRANSPORT | 4084 | TlsConnection.cxx:2
44 | TLS handshake failed
INFO | 20090228-003427.977 | repro | RESIP:TRANSPORT | 4084 | Connection.cxx:122
 | Write failed on socket: 1268, closing connection
INFO | 20090228-003427.993 | repro | RESIP:TRANSACTION | 4084 | TuSelector.cxx:8
5 | Sending ConnectionTerminated [ V4 192.168.1.101:7796 TLS target domain=192.1
68.1.101 mFlowKey=1268 ] to TUs
INFO | 20090228-003428.008 | repro | RESIP:TRANSACTION | 4084 | TransactionState
.cxx:1738 | Try sending request to a different dns result
INFO | 20090228-003428.008 | repro | RESIP:TRANSACTION | 4084 | TransactionState
.cxx:1633 | Ran out of dns entries for 192.168.1.101. Send 503
INFO | 20090228-003428.024 | repro | RESIP:DNS | 4084 | DnsUtil.cxx:145 | local
hostname does not contain a domain part TESTSERVER
INFO | 20090228-003428.039 | repro | REPRO:APP | 3760 | Proxy.cxx:292 | Looking
up RequestContext tid=c96ea83033067633
INFO | 20090228-003428.039 | repro | REPRO:APP | 3760 | ResponseContext.cxx:814
| processResponse:
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/TLS 192.168.1.198:5061;branch=z9hG4bK-d8754z-c96ea83033067633-1---d
8754z-;rport
Via: SIP/2.0/TLS 192.168.1.101:23689;branch=z9hG4bK-d8754z-c164d1343026f75d-1---
d8754z-;rport=6918
To: "user2"<sip:user2@xxxxxxxxxxxxx:5061>;tag=31680425
From: "user1"<sip:user1@xxxxxxxxxxxxx:5061>;tag=403a165c
Call-ID: YzBiZGEwZDdmY2I0NjljYWU4ZTNkOWU2NDFiMGFhOGI.
CSeq: 2 INVITE
Warning: 499 TESTSERVER ""
Content-Length: 0


INFO | 20090228-003428.086 | repro | REPRO:APP | 3760 | ResponseContext.cxx:867
| Search for c96ea83033067633 in [c96ea83033067633 -> Target: sip:user2@xxxxxxxx
1.101:7796;rinstance=7029b88f210f1ae0;transport=TLS  status=1]
INFO | 20090228-003428.102 | repro | REPRO:APP | 3760 | ResponseContext.cxx:1065
 | Terminating client transaction: c96ea83033067633 all = 0
INFO | 20090228-003428.102 | repro | REPRO:APP | 3760 | ResponseContext.cxx:1070
 | client transactions: [c96ea83033067633 -> Target: sip:user2@xxxxxxxxxxxxx:779
6;rinstance=7029b88f210f1ae0;transport=TLS  status=1]
INFO | 20090228-003428.118 | repro | REPRO:APP | 3760 | ResponseContext.cxx:1244
 | Forwarding best response: SipResp: 503 tid=c164d1343026f75d cseq=INVITE / 2 f
rom(wire)
INFO | 20090228-003428.133 | repro | REPRO:APP | 3760 | ResponseContext.cxx:294
| Cancel all proceeding client transactions: 0
INFO | 20090228-003428.133 | repro | REPRO:APP | 3760 | RequestContext.cxx:70 |
RequestContext::process(TransactionTerminated) c96ea83033067633 : RequestContext
:  identity=user1 count=2 final=1 orig requri=SipReq:  INVITE user2@xxxxxxxxxxxx
8:5061 tid=c164d1343026f75d cseq=INVITE contact=user1@xxxxxxxxxxxxx:6918 / 2 fro
m(wire) tlsd=192.168.1.198
INFO | 20090228-003428.352 | repro | REPRO:APP | 3760 | RequestContext.cxx:70 |
RequestContext::process(TransactionTerminated) c164d1343026f75d : RequestContext
:  identity=user1 count=1 final=1 orig requri=SipReq:  INVITE user2@xxxxxxxxxxxx
8:5061 tid=c164d1343026f75d cseq=INVITE contact=user1@xxxxxxxxxxxxx:6918 / 2 fro
m(wire) tlsd=192.168.1.198




On Fri, Feb 27, 2009 at 8:55 PM, Karlsson <boost.regex@xxxxxxxxx> wrote:
Thanks Alex, I'm running the repro on 192.168.1.198, the tls used 5061 port,
 and run bria pro and my UA on my PC: 192.168.1.101.

Now with TLS the problem is:

1: Eyebeam call to bria pro, the bria pro can't received the ACK after sent 200 OK.
2: The bria pro call to eyebeam, the eyebeam can't received ACK after sent 200 OK
3: My UA call to bria pro or eyebeam, the bria and eyebeam can't receivd ACK after sent 200 OK
4: My UA call to My UA, the server replied 503 and callee can't received call.
5: The bria or eyebeam call to my UA, the server replied 503 and my ua can't received call.






On Fri, Feb 27, 2009 at 5:41 PM, Alexander Chemeris <Alexander.Chemeris@xxxxxxxxx> wrote:
Hi Karlsson,

2009/2/27 Karlsson <boost.regex@xxxxxxxxx>:
> 2: I'm runing repro with on 192.168.1.198:5061 with TLS, I using my UA and
> bria pro to test the TLS call, after the bria anwered 200 ok, my ua sent an
> ACK,
> but the bria never received my ACK, so the bria was terminated call after 30
> seconds. Why ?

Are you sure it works in the same setup without TLS enabled?
I'm not sure about recon, but with sipX libs similar problem may
happen, if you run it on a machine with several network interfaces
without binding to a correct one. Then replies are routed to a wrong
network and are never received by remote party.


--
Regards,
Alexander Chemeris.

SIPez LLC.
SIP VoIP, IM and Presence Consulting
http://www.SIPez.com
tel: +1 (617) 273-4000