Receptionist hearing MOH on incoming call

Oatmeal · March 20, 2017, 3:27pm

This is kind of an odd situation, but here goes.

When we receive incoming calls from the local phone provider (only local calls cause this) occasionally, and seemingly at random, when our receptionist answers, they hear music on hold, and the external caller hears dead air or a busy signal.

I’ve verified on the asterisk console that MOH is actually starting. I’ve captured a sip trace and can’t find any reason for this there.

Most calls are just fine. Any call that doesn’t come from this one local provider’s local network is fine. about 3% of local land line calls trigger this problem.

I’m not even sure where to start here. My SIP provider (same company as the local land lines that have problems) says that it’s not on their end. Really at a loss here.

FreePBX 13.0.190.7
Inbound calls go to ring group, receptionists answer from there.

lgaetz · March 20, 2017, 4:39pm

Similar issue described here:

Oatmeal · March 20, 2017, 4:49pm

I will try that, canreinvite=no and see. I’m not seeing any reinvites in the sip trace anyway, so I’m not sure what that would do. Wait and see I guess.

lgaetz · March 20, 2017, 6:15pm

I can’t see how that would possibly help either.

xrobau · March 20, 2017, 7:57pm

Pasting the call trace (SIP debug is not required) would tell us why!

Oatmeal · March 20, 2017, 8:11pm

I’m not really sure how to paste the content of the packet capture from wireshark here, but this is from the asterisk console:

-- Channel SIP/201-00003729 joined 'simple_bridge' basic-bridge <d3df8713-74f9-445d-a0be-bf948b0ceb41>
-- Channel SIP/SIP-00003728 joined 'simple_bridge' basic-bridge <d3df8713-74f9-445d-a0be-bf948b0ceb41>
   > 0x3239f80 -- Probation passed - setting RTP source address to 192.168.1.166:3000
-- Started music on hold, class 'default', on channel 'SIP/201-00003729'
   > 0x7f97e8005d60 -- Probation passed - setting RTP source address to 192.168.0.69:60034
   > 0x7f97e8005d60 -- Switching RTP source address to 192.168.0.69:60036
-- Started music on hold, class 'default', on channel 'SIP/SIP-00003724'
   > 0x322d530 -- Probation passed - setting RTP source address to 192.168.1.210:3000

== Extension Changed 212[ext-local] new state Hold for Notify User 212
== Extension Changed 212[ext-local] new state Hold for Notify User 204
== Extension Changed 212[ext-local] new state Hold for Notify User 201

It’s literally putting the receptionist on hold.

xrobau · March 20, 2017, 8:13pm

Can you please paste ALL of the log (about 50 lines above that is what you want)

Oatmeal · March 20, 2017, 8:24pm

This is what I was able to capture, it’s a crapshoot because this doesn’t happen predictably. (changed names/numbers to protect the guilty)

-- Executing [2156@from-trunk:3] Set("SIP/SIP-00003728", "__FROM_DID=2156") in new stack
-- Executing [2156@from-trunk:4] Goto("SIP/SIP-00003728", "ext-did,s,1") in new stack
-- Goto (ext-did,s,1)
-- Executing [s@ext-did:1] Set("SIP/SIP-00003728", "__DIRECTION=INBOUND") in new stack
-- Executing [s@ext-did:2] Gosub("SIP/SIP-00003728", "sub-record-check,s,1(in,s,dontcare)") in new stack
-- Executing [s@sub-record-check:1] GotoIf("SIP/SIP-00003728", "0?initialized") in new stack
-- Executing [s@sub-record-check:2] Set("SIP/SIP-00003728", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [s@sub-record-check:3] Set("SIP/SIP-00003728", "NOW=1490020722") in new stack
-- Executing [s@sub-record-check:4] Set("SIP/SIP-00003728", "__DAY=20") in new stack
-- Executing [s@sub-record-check:5] Set("SIP/SIP-00003728", "__MONTH=03") in new stack
-- Executing [s@sub-record-check:6] Set("SIP/SIP-00003728", "__YEAR=2017") in new stack
-- Executing [s@sub-record-check:7] Set("SIP/SIP-00003728", "__TIMESTR=20170320-093842") in new stack
-- Executing [s@sub-record-check:8] Set("SIP/SIP-00003728", "__FROMEXTEN=unknown") in new stack
-- Executing [s@sub-record-check:9] Set("SIP/SIP-00003728", "__MON_FMT=wav") in new stack
-- Executing [s@sub-record-check:10] NoOp("SIP/SIP-00003728", "Recordings initialized") in new stack
-- Executing [s@sub-record-check:11] ExecIf("SIP/SIP-00003728", "0?Set(ARG3=dontcare)") in new stack
-- Executing [s@sub-record-check:12] Set("SIP/SIP-00003728", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [s@sub-record-check:13] ExecIf("SIP/SIP-00003728", "0?Set(REC_STATUS=NO)") in new stack
-- Executing [s@sub-record-check:14] GotoIf("SIP/SIP-00003728", "2?checkaction") in new stack
-- Goto (sub-record-check,s,17)
-- Executing [s@sub-record-check:17] GotoIf("SIP/SIP-00003728", "1?sub-record-check,in,1") in new stack
-- Goto (sub-record-check,in,1)
-- Executing [in@sub-record-check:1] NoOp("SIP/SIP-00003728", "Inbound Recording Check to s") in new stack
-- Executing [in@sub-record-check:2] Set("SIP/SIP-00003728", "FROMEXTEN=unknown") in new stack
-- Executing [in@sub-record-check:3] ExecIf("SIP/SIP-00003728", "10?Set(FROMEXTEN=EXTERNALCALLER)") in new stack
-- Executing [in@sub-record-check:4] Gosub("SIP/SIP-00003728", "recordcheck,1(dontcare,in,s)") in new stack
-- Executing [recordcheck@sub-record-check:1] NoOp("SIP/SIP-00003728", "Starting recording check against dontcare") in new stack
-- Executing [recordcheck@sub-record-check:2] Goto("SIP/SIP-00003728", "dontcare") in new stack
-- Goto (sub-record-check,recordcheck,3)
-- Executing [recordcheck@sub-record-check:3] Return("SIP/SIP-00003728", "") in new stack
-- Executing [in@sub-record-check:5] Return("SIP/SIP-00003728", "") in new stack
-- Executing [s@ext-did:3] Gosub("SIP/SIP-00003728", "app-blacklist-check,s,1()") in new stack
-- Executing [s@app-blacklist-check:1] GotoIf("SIP/SIP-00003728", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:2] Set("SIP/SIP-00003728", "CALLED_BLACKLIST=1") in new stack
-- Executing [s@app-blacklist-check:3] Return("SIP/SIP-00003728", "") in new stack
-- Executing [s@ext-did:4] ExecIf("SIP/SIP-00003728", "0?Set(__FROM_DID=s)") in new stack
-- Executing [s@ext-did:5] Set("SIP/SIP-00003728", "CDR(did)=2156") in new stack
-- Executing [s@ext-did:6] ExecIf("SIP/SIP-00003728", "0 ?Set(CALLERID(name)=EXTERNALCALLER)") in new stack
-- Executing [s@ext-did:7] Set("SIP/SIP-00003728", "__MOHCLASS=") in new stack
-- Executing [s@ext-did:8] Set("SIP/SIP-00003728", "__REVERSAL_REJECT=FALSE") in new stack
-- Executing [s@ext-did:9] GotoIf("SIP/SIP-00003728", "1?post-reverse-charge") in new stack
-- Goto (ext-did,s,11)
-- Executing [s@ext-did:11] NoOp("SIP/SIP-00003728", "") in new stack
-- Executing [s@ext-did:12] Set("SIP/SIP-00003728", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
-- Executing [s@ext-did:13] Set("SIP/SIP-00003728", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
-- Executing [s@ext-did:14] Set("SIP/SIP-00003728", "CALLERID(name-pres)=allowed_not_screened") in new stack
-- Executing [s@ext-did:15] Set("SIP/SIP-00003728", "CALLERID(num-pres)=allowed_not_screened") in new stack
-- Executing [s@ext-did:16] NoOp("SIP/SIP-00003728", "CallerID Entry Point") in new stack
-- Executing [s@ext-did:17] Goto("SIP/SIP-00003728", "ext-group,720,1") in new stack
-- Goto (ext-group,720,1)
-- Executing [720@ext-group:1] Progress("SIP/SIP-00003728", "") in new stack
-- Executing [720@ext-group:2] Macro("SIP/SIP-00003728", "user-callerid,") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/SIP-00003728", "TOUCH_MONITOR=1490020722.20950") in new stack
-- Executing [s@macro-user-callerid:2] Set("SIP/SIP-00003728", "AMPUSER=EXTERNALCALLER") in new stack
-- Executing [s@macro-user-callerid:3] GotoIf("SIP/SIP-00003728", "0?report") in new stack
-- Executing [s@macro-user-callerid:4] ExecIf("SIP/SIP-00003728", "1?Set(REALCALLERIDNUM=EXTERNALCALLER)") in new stack
-- Executing [s@macro-user-callerid:5] Set("SIP/SIP-00003728", "AMPUSER=") in new stack
-- Executing [s@macro-user-callerid:6] GotoIf("SIP/SIP-00003728", "0?limit") in new stack
-- Executing [s@macro-user-callerid:7] Set("SIP/SIP-00003728", "AMPUSERCIDNAME=") in new stack
-- Executing [s@macro-user-callerid:8] GotoIf("SIP/SIP-00003728", "1?report") in new stack
-- Goto (macro-user-callerid,s,15)
-- Executing [s@macro-user-callerid:15] GotoIf("SIP/SIP-00003728", "0?continue") in new stack
-- Executing [s@macro-user-callerid:16] ExecIf("SIP/SIP-00003728", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
-- Executing [s@macro-user-callerid:17] Set("SIP/SIP-00003728", "__TTL=64") in new stack
-- Executing [s@macro-user-callerid:18] GotoIf("SIP/SIP-00003728", "1?continue") in new stack
-- Goto (macro-user-callerid,s,29)
-- Executing [s@macro-user-callerid:29] Set("SIP/SIP-00003728", "CALLERID(number)=EXTERNALCALLER2") in new stack
-- Executing [s@macro-user-callerid:30] Set("SIP/SIP-00003728", "CALLERID(name)=EXTERNALCALLER") in new stack
-- Executing [s@macro-user-callerid:31] GotoIf("SIP/SIP-00003728", "0?cnum") in new stack
-- Executing [s@macro-user-callerid:32] Set("SIP/SIP-00003728", "CDR(cnam)=EXTERNALCALLER") in new stack
-- Executing [s@macro-user-callerid:33] Set("SIP/SIP-00003728", "CDR(cnum)=EXTERNALCALLER") in new stack
-- Executing [s@macro-user-callerid:34] Set("SIP/SIP-00003728", "CHANNEL(language)=en") in new stack
-- Executing [720@ext-group:3] Macro("SIP/SIP-00003728", "blkvm-setifempty,") in new stack
-- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/SIP-00003728", "1?init") in new stack
-- Goto (macro-blkvm-setifempty,s,4)
-- Executing [s@macro-blkvm-setifempty:4] Set("SIP/SIP-00003728", "__BLKVM_CHANNEL=SIP/SIP-00003728") in new stack
-- Executing [s@macro-blkvm-setifempty:5] Set("SIP/SIP-00003728", "SHARED(BLKVM,SIP/SIP-00003728)=TRUE") in new stack
-- Executing [s@macro-blkvm-setifempty:6] Set("SIP/SIP-00003728", "GOSUB_RETVAL=TRUE") in new stack
-- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/SIP-00003728", "") in new stack
-- Executing [720@ext-group:4] GotoIf("SIP/SIP-00003728", "1?skipov") in new stack
-- Goto (ext-group,720,7)
-- Executing [720@ext-group:7] Set("SIP/SIP-00003728", "RRNODEST=") in new stack
-- Executing [720@ext-group:8] Set("SIP/SIP-00003728", "__NODEST=720") in new stack
-- Executing [720@ext-group:9] GosubIf("SIP/SIP-00003728", "0?sub-rgsetcid,s,1()") in new stack
-- Executing [720@ext-group:10] Set("SIP/SIP-00003728", "__PICKUPMARK=720") in new stack
-- Executing [720@ext-group:11] Gosub("SIP/SIP-00003728", "sub-record-check,s,1(rg,720,dontcare)") in new stack
-- Executing [s@sub-record-check:1] GotoIf("SIP/SIP-00003728", "10?initialized") in new stack
-- Goto (sub-record-check,s,10)
-- Executing [s@sub-record-check:10] NoOp("SIP/SIP-00003728", "Recordings initialized") in new stack
-- Executing [s@sub-record-check:11] ExecIf("SIP/SIP-00003728", "0?Set(ARG3=dontcare)") in new stack
-- Executing [s@sub-record-check:12] Set("SIP/SIP-00003728", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [s@sub-record-check:13] ExecIf("SIP/SIP-00003728", "0?Set(REC_STATUS=NO)") in new stack
-- Executing [s@sub-record-check:14] GotoIf("SIP/SIP-00003728", "2?checkaction") in new stack
-- Goto (sub-record-check,s,17)
-- Executing [s@sub-record-check:17] GotoIf("SIP/SIP-00003728", "0?sub-record-check,rg,1") in new stack
-- Executing [s@sub-record-check:18] NoOp("SIP/SIP-00003728", "Generic rg Recording Check - EXTERNALCALLER 720") in new stack
-- Executing [s@sub-record-check:19] Gosub("SIP/SIP-00003728", "recordcheck,1(dontcare,rg,720)") in new stack
-- Executing [recordcheck@sub-record-check:1] NoOp("SIP/SIP-00003728", "Starting recording check against dontcare") in new stack
-- Executing [recordcheck@sub-record-check:2] Goto("SIP/SIP-00003728", "dontcare") in new stack
-- Goto (sub-record-check,recordcheck,3)
-- Executing [recordcheck@sub-record-check:3] Return("SIP/SIP-00003728", "") in new stack
-- Executing [s@sub-record-check:20] Return("SIP/SIP-00003728", "") in new stack
-- Executing [720@ext-group:12] Set("SIP/SIP-00003728", "RingGroupMethod=ringall") in new stack
-- Executing [720@ext-group:13] Macro("SIP/SIP-00003728", "dial,16,Ttr,201-204-212") in new stack
-- Executing [s@macro-dial:1] NoOp("SIP/SIP-00003728", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
-- Executing [s@macro-dial:2] ExecIf("SIP/SIP-00003728", "0?Set(ALERT_INFO=)") in new stack
-- Executing [s@macro-dial:3] ExecIf("SIP/SIP-00003728", "0?Set(ALERT_INFO=)") in new stack
-- Executing [s@macro-dial:4] ExecIf("SIP/SIP-00003728", "0?Set(ALERT_INFO=)") in new stack
-- Executing [s@macro-dial:5] ExecIf("SIP/SIP-00003728", "0?Set(CHANNEL(musicclass)=)") in new stack
-- Executing [s@macro-dial:6] AGI("SIP/SIP-00003728", "dialparties.agi") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
   > 0x7f97e8005d60 -- Probation passed - setting RTP source address to 192.168.0.69:60034
 dialparties.agi: Starting New Dialparties.agi
 dialparties.agi: Caller ID name is EXTERNALCALLER' number is 'EXTERNALCALLER'
   > dialparties.agi: USE_CONFIRMATION:  'FALSE'
   > dialparties.agi: RINGGROUP_INDEX:   ''
 dialparties.agi: Methodology of ring is  'ringall'
-- dialparties.agi: Added extension 201 to extension map
-- dialparties.agi: Added extension 204 to extension map
-- dialparties.agi: Added extension 212 to extension map
-- dialparties.agi: Extension 201 cf is disabled
-- dialparties.agi: Extension 204 cf is disabled
-- dialparties.agi: Extension 212 cf is disabled
-- dialparties.agi: Extension 201 do not disturb is disabled
-- dialparties.agi: Extension 204 do not disturb is disabled
-- dialparties.agi: Extension 212 do not disturb is disabled
   > dialparties.agi: extnum 201 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
-- dialparties.agi: dbset CALLTRACE/201 to 6058781202
   > dialparties.agi: extnum 204 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
-- dialparties.agi: dbset CALLTRACE/204 to 6058781202
   > dialparties.agi: extnum 212 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
-- dialparties.agi: dbset CALLTRACE/212 to 6058781202
-- dialparties.agi: Filtered ARG3: 201-204-212
   > dialparties.agi: NODEST: 720 adding M(auto-blkvm) to dialopts: TtrM(auto-blkvm)
   > dialparties.agi: NODEST: 720 blkvm enabled macro already in dialopts: TtrM(auto-blkvm)
-- <SIP/SIP-00003728>AGI Script dialparties.agi completed, returning 0
-- Executing [s@macro-dial:9] NoOp("SIP/SIP-00003728", "Returned from dialparties with groups to dial") in new stack
-- Executing [s@macro-dial:10] Set("SIP/SIP-00003728", "LOOPCNT=3") in new stack
-- Executing [s@macro-dial:11] Set("SIP/SIP-00003728", "ITER=1") in new stack
-- Executing [s@macro-dial:12] Set("SIP/SIP-00003728", "EXTTOCALL=201") in new stack
-- Executing [s@macro-dial:13] NoOp("SIP/SIP-00003728", "Working with 201") in new stack
-- Executing [s@macro-dial:14] ExecIf("SIP/SIP-00003728", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
-- Executing [s@macro-dial:15] ExecIf("SIP/SIP-00003728", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
-- Executing [s@macro-dial:16] Set("SIP/SIP-00003728", "ITER=2") in new stack
-- Executing [s@macro-dial:17] GotoIf("SIP/SIP-00003728", "1?ndloopbegin") in new stack
-- Goto (macro-dial,s,12)
-- Executing [s@macro-dial:12] Set("SIP/SIP-00003728", "EXTTOCALL=204") in new stack
-- Executing [s@macro-dial:13] NoOp("SIP/SIP-00003728", "Working with 204") in new stack
-- Executing [s@macro-dial:14] ExecIf("SIP/SIP-00003728", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
-- Executing [s@macro-dial:15] ExecIf("SIP/SIP-00003728", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
-- Executing [s@macro-dial:16] Set("SIP/SIP-00003728", "ITER=3") in new stack
-- Executing [s@macro-dial:17] GotoIf("SIP/SIP-00003728", "1?ndloopbegin") in new stack
-- Goto (macro-dial,s,12)
-- Executing [s@macro-dial:12] Set("SIP/SIP-00003728", "EXTTOCALL=212") in new stack
-- Executing [s@macro-dial:13] NoOp("SIP/SIP-00003728", "Working with 212") in new stack
-- Executing [s@macro-dial:14] ExecIf("SIP/SIP-00003728", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
-- Executing [s@macro-dial:15] ExecIf("SIP/SIP-00003728", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
-- Executing [s@macro-dial:16] Set("SIP/SIP-00003728", "ITER=4") in new stack
-- Executing [s@macro-dial:17] GotoIf("SIP/SIP-00003728", "0?ndloopbegin") in new stack
-- Executing [s@macro-dial:18] Macro("SIP/SIP-00003728", "dial-ringall-predial-hook,") in new stack
-- Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/SIP-00003728", "") in new stack
-- Executing [s@macro-dial:19] Dial("SIP/SIP-00003728", "SIP/201&SIP/204&SIP/212,16,trM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
  == Using SIP RTP CoS mark 5
  == Using SIP RTP CoS mark 5
  == Using SIP RTP CoS mark 5
-- SIP/201-00003729 Internal Gosub(func-apply-sipheaders,s,1) start
-- Executing [s@func-apply-sipheaders:1] NoOp("SIP/201-00003729", "Applying SIP Headers to channel") in new stack
-- Executing [s@func-apply-sipheaders:2] Set("SIP/201-00003729", "SIPHEADERKEYS=") in new stack
-- Executing [s@func-apply-sipheaders:3] While("SIP/201-00003729", "0") in new stack
-- Jumping to priority 7
-- Executing [s@func-apply-sipheaders:8] Return("SIP/201-00003729", "") in new stack
  == Spawn extension (from-internal, 720, 1) exited non-zero on 'SIP/201-00003729'
-- SIP/201-00003729 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
-- SIP/204-0000372a Internal Gosub(func-apply-sipheaders,s,1) start
-- Executing [s@func-apply-sipheaders:1] NoOp("SIP/204-0000372a", "Applying SIP Headers to channel") in new stack
-- Executing [s@func-apply-sipheaders:2] Set("SIP/204-0000372a", "SIPHEADERKEYS=") in new stack
-- Executing [s@func-apply-sipheaders:3] While("SIP/204-0000372a", "0") in new stack
-- Jumping to priority 7
-- Executing [s@func-apply-sipheaders:8] Return("SIP/204-0000372a", "") in new stack
  == Spawn extension (from-internal, 720, 1) exited non-zero on 'SIP/204-0000372a'
-- SIP/204-0000372a Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
-- SIP/212-0000372b Internal Gosub(func-apply-sipheaders,s,1) start
-- Executing [s@func-apply-sipheaders:1] NoOp("SIP/212-0000372b", "Applying SIP Headers to channel") in new stack
-- Executing [s@func-apply-sipheaders:2] Set("SIP/212-0000372b", "SIPHEADERKEYS=") in new stack
-- Executing [s@func-apply-sipheaders:3] While("SIP/212-0000372b", "0") in new stack
-- Jumping to priority 7
-- Executing [s@func-apply-sipheaders:8] Return("SIP/212-0000372b", "") in new stack
  == Spawn extension (from-internal, 720, 1) exited non-zero on 'SIP/212-0000372b'
-- SIP/212-0000372b Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
  == Extension Changed 201[ext-local] new state Ringing for Notify User 212
-- Called SIP/201
  == Extension Changed 201[ext-local] new state Ringing for Notify User 201
  == Extension Changed 201[ext-local] new state Ringing for Notify User 204
-- Called SIP/204
  == Extension Changed 204[ext-local] new state Ringing for Notify User 212
-- Called SIP/212
-- SIP/212-0000372b connected line has changed. Saving it until answer for SIP/SIP-00003728
  == Extension Changed 204[ext-local] new state Ringing for Notify User 204
  == Extension Changed 204[ext-local] new state Ringing for Notify User 201
-- SIP/204-0000372a connected line has changed. Saving it until answer for SIP/SIP-00003728
-- SIP/201-00003729 connected line has changed. Saving it until answer for SIP/SIP-00003728
  == Extension Changed 212[ext-local] new state InUse&Ringing for Notify User 212
  == Extension Changed 212[ext-local] new state InUse&Ringing for Notify User 204
  == Extension Changed 212[ext-local] new state InUse&Ringing for Notify User 201
-- SIP/201-00003729 is ringing
-- SIP/204-0000372a is ringing
-- SIP/212-0000372b is ringing
   > 0x3239f80 -- Probation passed - setting RTP source address to 192.168.1.166:3000
  == Extension Changed 201[ext-local] new state InUse for Notify User 212
  == Extension Changed 201[ext-local] new state InUse for Notify User 201
-- SIP/201-00003729 connected line has changed. Saving it until answer for SIP/SIP-00003728
  == Extension Changed 201[ext-local] new state InUse for Notify User 204
-- SIP/201-00003729 answered SIP/SIP-00003728
-- Executing [s@macro-auto-blkvm:1] Set("SIP/201-00003729", "__MACRO_RESULT=") in new stack
-- Executing [s@macro-auto-blkvm:2] Set("SIP/201-00003729", "CFIGNORE=") in new stack
  == Extension Changed 204[ext-local] new state Idle for Notify User 212
-- Executing [s@macro-auto-blkvm:3] Set("SIP/201-00003729", "MASTER_CHANNEL(CFIGNORE)=") in new stack
  == Extension Changed 204[ext-local] new state Idle for Notify User 204
-- Executing [s@macro-auto-blkvm:4] Set("SIP/201-00003729", "FORWARD_CONTEXT=from-internal") in new stack
-- Executing [s@macro-auto-blkvm:5] Set("SIP/201-00003729", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
  == Extension Changed 204[ext-local] new state Idle for Notify User 201
-- Executing [s@macro-auto-blkvm:6] Macro("SIP/201-00003729", "blkvm-clr,") in new stack
-- Executing [s@macro-blkvm-clr:1] Set("SIP/201-00003729", "SHARED(BLKVM,SIP/SIP-00003728)=") in new stack
  == Extension Changed 212[ext-local] new state InUse for Notify User 212
-- Executing [s@macro-blkvm-clr:2] Set("SIP/201-00003729", "GOSUB_RETVAL=") in new stack
-- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/201-00003729", "") in new stack
  == Extension Changed 212[ext-local] new state InUse for Notify User 204
  == Extension Changed 212[ext-local] new state InUse for Notify User 201
-- Executing [s@macro-auto-blkvm:7] ExecIf("SIP/201-00003729", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=201)") in new stack
-- Executing [s@macro-auto-blkvm:8] ExecIf("SIP/201-00003729", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=RECEPTIONIST)") in new stack
-- Channel SIP/201-00003729 joined 'simple_bridge' basic-bridge <d3df8713-74f9-445d-a0be-bf948b0ceb41>
-- Channel SIP/SIP-00003728 joined 'simple_bridge' basic-bridge <d3df8713-74f9-445d-a0be-bf948b0ceb41>
   > 0x3239f80 -- Probation passed - setting RTP source address to 192.168.1.166:3000
-- Started music on hold, class 'default', on channel 'SIP/201-00003729'
   > 0x7f97e8005d60 -- Probation passed - setting RTP source address to 192.168.0.69:60034
   > 0x7f97e8005d60 -- Switching RTP source address to 192.168.0.69:60036
-- Started music on hold, class 'default', on channel 'SIP/SIP-00003724'
   > 0x322d530 -- Probation passed - setting RTP source address to 192.168.1.210:3000