Outbound CID is "stuck"

Hi. I’ve been using FreePBX for a while, and recently configured a new system from the latest AsteriskNow download (3).

On the old system, one SIP trunk has two incoming DID numbers, which map to two SIP phones. Outbound calls worked fine, extn A sent CID “A” and extn B sent CID “B”.
The trunk had its CID set to number “A”, and extn “B” would override that with number “B”.

The new system won’t send any CID except number “A” no matter where I configure the outbound CID.
I have tried:

  • Clearing the CID field in the trunk and route and setting the CID to number “B” in the extension only. Trunk has Allow any CID. No good. Still sends number “A”
  • Setting the CID in the trunk and the route and the extension to number “B”. No good, still sends number “A”
  • Setting the trunk CID to number “B”, setting the trunk to Force the Trunk CID, and clearing the CID in the route and the extension. No good, still sends number “A”.
    -Setting the CID to number “B” in the trunk and the route, and clearing the extn CID.
    I logged this one. Log shows everything happening correctly, but the receiving phone shows number “A”.

I shut down the new system and restarted the old one on the same account with the same phones, and all is well. What’s going on with FreePBX 2.11.0.38 / Asterisk 11.7.0 ?

Here’s the log. On the receiving phone I saw a call from the assigned geographic number on the trunk, not the outbound CID number that asterisk shows that it is sending. (Note, I’ve changed the extension number, outbound CID and outbound number. The original values are all legal and work fine on the old AsteriskNow 2 system.

[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:27] Set("SIP/888-00000000", "CALLERID(number)=888") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:28] Set("SIP/888-00000000", "CALLERID(name)=John") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:29] Set("SIP/888-00000000", "CDR(cnum)=888") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:30] Set("SIP/888-00000000", "CDR(cnam)=John") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:31] Set("SIP/888-00000000", "CHANNEL(language)=en") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:2] Set("SIP/888-00000000", "MOHCLASS=classical") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/888-00000000", "1?Set(TRUNKCIDOVERRIDE=08000999999)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:4] Set("SIP/888-00000000", "_NODEST=") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:5] Gosub("SIP/888-00000000", "sub-record-check,s,1(out,01234111222,)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:1] Set("SIP/888-00000000", "REC_POLICY_MODE_SAVE=") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/888-00000000", "1?check") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Goto (sub-record-check,s,7)
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:7] Set("SIP/888-00000000", "__MON_FMT=wav") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/888-00000000", "1?next") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Goto (sub-record-check,s,11)
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/888-00000000", "0?Return()") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:12] ExecIf("SIP/888-00000000", "0?Set(__REC_POLICY_MODE=)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:13] GotoIf("SIP/888-00000000", "0?out,1") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:14] Set("SIP/888-00000000", "__REC_STATUS=INITIALIZED") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:15] Set("SIP/888-00000000", "NOW=1406717720") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:16] Set("SIP/888-00000000", "__DAY=30") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:17] Set("SIP/888-00000000", "__MONTH=07") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:18] Set("SIP/888-00000000", "__YEAR=2014") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:19] Set("SIP/888-00000000", "__TIMESTR=20140730-115520") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:20] Set("SIP/888-00000000", "__FROMEXTEN=201") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:21] Set("SIP/888-00000000", "__CALLFILENAME=out-01234111222-888-20140730-115520-1406717720.0") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:22] Goto("SIP/888-00000000", "out,1") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Goto (sub-record-check,out,1)
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/888-00000000", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:2] GosubIf("SIP/888-00000000", "0?record,1(exten,01234111222,888)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:3] Return("SIP/888-00000000", "") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:6] Macro("SIP/888-00000000", "dialout-trunk,3,01234111222,,off") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:1] Set("SIP/888-00000000", "DIAL_TRUNK=3") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:2] GosubIf("SIP/888-00000000", "0?sub-pincheck,s,1()") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/888-00000000", "0?disabletrunk,1") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:4] Set("SIP/888-00000000", "DIAL_NUMBER=01234111222") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:5] Set("SIP/888-00000000", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:6] Set("SIP/888-00000000", "OUTBOUND_GROUP=OUT_3") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/888-00000000", "0?nomax") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/888-00000000", "0?chanfull") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/888-00000000", "0?skipoutcid") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:10] Set("SIP/888-00000000", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:11] Macro("SIP/888-00000000", "outbound-callerid,3") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/888-00000000", "0?Set(CALLERPRES()=)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:2] ExecIf("SIP/888-00000000", "0?Set(REALCALLERIDNUM=888)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/888-00000000", "1?normcid") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Goto (macro-outbound-callerid,s,6)
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:6] Set("SIP/888-00000000", "USEROUTCID=") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:7] Set("SIP/888-00000000", "EMERGENCYCID=") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:8] Set("SIP/888-00000000", "TRUNKOUTCID=08000999999") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/888-00000000", "1?trunkcid") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Goto (macro-outbound-callerid,s,14)
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:14] ExecIf("SIP/888-00000000", "1?Set(CALLERID(all)=08000999999)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:15] ExecIf("SIP/888-00000000", "0?Set(CALLERID(all)=)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:16] ExecIf("SIP/888-00000000", "1?Set(CALLERID(all)=08000999999)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:17] ExecIf("SIP/888-00000000", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:18] Set("SIP/888-00000000", "CDR(outbound_cnum)=08000999999") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:19] Set("SIP/888-00000000", "CDR(outbound_cnam)=") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:12] GosubIf("SIP/888-00000000", "0?sub-flp-3,s,1()") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:13] Set("SIP/888-00000000", "OUTNUM=01234111222") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:14] Set("SIP/888-00000000", "custom=SIP/VOIP_PROVIDER") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:15] ExecIf("SIP/888-00000000", "1?Set(DIAL_TRUNK_OPTIONS=M(setmusic^classical)Tt)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:16] ExecIf("SIP/888-00000000", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^classical)TtM(confirm))") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:17] Macro("SIP/888-00000000", "dialout-trunk-predial-hook,") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:1] MacroExit("SIP/888-00000000", "") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:18] GotoIf("SIP/888-00000000", "0?bypass,1") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:19] ExecIf("SIP/888-00000000", "1?Set(CONNECTEDLINE(num,i)=01234111222)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:20] ExecIf("SIP/888-00000000", "1?Set(CONNECTEDLINE(name,i)=CID:08000999999)") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:21] GotoIf("SIP/888-00000000", "0?customtrunk") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:22] Dial("SIP/888-00000000", "SIP/VOIP_PROVIDER/01234111222,300,M(setmusic^classical)Tt") in new stack
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] netsock2.c: == Using SIP RTP TOS bits 184
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] netsock2.c: == Using SIP RTP CoS mark 5
[2014-07-30 11:55:20] VERBOSE[2845][C-00000000] app_dial.c: -- Called SIP/VOIP_PROVIDER/01234111222
[2014-07-30 11:55:25] VERBOSE[2845][C-00000000] app_dial.c: -- SIP/VOIP_PROVIDER-00000001 is ringing
[2014-07-30 11:55:25] VERBOSE[2845][C-00000000] app_dial.c: -- SIP/VOIP_PROVIDER-00000001 is making progress passing it to SIP/888-00000000
[2014-07-30 11:55:28] VERBOSE[2845][C-00000000] app_macro.c: == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/888-00000000' in macro 'dialout-trunk'
[2014-07-30 11:55:28] VERBOSE[2845][C-00000000] pbx.c: == Spawn extension (from-internal, 01234111222, 6) exited non-zero on 'SIP/888-00000000'
[2014-07-30 11:55:28] VERBOSE[2845][C-00000000] pbx.c: -- Executing [[email protected]:1] Hangup("SIP/888-00000000", "") in new stack
[2014-07-30 11:55:28] VERBOSE[2845][C-00000000] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/888-00000000'

Anyone have any idea why I have no control over the CID ?
Is the new version sending it differently and causing the VOIP provider to ignore it and send their default number instead ?

I just tested 448000999999 as the force trunk CID and still got number A.

Help !

Downloaded FreePBX ISO v5.211.65, configured trunk, in and out routes, and two extensions.

Set caller ID on trunk to number “B”, which I’ve edited to show as 02222222222 in the log. Extn and route have no caller id.
Caller ID shown on receiver display is number “A” - the geographic number assigned to the SIP trunk.

I rebooted after setting all the config and before making the test call.

here’s the log.

[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:14] ExecIf(“SIP/888-00000002”, “1?Set(CALLERID(all)=02222222222)”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:15] ExecIf(“SIP/888-00000002”, “1?Set(CALLERID(all)=02222222222)”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:16] ExecIf(“SIP/888-00000002”, “0?Set(CALLERID(all)=)”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:17] ExecIf(“SIP/888-00000002”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:18] Set(“SIP/888-00000002”, “CDR(outbound_cnum)=02222222222”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:19] Set(“SIP/888-00000002”, “CDR(outbound_cnam)=”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:12] GosubIf(“SIP/888-00000002”, “0?sub-flp-2,s,1()”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:13] Set(“SIP/888-00000002”, “OUTNUM=01111111111”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:14] Set(“SIP/888-00000002”, “custom=SIP/voiptalk_swanley”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:15] ExecIf(“SIP/888-00000002”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:16] ExecIf(“SIP/888-00000002”, “0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:17] Macro(“SIP/888-00000002”, “dialout-trunk-predial-hook,”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:1] MacroExit(“SIP/201-00000002”, “”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:18] GotoIf(“SIP/888-00000002”, “0?bypass,1”) in new stack
[2014-07-30 18:53:06] VERBOSE[2545][C-00000002] pbx.c: – Executing [[email protected]:19] ExecIf(“SIP/888-00000002”, “1?Set(CONNECTEDLINE(num,i)=01111111111)”) in new stack

Number “B”, the one I am setting and which asterisk seems to be trying to send, which is also assigned to the same SIP trunk will only appear if I regress to my old Asterisk 1.6 system.

It seems to me that my VoIP provider does not like the format the Asterisk 11 system is using and is substitiuting a generic number. What I’d like to know, please, is why FreePBX 2.11.0.38 / Asterisk 11 does not work, while FreePBX 2.7.0.11 / Asterisk 1.6.2.20 does.

I’ll ask the same question of my VoIP provider.

SOLVED

After some wireshark capturing I found Asterisk 11 simply wasn’t sending any caller id.
I googled that and found that including the line “fromuser” in the trunk PEER details list causes v11 not to send any caller id. v1.6 apparently doesn’t care or uses that information differently.

My provider was indeed substituting a default caller ID since v11 wasn’t sending any hence the appearance that the ID was stuck at the SIP trunk DID number.

Remove the line “fromuser” in the trunk outgoing settings PEER details section, and all is well with my provider.