Bugzilla – Bug 3848
free error; mysqld shutdown before committing db transactions
Last modified: 2011-03-16 04:34:10 UTC
SlimServer 6.5b 2006-07-30 Solaris SPARC 9 12/03 (update 5) perl v5.8.7 Note the two errors in the shutdown sequence below. This was in response to a "kill -TERM". 1. A free error, and 2. mysqld is shutdown and then there's an attempt to commit transactions to the db. 2006-07-31 11:44:01.9016 MySQLHelper: stopServer() Running shutdown. 060731 11:44:01 [Note] /usr/sbin/mysqld: Normal shutdown 060731 11:44:01 InnoDB: Starting shutdown... 060731 11:44:03 InnoDB: Shutdown completed; log sequence number 0 13866525 060731 11:44:03 [Note] /usr/sbin/mysqld: Shutdown complete * 2006-07-31 11:44:03.5253 Attempt to free unreferenced scalar: SV 0x2baaee4. * 2006-07-31 11:44:03.5265 ERROR: forceCommit: Trying to commit transactions before DB is initialized! 2006-07-31 11:44:03.5372 ERROR: DBI Connection failed: DBI connect('hostname=127.0.0.1;port=9092;database=slimserver:mysql_socket=/export/home/slimserver-beta/Cache/slimserver-mysql.sock','slimserver',...) failed: Can't connect to MySQL server on '127.0.0.1' (146) at /usr/local/src/SlimServer_v2006-07-30/CPAN/DBIx/Class/Storage/DBI.pm line 624 2006-07-31 11:44:03.5376 ERROR: Backtrace follows: 2006-07-31 11:44:03.5385 Backtrace: frame 0: Slim::Schema::Storage::throw_exception (/usr/local/src/SlimServer_v2006-07-30/CPAN/DBIx/Class/Storage/DBI.pm line 630) frame 1: DBIx::Class::Storage::DBI::_connect (/usr/local/src/SlimServer_v2006-07-30/CPAN/DBIx/Class/Storage/DBI.pm line 588) frame 2: DBIx::Class::Storage::DBI::_populate_dbh (/usr/local/src/SlimServer_v2006-07-30/Slim/Schema/Storage.pm line 32) frame 3: Slim::Schema::Storage::_populate_dbh (/usr/local/src/SlimServer_v2006-07-30/CPAN/DBIx/Class/Storage/DBI.pm line 515) frame 4: DBIx::Class::Storage::DBI::ensure_connected (/usr/local/src/SlimServer_v2006-07-30/CPAN/DBIx/Class/Storage/DBI.pm line 529) frame 5: DBIx::Class::Storage::DBI::dbh (/usr/local/src/SlimServer_v2006-07-30/Slim/Schema.pm line 191) frame 6: (eval) (/usr/local/src/SlimServer_v2006-07-30/Slim/Schema.pm line 191) frame 7: Slim::Schema::disconnect (./slimserver.pl line 1012) frame 8: main::cleanup (/usr/local/src/SlimServer_v2006-07-30/Slim/bootstrap.pm line 255) frame 9: Slim::bootstrap::sigint (/usr/local/src/SlimServer_v2006-07-30/Slim/bootstrap.pm line 286) frame 10: Slim::bootstrap::END (./slimserver.pl line 0) frame 11: (eval) (./slimserver.pl line 0)
And this bug is repeatable for you, Dan?
In reference to the db being shutdown and then a subsequent commit failing, it was repeatable on the day I reported it. By repeatable, I mean that I had done at least six, possibly more, shutdowns and that error message showed up everytime. But, in my attempt to be diligent, I just shut the server down now and it didn't happen. Difference this time is that the server has been up and running for >24 hours; whereas, the other times it was up for maybe 10 - 20 minutes at most each time. The other difference -- significant or not -- was that the day it was happening, the music library was being scanned while the shutdowns occurred. Not too sure how relevant that is, especially given that I believe the scans are down by a separate process running scanner.pl. (At the time, I was dealing with some slow, possibly stalled scans.) FWIW, what I now see in the log is 2006-08-02 18:00:59.4586 MySQLHelper: stopServer() Running shutdown. 060802 18:00:59 [Note] /usr/sbin/mysqld: Normal shutdown 060802 18:00:59 InnoDB: Starting shutdown... 060802 18:01:01 InnoDB: Shutdown completed; log sequence number 0 14421167 060802 18:01:01 [Note] /usr/sbin/mysqld: Shutdown complete 2006-08-02 18:01:01.8653 Attempt to free unreferenced scalar: SV 0x5fbef4. I've tried it twice, and no problems: once the server which had been long running and then again with one which had been up for about 45 seconds. I am, however, still seeing the "attempt to free unreferenced scalar" still which I also mentioned in the original report. Thanks for looking into this. And, FWIW, 6.5beta 2006-07-30 has been stable and running on my Solaris SPARC box since ~31 July when I fired it up.
And, for the record, running as "root" on my Solaris 9 U5 SPARC system, those unwanted permissions were indeed a result of permission defaults. That is, you're getting the default permission mask on that file as per the umask setting for the user. Here's an example below, where running as root I show the "umask" in effect -- my root's default setting -- and the result it has on a newly created file. I then change the umask and get a different set of permissions on subsequently created files. # umask 000 # mkdir /Cache # ls -ald /Cache drwxrwxrwx 2 root other 512 Aug 8 14:23 /Cache # cd /Cache # cat > a.cnf ddd # ls -al total 8 drwxrwxrwx 2 root other 512 Aug 8 14:23 . drwxr-xr-x 41 root root 1536 Aug 8 14:23 .. -rw-rw-rw- 1 root other 4 Aug 8 14:23 a.cnf # cd / # rm -rf /Cache # umask a=rx,ug+w # umask 002 # mkdir /Cache # ls -ald /Cache drwxrwxr-x 2 root other 512 Aug 8 14:28 /Cache # cd /Cache # cat > a.cnf ddd # ls -al a.cnf -rw-rw-r-- 1 root other 4 Aug 8 14:28 a.cnf
Whoops -- comment on the wrong bug...
Dan says this shouldn't be happening with newer nightlies. Can you give it a try?
I'll try it this evening with last night's nightly.
Seems to be fixed in as much as I can no longer reproduce the problem using the 16 August nightly build.