### Description
Yealink phones is subscribes using `application/dialog-info+xml`. In this case for many phones false reported `early` state.
### Troubleshooting
#### Reproduction
Not knows. Some phones is displayes properly, some is not.
#### Debugging Data
none
#### Log Messages
not yet done
#### SIP Traffic
In provided pcap. is subscribed two clients `yealink` phone and `x-lite` softphone. Created call to extension 201 (sip login). For `x-lite` status is changed properly for `yealink` is not. Filters `udp.port==13322` caller leg `udp.port==1025` callee legs `udp.srcport==5060&&udp.dstport==5060` yealink phone `udp.port==15502` xlite
[blf-test.pcap.gz](https://github.com/kamailio/kamailio/files/1849284/blf-test.pcap.gz)
packet 14 - kamailio reports 201 extension is Available to xlite packet 25 - kamailio reports 201 is early to yealink (unexpected) packet 108 - created call to 201 extension packer 109 - ringing to caller packet 118 - kamailio send ringing to caller packet 119 - INVITE send to callee packet 124 - callee send Trying packet 127 - kamailio reports 201 is ringing to yalink packet 129 - kamailio reports 201 is busy to xlite packet 145 - kamailio send session progress to caller packet 146 - callee send ringing packet 154 - caller send cancel packet 156 - kamailio send early to yealink (unexpected) packet 156 - kamailio send Available to x-lite
### Possible Solutions
not known
### Additional Information
Kamailio installed from kazoo team repo
``` [root@kamailio01 ~]# kamailio -V version: kamailio 5.0.3 (x86_64/linux) flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 11:07:05 Sep 23 2017 with gcc 4.8.5 [root@kamailio01 ~]# ```
* **Operating System**:
<!-- Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04, CentOS 7.1, ...), MacOS, xBSD, Solaris, ...; Kernel details (output of `uname -a`) -->
``` [root@kamailio01 ~]# uname -a Linux kamailio01.cloudpbx.ai.co.uk 3.10.0-514.6.1.el7.x86_64 #1 SMP Wed Jan 18 13:06:36 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux [root@kamailio01 ~]# cat /etc/redhat-release CentOS Linux release 7.3.1611 (Core) [root@kamailio01 ~]# ```
@sergey-safarov this doesn't look like a kamailio issue. you may need to capture amqp packets from/to kamailio andalso look into kamailio logs. the items you're reporting as `unexpected` seem like an `expectation from user` rather than `unexpected because current state is ...`. what i mean is, the attached pcap is not enough to do an assessement of a possible issue that doesn't occur with other deployments of kamailio with kazoo.
@lazedo, I will create docker container using your repo and test on my servers
Hello Luis @lazedo Kamailio and kazoo is updated 1) kamailio is kamailio-5.0.4j-3.1.x86_64 from your repo; 2) kazoo is 4.2.25 on alpine packaged to container.
I retake test and can see: 1) packet 2 received `INVITE`; 2) packet 27 send `early` to Yealink; 3) packet 28 send `busy` to X-Lite; 4) packet 112 send `ANSWER` to caller; 5) packet 121 send `early` to Yealink (unexpected); 6) packet 122 send `On the Phone` to X-Lite; 7) packet 185 received `BYE` from caller; 8) packet 196 send `early` to Yealink (unexpected); 9) packet 122 send `Available` to X-Lite.
Luis AMQP messages also captured in PCAP but i cannot read this. Could you look into pcap file [test2- blf.pcap.gz](https://github.com/kamailio/kamailio/files/1987284/test2-.blf.pcap.gz)
Hello Luis @lazedo I found that kamailio is send BLF events to already disconnected Call-ID `bafd2f3d-d3a9-4c7d-be75-10fca3f358ca`. Please looks packets 123, 125, 127, 196, 198. And relevant CDR from kazoo ``` [root@node0 ~]# curl -s -S 'https://cust.ai.co.uk/v2/accounts/a9f80a9e89baec870641c904b45e8bdd/cdrs/2018...' -H 'X-Auth-Token: XXXXX' | jq -j '.data' { "custom_channel_vars": { "account_id": "a9f80a9e89baec870641c904b45e8bdd", "authorizing_id": "dfa492e672c1c67d9c84d27415507a9f", "authorizing_type": "device", "bridge_id": "cad39f1f-be0f-1236-dba9-0242ac110006", "ecallmgr_node": "ecallmgr@kazoo-app02.cloudpbx.ai.co.uk", "inception": "442030263206@cust.ai.co.uk", "owner_id": "1ac8f140e6bf1662ca0c901a04e93b07", "realm": "ai.cust.ai.co.uk", "username": "user_x4a5hv" }, "to": "201@ai.cust.ai.co.uk", "timestamp": 63691318804, "switch_url": "sip:mod_sofia@31.28.75.195:11000", "switch_uri": "sip:31.28.75.195:11000", "switch_nodename": "freeswitch@freeswitch01.cloudpbx.ai.co.uk", "ringing_seconds": "0", "request": "user_x4a5hv@ai.cust.ai.co.uk", "presence_id": "201@ai.cust.ai.co.uk", "other_leg_direction": "inbound", "other_leg_destination_number": "442030263206", "other_leg_caller_id_number": "03333444466", "other_leg_caller_id_name": "03333444466", "other_leg_call_id": "cad39f1f-be0f-1236-dba9-0242ac110006", "media_server": "freeswitch01.cloudpbx.ai.co.uk", "local_sdp": "v=0\r\no=FreeSWITCH 1524078566 1524078567 IN IP4 31.28.75.195\r\ns=FreeSWITCH\r\nc=IN IP4 31.28.75.195\r\nt=0 0\r\nm=audio 21038 RTP/AVP 0 101 13\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-16\r\na=rtcp:21039 IN IP4 31.28.75.195\r\na=rtpmap:13 CN/8000\r\na=ptime:20\r\na=sendrecv\r\n", "hangup_code": "sip:900", "hangup_cause": "NORMAL_UNSPECIFIED", "from": "03333444466@ai.cust.ai.co.uk", "duration_seconds": "0", "custom_sip_headers": { "x_kazoo_invite_format": "username", "x_kazoo_aor": "sip:user_x4a5hv@ai.cust.ai.co.uk" }, "channel_state": "REPORTING", "channel_name": "sofia/sipinterface_1/user_x4a5hv@ai.cust.ai.co.uk", "channel_created_time": 1524099604028605, "channel_call_state": "HANGUP", "caller_id_number": "03333444466", "caller_id_name": "03333444466", "callee_id_number": "+442030263201", "callee_id_name": "Henry Merrett", "call_direction": "outbound", "billing_seconds": "0", "call_id": "bafd2f3d-d3a9-4c7d-be75-10fca3f358ca", "node": "ecallmgr@kazoo-app01.cloudpbx.ai.co.uk", "msg_id": "1524099604028605", "event_name": "CHANNEL_DESTROY", "event_category": "call_event", "app_version": "4.0.0", "app_name": "ecallmgr", "interaction_id": "63691318785-9b1a9e0e", "interaction_key": "9b1a9e0e", "interaction_time": 63691318785, "id": "201804-bafd2f3d-d3a9-4c7d-be75-10fca3f358ca" } ``` This call is `outbound` (b-leg) and disconnected with error `NORMAL_UNSPECIFIED` finished about 3 weeks ago. Call `billing_seconds` and `duration_seconds` is 0.
As you can see in this pcap kamailio not get any events from `ecallmgr` related to Call-ID `bafd2f3d-d3a9-4c7d-be75-10fca3f358ca` this is mean dialog state is maintained inside kamailio. I will try locate Call-ID `bafd2f3d-d3a9-4c7d-be75-10fca3f358ca` in sqlite dump file.
Here is relevant values from `db/kazoo.db` ``` sqlite> select * from presentity where etag='kfp+326f0d1353a3adb7949e6f6b76a06906c7@e8634ea1-68a0-471a-ac32-e7fd5ef5197e'; 15|201|ai.cust.ai.co.uk|dialog|kfp+326f0d1353a3adb7949e6f6b76a06906c7@e8634ea1-68a0-471a-ac32-e7fd5ef5197e|0|1524099505|<?xml version="1.0" encoding="UTF-8"?><dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="1" state="full" entity="sip:201@ai.cust.ai.co.uk"><dialog id="kfp+326f0d1353a3adb7949e6f6b76a06906c7@e8634ea1-68a0-471a-ac32-e7fd5ef5197e" call-id="kfp+326f0d1353a3adb7949e6f6b76a06906c7@e8634ea1-68a0-471a-ac32-e7fd5ef5197e" direction="recipient"><state>early</state><local><identity display="201">sip:201@ai.cust.ai.co.uk</identity><target uri="sip:201@ai.cust.ai.co.uk"/></local><remote><identity display="anonymous">sip:anonymous@ai.cust.ai.co.uk</identity><target uri="sip:201@ai.cust.ai.co.uk"/></remote></dialog></dialog-info>|sip:31.28.75.194:11000|0 sqlite> ``` And same formated XML value ``` <?xml version="1.0" encoding="UTF-8"?> <dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="1" state="full" entity="sip:201@ai.cust.ai.co.uk"> <dialog id="kfp+320867f87e21b7d6ba0621b609ce7f6a7f@bafd2f3d-d3a9-4c7d-be75-10fca3f358ca" call-id="kfp+320867f87e21b7d6ba0621b609ce7f6a7f@bafd2f3d-d3a9-4c7d-be75-10fca3f358ca" direction="recipient"> <state>early</state> <local> <identity display="201">sip:201@ai.cust.ai.co.uk</identity> <target uri="sip:201@ai.cust.ai.co.uk" /> </local> <remote> <identity display="03333444466">sip:03333444466@ai.cust.ai.co.uk</identity> <target uri="sip:201@ai.cust.ai.co.uk" /> </remote> </dialog> </dialog-info> ``` I cannot get PCAP file for Call-ID `bafd2f3d-d3a9-4c7d-be75-10fca3f358ca`. But I can find 3 similar other call. [call-1.pcap.gz](https://github.com/kamailio/kamailio/files/1990763/call-1.pcap.gz) [call-2.pcap.gz](https://github.com/kamailio/kamailio/files/1990764/call-2.pcap.gz) [call-3.pcap.gz](https://github.com/kamailio/kamailio/files/1990765/call-3.pcap.gz)
Looks as kamailio not receive dialog update from ecallmgr when FS cannot create channel: 1) `NORMAL_UNSPECIFIED` (in example above kazoo CDR contains hangup_code 900) 2) `480 Temporarily not available` in call-1.pcap and call-2.pcap.
Or when FS generate event `481 Call Does Not Exist` for already completed call (call-3.pcap).
**Relevan kazoo CDR for** call-1 ``` [root@node0 ~]# curl -s -S 'https://cust.ai.co.uk/v2/accounts/a73004697e232c237b9e16a34889d9e7/cdrs/2018...' -H 'X-Auth-Token: XXXXXX' | jq -j '.data' { "custom_channel_vars": { "account_id": "a73004697e232c237b9e16a34889d9e7", "authorizing_id": "616c66a3cd184d22182bd98dc0d4ccab", "authorizing_type": "device", "bridge_id": "06ef7f3e-cd66-1236-4389-0242ac110006", "channel_authorized": "true", "ecallmgr_node": "ecallmgr@kazoo-app02.cloudpbx.ai.co.uk", "global_resource": "false", "inception": "441480877546@cust.ai.co.uk", "owner_id": "ca5953c3e3c11c9aefdb08807f361c46", "realm": "monkey.cust.ai.co.uk", "username": "mth_joshua" }, "to": "1502@monkey.cust.ai.co.uk", "timestamp": 63693005097, "switch_url": "sip:mod_sofia@31.28.75.195:11000", "switch_uri": "sip:31.28.75.195:11000", "switch_nodename": "freeswitch@freeswitch01.cloudpbx.ai.co.uk", "switch_hostname": "freeswitch01.cloudpbx.ai.co.uk", "ringing_seconds": "0", "request": "mth_joshua@monkey.cust.ai.co.uk", "presence_id": "1502@monkey.cust.ai.co.uk", "other_leg_direction": "inbound", "other_leg_destination_number": "441480877546", "other_leg_caller_id_number": "07739343636", "other_leg_caller_id_name": "07739343636", "other_leg_call_id": "06ef7f3e-cd66-1236-4389-0242ac110006", "media_server": "freeswitch01.cloudpbx.ai.co.uk", "local_sdp": "v=0\r\no=FreeSWITCH 1525754553 1525754554 IN IP4 31.28.75.195\r\ns=FreeSWITCH\r\nc=IN IP4 31.28.75.195\r\nt=0 0\r\nm=audio 31338 RTP/AVP 8 0 101 13\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-16\r\na=rtcp:31339 IN IP4 31.28.75.195\r\na=rtpmap:13 CN/8000\r\na=ptime:20\r\na=sendrecv\r\n", "hangup_code": "sip:480", "hangup_cause": "NO_USER_RESPONSE", "from": "07739343636@monkey.cust.ai.co.uk", "duration_seconds": "0", "custom_sip_headers": { "x_kazoo_invite_format": "username", "x_kazoo_aor": "sip:mth_joshua@monkey.cust.ai.co.uk", "x_cid": "590a-585-482018132449-Slough_1-0-178.22.140.242" }, "custom_application_vars": {}, "channel_state": "REPORTING", "channel_name": "sofia/sipinterface_1/mth_joshua@monkey.cust.ai.co.uk", "channel_created_time": 1525785891398751, "channel_call_state": "HANGUP", "caller_id_number": "07739343636", "caller_id_name": "BROOKLANDS DOOR07739343636", "callee_id_number": "+442033580210", "callee_id_name": "Joshua Panter", "call_direction": "outbound", "billing_seconds": "0", "call_id": "b80e7a23-e2c9-407b-a061-f6c279efc7bb", "node": "ecallmgr@kazoo-app01.cloudpbx.ai.co.uk", "msg_id": "1525785897689011", "event_name": "CHANNEL_DESTROY", "event_category": "call_event", "app_version": "4.0.0", "app_name": "ecallmgr", "interaction_id": "63693005090-a21e1751", "interaction_key": "a21e1751", "interaction_time": 63693005090, "id": "201805-b80e7a23-e2c9-407b-a061-f6c279efc7bb" } ``` call-2 ``` [root@node0 ~]# curl -s -S 'https://cust.ai.co.uk/v2/accounts/a73004697e232c237b9e16a34889d9e7/cdrs/2018...' -H 'X-Auth-Token: XXXXX' | jq -j '.data' { "custom_channel_vars": { "account_id": "a73004697e232c237b9e16a34889d9e7", "authorizing_id": "e73b17c812973b68f92507d0dd74304e", "authorizing_type": "device", "bridge_id": "5a9c1087-ce43-1236-4389-0242ac110006", "channel_authorized": "true", "ecallmgr_node": "ecallmgr@kazoo-app01.cloudpbx.ai.co.uk", "global_resource": "false", "inception": "442033580210@cust.ai.co.uk", "owner_id": "4fd0a8df2bb325a29d4a9a11edfa1a5b", "realm": "monkey.cust.ai.co.uk", "username": "mth_lyam" }, "to": "1508@monkey.cust.ai.co.uk", "timestamp": 63693100163, "switch_url": "sip:mod_sofia@31.28.75.195:11000", "switch_uri": "sip:31.28.75.195:11000", "switch_nodename": "freeswitch@freeswitch01.cloudpbx.ai.co.uk", "switch_hostname": "freeswitch01.cloudpbx.ai.co.uk", "ringing_seconds": "0", "request": "mth_lyam@monkey.cust.ai.co.uk", "presence_id": "1508@monkey.cust.ai.co.uk", "other_leg_direction": "inbound", "other_leg_destination_number": "442033580210", "other_leg_caller_id_number": "01217947206", "other_leg_caller_id_name": "01217947206", "other_leg_call_id": "5a9c1087-ce43-1236-4389-0242ac110006", "media_server": "freeswitch01.cloudpbx.ai.co.uk", "local_sdp": "v=0\r\no=FreeSWITCH 1525862698 1525862699 IN IP4 31.28.75.195\r\ns=FreeSWITCH\r\nc=IN IP4 31.28.75.195\r\nt=0 0\r\nm=audio 18260 RTP/AVP 8 0 101 13\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-16\r\na=rtcp:18261 IN IP4 31.28.75.195\r\na=rtpmap:13 CN/8000\r\na=ptime:20\r\na=sendrecv\r\n", "hangup_code": "sip:480", "hangup_cause": "NO_USER_RESPONSE", "from": "01217947206@monkey.cust.ai.co.uk", "duration_seconds": "0", "custom_sip_headers": { "x_kazoo_invite_format": "username", "x_kazoo_aor": "sip:mth_lyam@monkey.cust.ai.co.uk", "x_cid": "772a-58a-49201815498-Slough_1-0-178.22.140.242" }, "custom_application_vars": {}, "channel_state": "REPORTING", "channel_name": "sofia/sipinterface_1/mth_lyam@monkey.cust.ai.co.uk", "channel_created_time": 1525880958618694, "channel_call_state": "HANGUP", "caller_id_number": "01217947206", "caller_id_name": "01217947206", "callee_id_number": "+442033580210", "callee_id_name": "Lyam James-Keeble", "call_direction": "outbound", "billing_seconds": "0", "call_id": "0d095ad6-28cb-4650-9b80-14efe1c44b7c", "node": "ecallmgr@kazoo-app01.cloudpbx.ai.co.uk", "msg_id": "1525880963248707", "event_name": "CHANNEL_DESTROY", "event_category": "call_event", "app_version": "4.0.0", "app_name": "ecallmgr", "interaction_id": "63693100149-8202a4d4", "interaction_key": "8202a4d4", "interaction_time": 63693100149, "id": "201805-0d095ad6-28cb-4650-9b80-14efe1c44b7c" } ``` call-3 ``` [root@node0 ~]# curl -s -S 'https://cust.ai.co.uk/v2/accounts/85f98bf1d9dc8e1fd2a2f6ab76ca6a8a/cdrs/2018...' -H 'X-Auth-Token: XXXX' | jq -j '.data' { "custom_channel_vars": { "account_id": "85f98bf1d9dc8e1fd2a2f6ab76ca6a8a", "authorizing_id": "5117e7d09ad6d9b83b6af54e77dc2879", "authorizing_type": "device", "bridge_id": "4c7e0c5f-c8c5-1236-5aa2-02efc1858da8", "channel_authorized": "true", "ecallmgr_node": "ecallmgr@kazoo-app02.cloudpbx.ai.co.uk", "global_resource": "false", "owner_id": "8f9bb35da6eca7330b5074bbcc2d7c05", "realm": "lcn.cust.ai.co.uk", "username": "user_68s66l" }, "user_agent": "Yealink SIP-T41S 66.81.0.110", "to_uri": "user_68s66l@lcn.cust.ai.co.uk", "to_tag": "1618781421", "to": "2010@lcn.cust.ai.co.uk", "timestamp": 63692496260, "switch_url": "sip:mod_sofia@31.28.75.195:11000", "switch_uri": "sip:31.28.75.195:11000", "switch_nodename": "freeswitch@freeswitch01.cloudpbx.ai.co.uk", "switch_hostname": "freeswitch01.cloudpbx.ai.co.uk", "ringing_seconds": "0", "request": "user_68s66l@lcn.cust.ai.co.uk", "remote_sdp": "v=0\r\no=- 20667 20667 IN IP4 185.135.166.77\r\ns=SDP data\r\nc=IN IP4 185.135.166.77\r\nt=0 0\r\nm=audio 12354 RTP/AVP 0 101\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=ptime:20\r\n", "presence_id": "2010@lcn.cust.ai.co.uk", "other_leg_direction": "inbound", "other_leg_destination_number": "2010", "other_leg_caller_id_number": "07771964749", "other_leg_caller_id_name": "07771964749", "other_leg_call_id": "4c7e0c5f-c8c5-1236-5aa2-02efc1858da8", "media_server": "freeswitch01.cloudpbx.ai.co.uk", "local_sdp": "v=0\r\no=FreeSWITCH 1525258705 1525258706 IN IP4 31.28.75.195\r\ns=FreeSWITCH\r\nc=IN IP4 31.28.75.195\r\nt=0 0\r\nm=audio 18350 RTP/AVP 0 8 101 13\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-16\r\na=rtcp:18351 IN IP4 31.28.75.195\r\na=rtpmap:13 CN/8000\r\na=ptime:20\r\na=sendrecv\r\n", "hangup_code": "sip:200", "hangup_cause": "NORMAL_CLEARING", "from_uri": "07771964749@lcn.cust.ai.co.uk", "from_tag": "rr2e7vFjFK7Hm", "from": "07771964749@lcn.cust.ai.co.uk", "duration_seconds": "5", "disposition": "ANSWER", "custom_sip_headers": { "x_kazoo_invite_format": "username", "x_kazoo_aor": "sip:user_68s66l@lcn.cust.ai.co.uk" }, "custom_application_vars": {}, "channel_state": "REPORTING", "channel_name": "sofia/sipinterface_1/user_68s66l@lcn.cust.ai.co.uk", "channel_created_time": 1525277055138697, "channel_call_state": "HANGUP", "caller_id_number": "07771964749", "caller_id_name": "07771964749", "callee_id_number": "2010", "callee_id_name": "Mark Durham", "call_direction": "outbound", "billing_seconds": "0", "call_id": "277da4cc-ce99-4551-a219-a408285db584", "node": "ecallmgr@kazoo-app01.cloudpbx.ai.co.uk", "msg_id": "1525277060948700", "event_name": "CHANNEL_DESTROY", "event_category": "call_event", "app_version": "4.0.0", "app_name": "ecallmgr", "interaction_id": "63692496254-80200771", "interaction_key": "80200771", "interaction_time": 63692496254, "id": "201805-277da4cc-ce99-4551-a219-a408285db584" } ```
Luis I found that in `presentity` table dialog event is stored with `expires` equal 0. Think if ecallmgr will set this value equal leg timeout then this will resolve this issue.
Could you also confirm that need add function to ecallmgr like `make_sure_dialog_is_removed_on_kamailio`?
As hot fix on kamailio hosts is created script ``` #!/bin/sh
DB_FILE=/etc/kazoo/kazoo-configs-kamailio/kamailio/db/kazoo.db
clean_dialogs() { local TIMESTAMP=$1 sqlite3 $DB_FILE "update presentity SET expires=(received_time+900) where expires=0 and event='dialog' and instr(body, 'direction="recipient"><state>early</state><local><identity display') > 0;" }
TIMESTAMP=$(date +%s) clean_dialogs "$TIMESTAMP" exit 0 ``` And added to `/etc/crontab` this record ``` 0,15,30,45 * * * * kamailio /usr/local/bin/clean_blf.sh ```
@sergey-safarov hi, what you're reporting has nothing to do with kamailio & kazoo module. i'm closing this here.
Closed #1489.
-
lazedo -
sergey-safarov