Call recording on trunk to trunk calls not working

beerbelly · October 20, 2012, 9:58pm

I have installed FreePBX Distro (FreePBX-1.817.210.58-x86_64-Full-1350436394) basically to act as a SIP gateway between a Lync Server and an old Cisco router. That’s working fine, it’s simply bridging 2 trunks, one to Lync, one to Cisco. I was hoping to leverage FreePBX to record all calls passing through. I have tried every variation of settings to record all calls on my two inbound routes to no avail. I’ve also tried redirecting the inbound route to a call recording module, then out the trunk but that hasn’t worked either.

Here’s a snippet of one inbound call, I notice that CALL_REC_POLICY doesn’t appear to be set. Did I miss something on the install, or (hopefully not) does calling from trunk to trunk end up bypassing the call recording logic?

-- Executing [s@sub-record-check:13] ^[[1;36mExecIf^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m0?Set(__REC_POLICY_MODE=)^[[0m") in new stack
    -- Executing [s@sub-record-check:14] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35mNOW=1350767390^[[0m") in new stack
    -- Executing [s@sub-record-check:15] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m__DAY=20^[[0m") in new stack
    -- Executing [s@sub-record-check:16] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m__MONTH=10^[[0m") in new stack
    -- Executing [s@sub-record-check:17] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m__YEAR=2012^[[0m") in new stack
    -- Executing [s@sub-record-check:18] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m__TIMESTR=20121020-170950^[[0m") in new stack
    -- Executing [s@sub-record-check:19] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m__FROMEXTEN=6039869333^[[0m") in new stack
    -- Executing [s@sub-record-check:20] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m__CALLFILENAME=out-1751-6039869333-20121020-170950-1350767390.50^[[0m") in new stack
    -- Executing [s@sub-record-check:21] ^[[1;36mGoto^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35mout,1^[[0m") in new stack
    -- Goto (sub-record-check,out,1)
    -- Executing [out@sub-record-check:1] ^[[1;36mExecIf^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m1?Set(__REC_POLICY_MODE=)^[[0m") in new stack
    -- Executing [out@sub-record-check:2] ^[[1;36mGosubIf^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m0?record,1(exten,1751,6039869333)^[[0m") in new stack
    -- Executing [out@sub-record-check:3] ^[[1;36mReturn^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m^[[0m") in new stack
    -- Executing [1751@from-internal:5] ^[[1;36mMacro^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35mdialout-trunk,2,+19173861751,^[[0m") in new stack
    -- Executing [s@macro-dialout-trunk:1] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35mDIAL_TRUNK=2^[[0m") in new stack
    -- Executing [s@macro-dialout-trunk:2] ^[[1;36mGosubIf^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m0?sub-pincheck,s,1()^[[0m") in new stack
    -- Executing [s@macro-dialout-trunk:3] ^[[1;36mGotoIf^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m0?disabletrunk,1^[[0m") in new stack
    -- Executing [s@macro-dialout-trunk:4] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35mDIAL_NUMBER=+19173861751^[[0m") in new stack
    -- Executing [s@macro-dialout-trunk:5] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35mDIAL_TRUNK_OPTIONS=trx^[[0m") in new stack
    -- Executing [s@macro-dialout-trunk:6] ^[[1;36mSet^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35mOUTBOUND_GROUP=OUT_2^[[0m") in new stack
    -- Executing [s@macro-dialout-trunk:7] ^[[1;36mGotoIf^[[0m("^[[1;35mSIP/Cisco_PSTN-00000032^[[0m", "^[[1;35m1?nomax^[[0m") in new stack
    -- Goto (macro-dialout-trunk,s,9)

Any help would be appreciated!

dicko · October 20, 2012, 10:44pm

It would appear that there is an attempt to record your call by default in

/var/spool/asterisk/monitor/out-1751-6039869333-20121020-170950-1350767390.50

If you care to re-post without the ansi sequences It would be easier for non vt100 compliant warmware ,like most of us here, to read though.

beerbelly · October 20, 2012, 11:31pm

Sorry about that! I was being lazy and didn’t increase the putty buffer or change the terminal settings. In any event, thanks for the quick response.

Here’s another capture:

    -- Executing [1751@from-internal:1] Macro("SIP/Cisco_PSTN-00000045", "user-callerid,LIMIT,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("SIP/Cisco_PSTN-00000045", "AMPUSER=6039869333") in new stack
    -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Cisco_PSTN-00000045", "0?report") in new stack
    -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Cisco_PSTN-00000045", "1?Set(REALCALLERIDNUM=6039869333)") in new stack
    -- Executing [s@macro-user-callerid:4] Set("SIP/Cisco_PSTN-00000045", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:5] Set("SIP/Cisco_PSTN-00000045", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Cisco_PSTN-00000045", "1?report") in new stack
    -- Goto (macro-user-callerid,s,13)
    -- Executing [s@macro-user-callerid:13] GotoIf("SIP/Cisco_PSTN-00000045", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,26)
    -- Executing [s@macro-user-callerid:26] Set("SIP/Cisco_PSTN-00000045", "CALLERID(number)=6039869333") in new stack
    -- Executing [s@macro-user-callerid:27] Set("SIP/Cisco_PSTN-00000045", "CALLERID(name)=") in new stack
    -- Executing [s@macro-user-callerid:28] Set("SIP/Cisco_PSTN-00000045", "CHANNEL(language)=en") in new stack
    -- Executing [1751@from-internal:2] Set("SIP/Cisco_PSTN-00000045", "MOHCLASS=default") in new stack
    -- Executing [1751@from-internal:3] Set("SIP/Cisco_PSTN-00000045", "_NODEST=") in new stack
    -- Executing [1751@from-internal:4] Gosub("SIP/Cisco_PSTN-00000045", "sub-record-check,s,1(out,1751,)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("SIP/Cisco_PSTN-00000045", "1?check") in new stack
    -- Goto (sub-record-check,s,6)
    -- Executing [s@sub-record-check:6] Set("SIP/Cisco_PSTN-00000045", "__MON_FMT=wav") in new stack
    -- Executing [s@sub-record-check:7] GotoIf("SIP/Cisco_PSTN-00000045", "1?next") in new stack
    -- Goto (sub-record-check,s,10)
    -- Executing [s@sub-record-check:10] ExecIf("SIP/Cisco_PSTN-00000045", "0?Return()") in new stack
    -- Executing [s@sub-record-check:11] GotoIf("SIP/Cisco_PSTN-00000045", "0?out,1") in new stack
    -- Executing [s@sub-record-check:12] Set("SIP/Cisco_PSTN-00000045", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(__REC_POLICY_MODE=)") in new stack
    -- Executing [s@sub-record-check:14] Set("SIP/Cisco_PSTN-00000045", "NOW=1350774713") in new stack
    -- Executing [s@sub-record-check:15] Set("SIP/Cisco_PSTN-00000045", "__DAY=20") in new stack
    -- Executing [s@sub-record-check:16] Set("SIP/Cisco_PSTN-00000045", "__MONTH=10") in new stack
    -- Executing [s@sub-record-check:17] Set("SIP/Cisco_PSTN-00000045", "__YEAR=2012") in new stack
    -- Executing [s@sub-record-check:18] Set("SIP/Cisco_PSTN-00000045", "__TIMESTR=20121020-191153") in new stack
    -- Executing [s@sub-record-check:19] Set("SIP/Cisco_PSTN-00000045", "__FROMEXTEN=6039869333") in new stack
    -- Executing [s@sub-record-check:20] Set("SIP/Cisco_PSTN-00000045", "__CALLFILENAME=out-1751-6039869333-20121020-191153-1350774713.69") in new stack
    -- Executing [s@sub-record-check:21] Goto("SIP/Cisco_PSTN-00000045", "out,1") in new stack
    -- Goto (sub-record-check,out,1)
    -- Executing [out@sub-record-check:1] ExecIf("SIP/Cisco_PSTN-00000045", "1?Set(__REC_POLICY_MODE=)") in new stack
    -- Executing [out@sub-record-check:2] GosubIf("SIP/Cisco_PSTN-00000045", "0?record,1(exten,1751,6039869333)") in new stack
    -- Executing [out@sub-record-check:3] Return("SIP/Cisco_PSTN-00000045", "") in new stack
    -- Executing [1751@from-internal:5] Macro("SIP/Cisco_PSTN-00000045", "dialout-trunk,2,+19173861751,") in new stack
    -- Executing [s@macro-dialout-trunk:1] Set("SIP/Cisco_PSTN-00000045", "DIAL_TRUNK=2") in new stack
    -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/Cisco_PSTN-00000045", "0?sub-pincheck,s,1()") in new stack
    -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/Cisco_PSTN-00000045", "0?disabletrunk,1") in new stack
    -- Executing [s@macro-dialout-trunk:4] Set("SIP/Cisco_PSTN-00000045", "DIAL_NUMBER=+19173861751") in new stack
    -- Executing [s@macro-dialout-trunk:5] Set("SIP/Cisco_PSTN-00000045", "DIAL_TRUNK_OPTIONS=trx") in new stack
    -- Executing [s@macro-dialout-trunk:6] Set("SIP/Cisco_PSTN-00000045", "OUTBOUND_GROUP=OUT_2") in new stack
    -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/Cisco_PSTN-00000045", "1?nomax") in new stack
    -- Goto (macro-dialout-trunk,s,9)
    -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/Cisco_PSTN-00000045", "0?skipoutcid") in new stack
    -- Executing [s@macro-dialout-trunk:10] Set("SIP/Cisco_PSTN-00000045", "DIAL_TRUNK_OPTIONS=X") in new stack
    -- Executing [s@macro-dialout-trunk:11] Macro("SIP/Cisco_PSTN-00000045", "outbound-callerid,2") in new stack
    -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(CALLERPRES()=)") in new stack
    -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(REALCALLERIDNUM=6039869333)") in new stack
    -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/Cisco_PSTN-00000045", "1?normcid") in new stack
    -- Goto (macro-outbound-callerid,s,6)
    -- Executing [s@macro-outbound-callerid:6] Set("SIP/Cisco_PSTN-00000045", "USEROUTCID=") in new stack
    -- Executing [s@macro-outbound-callerid:7] Set("SIP/Cisco_PSTN-00000045", "EMERGENCYCID=") in new stack
    -- Executing [s@macro-outbound-callerid:8] Set("SIP/Cisco_PSTN-00000045", "TRUNKOUTCID=") in new stack
    -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/Cisco_PSTN-00000045", "1?trunkcid") in new stack
    -- Goto (macro-outbound-callerid,s,12)
    -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(CALLERID(all)=)") in new stack
    -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(CALLERID(all)=)") in new stack
    -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(CALLERID(all)=)") in new stack
    -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
    -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/Cisco_PSTN-00000045", "0?sub-flp-2,s,1()") in new stack
    -- Executing [s@macro-dialout-trunk:13] Set("SIP/Cisco_PSTN-00000045", "OUTNUM=+19173861751") in new stack
    -- Executing [s@macro-dialout-trunk:14] Set("SIP/Cisco_PSTN-00000045", "custom=SIP/Lync") in new stack
    -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)X)") in new stack
    -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(DIAL_TRUNK_OPTIONS=XM(confirm))") in new stack
    -- Executing [s@macro-dialout-trunk:17] Macro("SIP/Cisco_PSTN-00000045", "dialout-trunk-predial-hook,") in new stack
    -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/Cisco_PSTN-00000045", "") in new stack
    -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/Cisco_PSTN-00000045", "0?bypass,1") in new stack
    -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(CONNECTEDLINE(num,i)=+19173861751)") in new stack
    -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/Cisco_PSTN-00000045", "0?Set(CONNECTEDLINE(name,i)=CID:6039869333)") in new stack
    -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/Cisco_PSTN-00000045", "0?customtrunk") in new stack
    -- Executing [s@macro-dialout-trunk:22] Dial("SIP/Cisco_PSTN-00000045", "SIP/Lync/+19173861751,300,X") in new stack
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
Audio is at 13542
Adding codec 0x4 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 192.168.11.35:5060:
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/TCP 192.168.11.38:5060;branch=z9hG4bK04569ec4;rport
Max-Forwards: 70
From: "6039869333" <sip:[email protected]>;tag=as11d3861e
To: <sip:[email protected]:5060>
Contact: <sip:[email protected]:5060;transport=TCP>
Call-ID: [email protected]
CSeq: 102 INVITE
User-Agent: FPBX-2.10.1(1.8.17.0)
Date: Sat, 20 Oct 2012 23:11:53 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 239

v=0
o=root 1825419471 1825419471 IN IP4 192.168.11.38
s=Asterisk PBX 1.8.17.0
c=IN IP4 192.168.11.38
t=0 0
m=audio 13542 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

(REMOVED MOST OF THE SIP)

Scheduling destruction of SIP dialog 'f006da82814942bbbfd2abda41392e5b' in 32000 ms (Method: OPTIONS)
    -- Executing [h@macro-dialout-trunk:1] Macro("SIP/Cisco_PSTN-00000049", "hangupcall,") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Cisco_PSTN-00000049", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("SIP/Cisco_PSTN-00000049", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("SIP/Cisco_PSTN-00000049", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Cisco_PSTN-00000049' in macro 'hangupcall'
  == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/Cisco_PSTN-00000049'
Scheduling destruction of SIP dialog '[email protected]' in 6400 ms (Method: INVITE)

I can see it setting the recording name, and it is creating the tree /var/spool/asterisk/monitor/2012/10/20 but it’s not populating it. Also, it’s worth noting that CDR seems to be working fine.

Thanks again!

dicko · October 20, 2012, 11:49pm

The only thing I note is there is no extension to the callfilename, it would normally be .wav by default, it was also brouught to my attention that FreePBX 2.10 uses a different set of logic as to what gets’s recorded comparded to previous releases, so sorry, If you are using 2.10 then I am as yet out of my depth.

beerbelly · October 21, 2012, 12:27am

I found it, I was using the from-internal context on my trunks which must not hit the call recorder properly (presumably because that might conflict with internal device recordings <-- WAG).

Now my Lync trunk (set to from-sip-external) won’t dial out, it hits “ss-noservice”, so I have to find a workaround for that. If you have any quick ideas on that I would be grateful, but I bet I can work that out with a custom context.

Thanks so much for your time!

beerbelly · October 21, 2012, 12:59am

OK, after looking at tweaking the contexts, I was getting some logging on the difference between the behavior of the Lync trunk and the Cisco trunk (which are configured for all intents and purposes identically) in order to put a custom context in play for Lync it “Just Started Working”. This concerns me, but maybe it was something lync was doing temporarily (I know Asterisk doesn’t cache much, and don’t put it past anything MS puts out!).

Anyway, hopefully it works stably through a couple days of testing and reboots.

Thanks again.