[Home]

Summary:ASTERISK-06570: iax - no audio
Reporter:radamson (radamson)Labels:
Date Opened:2006-03-20 06:59:28.000-0600Date Closed:2006-03-30 11:39:23.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:When placing a call between two asterisk boxes (one is svn trunk from Feb20th, other svn trunk from Mar19th), there is no audio. Undefining SCHED_MULTITHREADED in chan_iax2.c corrects the issue. Cli info does not provide any hints of an issue other then "NOTICE[6766]: sched.c:297 ast_sched_del: Attempted to delete nonexistent schedule entry 17!" on hangup. Sip to sip calls are not impacted.

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

Ethereal trace of the iax call indicates iax data packets flowing from svn Feb20th box to Mar19th box, but absolutely no iax packets flowing in reverse direction. Both * boxes are on registered IP addresses with no firewalls involved. Codec selection has no impact on this issue.
Iax calls between the two boxes when both are running svn trunk from Feb 20th have been very reliable. Both boxes use iax def's based on peer and user; no register statements involved.
The svn trunk from Mar19th was a fresh svn checkout with full make install and no compile errors.
Comments:By: tootai (tootai) 2006-03-20 09:30:28.000-0600

I can confirm, even if second asterisk box is a stable (1.2.0 and 1.2.5)

Also, in iax.conf, the iaxthreadcount variable isn't taken in account. Have to modify default_thread_count in chan_iax2.c
By: Joshua C. Colp (jcolp) 2006-03-20 11:50:20.000-0600

I have tested the iaxthreadcount option in iax.conf and it works as expected when placed in the general section. NOTE THOUGH: You -MUST- restart Asterisk for this to take effect. We do not currently have the ability to change this on the fly using reload. As for the standing issue with audio, I'm labbing it up now and will see what I can find.
By: radamson (radamson) 2006-03-20 11:59:07.000-0600

Before opening this bug, I did add iaxthreadcount=10, did a stop now and restarted. Same problem. This is on a fc3 box. The only fix I could find was to undefining SCHED_MULTITHREADED.  While testing in the stock svn trunk (no changes whatsoever), I did have one iax call (incoming) that functioned properly and all others failed consistently.
By: Joshua C. Colp (jcolp) 2006-03-20 12:02:04.000-0600

I was just referring to tootai's statement that the iaxthreadcount variable isn't taken into account. If you change the value to something other then the default, load up asterisk, and type iax2 show threads you should see the number of threads specified. As for the audio issue - I'm still in the process of labbing it up but thought I'd give some indication that the issue is being worked on and tested.
By: Joshua C. Colp (jcolp) 2006-03-20 12:14:35.000-0600

Okay here's the scenario I have right now:

1: Server running SVN trunk revision 12587
2: Server running SVN release 1.2.5

Server #1 calls Server #2 using IAX2
Server #2 starts echo application

Audio flows in both directions.

Is there any other information about your setup that you can give me so I can lab this up in exactly the right way to recreate the problem?
By: tootai (tootai) 2006-03-20 12:40:12.000-0600

Joshnet, ok for the iaxthreadcount, restarting asterisk did the trick. Sorry.

For the main problem, as told by ramdamson, I undefined MULTITHREADED and I can pass calls. But incoming calls are not working. On the calling party (1.2.5) IAX2 debug show me the debugs ending with RINGING ACK ACK 4 REJECT Cause: call rejected manually. Then a WARNING:

Mar 20 19:14:45 WARNING[1970]: chan_iax2.c:6985 socket_read: Call rejected by xxx.xxx.xxx.xxx: Call rejected manually.

On the other side (SVN 13587), IAX2 debug didn't show *ANY* logs from the calling server IP!

On the setup: SVN 13587 is running on a dynamic host, 1.2.5 has a fixed IP This setup is working well since at least 1 year.
By: tootai (tootai) 2006-03-21 09:46:56.000-0600

I start from a fresh installation and i'm now on SVN-trunk-13815. Problem is still there. The Asterisk box is connected also to FWD so I try to call 613 there. It's ringing and finish with a nobody pickup in 40000ms. When Asterisk hangup, phone is still ringing. Here are parts of the iax2 logs, notice the subclass (255?) and the ANSWER:

Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: RINGING
  Timestamp: 00200ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
  Timestamp: 00200ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?)
  Timestamp: 07205ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
  Timestamp: 07205ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 002 Type: CONTROL Subclass: ANSWER
  Timestamp: 07208ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 005 Type: IAX     Subclass: ACK
  Timestamp: 07208ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 002 Type: VOICE   Subclass: 4
  Timestamp: 07200ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 006 Type: IAX     Subclass: ACK
  Timestamp: 07200ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 002 Type: IAX     Subclass: LAGRQ
  Timestamp: 10010ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 007 Type: IAX     Subclass: LAGRP
  Timestamp: 10010ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 003 Type: IAX     Subclass: ACK
  Timestamp: 10010ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 003 Type: IAX     Subclass: PING
  Timestamp: 20011ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 008 Type: IAX     Subclass: PONG
  Timestamp: 20011ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
  RR_JITTER       : 67
  RR_LOSS         : 0
  RR_PKTS         : 638
  RR_DELAY        : 38
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 1

Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 003 Type: IAX     Subclass: LAGRQ

Here are the final logs:

Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 006 Type: IAX     Subclass: ACK
  Timestamp: 30010ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
   -- Nobody picked up in 40000 ms
Mar 21 16:26:59 NOTICE[15607]: sched.c:286 ast_sched_del: Attempted to delete nonexistent schedule entry 69!
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 010 Type: IAX     Subclass: HANGUP
  Timestamp: 40021ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
  CAUSE CODE      : 0

   -- Hungup 'IAX2/fwd-gw-16384'
   -- Executing Hangup("SIP/106-aa18", "") in new stack
 == Spawn extension (macro-dialFWD, s, 2) exited non-zero on 'SIP/106-aa18' in macro 'dialFWD'
 == Spawn extension (macro-dialFWD, s, 2) exited non-zero on 'SIP/106-aa18'
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 006 Type: IAX     Subclass: PING
  Timestamp: 40008ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 011 Type: IAX     Subclass: PONG
  Timestamp: 40008ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
  RR_JITTER       : 10
  RR_LOSS         : 0
  RR_PKTS         : 892
  RR_DELAY        : 38
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 1

Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 006 Type: IAX     Subclass: LAGRQ
  Timestamp: 40011ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 012 Type: IAX     Subclass: LAGRP
  Timestamp: 40011ms  SCall: 16384  DCall: 02252 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 007 Type: IAX     Subclass: ACK
  Timestamp: 40021ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
  Timestamp: 00000ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
  Timestamp: 00000ms  SCall: 02252  DCall: 16384 [192.246.69.186:4569]
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: REGREQ

I went back to chan_iax2.c, undefine SCHED_MULTITHREAD like this
/*#define SCHED_MULTITHREADED */
all went ok, I could call FWD or my other asterisk

What is to notice also, is that incoming calls are now working again when SCHED_MULTITHREAD is not define. Didn't test other way.

Could the problem be elsewhere that in chan_iax2?
By: radamson (radamson) 2006-03-24 13:55:01.000-0600

With the svn trunk commits from 3/23 and 3/24 (I think by Kevin), it would appear this issue has been resolved.  I did a 'make update' (etc) today and placed several iax test calls. Every one completed normally and audio was consistently good in both directions.  Will continue to test to ensure it really was addressed and not an intermitant issue. (Test via teliax and nufone, and two other customer boxes of various releases work fine now.)
By: tootai (tootai) 2006-03-26 10:39:31.000-0600

With 14988 I still have problem. Notice subclass 16 and timestamp 00000ms. The called IAX server answered (see playing 'demo-echotest') and hangs up immediately. On the caller end, ring tone that's all. Calling FWD server has the same behaviour. Here are the logs:

Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
  Timestamp: 00065ms  SCall: 00002  DCall: 00008 [xxx.xxx.xxx.xxx:1024]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: VOICE   Subclass: 16
  Timestamp: 00080ms  SCall: 00002  DCall: 00008 [xxx.xxx.xxx.xxx:1024]
   -- Playing 'demo-echotest' (language 'en')
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
  Timestamp: 00000ms  SCall: 00008  DCall: 00002 [xxx.xxx.xxx.xxx:1024]
 == Spawn extension (from-VOIP, 800, 3) exited non-zero on 'IAX2/xxx.xxx.xxx.xxx:1024-2'
   -- Hungup 'IAX2/xxx.xxx.xxx.xxx:1024-2'
 == Spawn extension (ServiceNumbers, 800, 2) exited non-zero on 'Local/800@ServiceNumbers-dfe4,2'
 == Spawn extension (default, 100, 1) exited non-zero on 'Local/100@default-ea28,2'
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
  Timestamp: 00000ms  SCall: 00008  DCall: 00002 [xxx.xxx.xxx.xxx:1024]
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: INVAL
  Timestamp: 00000ms  SCall: 00008  DCall: 00002 [xxx.xxx.xxx.xxx:1024]
By: Dmitriy Yermakov (dyer) 2006-03-28 10:29:05.000-0600

With 15476 revision and #define SCHED_MULTITHREADED same problem.
I'm running 15476 on both servers and following results:
Box A reject call from box B with INVAL or no-audio.
When i undefine SCHED_MULTITHREAD all went ok and calls succefully
established between my asterisk boxes.
By: Joshua C. Colp (jcolp) 2006-03-29 21:36:14.000-0600

Please give latest trunk a try and tell me how it works.
By: Russell Bryant (russell) 2006-03-29 22:19:23.000-0600

joshnet: Your commit fixed the problem for me.
By: tootai (tootai) 2006-03-30 10:54:56.000-0600

We can't make tests, asterisk is core dumping (see ASTERISK-6664) when we launch it.
By: tootai (tootai) 2006-03-30 11:34:46.000-0600

Joshnet: the commit fixed also the problem for us. Thanks.
By: Joshua C. Colp (jcolp) 2006-03-30 11:39:17.000-0600

Based on feedback, this problem seems to be gone now. If it reoccurs please reopen this bug so I can take a look.