Summary:	ASTERISK-25839: "Expected to acknowledge ticks" problem
Reporter:	David Cunningham (dcunningham)	Labels:
Date Opened:	2016-03-10 14:44:01.000-0600	Date Closed:	2017-12-18 07:43:36.000-0600
Priority:	Critical	Regression?
Status:	Closed/Complete	Components:	Channels/chan_sip/General
Versions:	11.21.2	Frequency of Occurrence	Frequent
Related Issues:
Environment:	Debian 7.6, 64 bit	Attachments:	( 0) C-00008542-clean.txt.gz
Description:	We are seeing an issue where a call will be "stuck" for roughly a minute or so and the Asterisk log gives many "Expected to acknowledge ticks" warnings as below. This is causing severe issues for a customer running a call centre. The system is running 11.21.2. Can you advise of the cause? Thank you. {noformat} [Mar 10 08:00:25] DEBUG[3158][C-0000273f] channel.c: Set channel Local/4171411@product-phone-0000217b;2 to write format slin [Mar 10 08:00:25] DEBUG[3158][C-0000273f] res_musiconhold.c: Local/4171411@product-phone-0000217b;2 Opened file 0 '/var/lib/product/music/2/2/1' [Mar 10 08:00:25] DEBUG[3146][C-0000273f] res_rtp_asterisk.c: Difference is 888, ms is 131 [Mar 10 08:00:25] DEBUG[3158][C-0000273f] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead [Mar 10 08:00:30] DEBUG[3146][C-0000273f] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Mar 10 08:00:30] DEBUG[3158][C-0000273f] res_musiconhold.c: Local/4171411@product-phone-0000217b;2 Opened file 0 '/var/lib/product/music/2/2/1' [Mar 10 08:00:30] DEBUG[3158][C-0000273f] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead [Mar 10 08:00:30] DEBUG[3146][C-0000273f] res_rtp_asterisk.c: Difference is 752, ms is 114 [Mar 10 08:00:32] DEBUG[3146][C-0000273f] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Mar 10 08:00:35] DEBUG[3158][C-0000273f] res_musiconhold.c: Local/4171411@product-phone-0000217b;2 Opened file 0 '/var/lib/product/music/2/2/1' [Mar 10 08:00:35] DEBUG[3158][C-0000273f] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 5 instead [Mar 10 08:00:35] DEBUG[3146][C-0000273f] res_rtp_asterisk.c: Difference is 824, ms is 123 [Mar 10 08:00:36] DEBUG[3146][C-0000273f] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Mar 10 08:00:40] DEBUG[3158][C-0000273f] res_musiconhold.c: Local/4171411@product-phone-0000217b;2 Opened file 0 '/var/lib/product/music/2/2/1' [Mar 10 08:00:40] DEBUG[3158][C-0000273f] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead {noformat}
Comments:	By: Asterisk Team (asteriskteam) 2016-03-10 14:44:02.231-0600 Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report. Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process]. By: Rusty Newton (rnewton) 2016-03-13 13:02:05.328-0500 Can you attach the rest of the debug log that includes all debug and verbose output for the call in question that triggers the issue? By: David Cunningham (dcunningham) 2016-03-14 18:46:30.521-0500 Attached is a full trace of the problem, in call C-00008542. It's compressed because the log is 78Mb as a plain file unfortunately. By: David Cunningham (dcunningham) 2016-03-14 18:50:00.815-0500 The attachment is a different example to the original problem description. If you grep for C-00008542 you'll see "Expected to acknowledge" warnings throughout the call, but it really seems to hold up the call in this bit: {noformat} [Feb 29 08:07:20] DEBUG[3109][C-00008542] res_musiconhold.c: SIP/product-local-000106d8 Opened file 0 '/var/lib/product/music/2/2/1' [Feb 29 08:07:20] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Difference is 976, ms is 142 [Feb 29 08:07:20] DEBUG[3109][C-00008542] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 6 instead [Feb 29 08:07:22] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Feb 29 08:07:25] DEBUG[3109][C-00008542] res_musiconhold.c: SIP/product-local-000106d8 Opened file 0 '/var/lib/product/music/2/2/1' [Feb 29 08:07:25] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Difference is 1488, ms is 206 [Feb 29 08:07:25] DEBUG[3109][C-00008542] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 9 instead [Feb 29 08:07:27] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Feb 29 08:07:30] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Feb 29 08:07:30] DEBUG[3109][C-00008542] res_musiconhold.c: SIP/product-local-000106d8 Opened file 0 '/var/lib/product/music/2/2/1' [Feb 29 08:07:30] DEBUG[3109][C-00008542] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead [Feb 29 08:07:34] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Feb 29 08:07:35] DEBUG[3109][C-00008542] res_musiconhold.c: SIP/product-local-000106d8 Opened file 0 '/var/lib/product/music/2/2/1' [Feb 29 08:07:35] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Difference is 768, ms is 116 [Feb 29 08:07:35] DEBUG[3109][C-00008542] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [Feb 29 08:07:40] DEBUG[3109][C-00008542] res_musiconhold.c: SIP/product-local-000106d8 Opened file 0 '/var/lib/product/music/2/2/1' [Feb 29 08:07:40] DEBUG[3109][C-00008542] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead [Feb 29 08:07:40] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Feb 29 08:07:45] DEBUG[3109][C-00008542] res_musiconhold.c: SIP/product-local-000106d8 Opened file 0 '/var/lib/product/music/2/2/1' [Feb 29 08:07:45] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Difference is 664, ms is 103 [Feb 29 08:07:45] DEBUG[3109][C-00008542] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 4 instead [Feb 29 08:07:46] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Feb 29 08:07:49] DEBUG[3109][C-00008542] res_rtp_asterisk.c: Got RTCP report of 76 bytes [Feb 29 08:07:50] DEBUG[3109][C-00008542] res_musiconhold.c: SIP/product-local-000106d8 Opened file 0 '/var/lib/product/music/2/2/1' [Feb 29 08:07:50] DEBUG[3109][C-00008542] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 3 instead {noformat} By: Joshua C. Colp (jcolp) 2016-03-17 08:46:23.194-0500 What sort of environment is this under (physical / virtual, specs)? How many channels are active? The message is output if timerfd reads more than is expected, which likely means it blocked for longer than it should. Given it says 4 or 5 that's 80-100ms of time instead of 20ms. By: Asterisk Team (asteriskteam) 2016-03-31 12:00:02 Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1]. [1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines By: David Cunningham (dcunningham) 2016-03-31 15:17:52.796-0500 I believe this may be due to an AGI process not responding, eg when it's held up doing database things. By: Asterisk Team (asteriskteam) 2016-03-31 15:17:52.994-0500 This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable. By: Joshua C. Colp (jcolp) 2017-12-18 07:43:37.014-0600 Closing as reporter stated that they believe it was due to an AGI holding up things. If this is still an issue under supported versions feel free to comment and reopen with the specific version and the details.