Hmm...while the answer about the TC being a "backup device and not intended for long term persistent network connections" may be expected behavior, the disconnects and reconnects hardly seem "normal." You have not indicated the frequency, but in my case they repeated on almost exact five second intervals. In addition, in my case and others that have been reported in each instance the sequence is accompanied by what I would describe as a "partial spinup" of the drive. I could hear it start to spinup on the reconnect, but not reach full speed, and then power down. I find it hard to believe that is "expected behavior," nor is it good for disks to be constantly changing speed.
If the system with the share mounted goes to sleep I do believe I saw it lose the connection. But you can prevent that with a script or an app like Caffeine. I do know that I can play music from the iTunes library I have on the drive without losing connectivity...I have done this for at least a couple of hours at a time. And that was true even during the period I was getting the disconnect/reconnect sequences and partial spinups.
To DJ GiNSU:
You should be able to have your iTunes library stored on the Time Capsule and not have a problem. You of course need to provide some other method of periodically backing your iTunes library (or any other files that you keep centrally on your Time Capsule).
You should be able to have a persistent share to the TC mounted on one or more Macs - over a period of multiple days - and the Macs should still be able to sleep and wake without notifying you that the connection has been lost - unless you are actually losing the Wifi connection (due to going out of range) or in the case of ethernet - disconnecting the ethernet cable.
You should be able to back up multiple Macs to the Time Capsule with Time Machine and simulatenously have shares persistently mounted - without any interference between the two.
Keep in mind - the Time Capsule is designed to spin down the drive after about 3 to 4 minutes of inactivity. A mounted share does not constitute activity - unless an app that is using the share is actively reading or writing data on the the Time Capsule. The very short (and non-user-configurable) spin down time on the Time Capsule - does not lend itself well to applications that require persistent shares - but nevertheless - the shares should remain mounted - the app (and user) will usually be inconvenienced by having to wait for the drive to spin up every time a request for data is made - because chances are high that the drive will be in a spun-down state more often than a spun-up state.
Don't confuse the 5 minute repeated partial spin up with the 3 to 4 minute inactivity spin down. The 5 minute partial spinup seems to be a bug of some sort. For me - this stopped as of Mountain Lion 10.8.2. If you listen carefully when the TC goes into the cycle of spinning up every 5 minutes - you will notice that the drive is not reaching full rotational speed before it spins down again - you can defintely tell by the sound.
If I do a full backup of a Mac - to the Time Capsule - using 5GHz wifi - I am going to say that I see an average throughput of about 30 gig per hour (and sometimes it is faster or slower - but usually faster) - so a 120 gig backup should not take more than 4 hours. Connecting to 2.4 GHz wifi - is exponentially slower. Wired is very fast 50 gig or more per hour. I will have to double check these numbers - they are off the top of my head. Multiple simultaneous full backups can also drastically affect throughput - at least that is what I have seen.
So when you say backing up a large system - how many gig are you referring to - just out of curisity? Time Machine does spend a lot of time gyrating through the backup to figure out what to back up and if you have a huge existing backup - as well as huge system - the backup may be slower - regardless of wifi or ethernet.
The time capsule throughput should not be slowing over time - the throughput should be consistent.
In your console log - you should only see AFP entries logged - when you first mount a share - and then whenever your Mac wakes from sleep - chances are you will see a handful of log entries where it tries to restablish the share after wake - usually it takes two tries to get reconnected - but the reconnection should be successful. If you prevent your Mac from sleeping - you should not see any AFP log entries until you disconnect the share.
If you specifically mount a share on the TC via SMB - your will see a different set of log entries - and both AFP and SMB have quite differening types of entries.
You will also see somewhat of an overload of log entries when the 5 minute partial spinup repeated cycle begins. It's almost as if the drive is spinning up to do something - and then changes its mind halfway through the spin up process.
I highly suggest Googling the support sites of other NAS manufacturers. You will see that they all seem to be struggling with AFP connectivity issues - and additional issues as well with unreliable Time Machine backups on their network drives. From what I am seeing - the Time Capsule is still the most dependable and trouble free backup solution for multiple Macs. I have two NAS drives from another drive manufacturer - and although they do not seem to have problems with persisting a share - they do not seem to be able to reliably back up multiple Macs - and seem to just slow to a crawl during a full backup (either wired or wireless).
Have you actually verified that your Wifi is working reliably - on both the TIme Capsule and the Mac Side? It may help to prove that before going down the road of troubleshooting the Time Capsule.
It also should not matter whether your Time Capsule is in Bridge Mode or Router Mode.
In my case, I have a wired connection to the TC from 2 Macs. I am using the wireless for other devices in the house. I don't use Time Machine, and my Retrospect backups don't go to the TC, they go elsewhere. I also backup the TC volume to the other drive (which is firewire-connected).
Sometimes I get the error, sometimes I don't. Here's he stuff I see in my console. I don't know what Data-1 and Data-2 are, because the volume name is Data:
2/7/13 7:23:10.000 AM kernel: ASP_TCP asp_tcp_usr_control: invalid kernelUseCount 0
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect started /Volumes/Data prevTrigger 376 currTrigger 377
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: doing reconnect on /Volumes/Data
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: soft mounted and hidden volume so do not notify KEA for /Volumes/Data
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: Max reconnect time: 30 secs, Connect timeout: 15 secs for /Volumes/Data
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/Data
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: Logging in with uam 13 /Volumes/Data
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: Restoring session /Volumes/Data
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: get the reconnect token
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: Restoring session /Volumes/Data-1
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: get the reconnect token
2/7/13 7:23:10.000 AM kernel: ASP_TCP Disconnect: triggering reconnect by bumping reconnTrigger from curr value 0 on so 0xffffff80242bb150
2/7/13 7:23:10.310 AM KernelEventAgent: tid 00000000 received event(s) VQ_NOTRESP (1)
2/7/13 7:23:10.344 AM KernelEventAgent: tid 00000000 received event(s) VQ_NOTRESP (1)
2/7/13 7:23:10.000 AM kernel: ASP_TCP asp_tcp_usr_control: invalid kernelUseCount 0
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect started /Volumes/Data-2 prevTrigger 0 currTrigger 1
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: doing reconnect on /Volumes/Data-2
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: posting to KEA EINPROGRESS for /Volumes/Data-2
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: Max reconnect time: 30 secs, Connect timeout: 15 secs for /Volumes/Data-2
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/Data-2
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: Logging in with uam 13 /Volumes/Data-2
2/7/13 7:23:10.000 AM kernel: AFP_VFS afpfs_DoReconnect: Restoring session /Volumes/Data-2
I have approx 1.2TB of data, and an initial backup to Time Capsule takes a few days. Apple should expect this behavior when shipping computers with 3TB drives in them.
I have tried mounting the shares as SMB, and the result is that after the arbitrary "everything works" time period, instead of the sessions dropping at 5 minute intervals, the connection simply fails catstrophically.
I also tried connecting an external USB drive, and leaving an open AFP session with that. But the behavior is the same. Also of note, if I leave another machine connected to the device, it also drops at 5 minute intervals after being asleep over night - but although both machines have the same time on them, the log entries for the sessions opening and closing are not timestamped the same.
Other testing I've done - after the 5 minute reconnect interval starts, I have ejected the drive, and then reconnected it. But 5 minutes later, the error messages start to show up, even though this is a new AFP session.
I still suspect this is an AFP problem with the operating system.
Feb 07 06:14:54 Severity:5 AFP login OK from DJ GiNSU@10.0.1.2. Feb 07 06:14:54 Severity:5 AFP session from DJ GiNSU@10.0.1.2 closing. Feb 07 06:18:01 Severity:5 Rotated CCMP group key. Feb 07 06:19:56 Severity:5 AFP login OK from DJ GiNSU@10.0.1.2. Feb 07 06:19:56 Severity:5 AFP session from DJ GiNSU@10.0.1.2 closing. Feb 07 06:22:32 Severity:5 AFP login OK from DJ GiNSU@10.0.1.6. Feb 07 06:22:32 Severity:5 AFP session from DJ GiNSU@10.0.1.6 closing.
Will do more testing and report back.
Mike - The log entries that you provided look just like the log entries that I see whenever the Mac wakes from sleep - and whatever network connection is reestablished (wired or wifi) and then any mounted AFP shares are reconnected. I believe this is normal behavior. At the moment my TC is working okay - and I have not seen a 5-minute spinup loop since November - after upgrading all Macs to 10.8.2 (all are clean installs except iMac).
The Data-1 is normal - but I have not seen a Data-2 in my case. Typically the volume will mount as Data. If another process (such as Time Machine) tries to mount the volume - and finds that it is already mounted - in a slightly different security context than what Time Machine expects - Time Machine will create a second mount point in /Volumes calles Data-1. Again - if something else tries to mount the Data volume is yet another security context - you would get a Data-2 - and vice-versa. It all depends on what processes are mounting shares on the Time Capsule and in what specific order.
Just curious - how are you controlling access to the Time Capsule - did you tell it in setup - 1) to use the device password (which means the TC password is also used as the drive password) 2) specify a password for the drive itself - or 3) create a list of specific users. In my case I am using option 1 - use the TC password as the drive password.
I do see Data and Data-1 regulary in my logs. Typically I don't have long term shares mounted to the TC other than on rare occasion - and I only see Data-1 in that very scenario. You also indicated that you are not using Time Machine at all? How many different apps are using (or require) a share to be mounted on the TC?
To DJ GiNSU
Here is an example of what I see in my TC log when a Time Machine Backup runs. (And as I am typing this a notification of new firmware 7.6.3 has just popped up - so I will install that this afternoon). Interesting - there is no 7.6.2 version available for install - it seems like they skipped over 7.6.2 and went right to 7.6.3.
Feb 07 10:08:46 Severity:5 Rotated CCMP group key. Feb 07 10:40:37 Severity:5 AFP login OK from Scott Beattie@10.0.7.10. Feb 07 10:42:26 Severity:5 AFP session from Scott Beattie@10.0.7.10 closing. Feb 07 10:42:32 Severity:5 AFP login OK from Scott Beattie@10.0.7.10. Feb 07 10:43:28 Severity:5 AFP session from Scott Beattie@10.0.7.10 closing. Feb 07 11:02:26 Severity:5 Rotated CCMP group key.
I don't believe these are errors - they are more of a notification. From observation - Time Machine backup does establish multiple connections to the TC - depending on what it's doing in the backup process - I believe it uses separate connections for each step. So I don't think these are errors. I also just changed my logging level to 6 instead of 5 - to see if I can see any more detail. In the past I believe I have set it at 7-debug - and never really saw anything with a level > 5.
1.3 TB is a lot of data to try to backup wirelessly. I would tend to want to do the full backup via wired ethernet - because I would be hestiant to trust a wifi connection for a backup that would have to run for such a long duration (all other issues aside). There are just too many things that could interrupt a long-term wifi connection. It almost seems that with that much data - that you might need to look at a larger scale backup solution than what the TC can provide.
I think the best thing to do at this point is to move forward with the 7.6.3 firmware and see if that provides any improvement. In your current situation - I would be more concerned about your actual observed disconnects than the other issues. In my experience - I only witnessed the problems when everything was basically idle - not when any type of data transfer was actually in progress. I never encounted any incomplete data transfers (copies or backups) and never encountered any corruption as a result of these issues.
My intent is to keep it mounted all the time as a shared drive. I have our iPhoto library on it ( I have a symbolic link set up in the pictures folder on 3 machines that tricks the Mac into thinking the iPhoto library is local). I don't remember if I am using option 1 or 2. Definitely not 3. I have it backed up every night.
If I keep the console open, I sometimes see those events logged even while I'm using the Mac, so it's not just when waking from sleep. iPhoto isn't usually running so I don't know why the Mac would be verifying that link all the time
Interesting - I don't see any AFP log entries in the console - if the Mac is prevented from sleeping and I don't have a share mounted. I will take a closer look in the near future.
I am now on the 7.6.3 Time Capsule firmware - as of about 2 hours ago. So far I have not noticed any problems - or any differences.
I have done additional testing and come up with some conclusive results. The time capsule begins to misbehave on any 7.6.x firmware after any clien has held an afp session open for longer than 20 hours. I tested this on both of my TCs - 2nd gen and a 4th gen and was able to duplicate the behavior on both using my iMac, Macbook and Mac Mini. It appears that once a client has held a session open for more than 20 hours, the TC's file sharing software experiences a catastrophic failure, and begins to disconnect shares from all of its connected clients, regardless of how long the nodes have been connected.
This is most definitely an apple firmware problem - and since the feature is not officially supported, its going to take a lot more than jusr my whining to get them to fix it. However, I do come to you with a solution.
IF you require a persistent share from your TC and your computer goes to sleep periodically you can set it up to automatically mount and dismount the share by doing this:
Download sleepwatcher from www.bernhard-baehr.de
Its very unintrusive and light weight. It just monitors your mac for sleep events. Follow the instructions in the readme file to install it
Open your favorite text editor, and create a file with these two lines (replace 'whatever' with your shared volume name)
Save it as: ~/.sleep
Create another text file with these two lines (replace 'whatever' with yout volume name and 'wherever' with the name of your time capsule)
osascript -e 'mount volume "afp://wherever.local/whatever" '
Save it as ~/.wakeup
I am not experiencing the 20 hour problem. I am able to have a share mounted for days - idle - while both the Mac and the Time Capsule sleep - independently of each other. When the Mac wakes - it reestablishes the connection to the drive. In rare circumstances it will display the server connections interrupted - but usually it does not. In this scenario - the server connections interrupted popup does not repeat - as it had been doing way back in the earlier stages of this thread.
Your particular scenario sounds different than what others have described - and it almost sounds like you have a separate issue going on. You should not have to use sleepwatcher to mount and dismount the share. Theoretically whatever app you are running that is accessing the share - is also going to sleep when the Mac sleeps and it should be able to manage the loss of the connection in a sleep scenario. I'm not sure I am following what sleepwatcher is doing that is not already automatically occuring when the Mac goes to sleep and wakes up.
I am not using CCC.
But the disconnect (for me) will not show up in finder as a "server connections interrupted" dialog, until the TC's performance gets so bad that OSX is unable to recover the session within the retry period.
If you are not having an issue holding sessions open longer than 20 hours, I'd be very interested in how you've achieved this, because both of my TCs do it in a rather predictable manner. It's entirely possible that you are still experiencing the problem, but do not notice it, because your mac is able to quickly reconnect the session and it does not show up as a "server connections interrupted" dialog box. But you can run the syslog utility and see if your machine is constantly reconnecting the session.
The disconnect shows up like this when you run syslog:
Feb 9 10:50:28 Cameron kernel <Debug>: AFP_VFS afpfs_DoReconnect started /Volumes/vault prevTrigger 0 currTrigger 1
Feb 9 10:50:28 Cameron kernel <Debug>: AFP_VFS afpfs_DoReconnect: doing reconnect on /Volumes/vault
Feb 9 10:50:28 Cameron kernel <Debug>: AFP_VFS afpfs_DoReconnect: posting to KEA EINPROGRESS for /Volumes/vault
Feb 9 10:50:28 Cameron kernel <Debug>: AFP_VFS afpfs_DoReconnect: Max reconnect time: 30 secs, Connect timeout: 15 secs for /Volumes/vault
Feb 9 10:50:28 Cameron kernel <Debug>: AFP_VFS afpfs_DoReconnect: connect to the server /Volumes/vault
Feb 9 10:50:28 Cameron kernel <Debug>: AFP_VFS afpfs_DoReconnect: connect on /Volumes/vault failed 65.
Feb 9 10:50:28 Cameron kernel <Debug>: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
It appears at 5 minute intervals, as long as the machine is awake. These entries in the Mac's syslog correspond to logs on the Time Capsule, - an AFP login, followed by an AFP session closed, with the same time stamp. A healthy time capsule will show connect and disconnect with a few minutes in between them (like the logs you posted above) as the machine backs itself up.
The flood of entries in the syslog are a problem in and of themselves, because they take up disk space, and generate unnecessary context switches which reduce performance and clutter the logs up, making it difficult to troubleshoot other problems. But the degradation in AFP performance causes application crashes for things like Serato, and Movist as the TC is basically pulling the file system out from under them every 5 minutes.
While the details differ, the symptoms of these errors have a lot in common...and I hypothesize that, though there is not much way to be certain, there is common cause...which lies somewhere between the TC firmware and OS X. I am doing a test right now where I will leave the TC share connected for 24 hours or more. I started the test earlier but forgot to turn off Time Machine. I had noticed in prior work with Scott that it appeared that if TM kicked off a backup while the share was connected it initiated the "five minute" error loop. While in this instance the timing was a bit off, a TM backup did indeed occur with the share up and an error sequence did indeed commence.
I disconnected the share, unmounted the TC, turned off TM, and then re-mounted the TC and reconnected the share. It has been in that state for long enough for the error to occur and it has not, but I will report back tomorrow night on the longer term test results.
I do continue to posit that, since Apple insists the TC was designed for use as a backup device only (and, by implication, for use with Time Machine) any other use is likely to produce inderminate results that they obviously have neither the interest nor the responsibility to address. Whether or not someone uses TM does not seem to be the issue. The fact that the TC is not being used with TM appears to me to result in confusion and similar types of disconnect/reconnect errors, though the specific characteristics might well vary a bit depending on the exact environment and uses imposed on the Time Capsule.