Unable to enable apps after upgrading to 6.11.1

[paulchen]

On my server, something similar to #32761 reappeared some days ago. However, I'm running a Docker installation instead of a manual setup.

Description:

The apps GIPHY and Tenor have been installed for a long time on my instance (they're grandfathered). Since a few days, both of them are disabled and can't be enabled.

When trying to enable them, an error message is shown:

See below for the error log.

Steps to reproduce:

1. Set up Rocket.Chat 3.16.0.
2. Install and enable the apps Tenor and Giphy.
3. Update Rocket.Chat step-by-step all the way up to 6.11.1.
4. Observe that Tenor and/or Giphy are no longer enabled.
5. Try to enable one of them which is currently disabled.

Expected behavior:

The app is now enabled.

Actual behavior:

An error message is shown:

Server Setup Information:

• Version of Rocket.Chat Server: 6.11.1
• License Type: Starter
• Number of Users: 22
• Deployment Method: Docker
• Number of Running Instances: 1
• MongoDB Version: 6.0.17 / wiredTiger (oplog Enabled)

Client Setup Information

• Desktop App or Browser Version:
  • Electron client 4.0.1
  • Google Chrome Version 128.0.6613.85 (Offizieller Build) (64-Bit)
• Operating System: Windows 10

Additional context

On a test instance, only Tenor was installed. I am unable to enable Tenor, but I was able to make GIPHY running.

On the same test instance, I uninstalled Tenor, but now I'm unable to reinstall it. When trying it, another error message is shown:

Error log:

2024-08-23T18:17:13.206986+02:00 alpha rocketchat-dev[1711287]: {"level":35,"time":"2024-08-23T16:17:13.206Z","pid":1,"hostname":"8e55b7fffd06","name":"API","method":"POST","url":"/api/apps","userId":"xq7oE4mtb2nEcfe2m","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Rocket.Chat/4.0.1 Chrome/124.0.6367.243 Electron/30.1.2 Safari/537.36","length":"85","host":"localhost:3001","referer":"https://<domain>/marketplace/explore","remoteIP":"2001:871:261:eab7:4d0a:c1cc:690a:3b10","err":{"type":"Error","message":"App already has an associated runtime","stack":"Error: App already has an associated runtime\n    at AppRuntimeManager.<anonymous> (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/managers/AppRuntimeManager.js:23:23)\n    at Generator.next (<anonymous>)\n    at /app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/managers/AppRuntimeManager.js:8:71\n    at new Promise (<anonymous>)\n    at __awaiter (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/managers/AppRuntimeManager.js:4:12)\n    at AppRuntimeManager.startRuntimeForApp (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/managers/AppRuntimeManager.js:20:16)\n    at AppCompiler.<anonymous> (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/compiler/AppCompiler.js:28:56)\n    at Generator.next (<anonymous>)\n    at /app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/compiler/AppCompiler.js:8:71\n    at new Promise (<anonymous>)\n    at __awaiter (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/compiler/AppCompiler.js:4:12)\n    at AppCompiler.toSandBox (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/compiler/AppCompiler.js:24:16)\n    at AppManager.<anonymous> (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/AppManager.js:398:50)\n    at Generator.next (<anonymous>)\n    at fulfilled (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/AppManager.js:5:58)\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40\n => awaited here:\n    at Function.Promise.await (/app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)\n    at ee/server/apps/communication/rest.ts:402:15\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40\n => awaited here:\n    at Function.Promise.await (/app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)\n    at packages/meteor.js:367:22\n    at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1389:31)\n    at app/api/server/api.ts:649:39\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40"},"status":400,"responseTime":1659,"msg":"App already has an associated runtime"}

On 2024-08-31 around 21:30, I rebooted the server running Docker. Afterwards, Giphy and Tenor started working on both Rocket.Chat instances. See below for the logs.

Relevant logs

Nothing is logged on client side.

Contents of the log file on server side:

2024-08-23T18:23:17.205137+02:00 alpha rocketchat[1711287]: {"level":35,"time":"2024-08-23T16:23:17.204Z","pid":1,"hostname":"9ad73d11caf9","name":"API","method":"POST","url":"/api/apps/ab4728ec-613e-472f-a24c-b48a77aacfff/status","userId":"L86W8h2Xtrpystbnd","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Rocket.Chat/4.0.1 Chrome/124.0.6367.243 Electron/30.1.2 Safari/537.36","length":"29","host":"localhost:3000","referer":"https://<domain>/marketplace/installed/list","remoteIP":"2001:871:261:eab7:4d0a:c1cc:690a:3b10","err":{"type":"Error","message":"The App had compiler errors, can not enable it.","stack":"Error: The App had compiler errors, can not enable it.\n    at AppManager.<anonymous> (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/AppManager.js:313:23)\n    at Generator.next (<anonymous>)\n    at fulfilled (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/AppManager.js:5:58)\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40\n => awaited here:\n    at Function.Promise.await (/app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)\n    at ee/server/apps/communication/rest.ts:1187:18\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40\n => awaited here:\n    at Function.Promise.await (/app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/promise_server.js:56:12)\n    at packages/meteor.js:367:22\n    at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1389:31)\n    at app/api/server/api.ts:649:39\n    at /app/bundle/programs/server/npm/node_modules/meteor/promise/node_modules/meteor-promise/fiber_pool.js:43:40"},"status":400,"responseTime":6,"msg":"The App had compiler errors, can not enable it."}

As suggested in one of the comments, I fired up the server with the environment variable, DEBUG=appsEngine:runtime:*:

2024-08-28T11:34:20.443607+02:00 alpha rocketchat[2340872]: 2024-08-28T09:34:20.443Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Setting up app subprocess
2024-08-28T11:34:20.491979+02:00 alpha rocketchat[2340872]: 2024-08-28T09:34:20.491Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Started subprocess 21 with options [
2024-08-28T11:34:20.492080+02:00 alpha rocketchat[2340872]:   'run',
2024-08-28T11:34:20.492148+02:00 alpha rocketchat[2340872]:   '--allow-net',
2024-08-28T11:34:20.492214+02:00 alpha rocketchat[2340872]:   '--allow-read=/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine,/app/bundle/programs/server/npm/node_modules',
2024-08-28T11:34:20.492283+02:00 alpha rocketchat[2340872]:   '--allow-env=NODE_EXTRA_CA_CERTS',
2024-08-28T11:34:20.492346+02:00 alpha rocketchat[2340872]:   '/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/deno-runtime/main.ts',
2024-08-28T11:34:20.492408+02:00 alpha rocketchat[2340872]:   '--subprocess',
2024-08-28T11:34:20.492467+02:00 alpha rocketchat[2340872]:   'ab4728ec-613e-472f-a24c-b48a77aacfff'
2024-08-28T11:34:20.492533+02:00 alpha rocketchat[2340872]: ]
2024-08-28T11:34:31.731836+02:00 alpha rocketchat[2340872]: Error while compiling the App "Tenor (ab4728ec-613e-472f-a24c-b48a77aacfff)":
2024-08-28T11:34:31.732135+02:00 alpha rocketchat[2340872]: Error: [ab4728ec-613e-472f-a24c-b48a77aacfff] Timeout: app process not ready
2024-08-28T11:34:31.732354+02:00 alpha rocketchat[2340872]:     at Timeout._onTimeout (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/runtime/deno/AppsEngineDenoRuntime.js:216:55)
2024-08-28T11:34:31.732603+02:00 alpha rocketchat[2340872]:     at listOnTimeout (internal/timers.js:557:17)
2024-08-28T11:34:31.734683+02:00 alpha rocketchat[2340872]:     at processTimers (internal/timers.js:500:7)
2024-08-28T11:34:31.735122+02:00 alpha rocketchat[2340872]: 2024-08-28T09:34:30.570Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Setting up app subprocess
2024-08-28T11:34:31.735395+02:00 alpha rocketchat[2340872]: 2024-08-28T09:34:30.622Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Started subprocess 42 with options [
2024-08-28T11:34:31.735851+02:00 alpha rocketchat[2340872]:   'run',
2024-08-28T11:34:31.736248+02:00 alpha rocketchat[2340872]:   '--allow-net',
2024-08-28T11:34:31.736483+02:00 alpha rocketchat[2340872]:   '--allow-read=/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine,/app/bundle/programs/server/npm/node_modules',
2024-08-28T11:34:31.737509+02:00 alpha rocketchat[2340872]:   '--allow-env=NODE_EXTRA_CA_CERTS',
2024-08-28T11:34:31.737684+02:00 alpha rocketchat[2340872]:   '/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/deno-runtime/main.ts',
2024-08-28T11:34:31.737997+02:00 alpha rocketchat[2340872]:   '--subprocess',
2024-08-28T11:34:31.739250+02:00 alpha rocketchat[2340872]:   '8b882242-0cb7-419f-87d8-93b1d09e1ec2'
2024-08-28T11:34:31.739599+02:00 alpha rocketchat[2340872]: ]
2024-08-28T11:35:23.631807+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:23.631Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', method: 'ready' }
2024-08-28T11:35:23.632516+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:23.632Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess '_zPING'
2024-08-28T11:35:23.634405+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:23.634Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess '_zPONG'
2024-08-28T11:35:23.634479+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:23.634Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Ping successful in 2 ms
2024-08-28T11:35:25.404171+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:25.403Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', method: 'ready' }
2024-08-28T11:35:25.445454+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:25.404Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess '_zPING'
2024-08-28T11:35:25.445505+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:25.406Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess '_zPONG'
2024-08-28T11:35:25.445553+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:25.406Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Ping successful in 2 ms
2024-08-28T11:35:33.637924+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:33.634Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess '_zPING'
2024-08-28T11:35:33.640342+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:33.639Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess '_zPONG'
2024-08-28T11:35:33.640428+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:33.639Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Ping successful in 5 ms
2024-08-28T11:35:35.407096+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:35.406Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess '_zPING'
2024-08-28T11:35:35.543278+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:35.410Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess '_zPONG'
2024-08-28T11:35:35.543994+02:00 alpha rocketchat[2340872]: 2024-08-28T09:35:35.410Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Ping successful in 4 ms
[...]

Both apps were not enabled, but they were periodically pinged with success.

After the reboot at 2024-08-31 around 21:30, there were a lot more log entries:

2024-08-31T21:39:53.672328+02:00 alpha rocketchat[6256]: 2024-08-31T19:39:53.672Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Setting up app subprocess
2024-08-31T21:39:54.025840+02:00 alpha rocketchat[6256]: 2024-08-31T19:39:54.025Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Started subprocess 89 with options [
2024-08-31T21:40:06.697159+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:06.696Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', method: 'ready' }
2024-08-31T21:40:06.697813+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:06.697Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess '_zPING'
2024-08-31T21:40:06.700111+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:06.699Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'amce6xsjbz5', method: 'app:construct', params: [ { info: [Object], files: [Object], languageContent: [Object], implemented: [AppImplements] } ] }
2024-08-31T21:40:06.747056+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:06.746Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess '_zPONG'
2024-08-31T21:40:06.747523+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:06.746Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Ping successful in 49 ms
2024-08-31T21:40:07.042890+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.042Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'amce6xsjbz5', result: { value: true, logs: { appId: 'ab4728ec-613e-472f-a24c-b48a77aacfff', method: 'app:construct', entries: [Array], startTime: 2024-08-31T19:40:07.015Z, endTime: 2024-08-31T19:40:07.040Z, totalTime: 25, _createdAt: 2024-08-31T19:40:07.040Z } } }
2024-08-31T21:40:07.194494+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.194Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request amce6xsjbz5 for method app:construct took 496ms
2024-08-31T21:40:07.200881+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.200Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Setting up app subprocess
2024-08-31T21:40:07.223578+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.223Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Started subprocess 127 with options [
2024-08-31T21:40:07.319124+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.318Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', method: 'ready' }
2024-08-31T21:40:07.319234+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.319Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess '_zPING'
2024-08-31T21:40:07.319792+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.319Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'c074teii8kk', method: 'app:construct', params: [ { info: [Object], files: [Object], languageContent: [Object], implemented: [AppImplements] } ] }
2024-08-31T21:40:07.322799+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.322Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess '_zPONG'
2024-08-31T21:40:07.322888+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.322Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Ping successful in 3 ms
2024-08-31T21:40:07.345288+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.345Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'c074teii8kk', result: { value: true, logs: { appId: '8b882242-0cb7-419f-87d8-93b1d09e1ec2', method: 'app:construct', entries: [Array], startTime: 2024-08-31T19:40:07.324Z, endTime: 2024-08-31T19:40:07.343Z, totalTime: 19, _createdAt: 2024-08-31T19:40:07.343Z } } }
2024-08-31T21:40:07.567655+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.567Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request c074teii8kk for method app:construct took 248ms
2024-08-31T21:40:07.571829+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.571Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'du17abyh6a', method: 'app:initialize', params: [] }
2024-08-31T21:40:07.573975+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.573Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: '4yc1au6je2q', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'tenor_apikey', type: 'string', packageValue: '', required: true, public: false, i18nLabel: 'Customize_Tenor_APIKey', i18nDescription: 'Customize_Tenor_APIKey_Description' } ] }
2024-08-31T21:40:07.574369+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.574Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'tenor_apikey', type: 'string', packageValue: '', required: true, public: false, i18nLabel: 'Customize_Tenor_APIKey', i18nDescription: 'Customize_Tenor_APIKey_Description' } ]
2024-08-31T21:40:07.575558+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.575Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: '4yc1au6je2q', result: null }
2024-08-31T21:40:07.577907+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.577Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: '9j9jecimpeo', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'tenor_lang_code', type: 'string', packageValue: 'en_US', required: true, public: false, i18nLabel: 'Customize_Tenor_Language', i18nDescription: 'Customize_Tenor_Language_Description' } ] }
2024-08-31T21:40:07.578080+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.577Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'tenor_lang_code', type: 'string', packageValue: 'en_US', required: true, public: false, i18nLabel: 'Customize_Tenor_Language', i18nDescription: 'Customize_Tenor_Language_Description' } ]
2024-08-31T21:40:07.578309+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.578Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: '9j9jecimpeo', result: null }
2024-08-31T21:40:07.579234+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.579Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: '52bjyh17n3f', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'tenor_content_filter', type: 'string', packageValue: 'low', required: true, public: false, i18nLabel: 'Customize_Tenor_ContentFilter', i18nDescription: 'Customize_Tenor_ContentFilter_Description' } ] }
2024-08-31T21:40:07.579414+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.579Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'tenor_content_filter', type: 'string', packageValue: 'low', required: true, public: false, i18nLabel: 'Customize_Tenor_ContentFilter', i18nDescription: 'Customize_Tenor_ContentFilter_Description' } ]
2024-08-31T21:40:07.579623+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.579Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: '52bjyh17n3f', result: null }
2024-08-31T21:40:07.580509+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.580Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'n61ew3h7pd', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'tenor_show_title', type: 'boolean', packageValue: true, required: true, public: false, i18nLabel: 'Customize_Tenor_Show_Title', i18nDescription: 'Customize_Tenor_Show_Title_Description' } ] }
2024-08-31T21:40:07.580656+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.580Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'tenor_show_title', type: 'boolean', packageValue: true, required: true, public: false, i18nLabel: 'Customize_Tenor_Show_Title', i18nDescription: 'Customize_Tenor_Show_Title_Description' } ]
2024-08-31T21:40:07.580866+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.580Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: 'n61ew3h7pd', result: null }
2024-08-31T21:40:07.616415+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.616Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'z8f2s1wxnld', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'tenor_show_link', type: 'boolean', packageValue: true, required: true, public: false, i18nLabel: 'Customize_Tenor_Show_Link', i18nDescription: 'Customize_Tenor_Show_Link_Description' } ] }
2024-08-31T21:40:07.616533+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.616Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'tenor_show_link', type: 'boolean', packageValue: true, required: true, public: false, i18nLabel: 'Customize_Tenor_Show_Link', i18nDescription: 'Customize_Tenor_Show_Link_Description' } ]
2024-08-31T21:40:07.616754+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.616Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: 'z8f2s1wxnld', result: null }
2024-08-31T21:40:07.886810+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.886Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: '7rqez6fto2', method: 'accessor:getConfigurationExtend:slashCommands:provideSlashCommand', params: [ { app: undefined, command: 'tenor', i18nParamsExample: 'Tenor_Search_Term', i18nDescription: 'Tenor_Command_Description', providesPreview: true } ] }
2024-08-31T21:40:07.987565+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.886Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Handling accessor message [ 'getConfigurationExtend', 'slashCommands', 'provideSlashCommand' ] with params [ { app: undefined, command: 'tenor', i18nParamsExample: 'Tenor_Search_Term', i18nDescription: 'Tenor_Command_Description', providesPreview: true } ]
2024-08-31T21:40:07.987685+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.888Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: '7rqez6fto2', result: null }
2024-08-31T21:40:07.987735+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:07.890Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'du17abyh6a', result: { value: true, logs: { appId: 'ab4728ec-613e-472f-a24c-b48a77aacfff', method: 'app:initialize', entries: [Array], startTime: 2024-08-31T19:40:07.571Z, endTime: 2024-08-31T19:40:07.888Z, totalTime: 317, _createdAt: 2024-08-31T19:40:07.888Z } } }
2024-08-31T21:40:08.402769+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.402Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request du17abyh6a for method app:initialize took 831ms
2024-08-31T21:40:08.403173+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.402Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: '4ynkre6a5na', method: 'app:setStatus', params: [ 'initialized' ] }
2024-08-31T21:40:08.405298+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.405Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: '4ynkre6a5na', result: { value: null, logs: { appId: 'ab4728ec-613e-472f-a24c-b48a77aacfff', method: 'app:setStatus', entries: [Array], startTime: 2024-08-31T19:40:08.403Z, endTime: 2024-08-31T19:40:08.404Z, totalTime: 1, _createdAt: 2024-08-31T19:40:08.404Z } } }
2024-08-31T21:40:08.698105+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.697Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request 4ynkre6a5na for method app:setStatus took 295ms
2024-08-31T21:40:08.702670+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.702Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: '9r4d8wr4sqr', method: 'app:getStatus', params: [] }
2024-08-31T21:40:08.703591+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.703Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'iamuq1hdgcq', method: 'app:getStatus', params: [] }
2024-08-31T21:40:08.704186+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.703Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: '9r4d8wr4sqr', result: { value: 'initialized' } }
2024-08-31T21:40:08.704643+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.704Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request 9r4d8wr4sqr for method app:getStatus took 2ms
2024-08-31T21:40:08.706479+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.706Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'iamuq1hdgcq', result: { value: 'initialized' } }
2024-08-31T21:40:08.706855+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.706Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request iamuq1hdgcq for method app:getStatus took 3ms
2024-08-31T21:40:08.709344+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.709Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'vv4z8fip1q', method: 'app:onEnable', params: [] }
2024-08-31T21:40:08.712512+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:08.712Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'vv4z8fip1q', result: { value: true, logs: { appId: 'ab4728ec-613e-472f-a24c-b48a77aacfff', method: 'app:onEnable', entries: [Array], startTime: 2024-08-31T19:40:08.709Z, endTime: 2024-08-31T19:40:08.710Z, totalTime: 1, _createdAt: 2024-08-31T19:40:08.710Z } } }
2024-08-31T21:40:09.084025+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.083Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request vv4z8fip1q for method app:onEnable took 375ms
2024-08-31T21:40:09.086071+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.085Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'm4bmltnyqns', method: 'app:setStatus', params: [ 'manually_enabled' ] }
2024-08-31T21:40:09.087450+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.087Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'm4bmltnyqns', result: { value: null, logs: { appId: 'ab4728ec-613e-472f-a24c-b48a77aacfff', method: 'app:setStatus', entries: [Array], startTime: 2024-08-31T19:40:09.086Z, endTime: 2024-08-31T19:40:09.086Z, totalTime: 0, _createdAt: 2024-08-31T19:40:09.086Z } } }
2024-08-31T21:40:09.263893+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.263Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request m4bmltnyqns for method app:setStatus took 178ms
2024-08-31T21:40:09.496402+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.496Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'yv9qrrcylwd', method: 'app:getStatus', params: [] }
2024-08-31T21:40:09.498202+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.498Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: '6qljo0t2qir', method: 'app:initialize', params: [] }
2024-08-31T21:40:09.498569+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.498Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'yv9qrrcylwd', result: { value: 'manually_enabled' } }
2024-08-31T21:40:09.498756+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.498Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request yv9qrrcylwd for method app:getStatus took 2ms
2024-08-31T21:40:09.500257+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.500Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'n2obu49fdq', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'giphy_apikey', type: 'string', packageValue: '', required: true, public: false, i18nLabel: 'Customize_GIPHY_APIKey', i18nDescription: 'Customize_GIPHY_APIKey_Description' } ] }
2024-08-31T21:40:09.500421+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.500Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'giphy_apikey', type: 'string', packageValue: '', required: true, public: false, i18nLabel: 'Customize_GIPHY_APIKey', i18nDescription: 'Customize_GIPHY_APIKey_Description' } ]
2024-08-31T21:40:09.500663+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.500Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: 'n2obu49fdq', result: null }
2024-08-31T21:40:09.502627+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.502Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'k4dehtmb3cs', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'giphy_lang_code', type: 'string', packageValue: 'en', required: true, public: false, i18nLabel: 'Customize_GIPHY_Language', i18nDescription: 'Customize_GIPHY_Language_Description' } ] }
2024-08-31T21:40:09.502766+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.502Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'giphy_lang_code', type: 'string', packageValue: 'en', required: true, public: false, i18nLabel: 'Customize_GIPHY_Language', i18nDescription: 'Customize_GIPHY_Language_Description' } ]
2024-08-31T21:40:09.503003+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.502Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: 'k4dehtmb3cs', result: null }
2024-08-31T21:40:09.504177+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.504Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: '4ywfplpwwmn', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'giphy_rating', type: 'string', packageValue: 'G', required: true, public: false, i18nLabel: 'Customize_GIPHY_Rating', i18nDescription: 'Customize_GIPHY_Rating_Description' } ] }
2024-08-31T21:40:09.504321+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.504Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'giphy_rating', type: 'string', packageValue: 'G', required: true, public: false, i18nLabel: 'Customize_GIPHY_Rating', i18nDescription: 'Customize_GIPHY_Rating_Description' } ]
2024-08-31T21:40:09.504564+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.504Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: '4ywfplpwwmn', result: null }
2024-08-31T21:40:09.505732+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.505Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'cwzqaawf46d', method: 'accessor:getConfigurationExtend:settings:provideSetting', params: [ { id: 'giphy_show_title', type: 'boolean', packageValue: true, required: true, public: false, i18nLabel: 'Customize_GIPHY_Show_Title', i18nDescription: 'Customize_GIPHY_Show_Title_Description' } ] }
2024-08-31T21:40:09.505921+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.505Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Handling accessor message [ 'getConfigurationExtend', 'settings', 'provideSetting' ] with params [ { id: 'giphy_show_title', type: 'boolean', packageValue: true, required: true, public: false, i18nLabel: 'Customize_GIPHY_Show_Title', i18nDescription: 'Customize_GIPHY_Show_Title_Description' } ]
2024-08-31T21:40:09.506157+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.506Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: 'cwzqaawf46d', result: null }
2024-08-31T21:40:09.507221+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.507Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'b1sd3lravch', method: 'accessor:getConfigurationExtend:slashCommands:provideSlashCommand', params: [ { app: undefined, command: 'giphy', i18nParamsExample: 'GIPHY_Search_Term', i18nDescription: 'GIPHY_Command_Description', providesPreview: true } ] }
2024-08-31T21:40:09.507398+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.507Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Handling accessor message [ 'getConfigurationExtend', 'slashCommands', 'provideSlashCommand' ] with params [ { app: undefined, command: 'giphy', i18nParamsExample: 'GIPHY_Search_Term', i18nDescription: 'GIPHY_Command_Description', providesPreview: true } ]
2024-08-31T21:40:09.507771+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.507Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess SuccessObject { jsonrpc: '2.0', id: 'b1sd3lravch', result: null }
2024-08-31T21:40:09.509384+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.509Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: '6qljo0t2qir', result: { value: true, logs: { appId: '8b882242-0cb7-419f-87d8-93b1d09e1ec2', method: 'app:initialize', entries: [Array], startTime: 2024-08-31T19:40:09.498Z, endTime: 2024-08-31T19:40:09.508Z, totalTime: 10, _createdAt: 2024-08-31T19:40:09.508Z } } }
2024-08-31T21:40:09.847003+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.846Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request 6qljo0t2qir for method app:initialize took 349ms
2024-08-31T21:40:09.847213+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.847Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'tf7oaepxy3s', method: 'app:setStatus', params: [ 'initialized' ] }
2024-08-31T21:40:09.849895+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:09.849Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'tf7oaepxy3s', result: { value: null, logs: { appId: '8b882242-0cb7-419f-87d8-93b1d09e1ec2', method: 'app:setStatus', entries: [Array], startTime: 2024-08-31T19:40:09.847Z, endTime: 2024-08-31T19:40:09.848Z, totalTime: 1, _createdAt: 2024-08-31T19:40:09.848Z } } }
2024-08-31T21:40:10.134108+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.132Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request tf7oaepxy3s for method app:setStatus took 286ms
2024-08-31T21:40:10.181240+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.181Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'taukjf0qcbb', method: 'app:getStatus', params: [] }
2024-08-31T21:40:10.182966+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.182Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'cls4rvvriij', method: 'app:getStatus', params: [] }
2024-08-31T21:40:10.185193+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.185Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'taukjf0qcbb', result: { value: 'initialized' } }
2024-08-31T21:40:10.185403+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.185Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request taukjf0qcbb for method app:getStatus took 5ms
2024-08-31T21:40:10.185525+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.185Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'cls4rvvriij', result: { value: 'initialized' } }
2024-08-31T21:40:10.185702+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.185Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request cls4rvvriij for method app:getStatus took 3ms
2024-08-31T21:40:10.187502+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.187Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'qvpx6pzw8fg', method: 'app:onEnable', params: [] }
2024-08-31T21:40:10.189154+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.188Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'qvpx6pzw8fg', result: { value: true, logs: { appId: '8b882242-0cb7-419f-87d8-93b1d09e1ec2', method: 'app:onEnable', entries: [Array], startTime: 2024-08-31T19:40:10.187Z, endTime: 2024-08-31T19:40:10.188Z, totalTime: 1, _createdAt: 2024-08-31T19:40:10.188Z } } }
2024-08-31T21:40:10.548144+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.547Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request qvpx6pzw8fg for method app:onEnable took 360ms
2024-08-31T21:40:10.548933+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.548Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: '8gzkzbii0h5', method: 'app:setStatus', params: [ 'manually_enabled' ] }
2024-08-31T21:40:10.559485+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.559Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: '8gzkzbii0h5', result: { value: null, logs: { appId: '8b882242-0cb7-419f-87d8-93b1d09e1ec2', method: 'app:setStatus', entries: [Array], startTime: 2024-08-31T19:40:10.549Z, endTime: 2024-08-31T19:40:10.549Z, totalTime: 0, _createdAt: 2024-08-31T19:40:10.549Z } } }
2024-08-31T21:40:10.990246+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:10.989Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request 8gzkzbii0h5 for method app:setStatus took 441ms
2024-08-31T21:40:11.271891+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.267Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: '210u911pfrfi', method: 'app:getStatus', params: [] }
2024-08-31T21:40:11.271995+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.268Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'r5j6h6syja', method: 'app:getStatus', params: [] }
2024-08-31T21:40:11.272047+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.270Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: '210u911pfrfi', result: { value: 'manually_enabled' } }
2024-08-31T21:40:11.272118+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.270Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request 210u911pfrfi for method app:getStatus took 3ms
2024-08-31T21:40:11.272173+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.270Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess { jsonrpc: '2.0', id: 'r5j6h6syja', result: { value: 'manually_enabled' } }
2024-08-31T21:40:11.272222+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.270Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Request r5j6h6syja for method app:getStatus took 2ms
2024-08-31T21:40:11.272278+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.271Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess RequestObject { jsonrpc: '2.0', id: 'o85b4bui2ri', method: 'app:getStatus', params: [] }
2024-08-31T21:40:11.278080+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.273Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess { jsonrpc: '2.0', id: 'o85b4bui2ri', result: { value: 'manually_enabled' } }
2024-08-31T21:40:11.278136+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:11.273Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Request o85b4bui2ri for method app:getStatus took 2ms
2024-08-31T21:40:16.748532+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:16.747Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess '_zPING'
2024-08-31T21:40:16.768085+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:16.767Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess '_zPONG'
2024-08-31T21:40:16.768329+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:16.767Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Ping successful in 20 ms
2024-08-31T21:40:17.323070+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:17.322Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess '_zPING'
2024-08-31T21:40:17.330387+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:17.330Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess '_zPONG'
2024-08-31T21:40:17.330547+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:17.330Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Ping successful in 8 ms
2024-08-31T21:40:51.893877+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:26.768Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Sending message to subprocess '_zPING'
2024-08-31T21:40:51.893917+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:26.786Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Received message from subprocess '_zPONG'
2024-08-31T21:40:51.895283+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:26.787Z appsEngine:runtime:deno:ab4728ec-613e-472f-a24c-b48a77aacfff Ping successful in 19 ms
2024-08-31T21:40:51.895324+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:27.331Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Sending message to subprocess '_zPING'
2024-08-31T21:40:51.895648+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:27.342Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Received message from subprocess '_zPONG'
2024-08-31T21:40:51.895735+02:00 alpha rocketchat[6256]: 2024-08-31T19:40:27.342Z appsEngine:runtime:deno:8b882242-0cb7-419f-87d8-93b1d09e1ec2 Ping successful in 11 ms
[...]

[reetp]

I'm running a Docker installation instead of a manual setup.

Please fill out a bug template.

We can't help you without it.

https://github.com/RocketChat/Rocket.Chat/issues/new?assignees=&labels=&projects=&template=bug_report.md

[RavuAlHemio]

Given that the bug template contains a section "Steps to reproduce": how exactly does one, on a clean instance, reproduce an app being grandfathered?

[reetp]

Given that the bug template contains a section "Steps to reproduce": how exactly does one, on a clean instance, reproduce an app being grandfathered?

Most likely you can't..... quite probably the devs can, or will know why this occurs.

Steps to reproduce (which is the information I was after) will likely be:

• Originally Installed vx.x.x
• Installed apps
• Upgraded several version until vx.x.x
• Apps then failed after upgrade from vx.x.x to v6.11.1

But that may be hard to reproduce with old apps that are no longer available.

[tapiarafael]

@paulchen Can you run your setup using DEBUG=appsEngine:runtime:* variable? This will enable some logs that may help us to understand what's happening. Please, be aware that this will show a lot of logs depending on the number of apps that you have installed. You can also use DEBUG=appsEngine:runtime:deno:[APP_ID] to show logs only for a single app.

[Mal0815]

Hi! I'm having the same problem. I updated the server from <6.10 to 6.11 directly without updating to 6.10.
I tried to get this debug running. Here is the output after trying to (re)install an app.
I hope this helps you.
debug_rocketchat.txt

[reetp]

Hi! I'm having the same problem. I updated the server from <6.10 to 6.11 directly without updating to 6.10.

Please fill out a bug template with your server details and your update history. Which version did you upgrade from? It may be the same issue, and it may not.

[Mal0815]

I did. :) Is there a way to get the actual update history of the rocketchat server?

[reetp]

I did. :)

Why on earth did you open a duplicate issue? All you had to do was put the server info here so we could see that you were using the same setup. Like this:

Version 6.11.1
Version der Anwendungs-Engine 1.44.0
Node-Version v14.21.3
Datenbankmigration 304 (30. August 2024 10:57)
MongoDB 5.0.28 / wiredTiger (oplog Deaktiviert)
Details festschreiben HEAD: (12e000d)
Zweig: HEAD Release 6.11.1

Starter license 1 instance
approx. 10 Users
OS: Debian 11
Deployment on Debian

Is there a way to get the actual update history of the rocketchat server?

Only via your logs as far as I remember.

[Mal0815]

Sorry, I'm new to this. I used the link above for the template as you said fill out the template.

[paulchen]

I'm running a Docker installation instead of a manual setup.

Please fill out a bug template.

@reetp I updated my initial comment to include the sections that I initially left out.

@paulchen Can you run your setup using DEBUG=appsEngine:runtime:* variable? This will enable some logs that may help us to understand what's happening. Please, be aware that this will show a lot of logs depending on the number of apps that you have installed. You can also use DEBUG=appsEngine:runtime:deno:[APP_ID] to show logs only for a single app.

@tapiarafael I ran my setup with that environment variable. I added the log output to the initial comment.

Hi! I'm having the same problem. I updated the server from <6.10 to 6.11 directly without updating to 6.10. I tried to get this debug running. Here is the output after trying to (re)install an app. I hope this helps you. debug_rocketchat.txt

@Mal0815 This is in fact possibly related. Your log contains the error Timeout: app process not ready that I observed as well.

However, my current "problem" is that after a reboot of the server running Docker, the apps work as expected and I do not experience the problem reported in this issue anymore.

Please be aware that due to various professional and private obligations, my replies to comments in this issue might be severely delayed in the next few weeks.

[Mal0815]

Good morning!
For me, a reboot didn't solve the problem.
Can I do something else?
The logs from @paulchen look different. I guess, I set the DEBUG=appsEngine:runtime:* option wrong.
I added

[Service]
ENVIRONMENT=DEBUG=appsEngine:runtime:*

by running systemctl edit rocketchat.service for my deployment on debian. Is this correct?

[keithdanielll]

Same here with Jitsi. https://forums.rocket.chat/t/jitsi-no-more-availabe-after-update-to-version-6-12-0/20524

[github-actions]

This issue has been marked as stale because there has been no further activity in the last 10 days. If the issue remains stale for the next 4 days (a total of 14 days with no activity), then it will be assumed that the question has been resolved and the issue will be automatically closed.