QDSMain.Exceptions.DistributionFailedException: Distribute failed with errors to follow.

[Dayna]

Hello,

Can you assist me with the error below, please? We are periodically getting a report failure within the management console, here's the details in the log:

17/07/2019 14:22:26.8866563	Information	Starting task 'Other/Frontline Reporting.qvw'. Id:57907059-a061-49bb-b38f-01be80343ae1. Triggered by 'ManualStartTrigger'. Id:00000001-0002-0003-0405-0607080a0b0c
17/07/2019 14:22:26.9022568	Information	Entering Task Execution. 
17/07/2019 14:22:26.9022568	Information	ClusterID=1
17/07/2019 14:22:26.9022568	Information	QDSID=89b09bd8-6795-a057-5875-856fcc6c96ba
17/07/2019 14:22:26.9022568	Information	TaskID=57907059-a061-49bb-b38f-01be80343ae1
17/07/2019 14:22:26.9022568	Information	MaxRunTime=00:05:00
17/07/2019 14:22:26.9022568	Information	MachineName=FLBIT004
17/07/2019 14:22:26.9022568	Information	Max attempts:1
17/07/2019 14:22:26.9022568	Information	Current Attempt=0
17/07/2019 14:22:26.9022568	Information	Task Dependencies are OK
17/07/2019 14:22:26.9178573	Information	Document is marked to be Reloaded with fresh data. Initializing Reload for Distribution.
17/07/2019 14:22:26.9178573	Information	Opening "E:\QLIKVIEWDOCUMENTS\OTHER\Frontline Reporting.qvw"
17/07/2019 14:22:26.9178573	Information	Allocating new QlikView Engine. Current usage count=1 of 4 (of type non-reader).
17/07/2019 14:22:26.9178573	Information	Max retries:5
17/07/2019 14:22:26.9178573	Information	Attempt:01
17/07/2019 14:22:27.6822818	Information	Opened the QlikView Engine successfully. ProcessID=2696
17/07/2019 14:22:27.6822818	Information	Allocated QlikView Engine successfully. Current usage count=2 of 4 (of type non-reader). Ticket number=6873.
17/07/2019 14:22:27.6822818	Information	Loading document "E:\QLIKVIEWDOCUMENTS\OTHER\Frontline Reporting.qvw" (10.29 Mb)
17/07/2019 14:22:28.0878948	Information	Physical FileSize=10.29 Mb. Memory Allocation Delta for this file=29.49 Mb. Available Physical Memory Before Open=3086.15 Mb. Available Physical Memory After Open=3053.82 Mb. Total Physical Memory=16383.49 Mb.
17/07/2019 14:22:28.0878948	Information	Attempted to load the document without data.
17/07/2019 14:22:28.0878948	Information	The document was loaded successfully.
17/07/2019 14:22:28.0878948	Information	Document was opened successfully
17/07/2019 14:22:28.0878948	Information	Starting reload
17/07/2019 14:22:28.1190958	Information	QlikView->Settings->Document Peferences->Generate Logfile in document is set. Enabling Log Copier.
17/07/2019 14:22:28.3999048	Information	The Source Document is being reloaded. DocumentPath=E:\QLIKVIEWDOCUMENTS\OTHER\Frontline Reporting.qvw
17/07/2019 14:22:28.3999048	Information	Waiting for the document log "E:\QLIKVIEWDOCUMENTS\OTHER\Frontline Reporting.qvw" to become available.. Check until 17/07/2019 14:22:58
17/07/2019 14:22:28.4623068	Information	Found a document log. FileName=E:\QLIKVIEWDOCUMENTS\OTHER\Frontline Reporting.qvw.2019_07_17_14_22_28.log
17/07/2019 14:22:28.4623068	Information	Writing documentLog to C:\ProgramData\QlikTech\DistributionService\1\Log\20190717\142226 - Other_Frontline Reporting.qvw\DocumentLog.txt
17/07/2019 14:22:29.1019273	Information	Reloading.
17/07/2019 14:22:30.1159598	Information	Reloading..
17/07/2019 14:22:31.1299923	Information	Reloading...
17/07/2019 14:22:32.1440248	Information	Reloading....
17/07/2019 14:22:33.1580573	Information	Reloading.....
17/07/2019 14:22:34.1720898	Information	Reloading......
17/07/2019 14:22:35.1861223	Information	Reloading.......
17/07/2019 14:22:36.2001548	Information	Reloading........
17/07/2019 14:22:37.2141873	Information	Reloading.........
17/07/2019 14:22:38.2282198	Information	Reloading..........
17/07/2019 14:22:39.2422523	Information	Slow down logging. Log every <2> seconds.
17/07/2019 14:22:39.2422523	Information	Reloading
17/07/2019 14:22:41.2703173	Information	Reloading.
17/07/2019 14:22:43.2983823	Information	Reloading..
17/07/2019 14:22:45.3264473	Information	Reloading...
17/07/2019 14:22:47.3545123	Information	Reloading....
17/07/2019 14:22:49.3825773	Information	Reloading.....
17/07/2019 14:22:51.4106423	Information	Reloading......
17/07/2019 14:22:53.4387073	Information	Reloading.......
17/07/2019 14:22:55.4667723	Information	Reloading........
17/07/2019 14:22:57.4948373	Information	Reloading.........
17/07/2019 14:22:59.5229023	Information	Reloading..........
17/07/2019 14:23:01.5509673	Information	Slow down logging. Log every <10> seconds.
17/07/2019 14:23:01.5509673	Information	Reloading
17/07/2019 14:23:11.6912923	Information	Reloading.
17/07/2019 14:23:21.8316173	Information	Reloading..
17/07/2019 14:23:31.9695427	Information	Reloading...
17/07/2019 14:23:42.1098677	Information	Reloading....
17/07/2019 14:23:52.2501927	Information	Reloading.....
17/07/2019 14:24:02.3905177	Information	Reloading......
17/07/2019 14:24:12.5308427	Information	Reloading.......
17/07/2019 14:24:22.6711677	Information	Reloading........
17/07/2019 14:24:32.8008924	Information	Reloading.........
17/07/2019 14:24:42.9412174	Information	Reloading..........
17/07/2019 14:24:53.0815424	Information	Slow down logging. Log every <60> seconds.
17/07/2019 14:24:53.0815424	Information	Reloading
17/07/2019 14:25:53.9203924	Information	Reloading.
17/07/2019 14:26:54.7517421	Information	Reloading..
17/07/2019 14:27:37.3617078	Warning	The QlikView Engine is Reloading, it will be killed (Please ignore logged warnings/errors about the kill).
17/07/2019 14:27:37.3773083	Information	Killing the QlikView Engine. ProcessID=2696
17/07/2019 14:27:37.3773083	Information	Reload was aborted.
17/07/2019 14:27:38.1261323	Information	Killing a child process of the QlikView Engine. ProcessID=2608. ProcessName=qvconnect32
17/07/2019 14:27:38.2353358	Information	Successfully killed a child process of the QlikView Engine. ProcessID=2696. ProcessName=qvb
17/07/2019 14:27:38.5005443	Information	Closed the QlikView Engine successfully. ProcessID=2696
17/07/2019 14:27:38.5005443	Error	The task "Other/Frontline Reporting.qvw" failed. Exception:
QDSMain.Exceptions.DistributionFailedException: Distribute failed with errors to follow. ---> QDSMain.Exceptions.ReloadFailedException: Reload failed ---> System.Threading.ThreadAbortException: Thread was being aborted.
   at System.Threading.WaitHandle.WaitOneNative(SafeHandle waitableSafeHandle, UInt32 millisecondsTimeout, Boolean hasThreadAffinity, Boolean exitContext)
   at System.Threading.WaitHandle.InternalWaitOne(SafeHandle waitableSafeHandle, Int64 millisecondsTimeout, Boolean hasThreadAffinity, Boolean exitContext)
   at SolutionGlobal.ThreadPool.ThreadPoolJob.SafeWaitEvent(WaitHandle eventWaitHandle)
   at QDSMain.ReloadTask.Reload(String fileName, TaskResult taskResult, String sectionAccessUserName, String sectionAccessPassword, eReloadOptions reloadOption, String variableName, String variableValue, Boolean moniterCpuUsage)
   --- End of inner exception stack trace ---
   at QDSMain.ReloadTask.Reload(String fileName, TaskResult taskResult, String sectionAccessUserName, String sectionAccessPassword, eReloadOptions reloadOption, String variableName, String variableValue, Boolean moniterCpuUsage)
   at QDSMain.DistributeTask.Execute(TaskResult currentTaskResult)
   --- End of inner exception stack trace ---
   at QDSMain.DistributeTask.Execute(TaskResult currentTaskResult)
   at QDSMain.Task.AbstractTask.TaskExecution(ILogBucket logBucket, TaskResult taskResult)
17/07/2019 14:27:38.5473458	Error	Task failed with exception
17/07/2019 14:27:38.5473458	Error	Exception=The currently executing operation was aborted.
17/07/2019 14:27:38.5473458	Information	Sending Alert mail
17/07/2019 14:27:39.7173833	Information	TaskResult.status=Finished
17/07/2019 14:27:39.7953858	Information	Notifying all triggers of new state:FinishedWithErrors
17/07/2019 14:27:39.7953858	Information	Notifying all triggers of new state:FinishedWithErrors - completed
17/07/2019 14:27:39.7953858	Information	Saving Task Result

Can you point me in the right direction on how to resolve this, please? The report loads fine when in the development application.

Many thanks!

Dayna

[Chip_Matejowsky]

Hi @Dayna,

Per the task log, the task is timing out after 5 minutes. The below entry shows that this task has a MaxRunTime of 5 minutes:

17/07/2019 14:22:26.9022568	Information	MaxRunTime=00:05:00

 Then the below entries show the task being killed after 5 minutes has elapsed:

17/07/2019 14:27:37.3773083	Information	Killing the QlikView Engine. ProcessID=2696
17/07/2019 14:27:37.3773083	Information	Reload was aborted.

 In QMC > Documents > Source Documents, edit the task and then select Triggers tab > Task Execute Options > Timeout in minutes entry to see what value you have there. You may need to increase this value to ensure the task has enough time to complete. The default value is 1440 minutes (24 hours).

[Dayna]

Hello,

I reduced the time on the timeout as it didn't matter what it was set to, it would always timeout. This way, it doesn't prevent the next scheduled load from running.

Can you assist in what I need to do to troubleshoot why it is timing out? I never get this issue when loading the report manually within the developer app.

Many thanks,

Dayna

[Chip_Matejowsky]

Thanks for the response. The log you posted shows that the task timed out after 5 minutes, as this is the time interval you have the configured the task to timeout. As it stands now, there isn't any information in this log to shed light on why the task didn't complete when the timeout was set to 1440 minutes. I understand that you set the task timeout in order to ensure Publisher would be able to progress to next scheduled task.

If you look at previous failed task logs before you set task timeout to 5 minutes, can you see if the QVW finished reloading and then failed upon the distribution portion of the task? That's what we'll need to continue investigating.

[Brett_Bleess]

Dayna, to clarify Chip's points, what you really want to set for the Task Timeout value is the amount of time it takes things to run when you run it 'manually' plus a minute or two buffer as well just to be safe.  

The other thing you can do is turn on the Script Log in the app, you do that via Settings\Document Properties\General tab and the Generate Logfile option, this way you can see exactly where things were in the reload process etc. too.  Hopefully this helps you get things figured out now.

Regards,
Brett

[Dayna · Accepted solution]

Thanks all. Sadly, I've not resolved the cause of the timeout and believe it's related to the method of querying the data - even updating the ODBC driver, there's no difference! But the below was useful anyway.