Backup ended and finish failed: backup ended but finished flag is not set

[yena]

Hello,
what doas it mean
"backup ended but finished flag is not set" ?

2021-12-01T02:05:21+01:00: starting new backup on datastore 'PBSDAY': "ct/701/2021-12-01T01:05:20Z"
2021-12-01T02:05:21+01:00: add blob "/BACKUP/PBSDA/ct/701/2021-12-01T01:05:20Z/pct.conf.blob" (256 bytes, comp: 256)
2021-12-01T02:05:21+01:00: created new dynamic index 1 ("ct/701/2021-12-01T01:05:20Z/root.pxar.didx")
2021-12-01T02:05:21+01:00: created new dynamic index 2 ("ct/701/2021-12-01T01:05:20Z/catalog.pcat1.didx")
2021-12-01T02:28:31+01:00: backup ended and finish failed: backup ended but finished flag is not set.
2021-12-01T02:28:31+01:00: removing unfinished backup
2021-12-01T02:28:31+01:00: TASK ERROR: backup ended but finished flag is not set.

Thanks

 

[Moayad]

Hi,

what doas it mean
"backup ended but finished flag is not set" ?

do you have I/O in your PVE during the backup job? you can check for IO in PVE GUI Datacenter->{NodeName}->Summary section IO delay.

 

[yena]

Hi,

do you have I/O in your PVE during the backup job? you can check for IO in PVE GUI Datacenter->{NodeName}->Summary section IO delay.

My IO/DELAY is ner zero during Backup:

 

[fabian]

it means the client went away without calling the endpoint finalizing the backup (what does the client-side log say?)

 

[yena]

it means the client went away without calling the endpoint finalizing the backup (what does the client-side log say?)

Can i manage the number of simultaneus backup jobs ?
Thanks

 

[fabian]

no

 

[hagen]

I got the same error with PVE 7.2-4 and PBS 2.2-1.

At PVE I tried to start a backup job by a script:

export PBS_PASSWORD=<MY-SECRET-KEY>
/usr/bin/proxmox-backup-client backup mirror.pxar:/daten/backup/mirror/ \
  --backup-id mirror \
  --repository root@pam!backup@$PBS:Mirror \
  --exclude "/.recycle.bin/*" \
  --exclude "/*.log" \
  --exclude "/.svn/*"

At PBS I always get this error, e.g.:

2022-06-25T06:50:28+02:00: starting new backup on datastore 'Mirror': "host/mirror/2022-06-25T04:50:28Z"
2022-06-25T06:50:28+02:00: created new dynamic index 1 ("host/mirror/2022-06-25T04:50:28Z/catalog.pcat1.didx")
2022-06-25T06:50:28+02:00: created new dynamic index 2 ("host/mirror/2022-06-25T04:50:28Z/mirror.pxar.didx")
2022-06-26T01:54:23+02:00: backup ended and finish failed: backup ended but finished flag is not set.
2022-06-26T01:54:23+02:00: removing unfinished backup
2022-06-26T01:54:25+02:00: TASK ERROR: backup ended but finished flag is not set.

The logs at PVE are everytime something like that:

Jun 26 01:54:23 hf-pve01 systemd[1]: session-19114.scope: Succeeded.
Jun 26 01:54:23 hf-pve01 systemd[1]: session-19114.scope: Consumed 16h 39min 42.721s CPU time.
Jun 26 01:54:23 hf-pve01 systemd-logind[1145]: Removed session 19114.
Jun 26 01:54:33 hf-pve01 systemd[1]: Stopping User Manager for UID 0...
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Stopped target Main User Target.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Stopped target Basic System.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Stopped target Paths.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Stopped target Sockets.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Stopped target Timers.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: dirmngr.socket: Succeeded.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Closed GnuPG network certificate management daemon.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: gpg-agent-browser.socket: Succeeded.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jun 26 01:54:33 hf-pve01 systemd[3292090]: gpg-agent-extra.socket: Succeeded.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Jun 26 01:54:33 hf-pve01 systemd[3292090]: gpg-agent-ssh.socket: Succeeded.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Jun 26 01:54:33 hf-pve01 systemd[3292090]: gpg-agent.socket: Succeeded.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Closed GnuPG cryptographic agent and passphrase cache.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Removed slice User Application Slice.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Reached target Shutdown.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: systemd-exit.service: Succeeded.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Finished Exit the Session.
Jun 26 01:54:33 hf-pve01 systemd[3292090]: Reached target Exit the Session.
Jun 26 01:54:33 hf-pve01 systemd[1]: user@0.service: Succeeded.
Jun 26 01:54:33 hf-pve01 systemd[1]: Stopped User Manager for UID 0.
Jun 26 01:54:33 hf-pve01 systemd[1]: Stopping User Runtime Directory /run/user/0...
Jun 26 01:54:34 hf-pve01 systemd[1]: run-user-0.mount: Succeeded.
Jun 26 01:54:34 hf-pve01 systemd[1]: user-runtime-dir@0.service: Succeeded.
Jun 26 01:54:34 hf-pve01 systemd[1]: Stopped User Runtime Directory /run/user/0.
Jun 26 01:54:34 hf-pve01 systemd[1]: Removed slice User Slice of UID 0.
Jun 26 01:54:34 hf-pve01 systemd[1]: user-0.slice: Consumed 16h 39min 43.137s CPU time.
Jun 26 02:00:01 hf-pve01 audit[4080352]: ...

I have no further ideas to get this backup finished. Can you please give an advise?

 

[fabian]

whats the output of the client/script?

 

[hagen]

Sorry, the backup job takes approx. 16 hours. I started this task as background process.
Is there a default log file for proxmox-backup-client tasks?

If not, I have to pipe the stdout to a file for answering your question.

 

[fabian]

no, there's not. maybe the journal lines before Jun 26 01:54:23 contain some hint? but yeah, collecting stdout/stderr somewhere when doing expensive tasks unattended is usually a good idea

 

[hagen]

Great. This night the backup job have been successfully ended. No idea what's different to the last tries, because this were the same script files.

Starting backup: host/mirror/2022-06-27T07:16:27Z
Client name: hf-pve01
Starting backup protocol: Mon Jun 27 09:16:27 2022
No previous manifest available.
Upload directory '/daten/backup/mirror/' to 'root@pam!backup@<IP>:8007:Mirror' as mirror.pxar.didx
mirror.pxar: had to backup 3.338 TiB of 3.385 TiB (compressed 3.236 TiB) in 72110.14s
mirror.pxar: average backup speed: 48.544 MiB/s
mirror.pxar: backup was done incrementally, reused 48.072 GiB (1.4%)
Uploaded backup catalog (4.696 MiB)
Duration: 72111.07s
End Time: Tue Jun 28 05:18:18 2022