How to use SIP stack with NIO TCP properly?

[lhodovsk]

I was trying to use the SIP stack (latest version) with the NIO TCP message channel. I have set the property "gov.nist.javax.sip.MESSAGE_PROCESSOR_FACTORY" to use the NioMessageProcessorFactory class,
Anyway, then I experienced strange behavior with even one outgoing TCP SIP call. It looked like the received messages were not parsed correctly. E.g. parser for first received OPTIONS from called party complained there is a Content-Length header with value of 133, although there was no any such Header in recieved OPTIONS. Looking into logs I found that 200 OK received for INVITE and also later for UPDATE sent by my application contained the content with the length of 133. Maybe I am missing some configuration, but I have not found any relevant example.

It was working fine with the default MessageProcessorFactory implementation.

A bit of my logs:

1. 200 OK for initial INVITE

21.09.2017 15:25:10,646 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Got something on nioTcpMessageChannel gov.nist.javax.sip.stack.NioTcpMessageChannel@593fd0f1 socket java.nio.channels.SocketChannel[connected local=/10.17.53.11:60258 remote=/10.17.53.43:5060]
21.09.2017 15:25:10,646 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug NioTcpMessageChannel::readChannel
21.09.2017 15:25:10,647 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Read 617 from socketChannel
21.09.2017 15:25:10,648 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Received CRLF
21.09.2017 15:25:10,648 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Content Length parsed is 133
21.09.2017 15:25:10,656 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Next thread id=0
21.09.2017 15:25:10,661 +02:00 INFO LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logInfo serving msg on call id [email protected]
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Unparsed message before parser is:
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug gov.nist.javax.sip.parser.NioPipelineParser$UnparsedMessage@1d40d399
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug SIP/2.0 200 OK
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Via: SIP/2.0/TCP 10.17.53.11:5060; branch=z9hG4bK-363332-193112260b0756b39fa8081e9b4f3d46
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Call-ID: [email protected]
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug CSeq: 1 INVITE
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug From: sip:[email protected];tag=-712247862
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug To: sip:[email protected];tag=5A36DCFD-F35B-4E67-A840-E87B6362FC27
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Contact: sip:[email protected]:5060
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Date: Thu, 21 Sep 2017 13:25:10 GMT
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug User-Agent: Recorder.SDP/400.00.001 libTPP/3.33.006
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Content-Type: application/sdp
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Content-Length: 133
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug
21.09.2017 15:25:10,661 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug ;
21.09.2017 15:25:10,663 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransactionImpl@8bbf3f41
21.09.2017 15:25:10,664 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug acquireSem() returning : true

2. received 200 OK for UPDATE message

21.09.2017 15:25:10,857 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Got something on nioTcpMessageChannel gov.nist.javax.sip.stack.NioTcpMessageChannel@593fd0f1 socket java.nio.channels.SocketChannel[connected local=/10.17.53.11:60258 remote=/10.17.53.43:5060]
21.09.2017 15:25:10,857 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug NioTcpMessageChannel::readChannel
21.09.2017 15:25:10,857 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Read 617 from socketChannel
21.09.2017 15:25:10,858 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Received CRLF
21.09.2017 15:25:10,858 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Content Length parsed is 133
21.09.2017 15:25:10,858 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Next thread id=0
21.09.2017 15:25:10,859 +02:00 INFO LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logInfo serving msg on call id [email protected]
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Unparsed message before parser is:
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug gov.nist.javax.sip.parser.NioPipelineParser$UnparsedMessage@69d0b343
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug SIP/2.0 200 OK
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Via: SIP/2.0/TCP 10.17.53.11:5060; branch=z9hG4bK-363332-02eac2f55df871532ebb2a66ac9c1e41
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Call-ID: [email protected]
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug CSeq: 2 UPDATE
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug From: sip:[email protected];tag=-712247862
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug To: sip:[email protected];tag=5A36DCFD-F35B-4E67-A840-E87B6362FC27
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Contact: sip:[email protected]:5060
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Date: Thu, 21 Sep 2017 13:25:10 GMT
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug User-Agent: Recorder.SDP/400.00.001 libTPP/3.33.006
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Content-Type: application/sdp
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug Content-Length: 133
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug
21.09.2017 15:25:10,860 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug ;
21.09.2017 15:25:10,863 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug acquireSem [[[[gov.nist.javax.sip.stack.SIPClientTransactionImpl@cd0baa51
21.09.2017 15:25:10,863 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T46 B2BUA/pool-AffinityJAIN-thread-1/SipStackLogger.logDebug acquireSem() returning : true

3. received OPTIONS with non-existing, but reported Content-Length

21.09.2017 15:25:20,996 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug We got selkey sun.nio.ch.SelectionKeyImpl@388977e7
21.09.2017 15:25:20,996 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Read sun.nio.ch.SelectionKeyImpl@388977e7
21.09.2017 15:25:20,996 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Got something on nioTcpMessageChannel gov.nist.javax.sip.stack.NioTcpMessageChannel@593fd0f1 socket java.nio.channels.SocketChannel[connected local=/10.17.53.11:60258 remote=/10.17.53.43:5060]
21.09.2017 15:25:20,996 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug NioTcpMessageChannel::readChannel
21.09.2017 15:25:20,996 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Read 426 from socketChannel
21.09.2017 15:25:20,997 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Received CRLF
21.09.2017 15:25:20,997 +02:00 DEBUG LX-S-MED-GSP-01 P17488/T27 B2BUA/NioSelector-TCP-10.17.53.11/5060/SipStackLogger.logDebug Content Length parsed is 133

4. later there was an exception reported:

21.09.2017 15:25:22,011 +02:00 INFO LX-S-MED-GSP-01 P17488/T25 B2BUA/EventScannerThread/SipEventDistributor.processRequest processRequest RequestEventExt[remoteIpAddress=10.17.53.43,remotePort=5060,m_request=OPTIONS sip:[email protected] SIP/2.0, Via: SIP/2.0/TCP 10.17.53.11:5060branch=z9hG4bK-363332-193112260b0756b39fa8081e9b4f3d46received=10.17.53.43rport=5060, From: sip:[email protected]=5A36DCFD-F35B-4E67-A840-E87B6362FC27, To: sip:[email protected]=-712247862, Call-ID: [email protected], CSeq: 0 OPTIONS, Date: Thu, 21 Sep 2017 13:25:21 GMT, User-Agent: Recorder.SDP/400.00.001 libTPP/3.33.006, Content-Length: 133, , OPTIONS sip:[email protected] SIP/2.0, Via: SIP/2.0/TCP 10.17.53.11:5060 branch=z9hG4bK-363332-193112260b0756b39fa8081e9b4,m_transaction=gov.nist.javax.sip.stack.SIPServerTransactionImpl@8bbf3f41,m_dialog=gov.nist.javax.sip.stack.SIPDialog@32c2f2b2]
21.09.2017 15:25:22,011 +02:00 ERROR LX-S-MED-GSP-01 P17488/T25 B2BUA/EventScannerThread/SipStackLogger.logException If there is a message body the media type MUST be given by the Content-Type header field.
21.09.2017 15:25:22,011 +02:00 ERROR LX-S-MED-GSP-01 P17488/T25 B2BUA/EventScannerThread/SipStackLogger.logException java.lang.IllegalArgumentException: If there is a message body the media type MUST be given by the Content-Type header field.

[pimenas]

I'm having a problem with NIO TCP as well, while it was working on version 1.2.307 . The symptoms are that requests that are destined to tcp destinations, are never being sent. Tcp connection is made, but the content is never sent. Reproduction can of this issue can easily be made using the following code:

SipApplicationSession appSession = servletSipFactory.createApplicationSession();
SipServletRequest req = servletSipFactory.createRequest(appSession, "OPTIONS", "sip:sip1.example.com:5080;transport=tcp", "sip:sip2.example.com:5080;transport=tcp");
URI serverUri = servletSipFactory.createURI("sip:sip2.example.com:5080;transport=tcp");
req.pushRoute((SipURI) serverUri);
req.send();

After a while the servlet's doErrorResponse will be called with status 408, and reason phrase 'Request timeout'

The exact same code is working if I replace jain-sip-ri jar with the 1.2.307 version.

[gsaslis]

@pimenas thanks for sharing your finds.

This does sound like a regression... Have you been able to track the code that might be causing the issue? Perhaps if you have, you would like to have a go at contributing a fix for this one? ;)

Let me know and I can assist along the way, etc.

[pimenas]

@gsaslis I'll try to find a few hours to spend on this during the next days!

[gsaslis]

@pimenas awesome stuff!

Again, plz feel free to reach out if you need any help.
Our Open Source Playbook might be of help too.

[pimenas]

Well, I started with writing a small test in groovy which only tried to send an options request to a remote sip server using NIO TCP, and made a 'git bisect'. Here's the log from bisect:

ocalhost:jain-sip pimenas$ git bisect log
git bisect start
# bad: [1b3bb7faf676e4564c103fc852278ccd6e686544] Merge pull request #173 from RestComm/feature/improve_readme
git bisect bad 1b3bb7faf676e4564c103fc852278ccd6e686544
# good: [4b8f13dbabba871b4b51626ec97bb1ec2b21a3ca] New release candidate
git bisect good 4b8f13dbabba871b4b51626ec97bb1ec2b21a3ca
# good: [31c18b45fdb0a5980dddd83165635bdc42e3b40a] Merge pull request #146 from RestComm/revert-141-issue/101-upgrade-to-log4j2
git bisect good 31c18b45fdb0a5980dddd83165635bdc42e3b40a
# bad: [aff2eb22f0d5af240c9c2f6382d8b189d064c82e] Fix for issue #151 https://github.com/RestComm/jain-sip/issues/151
git bisect bad aff2eb22f0d5af240c9c2f6382d8b189d064c82e
# bad: [53cdceaa3f0269282c1438ffa556f04d06e17870] fixed compilation issue after bad merge
git bisect bad 53cdceaa3f0269282c1438ffa556f04d06e17870
# good: [a92347ebea65170bfd647abdfa8a83a5ef8c0abb] if nothing else to write, switch to read mode
git bisect good a92347ebea65170bfd647abdfa8a83a5ef8c0abb
# bad: [115a59fe36ea4825c128ed95b305280a81a52799] fixed compilation issue after bad merge
git bisect bad 115a59fe36ea4825c128ed95b305280a81a52799
# good: [10aad05f9b9d85080d3fc93ae3b66d9930a71790] fixed compilation issue after bad merge
git bisect good 10aad05f9b9d85080d3fc93ae3b66d9930a71790
# good: [42ff9bc55d8ffcae0bc77fb58c7bdb77394371f1] fixed compilation issue after bad merge
git bisect good 42ff9bc55d8ffcae0bc77fb58c7bdb77394371f1
# good: [390dfe886a390ec14879f4df1434237f63ac5f38] fixes https://github.com/RestComm/jain-sip/issues/145
git bisect good 390dfe886a390ec14879f4df1434237f63ac5f38
# good: [390dfe886a390ec14879f4df1434237f63ac5f38] fixes https://github.com/RestComm/jain-sip/issues/145
git bisect good 390dfe886a390ec14879f4df1434237f63ac5f38
# bad: [365fb3eb4948b3ef524738105d13399bc28ef819] fixed fianlly condition on when to rmv semaphore
git bisect bad 365fb3eb4948b3ef524738105d13399bc28ef819
# first bad commit: [365fb3eb4948b3ef524738105d13399bc28ef819] fixed fianlly condition on when to rmv semaphore

So NIO TCP stops working at commit 365fb3e, which is this change:

git show 365fb3eb4948b3ef524738105d13399bc28ef819
commit 365fb3eb4948b3ef524738105d13399bc28ef819
Author: Jaime Casero <[email protected]>
Date:   Tue Mar 28 15:12:41 2017 +0200

    fixed fianlly condition on when to rmv semaphore

diff --git a/src/gov/nist/javax/sip/stack/NIOHandler.java b/src/gov/nist/javax/sip/stack/NIOHandler.java
index 37ad1ae..9a63ac7 100644
--- a/src/gov/nist/javax/sip/stack/NIOHandler.java
+++ b/src/gov/nist/javax/sip/stack/NIOHandler.java
@@ -366,7 +366,7 @@ public class NIOHandler {
             }
         } finally {
             if (entered) {
-                if (connected)
+                if (!connected)
                 {
                     // new connection is bad.
                     // remove from our table the socket and its semaphore

That "connected" variable never seems to be set at something other rather than false, so the socket is always removed. I believe the fix is easy, just set "connected" to true somewhere appropriately, I'll make a pull request later this evening.

[pimenas]

After reading more carefully the first comments, I guess @lhodovsk is experiencing a different issue with NIO TCP than the one I'm trying to fix...

[gsaslis]

@pimenas i guess your last comment means #176 is still WIP / currently invalid?

[pimenas]

@gsaslis my comment means that #176 is a fix to my issue which is described in my first comment in this issue, which is different than the one that @lhodovsk reported in the first comment. In any case, I think it should be merged in the master because it fixes outgoing tcp connections.

To tell you the truth, after reading the first comment, I'm not sure what is the issue that @lhodovsk tries to report here, otherwise I would have a look at this also.

Maybe I should create a new issue for my fix, but it seems to me a little overkill for just a one-line-of-code fix, so I think I'll just update the pull request description.

[gsaslis]

thanks for the clarifications @pimenas !

@lhodovsk any further input from your side?