[Home]

Summary:ASTERISK-18345: [patch] sips connection dropped by asterisk with a large INVITE
Reporter:Stephane Chazelas (stephane.chazelas)Labels:
Date Opened:2011-08-25 04:34:16Date Closed:2014-08-07 16:26:22
Priority:MajorRegression?
Status:Closed/CompleteComponents:Channels/chan_sip/TCP-TLS
Versions:SVN 1.8.4 11.4.0 11.5.0 Frequency of
Occurrence
Constant
Related
Issues:
is duplicated byASTERISK-19003 asterisk closes TLS connection after receiving ACK for 401 following INVITE sent by Snom m9
is related toASTERISK-18342 close() before SSL_Shutdown() in ssl_close()
is related toASTERISK-18700 chan_sip.c and tcptls.c - possible double close of file descriptor
Environment:Attachments:( 0) tcptls_poll.diff
( 1) tcptls_pollv2.diff
( 2) tls_read_fix_try1_1.8.11.1.diff
( 3) tls_read_fix_try2_1.8.11.1.diff
( 4) tls_read_fix_try3_1.8.11.1.diff
( 5) tls_read.patch
( 6) tlsBigSDP.patch
( 7) tlsBigSDPdebug.patch
Description:When using jitsi (http://jitsi.org) (debian amd64 one) as sip-tls extension, one can see the SSL connection to asterisk being dropped (abnormally, but that seems due to ASTERISK-18342) during the registration and placing calls don't work.

I first thought it was a SSL method issue as jitsi doesn't seem to support SSLv3 or TLSv1 and I was able to make it work by using a MitM that proxied the connection through socat: jitsi was able to talk to socat OK and socat to asterisk OK.

But it looks more like a timing/undeterministic issue. I then had a look at the code, added a little logging and found out that the connection was closed because of fgets() returning NULL in _sip_tcp_helper_thread().

I then added logging to ssl_read() to see if SSL_read() ever failed, but it doesn't so I don't understand how that fgets could return eof/error. In that case. Then, I had a hard time understanding that business of need_poll/after_poll.

If I understand correctly, tcptls_session->fd is the network socket that carries the encrypted data and other ssl out-of-band stuff and has been made non-blocking, and tcptls_session->f which is a funopen(tcptls_session->ssl, ssl_read, ssl_write, NULL, ssl_close) (or fopencookie Linux equivalent). polls are made on the fd before doing fgets that eventually call SSL_read. That sounds to me like a recipe for catastrophy, deadlocks and the like but I have to admit I have not understood/seen the design fully.

I still don't get how fgets() can return NULL here but I tried to bring the need_poll/after_poll trick further by doing:

{code}
@@ -2659,7 +2637,7 @@ static void *_sip_tcp_helper_thread(stru
                                * TLS layer */
                               if (!tcptls_session->ssl || need_poll) {
                                       need_poll = 0;
-                                       after_poll = 1;
+                                       after_poll++;
                                       res = ast_wait_for_input(tcptls_session->fd, timeout);
                                       if (res < 0) {
                                               ast_debug(2, "SIP TCP server :: ast_wait_for_input returned %d\n", res);
@@ -2674,7 +2654,7 @@ static void *_sip_tcp_helper_thread(stru
                               ast_mutex_lock(&tcptls_session->lock);
                               if (!fgets(buf, sizeof(buf), tcptls_session->f)) {
                                       ast_mutex_unlock(&tcptls_session->lock);
-                                       if (after_poll) {
+                                       if (after_poll > 1) {
                                               goto cleanup;
                                       } else {
                                               need_poll = 1;
{code}
and it fixed the issue.

So, there's something definitely wrong though I couldn't tell exactly what.
Comments:By: Stephane Chazelas (stephane.chazelas) 2011-08-25 05:51:22.215-0500

Sorry, my bad. Actually SSL_read did fail with SSL_ERROR_WANT_READ meaning that it needs to be called again when data is available to be read. Which means we "need_poll" again in that case. That explains why my change works and is not guaranteed to. Maybe a better fix would be to only use stdio functions (fgets/fread) when SSL_pending() has something, or maybe redesign it without non-blocking IO?

By: Jonathan Rose (jrose) 2011-11-30 16:07:59.102-0600

This issue was referenced in https://reviewboard.asterisk.org/r/1576/ and it's possible some of our changes might have had an impact here.

By: Gregor Schaffrath (kodomo) 2011-12-14 06:41:21.453-0600

I think this issue might relate to one I posted about asterisk 1.8.7.1 and svn trunk:
ASTERISK-19003

By: Matthias Nagl (mnagl) 2012-03-11 06:16:50.219-0500

This bug still occurs using Asterisk 10.1.3. I hope the patch or another fix will enter svn soon as it renders SIPS unusable and is a pain to track down without knowing this report.

By: Steve Davies (one47) 2012-05-11 11:09:05.808-0500

In my opinion, Stephane Chazelas hit the nail on the head. The current code assumes that if a poll() fires, then data will be available to read. When using SSL, this is completely wrong. You do need to use something like SSL_pending(), and if it reports no data, drop back into the poll.

I have a patch that compiles in 1.8.11.1, but has never been run. I will attach it. Give it a go?

By: frank koster (notthematrix) 2012-05-21 18:30:28.788-0500

Tryed tls_read_fix_try1_1.8.11.1.diff
on 1.8.12.0 get a
[May 21 20:20:18] WARNING[20418] loader.c: Error loading module 'chan_sip.so': /usr/lib/asterisk/modules/chan_sip.so: undefined symbol: ssl_pending                                
[May 21 20:20:18] WARNING[20418] loader.c: Module 'chan_sip.so' could not be loaded
so it think something is not working yet... :)
Btw we use granstream ht-50x and they also have issue's with this bug we have the support of the grandstream dev team and they are willing to help testing in this issue if possible.
this problem realy needs to be fixed :)


By: Steve Davies (one47) 2012-05-22 03:57:20.555-0500

Did you rebuild ALL of asterisk, and re-install it? I do not have a test environment at present, but I would only expect that error if you were running an old asterisk binary and a new chan_sip.so.

I'll try and assemble a working test environment soon. The symbols seem to be present in my build:

$ nm /usr/sbin/asterisk | grep -e ssl_pending -e ast_ssl_setup
08159b50 T ast_ssl_setup
0815a560 T ssl_pending



By: frank koster (notthematrix) 2012-05-22 08:34:03.886-0500

I downloaded 1.8.11.1 had a clean build and still the same problem....
May 22 10:18:29] WARNING[10801] loader.c: Error loading module 'chan_sip.so': /usr/lib/asterisk/modules/chan_sip.so: undefined symbol: ssl_pending
[May 22 10:18:29] WARNING[10801] loader.c: Module 'chan_sip.so' could not be loaded.

did the same to see if they were in.
and yes this is what we get ...

0818f550 T ast_ssl_setup
0818f050 t ssl_pending

so something else must be missing?
We have a test envoirment if you want to test :)


By: Steve Davies (one47) 2012-05-22 09:40:08.425-0500

Yours is showing a 't' (local/private symbol) - Mine is showing a 'T' (exported/public symbol). I am not entirely sure why.

What command did you use to patch your sources? Did you see any errors or warnings when patching?

I would expect to see the output you report if the ssl_pending function were declared "static" which it should not be.


By: frank koster (notthematrix) 2012-05-22 11:23:08.169-0500

cwd /home/frank
cd asterisk-1.8.11.1
cat /home/frank/tls_read_fix_try1_1.8.11.1.diff | patch -p1

uname -a
Linux ubuntu 3.0.0-12-generic #20-Ubuntu SMP Fri Oct 7 14:50:42 UTC 2011 i686 athlon i386 GNU/Linux
all was clean
make worked...
I did not compile as root.

Also tryed it on my 64 bit system.
Same problem as this system. maby ssl-lib version????
what linux version do you use?



By: Steve Davies (one47) 2012-05-23 05:27:32.741-0500

I'm building on an older Debian/Lenny system, but that should not affect this particular issue.

\# gcc --version
gcc (Debian 4.3.2-1.1) 4.3.2

\# uname -a
Linux bob 2.6.26-2-686 #1 SMP Wed Aug 19 06:06:52 UTC 2009 i686 GNU/Linux

libssl0.9.8          0.9.8g-15+lenny5      SSL shared libraries

I am building as root as I'm on a dedicated build box, but I would not expect that to make a difference. The code says the symbol is public, so it should be public! Here is the sequence I used...

\# mkdir /usr/src/tmp
\# cd /usr/src/tmp
\# tar xzvf ~/asterisk-1.8.11.1.tar.gz
[snip output]
\# cd asterisk-1.8.11.1/
\# patch -p1 < ~/tls_read_fix_try1_1.8.11.1.diff
patching file channels/chan_sip.c
Hunk #1 succeeded at 2673 (offset -36 lines).
patching file main/tcptls.c
patching file include/asterisk/tcptls.h
\# ./configure
[snip output]
\# make
[snip output]
\# nm ./main/asterisk | grep -e ssl_pending -e ast_ssl_setup -e ssl_read
0818af20 T ast_ssl_setup     < ---- Correctly 'T'
0818ba30 T ssl_pending       < ---- Capital 'T'
0818b650 t ssl_read          < ---- Correctly 't'



By: frank koster (notthematrix) 2012-05-23 06:31:28.601-0500

Installed
apt-get install libssl0.9.8

then did exactly as you did.

gcc -v
Using built-in specs.
COLLECT_GCC=gcc
COLLECT_LTO_WRAPPER=/usr/lib/gcc/i686-linux-gnu/4.6.1/lto-wrapper
Target: i686-linux-gnu
Configured with: ../src/configure -v --with-pkgversion='Ubuntu/Linaro 4.6.1-9ubuntu3' --with-bugurl=file:///usr/share/doc/gcc-4.6/README.Bugs --enable-languages=c,c++,fortran,objc,obj-c++,go --prefix=/usr --program-suffix=-4.6 --enable-shared --enable-linker-build-id --with-system-zlib --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --with-gxx-include-dir=/usr/include/c++/4.6 --libdir=/usr/lib --enable-nls --with-sysroot=/ --enable-clocale=gnu --enable-libstdcxx-debug --enable-libstdcxx-time=yes --enable-plugin --enable-objc-gc --enable-targets=all --disable-werror --with-arch-32=i686 --with-tune=generic --enable-checking=release --build=i686-linux-gnu --host=i686-linux-gnu --target=i686-linux-gnu
Thread model: posix
gcc version 4.6.1 (Ubuntu/Linaro 4.6.1-9ubuntu3)

nm ./main/asterisk | grep -e ssl_pending -e ast_ssl_setup -e ssl_read


0818f550 T ast_ssl_setup
0818f050 t ssl_pending
0818eb40 t ssl_read

So what can it be , missing dependecies?


By: Steve Davies (one47) 2012-05-23 06:46:41.224-0500

A small change to the patch - I think by default the function needs to be named ast_* for it to be exported and made available to chan_sip.so

That was an education (assuming it even works!)

By: frank koster (notthematrix) 2012-05-23 09:58:25.520-0500

Oke tryed 2nd patch...
It comples and yes the T messeges are good no unresolved symbles.
now whe have the following situation.

asteriswk trys to connect outsite but notting gats true.
my try's device connects to the TLS port but does not register...
This also seems to effect normal sip connections....

[May 23 11:52:45] VERBOSE[29860] chan_sip.c: Retransmitting #4 (NAT) to 77.72.169.131:5060:
OPTIONS sip:77.72.169.131 SIP/2.0
v: SIP/2.0/UDP 192.168.178.2:443;branch=z9hG4bK1ea9f3e9;rport
Max-Forwards: 70
f: "Unknown" <sip:Unknown@192.168.178.2:443>;tag=as0d8be8e8
t: <sip:77.72.169.131>
m: <sip:Unknown@192.168.178.2:443>
i: 79b742560c1686bc3091b27821aae9ba@192.168.178.2:443
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Date: Wed, 23 May 2012 14:52:41 GMT
x: 600
Min-SE: 120
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
k: replaces, timer
l: 0



By: Steve Davies (one47) 2012-05-23 10:58:29.698-0500

Looks like I've broken the receive path. The following adds some debug at verbose 2 level, but also avoids the new code unless it seems necessary to use it.

You may find this patch "spams" the screen with verbose output, but I'd be interested in seeing what it is.

Hopefully I can set-up a test environment "real soon now" and test this more thoroughly here.

By: frank koster (notthematrix) 2012-05-23 14:46:03.158-0500

well this is what I got it looks the port can not be set for some reason
we use port 443 but since asterisk is running as root this sould not be a problem....
This is what i get when I reload the chan_sip module at debug level 2
hope this helps...
If you need access to tyhe test box I can provide that....


[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31208081072' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31208081073' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31208081074' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31208081075' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788101' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788102' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788103' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788104' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788105' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788106' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788110' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788111' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788115' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788116' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788117' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788118' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '31251788119' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '33170615403' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '34961124284' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '552139580783' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 0 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] acl.c: 0.0.0.0:0/0.0.0.0:0 sense 1 appended to acl for peer
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 23 16:40:09] DEBUG[1644] db.c: Unable to find key '61889214119' in family 'SIP/Registry'
[May 23 16:40:09] DEBUG[1644] sched.c: Asterisk Schedule Dump (17 in Q, 1696 Total, 78 Cache, 94 high-water)
[May 23 16:40:09] DEBUG[1644] sched.c: =============================================================
[May 23 16:40:09] DEBUG[1644] sched.c: |ID    Callback          Data              Time  (sec:ms)   |
[May 23 16:40:09] DEBUG[1644] sched.c: +-----+-----------------+-----------------+-----------------+
[May 23 16:40:09] DEBUG[1644] sched.c: |1680 | 0x4c2a930       | 0x9ba2e08       | -000001 : 791994 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1689 | 0x4c119f0       | 0x9bad708       | -000001 : 794943 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1681 | 0x4c2a930       | 0x9ba2140       | -000001 : 792602 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1691 | 0x4c119f0       | 0x9e3d718       | -000001 : 941028 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1683 | 0x4c2a930       | 0x9ba5460       | 000000 : 391730 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1682 | 0x4c2a930       | 0x9ba1478       | -000001 : 942090 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1686 | 0x4c2a930       | 0x9ba6df0       | 000002 : 191781 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1693 | 0x4c119f0       | 0x9e40ab0       | -000001 : 941865 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1690 | 0x4c16190       | 0x9ba7ad8       | 000006 : 795194 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1687 | 0x4c2a930       | 0x9ba87c0       | 000002 : 341439 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1685 | 0x4c2a930       | 0x9ba0878       | 000000 : 694024 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1688 | 0x4c2a930       | 0x9ba3ad0       | 000002 : 791850 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1684 | 0x4c2a930       | 0x9ba4798       | 000000 : 693613 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1696 | 0x4c16190       | 0x9baa258       | 000007 : 090955 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1694 | 0x4c16190       | 0x9ba9590       | 000006 : 942083 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1692 | 0x4c16190       | 0x9ba6128       | 000006 : 941258 |
[May 23 16:40:09] DEBUG[1644] sched.c: |1695 | 0x4c119f0       | 0x9f0d280       | 000000 : 090718 |
[May 23 16:40:09] DEBUG[1644] sched.c: =============================================================
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 81.201.86.45:5060
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 81.201.84.45:5060
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 70.42.72.49:5060
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Session timer stopped: -1 - 7d65d32f44fb11ff555ae18368c54f5f@192.168.178.2:443
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Allocating new SIP dialog for 4364aef47663055e74b22a0a1a8e9945@127.0.1.1:443 - OPTIONS (No RTP)
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Initializing initreq for method OPTIONS - callid 4edd5c8e554a41284500c9e374c79dfa@192.168.178.2:443
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 81.201.86.45:5060
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 38.109.171.36:5060
[May 23 16:40:09] DEBUG[1644] chan_sip.c: That's odd...  Got a response on a call we don't know about. Callid 7d39b0680fed32be187da18c7e3dcf8f@94.208.239.101:443
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Invalid SIP message - rejected , no callid, len 349
[May 23 16:40:09] DEBUG[1644] chan_sip.c: That's odd...  Got a response on a call we don't know about. Callid 0e39328a6d02b18a3a7611a7071de51c@94.208.239.101:443
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Invalid SIP message - rejected , no callid, len 299
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Session timer stopped: -1 - 0e39328a6d02b18a3a7611a7071de51c@192.168.178.2:443
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Allocating new SIP dialog for 488250613aa97e8f5a99a19b03231790@127.0.1.1:443 - OPTIONS (No RTP)
[May 23 16:40:09] DEBUG[1644] chan_sip.c: Initializing initreq for method OPTIONS - calli

By: Filip Jenicek (phill) 2012-05-30 00:47:40.991-0500

I had been dealing with this issue for some time and I've finally found a solution.

The problem is in the whole design of polling. Someone most likely overlooked that calling ast_wait_for_input before every fgets is not sufficient. Function fgets internally calls read (=> SSL_read) until either "\n" or eof is found. And because the socket is polled only before the first SSL_read call, consequent calls can fail and return <=0 even though the data are on the way.

There are two ways how to fix it:

1. Make the socket blocking. This would make the SSL_read function to block until it gets data from the SSL layer. A negative side effect would be that the _sip_tcp_helper_thread will not exit on error data.

2. A better approach is to make the HOOK_T ssl_read function (asterisk/main/tcptls.c:55) behave the same way as the system read function (blocking, waiting for data, returning <=0 only in case of an error, not when SSL_ERROR_WANT_READ occurs). I believe, this is the right place to do the poll. The function body might look like this.  
{noformat} int i = SSL_read(cookie, buf, len-1);
while (i < 0 && SSL_get_error(cookie, i) == SSL_ERROR_WANT_READ) {
if (ast_wait_for_input(SSL_get_fd(cookie), 5000) <=0) return 0;
i = SSL_read(cookie, buf, len-1);
{noformat}

I've tested (2) and I can confirm that it solves the issue. Unfortunately, I can't upload a patch due to licensing issues right now, but I believe you can make one on your own.

By: frank koster (notthematrix) 2012-05-30 16:17:20.822-0500

Hello Filip Jenicek you can always send the patch directly to my email notthematrix ( At ) hotmail.com so i can test it too.
and them hoping the patch will be accepted soon.
Since the lines you gave me are not sufficiant to make anything usefull of it.


By: Filip Jenicek (phill) 2012-05-31 03:12:56.203-0500

Patch of HOOK_T ssl_read to fix the TLS issues

By: frank koster (notthematrix) 2012-05-31 19:22:14.321-0500

Filip Jenicek I can confirm that the Attachment tls_read.patch [ 43792 ] fix works on my grandstream ht-503 in TLS+SRTP mode
So I think this disign flaw is fixed :)

Now running 12 hours with the patch on asterisk 1.8.12.2 20 grandstream ht-502 / ht-503 boxes (fw 1.03.20) in tls/srtp mode attached evrything works fine.




By: frank koster (notthematrix) 2012-06-04 03:18:27.094-0500

Patch still working well.


By: frank koster (notthematrix) 2012-06-04 13:06:20.576-0500

grandstream ht-503 fw 1.0.6.8 works.
grandstream ht-701 fw 1.0.0.18 works.
Still no problems encountert after 3 days. using it as office system.


By: Ben Chavet (blc) 2013-07-07 22:39:43.057-0500

I have been trying to chase this issue down for DAYS!

My initial testing shows that the patch supplied here also fixes the issue for asterisk-11.4

By: Deo (bizzone) 2013-08-03 02:40:53.566-0500

Thank you very much for the patch! I have spent several FULL days to understand the nature of this bug and the patch seems to be worked for my 11.5 installation @FreeBSD!

+1 to get it into official release and don't forget to upgrade FreeBSD port please :)

By: Tzafrir Cohen (tzafrir) 2013-08-21 14:51:10.293-0500

I can reproduce this issue easily on Asterisk trunk and 11.5 on Centos 5 (server) with Asterisk 11.5 on Debian 7 as the client.

When I have 'allow=all' and a TLS connection, it blows up. When I either switch to TCP or use 'allow=alaw', all's well. The patch tls_read.patch applied well on trunk and seems to have fixed the issue.

By: Alex Khokhlov (alex-khokhlov) 2013-10-11 02:44:27.416-0500

I also have this issue in my system and it is 100% reproducable in the following environment:
Server: CentOS 6.4, OpenSSL 1.0.0-27.el6_4.2, Asterisk 11.5.1
Client: Counterpath Bria 2.3.6.61985, Android 4.3, Samsung Galaxy Nexus
Ways to reproduce: connect with TLS enabled, enable all codecs in the client, register with the server and try to make a call.

The connection is closed by the server side because it receives SSL_ERROR_WANT_READ from OpenSSL and then immediately returns -1 from ssl_read(). However, it does not actually signal the problem, it is merely a signal to repeat read (see https://www.openssl.org/docs/ssl/SSL_read.html ).

On the network level that happens because of TCP packet fragmentation. Diagnosing packets using wireshark shows that client sends one big TLS packet that is fragmented into two or more TCP packets. The server receives the first TCP packet and immediately decides to close connection (because of -1 from ssl_read). That happens just before the second packet comes to the server side and OpenSSL is able to process/decode TLS packet.

This is definitely a bug on the Asterisk side.

By: Shlomi Gutman (voicenter) 2013-11-27 11:21:57.371-0600

Had problems with outgoing calls from snom with SRTP mandatory asterisk 11.6.0 on Debian 7 (wheezy) 3.2.0-4-amd64(3.2.51-1 x86_64) with openssl 1.0.1e-2.
After applying patch the problem was resolved.

By: Alexander Traud (traud) 2014-06-20 08:18:15.195-0500

This is a follow-up of [ASTERISK-17753|ASTERISK-17753]. My attached tlsBigSDP.patch enables Asterisk to poll a second time even on the first TLS-message part. Would be cool, if you guys could test it because that is a one-line patch.

With some large SDP, a second poll is required on the first part of the message. The current code did not poll a second time because the variable need_poll was inited with yes (1). That poll was a no-operation because there was a socket event already (which mandates fgets without poll). In the current code, poll returned immediately, fgets returned NULL, after_poll was yes (1), sip_tls_read returned failed (-1), _sip_tcp_helper_thread went to cleanup, called ast_tcptls_close_session_file, which closes the TLS connection.

*Steps to reproduce*
# Asterisk sip.conf with tlsenable=yes and tlscertfile set.
# CounterPath [Bria Android Edition|https://play.google.com/store/apps/details?id=com.bria.voip]
# Bria » Settings » Accounts » your Asterisk account » Account Advanced
#* SIP transport: TLS
#* Encrypt Audio: Best Effort (not required, but increases SDP size)
# Bria » Settings » Advanced Settings » Audio Codecs » enable all
# start a call from Bria

*Expected Results*
The call should be established or rejected with an SIP status code.

*Results*
with both verbosity/debug set to 9, and SIP debugging enabled
ERROR tcptls.c: SSL_shutdown() failed: 5

*Notes*
The same happens with [CSipSimple|http://www.ip-phone-forum.de/showthread.php?t=270040#post2013773] if a lot of media codecs are enabled. With CounterPath [Bria iPhone Edition|https://itunes.apple.com/en/app/bria-voip-sip-phone-video/id373968636?mt=8]—even if the SDP message is bigger—it does not happen. I did not find a difference in Wireshark (same TLS version, same cipher suite, no renegotiation around). To double-check we really have an Asterisk issue here, I created the attached debug-patch (tlsBigSDPdebug.patch): In the above cases, SSL_read returns SSL_ERROR_WANT_READ. This is allowed by the OpenSSL API at any time. Therefore, we have an Asterisk issue.

By: Michael Kuron (mkuron) 2014-06-27 03:34:45.792-0500

I've used the tlsBigSDP.patch for a few days now on my Asterisk 1.8.28.2 and it does seem to resolve the issue with my Snom phones and the Media5Phone iPhone app.

By: Patrick Laimbock (laimbock) 2014-07-29 09:34:31.344-0500

I have used the tlsBigSDP.patch on Asterisk 11.10.2 with TLS/SRTP enforced on many hour+ long calls and I no longer see the issue in CSipSimple and both CSipSimple and Bria (on Android & iPhone) work fine. Kudos to Alexander Traud for finding the fix!

Isn't it time tlsBigSDP.patch went up for review for inclusion in Asterisk 1.8 and 11?

By: Matt Jordan (mjordan) 2014-07-29 12:31:08.889-0500

It did go up for review:

https://reviewboard.asterisk.org/r/3653/

Unfortunately, this patch does not fix the root cause of the problem. As mentioned on that review, there is an appropriate way to fix this that would fix it for good, instead of merely making the problem highly unlikely to occur.

It would be great if a patch was put together that fixes the root cause of the problem as recommended on that code review.

By: Elazar Broad (ebroad) 2014-07-31 01:15:31.131-0500

Hi All,
It's been a while. I have run into this same issue and attached a patch(tcptls_poll.diff) against trunk which starts the work of replacing sip_tls_read/write() and resolves the issue(see the discussion on the previous reviewboard link). My only concern is the while loop which handles the EAGAIN error has the potential to block infinitely. This patch was tested with CSipSimple utilizing TLS(with full SIP headers, multiple codecs and SRTP enabled) and TCP.

Thanks,
Elazar

By: Elazar Broad (ebroad) 2014-07-31 11:50:24.326-0500

This version removes the separate while loop for the read and instead continues the main while loop which already has the timeout implemented.

By: Elazar Broad (ebroad) 2014-08-05 21:23:43.345-0500

ReviewBoard Link: https://reviewboard.asterisk.org/r/3882/