topic Re: Reading NPrinting logs in Qlik NPrinting

Reading NPrinting logs

kdmarkee — Thu, 17 Dec 2020 15:48:36 GMT

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.

Re: Reading NPrinting logs

Ruggero_Piccoli — Thu, 17 Dec 2020 16:14:27 GMT

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

Re: Reading NPrinting logs

kdmarkee — Thu, 17 Dec 2020 21:39:46 GMT

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.

Re: Reading NPrinting logs

Ruggero_Piccoli — Fri, 18 Dec 2020 09:01:55 GMT

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

Re: Reading NPrinting logs

kdmarkee — Fri, 18 Dec 2020 19:28:18 GMT

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}]}}

Re: Reading NPrinting logs

Ruggero_Piccoli — Mon, 21 Dec 2020 14:07:50 GMT

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

Re: Reading NPrinting logs

kdmarkee — Tue, 22 Dec 2020 19:34:36 GMT

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

Re: Reading NPrinting logs

Ruggero_Piccoli — Wed, 23 Dec 2020 08:09:11 GMT

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

Re: Reading NPrinting logs

kdmarkee — Wed, 23 Dec 2020 17:12:02 GMT

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.

Re: Reading NPrinting logs

Ruggero_Piccoli — Thu, 07 Jan 2021 15:12:58 GMT

Hi,

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

Best Regards,

Ruggero