Asterisk hangs up call after transfer to extension

I am running PBX in a Flash ver 1.3 Asterisk 1.4.22 with FreePBX 2.5.0.1 I have 12 extensions setup and 3 of them have stopped working when the receptionist initiates a ## * extension transfer direct to voice mail. I have tried deleting the extension and re-creating it same problem. I have created a new extension number that was not previously used and same problem. Here is the output of the failure. I suspect its some issue with DBdel: Error deleting key from database but I don’t know how to resolve it. Can anyone help me resolve this problem ?

Connected to Asterisk 1.4.22 currently running on pbx (pid = 3079)
Verbosity is at least 4
– Started music on hold, class ‘default’, on Zap/1-1
– <SIP/101-09287bd8> Playing ‘pbx-transfer’ (language ‘en’)
– Stopped music on hold on Zap/1-1
== Spawn extension (macro-dial, s, 7) exited non-zero on ‘Zap/1-1’ in macro ‘dial’
== Spawn extension (macro-dial, s, 7) exited non-zero on ‘Zap/1-1’
– Executing [h@macro-dial:1] Macro(“Zap/1-1”, “hangupcall”) in new stack
– Executing [s@macro-hangupcall:1] ResetCDR(“Zap/1-1”, “w”) in new stack
Extension Changed 101[ext-local] new state Idle for Notify User 103
Extension Changed 101[ext-local] new state Idle for Notify User 109
– Executing [s@macro-hangupcall:2] NoCDR(“Zap/1-1”, “”) in new stack
– Executing [s@macro-hangupcall:3] GotoIf(“Zap/1-1”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,6)
– Executing [s@macro-hangupcall:6] GotoIf(“Zap/1-1”, “0?skipblkvm”) in new stack
– Executing [s@macro-hangupcall:7] NoOp(“Zap/1-1”, “Cleaning Up Block VM Flag: BLKVM/600/Zap/1-1”) in new stack
– Executing [s@macro-hangupcall:8] DBdel(“Zap/1-1”, “BLKVM/600/Zap/1-1”) in new stack
– DBdel: family=BLKVM, key=600/Zap/1-1
– DBdel: Error deleting key from database.
– Executing [s@macro-hangupcall:9] GotoIf(“Zap/1-1”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,11)
– Executing [s@macro-hangupcall:11] Hangup(“Zap/1-1”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Zap/1-1’ in macro ‘hangupcall’
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Zap/1-1’
– Hungup ‘Zap/1-1’

1 Like

the asterisk log may reveal something that the CLI is not, check it. (For example, if the call came in as g729 and you don’t have licenses, the subsequent transfer to voicemail would fail because of the inability to transcode (although I think you would have seen it hit the vm in the CLI). Anyhow - there are other things that the log may expose and you should review that.

It also could be related to #3092 although past testing showed that was only an issue with device side (SIP Redirect) transfers.

Thanks Philippe

Here is the info from /var/log/asterisk/full for same problem

[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Stopped music on hold on Zap/3-1
[Oct 27 14:39:58] VERBOSE[6459] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘Zap/3-1’ in macro ‘dial’
[Oct 27 14:39:58] VERBOSE[6459] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘Zap/3-1’
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [h@macro-dial:1] Macro(“Zap/3-1”, “hangupcall”) in new stack
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“Zap/3-1”, “w”) in new stack
[Oct 27 14:39:58] VERBOSE[3075] logger.c: Extension Changed 101[ext-local] new state Idle for Notify User 103
[Oct 27 14:39:58] VERBOSE[3075] logger.c: Extension Changed 101[ext-local] new state Idle for Notify User 109
[Oct 27 14:39:58] DEBUG[6459] app_macro.c: Executed application: ResetCDR
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [s@macro-hangupcall:2] NoCDR(“Zap/3-1”, “”) in new stack
[Oct 27 14:39:58] DEBUG[6459] app_macro.c: Executed application: NoCDR
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [s@macro-hangupcall:3] GotoIf(“Zap/3-1”, “1?skiprg”) in new stack
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Goto (macro-hangupcall,s,6)
[Oct 27 14:39:58] DEBUG[6459] app_macro.c: Executed application: GotoIf
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [s@macro-hangupcall:6] GotoIf(“Zap/3-1”, “0?skipblkvm”) in new stack
[Oct 27 14:39:58] DEBUG[6459] app_macro.c: Executed application: GotoIf
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [s@macro-hangupcall:7] NoOp(“Zap/3-1”, “Cleaning Up Block VM Flag: BLKVM/600/Zap/3-1”) in new stack
[Oct 27 14:39:58] DEBUG[6459] app_macro.c: Executed application: Noop
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [s@macro-hangupcall:8] DBdel(“Zap/3-1”, “BLKVM/600/Zap/3-1”) in new stack
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – DBdel: family=BLKVM, key=600/Zap/3-1
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – DBdel: Error deleting key from database.
[Oct 27 14:39:58] DEBUG[6459] app_macro.c: Executed application: DBDel
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [s@macro-hangupcall:9] GotoIf(“Zap/3-1”, “1?theend”) in new stack
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Goto (macro-hangupcall,s,11)
[Oct 27 14:39:58] DEBUG[6459] app_macro.c: Executed application: GotoIf
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Executing [s@macro-hangupcall:11] Hangup(“Zap/3-1”, “”) in new stack
[Oct 27 14:39:58] VERBOSE[6459] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Zap/3-1’ in macro ‘hangupcall’
[Oct 27 14:39:58] VERBOSE[6459] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Zap/3-1’
[Oct 27 14:39:58] DEBUG[6459] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on Zap/3-1
[Oct 27 14:39:58] DEBUG[6459] chan_dahdi.c: Not yet hungup… Calling hangup once with icause, and clearing call
[Oct 27 14:39:58] DEBUG[6459] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on Zap/3-1
[Oct 27 14:39:58] VERBOSE[6459] logger.c: – Hungup ‘Zap/3-1’
(END)

try pumping up verbosity to 5, and if that doesn’t reveal anything, turning on debug although debug should not be necessary.

As of Friday - Monday our PBX has been doing the same thing. It used to transfer calls previously as mentioned above. I will post a more detailed log in a few hours.

Quick Question…

Can you get to voicemail directly by pressing *+…and can you get to voicemail by dialing the extension and letting it time out to VM.

Bill/W5WAF

Philippe

Here is the log with verbosity set to 5

Connected to Asterisk 1.4.22 currently running on pbx (pid = 3071)
Verbosity is at least 5

– Started music on hold, class ‘default’, on Zap/1-1
– <SIP/101-0a16c238> Playing ‘pbx-transfer’ (language ‘en’)
== 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
== Manager ‘admin’ logged off from 127.0.0.1
– Stopped music on hold on Zap/1-1
== Spawn extension (macro-dial, s, 7) exited non-zero on ‘Zap/1-1’ in macro ‘dial’
== Spawn extension (macro-dial, s, 7) exited non-zero on ‘Zap/1-1’
– Executing [h@macro-dial:1] Macro(“Zap/1-1”, “hangupcall”) in new stack
– Executing [s@macro-hangupcall:1] ResetCDR(“Zap/1-1”, “w”) in new stack
– Executing [s@macro-hangupcall:2] NoCDR(“Zap/1-1”, “”) in new stack
– Executing [s@macro-hangupcall:3] GotoIf(“Zap/1-1”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,6)
– Executing [s@macro-hangupcall:6] GotoIf(“Zap/1-1”, “0?skipblkvm”) in new stack
– Executing [s@macro-hangupcall:7] NoOp(“Zap/1-1”, “Cleaning Up Block VM Flag: BLKVM/600/Zap/1-1”) in new stack
– Executing [s@macro-hangupcall:8] DBdel(“Zap/1-1”, “BLKVM/600/Zap/1-1”) in new stack
– DBdel: family=BLKVM, key=600/Zap/1-1
– DBdel: Error deleting key from database.
– Executing [s@macro-hangupcall:9] GotoIf(“Zap/1-1”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,11)
– Executing [s@macro-hangupcall:11] Hangup(“Zap/1-1”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Zap/1-1’ in macro ‘hangupcall’
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Zap/1-1’
– Hungup 'Zap/1-1’
Extension Changed 101[ext-local] new state Idle for Notify User 103
Extension Changed 101[ext-local] new state Idle for Notify User 109

Yes we can do an attended transfer to the extension and it will works fine. Also using the IVR for callers to reach
each persons voice mail works fine.

jwells,
that’s not the log, it’s the CLI. You will need to post the log (/var/log/asterisk/full by default) which contains additional information.

Philippe

Sorry I checked and the verbosity in the cli is set to 12 and best I can tell that determines the logger level as well ? Here is the output from the logfile full

Thanks
Jim

[Oct 29 14:02:22] VERBOSE[3514] logger.c: – Started music on hold, class ‘default’, on Zap/1-1
[Oct 29 14:02:22] VERBOSE[3514] logger.c: – <SIP/101-09b1d558> Playing ‘pbx-transfer’ (language ‘en’)
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Stopped music on hold on Zap/1-1
[Oct 29 14:02:24] VERBOSE[3514] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘Zap/1-1’ in macro ‘dial’
[Oct 29 14:02:24] VERBOSE[3514] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘Zap/1-1’
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [h@macro-dial:1] Macro(“Zap/1-1”, “hangupcall”) in new stack
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“Zap/1-1”, “w”) in new stack
[Oct 29 14:02:24] DEBUG[3514] app_macro.c: Executed application: ResetCDR
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [s@macro-hangupcall:2] NoCDR(“Zap/1-1”, “”) in new stack
[Oct 29 14:02:24] DEBUG[3514] app_macro.c: Executed application: NoCDR
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [s@macro-hangupcall:3] GotoIf(“Zap/1-1”, “1?skiprg”) in new stack
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Goto (macro-hangupcall,s,6)
[Oct 29 14:02:24] DEBUG[3514] app_macro.c: Executed application: GotoIf
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [s@macro-hangupcall:6] GotoIf(“Zap/1-1”, “0?skipblkvm”) in new stack
[Oct 29 14:02:24] DEBUG[3514] app_macro.c: Executed application: GotoIf
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [s@macro-hangupcall:7] NoOp(“Zap/1-1”, “Cleaning Up Block VM Flag: BLKVM/600/Zap/1-1”) in new stack
[Oct 29 14:02:24] DEBUG[3514] app_macro.c: Executed application: Noop
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [s@macro-hangupcall:8] DBdel(“Zap/1-1”, “BLKVM/600/Zap/1-1”) in new stack
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – DBdel: family=BLKVM, key=600/Zap/1-1
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – DBdel: Error deleting key from database.
[Oct 29 14:02:24] DEBUG[3514] app_macro.c: Executed application: DBDel
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [s@macro-hangupcall:9] GotoIf(“Zap/1-1”, “1?theend”) in new stack
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Goto (macro-hangupcall,s,11)
[Oct 29 14:02:24] DEBUG[3514] app_macro.c: Executed application: GotoIf
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Executing [s@macro-hangupcall:11] Hangup(“Zap/1-1”, “”) in new stack
[Oct 29 14:02:24] VERBOSE[3514] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Zap/1-1’ in macro ‘hangupcall’
[Oct 29 14:02:24] VERBOSE[3514] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Zap/1-1’
[Oct 29 14:02:24] DEBUG[3514] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
[Oct 29 14:02:24] DEBUG[3514] chan_dahdi.c: Not yet hungup… Calling hangup once with icause, and clearing call
[Oct 29 14:02:24] DEBUG[3514] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
[Oct 29 14:02:24] VERBOSE[3514] logger.c: – Hungup ‘Zap/1-1’

hmm - nothing more revealing, try setting you debug level to something like 10 and see if any useful information is spit out.

Currently its set at 12 but I turned on debug here is what I caught

Jim

[Oct 29 14:32:36] DEBUG[3072] chan_sip.c: Checking device state for peer 103
[Oct 29 14:32:36] DEBUG[3072] devicestate.c: Checking if I can find provider for “Custom” - number: DND103
[Oct 29 14:32:36] DEBUG[3072] devicestate.c: Checking provider SLA with Custom
[Oct 29 14:32:36] DEBUG[3072] devicestate.c: Checking provider Meetme with Custom
[Oct 29 14:32:36] DEBUG[3072] devicestate.c: Checking provider Park with Custom
[Oct 29 14:32:36] DEBUG[3096] app_queue.c: Device ‘SIP/103’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Oct 29 14:32:36] VERBOSE[3099] logger.c: Really destroying SIP dialog ‘[email protected]’ Method: INVITE
[Oct 29 14:32:37] DEBUG[3894] rtp.c: Got RTCP report of 92 bytes
[Oct 29 14:32:41] DEBUG[3903] rtp.c: Got RTCP report of 92 bytes
[Oct 29 14:32:42] DEBUG[3894] rtp.c: Got RTCP report of 92 bytes
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: Sending dtmf: 35 (#), at 192.168.125.20
[Oct 29 14:32:43] DEBUG[3903] channel.c: Got DTMF begin on channel (SIP/101-09b7ea98)
[Oct 29 14:32:43] DEBUG[3903] chan_dahdi.c: Requested indication 20 on channel Zap/2-1
[Oct 29 14:32:43] DEBUG[3903] channel.c: Bridge stops bridging channels Zap/2-1 and SIP/101-09b7ea98
[Oct 29 14:32:43] DEBUG[3903] chan_dahdi.c: Requested indication 20 on channel Zap/2-1
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: Sending dtmf: 35 (#), at 192.168.125.20
[Oct 29 14:32:43] DEBUG[3903] channel.c: Got DTMF end on channel (SIP/101-09b7ea98)
[Oct 29 14:32:43] DEBUG[3903] chan_dahdi.c: Requested indication 20 on channel Zap/2-1
[Oct 29 14:32:43] DEBUG[3903] channel.c: Bridge stops bridging channels Zap/2-1 and SIP/101-09b7ea98
[Oct 29 14:32:43] DEBUG[3903] res_features.c: Feature interpret: chan=Zap/2-1, peer=SIP/101-09b7ea98, code=#, sense=2, features=2 dynamic=(null)
[Oct 29 14:32:43] DEBUG[3903] res_features.c: Set time limit to 500
[Oct 29 14:32:43] DEBUG[3903] chan_dahdi.c: Requested indication 20 on channel Zap/2-1
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: Sending dtmf: 35 (#), at 192.168.125.20
[Oct 29 14:32:43] DEBUG[3903] channel.c: Got DTMF begin on channel (SIP/101-09b7ea98)
[Oct 29 14:32:43] DEBUG[3903] chan_dahdi.c: Requested indication 20 on channel Zap/2-1
[Oct 29 14:32:43] DEBUG[3903] channel.c: Bridge stops bridging channels Zap/2-1 and SIP/101-09b7ea98
[Oct 29 14:32:43] DEBUG[3903] chan_dahdi.c: Requested indication 20 on channel Zap/2-1
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Oct 29 14:32:43] DEBUG[3903] rtp.c: - RTP 2833 Event: 0000000b (len = 4)

Philippe

Any ideas on this issue ? If I didn’t get the correct log information then tell me what I need to do in Asterisk to provide what you need. I really have no other option at this time to get this resolved unless I re-load the entire PBX from scratch. I setup another system and I can’t duplicate the problem so not sure what happened ?

Jim