sync group failed - authentication failed - invalid ticket - expired

herzkerl

herzkerl

Member
Mar 18, 2021
95
15
13
Hallo zusammen,

leider habe ich nun bei einem Sync-Job (wir syncen derzeit von drei Kunden) auch den im Titel genannten Fehler. Log siehe unten.
Im Forum gibt es einige Threads zu diesem Fehler, jedoch beziehen sich die meisten auf einen Bug, der in 2020 gefixt wurde, und andere blieben unbeantwortet.

Code: 
2023-07-02T20:00:00+02:00: Starting datastore sync job 'xyz:nas:kunden-xyz::s-2e681556-87b9'
2023-07-02T20:00:00+02:00: task triggered by schedule '20:00'
2023-07-02T20:00:00+02:00: sync datastore 'kunden-xyz' from 'xyz/nas'
2023-07-02T20:00:00+02:00: ----
2023-07-02T20:00:00+02:00: Syncing datastore 'nas', root namespace into datastore 'kunden-xyz', root namespace
2023-07-02T20:00:04+02:00: found 7 groups to sync
2023-07-02T20:00:04+02:00: sync group vm/101
2023-07-02T20:00:09+02:00: skipped: 88 snapshot(s) (2023-06-05T07:13:52Z .. 2023-07-01T04:00:00Z) - older than the newest local snapshot
2023-07-02T20:00:09+02:00: re-sync snapshot vm/101/2023-07-01T16:00:07Z
2023-07-02T20:00:10+02:00: percentage done: 13.97% (0/7 groups, 89/91 snapshots in group #1)
2023-07-02T20:00:10+02:00: sync snapshot vm/101/2023-07-02T04:00:04Z
2023-07-02T20:00:10+02:00: sync archive qemu-server.conf.blob
2023-07-02T20:00:10+02:00: sync archive drive-scsi1.img.fidx
2023-07-02T20:14:17+02:00: downloaded 5324197168 bytes (6.00 MiB/s)
2023-07-02T20:14:17+02:00: sync archive drive-scsi0.img.fidx
2023-07-02T20:52:32+02:00: downloaded 12166827239 bytes (5.06 MiB/s)
2023-07-02T20:52:32+02:00: sync archive drive-efidisk0.img.fidx
2023-07-02T20:52:32+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-02T20:52:32+02:00: got backup log file "client.log.blob"
2023-07-02T20:52:32+02:00: sync snapshot vm/101/2023-07-02T04:00:04Z done
2023-07-02T20:52:32+02:00: percentage done: 14.13% (0/7 groups, 90/91 snapshots in group #1)
2023-07-02T20:52:32+02:00: sync snapshot vm/101/2023-07-02T16:00:02Z
2023-07-02T20:52:32+02:00: sync archive qemu-server.conf.blob
2023-07-02T20:52:32+02:00: sync archive drive-scsi1.img.fidx
2023-07-02T20:58:30+02:00: downloaded 2248043939 bytes (6.01 MiB/s)
2023-07-02T20:58:30+02:00: sync archive drive-scsi0.img.fidx
2023-07-02T21:25:03+02:00: downloaded 10023943471 bytes (6.00 MiB/s)
2023-07-02T21:25:03+02:00: sync archive drive-efidisk0.img.fidx
2023-07-02T21:25:03+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-02T21:25:03+02:00: got backup log file "client.log.blob"
2023-07-02T21:25:03+02:00: sync snapshot vm/101/2023-07-02T16:00:02Z done
2023-07-02T21:25:03+02:00: percentage done: 14.29% (1/7 groups)
2023-07-02T21:25:03+02:00: sync group vm/102
2023-07-02T21:25:14+02:00: skipped: 48 snapshot(s) (2023-06-05T09:34:29Z .. 2023-07-01T05:03:52Z) - older than the newest local snapshot
2023-07-02T21:25:15+02:00: re-sync snapshot vm/102/2023-07-01T16:11:39Z
2023-07-02T21:25:15+02:00: no data changes
2023-07-02T21:25:15+02:00: percentage done: 28.01% (1/7 groups, 49/51 snapshots in group #2)
2023-07-02T21:25:15+02:00: sync snapshot vm/102/2023-07-02T04:10:55Z
2023-07-02T21:25:15+02:00: sync archive qemu-server.conf.blob
2023-07-02T21:25:15+02:00: sync archive drive-scsi1.img.fidx
2023-07-02T21:37:33+02:00: downloaded 821356556 bytes (1.06 MiB/s)
2023-07-02T21:37:33+02:00: sync archive drive-scsi0.img.fidx
2023-07-02T22:11:55+02:00: downloaded 9325864647 bytes (4.32 MiB/s)
2023-07-02T22:11:55+02:00: sync archive drive-efidisk0.img.fidx
2023-07-02T22:11:55+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-02T22:11:55+02:00: got backup log file "client.log.blob"
2023-07-02T22:11:55+02:00: sync snapshot vm/102/2023-07-02T04:10:55Z done
2023-07-02T22:11:55+02:00: percentage done: 28.29% (1/7 groups, 50/51 snapshots in group #2)
2023-07-02T22:11:58+02:00: sync group vm/102 failed - permission check failed.
2023-07-02T22:11:58+02:00: sync group vm/103
2023-07-02T22:12:01+02:00: sync group vm/103 failed - authentication failed - invalid ticket - expired
2023-07-02T22:12:02+02:00: sync group vm/104
2023-07-02T22:12:05+02:00: sync group vm/104 failed - authentication failed - invalid ticket - expired
2023-07-02T22:12:05+02:00: sync group vm/111
2023-07-02T22:12:08+02:00: sync group vm/111 failed - authentication failed - invalid ticket - expired
2023-07-02T22:12:08+02:00: sync group vm/112
2023-07-02T22:12:11+02:00: sync group vm/112 failed - authentication failed - invalid ticket - expired
2023-07-02T22:12:11+02:00: sync group vm/201
2023-07-02T22:12:14+02:00: sync group vm/201 failed - authentication failed - invalid ticket - expired
2023-07-02T22:12:14+02:00: Finished syncing namespace , current progress: 6 groups, 0 snapshots
2023-07-02T22:12:14+02:00: TASK ERROR: sync failed with some errors.

Die Paketversionen auf unserer Seite:

Code: 
proxmox-backup: 2.4-1 (running kernel: 5.15.85-1-pve)
proxmox-backup-server: 2.4.2-2 (running version: 2.4.2)
pve-kernel-5.15: 7.4-4
pve-kernel-5.13: 7.1-9
pve-kernel-5.4: 6.4-4
pve-kernel-5.15.108-1-pve: 5.15.108-1
pve-kernel-5.15.107-2-pve: 5.15.107-2
pve-kernel-5.15.107-1-pve: 5.15.107-1
pve-kernel-5.15.102-1-pve: 5.15.102-1
pve-kernel-5.15.85-1-pve: 5.15.85-1
pve-kernel-5.15.83-1-pve: 5.15.83-1
pve-kernel-5.15.74-1-pve: 5.15.74-1
pve-kernel-5.15.64-1-pve: 5.15.64-1
pve-kernel-5.15.60-2-pve: 5.15.60-2
pve-kernel-5.15.60-1-pve: 5.15.60-1
pve-kernel-5.13.19-6-pve: 5.13.19-15
pve-kernel-5.13.19-2-pve: 5.13.19-4
pve-kernel-5.4.124-1-pve: 5.4.124-1
pve-kernel-5.4.65-1-pve: 5.4.65-1
ifupdown2: 3.1.0-1+pmx4
libjs-extjs: 7.0.0-1
proxmox-backup-docs: 2.4.2-1
proxmox-backup-client: 2.4.2-1
proxmox-mail-forward: 0.1.1-1
proxmox-mini-journalreader: 1.2-1
proxmox-offline-mirror-helper: 0.5.2
proxmox-widget-toolkit: 3.7.3
pve-xtermjs: 4.16.0-2
smartmontools: 7.2-pve3
zfsutils-linux: 2.1.11-pve1

Die Paketversionen beim Kunden – nicht ganz aktuell:

Code: 
proxmox-backup: 2.4-1 (running kernel: 5.15.107-2-pve)
proxmox-backup-server: 2.4.2-2 (running version: 2.4.2)
pve-kernel-5.15: 7.4-3
pve-kernel-5.15.107-2-pve: 5.15.107-2
pve-kernel-5.15.102-1-pve: 5.15.102-1
ifupdown2: 3.1.0-1+pmx4
libjs-extjs: 7.0.0-1
proxmox-backup-docs: 2.4.2-1
proxmox-backup-client: 2.4.2-1
proxmox-mail-forward: 0.1.1-1
proxmox-mini-journalreader: 1.2-1
proxmox-offline-mirror-helper: not correctly installed
proxmox-widget-toolkit: 3.7.3
pve-xtermjs: 4.16.0-2
smartmontools: 7.2-pve3
zfsutils-linux: 2.1.11-pve1

Dort installiere ich nun erstmal die zur Verfügung stehenden Updates (nur bind9 und pve-kernel).
 
Last edited:
Ich habe im Sync Job mal testweise einen group filter auf vm/103 eingestellt und der Sync läuft derzeit ohne Fehler.
Als nächstes werde ich dann noch vm/102 einzeln testen und mich zurückmelden.
 
Last edited:
Auch das hat funktioniert:

Code: 
2023-07-04T12:29:10+02:00: Starting datastore sync job 'xyz:nas:kunden-xyz::s-2e681556-87b9'
2023-07-04T12:29:10+02:00: sync datastore 'kunden-xyz' from 'xyz/nas'
2023-07-04T12:29:10+02:00: ----
2023-07-04T12:29:10+02:00: Syncing datastore 'nas', root namespace into datastore 'kunden-xyz', root namespace
2023-07-04T12:29:46+02:00: found 1 groups to sync (out of 7 total)
2023-07-04T12:29:46+02:00: sync group vm/102
2023-07-04T12:29:56+02:00: skipped: 52 snapshot(s) (2023-06-05T09:34:29Z .. 2023-07-03T04:17:01Z) - older than the newest local snapshot
2023-07-04T12:29:56+02:00: re-sync snapshot vm/102/2023-07-03T16:21:56Z
2023-07-04T12:29:57+02:00: percentage done: 98.15% (53/54 snapshots)
2023-07-04T12:29:57+02:00: sync snapshot vm/102/2023-07-04T04:12:09Z
2023-07-04T12:29:57+02:00: sync archive qemu-server.conf.blob
2023-07-04T12:29:57+02:00: sync archive drive-scsi1.img.fidx
2023-07-04T12:49:57+02:00: downloaded 1368370264 bytes (1.09 MiB/s)
2023-07-04T12:49:57+02:00: sync archive drive-scsi0.img.fidx
2023-07-04T13:37:43+02:00: downloaded 9103977609 bytes (3.03 MiB/s)
2023-07-04T13:37:43+02:00: sync archive drive-efidisk0.img.fidx
2023-07-04T13:37:43+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-04T13:37:43+02:00: got backup log file "client.log.blob"
2023-07-04T13:37:43+02:00: sync snapshot vm/102/2023-07-04T04:12:09Z done
2023-07-04T13:37:43+02:00: percentage done: 100.00% (54/54 snapshots)
2023-07-04T13:37:43+02:00: Finished syncing namespace , current progress: 0 groups, 54 snapshots
2023-07-04T13:37:43+02:00: sync job 'xyz:nas:kunden-xyz::s-2e681556-87b9' end
2023-07-04T13:37:43+02:00: TASK OK
 
So, Schlussmeldung: Ich habe nun den Filter wieder rausgenommen und der Sync ist ohne Fehler durchgelaufen.

Ich ging zuerst davon aus, dass es sich um diesen Bug aus 2020 handeln könnte, der evtl. wiedergekehrt ist – aber da der Sync nun um 13:40 Uhr startete und erst nach 17:00 Uhr endete, würde ich das auch ausschließen.

Falls jemand eine Idee hat, freue ich mich trotzdem über eine Nachricht – und beobachte das natürlich weiter und melde mich hier im Thread ggf. zurück, sollte es nochmal auftreten.
 
Danke für das Log und die Paketversionen. Kannst du evtl. noch die folgenden Informationen posten, das würde uns beim Reproduzieren vermutlich helfen:

  • Die Konfiguration des Syncjobs (findest du in /etc/proxmox-backup/sync.cfg).
  • Die Konfiguration des Remotes, bitte hier nicht vergessen zumindest das Passwort vor dem Posten zu entfernen! (findest du unter /etc/proxmox-backup/remote.cfg).
  • Falls es sich bei dem PBS um eine VM handelt, wäre dessen Konfiguration interessant. Wenn nicht, kannst du evtl. mehr Informationen über die Hardware des Systems und dessen Auslastung zum Zeitpunkt des Syncjobs geben?
  • Liefen mehrere Syncjobs gleichzeitig?

Um ein bisschen mehr Informationen zu geben: Dieses Problem scheint schon länger vereinzelt aufzutreten (z.B.: in diesen Post vom letzten Jahr [1]). Leider konnten wir das Problem damals nicht reproduzieren und wie du schon selbst bemerkt hast, ist es tendenziell eher flüchtig.

[1]: https://forum.proxmox.com/threads/73160/post-477645
 
sterzy said:
Falls es sich bei dem PBS um eine VM handelt, wäre dessen Konfiguration interessant. Wenn nicht, kannst du evtl. mehr Informationen über die Hardware des Systems und dessen Auslastung zum Zeitpunkt des Syncjobs geben?
Click to expand...
Beide sind visualisiert, ja.
Quelle: 1 socket, 4 cores, 4 GB ohne ballooning, CPU type kvm64
Ziel: 2 sockets, 8 cores, 8-16 GB (balloning), CPU type host +aes
Beider derzeit (leider) nur HDD; bei uns via Ceph, hier wollen wir zukünftig DB/WAL auf NVMe packenm Kunden auf einer Synology via CIFS, dort werden wir zeitnah testweise den SSD-Cache aktivieren.

sterzy said:
Liefen mehrere Syncjobs gleichzeitig?
Click to expand...
In diesem Fall ja – der Job des Kunden läuft um 20 Uhr, der nächste dann um 22 Uhr – die Fehlermeldung kam ja gegen 22:15 Uhr... Das hatte ich nicht bedacht, vielleicht ist das die Ursache?

Anbei noch die entsprechenden Stellen aus /etc/proxmox-backup/sync.cfg und /etc/proxmox-backup/remote.cfg
Code: 
sync: s-2e681556-87b9
        ns
        owner user@pbs
        remote xyz
        remote-ns
        remote-store nas
        remove-vanished false
        schedule 20:00
        store kunden-xyz
        transfer-last 7
Code: 
remote: xyz
        auth-id user@pbs
        fingerprint ...
        host fqpn
 
Zur Info: Es ist wieder aufgetreten, und diesmal nicht kurz nach 22 Uhr – somit glaube ich, dass der andere Sync-Job damit nicht direkt etwas zu tun hat.

Code: 
2023-07-09T20:00:00+02:00: Starting datastore sync job 'xyz:nas:kunden-xyz::s-2e681556-87b9'
2023-07-09T20:00:00+02:00: task triggered by schedule '20:00'
2023-07-09T20:00:00+02:00: sync datastore 'kunden-xyz' from 'xyz/nas'
2023-07-09T20:00:00+02:00: ----
2023-07-09T20:00:00+02:00: Syncing datastore 'nas', root namespace into datastore 'kunden-xyz', root namespace
2023-07-09T20:00:01+02:00: found 7 groups to sync
2023-07-09T20:00:01+02:00: sync group vm/101
2023-07-09T20:00:02+02:00: skipped: 102 snapshot(s) (2023-06-05T07:13:52Z .. 2023-07-08T04:00:03Z) - older than the newest local snapshot
2023-07-09T20:00:02+02:00: re-sync snapshot vm/101/2023-07-08T16:00:01Z
2023-07-09T20:00:02+02:00: percentage done: 14.01% (0/7 groups, 103/105 snapshots in group #1)
2023-07-09T20:00:02+02:00: sync snapshot vm/101/2023-07-09T04:00:06Z
2023-07-09T20:00:02+02:00: sync archive qemu-server.conf.blob
2023-07-09T20:00:02+02:00: sync archive drive-scsi1.img.fidx
2023-07-09T20:13:49+02:00: downloaded 5194936177 bytes (5.99 MiB/s)
2023-07-09T20:13:49+02:00: sync archive drive-scsi0.img.fidx
2023-07-09T20:45:40+02:00: downloaded 9039449057 bytes (4.51 MiB/s)
2023-07-09T20:45:41+02:00: sync archive drive-efidisk0.img.fidx
2023-07-09T20:45:41+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-09T20:45:41+02:00: got backup log file "client.log.blob"
2023-07-09T20:45:41+02:00: sync snapshot vm/101/2023-07-09T04:00:06Z done
2023-07-09T20:45:41+02:00: percentage done: 14.15% (0/7 groups, 104/105 snapshots in group #1)
2023-07-09T20:45:41+02:00: sync snapshot vm/101/2023-07-09T16:00:06Z
2023-07-09T20:45:41+02:00: sync archive qemu-server.conf.blob
2023-07-09T20:45:41+02:00: sync archive drive-scsi1.img.fidx
2023-07-09T20:53:02+02:00: downloaded 2768090835 bytes (5.99 MiB/s)
2023-07-09T20:53:02+02:00: sync archive drive-scsi0.img.fidx
2023-07-09T21:24:17+02:00: downloaded 11794602241 bytes (6.00 MiB/s)
2023-07-09T21:24:17+02:00: sync archive drive-efidisk0.img.fidx
2023-07-09T21:24:17+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-09T21:24:17+02:00: got backup log file "client.log.blob"
2023-07-09T21:24:17+02:00: sync snapshot vm/101/2023-07-09T16:00:06Z done
2023-07-09T21:24:17+02:00: percentage done: 14.29% (1/7 groups)
2023-07-09T21:24:17+02:00: sync group vm/102
2023-07-09T21:24:22+02:00: skipped: 62 snapshot(s) (2023-06-05T09:34:29Z .. 2023-07-08T04:04:19Z) - older than the newest local snapshot
2023-07-09T21:24:22+02:00: re-sync snapshot vm/102/2023-07-08T16:03:26Z
2023-07-09T21:24:22+02:00: no data changes
2023-07-09T21:24:22+02:00: percentage done: 28.13% (1/7 groups, 63/65 snapshots in group #2)
2023-07-09T21:24:22+02:00: sync snapshot vm/102/2023-07-09T04:04:35Z
2023-07-09T21:24:22+02:00: sync archive qemu-server.conf.blob
2023-07-09T21:24:22+02:00: sync archive drive-scsi1.img.fidx
2023-07-09T21:38:40+02:00: downloaded 1437447583 bytes (1.60 MiB/s)
2023-07-09T21:38:40+02:00: sync archive drive-scsi0.img.fidx
2023-07-09T22:12:18+02:00: downloaded 9364255735 bytes (4.43 MiB/s)
2023-07-09T22:12:18+02:00: sync archive drive-efidisk0.img.fidx
2023-07-09T22:12:18+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-09T22:12:19+02:00: got backup log file "client.log.blob"
2023-07-09T22:12:19+02:00: sync snapshot vm/102/2023-07-09T04:04:35Z done
2023-07-09T22:12:19+02:00: percentage done: 28.35% (1/7 groups, 64/65 snapshots in group #2)
2023-07-09T22:12:19+02:00: sync snapshot vm/102/2023-07-09T16:03:39Z
2023-07-09T22:12:19+02:00: sync archive qemu-server.conf.blob
2023-07-09T22:12:19+02:00: sync archive drive-scsi1.img.fidx
2023-07-09T22:12:33+02:00: downloaded 83588277 bytes (5.96 MiB/s)
2023-07-09T22:12:33+02:00: sync archive drive-scsi0.img.fidx
2023-07-09T22:38:31+02:00: downloaded 9808941469 bytes (6.01 MiB/s)
2023-07-09T22:38:31+02:00: sync archive drive-efidisk0.img.fidx
2023-07-09T22:38:31+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-09T22:38:31+02:00: got backup log file "client.log.blob"
2023-07-09T22:38:31+02:00: sync snapshot vm/102/2023-07-09T16:03:39Z done
2023-07-09T22:38:31+02:00: percentage done: 28.57% (2/7 groups)
2023-07-09T22:38:31+02:00: sync group vm/103
2023-07-09T22:38:37+02:00: skipped: 62 snapshot(s) (2023-06-05T10:25:57Z .. 2023-07-08T04:09:54Z) - older than the newest local snapshot
2023-07-09T22:38:37+02:00: re-sync snapshot vm/103/2023-07-08T16:13:47Z
2023-07-09T22:38:38+02:00: no data changes
2023-07-09T22:38:38+02:00: percentage done: 42.42% (2/7 groups, 63/65 snapshots in group #3)
2023-07-09T22:38:38+02:00: sync snapshot vm/103/2023-07-09T04:10:16Z
2023-07-09T22:38:38+02:00: sync archive qemu-server.conf.blob
2023-07-09T22:38:38+02:00: sync archive drive-scsi0.img.fidx
2023-07-09T23:27:16+02:00: downloaded 13723003978 bytes (4.49 MiB/s)
2023-07-09T23:27:16+02:00: sync archive drive-efidisk0.img.fidx
2023-07-09T23:27:16+02:00: downloaded 0 bytes (0.00 MiB/s)
2023-07-09T23:27:16+02:00: got backup log file "client.log.blob"
2023-07-09T23:27:16+02:00: sync snapshot vm/103/2023-07-09T04:10:16Z done
2023-07-09T23:27:16+02:00: percentage done: 42.64% (2/7 groups, 64/65 snapshots in group #3)
2023-07-09T23:27:20+02:00: sync group vm/103 failed - permission check failed.
2023-07-09T23:27:20+02:00: sync group vm/104
2023-07-09T23:27:23+02:00: sync group vm/104 failed - authentication failed - invalid ticket - expired
2023-07-09T23:27:23+02:00: sync group vm/111
2023-07-09T23:27:26+02:00: sync group vm/111 failed - authentication failed - invalid ticket - expired
2023-07-09T23:27:26+02:00: sync group vm/112
2023-07-09T23:27:29+02:00: sync group vm/112 failed - authentication failed - invalid ticket - expired
2023-07-09T23:27:29+02:00: sync group vm/201
2023-07-09T23:27:32+02:00: sync group vm/201 failed - authentication failed - invalid ticket - expired
2023-07-09T23:27:32+02:00: Finished syncing namespace , current progress: 6 groups, 0 snapshots
2023-07-09T23:27:32+02:00: TASK ERROR: sync failed with some errors.
 
Okay ... und wie ging es dann weiter ... ?
Habe den gleichen Fehler mit vergleichbarer Umgebung
(der Sync Job läuft auf einen virtualisierten PBS: proxmox-backup-server 3.2.7-1; der zu synchronisierende hat die gleiche aktuelle Version
aufgefallen ist mir, dass während des sync Jobs, der Upload des "remotes" bei 9 bis 13 Mibps liegt und selbst auf der Kommandozeile per ssh nur noch sehr verzögert reagiert .... Evtl. ist der Upload zu gering?
 
You must log in or register to reply here.

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Quick Navigation

Home Get Subscription Wiki Downloads Proxmox Customer Portal About

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!
Community platform by XenForo® © 2010-2024 XenForo Ltd.
Top Bottom
Back