conflicting messages

Question

richardlw Author

Level 1

20 points

conflicting messages

My widget says "backup failed" Finished June 9.

my time machine preferences says latest backup august 11

what gives?

mac book pro, Mac OS X (10.6.3)

Posted on Aug 14, 2010 9:38 AM

Reply

Answer 1

Pondini

Level 8

38,863 points

Aug 14, 2010 9:45 AM in response to richardlw

richardlw wrote:
My widget says "backup failed" Finished June 9.

What widget is that? If you mean +Time Machine Buddy,+ that would mean your system logs haven't "rolled over" in months. When you select that widget, it should show the most recent backup; you can then navigate back through your current system log and the first "archived" log (which usually isn't more than a couple of days) to see the messages for earlier backups.

my time machine preferences says latest backup august 11

That's probably correct. Take a look at the backups, via +Enter Time Machine,+ and see what's actually there.

Reply

Answer 2

richardlw Author

Level 1

20 points

Aug 16, 2010 5:22 AM in response to Pondini

How do I get the logs to "roll over" as you say?

It ran all day yesterday, still not changing the widget/buddy but I see files backed up til the 11th. Does that mean it started working again and still needs time to catch up to yesterday?

The time capsule is at home, where I take my macbook every evening except when I'm out of town, which is often for 4 to 7 weeks at a time. Curiously the june 9th last backup was the day before I left town for 6 weeks.

Reply

Answer 3

Pondini

Level 8

38,863 points

Aug 16, 2010 7:43 AM in response to richardlw

richardlw wrote:
How do I get the logs to "roll over" as you say?

That should happen automatically, shortly after midnight.

It ran all day yesterday, still not changing the widget/buddy but I see files backed up til the 11th. Does that mean it started working again and still needs time to catch up to yesterday?

No. If you can't see the backups in the "Star Wars" display, they aren't there. 😟

I'd suggest doing a "full reset" of Time Machine, per #A4 in Time Machine - Troubleshooting.

If that backup fails, see the pink box in #A1 in Troubleshooting for instructions on how to look directly at your logs, since something seems to be wrong with the +Time Machine Buddy+ widget.

Reply

Answer 4

richardlw Author

Level 1

20 points

Aug 16, 2010 8:58 AM in response to Pondini

Pondini wrote:

richardlw wrote:
How do I get the logs to "roll over" as you say?

That should happen automatically, shortly after midnight.

It ran all day yesterday, still not changing the widget/buddy but I see files backed up til the 11th. Does that mean it started working again and still needs time to catch up to yesterday?

No. If you can't see the backups in the "Star Wars" display, they aren't there. 😟

I'd suggest doing a "full reset" of Time Machine, per #A4 in Time Machine - Troubleshooting.

If that backup fails, see the pink box in #A1 in Troubleshooting for instructions on how to look directly at your logs, since something seems to be wrong with the +Time Machine Buddy+ widget.

The log shows activity. I'm curious as to what it means, copying different amounts of 65.6 GB each time

Aug 15 08:25:01 Richard com.apple.backupd[340]: Starting standard backup
Aug 15 08:25:01 Richard com.apple.backupd[340]: Attempting to mount network destination using URL: afp://Richard%20Widman@Time-Capsule.local/Data
Aug 15 08:25:11 Richard com.apple.backupd[340]: Mounted network destination using URL: afp://Richard%20Widman@Time-Capsule.local/Data
Aug 15 08:25:16 Richard com.apple.backupd[340]: QUICKCHECK ONLY; FILESYSTEM CLEAN
Aug 15 08:25:21 Richard com.apple.backupd[340]: Disk image /Volumes/Data/Richard.sparsebundle mounted at: /Volumes/Time Machine Backups
Aug 15 08:25:21 Richard com.apple.backupd[340]: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
Aug 15 08:36:35 Richard com.apple.backupd[340]: No pre-backup thinning needed: 79.65 GB requested (including padding), 248.64 GB available
Aug 15 08:42:28 Richard com.apple.backupd[340]: Bulk setting Spotlight attributes failed.
Aug 15 09:25:56 Richard com.apple.backupd[340]: Copied 1.4 GB of 65.6 GB, 23465 of 23465 items
Aug 15 10:26:33 Richard com.apple.backupd[340]: Copied 4.2 GB of 65.6 GB, 23465 of 23465 items
Aug 15 11:41:15 Richard com.apple.backupd[340]: Copied 5.2 GB of 65.6 GB, 23465 of 23465 items
Aug 15 12:42:58 Richard com.apple.backupd[340]: Copied 5.8 GB of 65.6 GB, 23465 of 23465 items
Aug 15 13:44:19 Richard com.apple.backupd[340]: Copied 7.7 GB of 65.6 GB, 23465 of 23465 items
Aug 15 14:44:21 Richard com.apple.backupd[340]: Copied 12.1 GB of 65.6 GB, 23465 of 23465 items
Aug 15 15:45:03 Richard com.apple.backupd[340]: Copied 20.5 GB of 65.6 GB, 23465 of 23465 items
Aug 15 16:47:37 Richard com.apple.backupd[340]: Copied 28.6 GB of 65.6 GB, 23465 of 23465 items
Aug 15 17:47:40 Richard com.apple.backupd[340]: Copied 31.5 GB of 65.6 GB, 23465 of 23465 items
Aug 15 18:47:41 Richard com.apple.backupd[340]: Copied 36.5 GB of 65.6 GB, 23465 of 23465 items
Aug 15 19:36:10 Richard com.apple.backupd[340]: Network destination already mounted at: /Volumes/Data
Aug 15 19:36:49 Richard com.apple.backupd[340]: Network destination already mounted at: /Volumes/Data
Aug 15 19:37:04 Richard com.apple.backupd[340]: Network destination already mounted at: /Volumes/Data
Aug 15 19:37:06 Richard com.apple.backupd[340]: Network destination already mounted at: /Volumes/Data
Aug 15 19:40:44 Richard com.apple.backupd[340]: Stopping backupd to allow ejection of backup destination disk!

Reply

Answer 5

Pondini

Level 8

38,863 points

Aug 16, 2010 9:41 AM in response to richardlw

richardlw wrote:
. . .
The log shows activity. I'm curious as to what it means, copying different amounts of 65.6 GB each time
. . .
Aug 15 08:42:28 Richard com.apple.backupd[340]: Bulk setting Spotlight attributes failed.

That may explain why your backup is so slow. See below.

Aug 15 17:47:40 Richard com.apple.backupd[340]: Copied 31.5 GB of 65.6 GB, 23465 of 23465 items
Aug 15 18:47:41 Richard com.apple.backupd[340]: Copied 36.5 GB of 65.6 GB, 23465 of 23465 items

Those are (roughly) hourly updates of how much has been copied so far.

Aug 15 19:37:06 Richard com.apple.backupd[340]: Network destination already mounted at: /Volumes/Data
Aug 15 19:40:44 Richard com.apple.backupd[340]: Stopping backupd to allow ejection of backup destination disk!

These indicate some sort of a problem communicating with the Time Capsule -- Time Machine has lost contact and the backup failed.

Connect to the TC via Ethernet cable, and try the things in #D2 of Time Machine - Troubleshooting.

Then try a backup, while connected via Ethernet. That will seem to be proceeding very slowly, while Time Machine recovers the failed backup.

See how that goes; if it works reasonably well via Ethernet, then you may have a WIFI interference problem. If not, there may be a problem with the TC.

Reply

Answer 6

richardlw Author

Level 1

20 points

Aug 16, 2010 6:34 PM in response to Pondini

This is what I get connected by cable to the time capsule.

Aug 16 18:57:51 Richard com.apple.backupd[1731]: Starting standard backup
Aug 16 18:58:04 Richard com.apple.backupd[1731]: Attempting to mount network destination using URL: afp://Richard%20Widman@Time-Capsule.local/Data
Aug 16 18:58:12 Richard com.apple.backupd[1731]: Mounted network destination using URL: afp://Richard%20Widman@Time-Capsule.local/Data
Aug 16 18:58:14 Richard com.apple.backupd[1731]: QUICKCHECK ONLY; FILESYSTEM CLEAN
Aug 16 18:58:17 Richard com.apple.backupd[1731]: Disk image /Volumes/Data/Richard.sparsebundle mounted at: /Volumes/Time Machine Backups
Aug 16 18:58:17 Richard com.apple.backupd[1731]: Backing up to: /Volumes/Time Machine Backups/Backups.backupdb
Aug 16 19:00:26 Richard com.apple.backupd[1731]: No pre-backup thinning needed: 79.76 GB requested (including padding), 235.25 GB available
Aug 16 19:58:26 Richard com.apple.backupd[1731]: Copied 23.0 GB of 65.7 GB, 24780 of 24780 items
Aug 16 20:58:27 Richard com.apple.backupd[1731]: Copied 51.2 GB of 65.7 GB, 24780 of 24780 items
Aug 16 21:24:29 Richard com.apple.backupd[1731]: Copied 25913 files (65.1 GB) from volume Macintosh HD.
Aug 16 21:24:42 Richard com.apple.backupd[1731]: No pre-backup thinning needed: 1012.0 MB requested (including padding), 210.77 GB available
Aug 16 21:25:22 Richard com.apple.backupd[1731]: Copied 1092 files (19.5 MB) from volume Macintosh HD.

It is still running, although not for long as it is getting late. I'll need to stop it as it makes to many clicking noises here in the bedroom.

Is it telling me that after backing up the originally requested 65 MB it now wants to backup 1012 MB? There can't be 1012 MB on my drive.
Capacity: 319.59 GB (319,594,741,760 bytes)
Available: 92.24 GB (92,235,771,904 bytes)

Reply

Answer 7

Pondini

Level 8

38,863 points

Aug 16, 2010 6:47 PM in response to richardlw

richardlw wrote:
. . .
Aug 16 21:24:29 Richard com.apple.backupd[1731]: Copied 25913 files (65.1 GB) from volume Macintosh HD.
Aug 16 21:24:42 Richard com.apple.backupd[1731]: No pre-backup thinning needed: 1012.0 MB requested (including padding), 210.77 GB available
Aug 16 21:25:22 Richard com.apple.backupd[1731]: Copied 1092 files (19.5 MB) from volume Macintosh HD.
. . .
Is it telling me that after backing up the originally requested 65 MB it now wants to backup 1012 MB? There can't be 1012 MB on my drive.

No -- it backed-up 65 gigabytes in about 2 1/2 hours. During that time, a few additional changes were made, so it copied 10.5 megabytes (in about a minute) in a second "pass".

It should be nearly done, now -- next is the "cleaning up" phase, where it will delete old backups, but it should be finished very soon.

Reply