PDA

View Full Version : SC7.0 broken ? mysql issue ?



geoff
2008-04-11, 15:33
I ran 6.5.4 on my Ubuntu 6.10 server for a long time successfully. I Decided to upgrade the Ubuntu platform to Ubuntu 7.10. Then I thought I may as well upgrade SC to 7.0 as well. Golden rule is to never change 2 things at once, I know! But now I'm in a bit of a mess.

SC7.0 sort of works. But it seems to be much slower than 6.5.4, the web interface is much less responsive. And I seem to be getting "drop outs" which I initially thought were problems with the wireless link to my SquuezeBox -- but surely that would be too much of a coincidence! A browse of the server log shows various error messages. The most critical of which seems to say there is something wrong with the MYSQL connection. But if so how is it working at all? Here is the log immediately following a restart:
<quote>
2008-04-12 08:02:16 squeezecenter_safe stopped.
2008-04-12 08:02:17 squeezecenter_safe started.
[08-04-12 08:02:18.9398] Slim::Schema::forceCommit (1363) Warning: Trying to commit transactions before DB is initialized!
[08-04-12 08:02:18.9418] Slim::Schema::Storage::throw_exception (67) Error: DBI Connection failed: DBI connect('hostname=127.0.0.1;port=9092;database=sli mserver:mysql_socket=/var/lib/squeezecenter/cache/squeezecenter-mysql.sock','slimserver',...) failed: Can't connect to MySQL server on '127.0.0.1' (111) at /usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 652
[08-04-12 08:02:18.9423] Slim::Schema::Storage::throw_exception (67) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema/Storage.pm line 67)
frame 1: Slim::Schema::Storage::throw_exception (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 658)
frame 2: DBIx::Class::Storage::DBI::_connect (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 616)
frame 3: DBIx::Class::Storage::DBI::_populate_dbh (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 543)
frame 4: DBIx::Class::Storage::DBI::ensure_connected (/usr/share/perl5/Slim/Schema/Storage.pm line 27)
frame 5: (eval) (/usr/share/perl5/Slim/Schema/Storage.pm line 27)
frame 6: Slim::Schema::Storage::dbh (/usr/share/perl5/Slim/Schema.pm line 244)
frame 7: (eval) (/usr/share/perl5/Slim/Schema.pm line 244)
frame 8: Slim::Schema::disconnect (/usr/sbin/squeezecenter-server line 964)
frame 9: main::cleanup (/usr/share/perl5/Slim/bootstrap.pm line 368)
frame 10: Slim::bootstrap::sigint (/usr/share/perl5/Slim/bootstrap.pm line 402)
frame 11: Slim::bootstrap::theEND (/usr/sbin/squeezecenter-server line 1001)
frame 12: main::END (/usr/sbin/squeezecenter-server line 0)
frame 13: (eval) (/usr/sbin/squeezecenter-server line 0)

[08-04-12 08:02:21.3057] Slim::Networking::mDNS::startAdvertising (110) Error: Couldn't find mDNSResponderPosix binary! Aborting!
</quote>

Googling suggested a problem with apparmor (introduced withe the Ubuntu upgrade). So I turned it off completely. The above log is with apparmor stopped.

Googling also suggested the mDNSResponderPosix message was harmless.

My server does have a full MYSQL instance running for other applications, but for SC I am using the embedded mysql. I installed it "out of the box" with no changes.

My log file also shows quite a few of the following:
<quote>
2008-04-12 07:48:15 SqueezeCenter died. Restarting.
</quote>

It seems to shut down, restart, and after a minutes silence it starts playing again.

Before I fall back to 6.5.4 does anyone have any suggestions on how to debug this?

geoff
2008-04-11, 17:28
It turns out the MYSQL error occurs when SC is stopped, not when it is started. The previous log was from an "/etc/init.d/sqeezecenter restart" command.

However, if I do a "stop" followed by a "start" with some time delay in between then I see the sequence looks like this (this time with mysql logging turned on to at debug level):

((( issue stop command )))
<log>
[08-04-12 10:12:48.0477] Slim::Utils::MySQLHelper::stopServer (344) Running shutdown.
2008-04-12 10:12:48 squeezecenter_safe stopped.
[08-04-12 10:12:50.0718] Slim::Schema::forceCommit (1363) Warning: Trying to commit transactions before DB is initialized!
[08-04-12 10:12:50.0738] Slim::Schema::Storage::throw_exception (67) Error: DBI Connection failed: DBI connect('hostname=127.0.0.1;port=9092;database=sli mserver:mysql_socket=/var/lib/squeezecenter/cache/squeezecenter-mysql.sock','slimserver',...) failed: Can't connect to MySQL server on '127.0.0.1' (111) at /usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 652
[08-04-12 10:12:50.0743] Slim::Schema::Storage::throw_exception (67) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema/Storage.pm line 67)
frame 1: Slim::Schema::Storage::throw_exception (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 658)
frame 2: DBIx::Class::Storage::DBI::_connect (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 616)
frame 3: DBIx::Class::Storage::DBI::_populate_dbh (/usr/share/squeezecenter/CPAN/DBIx/Class/Storage/DBI.pm line 543)
frame 4: DBIx::Class::Storage::DBI::ensure_connected (/usr/share/perl5/Slim/Schema/Storage.pm line 27)
frame 5: (eval) (/usr/share/perl5/Slim/Schema/Storage.pm line 27)
frame 6: Slim::Schema::Storage::dbh (/usr/share/perl5/Slim/Schema.pm line 244)
frame 7: (eval) (/usr/share/perl5/Slim/Schema.pm line 244)
frame 8: Slim::Schema::disconnect (/usr/sbin/squeezecenter-server line 964)
frame 9: main::cleanup (/usr/share/perl5/Slim/bootstrap.pm line 368)
frame 10: Slim::bootstrap::sigint (/usr/share/perl5/Slim/bootstrap.pm line 402)
frame 11: Slim::bootstrap::theEND (/usr/sbin/squeezecenter-server line 1001)
frame 12: main::END (/usr/sbin/squeezecenter-server line 0)
frame 13: (eval) (/usr/sbin/squeezecenter-server line 0)
</log>

((( time delay then issue start command ))))

<log>
2008-04-12 10:14:22 squeezecenter_safe started.
[08-04-12 10:14:23.3009] Slim::Utils::MySQLHelper::createConfig (182) createConfig() Creating config from file: [/usr/share/squeezecenter/MySQL/my.tt] -> [/var/lib/squeezecenter/cache/my.cnf].
[08-04-12 10:14:23.3558] Slim::Utils::MySQLHelper::startServer (247) About to start MySQL as a process with command: [/usr/sbin/mysqld --defaults-file=/var/lib/squeezecenter/cache/my.cnf]
[08-04-12 10:14:25.4730] Slim::Networking::mDNS::startAdvertising (110) Error: Couldn't find mDNSResponderPosix binary! Aborting!
</log>

snarlydwarf
2008-04-11, 17:44
Are you sure you don't have more than one instance of sc7 running?

Under some conditions of load, it can accidentally spawn a second instance which will never be able to actually start (since it is running already) and will keep restarting.

ps should only show one running.

If a second is running, just kill it.

geoff
2008-04-11, 20:36
I stopped mysql and squeezeserver.
Now:
ps -A | grep sq
shows nothing running.

Then:
/etc/init.d/squeezeserver start

Now:
ps -A | grep sq
shows two sc processes + mysqld:
32414 ? 00:00:00 squeezecenter_s
32416 ? 00:00:02 squeezecenter-s
32418 ? 00:00:00 mysqld

Note one with underscore _s and the second with hyphen -s.
Is that correct ?

snarlydwarf
2008-04-12, 10:36
yep, one is squeezecenter_safe and one is squeezecenter-server (the 'safe' just keeps rerunning -server... if it doesn't start 'fast enough', it assumes it died and starts another... which if that isnt fast enough.. gets another spawned..)

I'm confused because from the order of events in the log, it appears that the "_safe" script is ending, mysql has exited.. but SC is still running and complaining about mysql vanishing underneat it.

For some reason it isnt seeing the shutdown.

rkerr
2008-04-12, 12:25
Squeezecenter server.log:

frame 13: (eval) (/usr/sbin/squeezecenter-server line 0)

2008-04-12 15:11:54 squeezecenter_safe started.
[08-04-12 15:11:57.3383] main::checkDataSource (870) Warning: Schema updated or tracks in the database, initiating scan.
[08-04-12 15:11:57.4083] Slim::Networking::mDNS::startAdvertising (110) Error: Couldn't find mDNSResponderPosix binary! Aborting!
HTTP/1.1 200 OK
Server: SqueezeCenter (7.0 - 17793)
Connection: keep-alive
Date: Sat, 12 Apr 2008 19:18:15 GMT
Content-Length: 360
Content-Type: text/plain

frame 13: (eval) (/usr/sbin/squeezecenter-server line 0)

2008-04-12 15:11:54 squeezecenter_safe started.
[08-04-12 15:11:57.3383] main::checkDataSource (870) Warning: Schema updated or tracks in the database, initiating scan.
[08-04-12 15:11:57.4083] Slim::Networking::mDNS::startAdvertising (110) Error: Couldn't find mDNSResponderPosix binary! Aborting!

*****************

Squeezecenter scanner.log:

[08-04-12 10:27:02.2232] Ogg::Vorbis::Header::PurePerl::_loadInfo (187) Warning: Use of uninitialized value in seek at /usr/share/squeezecenter/lib/Ogg/Vorbis/Header/PurePerl.pm line 187.
[08-04-12 10:27:02.2235] Ogg::Vorbis::Header::PurePerl::_loadComments (242) Warning: No comment header? at /usr/share/squeezecenter/lib/Ogg/Vorbis/Header/PurePerl.pm line 242.
[08-04-12 10:27:02.2238] Ogg::Vorbis::Header::PurePerl::_calculateTrackLeng th (334) Warning: Use of uninitialized value in subtraction (-) at /usr/share/squeezecenter/lib/Ogg/Vorbis/Header/PurePerl.pm line 334.
[08-04-12 10:27:02.2288] Ogg::Vorbis::Header::PurePerl::_calculateTrackLeng th (364) Warning: Ogg::Vorbis::Header::PurePerl: Didn't find an ogg header - invalid file?
[08-04-12 10:27:02.2292] Slim::Formats::Ogg::getTag (78) Warning: Length for Ogg file: /home/rrkrr/Examples/Experience ubuntu.ogg is 0 - skipping.
HTTP/1.1 200 OK
Server: SqueezeCenter (7.0 - 17793)
Connection: keep-alive
Date: Sat, 12 Apr 2008 19:23:36 GMT
Content-Length: 888
Content-Type: text/plain

[08-04-12 10:27:02.2232] Ogg::Vorbis::Header::PurePerl::_loadInfo (187) Warning: Use of uninitialized value in seek at /usr/share/squeezecenter/lib/Ogg/Vorbis/Header/PurePerl.pm line 187.
[08-04-12 10:27:02.2235] Ogg::Vorbis::Header::PurePerl::_loadComments (242) Warning: No comment header? at /usr/share/squeezecenter/lib/Ogg/Vorbis/Header/PurePerl.pm line 242.
[08-04-12 10:27:02.2238] Ogg::Vorbis::Header::PurePerl::_calculateTrackLeng th (334) Warning: Use of uninitialized value in subtraction (-) at /usr/share/squeezecenter/lib/Ogg/Vorbis/Header/PurePerl.pm line 334.
[08-04-12 10:27:02.2288] Ogg::Vorbis::Header::PurePerl::_calculateTrackLeng th (364) Warning: Ogg::Vorbis::Header::PurePerl: Didn't find an ogg header - invalid file?
[08-04-12 10:27:02.2292] Slim::Formats::Ogg::getTag (78) Warning: Length for Ogg file: /home/rrkrr/Examples/Experience ubuntu.ogg is 0 - skipping.



Anyone know what this means?