Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
rodrigomonelos opened this issue Nov 21, 2017 · 11 comments
Open

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

rodrigomonelos opened this issue Nov 21, 2017 · 11 comments
Assignees

Comments

@rodrigomonelos
Copy link
Collaborator

rodrigomonelos commented Nov 21, 2017

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
Copy link
Collaborator Author

image

@sanchi
Copy link
Collaborator

sanchi commented Nov 22, 2017

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

@rodrigomonelos
Copy link
Collaborator Author

rodrigomonelos commented Nov 24, 2017 via email

@gmarcos87
Copy link
Collaborator

@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
Copy link
Collaborator

sanchi commented Nov 27, 2017

@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
Copy link
Collaborator

sanchi commented Nov 27, 2017

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

@gmarcos87
Copy link
Collaborator

gmarcos87 commented Nov 27, 2017 via email

@rodrigomonelos
Copy link
Collaborator Author

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
Copy link
Collaborator

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

@sanchi
Copy link
Collaborator

sanchi commented Nov 27, 2017

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
Copy link
Collaborator Author

rodrigomonelos commented Nov 29, 2017 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants