Document reload fails intermittently - log attached

[avantime]

Hi,

I have one task that keeps failing on reload from time to time in QMC. I am attaching the reload log, maybe you can find the source of the problem.

20161219T230000.311+0200	Information	Starting task 'Report.qvw'. Id:17f9481a-39c9-4198-9def-7395e1d6ad35. Triggered by 'ScheduleTrigger'. Id:27ace42e-8abc-4a32-b289-d5571ae474ee
20161219T230000.311+0200	Information	Entering Task Execution.
20161219T230000.311+0200	Information	ClusterID=1
20161219T230000.311+0200	Information	QDSID=4b613876-3901-9cd6-678d-2a8cfda0a7e0
20161219T230000.311+0200	Information	TaskID=17f9481a-39c9-4198-9def-7395e1d6ad35
20161219T230000.311+0200	Information	MaxRunTime=06:00:00
20161219T230000.311+0200	Information	MachineName=MachineName
20161219T230000.311+0200	Information	Max attempts:1
20161219T230000.311+0200	Information	Current Attempt=0
20161219T230000.311+0200	Information	Task Dependencies are OK
20161219T230000.327+0200	Information	Document is marked to be Reloaded with fresh data. Initializing Reload for Distribution.
20161219T230000.327+0200	Information	Opening "Report.qvw"
20161219T230000.327+0200	Information	Allocating new QlikView Engine. Current usage count=0 of 15 (of type non-reader).
20161219T230000.327+0200	Information	Max retries:5
20161219T230000.327+0200	Information	Attempt:01
20161219T230001.014+0200	Information	Opened the QlikView Engine successfully. ProcessID=3540
20161219T230001.030+0200	Information	Allocated QlikView Engine successfully. Current usage count=1 of 15 (of type non-reader). Ticket number=846.
20161219T230001.030+0200	Information	Loading document "Report.qvw" (110.97 Mb)
20161219T230001.108+0200	Information	Physical FileSize=110.97 Mb. Memory Allocation Delta for this file=2.59 Mb. Available Physical Memory Before Open=37074.18 Mb. Available Physical Memory After Open=37068.32 Mb. Total Physical Memory=65535.55 Mb.
20161219T230001.123+0200	Information	Attempted to load the document without data.
20161219T230001.123+0200	Information	The document was loaded successfully.
20161219T230001.123+0200	Information	Document was opened successfully
20161219T230001.123+0200	Information	Starting reload
20161219T230001.123+0200	Information	QlikView->Settings->Document Peferences->Generate Logfile in document is not set.
20161219T230001.123+0200	Information	The Source Document is being reloaded. DocumentPath=Report.qvw
20161219T230002.138+0200	Information	Reloading.
20161219T230003.141+0200	Information	Reloading..
20161219T230004.150+0200	Information	Reloading...
20161219T230005.166+0200	Information	Reloading....
20161219T230006.182+0200	Information	Reloading.....
20161219T230007.185+0200	Information	Reloading......
20161219T230008.186+0200	Information	Reloading.......
20161219T230009.186+0200	Information	Reloading........
20161219T230010.202+0200	Information	Reloading.........
20161219T230011.217+0200	Information	Reloading..........
20161219T230012.232+0200	Information	Slow down logging. Log every <2> seconds.
20161219T230012.232+0200	Information	Reloading
20161219T230014.248+0200	Information	Reloading.
20161219T230016.264+0200	Information	Reloading..
20161219T230018.283+0200	Information	Reloading...
20161219T230020.291+0200	Information	Reloading....
20161219T230022.310+0200	Information	Reloading.....
20161219T230024.310+0200	Information	Reloading......
20161219T230026.325+0200	Information	Reloading.......
20161219T230028.327+0200	Information	Reloading........
20161219T230030.353+0200	Information	Reloading.........
20161219T230032.356+0200	Information	Reloading..........
20161219T230034.359+0200	Information	Slow down logging. Log every <10> seconds.
20161219T230034.359+0200	Information	Reloading
20161219T230044.449+0200	Information	Reloading.
20161219T230054.483+0200	Information	Reloading..
20161219T230104.575+0200	Information	Reloading...
20161219T230114.684+0200	Information	Reloading....
20161219T230124.733+0200	Information	Reloading.....
20161219T230134.794+0200	Information	Reloading......
20161219T230144.857+0200	Information	Reloading.......
20161219T230154.903+0200	Information	Reloading........
20161219T230204.964+0200	Information	Reloading.........
20161219T230215.037+0200	Information	Reloading..........
20161219T230225.114+0200	Information	Slow down logging. Log every <60> seconds.
20161219T230225.114+0200	Information	Reloading
20161219T230325.554+0200	Information	Reloading.
20161219T230425.914+0200	Information	Reloading..
20161219T230526.369+0200	Information	Reloading...
20161219T230626.808+0200	Information	Reloading....
20161219T230727.281+0200	Information	Reloading.....
20161219T230827.760+0200	Information	Reloading......
20161219T230928.221+0200	Information	Reloading.......
20161219T231028.580+0200	Information	Reloading........
20161219T231128.958+0200	Information	Reloading.........
20161219T231229.389+0200	Information	Reloading..........
20161219T231329.751+0200	Information	Slow down logging. Log every <300> seconds.
20161219T231329.751+0200	Information	Reloading
20161219T231831.745+0200	Information	Reloading.
20161219T232333.517+0200	Information	Reloading..
20161219T232835.466+0200	Information	Reloading...
20161219T233337.447+0200	Information	Reloading....
20161219T233839.409+0200	Information	Reloading.....
20161219T234341.138+0200	Information	Reloading......
20161219T234843.024+0200	Information	Reloading.......
20161219T235345.135+0200	Information	Reloading........
20161219T235847.272+0200	Information	Reloading.........
20161220T000349.471+0200	Information	Reloading..........
20161220T000851.375+0200	Information	Slow down logging. Log every <600> seconds.
20161220T000851.375+0200	Information	Reloading
20161220T001855.790+0200	Information	Reloading.
20161220T002859.679+0200	Information	Reloading..
20161220T003903.797+0200	Information	Reloading...
20161220T004907.964+0200	Information	Reloading....
20161220T005911.869+0200	Information	Reloading.....
20161220T010915.958+0200	Information	Reloading......
20161220T011920.359+0200	Information	Reloading.......
20161220T012924.679+0200	Information	Reloading........
20161220T013928.801+0200	Information	Reloading.........
20161220T014932.884+0200	Information	Reloading..........
20161220T015936.618+0200	Information	Slow down logging. Log every <900> seconds.
20161220T015936.618+0200	Information	Reloading
20161220T021442.953+0200	Information	Reloading.
20161220T022948.987+0200	Information	Reloading..
20161220T024336.753+0200	Information	The Source Document reload complete. DocumentPath=Report.qvw
20161220T024336.753+0200	Information	Memory Allocation Delta for this file=39.29 Mb. Available Physical Memory Before Reload=37068.30 Mb. Available Physical Memory After Reload=45061.73 Mb. Total Physical Memory=45061.73 Mb.
20161220T024336.800+0200	Error	The Source Document was NOT reloaded successfully. DocumentPath=Report.qvw.
20161220T024336.816+0200	Information	Closing the document.
20161220T024337.441+0200	Information	Closed the QlikView Engine successfully. ProcessID=3540
20161220T024337.488+0200	Error	The task "Report.qvw" failed. Exception: || QDSMain.Exceptions.TaskFailedException: Task execution failed with errors to follow. ---> QDSMain.Exceptions.ReloadFailedException: Reload failed ---> QDSMain.Exceptions.LogBucketErrorException: The Source Document was NOT reloaded successfully. DocumentPath=Report.qvw.  ||    at QDSMain.ReloadTask.VerifyConditions(TaskResult taskResult) ||    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)
20161220T024337.488+0200	Information	Task Execute Duration=03:43:37.1766528
20161220T024337.488+0200	Information	Sending Alert mail
20161220T024338.019+0200	Information	TaskResult.status=Finished
20161220T024338.019+0200	Information	Notifying all triggers of new state:FinishedWithErrors
20161220T024338.019+0200	Information	Notifying all triggers of new state:FinishedWithErrors - completed
20161220T024338.019+0200	Information	Saving Task Result

[marcus_sommer]

With only the task-log it's difficult to say what the error is. It looked that reload itself was successful but the processing after them (creating the datamodel, storing the application, ...) was it not.

I suggest that you compares this log with another successful ones to find any differences and that you enabled the script-log of the application (within the document properties in tab general) to get a more useful error-message.

If there is no one you should take a look within the qlik event- and performance logs: QlikView Governance Dashboard and within the windows event-logs.

- Marcus

[avantime]

Hi Marcus,

The only difference I see between failed and completed reloads is that the memory delta on successful reloads is more than 300 mb, on failed ones is less than 40 mb (even 2-3 mb).

[vishsaggi]

We can see your dashboard is not set with document log. Can you open the dashboard and from Document properties check Generate log file and reload the dashboard on QMC. When it fails it will generate a log file in QV server. It would save that log file in QDS\log\.... folder on your server. You can find the full path in the log script (as seen above) on QMC with below line Information: eg:

Writing documentLog to S:\QlikView\QDS\1\Log\20161220\012254 - Yourdashboardname\DocumentLog.txt

[adinning]

Can you confirm the reload timeout?

It may be hitting the timeout maximum, and cancelling the task.

[Chip_Matejowsky]

Hello Catalin,

From the task log you posted, we can see the following error:

20161220T024337.488+0200

Error

The task "Report.qvw" failed. Exception: || QDSMain.Exceptions.TaskFailedException: Task execution failed with errors to follow. ---> QDSMain.Exceptions.ReloadFailedException: Reload failed ---> QDSMain.Exceptions.LogBucketErrorException: The Source Document was NOT reloaded successfully. DocumentPath=Report.qvw.  ||    at QDSMain.ReloadTask.VerifyConditions(TaskResult taskResult) ||    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)

So the task log is telling us that the actual document (.QVW file) didn't reload. To proceed, you'll want to review the document log of the file Report.qvw. If document logging is enabled, it will be stored in the same directory in which the QVW file is housed. If document logging is not enabled, you will need to open the QVW file in QlikView Developer, click Settings > Document Properties > General tab and ensure the Generate Logfile checkbox is ticked. Then run the reload task so that the document log is generated. Once the document log is generated, scroll to the bottom of the log to look for errors. When you have them, post them back on the this thread.

- Chip

[avantime]

Hi Andrew, the reload time was ~ 3 hours.

[avantime]

Hi Chip, I turned on logging, i`ll attach it on the next failed reload. Thanks!

[avantime · Accepted solution]

Here`s the log. What I`m guessing is that the app stores the qvd at the same time another application reads from the same qvd so it`s unable to overwrite it. Makes sense doesn`t it?

2016-12-22 00:05:01      Execution started.

2016-12-22 00:05:01      QVB Version                   12.0.20200.0

2016-12-22 00:05:01      CPU Target                    x64

2016-12-22 00:05:01      Operating System              Windows Server 2012 R2 Standard  (64 bit edition)

2016-12-22 00:05:01      Wow64 mode                    Not using Wow64

2016-12-22 00:05:01      Language                      0409 English (United States) English

2016-12-22 00:05:01      Country                       1 United States United States

2016-12-22 00:05:01      MDAC Version                  6.3.9600.16384

2016-12-22 00:05:01      MDAC Full Install Version     6.3.9600.16384

2016-12-22 00:05:01      PreferredCompression          2

2016-12-22 00:05:01      EnableParallelReload          1

2016-12-22 00:05:01      ParallelizeQvdLoads           1

2016-12-22 00:05:01      AutoSaveAfterReload           0

2016-12-22 00:05:01      BackupBeforeReload            0

2016-12-22 00:05:01      EnableFlushLog                0

2016-12-22 00:05:01      SaveInfoWhenSavingFile        0

2016-12-22 00:05:01      UserLogfileCharset            65001

2016-12-22 00:05:01      OdbcLoginTimeout              -1

2016-12-22 00:05:01      OdbcConnectionTimeout         -1

2016-12-22 00:05:01      ScriptWantsDbWrite            false

2016-12-22 00:05:01      ScriptWantsExe                false

2016-12-22 00:05:01      LogFile CodePage Used:        65001

2016-12-22 00:05:01      UseMemoryFillPattern          1

2016-12-22 00:05:01      ScriptMode                    Legacy (gives greater system access) (aka qv11 mode)

2016-12-22 00:05:01      ReloadCodebase                Classic

2016-12-22 00:05:01      Reload Executed By            User

2016-12-22 00:05:01      Process Executing             QVB

2016-12-22 00:05:01      Process ID                    4756

2016-12-22 02:26:11      Failed to open file in write mode for file Report.qvd

2016-12-22 02:26:11      Error: Error in hidden script. For details, open hidden script before reload.

2016-12-22 02:26:11      General Script Error

2016-12-22 02:26:11      Execution Failed

2016-12-22 02:26:11      Execution finished.

[Chip_Matejowsky]

Hi Catalin,

Yes, does make sense. Have a look at your reload schedule and ensure you don't have other jobs accessing the same QVD concurrently with this job. Also, I'd suggest that you un-hide the script for troubleshooting, as per the document log, that's where the error is occurring. I believe you'll receive more information in the document log if the script is unhidden.

- Chip