Firefly keeps crashing on startup

[Metzeler]

Hi,

I´m using firefly svn-1668 on a NSLU2 in combination with the roku soundbrigde. The server is startet automatically on NSLU startup via the rc.local file.

Nearly everytime (sometimes it works) I start the NSLU, the firefly server is starting and shutting down on startup. The logfile looks like the following:

2007-09-26 11:25:59 (00000400): Firefly Version svn-1668: Starting with debuglevel 6
2007-09-26 11:25:59 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/rsp.so (rsp/svn-1668)
2007-09-26 11:25:59 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/out-daap.so (daap/svn-1668)
2007-09-26 11:25:59 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/ssc-script.so (ssc-script/svn-1668)
2007-09-26 11:25:59 (00000400): Plugin loaded: ssc-script/svn-1668
2007-09-26 11:25:59 (00000400): Plugin loaded: daap/svn-1668
2007-09-26 11:25:59 (00000400): Plugin loaded: rsp/svn-1668
2007-09-26 11:25:59 (00000400): Starting rendezvous daemon
2007-09-26 11:25:59 (00000400): Starting signal handler
2007-09-26 11:26:00 (00000400): Initializing database
2007-09-26 11:27:13 (00000400): Starting web server from /opt/share/mt-daapd/admin-root on port 3689
2007-09-26 11:27:13 (00000400): Listening on port 3689
2007-09-26 11:27:13 (00000400): Listen port: socket/por2007-09-26 11:27:13 (00000400): Registering rendezvous names
2007-09-26 11:27:14 (00000400): Serving 220 songs. Startup complete in 78 seconds
2007-09-26 11:27:16 (00000400): Got shutdown signal.
2007-09-26 11:27:16 (00000400): Stopping gracefully
2007-09-26 11:27:16 (00000400): Stopping rendezvous daemon
2007-09-26 11:27:16 (00000400): Closing database
2007-09-26 11:27:16 (00000400): Done!

Where does this “got shutdown signal” come from?

Can you please give me a hint to get it working.

Thanks!

[fizze]

Are you sure you aren’t invoking another copy of firefly in another skript?

In unslung, after installing the ipkg a startup skript is in /opt/etc/init.d/ anyway. So if you invoke another copy, there may be conflicts, locks on the DB and whatnot… causing firefly to shutdown, eventually?

[Metzeler]

@fizze wrote:

Are you sure you aren’t invoking another copy of firefly in another skript?

In unslung, after installing the ipkg a startup skript is in /opt/etc/init.d/ anyway. So if you invoke another copy, there may be conflicts, locks on the DB and whatnot… causing firefly to shutdown, eventually?

But as far as I know the script under /opt/etc/init.d (S60mt-daapd) isn´t started during the NSLU boot process, that´s why I´ve put “./optetc/init.s/S60mt-daapd” in the rc.local.

[rpedde]

@Metzeler wrote:

@fizze wrote:

Are you sure you aren’t invoking another copy of firefly in another skript?

In unslung, after installing the ipkg a startup skript is in /opt/etc/init.d/ anyway. So if you invoke another copy, there may be conflicts, locks on the DB and whatnot… causing firefly to shutdown, eventually?

But as far as I know the script under /opt/etc/init.d (S60mt-daapd) isn´t started during the NSLU boot process, that´s why I´ve put “./optetc/init.s/S60mt-daapd” in the rc.local.

Don’t know if it helps, but there are only three ways to send it a shutdown signal.

1. Send a TERM signal to the pid
2. Run another copy with a “-k” option
3. Hit the shutdown button from the web interface.

That’s it.

You can maybe turn the debuglevel up to 9 and comb through the logs to see which of the three it is.

— Ron

[Metzeler]

@rpedde wrote:

@Metzeler wrote:

@fizze wrote:

Are you sure you aren’t invoking another copy of firefly in another skript?

In unslung, after installing the ipkg a startup skript is in /opt/etc/init.d/ anyway. So if you invoke another copy, there may be conflicts, locks on the DB and whatnot… causing firefly to shutdown, eventually?

But as far as I know the script under /opt/etc/init.d (S60mt-daapd) isn´t started during the NSLU boot process, that´s why I´ve put “./optetc/init.s/S60mt-daapd” in the rc.local.

Don’t know if it helps, but there are only three ways to send it a shutdown signal.

1. Send a TERM signal to the pid
2. Run another copy with a “-k” option
3. Hit the shutdown button from the web interface.

That’s it.

You can maybe turn the debuglevel up to 9 and comb through the logs to see which of the three it is.

— Ron

Hi Ron,

I´ve checked this, but amazingly I get different results with every start.
For the first start with debug level 9 the logfile looked like this:

2007-09-27 11:42:51 (00000400): Firefly Version svn-1668: Starting with debuglevel 9
2007-09-27 11:42:51 (00000400): Attempting to load plugin /opt/share/mt-daapd/plugins/rsp.so
2007-09-27 11:42:51 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/rsp.so (rsp/svn-1668)
2007-09-27 11:42:51 (00000400): New transcode codec list:
2007-09-27 11:42:51 (00000400): Attempting to load plugin /opt/share/mt-daapd/plugins/out-daap.so
2007-09-27 11:42:51 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/out-daap.so (daap/svn-1668)
2007-09-27 11:42:51 (00000400): New transcode codec list:
2007-09-27 11:42:51 (00000400): Attempting to load plugin /opt/share/mt-daapd/plugins/ssc-script.so
2007-09-27 11:42:51 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/ssc-script.so (ssc-script/svn-1668)
2007-09-27 11:42:51 (00000400): New transcode codec list: ogg,flac,alac
2007-09-27 11:42:51 (00000400): Plugin loaded: ssc-script/svn-1668
2007-09-27 11:42:51 (00000400): Plugin loaded: daap/svn-1668
2007-09-27 11:42:51 (00000400): Plugin loaded: rsp/svn-1668
2007-09-27 11:42:51 (00000400): Starting rendezvous daemon
2007-09-27 11:42:51 (00000400): Starting signal handler
2007-09-27 11:42:51 (00000400): Pid: 499
2007-09-27 11:42:51 (00000400): Opening database
2007-09-27 11:42:51 (00000400): Executing: select value from config where term=’version’
2007-09-27 11:43:28 (00000400): Error: enum_begin failed (error 1): Misc SQL Error: database is locked
2007-09-27 11:43:28 (00000400): Can’t get db version. New database?
2007-09-27 11:43:28 (00000400): Results: 0
2007-09-27 11:43:28 (00000400): Initializing database
2007-09-27 11:43:28 (00000400): Execu2007-09-27 11:43:56 (00000400): R2007-09-27 11:43:59 (00000400): Executing: select value from config where term=’rescan’
2007-09-27 11:43:59 (00000400): Executing: vacuum
2007-09-27 11:45:05 (00000400): Rows: 0
2007-09-27 11:45:05 (00000400): Executing: create index idx_path on songs(path,idx)
2007-09-27 11:45:05 (00000400): Query: create index idx_path on songs(path,idx)
2007-09-27 11:45:05 (00000400): Error: index idx_path already exists
2007-09-27 11:45:05 (00000400): Executing: create index idx_songid on playlistitems(songid)
2007-09-27 11:45:05 (00000400): Query: create index idx_songid on playlistitems(songid)
2007-09-27 11:45:05 (00000400): Error: index idx_songid already exists
2007-09-27 11:45:05 (00000400): Executing: create index idx_playlistid on playlistitems(playlistid,songid)
2007-09-27 11:45:05 (00000400): Query: create index idx_playlistid on playlistitems(playlistid,songid)
2007-09-27 11:45:05 (00000400): Error: index idx_playlistid already exists
2007-09-27 11:45:05 (00000400): Executing: select count(*) FROM songs
2007-09-27 11:45:08 (00000400): Starting web server from /opt/share/mt-daapd/admin-root on port 3689
2007-09-27 11:45:08 (00000400): Listening on port 3689
2007-09-27 11:45:08 (00000400): Opening listen://3689
2007-09-27 11:45:08 (00000400): Checking handler for listen
2007-09-27 11:45:08 (00000400): opening 3689
2007-09-27 11:45:08 (00000400): Doing io_listen_open
2007-09-27 11:45:08 (00000400): Socket opened
2007-09-27 11:45:08 (00000400): Preparing to listen with 5 backlog on 3689
2007-09-27 11:45:08 (00000400): Starting server thread
2007-09-27 11:45:08 (00000400): Registering rendezvous names
2007-09-27 11:45:08 (00000400): Processing rendezvous message
2007-09-27 11:45:08 (00000400): Registering Mucke Spender._http._tcp (3689)
2007-09-27 11:45:08 (00000400): Registered service 0, name ‘Mucke Spender’, type ‘_http._tcp’, port 3689
2007-09-27 11:45:08 (00000400): Checking ssc-script/svn-1668
2007-09-27 11:45:08 (00000400): Checking daap/svn-1668
2007-09-27 11:45:08 (00000400): Registering _daap._tcp
2007-09-27 11:45:08 (00000400): Processing rendezvous message
2007-09-27 11:45:08 (00000400): Registering Mucke Spender._daap._tcp (3689)
2007-09-27 11:45:08 (00000400): Registered service 1, name ‘Mucke Spender’, type ‘_daap._tcp’, port 3689
2007-09-27 11:45:08 (00000400): Checking rsp/svn-1668
2007-09-27 11:45:08 (00000400): Registering _rsp._tcp
2007-09-27 11:45:08 (00000400): Processing rendezvous message
2007-09-27 11:45:08 (00000400): Registering Mucke Spender._rsp._tcp (3689)
2007-09-27 11:45:08 (00000400): Registered service 2, name ‘Mucke Spender’, type ‘_rsp._tcp’, port 3689
2007-09-27 11:45:08 (00000400): Executing: select count(*) FROM songs
2007-09-27 11:45:09 (00000400): Callback:
Mucke Spender_http_tcplocal Name Registered
2007-09-27 11:45:09 (00000400): Callback:
Mucke Spender_daap_tcplocal Name Registered
2007-09-27 11:45:09 (00000400): Callback:
Mucke Spender_rsp_tcplocal Name Registered
2007-09-27 11:45:09 (00000400): Serving 220 songs. Startup complete in 137 seconds

The second time it contained this:

2007-09-27 11:49:21 (00000400): Firefly Version svn-1668: Starting with debuglevel 9
2007-09-27 11:49:21 (00000400): Attempting to load plugin /opt/share/mt-daapd/plugins/rsp.so
2007-09-27 11:49:21 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/rsp.so (rsp/svn-1668)
2007-09-27 11:49:21 (00000400): New transcode codec list:
2007-09-27 11:49:21 (00000400): Attempting to load plugin /opt/share/mt-daapd/plugins/out-daap.so
2007-09-27 11:49:21 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/out-daap.so (daap/svn-1668)
2007-09-27 11:49:21 (00000400): New transcode codec list:
2007-09-27 11:49:21 (00000400): Attempting to load plugin /opt/share/mt-daapd/plugins/ssc-script.so
2007-09-27 11:49:21 (00000400): Loaded plugin /opt/share/mt-daapd/plugins/ssc-script.so (ssc-script/svn-1668)
2007-09-27 11:49:21 (00000400): New transcode codec list: ogg,flac,alac
2007-09-27 11:49:21 (00000400): Plugin loaded: ssc-script/svn-1668
2007-09-27 11:49:21 (00000400): Plugin loaded: daap/svn-1668
2007-09-27 11:49:21 (00000400): Plugin loaded: rsp/svn-1668
2007-09-27 11:49:21 (00000400): Starting rendezvous daemon
2007-09-27 11:49:21 (00000400): Starting signal handler
2007-09-27 11:49:21 (00000400): Pid: 499
2007-09-27 11:49:21 (00000400): Opening database
2007-09-27 11:49:21 (00000400): Executing: select value from config where term=’version’
2007-09-27 11:49:21 (00000400): Results: 0
2007-09-27 11:49:21 (00000400): Initializing database
2007-09-27 11:49:21 (00000400): Executing: select count(*) FROM songs
2007-09-27 11:49:23 (00000400): Executing: select value from config where term=’rescan’
2007-09-27 11:49:23 (00000400): Executing: vacuum
2007-09-27 11:50:33 (00000400): Rows: 0
2007-09-27 11:50:33 (00000400): Executing: create index idx_path on songs(path,idx)
2007-09-27 11:50:33 (00000400): Query: create index idx_path on songs(path,idx)
2007-09-27 11:50:33 (00000400): Error: index idx_path already exists
2007-09-27 11:50:33 (00000400): Executing: create index idx_songid on playlistitems(songid)
2007-09-27 11:50:33 (00000400): Query: create index idx_songid on playlistitems(songid)
2007-09-27 11:50:33 (00000400): Error: index idx_songid already exists
2007-09-27 11:50:33 (00000400): Executing: create index idx_playlistid on playlistitems(playlistid,songid)
2007-09-27 11:50:33 (00000400): Query: create index idx_playlistid on playlistitems(playlistid,songid)
2007-09-27 11:50:33 (00000400): Error: index idx_playlistid already exists
2007-09-27 11:50:33 (00000400): Executing: select count(*) FROM songs
2007-09-27 11:50:37 (00000400): Starting web server from /opt/share/mt-daapd/admin-root on port 3689
2007-09-27 11:50:37 (00000400): Listening on port 3689
2007-09-27 11:50:37 (00000400): Opening listen://3689
2007-09-27 11:50:37 (00000400): Checking handler for listen
2007-09-27 11:50:37 (00000400): opening 3689
2007-09-27 11:50:37 (00000400): Doing io_listen_open
2007-09-27 11:50:37 (00000400): Socket opened
2007-09-27 11:50:37 (00000400): Error binding socket
2007-09-27 11:50:37 (00000400): Listen port: socket/port in use
2007-09-27 112007-09-27 11:50:37 (00000400): Registering rendezvous names
2007-09-27 11:50:37 (00000400): Processing rendezvous message
2007-09-27 11:50:37 (00000400): Registering Mucke Spender._http._tcp (3689)
2007-09-27 11:50:37 (00000400): Registered service 0, name ‘Mucke Spender’, type ‘_http._tcp’, port 3689
2007-09-27 11:50:37 (00000400): Checking ssc-script/svn-1668
2007-09-27 11:50:37 (00000400): Checking daap/svn-1668
2007-09-27 11:50:37 (00000400): Registering _daap._tcp
2007-09-27 11:50:37 (00000400): Processing rendezvous message
2007-09-27 11:50:37 (00000400): Registering Mucke Spender._daap._tcp (3689)
2007-09-27 11:50:37 (00000400): Registered service 1, name ‘Mucke Spender’, type ‘_daap._tcp’, port 3689
2007-09-27 11:50:37 (00000400): Checking rsp/svn-1668
2007-09-27 11:50:37 (00000400): Registering _rsp._tcp
2007-09-27 11:50:37 (00000400): Processing rendezvous message
2007-09-27 11:50:37 (00000400): Registering Mucke Spender._rsp._tcp (3689)
2007-09-27 11:50:37 (00000400): Registered service 2, name ‘Mucke Spender’, type ‘_rsp._tcp’, port 3689
2007-09-27 11:50:37 (00000400): Executing: select count(*) FROM songs
2007-09-27 11:50:38 (00000400): Serving 220 songs. Startup complete in 77 seconds
2007-09-27 11:50:38 (00000400): Callback:
Mucke Spender_http_tcplocal Name Registered
2007-09-27 11:50:38 (00000400): Callback:
Mucke Spender_daap_tcplocal Name Registered
2007-09-27 11:50:38 (00000400): Callback:
Mucke Spender_rsp_tcplocal Name Registered

Thanks for your help!
Sven

[fizze]

@Metzeler wrote:

@fizze wrote:

Are you sure you aren’t invoking another copy of firefly in another skript?

In unslung, after installing the ipkg a startup skript is in /opt/etc/init.d/ anyway. So if you invoke another copy, there may be conflicts, locks on the DB and whatnot… causing firefly to shutdown, eventually?

But as far as I know the script under /opt/etc/init.d (S60mt-daapd) isn´t started during the NSLU boot process, that´s why I´ve put “./optetc/init.s/S60mt-daapd” in the rc.local.

Yes it is being executed at startup. They all are.
That also goes well with your mixed experiences.

The socket is locked by another instance of mt-daapd, and so is the database. Go figure. 🙂

ps aux|grep daapd

is your friend.

You normally get 4 Threads of mt-daapd for each instance.
Depending on you using busybox or the real procps-ps, your mileage may vary.

[Metzeler]

Oh, thanks for this information. I´ve read in another forum that is has to be included in the rc.local otherwise the server must be started manually.

Anyways, I´ve changed the rc.local and deleted the entry for the S60mt-daapd script and…

IT WORKS! 😉

Thanks a lot! 😀

[Author]

Posts