[Home]

Summary:ASTERISK-09686: Premature Channel Hangup on AGI
Reporter:Bernard Chan (cbkihong)Labels:
Date Opened:2007-06-14 23:21:10Date Closed:2007-08-20 16:14:30
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Resources/res_agi
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:After we upgraded Asterisk from 1.2.9.1 we seem to have some issues about the combination of AGI and Dial(). As the same configuration was fine when all the servers were Asterisk 1.2.9.1, I guess that would probably be a bug somewhere. I have read previous bug trackers and did not find anything similar.

We are required to set up 2 separate servers (and thus 2 Asterisk instances) for incoming call reception and termination.

After executing the dialplan at reception server, a Dial() call would be made over IAX2 to the termination server. The termination server, on connection, will also execute a dialplan which involves some AGI calls among other things.

For testing, I was able to reproduce the issue with as simple as the following:

On the reception server, the context looks like this:

[testing-in]
exten => 111,1,Answer()
exten => 111,n,Dial(IAX2/user:secret@192.168.10.163/02555)
exten => 111,n,Hangup

On the termination server (192.168.10.163 above), the context looks like this:

[testing-in]
exten => _02.,1,Answer
exten => _02.,n,AGI(empty.sh)
exten => _02.,n,Wait(5)
exten => _02.,n,Playback(demo-congrats)
exten => _02.,n,Hangup

In the test, I used SIP to register to the reception server.

When the call comes in from the reception server, the empty.sh shell script is executed. In our test, the script is executable but is empty (no executable statements inside, with just the shebang line). But the channel seems to hangup shortly after the AGI script completes. Wait() no longer waits anymore, and the Playback() was skipped. But if I remove the AGI() call, this channel hangup no longer occurs.

The actual AGI script (Perl) itself is a pretty complex one, but we have ascertained there is no error or even warnings generated from the script, and the logging system implemented in the script itself also did not record any abnormal status. "agi debug" also does not show anything unusual too.

Note that it is the AGI() call that apparently cause the channel to hangup, so I suppose it is not related to the SIGHUP issue to Perl AGI scripts previously mentioned here. There is no apparent premature termination of the AGI script in my specific case. It's the channel hangup that appears mysterious.

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

Trixbox 2.2
Comments:By: Tilghman Lesher (tilghman) 2007-06-16 00:14:07

In your verbose output, there is a line that looks like:
AGI Script %s completed, returning %d

Please paste that line here.
By: Bernard Chan (cbkihong) 2007-06-16 09:08:36

AGI Script empty.sh completed, returning 0
By: Joshua C. Colp (jcolp) 2007-06-18 12:22:34

I've been unable to reproduce this so what would be handy is the console output from both servers, plus an iax2 debug. Thanks.
By: Bernard Chan (cbkihong) 2007-06-19 21:05:04

Here are the console output of reception server (192.168.10.162) with iax2 debug:

asterisk1*CLI>
   -- Executing Answer("SIP/voiptest-0819a8a0", "") in new stack
   -- Executing Dial("SIP/voiptest-0819a8a0", "IAX2/from-dialup:from-dialup@192.168.10.163/02555") in new stack
   -- Called from-dialup:from-dialup@192.168.10.163/02555
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW
  Timestamp: 00003ms  SCall: 00013  DCall: 00000 [192.168.10.163:4569]
  VERSION         : 2
  CALLED NUMBER   : 02555
  CODEC_PREFS     : (ulaw|alaw|gsm)
  CALLING NUMBER  : voiptest
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 0
  CALLING TRANSIT : 0
  CALLING NAME    : Dragon Test
  LANGUAGE        : en
  USERNAME        : from-dialup
  FORMAT          : 4
  CAPABILITY      : 63502
  ADSICPE         : 2
  DATE TIME       : 2007-06-20  10:00:50

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00013ms  SCall: 00007  DCall: 00013 [192.168.10.163:4569]
  AUTHMETHODS     : 3
  CHALLENGE       : 735534299
  USERNAME        : from-dialup

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00008ms  SCall: 00013  DCall: 00007 [192.168.10.163:4569]
  MD5 RESULT      : 1103e28fb4a2566ca723b7a947733237

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 00020ms  SCall: 00007  DCall: 00013 [192.168.10.163:4569]
  FORMAT          : 4

   -- Call accepted by 192.168.10.163 (format ulaw)
   -- Format for call is ulaw
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
  Timestamp: 00020ms  SCall: 00013  DCall: 00007 [192.168.10.163:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
  Timestamp: 00023ms  SCall: 00007  DCall: 00013 [192.168.10.163:4569]
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
  Timestamp: 00023ms  SCall: 00013  DCall: 00007 [192.168.10.163:4569]
   -- IAX2/192.168.10.163:4569-13 answered SIP/voiptest-0819a8a0
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: IAX     Subclass: HANGUP
  Timestamp: 00033ms  SCall: 00007  DCall: 00013 [192.168.10.163:4569]
  CAUSE CODE      : 0

Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
  Timestamp: 00033ms  SCall: 00013  DCall: 00007 [192.168.10.163:4569]
   -- Hungup 'IAX2/192.168.10.163:4569-13'
 == Spawn extension (testing-in, 111, 2) exited non-zero on 'SIP/voiptest-0819a8a0'


For the termination server (192.168.10.163) with iax2 debug:

asterisk1*CLI>
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW
  Timestamp: 00003ms  SCall: 00013  DCall: 00000 [192.168.10.162:4569]
  VERSION         : 2
  CALLED NUMBER   : 02555
  CODEC_PREFS     : (ulaw|alaw|gsm)
  CALLING NUMBER  : voiptest
  CALLING PRESNTN : 0
  CALLING TYPEOFN : 0
  CALLING TRANSIT : 0
  CALLING NAME    : Dragon Test
  LANGUAGE        : en
  USERNAME        : from-dialup
  FORMAT          : 4
  CAPABILITY      : 63502
  ADSICPE         : 2
  DATE TIME       : 2007-06-20  10:00:50

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00013ms  SCall: 00007  DCall: 00013 [192.168.10.162:4569]
  AUTHMETHODS     : 3
  CHALLENGE       : 735534299
  USERNAME        : from-dialup

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00008ms  SCall: 00013  DCall: 00007 [192.168.10.162:4569]
  MD5 RESULT      : 1103e28fb4a2566ca723b7a947733237

   -- Accepting AUTHENTICATED call from 192.168.10.162:
      > requested format = ulaw,
      > requested prefs = (ulaw|alaw|gsm),
      > actual format = ulaw,
      > host prefs = (ulaw|alaw|gsm),
      > priority = mine
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 00020ms  SCall: 00007  DCall: 00013 [192.168.10.162:4569]
  FORMAT          : 4

   -- Executing Answer("IAX2/from-dialup-7", "") in new stack
   -- Executing AGI("IAX2/from-dialup-7", "empty.sh") in new stack
   -- Launched AGI Script /var/lib/asterisk/agi-bin/empty.sh
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
  Timestamp: 00020ms  SCall: 00013  DCall: 00007 [192.168.10.162:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
  Timestamp: 00023ms  SCall: 00007  DCall: 00013 [192.168.10.162:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
  Timestamp: 00023ms  SCall: 00013  DCall: 00007 [192.168.10.162:4569]
   -- AGI Script empty.sh completed, returning 0
   -- Executing Wait("IAX2/from-dialup-7", "5") in new stack
 == Spawn extension (testing-in, 02555, 3) exited non-zero on 'IAX2/from-dialup-7'
   -- Hungup 'IAX2/from-dialup-7'
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: IAX     Subclass: HANGUP
  Timestamp: 00033ms  SCall: 00007  DCall: 00013 [192.168.10.162:4569]
  CAUSE CODE      : 0

Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX     Subclass: ACK
  Timestamp: 00033ms  SCall: 00013  DCall: 00007 [192.168.10.162:4569]
By: James MacLean (macleajb) 2007-06-20 08:05:26

Seeing hangup here also from a Dial-ed connection. Occurs after AGI (which can be anything) returns and a Playback or Background cmd is issued. That attempted command exits with:

-- Executing BackGround("IAX2/trix-1", "custom/SA_Intro") in new stack
-- Playing 'custom/SA_Intro' (language 'en')
== Spawn extension (ivr-2, s, 10) exited non-zero on 'IAX2/trix-1'

Works fine if connected direct and not bouncing off another Asterisk server.

Called box is :
Asterisk 1.2.18 built by root @ build.trixbox.org on a i686 running Linux on 2007-04-25 19:59:21 UTC

Calling box is :
Asterisk 1.2.19 built by root @ Asterisk on a i686 running Linux on 2007-06-20 14:03:55 UTC
By: Bernard Chan (cbkihong) 2007-06-21 22:29:43

We just have a chance to test this again on an AsteriskNOW based environment. With Asterisk 1.4.4 on both sides, there were no such issue. So I guess that would probably be some bug associated with the Asterisk 1.2 branch.
By: Jason Parker (jparker) 2007-08-20 16:14:30

Closing, since this is fixed in 1.4.