[asterisk-bugs] [JIRA] (ASTERISK-20834) Call Recording Fails (mixmonitor)

Thu Dec 20 15:55:45 CST 2012

    [ https://issues.asterisk.org/jira/browse/ASTERISK-20834?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=200924#comment-200924 ] 

Philippe Lindheimer commented on ASTERISK-20834:
------------------------------------------------

Here is a call trace including the leadup for the call recording check using 10.11.0. Note thought that it fails with queues and conferences as well and the setup for each of these is a little different:

[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:1] GotoIf("SIP/701-00000000", "1?check") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Goto (sub-record-check,s,6)
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:6] Set("SIP/701-00000000", "__MON_FMT=wav") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:7] GotoIf("SIP/701-00000000", "1?next") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Goto (sub-record-check,s,10)
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:10] ExecIf("SIP/701-00000000", "0?Return()") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:11] GotoIf("SIP/701-00000000", "0?out,1") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:12] Set("SIP/701-00000000", "__REC_STATUS=INITIALIZED") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:13] ExecIf("SIP/701-00000000", "0?Set(__REC_POLICY_MODE=)") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:14] Set("SIP/701-00000000", "NOW=1356037555") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:15] Set("SIP/701-00000000", "__DAY=20") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:16] Set("SIP/701-00000000", "__MONTH=12") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:17] Set("SIP/701-00000000", "__YEAR=2012") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:18] Set("SIP/701-00000000", "__TIMESTR=20121220-130555") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:19] Set("SIP/701-00000000", "__FROMEXTEN=701") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:20] Set("SIP/701-00000000", "__CALLFILENAME=out-4257365924-701-20121220-130555-1356037555.0") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at sub-record-check:21] Goto("SIP/701-00000000", "out,1") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Goto (sub-record-check,out,1)
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [out at sub-record-check:1] NoOp("SIP/701-00000000", "[TRACE](3) Recording Check out 4257365924") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [out at sub-record-check:2] ExecIf("SIP/701-00000000", "1?Set(__REC_POLICY_MODE=always)") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [out at sub-record-check:3] GosubIf("SIP/701-00000000", "1?record,1(exten,4257365924,701)") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [record at sub-record-check:1] NoOp("SIP/701-00000000", "[TRACE](3) Setting up recording: exten, 4257365924, 701") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [record at sub-record-check:2] Set("SIP/701-00000000", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [record at sub-record-check:3] MixMonitor("SIP/701-00000000", "2012/12/20/out-4257365924-701-20121220-130555-1356037555.0.wav,,") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [record at sub-record-check:4] Set("SIP/701-00000000", "__REC_STATUS=RECORDING") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [record at sub-record-check:5] Set("SIP/701-00000000", "CDR(recordingfile)=out-4257365924-701-20121220-130555-1356037555.0.wav") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [record at sub-record-check:6] Return("SIP/701-00000000", "") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [out at sub-record-check:4] Return("SIP/701-00000000", "") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [4257365924 at outbound-1-2-3-4-5-6-9:8] Macro("SIP/701-00000000", "dialout-trunk,2,4257365924,,off") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at macro-dialout-trunk:1] Set("SIP/701-00000000", "DIAL_TRUNK=2") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at macro-dialout-trunk:2] GosubIf("SIP/701-00000000", "0?sub-pincheck,s,1()") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at macro-dialout-trunk:3] GotoIf("SIP/701-00000000", "0?disabletrunk,1") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at macro-dialout-trunk:4] Set("SIP/701-00000000", "DIAL_NUMBER=4257365924") in new stack
[2012-12-20 13:05:55] VERBOSE[12428] pbx.c:     -- Executing [s at macro-dialout-trunk:5] Set("SIP/701-00000000", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2012-12-20 13:05:55] VERBOSE[12429] app_mixmonitor.c:   == Begin MixMonitor Recording SIP/701-00000000
[2012-12-20 13:05:55] WARNING[12429] file.c: No such format '<81>Ãó^W^V'
[2012-12-20 13:05:55] ERROR[12429] app_mixmonitor.c: Cannot open /var/spool/asterisk/monitor/2012/12/20/out-4257365924-701-20121220-130555-1356037555.0.<81>Ãó^W^V

Here is the dialplan used for setting up call recordings in general:

[sub-record-check]
include => sub-record-check-custom
exten => s,1,GotoIf($["${BLINDTRANSFER}" = ""]?check)
exten => s,n,ResetCDR()
exten => s,n,GotoIf($["${REC_STATUS}" != "RECORDING"]?check)
exten => s,n,Set(AUDIOHOOK_INHERIT(MixMonitor)=yes)
exten => s,n,MixMonitor(${MIXMON_DIR}${YEAR}/${MONTH}/${DAY}/${CALLFILENAME}.${MIXMON_FORMAT},a,${MIXMON_POST})
exten => s,n(check),Set(__MON_FMT=${IF($["${MIXMON_FORMAT}"="wav49"]?WAV:${MIXMON_FORMAT})})
exten => s,n,GotoIf($["${REC_STATUS}"!="RECORDING"]?next)
exten => s,n,Set(CDR(recordingfile)=${CALLFILENAME}.${MON_FMT})
exten => s,n,Return()
exten => s,n(next),ExecIf($[!${LEN(${ARG1})}]?Return())
exten => s,n,GotoIf($["${REC_STATUS}"!=""]?${ARG1},1)
exten => s,n,Set(__REC_STATUS=INITIALIZED)
exten => s,n,ExecIf($["${REC_POLICY_MODE}"="" & "${ARG3}"!=""]?Set(__REC_POLICY_MODE=${ARG3}))
exten => s,n,Set(NOW=${EPOCH})
exten => s,n,Set(__DAY=${STRFTIME(${NOW},,%d)})
exten => s,n,Set(__MONTH=${STRFTIME(${NOW},,%m)})
exten => s,n,Set(__YEAR=${STRFTIME(${NOW},,%Y)})
exten => s,n,Set(__TIMESTR=${YEAR}${MONTH}${DAY}-${STRFTIME(${NOW},,%H%M%S)})
exten => s,n,Set(__FROMEXTEN=${IF($[${LEN(${AMPUSER})}]?${AMPUSER}:${IF($[${LEN(${REALCALLERIDNUM})}]?${REALCALLERIDNUM}:unknown)})})
exten => s,n,Set(__CALLFILENAME=${ARG1}-${ARG2}-${FROMEXTEN}-${TIMESTR}-${UNIQUEID})
exten => s,n,Goto(${ARG1},1)

exten => rg,1,Noop([TRACE](3) Recording Check ${EXTEN} ${ARG2})
exten => rg,n,GosubIf($["${REC_POLICY_MODE}"="always"]?record,1(${EXTEN},${REC_POLICY_MODE},${FROMEXTEN}))
exten => rg,n,Return()

exten => force,1,Noop([TRACE](3) Recording Check ${EXTEN} ${ARG2})
exten => force,n,GosubIf($["${REC_POLICY_MODE}"="always"]?record,1(${EXTEN},${REC_POLICY_MODE},${FROMEXTEN}))
exten => force,n,Return()

exten => q,1,Noop([TRACE](3) Recording Check ${EXTEN} ${ARG2})
exten => q,n,GosubIf($["${REC_POLICY_MODE}"="always"]?recq,1(${EXTEN},${ARG2},${FROMEXTEN}))
exten => q,n,Return()

exten => out,1,Noop([TRACE](3) Recording Check ${EXTEN} ${ARG2})
exten => out,n,ExecIf($["${REC_POLICY_MODE}"=""]?Set(__REC_POLICY_MODE=${DB(AMPUSER/${FROMEXTEN}/recording/out/external)}))
exten => out,n,GosubIf($["${REC_POLICY_MODE}"="always"]?record,1(exten,${ARG2},${FROMEXTEN}))
exten => out,n,Return()

exten => exten,1,Noop([TRACE](3) Recording Check ${EXTEN} ${ARG2})
exten => exten,n,GotoIf($["${REC_POLICY_MODE}"!=""]?callee)
exten => exten,n,Set(__REC_POLICY_MODE=${IF($[${LEN(${FROM_DID})}]?${DB(AMPUSER/${ARG2}/recording/in/external)}:${DB(AMPUSER/${ARG2}/recording/in/internal)})})
exten => exten,n,GotoIf($["${REC_POLICY_MODE}"="dontcare"]?caller)
exten => exten,n,GotoIf($["${DB(AMPUSER/${FROMEXTEN}/recording/out/internal)}"="dontcare" | "${FROM_DID}"!=""]?callee)
exten => exten,n,ExecIf($[${LEN(${DB(AMPUSER/${FROMEXTEN}/recording/priority)})}]?Set(CALLER_PRI=${DB(AMPUSER/${FROMEXTEN}/recording/priority)}):Set(CALLER_PRI=0))
exten => exten,n,ExecIf($[${LEN(${DB(AMPUSER/${ARG2}/recording/priority)})}]?Set(CALLEE_PRI=${DB(AMPUSER/${ARG2}/recording/priority)}):Set(CALLEE_PRI=0))
exten => exten,n,GotoIf($["${CALLER_PRI}"="${CALLEE_PRI}"]?${REC_POLICY}:${IF($[${CALLER_PRI}>${CALLEE_PRI}]?caller:callee)})
exten => exten,n(callee),GosubIf($["${REC_POLICY_MODE}"="always"]?record,1(${EXTEN},${ARG2},${FROMEXTEN}))
exten => exten,n,Return()
exten => exten,n(caller),Set(__REC_POLICY_MODE=${DB(AMPUSER/${FROMEXTEN}/recording/out/internal)})
exten => exten,n,GosubIf($["${REC_POLICY_MODE}"="always"]?record,1(${EXTEN},${ARG2},${FROMEXTEN}))
exten => exten,n,Return()

exten => conf,1,Noop([TRACE](3) Recording Check ${EXTEN} ${ARG2})
exten => conf,n,Gosub(recconf,1(${EXTEN},${ARG2},${ARG2}))
exten => conf,n,Return()

exten => page,1,Noop([TRACE](3) Recording Check ${EXTEN} ${ARG2})
exten => page,n,GosubIf($["${REC_POLICY_MODE}"="always"]?recconf,1(${EXTEN},${ARG2},${FROMEXTEN}))
exten => page,n,Return()

exten => record,1,Noop([TRACE](3) Setting up recording: ${ARG1}, ${ARG2}, ${ARG3})
exten => record,n,Set(AUDIOHOOK_INHERIT(MixMonitor)=yes)
exten => record,n,MixMonitor(${MIXMON_DIR}${YEAR}/${MONTH}/${DAY}/${CALLFILENAME}.${MIXMON_FORMAT},,${MIXMON_POST})
exten => record,n,Set(__REC_STATUS=RECORDING)
exten => record,n,Set(CDR(recordingfile)=${CALLFILENAME}.${MON_FMT})
exten => record,n,Return()

exten => recq,1,Noop([TRACE](3) Setting up recording: ${ARG1}, ${ARG2}, ${ARG3})
exten => recq,n,Set(AUDIOHOOK_INHERIT(MixMonitor)=yes)
exten => recq,n,Set(MONITOR_FILENAME=${MIXMON_DIR}${YEAR}/${MONTH}/${DAY}/${CALLFILENAME})
exten => recq,n,Set(__REC_STATUS=RECORDING)
exten => recq,n,Set(CDR(recordingfile)=${CALLFILENAME}.${MON_FMT})
exten => recq,n,Return()

exten => recconf,1,Noop([TRACE](3) Setting up recording: ${ARG1}, ${ARG2}, ${ARG3})
exten => recconf,n,Set(__CALLFILENAME=${IF($[${CONFBRIDGE_INFO(parties,${ARG2})}]?${DB(RECCONF/${ARG2})}:${ARG1}-${ARG2}-${ARG3}-${TIMESTR}-${UNIQUEID})})
exten => recconf,n,ExecIf($[!${CONFBRIDGE_INFO(parties,${ARG2})}]?Set(DB(RECCONF/${ARG2})=${CALLFILENAME}))
exten => recconf,n,Set(CONFBRIDGE(bridge,record_file)=${MIXMON_DIR}${YEAR}/${MONTH}/${DAY}/${CALLFILENAME}.${MON_FMT})
exten => recconf,n,ExecIf($["${REC_POLICY_MODE}"!="always"]?Return())
exten => recconf,n,Set(CONFBRIDGE(bridge,record_conference)=yes)
exten => recconf,n,Set(__REC_STATUS=RECORDING)
exten => recconf,n,Set(CDR(recordingfile)=${CALLFILENAME}.${MON_FMT})
exten => recconf,n,Return()

;--== end of [sub-record-check] ==--;

> Call Recording Fails (mixmonitor)
> ---------------------------------
>
>                 Key: ASTERISK-20834
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-20834
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>    Affects Versions: 10.11.0-digiumphones
>         Environment: FreePBX versions 2.10 and 2.11 and probably earlier
>            Reporter: Philippe Lindheimer
>            Severity: Critical
>
> when trying to record calls whether directly through mix monitor or indirectly in queues and conferences it returns with a format error. Here is an example of the error log:
> {noformat}
> [2012-12-20 15:55:57] WARNING[25595]: file.c:1241 ast_writefile: No such format 'Ãó'
> -- Executing [record at sub-record-check:4] Set("SIP/201-00000017", "CDR(recordingfile)=out-XXXXXXXXXX5-201-20121220-155557-1356011757.23.WAV") in new stack
> [2012-12-20 15:55:57] ERROR[25595]: app_mixmonitor.c:517 mixmonitor_save_prep: Cannot open /var/spool/asterisk/monitor/2012/12/20/out-XXXXXXXXXX-201-20121220-155557-1356011757.23.Ãó
> {noformat}
> This has failed since 10.9.0 (or earlier). It has been tested in both 1.8.19 and 11.1 and the error is not present in those releases so seems to be isolated to 10 for now.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira