System Down: "failed (111: Connection refused) while connecting to upstream"

[mplan]

Hallo,
gestern abend habe ich das Kix 18 (Build 3851) (Test-)System gestoppt und heute wieder gestartet (Docker in Windows).
Jetzt kann ich mich nicht mehr anmelden und das System steht. Das Log zeigt Meldungen:

Code: [Auswählen]

backend_1   | API ERROR: ProcessID: 95 Time: 2021-12-28 09:03:41
backend_1   |
backend_1   |      Method: DELETE
backend_1   |    Resource: /system/config/definitions/ticket-article-new-form-group-data
backend_1   |    Duration: 62 ms
backend_1   |  HTTPStatus: 404 Not Found
backend_1   |        Code: Object.NotFound
backend_1   |     Message: Cannot delete SysConfigOptionDefinition. SysConfigOptionDefinition 'ticket-article-new-form-group-data' not found.
backend_1   |
backend_1   | ::ffff:172.21.0.5 - - [28/Dec/2021:09:03:41 +0100] "DELETE /api/v1/system/config/definitions/ticket-article-new-form-page HTTP/1.1" 404 - "-" "axios/0.21.4"
backend_1   | ::ffff:172.21.0.5 - - [28/Dec/2021:09:03:41 +0100] "DELETE /api/v1/system/config/definitions/ticket-article-new-form-page HTTP/1.1" 404 147 185115
backend_1   | ::ffff:172.21.0.5 - - [28/Dec/2021:09:03:41 +0100] "DELETE /api/v1/system/config/definitions/ticket-article-new-form-group-data HTTP/1.1" 404 - "-" "axios/0.21.4"
backend_1   | ::ffff:172.21.0.5 - - [28/Dec/2021:09:03:41 +0100] "DELETE /api/v1/system/config/definitions/ticket-article-new-form-group-data HTTP/1.1" 404 153 194414
backend_1   | ::ffff:172.21.0.5 - - [28/Dec/2021:09:03:42 +0100] "DELETE /api/v1/clientregistrations/kix-agent-portal-development-userid HTTP/1.1" 204 - "-" "axios/0.21.4"
backend_1   | ::ffff:172.21.0.5 - - [28/Dec/2021:09:03:42 +0100] "DELETE /api/v1/clientregistrations/kix-agent-portal-development-userid HTTP/1.1" 204 0 136950
proxy_1     | 2021/12/28 08:03:44 [error] 32#32: *140 connect() failed (111: Connection refused) while connecting to upstream, client: 172.21.0.1, server: , request: "GET /socket.io/?EIO=4&transport=polling&t=Nu04GtE HTTP/1.1", upstream: "http://172.21.0.5:3000/socket.io/?EIO=4&transport=polling&t=Nu04GtE", host: "127.0.0.1:20001", referrer: "http://127.0.0.1:20001/"
proxy_1     | 172.21.0.1 - - [28/Dec/2021:08:03:44 +0000] "GET /socket.io/?EIO=4&transport=polling&t=Nu04GtE HTTP/1.1" 502 2179 "http://127.0.0.1:20001/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:95.0) Gecko/20100101 Firefox/95.0" "-"
proxy_1     | 2021/12/28 08:03:50 [error] 32#32: *140 connect() failed (111: Connection refused) while connecting to upstream, client: 172.21.0.1, server: , request: "GET /socket.io/?EIO=4&transport=polling&t=Nu04ILC HTTP/1.1", upstream: "http://172.21.0.5:3000/socket.io/?EIO=4&transport=polling&t=Nu04ILC", host: "127.0.0.1:20001", referrer: "http://127.0.0.1:20001/"
Das Frontend crashed immer wieder. (Container (re)starts)
Den "backend_api_token" wie in "Re: kein Login, UI hängt mit "Connection refused) while connecting to upstream" habe ich gelöscht, aber es gibt keine Verbesserung.
Die Meldungen zum Delete von "ticket-article-new-form-group-data" irritieren mich ebenfalls.

Container wurden gestoppt und ein Update durchgeführt, was auch einige neue Dateien geladen hat. Fehler bleiben aber dieselben.
"docker network ls" zeigt normale Ausgabe (kix_default existiert).
docker network inspect zeigt für mich jetzt keine Unstimmigkeiten. kix_default baut ein Netzwerk in 172.21.0.0. für die Container auf.

Letzte Änderung war das Testen der LDAP Anbindung in Authentication###000-Default. Damit gibt es bei mir Probleme. Aber diese sollten ja nicht in Verbindungsproblemen enden, stimmt's?
Was passiert hier? ... und wie kann man die Umgebung wieder reparieren?

Viele Grüße,Michael

[René Böhm]

Hi Michael,
kannst du mal bitte in das Frontend-Log schauen. Du findest das im Frontend-Volume (kix_frontend) im Verzeichnis "logs".
Die DELETE-Meldungen sind nicht relevant. Das ist die normale Startup-Prozedur des Frontends, wobei es seine Default-Configs updated. Die Configs sind rein für das Frontend bestimmt (also sozusagen dessen Eigentum ;)). Wenn das Backend das was gelöscht werden soll, nicht kennt, dann werden diese Fehler im Log ausgegeben.

Viele GrüßeRené

[mplan]

Hallo René,Danke für die schnelle Antwort.
Ich habe jetzt mit Backups "herumgespielt", d.h. von der defekten Installation ein Backup erzeugt (Volumes gesichert+DB) und neu installiert. Anyway:FrontEnd Log zeigt

Code: [Auswählen]

Tue Dec 28 2021 09:18:19 GMT+0000 (Coordinated Universal Time) - error: Object.NotFound: Cannot delete SysConfigOptionDefinition. SysConfigOptionDefinition 'ticket-article-new-form-group-data' not found. {
  "Code": "Object.NotFound",
  "Message": "Cannot delete SysConfigOptionDefinition. SysConfigOptionDefinition 'ticket-article-new-form-group-data' not found.",
  "StatusCode": 404,
  "stackTrace": "\n    at Array.forEach (<anonymous>)\n    at SysConfigService.<anonymous> (/opt/kix/dist/frontend-applications/agent-portal/modules/sysconfig/server/SysConfigService.js:114:24)\n    at Generator.next (<anonymous>)\n    at fulfilled (/opt/kix/dist/frontend-applications/agent-portal/modules/sysconfig/server/SysConfigService.js:13:58)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)"
}
Tue Dec 28 2021 09:18:54 GMT+0000 (Coordinated Universal Time) - info: ClientRegistration created.
Tue Dec 28 2021 09:18:55 GMT+0000 (Coordinated Universal Time) - info: Initialize 29 service extensions
Tue Dec 28 2021 09:18:55 GMT+0000 (Coordinated Universal Time) - info: Create initial data (4 extensions)
Tue Dec 28 2021 09:19:02 GMT+0000 (Coordinated Universal Time) - info: Build 2 marko applications
Tue Dec 28 2021 09:19:02 GMT+0000 (Coordinated Universal Time) - info: Build marko app agent-portal
Tue Dec 28 2021 09:19:03 GMT+0000 (Coordinated Universal Time) - info: Clear Cache: (ignore) 
Tue Dec 28 2021 09:19:08 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:19:14 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:19:20 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:19:26 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:19:32 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:19:38 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:19:44 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:19:52 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:19:58 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:20:04 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:20:10 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:20:21 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:20:27 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:20:27 GMT+0000 (Coordinated Universal Time) - info: marko app build finished: agent-portal
Tue Dec 28 2021 09:20:27 GMT+0000 (Coordinated Universal Time) - info: Build marko app authentication-login
Tue Dec 28 2021 09:20:33 GMT+0000 (Coordinated Universal Time) - info: App build in progress
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: marko app build finished: authentication-login
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Init 4 router extensions
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: KIX (HTTP) running on *:3000
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: NotificationNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: AuthenticationNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: ContextNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: KIXModuleNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: KIXObjectNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: AdministrationNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: MainMenuNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: NotesNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: SearchNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: TicketNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: AgentNamespace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: WebformNameSpace
Tue Dec 28 2021 09:20:34 GMT+0000 (Coordinated Universal Time) - info: Register socket namespace: MapNamespace
Tue Dec 28 2021 09:20:35 GMT+0000 (Coordinated Universal Time) - error: Error during HTTP (system/config/kix-customer-portal-light-webforms) GET request. {
  "config": {
    "url": "http://backend:8080/api/v1/system/config/kix-customer-portal-light-webforms",
    "method": "get",
    "headers": {
      "Accept": "application/json, text/plain, */*",
      "Authorization": "Token eyJhbGciOiJIUzI1NiJ9.eyJBbGxvd2VkT3BlcmF0aW9ucyI6W10sIkNyZWF0ZVRpbWVVbml4IjoxNjQwNjgzMDIxLCJSZW1vdGVJUCI6Im5vbmUiLCJEZXNjcmlwdGlvbiI6ImZyb250ZW5kIEFQSSB0b2tlbiIsIlVzZXJJRCI6MSwiRGVuaWVkT3BlcmF0aW9ucyI6W10sIlZhbGlkVW50aWwiOiI5OTk5LTEyLTMxIDIzOjU5OjU5IiwiVmFsaWRVbnRpbFRpbWVVbml4IjoyNTM0MDIyOTcxOTksIklnbm9yZU1heElkbGVUaW1lIjoxLCJVc2VyVHlwZSI6IkFnZW50IiwiVG9rZW5UeXBlIjoiQWNjZXNzVG9rZW4ifQ.-pTIU3fz5IjD6ZOeKrvlojzPjD_JA24XEQGQMcnlt-U",
      "KIX-Request-ID": null,
      "User-Agent": "axios/0.21.4"
    },
    "params": {},
    "baseURL": "http://backend:8080/api/v1",
    "transformRequest": [
      null
    ],
    "transformResponse": [
      null
    ],
    "timeout": 0,
    "xsrfCookieName": "XSRF-TOKEN",
    "xsrfHeaderName": "X-XSRF-TOKEN",
    "maxContentLength": -1,
    "maxBodyLength": -1,
    "transitional": {
      "silentJSONParsing": true,
      "forcedJSONParsing": true,
      "clarifyTimeoutError": false
    }
  }
}
Leider stimmen die Timestamps zwischen Backend und Frontend nicht ganz. da ich keine Einträge in den Frontendlogs von 9:03 Uhr finde. Aber ich hoffe, es hat trotzdem eine gewisse Aussage.

Nach dem Restore sieht es derzeit so aus, als ob das Backend nicht bereit ist und diesmal wird das Backend immer wieder neu gestartet:

Code: [Auswählen]

proxy_1     | 172.30.0.1 - - [28/Dec/2021:16:23:54 +0000] "GET / HTTP/1.1" 502 2179 "http://127.0.0.1:20001/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:95.0) Gecko/20100101 Firefox/95.0" "-"
frontend_1  | backend not ready yet, waiting for 10 seconds...
proxy_1     | 2021/12/28 16:23:57 [error] 32#32: *10 connect() failed (111: Connection refused) while connecting to upstream, client: 172.30.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://172.30.0.5:3000/", host: "127.0.0.1:20001", referrer: "http://127.0.0.1:20001/"
proxy_1     | 172.30.0.1 - - [28/Dec/2021:16:23:57 +0000] "GET / HTTP/1.1" 502 2179 "http://127.0.0.1:20001/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:95.0) Gecko/20100101 Firefox/95.0" "-"
proxy_1     | 2021/12/28 16:24:00 [error] 32#32: *10 connect() failed (111: Connection refused) while connecting to upstream, client: 172.30.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://172.30.0.5:3000/", host: "127.0.0.1:20001", referrer: "http://127.0.0.1:20001/"
proxy_1     | 172.30.0.1 - - [28/Dec/2021:16:24:00 +0000] "GET / HTTP/1.1" 502 2179 "http://127.0.0.1:20001/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:95.0) Gecko/20100101 Firefox/95.0" "-"
proxy_1     | 2021/12/28 16:24:03 [error] 32#32: *10 connect() failed (111: Connection refused) while connecting to upstream, client: 172.30.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://172.30.0.5:3000/", host: "127.0.0.1:20001", referrer: "http://127.0.0.1:20001/"
proxy_1     | 172.30.0.1 - - [28/Dec/2021:16:24:03 +0000] "GET / HTTP/1.1" 502 2179 "http://127.0.0.1:20001/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:95.0) Gecko/20100101 Firefox/95.0" "-"
frontend_1  | backend not ready yet, waiting for 10 seconds...

Code: [Auswählen]

Status Kix v18 ... #
CONTAINER ID   STATUS          CREATED         NAMES
aae18d06c0a0   Up 6 minutes    6 minutes ago   kix_proxy_1
7c6c2c461e86   Up 6 minutes    6 minutes ago   kix_frontend_1
3ad5d3c90485   Up 12 seconds   6 minutes ago   kix_backend_1
62a46dd61b2f   Up 6 minutes    6 minutes ago   kix_redis_1
bcf567164622   Up 6 minutes    6 minutes ago   kix_db_1
Vielen Dank und einen guten Rutsch ins Neue Jahr!
Michael

[René Böhm]

Danke für die Logs. Darin ist leider noch nichts enthalten, was auf einen Problem hindeuten könnte. Wg. des Restarts des Backends: was sagt das Container-Log des Backends und was sagt ein "docker inspect kix_backend_1" ?
Viele Grüße und ebenfalls einen guten Rutsch :)René

[mplan]

Hallo René,
Ich sehe in den Inspect Ausgaben nichts, was aber nichts bedeuten soll.Ich habe mal von fast allen Containern die Ausgabe und auch das Gesamtlog angehängt.Das Backend meldet im Log Permissionprobleme und ein Problem mit einem nicht initialisierten Wert.

Code: [Auswählen]

backend_1   |  >> Can't write /opt/kix/var/log/kix.log.2021-12: Permission denied <<
backend_1   | 2021-12-30T07:59:31.082724889Z Error while loading /opt/kix/bin/server/app.psgi: mkdir /mnt/data/articles/2021/12/30: Permission denied at /opt/kix/Kernel/System/Ticket/ArticleStorageFS.pm line 47.
backend_1   | 2021-12-30T07:59:31.099140969Z Use of uninitialized value $alias in lc at /usr/lib/x86_64-linux-gnu/perl/5.28/Encode/Alias.pm line 38 during global destruction.
backend_1   | 2021-12-30T07:59:31.099161296Z Use of uninitialized value $alias in lc at /usr/lib/x86_64-linux-gnu/perl/5.28/Encode/Alias.pm line 38 during global destruction.
Können die Permissionprobleme durch das Backup & Restore kommen?
Habe wie in der Anleitung beschrieben, die Volumes bei gestoppter Anwendung kopiert und dann wieder zurück geschrieben.
Dazwischen wurde ein Backup eines neu installierten Kix geladen. Zwischen vorgestern und heute habe ich deshalb kein Backup Restore mehr gemacht, und nur docker gestoppt und gestartet mit den fehlerhaften Containern.
Auf das Backend komme ich jetzt gar nicht mehr mit der Shell (docker exec), da der Container zu schnell zusammenbricht.

Viele Grüße und alles Gute für das Neue Jahr!
Michael

[René Böhm]

Hallo Michael,
falls du das Kopieren direkt gemacht hast, ohne die Berechtigungen zu behalten (cp --preserve), dann sind die Berechtigungen abhanden gekommen. Du müsstest den Daten im Volume dann den Owner und Group zurückgeben, die sie vorher hatten. Danach sollte es wieder funktionieren. Wenn du nicht mehr weißt, welcher Owner/welche Group vorher gesetzt war, dann erstmal alle Files auf rw setzen und alle Verzeichnisse auf rwx, für owner, group und other.
Viele GrüßeRené

[mplan]

Hallo RenéDas System befindet sich auf Windows.
Im Docker Volume sehe ich, dass die Logdatei root:root gehört statt 110010100:root. Hab's mal wieder darauf geändert.Das Backup mache ich für die Volumes bei gestoppten Containern mit 7Zip. Deshalb habe ich keine Probleme mit den Rechten innerhalb der Container vermutet.

d.h. ich müßte im Archiv die Rechte umsetzen, erneut ein Restore machen und schauen, ob die Container wieder starten, richtg?
VG Michael

[René Böhm]

Hi Michael,
wichtig ist, dass der Container darauf zugreifen kann. Lesend und schreibend. Die Prozesse im Container laufen mit dem anonymen Nutzer.
VGRené

[mplan]

Hallo René,
besten Dank. Ich habe in Windows bei den Dateirechten vom Volume den Schreibschutz aufgehoben und nun startet die Umgebung erst einmal wieder, ohne dass die Container wegbrechen.
Es gibt zwar noch Fehlermeldungen, aber die Ursache für die ursprünglichen Fehler liegt in den falschen Dateiberechtigungen.

Vielen Dank!
Viele GrüßeMichael