remote sync seems to time out after 2 hours when run by hand

[RobFantini]

I ran this by clicking 'run now' at pbs web page.
looks like ticket times out after 2 hours

020-07-18T11:27:52-04:00: sync job 'get-fbc-backup' start
2020-07-18T11:27:52-04:00: sync snapshot "ct/101/2020-07-18T13:06:43Z"
2020-07-18T11:27:52-04:00: sync archive pct.conf.blob
2020-07-18T11:27:52-04:00: sync archive root.pxar.didx
2020-07-18T11:32:52-04:00: sync archive catalog.pcat1.didx
2020-07-18T11:32:52-04:00: got backup log file "client.log.blob"
2020-07-18T11:32:52-04:00: sync snapshot "ct/101/2020-07-18T13:06:43Z" done
2020-07-18T11:32:52-04:00: sync snapshot "ct/105/2020-07-11T18:18:02Z"
2020-07-18T11:32:52-04:00: sync archive pct.conf.blob
2020-07-18T11:32:52-04:00: sync archive root.pxar.didx
2020-07-18T11:39:56-04:00: sync archive catalog.pcat1.didx
2020-07-18T11:39:56-04:00: got backup log file "client.log.blob"
2020-07-18T11:39:56-04:00: sync snapshot "ct/105/2020-07-11T18:18:02Z" done

... many more ok then:


2020-07-18T13:28:46-04:00: got backup log file "client.log.blob"
2020-07-18T13:28:46-04:00: sync snapshot "ct/607/2020-07-11T20:35:13Z" done
2020-07-18T13:28:49-04:00: sync group ct/607 failed - HTTP Error 401 Unauthorized: permission check failed.
2020-07-18T13:28:52-04:00: sync group ct/66741 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:28:55-04:00: sync group ct/701 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:28:58-04:00: sync group vm/100 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:01-04:00: sync group vm/102 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:04-04:00: sync group vm/103 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:07-04:00: sync group vm/10784 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:10-04:00: sync group vm/108 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:13-04:00: sync group vm/111 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:16-04:00: sync group vm/112 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:19-04:00: sync group vm/204 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:22-04:00: sync group vm/207 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:25-04:00: sync group vm/216 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:28-04:00: sync group vm/2165 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:31-04:00: sync group vm/223 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:34-04:00: sync group vm/224 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:37-04:00: sync group vm/3120 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:40-04:00: sync group vm/4120 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:43-04:00: sync group vm/4121 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:46-04:00: sync group vm/446 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:49-04:00: sync group vm/66780 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:52-04:00: sync group vm/66791 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:55-04:00: sync group vm/7211 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:29:58-04:00: sync group vm/727 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:30:01-04:00: sync group vm/801 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:30:04-04:00: sync group vm/88691 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:30:07-04:00: sync group vm/88903 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:30:10-04:00: sync group vm/88950 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:30:13-04:00: sync group vm/88951 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:30:16-04:00: sync group vm/902 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:30:19-04:00: sync group vm/978 failed - HTTP Error 401 Unauthorized: authentication failed - invalid ticket - timestamp too old.
2020-07-18T13:30:19-04:00: TASK ERROR: sync failed with some errors.

[/CODE]

 

[fabian]

filed as https://bugzilla.proxmox.com/show_bug.cgi?id=2870 , thanks!

 

[MarvinE]

I think, my is the same problem?

2020-09-03T08:17:02+02:00: re-sync snapshot "vm/121/2020-08-22T17:00:44Z" done
2020-09-03T08:17:03+02:00: sync snapshot "vm/121/2020-08-23T17:00:35Z"
2020-09-03T08:17:03+02:00: sync archive qemu-server.conf.blob
2020-09-03T08:17:03+02:00: sync archive drive-virtio0.img.fidx
2020-09-03T09:31:46+02:00: got backup log file "client.log.blob"
2020-09-03T09:31:46+02:00: sync snapshot "vm/121/2020-08-23T17:00:35Z" done
2020-09-03T09:31:46+02:00: sync snapshot "vm/121/2020-08-24T17:00:39Z"
2020-09-03T09:31:46+02:00: sync archive qemu-server.conf.blob
2020-09-03T09:31:47+02:00: sync archive drive-virtio0.img.fidx
2020-09-03T11:16:06+02:00: got backup log file "client.log.blob"
2020-09-03T11:16:06+02:00: sync snapshot "vm/121/2020-08-24T17:00:39Z" done
2020-09-03T11:16:10+02:00: sync group vm/121 failed - permission check failed.
2020-09-03T11:16:13+02:00: sync group vm/123 failed - authentication failed - invalid ticket - expired
2020-09-03T11:16:16+02:00: sync group vm/142 failed - authentication failed - invalid ticket - expired
2020-09-03T11:16:16+02:00: TASK ERROR: sync failed with some errors.

 

[fabian]

yes

 

[flames]

Just fyi, same happens after an hour on pbs cli/shell, while "proxmox-backup-manager verify datastorename" is running. Thanks

 

[indi]

Similar error. But after 45 hours of synchronization.

2022-06-11T09:15:00+03:00: Starting datastore sync job 'vs:hot:rmt::vs-hot'
...
2022-06-13T06:23:40+03:00: sync group vm/1249 failed - permission check failed.
2022-06-13T06:23:43+03:00: sync group vm/1250 failed - authentication failed - invalid ticket - expired
2022-06-13T06:23:48+03:00: sync group vm/1252 failed - authentication failed - invalid ticket - expired
2022-06-13T06:23:51+03:00: sync group vm/1253 failed - authentication failed - invalid ticket - expired
...
2022-06-13T06:24:18+03:00: TASK ERROR: sync failed with some errors.

 

[fabian]

the lines before "permission check failed" would be interesting if possible..

 

[indi]

the lines before "permission check failed" would be interesting if possible..

2022-06-13T03:24:17+03:00: sync snapshot vm/1248/2022-06-12T21:29:35Z done
2022-06-13T03:24:17+03:00: percentage done: 83.75% (67/80 groups)
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-31T21:42:18Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-21T21:37:03Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-17T21:59:14Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-06-02T21:45:58Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-19T21:48:16Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-06-01T21:38:27Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-18T21:45:43Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-14T22:32:14Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-22T21:33:49Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-20T22:06:26Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-30T21:56:42Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-06-03T21:59:48Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2022-05-17T00:19:49Z
2022-06-13T03:24:17+03:00: delete vanished snapshot vm/1248/2021-07-24T21:38:13Z
2022-06-13T03:24:17+03:00: skipped: 6 snapshot(s) (2021-08-18T21:30:33Z .. 2022-05-28T21:37:46Z) older than the newest local snapshot
2022-06-13T03:24:18+03:00: sync snapshot vm/1249/2022-05-28T21:15:18Z
2022-06-13T03:24:18+03:00: sync archive qemu-server.conf.blob
2022-06-13T03:24:18+03:00: sync archive drive-virtio2.img.fidx
2022-06-13T03:24:18+03:00: downloaded 306857 bytes (0.37 MiB/s)
2022-06-13T03:24:18+03:00: sync archive drive-virtio1.img.fidx
2022-06-13T03:24:27+03:00: downloaded 3876161 bytes (0.46 MiB/s)
2022-06-13T03:24:27+03:00: sync archive drive-virtio0.img.fidx
2022-06-13T06:23:37+03:00: downloaded 75234291146 bytes (6.67 MiB/s)
2022-06-13T06:23:37+03:00: got backup log file "client.log.blob"
2022-06-13T06:23:37+03:00: sync snapshot vm/1249/2022-05-28T21:15:18Z done
2022-06-13T06:23:37+03:00: percentage done: 84.25% (67/80 groups, 6/15 snapshots in group #68)
2022-06-13T06:23:40+03:00: sync group vm/1249 failed - permission check failed.
2022-06-13T06:23:43+03:00: sync group vm/1250 failed - authentication failed - invalid ticket - expired
2022-06-13T06:23:48+03:00: sync group vm/1252 failed - authentication failed - invalid ticket - expired
...

Аnd a long list of successful syncs before that.

At remote source at Tasks:
Datastore hot Read Objects VM 1248:

2022-06-13T02:54:52+03:00: starting new backup reader datastore 'hot': "/mnt/big/hot"
...
2022-06-13T03:24:17+03:00: reader finished successfully
2022-06-13T03:24:17+03:00: TASK OK

Datastore hot Read Objects VM 1249:

2022-06-13T03:24:18+03:00: starting new backup reader datastore 'hot': "/mnt/big/hot"
...
2022-06-13T06:23:37+03:00: reader finished successfully
2022-06-13T06:23:37+03:00: TASK OK

and nothing more

 

[fabian]

thanks! that seems like a pretty clear reproducer (individual group / snapshot / index taking longer than 2h to sync).

 

[indi]

thanks! that seems like a pretty clear reproducer (individual group / snapshot / index taking longer than 2h to sync).

vm/1247 at same Task also longer than 2h to sync but would not break the Task:

...
2022-06-12T08:37:24+03:00: re-sync snapshot vm/1247/2022-06-05T21:19:02Z
2022-06-12T08:37:24+03:00: no data changes
2022-06-12T08:37:24+03:00: re-sync snapshot vm/1247/2022-06-05T21:19:02Z done
2022-06-12T08:37:24+03:00: percentage done: 81.96% (65/80 groups, 8/14 snapshots in group #66)
2022-06-12T08:37:24+03:00: sync snapshot vm/1247/2022-06-06T21:33:18Z
2022-06-12T08:37:24+03:00: sync archive qemu-server.conf.blob
2022-06-12T08:37:24+03:00: sync archive drive-virtio1.img.fidx
2022-06-12T08:41:05+03:00: downloaded 1274636610 bytes (5.50 MiB/s)
2022-06-12T08:41:05+03:00: sync archive drive-virtio0.img.fidx
2022-06-12T12:20:46+03:00: downloaded 76539589884 bytes (5.54 MiB/s)
2022-06-12T12:20:46+03:00: got backup log file "client.log.blob"
2022-06-12T12:20:46+03:00: sync snapshot vm/1247/2022-06-06T21:33:18Z done
2022-06-12T12:20:46+03:00: percentage done: 82.05% (65/80 groups, 9/14 snapshots in group #66)
2022-06-12T12:20:46+03:00: sync snapshot vm/1247/2022-06-07T21:30:43Z
2022-06-12T12:20:46+03:00: sync archive qemu-server.conf.blob
2022-06-12T12:20:46+03:00: sync archive drive-virtio1.img.fidx
2022-06-12T12:23:00+03:00: downloaded 844823011 bytes (6.05 MiB/s)
2022-06-12T12:23:00+03:00: sync archive drive-virtio0.img.fidx
2022-06-12T15:46:04+03:00: downloaded 76450090945 bytes (5.98 MiB/s)
2022-06-12T15:46:04+03:00: got backup log file "client.log.blob"
2022-06-12T15:46:04+03:00: sync snapshot vm/1247/2022-06-07T21:30:43Z done
2022-06-12T15:46:04+03:00: percentage done: 82.14% (65/80 groups, 10/14 snapshots in group #66)
2022-06-12T15:46:04+03:00: sync snapshot vm/1247/2022-06-08T21:27:52Z
2022-06-12T15:46:04+03:00: sync archive qemu-server.conf.blob
2022-06-12T15:46:04+03:00: sync archive drive-virtio1.img.fidx
2022-06-12T15:50:25+03:00: downloaded 1776345946 bytes (6.50 MiB/s)
2022-06-12T15:50:25+03:00: sync archive drive-virtio0.img.fidx
2022-06-12T18:48:55+03:00: downloaded 72494847128 bytes (6.46 MiB/s)
2022-06-12T18:48:55+03:00: got backup log file "client.log.blob"
2022-06-12T18:48:55+03:00: sync snapshot vm/1247/2022-06-08T21:27:52Z done
2022-06-12T18:48:55+03:00: percentage done: 82.23% (65/80 groups, 11/14 snapshots in group #66)
2022-06-12T18:48:55+03:00: sync snapshot vm/1247/2022-06-09T21:38:07Z
2022-06-12T18:48:55+03:00: sync archive qemu-server.conf.blob
2022-06-12T18:48:56+03:00: sync archive drive-virtio1.img.fidx
2022-06-12T18:53:51+03:00: downloaded 2073559258 bytes (6.69 MiB/s)
2022-06-12T18:53:51+03:00: sync archive drive-virtio0.img.fidx
2022-06-12T21:59:11+03:00: downloaded 73552910743 bytes (6.31 MiB/s)
2022-06-12T21:59:11+03:00: got backup log file "client.log.blob"
2022-06-12T21:59:11+03:00: sync snapshot vm/1247/2022-06-09T21:38:07Z done
2022-06-12T21:59:11+03:00: percentage done: 82.32% (65/80 groups, 12/14 snapshots in group #66)
2022-06-12T21:59:11+03:00: sync snapshot vm/1247/2022-06-10T21:35:52Z
2022-06-12T21:59:11+03:00: sync archive qemu-server.conf.blob
2022-06-12T21:59:11+03:00: sync archive drive-virtio1.img.fidx
2022-06-12T22:03:02+03:00: downloaded 1623790828 bytes (6.70 MiB/s)
2022-06-12T22:03:02+03:00: sync archive drive-virtio0.img.fidx
2022-06-13T00:57:52+03:00: downloaded 72734442323 bytes (6.61 MiB/s)
2022-06-13T00:57:52+03:00: got backup log file "client.log.blob"
2022-06-13T00:57:52+03:00: sync snapshot vm/1247/2022-06-10T21:35:52Z done
2022-06-13T00:57:52+03:00: percentage done: 82.41% (65/80 groups, 13/14 snapshots in group #66)
2022-06-13T00:57:52+03:00: sync snapshot vm/1247/2022-06-11T21:19:43Z
2022-06-13T00:57:52+03:00: sync archive qemu-server.conf.blob
2022-06-13T00:57:52+03:00: sync archive drive-virtio1.img.fidx
2022-06-13T00:57:53+03:00: downloaded 0 bytes (0.00 MiB/s)
2022-06-13T00:57:53+03:00: sync archive drive-virtio0.img.fidx
2022-06-13T02:03:24+03:00: downloaded 27583842253 bytes (6.69 MiB/s)
2022-06-13T02:03:24+03:00: got backup log file "client.log.blob"
2022-06-13T02:03:24+03:00: sync snapshot vm/1247/2022-06-11T21:19:43Z done
2022-06-13T02:03:24+03:00: percentage done: 82.50% (66/80 groups)
2022-06-13T02:03:25+03:00: delete vanished snapshot vm/1247/2022-06-01T21:35:34Z
2022-06-13T02:03:25+03:00: delete vanished snapshot vm/1247/2022-06-03T21:45:06Z
2022-06-13T02:03:25+03:00: delete vanished snapshot vm/1247/2022-05-31T21:31:07Z
2022-06-13T02:03:25+03:00: delete vanished snapshot vm/1247/2022-06-02T21:56:39Z
2022-06-13T02:03:25+03:00: delete vanished snapshot vm/1247/2022-05-30T21:28:01Z
2022-06-13T02:03:25+03:00: delete vanished snapshot vm/1247/2022-05-29T21:19:03Z
...

 

[sterzy]

Hi,

@indi can you maybe provide your pbs version and the journal from the time of the log (journalctl --since="2022-06-12" --until="2022-06-15")?

Thanks!