Getting Caller ID Working [SOLVED]

I’ve got my Asterisk/FreePBX setup working with two Grandstream HT-503 gateways. The two PSTN lines from Comcast do have Caller ID: it was displaying on the previous system.

I’ve seen notes to configure the HT-503s to transfer after two rings to give the caller ID info time to insert and I’ve done this.

However still no caller ID display on the phones.

Any ideas on where to look?

Caller ID normally comes in between the first and second ring on the PSTN line. Let that ring twice before you pick up to make sure the Caller ID gets processed.

Remember, the phones aren’t answering the call - Asterisk is. Your phones are answering a call from Asterisk.

Well, no. Isn’t the gateway device picking up and then forwarding the call?

I’m holding the call at the gateway – the HT503. That has a rings before forwarding setting which I’ve set to two. So the caller ID info should be there.

So what rings setting within Asterisk are you talking about? I’ll try anything and see if it’ll work.

I did a verbose packet capture on an inbound call:

Frame 7: 1152 bytes on wire (9216 bits), 1152 bytes captured (9216 bits) on interface 0
    Interface id: 0 (eth0)
    Encapsulation type: Ethernet (1)
    Arrival Time: Apr 16, 2016 21:33:02.553337000 PDT
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1460867582.553337000 seconds
    [Time delta from previous captured frame: 2.463686000 seconds]
    [Time delta from previous displayed frame: 2.463686000 seconds]
    [Time since reference or first frame: 7.470175000 seconds]
    Frame Number: 7
    Frame Length: 1152 bytes (9216 bits)
    Capture Length: 1152 bytes (9216 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ethertype:ip:udp:sip:sdp]
Ethernet II, Src: Grandstr_7b:04:b9 (00:0b:82:7b:04:b9), Dst: Raspberr_dc:63:0d (b8:27:eb:dc:63:0d)
    Destination: Raspberr_dc:63:0d (b8:27:eb:dc:63:0d)
        Address: Raspberr_dc:63:0d (b8:27:eb:dc:63:0d)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Source: Grandstr_7b:04:b9 (00:0b:82:7b:04:b9)
        Address: Grandstr_7b:04:b9 (00:0b:82:7b:04:b9)
        .... ..0. .... .... .... .... = LG bit: Globally unique address (factory default)
        .... ...0 .... .... .... .... = IG bit: Individual address (unicast)
    Type: IP (0x0800)
Internet Protocol Version 4, Src: 10.0.2.22 (10.0.2.22), Dst: 10.0.2.28 (10.0.2.28)
    Version: 4
    Header Length: 20 bytes
    Differentiated Services Field: 0x68 (DSCP 0x1a: Assured Forwarding 31; ECN: 0x00: Not-ECT (Not ECN-Capable Transport))
        0110 10.. = Differentiated Services Codepoint: Assured Forwarding 31 (0x1a)
        .... ..00 = Explicit Congestion Notification: Not-ECT (Not ECN-Capable Transport) (0x00)
    Total Length: 1138
    Identification: 0x6405 (25605)
    Flags: 0x00
        0... .... = Reserved bit: Not set
        .0.. .... = Don't fragment: Not set
        ..0. .... = More fragments: Not set
    Fragment offset: 0
    Time to live: 64
    Protocol: UDP (17)
    Header checksum: 0xf9dc [validation disabled]
        [Good: False]
        [Bad: False]
    Source: 10.0.2.22 (10.0.2.22)
    Destination: 10.0.2.28 (10.0.2.28)
    [Source GeoIP: Unknown]
    [Destination GeoIP: Unknown]
User Datagram Protocol, Src Port: 5062 (5062), Dst Port: 5060 (5060)
    Source Port: 5062 (5062)
    Destination Port: 5060 (5060)
    Length: 1118
    Checksum: 0xc807 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    [Stream index: 1]
Session Initiation Protocol (INVITE)
    Request-Line: INVITE sip:[email protected]:5060 SIP/2.0
        Method: INVITE
        Request-URI: sip:[email protected]:5060
            Request-URI User Part: 09253139391
            Request-URI Host Part: 10.0.2.28
            Request-URI Host Port: 5060
        [Resent Packet: False]
    Message Header
        Via: SIP/2.0/UDP 10.0.2.22:5062;branch=z9hG4bK868905952;rport
            Transport: UDP
            Sent-by Address: 10.0.2.22
            Sent-by port: 5062
            Branch: z9hG4bK868905952
            RPort: rport
        Route: <sip:10.0.2.28:5060;lr>
            Route URI: sip:10.0.2.28:5060;lr
                Route Host Part: 10.0.2.28
                Route Host Port: 5060
                Route URI parameter: lr
        From: "Martinez     CA" <sip:[email protected]>;tag=993770341
            SIP Display info: "Martinez     CA"
            SIP from address: sip:[email protected]
                SIP from address User Part: 9253356110
                SIP from address Host Part: 10.0.2.28
            SIP from tag: 993770341
        To: <sip:[email protected]:5060>
            SIP to address: sip:[email protected]:5060
                SIP to address User Part: 09253139391
                SIP to address Host Part: 10.0.2.28
                SIP to address Host Port: 5060
        Call-ID: [email protected]
        CSeq: 220 INVITE
            Sequence Number: 220
            Method: INVITE
        Contact: <sip:[email protected]:5062>
            Contact URI: sip:[email protected]:5062
                Contact URI User Part: 09253139391
                Contact URI Host Part: 10.0.2.22
                Contact URI Host Port: 5062
        Max-Forwards: 70
        User-Agent: Grandstream HT-503  V2.0A 1.0.14.100  chip V2.2
        Supported: replaces, path, timer, eventlist
        Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
        Content-Type: application/sdp
        Accept: application/sdp, application/dtmf-relay
        Content-Length:   453
    Message Body
        Session Description Protocol
            Session Description Protocol Version (v): 0
            Owner/Creator, Session Id (o): 09253139391 8002 8000 IN IP4 10.0.2.22
                Owner Username: 09253139391
                Session ID: 8002
                Session Version: 8000
                Owner Network Type: IN
                Owner Address Type: IP4
                Owner Address: 10.0.2.22
            Session Name (s): SIP Call
            Connection Information (c): IN IP4 10.0.2.22
                Connection Network Type: IN
                Connection Address Type: IP4
                Connection Address: 10.0.2.22
            Time Description, active time (t): 0 0
                Session Start Time: 0
                Session Stop Time: 0
            Media Description, name and address (m): audio 5014 RTP/AVP 0 8 4 18 2 97 102 100 101
                Media Type: audio
                Media Port: 5014
                Media Protocol: RTP/AVP
                Media Format: ITU-T G.711 PCMU
                Media Format: ITU-T G.711 PCMA
                Media Format: ITU-T G.723
                Media Format: ITU-T G.729
                Media Format: ITU-T G.721
                Media Format: DynamicRTP-Type-97
                Media Format: DynamicRTP-Type-102
                Media Format: DynamicRTP-Type-100
                Media Format: DynamicRTP-Type-101
            Media Attribute (a): sendrecv
            Media Attribute (a): rtpmap:0 PCMU/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 0
                MIME Type: PCMU
                Sample Rate: 8000
            Media Attribute (a): ptime:20
                Media Attribute Fieldname: ptime
                Media Attribute Value: 20
            Media Attribute (a): rtpmap:8 PCMA/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 8
                MIME Type: PCMA
                Sample Rate: 8000
            Media Attribute (a): rtpmap:4 G723/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 4
                MIME Type: G723
                Sample Rate: 8000
            Media Attribute (a): rtpmap:18 G729/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 18
                MIME Type: G729
                Sample Rate: 8000
            Media Attribute (a): fmtp:18 annexb=no
                Media Attribute Fieldname: fmtp
                Media Format: 18 [G729]
                Media format specific parameters: annexb=no
            Media Attribute (a): rtpmap:2 G726-32/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 2
                MIME Type: G726-32
                Sample Rate: 8000
            Media Attribute (a): rtpmap:97 iLBC/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 97
                MIME Type: iLBC
                Sample Rate: 8000
            Media Attribute (a): fmtp:97 mode=20
                Media Attribute Fieldname: fmtp
                Media Format: 97 [iLBC]
                Media format specific parameters: mode=20
            Media Attribute (a): rtpmap:102 G729E/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 102
                MIME Type: G729E
                Sample Rate: 8000
            Media Attribute (a): rtpmap:100 AAL2-G726-16/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 100
                MIME Type: AAL2-G726-16
                Sample Rate: 8000
            Media Attribute (a): rtpmap:101 telephone-event/8000
                Media Attribute Fieldname: rtpmap
                Media Format: 101
                MIME Type: telephone-event
                Sample Rate: 8000
            Media Attribute (a): fmtp:101 0-16,32-36,54
                Media Attribute Fieldname: fmtp
                Media Format: 101 [telephone-event]
                Media format specific parameters: 0-16,32-36,54

And it looks like CID is being sent.

  From: "Martinez     CA" <sip:[email protected]>;tag=993770341
  SIP Display info: "Martinez     CA"
 SIP from address: sip:[email protected]
    SIP from address User Part: 9253356110

That looks right to me. So can anyone suggest the next step in why I am getting no display on the phone?

So I’ve confirmed that CID info is being sent from my HT503s. But still no display on my phones.

I’m playing with a couple of things.

I have two inbound routes, one for each DID. I tried going with one inbound route and leaving the DID field blank. I thought I understood that that would match any inbound call. But a call to one of my trunks yields a “This user is busy” message instead of the phones ringing. So I’ve recreated the two inbound routes.

Next thought is that each inbound route has the same ring group as it’s destination. Could that be the cause of my CID loss? Could the ring group be the problem somehow?

Any ideas would be helpful.

Thanks.

I am still really struggling with getting Caller ID to display on my phones. I’ve gotten some help over on the Asterisk forums and have been looking at Asterisk internals but have no solution yet. I’ve been pointed at trustrpid and sendrpid but those seem to be set right.

I found a posting from 2011 that said to turn on Privacy Manager on inbound routes. I’ve tried that but CNAM values are still not getting through.

Trunks do not seem to be involved here on inbound calls. My HT-503s forward calls to a configured extension and those make use of an inbound route which in turn use a ring group to ring the physical phones. The name and number of the configured extension is what is displayed on the phones.

What I need to do is turn off the rewriting of the Caller ID info and allow the Caller ID info from the PSTN to get through. Does anyone know how to do that?

Hey Kirk,
firstly I would assume that you are getting the callerid into the HT-503.
Do they have some sort of call log or debug that you can check to see if you got a valid string from the PSTN.

If it is then next step make a call and look at the asterisk logs. 200 to 1000 lines.
Just call in and ring once or twice , do not bother to answer it.

they are very detailed and you should be able to follow the call flow to see if the callerid is passed from the HT or where it maybe getting trashed.

I am no expert but that’s the first things I would do , then shout out again.
Good luck, I have actually just sorted a callerid niggle myself so I have faith that you will resolve it, it’s not that hard after all.

Oops , just read the thread from the start.!
so it is coming thru just being lost in the pbx or on the way to the phone.
paste up some normal logs without so much clutter and I shall have a stare.

Hv.

Some advancement!! It looks like privacy manager is actually doing something. For the first time I am seeing CID information in the asterisk logs:

[2016-04-21 13:38:53] NOTICE[6617][C-0000000a] chan_sip.c: Failed to authenticate device "Martinez CA" <sip:[email protected]>;tag=1389598408

Now this call did not go through. But the info did get through.

However I am not finding any information on how to configure Privacy Manager. What I need to do is whitelist everything and then blacklist what I want.

Hey K,

Not seen Privacy Manager.
Just to confirm that the DID is going to be something you dictate.
Setting it in the HT device I would guess much like the Dahdi Channel DID’s

I would say start with the basics.
Setup one trunk per device
Create a catch all inbound route
make sure it is sending a DID,
Just check the logs it will normally advise to create a route if I remember right.
if you got the DID then you can setup an incoming route per device.

The callerid stuff you can put in some debug/custom dialplans to show you any information along the way, you can fill the logs with stuff that you need to see.

Not seen a HT device so do not have any reference point to start from.

Hv.

But hv, here is what an incoming call in /var/log/asterisk/full after turning Privacy Manager off on this line looks like:

[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/09253131111-00000029", "1?theend") in new stack
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Goto (macro-hangupcall,s,3)
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/09253131111-00000029", "0?Set(CDR(recordingfile)=)") in new stack
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/09253131111-00000029", "") in new stack
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/09253131111-00000029' in macro 'hangupcall'
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/09253131111-00000029'

All that is logged is the extension information.

I am just not finding any clear information on configuring Privacy Manager.

Hey Kirk,
that’s not a stares worth, more just a couple of steps.
I have no idea what is or how to configure Privacy manager,
turn it off for now till you have things working then introduce the new stuff.
Unless I am reading this wrong.

Don’t be shy, give us a chunky log to stare at.
Hang on, that sounds very strange…
No pictures, text only thanks.

Hv.

A quick way to get the log of that particular call (30414) would be to post the result of:-

grep "\[30414\]" /var/log/asterisk/full

Okay, this seems like a lot but here you go. I had to cut out some duplicate stuff about extensions to get under the posting limit size:

 [2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:1] Set("SIP/09253131111-00000029", 

"__DIRECTION=INBOUND") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:2] Gosub("SIP/09253131111-00000029", "sub-

record-check,s,1(in,09253131111,dontcare)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/09253131111-00000029", "0?

initialized") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:2] Set("SIP/09253131111-00000029", 

"__REC_STATUS=INITIALIZED") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:3] Set("SIP/09253131111-00000029", "NOW=1461272941") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:4] Set("SIP/09253131111-00000029", "__DAY=21") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:5] Set("SIP/09253131111-00000029", "__MONTH=04") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:6] Set("SIP/09253131111-00000029", "__YEAR=2016") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:7] Set("SIP/09253131111-00000029", 

"__TIMESTR=20160421-140901") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:8] Set("SIP/09253131111-00000029", 

"__FROMEXTEN=unknown") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:9] Set("SIP/09253131111-00000029", "__MON_FMT=wav") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/09253131111-00000029", "Recordings 

initialized") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/09253131111-00000029", "0?Set

(ARG3=dontcare)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:12] Set("SIP/09253131111-00000029", 

"REC_POLICY_MODE_SAVE=") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/09253131111-00000029", "0?Set

(REC_STATUS=NO)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/09253131111-00000029", "2?

checkaction") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (sub-record-check,s,17)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/09253131111-00000029", "1?sub-

record-check,in,1") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (sub-record-check,in,1)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/09253131111-00000029", "Inbound 

Recording Check to 09253131111") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [in@sub-record-check:2] Set("SIP/09253131111-00000029", 

"FROMEXTEN=unknown") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/09253131111-00000029", "11?Set

(FROMEXTEN=09253131111)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/09253131111-00000029", 

"recordcheck,1(dontcare,in,09253131111)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/09253131111-00000029", 

"Starting recording check against dontcare") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/09253131111-00000029", 

"dontcare") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (sub-record-check,recordcheck,3)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/09253131111-00000029", "") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [in@sub-record-check:5] Return("SIP/09253131111-00000029", "") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:3] Set("SIP/09253131111-00000029", 

"__FROM_DID=09253131111") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:4] Set("SIP/09253131111-00000029", "CDR(did)

=09253131111") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:5] ExecIf("SIP/09253131111-00000029", "0 ?Set

(CALLERID(name)=09253131111)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:6] Set("SIP/09253131111-00000029", "CHANNEL

(musicclass)=customuploaded") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:7] Set("SIP/09253131111-00000029", 

"__MOHCLASS=customuploaded") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:8] Set("SIP/09253131111-00000029", 

"__REVERSAL_REJECT=FALSE") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:9] GotoIf("SIP/09253131111-00000029", "1?post-

reverse-charge") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (from-trunk,09253131111,11)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:11] NoOp("SIP/09253131111-00000029", "") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:12] Set("SIP/09253131111-00000029", 

"__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:13] Set("SIP/09253131111-00000029", 

"__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:14] Set("SIP/09253131111-00000029", "CALLERID

(name-pres)=allowed_not_screened") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:15] Set("SIP/09253131111-00000029", "CALLERID

(num-pres)=allowed_not_screened") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:16] NoOp("SIP/09253131111-00000029", "CallerID 

Entry Point") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [09253131111@from-trunk:17] Goto("SIP/09253131111-00000029", "ext-

group,1,1") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (ext-group,1,1)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:1] Progress("SIP/09253131111-00000029", "") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:2] Macro("SIP/09253131111-00000029", "user-callerid,") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/09253131111-00000029", 

"TOUCH_MONITOR=1461272941.41") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/09253131111-00000029", 

"AMPUSER=09253131111") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/09253131111-00000029", "0?report") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/09253131111-00000029", "1?Set

(REALCALLERIDNUM=09253131111)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/09253131111-00000029", 

"AMPUSER=09253131111") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/09253131111-00000029", "0?limit") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/09253131111-00000029", 

"AMPUSERCIDNAME=Home Line") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/09253131111-00000029", "0?report") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/09253131111-00000029", 

"AMPUSERCID=09253131111") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/09253131111-00000029", 

"__DIAL_OPTIONS=Ttr") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/09253131111-00000029", "CALLERID

(all)="Home Line" <09253131111>") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:12] GotoIf("SIP/09253131111-00000029", "0?limit") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("SIP/09253131111-00000029", "0?Set

(GROUP(concurrency_limit)=09253131111)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("SIP/09253131111-00000029", "0?

continue") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:15] Set("SIP/09253131111-00000029", "__TTL=64") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("SIP/09253131111-00000029", "1?

continue") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (macro-user-callerid,s,27)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:27] Set("SIP/09253131111-00000029", "CALLERID

(number)=09253131111") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:28] Set("SIP/09253131111-00000029", "CALLERID

(name)=Home Line") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/09253131111-00000029", "CDR(cnum)

=09253131111") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/09253131111-00000029", "CDR(cnam)

=Home Line") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-user-callerid:31] Set("SIP/09253131111-00000029", "CHANNEL

(language)=en") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:3] Macro("SIP/09253131111-00000029", "blkvm-setifempty,") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/09253131111-00000029", "1?

init") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (macro-blkvm-setifempty,s,4)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-blkvm-setifempty:4] Set("SIP/09253131111-00000029", 

"__BLKVM_CHANNEL=SIP/09253131111-00000029") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-blkvm-setifempty:5] Set("SIP/09253131111-00000029", "SHARED

(BLKVM,SIP/09253131111-00000029)=TRUE") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-blkvm-setifempty:6] Set("SIP/09253131111-00000029", 

"GOSUB_RETVAL=TRUE") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/09253131111-00000029", "") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:4] GotoIf("SIP/09253131111-00000029", "1?skipov") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (ext-group,1,7)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:7] Set("SIP/09253131111-00000029", "RRNODEST=") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:8] Set("SIP/09253131111-00000029", "__NODEST=1") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:9] GosubIf("SIP/09253131111-00000029", "0?sub-rgsetcid,s,1

()") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:10] Gosub("SIP/09253131111-00000029", "sub-record-

check,s,1(rg,1,dontcare)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/09253131111-00000029", "11?

initialized") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (sub-record-check,s,10)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/09253131111-00000029", "Recordings 

initialized") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/09253131111-00000029", "0?Set

(ARG3=dontcare)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:12] Set("SIP/09253131111-00000029", 

"REC_POLICY_MODE_SAVE=") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/09253131111-00000029", "0?Set

(REC_STATUS=NO)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/09253131111-00000029", "2?

checkaction") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (sub-record-check,s,17)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/09253131111-00000029", "0?sub-

record-check,rg,1") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:18] NoOp("SIP/09253131111-00000029", "Generic rg 

Recording Check - 09253131111 1") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:19] Gosub("SIP/09253131111-00000029", 

"recordcheck,1(dontcare,rg,1)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/09253131111-00000029", 

"Starting recording check against dontcare") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/09253131111-00000029", 

"dontcare") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (sub-record-check,recordcheck,3)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/09253131111-00000029", "") 

in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@sub-record-check:20] Return("SIP/09253131111-00000029", "") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:11] Set("SIP/09253131111-00000029", 

"RingGroupMethod=ringall") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [1@ext-group:12] Macro("SIP/09253131111-00000029", "dial,35,m

(customuploaded)Tt,10-11-12-13-14-15") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:1] NoOp("SIP/09253131111-00000029", "Blind Transfer: , 

Attended Transfer: , User: 09253131111, Alert Info: ") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:2] ExecIf("SIP/09253131111-00000029", "1?Set

(ALERT_INFO=)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:3] ExecIf("SIP/09253131111-00000029", "0?Set

(ALERT_INFO=)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:4] ExecIf("SIP/09253131111-00000029", "0?Set

(ALERT_INFO=)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:5] ExecIf("SIP/09253131111-00000029", "1?Set(CHANNEL

(musicclass)=customuploaded)") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:6] AGI("SIP/09253131111-00000029", "dialparties.agi") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Caller ID name is 'Home Line' number is '09253131111'
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Methodology of ring is  'ringall'

[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Added extension 15 to extension map
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Extension 10 cf is disabled

[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Extension 15 cf is disabled
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Extension 10 do not disturb is disabled

[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Extension 14 do not disturb is disabled
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Extension 15 do not disturb is disabled

[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: dbset CALLTRACE/14 to 09253131111
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: dbset CALLTRACE/15 to 09253131111
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: dialparties.agi: Filtered ARG3: 10-11-12-13-14-15
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_agi.c: <SIP/09253131111-00000029>AGI Script dialparties.agi completed, returning 0
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:9] NoOp("SIP/09253131111-00000029", "Returned from 

dialparties with groups to dial") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:10] Set("SIP/09253131111-00000029", "LOOPCNT=6") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:11] Set("SIP/09253131111-00000029", "ITER=1") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000029", "EXTTOCALL=10") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000029", "Working with 10") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000029", "ITER=2") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000029", "1?ndloopbegin") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (macro-dial,s,12)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000029", "EXTTOCALL=11") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000029", "Working with 11") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000029", "ITER=3") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000029", "1?ndloopbegin") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (macro-dial,s,12)


[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Goto (macro-dial,s,12)
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000029", "EXTTOCALL=15") in new 

stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000029", "Working with 15") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000029", "ITER=7") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000029", "0?ndloopbegin") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:16] Macro("SIP/09253131111-00000029", "dial-ringall-

predial-hook,") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/09253131111-

00000029", "") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-dial:17] Dial("SIP/09253131111-00000029", 

"SIP/10&SIP/11&SIP/12&SIP/13&SIP/14&SIP/15,35,m(customuploaded)tM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] netsock2.c: Using SIP RTP CoS mark 5

[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/10-0000002a Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/10-0000002a", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/10-0000002a", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/10-0000002a", "0") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_while.c: Jumping to priority 7
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/10-0000002a", "") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/10-0000002a'
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/10-0000002a Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/11-0000002b Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/11-0000002b", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/11-0000002b", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/11-0000002b", "0") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_while.c: Jumping to priority 7
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/11-0000002b", "") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/11-0000002b'
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/11-0000002b Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/12-0000002c Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/12-0000002c", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/12-0000002c", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/12-0000002c", "0") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_while.c: Jumping to priority 7
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/12-0000002c", "") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/12-0000002c'
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/12-0000002c Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/13-0000002d Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/13-0000002d", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/13-0000002d", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/13-0000002d", "0") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_while.c: Jumping to priority 7
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/13-0000002d", "") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/13-0000002d'
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/13-0000002d Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/14-0000002e Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/14-0000002e", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/14-0000002e", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/14-0000002e", "0") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_while.c: Jumping to priority 7
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/14-0000002e", "") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/14-0000002e'
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/14-0000002e Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/15-0000002f Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/15-0000002f", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/15-0000002f", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/15-0000002f", "0") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_while.c: Jumping to priority 7
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/15-0000002f", "") in new stack
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/15-0000002f'
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_stack.c: SIP/15-0000002f Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_dial.c: Called SIP/10
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_dial.c: Called SIP/11
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_dial.c: Called SIP/15
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] res_musiconhold.c: Started music on hold, class 'customuploaded', on channel 

'SIP/09253131111-00000029'
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_dial.c: SIP/15-0000002f connected line has changed. Saving it until answer for 

SIP/09253131111-00000029

[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_dial.c: SIP/10-0000002a connected line has changed. Saving it until answer for 

SIP/09253131111-00000029
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_dial.c: SIP/11-0000002b is ringing
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_dial.c: SIP/10-0000002a is ringing
[
[2016-04-21 14:09:01] VERBOSE[30414][C-0000000c] app_dial.c: SIP/15-0000002f is ringing
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] res_musiconhold.c: Stopped music on hold on SIP/09253131111-00000029
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] app_macro.c: Spawn extension (macro-dial, s, 17) exited non-zero on 'SIP/09253131111-

00000029' in macro 'dial'
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Spawn extension (ext-group, 1, 12) exited non-zero on 'SIP/09253131111-00000029'
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Executing [h@ext-group:1] Macro("SIP/09253131111-00000029", "hangupcall,") in new 

stack
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/09253131111-00000029", "1?theend") in 

new stack
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Goto (macro-hangupcall,s,3)
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/09253131111-00000029", "0?Set(CDR

(recordingfile)=)") in new stack
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/09253131111-00000029", "") in new 

stack
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 

'SIP/09253131111-00000029' in macro 'hangupcall'
[2016-04-21 14:09:07] VERBOSE[30414][C-0000000c] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/09253131111-00000029'

You should notice that you truncated the relevant lines before the important bits.

Okay, well here’s a new call. I’ll post in two parts so nothing is missing. Starts with DIRECTION=INBOUND and ends with hangupcall.

[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:1] Set("SIP/09253131111-00000037", 

"__DIRECTION=INBOUND") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:2] Gosub("SIP/09253131111-00000037", "sub-

record-check,s,1(in,09253131111,dontcare)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/09253131111-00000037", "0?

initialized") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:2] Set("SIP/09253131111-00000037", 

"__REC_STATUS=INITIALIZED") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:3] Set("SIP/09253131111-00000037", "NOW=1461296624") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:4] Set("SIP/09253131111-00000037", "__DAY=21") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:5] Set("SIP/09253131111-00000037", "__MONTH=04") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:6] Set("SIP/09253131111-00000037", "__YEAR=2016") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:7] Set("SIP/09253131111-00000037", 

"__TIMESTR=20160421-204344") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:8] Set("SIP/09253131111-00000037", 

"__FROMEXTEN=unknown") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:9] Set("SIP/09253131111-00000037", "__MON_FMT=wav") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/09253131111-00000037", "Recordings 

initialized") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/09253131111-00000037", "0?Set

(ARG3=dontcare)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:12] Set("SIP/09253131111-00000037", 

"REC_POLICY_MODE_SAVE=") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/09253131111-00000037", "0?Set

(REC_STATUS=NO)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/09253131111-00000037", "2?

checkaction") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (sub-record-check,s,17)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/09253131111-00000037", "1?sub-

record-check,in,1") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (sub-record-check,in,1)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/09253131111-00000037", "Inbound 

Recording Check to 09253131111") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [in@sub-record-check:2] Set("SIP/09253131111-00000037", 

"FROMEXTEN=unknown") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/09253131111-00000037", "11?Set

(FROMEXTEN=09253131111)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/09253131111-00000037", 

"recordcheck,1(dontcare,in,09253131111)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/09253131111-00000037", 

"Starting recording check against dontcare") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/09253131111-00000037", 

"dontcare") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (sub-record-check,recordcheck,3)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/09253131111-00000037", "") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [in@sub-record-check:5] Return("SIP/09253131111-00000037", "") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:3] Set("SIP/09253131111-00000037", 

"__FROM_DID=09253131111") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:4] Set("SIP/09253131111-00000037", "CDR(did)

=09253131111") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:5] ExecIf("SIP/09253131111-00000037", "0 ?Set

(CALLERID(name)=09253131111)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:6] Set("SIP/09253131111-00000037", "CHANNEL

(musicclass)=customuploaded") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:7] Set("SIP/09253131111-00000037", 

"__MOHCLASS=customuploaded") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:8] Set("SIP/09253131111-00000037", 

"__REVERSAL_REJECT=FALSE") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:9] GotoIf("SIP/09253131111-00000037", "1?post-

reverse-charge") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (from-trunk,09253131111,11)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:11] NoOp("SIP/09253131111-00000037", "") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:12] Set("SIP/09253131111-00000037", 

"__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:13] Set("SIP/09253131111-00000037", 

"__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:14] Set("SIP/09253131111-00000037", "CALLERID

(name-pres)=allowed_not_screened") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:15] Set("SIP/09253131111-00000037", "CALLERID

(num-pres)=allowed_not_screened") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:16] NoOp("SIP/09253131111-00000037", "CallerID 

Entry Point") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [09253131111@from-trunk:17] Goto("SIP/09253131111-00000037", "ext-

group,1,1") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (ext-group,1,1)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:1] Progress("SIP/09253131111-00000037", "") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:2] Macro("SIP/09253131111-00000037", "user-callerid,") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/09253131111-00000037", 

"TOUCH_MONITOR=1461296624.69") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/09253131111-00000037", 

"AMPUSER=09253131111") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/09253131111-00000037", "0?report") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/09253131111-00000037", "1?Set

(REALCALLERIDNUM=09253131111)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/09253131111-00000037", 

"AMPUSER=09253131111") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/09253131111-00000037", "0?limit") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/09253131111-00000037", 

"AMPUSERCIDNAME=Home Line") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/09253131111-00000037", "0?report") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/09253131111-00000037", 

"AMPUSERCID=09253131111") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/09253131111-00000037", 

"__DIAL_OPTIONS=Ttr") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/09253131111-00000037", "CALLERID

(all)="Home Line" <09253131111>") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:12] GotoIf("SIP/09253131111-00000037", "0?limit") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("SIP/09253131111-00000037", "0?Set

(GROUP(concurrency_limit)=09253131111)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("SIP/09253131111-00000037", "0?

continue") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:15] Set("SIP/09253131111-00000037", "__TTL=64") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("SIP/09253131111-00000037", "1?

continue") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (macro-user-callerid,s,27)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:27] Set("SIP/09253131111-00000037", "CALLERID

(number)=09253131111") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:28] Set("SIP/09253131111-00000037", "CALLERID

(name)=Home Line") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/09253131111-00000037", "CDR(cnum)

=09253131111") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/09253131111-00000037", "CDR(cnam)

=Home Line") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-user-callerid:31] Set("SIP/09253131111-00000037", "CHANNEL

(language)=en") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:3] Macro("SIP/09253131111-00000037", "blkvm-setifempty,") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/09253131111-00000037", "1?

init") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (macro-blkvm-setifempty,s,4)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-blkvm-setifempty:4] Set("SIP/09253131111-00000037", 

"__BLKVM_CHANNEL=SIP/09253131111-00000037") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-blkvm-setifempty:5] Set("SIP/09253131111-00000037", "SHARED

(BLKVM,SIP/09253131111-00000037)=TRUE") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-blkvm-setifempty:6] Set("SIP/09253131111-00000037", 

"GOSUB_RETVAL=TRUE") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/09253131111-00000037", "") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:4] GotoIf("SIP/09253131111-00000037", "1?skipov") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (ext-group,1,7)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:7] Set("SIP/09253131111-00000037", "RRNODEST=") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:8] Set("SIP/09253131111-00000037", "__NODEST=1") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:9] GosubIf("SIP/09253131111-00000037", "0?sub-rgsetcid,s,1

()") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:10] Gosub("SIP/09253131111-00000037", "sub-record-

check,s,1(rg,1,dontcare)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/09253131111-00000037", "11?

initialized") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (sub-record-check,s,10)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/09253131111-00000037", "Recordings 

initialized") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/09253131111-00000037", "0?Set

(ARG3=dontcare)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:12] Set("SIP/09253131111-00000037", 

"REC_POLICY_MODE_SAVE=") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/09253131111-00000037", "0?Set

(REC_STATUS=NO)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/09253131111-00000037", "2?

checkaction") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (sub-record-check,s,17)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/09253131111-00000037", "0?sub-

record-check,rg,1") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:18] NoOp("SIP/09253131111-00000037", "Generic rg 

Recording Check - 09253131111 1") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:19] Gosub("SIP/09253131111-00000037", 

"recordcheck,1(dontcare,rg,1)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/09253131111-00000037", 

"Starting recording check against dontcare") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/09253131111-00000037", 

"dontcare") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (sub-record-check,recordcheck,3)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/09253131111-00000037", "") 

in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@sub-record-check:20] Return("SIP/09253131111-00000037", "") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:11] Set("SIP/09253131111-00000037", 

"RingGroupMethod=ringall") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [1@ext-group:12] Macro("SIP/09253131111-00000037", "dial,35,m

(customuploaded)Tt,10-11-12-13-14-15") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:1] NoOp("SIP/09253131111-00000037", "Blind Transfer: , 

Attended Transfer: , User: 09253131111, Alert Info: ") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:2] ExecIf("SIP/09253131111-00000037", "1?Set

(ALERT_INFO=)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:3] ExecIf("SIP/09253131111-00000037", "0?Set

(ALERT_INFO=)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:4] ExecIf("SIP/09253131111-00000037", "0?Set

(ALERT_INFO=)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:5] ExecIf("SIP/09253131111-00000037", "1?Set(CHANNEL

(musicclass)=customuploaded)") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:6] AGI("SIP/09253131111-00000037", "dialparties.agi") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Caller ID name is 'Home Line' number is '09253131111'
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Methodology of ring is  'ringall'
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Added extension 10 to extension map
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Added extension 11 to extension map
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Added extension 12 to extension map
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Added extension 13 to extension map
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Added extension 14 to extension map
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Added extension 15 to extension map
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 10 cf is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 11 cf is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 12 cf is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 13 cf is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 14 cf is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 15 cf is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 10 do not disturb is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 11 do not disturb is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 12 do not disturb is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 13 do not disturb is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 14 do not disturb is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Extension 15 do not disturb is disabled
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: dbset CALLTRACE/10 to 09253131111
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: dbset CALLTRACE/11 to 09253131111
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: dbset CALLTRACE/12 to 09253131111
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: dbset CALLTRACE/13 to 09253131111
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: dbset CALLTRACE/14 to 09253131111
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: dbset CALLTRACE/15 to 09253131111

Here’s the second half. I’m copying and pasting and setting code formatting. If there’s a better way to post these logs, let me know.

[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: dialparties.agi: Filtered ARG3: 10-11-12-13-14-15
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] res_agi.c: <SIP/09253131111-00000037>AGI Script dialparties.agi completed, returning 0
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:9] NoOp("SIP/09253131111-00000037", "Returned from 

dialparties with groups to dial") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:10] Set("SIP/09253131111-00000037", "LOOPCNT=6") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:11] Set("SIP/09253131111-00000037", "ITER=1") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000037", "EXTTOCALL=10") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000037", "Working with 10") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000037", "ITER=2") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000037", "1?ndloopbegin") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (macro-dial,s,12)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000037", "EXTTOCALL=11") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000037", "Working with 11") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000037", "ITER=3") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000037", "1?ndloopbegin") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (macro-dial,s,12)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000037", "EXTTOCALL=12") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000037", "Working with 12") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000037", "ITER=4") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000037", "1?ndloopbegin") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (macro-dial,s,12)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000037", "EXTTOCALL=13") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000037", "Working with 13") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000037", "ITER=5") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000037", "1?ndloopbegin") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (macro-dial,s,12)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000037", "EXTTOCALL=14") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000037", "Working with 14") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000037", "ITER=6") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000037", "1?ndloopbegin") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Goto (macro-dial,s,12)
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:12] Set("SIP/09253131111-00000037", "EXTTOCALL=15") in new 

stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/09253131111-00000037", "Working with 15") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:14] Set("SIP/09253131111-00000037", "ITER=7") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/09253131111-00000037", "0?ndloopbegin") in 

new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:16] Macro("SIP/09253131111-00000037", "dial-ringall-

predial-hook,") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/09253131111-

00000037", "") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-dial:17] Dial("SIP/09253131111-00000037", 

"SIP/10&SIP/11&SIP/12&SIP/13&SIP/14&SIP/15,35,m(customuploaded)tM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-21 20:43:44] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/10-00000038 Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/10-00000038", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/10-00000038", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/10-00000038", "0") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_while.c: Jumping to priority 7
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/10-00000038", "") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/10-00000038'
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/10-00000038 Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/11-00000039 Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/11-00000039", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/11-00000039", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/11-00000039", "0") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_while.c: Jumping to priority 7
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/11-00000039", "") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/11-00000039'
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/11-00000039 Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/12-0000003a Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/12-0000003a", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/12-0000003a", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/12-0000003a", "0") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_while.c: Jumping to priority 7
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/12-0000003a", "") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/12-0000003a'
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/12-0000003a Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/13-0000003b Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/13-0000003b", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/13-0000003b", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/13-0000003b", "0") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_while.c: Jumping to priority 7
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/13-0000003b", "") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/13-0000003b'
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/13-0000003b Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/14-0000003c Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/14-0000003c", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/14-0000003c", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/14-0000003c", "0") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_while.c: Jumping to priority 7
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/14-0000003c", "") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/14-0000003c'
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/14-0000003c Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/15-0000003d Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/15-0000003d", "Applying SIP 

Headers to channel") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/15-0000003d", "SIPHEADERKEYS=") in 

new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/15-0000003d", "0") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_while.c: Jumping to priority 7
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/15-0000003d", "") in new stack
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: Spawn extension (from-internal, 1, 1) exited non-zero on 'SIP/15-0000003d'
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_stack.c: SIP/15-0000003d Internal Gosub(func-apply-sipheaders,s,1) complete 

GOSUB_RETVAL=
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: Called SIP/10
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: Called SIP/11
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: Called SIP/12
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: Called SIP/13
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: Called SIP/14
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: Called SIP/15
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] res_musiconhold.c: Started music on hold, class 'customuploaded', on channel 

'SIP/09253131111-00000037'
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/15-0000003d connected line has changed. Saving it until answer for 

SIP/09253131111-00000037
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/14-0000003c connected line has changed. Saving it until answer for 

SIP/09253131111-00000037
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/13-0000003b connected line has changed. Saving it until answer for 

SIP/09253131111-00000037
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/12-0000003a connected line has changed. Saving it until answer for 

SIP/09253131111-00000037
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/11-00000039 connected line has changed. Saving it until answer for 

SIP/09253131111-00000037
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/10-00000038 connected line has changed. Saving it until answer for 

SIP/09253131111-00000037
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/12-0000003a is ringing
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/10-00000038 is ringing
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/11-00000039 is ringing
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/13-0000003b is ringing
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/14-0000003c is ringing
[2016-04-21 20:43:45] VERBOSE[16048][C-00000017] app_dial.c: SIP/15-0000003d is ringing
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] res_musiconhold.c: Stopped music on hold on SIP/09253131111-00000037
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] app_macro.c: Spawn extension (macro-dial, s, 17) exited non-zero on 'SIP/09253131111-

00000037' in macro 'dial'
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] pbx.c: Spawn extension (ext-group, 1, 12) exited non-zero on 'SIP/09253131111-00000037'
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] pbx.c: Executing [h@ext-group:1] Macro("SIP/09253131111-00000037", "hangupcall,") in new 

stack
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/09253131111-00000037", "1?theend") in 

new stack
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] pbx.c: Goto (macro-hangupcall,s,3)
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/09253131111-00000037", "0?Set(CDR

(recordingfile)=)") in new stack
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/09253131111-00000037", "") in new 

stack
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 

'SIP/09253131111-00000037' in macro 'hangupcall'
[2016-04-21 20:43:56] VERBOSE[16048][C-00000017] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/09253131111-00000037'

No, still missing the important bits, compare what you have posted here with what prints when you are watching it in the asterisk cli.

How are you posting the log lines?

I grep from the asterisk log file the way you said and redirect to a text file. I replace the phone number then copy and paste into the message and set the log text to code formatting. It looks like the copy process breaks the lines into two here.

How about this. I confirmed verbose mode was on:

asterisk -rx "logger set level VERBOSE on"

and generated a new call. Here is the log information on Google Drive:

File Removed

[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/09253131111-00000007", "CALLERID(all)="Home Line" <09253131111>") in new stack

and then

[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Caller ID name is 'Home Line' number is '09253131111'
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Methodology of ring is  'ringall'
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Added extension 10 to extension map
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Added extension 11 to extension map
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Added extension 12 to extension map
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Added extension 13 to extension map
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Added extension 14 to extension map
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] res_agi.c: dialparties.agi: Added extension 15 to extension map

show it is being set, then

[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] app_dial.c: SIP/11-00000009 is ringing
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] app_dial.c: SIP/14-0000000c is ringing
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] app_dial.c: SIP/13-0000000b is ringing
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] app_dial.c: SIP/12-0000000a is ringing
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] app_dial.c: SIP/15-0000000d is ringing
[2016-04-22 07:56:23] VERBOSE[14594][C-00000001] app_dial.c: SIP/10-00000008 is ringing
[2016-04-22 07:56:29] VERBOSE[14594][C-00000001] res_musiconhold.c: Stopped music on hold on SIP/09253131111-00000007

show it hanging up the call after 6 seconds after ringing exts. 10-15

Yes, to generate this, I made a call from my cell (actually Google Voice), let it ring a couple of times and hung up. So the six seconds sounds right. The six phones are the phones in the house. That all looks right.

So I started looking at the code that’s doing all the monkey business with caller id: macro-user-callerid. This resides in extensions_addional.conf and is clearly marked by FreePBX as do not modify.

You jumped right to the line that I saw that is setting the caller ID as the number and name of the extension receiving the call from the HT-503.

I’m not very strong with asterisk’s macro language, but I’m seeing lots of conditional language that if some piece of CNAM is missing, set caller id this way.

Maybe I could put some code in macro-user-callerid-custom which is included and put it in extensions_custom.conf. I’d have that code log whatever CNAM info is coming from the HT-503.