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

Thu Nov 9 00:57:31 MST 2006

Quite a -users answer. Not sure if the is a -users question or not.

On Wed, Nov 08, 2006 at 10:48:15PM +0000, Tony Mountifield wrote:
> 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:

Have you run ztcfg (sucecessfully)? What does your zaptel.conf look
like? What do you see on 'zap show channels' in asterisk?

In addition, compare that to what you have under /proc/zaptel/ . Another
place to get a sort of picture of the availble channels is
/sys/class/zaptel/ and (if udev is used and well-configured) the 
projected /dev/zap/* .

> 
> 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

Which file does descriptor 14 relate to?

ls -l /proc/NNN/fd/14

where NNN is the file descriptor of Asterisk.

> 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
> _______________________________________________
> --Bandwidth and Colocation provided by Easynews.com --
> 
> asterisk-dev mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-dev
> 

-- 
               Tzafrir Cohen       
icq#16849755                    jabber:tzafrir at jabber.org
+972-50-7952406           mailto:tzafrir.cohen at xorcom.com       
http://www.xorcom.com  iax:guest at local.xorcom.com/tzafrir