hoakley May 19, 2019 Macs, Technology

T2M2 Support

This page is for your support questions and comments on my free utility The Time Machine Mechanic, T2M2.

Full details, current versions, known issues, and much more about T2M2 and related tools are on this page.

You can also email me if you prefer: my address is given in the About page for this blog.

12Comments

Add yours

1

artiste212 on November 3, 2019 at 10:25 pm

Hi Howard,

I just tried T2M2 v1.7 on my late 2012 Mac mini with Catalina (the installation that won’t show .webloc icons). T2M2 shows an error message “TM log command returned an error number 77” when I click “Check Time Machine.” This happens several time, across reboots. Time Machine, as far as I can tell, is working because it has the recently changed files. Clicking “Back up now” works and TM does a full backup. Do you have any suggestions?

Thanks.

Bruce

LikeLiked by 1 person
- 2
  
  hoakley on November 3, 2019 at 10:28 pm
  
  Are you running it as an admin user? See the Welcome page at the start of its Help book, third paragraph.
  Howard
  
  LikeLike
- 3
  
  hoakley on November 3, 2019 at 11:59 pm
  
  There are additional tips in this article which may also help.
  Howard.
  
  LikeLike
4

artiste212 on November 4, 2019 at 1:40 am

I was not running as an admin user. Fortunately, Run T2M2 allowed me to run as root, and it worked fine. Usually I look at the manual, but there is no manual included in the zip file for T2M2, so I didn’t know about running as root. The report said there were no errors.

Running as a regular user is a disadvantage in running certain utilities, but the consensus seems to be that it’s safer for general use. It’s difficult running my admin user, as there are lots of utilities wanting to be configured (Little Snitch, etc.), so it takes time. I’m glad I saw the reference to Run T2M2. Thank you very much!

Bruce

LikeLiked by 1 person
- 5
  
  hoakley on November 4, 2019 at 7:57 am
  
  I’m sorry about this limitation, but it’s imposed by the log show command. You don’t need to run as root, just as an admin user. Sadly, RunT2M2 doesn’t work reliably in more recent versions of macOS, but fast user switching can solve the problem more reliably now.
  Howard.
  
  LikeLike
6

Bob Freeman on November 5, 2019 at 1:15 am

Hi, Just wanted to say thanks for all you do to make the Mac community a better place!!! Tried out your T2M2 app on High Sierra and have a couple of suggestions. First, is to make the maximum a lot more than 48 hours, perhaps even make it a setting in the Preferences, if there were any Preferences that is. I use a utility called TimeMachineEditor which lets me set when I want to do backups, and currently do them once a day at about 8:00pm. Sometimes there is a glitch and they don’t get done for a few days, and hence the need for looking beyond 48 hours. In any event T2M2 does not show anything at all when I let it run with the max 48 hours except this:

Analysis from 2019-11-03 01:11:12 +0000 to 2019-11-05 01:11:12 +0000 for 48 hours:
No backup folder was selected.
No auto backups started in the period, no backup has been completed successfully in the period,
Created 0 new backups, and deleted 0 old backups,
Created 0 new snapshots, and deleted 0 old snapshots,
cancelled 20 backups.
No error messages found.
Running check on scheduling system (CTS and DAS).
DAS appears to be rescoring normally over the last 90 minutes.
Running CTS check next.
CTS has been told to run a backup in the last 90 minutes but failed to do so.
Consider restarting your Mac.

Seems odd that there were no error messages at all — the TimeMachine icon in the Menu bar at the top of the screen knows that the last backup was done Nov 1, 2019, but not sure if TimeMachine is keeping track of this or if this is something that TimeMachineEditor is keeping track of.

Anyway, thanks again for all the tools you create and am looking forward to using more of them.

-Bob

LikeLike
- 7
  
  hoakley on November 5, 2019 at 7:23 am
  
  I’m sorry, but if you read the TimeMachineEditor docs, you’ll realise that when you use it, macOS doesn’t despatch backups at all, but TimeMachineEditor does. In doing so, you’ll get completely different log entries, not those on which T2M2 relies.
  There is no way that T2M2 will, for the foreseeable future, assess backups which are controlled by TimeMachineEditor, I’m afraid.
  Sorry.
  Howard.
  
  LikeLike
8

Bob Freeman on November 5, 2019 at 2:38 am

Just noticed another item having to do with the time displayed — seems like it’s UTC rather than local time zone – is that correct? Is there a reason for that, as seems like local time would be preferred? It does see a backup in progress when I manually trigger one via the TM icon in Menu bar, so that’s good to see. As soon as the current backup finishes will rerun T2M2 and see what it says… Well, here is what it said:

Analysis from 2019-11-04 23:39:31 +0000 to 2019-11-05 01:39:31 +0000 for 2 hours:
Backing up to /dev/disk5s2: /Volumes/zzzz/Backups.backupdb
on which there were 481.4 GB available.
No auto backups started in the period, last backup completed successfully 0.3 minutes ago,
last manual backup started 21.4 minutes ago,
backed up a total of 37619 files, range 528 to 20003 in each backup,
total data for each backup was 29.94 GB, 657.5 MB, 19.37 GB.
Created 1 new backups, and deleted 4 old backups,
Created 0 new snapshots, and deleted 0 old snapshots,
cancelled 3 backups.
No error messages found.
Running check on scheduling system (CTS and DAS).
DAS appears to be rescoring normally over the last 90 minutes.
Running CTS check next.
CTS has been told to run a backup in the last 90 minutes but failed to do so.
Consider restarting your Mac.

But the above is not in agreement with the contents of “.Backup.log” file, which contains this (I’ve edited to not include any personal info, but have done in a consistent way, so the differences will stay the same):
=============================================================
xxx$ sudo more .Backup.log
2019-11-04-18:18:19 – Starting backup

Previous snapshot:
/Volumes/zzz/Backups.backupdb/yyy/2019-10-30-201612

Date of Previous snapshot: 1572491772493109

Will use FS events for “aaa” (device: /dev/disk3s2 mount: ‘/Volumes/aaaa’ fsUUID: 7x4x8x2x-AxFx-3xCx-9x7x-DxFx6x6xEx5x eventDBUUID: Cx9x5xDx-DxFx-4x7x-Bx0x-7x4xEx6x9x4x)
Gathering events since 18158644465656096200.
Will use FS events for “bbbb” (device: /dev/disk1s3 mount: ‘/Volumes/bbbb’ fsUUID: CxAxEx5x-8xCx-3x0x-AxAx-FxAx7x8x7xBx eventDBUUID: Dx9x1xAx-ExBx-4x8x-Bx9x-7xDx8x8xCx5x)
Gathering events since 18158644465656107488.
Will use FS events for “cccc” (device: /dev/disk0s2 mount: ‘/’ fsUUID: Ex6xEx0x-2x1x-3x7x-Bx7x-24x9x2xFxAx eventDBUUID: FxBxDx6x-Dx0x-4x2x-Bx1x-2xAxAx6xDx8x)
Gathering events since 18158644465656097253.
=== Starting backup loop #1 ===
Will use IncrementalBackupCopier

Running preflight for “aaaa” (device: /dev/disk3s2 mount: ‘/Volumes/aaaa’ fsUUID: 7x4x8x2x-AxFx-3xCx-9x7x-DxFx6x6xEx5x eventDBUUID: Cx9x5xDx-DxFx-4x7x-Bx0x-7x4xEx6x9x4x)
Calculating size of changes
Should copy 17097 items (29.94 GB) representing 3654731 blocks of size 8192. 58764939 blocks available.
Preflight complete for “aaaa” (device: /dev/disk3s2 mount: ‘/Volumes/aaaa’ fsUUID: 7x4x8x2x-AxFx-3xCx-9x7x-DxFx6x6xEx5x eventDBUUID: Cx9x5xDx-DxFx-4x7x-Bx0x-7x4xEx6x9x4x)
Time elapsed: 4.630 seconds

Running preflight for “bbbb” (device: /dev/disk1s3 mount: ‘/Volumes/bbbb’ fsUUID: CxAxEx5x-8xCx-3x0x-AxAx-FxAx7x8x7xBx eventDBUUID: Dx9x1xAx-ExBx-4x8x-Bx9x-7xDx8x8xCx5x)
Calculating size of changes
Should copy 17723 items (30.71 GB) representing 3749328 blocks of size 8192. 58764939 blocks available.
Preflight complete for “bbbb” (device: /dev/disk1s3 mount: ‘/Volumes/bbbb’ fsUUID: CxAxEx5x-8xCx-3x0x-AxAx-FxAx7x8x7xBx eventDBUUID: Dx9x1xAx-ExBx-4x8x-Bx9x-7xDx8x8xCx5x)
Time elapsed: 1.126 seconds

Running preflight for “cccc” (device: /dev/disk0s2 mount: ‘/’ fsUUID: Ex6xEx0x-2x1x-3x7x-Bx7x-2x4x9x2xFxAx eventDBUUID: FxBxDx6x-Dx0x-4x2x-Bx1x-2xAxAx6xDx8x)
Calculating size of changes
Should copy 37136 items (50.18 GB) representing 6125793 blocks of size 8192. 58764939 blocks available.
Preflight complete for “cccc” (device: /dev/disk0s2 mount: ‘/’ fsUUID: Ex6xEx0x-2x1x-3x7x-Bx7x-2x4x9x2xFxAx eventDBUUID: FxBxDx6x-Dx0x-4x2x-Bx1x-2xAxAx6xDx8x)
Time elapsed: 14.542 seconds

Processing preflight info
Space needed for this backup: 69.61 GB (8496997 blocks of size 8192)
Preserving last snapshot /Volumes/zzzz/Backups.backupdb/yyyy/2019-10-30-201612
Finished processing preflight info

Copying items from “aaaa” (device: /dev/disk3s2 mount: ‘/Volumes/aaaa’ fsUUID: 7x4x8x2x-AxFx-3xCx-9x7x-DxFx6x6xEx5x eventDBUUID: Cx9x5xDx-DxFx-4x7x-Bx0x-7x4xEx6x9x4x)
Finished copying items for “aaaa” (device: /dev/disk3s2 mount: ‘/Volumes/aaaa’ fsUUID: 7x4x8x2x-AxFx-3xCx-9x7x-DxFx6x6xEx5x eventDBUUID: Cx9x5xDx-DxFx-4x7x-Bx0x-7x4xEx6x9x4x)
Time elapsed: 6 minutes, 49.000 seconds
Copied 17836 items (29.94 GB)
Gathering events since 18158644465660308440.

Copying items from “bbbb” (device: /dev/disk1s3 mount: ‘/Volumes/bbbb’ fsUUID: CxAxEx5x-8xCx-3x0x-AxAx-F9A4718A72B9 eventDBUUID: Dx9x1xAx-ExBx-4x8x-Bx9x-7BD68F8CCA57)
Finished copying items for “bbbb” (device: /dev/disk1s3 mount: ‘/Volumes/bbbb’ fsUUID: CxAxEx5x-8xCx-3x0x-AxAx-FxAx7x8x7xBx eventDBUUID: Dx9x1xAx-ExBx-4x8x-Bx9x-7xDx8x8xCx5x)
Time elapsed: 37.196 seconds
Copied 19377 items (30.6 GB)
Gathering events since 18158644465660342193.

Copying items from “cccc” (device: /dev/disk0s2 mount: ‘/’ fsUUID: Ex6xEx0x-2x1x-3x7x-Bx7x-2x4x9x2xFxAx eventDBUUID: FxBxDx6x-Dx0x-4x2x-Bx1x-2xAxAx6xDx8x)
Finished copying items for “cccc” (device: /dev/disk0s2 mount: ‘/’ fsUUID: Ex6xEx0x-2x1x-3x7x-Bx7x-2x4x9x2xFxAx eventDBUUID: FxBxDx6x-Dx0x-4x2x-Bx1x-2xAxAx6xDx8x)
Time elapsed: 9 minutes, 25.000 seconds
Copied 63090 items (49.97 GB)
Gathering events since 18158644465660368486.

Backup complete.
Total time elapsed: 18 minutes, 8.000 seconds
==================================================

So, the .Backup.log file says there were 17097 items for aaaa filesystem, 17723 for bbbb filesystem (am assuming this is a cumulative total and the actual number of files in bbbb that were backed up is really 626=17723-17097), and 37136 for cccc filesystem(am assuming this is a cumulative total and the actual number of files in cccc that were backed up is really 19413=37136-17723), but the T2M2 program says “backed up a total of 37619 files, range 528 to 20003 in each backup,” and the numbers don’t seem to be in agreement — so basically my question is why the difference between what T2M2 says and what the .Backup.log says? The numbers in the first preflight set of values also don’t agree with the numbers in the “copying items” phase of the “.Backup.log” file, and have always wondered about that as well, but neither set of values agree with what T2M2 says.

Thanks…

LikeLike
- 9
  
  hoakley on November 5, 2019 at 8:29 am
  
  Thank you.
  As you see from the timezones given in the datestamps, those times are given in UTC. Otherwise when the clock or timezone changes, they are hard to interpret. Only UTC provides unique times. This has already been discussed to death here, and it’s the only system which works.
  You refer here to a .Backup.log file. Where is that, please?
  T2M2 uses the unified log, which is where TM records its backups in detail.
  Howard.
  
  LikeLike
10

Bob Freeman on November 5, 2019 at 4:56 pm

The .Backup.log file is stored in each of the snapshot folders, .e.g. /Volumes/TMdrive/Backups.backupdb/SystemName/2010-11-04-123456/.Backup.log — but still seems odd that the information there is so different than what the log, but TM is rather hard to understand at times.

Your note about how TimeMachineEditor is so different from how normal TM works surprised me, but that’s good to know. I understand that TimeMachineEditor takes over the queueing up of the backups, but would have thought that after the backup starts things work the same.

And also thanks for explaining about how T2M2 won’t be much help if using TimeMachineEditor. I’ve monitored logs using the Console app and while the TimeMachineEditor initiated backups are in progress, I do see various log entries regarding “backupd”. I will try to do the same thing when the real TimeMachine is active and see what sort of differences I notice — any suggestion on how best to monitor TimeMachine in Console to see it’s progress, or even better what does T2M2 really do to create it’s output as TimeMachine progresses (i.e. what log entries does it look at)?

Thanks again …

-bob

LikeLiked by 1 person
- 11
  
  hoakley on November 5, 2019 at 9:17 pm
  
  Thanks.
  One reason for using the unified log is that it works with all versions of macOS from Sierra, irrespective of whether they’re also backing up from APFS. When they’re not backing up from APFS, and in all Sierra cases, those logs don’t exist.
  There are other insurmountable problems with backup volumes which aren’t permanently mounted, which applies to a large number of Mac users.
  So forgive me if I don’t use those logs.
  T2M2 follows automatically despatched backups controlled by DAS and CTS, which in Sierra suffer a bug which was the primary reason for me to write the app. Parsing log files to work out exactly what happened and when is non-trivial. It therefore relies on the backups being despatched by those systems, and following the pattern of that type of backup. Log output from other types of backup isn’t as consistent or as comprehensive, which is why you’re observing these issues.
  T2M2 does this using the log show command to return JSON-format log entries, which it turns into a collection of dictionaries. From those, it extracts times and other information, then analyses those to determine intervals and quantities that are backed up. It also looks at DAS and CTS despatching, particularly when backups have occurred at irregular or prolonged intervals. You can’t do those sorts of things in Console, which in any case only looks at present log entries, and can’t readily analyse the past.
  Howard.
  
  LikeLike
12

Bob Freeman on November 5, 2019 at 4:58 pm

ps — one other note about the .Backup.log file — you can monitor progress by doing something like

sudo tail -f .Backup.log

while the backups are being created.

LikeLiked by 1 person

·Comments are closed.

Share this:

Related