Strange 5-25 seconds delay on answering incoming calls

Asterisk Asterisk Support
1

Hello,

I have installed asterisk 1.6 (on centos) and somehow there is a delay in answer. I show the logs, i think it will make clear everything however I do not have timestamps for the logs.

The system is NATed

That happens when someone calls the IVR (from asterisk console):

== Using SIP RTP CoS mark 5
– Executing [xxxxxxxxxx@DID_trunk_1:1] Goto(“SIP/trunk_1-00000009”, “default,7900,1”) in new stack
– Goto (default,7900,1)
– Executing [7900@default:1] Goto(“SIP/trunk_1-00000009”, “voicemenu-custom-2,s,1”) in new stack
– Goto (voicemenu-custom-2,s,1)
– Executing [s@voicemenu-custom-2:1] NoOp(“SIP/trunk_1-00000009”, “IVR_hu”) in new stack
– Executing [s@voicemenu-custom-2:2] Answer(“SIP/trunk_1-00000009”, “”) in new stack <—
– Executing [s@voicemenu-custom-2:3] Set(“SIP/trunk_1-00000009”, “CHANNEL(language)=hu”) in new stack
– Executing [s@voicemenu-custom-2:4] Set(“SIP/trunk_1-00000009”, “modify=0”) in new stack
– Executing [s@voicemenu-custom-2:5] AGI(“SIP/trunk_1-00000009”, “parking/checkuser2.php”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/parking/checkuser2.php
parking/checkuser2.php: Agi started
parking/checkuser2.php: xxxxxxxxxxxx
parking/checkuser2.php: <SIP/trunk_1-00000009>-http://192.168.0.1:81/IVR/mParking_IVR_checkUser.php?callerID=xxxxxxxxxxx@
parking/checkuser2.php: <SIP/trunk_1-00000009>-NextOGM=UserNotRegistered
– <SIP/trunk_1-00000009>AGI Script parking/checkuser2.php completed, returning 0
– Executing [s@voicemenu-custom-2:6] GotoIf(“SIP/trunk_1-00000009”, “0?900”) in new stack
– Executing [s@voicemenu-custom-2:7] GotoIf(“SIP/trunk_1-00000009”, “0?100”) in new stack
– Executing [s@voicemenu-custom-2:8] GotoIf(“SIP/trunk_1-00000009”, “0?200”) in new stack
– Executing [s@voicemenu-custom-2:9] Playback(“SIP/trunk_1-00000009”, “UserNotRegistered”) in new stack
– <SIP/trunk_1-00000009> Playing ‘UserNotRegistered.slin’ (language ‘hu’)
– Executing [s@voicemenu-custom-2:10] GotoIf(“SIP/trunk_1-00000009”, “0?1000”) in new stack
– Executing [s@voicemenu-custom-2:11] GotoIf(“SIP/trunk_1-00000009”, “1?1000”) in new stack
– Goto (voicemenu-custom-2,s,1000)
– Executing [s@voicemenu-custom-2:1000] Playback(“SIP/trunk_1-00000009”, “GoodBye”) in new stack
– <SIP/trunk_1-00000009> Playing ‘GoodBye.slin’ (language ‘hu’)
– Executing [s@voicemenu-custom-2:1001] Hangup(“SIP/trunk_1-00000009”, “”) in new stack
== Spawn extension (voicemenu-custom-2, s, 1001) exited non-zero on ‘SIP/trunk_1-00000009’

Sadly it has no timestamps, but at the asnwer command (<–) it waits for something, but I can’t guess what.

Here is the SIP log between asnwer egy set channel:

– Executing [s@voicemenu-custom-2:2] Answer(“SIP/trunk_1-0000000b”, “”) in new stack
Audio is at 195.70.62.197 port 13770
Adding codec 0x8 (alaw) to SDP
Adding codec 0x100 (g729) to SDP
Adding codec 0x1 (g723) to SDP
Adding non-codec 0x1 (telephone-event) to SDP

<— Reliably Transmitting (NAT) to 195.56.192.1:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 195.56.192.1:5060;branch=z9hG4bK-6B63-381A09;received=195.56.192.1
From: sip:36205222947@datanet.hu;user=phone;tag=15813-JX-0094dfff-118321eb6
To: sip:3619999798@195.70.62.197;user=phone;tag=as3205f41b
Call-ID: 15813-PE-0094dffe-22895b751@datanet.hu
CSeq: 8847380 INVITE
Server: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: sip:3619999798@195.70.62.197
Content-Type: application/sdp
Content-Length: 328

v=0
o=root 875985104 875985104 IN IP4 195.70.62.197
s=Asterisk PBX 1.6.2.12
c=IN IP4 195.70.62.197
t=0 0
m=audio 13770 RTP/AVP 8 18 4 101
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>

<— SIP read from UDP:195.56.192.1:5060 —>
ACK sip:3619999798@195.70.62.197 SIP/2.0
Call-ID: 15813-PE-0094dffe-22895b751@datanet.hu
Contact: sip:195.56.192.1:5060
CSeq: 8847380 ACK
From: sip:36205222947@datanet.hu;user=phone;tag=15813-JX-0094dfff-118321eb6
Max-Forwards: 30
To: sip:3619999798@195.70.62.197;user=phone;tag=as3205f41b
User-Agent: Cirpack/v4.42q (gw_sip)
Via: SIP/2.0/UDP 195.56.192.1:5060;branch=z9hG4bK-5085-381A0A
Content-Length: 0

<------------->
— (10 headers 0 lines) —
– Executing [s@voicemenu-custom-2:3] Set(“SIP/trunk_1-0000000b”, “CHANNEL(language)=hu”) in new stack

I though core set debug 9 would show something, but nothing more.

Any guess?

Thank you in advance!

Thomas

2

Uncomment the full log in logger.conf (assuming you use the sample one as a basis) and you will get a log with timestamps. I’d also advise turning on millisecond timestamps.

3

It seem’s that whole machine stops for a couple of seconds on every Answer. When it’s in that command, I can’t wirte to console, or bash.

I tried it with the console dial command, and that way it has no delay (though I don’t know if it has any connection).

This behaviour has been started when the server was moved to the hostel. This is a replacement to a windows machine, but the IVR program could not communicate with our new provider. The network status is:

Internet <-> other server <-> Asterisk server in private lan (192.168.0.0/24).

Any ideas?

Thanks in advance!

Thomas

4

Sounds like some sort of deadlock or livelock. You need to compile with no optimisation and with thread debugging on. When it freezes, use a dedicated CLI session to run core show locks. Also use gdb to run “thread apply all bt” to try and find any looping thread.

5

Hi!

Thanks I haven’t noticed that I have already made the full log active :smile:

It’s somehow different from what I can see in the console. It looks like this:

[Mar 4 12:56:13] VERBOSE[23551] pbx.c: – Executing [s@voicemenu-custom-2:1] Answer(“SIP/trunk_1-00000024”, “”) in new stack
[Mar 4 12:56:13] VERBOSE[23551] pbx.c: – Executing [s@voicemenu-custom-2:2] Set(“SIP/trunk_1-00000024”, “CHANNEL(language)=hu”) in new stack
[Mar 4 12:56:13] VERBOSE[23551] pbx.c: – Executing [s@voicemenu-custom-2:3] Set(“SIP/trunk_1-00000024”, “modify=0”) in new stack
[Mar 4 12:56:13] VERBOSE[23551] pbx.c: – Executing [s@voicemenu-custom-2:4] AGI(“SIP/trunk_1-00000024”, “parking/checkuser2.php”) in new stack
[Mar 4 12:56:13] VERBOSE[23551] res_agi.c: – Launched AGI Script /var/lib/asterisk/agi-bin/parking/checkuser2.php
[Mar 4 12:56:13] VERBOSE[23551] res_agi.c: parking/checkuser2.php: Agi started
[Mar 4 12:56:13] VERBOSE[23551] res_agi.c: parking/checkuser2.php: 36xxxxxxxxx
[Mar 4 12:56:13] VERBOSE[23551] res_agi.c: parking/checkuser2.php: <SIP/trunk_1-00000024>-http://192.168.0.1:81/IVR/mParking_IVR_checkUser.php?callerID=36xxxxxxxxx@
[Mar 4 12:56:19] VERBOSE[23551] res_agi.c: parking/checkuser2.php: <SIP/trunk_1-00000024>-NextOGM=UserNotRegistered
[Mar 4 12:56:19] VERBOSE[23551] res_agi.c: – <SIP/trunk_1-00000024>AGI Script parking/checkuser2.php completed, returning 0
[Mar 4 12:56:19] VERBOSE[23551] pbx.c: – Executing [s@voicemenu-custom-2:5] GotoIf(“SIP/trunk_1-00000024”, “0?900”) in new stack
[Mar 4 12:56:19] VERBOSE[23551] pbx.c: – Executing [s@voicemenu-custom-2:6] GotoIf(“SIP/trunk_1-00000024”, “0?100”) in new stack
[Mar 4 12:56:19] VERBOSE[23551] pbx.c: – Executing [s@voicemenu-custom-2:7] GotoIf(“SIP/trunk_1-00000024”, “0?200”) in new stack
[Mar 4 12:56:19] VERBOSE[23551] pbx.c: – Executing [s@voicemenu-custom-2:8] Playback(“SIP/trunk_1-00000024”, “UserNotRegistered”) in new stack

As you can see, the full log says, that the delay is in the checkuser.php file, whick does a file_get_contents() for the url above. It takes 5-6 seconds, while the whole system looks frozen. Ocassionally we experience 25-30 seconds of delay.

If I try to get the data from bash it works like charm, with no delay (it an apache, with a less than 50 chars of response).

I also suspect that now this is not the best forum for this problem, but if anyone has an idea, please write it down.

Thanks

Thomas

6

Just to be sure I did this for testing:
php -r ‘echo date(“H-i-s”); echo “\n”;echo file_get_contents(“http://192.168.0.1:81/IVR/mParking_IVR_checkUser.php?callerID=36xxxxxxxxx@”);echo “\n”;echo date(“H-i-s”);echo “\n”;’

It does the same as the AGI PHP script. It has no delay at most, but approx every 10th makes a 3 sec delay, but the server is not freezing…

7

Hi everybody!

I was unable to resolve te issue… The solution was to move the whole system to an other machine.

8

Some of Asterisk modules need to resolve the HOSTNAME. In my case, the server itself cannot solve its own hostname internally. So, I map it in /etc/hosts and the delay issue has been solved.