Rocket.Chat Unable to enable apps after upgrading to 6.11.1

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:

Set up Rocket.Chat 3.16.0.
Install and enable the apps Tenor and Giphy.
Update Rocket.Chat step-by-step all the way up to 6.11.1.
Observe that Tenor and/or Giphy are no longer enabled.
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
[...]

Aug 23 '24 16:08 paulchen

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

Aug 24 '24 12:08 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?

Aug 24 '24 13:08 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?

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.

Aug 24 '24 14:08 reetp

@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.

Aug 26 '24 22:08 tapiarafael

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

Aug 30 '24 09:08 Mal0815

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.

Aug 30 '24 09:08 reetp

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

Aug 30 '24 10:08 Mal0815

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: (https://github.com/RocketChat/Rocket.Chat/commit/12e000d8894e83418345f2550e22d2a3c444eb4b) 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.

Aug 30 '24 10:08 reetp

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

Aug 30 '24 10:08 Mal0815

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.

Aug 31 '24 23:08 paulchen

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?

Sep 03 '24 07:09 Mal0815

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

Sep 09 '24 12:09 keithdanielll

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.

Sep 23 '24 18:09 github-actions[bot]

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?

I think so.

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.

The issue still persists. Today, I updated my setup to Rocket.Chat 6.12.1.

Sep 23 '24 18:09 paulchen

The issue still persists. Today, I updated my setup to Rocket.Chat 6.12.1.

Yep

Sep 24 '24 13:09 Mal0815

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.

Oct 08 '24 18:10 github-actions[bot]

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.

The issue still persists. No Rocket.Chat update was released in the meantime.

The fact that I have to write a comment in this thread every two weeks because there is no activity by the Rocket.Chat team is slightly annoying.

Oct 08 '24 18:10 paulchen

Rocket is a big org and paid customers come first.

If you have a paid subscription you can contact support directly.

Otherwise, as you know, it is open source. YMMV. There are no guarantees.

I know devs have been putting in hours on v7 which is their focus right now. Doesn't help.

Also difficult to reproduce so hard to debug.

Oct 08 '24 19:10 reetp

If the Rocket team cannot get to this issue within ten days, they should turn off the bot.

Oct 08 '24 19:10 RavuAlHemio

If the Rocket team cannot get to this issue within ten days, they should turn off the bot.

This.

Just to be clear, I don't expect anything to happen within any timeframe. I'm also fine with closing issues that have been waiting for input from the reporter for a long time. However, I don't see any point in generating two comments in this issue every two weeks just to make sure it doesn't get closed.

Oct 08 '24 19:10 paulchen

Regrettably a large number of issues are just left and not closed by the OPs even if they have a solution, or possibly fixed but not tagged.

Hence umpteen thousand open issues, most of which in reality could be closed.

This is an exception to the rule.

Note. When I worked at Rocket we did take the bot off, which is fine if managed continuously.

But I left, and again, no one in the community steps up to help. If the community isn't bothered to help? 🤷‍♂️

You reap what you sow.

I do what I can, as and when I can. Currently trying to relax with a glass of wine on the sofa after a long day :-)

The dev did respond, but without being able to recreate this it will be difficult, and I'd imagine the short answer might be to remove apps and install fresh versions to see if it clears it.

You did that on the test vm and it worked?

Oct 08 '24 21:10 reetp

The dev did respond, but without being able to recreate this it will be difficult, and I'd imagine the short answer might be to remove apps and install fresh versions to see if it clears it.

You did that on the test vm and it worked?

I just tried that once more, to no avail. This error showed up:

From the logs:

2024-10-09T19:48:07.426320+02:00 alpha rocketchat-dev[6250]: {"level":35,"time":"2024-10-09T17:48:07.426Z","pid":1,"hostname":"47edcc1048c6","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.1.1 Chrome/126.0.6478.234 Electron/31.6.0 Safari/537.36","length":"85","host":"localhost:3001","referer":"https://chat-dev.rueckgr.at/marketplace/explore","remoteIP":"188.23.44.241","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":2857,"msg":"App already has an associated runtime"}

Oct 09 '24 17:10 paulchen

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.

Oct 23 '24 18:10 github-actions[bot]

I updated my setup to Rocket.Chat 6.13.0 on Oct 13, soon after its release.

The issue persists.

Currently, GIPHY works while Tenor doesn't. However, after the next restart of the container, things will be different once more.

Oct 23 '24 18:10 paulchen

same issue occurs with the jitsi app (among others) startup after upgrade from 6.9.x to 6.12.2 shows:

Oct 30 08:31:31 server rocketchat[1152770]: Error while compiling the App "Jitsi (3b387ba9-f57c-44c6-9810-8c0256abd64c)":
Oct 30 08:31:31 server rocketchat[1152770]: Error: [3b387ba9-f57c-44c6-9810-8c0256abd64c] Timeout: app process not ready
Oct 30 08:31:31 server rocketchat[1152770]:    at Timeout._onTimeout (/rockechat/programs/server/npm/node_modules/@rocket.chat/apps-engine/server/runtime/deno/AppsEngineDenoRuntime.js:216:55)
Oct 30 08:31:31 server rocketchat[1152770]:    at listOnTimeout (internal/timers.js:557:17)
Oct 30 08:31:31 server rocketchat[1152770]:    at processTimers (internal/timers.js:500:7)
Oct 30 08:31:31 server rocketchat[1152770]: Failed to startup Deno subprocess Error: spawn /rockechat/programs/server/npm/node_modules/deno-bin/bin/deno EACCES
Oct 30 08:31:31 server rocketchat[1152770]:    at Process.ChildProcess._handle.onexit (internal/child_process.js:277:19)
Oct 30 08:31:31 server rocketchat[1152770]:    at onErrorNT (internal/child_process.js:472:16)
Oct 30 08:31:31 server rocketchat[1152770]:    at processTicksAndRejections (internal/process/task_queues.js:82:21) {
Oct 30 08:31:31 server rocketchat[1152770]:  errno: -13,
Oct 30 08:31:31 server rocketchat[1152770]:  code: 'EACCES',
Oct 30 08:31:31 server rocketchat[1152770]:  syscall: 'spawn /rockechat/programs/server/npm/node_modules/deno-bin/bin/deno',
Oct 30 08:31:31 server rocketchat[1152770]:  path: '/rockechat/programs/server/npm/node_modules/deno-bin/bin/deno',
Oct 30 08:31:31 server rocketchat[1152770]:  spawnargs: [
Oct 30 08:31:31 server rocketchat[1152770]:    'run',
Oct 30 08:31:31 server rocketchat[1152770]:    '--allow-net',
Oct 30 08:31:31 server rocketchat[1152770]:    '--allow-read=/rockechat/programs/server/npm/node_modules/@rocket.chat/apps-engine,/rockechat/programs/server/npm/node_modules',
Oct 30 08:31:31 server rocketchat[1152770]:    '--allow-env=NODE_EXTRA_CA_CERTS',
Oct 30 08:31:31 server rocketchat[1152770]:    '/rockechat/programs/server/npm/node_modules/@rocket.chat/apps-engine/deno-runtime/main.ts',
Oct 30 08:31:31 server rocketchat[1152770]:    '--subprocess',
Oct 30 08:31:31 server rocketchat[1152770]:    '684202ed-1461-4983-9ea7-fde74b15026c'
Oct 30 08:31:31 server rocketchat[1152770]:  ]
Oct 30 08:31:31 server rocketchat[1152770]: }

this may be a symptom from deno? (a requirement?) which also fails to start/spawn/run

Oct 30 08:29:34 server rocketchat[1152565]: Failed to startup Deno subprocess Error: spawn /rocketchat/programs/server/npm/node_modules/deno-bin/bin/deno EACCES
Oct 30 08:29:34 server rocketchat[1152565]:    at Process.ChildProcess._handle.onexit (internal/child_process.js:277:19)
Oct 30 08:29:34 server rocketchat[1152565]:    at onErrorNT (internal/child_process.js:472:16)
Oct 30 08:29:34 server rocketchat[1152565]:    at processTicksAndRejections (internal/process/task_queues.js:82:21) {
Oct 30 08:29:34 server rocketchat[1152565]:  errno: -13,
Oct 30 08:29:34 server rocketchat[1152565]:  code: 'EACCES',
Oct 30 08:29:34 server rocketchat[1152565]:  syscall: 'spawn /rocketchat/programs/server/npm/node_modules/deno-bin/bin/deno',
Oct 30 08:29:34 server rocketchat[1152565]:  path: '/rocketchat/programs/server/npm/node_modules/deno-bin/bin/deno',
Oct 30 08:29:34 server rocketchat[1152565]:  spawnargs: [
Oct 30 08:29:34 server rocketchat[1152565]:    'run',
Oct 30 08:29:34 server rocketchat[1152565]:    '--allow-net',
Oct 30 08:29:34 server rocketchat[1152565]:    '--allow-read=/rocketchat/programs/server/npm/node_modules/@rocket.chat/apps-engine,/rocketchat/programs/server/npm/node_modules',
Oct 30 08:29:34 server rocketchat[1152565]:    '--allow-env=NODE_EXTRA_CA_CERTS',
Oct 30 08:29:34 server rocketchat[1152565]:    '/rocketchat/programs/server/npm/node_modules/@rocket.chat/apps-engine/deno-runtime/main.ts',
Oct 30 08:29:34 server rocketchat[1152565]:    '--subprocess',
Oct 30 08:29:34 server rocketchat[1152565]:    '684202ed-1461-4983-9ea7-fde74b15026c'
Oct 30 08:29:34 server rocketchat[1152565]:  ]
Oct 30 08:29:34 server rocketchat[1152565]: }

Note: this server has no internet access

attempting to build and manually upload with rc-apps deploy

   Starting App Deployment to Server

   Getting Server Info... ✓
2024-10-30 09:14:14.921 WARN  App has external module(s) as dependency
   Packaging the app... ✓
   Uploading App... ✖
 ›   Error:    ⟿  Error: Deployment error: App already has an associated runtime

removing and attempting to re-install the app has no effect

edit: just tried going from 6.9.5 -> 6.10.6 ->results in same issue

Oct 30 '24 08:10 amsnek

Just tried this on Rocket.Chat 7.0.0. Unfortunately, the issue still persists. I see the Timeout: app process not ready error during startup.

After startup, Tenor is disabled. When I try to enable it, the error message "Apps_Error_The App had compiler errors, can not enable it." is shown. The logs contain:

{"level":35,"time":"2024-11-04T19:30:06.459Z","pid":1,"hostname":"2f750f9dd7d3","name":"API","method":"POST","url":"/api/apps/ab4728ec-613e-472f-a24c-b48a77aacfff/status","userId":"xq7oE4mtb2nEcfe2m","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36","length":"29","host":"localhost:3001","referer":"https://chat-dev.rueckgr.at/marketplace/installed","remoteIP":"2001:871:261:9c1a:ef5c:1ac:edce:13fe","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/src/server/AppManager.ts:446:19)\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 processTicksAndRejections (node:internal/process/task_queues:95:5)"},"status":400,"responseTime":3,"msg":"The App had compiler errors, can not enable it."}

GIPHY currently shows as enabled, but it doesn't seem to work (typing /giphy doesn't do anything). I just stumbled upon a new error message when trying to disable it: "Apps_Error_Can not disable an App which is not enabled."

{"level":35,"time":"2024-11-04T19:45:18.431Z","pid":1,"hostname":"b0cc24e52cf1","name":"API","method":"POST","url":"/api/apps/8b882242-0cb7-419f-87d8-93b1d09e1ec2/status","userId":"xq7oE4mtb2nEcfe2m","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36","length":"30","host":"localhost:3001","referer":"https://chat-dev.rueckgr.at/marketplace/installed","remoteIP":"2001:871:261:9c1a:ef5c:1ac:edce:13fe","err":{"type":"Error","message":"Can not disable an App which is not enabled.","stack":"Error: Can not disable an App which is not enabled.\n    at AppManager.<anonymous> (/app/bundle/programs/server/npm/node_modules/@rocket.chat/apps-engine/src/server/AppManager.ts:855: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 processTicksAndRejections (node:internal/process/task_queues:95:5)"},"status":400,"responseTime":1,"msg":"Can not disable an App which is not enabled."}

Nov 04 '24 19:11 paulchen

We are checking into it paulchen.

Nov 04 '24 19:11 casalsgh

Hey everyone. I've tried replicating this issue, with no success. Here is the docker compose file I've used to start the service on version 6.9.5:

volumes:
  mongodb_data: { driver: local }

services:
  rocketchat:
    image: registry.rocket.chat/rocketchat/rocket.chat:6.9.5
    environment:
      MONGO_URL: "${MONGO_URL:-\
        mongodb://${MONGODB_ADVERTISED_HOSTNAME:-mongodb}:${MONGODB_INITIAL_PRIMARY_PORT_NUMBER:-27017}/\
        ${MONGODB_DATABASE:-rocketchat}?replicaSet=${MONGODB_REPLICA_SET_NAME:-rs0}}"
      MONGO_OPLOG_URL: "${MONGO_OPLOG_URL:\
        -mongodb://${MONGODB_ADVERTISED_HOSTNAME:-mongodb}:${MONGODB_INITIAL_PRIMARY_PORT_NUMBER:-27017}/\
        local?replicaSet=${MONGODB_REPLICA_SET_NAME:-rs0}}"
      ROOT_URL: ${ROOT_URL:-http://localhost:${HOST_PORT:-3000}}
      PORT: ${PORT:-3000}
      DEPLOY_METHOD: docker
      DEPLOY_PLATFORM: ${DEPLOY_PLATFORM}
    depends_on:
      mongodb:
        condition: service_started
    ports:
      - 3000:3000

  mongodb:
    image: docker.io/bitnami/mongodb:${MONGODB_VERSION:-6.0}
    volumes:
      - mongodb_data:/bitnami/mongodb
    environment:
      MONGODB_REPLICA_SET_MODE: primary
      MONGODB_REPLICA_SET_NAME: ${MONGODB_REPLICA_SET_NAME:-rs0}
      MONGODB_PORT_NUMBER: ${MONGODB_PORT_NUMBER:-27017}
      MONGODB_INITIAL_PRIMARY_HOST: ${MONGODB_INITIAL_PRIMARY_HOST:-mongodb}
      MONGODB_INITIAL_PRIMARY_PORT_NUMBER: ${MONGODB_INITIAL_PRIMARY_PORT_NUMBER:-27017}
      MONGODB_ADVERTISED_HOSTNAME: ${MONGODB_ADVERTISED_HOSTNAME:-mongodb}
      MONGODB_ENABLE_JOURNAL: ${MONGODB_ENABLE_JOURNAL:-true}
      ALLOW_EMPTY_PASSWORD: ${ALLOW_EMPTY_PASSWORD:-yes}

I've then proceeded to install the apps mentioned here in the thread (Giphy, Tenor, Jitsi) from the marketplace, and after all of them were enabled, I changed the rocket.chat version in my docker compose file and redeployed using docker compose up -d. All apps were still enabled after the upgrade.

@paulchen @amsnek what version of the apps are you on?

Update: I've also tried creating a new workspace all the way back in v3.16.0, and followed the upgrade guide to v6.9.5, then v6.11.1 (same docker compose file, just new environment). At the end of the process, Tenor and Giphy (the only ones I've used this time) were correctly enabled as my previous attempt

Nov 05 '24 20:11 d-gubert

hello @d-gubert Thanks you for looking into this. Jitsi App Version installed (before updating rocketchat version):

Jitsi
Enabled*
Rocket.Chat Technologies Corp. | Version 2.0.4

Latest would be 2.1.0 -> would it make sense updating the App before updating Rocket.Chat? This is something I have not yet tried.

It is maybe important to note that I dont install via Marketplace directly since this instance has no Internet Access at all. Apps are installed "locally/offline" via rc-deploy.

Nov 06 '24 07:11 amsnek

Hello, I updated the Jitsi App to 2.1.1 while still on Rocketchat 6.9.5

Then Rocketchat was updated from 6.9.5 -> 6.11.1. After the Update the errors persisted, see error Messages below. Application does not start/compile, could not be used in Rocketchat.

However after looking again at the error for "programs/server/npm/node_modules/deno-bin/bin/deno" -> errno: -13 / EACCESS -> I noticed that the binary has had no executable flag set -> this may be due to (my) build process (? -> will investigate that) -> after setting the binary to executeable, the compilation errors dissapeared and my jitsi.app worked in 6.11.1

will try to update at 6.13.0 as next step

deno binary error (due to missing execute rights in my case)

Nov  6 09:57:22 server rocketchat[2533103]: Failed to startup Deno subprocess Error: spawn /rocketchat/programs/server/npm/node_modules/deno-bin/bin/deno EACCES
Nov  6 09:57:22 server rocketchat[2533103]:    at Process.ChildProcess._handle.onexit (internal/child_process.js:277:19)
Nov  6 09:57:22 server rocketchat[2533103]:    at onErrorNT (internal/child_process.js:472:16)
Nov  6 09:57:22 server rocketchat[2533103]:    at processTicksAndRejections (internal/process/task_queues.js:82:21) {
Nov  6 09:57:22 server rocketchat[2533103]:  errno: -13,
Nov  6 09:57:22 server rocketchat[2533103]:  code: 'EACCES',
Nov  6 09:57:22 server rocketchat[2533103]:  syscall: 'spawn /rocketchat/programs/server/npm/node_modules/deno-bin/bin/deno',
Nov  6 09:57:22 server rocketchat[2533103]:  path: '/rocketchat/programs/server/npm/node_modules/deno-bin/bin/deno',
Nov  6 09:57:22 server rocketchat[2533103]:  spawnargs: [
Nov  6 09:57:22 server rocketchat[2533103]:    'run',
Nov  6 09:57:22 server rocketchat[2533103]:    '--allow-net',
Nov  6 09:57:22 server rocketchat[2533103]:    '--allow-read=/rocketchat/programs/server/npm/node_modules/@rocket.chat/apps-engine,/rocketchat/programs/server/npm/node_modules',
Nov  6 09:57:22 server rocketchat[2533103]:    '--allow-env=NODE_EXTRA_CA_CERTS',
Nov  6 09:57:22 server rocketchat[2533103]:    '/rocketchat/programs/server/npm/node_modules/@rocket.chat/apps-engine/deno-runtime/main.ts',
Nov  6 09:57:22 server rocketchat[2533103]:    '--subprocess',
Nov  6 09:57:22 server rocketchat[2533103]:    '3b387ba9-f57c-44c6-9810-8c0256abd64c'
Nov  6 09:57:22 server rocketchat[2533103]:  ]
Nov  6 09:57:22 server rocketchat[2533103]: }

Nov 06 '24 09:11 amsnek