Want to protect your cyber security and still get fast solutions? Ask a secure question today.Go Premium

x
?
Solved

Intermittent no audio on incoming calls

Posted on 2009-12-16
17
Medium Priority
?
1,461 Views
Last Modified: 2013-12-21
First ever question so hope everything is ok with information provided.

OS: CentOS
PS: AsteriskNOW

We seem to be having intermittent audio issues on our incoming IAX calls, out of 10 calls placed 4 calls worked perfectly and 6 calls failed with no audio. When we place a call to our phone system from an external landline/mobile they are not hearing anything at their end (even though our phone is ringing) when answered the line still has no audio and after a short period of time the call disconnects. As part of the troubleshooting we gave the server a public ip and disabled apf, flushed all the rules out of iptables, set DTMF to auto and allow alaw only. Below is an iax debug output on a call without audio.

Thanks for your time.

Additional note:
We have more IAX DDIs that are working without any problems all coming over the same trunk, the only thing different is that this number was ported from BT

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW
   Timestamp: 00005ms  SCall: 00034  DCall: 00000 [a.b.c.d:4569]
   VERSION         : 2
   CALLED NUMBER   : <masked>
   CODEC_PREFS     : ()
   CALLING NUMBER  : <masked>
   CALLING PRESNTN : 0
   CALLING TYPEOFN : 0
   CALLING TRANSIT : 0
   CALLING NAME    : <masked>
   LANGUAGE        : en
   USERNAME        : <masked>
   FORMAT          : 8
   CAPABILITY      : 65407
   ADSICPE         : 2
   DATE TIME       : 2009-12-16  22:22:58
79*CLI>
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
   Timestamp: 00012ms  SCall: 00438  DCall: 00034 [a.b.c.d:4569]
   AUTHMETHODS     : 3
   CHALLENGE       : 393122854
   USERNAME        : <masked>

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
   Timestamp: 00052ms  SCall: 00034  DCall: 00438 [a.b.c.d:4569]
   MD5 RESULT      : <masked>
79*CLI>
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
   Timestamp: 00055ms  SCall: 00438  DCall: 00034 [a.b.c.d:4569]
   FORMAT          : 8

Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
   Timestamp: 00055ms  SCall: 00034  DCall: 00438 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: RINGING
   Timestamp: 00058ms  SCall: 00438  DCall: 00034 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00058ms  SCall: 00034  DCall: 00438 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: LAGRQ
   Timestamp: 10004ms  SCall: 00034  DCall: 00438 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: LAGRP
   Timestamp: 10004ms  SCall: 00438  DCall: 00034 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: LAGRQ
   Timestamp: 10012ms  SCall: 00438  DCall: 00034 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 10004ms  SCall: 00034  DCall: 00438 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX     Subclass: LAGRP
   Timestamp: 10012ms  SCall: 00034  DCall: 00438 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 10012ms  SCall: 00438  DCall: 00034 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: HANGUP
   Timestamp: 19065ms  SCall: 00034  DCall: 00438 [a.b.c.d:4569]
   CAUSE CODE      : 0
79*CLI>
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 19065ms  SCall: 00438  DCall: 00034 [a.b.c.d:4569]

Open in new window

0
Comment
Question by:MadBarry101
  • 10
  • 7
17 Comments
 
LVL 7

Expert Comment

by:icenick
ID: 26070539
Dear MadBarry101,

I suggest first you download and install wireshark. Wireshark is a packet sniffing tool that will help you capture calls and monitor them on the protocol level.

It will give you an idea on what is happening to the media stream (RTP) after call has been answered (sip 200 OK).

http://www.wireshark.org/
0
 

Author Comment

by:MadBarry101
ID: 26070698
Hi icenick,
Thankyou for your reply. Our server has 2 interfaces one for local lan and 1 for the internet, currently I've been using a windows box to capture traffic via wireshark and have been monitoring the net side interface so no sip packets are being monitored only iax2 are showing in wireshark, should I be looking at the lan side interface?

Thanks again
0
 
LVL 7

Expert Comment

by:icenick
ID: 26070737
Dear MadBarry101,

Sorry for referring to sip instead of iax2. I am used to work with sip, that's why.

As far as I know, wireshark captures all kind of traffic. Can you trace an iax2 call and try to figure out after the call is accepted, what happens to the media stream?

Can you do that?
0
Configuration Guide and Best Practices

Read the guide to learn how to orchestrate Data ONTAP, create application-consistent backups and enable fast recovery from NetApp storage snapshots. Version 9.5 also contains performance and scalability enhancements to meet the needs of the largest enterprise environments.

 

Author Comment

by:MadBarry101
ID: 26070849
Hi icenick,
I'm sort of learning as we go on this, should have stuck to sip, much eaiser to see things. When I select one of the IAX calls(with no audio) there are some entries there for that one call

Local = Asterisk IP
Remote = TISP IP

Source | Destination | Protocol | Info

Remote | Local | IAX2 | IAX, source call# 42, timestamp 9ms NEW
Local | Remote | IAX2 | IAX, source call# 1374, timestamp 12 AUTHREQ
Remote | Local | IAX2 | IAX, source call# 42, timestamp 52ms AUTHREP
Local | Remote | IAX2 | IAX, source call#1374, timestamp 55ms ACCEPT
Remote | Local | IAX2 | IAX, source call# 42, timestamp 55ms ACK
Local | Remote | IAX2 | IAX, Control, source call# 1374, timestamp 58ms RINGING
Remote | Local | IAX2 | IAX, source call# 42, timestamp 58ms ACK
Remote | Local | IAX2 | IAX, source call# 42, timestamp 2446ms HANGUP
Local | Remote | IAX2 | IAX, source call# 1374, timestamp 2446ms ACK
0
 

Author Comment

by:MadBarry101
ID: 26070916
When I look at a successful call it seems to have more entries, specifically and stop sounds and answer (see pic)
IAX2.PNG
0
 
LVL 7

Expert Comment

by:icenick
ID: 26070956
Dear MadBarry101,

I read your question again and I want to ask you this:

How do you receive the calls from external landline/mobile into your phone system?

From the above entries, it seems that the remote side sends a HANGUP request after RINGING. The call is not answered at all.
0
 

Author Comment

by:MadBarry101
ID: 26071007
Hi icenick,
From my understanding the number we are having problems with comes in this way

External Telco -> TSIP -> My system

I have an support ticket open with my TISP and they tell me that thier telco(who deal with there ported numbers) are reporting that everything at there end is fine and keep getting me to troubleshoot it at my phone system
0
 

Author Comment

by:MadBarry101
ID: 26071014
That should have been

"External Telco -> TISP -> My system"

0
 
LVL 7

Expert Comment

by:icenick
ID: 26071075
Dear MadBarry101,

We have a toll free number connected to a cisco voice gateway. I send all calls that hit the cisco ( and of course that match the dial peer in the cisco) to an Asterisk server. We use SIP.

I had some difficulties in configuring Asterisk to receive calls from cisco. I had hits on asterisk but calls failed. After some time, I found that by adding "insecure=very" to my sip.conf solved the problem.

Also, I had a lot of problems dealing with calls that use progress indicator. After all, I stopped to use progress in my calls.

I can't figure out what is really going in your case. Can you post messages from your asterisk terminal?




0
 

Author Comment

by:MadBarry101
ID: 26074272
Sorry for the delay, it was hard to get a clean copy with people redialing in,verbose level was at 3 when I got this dump. No one is in the office to answer the call so this one should have rang for a short time and then when to voicemail
-- Accepting AUTHENTICATED call from a.b.c.d:
       > requested format = alaw,
       > requested prefs = (),
       > actual format = alaw,
       > host prefs = (alaw),
       > priority = mine
    -- Executing [<CLID>@from-pstn:1] Set("IAX2/<UNAME>-9588", "__FROM_DID=<CLID>") in new stack
    -- Executing [<CLID>@from-pstn:2] Gosub("IAX2/<UNAME>-9588", "cidlookup|cidlookup_2|1") in new stack
    -- Executing [cidlookup_2@cidlookup:1] LookupCIDName("IAX2/<UNAME>-9588", "") in new stack
    -- Changed Caller*ID name to <MYNAME>
    -- Executing [cidlookup_2@cidlookup:2] Return("IAX2/<UNAME>-9588", "") in new stack
    -- Executing [<CLID>@from-pstn:3] ExecIf("IAX2/<UNAME>-9588", "0 |Set|CALLERID(name)=<MYMOBILENUMBER>") in new stack
    -- Executing [<CLID>@from-pstn:4] Set("IAX2/<UNAME>-9588", "__CALLINGPRES_SV=allowed_not_screened") in new stack
    -- Executing [<CLID>@from-pstn:5] SetCallerPres("IAX2/<UNAME>-9588", "allowed_not_screened") in new stack
    -- Executing [<CLID>@from-pstn:6] Goto("IAX2/<UNAME>-9588", "ext-group|603|1") in new stack
    -- Goto (ext-group,603,1)
    -- Executing [603@ext-group:1] Macro("IAX2/<UANME>-9588", "user-callerid|") in new stack
    -- Executing [s@macro-user-callerid:1] Set("IAX2/<UNAME>-9588", "AMPUSER=<MYMOBILENUMBER>") in new stack
    -- Executing [s@macro-user-callerid:2] GotoIf("IAX2/<UNAME-9588", "0?report") in new stack
    -- Executing [s@macro-user-callerid:3] ExecIf("IAX2/<UNAME>-9588", "1|Set|REALCALLERIDNUM=<MYMOBILENUMBER>") in new stack
    -- Executing [s@macro-user-callerid:4] Set("IAX2/<UNAME>-9588", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:5] Set("IAX2/<UNAME>-9588", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:6] GotoIf("IAX2/<UNAME>-9588", "1?report") in new stack
    -- Goto (macro-user-callerid,s,10)
    -- Executing [s@macro-user-callerid:10] GotoIf("IAX2/<UNAME>-9588", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:11] Set("IAX2/<UNAME>-9588", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:12] GotoIf("IAX2/<UNAME>-9588", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,19)
    -- Executing [s@macro-user-callerid:19] NoOp("IAX2/<UNAME>-9588", "Using CallerID "MYNAME" <MYMOBILENUMBER>") in new stack
    -- Executing [603@ext-group:2] GotoIf("IAX2/<UNAME>-9588", "1?skipdb") in new stack
    -- Goto (ext-group,603,4)
    -- Executing [603@ext-group:4] Set("IAX2/<UNAME>-9588", "__NODEST=") in new stack
    -- Executing [603@ext-group:5] Set("IAX2/<UNAME>-9588", "__BLKVM_OVERRIDE=BLKVM/603/IAX2/<UNAME>-9588") in new stack
    -- Executing [603@ext-group:6] Set("IAX2/<UNAME>-9588", "__BLKVM_BASE=603") in new stack
    -- Executing [603@ext-group:7] Set("IAX2/<UNAME>-9588", "DB(BLKVM/603/IAX2/<UNAME>-9588)=TRUE") in new stack
    -- Executing [603@ext-group:8] Set("IAX2/<UNAME>-9588", "RRNODEST=") in new stack
    -- Executing [603@ext-group:9] Set("IAX2/<UNAME>-9588", "__NODEST=603") in new stack
    -- Executing [603@ext-group:10] GotoIf("IAX2/<UNAME>-9588", "1?REPCID") in new stack
    -- Goto (ext-group,603,15)
    -- Executing [603@ext-group:15] NoOp("IAX2/<UNAME>-9588", "CALLERID(name) is <MYNAME>") in new stack
    -- Executing [603@ext-group:16] Set("IAX2/<UNAME>-9588", "_RGPREFIX=<PREFIXCLID>") in new stack
    -- Executing [603@ext-group:17] Set("IAX2/<UNAME>-9588", "CALLERID(name)=<MYNAME>") in new stack
    -- Executing [603@ext-group:18] Set("IAX2/<UNAME>-9588", "__CWIGNORE=TRUE") in new stack
    -- Executing [603@ext-group:19] Set("IAX2/<UNAME>-9588", "_CFIGNORE=TRUE") in new stack
    -- Executing [603@ext-group:20] Set("IAX2/<UNAME>-9588", "_FORWARD_CONTEXT=block-cf") in new stack
    -- Executing [603@ext-group:21] Set("IAX2/<UNAME>-9588", "RecordMethod=Group") in new stack
    -- Executing [603@ext-group:22] Macro("IAX2/<UNAME>-9588", "record-enable|<EXTENSIONS>|Group") in new stack
    -- Executing [s@macro-record-enable:1] GotoIf("IAX2/<UNAME>-9588", "1?check") in new stack
    -- Goto (macro-record-enable,s,4)
    -- Executing [s@macro-record-enable:4] AGI("IAX2/<UNAME>-9588", "recordingcheck|20091217-181457|1261073697.1022") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
    -- AGI Script recordingcheck completed, returning 0
    -- Executing [s@macro-record-enable:5] MacroExit("IAX2/<UNAME>-9588", "") in new stack
    -- Executing [603@ext-group:23] Set("IAX2/<UNAME>-9588", "RingGroupMethod=ringall") in new stack
    -- Executing [603@ext-group:24] Macro("IAX2/<UNAME>-9588", "dial|20|tr|<EXTENSIONS>") in new stack
    -- Executing [s@macro-dial:1] GotoIf("IAX2/<UNAME>-9588", "1?dial") in new stack
    -- Goto (macro-dial,s,3)
    -- Executing [s@macro-dial:3] AGI("IAX2/<UNAME>-9588", "dialparties.agi") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
  dialparties.agi: Starting New Dialparties.agi
  == Parsing '/etc/asterisk/manager.conf': Found
  == Parsing '/etc/asterisk/manager_additional.conf': Found
  == Parsing '/etc/asterisk/manager_custom.conf': Found
  == Manager 'admin' logged on from 127.0.0.1
  dialparties.agi: Caller ID name is '<MYNAME>' number is '<MYMOBILENUMBER>'
  dialparties.agi: Methodology of ring is  'ringall'
    --  dialparties.agi: Added extension <EXTENSION> to extension map
    --  dialparties.agi: Added extension <EXTENSION> to extension map
    --  dialparties.agi: Extension <EXTENSION> cf is disabled
    --  dialparties.agi: Extension <EXTENSION> cf is disabled
    --  dialparties.agi: Extension <EXTENSION> do not disturb is disabled
    --  dialparties.agi: Extension <EXTENSION> do not disturb is disabled
  dialparties.agi: ExtensionState: 0
  dialparties.agi: Extension <EXTENSION> has ExtensionState: 0
    --  dialparties.agi: Checking CW and CFB status for extension <EXTENSION>
    --  dialparties.agi: dbset CALLTRACE/<EXTENSION> to <MYNUMBER>
  dialparties.agi: ExtensionState: 0
  dialparties.agi: Extension <EXTENSION> has ExtensionState: 0
    --  dialparties.agi: Checking CW and CFB status for extension <EXTENSION>
    --  dialparties.agi: dbset CALLTRACE/<EXTENSION> to <MYNUMBER>
    --  dialparties.agi: Filtered ARG3: <EXTENSIONS>
  == Manager 'admin' logged off from 127.0.0.1
    -- AGI Script dialparties.agi completed, returning 0
    -- Executing [s@macro-dial:7] Dial("IAX2/<UNAME>-9588", "SIP/<EXTENSIONS>&SIP/<EXTENSIONS>|20|trM(auto-blkvm)") in new stack
    -- Called <EXTENSIONS>
    -- Called <EXTENSIONS>
    -- SIP/<EXTENSIONS>-c4011e40 is ringing
    -- SIP/<EXTENSIONS>-c400e550 is ringing
  == Spawn extension (macro-dial, s, 7) exited non-zero on 'IAX2/<UNAME>-9588' in macro 'dial'
  == Spawn extension (ext-group, 603, 24) exited non-zero on 'IAX2/<UNAME>-9588'
    -- Executing [h@macro-dial:1] Macro("IAX2/<UNAME>-9588", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("IAX2/<UNAME>-9588", "1?skiprg") in new stack
    -- Goto (macro-hangupcall,s,4)
    -- Executing [s@macro-hangupcall:4] GotoIf("IAX2/<UNAME>-9588", "0?skipblkvm") in new stack
    -- Executing [s@macro-hangupcall:5] NoOp("IAX2/<UNAME>-9588", "Cleaning Up Block VM Flag: BLKVM/603/IAX2/<UNAME>-9588") in new stack
    -- Executing [s@macro-hangupcall:6] DBdel("IAX2/<UNAME>-9588", "BLKVM/603/IAX2/<UNAME>-9588") in new stack
    -- DBdel: family=BLKVM, key=603/IAX2/<UNAME>-9588
    -- Executing [s@macro-hangupcall:7] GotoIf("IAX2/<UNAME>-9588", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,9)
    -- Executing [s@macro-hangupcall:9] Hangup("IAX2/<UNAME>-9588", "") in new stack
  == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'IAX2/<UNAME>-9588' in macro 'hangupcall'
  == Spawn extension (macro-dial, h, 1) exited non-zero on 'IAX2/<UNAME>-9588'
    -- Hungup 'IAX2/<UNAME>-9588'

Open in new window

0
 
LVL 7

Expert Comment

by:icenick
ID: 26074720
Dear MadBarry101,

From the messages above, I noticed that you are trying to ring all. Is that right?

Lines 85 and 86 is trying to dial two SIP extensions. Both are ringing and then they hangup. From your initial message you mentioned that out of the 10 calls, only 4 go through.

Is it always 10 calls together? Can you describe the scenario more?

All I can think of now is queuing.

Take a look at the following:

http://www.voip-info.org/wiki/view/Asterisk+call+queues

http://www.voip-info.org/wiki/view/Asterisk+cmd+Queue

Hope they can bring some light to this.
0
 

Author Comment

by:MadBarry101
ID: 26075412
Evening icenick,
I should have enabled IAX debugging when I took the dump, its not the phones that are generating the hangup (see code)

Our asterisk server has over 36 DDIs coming in from our TISP over a single trunk, only one number is being affected by this issue and the only thing different from the other numbers is that it was a ported number from BT. My TISP lets an external telco manage these numbers, currently when a call is made to this number it goes to a ring group with the ringall option, 2 phones are in this group. Internal call to this ring group work as expected, call to the 2 phones directly on their DDI/EXT work as expected.

As for the failed calls, there doesn't seem to be any pattern to it and I only placed 10 calls to test it out but sometimes there can be 3 good and then some bad but still very random.

Hope this helps some more and I really appreciate your help.

  == Manager 'admin' logged off from 127.0.0.1
    -- AGI Script dialparties.agi completed, returning 0
    -- Executing [s@macro-dial:7] Dial("IAX2/<UNAME>-237", "SIP/<EXTENSION>&SIP/<EXTENSION>|20|trM(auto-blkvm)") in new stack
    -- Called <EXTENSION>
    -- Called <EXTENSION>
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: RINGING
   Timestamp: 00054ms  SCall: 00237  DCall: 00012 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00054ms  SCall: 00012  DCall: 00237 [a.b.c.d:4569]
    -- SIP/<EXTENSION>-c4011e40 is ringing
    -- SIP/<EXTENSION>-c400e550 is ringing
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
   Timestamp: 00006ms  SCall: 01822  DCall: 00000 [a.b.c.d:4569]
79*CLI>
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
   Timestamp: 00006ms  SCall: 32682  DCall: 01822 [a.b.c.d:4569]
79*CLI>
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
   Timestamp: 00006ms  SCall: 01822  DCall: 32682 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: LAGRQ
   Timestamp: 10009ms  SCall: 00012  DCall: 00237 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: LAGRP
   Timestamp: 10009ms  SCall: 00237  DCall: 00012 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: LAGRQ
   Timestamp: 10009ms  SCall: 00237  DCall: 00012 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 10009ms  SCall: 00012  DCall: 00237 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX     Subclass: LAGRP
   Timestamp: 10009ms  SCall: 00012  DCall: 00237 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 10009ms  SCall: 00237  DCall: 00012 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: HANGUP
   Timestamp: 18830ms  SCall: 00012  DCall: 00237 [a.b.c.d:4569]
   CAUSE CODE      : 0
79*CLI>
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: ACK
   Timestamp: 18830ms  SCall: 00237  DCall: 00012 [a.b.c.d:4569]
  == Spawn extension (macro-dial, s, 7) exited non-zero on 'IAX2/<UNAME>-237' in macro 'dial'
  == Spawn extension (ext-group, 603, 24) exited non-zero on 'IAX2/<UNAME>-237'
    -- Executing [h@macro-dial:1] Macro("IAX2/<UNAME>-237", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("IAX2/<UNAME>-237", "1?skiprg") in new stack
    -- Goto (macro-hangupcall,s,4)
    -- Executing [s@macro-hangupcall:4] GotoIf("IAX2/<UNAME>-237", "0?skipblkvm") in new stack
    -- Executing [s@macro-hangupcall:5] NoOp("IAX2/<UNAME>-237", "Cleaning Up Block VM Flag: BLKVM/603/IAX2/<UNAME>-237") in new stack
    -- Executing [s@macro-hangupcall:6] DBdel("IAX2/<UNAME>-237", "BLKVM/603/IAX2/<UNAME>-237") in new stack
    -- DBdel: family=BLKVM, key=603/IAX2/<UNAME>-237
    -- Executing [s@macro-hangupcall:7] GotoIf("IAX2/<UNAME>-237", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,9)
    -- Executing [s@macro-hangupcall:9] Hangup("IAX2/<UNAME>-237", "") in new stack
  == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'IAX2/<UNAME>-237' in macro 'hangupcall'
  == Spawn extension (macro-dial, h, 1) exited non-zero on 'IAX2/<UNAME>-237'
    -- Hungup 'IAX2/<UNAME>-237'
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
   Timestamp: 00017ms  SCall: 04072  DCall: 00000 [a.b.c.d:4569]

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
   Timestamp: 00017ms  SCall: 32747  DCall: 04072 [a.b.c.d:4569]

Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
   Timestamp: 00017ms  SCall: 04072  DCall: 32747 [a.b.c.d:4569]

Open in new window

0
 
LVL 7

Accepted Solution

by:
icenick earned 2000 total points
ID: 26076130
In the messages above, I see poke/pong and lagrq/lagrp. Does poke/pong, lagrq/lagrp appear for all the calls (succeeded and failed)?

I found this regarding LAGRQ (here is the source http://lists.digium.com/pipermail/asterisk-dev/2005-April/011593.html):

LAGRQ      A LAGRQ is a lag request.  It is sent to determine the lag between      2 IAX endpoints, including the amount of time used to process a      frame through a jitterbuffer (if any).  It requires a clock-based      timestamp, and must be answered with a LAGRP, which must echo the      LAGRQ's timestamp.  The lag between the 2 peers can be computed on      the peer sending the LAGRQ by comparing the timestamp of the LAGRQ      and the time the LAGRP was received.I'd say we should really just deprecate LAGRQ;  The present implementation (or, last I looked) tried to send the LAGRQ through the jitterbuffer on one end, and then the LAGRP through the jitterbuffer on the other end.  This often really broke things, because the LAGRP has the wrong end's timestamp, and therefore, if the clocks between both sides have skewed, just gave you nonesense results.  Using the RR IE's in PONGs is probably a better way to get the same information.I think if we marked it as deprecated, and said that compliant implementations should not send LAGRQ, and should acknowledge and then ignore them if they are received, nothing would break (because it's just used for display in iax2 show channels, and even there, that command would show zero lag if it never received LAGRP.
You should take a look at this.  It's very interesting:

http://www.rfc-editor.org/authors/rfc5456.txt

What I have understood so far is that poke/pong and lagrq/lagrp should always has the same timestamp value. From the messages above, timestamp values match so I think those messages are fine.

After those messages there is hangup. Something is missing here (since timestamps match). Can't figure out what is wrong.
0
 

Author Comment

by:MadBarry101
ID: 26076334
Over the course of the call, yes they do. Thank for that link I'll have a read over it now
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
   Timestamp: 00047ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: RINGING
   Timestamp: 00050ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
   Timestamp: 00050ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: LAGRQ
   Timestamp: 10012ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: LAGRP
   Timestamp: 10012ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 003 Type: IAX     Subclass: LAGRQ
   Timestamp: 10004ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 10012ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX     Subclass: LAGRP
   Timestamp: 10004ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: ACK
   Timestamp: 10004ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: LAGRQ
   Timestamp: 20012ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: LAGRP
   Timestamp: 20012ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 005 Type: IAX     Subclass: LAGRQ
   Timestamp: 20005ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 006 Type: IAX     Subclass: ACK
   Timestamp: 20012ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 007 Type: IAX     Subclass: LAGRP
   Timestamp: 20005ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 007 ISeqno: 006 Type: IAX     Subclass: ACK
   Timestamp: 20005ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 006 Type: CONTROL Subclass: (255?)
   Timestamp: 20051ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 006 Type: CONTROL Subclass: ANSWER
   Timestamp: 20054ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 006 Type: CONTROL Subclass: (255?)
   Timestamp: 20057ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 010 ISeqno: 006 Type: VOICE   Subclass: 8
   Timestamp: 20160ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 008 Type: IAX     Subclass: ACK
   Timestamp: 20051ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 009 Type: IAX     Subclass: ACK
   Timestamp: 20054ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 010 Type: IAX     Subclass: ACK
   Timestamp: 20057ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 011 Type: IAX     Subclass: ACK
   Timestamp: 20160ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 011 Type: CONTROL Subclass: (20?)
   Timestamp: 20238ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 007 Type: IAX     Subclass: ACK
   Timestamp: 20238ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 011 Type: VOICE   Subclass: 8
   Timestamp: 20246ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 008 Type: IAX     Subclass: ACK
   Timestamp: 20246ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 011 Type: CONTROL Subclass: (20?)
   Timestamp: 20249ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 009 Type: IAX     Subclass: ACK
   Timestamp: 20249ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 011 Type: CONTROL Subclass: (20?)
   Timestamp: 20252ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 010 Type: IAX     Subclass: ACK
   Timestamp: 20252ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 011 Type: IAX     Subclass: PING
   Timestamp: 21012ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 011 ISeqno: 011 Type: IAX     Subclass: PONG
   Timestamp: 21012ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
   RR_JITTER       : 0
   RR_LOSS         : 0
   RR_PKTS         : 1
   RR_DELAY        : 40
   RR_DROPPED      : 0
   RR_OUTOFORDER   : 0

Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 011 Type: IAX     Subclass: PING
   Timestamp: 21022ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 012 Type: IAX     Subclass: ACK
   Timestamp: 21012ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 013 Type: IAX     Subclass: PONG
   Timestamp: 21022ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
   RR_JITTER       : 0
   RR_LOSS         : 0
   RR_PKTS         : 1
   RR_DELAY        : 40
   RR_DROPPED      : 0
   RR_OUTOFORDER   : 0
79*CLI>
Tx-Frame Retry[-01] -- OSeqno: 013 ISeqno: 012 Type: IAX     Subclass: ACK
   Timestamp: 21022ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 012 ISeqno: 013 Type: IAX     Subclass: LAGRQ
   Timestamp: 30012ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 013 ISeqno: 013 Type: IAX     Subclass: LAGRP
   Timestamp: 30012ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 014 ISeqno: 013 Type: IAX     Subclass: LAGRQ
   Timestamp: 30020ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 014 Type: IAX     Subclass: ACK
   Timestamp: 30012ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 013 ISeqno: 015 Type: IAX     Subclass: LAGRP
   Timestamp: 30020ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 015 ISeqno: 014 Type: IAX     Subclass: ACK
   Timestamp: 30020ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 015 ISeqno: 014 Type: CONTROL Subclass: VIDUPDT
   Timestamp: 39567ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 014 ISeqno: 016 Type: IAX     Subclass: ACK
   Timestamp: 39567ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 014 ISeqno: 016 Type: IAX     Subclass: LAGRQ
   Timestamp: 40011ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 016 ISeqno: 015 Type: IAX     Subclass: LAGRP
   Timestamp: 40011ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 017 ISeqno: 015 Type: IAX     Subclass: LAGRQ
   Timestamp: 39996ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 015 ISeqno: 017 Type: IAX     Subclass: ACK
   Timestamp: 40011ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 015 ISeqno: 018 Type: IAX     Subclass: LAGRP
   Timestamp: 39996ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 018 ISeqno: 016 Type: IAX     Subclass: ACK
   Timestamp: 39996ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 016 ISeqno: 018 Type: CONTROL Subclass: (20?)
   Timestamp: 40609ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
Tx-Frame Retry[-01] -- OSeqno: 018 ISeqno: 017 Type: IAX     Subclass: ACK
   Timestamp: 40609ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Rx-Frame Retry[ No] -- OSeqno: 017 ISeqno: 018 Type: IAX     Subclass: HANGUP
   Timestamp: 40626ms  SCall: 00015  DCall: 04094 [a.b.c.d:4569]
   CAUSE CODE      : 16
79*CLI>
Tx-Frame Retry[-01] -- OSeqno: 018 ISeqno: 018 Type: IAX     Subclass: ACK
   Timestamp: 40626ms  SCall: 04094  DCall: 00015 [a.b.c.d:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
   Timestamp: 00019ms  SCall: 03539  DCall: 00000 [a.b.c.d:4569]
79*CLI>
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
   Timestamp: 00019ms  SCall: 32747  DCall: 03539 [a.b.c.d:4569]

Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
   Timestamp: 00019ms  SCall: 03539  DCall: 32747

Open in new window

0
 

Author Comment

by:MadBarry101
ID: 26091543
Hi icenick, The TISP where trying to diagnose it from there end on Firday although they said they couldn't find any problems the issue has seem to have mysteriously subsided. I will allocate you the point for your great effort in trying to get to the root of the cause. Thanks agin.
0
 

Author Closing Comment

by:MadBarry101
ID: 31667069
Although we didn't find the issue icenick was very helpful and tried to get to the problem
0
 
LVL 7

Expert Comment

by:icenick
ID: 26091648
Dear MadBarry101,

I am glad to hear that the problem is solved after all. Thanks for the points.

I will be here in the future if you need any help. Good luck.
0

Featured Post

Get your Disaster Recovery as a Service basics

Disaster Recovery as a Service is one go-to solution that revolutionizes DR planning. Implementing DRaaS could be an efficient process, easily accessible to non-DR experts. Learn about monitoring, testing, executing failovers and failbacks to ensure a "healthy" DR environment.

Question has a verified solution.

If you are experiencing a similar issue, please ask a related question

How To Create Custom / Distinctive Ring Tones on Polycom Phones Purpose and Overview When creating a custom ring tone, you have simple aspirations: to make your phone cooler than everyone else's. Perhaps you need a louder ringer. Perhaps you w…
Skype is a P2P (Peer to Peer) instant messaging and VOIP (Voice over IP) service – as well as a whole lot more.
this video summaries big data hadoop online training demo (http://onlineitguru.com/big-data-hadoop-online-training-placement.html) , and covers basics in big data hadoop .
Exchange organizations may use the Journaling Agent of the Transport Service to archive messages going through Exchange. However, if the Transport Service is integrated with some email content management application (such as an anti-spam), the admin…

580 members asked questions and received personalized solutions in the past 7 days.

Join the community of 500,000 technology professionals and ask your questions.

Join & Ask a Question