Asterisk v1.8 TLS negotiating hanging

Asterisk Asterisk Support
1

Greeting all. I have a very strange situation that I hope someone has encountered before. Not sure if I’ve stumbled onto a bug or not, but you all have a look and let me know.

I’m attempting to enable TLS for Asterisk v1.8.4. It was built from source just recently (May 19, 2011). I’ve followed the secure calling tutorial located here: https://wiki.asterisk.org/wiki/display/AST/Secure+Calling+Tutorial. I’ve also captured the data traffic to/from the Asterisk server with Wireshark for more analysis.

Initially, I tried the TLS connection with CSipSimple for Android (using a TLS build). My Android clients could not establish a TLS connection with Asterisk. To eliminate the problem with clients, I switched to SFLphone VoIP client for Linux (it has TLS support). I see the same behavior (and in fact the same Wireshark data capture).

The problem is that the TLS handshake completes, but the server doesn’t do anything with the SIP registration that the client requests. I keep getting Request Timeouts from the clients. Here’s some addtional information:

------- Relavent portion of CLI startup from “asterisk -vvvvvv -g -dddddd -c” -------
SIP channel loading…
== Parsing ‘/etc/asterisk/sip.conf’: == Found
== Parsing ‘/etc/asterisk/users.conf’: == Found
== SIP Listening on 0.0.0.0:5060
== Using SIP CoS mark 4
SSL certificate ok

------- LOGGER @ “Full debug” (from logger.conf: “full => notice,warning,error,debug,verbose,dtmf”)
------- with core set debug == 15, core set verbose == 15, sip set debug on
[2011-05-23 08:31:53.402] VERBOSE[9736] config.c: == Parsing ‘/etc/asterisk/logger.conf’: [2011-05-23 08:31:53.402] DEBUG[9736] config.c: Parsing /etc/asterisk/logger.conf
[2011-05-23 08:31:53.402] VERBOSE[9736] config.c: == Found
[2011-05-23 08:31:53.402] VERBOSE[9736] logger.c: Asterisk Queue Logger restarted
[2011-05-23 08:32:47.169] DEBUG[9779] chan_sip.c: Starting thread for SSL server
[2011-05-23 08:33:17.200] DEBUG[9779] chan_sip.c: SIP SSL server timed out

------- Wireshark packet capture -------
10.31.32.12 -> 10.31.31.19: TCP, sip-tls [SYN]
10.31.31.19 -> 10.31.32.12: TCP, sip-tls [SYN, ACK]
10.31.32.12 -> 10.31.31.19: TCP, sip-tls [ACK] (connection established, sip-tls, port 5061)
10.31.32.12 -> 10.31.31.19: TLSv1, Client Hello
10.31.31.19 -> 10.31.32.12: TCP, sip-tls [ACK] (server acks client hello)
10.31.31.19 -> 10.31.32.12: TLSv1, Server Hello,
10.31.32.12 -> 10.31.31.19: TCP, sip-tls [ACK] (client acks server hello)
10.31.31.19 -> 10.31.32.12: TLSv1, Certificate, Server Hello Done
10.31.32.12 -> 10.31.31.19: TCP, sip-tls [ACK] (client acks server certificate)
10.31.32.12 -> 10.31.31.19: TLSv1, Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message
10.31.31.19 -> 10.31.32.12: TLSv1, Encrypted Handshake Message, Change Cipher Spec, Encrypted Handshake Message
10.31.32.12 -> 10.31.31.19: TLSv1, Application Data, Application Data (here’s the encrypted SIP registration)
10.31.31.19 -> 10.31.32.12: TCP, sip-tls [ACK] (server acks client application data)
(time passes, ~30 seconds)
10.31.31.19 -> 10.31.32.12: TCP, sip-tls [FIN, ACK] (server closes connection)
10.31.32.12 -> 10.31.31.19: TCP, sip-tls [ACK] (client acks, connection closed)

Why isn’t Asterisk sending back any data to the client after the first client application data (which I can only assume its a SIP registration)? Is there any way to get more TLS debug information on the server side?

Has anyone ever seen this behavior before? Got any suggestions?

2

There are a couple of TLS bugs with 1.8.4. Try the 1.8.4.1 tag:

svn co svn.digium.com/svn/asterisk/tags/1.8.4.1 asterisk-1.8.4.1

Cheers.

3

[quote=“malcolmd”]There are a couple of TLS bugs with 1.8.4. Try the 1.8.4.1 tag:

svn co svn.digium.com/svn/asterisk/tags/1.8.4.1 asterisk-1.8.4.1

Cheers.[/quote]

Nothing like pounding your head against the wall for a couple of days before realizing that you may have come across a bug. Should have looked at the bug tracker first. :laughing:

v1.8.4.1 did the trick. Thanks! And thanks for the quick turn around.

4

w00t :smile:

Sorry for the troubles in the first place. :frowning:

Cheers.

5

Looks like I was too quick in my last posting. I’ve rebuilt and installed v1.8.4.1. It does fix the TLS registration issue. I see VoIP clients successfully registering.

The problem now is that it looks like there is another “bug” when it comes to dialing over the TLS connection. Attaches are two logs (one from the CLI, the other from a full debug log):

----------- CLI ------------
– Registered SIP ‘libby’ at 192.168.2.100:[color=#8000BF]5061[/color]
> Saved useragent “CSipSimple r867 / passion-8” for peer libby

--------- Debug log ---------
[2011-05-23 12:53:21.634] DEBUG[16865] devicestate.c: device ‘SIP/libby’ state ‘1’
[2011-05-23 12:53:21.634] DEBUG[16900] app_queue.c: Device ‘SIP/libby’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2011-05-23 12:53:29.915] DEBUG[16960] chan_sip.c: = Looking for Call ID: PMNC-H9Rft4L8GT.c5ENhmQhGi8rks90 (Checking From) --From tag wMoiZfkKuBMhkKE5xI6BW-3bcwhLUaP1 --To-tag
[2011-05-23 12:53:29.915] DEBUG[16960] acl.c: For destination ‘192.168.2.100’, our source address is ‘192.168.2.2’.
[2011-05-23 12:53:29.915] DEBUG[16960] chan_sip.c: Setting SIP_TRANSPORT_TLS with address 192.168.2.2:[color=#8000BF]5061[/color]
[2011-05-23 12:53:29.915] DEBUG[16960] chan_sip.c: Allocating new SIP dialog for PMNC-H9Rft4L8GT.c5ENhmQhGi8rks90 - INVITE (No RTP)
[2011-05-23 12:53:29.915] DEBUG[16960] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Begin: parsing SIP “Supported: replaces, 100rel, timer, norefersub”
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Found SIP option: -replaces-
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Matched SIP option: replaces
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Found SIP option: -100rel-
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Matched SIP option: 100rel
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Found SIP option: -timer-
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Matched SIP option: timer
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Found SIP option: -norefersub-
[2011-05-23 12:53:29.915] DEBUG[16960] sip/reqresp_parser.c: Matched SIP option: norefersub
[2011-05-23 12:53:29.915] DEBUG[16960] netsock2.c: Splitting ‘192.168.2.100:[color=#FF0000]32787[/color]’ gives…
[color=#FF0000][2011-05-23 12:53:29.915] DEBUG[16960] netsock2.c: …host ‘192.168.2.100’ and port ‘32787’[/color].
[2011-05-23 12:53:29.915] DEBUG[16960] chan_sip.c: Trying to put ‘SIP/2.0 401’ onto TLS socket destined for 192.168.2.100:32787
[2011-05-23 12:53:30.316] DEBUG[16960] chan_sip.c: = Looking for Call ID: PMNC-H9Rft4L8GT.c5ENhmQhGi8rks90 (Checking From) --From tag wMoiZfkKuBMhkKE5xI6BW-3bcwhLUaP1 --To-tag as482c59b8
[2011-05-23 12:53:30.316] DEBUG[16960] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2011-05-23 12:53:30.316] DEBUG[16960] chan_sip.c: Stopping retransmission on ‘PMNC-H9Rft4L8GT.c5ENhmQhGi8rks90’ of Response 16127: Match Not Found
[2011-05-23 12:53:40.449] DEBUG[16887] chan_sip.c: Auto destroying SIP dialog ‘FOoc7N9Q5hJrOVkSipXwSgAqw7T3LwtC’
[2011-05-23 12:53:40.449] DEBUG[16887] chan_sip.c: Destroying SIP dialog FOoc7N9Q5hJrOVkSipXwSgAqw7T3LwtC

Please note the colors above. It appears that the client’s port # (which I happened to hardcode to 5061) isn’t being determined properly in netsock2.c.

The behavior I see is that the client succesfully registers, but cannot make any calls due to the fact that all SIP messages cannot make it back to the client. I’m going to dig into the code further to see if I can track this down (with specifics). Let me know if this should move to a bug tracker for future reference.

6

The same client works using UDP or TCP, without TLS?

What does a SIP debug look like when you’re trying this call?

7

I may have mistakenly blamed Asterisk for this one. Not sure, though. I believe I got confused in the previous post due to the Contact: header having a different port number than the originating socket descriptor used to establish the TLS session. This could point to a bug in the actual client, rather than the Asterisk server. More research needed.

Regardless, here is the “sip set debug on” log:

[code][2011-05-23 13:47:16.422] DEBUG[16996] chan_sip.c: Starting thread for SSL server
[2011-05-23 13:47:16.429] DEBUG[16996] chan_sip.c: Header 0 [ 32]: REGISTER sip:192.168.2.2 SIP/2.0
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjiq8SHofNrzsCyfJqx7mHcHz7L-jXdVT8
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 2 [ 41]: Route: sip:192.168.2.2;transport=tls;lr
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 4 [ 66]: From: sip:libby@192.168.2.2;tag=iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 5 [ 27]: To: sip:libby@192.168.2.2
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 6 [ 41]: Call-ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 7 [ 20]: CSeq: 53577 REGISTER
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 8 [ 39]: User-Agent: CSipSimple r867 / passion-8
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 9 [ 25]: Supported: outbound, path
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 10 [130]: Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob;reg-id=1;+sip.instance=“urn:uuid:00000000-0000-0000-0000-0000e922f243”
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 11 [ 12]: Expires: 900
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 12 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 13 [ 18]: Content-Length: 0
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 14 [ 0]:
[2011-05-23 13:47:16.430] VERBOSE[16996] chan_sip.c:
<— SIP read from TLS:192.168.2.100:46355 —>
REGISTER sip:192.168.2.2 SIP/2.0
Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjiq8SHofNrzsCyfJqx7mHcHz7L-jXdVT8
Route: sip:192.168.2.2;transport=tls;lr
Max-Forwards: 70
From: sip:libby@192.168.2.2;tag=iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS
To: sip:libby@192.168.2.2
Call-ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
CSeq: 53577 REGISTER
User-Agent: CSipSimple r867 / passion-8
Supported: outbound, path
Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob;reg-id=1;+sip.instance="urn:uuid:00000000-0000-0000-0000-0000e922f243"
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length: 0

<------------->
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 0 [ 32]: REGISTER sip:192.168.2.2 SIP/2.0
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjiq8SHofNrzsCyfJqx7mHcHz7L-jXdVT8
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 2 [ 41]: Route: sip:192.168.2.2;transport=tls;lr
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 4 [ 66]: From: sip:libby@192.168.2.2;tag=iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 5 [ 27]: To: sip:libby@192.168.2.2
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 6 [ 41]: Call-ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 7 [ 20]: CSeq: 53577 REGISTER
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 8 [ 39]: User-Agent: CSipSimple r867 / passion-8
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 9 [ 25]: Supported: outbound, path
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 10 [130]: Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob;reg-id=1;+sip.instance=“urn:uuid:00000000-0000-0000-0000-0000e922f243”
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 11 [ 12]: Expires: 900
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 12 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Header 13 [ 17]: Content-Length: 0
[2011-05-23 13:47:16.430] VERBOSE[16996] chan_sip.c: — (14 headers 0 lines) —
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: = Looking for Call ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg (Checking From) --From tag iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS --To-tag
[2011-05-23 13:47:16.430] DEBUG[16996] acl.c: For destination ‘192.168.2.100’, our source address is ‘192.168.2.2’.
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Setting SIP_TRANSPORT_TLS with address 192.168.2.2:5061
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Allocating new SIP dialog for AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg - REGISTER (No RTP)
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Initializing initreq for method REGISTER - callid AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
[2011-05-23 13:47:16.430] DEBUG[16996] netsock2.c: Splitting ‘192.168.2.100:46355’ gives…
[2011-05-23 13:47:16.430] DEBUG[16996] netsock2.c: …host ‘192.168.2.100’ and port ‘46355’.
[2011-05-23 13:47:16.430] VERBOSE[16996] chan_sip.c: Sending to 192.168.2.100:46355 (no NAT)
[2011-05-23 13:47:16.430] VERBOSE[16996] chan_sip.c:
<— Transmitting (no NAT) to 192.168.2.100:46355 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/TLS 192.168.2.100:46355;branch=z9hG4bKPjiq8SHofNrzsCyfJqx7mHcHz7L-jXdVT8;received=192.168.2.100;rport=46355
From: sip:libby@192.168.2.2;tag=iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS
To: sip:libby@192.168.2.2;tag=as36ac7c8f
Call-ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
CSeq: 53577 REGISTER
Server: Asterisk PBX 1.8.4.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="6800dc4e"
Content-Length: 0

<------------>
[2011-05-23 13:47:16.430] DEBUG[16996] chan_sip.c: Trying to put ‘SIP/2.0 401’ onto TLS socket destined for 192.168.2.100:46355
[2011-05-23 13:47:16.430] VERBOSE[16996] chan_sip.c: Scheduling destruction of SIP dialog ‘AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg’ in 32000 ms (Method: REGISTER)
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 0 [ 32]: REGISTER sip:192.168.2.2 SIP/2.0
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjGSbgv08Wv6hV7H2UACEr0.4n9hw5BAIO
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 2 [ 41]: Route: sip:192.168.2.2;transport=tls;lr
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 4 [ 66]: From: sip:libby@192.168.2.2;tag=iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 5 [ 27]: To: sip:libby@192.168.2.2
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 6 [ 41]: Call-ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 7 [ 20]: CSeq: 53578 REGISTER
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 8 [ 39]: User-Agent: CSipSimple r867 / passion-8
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 9 [ 25]: Supported: outbound, path
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 10 [130]: Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob;reg-id=1;+sip.instance=“urn:uuid:00000000-0000-0000-0000-0000e922f243”
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 11 [ 12]: Expires: 900
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 12 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 13 [157]: Authorization: Digest username=“libby”, realm=“asterisk”, nonce=“6800dc4e”, uri=“sip:192.168.2.2”, response=“a9029a89b5d8711dc8f077c4f1099e38”, algorithm=MD5
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 14 [ 18]: Content-Length: 0
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 15 [ 0]:
[2011-05-23 13:47:16.435] VERBOSE[16996] chan_sip.c:
<— SIP read from TLS:192.168.2.100:46355 —>
REGISTER sip:192.168.2.2 SIP/2.0
Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjGSbgv08Wv6hV7H2UACEr0.4n9hw5BAIO
Route: sip:192.168.2.2;transport=tls;lr
Max-Forwards: 70
From: sip:libby@192.168.2.2;tag=iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS
To: sip:libby@192.168.2.2
Call-ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
CSeq: 53578 REGISTER
User-Agent: CSipSimple r867 / passion-8
Supported: outbound, path
Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob;reg-id=1;+sip.instance="urn:uuid:00000000-0000-0000-0000-0000e922f243"
Expires: 900
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Authorization: Digest username=“libby”, realm=“asterisk”, nonce=“6800dc4e”, uri=“sip:192.168.2.2”, response=“a9029a89b5d8711dc8f077c4f1099e38”, algorithm=MD5
Content-Length: 0

<------------->
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 0 [ 32]: REGISTER sip:192.168.2.2 SIP/2.0
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjGSbgv08Wv6hV7H2UACEr0.4n9hw5BAIO
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 2 [ 41]: Route: sip:192.168.2.2;transport=tls;lr
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 4 [ 66]: From: sip:libby@192.168.2.2;tag=iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 5 [ 27]: To: sip:libby@192.168.2.2
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 6 [ 41]: Call-ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 7 [ 20]: CSeq: 53578 REGISTER
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 8 [ 39]: User-Agent: CSipSimple r867 / passion-8
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 9 [ 25]: Supported: outbound, path
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 10 [130]: Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob;reg-id=1;+sip.instance=“urn:uuid:00000000-0000-0000-0000-0000e922f243”
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 11 [ 12]: Expires: 900
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 12 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 13 [157]: Authorization: Digest username=“libby”, realm=“asterisk”, nonce=“6800dc4e”, uri=“sip:192.168.2.2”, response=“a9029a89b5d8711dc8f077c4f1099e38”, algorithm=MD5
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Header 14 [ 17]: Content-Length: 0
[2011-05-23 13:47:16.435] VERBOSE[16996] chan_sip.c: — (15 headers 0 lines) —
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: = Looking for Call ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg (Checking From) --From tag iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS --To-tag
[2011-05-23 13:47:16.435] DEBUG[16996] netsock2.c: Splitting ‘192.168.2.2’ gives…
[2011-05-23 13:47:16.435] DEBUG[16996] netsock2.c: …host ‘192.168.2.2’ and port ‘(null)’.
[2011-05-23 13:47:16.435] DEBUG[16996] netsock2.c: Splitting ‘192.168.2.2’ gives…
[2011-05-23 13:47:16.435] DEBUG[16996] netsock2.c: …host ‘192.168.2.2’ and port ‘(null)’.
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Initializing initreq for method REGISTER - callid AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
[2011-05-23 13:47:16.435] DEBUG[16996] netsock2.c: Splitting ‘192.168.2.100:46355’ gives…
[2011-05-23 13:47:16.435] DEBUG[16996] netsock2.c: …host ‘192.168.2.100’ and port ‘46355’.
[2011-05-23 13:47:16.435] VERBOSE[16996] chan_sip.c: Sending to 192.168.2.100:46355 (no NAT)
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: peer ‘libby’ has contacted us over TLS even though we prefer UDP.
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Store REGISTER’s Contact header for call routing.
[2011-05-23 13:47:16.435] DEBUG[16996] netsock2.c: Splitting ‘192.168.2.100:51803’ gives…
[2011-05-23 13:47:16.435] DEBUG[16996] netsock2.c: …host ‘192.168.2.100’ and port ‘51803’.
[2011-05-23 13:47:16.435] VERBOSE[16996] chan_sip.c: – Registered SIP ‘libby’ at 192.168.2.100:51803
[2011-05-23 13:47:16.435] VERBOSE[16996] chan_sip.c: > Saved useragent “CSipSimple r867 / passion-8” for peer libby
[2011-05-23 13:47:16.435] VERBOSE[16996] chan_sip.c:
<— Transmitting (no NAT) to 192.168.2.100:46355 —>
SIP/2.0 200 OK
Via: SIP/2.0/TLS 192.168.2.100:46355;branch=z9hG4bKPjGSbgv08Wv6hV7H2UACEr0.4n9hw5BAIO;received=192.168.2.100;rport=46355
From: sip:libby@192.168.2.2;tag=iS3XGMplUslkW2Agj3tsBBWIfTwVDkDS
To: sip:libby@192.168.2.2;tag=as36ac7c8f
Call-ID: AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
CSeq: 53578 REGISTER
Server: Asterisk PBX 1.8.4.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 900
Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob;expires=900
Date: Mon, 23 May 2011 20:47:16 GMT
Content-Length: 0

<------------>
[2011-05-23 13:47:16.435] DEBUG[16996] chan_sip.c: Trying to put ‘SIP/2.0 200’ onto TLS socket destined for 192.168.2.100:46355
[2011-05-23 13:47:16.435] VERBOSE[16996] chan_sip.c: Scheduling destruction of SIP dialog ‘AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg’ in 32000 ms (Method: REGISTER)
[2011-05-23 13:47:16.435] DEBUG[16865] devicestate.c: No provider found, checking channel drivers for SIP - libby
[2011-05-23 13:47:16.435] DEBUG[16865] chan_sip.c: Checking device state for peer libby
[2011-05-23 13:47:16.435] DEBUG[16865] devicestate.c: Changing state for SIP/libby - state 1 (Not in use)
[2011-05-23 13:47:16.435] DEBUG[16865] devicestate.c: device ‘SIP/libby’ state ‘1’
[2011-05-23 13:47:16.435] DEBUG[16900] app_queue.c: Device ‘SIP/libby’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 0 [ 34]: INVITE sip:600@192.168.2.2 SIP/2.0
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjh3l1WCnvNUs-ti.WM15wcNG5WTTkKwYz
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 3 [ 66]: From: sip:libby@192.168.2.2;tag=3Ol0jGc142tn4TheiIPyzpyhxiLXanO7
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 4 [ 25]: To: sip:600@192.168.2.2
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 5 [ 57]: Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 6 [ 41]: Call-ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 7 [ 18]: CSeq: 25398 INVITE
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 8 [ 41]: Route: sip:192.168.2.2;transport=tls;lr
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 9 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 10 [ 46]: Supported: replaces, 100rel, timer, norefersub
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 11 [ 21]: Session-Expires: 1800
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 12 [ 10]: Min-SE: 90
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 13 [ 39]: User-Agent: CSipSimple r867 / passion-8
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 15 [ 21]: Content-Length: 560
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 16 [ 0]:
[2011-05-23 13:47:24.371] VERBOSE[16996] chan_sip.c:
<— SIP read from TLS:192.168.2.100:46355 —>
INVITE sip:600@192.168.2.2 SIP/2.0
Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjh3l1WCnvNUs-ti.WM15wcNG5WTTkKwYz
Max-Forwards: 70
From: sip:libby@192.168.2.2;tag=3Ol0jGc142tn4TheiIPyzpyhxiLXanO7
To: sip:600@192.168.2.2
Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob
Call-ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
CSeq: 25398 INVITE
Route: sip:192.168.2.2;transport=tls;lr
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: CSipSimple r867 / passion-8
Content-Type: application/sdp
Content-Length: 560

v=0
o=- 3515172438 3515172438 IN IP4 192.168.2.100
s=pjmedia
c=IN IP4 192.168.2.100
t=0 0
a=X-nat:0
m=audio 4000 RTP/SAVP 9 104 103 102 0 8 101
a=rtcp:4001 IN IP4 192.168.2.100
a=rtpmap:9 G722/8000
a=rtpmap:104 speex/32000
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=sendrecv
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:j5ur/tg7k6auM1vKKhVpF7D+t/2deJssJbACcwx9
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:cgbXmpBRLSucOdYW4nVTzk5Qy63gK9tFfxniSzYv
<------------->
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 0 [ 34]: INVITE sip:600@192.168.2.2 SIP/2.0
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjh3l1WCnvNUs-ti.WM15wcNG5WTTkKwYz
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 3 [ 66]: From: sip:libby@192.168.2.2;tag=3Ol0jGc142tn4TheiIPyzpyhxiLXanO7
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 4 [ 25]: To: sip:600@192.168.2.2
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 5 [ 57]: Contact: sip:libby@192.168.2.100:51803;transport=TLS;ob
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 6 [ 41]: Call-ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 7 [ 18]: CSeq: 25398 INVITE
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 8 [ 41]: Route: sip:192.168.2.2;transport=tls;lr
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 9 [ 90]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 10 [ 46]: Supported: replaces, 100rel, timer, norefersub
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 11 [ 21]: Session-Expires: 1800
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 12 [ 10]: Min-SE: 90
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 13 [ 39]: User-Agent: CSipSimple r867 / passion-8
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 15 [ 19]: Content-Length: 560
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Header 16 [ 0]:
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 0 [ 3]: v=0
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 1 [ 46]: o=- 3515172438 3515172438 IN IP4 192.168.2.100
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 2 [ 9]: s=pjmedia
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 3 [ 22]: c=IN IP4 192.168.2.100
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 4 [ 5]: t=0 0
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 5 [ 9]: a=X-nat:0
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 6 [ 43]: m=audio 4000 RTP/SAVP 9 104 103 102 0 8 101
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 7 [ 32]: a=rtcp:4001 IN IP4 192.168.2.100
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 8 [ 20]: a=rtpmap:9 G722/8000
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 9 [ 24]: a=rtpmap:104 speex/32000
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 10 [ 24]: a=rtpmap:103 speex/16000
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 11 [ 23]: a=rtpmap:102 speex/8000
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 12 [ 20]: a=rtpmap:0 PCMU/8000
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 13 [ 20]: a=rtpmap:8 PCMA/8000
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 14 [ 10]: a=sendrecv
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 15 [ 33]: a=rtpmap:101 telephone-event/8000
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 16 [ 15]: a=fmtp:101 0-15
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 17 [ 82]: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:j5ur/tg7k6auM1vKKhVpF7D+t/2deJssJbACcwx9
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Body 18 [ 82]: a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:cgbXmpBRLSucOdYW4nVTzk5Qy63gK9tFfxniSzYv
[2011-05-23 13:47:24.371] VERBOSE[16996] chan_sip.c: — (16 headers 19 lines) —
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: = Looking for Call ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c. (Checking From) --From tag 3Ol0jGc142tn4TheiIPyzpyhxiLXanO7 --To-tag
[2011-05-23 13:47:24.371] DEBUG[16996] acl.c: For destination ‘192.168.2.100’, our source address is ‘192.168.2.2’.
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Setting SIP_TRANSPORT_TLS with address 192.168.2.2:5061
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Allocating new SIP dialog for 7xBvQQmJq6g7otWVBZGmVo53oKctg9c. - INVITE (No RTP)
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Begin: parsing SIP “Supported: replaces, 100rel, timer, norefersub”
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Found SIP option: -replaces-
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Matched SIP option: replaces
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Found SIP option: -100rel-
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Matched SIP option: 100rel
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Found SIP option: -timer-
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Matched SIP option: timer
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Found SIP option: -norefersub-
[2011-05-23 13:47:24.371] DEBUG[16996] sip/reqresp_parser.c: Matched SIP option: norefersub
[2011-05-23 13:47:24.371] DEBUG[16996] netsock2.c: Splitting ‘192.168.2.100:46355’ gives…
[2011-05-23 13:47:24.371] DEBUG[16996] netsock2.c: …host ‘192.168.2.100’ and port ‘46355’.
[2011-05-23 13:47:24.371] VERBOSE[16996] chan_sip.c: Sending to 192.168.2.100:46355 (no NAT)
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Initializing initreq for method INVITE - callid 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
[2011-05-23 13:47:24.371] VERBOSE[16996] chan_sip.c: Using INVITE request as basis request - 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
[2011-05-23 13:47:24.371] VERBOSE[16996] chan_sip.c: Found peer ‘libby’ for ‘libby’ from 192.168.2.100:46355
[2011-05-23 13:47:24.371] VERBOSE[16996] chan_sip.c:
<— Reliably Transmitting (no NAT) to 192.168.2.100:46355 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/TLS 192.168.2.100:46355;branch=z9hG4bKPjh3l1WCnvNUs-ti.WM15wcNG5WTTkKwYz;received=192.168.2.100;rport=46355
From: sip:libby@192.168.2.2;tag=3Ol0jGc142tn4TheiIPyzpyhxiLXanO7
To: sip:600@192.168.2.2;tag=as00def58d
Call-ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
CSeq: 25398 INVITE
Server: Asterisk PBX 1.8.4.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="633fa1bb"
Content-Length: 0

<------------>
[2011-05-23 13:47:24.371] DEBUG[16996] chan_sip.c: Trying to put ‘SIP/2.0 401’ onto TLS socket destined for 192.168.2.100:46355
[2011-05-23 13:47:24.372] VERBOSE[16996] chan_sip.c: Scheduling destruction of SIP dialog ‘7xBvQQmJq6g7otWVBZGmVo53oKctg9c.’ in 32000 ms (Method: INVITE)
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 0 [ 31]: ACK sip:600@192.168.2.2 SIP/2.0
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjh3l1WCnvNUs-ti.WM15wcNG5WTTkKwYz
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 3 [ 66]: From: sip:libby@192.168.2.2;tag=3Ol0jGc142tn4TheiIPyzpyhxiLXanO7
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 4 [ 40]: To: sip:600@192.168.2.2;tag=as00def58d
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 5 [ 41]: Call-ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 6 [ 15]: CSeq: 25398 ACK
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 7 [ 41]: Route: sip:192.168.2.2;transport=tls;lr
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 8 [ 18]: Content-Length: 0
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 9 [ 0]:
[2011-05-23 13:47:24.376] VERBOSE[16996] chan_sip.c:
<— SIP read from TLS:192.168.2.100:46355 —>
ACK sip:600@192.168.2.2 SIP/2.0
Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjh3l1WCnvNUs-ti.WM15wcNG5WTTkKwYz
Max-Forwards: 70
From: sip:libby@192.168.2.2;tag=3Ol0jGc142tn4TheiIPyzpyhxiLXanO7
To: sip:600@192.168.2.2;tag=as00def58d
Call-ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
CSeq: 25398 ACK
Route: sip:192.168.2.2;transport=tls;lr
Content-Length: 0

<------------->
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 0 [ 31]: ACK sip:600@192.168.2.2 SIP/2.0
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 1 [ 91]: Via: SIP/2.0/TLS 192.168.2.100:46355;rport;branch=z9hG4bKPjh3l1WCnvNUs-ti.WM15wcNG5WTTkKwYz
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 3 [ 66]: From: sip:libby@192.168.2.2;tag=3Ol0jGc142tn4TheiIPyzpyhxiLXanO7
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 4 [ 40]: To: sip:600@192.168.2.2;tag=as00def58d
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 5 [ 41]: Call-ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c.
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 6 [ 15]: CSeq: 25398 ACK
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 7 [ 41]: Route: sip:192.168.2.2;transport=tls;lr
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Header 8 [ 17]: Content-Length: 0
[2011-05-23 13:47:24.376] VERBOSE[16996] chan_sip.c: — (9 headers 0 lines) —
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: = Looking for Call ID: 7xBvQQmJq6g7otWVBZGmVo53oKctg9c. (Checking From) --From tag 3Ol0jGc142tn4TheiIPyzpyhxiLXanO7 --To-tag as00def58d
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2011-05-23 13:47:24.376] DEBUG[16996] chan_sip.c: Stopping retransmission on ‘7xBvQQmJq6g7otWVBZGmVo53oKctg9c.’ of Response 25398: Match Not Found
[2011-05-23 13:47:48.436] DEBUG[16887] chan_sip.c: Auto destroying SIP dialog ‘AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg’
[2011-05-23 13:47:48.436] DEBUG[16887] chan_sip.c: Destroying SIP dialog AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg
[2011-05-23 13:47:48.436] VERBOSE[16887] chan_sip.c: Really destroying SIP dialog ‘AvhQTDlfiXiw0Us.XqYXgYZoS.5Ndmkg’ Method: REGISTER[/code]

8

I asked one of the devs to take a look at that log, and he said it appeared to be normal operation on the Asterisk side.

9

Hi @ all,

I am doing the same tutorial like itodroid. Using the blink softphone on windows 7.
After trying to register nothing happens.
Wireshark shows this:

172.16.xxx.xxx 172.16.xxx.xxx SSL Client Hello
172.16.xxx.xxx 172.16.xxx.xxx TCP sip-tls > 59579 [ACK] Seq=1 Ack=95 Win=5888 Len=0
172.16.xxx.xxx 172.16.xxx.xxx TCP 59579 > sip-tls [FIN, ACK] Seq=95 Ack=1 Win=65536 [TCP CHECKSUM INCORRECT] Len=0
172.16.xxx.xxx 172.16.xxx.xxx TCP sip-tls > 59579 [FIN, ACK] Seq=1 Ack=96 Win=5888 Len=0
172.16.xxx.xxx 172.16.xxx.xxx TCP 59579 > sip-tls [ACK] Seq=96 Ack=2 Win=65536 [TCP CHECKSUM INCORRECT] Len=0
etc.
then begins on Client Hello again.

Here are my sip.conf settings

[general]
…
tcpenable=yes
tcpbindaddr=0.0.0.0:5061
tlsenable=yes
tlsbindaddr=0.0.0.0:5061
tlscertfile=/asterisk.pem
tlscafile=/ca.crt
tlscipher=ALL
tlsclientmethod=tlsv1

[90]
…
transport=yes
encryption=yes
…

what could be my problem that it isn´t running with TLS?

Best Regards
Karsten

10

Don’t try to run TCP and TLS on the same port.

Are you using 1.8.4.1 or 1.8 out of SVN? There’s a bug in 1.8.4 that hoses up registration of TLS clients, including Blink, which I’m running on my Mac.

Also, set transport for the peer equal to tls.

11

But If I try to run tcp on 5060 then no Client Hello Request will send.

We use 1.8.4 with the last Patch with Revision 320709 which we had installed this morning.
Also the last SVN Branch

transport for peer is set to tls and not to yes:D:D

EDIT:
So now we have patch with the newest Branch 320711
And with settings to tcpbindaddr=0.0.0.0:5060
this result is given by wireshark

172.16.xxx.xxx 172.16.xxx.xxx TCP 63087 > sip-tls [SYN] Seq=0 Win=8192 [TCP CHECKSUM INCORRECT] Len=0 MSS=1460 WS=8
172.16.xxx.xxx 172.16.xxx.xxx TCP sip-tls > 63087 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0
172.16.xxx.xxx 172.16.xxx.xxx TCP 63087 > sip-tls [SYN] Seq=0 Win=8192 [TCP CHECKSUM INCORRECT] Len=0 MSS=1460 WS=8
172.16.xxx.xxx 172.16.xxx.xxx TCP sip-tls > 63087 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0
172.16.xxx.xxx 172.16.xxx.xxx TCP 63087 > sip-tls [SYN] Seq=0 Win=8192 [TCP CHECKSUM INCORRECT] Len=0 MSS=1460
172.16.xxx.xxx 172.16.xxx.xxx TCP sip-tls > 63087 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0
172.16.xxx.xxx 172.16.xxx.xxx TCP 63088 > sip-tls [SYN] Seq=0 Win=8192 [TCP CHECKSUM INCORRECT] Len=0 MSS=1460 WS=8
172.16.xxx.xxx 172.16.xxx.xxx TCP sip-tls > 63088 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0
and so on.

12

r320709 is lists.digium.com/pipermail/svn-c … 66838.html.

That’s not 1.8 out of branch, nor is it 1.8.4.1.

My sip.conf reads like:

[general]
context=default
allowguest=no
udpbindaddr=0.0.0.0
tcpenable=yes
tcpbindaddr=0.0.0.0
tlsbindaddr=0.0.0.0
tlscertfile=/etc/asterisk/keys/asterisk.pem
tlscafile=/etc/asterisk/keys/ca.crt
tlscipher=ALL
tlsclientmethod=tlsv1

[mypeer]
type = peer
secret = mysecret
host=dynamic
dtmfmode=rfc2833
disallow=all
allow=all
context=testing
transport = tls

And I’m using SVN from this morning and I can register okay.

13

Nice Morning,

now we have installed the 1.8.4.1 Version.
But I have the same problem again.

Is there a difference with the certificates perhaps?
Is it a problem to generate the keys on the Asterisk Console and
then using them in Windows?
What else could be wrong?
I´m trying it with the same settings like you.
I tried it with PhonerLite too but it also doesn´t work.

EDIT:
If I take a look at this from first thread

I can´t find this in my DEBUG output. I have set in my logger.conf
full => notice, warning, error, debug, verbose, dtmf, fax
and debug => debug uncommented.
Regards
Karsten

14

I’ve also registered a Polycom 670 using TLS using the same settings without trouble.

You followed the instructions exactly?

15

I followed them exactly…step for step.

Is it correct that there are no advice of starting thread ssl server by starting asterisk?
I don´t get the advice that SSL Certicate ok like in the first thread of this discussion.

16

I’ve generated client certificates and used them on Mac with Blink and on a Polycom phone without issue.

17

I´m generating the client certificates like you described it in your tutorial. Then I copied this and the ca.crt to my windows client and set them in blink. But If I start blink with tls on port 5061 in wireshark these are the messages by filtering with tcp.port == 5061
172.16.xxx.xxx 172.16.xxx.xxx TCP 58843 > sip-tls [SYN] Seq=0 Win=8192 [TCP CHECKSUM INCORRECT] Len=0 MSS=1460 WS=8
172.16.xxx.xxx 172.16.xxx.xxx TCP sip-tls > 58843 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0

and on asterisk there is no reaction.

18

Digium offers paid support options, detailed here:
digium.com/en/supportcenter/asterisk.php

If you want one of our guys to look into it, that’s a route you can take.

Cheers.

19

I will try to find out by myself. That´s a nice offer and I will see If I need it in time.

20

I hope I can share my expereince .
I can use TSL and SRTP to connect lync server.
I think you need to ensure the TLs is ok first .
The cert and key is important thing as if they are not auth, the TLS cannot work any more .
You can view belo post . That is my TSL SRTP experience connect from asterisk to lync server …
Hope this is help …

http://forums.digium.com/viewtopic.php?f=1&t=84559