Re: [PATCH proxmox-backup v6 11/15] server: pull: prefix log messages and add error context

Christian Ebner
2026-04-21T08:05:37Z

On 4/21/26 9:59 AM, Fabian Grünbichler wrote:
> On April 21, 2026 9:42 am, Christian Ebner wrote:
>> On 4/21/26 9:21 AM, Christian Ebner wrote:
>>> On 4/20/26 1:54 PM, Fabian Grünbichler wrote:
>>>> On April 17, 2026 11:26 am, Christian Ebner wrote:
>>>>> Pulling groups and therefore also snapshots in parallel leads to
>>>>> unordered log outputs, making it mostly impossible to relate a log
>>>>> message to a backup snapshot/group.
>>>>>
>>>>> Therefore, prefix pull job log messages by the corresponding group or
>>>>> snapshot and set the error context accordingly.
>>>>>
>>>>> Also, reword some messages, inline variables in format strings and
>>>>> start log lines with capital letters to get consistent output.
>>>>>
>>>>> By using the buffered logger implementation and buffer up to 5 lines
>>>>> with a timeout of 1 second, subsequent log lines arriving in fast
>>>>> succession are kept together, reducing the mixing of lines.
>>>>>
>>>>> Example output for a sequential pull job:
>>>>> ```
>>>>> ...
>>>>> [ct/100]: 2025-11-17T10:11:42Z: start sync
>>>>> [ct/100]: 2025-11-17T10:11:42Z: pct.conf.blob: sync archive
>>>>> [ct/100]: 2025-11-17T10:11:42Z: root.ppxar.didx: sync archive
>>>>> [ct/100]: 2025-11-17T10:11:42Z: root.ppxar.didx: downloaded 16.785
>>>>> MiB (280.791 MiB/s)
>>>>> [ct/100]: 2025-11-17T10:11:42Z: root.mpxar.didx: sync archive
>>>>> [ct/100]: 2025-11-17T10:11:42Z: root.mpxar.didx: downloaded 65.703
>>>>> KiB (29.1 MiB/s)
>>>>> [ct/100]: 2025-11-17T10:11:42Z: sync done
>>>>> [ct/100]: percentage done: 9.09% (1/11 groups)
>>>>> [ct/101]: 2026-03-31T12:20:16Z: start sync
>>>>> [ct/101]: 2026-03-31T12:20:16Z: pct.conf.blob: sync archive
>>>>> [ct/101]: 2026-03-31T12:20:16Z: root.pxar.didx: sync archive
>>>>> [ct/101]: 2026-03-31T12:20:16Z: root.pxar.didx: downloaded 199.806
>>>>> MiB (311.91 MiB/s)
>>>>> [ct/101]: 2026-03-31T12:20:16Z: catalog.pcat1.didx: sync archive
>>>>> [ct/101]: 2026-03-31T12:20:16Z: catalog.pcat1.didx: downloaded
>>>>> 180.379 KiB (22.748 MiB/s)
>>>>> [ct/101]: 2026-03-31T12:20:16Z: sync done
>>>>
>>>> this is probably the wrong patch for this comment, but since you have
>>>> the sample output here ;)
>>>>
>>>> should we pad the labels? the buffered logger knows all currently active
>>>> labels and could adapt it? otherwise especially for host backups the
>>>> logs are again not really scannable by humans, because there will be
>>>> weird jumps in alignment.. or (.. continued below)
>>>
>>> That will not work though? While the logger knows about the labels when
>>> receiving them, it does not know at all about future ones that might
>>> still come in. So it can happen that the padding does not fit anymore,
>>> and one gets even uglier formatting issues.
>>>
>>> I would prefer to keep them as is for the time being. For vm/ct it is
>>> not that bad, one could maybe forsee the ID to be a 4 digit number and
>>> define a minimum label lenght to be padded if not reached.
>
> ack, let's leave this as it is for now, can always be bikeshedded if
> needed later on!
>
>>>
>>> Host backups or backups with explicit label
>>>
>
> cut off?
>
>>>
>>>>> ...
>>>>> ```
>>>>>
>>>>> Example output for a parallel pull job:
>>>>> ```
>>>>> ...
>>>>> [ct/107]: 2025-07-16T09:14:01Z: start sync
>>>>> [ct/107]: 2025-07-16T09:14:01Z: pct.conf.blob: sync archive
>>>>> [ct/107]: 2025-07-16T09:14:01Z: root.ppxar.didx: sync archive
>>>>> [vm/108]: 2025-09-19T07:37:19Z: start sync
>>>>> [vm/108]: 2025-09-19T07:37:19Z: qemu-server.conf.blob: sync archive
>>>>> [vm/108]: 2025-09-19T07:37:19Z: drive-scsi0.img.fidx: sync archive
>>>>> [ct/107]: 2025-07-16T09:14:01Z: root.ppxar.didx: downloaded 609.233
>>>>> MiB (112.628 MiB/s)
>>>>> [ct/107]: 2025-07-16T09:14:01Z: root.mpxar.didx: sync archive
>>>>> [ct/107]: 2025-07-16T09:14:01Z: root.mpxar.didx: downloaded 1.172 MiB
>>>>> (17.838 MiB/s)
>>>>> [ct/107]: 2025-07-16T09:14:01Z: sync done
>>>>> [ct/107]: percentage done: 72.73% (8/11 groups)
>>>>
>>>> the way the prefix and snapshot are formatted could also be interpreted
>>>> at first glance as a timestamp of the log line.. why not just prepend
>>>> the prefix on the logger side, and leave it up to the caller to do the
>>>> formatting? then we could us "{type}/{id}/" as prefix here? or add
>>>> 'snapshot' in those lines to make it clear? granted, this is more of an
>>>> issue when viewing the log via `proxmox-backup-manager`, as in the UI we
>>>> have the log timestamps up front..
>>>
>>> I simply followed along the line of your suggestion here. In prior
>>> versions I had exactly that but you rejected it as to verbose? :)
>>>
>>> https://lore.proxmox.com/pbs-devel/1774263381.bngcrer2th.astroid@yuna.none/
>>>
>
> my suggestions (for just the ct/107 lines above) would have been:
>
> ct/107: 2025-07-16T09:14:01Z: start sync
> ct/107: 2025-07-16T09:14:01Z pct.conf.blob: sync archive
> ct/107: 2025-07-16T09:14:01Z root.ppxar.didx: sync archive
> ct/107: 2025-07-16T09:14:01Z root.ppxar.didx: downloaded 609.233 MiB (112.628 MiB/s)
> ct/107: 2025-07-16T09:14:01Z root.mpxar.didx: sync archive
> ct/107: 2025-07-16T09:14:01Z root.mpxar.didx: downloaded 1.172 MiB (17.838 MiB/s)
> ct/107: 2025-07-16T09:14:01Z: sync done
> ct/107: percentage done: 72.73% (8/11 groups)
>
> though it might make sense to group that even more visually
>
> ct/107: 2025-07-16T09:14:01Z: start sync
> ct/107: 2025-07-16T09:14:01Z/pct.conf.blob: sync archive
> ct/107: 2025-07-16T09:14:01Z/root.ppxar.didx: sync archive
> ct/107: 2025-07-16T09:14:01Z/root.ppxar.didx: downloaded 609.233 MiB (112.628 MiB/s)
> ct/107: 2025-07-16T09:14:01Z/root.mpxar.didx: sync archive
> ct/107: 2025-07-16T09:14:01Z/root.mpxar.didx: downloaded 1.172 MiB (17.838 MiB/s)
> ct/107: 2025-07-16T09:14:01Z: sync done
> ct/107: percentage done: 72.73% (8/11 groups)
>
> or
>
> [ct/107 2025-07-16T09:14:01Z] start sync
> [ct/107 2025-07-16T09:14:01Z pct.conf.blob] sync archive
> [ct/107 2025-07-16T09:14:01Z root.ppxar.didx] sync archive
> [ct/107 2025-07-16T09:14:01Z root.ppxar.didx] downloaded 609.233 MiB (112.628 MiB/s)
> [ct/107 2025-07-16T09:14:01Z root.mpxar.didx] sync archive
> [ct/107 2025-07-16T09:14:01Z root.mpxar.didx] downloaded 1.172 MiB (17.838 MiB/s)
> [ct/107 2025-07-16T09:14:01Z] sync done
> [ct/107] percentage done: 72.73% (8/11 groups)
>
> but that is probably a matter of taste, so let's postpone this aspect
> for now.
>
>>>>
>>>> and maybe(?) log the progress line using a different prefix? because
>>>> right now the information that the group [ct/107] is finished is not
>>>> really clear from the output, IMHO.
>>>
>>> That I can add, yes.
>
> thanks!
>
>>>
>>>>
>>>> the progress logging is also still broken (this is for a sync that takes
>>>> a while, this is not log messages being buffered and re-ordered!):
>>>>
>>>> $ proxmox-backup-manager task log
>>>> 'UPID:yuna:00070656:001E420F:00000002:69E610EB:syncjob:local\x3atest\x3atank\x3a\x3as\x2dbc01cba6\x2d805a:root@pam:' | grep -e namespace -e 'percentage done'
>>>> Syncing datastore 'test', root namespace into datastore 'tank', root
>>>> namespace
>>>> Finished syncing root namespace, current progress: 0 groups, 0 snapshots
>>>> Syncing datastore 'test', namespace 'test' into datastore 'tank',
>>>> namespace 'test'
>>>> [host/exclusion-test]: percentage done: 5.26% (1/19 groups)
>>>> [host/acltest]: percentage done: 5.26% (1/19 groups)
>>>> [host/logtest]: percentage done: 5.26% (1/19 groups)
>>>> [host/onemeg]: percentage done: 5.26% (1/19 groups)
>>>> [host/fourmeg]: percentage done: 2.63% (0/19 groups, 1/2 snapshots in
>>>> group #1)
>>>> [host/symlink]: percentage done: 2.63% (0/19 groups, 1/2 snapshots in
>>>> group #1)
>>>> [host/symlink]: percentage done: 5.26% (1/19 groups)
>>>> [host/fourmeg]: percentage done: 5.26% (1/19 groups)
>>>> [host/format-v2-test]: percentage done: 1.75% (0/19 groups, 1/3
>>>> snapshots in group #1)
>>>> [host/format-v2-test]: percentage done: 3.51% (0/19 groups, 2/3
>>>> snapshots in group #1)
>>>> [host/format-v2-test]: percentage done: 5.26% (1/19 groups)
>>>> [host/incrementaltest2]: percentage done: 2.63% (0/19 groups, 1/2
>>>> snapshots in group #1)
>>>> [host/incrementaltest2]: percentage done: 5.26% (1/19 groups)
>>>
>>> There will always be cases where it does not work I guess, not sure what
>>> I can do to make you happy here.
>>
>> Oh, sorry, might have been to quick on this one. You are saying this
>> happens for a non-parallel sync?
>
> no, this was a parallel sync, but the progress should be correct for
> parallel syncs as well, shouldn't it?
>
> here's the same log but less truncated:
>
> [..]
> 2026-04-20T13:41:31+02:00: ----
> 2026-04-20T13:41:31+02:00: Syncing datastore 'test', namespace 'test' into datastore 'tank', namespace 'test'
> 2026-04-20T13:41:31+02:00: Found 19 groups to sync (out of 19 total)
> 2026-04-20T13:41:31+02:00: [ct/106]: sync group ct/106 failed - owner check failed (test@pbs != root@pam)
> 2026-04-20T13:41:31+02:00: [ct/999]: sync group ct/999 failed - owner check failed (test@pbs != root@pam)
> 2026-04-20T13:41:31+02:00: skipping snapshot host/test-another-mail/2024-03-14T08:44:25Z - in-progress backup
> 2026-04-20T13:41:31+02:00: [host/exclusion-test]: host/exclusion-test: skipped: 1 snapshot(s) (2024-04-23T06:53:44Z) - older than the newest snapshot present on sync target
> 2026-04-20T13:41:31+02:00: [host/exclusion-test]: re-sync snapshot 2024-04-23T06:54:30Z
> 2026-04-20T13:41:31+02:00: [host/exclusion-test]: 2024-04-23T06:54:30Z: no data changes
> 2026-04-20T13:41:31+02:00: [host/exclusion-test]: percentage done: 5.26% (1/19 groups)
> 2026-04-20T13:41:31+02:00: [host/acltest]: re-sync snapshot 2024-10-07T11:17:58Z
> 2026-04-20T13:41:31+02:00: [host/acltest]: 2024-10-07T11:17:58Z: no data changes
> 2026-04-20T13:41:31+02:00: [host/acltest]: percentage done: 5.26% (1/19 groups)
> 2026-04-20T13:41:32+02:00: [host/logtest]: 2024-01-30T10:52:34Z: start sync
> 2026-04-20T13:41:32+02:00: [host/logtest]: 2024-01-30T10:52:34Z: test.pxar.didx: sync archive
> 2026-04-20T13:41:32+02:00: [host/logtest]: 2024-01-30T10:52:34Z: test.pxar.didx: downloaded 13.169 KiB (168.332 KiB/s)
> 2026-04-20T13:41:32+02:00: [host/logtest]: 2024-01-30T10:52:34Z: catalog.pcat1.didx: sync archive
> 2026-04-20T13:41:32+02:00: [host/logtest]: 2024-01-30T10:52:34Z: catalog.pcat1.didx: downloaded 2.157 KiB (10.2 KiB/s)
> 2026-04-20T13:41:32+02:00: [host/logtest]: 2024-01-30T10:52:34Z: rsa-encrypted.key.blob: sync archive
> 2026-04-20T13:41:33+02:00: [host/logtest]: 2024-01-30T10:52:34Z: sync done
> 2026-04-20T13:41:33+02:00: [host/logtest]: percentage done: 5.26% (1/19 groups)
> 2026-04-20T13:41:33+02:00: [host/onemeg]: 2023-06-28T11:13:51Z: start sync
> 2026-04-20T13:41:33+02:00: [host/onemeg]: 2023-06-28T11:13:51Z: test.img.fidx: sync archive
> 2026-04-20T13:41:33+02:00: [host/onemeg]: 2023-06-28T11:13:51Z: test.img.fidx: downloaded 2.012 KiB (5.704 KiB/s)
> 2026-04-20T13:41:33+02:00: [host/onemeg]: 2023-06-28T11:13:51Z: sync done
> 2026-04-20T13:41:33+02:00: [host/onemeg]: percentage done: 5.26% (1/19 groups)
> 2026-04-20T13:41:33+02:00: [host/fourmeg]: 2023-06-28T11:14:35Z: start sync
> 2026-04-20T13:41:33+02:00: [host/fourmeg]: 2023-06-28T11:14:35Z: test.img.fidx: sync archive
> 2026-04-20T13:41:33+02:00: [host/fourmeg]: 2023-06-28T11:14:35Z: test.img.fidx: downloaded 2.012 KiB (5.885 KiB/s)
> 2026-04-20T13:41:33+02:00: [host/fourmeg]: 2023-06-28T11:14:35Z: sync done
> 2026-04-20T13:41:33+02:00: [host/fourmeg]: percentage done: 2.63% (0/19 groups, 1/2 snapshots in group #1)
> 2026-04-20T13:41:33+02:00: [host/fourmeg]: 2023-06-28T12:37:16Z: start sync
> 2026-04-20T13:41:34+02:00: [host/symlink]: 2023-06-07T06:48:26Z: start sync
> 2026-04-20T13:41:34+02:00: [host/symlink]: 2023-06-07T06:48:26Z: symlink.pxar.didx: sync archive
> 2026-04-20T13:41:34+02:00: [host/symlink]: 2023-06-07T06:48:26Z: symlink.pxar.didx: downloaded 145 B (802.587 B/s)
> 2026-04-20T13:41:34+02:00: [host/symlink]: 2023-06-07T06:48:26Z: catalog.pcat1.didx: sync archive
> 2026-04-20T13:41:34+02:00: [host/symlink]: 2023-06-07T06:48:26Z: catalog.pcat1.didx: downloaded 57 B (279.566 B/s)
> 2026-04-20T13:41:34+02:00: [host/symlink]: 2023-06-07T06:48:26Z: sync done
> 2026-04-20T13:41:37+02:00: [host/incrementaltest2]: 2023-09-25T13:43:25Z: start sync
> 2026-04-20T13:41:37+02:00: [host/incrementaltest2]: 2023-09-25T13:43:25Z: test.pxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/format-v3-test]: 2024-06-03T10:34:11Z: start sync
> 2026-04-20T13:41:37+02:00: [host/format-v3-test]: 2024-06-03T10:34:11Z: linux.ppxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/fourmeg]: 2023-06-28T12:37:16Z: test.img.fidx: sync archive
> 2026-04-20T13:41:37+02:00: [host/linuxtesttest]: 2024-07-17T13:38:31Z: start sync
> 2026-04-20T13:41:37+02:00: [host/linuxtesttest]: 2024-07-17T13:38:31Z: linux.pxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/inctest]: 2023-11-13T13:22:57Z: start sync
> 2026-04-20T13:41:37+02:00: [host/inctest]: 2023-11-13T13:22:57Z: test.pxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/inctest2]: 2023-11-13T13:53:27Z: start sync
> 2026-04-20T13:41:37+02:00: [host/inctest2]: 2023-11-13T13:53:27Z: test.pxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/format-v2-test]: 2024-06-07T12:08:37Z: start sync
> 2026-04-20T13:41:37+02:00: [host/format-v2-test]: 2024-06-07T12:08:37Z: linux.ppxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/foobar]: re-sync snapshot 2024-06-10T07:48:51Z due to corruption
> 2026-04-20T13:41:37+02:00: [host/foobar]: 2024-06-10T07:48:51Z: foobar.ppxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/symlink]: percentage done: 2.63% (0/19 groups, 1/2 snapshots in group #1)
> 2026-04-20T13:41:37+02:00: [host/symlink]: 2023-06-07T06:49:43Z: start sync
> 2026-04-20T13:41:37+02:00: [host/symlink]: 2023-06-07T06:49:43Z: foo.pxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/symlink]: 2023-06-07T06:49:43Z: foo.pxar.didx: downloaded 0 B (0 B/s)
> 2026-04-20T13:41:37+02:00: [host/symlink]: 2023-06-07T06:49:43Z: catalog.pcat1.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/bookworm]: re-sync snapshot 2023-01-18T11:10:34Z due to corruption
> 2026-04-20T13:41:37+02:00: [host/bookworm]: 2023-01-18T11:10:34Z: repo.pxar.didx: sync archive
> 2026-04-20T13:41:37+02:00: [host/test]: 2024-07-10T08:18:51Z: start sync
> 2026-04-20T13:41:37+02:00: [host/test]: 2024-07-10T08:18:51Z: test.img.fidx: sync archive
> 2026-04-20T13:41:37+02:00: [host/symlink]: 2023-06-07T06:49:43Z: catalog.pcat1.didx: downloaded 53 B (216.705 B/s)
> 2026-04-20T13:41:37+02:00: [host/symlink]: 2023-06-07T06:49:43Z: sync done
> 2026-04-20T13:41:37+02:00: [host/symlink]: percentage done: 5.26% (1/19 groups)
> 2026-04-20T13:42:55+02:00: [host/fourmeg]: 2023-06-28T12:37:16Z: test.img.fidx: downloaded 4 MiB (51.191 KiB/s)
> 2026-04-20T13:42:55+02:00: [host/fourmeg]: 2023-06-28T12:37:16Z: sync done
> 2026-04-20T13:42:55+02:00: [host/fourmeg]: percentage done: 5.26% (1/19 groups)
>
> those percentage lines are just complete bogus?? and there are at least
> two "breaks" of over a second where all buffered log lines must have
> been flushed, so it's also not that the lines with lower perecentage
> were re-ordered somehow..
>
> it goes on and on and the percentage always stays at at most 5.26% since
> the finished group count never goes higher than 1.. though I have to
> admit I stopped it before it finished, so maybe it would have later gone
> higher? I can re-run it to completion and check what it says before it's
> done?
That is because the store progress calculates the percent based on the
groups and snapshots within that group. But since groups are now being
pulled in parallel, the percent is per group... Not sure if and how to
fix that.