Reading NPrinting logs

[kdmarkee]

Is anyone able to explain to me why when I look at the nprinting logs (I am using DEBUG mode) and am researching a certain time or time range that I had a task running, why do I also see logging in those time frames for task that are not currently running?  There's always references to other tasks, connections, reports, users, etc that do not pertain to what nprinting is actually processing during the time I'm researching.  I already find the logs impossible to understand and this adds extra confusion/complexity.  Maybe I don't understand how nprinting works in the background or something.  Any insight would be great, thanks.

[Ruggero_Piccoli]

Hi,

Qlik NPrinting has many different log files. Which log file are you checking? 

Are you looking for errors after a specific issue?

Timestamps in the logs are in the timezone of the server and it is normal that in Debug logs there are rows also when the are not publish tasks running.

Best Regards,

Ruggero

[kdmarkee]

And it would be abnormal to see future timestamps in the log compared to current time correct?  ie, if it is 2:45pm and I see timestamps for 7:45 pm, there's a server clock issue somewhere correct?  I just want to make sure the logs do not show predicted completion times of jobs, and maybe that would explain it.  Thanks.

[Ruggero_Piccoli]

Hi,

There are not predictions on the log. The timestamps are in the time zone of the server followed by the info about the time zone. Maybe the server has a different time zone.

In any case, it is hard to understand what you mean without seeing your logs.

Best Regards,

Ruggero

[kdmarkee]

Here’s an example.  I looked at this enging log on 12/17/2020 at about T16:10 which is well before the 1900 hour on 12/17/2020 but yet I see timestamps with 7pm/1900hr in this, and that seems odd to me.  I will also mention that our NP is on a virtual machine, could be relevant maybe??

Qlik.NPrinting.Engine     20.39.3.0              Qlik.NPrinting.Engine.Consumer.EngineConsumer              20201217T134450.002-06:00     DEBUG PRDNPRINTING               0              0            0            0            0            0            0            0            Sending engine status feedback with allocation timestamp 12/17/2020 7:44:44 PM from engine e899e2d9-952a-4edf-9184-99db6d5ce536 to scheduler↓{"Properties":{"ContentType":null,"ContentEncoding":null,"Headers":{},"DeliveryMode":0,"Priority":0,"CorrelationId":null,"ReplyTo":null,"Expiration":null,"MessageId":null,"Timestamp":0,"Type":null,"UserId":null,"AppId":null,"ClusterId":null,"ContentTypePresent":false,"ContentEncodingPresent":false,"HeadersPresent":true,"DeliveryModePresent":false,"PriorityPresent":false,"CorrelationIdPresent":false,"ReplyToPresent":false,"ExpirationPresent":false,"MessageIdPresent":false,"TimestampPresent":false,"TypePresent":false,"UserIdPresent":false,"AppIdPresent":false,"ClusterIdPresent":false},"MessageType":"Qlik.NPrinting.Common.Messages.EngineAllocationStatusMessage, Qlik.NPrinting.Common, Version=20.39.3.0, Culture=neutral, PublicKeyToken=null","Body":{"EngineId":"e899e2d9-952a-4edf-9184-99db6d5ce536","Timestamp":"2020-12-17T19:44:50.0022436Z","ExpirationTimeMillis":3900,"LastAllocationMapTimestamp":"2020-12-17T19:44:44.6956472Z","ConnectionAllocations":[{"ConnectionString":"navigator=qlikview;documentpath=\"qvp://prdqlikdes2/LocalUserPublishedDocuments/kdm MAIN EOB Analytics.qvw\";identity=xxxx\\nprinting","Status":0,"StartupMillis":null,"ShutdownMillis":null,"AllocationMapTimestamp":"2020-12-17T19:06:23.7675159Z","ResolverBufferMaxSize":1,"ResolverBufferUsage":0,"ErrorMessage":null},{"ConnectionString":"navigator=qlikview;documentpath=\"qvp://prdqlikdes2/LocalUserPublishedDocuments/DMG Data.qvw\";identity=xxxx\\xxxx","Status":1,"StartupMillis":12279,"ShutdownMillis":null,"AllocationMapTimestamp":"2020-12-17T16:50:37.2931674Z","ResolverBufferMaxSize":500,"ResolverBufferUsage":500,"ErrorMessage":null},{"ConnectionString":"navigator=qlikview;documentpath=\"qvp://prdqlikdes2/LocalUserPublishedDocuments/DMG Data.qvw\";identity=xxxx\\xxxx","Status":1,"StartupMillis":13271,"ShutdownMillis":null,"AllocationMapTimestamp":"2020-12-17T16:51:57.481536Z","ResolverBufferMaxSize":154,"ResolverBufferUsage":0,"ErrorMessage":null},{"ConnectionString":"navigator=qlikview;documentpath=\"qvp://prdqlikdes2/LocalUserPublishedDocuments/DMG Data.qvw\";identity=xxxx\\xxxx","Status":1,"StartupMillis":12131,"ShutdownMillis":null,"AllocationMapTimestamp":"2020-12-17T16:51:25.418163Z","ResolverBufferMaxSize":500,"ResolverBufferUsage":440,"ErrorMessage":null},{"ConnectionString":"navigator=qlikview;documentpath=\"qvp://prdqlikdes2/LocalUserPublishedDocuments/DMG Data.qvw\";identity=xxxx\\xxxx","Status":1,"StartupMillis":12715,"ShutdownMillis":null,"AllocationMapTimestamp":"2020-12-17T16:49:33.1304108Z","ResolverBufferMaxSize":771,"ResolverBufferUsage":730,"ErrorMessage":null},{"ConnectionString":"navigator=qlikview;documentpath=\"qvp://prdqlikdes2/LocalUserPublishedDocuments/DMG Data.qvw\";identity=xxxx\\xxxx","Status":1,"StartupMillis":11634,"ShutdownMillis":null,"AllocationMapTimestamp":"2020-12-17T16:51:41.4538518Z","ResolverBufferMaxSize":460,"ResolverBufferUsage":220,"ErrorMessage":null},{"ConnectionString":"navigator=qlikview;documentpath=\"qvp://prdqlikdes2/LocalUserPublishedDocuments/DMG Data.qvw\";identity=physiciansacct\\kmarkee","Status":1,"StartupMillis":13337,"ShutdownMillis":null,"AllocationMapTimestamp":"2020-12-17T16:49:57.1834435Z","ResolverBufferMaxSize":542,"ResolverBufferUsage":500,"ErrorMessage":null},{"ConnectionString":"navigator=qlikview;documentpath=\"qvp://prdqlikdes2/LocalUserPublishedDocuments/DMG Data.qvw\";identity=xxxx\\xxxx","Status":1,"StartupMillis":12840,"ShutdownMillis":null,"AllocationMapTimestamp":"2020-12-17T16:49:01.0842464Z","ResolverBufferMaxSize":756,"ResolverBufferUsage":737,"ErrorMessage":null}]}}             

[Ruggero_Piccoli]

Hi,

This is the "engine status feedback" log that is not related with the execution of a task. It is periodic and it should be written every 8 seconds. 

The time zone is GMT-6 so maybe this could be the reason why you are reading the wrong time.

Best Regards,

Ruggero

[kdmarkee]

So GMT-6 is the default for the logs, is that what you mean?  Thanks.

[Ruggero_Piccoli]

Hi,

No. The logs use the time zone set in the Qlik NPrinting Server computer, so in your case it is set to GMT-6 based on the log you posted. So I suggest you to check the settings of the Qlik NPrinting Server and all Qlik NPrinting Engines if you have more than one on different computers than the Server.

Best Regards,

Ruggero

[kdmarkee]

Not sure what to think then, as I had our tech people confirm we are using CST (-6).  Perhaps it is a client machine then generating the oddity.

[Ruggero_Piccoli]

Hi,

If you are using GMT-6 the logs are correct because they state that.

Best Regards,

Ruggero