[asterisk-bugs] [JIRA] (ASTERISK-20032) Call to timerfd_gettime() error: Bad file descriptor

Fri Nov 30 10:03:45 CST 2012

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

Matt Hamilton commented on ASTERISK-20032:
------------------------------------------

Addendum to my previous comment:

This error originates from ast_timer_set_rate in ast_read (AST_TIMING_EVENT_EXPIRED) in  channel.c.

Unlike ast_timer_ack, ast_timer_set_rate returns an error (-1), but this is not checked. However, the recent changes to ast_timer_ack in the patch should prevent the code reaching there.

So far we haven't been able to pinpoint why/when the timer fd goes bad (assuming that's the case). We get this error (and crash) every couple of days - it's random, might happen under very light load. Having said that, it started happening less after some changes to our dialplan which resulted in less musiconhold activity. Of course, might be just a coincidence...

> Call to timerfd_gettime() error: Bad file descriptor
> ----------------------------------------------------
>
>                 Key: ASTERISK-20032
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-20032
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Resources/res_timing_timerfd
>    Affects Versions: 10.5.1
>         Environment: openSUSE 11.4 x86_64 on Dell M610 blade
>            Reporter: Jeremiah Gowdy
>            Severity: Critical
>         Attachments: jgowdy-timerfd-6-22-2012.diff
>
>
> I have seen this issue previously on previous 10.x releases.  After running call load against our ExternalIVR based application for a random amount of time, the log will flood this:
> [Jun 21 12:39:18] VERBOSE[30608] pbx.c:     -- Executing [s at originate:1] Answer("Local/s at originate-dc89;2", "") in new stack
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] VERBOSE[30609] pbx.c:     -- Executing [9007862194338 at dial:1] Goto("Local/s at originate-dc89;1", "dial-sansay,5400117862194338,1") in new stack
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] VERBOSE[30609] pbx.c:     -- Goto (dial-sansay,5400117862194338,1)
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] VERBOSE[30609] pbx.c:     -- Executing [5400117862194338 at dial-sansay:1] Dial("Local/s at originate-dc89;1", "SIP/5400117862194338 at sansay,,G(post^s^1)") in new stack
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> [Jun 21 12:39:18] ERROR[30608] res_timing_timerfd.c: Call to timerfd_gettime() error: Bad file descriptor
> The log only seems to contain a single thread that is stuck in this state.  Other calls on other channels seem to continue to function.  I am working to provide better context surrounding when this error occurs. 
> ---
> I've changed the timer interface to make the timer ack function(s) in all of the timer implementations return 0 on success / -1 on failure, and I've changed all the places that call ast_timer_ack check that return code and return error themselves if it fails.  This stops the streaming of the timer errors and allowed me to determine which call is getting the error:
> [Jun 22 10:46:09] VERBOSE[20352] pbx.c:     -- Executing [s at originate:1] Answer("Local/s at originate-3722;2", "") in new stack
> [Jun 22 10:46:09] ERROR[20352] res_timing_timerfd.c: Call to timerfd_gettime() using handle 257 error: Bad file descriptor
> [Jun 22 10:46:09] ERROR[20352] channel.c: Timer failed in ast_read
> [Jun 22 10:46:09] VERBOSE[20352] pbx.c:   == Spawn extension (originate, s, 1) exited non-zero on 'Local/s at originate-3722;2'
> It seems that the issue happens when channel.c calls ast_timer_ack from ast_read

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira