Here’s a trace:
[root@freepbx ~]# tail -f /var/log/asterisk/full
[2018-10-08 09:11:37] VERBOSE[13570][C-0000006d] pbx.c: Executing [s@bad-number: 1] Goto(“SIP/104-000000f4”, “11,1”) in new stack
[2018-10-08 09:11:37] VERBOSE[13570][C-0000006d] pbx_builtins.c: Goto (bad-numbe r,11,1)
[2018-10-08 09:11:37] VERBOSE[13570][C-0000006d] pbx.c: Executing [11@bad-number :1] ResetCDR(“SIP/104-000000f4”, “”) in new stack
[2018-10-08 09:11:37] VERBOSE[13570][C-0000006d] pbx.c: Executing [11@bad-number :2] NoCDR(“SIP/104-000000f4”, “”) in new stack
[2018-10-08 09:11:37] VERBOSE[13570][C-0000006d] pbx.c: Executing [11@bad-number :3] Progress(“SIP/104-000000f4”, “”) in new stack
[2018-10-08 09:11:37] VERBOSE[13570][C-0000006d] pbx.c: Executing [11@bad-number :4] Wait(“SIP/104-000000f4”, “1”) in new stack
[2018-10-08 09:11:38] VERBOSE[13570][C-0000006d] pbx.c: Executing [11@bad-number :5] Playback(“SIP/104-000000f4”, “silence/1&cannot-complete-as-dialed&check-numb er-dial-again,noanswer”) in new stack
[2018-10-08 09:11:38] VERBOSE[13570][C-0000006d] file.c: <SIP/104-000000f4> Play ing ‘silence/1.ulaw’ (language ‘en’)
[2018-10-08 09:11:39] VERBOSE[13570][C-0000006d] file.c: <SIP/104-000000f4> Play ing ‘cannot-complete-as-dialed.ulaw’ (language ‘en’)
[2018-10-08 09:11:39] VERBOSE[13570][C-0000006d] file.c: <SIP/104-000000f4> Play ing ‘check-number-dial-again.ulaw’ (language ‘en’)
[2018-10-08 09:12:25] VERBOSE[3256][C-0000006e] netsock2.c: Using SIP RTP TOS bits 184
[2018-10-08 09:12:25] VERBOSE[3256][C-0000006e] netsock2.c: Using SIP RTP CoS mark 5
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [8183783905@from-internal:1] Macro(“SIP/104-000000f5”, “user-callerid,LIMIT”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:1] Set(“SIP/104-000000f5”, “TOUCH_MONITOR=1539015145.285”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:2] Set(“SIP/104-000000f5”, “AMPUSER=104”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“SIP/104-000000f5”, “0?report”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“SIP/104-000000f5”, “1?Set(REALCALLERIDNUM=104)”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:5] Set(“SIP/104-000000f5”, “AMPUSER=104”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:6] GotoIf(“SIP/104-000000f5”, “0?limit”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:7] Set(“SIP/104-000000f5”, “AMPUSERCIDNAME=Len 450”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:8] ExecIf(“SIP/104-000000f5”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:9] GotoIf(“SIP/104-000000f5”, “0?report”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:10] Set(“SIP/104-000000f5”, “AMPUSERCID=104”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:11] Set(“SIP/104-000000f5”, “__DIAL_OPTIONS=HhTtr”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:12] Set(“SIP/104-000000f5”, “CALLERID(all)=“Len 450” <104>”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:13] GotoIf(“SIP/104-000000f5”, “0?limit”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:14] ExecIf(“SIP/104-000000f5”, “1?Set(GROUP(concurrency_limit)=104)”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:15] ExecIf(“SIP/104-000000f5”, “0?Set(CHANNEL(language)=)”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:16] NoOp(“SIP/104-000000f5”, “Macro Depth is 1”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:17] GotoIf(“SIP/104-000000f5”, “1?report2:macroerror”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:18] GotoIf(“SIP/104-000000f5”, “1?continue”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:37] Set(“SIP/104-000000f5”, “CALLERID(number)=104”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:38] Set(“SIP/104-000000f5”, “CALLERID(name)=Len 450”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:39] GotoIf(“SIP/104-000000f5”, “0?cnum”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:40] Set(“SIP/104-000000f5”, “CDR(cnam)=Len 450”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:41] Set(“SIP/104-000000f5”, “CDR(cnum)=104”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@macro-user-callerid:42] Set(“SIP/104-000000f5”, “CHANNEL(language)=en”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [[10 digits]@from-internal:2] Set(“SIP/104-000000f5”, “ROUTEUSER=104”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [[10 digits]@from-internal:3] Set(“SIP/104-000000f5”, “ROUTEUSER=104”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [[10 digits]@from-internal:4] GotoIf(“SIP/104-000000f5”, “1?notblind”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx_builtins.c: Goto (from-internal,[10 digits],7)
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [[10 digits]@from-internal:7] GotoIf(“SIP/104-000000f5”, “1?restrictedroute-c4ca4238a0b923820dcc509a6f75849b,[10 digits],2:outbound-allroutes,[10 digits],2”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx_builtins.c: Goto (restrictedroute-c4ca4238a0b923820dcc509a6f75849b,[10 digits],2)
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Channel ‘SIP/104-000000f5’ sent to invalid extension: context,exten,priority=restrictedroute-c4ca4238a0b923820dcc509a6f75849b,[10 digits],2
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [i@restrictedroute-c4ca4238a0b923820dcc509a6f75849b:1] Goto(“SIP/104-000000f5”, “bad-number,s,1”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx_builtins.c: Goto (bad-number,s,1)
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [s@bad-number:1] Goto(“SIP/104-000000f5”, “11,1”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx_builtins.c: Goto (bad-number,11,1)
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [11@bad-number:1] ResetCDR(“SIP/104-000000f5”, “”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [11@bad-number:2] NoCDR(“SIP/104-000000f5”, “”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [11@bad-number:3] Progress(“SIP/104-000000f5”, “”) in new stack
[2018-10-08 09:12:25] VERBOSE[13861][C-0000006e] pbx.c: Executing [11@bad-number:4] Wait(“SIP/104-000000f5”, “1”) in new stack
[2018-10-08 09:12:26] VERBOSE[13861][C-0000006e] pbx.c: Executing [11@bad-number:5] Playback(“SIP/104-000000f5”, “silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer”) in new stack
[2018-10-08 09:12:26] VERBOSE[13861][C-0000006e] file.c: <SIP/104-000000f5> Playing ‘silence/1.ulaw’ (language ‘en’)
[2018-10-08 09:12:27] VERBOSE[13861][C-0000006e] file.c: <SIP/104-000000f5> Playing ‘cannot-complete-as-dialed.ulaw’ (language ‘en’)
[2018-10-08 09:12:29] VERBOSE[13861][C-0000006e] file.c: <SIP/104-000000f5> Playing ‘check-number-dial-again.ulaw’ (language ‘en’)