при обычном звонке Hangup на софтфоне отрабатывается сразу как положенно. Копировал app_voicemail.so с работающего Voicemail на такомже астериске. Пару недель назад работало. Нет даже мыслей что сломалось и куда смотреть

VoiceMail не замечает Hangup и продолжает дальше работать как с активным каналом. При этом в /var/spool/asterisk/voicemail/default/9999/tmp/ создаются файлы

-rw------- 1 asterisk asterisk 0 Jun 10 19:43 1WR2ro
-rwx------ 1 asterisk asterisk 44 Jun 10 19:43 1WR2ro.wav
-rw------- 1 asterisk asterisk 0 Jun 10 19:41 yGWVqp
-rwx------ 1 asterisk asterisk 44 Jun 10 19:41 yGWVqp.wav

по диалплану дальше не идет. Астериск уже перегружал не раз. Версия * 1.4 (trixbox)

exten => 2244,1,Answer
exten => 2244,n,VoiceMail(9999@default)
exten => 2244,n,hangup

в консоли

-- Executing [2244@from-internal:1] Answer("SIP/23-094af650", "") in new stack
-- Executing [2244@from-internal:2] VoiceMail("SIP/23-094af650", "9999@default") in new stack
-- <SIP/23-094af650> Playing 'vm-intro' (language 'en')
-- <SIP/23-094af650> Playing 'beep' (language 'en')
-- Recording the message
-- x=0, open writing: /var/spool/asterisk/voicemail/default/9999/tmp/ChHvXU format: wav, 0x9413f80

и тишина

*CLI> show channel SIP/23-094af650
-- General --CLI>
Name: SIP/23-094af650
Type: SIP
UniqueID: 1276193215.31
Caller ID: 23
Caller ID Name: device
DNID Digits: 2244
State: Up (6)
Rings: 0
NativeFormats: 0x4 (ulaw)
WriteFormat: 0x40 (slin)
ReadFormat: 0x40 (slin)
WriteTranscode: Yes
ReadTranscode: Yes
1st File Descriptor: 18
Frames in: 0
Frames out: 2194
Time to Hangup: 0
Elapsed Time: 0h0m44s
Direct Bridge: <none>
Indirect Bridge: <none>
-- PBX --
Context: from-internal
Extension: 2244
Priority: 2
Call Group: 2
Pickup Group: 2
Application: VoiceMail
Data: 9999@default
Blocking in: ast_waitfor_nandfds
Variables:I>
SIPCALLID=B83B9ECE9CB44558A2818FC7E35C3F9E0xac10013b
SIPUSERAGENT=SJphone/1.65.377a (SJ Labs)
SIPDOMAIN=192.168.10.5
SIPURI=sip:23@192.168.10.6

CDR Variables:I>
level 1: clid="device" <23>
level 1: src=23
level 1: dst=2244
level 1: dcontext=from-internal
level 1: channel=SIP/23-094af650
level 1: lastapp=VoiceMail
level 1: lastdata=9999@default
level 1: start=2010-06-10 20:06:55
level 1: answer=2010-06-10 20:06:55
level 1: duration=0
level 1: billsec=0
level 1: disposition=ANSWERED
level 1: amaflags=DOCUMENTATION
level 1: uniqueid=1276193215.31

*CLI>show channels
Channel Location State Application(Data)
SIP/23-094af650 2244@from-internal:2 Up VoiceMail(9999@default)
1 active channel
1 active call

в тоже время на другом диалплане без Voicemail hangup работает

-- Executing [*65@from-internal:1] Answer("SIP/23-094bdd50", "") in new stack
-- Executing [*65@from-internal:2] Wait("SIP/23-094bdd50", "1") in new stack
-- Executing [*65@from-internal:3] Macro("SIP/23-094bdd50", "user-callerid|") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/23-094bdd50", "AMPUSER=23") in new stack
-- Executing [s@macro-user-callerid:2] GotoIf("SIP/23-094bdd50", "0?report") in new stack
-- Executing [s@macro-user-callerid:3] ExecIf("SIP/23-094bdd50", "1|Set|REALCALLERIDNUM=23") in new stack
-- Executing [s@macro-user-callerid:4] Set("SIP/23-094bdd50", "AMPUSER=23") in new stack
-- Executing [s@macro-user-callerid:5] Set("SIP/23-094bdd50", "AMPUSERCIDNAME=ESH-23") in new stack
-- Executing [s@macro-user-callerid:6] GotoIf("SIP/23-094bdd50", "0?report") in new stack
-- Executing [s@macro-user-callerid:7] Set("SIP/23-094bdd50", "AMPUSERCID=23") in new stack
-- Executing [s@macro-user-callerid:8] Set("SIP/23-094bdd50", "CALLERID(all)="ESH-23" <23>") in new stack
-- Executing [s@macro-user-callerid:9] Set("SIP/23-094bdd50", "REALCALLERIDNUM=23") in new stack
-- Executing [s@macro-user-callerid:10] ExecIf("SIP/23-094bdd50", "1|Set|CHANNEL(language)=de") in new stack
-- Executing [s@macro-user-callerid:11] GotoIf("SIP/23-094bdd50", "0?continue") in new stack
-- Executing [s@macro-user-callerid:12] Set("SIP/23-094bdd50", "__TTL=64") in new stack
-- Executing [s@macro-user-callerid:13] GotoIf("SIP/23-094bdd50", "1?continue") in new stack
-- Goto (macro-user-callerid,s,20)
-- Executing [s@macro-user-callerid:20] NoOp("SIP/23-094bdd50", "Using CallerID "ESH-23" <23>") in new stack
-- Executing [*65@from-internal:4] Playback("SIP/23-094bdd50", "your") in new stack
-- <SIP/23-094bdd50> Playing 'your' (language 'de')
-- Executing [*65@from-internal:5] Playback("SIP/23-094bdd50", "extension") in new stack
-- <SIP/23-094bdd50> Playing 'extension' (language 'de')
-- Executing [*65@from-internal:6] Playback("SIP/23-094bdd50", "number") in new stack
-- <SIP/23-094bdd50> Playing 'number' (language 'de')
-- Executing [*65@from-internal:7] Playback("SIP/23-094bdd50", "is") in new stack
-- <SIP/23-094bdd50> Playing 'is' (language 'de')
-- Executing [*65@from-internal:8] SayDigits("SIP/23-094bdd50", "23") in new stack
-- <SIP/23-094bdd50> Playing 'digits/2' (language 'de')
-- <SIP/23-094bdd50> Playing 'digits/3' (language 'de')
-- <SIP/23-094af650> Playing 'vm-review' (language 'en')
-- Executing [*65@from-internal:9] Wait("SIP/23-094bdd50", "2") in new stack
-- Executing [*65@from-internal:10] Hangup("SIP/23-094bdd50", "") in new stack
== Spawn extension (from-internal, *65, 10) exited non-zero on 'SIP/23-094bdd50'
-- Executing [h@from-internal:1] NoOp("SIP/23-094bdd50", "") in new stack
-- Executing [h@from-internal:2] Macro("SIP/23-094bdd50", "CID-DID-check|from-internal-H") in new stack
-- Executing [h@from-internal:3] Macro("SIP/23-094bdd50", "hangupcall") in new stack
-- Executing [s@macro-hangupcall:1] ResetCDR("SIP/23-094bdd50", "w") in new stack
-- Executing [s@macro-hangupcall:2] NoCDR("SIP/23-094bdd50", "") in new stack
-- Executing [s@macro-hangupcall:3] GotoIf("SIP/23-094bdd50", "1?skiprg") in new stack
-- Goto (macro-hangupcall,s,6)
-- Executing [s@macro-hangupcall:6] GotoIf("SIP/23-094bdd50", "1?skipblkvm") in new stack
-- Goto (macro-hangupcall,s,9)
-- Executing [s@macro-hangupcall:9] GotoIf("SIP/23-094bdd50", "1?theend") in new stack
-- Goto (macro-hangupcall,s,11)
-- Executing [s@macro-hangupcall:11] Hangup("SIP/23-094bdd50", "") in new stack
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/23-094bdd50' in macro 'hangupcall'
== Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/23-094bdd50'

И дебаг как обычно ничего не говорит?

И долго ль может он так висеть? А если звонящий трубку положит, завершиться VoiceMail?

voicemail.conf покаж =)

[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [9999@from-internal:1] Macro("SIP/22-b7956f50", "exten-vm|9999|9999") in new stack
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:1] Macro("SIP/22-b7956f50", "user-callerid") in new stack
[Jun 11 09:01:31] VERBOSE[2207] logger.c: Extension Changed 22[ext-local] new state InUse for Notify User 21
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/22-b7956f50", "AMPUSER=22") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/22-b7956f50", "0?report") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/22-b7956f50", "1|Set|REALCALLERIDNUM=22") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: ExecIf
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/22-b7956f50", "AMPUSER=22") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/22-b7956f50", "AMPUSERCIDNAME=D-Kirschey") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/22-b7956f50", "0?report") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/22-b7956f50", "AMPUSERCID=22") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/22-b7956f50", "CALLERID(all)="D-Kirschey" <22>") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:9] Set("SIP/22-b7956f50", "REALCALLERIDNUM=22") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/22-b7956f50", "1|Set|CHANNEL(language)=de") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: ExecIf
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Last app: Set|CHANNEL(language)=de
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:11] GotoIf("SIP/22-b7956f50", "0?continue") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:12] Set("SIP/22-b7956f50", "__TTL=64") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/22-b7956f50", "1?continue") in new stack
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Goto (macro-user-callerid,s,20)
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:20] NoOp("SIP/22-b7956f50", "Using CallerID "D-Kirschey" <22>") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Noop
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Macro
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:2] Set("SIP/22-b7956f50", "RingGroupMethod=none") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:3] Set("SIP/22-b7956f50", "VMBOX=9999") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:4] Set("SIP/22-b7956f50", "EXTTOCALL=9999") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] DEBUG[3375] func_db.c: DB: CFU/9999 not found in database.
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:5] Set("SIP/22-b7956f50", "CFUEXT=") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] DEBUG[3375] func_db.c: DB: CFB/9999 not found in database.
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:6] Set("SIP/22-b7956f50", "CFBEXT=") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:7] Set("SIP/22-b7956f50", "RT=15") in new stack
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:8] Macro("SIP/22-b7956f50", "record-enable|9999|IN") in new stack
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/22-b7956f50", "1?check") in new stack
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Goto (macro-record-enable,s,4)
[Jun 11 09:01:31] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/22-b7956f50", "recordingcheck|20100611-090131|1276239691.33") in new stack
[Jun 11 09:01:31] VERBOSE[3375] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jun 11 09:01:32] VERBOSE[3375] logger.c: recordingcheck|20100611-090131|1276239691.33: Inbound recording not enabled
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- AGI Script recordingcheck completed, returning 0
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: AGI
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("SIP/22-b7956f50", "") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Macro
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:9] Macro("SIP/22-b7956f50", "dial|15|tr|9999") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-dial:1] GotoIf("SIP/22-b7956f50", "1?dial") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Goto (macro-dial,s,3)
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-dial:4] AGI("SIP/22-b7956f50", "dialparties.agi") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jun 11 09:01:32] VERBOSE[3375] logger.c: dialparties.agi: Starting New Dialparties.agi
[Jun 11 09:01:32] VERBOSE[3378] logger.c: == Parsing '/etc/asterisk/manager.conf': [Jun 11 09:01:32] VERBOSE[3378] logger.c: Found
[Jun 11 09:01:32] VERBOSE[3378] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Jun 11 09:01:32] VERBOSE[3378] logger.c: Found
[Jun 11 09:01:32] VERBOSE[3378] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Jun 11 09:01:32] VERBOSE[3378] logger.c: Found
[Jun 11 09:01:32] VERBOSE[3378] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Jun 11 09:01:32] VERBOSE[3375] logger.c: dialparties.agi: Caller ID name is 'D-Kirschey' number is '22'
[Jun 11 09:01:32] VERBOSE[3375] logger.c: dialparties.agi: Methodology of ring is 'none'
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- dialparties.agi: Added extension 9999 to extension map
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- dialparties.agi: Extension 9999 cf is disabled
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- dialparties.agi: Extension 9999 do not disturb is disabled
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- dialparties.agi: dbset CALLTRACE/9999 to 22
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- dialparties.agi: Filtered ARG3: 9999
[Jun 11 09:01:32] VERBOSE[3378] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- AGI Script dialparties.agi completed, returning 0
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: AGI
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-dial:7] Dial("SIP/22-b7956f50", "SIP/9999|15|tr") in new stack
[Jun 11 09:01:32] WARNING[3375] app_dial.c: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Jun 11 09:01:32] VERBOSE[3375] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Dial
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-dial:8] Dial("SIP/22-b7956f50", "SIP/9999|15|tr") in new stack
[Jun 11 09:01:32] WARNING[3375] app_dial.c: Unable to create channel of type 'SIP' (cause 3 - No route to destination)
[Jun 11 09:01:32] VERBOSE[3375] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Dial
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-dial:9] Set("SIP/22-b7956f50", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-dial:10] GosubIf("SIP/22-b7956f50", "0?CHANUNAVAIL|1") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GosubIf
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Macro
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:10] GotoIf("SIP/22-b7956f50", "0?exit|return") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:11] Set("SIP/22-b7956f50", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:12] GosubIf("SIP/22-b7956f50", "0?docfu|1") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GosubIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:13] GosubIf("SIP/22-b7956f50", "0?docfb|1") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GosubIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:14] Set("SIP/22-b7956f50", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:15] NoOp("SIP/22-b7956f50", "Voicemail is 9999") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: NoOp
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:16] GotoIf("SIP/22-b7956f50", "0?s-CHANUNAVAIL|1") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:17] NoOp("SIP/22-b7956f50", "Sending to Voicemail box 9999") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: NoOp
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-exten-vm:18] Macro("SIP/22-b7956f50", "vm|9999|CHANUNAVAIL|") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-vm:1] Macro("SIP/22-b7956f50", "user-callerid|SKIPTTL") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/22-b7956f50", "AMPUSER=22") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/22-b7956f50", "0?report") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/22-b7956f50", "0|Set|REALCALLERIDNUM=22") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: ExecIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/22-b7956f50", "AMPUSER=22") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/22-b7956f50", "AMPUSERCIDNAME=D-Kirschey") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/22-b7956f50", "0?report") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/22-b7956f50", "AMPUSERCID=22") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/22-b7956f50", "CALLERID(all)="D-Kirschey" <22>") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:9] Set("SIP/22-b7956f50", "REALCALLERIDNUM=22") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/22-b7956f50", "1|Set|CHANNEL(language)=de") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: ExecIf
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Last app: Set|CHANNEL(language)=de
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:11] GotoIf("SIP/22-b7956f50", "1?continue") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Goto (macro-user-callerid,s,20)
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-user-callerid:20] NoOp("SIP/22-b7956f50", "Using CallerID "D-Kirschey" <22>") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Noop
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Macro
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-vm:2] Set("SIP/22-b7956f50", "VMGAIN=""") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] WARNING[3375] func_db.c: DB requires an argument, DB(<family>/<key>)
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-vm:3] GotoIf("SIP/22-b7956f50", "1?vmx|1") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Goto (macro-vm,vmx,1)
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [vmx@macro-vm:1] GotoIf("SIP/22-b7956f50", "0?s-CHANUNAVAIL|1") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [vmx@macro-vm:2] Set("SIP/22-b7956f50", "MODE=unavail") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [vmx@macro-vm:3] GotoIf("SIP/22-b7956f50", "1?notdirect") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Goto (macro-vm,vmx,5)
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] DEBUG[3375] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [vmx@macro-vm:5] NoOp("SIP/22-b7956f50", "Checking if ext 9999 is enabled: ") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Noop
[Jun 11 09:01:32] DEBUG[3375] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [vmx@macro-vm:6] GotoIf("SIP/22-b7956f50", "1?s-CHANUNAVAIL|1") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Goto (macro-vm,s-CHANUNAVAIL,1)
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s-CHANUNAVAIL@macro-vm:1] Macro("SIP/22-b7956f50", "get-vmcontext|9999") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/22-b7956f50", "VMCONTEXT=default") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Set
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/22-b7956f50", "0?200:300") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Goto (macro-get-vmcontext,s,300)
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: GotoIf
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/22-b7956f50", "") in new stack
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: NoOp
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Macro
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s-CHANUNAVAIL@macro-vm:2] Playback("SIP/22-b7956f50", "custom/voicemail_9999") in new stack
[Jun 11 09:01:32] WARNING[3375] file.c: File custom/voicemail_9999 does not exist in any format
[Jun 11 09:01:32] WARNING[3375] file.c: Unable to open custom/voicemail_9999 (format 0x4 (ulaw)): No such file or directory
[Jun 11 09:01:32] WARNING[3375] app_playback.c: ast_streamfile failed on SIP/22-b7956f50 for custom/voicemail_9999
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Playback
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s-CHANUNAVAIL@macro-vm:3] VoiceMail("SIP/22-b7956f50", "9999@default|") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- <SIP/22-b7956f50> Playing 'vm-intro' (language 'de')
[Jun 11 09:01:32] WARNING[3375] file.c: File custom/voicemail_9999 does not exist in any format
[Jun 11 09:01:32] WARNING[3375] file.c: Unable to open custom/voicemail_9999 (format 0x4 (ulaw)): No such file or directory
[Jun 11 09:01:32] WARNING[3375] app_playback.c: ast_streamfile failed on SIP/22-b7956f50 for custom/voicemail_9999
[Jun 11 09:01:32] DEBUG[3375] app_macro.c: Executed application: Playback
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- Executing [s-CHANUNAVAIL@macro-vm:3] VoiceMail("SIP/22-b7956f50", "9999@default|") in new stack
[Jun 11 09:01:32] VERBOSE[3375] logger.c: -- <SIP/22-b7956f50> Playing 'vm-intro' (language 'de')
[Jun 11 09:01:35] VERBOSE[2292] logger.c: -- Registered SIP '22' at 192.168.10.6 port 5060 expires 120
[Jun 11 09:01:38] VERBOSE[3375] logger.c: -- <SIP/22-b7956f50> Playing 'beep' (language 'de')
[Jun 11 09:01:38] VERBOSE[2292] logger.c: -- Registered SIP '22' at 192.168.0.78 port 2051 expires 60
[Jun 11 09:01:38] VERBOSE[3375] logger.c: -- Recording the message
[Jun 11 09:01:38] VERBOSE[3375] logger.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/9999/tmp/XwW7Gv format: wav, 0x927d560

висеть может несколько минут, завершает по таймауту

когда звонящий кладет трубку Voicemail на это никак не реагирует

voicemail.conf:

[general]

emailbody=${VM_NAME},\n\nThere is a new voicemail in mailbox ${VM_MAILBOX}:\n\n\tFrom:\t${VM_CALLERID}\n\tLength:\t${VM_DUR} seconds\n\tDate:\t${VM_DATE}\n\n

; 1st listed format gets emailed
;format=wav49|wav
format=wav
serveremail=vm@asterisk


attach=yes
pbxskip=yes ; Don't put [PBX]: in the subject line
fromstring=Voicemail System ; Real name of email sender
maxmessage=180 ; max length of vm message
minmessage=3 ; Minimum length of a voicemail message in seconds
maxsilence=5 ; Wait for 5 silent seconds and end the voicemail
silencethreshold=128 ; What do we consider to be silence
skipms=3000 ; How many miliseconds to skip forward/back when rew/ff in message playback
review=yes ; Allow sender to review/rerecord their message before saving it
operator=yes ; Allow caller to press 0
nextaftercmd=yes ; Automagically play next message when current message is deleted or saved


[default]

9999 => 11,VM-ext-9999,astersik-test@localhost,astersik-test@localhost,attach=yes|saycid=no|envelope=no|delete=no

Полагаю, что у * проблемы с созданием временного файла и открытием его для записи. На этом процессе он и виснет.
ФС в порядке? lsof что говорит, файл создан? А если попробовать записать разговор, запишется?

# lsof /var/spool/asterisk/voicemail/default/9999/tmp/GbuH5o
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
asterisk 2201 asterisk 36u REG 3,2 0 550006 /var/spool/asterisk/voicemail/default/9999/tmp/GbuH5o

ls -l /var/spool/asterisk/voicemail/default/9999/tmp/
total 4
-rw------- 1 asterisk asterisk 0 Jun 11 10:17 GbuH5o
-rwx------ 1 asterisk asterisk 44 Jun 11 10:17 GbuH5o.wav


файл создается, но размер не изменяется

Еще 2 вопроса были =) Можно вместо ответа на них подправить код *, чтобы он на каждый чих выдавал какое-либо сообщение в консоль и таким образом ловить точку залипания.

проверить ФС не могу т.к. нет доступа к управлению виртуальной машины чтобы загрузиться с другой системы

про чих имелось ввиду logger.conf ?
console => notice,warning,error,dtmf,verbose,debug

cat /var/log/messages|grep error -i
выдает пустой ответ

-- Executing [s@macro-get-vmcontext:300] NoOp("SIP/22-b7978a40", "") in new stack
[Jun 11 10:56:51] DEBUG[4008]: app_macro.c:337 _macro_exec: Executed application: NoOp
[Jun 11 10:56:51] DEBUG[4008]: app_macro.c:337 _macro_exec: Executed application: Macro
-- Executing [s-CHANUNAVAIL@macro-vm:2] Playback("SIP/22-b7978a40", "custom/voicemail_9999") in new stack
[Jun 11 10:56:51] WARNING[4008]: file.c:602 ast_openstream_full: File custom/voicemail_9999 does not exist in any format
[Jun 11 10:56:51] WARNING[4008]: file.c:912 ast_streamfile: Unable to open custom/voicemail_9999 (format 0x4 (ulaw)): No such file or directory
[Jun 11 10:56:51] WARNING[4008]: app_playback.c:439 playback_exec: ast_streamfile failed on SIP/22-b7978a40 for custom/voicemail_9999
[Jun 11 10:56:51] DEBUG[4008]: app_macro.c:337 _macro_exec: Executed application: Playback
-- Executing [s-CHANUNAVAIL@macro-vm:3] VoiceMail("SIP/22-b7978a40", "9999@default|") in new stack
-- <SIP/22-b7978a40> Playing 'vm-intro' (language 'de')
-- <SIP/22-b7978a40> Playing 'beep' (language 'de')
-- Recording the message
-- x=0, open writing: /var/spool/asterisk/voicemail/default/9999/tmp/11Q8sJ format: wav, 0x92c3bb0

и тишина

Monitor пишет разговор. Hangup не видит и продолжает писать дальше. Файл создается и растет по размеру до принудительного разрыва канала командой soft hangup. Писал как в папку Monitor (по умолчанию), так и в var/spool/asterisk/voicemail/default/9999/tmp/