Had a problem and no way was I going to factory restore my NAS, losing everything on it. Luckily I had fiddled, turned on the TronkyServer log and forgot to turn it off. Problem was that the TwonkyService started then immediately stopped with the NAS repeatedly trying to re-start it. No power loss or anything the likes. Just stopped working for no reason. Version of the TronkyService is v5.1.9.
Luckily WDC allows access to the Linux shell and the root user so the fault was fixed within minutes.
What was logged…
15:36:11:024 ** mediaserver starts.**
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for /DeviceDescription.xml 3
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for /ConnectionManager.xml 3
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for /ConnectionManager/Control 4
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for /ContentDirectory.xml 3
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for /ContentDirectory/Control 4
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for /MediaReceiverRegistrar.xml 3
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for /MediaReceiverRegistrar/Control 4
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for 8
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for 16
15:36:11:024 LOG_HTTP:upnp_http_register_handler registered a handler for /disk 3
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /httpproxy 3
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /albumart 3
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /configpage 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /config 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /setup 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /images 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /index 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /resources 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /webbrowse 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /cgi-bin 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /bgtrans 3
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /createobject 7
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /rpc 5
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /rss 3
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /mediarss 3
15:36:11:025 LOG_HTTP:upnp_http_register_handler registered a handler for /wii/feed 3
15:36:11:026 LOG_HTTP:upnp_http_register_handler registered a handler for /json/feed/ 3
15:36:11:026 [Info] dbx_init - using database: /CacheVolume/twonkymedia/twonky.db
15:36:11:027 [Error] dbx_query - SQL error: database disk image is malformed
15:36:11:027 sqlError - I/O error occured (11). Checking database location
15:36:11:027 sqlError - regular database corrupted, invoking rebuild
15:36:11:027 LOG_SYSTEM:upnp_init_thread (id=1208349824) with name rpc_stop_server
15:36:11:727 LOG_SYSTEM:upnp_server_stop Server terminated
15:36:11:927 dbx_queue_release called
15:36:11:927 LOG_SYSTEM:file_unlink error (errno=2,filename=/CacheVolume/twonkymedia/twonkymedia-locations.db)
15:36:11:928 LOG_SYSTEM:file_unlink error (errno=2,filename=/CacheVolume/twonkymedia/5.1.9)
15:36:11:928 [Error] dbx_delete_db - called without dbx_open
15:36:11:928 LOG_SCAN: upnp_file_scanner_exit(): In
15:36:11:928 LOG_SCAN: upnp_file_scanner_lock - critical section not initialized
15:36:11:928 LOG_SCAN: upnp_file_scanner_unlock - critical section not initialized
15:36:11:928 LOG_SCAN: upnp_file_scanner_exit - critical section not initialized
15:36:11:928 LOG_SCAN: upnp_file_scanner_exit(): Out
15:36:11:928 LOG_SYSTEM:upnp_cds_actions_release()
15:36:11:929 [Error] dbx_close - called without dbx_open
15:36:11:929 ** mediaserver stops.**
Solution…
Make sure under the Media configuration section that the Twonky service is disabled.
Enable SSH access.
Login as root.
Commands to issue are:
cd /CacheVolume/twonkymedia
mv twonky.db PossiblyCorrupt_twonky.db
mv db.info PossiblyCorrupt_db.info
Logout of the root shell.
Under the Media configuration section enable the Twonky service and select the option to rebuild the database.
Did this and the TwonkyServer on my NAS is happy and functional again.
The fault is not evident ANYWHERE unless logging is enabled.
Don’t have a clue why this happened. Don’t know what the bug is just what I did to cure the problem.
WDC should really provide an option to fully factory restore each individual service as opposed to just offering a factory restore for the entire NAS. The latter should really be a last resort.
PS: Be VERY careful when you are messing around within the NAS’s Linux operating system as if you do the wrong thing then you’ll can brick the NAS and it’ll need to be sent back to WDC to be wiped and restored.
