Problem triggering nPrint job from QlikView QMC

[JacobT]

Hi,

We have a monthly report in nPrint that gets triggered from QlikView QMC every night at 01:00.

This started to fail from the 24:th of September, been running fine for a year before.

The job can be executed in the morning without having the issue.

No maintenance, patching or uppgrading of apps has been done close to this date.

I found errors in the applog on the QlikView server and errors in the nPrintWebEngine, see below.

Qlik.NPrinting.WebEngine 19.19.4.0 Qlik.NPrinting.WebEngine.ExceptionHandling.GenericTextExceptionHandler 20200926T010035.491+02:00 ERROR servername serviceaccount 0 0 0 0 0 0 0 0 Unhandled exception in request http://servername:4996/api/v1/tasks/88deb1eb-eb08-4ee6-a5c8-32c1edd576bd/executions. ERROR: System.AggregateException: One or more errors occurred. ---> System.TimeoutException: The operation requested on PersistentChannel timed out↓↓ at EasyNetQ.Producer.PersistentChannel.InvokeChannelAction(Action`1 channelAction)↓↓ at Qlik.NPrinting.Common.EasyNetQ.NPrintingClientCommandDispatcherThreaded.Invoke(Action`1 channelAction, CancellationToken cancellationToken) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Common\EasyNetQ\NPrintingClientCommandDispatcher.cs:line 136↓↓ at Qlik.NPrinting.Common.EasyNetQ.NPrintingClientCommandDispatcherThreaded.Invoke(Action`1 channelAction) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Common\EasyNetQ\NPrintingClientCommandDispatcher.cs:line 174↓↓ at EasyNetQ.RabbitAdvancedBus.ExchangeDeclare(String name, String type, Boolean passive, Boolean durable, Boolean autoDelete, Boolean internal, String alternateExchange, Boolean delayed)↓↓ at EasyNetQ.Producer.PublishExchangeDeclareStrategy.DeclareExchange(String exchangeName, String exchangeType)↓↓ at EasyNetQ.RabbitBus.Publish[T](T message, Action`1 configure)↓↓ at Qlik.NPrinting.WebEngine.Controllers.SchedulerClient.Publish[T](T message) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\SchedulerClient.cs:line 45↓↓ at Qlik.NPrinting.WebEngine.Controllers.SchedulerClient.RequestReschedule() in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\SchedulerClient.cs:line 34↓↓ at Qlik.NPrinting.Repo.Service.TaskExecutionService.EnqueueTask(TaskIdConfig taskConfig, SchedulingOptions schedulingOptions, Nullable`1 triggerId) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Repo\Service\TaskExecutionService.cs:line 130↓↓ at Qlik.NPrinting.Repo.Service.PublishTaskExecutionService.Run(Nullable`1 priority) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Repo\Service\PublishTaskExecutionService.cs:line 95↓↓ at Qlik.NPrinting.WebEngine.Controllers.API.ApiTasksController.<>c__DisplayClass16_0.<PostExecution>b__0(ISession s) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\API\ApiTasksController.cs:line 188↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.<>c__DisplayClass10_0`2.<WithSessionAndMapping>b__0(ISession session) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 99↓↓ at Qlik.NPrinting.Repo.Service.SessionManager.WithSession[T](Func`2 body, IsolationLevel isolationLevel, Boolean readOnly) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Repo\Service\SessionManager.cs:line 76↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.WithSessionAndMapping[TV,TD](Func`2 body, Func`2 mapper) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 97↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.WithSessionAndMapping[TV,TD](Func`2 body) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 91↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.<>c__DisplayClass8_0`2.<WithSessionAndErrorHandling>b__0() in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 80↓↓ at Qlik.NPrinting.WebEngine.Controllers.API.ApiHttpHelper.WithErrorHandling[T](HttpRequestMessage request, String nullMsg, Func`1 body, ApiCrudOperation crudOperation, String locationHeaderPath) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\API\ApiHttpHelper.cs:line 57↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.WithSessionAndErrorHandling[TV,TD](HttpRequestMessage request, String notFoundMsg, Func`2 body, TV& viewResult) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 77↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.WithSessionAndErrorHandling[TV,TD](HttpRequestMessage request, String notFoundMsg, Func`2 body) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 70↓↓ at Qlik.NPrinting.WebEngine.Controllers.API.ApiTasksController.PostExecution(String taskId, ApiTaskExecutionConfig config) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\API\ApiTasksController.cs:line 172↓↓ at lambda_method(Closure , Object , Object[] )↓↓ at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass10.<GetExecutor>b__9(Object instance, Object[] methodParameters)↓↓ at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken)↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.Controllers.ApiControllerActionInvoker.<InvokeActionAsyncCore>d__0.MoveNext()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.Controllers.ActionFilterResult.<ExecuteAsync>d__2.MoveNext()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.Filters.AuthorizationFilterAttribute.<ExecuteAuthorizationFilterAsyncCore>d__2.MoveNext()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.Dispatcher.HttpControllerDispatcher.<SendAsync>d__1.MoveNext()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Web.Http.Dispatcher.HttpControllerDispatcher.<SendAsync>d__1.MoveNext()↓↓ --- End of inner exception stack trace ---↓↓ at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)↓↓ at Qlik.NPrinting.WebEngine.Cors.NpCorsHandler.<>c__DisplayClass11_0.<SendAsync>b__1(Task`1 t) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Cors\NpCorsHandler.cs:line 112↓↓ at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()↓↓ at System.Threading.Tasks.Task.Execute()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.HttpServer.<SendAsync>d__0.MoveNext()↓↓---> (Inner Exception #0) System.TimeoutException: The operation requested on PersistentChannel timed out↓↓ at EasyNetQ.Producer.PersistentChannel.InvokeChannelAction(Action`1 channelAction)↓↓ at Qlik.NPrinting.Common.EasyNetQ.NPrintingClientCommandDispatcherThreaded.Invoke(Action`1 channelAction, CancellationToken cancellationToken) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Common\EasyNetQ\NPrintingClientCommandDispatcher.cs:line 136↓↓ at Qlik.NPrinting.Common.EasyNetQ.NPrintingClientCommandDispatcherThreaded.Invoke(Action`1 channelAction) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Common\EasyNetQ\NPrintingClientCommandDispatcher.cs:line 174↓↓ at EasyNetQ.RabbitAdvancedBus.ExchangeDeclare(String name, String type, Boolean passive, Boolean durable, Boolean autoDelete, Boolean internal, String alternateExchange, Boolean delayed)↓↓ at EasyNetQ.Producer.PublishExchangeDeclareStrategy.DeclareExchange(String exchangeName, String exchangeType)↓↓ at EasyNetQ.RabbitBus.Publish[T](T message, Action`1 configure)↓↓ at Qlik.NPrinting.WebEngine.Controllers.SchedulerClient.Publish[T](T message) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\SchedulerClient.cs:line 45↓↓ at Qlik.NPrinting.WebEngine.Controllers.SchedulerClient.RequestReschedule() in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\SchedulerClient.cs:line 34↓↓ at Qlik.NPrinting.Repo.Service.TaskExecutionService.EnqueueTask(TaskIdConfig taskConfig, SchedulingOptions schedulingOptions, Nullable`1 triggerId) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Repo\Service\TaskExecutionService.cs:line 130↓↓ at Qlik.NPrinting.Repo.Service.PublishTaskExecutionService.Run(Nullable`1 priority) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Repo\Service\PublishTaskExecutionService.cs:line 95↓↓ at Qlik.NPrinting.WebEngine.Controllers.API.ApiTasksController.<>c__DisplayClass16_0.<PostExecution>b__0(ISession s) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\API\ApiTasksController.cs:line 188↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.<>c__DisplayClass10_0`2.<WithSessionAndMapping>b__0(ISession session) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 99↓↓ at Qlik.NPrinting.Repo.Service.SessionManager.WithSession[T](Func`2 body, IsolationLevel isolationLevel, Boolean readOnly) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\Repo\Service\SessionManager.cs:line 76↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.WithSessionAndMapping[TV,TD](Func`2 body, Func`2 mapper) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 97↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.WithSessionAndMapping[TV,TD](Func`2 body) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 91↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.<>c__DisplayClass8_0`2.<WithSessionAndErrorHandling>b__0() in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 80↓↓ at Qlik.NPrinting.WebEngine.Controllers.API.ApiHttpHelper.WithErrorHandling[T](HttpRequestMessage request, String nullMsg, Func`1 body, ApiCrudOperation crudOperation, String locationHeaderPath) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\API\ApiHttpHelper.cs:line 57↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.WithSessionAndErrorHandling[TV,TD](HttpRequestMessage request, String notFoundMsg, Func`2 body, TV& viewResult) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 77↓↓ at Qlik.NPrinting.WebEngine.Controllers.HttpHelper.WithSessionAndErrorHandling[TV,TD](HttpRequestMessage request, String notFoundMsg, Func`2 body) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\HttpHelper.cs:line 70↓↓ at Qlik.NPrinting.WebEngine.Controllers.API.ApiTasksController.PostExecution(String taskId, ApiTaskExecutionConfig config) in C:\Jws\release-19.19.x-NOvyT9XXE\server\NPrinting\src\WebEngine\Controllers\API\ApiTasksController.cs:line 172↓↓ at lambda_method(Closure , Object , Object[] )↓↓ at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass10.<GetExecutor>b__9(Object instance, Object[] methodParameters)↓↓ at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken)↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.Controllers.ApiControllerActionInvoker.<InvokeActionAsyncCore>d__0.MoveNext()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.Controllers.ActionFilterResult.<ExecuteAsync>d__2.MoveNext()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.Filters.AuthorizationFilterAttribute.<ExecuteAuthorizationFilterAsyncCore>d__2.MoveNext()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)↓↓ at System.Web.Http.Dispatcher.HttpControllerDispatcher.<SendAsync>d__1.MoveNext()↓↓--- End of stack trace from previous location where exception was thrown ---↓↓ at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()↓↓ at System.Web.Http.Dispatcher.HttpControllerDispatcher.<SendAsync>d__1.MoveNext()<---

and from the applog: 

2020-09-30 01:00:08 0042 sql SELECT "__KEY_data" FROM JSON (wrap off) "data" PK "__KEY_data" WITH CONNECTION( URL "https://severname:4993/api/v1/tasks/88deb1eb-eb08-4ee6-a5c8-32c1edd576bd/executions", HTTPHEADER "cookie" "NPWEBCONSOLE_SESSION=a1d807107becfd2ffbce5fbf8dbd4b00b0888c4f-%00NPWEBCONSOLE_XSRF-TOKEN%3AXOBJibft5BEr90WCaxTMVTwX8caHrG726lzDIFikiiw%3D%00%00_TS%3Asession%00%00userid%3Abf1a5433187e47d68e2306f81d910dd0%00%00userlogin%3A2020-09-29T23%3A00%3A06.4993513Z%00; ")
2020-09-30 01:00:35 2 fields found: __KEY_data, __extra_,
2020-09-30 01:00:35 Error: HTTP protocol error 500 (Internal Server Error):

Nothing in the Windows Event Viewer logs that would poin on the egine beeing down or simular. No other jobs run at this time either.

Any idéas what could cause this reoccuring problem out of nowhere?

[Lech_Miszkiewicz]

Hi Jacob,

Lets structure your post little bit and set some facts:

• Version of NPrinting: June 2019 (which patch?)
• Version of QlikView?
• Version of RestConnector
• Are NPrinting and QlikView installed on separate servers?
• This happens at night but in the morning the same report can run without issues, is that right?
• Specs of both machines (Hardware RAM and CPU + is there enough disk space on both servers)
• What connection is used in this NPrinting report (Local or QVP)
• Can you take us through what is reload of qvw doing, as in which API endpoint you are calling in what order and in what intervals? Seems like you are not using my library NPrinting.qvs for this
• Does this report run straight after qvw app is reloaded? Do you allow enough time by using Sleep() function in your API call script for qvw to be saved properly, and in case it is QVP connection for load to the server?
• Did you change attached logfiles. I see http and https calls, also server names seem to be amended - therefore it is hard to trust those logs without knowing what was changed?
• What are the resources on the server at the time when error appears (maybe you are running out of memory, maybe another reload is running at the same time, maybe there is simply too much going on?),

What is the error visible in the NPrinting execution section? Does this task start at all? Looks like it does not.  We would need to know full picture on what is this script going through, whether it authenticates properly, which steps are successful and which ones are not. What we have is not enough to come to any conclusion. Your errors are little bit misleading.. It almost seems like the user used to run this task and configured in a RESTAPI for login is not logged on properly and cannot execute task.