3. unoconv pdf conversion having problems with simultaneous requests

unoconv pdf conversion having problems with simultaneous requests

  • A

    Hi,
    We use docx quite a lot of docx templates which need to be converted to PDF, so we use the unoconv with pdf format for this.
    Recently I discovered a problem when generating multiple reports of the same request simultaneously. We have some async code which generates 1-10 simulateneous requests for the same template.

    Below are the logs of such a scenario, in this case we made 7 simultaneous reqeusts:

    2023-10-31T15:07:39.398Z - info: Render request 33 queued for execution and waiting for available worker rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.399Z - warn: Failed persist profile Cannot read properties of undefined (reading 'toString') stack=TypeError: Cannot read properties of undefined (reading 'toString')
    at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-authorization/lib/modificationListeners.js:33:90)
    at ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:32)
    at async Object.insert (/app/node_modules/@jsreport/jsreport-core/lib/main/store/collection.js:141:5)
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:184:7
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:63:11
2023-10-31T15:07:39.400Z - info: Render request 34 queued for execution and waiting for available worker rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.401Z - warn: Failed persist profile Cannot read properties of undefined (reading 'toString') stack=TypeError: Cannot read properties of undefined (reading 'toString')
    at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-authorization/lib/modificationListeners.js:33:90)
    at ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:32)
    at async Object.insert (/app/node_modules/@jsreport/jsreport-core/lib/main/store/collection.js:141:5)
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:184:7
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:63:11
2023-10-31T15:07:39.401Z - info: Render request 35 queued for execution and waiting for available worker rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:39.402Z - warn: Failed persist profile Cannot read properties of undefined (reading 'toString') stack=TypeError: Cannot read properties of undefined (reading 'toString')
    at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-authorization/lib/modificationListeners.js:33:90)
    at ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:32)
    at async Object.insert (/app/node_modules/@jsreport/jsreport-core/lib/main/store/collection.js:141:5)
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:184:7
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:63:11
2023-10-31T15:07:39.430Z - info: Render request 36 queued for execution and waiting for available worker rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:39.432Z - warn: Failed persist profile Cannot read properties of undefined (reading 'toString') stack=TypeError: Cannot read properties of undefined (reading 'toString')
    at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-authorization/lib/modificationListeners.js:33:90)
    at ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:32)
    at async Object.insert (/app/node_modules/@jsreport/jsreport-core/lib/main/store/collection.js:141:5)
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:184:7
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:63:11
2023-10-31T15:07:39.461Z - info: Starting rendering request 33 (user: :group/Clients/service-account) rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.461Z - info: Rendering template { name: PDF-nl, recipe: docx, engine: handlebars, preview: false } rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.463Z - info: Render request 37 queued for execution and waiting for available worker rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:39.464Z - warn: Failed persist profile Cannot read properties of undefined (reading 'toString') stack=TypeError: Cannot read properties of undefined (reading 'toString')
    at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-authorization/lib/modificationListeners.js:33:90)
    at ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:32)
    at async Object.insert (/app/node_modules/@jsreport/jsreport-core/lib/main/store/collection.js:141:5)
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:184:7
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:63:11
2023-10-31T15:07:39.465Z - info: Starting rendering request 34 (user: :group/Clients/service-account) rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.465Z - info: Rendering template { name: PDF-nl, recipe: docx, engine: handlebars, preview: false } rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.465Z - debug: Inline data specified. rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.467Z - debug: Base url not specified, skipping its injection. rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.467Z - debug: Rendering engine handlebars rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.486Z - debug: Token auth in authorization server was validated correctly
2023-10-31T15:07:39.487Z - debug: API logging in user :group/Clients/service-account
2023-10-31T15:07:39.490Z - debug: Token auth in authorization server was validated correctly
2023-10-31T15:07:39.490Z - debug: API logging in user :group/Clients/service-account
2023-10-31T15:07:39.500Z - info: Render request 38 queued for execution and waiting for available worker rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:39.501Z - warn: Failed persist profile Cannot read properties of undefined (reading 'toString') stack=TypeError: Cannot read properties of undefined (reading 'toString')
    at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-authorization/lib/modificationListeners.js:33:90)
    at ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:32)
    at async Object.insert (/app/node_modules/@jsreport/jsreport-core/lib/main/store/collection.js:141:5)
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:184:7
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:63:11
2023-10-31T15:07:39.502Z - info: Render request 39 queued for execution and waiting for available worker rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:39.503Z - warn: Failed persist profile Cannot read properties of undefined (reading 'toString') stack=TypeError: Cannot read properties of undefined (reading 'toString')
    at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-authorization/lib/modificationListeners.js:33:90)
    at ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:32)
    at async Object.insert (/app/node_modules/@jsreport/jsreport-core/lib/main/store/collection.js:141:5)
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:184:7
    at async /app/node_modules/@jsreport/jsreport-core/lib/main/profiler.js:63:11
2023-10-31T15:07:39.504Z - debug: Inline data specified. rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.504Z - debug: Base url not specified, skipping its injection. rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.505Z - debug: Rendering engine handlebars rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.600Z - debug: Executing recipe docx rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.601Z - info: docx generation is starting rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.601Z - debug: Starting child request to render docx dynamic parts rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.601Z - info: Starting rendering (child) request (user: :group/Clients/service-account) rootId=olpqs2f2xpb47b4, id=t6w36l9pnmhn00p
2023-10-31T15:07:39.602Z - info: Rendering anonymous template { recipe: html, engine: handlebars } rootId=olpqs2f2xpb47b4, id=t6w36l9pnmhn00p
2023-10-31T15:07:39.602Z - debug: Inline data specified. rootId=olpqs2f2xpb47b4, id=t6w36l9pnmhn00p
2023-10-31T15:07:39.608Z - debug: Base url not specified, skipping its injection. rootId=olpqs2f2xpb47b4, id=t6w36l9pnmhn00p
2023-10-31T15:07:39.608Z - debug: Rendering engine handlebars rootId=olpqs2f2xpb47b4, id=t6w36l9pnmhn00p
2023-10-31T15:07:39.629Z - debug: Executing recipe docx rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.630Z - info: docx generation is starting rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.630Z - debug: Starting child request to render docx dynamic parts rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.630Z - info: Starting rendering (child) request (user: :group/Clients/service-account) rootId=6f0hkmepfq04xet, id=uxhchxjryajrqbv
2023-10-31T15:07:39.630Z - info: Rendering anonymous template { recipe: html, engine: handlebars } rootId=6f0hkmepfq04xet, id=uxhchxjryajrqbv
2023-10-31T15:07:39.631Z - debug: Inline data specified. rootId=6f0hkmepfq04xet, id=uxhchxjryajrqbv
2023-10-31T15:07:39.634Z - debug: Base url not specified, skipping its injection. rootId=6f0hkmepfq04xet, id=uxhchxjryajrqbv
2023-10-31T15:07:39.634Z - debug: Rendering engine handlebars rootId=6f0hkmepfq04xet, id=uxhchxjryajrqbv
2023-10-31T15:07:39.692Z - debug: Executing recipe html rootId=olpqs2f2xpb47b4, id=t6w36l9pnmhn00p
2023-10-31T15:07:39.693Z - debug: Skipping storing report. rootId=olpqs2f2xpb47b4, id=t6w36l9pnmhn00p
2023-10-31T15:07:39.693Z - info: Rendering (child) request finished in 237 ms rootId=olpqs2f2xpb47b4, id=t6w36l9pnmhn00p
2023-10-31T15:07:39.735Z - debug: Executing recipe html rootId=6f0hkmepfq04xet, id=uxhchxjryajrqbv
2023-10-31T15:07:39.736Z - debug: Skipping storing report. rootId=6f0hkmepfq04xet, id=uxhchxjryajrqbv
2023-10-31T15:07:39.736Z - info: Rendering (child) request finished in 275 ms rootId=6f0hkmepfq04xet, id=uxhchxjryajrqbv
2023-10-31T15:07:39.794Z - info: docx generation was finished rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.795Z - debug: Executing unoconv commmand unoconv -f pdf /tmp/jsreport/autocleanup/61fbe122-0be1-423a-88b1-759582177c31.docx rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:39.833Z - info: docx generation was finished rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:39.834Z - debug: Executing unoconv commmand unoconv -f pdf /tmp/jsreport/autocleanup/9c1d9407-05c2-456a-9191-54ca7a79f6a6.docx rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:40.531Z - warn: Error when processing render request 33
(because) error while executing unoconv
(because) command failed: unoconv -f pdf /tmp/jsreport/autocleanup/9c1d9407-05c2-456a-9191-54ca7a79f6a6.docx
Error: Unable to connect or start own listener. Aborting.

Error: Command failed: unoconv -f pdf /tmp/jsreport/autocleanup/9c1d9407-05c2-456a-9191-54ca7a79f6a6.docx
Error: Unable to connect or start own listener. Aborting.

  at ChildProcess.exithandler (node:child_process:419:12)
  at ChildProcess.emit (node:events:514:28)
  at maybeClose (node:internal/child_process:1091:16)
  at ChildProcess._handle.onexit (node:internal/child_process:302:5)
wrapped by:
Error: Error while executing unoconv
(because) command failed: unoconv -f pdf /tmp/jsreport/autocleanup/9c1d9407-05c2-456a-9191-54ca7a79f6a6.docx
Error: Unable to connect or start own listener. Aborting.

  at module.exports (/app/node_modules/@jsreport/jsreport-core/lib/shared/createError.js:10:13)
  at WorkerReporter.createError (/app/node_modules/@jsreport/jsreport-core/lib/shared/reporter.js:49:12)
  at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-unoconv/lib/worker.js:46:22)
  at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
  at async ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:21)
  at async afterRender (/app/node_modules/@jsreport/jsreport-core/lib/worker/render/render.js:103:5)
  at async WorkerReporter._render (/app/node_modules/@jsreport/jsreport-core/lib/worker/render/render.js:148:7)
  at async /app/node_modules/@jsreport/jsreport-core/lib/worker/reporter.js:224:19
  at async processAndResponse (/app/node_modules/@jsreport/advanced-workers/lib/workerHandler.js:41:17) rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:40.531Z - warn: Rendering request 33 finished with error in 1152 ms rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet
2023-10-31T15:07:40.533Z - warn: Error during processing request at http://localhost:8506/api/report
2023-10-31T15:07:40.576Z - info: Starting rendering request 35 (user: :group/Clients/service-account) rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.576Z - info: Rendering template { name: PDF-nl, recipe: docx, engine: handlebars, preview: false } rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.576Z - debug: Inline data specified. rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.576Z - debug: Base url not specified, skipping its injection. rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.577Z - debug: Rendering engine handlebars rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.684Z - debug: Executing recipe docx rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.684Z - info: docx generation is starting rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.685Z - debug: Starting child request to render docx dynamic parts rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.685Z - info: Starting rendering (child) request (user: :group/Clients/service-account) rootId=l9cw7wdxg52lhi4, id=blyn2avor7iuqr3
2023-10-31T15:07:40.685Z - info: Rendering anonymous template { recipe: html, engine: handlebars } rootId=l9cw7wdxg52lhi4, id=blyn2avor7iuqr3
2023-10-31T15:07:40.685Z - debug: Inline data specified. rootId=l9cw7wdxg52lhi4, id=blyn2avor7iuqr3
2023-10-31T15:07:40.688Z - debug: Base url not specified, skipping its injection. rootId=l9cw7wdxg52lhi4, id=blyn2avor7iuqr3
2023-10-31T15:07:40.688Z - debug: Rendering engine handlebars rootId=l9cw7wdxg52lhi4, id=blyn2avor7iuqr3
2023-10-31T15:07:40.809Z - debug: Executing recipe html rootId=l9cw7wdxg52lhi4, id=blyn2avor7iuqr3
2023-10-31T15:07:40.810Z - debug: Skipping storing report. rootId=l9cw7wdxg52lhi4, id=blyn2avor7iuqr3
2023-10-31T15:07:40.810Z - info: Rendering (child) request finished in 1311 ms rootId=l9cw7wdxg52lhi4, id=blyn2avor7iuqr3
2023-10-31T15:07:40.811Z - info: docx generation was finished rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.811Z - debug: Executing unoconv commmand unoconv -f pdf /tmp/jsreport/autocleanup/0c6c5fe3-2dd0-41d8-a086-85b540c12abf.docx rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:40.929Z - debug: Skipping storing report. rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:40.929Z - info: Rendering request 34 finished in 1543 ms rootId=olpqs2f2xpb47b4, id=olpqs2f2xpb47b4
2023-10-31T15:07:40.971Z - info: Starting rendering request 36 (user: :group/Clients/service-account) rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:40.972Z - info: Rendering template { name: PDF-nl, recipe: docx, engine: handlebars, preview: false } rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:40.972Z - debug: Inline data specified. rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:40.972Z - debug: Base url not specified, skipping its injection. rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:40.972Z - debug: Rendering engine handlebars rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:40.995Z - debug: Executing recipe docx rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:40.996Z - info: docx generation is starting rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:41.067Z - debug: Starting child request to render docx dynamic parts rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:41.067Z - info: Starting rendering (child) request (user: :group/Clients/service-account) rootId=jsulq82hmxkm2ak, id=vjelvi6d85dkqgm
2023-10-31T15:07:41.067Z - info: Rendering anonymous template { recipe: html, engine: handlebars } rootId=jsulq82hmxkm2ak, id=vjelvi6d85dkqgm
2023-10-31T15:07:41.067Z - debug: Inline data specified. rootId=jsulq82hmxkm2ak, id=vjelvi6d85dkqgm
2023-10-31T15:07:41.067Z - debug: Base url not specified, skipping its injection. rootId=jsulq82hmxkm2ak, id=vjelvi6d85dkqgm
2023-10-31T15:07:41.069Z - debug: Rendering engine handlebars rootId=jsulq82hmxkm2ak, id=vjelvi6d85dkqgm
2023-10-31T15:07:41.121Z - debug: Executing recipe html rootId=jsulq82hmxkm2ak, id=vjelvi6d85dkqgm
2023-10-31T15:07:41.121Z - debug: Skipping storing report. rootId=jsulq82hmxkm2ak, id=vjelvi6d85dkqgm
2023-10-31T15:07:41.121Z - info: Rendering (child) request finished in 1659 ms rootId=jsulq82hmxkm2ak, id=vjelvi6d85dkqgm
2023-10-31T15:07:41.222Z - info: docx generation was finished rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:41.223Z - debug: Executing unoconv commmand unoconv -f pdf /tmp/jsreport/autocleanup/38800ad4-3ed6-445b-ac66-42bac514014f.docx rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:41.589Z - debug: Skipping storing report. rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:41.590Z - info: Rendering request 36 finished in 2163 ms rootId=jsulq82hmxkm2ak, id=jsulq82hmxkm2ak
2023-10-31T15:07:41.624Z - info: Starting rendering request 37 (user: :group/Clients/service-account) rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.625Z - info: Rendering template { name: PDF-nl, recipe: docx, engine: handlebars, preview: false } rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.625Z - debug: Inline data specified. rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.643Z - debug: Base url not specified, skipping its injection. rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.644Z - debug: Rendering engine handlebars rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.750Z - debug: Executing recipe docx rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.750Z - info: docx generation is starting rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.750Z - debug: Starting child request to render docx dynamic parts rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.750Z - info: Starting rendering (child) request (user: :group/Clients/service-account) rootId=zj1tibf8bnv1x46, id=amjvycqs5tddz23
2023-10-31T15:07:41.750Z - info: Rendering anonymous template { recipe: html, engine: handlebars } rootId=zj1tibf8bnv1x46, id=amjvycqs5tddz23
2023-10-31T15:07:41.751Z - debug: Inline data specified. rootId=zj1tibf8bnv1x46, id=amjvycqs5tddz23
2023-10-31T15:07:41.754Z - debug: Base url not specified, skipping its injection. rootId=zj1tibf8bnv1x46, id=amjvycqs5tddz23
2023-10-31T15:07:41.754Z - debug: Rendering engine handlebars rootId=zj1tibf8bnv1x46, id=amjvycqs5tddz23
2023-10-31T15:07:41.869Z - debug: Skipping storing report. rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:41.869Z - info: Rendering request 35 finished in 2476 ms rootId=l9cw7wdxg52lhi4, id=l9cw7wdxg52lhi4
2023-10-31T15:07:41.876Z - debug: Executing recipe html rootId=zj1tibf8bnv1x46, id=amjvycqs5tddz23
2023-10-31T15:07:41.876Z - debug: Skipping storing report. rootId=zj1tibf8bnv1x46, id=amjvycqs5tddz23
2023-10-31T15:07:41.876Z - info: Rendering (child) request finished in 2310 ms rootId=zj1tibf8bnv1x46, id=amjvycqs5tddz23
2023-10-31T15:07:41.876Z - info: docx generation was finished rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.876Z - debug: Executing unoconv commmand unoconv -f pdf /tmp/jsreport/autocleanup/fcf591c8-3b18-4669-9408-6209a86bed61.docx rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:41.912Z - info: Starting rendering request 38 (user: :group/Clients/service-account) rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:41.913Z - info: Rendering template { name: PDF-nl, recipe: docx, engine: handlebars, preview: false } rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:41.914Z - debug: Inline data specified. rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:41.919Z - debug: Base url not specified, skipping its injection. rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:41.919Z - debug: Rendering engine handlebars rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:42.007Z - debug: Executing recipe docx rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:42.007Z - info: docx generation is starting rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:42.007Z - debug: Starting child request to render docx dynamic parts rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:42.007Z - info: Starting rendering (child) request (user: :group/Clients/service-account) rootId=tfj1360ad0ufn0c, id=ctfh53ftfqbcfi5
2023-10-31T15:07:42.008Z - info: Rendering anonymous template { recipe: html, engine: handlebars } rootId=tfj1360ad0ufn0c, id=ctfh53ftfqbcfi5
2023-10-31T15:07:42.008Z - debug: Inline data specified. rootId=tfj1360ad0ufn0c, id=ctfh53ftfqbcfi5
2023-10-31T15:07:42.008Z - debug: Base url not specified, skipping its injection. rootId=tfj1360ad0ufn0c, id=ctfh53ftfqbcfi5
2023-10-31T15:07:42.008Z - debug: Rendering engine handlebars rootId=tfj1360ad0ufn0c, id=ctfh53ftfqbcfi5
2023-10-31T15:07:42.121Z - debug: Executing recipe html rootId=tfj1360ad0ufn0c, id=ctfh53ftfqbcfi5
2023-10-31T15:07:42.122Z - debug: Skipping storing report. rootId=tfj1360ad0ufn0c, id=ctfh53ftfqbcfi5
2023-10-31T15:07:42.122Z - info: Rendering (child) request finished in 2535 ms rootId=tfj1360ad0ufn0c, id=ctfh53ftfqbcfi5
2023-10-31T15:07:42.122Z - info: docx generation was finished rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:42.122Z - debug: Executing unoconv commmand unoconv -f pdf /tmp/jsreport/autocleanup/515d6fb0-60bd-48ef-b2a1-d3c31fa77fe0.docx rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:42.487Z - debug: Skipping storing report. rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:42.487Z - info: Rendering request 38 finished in 2999 ms rootId=tfj1360ad0ufn0c, id=tfj1360ad0ufn0c
2023-10-31T15:07:42.520Z - info: Starting rendering request 39 (user: :group/Clients/service-account) rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.520Z - info: Rendering template { name: PDF-nl, recipe: docx, engine: handlebars, preview: false } rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.520Z - debug: Inline data specified. rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.520Z - debug: Base url not specified, skipping its injection. rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.520Z - debug: Rendering engine handlebars rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.622Z - debug: Executing recipe docx rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.623Z - info: docx generation is starting rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.623Z - debug: Starting child request to render docx dynamic parts rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.623Z - info: Starting rendering (child) request (user: :group/Clients/service-account) rootId=40awjagj02kfdmn, id=kew5i5egdruzv8f
2023-10-31T15:07:42.623Z - info: Rendering anonymous template { recipe: html, engine: handlebars } rootId=40awjagj02kfdmn, id=kew5i5egdruzv8f
2023-10-31T15:07:42.623Z - debug: Inline data specified. rootId=40awjagj02kfdmn, id=kew5i5egdruzv8f
2023-10-31T15:07:42.623Z - debug: Base url not specified, skipping its injection. rootId=40awjagj02kfdmn, id=kew5i5egdruzv8f
2023-10-31T15:07:42.624Z - debug: Rendering engine handlebars rootId=40awjagj02kfdmn, id=kew5i5egdruzv8f
2023-10-31T15:07:42.733Z - debug: Executing recipe html rootId=40awjagj02kfdmn, id=kew5i5egdruzv8f
2023-10-31T15:07:42.733Z - debug: Skipping storing report. rootId=40awjagj02kfdmn, id=kew5i5egdruzv8f
2023-10-31T15:07:42.734Z - info: Rendering (child) request finished in 3150 ms rootId=40awjagj02kfdmn, id=kew5i5egdruzv8f
2023-10-31T15:07:42.833Z - info: docx generation was finished rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.834Z - debug: Executing unoconv commmand unoconv -f pdf /tmp/jsreport/autocleanup/4f207934-98d1-4c59-a30c-8af7267f6b06.docx rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:42.883Z - debug: Skipping storing report. rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:42.883Z - info: Rendering request 37 finished in 3426 ms rootId=zj1tibf8bnv1x46, id=zj1tibf8bnv1x46
2023-10-31T15:07:43.833Z - debug: Skipping storing report. rootId=40awjagj02kfdmn, id=40awjagj02kfdmn
2023-10-31T15:07:43.833Z - info: Rendering request 39 finished in 4341 ms rootId=40awjagj02kfdmn, id=40awjagj02kfdmn

    Besides some warnings about saving profiles (which don't bother me too much), the following shows the failing request:

    2023-10-31T15:07:40.531Z - warn: Error when processing render request 33
(because) error while executing unoconv
(because) command failed: unoconv -f pdf /tmp/jsreport/autocleanup/9c1d9407-05c2-456a-9191-54ca7a79f6a6.docx
Error: Unable to connect or start own listener. Aborting.

Error: Command failed: unoconv -f pdf /tmp/jsreport/autocleanup/9c1d9407-05c2-456a-9191-54ca7a79f6a6.docx
Error: Unable to connect or start own listener. Aborting.

  at ChildProcess.exithandler (node:child_process:419:12)
  at ChildProcess.emit (node:events:514:28)
  at maybeClose (node:internal/child_process:1091:16)
  at ChildProcess._handle.onexit (node:internal/child_process:302:5)
wrapped by:
Error: Error while executing unoconv
(because) command failed: unoconv -f pdf /tmp/jsreport/autocleanup/9c1d9407-05c2-456a-9191-54ca7a79f6a6.docx
Error: Unable to connect or start own listener. Aborting.

  at module.exports (/app/node_modules/@jsreport/jsreport-core/lib/shared/createError.js:10:13)
  at WorkerReporter.createError (/app/node_modules/@jsreport/jsreport-core/lib/shared/reporter.js:49:12)
  at AsyncFunction.<anonymous> (/app/node_modules/@jsreport/jsreport-unoconv/lib/worker.js:46:22)
  at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
  at async ListenerCollection.fire (/app/node_modules/@jsreport/jsreport-core/lib/shared/listenerCollection.js:157:21)
  at async afterRender (/app/node_modules/@jsreport/jsreport-core/lib/worker/render/render.js:103:5)
  at async WorkerReporter._render (/app/node_modules/@jsreport/jsreport-core/lib/worker/render/render.js:148:7)
  at async /app/node_modules/@jsreport/jsreport-core/lib/worker/reporter.js:224:19
  at async processAndResponse (/app/node_modules/@jsreport/advanced-workers/lib/workerHandler.js:41:17) rootId=6f0hkmepfq04xet, id=6f0hkmepfq04xet

    Is it to be expected that JSReport handles this correctly?

    When I disable the 'unoconv' property on this request, everything works fine, but as we need PDF reports that is not really an option.

    0

  • It seems like this is a known unoconv/libreoffice issue
    https://github.com/unoconv/unoconv/issues/225

    Here is a solution mentioned to synchronize calls to unoconv which could help.
    https://github.com/unoconv/unoconv/issues/225#issuecomment-440901799
    You won't get office parallelization, but maybe it's a solution for you.

    We have in backlog a task to migrate to a newer implementation of unoconv. Maybe it's solving this, but we didn't get there yet
    https://github.com/jsreport/jsreport/issues/1019

    0
  • A

    Thanks for clarifying that!
    The 'solution' you linked is not so much a solution, but more a workaround, as it creates a lockfile using flock with a timeout of 20 seconds which ensures that the executed unoconv command is never executed in parallel. That of course has the impact of decreasing performance of parallel requests.
    But for us this workaround is workable.

    I was able to implement this by configuring jsreport to use a custom unoconv command as documented here, and specifying the following command as the custom command: /usr/bin/timeout 30 flock -w 20 lockfile /usr/bin/unoconv.
    Its slightly different than the one mentioned in the github issue, since that uses xvfb-run which apparently is needed in certain scenarios involving Apache, but as xvfb-run is not available in the jsreport/jsreport docker image, and it seemed to work withouth xvfb-run, I decided to go without it instead.

    Other people copying this workaround should be aware of the aforementioned risk that this will enforce that unoconv is run serially instead of in parallel, on a global scale (also across different requests). High volumes of requests might even run into the 20 second timeout value and still have failures.

    0

  • Thank you for sharing your workaround. I've included it in the documentation.

    0
pdf 5
Log in to reply
 

Looks like your connection to jsreport forum was lost, please wait while we try to reconnect.