I’m following Shaun Ewing’s guide to installing the “Lenny” application
(I’m using FreePBX 14.0.13.23 on a fully-updated RasPBX 04-04-2018 image running on a Pi 2B. I deliberately wanted to use the latest FreePBX 14 as I’m expecting to use the John Fawcett’s Dynamic Routing module and that doesn’t seem to have a version for FreePBX 15 yet.)
Lenny is working perfectly fine, from the callers point of view. I get to listen to Lenny, he detects my silences or chatter just fine.
But having set up call recording on all incoming calls, I’m unable to discover why calls to Lenny end up as 44 byte .wav files, whereas calls between extensions or from trunks that don’t reach his dulcet tones are recorded normally? (Clearly half the point of Lenny is recording the chaos wrought by him!)
Shaun’s instructions had me create a virtual extension as the destination for the calls, and set recording preferences on that extension. This approach generated some errors in the asterisk log:
...
[2019-12-27 22:04:31] VERBOSE[4501][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp("SIP/8888-00000015", "Starting recording: internal, 6666") in new stack
[2019-12-27 22:04:31] VERBOSE[4501][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:17] Set("SIP/8888-00000015", "__CALLFILENAME=internal-6666-8888-20191227-220431-1577484271.21") in new stack
...
[2019-12-27 22:04:31] WARNING[4501][C-0000000e] channel.c: No channel type registered for 'VIRTUAL'
[2019-12-27 22:04:31] WARNING[4501][C-0000000e] app_dial.c: Unable to create channel of type 'VIRTUAL' (cause 66 - Channel not implemented)
[2019-12-27 22:04:31] VERBOSE[4501][C-0000000e] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
...
…and the recording file was a truncated 44 byte stub:
root@raspbx:/var/spool/asterisk/monitor/2019/12/27# ls -l /var/spool/asterisk/monitor/*/*/*/*1577484271.21*
-rw-r--r-- 1 asterisk asterisk 44 Dec 27 22:04 internal-6666-8888-20191227-220431-1577484271.21.wav
I then tried his other approach and included the MixMonitor application in the Lenny dial plan itself, which made no detectable difference to the outcome:
[Lenny]
exten => talk,1,Set(i=${IF($["0${i}"="016"]?7:$[0${i}+1])})
same => n,ExecIf($[${i}=1]?MixMonitor(${UNIQUEID}.wav))
same => n,Playback(Lenny/Lenny${i})
same => n,BackgroundDetect(Lenny/backgroundnoise,1500)
Next I tried @lgaetz advice in this post, and instead created a Misc. Application to point to the Custom Destination.
Here are the logs from another successful call to Lenny, with no errors:
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [6667@from-internal:1] NoOp("SIP/8888-00000017", "Running miscapp 1: Its Lenny") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [6667@from-internal:2] Macro("SIP/8888-00000017", "user-callerid,") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/8888-00000017", "TOUCH_MONITOR=1577485200.23") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/8888-00000017", "AMPUSER=8888") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/8888-00000017", "0?report") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/8888-00000017", "1?Set(REALCALLERIDNUM=8888)") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/8888-00000017", "AMPUSER=8888") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/8888-00000017", "0?limit") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/8888-00000017", "AMPUSERCIDNAME=RasPBX Test") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/8888-00000017", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/8888-00000017", "0?report") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/8888-00000017", "AMPUSERCID=8888") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/8888-00000017", "__DIAL_OPTIONS=Ttr") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:12] Set("SIP/8888-00000017", "CALLERID(all)="RasPBX Test" <8888>") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("SIP/8888-00000017", "0?Set(CALLERID(all)=)") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("SIP/8888-00000017", "0?limit") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("SIP/8888-00000017", "0?Set(GROUP(concurrency_limit)=8888)") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:16] NoOp("SIP/8888-00000017", "Macro Depth is 1") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("SIP/8888-00000017", "1?report2:macroerror") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/8888-00000017", "0?continue") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:19] Set("SIP/8888-00000017", "__TTL=64") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:20] GotoIf("SIP/8888-00000017", "1?continue") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx_builtins.c: Goto (macro-user-callerid,s,36)
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:36] Set("SIP/8888-00000017", "CALLERID(number)=8888") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/8888-00000017", "CALLERID(name)=RasPBX Test") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:38] GotoIf("SIP/8888-00000017", "0?cnum") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:39] Set("SIP/8888-00000017", "CDR(cnam)=RasPBX Test") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/8888-00000017", "CDR(cnum)=8888") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/8888-00000017", "CHANNEL(language)=en_GB") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [6667@from-internal:3] Goto("SIP/8888-00000017", "Lenny,talk,1") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx_builtins.c: Goto (Lenny,talk,1)
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [talk@Lenny:1] Set("SIP/8888-00000017", "i=1") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [talk@Lenny:2] ExecIf("SIP/8888-00000017", "1?MixMonitor(1577485200.23.wav)") in new stack
[2019-12-27 22:20:00] VERBOSE[5344][C-00000010] app_mixmonitor.c: Begin MixMonitor Recording SIP/8888-00000017
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] pbx.c: Executing [talk@Lenny:3] Playback("SIP/8888-00000017", "Lenny/Lenny1") in new stack
[2019-12-27 22:20:00] VERBOSE[5343][C-00000010] file.c: <SIP/8888-00000017> Playing 'Lenny/Lenny1.ulaw' (language 'en_GB')
[2019-12-27 22:20:05] VERBOSE[5343][C-00000010] pbx.c: Executing [talk@Lenny:4] BackgroundDetect("SIP/8888-00000017", "Lenny/backgroundnoise,1500") in new stack
[2019-12-27 22:20:05] VERBOSE[5343][C-00000010] file.c: <SIP/8888-00000017> Playing 'Lenny/backgroundnoise.ulaw' (language 'en_GB')
[2019-12-27 22:20:11] VERBOSE[5343][C-00000010] pbx.c: Spawn extension (Lenny, talk, 4) exited non-zero on 'SIP/8888-00000017'
[2019-12-27 22:20:11] VERBOSE[5344][C-00000010] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2019-12-27 22:20:11] VERBOSE[5344][C-00000010] app_mixmonitor.c: End MixMonitor Recording SIP/8888-00000017
But in this case I don’t get a recording file created at all, despite the MixMonitor entries above?
I’m puzzled and would appreciate any guidance!
My googling had indicated this “44 byte recording” issue might be related to missing / incompatible codecs or transcoders? So I updated Asterisk SIP Settings to include only alaw, gsm, g726 and ulaw (I’m in the UK, if it matters). No improvement.
This next bit may be irrelevant, please ignore if so.
When a call is in progress between extensions (that does generate a recording), the CLI shows two active legs of the call, and on one I see:
raspbx*CLI> core show channel SIP/8888-00000013
-- General --
Name: SIP/8888-00000013
Type: SIP
UniqueID: 1577484006.19
LinkedID: 1577484006.19
Caller ID: 8888
Caller ID Name: RasPBX Test
Connected Line ID: 44***redacted***
Connected Line ID Name: Maven Cottage Phones
Eff. Connected Line ID: 44***redacted***
Eff. Connected Line ID Name: Maven Cottage Phones
DNID Digits: 44***redacted***
Language: en_GB
State: Up (6)
NativeFormats: (alaw)
WriteFormat: alaw
ReadFormat: alaw
WriteTranscode: No
ReadTranscode: No
When I do the same with a call to Lenny, there’s only one leg to the call, and it shows:
raspbx*CLI> core show channel SIP/8888-00000010
-- General --
Name: SIP/8888-00000010
Type: SIP
UniqueID: 1577483908.16
LinkedID: 1577483908.16
Caller ID: 8888
Caller ID Name: RasPBX Test
Connected Line ID: 6666
Connected Line ID Name: Its Lenny
Eff. Connected Line ID: 6666
Eff. Connected Line ID Name: Its Lenny
DNID Digits: 6666
Language: en_GB
State: Up (6)
NativeFormats: (alaw)
WriteFormat: ulaw
ReadFormat: slin
WriteTranscode: Yes (ulaw@8000)->(alaw@8000)
ReadTranscode: Yes (alaw@8000)->(slin@8000)
Any pointers gratefully received!
Mike Thomson