Zap .call file fails with strange error in log file

I use .call files to remind others of upcoming appointments. A couple each day will fail. The person says that they never got the call. I see an error in the log, but can’t decipher it. I would appreciate your help.

[code][message]
exten => s,1,Answer
exten => s,2,NoOp(Channel: ${custom} ) ; freepbx defines true channel as custom, not channel
exten => s,3,Set(ChannelType=${CUT(custom,/,1)}) ; get just the trunk type here
exten => s,4,NoOp(ChannelType: ${ChannelType})
exten => s,5,GotoIf($[${ChannelType} = ZAP]?12:6) ; Zap channel need more waitforsilence time

;not zap trunk
exten => s,6,Wait(2)
exten => s,7,WaitForSilence(2000,1) ; line supervision works on sip/iax so keep it short
exten => s,8,NoOp(silence waitstatus: ${WAITSTATUS})
exten => s,9,GotoIf($[${WAITSTATUS} = SILENCE]?11:10) ; so it exits with silence detected? goto talk,1
exten => s,10,Goto(91,1)
exten => s,11,Goto(talk,2)

;zap trunk, use backgrounddetect so person hears message until silence detected
exten => s,12,AbsoluteTimeout(70) ; avoid situation when person does not answer, has no machine either
exten => s,13,BackgroundDetect(custom/message,5000,10,145000)

exten => h,1,NoOp(Failed call)
exten => h,2,GotoIf($[${STATUS} = TIMEOUT]?3:6) ; if we came from T extension, then set status to timeout
exten => h,3,Set(Result=‘TIMEOUT’|g)
exten => h,4,Hangup
exten => h,6,Set(STATUS=‘Failed call’|g)
exten => h,7,Hangup[/code]

Mar 6 18:02:01 VERBOSE[16888] logger.c: -- Executing Dial("Local/2581578@from-internal-9b7d,2", "ZAP/4/www2581578|300|") in new stack Mar 6 18:02:01 DEBUG[16888] chan_zap.c: Dialing 'www2581578' Mar 6 18:02:01 DEBUG[16888] chan_zap.c: Deferring dialing... Mar 6 18:02:01 DEBUG[2520] channel.c: Avoiding initial deadlock for 'Zap/4-1' Mar 6 18:02:01 DEBUG[2520] channel.c: Avoiding initial deadlock for 'Zap/4-1' Mar 6 18:02:01 VERBOSE[16888] logger.c: -- Called 4/www2581578 Mar 6 18:02:02 DEBUG[16888] chan_zap.c: Exception on 16, channel 4 Mar 6 18:02:02 DEBUG[16888] chan_zap.c: Got event Hook Transition Complete(12) on channel 4 (index 0) Mar 6 18:02:03 DEBUG[2531] chan_iax2.c: Peer lastms 42, historicms 42, maxms 2000 Mar 6 18:02:05 DEBUG[16888] chan_zap.c: Exception on 16, channel 4 Mar 6 18:02:05 DEBUG[16888] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0) Mar 6 18:02:05 DEBUG[16888] chan_zap.c: Enabled echo cancellation on channel 4 Mar 6 18:02:05 DEBUG[16888] chan_zap.c: Engaged echo training on channel 4 Mar 6 18:02:06 NOTICE[2530] chan_sip.c: -- Registration for '2060@66.246.246.52' timed out, trying again (Attempt #4) Mar 6 18:02:06 DEBUG[2530] chan_sip.c: Scheduled a registration timeout for 66.246.246.52 id #299095 Mar 6 18:02:06 DEBUG[16888] chan_zap.c: Exception on 16, channel 4 Mar 6 18:02:06 DEBUG[16888] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0) Mar 6 18:02:06 DEBUG[16888] chan_zap.c: Echo cancellation already on Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Zap/4-1 answered Local/2581578@from-internal-9b7d,2 Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Executing Answer("Local/2581578@from-internal-9b7d,1", "") in new stack Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Executing NoOp("Local/2581578@from-internal-9b7d,1", "Channel: ZAP/4 ") in new stack Mar 6 18:02:06 DEBUG[16886] pbx.c: Function result is 'ZAP' Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Executing Set("Local/2581578@from-internal-9b7d,1", "ChannelType=ZAP") in new stack Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Executing NoOp("Local/2581578@from-internal-9b7d,1", "ChannelType: ZAP") in new stack Mar 6 18:02:06 DEBUG[16886] pbx.c: Expression result is '1' Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Executing GotoIf("Local/2581578@from-internal-9b7d,1", "1?12:6") in new stack Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Goto (message,s,12) Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Executing AbsoluteTimeout("Local/2581578@from-internal-9b7d,1", "70") in new stack Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Set Absolute Timeout to 70 Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Executing BackgroundDetect("Local/2581578@from-internal-9b7d,1", "custom/message|5000|10|145000") in new stack Mar 6 18:02:06 DEBUG[16886] app_talkdetect.c: Preparing detect of 'custom/message', sil=5000,min=10,max=145000 Mar 6 18:02:06 DEBUG[2520] channel.c: Avoiding initial deadlock for 'Local/2581578@from-internal-9b7d,2' Mar 6 18:02:06 DEBUG[16886] channel.c: Scheduling timer at 160 sample intervals Mar 6 18:02:06 VERBOSE[16886] logger.c: -- Playing 'custom/message' (language 'en') Mar 6 18:02:06 DEBUG[16888] channel.c: Planning to masquerade channel Zap/4-1 into the structure of Local/2581578@from-internal-9b7d,1 Mar 6 18:02:06 DEBUG[16888] channel.c: Done planning to masquerade channel Zap/4-1 into the structure of Local/2581578@from-internal-9b7d,1 Mar 6 18:02:06 DEBUG[16888] chan_local.c: Not posting to queue since already masked on 'Local/2581578@from-internal-9b7d,2' Mar 6 18:02:06 DEBUG[16886] channel.c: Got clone lock for masquerade on 'Zap/4-1' at 0x9a77fe4 Mar 6 18:02:06 DEBUG[16888] channel.c: Didn't get a frame from channel: Local/2581578@from-internal-9b7d,2 Mar 6 18:02:06 DEBUG[16888] channel.c: Bridge stops bridging channels Local/2581578@from-internal-9b7d,2 and Zap/4-1<MASQ> Mar 6 18:02:06 DEBUG[16886] channel.c: Putting channel Zap/4-1 in 64/64 formats Mar 6 18:02:06 DEBUG[16886] chan_zap.c: New owner for channel 4 is Zap/4-1 Mar 6 18:02:06 DEBUG[16886] chan_zap.c: Updated conferencing on 4, with 0 conference users Mar 6 18:02:06 DEBUG[16886] chan_zap.c: Updated conferencing on 4, with 0 conference users Mar 6 18:02:06 DEBUG[16886] channel.c: Released clone lock on 'Local/2581578@from-internal-9b7d,1<ZOMBIE>' Mar 6 18:02:06 DEBUG[16888] app_dial.c: Exiting with DIALSTATUS=ANSWER. Mar 6 18:02:06 VERBOSE[16888] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'Local/2581578@from-internal-9b7d,2' in macro 'dialout-trunk' Mar 6 18:02:06 VERBOSE[16888] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'Local/2581578@from-internal-9b7d,2' Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Executing Macro("Local/2581578@from-internal-9b7d,2", "hangupcall") in new stack Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Executing ResetCDR("Local/2581578@from-internal-9b7d,2", "w") in new stack Mar 6 18:02:06 DEBUG[16886] channel.c: Done Masquerading Zap/4-1 (6) Mar 6 18:02:06 DEBUG[16886] app_talkdetect.c: Start of voice token! Mar 6 18:02:06 DEBUG[16888] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Mar 6 18:02:06 DEBUG[16888] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2007-03-06 18:02:01','7575648182','7575648182','2581578','from-internal', 'Local/2581578@from-internal-9b7d,2','Zap/4-1','ResetCDR','w',5,0,'ANSWERED',3,'') Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Executing NoCDR("Local/2581578@from-internal-9b7d,2", "") in new stack Mar 6 18:02:06 NOTICE[16888] cdr.c: CDR on channel 'Local/2581578@from-internal-9b7d,2' not posted Mar 6 18:02:06 NOTICE[16888] cdr.c: CDR on channel 'Local/2581578@from-internal-9b7d,2' lacks end Mar 6 18:02:06 DEBUG[16888] pbx.c: Expression result is '1' Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Executing GotoIf("Local/2581578@from-internal-9b7d,2", "1?skiprg") in new stack Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Goto (macro-hangupcall,s,6) Mar 6 18:02:06 DEBUG[16888] pbx.c: Expression result is '1' Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Executing GotoIf("Local/2581578@from-internal-9b7d,2", "1?theend") in new stack Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Goto (macro-hangupcall,s,9) Mar 6 18:02:06 VERBOSE[16888] logger.c: -- Executing Wait("Local/2581578@from-internal-9b7d,2", "5") in new stack Mar 6 18:02:08 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14381: Found Mar 6 18:02:08 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14381: Match Found Mar 6 18:02:08 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14381: Not Found Mar 6 18:02:08 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14381: Match Not Found Mar 6 18:02:10 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14382: Found Mar 6 18:02:10 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14382: Match Found Mar 6 18:02:10 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14383: Found Mar 6 18:02:10 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14383: Match Found Mar 6 18:02:10 NOTICE[2530] chan_sip.c: Failed to authenticate on REGISTER to '2060@66.246.246.52' (Tries 3) Mar 6 18:02:10 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14382: Match Not Found Mar 6 18:02:10 VERBOSE[2530] logger.c: -- Got SIP response 503 "Server error" back from 66.246.246.52 Mar 6 18:02:10 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14383: Not Found Mar 6 18:02:10 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14383: Match Not Found Mar 6 18:02:10 NOTICE[2530] chan_sip.c: Failed to authenticate on REGISTER to '2060@66.246.246.52' (Tries 3) Mar 6 18:02:10 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14382: Match Not Found Mar 6 18:02:10 VERBOSE[2530] logger.c: -- Got SIP response 503 "Server error" back from 66.246.246.52 Mar 6 18:02:10 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14384: Found Mar 6 18:02:10 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14384: Match Found Mar 6 18:02:10 NOTICE[2530] chan_sip.c: Failed to authenticate on REGISTER to '2060@66.246.246.52' (Tries 3) Mar 6 18:02:11 VERBOSE[16888] logger.c: -- Executing Hangup("Local/2581578@from-internal-9b7d,2", "") in new stack Mar 6 18:02:11 VERBOSE[16888] logger.c: == Spawn extension (macro-hangupcall, s, 10) exited non-zero on 'Local/2581578@from-internal-9b7d,2' in macro 'hangupcall' Mar 6 18:02:11 VERBOSE[16888] logger.c: == Spawn extension (macro-hangupcall, s, 10) exited non-zero on 'Local/2581578@from-internal-9b7d,2' Mar 6 18:02:26 NOTICE[2530] chan_sip.c: -- Registration for '2060@66.246.246.52' timed out, trying again (Attempt #8) Mar 6 18:02:26 DEBUG[2530] chan_sip.c: Scheduled a registration timeout for 66.246.246.52 id #299100 Mar 6 18:02:28 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14385: Found Mar 6 18:02:28 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14385: Match Found Mar 6 18:02:28 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14385: Not Found Mar 6 18:02:28 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14385: Match Not Found Mar 6 18:02:29 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14386: Found Mar 6 18:02:29 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14386: Match Found Mar 6 18:02:30 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14387: Found Mar 6 18:02:30 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14387: Match Found Mar 6 18:02:30 NOTICE[2530] chan_sip.c: Failed to authenticate on REGISTER to '2060@66.246.246.52' (Tries 3) Mar 6 18:02:30 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14386: Match Not Found Mar 6 18:02:30 VERBOSE[2530] logger.c: -- Got SIP response 503 "Server error" back from 66.246.246.52 Mar 6 18:02:30 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14387: Not Found Mar 6 18:02:30 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14387: Match Not Found Mar 6 18:02:30 NOTICE[2530] chan_sip.c: Failed to authenticate on REGISTER to '2060@66.246.246.52' (Tries 3) Mar 6 18:02:30 DEBUG[2530] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' Request 14388: Found Mar 6 18:02:30 DEBUG[2530] chan_sip.c: Stopping retransmission on '687ce46c2224c76732dea63c1d5b0478@127.0.0.1' of Request 14388: Match Found Mar 6 18:02:30 NOTICE[2530] chan_sip.c: Failed to authenticate on REGISTER to '2060@66.246.246.52' (Tries 3) Mar 6 18:02:33 DEBUG[2530] chan_sip.c: Stopping retransmission on '493457d544cdb42f4e51f1a6051575bb@192.168.0.14' of Request 102: Match Found Mar 6 18:02:36 DEBUG[16886] chan_zap.c: Exception on 16, channel 4 Mar 6 18:02:36 DEBUG[16886] chan_zap.c: Got event On hook(1) on channel 4 (index 0) Mar 6 18:02:36 DEBUG[16886] chan_zap.c: disabled echo cancellation on channel 4 Mar 6 18:02:36 DEBUG[16886] channel.c: Scheduling timer at 0 sample intervals Mar 6 18:02:36 VERBOSE[16886] logger.c: == Spawn extension (message, s, 13) exited non-zero on 'Zap/4-1' Mar 6 18:02:36 VERBOSE[16886] logger.c: -- Executing NoOp("Zap/4-1", "Failed call") in new stack Mar 6 18:02:36 DEBUG[16886] pbx.c: Expression result is '0' Mar 6 18:02:36 VERBOSE[16886] logger.c: -- Executing GotoIf("Zap/4-1", "0?3:6") in new stack Mar 6 18:02:36 VERBOSE[16886] logger.c: -- Goto (message,h,6) Mar 6 18:02:36 VERBOSE[16886] logger.c: -- Executing Set("Zap/4-1", "Result=Failed call|g"