[sip-comm-dev] corrections to SIP IM


#1

Hi all,

Here are some corrections to the SIP IM OpSet. This corrections fix some major bugs with the implementation and correct it to fit the sc api requirements.
It is now (really) ready for use and for tests :).

ben

OpSetBasicIM1-1.txt (11.1 KB)


#2

Hi Benoit,

I've commited your work in the CVS with no modification. I've also commited your test cases, but did not activate them yet. I must say that I'm really impressed by the quality of your code. Congratulations, and keep it up!

Martin

Benoit Pradelle wrote:

···

Hi all,

Here are some corrections to the SIP IM OpSet. This corrections fix some major bugs with the implementation and correct it to fit the sc api requirements.
It is now (really) ready for use and for tests :).
ben

------------------------------------------------------------------------

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#3

Thank you Martin !

Martin Andr� a �crit :

···

Hi Benoit,

I've commited your work in the CVS with no modification. I've also commited your test cases, but did not activate them yet. I must say that I'm really impressed by the quality of your code. Congratulations, and keep it up!

Martin

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#4

Hello guys,

I've only now found the time to review the changes in the test case. In order to save time I've committed them myself but am sharing my comments just the same.

SipSlickFixture:

* Line 9: This is a minor one, but since I am at it:

+import java.util.Iterator;
+import java.util.Map;
+import java.util.Vector;

SC conventions state that we use package imports rather than explicit ones.

* Line 194:

clearProviderList() - added javadocs.

* Line 248 and below: No need to first extract contacts and groups in a vector and then loop over the vector to remove them. I've remove the second loop and remove them in the first one.

TestOperationSetBasicInztantMessaging.java

* Line 1: Added license statement

* Lines 180 and 189:

     catch (OperationFailedException ex1)
     {
         // the contact already exist its OK
     }

It would indeed be OK if that was the reason. Otherwise we need to rethrow the exception.

And I guess that's all :).

Cheers
Emil

Martin Andr� wrote:

···

Hi Benoit,

I've commited your work in the CVS with no modification. I've also commited your test cases, but did not activate them yet. I must say that I'm really impressed by the quality of your code. Congratulations, and keep it up!

Martin

Benoit Pradelle wrote:

Hi all,

Here are some corrections to the SIP IM OpSet. This corrections fix some major bugs with the implementation and correct it to fit the sc api requirements.
It is now (really) ready for use and for tests :).
ben

------------------------------------------------------------------------

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#5

Hello Ben,

I'll second Martin: very nice and complete code. You've been thinking of many of the corner cases! Very good work!

I do have some minor suggestions though:

* Line 578:
if (evt.getNewState() == RegistrationState.REGISTERED)
{
     ...
     sipProvider.registerMethodProcessor(Request.MESSAGE,
                   new SipMessageListener());
}

Is there any particular reason why you register your method processor in the registration listener? This way your SipMessageListener would get re-registered every time we go off and then back online. Is this really necessary?

Oh and btw, when splitting parameter lists over multiple lines, the commas that get caught right in the middle of two lines should go to the new line instead remaining last on the previous one. This makes it easier to distinguish between new params, string concatenation and other operators. In other words, in this case you'd have:
     sipProvider.registerMethodProcessor(Request.MESSAGE
                   , new SipMessageListener());

* Line 641:
     public void processTimeout(TimeoutEvent timeoutEvent)
     {
         /** @todo implement a retransmit ?? */
     }

No a retransmit won't be necessary. jain-sip is handling this for us. Firing a MessageDeliveryFailedEvent event instead seems like a good idea though.

* Lines 661:
                   content = new String(
                     requestEvent.getRequest().getRawContent(),
                     requestEvent.getRequest().getContentEncoding()
                     .getEncoding());
and 740:
                 content = new String(
                     req.getRawContent(),
                     req.getContentEncoding()
                     .getEncoding());

Oh, nice! Personally i would have forgotten to take the encoding into account! And you are also handling possible exceptions in case the encoding causes trouble. Very good!

It may be a good idea to log the exception though in case people (developers) would like to know what the exact problem was. You do so in the second case but even there you are only logging a message. Passing the ex instance to the log method would be a good idea so that the stack trace could also be saved in the log files.

* Line 696:
     Response ack = sipProvider.getMessageFactory()
         .createResponse(Response.OK, requestEvent.getRequest());

We've been discussing this off-list but I'll add a reminder in this letter as well. The ack name may be confusing to some people and a careless observer (like me :wink: ) may take it for an ACK request. Wouldn't it be better to simply call it ok?

* Line 703:
     catch (ParseException ex)
     {
         logger.error("failed to build the response");
     }
     catch (SipException exc)
     {
         logger.error("failed to send the response : "
                      + exc.getMessage());
     }
     catch (InvalidArgumentException exc1)
     {
         logger.debug("Invalid argument for createResponse : "
                      + exc1.getMessage());
     }

Same thing here. Logging the exception message is nice (that's what you are doing in cath clauses 2 and 3) but it might not be enough in some cases. It would be better to also add the exception as a second param so that we could have the stack trace in the logs.

* Line 788:

     Integer key = new Integer(to.hashCode() + (int) seqNum);

(hashCode + seqNum) is not really guaranteed to be unique so I guess one could argue that it's kind of wrong to use it for a key. What I mean is that an object with hashcode "X" and seqnum "Y" would produce the same key as an object with a hashcode "X+a" and seqnum "Y-a". I guess I'd suggest using strings as keys instead. This would give you

      String key = Integer.toString(to.hashCode())
                 + Long.toString(seqNum);

* Line 790:
     if (key == null) {
         // should never happen
         ....
     }

I guess "will" fits better here than "should" :). You have just instantiated the key object. There is absolutely no way it could be null. If anything goes wrong during the instantiation, then it would be an exception ( but in this case you won't be reaching the if statement either). If you feel there's a chance an exception might occur (I personally don't see a risk) then you should do your error handling in a try/catch clause around the instantiation.

Several lines below, you have this:
     Message newMessage = (Message) sentMsg.get(key);

     if (newMessage == null) {
         // should never happen
         ...

and here it's kind of justified (e.g. someone might have mangled your sentMsg table since you sent your request) so you could keep it there :).

* Line 835: This time it's me. I saw you retrieving the reason phrase from the error response and was wondering why you weren't handing it along to the MessageDeliveryFailedEvent ... and the reason, of course, was that none of its existing constructors would take a reasonPhrase param. I've modified it so you could now pass the reason string to the event :slight_smile:

* Line 877:
     sentMsg.remove(key);
     sentMsg.put(new Integer(key.intValue() + 1), newMessage);

The put() method automatically replaces any previous values so I guess you don't need the remove.

* Line 898:
     try {
         responseEvent.getClientTransaction().terminate();
     } catch (ObjectInUseException e) {
         // should never happer (we don't user Dialogs)
         logger.debug("transaction in use while trying to close it");
     }

You don't have to end the transaction yourself since at this point (once a final response has been received) the stack has already done it for you.

* Line 924: It was nice you thought about the case where the user might have entered a contact without the domain suffix!

Guess, that's all!

Thanks for all your efforts Ben!

Emil

Benoit Pradelle wrote:

···

Thank you Martin !

Martin Andr� a �crit :

Hi Benoit,

I've commited your work in the CVS with no modification. I've also commited your test cases, but did not activate them yet. I must say that I'm really impressed by the quality of your code. Congratulations, and keep it up!

Martin

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#6

Hi Emil,

Here are the corrections about what you suggested.
Everything is done except this :

* Line 877:
    sentMsg.remove(key);
    sentMsg.put(new Integer(key.intValue() + 1), newMessage);

The put() method automatically replaces any previous values so I guess you don't need the remove.

because the new key value is different from the old one so the remove is really needed.

Can someone please commit this patch on the CVS ? the message can be :
minor fixes on the basicIM opset

Cheers,
Ben

OpSetBasicIMCorrections.txt (10.9 KB)


#7

Hi again Ben,

I've just committed your last changes (and the modifications that we committed off-list).

Can you please test when you find the time and let me know if it all works as expected!

I've also just noticed that I haven't turn your IM tests on. Can you please try those too and if they work we'll enable them so that the cruisecontrol machine would run them on nightly builds.

Cheers
Emil

Benoit Pradelle wrote:

···

Hi Emil,

Here are the corrections about what you suggested.
Everything is done except this :

* Line 877:
    sentMsg.remove(key);
    sentMsg.put(new Integer(key.intValue() + 1), newMessage);

The put() method automatically replaces any previous values so I guess you don't need the remove.

because the new key value is different from the old one so the remove is really needed.

Can someone please commit this patch on the CVS ? the message can be :
minor fixes on the basicIM opset

Cheers,
Ben

------------------------------------------------------------------------

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#8

Hi Emil,

I've tested the modifications and everything seems to be fine.
But there still are two bugs :

- When we receive a message from an unknown contact, a volatile contact is created to represent him. I call createVolatileContact only one time but the contact is created twice in the list. It may be a problem in the presence OpSet.

- During my tests, everytime I need to authenticate a message, the final (authenticated) message is send twice. Here is a sample capture I've made :

No. Time Source Destination Protocol Info
      1 0.000000 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
      2 0.062686 213.192.59.75 192.168.0.2 SIP Status: 407 Proxy Authentication Required
      3 0.132335 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
      4 0.239345 213.192.59.75 192.168.0.2 SIP Request: MESSAGE sip:zerealneo2@192.168.0.2:5060
      5 0.423675 192.168.0.2 213.192.59.75 SIP Status: 200 OK
      6 0.492300 213.192.59.75 192.168.0.2 SIP Status: 200 OK
      7 0.634127 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
      8 0.703458 213.192.59.75 192.168.0.2 SIP Status: 200 OK

in this capture the packet 4 and 7 are the same even if we received the OK corresponding to the packet 4. (I'm sending a message from zerealneo to zerealneo2, both are located in 192.168.0.2).

I don't understand why this occurs, perhaps a bug in handleChallenge in the securityManager ? As the transport doesn't seem to associate the first OK with the right transaction, perhaps the transaction building is incorrect ?

This bug may involve a failure during the test (as two consecutives tests are done, the second OK here (packet 8) may be received during the second test and as it's not expected, the test fail). So it's probably not a good idea to activate this testcase until this bug is corrected.

Cheers,
Ben

Emil Ivov a �crit :

···

Hi again Ben,

I've just committed your last changes (and the modifications that we committed off-list).

Can you please test when you find the time and let me know if it all works as expected!

I've also just noticed that I haven't turn your IM tests on. Can you please try those too and if they work we'll enable them so that the cruisecontrol machine would run them on nightly builds.

Cheers
Emil

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#9

Hi all,

Benoit Pradelle a �crit :

Hi Emil,

I've tested the modifications and everything seems to be fine.
But there still are two bugs :

- When we receive a message from an unknown contact, a volatile contact is created to represent him. I call createVolatileContact only one time but the contact is created twice in the list. It may be a problem in the presence OpSet.

This bug is fixed now.

- During my tests, everytime I need to authenticate a message, the final (authenticated) message is send twice. Here is a sample capture I've made :

No. Time Source Destination Protocol Info
     1 0.000000 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
     2 0.062686 213.192.59.75 192.168.0.2 SIP Status: 407 Proxy Authentication Required
     3 0.132335 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
     4 0.239345 213.192.59.75 192.168.0.2 SIP Request: MESSAGE sip:zerealneo2@192.168.0.2:5060
     5 0.423675 192.168.0.2 213.192.59.75 SIP Status: 200 OK
     6 0.492300 213.192.59.75 192.168.0.2 SIP Status: 200 OK
     7 0.634127 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
     8 0.703458 213.192.59.75 192.168.0.2 SIP Status: 200 OK

in this capture the packet 4 and 7 are the same even if we received the OK corresponding to the packet 4. (I'm sending a message from zerealneo to zerealneo2, both are located in 192.168.0.2).

I don't understand why this occurs, perhaps a bug in handleChallenge in the securityManager ? As the transport doesn't seem to associate the first OK with the right transaction, perhaps the transaction building is incorrect ?

This bug may involve a failure during the test (as two consecutives tests are done, the second OK here (packet 8) may be received during the second test and as it's not expected, the test fail). So it's probably not a good idea to activate this testcase until this bug is corrected.

Cheers,
Ben

Emil Ivov a �crit :

Hi again Ben,

I've just committed your last changes (and the modifications that we committed off-list).

Can you please test when you find the time and let me know if it all works as expected!

I've also just noticed that I haven't turn your IM tests on. Can you please try those too and if they work we'll enable them so that the cruisecontrol machine would run them on nightly builds.

Cheers
Emil

Cheers,
Ben

···

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#10

Hi all,

After a very intense and deep exploration of the logs and a lot of traffic I got an explanation for the bug of the "resend MESSAGE".

My conclusion is very simple : it takes more than the timeout value for jain sip and SC to handle a SIP packet. In our case the timeout is 500 ms and I've seen in the logs that in some cases, the packet treatment (wait the packet, receiving it from the operating system, converting it into a SIPMessage, transfering it to SC and treat the message in SC takes more than 500 ms).

It may appear really unbelievable that we need more than 500ms to treat a packet (at least over my decent computer) but it's the case and if you don't believe me, take a look to this scenario that I observed in wireshark:

We send a REQUEST at time 0
We receive a 401 / Unauthorized response at time 100 ms.
We resend the original REQUEST at time 600 ms. (timeout + some lag)
We send the new REQUEST with the authorization stuff at time 650 ms.
We receive a 401 / Unauthorized response at time 670 ms.
We receive an 200 / OK response at time 750 ms.

As you can see jain sip as seen the first response and has transmitted it to SC but as transactions seems to be physically closed AFTER all the SC treatments, a timeout occurs even if the challeng is being solved.

It's exactly what happened with the different cases I've seen with the MESSAGE requests : the OK response was received but not totally treated when a timeout occurs.

- During my tests, everytime I need to authenticate a message, the final (authenticated) message is send twice. Here is a sample capture I've made :

No. Time Source Destination Protocol Info
     1 0.000000 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
     2 0.062686 213.192.59.75 192.168.0.2 SIP Status: 407 Proxy Authentication Required
     3 0.132335 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
     4 0.239345 213.192.59.75 192.168.0.2 SIP Request: MESSAGE sip:zerealneo2@192.168.0.2:5060
     5 0.423675 192.168.0.2 213.192.59.75 SIP Status: 200 OK
     6 0.492300 213.192.59.75 192.168.0.2 SIP Status: 200 OK
     7 0.634127 192.168.0.2 213.192.59.75 SIP Request: MESSAGE sip:zerealneo2@iptel.org
     8 0.703458 213.192.59.75 192.168.0.2 SIP Status: 200 OK

This also mean that we should be careful with this specific situation when we are designing the test cases to be sure that this behavior doesn't disturb the test case.

here are two interesting points about the jain-sip logs :
- the log names are bugged : doesn't it come from the lines 522 - 523 in ProtocolProviderServiceSipImpl which should be:
            NSPNAME_DEBUG_LOG = NSPVALUE_DEBUG_LOG;
            NSPNAME_SERVER_LOG = NSPVALUE_SERVER_LOG;
isn't it ?

- if you are confronted to the nightmare of searching something in these logs, try this shell command before opening the logs :
awk '{ gsub("]]0", "]]\n0", $0); gsub("]]1", "]]\n1", $0); gsub("]]2", "]]\n2", $0); print $0 }' gov.nist.javax.sip.DEBUG_LOG > jainlog
(by replacing gov.nist.javax.sip.DEBUG_LOG by the original log name and jainlog by the new log you will create).

Cheers,
Ben

···

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#11

Hi all,

I'm back with some new revelations about the "resent packet mystery".
Yesterday I've speak with Sherlock (aka Emil) and he told me "Watson (it's me), your first conclusions about the mystery of the resent packet are strange, I cannot believe that SER takes more than 500 ms to treat a packet. Find what's wrong".

So I've continued my investigations. I launched SC using a profile (profiler4j) to see where do we lost most of the time and as I supposed, we loose an huge amount of time in jain-sip just after the reception of an UDP packet. Exactly in the method parseMessage (the profiler say that it belongs to StringParser but in the source code I got there isn't such a method so perhaps it is inlined or my source code is not the one used in SC). Anyway, we are spending more time in handling 8 packets than in initializing the gui !!!

So for the moment, I don't know why this method takes so much time to execute (as I wasn't able to find it in the source code) but I'm now sure of my hypothesis and perhaps something can be optimised here.

Note that if one day you need to use a profiler with SC, don't waste time in testing every java profiler from the Net, none of them works correctly, use profiler4j.

Ben

···

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#12

Hi Benoit,

Very funny story :slight_smile: . I wish you good luck in your profiling endeavors, and am happy to learn this advice about profiler4j. It might be useful for me later.

Thanks !

Jean

Benoit Pradelle wrote:

···

Hi all,

I'm back with some new revelations about the "resent packet mystery".
Yesterday I've speak with Sherlock (aka Emil) and he told me "Watson (it's me), your first conclusions about the mystery of the resent packet are strange, I cannot believe that SER takes more than 500 ms to treat a packet. Find what's wrong".

So I've continued my investigations. I launched SC using a profile (profiler4j) to see where do we lost most of the time and as I supposed, we loose an huge amount of time in jain-sip just after the reception of an UDP packet. Exactly in the method parseMessage (the profiler say that it belongs to StringParser but in the source code I got there isn't such a method so perhaps it is inlined or my source code is not the one used in SC). Anyway, we are spending more time in handling 8 packets than in initializing the gui !!!

So for the moment, I don't know why this method takes so much time to execute (as I wasn't able to find it in the source code) but I'm now sure of my hypothesis and perhaps something can be optimised here.

Note that if one day you need to use a profiler with SC, don't waste time in testing every java profiler from the Net, none of them works correctly, use profiler4j.

Ben

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net


#13

Hi Jean,

Jean Lorchat a �crit :

Hi Benoit,

Very funny story :slight_smile: . I wish you good luck in your profiling endeavors, and am happy to learn this advice about profiler4j. It might be useful for me later.

Thanks !

Jean

Thank you jean :slight_smile: I'd like to precise something about the profilers. In fact I'm a little pessimistic here because I needed a profiler able to measure the amount of time spent in each method and profiler4j is the only one which work and which can do this. But if you're more interested in the memory profiling, Damian achieve to make jmemprof work and I successfully ran jmp.

Cheers,
Ben

···

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@sip-communicator.dev.java.net
For additional commands, e-mail: dev-help@sip-communicator.dev.java.net