Reload log shows 'Execution finished' but 'Reload Failed'

[#1]

Hello,

We have a QlikView .qvw reload which runs once an hour (and has done for > 12 months). There have been no recent modifications to the .qvw. The reload itself typically runs for about 35+ minutes.

For the past three hours, it has been coughing up this fur-ball:

The task "1h Reload JDE (xx:00)" failed. Part
of the log file follows:

12.09.2012 16:01:45     Error The Source Document was NOT reloaded
successfully. DocumentPath=D:\Qlikview\Data\JDE\TWI_Extract.qvw.

12.09.2012 16:01:45     Error Reload failed.

12.09.2012 16:01:46     Error Reload failed. Distribution skipped.

12.09.2012 16:01:46     Error The task "1h Reload JDE (xx:00)"
failed. ErrorCount=3

12.09.2012 16:02:07     Error Aborting Reload. Error=QDSMain.TaskResult

12.09.2012 16:41:36     Error Reload was aborted.

12.09.2012 16:41:37     Error Reload failed.

12.09.2012 16:41:37     Error Reload failed. Distribution skipped.

12.09.2012 16:41:37     Error The task "1h Reload JDE (xx:00)"
failed. ErrorCount=4

Looking in the job's log file, it appears as if it reloaded normally to completion:

...

9/12/2012 4:41:36 PM:        4 fields found: ACCESS, NTNAME, Reporting Code 16, Reporting Code 17, 75 lines fetched

9/12/2012 4:41:36 PM: 0471  Store * from CatCode17 into CatCode17.QVD

9/12/2012 4:41:36 PM: 0472  Store * from CatCode17 into CatCode17.txt (txt)

9/12/2012 4:41:36 PM: 0475  DROP Table CatCode17

9/12/2012 4:41:36 PM:      Execution finished.

Looking at the log in QV Enterprise manager, I see this:

(2012-09-12 16:00:00) Information: Executing ClusterID=1, QDSID=521ab837-9c17-0a46-43e0-6db7b10d30e5 QDSMain.DistributeTask

(2012-09-12 16:00:00) Information: Starting task "1h Reload JDE (xx:00)" (Attempt 1 of 2)

(2012-09-12 16:00:00) Information: Max run time: 1.00:00:00

(2012-09-12 16:00:00) Information: Document is marked for refresh; Initializing Reload.

(2012-09-12 16:00:00) Information: Opening "D:\Qlikview\Data\JDE\TWI_Extract.qvw"

(2012-09-12 16:00:00) Information: Allocating QlikView Engine

(2012-09-12 16:00:30) Information: Allocating new QlikView Engine. Current usagecount=3 of 3

(2012-09-12 16:00:30) Information: An instance of the QlikView Engine is being created

(2012-09-12 16:00:30) Information: Starting QlikView Engine

(2012-09-12 16:00:31) Information: Allocated QlikView Engine successfully. Current usagecount=3 of 3, Ticket=22683

(2012-09-12 16:00:31) Information: Loading document "D:\Qlikview\Data\JDE\TWI_Extract.qvw" (0.16 Mb)

(2012-09-12 16:00:31) Information: Physical FileSize=0.16 Mb. Memory Allocation Delta for this file=4.23 Mb. Available Physical Memory Before Open=1372.21 Mb. Available Physical Memory After Open=1364.04 Mb. Total Physical Memory=8190.60 Mb.

(2012-09-12 16:00:31) Information: The document was loaded successfully.

(2012-09-12 16:00:31) Information: Initializing Checkout (0), Loading document (30750), Initializing load (30750), Checking read (30750), Creating QlikView Engine (30782), Checking Size (30813), Load (30813), Load Completed (30891), Tables read (31079), Opened successfully (31094)

(2012-09-12 16:00:31) Information: Document was opened successfully

(2012-09-12 16:00:31) Information: Opened successfully (0)

(2012-09-12 16:00:31) Information: Starting reload

(2012-09-12 16:00:31) Information: QlikView->Settings->Document Preferences->Generate Logfile in document is set. Enabling Log Copier.

(2012-09-12 16:00:31) Information: Waiting for the document log "D:\Qlikview\Data\JDE\TWI_Extract.qvw" to become available..

(2012-09-12 16:00:31) Information: The Source Document is being reloaded. DocumentPath=D:\Qlikview\Data\JDE\TWI_Extract.qvw

(2012-09-12 16:00:31) Information: Found a document log. FileName=D:\Qlikview\Data\JDE\TWI_Extract.qvw.2012_09_12_16_00_31.log

(2012-09-12 16:00:31) Information: Writing documentLog to C:\ProgramData\QlikTech\DistributionService\1\Log\20120912\160000 - 1h Reload JDE (xx_00)\DocumentLog.txt

(2012-09-12 16:00:32) Information: Reloading.

(2012-09-12 16:00:33) Information: Reloading..

(2012-09-12 16:00:34) Information: Reloading...

(2012-09-12 16:00:35) Information: Reloading....

(2012-09-12 16:00:36) Information: Reloading.....

(2012-09-12 16:00:37) Information: Reloading......

(2012-09-12 16:00:38) Information: Reloading.......

(2012-09-12 16:00:39) Information: Reloading........

(2012-09-12 16:00:40) Information: Reloading.........

(2012-09-12 16:00:41) Information: Reloading..........

(2012-09-12 16:00:42) Information: Slowing down logging. LoggingSeconds=2

(2012-09-12 16:00:42) Information: Reloading

(2012-09-12 16:00:44) Information: Reloading.

(2012-09-12 16:00:46) Information: Reloading..

(2012-09-12 16:00:48) Information: Reloading...

(2012-09-12 16:00:50) Information: Reloading....

(2012-09-12 16:00:52) Information: Reloading.....

(2012-09-12 16:00:54) Information: Reloading......

(2012-09-12 16:00:56) Information: Reloading.......

(2012-09-12 16:00:58) Information: Reloading........

(2012-09-12 16:01:00) Information: Reloading.........

(2012-09-12 16:01:02) Information: Reloading..........

(2012-09-12 16:01:04) Information: Slowing down logging. LoggingSeconds=10

(2012-09-12 16:01:04) Information: Reloading

(2012-09-12 16:01:14) Information: Reloading.

(2012-09-12 16:01:24) Information: Reloading..

(2012-09-12 16:01:34) Information: Reloading...

(2012-09-12 16:01:44) Information: Reloading....

(2012-09-12 16:01:45) Information: The Source Document reload complete. DocumentPath=D:\Qlikview\Data\JDE\TWI_Extract.qvw

(2012-09-12 16:01:45) Information: Memory Allocation Delta for this file=50.98 Mb. Available Physical Memory Before Reload=1362.61 Mb. Available Physical Memory After Reload=514.48 Mb. Total Physical Memory=514.48 Mb.

(2012-09-12 16:01:45) Error: The Source Document was NOT reloaded successfully. DocumentPath=D:\Qlikview\Data\JDE\TWI_Extract.qvw.

(2012-09-12 16:01:45) Information: Initializing Reload (0), Finished (73906)

(2012-09-12 16:01:45) Error: Reload failed.

(2012-09-12 16:01:45) Information: Closing the document.

(2012-09-12 16:01:46) Information: Closed the QlikView Engine successfully. ProcessID=5364

(2012-09-12 16:01:46) Information: Initializing (0), Finished (735)

(2012-09-12 16:01:46) Error: Reload failed. Distribution skipped.

(2012-09-12 16:01:46) Error: The task "1h Reload JDE (xx:00)" failed. ErrorCount=3

(2012-09-12 16:01:46) Information: ----------------------------------------------

(2012-09-12 16:01:46) Information: Retrying!

(2012-09-12 16:01:46) Information: Executing ClusterID=1, QDSID=521ab837-9c17-0a46-43e0-6db7b10d30e5 QDSMain.DistributeTask

(2012-09-12 16:01:46) Information: Starting task "1h Reload JDE (xx:00)" (Attempt 2 of 2)

(2012-09-12 16:01:46) Information: Max run time: 1.00:00:00

(2012-09-12 16:01:46) Information: Document is marked for refresh; Initializing Reload.

(2012-09-12 16:01:46) Information: Opening "D:\Qlikview\Data\JDE\TWI_Extract.qvw"

(2012-09-12 16:01:46) Information: Allocating QlikView Engine

(2012-09-12 16:01:48) Information: Failed to allocate new QlikView Engine. Retrying (2)! Current usagecount=3 of 3

(2012-09-12 16:02:05) Information: Allocating new QlikView Engine. Current usagecount=3 of 3

(2012-09-12 16:02:05) Information: An instance of the QlikView Engine is being created

(2012-09-12 16:02:05) Information: Starting QlikView Engine

(2012-09-12 16:02:06) Information: Allocated QlikView Engine successfully. Current usagecount=3 of 3, Ticket=22688

(2012-09-12 16:02:06) Information: Loading document "D:\Qlikview\Data\JDE\TWI_Extract.qvw" (0.16 Mb)

(2012-09-12 16:02:06) Information: Physical FileSize=0.16 Mb. Memory Allocation Delta for this file=4.28 Mb. Available Physical Memory Before Open=723.43 Mb. Available Physical Memory After Open=721.25 Mb. Total Physical Memory=8190.60 Mb.

(2012-09-12 16:02:06) Information: The document was loaded successfully.

(2012-09-12 16:02:06) Information: Initializing Checkout (0), Loading document (20407), Initializing load (20407), Checking read (20407), Creating QlikView Engine (20422), Checking Size (20422), Load (20422), Load Completed (20454), Tables read (20469), Opened successfully (20469)

(2012-09-12 16:02:06) Information: Document was opened successfully

(2012-09-12 16:02:06) Information: Opened successfully (0)

(2012-09-12 16:02:06) Information: Starting reload

(2012-09-12 16:02:06) Information: QlikView->Settings->Document Preferences->Generate Logfile in document is set. Enabling Log Copier.

(2012-09-12 16:02:06) Information: Waiting for the document log "D:\Qlikview\Data\JDE\TWI_Extract.qvw" to become available..

(2012-09-12 16:02:06) Information: The Source Document is being reloaded. DocumentPath=D:\Qlikview\Data\JDE\TWI_Extract.qvw

(2012-09-12 16:02:06) Information: Found a document log. FileName=D:\Qlikview\Data\JDE\TWI_Extract.qvw.2012_09_12_16_02_06.log

(2012-09-12 16:02:06) Information: Writing documentLog to C:\ProgramData\QlikTech\DistributionService\1\Log\20120912\160000 - 1h Reload JDE (xx_00)\DocumentLog.txt

(2012-09-12 16:02:07) Information: Reloading.

(2012-09-12 16:02:07) Error: Aborting Reload. Error=QDSMain.TaskResult

(2012-09-12 16:41:36) Error: Reload was aborted.

(2012-09-12 16:41:36) Information: Closing the document.

(2012-09-12 16:41:37) Information: Initializing Reload (0), Finished (2370422)

(2012-09-12 16:41:37) Error: Reload failed.

(2012-09-12 16:41:37) Information: Closed the QlikView Engine successfully. ProcessID=2068

(2012-09-12 16:41:37) Information: Initializing (0), Finished (0)

(2012-09-12 16:41:37) Error: Reload failed. Distribution skipped.

(2012-09-12 16:41:37) Error: The task "1h Reload JDE (xx:00)" failed. ErrorCount=4

(2012-09-12 16:41:37) Information: Sending Alert Mail to 2 recipients.

(2012-09-12 16:41:37) Information: Closed the QlikView Engine successfully. ProcessID=2068

(2012-09-12 16:41:37) Error: All retries failed.

No user aborted the reload, plus the log file indicates that it actually completed. The .qvw itself loads no data - it simply opens tables from an Oracle database and writes them to .qvd's before closing.

There is ample room both on the system's System disk as well as the data disk on which the .qvw's/.qvd's reside.

I see no relevant error messages in the system event log.

Any help welcome.

[#2]

I had the same problem a week ago.

I reimposted the reload and now is working fine. No idea if the problem will show up again though.

[#3]

True enough. I can re-run the job just after it fails and it works fine.

The maddening part: the log file shows it running to completion... normally. The job then 'fails' for some unknown reason. This causes dependent jobs to not start.

In our case, the .qvw is simply there to generate a stack of .qvd's. The .qvw itself is minimal. It's not saving/storing data per se. The 'failure' comes after the script completes and the job completes and the .qvw is closed (presumably).

I've got one word for it: aaargh. Or, in German, mühsam...

[#4]

I only very recently got the Mail Server and Alerts set up to send when there is a problem with the reload.  The task log file for the reload and the document log both show that the reload was successful, however an email saying problem with the reload is being sent!  I don't see what is triggering this alert when everything is fine.  Any thoughts on where I should look would be appreciated.

Thanks,

Lorna

[#5]

I have checked with QlikTech Support.

If you are having issue for reload success during the retrial but shows fail in publisher. It was a bug in QV 10 SR4.

[#6]

...which would imply that it's fixed in...

[#7]

According to support, it should be QV10 SR5

[Bill_Britt]

Hi David,

What is in the document log?  TWI_Extract.qvw.2012_09_12_16_02_06.log

(2012-09-12 16:02:06) Information: Found a document log. FileName=D:\Qlikview\Data\JDE\TWI_Extract.qvw.2012_09_12_16_02_06.log

(2012-09-12 16:02:06) Information: Writing documentLog to C:\ProgramData\QlikTech\DistributionService\1\Log\20120912\160000 - 1h Reload JDE (xx_00)\DocumentLog.txt

(2012-09-12 16:02:07) Information: Reloading.

(2012-09-12 16:02:07) Error: Aborting Reload. Error=QDSMain.TaskResult

Think you might find more information there.

Bill

[#9]

Yes, you would think so, but unfortunately... not so much. As stated way at the top, the log file shows that everything worked just fine. It looks exactly like the log file from the previous/subsequent log file from jobs that ran fine.

9/12/2012 4:41:36 PM:      Execution finished.

[#10]

Hello,

anybody can resolved this discution?

This problem ocurred with my client, and log´s don´t tell me nothing about this problem.

The client use QlikView 10.00.9061.7 SR3 64-bit.

Just change the version and my problem is resolved?

Great for the atention.

[Chris_Rice]

Hey Paulo,

If your issue is exactly the same as what David is describing above, then it's likely an upgrade will fix this issue.  David originally posted this in 2012, and QV has been updated quite a bit since then.  Otherwise, without logs it's difficult to tell what exactly your issue is related to or how to fix it.  If this is an ongoing issue, and upgrading does not fix the problem, I would recommend opening a case with QV Support.