Long delay in answering

Asterisk Asterisk Support
1

I’m running Asterisk 1.2.4 on Fedora Core 4 where everything I currently need is working to satisfaction. I notice an odd problem once in a while, about once a week, that makes me think Asterisk crashed but when I check I see that it did not.

What happens is that sometimes there is a very, very long delay in answering,close to 1 or 2 minutes (things seem longer when you’re waiting though…). I don’t mean Answer() but the backgound audio of “hello world”, “dial the extension of the party …” or the voice mail prompts. Somwhat like having the dial plan “stuck” at some point. I can’t really pin down the situation that makes this happen but I think that if I make several calls to the voice mail program and hang up without dialing a voice mail number the chances of getting the problem are there.

This is the relevant part of the dial plan where this problem comes up:

…
[incoming]
exten => s,1,Answer( )
exten => s,2,Playback(hello-world)
exten => s,3,Background(enter-ext-of-person)
…

exten => 999,1,VoicemailMain( )

In other words, if I dial 999 I have had 2 situations where it took a minute or more for anything to happen. Same with “hello-world”.

At the moment only about 3 people use this PBX, so I’m somewhat apprehensive when about 30 people would start using it.

Does anybody have an idea of what might be wrong?

2

can you timestamp your logs, make sure they include DEBUG, and post an appropriate section here ?

3

My logs up to yesterday don’t have this information because they just logged warnings and notices. Since I know that this happened on Feb. 23rd at about 4 o 5 pm, this is what I have (not much though):

Feb 23 16:01:02 NOTICE[19572] chan_sip.c: Peer ‘user1’ is now UNREACHABLE! Last qualify: 176
Feb 23 16:01:27 NOTICE[19572] chan_sip.c: Peer ‘user1’ is now REACHABLE! (196ms / 2000ms)
Feb 23 16:04:31 NOTICE[19572] chan_sip.c: Peer ‘user1’ is now UNREACHABLE! Last qualify: 179
Feb 23 16:04:41 NOTICE[19572] chan_sip.c: Peer ‘user1’ is now REACHABLE! (177ms / 2000ms)
Feb 23 16:05:45 NOTICE[19572] chan_sip.c: Peer ‘user1’ is now UNREACHABLE! Last qualify: 177
Feb 23 16:05:55 NOTICE[19572] chan_sip.c: Peer ‘user1’ is now REACHABLE! (187ms / 2000ms)
Feb 23 17:02:13 NOTICE[19572] chan_sip.c: Peer ‘user2’ is now TOO LAGGED! (2799ms / 2000ms)
Feb 23 17:02:23 NOTICE[19572] chan_sip.c: Peer ‘user2’ is now REACHABLE! (422ms / 2000ms)
Feb 23 17:04:59 WARNING[30856] pbx.c: Invalid extension ‘2’, but no rule ‘i’ in context 'incoming’
Feb 23 17:05:24 WARNING[30880] pbx.c: Timeout, but no rule ‘t’ in context 'incoming’
Feb 23 17:05:59 WARNING[30898] pbx.c: Timeout, but no rule ‘t’ in context 'incoming’
Feb 23 17:06:23 WARNING[30920] pbx.c: Timeout, but no rule ‘t’ in context 'incoming’
Feb 23 19:01:41 NOTICE[19576] chan_iax2.c: Peer ‘iaxfwd-out’ is now TOO LAGGED (2430 ms)!

I now have the system on debug and I’ll try to post any log when I detect the problem. The debug log gets really big, so I hope to detect something soon.

4

I now managed to catch this problem in the log file. I’ve since updated to asterisk 1.2.7.1 but unfortunaltely the problem is still there. After looking at the relevant parts of the log file I can’t really see a problem. This log shows 2 calls to a voip number (from www.vono.net.br) that is answered by my Asterisk server. The sympton is that you notice that the call gets answered but nothing else happens. After I restarted Asterisk it worked again.

Here are the relevant parts of the log:

Jun 3 18:05:07 DEBUG[2648] chan_sip.c: Setting NAT on RTP to 524288
Jun 3 18:05:07 DEBUG[2648] chan_sip.c: Checking SIP call limits for device pm21
Jun 3 18:05:07 DEBUG[2648] chan_sip.c: build_route: Contact hop: sip:1138191708-acme-d58fopk43von7@200.146.79.165:5060;transport=udp
Jun 3 18:05:07 VERBOSE[2677] logger.c: – Executing Goto(“SIP/pm21-c76b”, “vono-in-40637231|ktex|1”) in new stack
Jun 3 18:05:07 VERBOSE[2677] logger.c: – Goto (vono-in-40637231,ktex,1)
Jun 3 18:05:07 VERBOSE[2677] logger.c: – Executing Goto(“SIP/pm21-c76b”, “vono-in-40637231-x|s|1”) in new stack
Jun 3 18:05:07 VERBOSE[2677] logger.c: – Goto (vono-in-40637231-x,s,1)
Jun 3 18:05:07 VERBOSE[2677] logger.c: – Executing Answer(“SIP/pm21-c76b”, " ") in new stack
Jun 3 18:05:07 VERBOSE[2677] logger.c: – Executing SetMusicOnHold(“SIP/pm21-c76b”, “default”) in new stack
Jun 3 18:05:07 VERBOSE[2677] logger.c: – Executing BackGround(“SIP/pm21-c76b”, “enter-ext-of-person”) in new stack
Jun 3 18:05:07 DEBUG[2677] channel.c: Scheduling timer at 160 sample intervals
Jun 3 18:05:07 VERBOSE[2677] logger.c: – Playing ‘enter-ext-of-person’ (language ‘en’)
Jun 3 18:05:07 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘SDdpdl601-9c8199b4d19412bf882cf3c7c37566a5-8m4vki2’ of Response 102: Match Found
Jun 3 18:05:16 DEBUG[2648] chan_sip.c: Auto destroying call ‘1c7ea7ad4dae973978dc59165d0b4b56@127.0.0.1’
Jun 3 18:05:16 DEBUG[2648] chan_sip.c: Auto destroying call ‘7cf046562b522e6e582fd2cb44c3f019@127.0.0.1’
Jun 3 18:05:16 DEBUG[2648] chan_sip.c: Auto destroying call ‘48d60e334ebcef850f61d352761fa2f6@127.0.0.1’
Jun 3 18:05:16 DEBUG[2648] chan_sip.c: Auto destroying call ‘1f2dc0072c9a98503da638e908a252b0@127.0.0.1’
Jun 3 18:05:26 DEBUG[2677] channel.c: Scheduling timer at 0 sample intervals
Jun 3 18:05:26 VERBOSE[2677] logger.c: == Spawn extension (vono-in-40637231-x, s, 3) exited non-zero on ‘SIP/pm21-c76b’
Jun 3 18:05:26 DEBUG[2677] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jun 3 18:05:26 DEBUG[2677] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-06-03 18:05:07’,’“PM21” <1138191708acmed58fopk43von7>’,‘1138191708acmed58fopk43von7’,‘s’,‘vono-in-40637231-x’, ‘SIP/pm21-c76b’,’’,‘BackGround’,‘enter-ext-of-person’,19,19,‘ANSWERED’,3,’’)
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '“PM21” <1138191708acmed58fopk43von7>'
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '1138191708acmed58fopk43von7’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is 's’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is 'vono-in-40637231-x’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is 'SIP/pm21-c76b’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '(null)'
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is 'BackGround’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is 'enter-ext-of-person’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '2006-06-03 18:05:07’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '2006-06-03 18:05:07’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '2006-06-03 18:05:26’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '19’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '19’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is 'ANSWERED’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is 'DOCUMENTATION’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '(null)'
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '1149368707.0’
Jun 3 18:05:26 DEBUG[2677] pbx.c: Function result is '(null)'
Jun 3 18:05:26 DEBUG[2677] chan_sip.c: update_call_counter(pm21) - decrement call limit counter
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Scheduled a registration timeout for vono.net.br id #65
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Scheduled a registration timeout for vono.net.br id #67
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘1c7ea7ad4dae973978dc59165d0b4b56@127.0.0.1’ of Request 103: Match Found
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Registration successful
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Cancelling timeout 65
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Scheduled a registration timeout for vono.net.br id #71
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘7cf046562b522e6e582fd2cb44c3f019@127.0.0.1’ of Request 103: Match Found
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Registration successful
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Cancelling timeout 67
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘1f2dc0072c9a98503da638e908a252b0@127.0.0.1’ of Request 103: Match Found
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Registration successful
Jun 3 18:05:29 DEBUG[2648] chan_sip.c: Cancelling timeout 71

Thisn is the second try:

Jun 3 18:05:38 DEBUG[2648] chan_sip.c: Setting NAT on RTP to 524288
Jun 3 18:05:38 DEBUG[2648] chan_sip.c: Checking SIP call limits for device pm21
Jun 3 18:05:38 DEBUG[2648] chan_sip.c: build_route: Contact hop: sip:1138191708-acme-d58fopk43von7@200.146.79.165:5060;transport=udp
Jun 3 18:05:38 VERBOSE[2693] logger.c: – Executing Goto(“SIP/pm21-5e42”, “vono-in-40637231|ktex|1”) in new stack
Jun 3 18:05:38 VERBOSE[2693] logger.c: – Goto (vono-in-40637231,ktex,1)
Jun 3 18:05:38 VERBOSE[2693] logger.c: – Executing Goto(“SIP/pm21-5e42”, “vono-in-40637231-x|s|1”) in new stack
Jun 3 18:05:38 VERBOSE[2693] logger.c: – Goto (vono-in-40637231-x,s,1)
Jun 3 18:05:38 VERBOSE[2693] logger.c: – Executing Answer(“SIP/pm21-5e42”, " ") in new stack
Jun 3 18:05:38 VERBOSE[2693] logger.c: – Executing SetMusicOnHold(“SIP/pm21-5e42”, “default”) in new stack
Jun 3 18:05:38 VERBOSE[2693] logger.c: – Executing BackGround(“SIP/pm21-5e42”, “enter-ext-of-person”) in new stack
Jun 3 18:05:38 DEBUG[2693] channel.c: Scheduling timer at 160 sample intervals
Jun 3 18:05:38 VERBOSE[2693] logger.c: – Playing ‘enter-ext-of-person’ (language ‘en’)
Jun 3 18:05:38 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘SDlpc2a01-2f3e4d5ea76db03945f4ce1114555897-8m4vki2’ of Response 102: Match Found
Jun 3 18:05:38 DEBUG[2693] chan_sip.c: Oooh, format changed to 1024
Jun 3 18:05:39 DEBUG[2652] chan_iax2.c: Raw Hangup 192.246.69.186:4569, src=4, dst=1234
Jun 3 18:05:43 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘38005c1a417bf54c33acdd1838dae068@10.1.9.1’ of Request 102: Match Found
Jun 3 18:05:43 DEBUG[2648] chan_sip.c: That’s odd… Got a response on a call we dont know about. Cseq 102 Cmd SIP/2.0
Jun 3 18:05:43 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘49ff7a6a19c29cb749b27e3079e20650@10.1.9.1’ of Request 102: Match Found
Jun 3 18:05:43 DEBUG[2648] chan_sip.c: That’s odd… Got a response on a call we dont know about. Cseq 102 Cmd SIP/2.0
Jun 3 18:05:43 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘15a36df91d611da72f7afe24266f77a4@10.1.9.1’ of Request 102: Match Found
Jun 3 18:05:43 DEBUG[2648] chan_sip.c: That’s odd… Got a response on a call we dont know about. Cseq 102 Cmd SIP/2.0
Jun 3 18:05:43 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘3b433c081d43c98b74da31725074681d@10.1.9.1’ of Request 102: Match Found
Jun 3 18:05:43 DEBUG[2648] chan_sip.c: That’s odd… Got a response on a call we dont know about. Cseq 102 Cmd SIP/2.0
Jun 3 18:05:44 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘1ca892020f996da85c07db263961e954@200.233.58.40’ of Request 102: Match Found
Jun 3 18:05:44 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘32bf2e3f743b238b27e800a360c2e10b@200.233.58.40’ of Request 102: Match Found
Jun 3 18:05:44 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘4ec48f3f3058568545fbc47e635ce226@200.233.58.40’ of Request 102: Match Found
Jun 3 18:05:44 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘3868651426151ff761585bff7e9c258b@200.233.58.40’ of Request 102: Match Found
Jun 3 18:05:44 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘3a1a49f97112429d3b11bd0754d459bf@200.233.58.40’ of Request 102: Match Found
Jun 3 18:05:44 DEBUG[2648] chan_sip.c: Stopping retransmission on ‘03a026ed0c08a2a161b1f6170579fe16@200.233.58.40’ of Request 102: Match Found
Jun 3 18:05:46 DEBUG[2652] chan_iax2.c: Peer lastms 130, historicms 130, maxms 2000
Jun 3 18:05:46 DEBUG[2652] chan_iax2.c: Peer lastms 134, historicms 134, maxms 2000
Jun 3 18:05:52 DEBUG[2693] channel.c: Scheduling timer at 0 sample intervals
Jun 3 18:05:52 VERBOSE[2693] logger.c: == Spawn extension (vono-in-40637231-x, s, 3) exited non-zero on ‘SIP/pm21-5e42’
Jun 3 18:05:52 DEBUG[2693] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jun 3 18:05:52 DEBUG[2693] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-06-03 18:05:38’,’“PM21” <1138191708acmed58fopk43von7>’,‘1138191708acmed58fopk43von7’,‘s’,‘vono-in-40637231-x’, ‘SIP/pm21-5e42’,’’,‘BackGround’,‘enter-ext-of-person’,14,14,‘ANSWERED’,3,’’)
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '“PM21” <1138191708acmed58fopk43von7>'
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '1138191708acmed58fopk43von7’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is 's’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is 'vono-in-40637231-x’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is 'SIP/pm21-5e42’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '(null)'
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is 'BackGround’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is 'enter-ext-of-person’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '2006-06-03 18:05:38’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '2006-06-03 18:05:38’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '2006-06-03 18:05:52’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '14’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '14’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is 'ANSWERED’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is 'DOCUMENTATION’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '(null)'
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '1149368738.1’
Jun 3 18:05:52 DEBUG[2693] pbx.c: Function result is '(null)'
Jun 3 18:05:52 DEBUG[2693] chan_sip.c: update_call_counter(pm21) - decrement call limit counter
Jun 3 18:05:55 VERBOSE[2664] logger.c: – Remote UNIX connection disconnected
Jun 3 18:06:01 DEBUG[2648] chan_sip.c: Auto destroying call '1c7ea7ad4dae973978dc59165d0b4b56@127.0.0.1’
Jun 3 18:06:01 DEBUG[2648] chan_sip.c: Auto destroying call '7cf046562b522e6e582fd2cb44c3f019@127.0.0.1’
Jun 3 18:06:01 DEBUG[2648] chan_sip.c: Auto destroying call ‘1f2dc0072c9a98503da638e908a252b0@127.0.0.1’

This is a log of a correctly handled call:

Jun 3 18:57:40 DEBUG[4493] chan_sip.c: Setting NAT on RTP to 524288
Jun 3 18:57:40 DEBUG[4493] chan_sip.c: Checking SIP call limits for device pm21
Jun 3 18:57:40 DEBUG[4493] chan_sip.c: build_route: Contact hop: sip:1138191708-acme-ct7d8pc41foj7@200.146.79.165:5060;transport=udp
Jun 3 18:57:40 VERBOSE[4501] logger.c: – Executing Goto(“SIP/pm21-441d”, “vono-in-40637231|ktex|1”) in new stack
Jun 3 18:57:40 VERBOSE[4501] logger.c: – Goto (vono-in-40637231,ktex,1)
Jun 3 18:57:40 VERBOSE[4501] logger.c: – Executing Goto(“SIP/pm21-441d”, “vono-in-40637231-x|s|1”) in new stack
Jun 3 18:57:40 VERBOSE[4501] logger.c: – Goto (vono-in-40637231-x,s,1)
Jun 3 18:57:40 VERBOSE[4501] logger.c: – Executing Answer(“SIP/pm21-441d”, " ") in new stack
Jun 3 18:57:40 VERBOSE[4501] logger.c: – Executing SetMusicOnHold(“SIP/pm21-441d”, “default”) in new stack
Jun 3 18:57:40 VERBOSE[4501] logger.c: – Executing BackGround(“SIP/pm21-441d”, “enter-ext-of-person”) in new stack
Jun 3 18:57:40 DEBUG[4501] channel.c: Scheduling timer at 160 sample intervals
Jun 3 18:57:40 VERBOSE[4501] logger.c: – Playing ‘enter-ext-of-person’ (language ‘en’)
Jun 3 18:57:40 DEBUG[4493] chan_sip.c: Stopping retransmission on ‘SDdoc6601-e6fc84654109a98b1a631e5b7f816583-8m4vki2’ of Response 102: Match Found
Jun 3 18:57:42 DEBUG[4501] channel.c: Scheduling timer at 0 sample intervals
Jun 3 18:57:42 DEBUG[4501] channel.c: Scheduling timer at 0 sample intervals
Jun 3 18:57:45 DEBUG[4501] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jun 3 18:57:45 DEBUG[4501] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-06-03 18:57:40’,’“PM21” <1138191708acmect7d8pc41foj7>’,‘1138191708acmect7d8pc41foj7’,‘s’,‘vono-in-40637231-x’, ‘SIP/pm21-441d’,’’,‘BackGround’,‘enter-ext-of-person’,5,5,‘ANSWERED’,3,’’)
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '“PM21” <1138191708acmect7d8pc41foj7>'
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '1138191708acmect7d8pc41foj7’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is 's’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is 'vono-in-40637231-x’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is 'SIP/pm21-441d’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '(null)'
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is 'BackGround’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is 'enter-ext-of-person’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '2006-06-03 18:57:40’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '2006-06-03 18:57:40’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '2006-06-03 18:57:45’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '5’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '5’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is 'ANSWERED’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is 'DOCUMENTATION’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '(null)'
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '1149371860.0’
Jun 3 18:57:45 DEBUG[4501] pbx.c: Function result is '(null)'
Jun 3 18:57:45 DEBUG[4501] chan_sip.c: update_call_counter(pm21) - decrement call limit counter

The difference is that in the bad tries I do not hear the message (enter the extension of the person you are trying to reach) and in the last try I did hear it.

Any clues?