Bugzilla – Bug 6367
Database problems on upgrade to 7.0a1
Last modified: 2009-09-08 09:20:31 UTC
On upgrade from 6.5.4 to 7.0a1 (via apt-get, from 2007-12-14 10:03), the migration process doesn't seem to work. The server never starts properly. First I got errors like this in server.log: [07-12-14 23:15:32.8077] Slim::Schema::Storage::throw_exception (67) Error: DBI Connection failed: DBI con nect('hostname=127.0.0.1;port=9092;database=slimserver:mysql_socket=/var/cache/slimserver/squeezecenter-my sql.sock','slimserver',...) failed: Can't connect to MySQL server on '127.0.0.1' (111) at /usr/share/slims erver/CPAN/DBIx/Class/Storage/DBI.pm line 652 [07-12-14 23:15:32.8104] 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/slimserver/CPAN/DBIx/Class/Storage/DBI.pm l ine 658) frame 2: DBIx::Class::Storage::DBI::_connect (/usr/share/slimserver/CPAN/DBIx/Class/Storage/DBI.pm line 616) frame 3: DBIx::Class::Storage::DBI::_populate_dbh (/usr/share/slimserver/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/slimserver line 959) 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/slimserver line 996) frame 12: main::END (/usr/sbin/slimserver line 0) frame 13: (eval) (/usr/sbin/slimserver line 0) Now I get errors like this: 2007-12-14 23:16:55 slimserver_safe started. [07-12-14 23:21:57.5729] DBIx::Migration::migrate (115) Warning: Database error: Can't DROP 'thumb'; check that column/key exists at /usr/share/slimserver/CPAN/DBIx/Migration.pm line 115. [07-12-14 23:21:57.5760] Slim::Schema::forceCommit (1358) Warning: Trying to commit transactions before DB is initialized! 2007-12-14 23:22:03 SqueezeCenter died. Restarting. etc... These are the relevant running processes: 7535 ? S 0:00 /bin/bash /usr/sbin/slimserver_safe /usr/sbin/slimserver --prefsfile /etc/slims 7678 ? S 0:08 /usr/bin/perl -w /usr/sbin/slimserver --prefsfile /etc/slimserver/slimserver.pr 7684 ? Sl 1:02 /usr/sbin/mysqld --defaults-file=/var/cache/slimserver/my.cnf
I'm not sure, but this might be related to bug 5620. I'm guessing that the old mysqld isn't stopped when the new 7.0 install tries to start a new instance. Can you also post the contents of /var/cache/slimserver/mysql-error-log.txt?
There's nothing very interesting in /var/cache/slimserver/mysql-error-log.txt, I'm afraid: 071214 23:42:55 InnoDB: Started; log sequence number 2 3120879719 071214 23:42:55 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.0.45-Debian_1' socket: '/var/cache/slimserver/squeezecenter-mysql.sock' port: 9092 Debian etch distribution The old mysqld might have been running the first time I started 7.0a1, but it wasn't running on my following attempts.
I solved it by adding the "thumb" column to the "tracks" table. I guess I managed to abort mysqld/slimserver in the middle of an sql update. Now SqueezeCenter starts OK. I get some warnings in server.log, though, should I be worried? [07-12-15 00:23:14.7617] Slim::Utils::PluginManager::enablePlugins (449) Warning: Couldn't call Slim::Plugin::InfoBrowser::Plugin->initPlugin: Can't call method "searchDirs" on an undefined value at /usr/share/perl5/Slim/Plugin/InfoBrowser/Settings.pm line 62. [07-12-15 00:23:14.8288] Slim::Formats::RemoteStream::open (96) Can't open socket to [localhost:10002]: 111: Oppkobling nektes [07-12-15 00:23:14.8308] Slim::Plugin::MusicMagic::Plugin::initPlugin (141) Can't connect to port 10002 - MusicMagic disabled. [07-12-15 00:23:15.6813] main::checkDataSource (867) Warning: Schema updated or tracks in the database, initiating scan. [07-12-15 00:23:15.8995] Slim::Networking::mDNS::startAdvertising (110) Error: Couldn't find mDNSResponderPosix binary! Aborting! [07-12-15 00:25:54.7281] Slim::Formats::RemoteStream::open (96) Can't open socket to [localhost:10002]: 111: Oppkobling nektes
QA to repro
If this is what I think it is, maybe MySQLHelper.pm could try to find and kill orphan mysqld children before starting it up. I'm not sure how to do that though...
I'll try to reproduce this.
Reproduced. Had 6.5.4 running with a small library, upgraded to 7.0 and it doesn't start. Rebooted and SqueezeCenter started perfectly, reducing the severity due to the simple work around.
Ross: how did you reproduce this? I this a common case?
I've been meaning to comment on this. Ross, when you reproduced it, could you confirm that it was bug 5620? Was it on a VM instance or other slow machine? (That's where I saw it but couldn't reliably reproduce it.) I fixed bug 5620 in the RPM so that future upgrades from 7.0 to 7+ anything should work. I'm still concerned we may see a bunch of these, though, when the masses upgrade from 6.5 to 7.0. There's no real way to fix that in the RPM since it's a function of the stop script in the old RPM.
I reproduced this with a VMware instance. We also have a slow (400mhz celeron) with Ubuntu on it, we could test there if you'd like as well. Fletch did you say you were able to reproduce this bug? I don't believe it was bug 5620 since I wasn't stopping SC7. Dean would you like me to reproducing this with some other environment than VMware?
(In reply to comment #10) > with Ubuntu on it, we could test there if you'd like as well. Fletch did you > say you were able to reproduce this bug? I'm not really sure. I saw something similar when I was testing RPM upgrades from 6.5 to 7.0. I was never able to reproduce it reliably and I've never tried to reproduce it on Debian/Ubuntu. > I don't believe it was bug 5620 since > I wasn't stopping SC7. If you're able to reproduce it, try this. After the upgrade to 7.0 fails to start, take a look at "ps -ef | grep slim" and see if the old mysqld instance from SS 6.5 is still running. Looking at the contents of /var/cache/squeezecenter/mysql-error-log.txt might also be interesting. I may be completely off-base here. Note than my theory has no explanation for the OP's missing thumb column...
Ping ross...
Sorry for lack of response I haven't forgotten about this bug, I've been unable to reproduce it. I've tried 3 times now and each time I upgrade from 6.5.4 or 6.5.5 to 7.0, 7.0 starts just fine. I'll keep at it and respond to Fletch just as soon as I can repro. OP are you still seeing this maybe you could help me out? :)
slimdevices@henrik.synth.no: Is this still an issue with the latest 7.0 release?
I managed to reproduce! Here is the output as requested Fletch: root@ubuntu710qavmrl:/etc/apt# ps -ef | grep slim slim 5129 1 0 Jan30 ? 00:00:00 /usr/bin/gnome-keyring-daemon -d slim 5132 4894 0 Jan30 ? 00:00:00 x-session-manager slim 5167 5132 0 Jan30 ? 00:00:00 /usr/bin/ssh-agent x-session-manager slim 5169 1 0 Jan30 ? 00:00:00 /usr/lib/libgconf2-4/gconfd-2 6 slim 5173 1 0 Jan30 ? 00:00:00 dbus-daemon --fork --print-address 17 --print-pid 19 --session slim 5175 1 0 Jan30 ? 00:00:01 /usr/lib/gnome-control-center/gnome-settings-daemon slim 5181 5132 0 Jan30 ? 00:00:03 /usr/bin/metacity --replace --sm-client-id default0 slim 5184 5132 0 Jan30 ? 00:00:05 gnome-panel --sm-client-id default1 slim 5185 5132 0 Jan30 ? 00:00:39 nautilus --no-default-window --sm-client-id default2 slim 5189 1 0 Jan30 ? 00:00:00 gnome-volume-manager --sm-client-id default4 slim 5196 1 0 Jan30 ? 00:00:00 /usr/lib/bonobo-activation/bonobo-activation-server --ac-activate --ior-output-fd=16 slim 5209 1 0 Jan30 ? 00:00:22 /usr/lib/gnome-vfs-2.0/gnome-vfs-daemon slim 5210 5132 0 Jan30 ? 00:00:00 vino-session --sm-client-id default5 slim 5211 5132 0 Jan30 ? 00:00:00 bluetooth-applet slim 5215 5132 0 Jan30 ? 00:00:02 update-notifier slim 5227 5132 0 Jan30 ? 00:00:00 /usr/lib/evolution/2.12/evolution-alarm-notify slim 5228 1 0 Jan30 ? 00:00:03 gnome-screensaver slim 5233 5132 0 Jan30 ? 00:00:01 trackerd slim 5236 5132 0 Jan30 ? 00:00:01 nm-applet --sm-disable slim 5241 5132 0 Jan30 ? 00:00:00 python /usr/share/system-config-printer/applet.py slim 5253 1 0 Jan30 ? 00:00:00 /usr/lib/gnome-applets/trashapplet --oaf-activate-iid=OAFIID:GNOME_Panel_TrashApplet_Factory --oaf-ior-fd=19 slim 5257 1 0 Jan30 ? 00:00:00 gnome-power-manager slim 5259 1 0 Jan30 ? 00:00:00 /usr/lib/nautilus-cd-burner/mapping-daemon slim 5282 1 0 Jan30 ? 00:00:00 /usr/lib/fast-user-switch-applet/fast-user-switch-applet --oaf-activate-iid=OAFIID:GNOME_FastUserSwitchApplet_Factory --oaf-ior-fd=23 slim 5284 1 0 Jan30 ? 00:00:02 /usr/bin/python /usr/lib/deskbar-applet/deskbar-applet --oaf-activate-iid=OAFIID:Deskbar_Applet_Factory --oaf-ior-fd=29 slim 5286 1 0 Jan30 ? 00:00:00 /usr/lib/gnome-applets/mixer_applet2 --oaf-activate-iid=OAFIID:GNOME_MixerApplet_Factory --oaf-ior-fd=32 slim 5306 1 0 Jan30 ? 00:00:00 /usr/lib/notification-daemon/notification-daemon slim 5309 1 0 Jan30 ? 00:00:02 gnome-terminal slim 5312 5309 0 Jan30 ? 00:00:00 gnome-pty-helper slim 5313 5309 0 Jan30 pts/0 00:00:00 bash slim 7146 1 0 Jan30 ? 00:00:00 /bin/sh /usr/bin/firefox slim 7158 7146 0 Jan30 ? 00:00:00 /bin/sh /usr/lib/firefox/run-mozilla.sh /usr/lib/firefox/firefox-bin slim 7162 7158 2 Jan30 ? 00:54:16 /usr/lib/firefox/firefox-bin 110 9984 1 0 12:59 ? 00:00:00 /usr/sbin/mysqld --defaults-file=/var/cache/slimserver/my.cnf 110 10030 1 0 12:59 ? 00:00:00 /bin/bash /usr/sbin/slimserver_safe /usr/sbin/slimserver --prefsfile /etc/slimserver/slimserver.pref --logdir /var/log/slimserver/ --cachedir /var/cache/slimserver 110 10073 1 0 13:02 ? 00:00:00 /usr/sbin/mysqld --defaults-file=/var/cache/slimserver/my.cnf 110 10083 1 0 13:02 ? 00:00:00 /usr/sbin/mysqld --defaults-file=/var/cache/slimserver/my.cnf 110 10091 10030 12 13:03 ? 00:00:01 /usr/bin/perl -w /usr/sbin/slimserver --prefsfile /etc/slimserver/slimserver.pref --logdir /var/log/slimserver/ --cachedir /var/cache/slimserver 110 10093 10091 0 13:03 ? 00:00:00 /usr/sbin/mysqld --defaults-file=/var/cache/slimserver/my.cnf root 10101 5330 0 13:03 pts/0 00:00:00 grep slim root@ubuntu710qavmrl:/etc/apt#
Created attachment 2797 [details] mysql-error-log
Dean / Matt, who should this be assigned to?
(In reply to comment #15) > I managed to reproduce! Here is the output as requested Fletch: :-) I guess "grep slim" is problematic if you also have a user slim. > 110 9984 1 0 12:59 ? 00:00:00 /usr/sbin/mysqld > --defaults-file=/var/cache/slimserver/my.cnf > 110 10030 1 0 12:59 ? 00:00:00 /bin/bash > /usr/sbin/slimserver_safe /usr/sbin/slimserver --prefsfile > /etc/slimserver/slimserver.pref --logdir /var/log/slimserver/ > --cachedir /var/cache/slimserver > 110 10073 1 0 13:02 ? 00:00:00 /usr/sbin/mysqld > --defaults-file=/var/cache/slimserver/my.cnf > 110 10083 1 0 13:02 ? 00:00:00 /usr/sbin/mysqld > --defaults-file=/var/cache/slimserver/my.cnf > 110 10091 10030 12 13:03 ? 00:00:01 /usr/bin/perl -w > /usr/sbin/slimserver --prefsfile /etc/slimserver/slimserver.pref > --logdir /var/log/slimserver/ --cachedir /var/cache/slimserver > 110 10093 10091 0 13:03 ? 00:00:00 /usr/sbin/mysqld > --defaults-file=/var/cache/slimserver/my.cnf > root 10101 5330 0 13:03 pts/0 00:00:00 grep slim > root@ubuntu710qavmrl:/etc/apt# > OK, this is the problem. Not only is the old mysqld instance still running, but slimserver itself is still running. It should stop itself in the prerm script. Since the old /var/log/slimserver should now be removed, I'm not sure the best way to track down why. This is different from bug 5620.
I can't seem to reproduce this issue... I did a 6.5.4 install and then upgraded to 7.0 with no problems at all. Using only the apt-get program to do the update. I'm also not seeing any other messages in the boards about this. Can anyone else reproduce it, or should we call it tentatively fixed for now?
I can't reproduce this bug right now... assuming it is no longer an issue, or was a one-time problem. Closing per dean's request.
This bug is being closed since it was resolved for a version which is now released! Please download the new version of SqueezeCenter (formerly SlimServer) at http://www.slimdevices.com/su_downloads.html If you are still seeing this bug, please re-open it and we will consider it for a future release.