Twice is two days since updating to 4.2.19-T4 I have had to stop and start AFP to be able to connect.
I am using OS X Lion. I see my NAS Pro in the finder. When I click on the AFP entry for my NAS it shows that it is disconnected. WHen I click the Connect as ... it says that it is unreachable.
Once I restart AFP on the NAS it connects just fine.
I do not see anything the netatalk.log file.
Another odd thing is that using a Bonjour browser utility I see the NAS Pro as broadcasting on IPv6 but I do not see any IPv4 advertisement.
Twice is two days since updating to 4.2.19-T4 I have had to stop and start AFP to be able to connect.
I am using OS X Lion. I see my NAS Pro in the finder. When I click on the AFP entry for my NAS it shows that it is disconnected. WHen I click the Connect as ... it says that it is unreachable.
Once I restart AFP on the NAS it connects just fine.
I do not see anything the netatalk.log file.
Another odd thing is that using a Bonjour browser utility I see the NAS Pro as broadcasting on IPv6 but I do not see any IPv4 advertisement.
My Mac systems are shut off and there ahs been no AFP access sonce last night. I decided to check on the system and the last line in the netatalk.log file and the only one from today is a line that says: Aug 03 06:25:04.522979 afpd[4870] {main.c:148} (N:AFPDaemon): AFP Server shutting down on SIGTERM
I looked in Frontview and it shows AFP as runing but there is no netatalk or afpd process on the system.
Charles, is there a service that you may be running (i.e. community add-on or self-added cron job) that would stop AFP service at 6:25am? I'm seeing this on July 28, 29, 30, and Aug 2. This seems a little too coincidental.
I will look, the only thing that runs about that time is on my ReadyNAS NV that backs up important shares from the Pro. I am not aware of anything on the Pro that is running at that time. I will look.
From the backup logs on the NV they are done at least an hour before the AFP failure on the Pro.
The only thing that looks like it is running at that time is the cron.daily and just before the AFP SIGTERM is the DnsOMatic and OpenDNS add-on scripts. The OpenDNS add-on has been disabled for a long time. I have disabled DnsOMatic to see if it makes any difference.
I have also changed the system cron times to see if that will change the failure time.
The afpd process encountered a SIGTERM again this morning at the new time for the cron.daily process. Disabling the DnsOMatic add-on did not help. I have now removed both the DnsOMatic and OpenDNS add-ons.
To speed up testing I am running the cron.daily using the command in the crontab file and every time it runs the afpd dies with a SIGTERM.
I am going to do a bit more digging to see what I can find.
OK, I have narrowed it down to the /etc/cron.daily/logtruncate script.
Looking at the script I saw that it checks for a file /ramfs/.logtruncate.lock and it it is there it exists without doing anything. I created that file and ran the command:
run-parts --report /etc/cron.daily
The afpd process did not SIGTERM, I removed the lock file and reran the run-parts command and the afpd SIGTERMed.
It also kiil the afpd process. Looking at the log truncate script. I duplicated portions of it that were relevant to the netatalk.log files and the afpd process kept running.
Finally I narrowed it down to the line that runs "start-stop-daemon -K -n apache-ssl -R 5". If I run that command the afpd process SIGTERMs.
Skywalker asked for access to look a things. After the mucking around I had done I decided to reboot the ReadyNAS to make sure things were coming up cleanly. I gave Skywalker access to the box and he could not reproduce the problem.
The only thing I can think of is that there was something cached or left over from the DnsOMatic and OpenDNS add-ons that was cleared by the reboot. Or could is have been the presence of the Force from Skywalkers attention?
