[asterisk-bugs] [JIRA] (ASTERISK-25839) "Expected to acknowledge ticks" problem

[David Cunningham (JIRA)]

    [ https://issues.asterisk.org/jira/browse/ASTERISK-25839?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=229887#comment-229887 ] 

David Cunningham commented on ASTERISK-25839:
---------------------------------------------

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}

> "Expected to acknowledge ticks" problem
> ---------------------------------------
>
>                 Key: ASTERISK-25839
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-25839
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Channels/chan_sip/General
>    Affects Versions: 11.21.2
>         Environment: Debian 7.6, 64 bit
>            Reporter: David Cunningham
>            Assignee: Unassigned
>            Severity: Critical
>         Attachments: C-00008542-clean.txt.gz
>
>
> 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 at product-phone-0000217b;2 to write format slin
> [Mar 10 08:00:25] DEBUG[3158][C-0000273f] res_musiconhold.c: Local/4171411 at 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 at 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 at 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 at 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}



--
This message was sent by Atlassian JIRA
(v6.2#6252)