KIX Pro 18 v34.1: frontend startet nicht

[kerstin]

Hallo,

ich habe heute unseren Testserver auf KIX Pro 18 v34.1 geupdatet und das frontend bleibt scheinbar in einem Endlosloop mit folgender Fehlermeldung hängen:

Code Auswählen Erweitern

frontend-1  | Error: EEXIST: file already exists, mkdir '/opt/kix/.cache'
frontend-1  | Rendered by lasso-slot:head
frontend-1  | Rendered by lasso-slot:body
frontend-1  |     at Object.mkdirSync (node:fs:1364:26)
frontend-1  |     at mkdirpManualSync (/opt/kix/node_modules/lasso/node_modules/mkdirp/lib/mkdirp-manual.js:48:10)
frontend-1  |     at mkdirpManualSync (/opt/kix/node_modules/lasso/node_modules/mkdirp/lib/mkdirp-manual.js:52:43)
frontend-1  |     at mkdirpManualSync (/opt/kix/node_modules/lasso/node_modules/mkdirp/lib/mkdirp-manual.js:52:43)
frontend-1  |     at mkdirpManualSync (/opt/kix/node_modules/lasso/node_modules/mkdirp/lib/mkdirp-manual.js:52:43)
frontend-1  |     at mkdirpNativeSync (/opt/kix/node_modules/lasso/node_modules/mkdirp/lib/mkdirp-native.js:33:14)
frontend-1  |     at Function.mkdirpSync [as sync] (/opt/kix/node_modules/lasso/node_modules/mkdirp/index.js:21:7)
frontend-1  |     at new LassoCache (/opt/kix/node_modules/lasso/src/LassoCache.js:112:16)
frontend-1  |     at Lasso.getLassoCache (/opt/kix/node_modules/lasso/src/Lasso.js:698:54)
frontend-1  |     at Lasso.createLassoContext (/opt/kix/node_modules/lasso/src/Lasso.js:776:35)
frontend-1  |     at Lasso.lassoPage (/opt/kix/node_modules/lasso/src/Lasso.js:782:59)
frontend-1  |     at doLassoPage (/opt/kix/node_modules/@lasso/marko-taglib/taglib/page-tag.js:70:21)
frontend-1  |     at render (/opt/kix/node_modules/@lasso/marko-taglib/taglib/page-tag.js:160:5)
frontend-1  |     at render (/opt/kix/node_modules/@lasso/marko-taglib/taglib/slot-tag.js:118:5)
frontend-1  |     at render (/opt/kix/node_modules/@lasso/marko-taglib/taglib/head-tag.js:16:3)
frontend-1  |     at renderTagHelper (/opt/kix/node_modules/marko/dist/runtime/helpers/render-tag.js:15:77)
frontend-1  |     at _marko_template._.t (/opt/kix/dist/frontend-applications/agent-portal/modules/agent-portal/webapp/application/index.marko:30:26)
frontend-1  |     at renderer (/opt/kix/node_modules/marko/dist/runtime/components/renderer.js:218:5)
frontend-1  |     at safeRender (/opt/kix/node_modules/marko/dist/runtime/renderable.js:9:5)
frontend-1  |     at Template.render (/opt/kix/node_modules/marko/dist/runtime/renderable.js:191:14)
frontend-1  |     at ServerResponse.renderMarkoTemplate [as marko] (/opt/kix/node_modules/@marko/express/dist/cjs/index.js:20:10)
frontend-1  |     at ApplicationRouter.handleRoute (/opt/kix/dist/frontend-applications/agent-portal/server/routes/ApplicationRouter.js:78:17)
frontend-1  |     at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
frontend-1  |     at async ApplicationRouter.getModule (/opt/kix/dist/frontend-applications/agent-portal/server/routes/ApplicationRouter.js:49:9)
sollte das nicht eigentlich im Patch release gefixt sein, oder ist das ein anderen Fehler?

Danke und Gruß,
Kerstin

[Frank Niethardt]

Moin Kerstin,

bei uns kam der Fehler, weil der User unter dem der Docker läuft, keine Schreibrechte auf das root-Verzeichnis des volumes hatte. Ich hab damals einfach ein chown gemacht.
An der Stelle versucht er da ein Verzeichnis zu erstellen, aber dort gibt es bereits einen Symlink, ohne dass dahinter ein Verzeichnis wäre.

Sprich meine Lösung war:

Code Auswählen Erweitern

$ sudo chown 110010100 /var/lib/docker/volumes/testkix_frontend/_data/.cache
Viele Grüße
Frank

[kerstin]

Moin Frank,

Da ich die letzten Wochen anderweitig beschäftigt war, ein etwas verspätetes Dankeschön :-)
Das hat tatsächlich den obigen Fehler behoben, aber unser frontend hat wohl noch ein weiteres Problem - das ist allerdings, soweit ich das überprüfen kann, unabhängig von dem Update. Folgende Fehlermeldung kommt und dann passiert (am frontend) nichts mehr:

Code Auswählen Erweitern

Tue Feb 18 2025 15:54:08 GMT+0100 (Central European Standard Time) - error: 47 - Error during HTTP (session/user) GET request. {
  "config": {
    "url": "http://backend:8080/api/v1/session/user",
    "method": "get",
    "headers": {
      "Accept": "application/json, text/plain, */*",
      "Authorization": "Token xxx",
      "KIX-Request-ID": "",
      "User-Agent": "axios/0.21.4"
    },
    "params": {
      "include": "Preferences,RoleIDs,Contact,DynamicFields"
    },
    "transformRequest": [
     null
   ],
    "transformResponse": [
     null
   ],
    "timeout": 0,
    "xsrfCookieName": "XSRF-TOKEN",
    "xsrfHeaderName": "X-XSRF-TOKEN",
    "maxContentLength": -1,
    "maxBodyLength": -1,
    "transitional": {
      "silentJSONParsing": true,
      "forcedJSONParsing": true,
      "clarifyTimeoutError": false
    }
  }
}
Tue Feb 18 2025 15:54:08 GMT+0100 (Central European Standard Time) - error: 47 - (401) Unauthorized User is not authorized. The requested operation cannot be executed. {
  "stackTrace": "\n    at /opt/kix/dist/frontend-applications/agent-portal/server/services/HttpService.js:325:32\n    at process.processTicksAndRejections (node:internal/process/task_queues:105:5)\n    at async /opt/kix/dist/frontend-applications/agent-portal/server/services/HttpService.js:316:30"
}
Tue Feb 18 2025 15:54:08 GMT+0100 (Central European Standard Time) - error: 47 - An unhandledRejection occured: {
  "Code": "Unauthorized",
  "Message": "User is not authorized. The requested operation cannot be executed.",
  "StatusCode": 401,
  "stackTrace": "\n    at process.emit (node:events:524:28)\n    at emitUnhandledRejection (node:internal/process/promises:252:13)\n    at throwUnhandledRejectionsMode (node:internal/process/promises:388:19)\n    at processPromiseRejections (node:internal/process/promises:475:17)\n    at process.processTicksAndRejections (node:internal/process/task_queues:106:32)"
}
Tue Feb 18 2025 15:54:08 GMT+0100 (Central European Standard Time) - error: 47 - [object Object] {
  "Code": "Unauthorized",
  "Message": "User is not authorized. The requested operation cannot be executed.",
  "StatusCode": 401,
  "stackTrace": "\n    at process.emit (node:events:524:28)\n    at emitUnhandledRejection (node:internal/process/promises:252:13)\n    at throwUnhandledRejectionsMode (node:internal/process/promises:388:19)\n    at processPromiseRejections (node:internal/process/promi
ses:475:17)\n    at process.processTicksAndRejections (node:internal/process/task_queues:106:32)"
}
Ich kann den Fehler vermeiden, wenn ich das längst veraltete docker-compose_ssp.yml einbinde. Die ssp_legacy ports bzw. der entsprechende serverblock in proxy config, environment und docker-compose.yml sind entfernt. Der Testserver, von dem das log stammt, ist inzwischen theoretisch auf v34.3.
Kann mir da vielleicht jemand weiterhelfen?

Danke und Gruß,
Kerstin

[AndreasU]

Hi,
wir haben in unserem Testsystem (v34.3) leider das gleiche Problem wie bei Kerstin (das Prod läuft zum Glück ohne Probleme).
Lösungsvorschläge vom Support waren bis jetzt diese beiden Sachen:

rm /var/lib/docker/volumes/kix_shared/_data/backend_api_token
(kix_shared muss ggf. sich je nach Namen Ihres Stacks angepasst werden)
Hiernach müsste der Stack neu gestartet werden
Sollte das Frontend hiernach noch nicht starten, müssten noch folgende Befehle ausgeführt werden:
docker exec -it kix-frontend-1 rm -r /opt/kix/.cache/lasso
docker restart kix-frontend-1
(Auch hier müssten ggf. die Containernamen angepasst werden. Z.B. kix_frontend_1)

Das Löschen des API Tokens bringt leider nichts. Auch das löschen des Cache bringt nichts, da ist auch nach dem Start des Conainers nichts zum löschen vorhanden. Die einzige Lösung die bisher funktioniert ist, den frontend Container einfach 2-3min nach dem Start des Stacks nochmal zu starten, dann fährt auch das Frontend korrekt hoch. Gibt es hier noch eine andere Lösung?

Das Problem tritt seit dem Update im Januar auf v34 auf.

Viele Grüße

Andreas

[kerstin]

Hallo Andreas,

Danke für die Tipps. Das Löschen des API Tokens hatte ich auch schon mal probiert, weil es mir aufgrund der Fehlermeldung verdächtig vorkam - hat bei uns aber auch nichts verändert. Dein Hinweis, dass das der Neustart des frontends nach einigen Minuten funktioniert bestärkt meine Vermutung, dass das Einbinden des veralteten docker-compose_ssp.yml bzw. das dadurch entstehende Starten des SSP legacy containers dem frontend einfach ein timelag verschafft. Daher habe ich mir alle logs nochmal im Zusammenhang angeschaut. Und tatsächlich tritt sowohl bei erfolgreichen, als auch gescheitertem Start des frontends folgender "Fehler" im backend auf:

Code Auswählen Erweitern

backend-1   | [Wed Feb 19 08:34:38 2025] plackup: DBD::Pg::st execute failed: server closed the connection unexpectedly
backend-1   | [Wed Feb 19 08:34:38 2025] plackup: This probably means the server terminated abnormally
backend-1   | [Wed Feb 19 08:34:38 2025] plackup: before or while processing the request. at /opt/kix/Kernel/System/DB.pm line 791.
backend-1   | [Wed Feb 19 08:34:38 2025][Error][Kernel::System::Token::ValidateToken][88] server closed the connection unexpectedly
backend-1   | This probably means the server terminated abnormally
backend-1   | before or while processing the request., SQL: 'SELECT token, last_request_time FROM token WHERE token = ?'
backend-1   | ERROR: API-1 Perl: 5.36.0 OS: linux Time: Wed Feb 19 08:34:38 2025
backend-1   |
backend-1   |  Message: server closed the connection unexpectedly
backend-1   | This probably means the server terminated abnormally
backend-1   | before or while processing the request., SQL: 'SELECT token, last_request_time FROM token WHERE token = ?'
backend-1   |
backend-1   |  RemoteAddress: 192.168.0.5
backend-1   |  RequestURI: /system/config/definitions
backend-1   |
backend-1   |  Traceback (63):
backend-1   |    Module: Kernel::System::Token::ValidateToken Line: 88
backend-1   |    Module: Kernel::API::Provider::REST::CheckAuthorization Line: 75
backend-1   |    Module: Kernel::API::Provider::Run Line: 196
backend-1   |    Module: (eval) Line: 72
backend-1   |    Module: Plack::Sandbox::_2fopt_2fkix_2fbin_2fserver_2fapp_2epsgi::__ANON__ Line: 70
backend-1   |    Module: CGI::Emulate::PSGI::__ANON__ (v0.23) Line: 30
backend-1   |    Module: Plack::Middleware::StackTrace::try {...}  Line: 38
backend-1   |    Module: (eval) (v0.31) Line: 100
backend-1   |    Module: Try::Tiny::try (v0.31) Line: 93
backend-1   |    Module: Plack::Middleware::StackTrace::call Line: 42
backend-1   |    Module: Plack::Component::__ANON__ Line: 50
backend-1   |    Module: Plack::Middleware::AccessLog::Timed::call Line: 17
backend-1   |    Module: Plack::Component::__ANON__ Line: 50
backend-1   |    Module: Plack::Middleware::Deflater::call (v0.12) Line: 20
backend-1   |    Module: Plack::Component::__ANON__ Line: 50
backend-1   |    Module: Plack::Middleware::Refresh::call Line: 23
backend-1   |    Module: Plack::Component::__ANON__ Line: 50
backend-1   |    Module: (eval) Line: 145
backend-1   |    Module: Plack::Util::run_app Line: 145
backend-1   |    Module: Starman::Server::dispatch_request Line: 195
backend-1   |    Module: Starman::Server::process_request Line: 299
backend-1   |    Module: Net::Server::run_client_connection (v2.013) Line: 72
backend-1   |    Module: (eval) Line: 226
backend-1   |    Module: Net::Server::PreFork::run_child Line: 226
backend-1   |    Module: Net::Server::PreFork::run_n_children Line: 184
backend-1   |    Module: Net::Server::PreFork::loop Line: 107
backend-1   |    Module: Net::Server::run (v2.013) Line: 58
backend-1   |    Module: Starman::Server::run Line: 106
backend-1   |    Module: Plack::Handler::Starman::run Line: 25
backend-1   |    Module: Plack::Loader::run Line: 84
backend-1   |
backend-1   | [Wed Feb 19 08:34:38 2025] plackup: DBD::Pg::st fetchrow_array failed: no statement executing at /opt/kix/Kernel/System/DB.pm line 859.
backend-1   |
backend-1   | API ERROR: ProcessID: 63 Time: 2025-02-19 08:34:38
backend-1   |
backend-1   |      Method: POST
backend-1   |    Resource: /system/config/definitions
backend-1   |    Duration: 21 ms
backend-1   |  HTTPStatus: 401 Unauthorized
backend-1   |        Code: Unauthorized
backend-1   |     Message: User is not authorized. The requested operation cannot be executed.
backend-1   |
backend-1   | 192.168.0.5 - - [19/Feb/2025:08:34:38 +0100] "POST /api/v1/system/config/definitions HTTP/1.1" 401 103 64753
backend-1   | [Wed Feb 19 08:34:38 2025] plackup: DBD::Pg::st execute failed: server closed the connection unexpectedly
backend-1   | [Wed Feb 19 08:34:38 2025] plackup: This probably means the server terminated abnormally
backend-1   | [Wed Feb 19 08:34:38 2025] plackup: before or while processing the request. at /opt/kix/Kernel/System/DB.pm line 791.
backend-1   | [Wed Feb 19 08:34:38 2025][Error][Kernel::System::Token::ValidateToken][88] server closed the connection unexpectedly
backend-1   | This probably means the server terminated abnormally
backend-1   | before or while processing the request., SQL: 'SELECT token, last_request_time FROM token WHERE token = ?'
backend-1   | ERROR: API-1 Perl: 5.36.0 OS: linux Time: Wed Feb 19 08:34:38 2025
backend-1   |
backend-1   |  Message: server closed the connection unexpectedly
backend-1   | This probably means the server terminated abnormally
backend-1   | before or while processing the request., SQL: 'SELECT token, last_request_time FROM token WHERE token = ?'
backend-1   |
backend-1   |  RemoteAddress: 192.168.0.5
backend-1   |  RequestURI: /system/config/definitions
backend-1   |
backend-1   |  Traceback (64):
backend-1   |    Module: Kernel::System::Token::ValidateToken Line: 88
backend-1   |    Module: Kernel::API::Provider::REST::CheckAuthorization Line: 75
backend-1   |    Module: Kernel::API::Provider::Run Line: 196
backend-1   |    Module: (eval) Line: 72
backend-1   |    Module: Plack::Sandbox::_2fopt_2fkix_2fbin_2fserver_2fapp_2epsgi::__ANON__ Line: 70
backend-1   |    Module: CGI::Emulate::PSGI::__ANON__ (v0.23) Line: 30
backend-1   |    Module: Plack::Middleware::StackTrace::try {...}  Line: 38
backend-1   |    Module: (eval) (v0.31) Line: 100
backend-1   |    Module: Try::Tiny::try (v0.31) Line: 93
backend-1   |    Module: Plack::Middleware::StackTrace::call Line: 42
backend-1   |    Module: Plack::Component::__ANON__ Line: 50
backend-1   |    Module: Plack::Middleware::AccessLog::Timed::call Line: 17
backend-1   |    Module: Plack::Component::__ANON__ Line: 50
backend-1   |    Module: Plack::Middleware::Deflater::call (v0.12) Line: 20
backend-1   |    Module: Plack::Component::__ANON__ Line: 50
backend-1   |    Module: Plack::Middleware::Refresh::call Line: 23
backend-1   |    Module: Plack::Component::__ANON__ Line: 50
backend-1   |    Module: (eval) Line: 145
backend-1   |    Module: Plack::Util::run_app Line: 145
backend-1   |    Module: Starman::Server::dispatch_request Line: 195
backend-1   |    Module: Starman::Server::process_request Line: 299
backend-1   |    Module: Net::Server::run_client_connection (v2.013) Line: 72
backend-1   |    Module: (eval) Line: 226
backend-1   |    Module: Net::Server::PreFork::run_child Line: 226
backend-1   |    Module: Net::Server::PreFork::run_n_children Line: 184
backend-1   |    Module: Net::Server::PreFork::loop Line: 107
backend-1   |    Module: Net::Server::run (v2.013) Line: 58
backend-1   |    Module: Starman::Server::run Line: 106
backend-1   |    Module: Plack::Handler::Starman::run Line: 25
backend-1   |    Module: Plack::Loader::run Line: 84
backend-1   |
backend-1   | [Wed Feb 19 08:34:38 2025] plackup: DBD::Pg::st fetchrow_array failed: no statement executing at /opt/kix/Kernel/System/DB.pm line 859.
backend-1   |
backend-1   | API ERROR: ProcessID: 64 Time: 2025-02-19 08:34:38
backend-1   |
backend-1   |      Method: POST
backend-1   |    Resource: /system/config/definitions
backend-1   |    Duration: 20 ms
backend-1   |  HTTPStatus: 401 Unauthorized
backend-1   |        Code: Unauthorized
backend-1   |     Message: User is not authorized. The requested operation cannot be executed.
backend-1   |
Im Fall des erfolgreichen Starts startet das frontend erst nach diesem Fehler (wahrscheinlich aufgrund der zwischenzeitlichen Anfragen des SSP1 ans backend), während im Fall des erfolglosen Starts das frontend bereits vor dem Fehler startet und augenscheinlich daran dann scheitert.

Jetzt wäre also die Frage, was es mit dieser Fehlermeldung auf sich hat? Warum bricht die Verbindung zur Datenbank kurz nach dem Starten nochmal ab? Kann das evtl. mit Update von Postgresql auf v15 zu tun haben?

@Andreas - läuft Eure Produktionsversion denn auch auf v34.3? (den Schritt habe ich bisher noch nicht gewagt ;-))

Danke und schöne Grüße,
Kerstin

[AndreasU]

@Kerstin 
Wir sind gerade am Testing der v34.3, v34.2 mussten wir aufgrund der Probleme im SSP auslassen. Wenn alles positiv verläuft, dann stellen wir am Wochenende das Prod um. Dort haben wir das Problem mit dem nicht startenden Frontend zum Glück nicht.

[kerstin]

Moin Andreas,

Danke für die Info. Wir haben die v34.3 jetzt auch druchgetestet, aber bevor ich nicht sicher bin, dass das frontend auf dem Produktionsserver nicht auch hängen bleibt, lassen wir den lieber noch auf v33

Es scheint jetzt aber so, als hätte ich eine "Lösung" oder zumindest einen workaround gefunden, der nicht den manuellen Neustart des frontends beinhaltet (was für und keine Option wäre). Ich habe im docker-compose file für die dependency des frontends zum backend eine entsprechende condition mit health-check eingefügt (s. https://docs.docker.com/reference/compose-file/services/#long-syntax-1), konkret habe ich im depend_on des frontends folgendes gesetzt:

Code Auswählen Erweitern

   depends_on:
      backend:
        condition: service_healthy
      redis:
        condition: service_started

Das scheint zu funktionieren, lustiger Weise auch ohne, dass ich für das backend einen health-check definiere. Ich gehe davon aus, dass der health-check bereits im dockerfile des backend images definiert wurde.

Wenn ich dieses veränderte docker-compose file zum Start nuzte, sehe ich zwar immernoch einige Meldungen zu unautorisierten Requests im FE-Container-Log, aber keinen Warnung mehr, dass die Datenbank nicht zu erreichen ist und das frontend kommt problemlos hoch. Der Nachteil ist, dass das frontend halt wirklich erst startet, wenn das backend healthy ist, was dazu führt, dass man während des Starts im Webinterface nicht mehr das "wartende" KIX-Logo sieht, sondern im Zweifelsfall eine "Netzwerk-Zeitüberschreitung". Das ist nicht so schön, aber ich denke damit können wir besser leben als damit, dass das frontend gar nicht hochkommt ;-)

Schöne Grüße,
Kerstin