[Home]

Summary:ASTERISK-01797: Quick Net Internet Phonejack Goes Bezerk
Reporter:tormez (tormez)Labels:
Date Opened:2004-06-10 15:16:36Date Closed:2011-06-07 14:10:38
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Every so often I have to kill my asterisk box because the  chan_phone.c goes bezerk.  It does a loop job that just keeps going on forever until I do a killall asterisk, and restart it.

This is what it's looping.

Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Jun 10 15:32:31 WARNING[1949772]: chan_phone.c:699 phone_mini_packet: Read returned -1
Comments:By: alric (alric) 2004-06-11 08:25:32

Please provide more information about your system.  CVS version date and hardware setup (understand one PhoneJack, anything else?).
By: tormez (tormez) 2004-06-11 08:44:47

i'm running Asterisk CVS-HEAD-06/07/04-06:48:30

I have 4 x100p cards, and 1 Quick Net Internet phone jack into my asterisk box.  It's very random when this error happens.  Like this morning, I went into the comedian mail, and check my voice messages, and after I got done and hit # to log off and hang up, it happened again looping the exact same error.  

Last time this happened was after taking a call.
By: Mark Spencer (markster) 2004-06-12 11:44:48

I'm a little surprised with all the recent interest in chan_phone.  Maybe we need to find someone from quicknet to participate in this.  

Your code looks like it's a little old since line 699 didn't line up with mine.  I've updated CVS to provide more information on the reason the read() call is failing.  Please update to latest CVS and if you still receive the error, post what the new error message looks like.  Thanks.
By: tormez (tormez) 2004-06-14 14:57:37

I just updated to Asterisk CVS-HEAD-06/14/04-07:04:56

This is what it's looping every so often.

Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 14 15:17:46 WARNING[1785935]:

edited on: 06-14-04 14:42
By: Mark Spencer (markster) 2004-06-15 23:25:49

Might be good to attach gdb and see if something is in the process of reading the channel.
By: tormez (tormez) 2004-06-16 06:49:06

I'm not really experienced with using gdb, but I gave it an attempt, i doubt this is what your looking for.  What should I type in once i get it to start the loop job?

Jun 16 07:07:34 WARNING[311316]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 16 07:07:34 WARNING[311316]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 16 07:07:34 WARNING[311316]: chan_phone.c:711 phone_mini_packet: Read returned -1: Operation already in progress
Jun 16 07:07:34 WARNING[311316]: chan_phone.c:711 phone_mini_packet: Read returned
Program received signal SIGINT, Interrupt.
[Switching to Thread 16386 (LWP 23008)]
0x401bf5b7 in poll () from /lib/libc.so.6
(gdb) backtrace
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x080999dd in listener (unused=0x0) at asterisk.c:301
#2  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
#3  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
#4  0x401c71b7 in clone () from /lib/libc.so.
By: Mark Spencer (markster) 2004-06-16 14:23:35

It's a good start, but probably "thread apply all bt" would be most helpful.  Also the result of "show channels".  thanks!
By: tormez (tormez) 2004-06-16 15:03:13

(gdb) thread apply all bt

Thread 47 (Thread 737326 (LWP 26733)):
#0  0x401babbb in write () from /lib/libc.so.6
#1  0x40216980 in __DTOR_END__ () from /lib/libc.so.6

Thread 15 (Thread 213006 (LWP 26688)):
#0  0x40199b06 in nanosleep () from /lib/libc.so.6
#1  0xffffff80 in ?? ()
#2  0x40199969 in sleep () from /lib/libc.so.6
#3  0x40713fab in qcall (ignore=0x0) at app_qcall.c:167
#4  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
ASTERISK-1  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
ASTERISK-2  0x401c71b7 in clone () from /lib/libc.so.6

Thread 14 (Thread 196621 (LWP 26687)):
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x40696a22 in autodial (ignore=0x0) at pbx_wilcalu.c:82
#2  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
#3  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
#4  0x401c71b7 in clone () from /lib/libc.so.6

Thread 13 (Thread 180236 (LWP 26686)):
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x4065f81d in do_monitor (data=0x0) at chan_zap.c:5310
#2  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
#3  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
#4  0x401c71b7 in clone () from /lib/libc.so.6

Thread 11 (Thread 147466 (LWP 26682)):
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x08051dc4 in ast_io_wait (ioc=0x40319720, howlong=-4) at io.c:254
#2  0x402ee404 in do_monitor (data=0x0) at chan_skinny.c:2416
#3  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
#4  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
ASTERISK-1  0x401c71b7 in clone () from /lib/libc.so.6

Thread 10 (Thread 131081 (LWP 26681)):
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x08051dc4 in ast_io_wait (ioc=0x40316b10, howlong=-4) at io.c:254
#2  0x404dbd52 in network_thread (ignore=0x0) at chan_iax2.c:5814
#3  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
#4  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
ASTERISK-1  0x401c71b7 in clone () from /lib/libc.so.6

Thread 9 (Thread 114696 (LWP 26680)):
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x08051dc4 in ast_io_wait (ioc=0x40315058, howlong=-4) at io.c:254
#2  0x402d0fb1 in do_monitor (data=0x0) at chan_mgcp.c:3276
#3  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
#4  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
ASTERISK-1  0x401c71b7 in clone () from /lib/libc.so.6

Thread 8 (Thread 98311 (LWP 26679)):
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x08051dc4 in ast_io_wait (ioc=0x4030d508, howlong=-4) at io.c:254
#2  0x40289e96 in do_monitor (data=0x0) at chan_sip.c:6960
#3  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
#4  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
ASTERISK-1  0x401c71b7 in clone () from /lib/libc.so.6

Thread 7 (Thread 81926 (LWP 26678)):
#0  0x40199b06 in nanosleep () from /lib/libc.so.6
#1  0xffffff80 in ?? ()
#2  0x40199969 in sleep () from /lib/libc.so.6
#3  0x4027522c in scan_thread (unused=0x0) at pbx_spool.c:326
#4  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
ASTERISK-1  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
ASTERISK-2  0x401c71b7 in clone () from /lib/libc.so.6
---Type <return> to continue, or q <return> to quit---

Thread 6 (Thread 65541 (LWP 26677)):
#0  0x401c0f01 in select () from /lib/libc.so.6
#1  0x4023586c in ?? () from /usr/lib/asterisk/modules/res_parking.so
#2  0xbf1ff8b4 in ?? ()
#3  0xbf1ffa3c in ?? ()

Thread 5 (Thread 49156 (LWP 26674)):
#0  0x400268cb in read () from /lib/libpthread.so.0
#1  0x402298d0 in ?? () from /usr/lib/asterisk/modules/res_musiconhold.so
#2  0xffffffdc in ?? ()
#3  0x402273ad in monmp3thread (data=0x80fb508) at res_musiconhold.c:247
#4  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
ASTERISK-1  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
ASTERISK-2  0x401c71b7 in clone () from /lib/libc.so.6

Thread 4 (Thread 32771 (LWP 26673)):
#0  0x401c0f01 in select () from /lib/libc.so.6
#1  0x40220418 in ?? () from /usr/lib/asterisk/modules/chan_modem.so
#2  0xbf5ffa3c in ?? ()

Thread 3 (Thread 16386 (LWP 26672)):
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x080999dd in listener (unused=0x0) at asterisk.c:301
#2  0x40020bd0 in pthread_start_thread () from /lib/libpthread.so.0
#3  0x40020c4f in pthread_start_thread_event () from /lib/libpthread.so.0
#4  0x401c71b7 in clone () from /lib/libc.so.6

Thread 2 (Thread 32769 (LWP 26671)):
#0  0x401bf5b7 in poll () from /lib/libc.so.6
#1  0x400208de in __pthread_manager () from /lib/libpthread.so.0
#2  0x40020ad7 in __pthread_manager_event () from /lib/libpthread.so.0
#3  0x401c71b7 in clone () from /lib/libc.so.6

Thread 1 (Thread 16384 (LWP 26669)):
#0  0x400268cb in read () from /lib/libpthread.so.0
#0  0x401bf5b7 in poll () from /lib/libc.so.6

The only other thing that was kind of interesting, when i broke out of gdb it did this.

(gdb) quit
The program is running.  Exit anyway? (y or n) y
Ouch ... error while writing audio data: : Broken pipe

When it's in the looping state.. i'm unable to get a show channels because it won't let me use the console.

edited on: 06-16-04 14:47
By: tormez (tormez) 2004-06-22 07:57:55

I've noticed that this loop only happens after a hangup.  I'm not sure if that gives any additional leads.
By: qtidev (qtidev) 2004-06-24 16:21:53

Please send the contents of /proc/ixj to qtidev@quicknet.net
By: Mark Spencer (markster) 2004-06-30 10:30:01

Any update here?
By: qtidev (qtidev) 2004-06-30 10:45:20

No response back from the reporter
By: tormez (tormez) 2004-06-30 11:03:25

Sorry for the delay, I actually I was out of town for a while.  Once this happens again, i'll get that email shipped off.
By: tormez (tormez) 2004-06-30 11:15:52

I just sent a copy of my /proc/ixj to qtidev@quicknet.net, once i had the error to occur, which included.

$Id: ixj.c,v 1.103 2003/10/23 00:29:48 dereksmithies Exp $
$Id: ixj.h,v 1.18 2003/09/18 09:52:15 dereksmithies Exp $
$Id: ixjuser.h,v 1.14 2003/08/31 22:26:43 dereksmithies Exp $
$Id: ixj_data.h,v 1.18 2003/09/18 09:52:15 dereksmithies Exp $
Driver version 3.1.0
sizeof IXJ struct 24020 bytes
sizeof DAA struct 642 bytes
Using old telephony API
Debugging flags:


Card Num 0
DSP Base Address 0xc8c0
XILINX Base Address 0x0000/0x00
DSP Type 8022
DSP Version 01.17
Serial Number 533a006f
Card Type = Internet Phonejack TJ pci
Readers 1
Writers 1
Capabilities 13
DSP Processor load 204
Play Codec : 16 bit Linear
Record Codec : 16 bit Linear
AEC med
Rec volume 0x100
Play volume 0x100
DTMF prescale 0x40
Hook:  off hook
Port pots
SLIC state PLD_SLIC_STATE_ACTIVE
Base Frame 00.00
CID Base Frame  0
Frames Read 68813
Frames Written 67525
Pots send ring pattern:  [1000]    3000  [1000]    3000
By: twisted (twisted) 2004-07-08 08:49:55

Is there any update available for this yet?
By: tormez (tormez) 2004-07-08 12:47:51

Waiting on responce from qtidev
By: tormez (tormez) 2004-07-12 11:02:18

I just did an update on asterisk to Jul 12, and i'm still getting the same issue.  

Jul 12 11:25:26 WARNING[12698175]: chan_phone.c:714 phone_mini_packet: Read returned -1: Operation already in progress
Jul 12 11:25:26 WARNING[12698175]: chan_phone.c:714 phone_mini_packet: Read returned -1: Operation already in progress
Jul 12 11:25:26 WARNING[12698175]: chan_phone.c:714 phone_mini_packet: Read returned -1: Operation already in progress
Jul 12 11:25:26 WARNING[12698175]: chan_phone.c:714 phone_mini_packet: Read returned -1: Operation already in progress
Jul 12 11:25:26 WARNING[12698175]: chan_phone.c:714 phone_mini_packet: Read returned -1: Operation already in progress
Jul 12 11:25:26 WARNING[12698175]: chan_phone.c:714 phone_mini_packet: Read returned -1: Operation already in progress
Jul 12 11:25:26 WARNING[12698175]: chan_phone.c:714 phone_mini_packet: Read returned -1: Operation already in progress
Jul 12 11:25:26 WARNING[12698175]: chan_phone.c:714 phone_mini_packet: Read returned -1: Operation already in progress
By: Mark Spencer (markster) 2004-07-12 15:36:18

Reminder sent to qtidev

I think these fellows are waiting on some input from you.  You won't be able to reply to the reminder e-mail but if you will login to the bug tracker it would be nice to add some comments if you're still working on this.

Mark
By: qtidev (qtidev) 2004-07-12 15:54:11

Still looking at this.  SO far, I've been unable to replicate it on a redhat 7.3 system.
By: tormez (tormez) 2004-07-15 12:42:22

I don't know if this helps any but i'm running the 2.4.26 kernel on gentoo linux.
By: qtidev (qtidev) 2004-07-15 13:16:09

Well, it's a datapoint.  The kernel I'm using is 2.4.25 (linus) from kernel.org no patches.

Willing to try that?
By: Brian West (bkw918) 2004-07-17 19:34:05

Not really a major bug.
By: Mark Spencer (markster) 2004-07-17 20:20:02

It's a major bug in that it clearly is a source of significant instability in the /dev/phone driver.  The question is how critical that is to releasing a 1.0 version.
By: tormez (tormez) 2004-07-23 07:36:03

Just updated today to the most current CVS and am still having the same issues.  I'm also using the 2.4.25 vanella kernel as well, which didn't seem to make any difference.

l 23 07:59:23 WARNING[2310277]: chan_phone.c:715 phone_mini_packet: Read returned -1: Operation already in progress
Jul 23 07:59:23 WARNING[2310277]: chan_phone.c:715 phone_mini_packet: Read returned -1: Operation already in progress
Jul 23 07:59:23 WARNING[2310277]: chan_phone.c:715 phone_mini_packet: Read returned -1: Operation already in progress
Jul 23 07:59:23 WARNING[2310277]: chan_phone.c:715 phone_mini_packet: Read returned -1: Operation already in progress
Jul 23 07:59:23 WARNING[2310277]: chan_phone.c:715 phone_mini_packet: Read returned -1: Operation already in progress
Jul 23 07:59:23 WARNING[2310277]: chan_phone.c:715 phone_mini_packet: Read returned -1: Operation already in progress
Jul 23 07:59:23 WARNING[2310277]: chan_phone.c:715 phone_mini_packet: Read returned -1: Operation already in progress
Jul 23 07:59:23 WARNING[2310277]: chan_phone.c:715 phone_mini_packet: Read returned -1: Operation already in progress
By: Olle Johansson (oej) 2004-08-14 12:15:25

Any updates, anyone that can look further into this?
By: twisted (twisted) 2004-08-25 18:22:54

Closed due to 10 days of inactivity after update request.  Please note, closed does not mean gone, if soemone wants to pick this up, please notifiy one of the bug marshalls and we can re-open it.
By: twisted (twisted) 2004-11-15 22:00:52.000-0600

reopened per request in #asterisk
By: qtidev (qtidev) 2004-11-15 22:08:11.000-0600

is anything appearing in the system kernel logs?  what if anything does lsof show?
By: gregk (gregk) 2004-11-16 21:13:48.000-0600

I am getting this error a lot, always on hang-up.  First on 1.0.2 stable, roughly 1 in 5 times I hung up the phone.  With CVS-HEAD-11/15/04-00:41:24 it's roughly 1 in 20.  I have 1 QuickNet PhoneJack ISA card in a Pentium 233.  Wander if having a slow machine helps me hit the race condition.  Kernel is 2.4.20 from kernel.org.  I'd like to fix this, because it makes Asterisk unusable for me.

qtidev, are you still interested in looking into this?  Regardless, I am very interested to hear anyone's theories about this.

edited on: 11-16-04 21:14
By: twisted (twisted) 2004-12-01 01:09:39.000-0600

Reminder sent to qtidev

qtidev - still going to work on this one?
By: twisted (twisted) 2004-12-15 20:39:29.000-0600

Reminder sent to qtidev

Last reminder to qtidev, and to anyone else monitoring this bug.  We MUST make a move on this, or it will be closed due to lack of interest from all parties.

--Housekeeping
By: twisted (twisted) 2004-12-28 10:36:24.000-0600

Lack of interest