Huge MBL Operating System File - Could It Be Preventing Sleep?

[WilliamH]

My MBL 3TB has never gone to sleep. When I first powered it up on 14 Oct 2011 with the as received F/W 02.01.06-026 it did not go to sleep nor has it been able to Sleep through 3 sebsequent F/W updates to the present F/W 02.10.09-126. I have never loaded any WDC software to my PC, never transferred any files to the MBL and no Media, FTP, Remote or Email Alets are enabled nor is the drive being accessed by a browser.

When I first accessed the MBL via SSH on 16 Oct 2011 I noticed that the file var/log/user.log was huge - of the order of 650 million bytes. It didn’t seem right but I didn’t do anything about it at the time but had plans to further investigate it. On Sat 26 Nov 2011 after reading Myron’s post regarding Twonky logging (a large log file can cause the MBL to not Sleep) in the thread “Re: New Release - Firmware Version 02.10.09-124 for My Book Live (11/17/11)”, I decided to look into my huge file problem sooner rather than later.

I accessed the MBL via SSH and noticed that the originally offending file ‘user.log’ was now of moderate size however it appeared that the older contents of the ‘user.log’ file had been transferred to the file ‘daemon.log.1’ and this file was 659,648,549 bytes in size!!!   Most of the entries were of the form:

“Dec 31 19:00:57 MyBookLive cnid_metad[2214]: error in accept: Socket operation on non-socket”

and the entries extended over a 34 minute period from 19:00:57 to 19:34:22 at which time the MBL picked up the correct date and time.

I wrote an awk script and analyzed the file. There were 7,093,007 lines of the form above and they had accumulated at a rate of over 200,000 lines per minute over the 34 minute period before the MBL picked up the correct date and time. I presume that the 31 Dec date is some kind of a Debian default. Unfortunatly the entries didn’t report the year. After 34 minutes the MBL picked up an IP address and with an IP address and the correct time it then commenced normal size (not huge) log filing.

My question, prompted by Myron’s statement regarding Twonky, is could this huge file in the var/log directory (or possibly some other huge file that I haven’t found yet) be responsible for my MBLs failure to sleep. Any insight that the community might be able to offer on this matter would be much appreciated.   

Thanks in advance. WilliamH

[ThePizzaMatrix]

Interesting, I’ll test this out and see.

[WilliamH]

I am pleased to report that the inability to Sleep problem that has plagued my MBL 3TB since its initial power-up on 14 Oct 2011 has been resolved.

The Problem:
The problem has always been that my MBL has never gone to Sleep/Standby. The file /var/log/user.log typically reports that the drive enters Sleep/Standby for a maximum period of 61 seconds every 10 minutes or so (when not being accessed by a browser). In fact the problem was actually worse than that because even though the log indicated a 61 second Sleep/Standby period and the activity LED changed from Green to Blue for 61 seconds, the drive never actually totally spun down. By listening to the drive I determined that power was removed from the drive when the LED changed from Green to Blue. The drive would start to spin-down however within less than one second power would be re-applied and the drive would start to spin-up again (before it had had a chance to totally stop spinning). The log and LED indicate a 61 second Sleep/Standby period but the actual hard drive inside the MBL was not even doing that minimal shutdown.

Oct 26 00:29:00 localhost logger: Enter standby
Oct 26 00:30:01 localhost logger: exit standby after 61
Oct 26 00:38:28 localhost apache2: 192.168.0.11 WebUI::session_id=d93e21b83c94185858db5bc3641a913c
Oct 26 00:38:28 localhost apache2: 192.168.0.11 WebUI::session_id=d93e21b83c94185858db5bc3641a913c
Oct 26 00:38:40 localhost apache2: 192.168.0.11 WebUI::session_id=d93e21b83c94185858db5bc3641a913c
Oct 26 00:40:40 localhost apache2: 192.168.0.11 WebUI::session_id=d93e21b83c94185858db5bc3641a913c
Oct 26 00:40:40 localhost apache2: 192.168.0.11 WebUI::session_id=d93e21b83c94185858db5bc3641a913c
Oct 26 00:41:35 localhost apache2: 192.168.0.11 WebUI::session_id=d93e21b83c94185858db5bc3641a913c
Oct 26 00:41:35 localhost apache2: 192.168.0.11 WebUI::session_id=d93e21b83c94185858db5bc3641a913c
Oct 26 00:53:17 localhost logger: Enter standby
Oct 26 00:54:18 localhost logger: exit standby after 61
Oct 26 01:05:27 localhost logger: Enter standby
Oct 26 01:06:28 localhost logger: exit standby after 61
(and so on)

As suggested in my initial posting of Mon 28 Nov 2011 in this thread, the problem was subsequently determined to be the huge file (var/log/daemon.log.1 of 659,648,549 bytes in size) that had been generated during the first 34 minutes after the drives initial power-up. There were 7,093,007 lines of the form

“Dec 31 19:00:57 MyBookLive cnid_metad[2214]: error in accept: Socket operation on non-socket”

that created the huge size of the file (originally in file “user.log” but subsequently transferred by the OS (after a F/W upgrade?) to the file “daemon.log.1”

The Fix:
The fix was simple. I deleted the file “daemon.log.1” and although it did not immediately resove the problem, it did resolve the problem after a shut-down via the Dashboard and a subsequent power-up. During the reboot the OS must have detected the greatly reduced size of the files in the “/var/log” directory and this subsequently allowed the drive to enter Sleep/Standby. An extract from the file /var/log/user.log showing the MBLs newly acquired ability to Sleep/Standby is attached below. As you can see from the log file, a couple of times in the past week the drive was actually in Sleep for 85,793 seconds - that’s approximately 23.83 hours. I confirmed, by listening to the drive, that when the Blue LED was on, the drive was not spinning but was in fact now totally powered-down. Wow, what a change. The log file with the new Sleep/Standby capability is attached below:

Nov 28 10:50:31 localhost logger: Starting orion services: miocrawlerd, mediacrawlerd, communicationmanagerd
Nov 28 10:50:33 localhost logger: WD NAS: Email alerts REST API failed to return Success
Nov 28 11:02:41 localhost logger: Enter standby
Nov 28 11:09:11 localhost logger: exit standby after 390
Nov 28 11:26:23 localhost logger: Enter standby
Nov 28 11:29:31 localhost logger: exit standby after 188
Nov 28 11:49:45 localhost logger: Enter standby
Nov 28 12:09:17 localhost logger: exit standby after 1172
Nov 28 12:28:31 localhost logger: Enter standby
Nov 28 23:26:58 localhost logger: exit standby after 39507
Nov 28 23:37:05 localhost logger: Enter standby
Nov 29 03:03:55 localhost logger: exit standby after 12410
Nov 29 03:05:13 localhost logger: WD NAS: Email alerts REST API failed to return Success
Nov 29 03:14:01 localhost logger: Enter standby
Nov 29 03:26:21 localhost logger: exit standby after 740
Nov 29 03:36:28 localhost logger: Enter standby
Nov 29 03:39:17 localhost logger: exit standby after 169
Nov 29 03:49:24 localhost logger: Enter standby
Nov 29 04:09:17 localhost logger: exit standby after 1193
Nov 29 04:19:24 localhost logger: Enter standby
Nov 29 06:25:11 localhost logger: exit standby after 7547
Nov 29 06:35:19 localhost logger: Enter standby
Nov 30 04:28:41 localhost logger: exit standby after 78802
Nov 30 04:38:48 localhost logger: Enter standby
Nov 30 06:25:11 localhost logger: exit standby after 6383
Nov 30 06:35:18 localhost logger: Enter standby
Dec  1 06:25:11 localhost logger: exit standby after 85793
Dec  1 06:35:19 localhost logger: Enter standby
Dec  1 06:52:11 localhost logger: exit standby after 1012
Dec  1 07:02:19 localhost logger: Enter standby
Dec  2 01:07:19 localhost logger: exit standby after 65100
Dec  2 01:17:27 localhost logger: Enter standby
Dec  2 06:25:12 localhost logger: exit standby after 18465
Dec  2 06:35:19 localhost logger: Enter standby
Dec  3 06:25:12 localhost logger: exit standby after 85793
Dec  3 06:35:19 localhost logger: Enter standby
Dec  4 00:57:11 localhost logger: exit standby after 66112
Dec  4 01:07:18 localhost logger: Enter standby
Dec  4 06:25:11 localhost logger: exit standby after 19073
Dec  4 06:35:19 localhost logger: Enter standby
Dec  4 06:47:11 localhost logger: exit standby after 712
Dec  4 06:57:18 localhost logger: Enter standby
Dec  5 06:25:11 localhost logger: exit standby after 84473

Needless to say I’m now a happy camper with this new development and am looking forward to finally starting to use my MBL for the purposes for which it was originally designed.

Recommendations for WDC:
Assuming the code that generated the huge file in the first place is under WDCs control. I would suggest they look into the merit of the following recommendations to try and prevent a reoccurance of this (presumably unusual) situation in the future and remedy any drives that currently have the problem.

1.) Suggest that the code that canveses the socket connection; the code that generated the huge number of lines of the form:
“Dec 31 19:00:57 MyBookLive cnid_metad[2214]: error in accept: Socket operation on non-socket”
be throttled back to not canvas the socket so often. It was generating over 200,000 lines per minute (over 3300 queries pe second) and these were all logged and contributed to the huge size of the log file. Suggest the canvas of the socket be reduced to perhaps once per second or once every 5 seconds. If the socket had not been canvased so often then the huge file that created the Sleep problem would not have occurred. If this is not possible then perhaps not logging all the socket operations could be considered.
2.) Suggest that during the next firmware update, that WDC incorporate code that looks at the size of the files in certain critical directories and if the files are too large and thus could be creating the Sleep problem, that they be reduced in size or deleted.

Trust that this posting is of some use to the WD MBL Community.

Regards, WilliamH

[Myron]

Certainly is interesting that a log file when the RAM disk where the log files are maintained is only 21Mb in size!

NAS:~# df -H
Filesystem Size Used Avail Use% Mounted on . . .ramlog-tmpfs 21M 6.1M 15M 29% /var/log
 . . .

 With your /var/log/user.log file ending up being about 650Mb in total size!

How does the RAM disc work?  If it fills up, does it then start writing all the logs directly to the hard disc?  That would certainly now allow the hard disc to sleep.

The RAMDISK flushes it’s content to the folder **/var/log.hdd** when it it shut down. So what does the RAMDISK driver do when it’s ram disk is chock-a-block full?

ramlog’s developer’s home page is:  http://www.tremende.com/ramlog/index.htm

[Myron]

Something else…  May be significant.  I added my own preferred NTP server in addition to the detault NTP servers right from the start.

For the primary NTP server I use **ntp1.npl.co.uk** which houses, what the scientific community says, the most accurate atomic clock on the planet.  All my computers and gadgets use that public network time server.

[Myron]

http://netatalk.sourceforge.net/2.0/htmldocs/cnid_metad.8.html

cnid_metad waits for requests from afpd to start up instances of the cnid_dbd daemon. It keeps track of the status of a cnid_dbd instance once started and will restart it if necessary. cnid_metad is normally started at boot time from /etc/rc or equivalent and runs until shutdown. afpd needs to be configured with the -cnidserver option in afpd.conf in order to access cnid_metad. It is possible to run more than one instance of cnid_metad on the same machine if different values for the interface and/or port are specified with the -h and -p options.

So…  If I don’t have an Apple computer of device on my network, how can I safely stop all the services to do with Apple networking within the MyBook Live that I own?

Would be cool to have an option on the Dashboard UI that can start and enable and disable individual network file sharing services.

[WilliamH]

Myron,

Glad you are looking into this. Of course it was your remarks about Twonky logging on Sat 26 Nov 2011 (a large log file can cause the MBL to not Sleep) in the thread “Re: New Release - Firmware Version 02.10.09-124 for My Book Live (11/17/11)” that pointed me in the right direction to a solution. I thank you kindly for that most helpful post

Are you saying that all those 7million lines that got generated with “… cnid_metad[2214]: error in accept: Socket operation on non-socket” in them were all associated with something associated with Apple? I don’t own anything with the Apple brand name on it and after all the grief that I’ve had with the MBL Sleep/Standby issues, if it was Apple behind it all I will very likely keep it that way.

Any ideas why I had this particular problem yet not very many other people have had a similar problem? And why wasn’t WDC able to give any hints as to what the problem might have been? Surely they must be well aware of the 21 MB RAM Disk directory limitation and the havoc that is created if that size is exceeded.

WilliamH

[Skyweir]

Had lots of hope, but deleting the log did not let the drive sleep. I keep hoping we’ll hear from the WD folks soon about this.

[Myron]

Here are what my assumptions are based on:

• If the log storage space fills up then denying log file expansion will destroy evidence of any probles and can even kill/crash/panic services when all of a sudden they find out they can’t add to their log files so ramlog may begin using /var/log.hdd on a full time basis.  Especially as you’ve seen one single log file being 650 megabytes in size when the ramlog’s (not ram disc as I has described it) space is only configured to be 20 megabytes in size.
• Tronky’s log, by design, is written into the DataVolume partition so it will always prevent the MBL from sleeping but Twonky’s log is only needed for diagnostic purposes and it does grow REALLY FAST!

The question now is this other poor soul who seems to have a ramlog wihin capacity and his MBL is still not going to sleep.

It would be interesting to see how the MBL behaves when all the Apple networking services are stopped. I’ll try this at some point but just manually stop the services so on reboot everything still starts as W.D. has designed it to operate.

I do think (positive criticism!) that W.D. should build in the facility to allow the user to shut-off all and any services that they don’t need to use. Like why do I need AppleTalk and the Apple Filing System active on my network when I don’t have ANY equipment from the Apple stable?

That’s a suggestion for the next firmware update.  (Together with a suggestion to allow user selected network shares to to be omitted from a SafePoint back-up.)

[Myron]

Try moving a log file out of /var/log as you may be destroying evidence.

Also, have a look in /var/log.hdd to see if the total size of all the files is above 19 megabytes.  If this is the case I suspect the ramlog will never be used for all the log files hence the MBL won’g to go sleep.

ramlog’s developer does not have a lot of information on his web site on exactly how ramlog deals with log files totalling more than 20 megabytes in size.

Skyweir wrote:

Had lots of hope, but deleting the log did not let the drive sleep. I keep hoping we’ll hear from the WD folks soon about this.

[WDTony]

WilliamH,

We do prune the logs on a regular basis. It looks as if you have something in your system/environment causing this issue with the netatalk client. The fact that it fills up the log so fast is the issue. our pruning would not catch this log being so big so fast, hence the issue with the sleep problems. I have communicated this to our developers as this is two separate issues. We have not seen this error you are reporting and we will look into the log size keeping the system from going into sleep.

[Myron]

Could an option be put in on the next firmware update that allowes the MyBook Live owner turn off the software components associated with Apple networking or ar least let us know what services within the MBL to stop.

WDTony wrote:

WilliamH,

 

We do prune the logs on a regular basis. It looks as if you have something in your system/environment causing this issue with the netatalk client. The fact that it fills up the log so fast is the issue. our pruning would not catch this log being so big so fast, hence the issue with the sleep problems. I have communicated this to our developers as this is two separate issues. We have not seen this error you are reporting and we will look into the log size keeping the system from going into sleep.

[Myron]

I’m sure WDTony will frown at this but I’m gonna try my MBL with the Apple networking turned off.  The command to turn it off is . . .

/etc/init.d//netatalk stop

This stop the afp and cnid_metad services.

 To start afp and cnid_metad use the command . . .

/etc/init.d//netatalk start

 If you have nothing on one’s network that used Apple networking then why have these services enabled?

Good advise is not to change anything to make it permanantly disabled. Just incase the MBL wobbles. Rebooting the MBL will re-start the Apple network components.

Will try use my MBL without, see what happens and report back here.

[WDTony]

Myron,

That goes against who we are trying to target this product to. We want to make this as easy as possible for users to get up and running and get started. The fact that netatalk is running should not be an issue for most people. The fact that there is some error that is pounding the logs is an issue.

[cman548]

WDTony wrote:

pounding the logs is an issue.

I’m still new here and didn’t read the forum rules, but there’s a good mom joke in there.

[WDTony]

oh man - thats just wrong!

[Skyweir]

My bad.

In my case I had installed a Squid proxy which was preventing disk sleep. While I understand that Squid is known to do this,  the prior firmware somehow allowed the disk to sleep.

[Myron]

Understood Tony, but still, I don’t have any Apple manufactured equipment on my network and don’t want this service running. I’ve worked round this problem by manually stopping netatalk. It would be simple to have the option in the Dashboard UI that can be used to enable and disable netatak with the factory default beinbg enabed. I don’t see the problem not including such an option.

By allowing the user/owner to turn off and on services at will within the MBL, it gives the owner choice. With unneeded services being turned off then there is less within the MBL to go wrong. It’s logical common sense.

WDTony wrote:

Myron,

 

That goes against who we are trying to target this product to. We want to make this as easy as possible for users to get up and running and get started. The fact that netatalk is running should not be an issue for most people. The fact that there is some error that is pounding the logs is an issue.

[jives11]

This is an interesting thread. However I’m not seeing users.log growing at anything like that speed. My build is

#uname -a
Linux MyBookLive 2.6.32.11-svn48181 #1 Thu Sep 15 18:22:06 PDT 2011 ppc GNU/Linux

In fact  my user.log was last updated about 2 weeks ago.

I think you need to determine what is causing logging at that level. I’m not seeing it on my machine. Mind I don’t run any of the orion scripts, nor the monitorio.sh script (ironically the script used to determine sleep condition). I favour constant green light but minimal activity

[WDTony]

The file in question was daemon.log.1 (or possibly daemon.log).