Last backup stats not recorded correctly.

[adhawkins]

Current emborg version installed:

xcp-alpine-emborg:~$ emborg --version
1.37 (2023-05-18)

I realise there's a newer version, but I need to schedule this in to coincide with the borg update that requires potential repository maintenance when upgrading.

I run emborg daily to back up a number of different locations. I receive emails showing that these daily backups are taking place.

However, in vmbackup.latest.nt I see:

xcp-alpine-emborg:~# cat "/root/.local/share/emborg/vmbackup.latest.nt"
prune last run: 2023-11-22T06:24:35.640750+00:00
compact last run: 2023-11-22T06:34:30.703805+00:00
create last run: 2023-10-06T05:56:39.428824+01:00
repository size: 1.12410685623 TB

The due command seems to reflect these entries:

xcp-alpine-emborg:~# emborg -c vmbackup due
vmbackup: 7 weeks since last backup.  1 hour since last squeeze.

However, if I list mybackups:

xcp-alpine-emborg:~# emborg -c vmbackup list
2023-11-16-09-41-57
2023-11-17-02-10-12
2023-11-18-04-08-49
2023-11-19-01-45-51
2023-11-20-01-58-45
2023-11-21-02-39-19
2023-11-22-02-11-52

The backup is run using:

emborg -c "$config" create --fast --stats 2>&1
emborg -c "$config" prune --list --stats 2>&1

In this case, $config would be vmbackup.

It would appear that the value for repository size also isn't being updated, as the history for this records the same value since the last logged backup (in /root/.local/share/borg-space/vmbackup@x cp-alpine-emborg~root.nt):

2023-09-30T11:18:10.731709+01:00: 1113311319163 B
2023-10-01T02:42:51.382073+01:00: 1158662549918 B
2023-10-02T05:55:06.626976+01:00: 1143813525675 B
2023-10-03T05:58:07.490206+01:00: 1141503358125 B
2023-10-04T05:51:56.327845+01:00: 1140701585959 B
2023-10-05T05:51:55.519148+01:00: 1136526156979 B
2023-10-06T05:56:35.261144+01:00: 1130838572820 B
2023-10-07T12:46:31.067724+01:00: 1124106856230 B
2023-10-08T02:34:19.302866+01:00: 1124106856230 B
2023-10-09T05:48:23.424443+01:00: 1124106856230 B
2023-10-10T05:48:40.422909+01:00: 1124106856230 B
2023-10-11T06:01:54.106732+01:00: 1124106856230 B
2023-10-12T05:54:50.294790+01:00: 1124106856230 B
2023-10-13T05:59:34.779661+01:00: 1124106856230 B
2023-10-14T10:48:04.502385+01:00: 1124106856230 B
2023-10-15T02:37:06.215715+01:00: 1124106856230 B
2023-10-16T05:56:02.510948+01:00: 1124106856230 B
2023-10-17T06:05:28.394421+01:00: 1124106856230 B
2023-10-18T05:54:20.470430+01:00: 1124106856230 B
2023-10-19T06:17:28.836173+01:00: 1124106856230 B
2023-10-20T06:08:04.801336+01:00: 1124106856230 B
2023-10-21T11:12:57.730766+01:00: 1124106856230 B
2023-10-22T02:48:32.918130+01:00: 1124106856230 B

Am I doing something wrong?

[KenKundert]

I have a partial answer for you. The --fast option suppresses the step where emborg asks borg for the repository size. In version 1.37 if you asked for --fast the previous repository size was kept. In version 1.38 the repository size is now deleted when you use --fast.

I'll keep looking to see why the create date is not being updated, but you might want to simply retry your backup without the --fast option. That might just fix everything. You don't want --fast anyway if you are tracking your respository size with borg-space. I should probably make a note of that in the borg-space documentation.

[KenKundert]

I have installed version 1.37, but cannot replicate your issue. Updating the latest file is the last thing the create command does. Can you check the logfile and look for 'updating date file for create' to see if it is attempting to update latest. Perhaps you can email me the logfile so I can take a look.

[adhawkins]

This is the log of a manually run create using the same options:

xcp-alpine-emborg:~/.local/share/emborg# cat vmbackup.log
emborg: version: 1.37 (2023-05-18)
emborg: invoked as: /usr/bin/emborg -c vmbackup create --fast --stats
emborg: log opened on Thursday, 23 November 2023 at 9:57:43 AM GMT.
reading: /root/.config/emborg/settings
reading: /root/.config/emborg/vmbackup
working directory: /
running command: create
staging run_before_backup[0] pre-backup script
running: borg \
    '--version;' \
    echo \
    'emborg $(emborg --version);' \
    echo \
    'borg-space $(borg-space --version)'
exit status: 0
signaling start of backups to healthchecks.io: https://healthchecks.gently.org.uk:7000/ping/d15bf895-403d-4dca-8a19-024f02df2fdf/start.
Setting BORG_PASSPHRASE.
Borg-related environment variables: {
    'BORG_PASSPHRASE': '<redacted>',
    'BORG_DISPLAY_PASSPHRASE': 'no',
    'BORG_RSH': 'ssh -4 -i /root/.ssh/id_emborg',
}
running in: /

Running Borg create command ...
running:
    borg \
        create \
        --stats \
        '<redacted>@<redacted>.repo.borgbase.com:repo::{now:%Y-%m-%d-%H-%M-%S}' \
        /backups/vmbackup
starts at: 2023-11-23T09:57:45.283275+00:00
Unsetting BORG_PASSPHRASE.
ends at: 2023-11-23T09:57:54.494447+00:00
elapsed: 0:00:09.211172
Borg exit status: 0
staging run_after_backup[0] post-backup script
running: borg-space -r vmbackup --style compact
exit status: 0
staging run_after_backup[1] post-backup script
running: borg-space -g -S /var/www/localhost/htdocs/vmbackup.svg vmbackup
exit status: 0
signaling success of backups to healthchecks.io: https://healthchecks.gently.org.uk:7000/ping/d15bf895-403d-4dca-8a19-024f02df2fdf/0.
emborg: terminates with status 0.
emborg: log closed on Thursday, 23 November 2023 at 9:57:55 AM GMT.

No mention there of updating the date file as far as I can see. If I look at the previous log, it does include an entry for the prune and compact steps:

xcp-alpine-emborg:~/.local/share/emborg# cat vmbackup.log.prev
emborg: version: 1.37 (2023-05-18)
emborg: invoked as: /usr/bin/emborg -c vmbackup prune --list --stats
emborg: log opened on Thursday, 23 November 2023 at 6:16:51 AM GMT.
reading: /root/.config/emborg/settings
reading: /root/.config/emborg/vmbackup
working directory: /
running command: prune
Setting BORG_PASSPHRASE.
Borg-related environment variables: {
    'BORG_PASSPHRASE': '<redacted>',
    'BORG_DISPLAY_PASSPHRASE': 'no',
    'BORG_RSH': 'ssh -4 -i /root/.ssh/id_emborg',
}
running in: /root/emborg-scripts

Running Borg prune command ...
running:
    borg \
        prune \
        --stats \
        --list \
        --keep-daily 7 \
        <redacted>@<redacted>.repo.borgbase.com:repo
starts at: 2023-11-23T06:16:51.040680+00:00
Unsetting BORG_PASSPHRASE.
ends at: 2023-11-23T06:23:12.003146+00:00
elapsed: 0:06:20.962466
Borg exit status: 0
updating date file for prune: /root/.local/share/emborg/vmbackup.latest.nt
Compacting repository ...
Setting BORG_PASSPHRASE.
Borg-related environment variables: {
    'BORG_DISPLAY_PASSPHRASE': 'no',
    'BORG_RSH': 'ssh -4 -i /root/.ssh/id_emborg',
    'BORG_PASSPHRASE': '<redacted>',
}
running in: /root/emborg-scripts
running:
    borg compact --threshold 1 <redacted>@<redacted>.repo.borgbase.com:repo
starts at: 2023-11-23T06:23:12.005517+00:00
Unsetting BORG_PASSPHRASE.
ends at: 2023-11-23T06:34:15.304062+00:00
elapsed: 0:11:03.298545
Borg exit status: 0
updating date file for compact: /root/.local/share/emborg/vmbackup.latest.nt
emborg: terminates with status 0.
emborg: log closed on Thursday, 23 November 2023 at 6:34:15 AM GMT.

This is the log of a run without --fast

xcp-alpine-emborg:~/.local/share/emborg# cat vmbackup.log
emborg: version: 1.37 (2023-05-18)
emborg: invoked as: /usr/bin/emborg -c vmbackup create --stats
emborg: log opened on Thursday, 23 November 2023 at 10:05:55 AM GMT.
reading: /root/.config/emborg/settings
reading: /root/.config/emborg/vmbackup
working directory: /
running command: create
staging run_before_backup[0] pre-backup script
running: borg \
    '--version;' \
    echo \
    'emborg $(emborg --version);' \
    echo \
    'borg-space $(borg-space --version)'
exit status: 0
signaling start of backups to healthchecks.io: https://healthchecks.gently.org.uk:7000/ping/d15bf895-403d-4dca-8a19-024f02df2fdf/start.
Setting BORG_PASSPHRASE.
Borg-related environment variables: {
    'BORG_PASSPHRASE': '<redacted>',
    'BORG_DISPLAY_PASSPHRASE': 'no',
    'BORG_RSH': 'ssh -4 -i /root/.ssh/id_emborg',
}
running in: /

Running Borg create command ...
running:
    borg \
        create \
        --stats \
        '<redacted>@<redacted>.repo.borgbase.com:repo::{now:%Y-%m-%d-%H-%M-%S}' \
        /backups/vmbackup
starts at: 2023-11-23T10:05:56.353153+00:00
Unsetting BORG_PASSPHRASE.
ends at: 2023-11-23T10:06:05.534054+00:00
elapsed: 0:00:09.180901
Borg exit status: 0
staging run_after_backup[0] post-backup script
running: borg-space -r vmbackup --style compact
exit status: 0
staging run_after_backup[1] post-backup script
running: borg-space -g -S /var/www/localhost/htdocs/vmbackup.svg vmbackup
exit status: 0
signaling success of backups to healthchecks.io: https://healthchecks.gently.org.uk:7000/ping/d15bf895-403d-4dca-8a19-024f02df2fdf/0.
Setting BORG_PASSPHRASE.
Borg-related environment variables: {
    'BORG_DISPLAY_PASSPHRASE': 'no',
    'BORG_RSH': 'ssh -4 -i /root/.ssh/id_emborg',
    'BORG_PASSPHRASE': '<redacted>',
}
running in: /root
running:
    borg info --json <redacted>@<redacted>.repo.borgbase.com:repo
starts at: 2023-11-23T10:06:06.625902+00:00
Unsetting BORG_PASSPHRASE.
ends at: 2023-11-23T10:06:08.338131+00:00
elapsed: 0:00:01.712229
Borg exit status: 0
Borg stdout:
    {
        "cache": {
            "path": "/root/.cache/borg/7c50729803423414cd223c0942868e8d1499861566648fd8ef78d3af9ecd2a07",
            "stats": {
                "total_chunks": 9607373,
                "total_csize": 11134883924296,
                "total_size": 21876082263446,
                "total_unique_chunks": 874485,
                "unique_csize": 1219575444743,
                "unique_size": 2650884902527
            }
        },
        "encryption": {
            "mode": "repokey-blake2"
        },
        "repository": {
            "id": "7c50729803423414cd223c0942868e8d1499861566648fd8ef78d3af9ecd2a07",
            "last_modified": "2023-11-23T10:06:02.000000",
            "location": "ssh://<redacted>@<redacted>.repo.borgbase.com/./repo"
        },
        "security_dir": "/root/.config/borg/security/7c50729803423414cd223c0942868e8d1499861566648fd8ef78d3af9ecd2a07"
    }

updating date file for create: /root/.local/share/emborg/vmbackup.latest.nt
emborg: terminates with status 0.
emborg: log closed on Thursday, 23 November 2023 at 10:06:08 AM GMT.

As you can see, that one does update the create date, after running borg --info

I can't remember why I decided to run with --fast. What does this flag do?

[adhawkins]

A bit more info. My settings file contains these:

prune_after_create = False
check_after_create = False

Could it be related to this?

[KenKundert]

Okay, I found the issue. I don't know why I did not see this earlier. My git foo failed me.

This is a bug in version 1.37. If you use the --fast option the latest file is not updated. The way to resolve this is to update to 1.38.

In your case the use if --fast does not really help you at all. --fast tells the create command to skip any configured prune, compact, and check operations in order to do a quick backup. But you have not configured a prune or check to run after the create, so --fast is largely a no-op for you.

[adhawkins]

Glad I could help you track it down.

I'll remove the '--fast' from my scripts. I was coming to the same conclusion as you that it was un-necessary as I have check / prune disabled in the config anyway.