Server crashing on Terrastation Live

[mbaker]

Hiya. I’ve done a search around and haven’t found a solution to this problem so…

I’ve been using Firefly for a couple of years on Windoze but just got a TSLive (Arm9) and figured it would be worth trying to get it going so I can permanently brick my old server. I used the guidance and downloads I found here (which were extremely helpful):
http://buffalo.nas-central.org/index.php/Firefly_on_StockFirmware

Managed to get pretty far:
– downloaded and installed all the pieces (svn-1586)
– tweaked the config
– started firefly and indexed 15,000 songs in 15min (using only 10% of my TSLive CPU)

But once the beast finished indexing it died:

2008-01-06 17:49:57 (4001d4a0): Can't get db version. New database?

2008-01-06 17:49:57 (4001d4a0): Initializing database

2008-01-06 17:49:57 (4001d4a0): Error: enum_begin failed (error 1): ?

2008-01-06 17:49:57 (4001d4a0): Error: enum_begin failed (error 1): ?

2008-01-06 17:49:57 (4001d4a0): Full reload...

2008-01-06 17:49:57 (4001d4a0): Starting web server from /usr/local/share/mt-daapd/admin-root on port 3689

2008-01-06 17:49:57 (4001d4a0): Registering rendezvous names

2008-01-06 17:49:57 (4001d4a0): Serving 0 songs.  Startup complete in 1 seconds

2008-01-06 17:49:57 (4001d4a0): Rescanning database

2008-01-06 18:04:32 (4001d4a0): Starting playlist scan

2008-01-06 18:05:58 (4001d4a0): Rendezvous socket closed (daap server crashed?) Aborting.

2008-01-06 18:05:58: Aborting

If I restart (using debug 9) I get the following pretty quickly:

2008-01-06 18:51:27 (4001d4a0): Executing: select value from config where term='rescan'

2008-01-06 18:51:27 (4001d4a0): Executing: vacuum

2008-01-06 18:51:27 (4001d4a0): select(8, 0.099609)

2008-01-06 18:51:27 (4001d4a0): select(8, 0.099609)

2008-01-06 18:51:27 (4001d4a0): select(8, 1.899414)

2008-01-06 18:51:29 (4001d4a0): select(8, 0.099609)

2008-01-06 18:51:29 (4001d4a0): select(8, 0.099609)

2008-01-06 18:51:29 (4001d4a0): select(8, 3.899414)

2008-01-06 18:51:33 (4001d4a0): select(8, 0.100585)

2008-01-06 18:51:33 (4001d4a0): select(8, 0.099609)

2008-01-06 18:51:33 (4001d4a0): select(8, 5.000000)

2008-01-06 18:51:38 (4001d4a0): select(8, 2.899414)

2008-01-06 18:51:41 (4001d4a0): select(8, 0.080078)

2008-01-06 18:51:41 (4001d4a0): select(8, 0.079101)

2008-01-06 18:51:41 (4001d4a0): select(8, 5.000000)

2008-01-06 18:51:46 (4001d4a0): select(8, 5.000000)

2008-01-06 18:51:50 (4001d4a0): Query: vacuum

2008-01-06 18:51:50 (4001d4a0): Error: disk I/O error

2008-01-06 18:51:50: Aborting

2008-01-06 18:51:50 (4001d4a0): Processing rendezvous message

2008-01-06 18:51:50 (4001d4a0): Rendezvous socket closed (daap server crashed?) Aborting.

2008-01-06 18:51:50: Aborting

I found a reference to Query: vacuum in the forum and it recommended deleting songs.db and then rebuilding. I’ve tried that twice now but get the same result.

I can connect directly to the DB using sqlite and it looks fine but is missing the playlists from my iTunes xml file (which it’s used successfully to build the file list).

Any thoughts?

M

[rpedde]

@mbaker wrote:

2008-01-06 18:51:50 (4001d4a0): Query: vacuum

2008-01-06 18:51:50 (4001d4a0): Error: disk I/O error

That’s really what it is. It got a read or write error trying do something iwth the database.

Is it possible the /tmp directory isn’t writable by the “runas” user? also, look for a .journal file in the same directory as the db file and delete both. You might also have better luck with sqlite3 versus sqlite2.

These are the things that come to mind first. Also, make sure to do the initial index at -d9. It may (will?) take quite some time, but you’ll get a better idea of why it’s crashing int he first place.

— Ron

[mbaker]

Thanks Ron.

I’ve checked /tmp (which points to /mnt/ram, a small ram drive it seems) and it’s writable. We’re not trying to write anything large there, are we? It’s got a max size of 15M.

I’ll try the from scratch -9 first before having a go at a new DB version.

How goes that DB rebuild?

M

[mbaker]

OK. Tried the rebuild with -9. Happily found that this didn’t slow down the build at all. Still managing about 1000 songs per minute.

However, it didn’t reach the end of the scan, seemingly crashing due to one of the other processes. See below…

M

2008-01-12 09:02:09 (4001d4a0): Found music file: 06 Chainsaw.m4a

2008-01-12 09:02:09 (4001d4a0): Codec type: mp4a

2008-01-12 09:02:09 (41b77520): Thread 168: Read: Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *Accept=text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;

q=0.5*

2008-01-12 09:02:09 (41b77520): Added *Accept=text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: Accept-Language: en-us,en;q=0.5

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *Accept-Language=en-us,en;q=0.5*

2008-01-12 09:02:09 (41b77520): Added *Accept-Language=en-us,en;q=0.5*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: Accept-Encoding: gzip,deflate

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *Accept-Encoding=gzip,deflate*

2008-01-12 09:02:09 (41b77520): Added *Accept-Encoding=gzip,deflate*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: Accept-Charset: ISO-8859-1,utf

-8;q=0.7,*;q=0.7

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *Accept-Charset=ISO-88

59-1,utf-8;q=0.7,*;q=0.7*

2008-01-12 09:02:09 (41b77520): Added *Accept-Charset=ISO-8859-1,utf-8;q=0.7,*;q

=0.7*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: Keep-Alive: 300

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *Keep-Alive=300*

2008-01-12 09:02:09 (41b77520): Added *Keep-Alive=300*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: Connection: keep-alive

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *Connection=keep-alive

*

2008-01-12 09:02:09 (41b77520): Added *Connection=keep-alive*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: X-Requested-With: XMLHttpReque

st

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *X-Requested-With=XMLH

ttpRequest*

2008-01-12 09:02:09 (41b77520): Added *X-Requested-With=XMLHttpRequest*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: X-Prototype-Version: 1.4.0

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *X-Prototype-Version=1

.4.0*

2008-01-12 09:02:09 (41b77520): Added *X-Prototype-Version=1.4.0*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: Referer: http://gaia:3689/inde

x.html

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *Referer=http://gaia:3

689/index.html*

2008-01-12 09:02:09 (41b77520): Added *Referer=http://gaia:3689/index.html*

2008-01-12 09:02:09 (41b77520): Thread 168: Read: Authorization: Basic OmZpcmVmb

Hk=

2008-01-12 09:02:09 (41b77520): Thread 168: Adding header *Authorization=Basic O

mZpcmVmbHk=*

2008-01-12 09:02:09 (41b77520): Added *Authorization=Basic OmZpcmVmbHk=*

2008-01-12 09:02:09 (41b77520): Thread 168: Read:

2008-01-12 09:02:09 (41b77520): Thread 168: Headers parsed!

2008-01-12 09:02:09 (41b77520): Checking to see if connection matches close

2008-01-12 09:02:09 (41b77520): And it does NOT

2008-01-12 09:02:09 (41b77520): Thread 168: Connection type HTTP/1.1

: Connection: persist

2008-01-12 09:02:09 (41b77520): Thread 168: parsing GET args

2008-01-12 09:02:09 (41b77520): Thread 168: Entering ws_getgetvars (method=stats

)

2008-01-12 09:02:09 (41b77520): Thread 168: Adding arg method = stats

2008-01-12 09:02:09 (41b77520): Added *method=stats*

2008-01-12 09:02:09 (41b77520): Thread 168: Done parsing GET/POST args!

2008-01-12 09:02:09 (41b77520): Thread 168: Original URI: /xml-rpc

2008-01-12 09:02:09 (41b77520): Thread 168: Translated URI: /xml-rpc

2008-01-12 09:02:09 (41b77520): Thread 168: Preparing to find handler

2008-01-12 09:02:09 (41b77520): Checking /xml-rpc against handler for /

2008-01-12 09:02:09 (41b77520): Thread 168: URI Match!

2008-01-12 09:02:09 (41b77520): Thread 168: Time is 1200128529 seconds after epo

ch

2008-01-12 09:02:09 (41b77520): Thread 168: Setting time header

2008-01-12 09:02:09 (41b77520): Added *Date=Sat, 12 Jan 2008 09:02:09 GMT*

2008-01-12 09:02:09 (41b77520): Added *Connection=keep-alive*

2008-01-12 09:02:09 (41b77520): Added *Server=mt-daapd/svn-1586*

2008-01-12 09:02:09 (41b77520): Added *Content-Type=text/html*

2008-01-12 09:02:09 (41b77520): Added *Content-Language=en_us*

2008-01-12 09:02:09 (41b77520): Thread 168: Using non-default handler

2008-01-12 09:02:09 (41b77520): in main_auth

2008-01-12 09:02:09 (41b77520): Checking url /xml-rpc

2008-01-12 09:02:09 (41b77520): Checking url /xml-rpc

2008-01-12 09:02:09 (41b77520): Dispatching auth for /xml-rpc to config auth

2008-01-12 09:02:09 (41b77520): Checking if pw required for /xml-rpc as admin

2008-01-12 09:02:09 (41b77520): Yep

2008-01-12 09:02:09 (41b77520): Preparing to decode OmZpcmVmbHk=

2008-01-12 09:02:09 (41b77520): Decoded :firefly

2008-01-12 09:02:09 (41b77520): Decoded user=, pw=firefly

2008-01-12 09:02:09 (41b77520): in main_auth

2008-01-12 09:02:09 (41b77520): Checking url /xml-rpc

2008-01-12 09:02:09 (41b77520): Checking url /xml-rpc

2008-01-12 09:02:09 (41b77520): Dispatching auth for /xml-rpc to config auth

2008-01-12 09:02:09 (41b77520): Added *HTTP_USER=*

2008-01-12 09:02:09 (41b77520): Added *HTTP_PASSWD=firefly*

2008-01-12 09:02:09 (41b77520): in main_handler

2008-01-12 09:02:09 (41b77520): Checking url /xml-rpc

2008-01-12 09:02:09 (41b77520): Checking url /xml-rpc

2008-01-12 09:02:09 (41b77520): Dispatching /xml-rpc to config handler

2008-01-12 09:02:09 (41b77520): Entering config_handler

2008-01-12 09:02:09 (41b77520): Entering config_set_status

2008-01-12 09:02:09 (41b77520): Exiting config_set_status

2008-01-12 09:02:09 (41b77520): Updating Connection from keep-alive to close

2008-01-12 09:02:09 (41b77520): Entering config_set_status

2008-01-12 09:02:09 (41b77520): Exiting config_set_status

2008-01-12 09:02:09 (41b77520): Added *Cache-Control=no-cache*

2008-01-12 09:02:09 (41b77520): Added *Expires=-1*

2008-01-12 09:02:09 (41b77520): Updating Content-Type from text/html to text/xml

; charset=utf-8

2008-01-12 09:02:09 (41b77520): Emitting reponse header Expires: -1

2008-01-12 09:02:09 (41b77520): Emitting reponse header Cache-Control: no-cache

2008-01-12 09:02:09 (41b77520): Emitting reponse header Content-Language: en_us

2008-01-12 09:02:09 (41b77520): Emitting reponse header Content-Type: text/xml;

charset=utf-8

2008-01-12 09:02:09 (41b77520): Emitting reponse header Server: mt-daapd/svn-158

6

2008-01-12 09:02:09 (41b77520): Emitting reponse header Connection: close

2008-01-12 09:02:09 (41b77520): Emitting reponse header Date: Sat, 12 Jan 2008 0

9:02:09 GMT

2008-01-12 09:02:09 (41b77520): Status inquiry

2008-01-12 09:02:09 (4001d4a0): Processing rendezvous message

2008-01-12 09:02:09 (4001d4a0): select(8, 5.000000)

2008-01-12 09:02:09 (41b77520): Returning status 0

2008-01-12 09:02:09 (41b77520): Executing: select count(*) FROM songs

2008-01-12 09:02:09 (4001d4a0): Song length: 355 seconds

2008-01-12 09:02:09 (4001d4a0): esds bitrate: 128

2008-01-12 09:02:09 (4001d4a0):  Date Added: 1155231063

2008-01-12 09:02:09 (4001d4a0):  Codec: mp4a

2008-01-12 09:02:13 (4001d4a0): Processing rendezvous message

2008-01-12 09:02:13 (4001d4a0): Rendezvous socket closed (daap server crashed?)

Aborting.

2008-01-12 09:02:13: Aborting

[mbaker]

Me again. Continued testing and think I found a more useful error message that helped me to solve the problem.

2008-01-13 08:27:32 (4001d4a0): Found /mnt/array1/Music/Album Artwork/Download/8DC1DD60EC7C97F3/09/00/10

2008-01-13 08:27:32 (4001d4a0): Found 10.. recursing

2008-01-13 08:27:32 (4001d4a0): Found /mnt/array1/Music/Album Artwork/Download/8DC1DD60EC7C97F3/09/00/10/8DC1DD60EC7C97F3-2F960DF25E02008-01-13 08:59:07 (4001d4a0): select(8, 5.000000)

2008-01-13 08:59:08 (4001d4a0): Query: commit transaction

2008-01-13 08:59:08 (4001d4a0): Error: database is full

2008-01-13 08:59:08: Aborting

2008-01-13 08:59:08 (4001d4a0): Processing rendezvous message

2008-01-13 08:59:08 (4001d4a0): Rendezvous socket closed (daap server crashed?) Aborting.

2008-01-13 08:59:08: Aborting

The database is full message made me do a quick df. It turns out that both the cache and log folders are on the TSL’s small / partition. With a large database like mine (plus running at debug 9) I was maxing out the partition, causing the write error and the crash.

The TSL comes with a nasty mt-daapd pre-installed and it keeps its files in a pre-created directory on the main disk array. I’ve changed the conf to put the log and db there and now it’s running perfectly.

I’ll go back to the original instruction writers and provide them with the update.

Cheers and good luck with the db rebuild!

M

[Author]

Posts