[Home]

Summary:ASTERISK-01105: IAX possible problem
Reporter:Olle Johansson (oej)Labels:
Date Opened:2004-02-26 08:28:48.000-0600Date Closed:2011-06-07 14:05:31
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Feb 26 14:17:12 NOTICE[139942912]: chan_iax2.c:1971 iax2_read: I should never be called!

I think this should never be called. How do I help trace this error? Don't know that much of the IAX2 protocol...

****** ADDITIONAL INFORMATION ******

I have a lot of these error messages. The call that caused this is IAX2 from a registred IAX2 user inside NAT to an IAX server outside on a public IP.
Comments:By: zoa (zoa) 2004-03-10 07:54:38.000-0600

i have the same error today, all the time...
By: Olle Johansson (oej) 2004-03-10 07:58:11.000-0600

Occassionally the other end bails out and loops, trying to destroy an IAX call. have to kill -9 to get out of it.

Both on CVS dev branch. The server I have to kill is inside a NAT device.
By: zoa (zoa) 2004-03-10 08:30:02.000-0600

mine both have public ip's.
By: zoa (zoa) 2004-03-10 08:34:33.000-0600

-- Zap/1-1 is ringing
   -- Nobody picked up in -1 ms
   -- Hungup 'Zap/1-1'
This happened on the same server, on not just once, but every call was like that, but it would strange if it would be related.
By: zoa (zoa) 2004-03-10 08:57:35.000-0600

i'm able to reproduce this:

  -- Executing Goto("IAX2[x@x.x.x.x:4569]/13", "zaptel-incoming|3212121212|1") in new stack
   -- Goto (zaptel-incoming,3212121212,1)
   -- Executing SetAccount("IAX2[x@x.x.x.x:4569]/13", "x") in new stack
      -- Executing BackGround("IAX2[x@x.x.x.x:4569]/13", "nobody-but-chickens") in new stack
   -- Playing 'nobody-but-chickens' (language 'en')
     -- Executing ZapScan("IAX2[x@x.x.x.x:4569]/13", "") in new stack
Apr  7 14:38:26 NOTICE[245776]: chan_iax2.c:1974 iax2_read: I should never be called!
Apr  7 14:38:26 NOTICE[245776]: chan_iax2.c:1974 iax2_read: I should never be called!
Apr  7 14:38:26 NOTICE[245776]: chan_iax2.c:1974 iax2_read: I should never be called!
Apr  7 14:38:26 NOTICE[245776]: chan_iax2.c:1974 iax2_read: I should never be called!
Apr  7 14:38:26 NOTICE[245776]: chan_iax2.c:1974 iax2_read: I should never be called!
Apr  7 14:38:26 NOTICE[245776]: chan_iax2.c:1974 iax2_read: I should never be called!
Apr  7 14:38:26 NOTICE[245776]: chan_iax2.c:1974 iax2_read: I should never be called!


Can reproduce it like this, with zapscan.
todays cvs.
By: zoa (zoa) 2004-03-10 09:02:49.000-0600

(stable branch, with james' changed zapscan from last night)
By: James Golovich (jamesgolovich) 2004-03-10 18:14:51.000-0600

iax2_read should only be called if there isn't anything in the chan->pvt->readq.  if you look at ast_read the first thing it does is check for the readq, and if its NULL then it does a few other things and eventually will call the channel's defined read function (in this case iax2_read).

So in zapscan the for loop is probably running too quickly and the queue is probably getting emptied, so eventually it has an empty readq and prints that message.  I'll see what I can come up with when I get home, but I'm guessing that this can be solved by a bit of ast_safe_sleep before the read call
By: twisted (twisted) 2004-04-07 04:08:29

was this handled?  If so, I'd like to report that I still get the problem occasionally using simple Playback() app.  If not, i guess it still should be handled. :)
By: James Golovich (jamesgolovich) 2004-04-07 05:04:32

I think perhaps we should change the message to something like 'Resource Temporarily Unavailable'.  On channel drivers that have a readq the actual channel specific read only gets called if the readq is empty.  In some cases its because some code is looping too quick and emptying out the readq.
By: stevekstevek (stevekstevek) 2004-04-14 20:16:21

Ok, here's my big problem here.

If I'm an application, and I call ast_read, how can I tell the difference between getting back NULL because the readq is empty, and getting back NULL because I got a hangup.


The former is a temporary error, and the latter is a permanent event.

Now, the question then becomes, why would an application call ast_read when there is nothing in the readq?

I have an application (app_conference, you can read the source at iaxclient.sf.net), which, as it should, only calls ast_read if ast_waitfor returns a positive number.  Yet I still get these -- a lot.

It seems to be symptomatic of larger problems, but I'm not sure.  Maybe the larger problems occur because we _treat_ it as a hangup, and the call ends up in never-never land or something.

I looked through channel.c, and I'm not exactly clear on how the readq is checked by ast_waitfor, but I see already two conditions which would cause it to return a positive number falsely:

First, if the select system call is interrupted:

  851         if (*ms >= 0)
   852                 res = ast_select(max + 1, &rfds, NULL, &efds, &tv);
   853         else
   854                 res = ast_select(max + 1, &rfds, NULL, &efds, NULL);
   855
   856         if (res < 0) {
   857                 for (x=0;x<n;x++)
   858                         c[x]->blocking = 0;
   859                 /* Simulate a timeout if we were interrupted */
   860                 if (errno != EINTR)
   861                         *ms = -1;
   862                 else {
   863                         /* Just an interrupt */
   864 #if 0
   865                         *ms = 0;
   866 #endif
   867                 }
   868                 return NULL;
   869         }

Second, ms is set to the result of select, but gets truncated.  If there was less than 1ms left, then it can return too early:

 894         *ms = tv.tv_sec * 1000 + tv.tv_usec / 1000;
   895         return winner;
   896 }

The above isn't a totally unlikely scenario.  It seems like there's a 1 in 20 chance or so to get this to happen..  (all you need to do is happen to call ast_waitfor 19.5ms before a frame arrives.  This would happen easily, for example, if frames came every 20ms on the button, and you took < 1ms to process them.
By: stevekstevek (stevekstevek) 2004-04-14 20:47:22

OK, so, now I see that iax2_read actually returns a valid frame of type AST_FRAME_NULL, which applications can safely ignore (and my application does).  

So, callers can easily differentiate between a frame == NULL and frame type AST_FRAME_NULL, and ignore those.  

So, although the "I should never be called" messages seem coincident with my problem, they may be unrelated.
By: Brian West (bkw918) 2004-04-18 01:42:01

Ok lets change the message, please all involved respond and we can reopen.

Thanks,
bkw