[SR-Users] Msilo not delivering message (status 408)

Thu Jul 17 23:46:58 CEST 2014

Well I've been experimenting with this for hours and still no joy
 :(  Hair pulling continues

Here's what I did to help debug. I updated to 4.2 and I started using the
default TCP listener on 5060 and have turned off the TLS listener to make
debugging easier.
I have also tried using the routing config from here
<http://telephonynetworks.blogspot.pt/2012/08/configuracion-de-kamailio-33-con-nat.html>
but
I get the exact same results as with the routing posted above, which tends
to rule out any config issues (I think).

Here's what I found so far.

If I don't set the msilo outbound proxy like Daniel suggested, I get the
dreaded "no socket found" error I mentioned earlier.

If I do set the proxy, the offline message does get delivered as expected.
The problem is that once I send a new message to an offline user, the
caller doesn't receive the "user whatever is offline" message, but simply a
202.
Then I look in msilo DB and suddenly I have 7k messages and growing and
have to shut down kamailio and clean the db.

Example to make understanding this weird behavior easier. Msilo outbound
proxy set:

1010 sends msg "testing 123" to 1000 (offline). Msilo stores the msg
correctly, although 1010 never does receive the "***User 1000 is offline!"
message, only a 202 I see in ngrep.
I then look in the msilo db and confirm the "testing 123" msg is there. But
right after there is another message stored in msilo, which is what should
have been sent to 1000 instead of being stored in the silo.

sip:registrar at my.domain.comsip:1010 at my.domain.com1010my.domain.com2014-07-17
14:11:00*** User 1000 is offline!
And then registrar storing a message for registrar saying 1010 is offline
(which is obviously wrong since 1010 just sent the msg)

sip:registrar at my.domain.comsip:registrar at my.domain.comregistrarmy.domain.com
2014-07-17 14:11:00*** User 1010 is offline!

And then it gets simply crazy with over 7K repeating messages in the silo
saying the user registrar is offline.

sip:registrar at my.domain.comsip:registrar at my.domain.comregistrarmy.domain.com
2014-07-17 14:11:00*** User registrar is offline!

To top it all off I see this in the sip trace

What's puzzling me is this: 79.my.server.IP1:58487 -> 79.my.server.IP1:5060

Why does kamailio send to itself from port 58487 to 5060 and not from 5060
to the UAC's public IP?

Sorry to dump so much info here but I'm hoping to resolve this before I go
nuts.

Daniel, when you have the time can you take a look please?

Thanks,
Peter

T 2014/07/17 21:10:30.383043 85.xx.xx.xx:50235 -> 79.my.server.IP1:5060 [AP]
MESSAGE sip:1000 at my.domain.com SIP/2.0.
v: SIP/2.0/TCP 192.168.1.4:50235
;rport;branch=z9hG4bKPjCYikazjsY44q1jqMtDzapRCfqofgZ.3O;alias.
Max-Forwards: 70.
f: <sip:1010 at my.domain.com>;tag=s.HDD1ArN1dDgnwxgeWWK7meY98dkvrS.
t: <sip:1000 at my.domain.com>.
i: p8PAwoJ6ZLCy7ClSqe8sXD8FWMTU3LQ9.
CSeq: 64674 MESSAGE.
Accept: text/plain, application/im-iscomposing+xml.
User-Agent: PJSIP_m3-19/r2423.
Route: <sip:my.domain.com;transport=tcp;lr>.
c: text/plain.
l:    25.
.
msg from 1010 to 1000

T 2014/07/17 21:10:30.390095 *79.my.server.IP1:58487 ->
79.my.server.IP1:5060* [AP]
MESSAGE sip:1010 at my.domain.com SIP/2.0.
Via: SIP/2.0/TCP
79.my.server.IP1;branch=z9hG4bK17.50c7d2e1000000000000000000000000.0.
To: <sip:1010 at my.domain.com>.
From: <sip:registrar at my.domain.com
>;tag=416b6f80e891b334140ffeafcc1fa032-ecd9.
CSeq: 10 MESSAGE.
Call-ID: 6807412f0f15f619-29814 at 79.my.server.IP1.
Max-Forwards: 70.
Content-Length: 25.
User-Agent: kamailio (4.2.0-dev7 (x86_64/linux)).
Contact: registrar at my.domain.com;msilo=yes.
Content-Type: text/plain.
.
*** User 1000 is offline!

T 2014/07/17 21:10:30.390156 79.my.server.IP1:5060 -> 85.xx.xx.xx:50235 [AP]
SIP/2.0 202 ACCEPTED.
v: SIP/2.0/TCP 192.168.1.4:50235
;rport=50235;branch=z9hG4bKPjCYikazjsY44q1jqMtDzapRCfqofgZ.3O;alias;received=85.xx.xx.xx.
f: <sip:1010 at my.domain.com>;tag=s.HDD1ArN1dDgnwxgeWWK7meY98dkvrS.
t: <sip:1000 at my.domain.com>;tag=83a51ef5beb3f269619e74eb008b8b4e.7652.
i: p8PAwoJ6ZLCy7ClSqe8sXD8FWMTU3LQ9.
CSeq: 64674 MESSAGE.
Server: kamailio (4.2.0-dev7 (x86_64/linux)).
Content-Length: 0.
.

T 2014/07/17 21:10:30.390441 79.my.server.IP1:5060 -> 85.xx.xx.xx:50235 [AP]
MESSAGE sip:1010 at 85.xx.xx.xx:50235;transport=TCP SIP/2.0.
Via: SIP/2.0/TCP
79.my.server.IP1;branch=z9hG4bK17.f09631e651d35b19e10d44b11fe53d81.0;i=3.
Via: SIP/2.0/TCP
79.my.server.IP1;rport=58487;branch=z9hG4bK17.50c7d2e1000000000000000000000000.0.
To: <sip:1010 at my.domain.com>.
From: <sip:registrar at my.domain.com
>;tag=416b6f80e891b334140ffeafcc1fa032-ecd9.
CSeq: 10 MESSAGE.
Call-ID: 6807412f0f15f619-29814 at 79.my.server.IP1.
Max-Forwards: 69.
Content-Length: 25.
User-Agent: kamailio (4.2.0-dev7 (x86_64/linux)).
Contact: registrar at my.domain.com;msilo=yes.
Content-Type: text/plain.
.
*** User 1000 is offline!

T 2014/07/17 21:11:00.357394 79.my.server.IP1:58487 ->
79.my.server.IP1:5060 [AP]
MESSAGE sip:registrar at my.domain.com SIP/2.0.
Via: SIP/2.0/TCP
79.my.server.IP1;branch=z9hG4bK24f7.237c32d3000000000000000000000000.0.
To: <sip:registrar at my.domain.com>.
From: <sip:registrar at my.domain.com
>;tag=416b6f80e891b334140ffeafcc1fa032-a22d.
CSeq: 10 MESSAGE.
Call-ID: 6807412f0f15f618-29809 at 79.my.server.IP1.
Max-Forwards: 70.
Content-Length: 25.
User-Agent: kamailio (4.2.0-dev7 (x86_64/linux)).
Contact: registrar at my.domain.com;msilo=yes.
Content-Type: text/plain.
.
*** User 1010 is offline!

T 2014/07/17 21:11:00.358375 79.my.server.IP1:5060 ->
79.my.server.IP1:58487 [AP]
SIP/2.0 202 ACCEPTED.
Via: SIP/2.0/TCP
79.my.server.IP1;branch=z9hG4bK17.50c7d2e1000000000000000000000000.0;rport=58487.
To: <sip:1010 at my.domain.com>;tag=9916224dd8b1ec9235e0f958cedf67cc-fe6b.
From: <sip:registrar at my.domain.com
>;tag=416b6f80e891b334140ffeafcc1fa032-ecd9.
CSeq: 10 MESSAGE.
Call-ID: 6807412f0f15f619-29814 at 79.my.server.IP1.
Server: kamailio (4.2.0-dev7 (x86_64/linux)).
Content-Length: 0.
.

T 2014/07/17 21:11:00.359438 79.my.server.IP1:58487 ->
79.my.server.IP1:5060 [AP]
MESSAGE sip:registrar at my.domain.com SIP/2.0.
Via: SIP/2.0/TCP
79.my.server.IP1;branch=z9hG4bK810c.0eb84110000000000000000000000000.0.
To: <sip:registrar at my.domain.com>.
From: <sip:registrar at my.domain.com
>;tag=416b6f80e891b334140ffeafcc1fa032-2a02.
CSeq: 10 MESSAGE.
Call-ID: 6807412f0f15f618-29816 at 79.my.server.IP1.
Max-Forwards: 70.
Content-Length: 30.
User-Agent: kamailio (4.2.0-dev7 (x86_64/linux)).
Contact: registrar at my.domain.com;msilo=yes.
Content-Type: text/plain.
.
*** User registrar is offline!

T 2014/07/17 21:11:00.359495 79.my.server.IP1:5060 ->
79.my.server.IP1:58487 [AP]
SIP/2.0 202 ACCEPTED.
Via: SIP/2.0/TCP
79.my.server.IP1;branch=z9hG4bK24f7.237c32d3000000000000000000000000.0;rport=58487.
To: <sip:registrar at my.domain.com>;tag=83a51ef5beb3f269619e74eb008b8b4e.a9f2.
From: <sip:registrar at my.domain.com
>;tag=416b6f80e891b334140ffeafcc1fa032-a22d.
CSeq: 10 MESSAGE.
Call-ID: 6807412f0f15f618-29809 at 79.my.server.IP1.
Server: kamailio (4.2.0-dev7 (x86_64/linux)).
Content-Length: 0.
.

On Thu, Jul 17, 2014 at 3:35 PM, Peter Villeneuve <petervnv1 at gmail.com>
wrote:

> Thanks for helping out Hugh (and obviously Daniel)
>
> I have made some progress by adding the modparam ("msilo",
> "outbound_proxy", "sip:my.domain.com:5061;transport=tls").
> Now indeed the stored message gets delivered when a UAC registers.
>
> But I just noticed that it was also filling up msilo db with "user xxx is
> offline!" messages, instead of sending that msg to the initial UAC sending
> the msg.
> This likely means I'm doing something wrong with the routing, as it feels
> like it's in an endless loop. I think Daniel earlier suggested adding if(src_ip
> != myself) t_on_failure("FAIL_MESSAGE") to another poster that was having
> trouble with the exact same routing config, but I'm not sure exactly where
> to insert it.
>
> Can someone experienced with the routing syntax point out my - likely
> obvious - mistake?
>
> Cheers,
> Peter
>
>
> On Thu, Jul 17, 2014 at 3:11 PM, Waite, Hugh <hugh.waite at acision.com>
> wrote:
>
>>  Hi,
>>
>> We did have a working msilo implementation a while back, but we don’t use
>> it any more, so I can only look back at the config files (which are a lot
>> more complicated than yours).
>>
>>
>>
>> We added the a modparam *modparam("msilo", "outbound_proxy",
>> "sip:MY_REAL_IP:MY_SIP_PORT;transport=tcp")*
>>
>> which will make it arrive on the local machine on the given socket
>> (instead of localhost) to be processed, but that probably isn’t your
>> problem.
>>
>>
>>
>> Is it possible that Kamailio is trying to establish a new connection,
>> instead of reusing the existing connection to the client? That would be
>> visible as TCP SYNs in a trace and would cause a 408 after the timeout. We
>> are using a separate outbound enabled edge proxy so this isn’t a problem
>> for us.
>>
>>
>>
>> Regards,
>>
>> Hugh
>>
>>
>>
>>
>>
>> *From:* sr-users-bounces at lists.sip-router.org [mailto:
>> sr-users-bounces at lists.sip-router.org] *On Behalf Of *Peter Villeneuve
>> *Sent:* 17 July 2014 13:10
>> *To:* Daniel-Constantin Mierla; Kamailio (SER) - Users Mailing List
>> *Subject:* Re: [SR-Users] Msilo not delivering message (status 408)
>>
>>
>>
>> I guess no one really knows why it isn't working either.
>>
>> The only option I have left seems to be to try and update to the 4.2
>> nightly and hope that whatever's wrong is a bug with 4.1.4 and not a simple
>> mistake in my routing syntax or logic.
>>
>>
>>
>> Daniel, is 4.2 nightly debian package stable enough for a production
>> system? Would you recommend I upgrade?
>>
>>
>>
>> Thanks
>>
>>
>>
>> On Wed, Jul 16, 2014 at 9:37 PM, Peter Villeneuve <petervnv1 at gmail.com>
>> wrote:
>>
>> Can anyone help please? I was supposed to have this server up and running
>> hours ago and I can't think of anything to do next to help debug this.
>>
>>
>>
>> Thanks
>>
>>
>>
>> On Wed, Jul 16, 2014 at 7:01 PM, Peter Villeneuve <petervnv1 at gmail.com>
>> wrote:
>>
>> I removed the localhost listeners on TCP and UDP, and, as I suspected,
>> Kamailio doesn't seem to like that.
>>
>> Why isn't kamailio sending the message back through the TLS socket?
>>
>>
>>
>>
>>
>> NOTICE: <script>: -------------------------MESSAGE PROCESSING: dumping offline messages
>>
>> ERROR: tm [ut.h:343]: uri2dst2(): no corresponding socket for af 2
>>
>> ERROR: tm [uac.c:266]: t_uac_prepare(): t_uac: no socket found
>>
>>
>>
>> On Wed, Jul 16, 2014 at 4:44 PM, Peter Villeneuve <petervnv1 at gmail.com>
>> wrote:
>>
>> And here's the full routing block. I copied it from someone else on the
>> list that was troubleshooting msilo a while back.
>>
>> Also, I can confirm the message never gets delivered because it remains
>> in msilo DB and kamailio logs shows it trying and trying.
>>
>>
>>
>>
>>
>> ####### Routing Logic ########
>>
>>
>>
>> …
>>
>> On Wed, Jul 16, 2014 at 4:38 PM, Peter Villeneuve <petervnv1 at gmail.com>
>> wrote:
>>
>> Thanks for your help Daniel.
>>
>>
>>
>> OK I ngrepped port 5060 and indeed the message tries to get delivered.
>> However it never arrives at the client (1010 in this case).
>>
>> I have added localhost listeners for UDP and TCP, even though all clients
>> register through TLS only (could this be the root of the problem?). I added
>> localhost listeners because I was getting the no socket found error message.
>>
>>
>>
>> Listening on
>>
>>              udp: 127.0.0.1:5080
>>
>>              tcp: 127.0.0.1:5060
>>
>>              tls: 79.my.server.IP1:5061
>>
>> Aliases:
>>
>>              tcp: localhost:5060
>>
>>              udp: localhost:5080
>>
>>              *: my.domain.com:*
>>
>>
>>
>> U 2014/07/16 15:29:14.904285 127.0.0.1:5080 -> 79.my.server.IP1:5060
>>
>> MESSAGE sip:1010 at my.domain.com SIP/2.0.
>>
>> Via: SIP/2.0/UDP 127.0.0.1:5080
>> ;branch=z9hG4bKcde3.542219f4000000000000000000000000.0.
>>
>> To: <sip:1010 at my.domain.com>.
>>
>> From: <sip:1000 at my.domain.com>;tag=def4124455da8a0b8e97eafabd028e26-2c30.
>>
>> CSeq: 10 MESSAGE.
>>
>> Call-ID: 16b126996f51d89c-12460 at 127.0.0.1.
>>
>> Max-Forwards: 70.
>>
>> Content-Length: 58.
>>
>> User-Agent: kamailio (4.1.4 (x86_64/linux)).
>>
>> Date: Wed, 16 Jul 2014 15:22:31 GMT.
>>
>> Content-Type: text/plain.
>>
>> .
>>
>> [Offline message - Wed Jul 16 15:22:31 2014] Test 1,2,3
>>
>>
>>
>> On Wed, Jul 16, 2014 at 8:58 AM, Daniel-Constantin Mierla <
>> miconda at gmail.com> wrote:
>>
>> Hello,
>>
>> can you watch the sip traffic on the network to see if the sip messages
>> is sent out? You can use ngrep, like:
>>
>> ngrep -d any -qt -W byline "sip" port 5060
>>
>> Cheers,
>> Daniel
>>
>>
>>
>> On 14/07/14 19:56, Peter Villeneuve wrote:
>>
>>   Hi,
>>
>>
>>
>> This is most likely a stupid mistake on my route config, but msilo
>> correctly stores messages for offline users, but when they come back
>> online, the message never arrives.
>>
>>
>>
>> Looking through the debug logs indeed there is an error, with status 408,
>> which suggests kamaiio can't find a route to the user that just logged.
>> Before I spend hours looking through all the routing blocks, perhaps
>> someone more exprienced in kamailio can see the problem right away and
>> offer a solution?
>>
>>
>>
>> Thanks
>>
>>
>>
>>
>>
>> DEBUG: msilo [msilo.c:1148]: m_dump(): msg [1-12] for:
>> sip:1010 at my.domain.com
>>
>> DEBUG: <core> [io_wait.h:617]: io_watch_del(): DBG: io_watch_del
>> (0x8e3040, 9, -1, 0x10) fd_no=2 called
>>
>> DEBUG: <core> [tcp_read.c:1437]: release_tcpconn(): releasing con
>> 0x7f61ced1b1b0, state 1, fd=9, id=1
>>
>>  DEBUG: <core> [tcp_read.c:1438]: release_tcpconn():  extra_data
>> 0x7f61ced1c4f8
>>
>> DEBUG: <core> [tcp_main.c:3385]: handle_tcp_child(): handle_tcp_child:
>> reader response= 7f61ced1b1b0, 1 from 0
>>
>> DEBUG: <core> [io_wait.h:390]: io_watch_add(): DBG:
>> io_watch_add(0x89ec40, 26, 2, 0x7f61ced1b1b0), fd_no=21
>>
>> DEBUG: <core> [tcp_main.c:3515]: handle_tcp_child(): handle_tcp_child:
>> CONN_RELEASE  0x7f61ced1b1b0 refcnt= 1
>>
>> DEBUG: tm [t_reply.c:1304]: t_should_relay_response(): ->>>>>>>>>
>> T_code=0, new_code=408
>>
>> DEBUG: tm [t_reply.c:2086]: local_reply(): DEBUG: local_reply: branch=0,
>> save=0, winner=0
>>
>> DEBUG: tm [t_reply.c:2123]: local_reply(): DEBUG: local transaction
>> completed
>>
>> DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG:
>> trans=0x7f61ced1d868, callback type 1024, id 0 entered
>>
>> DEBUG: msilo [msilo.c:1317]: m_tm_callback(): *completed with status 408*
>> [mid: 140058058335472/13]
>>
>> DEBUG: msilo [msilo.c:1325]: m_tm_callback(): message <13> was not sent
>> successfully
>>
>> DEBUG: msilo [ms_msg_list.c:236]: msg_list_set_flag(): mid:13 fl:8
>>
>> DEBUG: tm [t_reply.c:1304]: t_should_relay_response(): ->>>>>>>>>
>> T_code=0, new_code=408
>>
>> DEBUG: tm [t_reply.c:2086]: local_reply(): DEBUG: local_reply: branch=0,
>> save=0, winner=0
>>
>> DEBUG: tm [t_reply.c:2123]: local_reply(): DEBUG: local transaction
>> completed
>>
>> DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG:
>> trans=0x7f61ced5f098, callback type 1024, id 0 entered
>>
>> DEBUG: msilo [msilo.c:1317]: m_tm_callback(): completed with status 408
>> [mid: 140058058329184/12]
>>
>> DEBUG: msilo [msilo.c:1325]: m_tm_callback(): message <12> was not sent
>> successfully
>>
>> DEBUG: msilo [ms_msg_list.c:236]: msg_list_set_flag(): mid:12 fl:8
>>
>>
>>
>>
>>
>>
>>
>> _______________________________________________
>>
>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
>>
>> sr-users at lists.sip-router.org
>>
>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>
>>
>>
>>  --
>>
>> Daniel-Constantin Mierla - http://www.asipto.com
>>
>> http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
>>
>>
>> _______________________________________________
>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
>> sr-users at lists.sip-router.org
>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>  ------------------------------
>>
>> This e-mail and any attachment is for authorised use by the intended
>> recipient(s) only. It may contain proprietary material, confidential
>> information and/or be subject to legal privilege. It should not be copied,
>> disclosed to, retained or used by, any other party. If you are not an
>> intended recipient then please promptly delete this e-mail and any
>> attachment and all copies and inform the sender. Thank you for
>> understanding.
>>
>> _______________________________________________
>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
>> sr-users at lists.sip-router.org
>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20140717/ad9bad73/attachment.html>