SOLVED Time Machine Hangs on AFP

[Llibyddap]

There are several posts dealing with 'long' backup times - but this is actually a failure to progress on the backup without terminating or timing out. I have 4 Macs (three desk tops (mac1-3) and a laptop (macpro)). I added the third desktop last week - and then stuff stopped working.

Mac1, Mac2 and MacPro all used a single user (`TM_USER`) and all used a single share (`TimeMachine`). All the Macs run High Sierra 10.13.5. They've worked flawlessly for at least the last 12 to 18 months. When I added Mac3, I setup Time Machine using the same user credentials as everything else but noticed that it was really slow. I tried resetting everything a couple of times and then noticed it isn't slow - it hanged.

Since then, I've updated Freenas to the latest stable build, and separating out the users and shares by machine. Mac1 & Mac2 works flawlessly - Mac3 (the new machine) and now for some reason MacPro will start an AFP Login, start the file transfer process, stop at some point and never finish, disconnect or timeout.

System Information
Hostname LostCity.local
Build FreeNAS-11.1-U5
Platform Intel(R) Atom(TM) CPU C2750 @ 2.40GHz
Memory 32703MB
System Time Tue, 3 Jul 2018 06:48:03 -0700
Uptime 6:48AM up 6:39, 0 users
Load Average 0.22, 0.27, 0.25

For example - here is an example of the log:

Jul 3 00:11:55 LostCity syslog-ng[4506]: syslog-ng starting up; version='3.7.3'
Jul 3 00:11:55 LostCity kernel: pid 1970 (syslog-ng), uid 0: exited on signal 6 (core dumped)
Jul 3 00:12:33 LostCity afpd[4760]: Login by TM_PRO (AFP3.4)
Jul 3 00:21:35 LostCity afpd[6239]: Login by TM_PA (AFP3.4)
Jul 3 00:26:33 LostCity afpd[7481]: Login by TM_USER (AFP3.4)
Jul 3 00:37:23 LostCity afpd[4760]: read: Operation timed out
Jul 3 00:37:23 LostCity afpd[4760]: dsi_stream_read: len:-1, Operation timed out
Jul 3 00:37:23 LostCity afpd[4760]: dsi_disconnect: entering disconnected state
Jul 3 00:43:00 LostCity afpd[7481]: AFP logout by TM_USER
Jul 3 00:43:00 LostCity afpd[7481]: AFP statistics: 1208546.60 KB read, 944439.07 KB written
Jul 3 00:43:00 LostCity afpd[7481]: done
Jul 3 01:31:23 LostCity afpd[15511]: Login by TM_USER (AFP3.4)
Jul 3 01:37:35 LostCity afpd[15511]: AFP logout by TM_USER
Jul 3 01:37:35 LostCity afpd[15511]: AFP statistics: 1053619.89 KB read, 767982.19 KB written
Jul 3 01:37:35 LostCity afpd[15511]: done
Jul 3 01:54:07 LostCity afpd[17700]: Login by TM_PRO (AFP3.4)
Jul 3 01:54:07 LostCity afpd[4760]: Disconnected session terminating
Jul 3 01:54:07 LostCity afpd[3280]: Terminated disconnected child[4760], client rebooted.
Jul 3 01:54:08 LostCity afpd[17700]: afp_zzz: entering extended sleep
Jul 3 02:36:45 LostCity afpd[22000]: Login by TM_USER (AFP3.4)
Jul 3 02:40:48 LostCity afpd[22000]: AFP logout by TM_USER
Jul 3 02:40:48 LostCity afpd[22000]: AFP statistics: 812035.35 KB read, 541565.97 KB written
Jul 3 02:40:48 LostCity afpd[22000]: done
Jul 3 03:29:32 LostCity afpd[27673]: Login by TM_USER (AFP3.4)
Jul 3 03:34:17 LostCity afpd[27673]: AFP logout by TM_USER
Jul 3 03:34:17 LostCity afpd[27673]: AFP statistics: 898046.10 KB read, 628766.88 KB written
Jul 3 03:34:17 LostCity afpd[27673]: done
Jul 3 04:37:53 LostCity afpd[34739]: Login by TM_USER (AFP3.4)
Jul 3 04:42:08 LostCity afpd[34739]: AFP logout by TM_USER
Jul 3 04:42:08 LostCity afpd[34739]: AFP statistics: 868495.48 KB read, 616405.91 KB written
Jul 3 04:42:08 LostCity afpd[34739]: done
Jul 3 05:33:43 LostCity afpd[40402]: Login by TM_USER (AFP3.4)
Jul 3 05:38:57 LostCity afpd[40402]: AFP logout by TM_USER
Jul 3 05:38:57 LostCity afpd[40402]: AFP statistics: 935673.75 KB read, 657400.20 KB written
Jul 3 05:38:57 LostCity afpd[40402]: done
Jul 3 06:31:14 LostCity afpd[45957]: Login by TM_USER (AFP3.4)
Jul 3 06:34:46 LostCity afpd[45957]: AFP logout by TM_USER
Jul 3 06:34:46 LostCity afpd[45957]: AFP statistics: 829779.37 KB read, 562117.09 KB written
Jul 3 06:34:46 LostCity afpd[45957]: done
Jul 3 06:45:53 LostCity afpd[17700]: afp_zzz: waking up from extended sleep
Jul 3 07:34:43 LostCity afpd[55208]: Login by TM_USER (AFP3.4)
Jul 3 07:39:38 LostCity afpd[55208]: AFP logout by TM_USER
Jul 3 07:39:38 LostCity afpd[55208]: AFP statistics: 908657.26 KB read, 642843.12 KB written
Jul 3 07:39:38 LostCity afpd[55208]: done

This is from a fresh reboot last night... The `TM_USER` AFP lines are (what I beleive to be) normal Time Machine backups. The user logs in, stuff happens, the user logs out and then there is an AFP report back on the stats. But you can see that at Jul 3 00:12:33 TM_PRO has this session:

Jul 3 00:12:33 LostCity afpd[4760]: Login by TM_PRO (AFP3.4)
Jul 3 00:37:23 LostCity afpd[4760]: read: Operation timed out
Jul 3 00:37:23 LostCity afpd[4760]: dsi_stream_read: len:-1, Operation timed out
Jul 3 00:37:23 LostCity afpd[4760]: dsi_disconnect: entering disconnected state
Jul 3 01:54:07 LostCity afpd[4760]: Disconnected session terminating

And the laptop TM_PRO has this session since last night...

Jul 3 01:54:07 LostCity afpd[17700]: Login by TM_PRO (AFP3.4)
Jul 3 01:54:08 LostCity afpd[17700]: afp_zzz: entering extended sleep
Jul 3 06:45:53 LostCity afpd[17700]: afp_zzz: waking up from extended sleep

The TM_PRO session is still running. It is currently at 2.15GB of 30.08GB. The first 2.15GB transferred within 10 or so minutes and hasn't moved since then. The afp_zzz, I don't think is part of the problem since the other desktop TM_PA has this log since last night...

Jul 3 00:21:35 LostCity afpd[6239]: Login by TM_PA (AFP3.4)

Any thoughts on where to look? I'm not an IT guy - so learning this is slow, but still a must since it's my backup of my data...

 

[Llibyddap]

An Update...

I decided to start from scratch on the the Macs that weren't actually completing the backup. A couple of observations on likely issues:

a) In sifting through logs I noticed that the shares that wouldn't allow for completed backups (TM_PRO and TM_PA) showed two connection instances which meant that I couldn't destroy them from the GUI. I ended up unmounting from the command line - I'm guessing that was part of the problem.

b) I use the Wizard to setup everything on this round... Although I have no doubt that I did it perfectly correct when I did it manually - . I noticed that after using the Wizard that the "available" space on the Time Machine client app actually matched what I set as the Quota. My guess (although the datasets are destroyed so no way to check) is that there may have been a small (but insignificant) typo or something in the .com.apple.TimeMachine.quota.plist file.

c) I did read the manual for 11.1-U5, finally (), and see that separate datastores are recommended - so I did. I'll note that the Wizard was awesome in that it allowed you to set up multiple users, shares and groups all in one step.

My conclusion - - it had nothing to do with user error... :D;)

While I was typing this post, they have backed up 26G of the 3.2T of data... So all is good...