SIP Failure Code during the first ~30 a user is disconnected

rodrigomonelos commented 6 years ago

I get a SIP Failure Code message on the sms-version of the app when trying to send a message to a user that has just disconnected. Messaging works fine both when both users are online as well as when the one offline has been on that state for more than ~30''. Steps to reproduce:

Text from App (A) to App (B)
Close one of the two ends (B)
Send a message form A to B during the following <30'' of having closed B

According with @gmarcos87 this has to do with the time that the backend is taking to register that a user went offline. How can we know this?

rodrigomonelos commented 6 years ago

sanchi commented 6 years ago

please collect a trace from the server. ssh root@rhizortc.specialstories.org run this: tail -f /var/log/daemon.log > kamailiologdate +"%F-%H_%M_%S".txt and make the test. thanks!

rodrigomonelos commented 6 years ago

I'm getting Permission denied (publickey). I guess this means that I'm not authorized to ssh rhizortc (I never gave my public key for that). I think that the shortest way to move on is @gmarcos87 to log this test, since I understand he knows how to reproduce the SIP Failure Code message and has the necessary permisions. Anyway, I'm available to run the test if someone gives me the support for that.

rodrigo@rodrigo-UX303UB:~$ ssh root@rhizortc.specialstories.org

The authenticity of host 'rhizortc.specialstories.org (138.68.99.252)' can't be established. ECDSA key fingerprint is SHA256:d52zMlx0IPM3llEU3MjWLRl QDOIKF/fBkl1dhQS8yU0. Are you sure you want to continue connecting (yes/no)? yes Warning: Permanently added 'rhizortc.specialstories.org,138.68.99.252' (ECDSA) to the list of known hosts. Permission denied (publickey). rodrigo@rodrigo-UX303UB:~$ tail -f /var/log/daemon.log > kamailio_logdate +"%F-%H%M%S".txt tail: no se puede abrir '/var/log/daemon.log' para lectura: No existe el archivo o el directorio tail: no se puede abrir '+%F-%H%M_%S.txt' para lectura: No existe el archivo o el directorio tail: no queda ningún fichero

2017-11-22 12:31 GMT-04:00 Stefan Sayer notifications@github.com:

please collect a trace from the server. ssh root@rhizortc.specialstories.org run this: tail -f /var/log/daemon.log > kamailio_logdate +"%F-%H%M_%S".txt and make the test. thanks!

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/saycel/webph.one/issues/142#issuecomment-346403743, or mute the thread https://github.com/notifications/unsubscribe-auth/AZmH3kjUK1D_nfNpRK-USkw3kHyZUvQ0ks5s5Ex1gaJpZM4QmpD9 .

gmarcos87 commented 6 years ago

@sanchi

Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) exec: *** cfgtrace:request_route=[REGISTRAR] c=[/etc/kamailio/kamailio.cfg] l=872 a=2 n=exit
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/receive.c:275]: receive_msg(): request-route executed in: 43143 usec
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list 0x7f5e9dbdd640
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/usr_avp.c:631]: destroy_avp_list(): destroying list (nil)
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil)
Nov 25 15:12:40 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/receive.c:364]: receive_msg(): cleaning up
Nov 25 15:12:41 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:515]: wsconn_put_list(): wsconn_put_list [0x7f5ea8617e50]
Nov 25 15:12:41 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd6a578] refcnt [2]
Nov 25 15:12:41 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd6a578] refcnt [1]
Nov 25 15:12:41 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd31c50] refcnt [2]
Nov 25 15:12:41 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd31c50] refcnt [1]
Nov 25 15:12:41 rhizortc rtpengine[30545]: DEBUG: [of71tcgfcfa4gd3th5jm/v0qvh6h77r/1]: Setting ICE candidate pair 7cV6BcQMBNiWMhiw:149054977:1 as failed
Nov 25 15:12:42 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:515]: wsconn_put_list(): wsconn_put_list [0x7f5ea8617e50]
Nov 25 15:12:42 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd6a578] refcnt [2]
Nov 25 15:12:42 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd6a578] refcnt [1]
Nov 25 15:12:42 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd31c50] refcnt [2]
Nov 25 15:12:42 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd31c50] refcnt [1]
Nov 25 15:12:43 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:515]: wsconn_put_list(): wsconn_put_list [0x7f5ea8617e50]
Nov 25 15:12:43 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd6a578] refcnt [2]
Nov 25 15:12:43 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd6a578] refcnt [1]
Nov 25 15:12:43 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd31c50] refcnt [2]
Nov 25 15:12:43 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd31c50] refcnt [1]
Nov 25 15:12:44 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:515]: wsconn_put_list(): wsconn_put_list [0x7f5ea8617e50]
Nov 25 15:12:44 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd6a578] refcnt [2]
Nov 25 15:12:44 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd6a578] refcnt [1]
Nov 25 15:12:44 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd31c50] refcnt [2]
Nov 25 15:12:44 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd31c50] refcnt [1]
Nov 25 15:12:45 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:515]: wsconn_put_list(): wsconn_put_list [0x7f5ea8617e50]
Nov 25 15:12:45 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd6a578] refcnt [2]
Nov 25 15:12:45 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd6a578] refcnt [1]
Nov 25 15:12:45 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd31c50] refcnt [2]
Nov 25 15:12:45 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd31c50] refcnt [1]
Nov 25 15:12:46 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:515]: wsconn_put_list(): wsconn_put_list [0x7f5ea8617e50]
Nov 25 15:12:46 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd6a578] refcnt [2]
Nov 25 15:12:46 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd6a578] refcnt [1]
Nov 25 15:12:46 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd31c50] refcnt [2]
Nov 25 15:12:46 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd31c50] refcnt [1]
Nov 25 15:12:46 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa996c0, 8, -1, 0x10) fd_no=2 called
Nov 25 15:12:46 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/tcp_read.c:1504]: release_tcpconn(): releasing con 0x7f5e9dca6aa0, state 1, fd=8, id=289 ([138.255.88.1]:42028 -> [138.255.88.1]:8443)
Nov 25 15:12:46 rhizortc kamailio[18230]: 19(18262) DEBUG: <core> [core/tcp_read.c:1505]: release_tcpconn(): extra_data 0x7f5e9dbc9bd8
Nov 25 15:12:46 rhizortc kamailio[18230]: 26(18276) DEBUG: <core> [core/tcp_main.c:3257]: handle_tcp_child(): reader response= 7f5e9dca6aa0, 1 from 1
Nov 25 15:12:46 rhizortc kamailio[18230]: 26(18276) DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0xa50280, 45, 2, 0x7f5e9dca6aa0), fd_no=38
Nov 25 15:12:46 rhizortc kamailio[18230]: 26(18276) DEBUG: <core> [core/tcp_main.c:3384]: handle_tcp_child(): CONN_RELEASE  0x7f5e9dca6aa0 refcnt= 1
Nov 25 15:12:47 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:515]: wsconn_put_list(): wsconn_put_list [0x7f5ea8617e50]
Nov 25 15:12:47 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd6a578] refcnt [2]
Nov 25 15:12:47 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd6a578] refcnt [1]
Nov 25 15:12:47 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:384]: wsconn_put(): wsconn_put start for [0x7f5e9dd31c50] refcnt [2]
Nov 25 15:12:47 rhizortc kamailio[18230]: 16(18255) DEBUG: websocket [ws_conn.c:417]: wsconn_put(): wsconn_put end for [0x7f5e9dd31c50] refcnt [1]
Nov 25 15:12:47 rhizortc kamailio[18230]: 26(18276) DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0xa50280, 46, -1, 0x0) fd_no=39 called
Nov 25 15:12:47 rhizortc kamailio[18230]: 26(18276) DEBUG: <core> [core/tcp_main.c:4145]: handle_tcpconn_ev(): sending to child, events 1
Nov 25 15:12:47 rhizortc kamailio[18230]: 26(18276) DEBUG: <core> [core/tcp_main.c:3827]: send2child(): selected tcp worker 3 21(18266) for activity on [tls:138.68.99.252:8443], 0x7f5e9dcbbb58
Nov 25 15:12:47 rhizortc kamailio[18230]: 21(18266) DEBUG: <core> [core/tcp_read.c:1580]: handle_io(): received n=8 con=0x7f5e9dcbbb58, fd=8
Nov 25 15:12:47 rhizortc kamailio[18230]: 21(18266) DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0xa996c0, 8, 2, 0x7f5e9dcbbb58), fd_no=1
Nov 25 15:12:47 rhizortc kamailio[18230]: 21(18266) DEBUG: <core> [core/tcp_read.c:1189]: ws_process_msg(): WebSocket Message: [[>>>
Nov 25 15:12:47 rhizortc kamailio[18230]: ��
Nov 25 15:12:47 rhizortc kamailio[18230]: ���������ּ˞㦁Ϊ��Ǥ��â�ʟ��ׅ������۞��˃��ђ��ׅ����ó�٣����������ء���������������Ͻ�ց��ѓ��ʖ������а���£��ŧ���������ʀ��܄���Ξ�옩������Ϊ��ǣ��Χ�����������ݔ��Ԅ��ʞ�������ʘ���ժ��ƣ������ճ�˞㦁Ϊ��Ǫ��Π�ʟ��ׅ������۞��˃��ђ��ׅ��������������ȕ⑲������؂�����篏���Ι������͟�������׫��γ��������

I did the following steps:

I started to register the logs
I called from app A to app B
I answered and then I cut the call
I closed app B
I tried to call from A to B and the error happened.
I stopped the logs.

sanchi commented 6 years ago

@gmarcos87 thanks for the log (the interesting part was much lower in the log, but I could actually find it on the server).

I have added a t_set_disable_internal_reply(1); which should prevent the server from generating that reply, but I am struggling to reproduce (I get always 480 back from the app when I try to pick up - 4af84ff)

sanchi commented 6 years ago

re log tracing: you can on rhizortc now run kamailio-trace

gmarcos87 commented 6 years ago

Can you see the app logs when try to pick up? Maybe it's an error. What browser do you use? Are you using the app from https?

El 27 nov. 2017 2:55 p. m., "Stefan Sayer" notifications@github.com escribió:

@gmarcos87 https://github.com/gmarcos87 thanks for the log (the interesting part was much lower in the log, but I could actually find it on the server).

I have added a t_set_disable_internal_reply(1); which should prevent the server from generating that reply, but I am struggling to reproduce (I get always 480 back from the app when I try to pick up - 4af84ff)

— You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub https://github.com/saycel/webph.one/issues/142#issuecomment-347267596, or mute the thread https://github.com/notifications/unsubscribe-auth/AKRlThVs38E2hHBYiUev9lzuH-80JND9ks5s6veRgaJpZM4QmpD9 .

rodrigomonelos commented 6 years ago

Hi @sanchi I tested and I still get the "SIP Failure Code" message. Anyway, I'm a bit confused with the conversation you are having. You talk about "calling" and this issue is happening with texting.

gmarcos87 commented 6 years ago

Is related to the user status. It is independent of whether it is call or message.

sanchi commented 6 years ago

hm, can you please try to get a log? @rodrigomonelos your key is on the server. just ssh to it (ssh rhizortc.specialstories.org) and run kamailio-trace

rodrigomonelos commented 6 years ago

I logged in and ran the command you indicated, getting a cannot open error message. Find below the log from my terminal. I ran the test anyway, I don't know if there is something logged anyway. I also remember you saying that we should turn off the logging after testing. I do not know if it is actually turned on, but anyway can you check if it is necessary to turn it off?

tnks

rodrigo@rodrigo-UX303UB:~$ ssh root@rhizortc.specialstories.org

The programs included with the Debian GNU/Linux system are free software; the exact distribution terms for each program are described in the individual files in /usr/share/doc/*/copyright. Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent permitted by applicable law. root@rhizortc:~# tail -f /var/log/daemon.log > kamailio_logdate +"%F-%H%M%S".txt tail: cannot open '+%F-%H%M_%S.txt' for reading: No such file or directory packet_write_wait: Connection to 138.68.99.252 port 22: Broken pipe

2017-11-27 19:34 GMT-04:00 Stefan Sayer notifications@github.com:

hm, can you please try to get a log? @rodrigomonelos https://github.com/rodrigomonelos your key is on the server. just ssh to it (ssh rhizortc.specialstories.org) and run kamailio-trace

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/saycel/webph.one/issues/142#issuecomment-347364862, or mute the thread https://github.com/notifications/unsubscribe-auth/AZmH3rqBiCyicdRkCffxi5OLn-RVvONBks5s60cbgaJpZM4QmpD9 .

saycel / webph.one

SIP Failure Code during the first ~30 a user is disconnected #142