[BUG] tmprotect stopped making snapshots upon successful Time Machine backup: tmprotect_disconnect: No changes recorded in snapshot history file

[saspus]

TLDR: Some time ago tmprotect stopped taking new snapshots. The reasons seems to be it fails to detect changes in the history file, seemingly it does not recognize changed format of snapshot record in Sonoma.


The problem:
tmprotect stopped making snapshots upon successful Time Machine backup: tmprotect_disconnect: No changes recorded in snapshot history file

Software:
Current TrueNAS OS is TrueNAS-13.0-U5.3
MacOS 14.1(23B74)

Last snapshot in the list was taken back in October. (Before macOS update to Sonoma)

Repro:
I've enabled logging with:

Code:

net conf setparm global "log level" "1 tmprotect:10"
service smbd restart

and started watching

Code:

tail -f /var/log/samba4/log.smbd

I saved full log, but can't attach here for some reason.

Analysis:
It seems it is skipping all the lines in the lines in the com.apple.TimeMachine.SnapshotHistory.plist, including the last backup, and therefore does not detect any changes and skips snapshotting:

Code:

[2023/11/12 07:53:57.234725, 10, pid=49084, effective(0, 0), real(0, 0), class=tmprotect] ../../source3/modules/vfs_tmprotect.c:192(parse_history)
  parse_history: skipping line:             <string>2023-11-02-001226.backup</string>

...

[2023/11/12 07:53:57.235065,  5, pid=49084, effective(0, 0), real(0, 0), class=tmprotect] ../../source3/modules/vfs_tmprotect.c:323(history_changed)
  history_changed: Backup history file: 20 backups, last: 1698934346
[2023/11/12 07:53:57.235089,  5, pid=49084, effective(0, 0), real(0, 0), class=tmprotect] ../../source3/modules/vfs_tmprotect.c:356(tmprotect_disconnect)
  tmprotect_disconnect: No changes recorded in snapshot history file

Culrput
Here is the record in the dictionary entry in the current format:

Code:

        <dict>
            <key>com.apple.backupd.SnapshotCompletionDate</key>
            <date>2023-11-02T07:12:26Z</date>
            <key>com.apple.backupd.SnapshotName</key>
            <string>2023-11-02-001226.backup</string>
        </dict>

and here is the entry in the old format, pre-Sonoma:

Code:

        <dict>
            <key>com.apple.backupd.SnapshotCompletionDate</key>
            <date>2022-04-15T06:48:06Z</date>
            <key>com.apple.backupd.SnapshotName</key>
            <string>2022-04-14-234806</string>
            <key>com.apple.backupd.SnapshotTotalBytesCopied</key>
            <integer>221195816</integer>
        </dict>

See there is now .backup suffix in SnapshotName? This seems to be a culprit.

 

[saspus]

filed a bug https://ixsystems.atlassian.net/browse/NAS-125197

 

[EtienneB]

I realised this yesterday evening too.
One macbook with Ventura is still doing snapshots, but the other Macbook with Sonoma stopped having snapshots.
I have 2 Child datasets under my TimeMachine dataset, one for each macbook.

Looking forward to a quick bugfix.