An error has occured on call forwarding

I have heard this intercept on VM, never on CF. I see this TRACE_ID before it happens.

Asterisk 1.8.12 current FreePBX 2.10
Anybody have any ideas, it’s new to me:

[size=8]
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Examining event:
Event: Newexten^M
Privilege: dialplan,all^M
Channel: SIP/hip2-001a4328^M
Context: macro-user-callerid^M
Extension: s^M
Priority: 18^M
Application: Wait^M
AppData: 1^M
Uniqueid: 1370895867.1759052^M
^M

[2013-06-10 16:24:44] DEBUG[6769] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2013-06-10 16:24:44] DEBUG[6769] channel.c: Started silence generator on 'SIP/hip2-001a4328'
[2013-06-10 16:24:44] DEBUG[6769] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw
[2013-06-10 16:24:44] DEBUG[6769] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=3.13E+09, Et=2.20E+11, s/n=      0.01
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=8.59E+04, Et=2.10E+06, s/n=      0.04
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=4.72E+03, Et=1.82E+06, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=1.93E+03, Et=1.85E+06, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=2.96E+03, Et=1.79E+06, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=5.80E+01, Et=1.76E+06, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=1.30E+02, Et=1.98E+06, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=6.38E+03, Et=1.33E+06, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=0.00E+00, Et=0.00E+00, s/n=       nan
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=1.10E+07, Et=2.80E+09, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=1.16E+04, Et=2.59E+08, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=7.22E+02, Et=1.75E+08, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=8.62E+04, Et=1.34E+08, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=3.31E+04, Et=1.11E+08, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=3.90E+03, Et=9.61E+07, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=2.06E+04, Et=8.59E+07, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=2.59E+04, Et=7.71E+07, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=1.24E+04, Et=7.15E+07, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=4.14E+04, Et=6.71E+07, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=5.44E+02, Et=6.11E+07, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=8.97E+04, Et=5.75E+07, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:44] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=2.11E+04, Et=5.37E+07, s/n=      0.00
[2013-06-10 16:24:44] DEBUG[6769] dsp.c: tone 1100, Ew=5.97E+03, Et=5.00E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=1.04E+04, Et=4.73E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=2.50E+04, Et=4.43E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=7.27E+03, Et=4.19E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=8.95E+04, Et=3.94E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=8.81E+04, Et=3.80E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=4.13E+03, Et=3.59E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=2.08E+04, Et=3.40E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=8.78E+04, Et=3.41E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=7.25E+03, Et=3.10E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=2.37E+03, Et=2.84E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=1.93E+04, Et=2.72E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=3.60E+03, Et=2.80E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=8.60E+04, Et=2.63E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=1.74E+04, Et=2.56E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=9.23E+04, Et=2.52E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=6.57E+03, Et=2.38E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=5.67E+03, Et=2.37E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[32571] pbx.c: Result of 'AJ_TRACE_ID' is NULL
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[6769] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2013-06-10 16:24:45] DEBUG[6769] channel.c: Stopped silence generator on 'SIP/hip2-001a4328'
[2013-06-10 16:24:45] DEBUG[6769] channel.c: Set channel SIP/hip2-001a4328 to write format ulaw
[2013-06-10 16:24:45] DEBUG[6769] app_macro.c: Executed application: Wait
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Examining event:
Event: VarSet^M
Privilege: dialplan,all^M
Channel: SIP/hip2-001a4328^M
Variable: MACRO_DEPTH^M
Value: 1^M
Uniqueid: 1370895867.1759052^M
^M

[2013-06-10 16:24:45] DEBUG[6769] pbx.c: Launching 'Playback'
[2013-06-10 16:24:45] VERBOSE[6769] pbx.c:     -- Executing [s@macro-user-callerid:19] Playback("SIP/hip2-001a4328", "im-sorry&an-error-has-occured&with&call-forwarding") in new stack
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Examining event:
Event: Newexten^M
Privilege: dialplan,all^M
Channel: SIP/hip2-001a4328^M
Context: macro-user-callerid^M
Extension: s^M
Priority: 19^M
Application: Playback^M
AppData: im-sorry&an-error-has-occured&with&call-forwarding^M
Uniqueid: 1370895867.1759052^M
^M

[2013-06-10 16:24:45] DEBUG[6769] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2013-06-10 16:24:45] VERBOSE[6769] file.c:     -- <SIP/hip2-001a4328> Playing 'im-sorry.ulaw' (language 'en')
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=6.34E+03, Et=2.25E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=1.91E+04, Et=2.23E+07, s/n=      0.00
[2013-06-10 16:24:45] DEBUG[32571] manager.c: Running action 'Getvar'
[2013-06-10 16:24:45] DEBUG[6769] dsp.c: tone 1100, Ew=9.97E+03, Et=2.16E+07, s/n=      0.00

[/size]

I know I posted a repetitive log but I wanted you to get a flavor for the time of the loop.

Any help appreciated.