[SOLVED] NAS not hibernating after upgrading to 1.0

[xs2inattar]

My Synology NAS does not hibernate after upgrading to 1.0. It seems like Serviio is reading online repositories every one minute instead of using the feed expiry interval set in the console.

  Code:

2012-07-29 01:15:39,479 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 112)
2012-07-29 01:15:39,490 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 114)
2012-07-29 01:15:39,491 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 118)
2012-07-29 01:15:39,492 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 119)
2012-07-29 01:15:39,494 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 120)
2012-07-29 01:15:39,495 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 121)
2012-07-29 01:15:39,497 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 125)
2012-07-29 01:15:56,840 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth0 (eth0) and address 192.168.1.11, timeout = 0
2012-07-29 01:15:56,841 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 61cd396e-1894-3da9-91a2-e8090bcf4e54
2012-07-29 01:15:58,820 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:57
2012-07-29 01:16:39,500 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-07-29 01:16:39,500 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-07-29 01:16:39,504 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 98)
2012-07-29 01:16:39,532 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 99)
2012-07-29 01:16:39,533 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 100)
2012-07-29 01:16:39,534 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 101)
2012-07-29 01:16:39,535 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 102)
2012-07-29 01:16:39,536 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 103)
2012-07-29 01:16:39,537 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 104)
2012-07-29 01:16:39,537 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 105)
2012-07-29 01:16:39,538 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 106)
2012-07-29 01:16:39,539 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 107)
2012-07-29 01:16:39,555 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 108)
2012-07-29 01:16:39,556 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 109)
2012-07-29 01:16:39,557 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 110)
2012-07-29 01:16:39,558 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 111)
2012-07-29 01:16:39,559 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 112)
2012-07-29 01:16:39,580 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 114)
2012-07-29 01:16:39,581 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 118)
2012-07-29 01:16:39,582 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 119)
2012-07-29 01:16:39,584 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 120)
2012-07-29 01:16:39,585 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 121)
2012-07-29 01:16:39,587 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 125)
2012-07-29 01:16:56,710 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth0 (eth0) and address 192.168.1.11, timeout = 0
2012-07-29 01:16:56,711 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 61cd396e-1894-3da9-91a2-e8090bcf4e54
2012-07-29 01:16:58,690 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:38
2012-07-29 01:17:36,711 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth0 (eth0) and address 192.168.1.11, timeout = 0
2012-07-29 01:17:36,712 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 61cd396e-1894-3da9-91a2-e8090bcf4e54
2012-07-29 01:17:38,690 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:51
2012-07-29 01:17:39,590 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-07-29 01:17:39,590 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-07-29 01:17:39,590 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-07-29 01:17:39,590 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-07-29 01:17:39,594 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 98)
2012-07-29 01:17:39,632 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 99)
2012-07-29 01:17:39,633 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 100)
2012-07-29 01:17:39,634 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 101)
2012-07-29 01:17:39,635 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 102)
2012-07-29 01:17:39,636 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 103)
2012-07-29 01:17:39,637 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 104)
2012-07-29 01:17:39,637 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 105)
2012-07-29 01:17:39,638 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 106)
2012-07-29 01:17:39,639 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 107)
2012-07-29 01:17:39,655 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 108)
2012-07-29 01:17:39,656 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 109)
2012-07-29 01:17:39,657 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 110)
2012-07-29 01:17:39,658 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 111)
2012-07-29 01:17:39,659 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 112)
2012-07-29 01:17:39,690 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 114)
2012-07-29 01:17:39,691 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 118)
2012-07-29 01:17:39,692 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 119)
2012-07-29 01:17:39,694 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 120)
2012-07-29 01:17:39,695 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 121)
2012-07-29 01:17:39,697 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 125)
2012-07-29 01:18:30,011 DEBUG [DiscoveryAdvertisementNotifier] Multicasting SSDP alive using interface eth0 (eth0) and address 192.168.1.11, timeout = 0
2012-07-29 01:18:30,011 DEBUG [DiscoveryAdvertisementNotifier] Sending 6 'alive' messages describing device 61cd396e-1894-3da9-91a2-e8090bcf4e54
2012-07-29 01:18:31,990 DEBUG [DiscoveryAdvertisementNotifier] Will advertise again in 00:00:38
2012-07-29 01:18:39,700 DEBUG [FeedUpdaterThread] Checking for new and expired online resources
2012-07-29 01:18:39,700 DEBUG [OnlineRepositoryDAOImpl] Reading all OnlineRepositories
2012-07-29 01:18:39,704 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 98)
2012-07-29 01:18:39,742 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 99)
2012-07-29 01:18:39,743 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 100)
2012-07-29 01:18:39,744 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 101)
2012-07-29 01:18:39,745 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 102)
2012-07-29 01:18:39,746 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 103)
2012-07-29 01:18:39,747 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 104)
2012-07-29 01:18:39,747 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 105)
2012-07-29 01:18:39,748 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 106)
2012-07-29 01:18:39,749 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 107)
2012-07-29 01:18:39,775 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 108)
2012-07-29 01:18:39,776 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 109)
2012-07-29 01:18:39,777 DEBUG [OnlineRepositoryDAOImpl] Reading an OnlineRepository (id = 110)


Any ideas???

[zip]

It always checked every minute. No change there from 0.6.

[patters]

My Synology has never hibernated while running Serviio. I did try symlinking the log folder to a ramdisk but it didn't seem to help so maybe it's some kind of Java issue.

[xs2inattar]

My Synology used to hibernate with Serviio 0.6.2. It stopped after upgrading to 1.0. I am still trying to figure out what changed.

Well, after upgrading my Synology DS212+ to the latest Serviio version (very bad idea), it also doesn't hibernate...

After some fiddling around, there is a command on the Synology to debug hibernation issues:

syno_hibernate_debug_tool --enable 1

then

cd /var/log

tail -f messages

So I've found out that ever 30s, the Serviio server checks this file on the disk:

[/volume1/homes/serviio/.java/.userPrefs/.user.lock.serviio] opened by pid 10290 [u:(/volume1/@appstore/java7/jre/bi), comm:(java)]

(it repeats this endlessly every 30s...)

I think this is the reason why the NAS doesn't hibernate.

Stoping Serviio, the message stops, and the NAS hibernates.

Any solutions?

[xs2inattar]

Zip, we would really appreciate if you could comment on syncmaster's findings.

[zip]

OK, this is caused by Java preferences subsystem - out of my hands. Apparently you can change the syncing interval form 30 seconds to some very high number using this system property:

  Code:

-Djava.util.prefs.syncInterval

e.g.:

  Code:

-Djava.util.prefs.syncInterval=2000000

[xs2inattar]

1. the value is in milliseconds right ?
2. Where does the parameter go ? serviio java options file ?

[patters]

Nice detective work syncmaster - I'll take a look at incorporating this fix into the package. Can you guys confirm it works? Add that parameter to the variable JAVA_OPTS in /volume1/@appstore/Serviio/bin/serviio.sh

[xs2inattar]

Just restarted my server with the parameter added. Will update shortly.

[zip]

1. the value is in milliseconds right ?

seconds

Ok, just added the parameter with value 9999999.

Let's see how it goes.

I'll be back in an hour or two .

Ok.

Adding the parameter and starting Serviio, after a while the NAS does hibernate. So at least starting on boot does allow to hibernate.

When using it the NAS does wake up and Serviio works, it seems, fine.

So I've stop using it, and now I'm waiting that the NAS hibernates again.

But at least it looks promising, and probably the issue is solved.

[xs2inattar]

Confirming that my ds212+ hibernates after adding the java option.

Thanks syncmaster for identifying what was causing this

Thanks Petr for the quick response.

x2 for me.

Adding the Java option allows the NAS to hibernate.

Problem solved.

off-topic:

I'll have to check if with the Crashplan package for the Synology, that when running, the NAS also doesn't hibernate, if the issue is the same...

[patters]

What sort of default do you think I should add to the package? 12 hours? 24 hours?
That debugging will be useful for diagnosing why CrashPlan prevents hibernation too.

well, I have the library scan 12h (720m).

Regarding the preferences scan, if Serviio doesn't use it, I think 24h, would be fine. It would mean one wake up/day.

OK, this is caused by Java preferences subsystem - out of my hands. Apparently you can change the syncing interval form 30 seconds to some very high number using this system property:

  Code:

-Djava.util.prefs.syncInterval

e.g.:

  Code:

-Djava.util.prefs.syncInterval=2000000

Hi all,

sorry, I am a Linux newbie so my question is: In wich file (and where) I have to insert the code?

Thanks a lot!

Regards,
Fleetship1

[patters]

If you have a Synology - don't worry, I'll update the package today with a new version incorporating that setting.

[patters]

Done.