Sporadically error when cached version is not available

OL Connect Enterprise Workflow
1

Hello,

We have a data mapper that contains scripting. This scripting calls JSON files located at another location. At times, the service crashes with an error.

We have the impression that it happens when the respective form is not used for an extended period (a few hours). When the form is then submitted, an error occurs, causing the service to stop. If we restart the service and submit the document again, it is processed correctly.

Service: Pres Connect Service.
Snippet of the log:
WARN: 15:57:08.505 [0037] Cached version not available, attempting to upload the file.
WARN: 15:57:09.053 [0038] Cached version not available, attempting to upload the file.
ERROR: 15:57:10.265 [0038] W3001: Error while executing plugin: Socket Error #10054
Connection reset by peer
ERROR: 15:57:10.265 [0038] 1: Error in content creation
A little later follows:
ERROR: 15:57:12.515 [0043] W3001: Error while executing plugin: Socket Error #10061

Given the response in: Cached version not available message - General - Upland OL User community it seems that refilling the cache may lead to problems. We cannot test this thoroughly because it occurs sporadically. Also, stopping and starting services does not immediately result in an error. How can we determine the exact cause of the error?

Kind regards,

Freek Zomer
Nedasco BV

2

Hello @zomer,

First of all, welcome to our online community!

Concerning the issue at hand I would recommend you to submit a ticket via our support portal and attach the following logs to the ticket so that we can investigate these logs:

  • PlanetPress Watch: C:\ProgramData\Objectif Lune\PlanetPress Workflow 8\PlanetPress Watch\Log\ppw[Date].log
  • Merge Engine: C:\Users\[Username]\Connect\logs\Mergeengine\Mergeengine-[Date]-([ID]).log
  • Server: C:\Users\[Username]\Connect\logs\Server\Server-[Date]-([ID]).log
3

It seems that too much log information was being written when an error occurred. By no longer writing its own logs to the designer’s logger, the issue seems to be resolved. We will continue to monitor the situation.

4

The problem persists. We thought that excessive logging might be an issue. But since the problem occurs sporadically, it seemed as if it had been resolved.

The problem is as follows:
We introduced a new template/datamapper. These are currently being tested, and we noticed that, for example, after a weekend, when processing the very first input file, the presconnect service would crash. If you offer the same document again after restarting the service, it is handled perfectly without any problems. Because it (sometimes) only happens after the template has not been accessed for some time (weekend?) and then only fails on the very first processing of that type of document, it must have something to do with loading this datamapper and template. We also see that the datamapper is successfully loaded but that the problem occurs when processing the template. However, this does not always happen. Due to this uncertainty, we still cannot move to production. Meanwhile, we have set the log to maximum, but even there, we do not gain much insight.

In the MergeEngine log, for example, it states:
[2024-04-03 08:21:12,281] INFO [IPC Input] com.objectiflune.contentcreation.mergeengine.product.internal.MergeEngineCommandProcessor.a(MergeEngineCommandProcessor.java) PROGRESS: 1 (Cc_118)
[2024-04-03 08:21:14,569] INFO [Thread-6] com.objectiflune.core.runtime.OLPlatform.run(d.java) Parent connection lost, shutting down (Core_1270)
and when it goes well:
[2024-04-03 09:35:23,662] INFO [IPC Input] com.objectiflune.contentcreation.mergeengine.product.internal.MergeEngineCommandProcessor.a(MergeEngineCommandProcessor.java) PROGRESS: 1 (Cc_118)
[2024-04-03 09:35:28,133] INFO [main] com.objectiflune.contentcreation.mergeengine.product.internal.MergeEngineCommandProcessor.a(MergeEngineCommandProcessor.java) PROGRESS: 50 (Cc_118)

The PPw log then shows:
WARN: 08:21:09.198 [0038] Cached version not available, attempting to upload file.
DEBUG: 08:21:09.216 [0038] Template C:\ProgramData\Objectif Lune\PlanetPress Workflow 8\PlanetPress Watch\OLConnect\Template\XPOL1.ol-template uploaded to the server
DEBUG: 08:21:09.216 [0038] Starting content creation operation…
DEBUG: 08:21:09.263 [0038] [2024-04-03 08:21:09.263] Print content creation> Retrieving results
ERROR: 08:21:14.569 [0038] W3001: Error while executing plugin: Socket Error # 10054

As far as we can see, without further indication, the connection is lost, and the service is stopped. Of course, we have many other types of forms, and they all work as they should. The difference with this form is that the template contains JavaScript that refers, among other things, to JSON files on disk. It is also noticeable that after a period of not using this template, it only fails on the very first attempt. We know that there is a clean script running and suspect that this template needs to be reloaded. It seems as if a timeout occurs, but without proper logging, it cannot be proven. When the service is then restarted, it works again, and the same document is processed without errors. It seems then as if everything is correctly loaded.

Has anyone experienced this before or can provide a hint on how we can solve this problem?

5

And what about the Server logs? Are there any warning or error messages being logged in the Server logs?

6

Hello Marten,

Server.log

[2024-04-03 08:21:06,545] INFO [DM-1220858722] com.objectiflune.serverengine.rest.workflow.DataMiningRestService.call(f.java) Starting Datamapping (Se_508)
[2024-04-03 08:21:06,564] INFO [DM-1643599255] com.objectiflune.scheduling.TaskScheduler.allocatePlugins(TaskScheduler.java) Request for engine added to the end of queue: JobSummary [jobId=84e629b4-0496-4013-8794-a86521cfa2af, configClass=class com.objectiflune.core.config.RemoteDataminingStreamConfig, size=1, explicitInstances=1, callback=null, extraEnginesOperation=null] (Core_8425)
[2024-04-03 08:21:06,564] INFO [Data Mapping - Job Queue Processor] com.objectiflune.scheduling.EngineAssignmentProcessor.a(EngineAssignmentProcessor.java) Assigning a867-790f-0000-02a2:2456 to JobSummary [jobId=84e629b4-0496-4013-8794-a86521cfa2af, configClass=class com.objectiflune.core.config.RemoteDataminingStreamConfig, size=1, explicitInstances=1, callback=null, extraEnginesOperation=null] (Core_8459)
[2024-04-03 08:21:09,024] INFO [DM-1643599255] com.objectiflune.scheduling.TaskScheduler.releasePlugin(TaskScheduler.java) Releasing plugin com.objectiflune.core.config.RemoteDataminingStreamConfig: a867-790f-0000-02a2:2456 (Core_8420)
[2024-04-03 08:21:09,024] INFO [DM-1643599255] com.objectiflune.datamining.dmengine.remote.DataminingExecuteOperation.execute(DataminingExecuteOperation.java) Execute DataMapper engine took: 00:00:02.460 (Dm_1707)
[2024-04-03 08:21:09,024] INFO [DM-1643599255] com.objectiflune.serverengine.rest.workflow.DataMiningRestService.call(f.java) Datamapping took: 00:00:02.479 (Se_509)
[2024-04-03 08:21:09,275] INFO [CC-999048425] com.objectiflune.serverengine.rest.workflow.ContentCreationRestService.b(ContentCreationRestService.java) Starting Content creation (Se_508)
[2024-04-03 08:21:09,286] INFO [CC-1246062075] com.objectiflune.scheduling.TaskScheduler.allocatePlugins(TaskScheduler.java) Request for engine added to the end of queue: JobSummary [jobId=5c1d46b3-6dea-4ac4-977e-6caddc8343f8, configClass=class com.objectiflune.core.config.ContentCreationConfig, size=2, explicitInstances=2147483647, callback=null, extraEnginesOperation=com.objectiflune.contentcreation.mergeengine.remote.ContentCreationOperation@4a4565fb] (Core_8425)
[2024-04-03 08:21:09,287] INFO [Content Creation - Job Queue Processor] com.objectiflune.scheduling.EngineAssignmentProcessor.a(EngineAssignmentProcessor.java) Assigning a867-790f-0000-02a2:11296 to JobSummary [jobId=5c1d46b3-6dea-4ac4-977e-6caddc8343f8, configClass=class com.objectiflune.core.config.ContentCreationConfig, size=2, explicitInstances=2147483647, callback=null, extraEnginesOperation=com.objectiflune.contentcreation.mergeengine.remote.ContentCreationOperation@4a4565fb] (Core_8459)

And then the log stops. And after restarting the service, a new log file is created.

7

I would still recommend to open a ticket via our support portal as I assume that this needs to be examined further to find out what is causing this issue.