[asterisk-dev] Weird errors returned to chan_zap by zaptel

[Tony Mountifield]

I'm seeing some weird behaviour occurring randomly in chan_zap, and I am
wondering if anyone else has ever seen anything like it, because it does
not appear to make sense.

I'm posting it here initially instead of to Mantis, because I want to
get some ideas on why it could be occurring, so I can fix it quickly...

I'm using Asterisk 1.2-SVN and Zaptel 1.2-SVN with a TE410P card. Operation
is mostly OK, but I occasionally get the following batch of errors:

Nov  9 03:25:59 VERBOSE[29125] logger.c:907 ast_verbose:     -- Executing DeadAGI("Zap/2-1", "starhubagi|end") in new stack
Nov  9 03:25:59 VERBOSE[29125] logger.c:907 ast_verbose:     -- Launched AGI Script /var/lib/asterisk/agi-bin/starhubagi
Nov  9 03:25:59 VERBOSE[29125] logger.c:907 ast_verbose:     -- AGI Script starhubagi completed, returning 0
Nov  9 03:25:59 WARNING[29125] chan_zap.c:2887 zt_setoption: Unable to set audio mode to 1 on channel 2: (fd=14, res=-1) Bad file descriptor
Nov  9 03:25:59 WARNING[29125] chan_zap.c:1615 zt_confmute: Unable to set audio mode on channel 2: (fd=14, res=-1) Bad file descriptor
Nov  9 03:25:59 WARNING[29125] chan_zap.c:1619 zt_confmute: zt confmute(0) failed on channel 2: (fd=14, res=-1) Bad file descriptor
Nov  9 03:25:59 WARNING[29125] chan_zap.c:1587 restore_gains: Unable to restore gains on channel 2: (fd=14, res=-1) Bad file descriptor
Nov  9 03:25:59 WARNING[29125] chan_zap.c:2486 zt_hangup: Unable to set law on channel 2 to default: (fd=14, res=-1) Bad file descriptor
Nov  9 03:25:59 WARNING[29125] chan_zap.c:2527 zt_hangup: pri_disconnect failed
Nov  9 03:25:59 WARNING[29125] chan_zap.c:2555 zt_hangup: Unable to hangup line Zap/2-1 channel 2: (fd=14, res=-1) Bad file descriptor
Nov  9 03:25:59 WARNING[29125] chan_zap.c:1333 reset_conf: Failed to reset conferencing on channel 2: (fd=14, res=-1) Bad file descriptor
Nov  9 03:25:59 WARNING[29125] chan_zap.c:2887 zt_setoption: Unable to set audio mode to 0 on channel 2: (fd=14, res=-1) Bad file descriptor
Nov  9 03:25:59 VERBOSE[29125] logger.c:907 ast_verbose:     -- Hungup 'Zap/2-1'

The DeadAGI is always the last step in the h extension.

You'll notice that the error messages from chan_zap have more information
than usual. I've been enhancing them as I'm trying to track this down.
I reset errno to 0 immediately before calling the ioctl, and log the fd
in the log message. Since the fd is valid, I don't understand why I could
be getting "Bad file descriptor". I also log opens and closes, and fd 14
was opened for channel 2 at startup:

Nov  8 20:42:58 NOTICE[26227] chan_zap.c:919 zt_open: Opened '/dev/zap/channel' for channel 2, fd=14
Nov  8 20:42:58 VERBOSE[26227] logger.c:907 ast_verbose:     -- Registered channel 2, PRI Signalling signalling

It hasn't logged a close since.

A little later, a call comes in on that same channel, and further, different
errors get logged on the same fd, which prove that it hadn't been closed.

Nov  9 04:22:26 WARNING[26308] chan_zap.c:8513 pri_dchannel: Unable to set audio mode on channel 2 to 1: (fd=14, res=-1) Inappropriate ioctl for device
Nov  9 04:22:26 WARNING[26308] chan_zap.c:8521 pri_dchannel: Unable to set law on channel 2: (fd=14, res=-1) Inappropriate ioctl for device
Nov  9 04:22:26 WARNING[26308] chan_zap.c:8524 pri_dchannel: Unable to set gains on channel 2: (fd=14, res=-1) Inappropriate ioctl for device
Nov  9 04:22:26 WARNING[26308] chan_zap.c:5022 zt_new: Unable to get parameters, assuming MULAW on channel 2: (fd=14, res=-1) Inappropriate ioctl for device
Nov  9 04:22:26 WARNING[26308] chan_zap.c:1615 zt_confmute: Unable to set audio mode on channel 2: (fd=14, res=-1) Inappropriate ioctl for device
Nov  9 04:22:26 WARNING[26308] chan_zap.c:1619 zt_confmute: zt confmute(0) failed on channel 2: (fd=14, res=-1) Inappropriate ioctl for device
Nov  9 04:22:26 VERBOSE[26308] logger.c:907 ast_verbose:     -- Accepting call from '64034000' to '64034092' on channel 0/2, span 1
Nov  9 04:22:26 VERBOSE[30136] logger.c:907 ast_verbose:     -- Executing Goto("Zap/2-1", "starhub-mpt|6564034092|1") in new stack

The call attempts to proceed, but I'm not sure how successful it is. I can't
provoke this problem at will.

Here is an example of the ioctl calling and logging code I have put in
chan_zap:

if ((res = ioctl((errno=0,p->subs[SUB_REAL].zfd), ZT_AUDIOMODE, &x)) == -1)
    ast_log(LOG_WARNING, "Unable to set audio mode to %d on channel %d: (fd=%d, res=%d) %s\n", x, p->channel, p->subs[SUB_REAL].zfd, res, strerror(errno));

You can see the reset of errno (to make sure it's not an old value being
reported) and that the same fd is logged as was given to ioctl(). So why
a "Bad file descriptor" error? It's baffling.

Just in case it's relevant, here are some system details:

Centos 4.4, kernel 2.6.9-42.0.2.ELsmp
GCC 3.4.6, glibc 2.3.4
Asterisk running WITHOUT LD_ASSUME_KERNEL=2.4.1, i.e. with NPTL.

If anyone can suggest how to home in on this error, I'd be extremely
grateful!

Cheers
Tony
-- 
Tony Mountifield
Work: tony at softins.co.uk - http://www.softins.co.uk
Play: tony at mountifield.org - http://tony.mountifield.org