Bug #44992 | no log file created when specified from configuration .. | ||
---|---|---|---|
Submitted: | 20 May 2009 19:24 | Modified: | 31 May 2009 11:58 |
Reporter: | Peter Laursen (Basic Quality Contributor) | Email Updates: | |
Status: | Can't repeat | Impact on me: | |
Category: | MySQL Server | Severity: | S2 (Serious) |
Version: | 5.1.34 - 64 bit | OS: | Windows (Win7 RC - 64 bit) |
Assigned to: | CPU Architecture: | Any | |
Tags: | qc |
[20 May 2009 19:24]
Peter Laursen
[20 May 2009 19:45]
Paul DuBois
I don't suppose log_output is set to NONE?
[20 May 2009 19:55]
Peter Laursen
@Paul .. I do not understand your remark! This page http://dev.mysql.com/doc/refman/5.1/en/query-log.html does not describe such "NONE" option. I believe I followed the guidelines from the documentation - added the server startup options in the configuration file! Also I have not SET any such thing anywhere. The configuration is 'fresh' from the configuration wizard.
[20 May 2009 19:57]
Peter Laursen
SHOW VARIABLES LIKE 'log_output' /* returns Variable_name Value ------------- ------ log_output FILE */
[20 May 2009 20:04]
Sveta Smirnova
Thank you for the report I believe Paul wants to know value of log_output variable. See also http://dev.mysql.com/doc/refman/5.1/en/log-tables.html
[20 May 2009 20:09]
Peter Laursen
yup .. and I think my very last post (the one before this one) already answers this! (and sorry for not getting the point immediately!)
[21 May 2009 15:04]
MySQL Verification Team
Thank you for the feedback. Please see if you get permission denied to create the file in the C:\ i.e: Microsoft Windows [Version 6.0.6002] Copyright (c) 2006 Microsoft Corporation. All rights reserved. c:\dbs>51 c:\dbs>c:\dbs\5.1\bin\mysqld --defaults-file=c:\dbs\5.1\my.ini --standalone --console 090521 11:56:10 InnoDB: Started; log sequence number 0 46409 c:\dbs\5.1\bin\mysqld: File 'c:\mylog.log' not found (Errcode: 13) 090521 11:56:10 [ERROR] Could not use c:\mylog.log for logging (error 13). Turning logging off for the whole duration of the MySQL server process. To turn it on again: fix the cause, shutdown the MySQL server and restart it. 090521 11:56:11 [Note] Event Scheduler: Loaded 0 events 090521 11:56:11 [Note] c:\dbs\5.1\bin\mysqld: ready for connections. Version: '5.1.35-Win X64 revno: 2853-log' socket: '' port: 3510 Source distribution "below after changed to general_log_file = c:\dbs\5.1\mylog.log" c:\dbs>cat 5.1\mylog.log c:\dbs\5.1\bin\mysqld, Version: 5.1.35-Win X64 revno: 2853-log (Source distribution). started with: TCP Port: 3510, Named Pipe: (null) Time Id Command Argument
[21 May 2009 15:35]
Peter Laursen
OK .. It may be after the weekend only that I get time for this (but I will try to squeeze it in tonight).
[21 May 2009 17:46]
Peter Laursen
1) -->.ini settings general_log = 1 general_log_file = c:\blah\blih\bluh\mylog.log --> command "C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld" --defaults-file="C:\Program Files\MySQL\MySQL Server 5.1\my.ini" --> mysqld starts, no log file is created in c:\blah\blih\bluh (the folder tree was cresated in advance) 2) -->.ini settings general_log = 1 general_log_file = c:\mylog.log --> command "C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld" --defaults-file="C:\Program Files\MySQL\MySQL Server 5.1\my.ini" --> mysqld starts, no log file is created in C:\ 3) -->.ini settings general_log = 1 general_log_file = c:/mylog.log --> command "C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld" --defaults-file="C:\Program Files\MySQL\MySQL Server 5.1\my.ini" --> mysqld starts, no log file is created in c:\ 4) -->.ini settings general_log = 1 general_log_file = C:\ProgramData\MySQL\MySQL Server 5.1\data --> command "C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld" --defaults-file="C:\Program Files\MySQL\MySQL Server 5.1\my.ini" --> mysqld starts, no log file is created in C:\ProgramData\MySQL\MySQL Server 5.1\data 5) now killing mysqld and 'net start mysql51' C:\>net start mysql51 System error 193 has occurred. *** is not a valid Win32 application. 6) starting command .exe again, net start mysql51' and now again '*** is not a valid Win32 application.' occurs. 7) Rebooted the machine. MySQL failed to start with the OS as it normally would! 'net start' still returns '*** is not a valid Win32 application.' 8) Installed MySQL 5.1.34 again (with MSI 'repair' option). 'net start' still returns '*** is not a valid Win32 application.' 9) Ran 'system restore' using a restore point from before these experiments. 'net start' still returns '*** is not a valid Win32 application.' 10) Uninstalled MySQL. a 'mysqld' file of ZERO-size was left behind by the installer and the service we not removed from the system. After install MySQL refused to start with the same error. 11) Only after removing every trace of the service from the registry and rebooting I was able to install and start MySQL again using same service name. So in addition to the failure to create logs I experienced problems withuninstall. Maybe because of a Win7 issue, a 64-bit issue or a file or registry corruption happening during this experiment!
[21 May 2009 17:47]
Peter Laursen
uninstaller failed to remove the service
Attachment: uninstall_fail.jpg (image/jpeg, text), 74.28 KiB.
[21 May 2009 17:48]
Peter Laursen
also uninstalling service from MA tray applet fails
Attachment: service issue.jpg (image/jpeg, text), 40.69 KiB.
[21 May 2009 18:15]
Peter Laursen
I well add a few screenshots ...
[21 May 2009 18:15]
Peter Laursen
log setttings in my.ini
Attachment: inisettings.jpg (image/jpeg, text), 10.86 KiB.
[21 May 2009 18:16]
Peter Laursen
mysql is running started from console (verified in task manager)
Attachment: mysqlrunning.jpg (image/jpeg, text), 47.78 KiB.
[21 May 2009 18:17]
Peter Laursen
no files in folder specified for logging
Attachment: blahblihbluhempty.jpg (image/jpeg, text), 39.03 KiB.
[21 May 2009 21:24]
Peter Laursen
However this console command "C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld" --defaults-file="C:\Program Files\MySQL\MySQL Server 5.1\my.ini" --general_log=1 --general_log_file=c:\mylog.log causes the server to create the logfile c:\mylog.log on startup. I also tried (thinking that coud be the issue) stripping spaces in my.ini like general_log=1 general_log_file=c:\mylog.log (as opposed to as before general_log = 1 general_log_file = c:\mylog.log) .. still starting server that does not create the log file (no matter if started as a service or from command line). Specifying log file parameters from command line creates the log - specifying in configuration does not (at least on my system)!
[23 May 2009 18:50]
Peter Laursen
I created another report about the uninstaller problem here: http://bugs.mysql.com/bug.php?id=45050 The corruption of the server binary I experienced is not reproducable! So here let us concentrate on the the faailure of the server to create the logfile if details are specified in configuration file!
[26 May 2009 7:47]
Tonci Grgin
C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld, Version: 5.1.34-community-log (MySQL Community Server (GPL)). started with: TCP Port: 3306, Named Pipe: (null) Time Id Command Argument 090526 9:40:30 1 Connect root@localhost on 1 Query select @@version_comment limit 1 090526 9:40:39 1 Query show databases 090526 9:40:43 1 Query SELECT DATABASE() 1 Init DB mysql 090526 9:40:47 1 Query show tables 090526 9:40:49 1 Quit [mysqld] # The TCP/IP Port the MySQL Server will listen on port=3306 general_log = 1 general_log_file = "C:/Test/mylog.log" Everything works as expected on my Windows 7 32bit (build 7000) VM. By default, normal user can not write to either "Program Files" nor to C:. As a matter of fact it can only write to folders that he/she made themselves or system folders, such as "My Documents", belonging to them. 7 is still beta and, till at least SP1, I would not be all that troubled with stupid things happening. For example, my perfectly working copy wants to be re-registered right now. Sorry, got to run to MSDN fetch me some more 7 keys...
[26 May 2009 7:57]
Peter Laursen
Win7 is not *BETA*. It is *RC*! Final is expected in August (though not an official Microsoft announcement). For me log file gets created in both c:\blah\blih\bluh and c:\ when I specify it from command line (with the new command syntax introduced in 5.1.29) and not when specified in configuration. Besides when server runs as a *SERVICE* it has administrator access to file system. I accept of course that Tonci cannot repeat - but I did expect testing with 64 bit and also some code review with the new command syntax. In my opinion you are repeating the same mistake as you did when Vista was introduced - not using the RC period to solve issues - and it will take 6-12 months after FINAL release before it works smoothly!
[26 May 2009 8:33]
Tonci Grgin
Peter, > Win7 is not *BETA*. It is *RC*! Final is expected in August (though not an official Microsoft announcement). What good is it to me or you when we both know it'll become usable somewhere around or after SP1 as every other MS OS? > For me log file gets created in both c:\blah\blih\bluh and c:\ when I specify it from command line (with the new command syntax introduced in 5.1.29) and not when specified in configuration. I can not repeat this problem using exact lines you posted... However, my config and log file are placed in folder that does not require administrative privileges. > Besides when server runs as a *SERVICE* it has administrator access to file system. True, but I do not see the relevance as I think this is a bug/misbehavior in 7 and not in MySQL server. > I accept of course that Tonci cannot repeat - but I did expect testing with 64 bit and also some code review with the new command syntax. Testing different architecture on, basically, same OS doesn't make much sense. Now, if our installer was to use some stuff differentiated by OS on the basis of architecture (like for example c/ODBC does) I would have tested. > In my opinion you are repeating the same mistake as you did when Vista was introduced - not using the RC period to solve issues - and it will take 6-12 months after FINAL release before it works smoothly! Could be thus I'll ask Iggy to take a second look.
[26 May 2009 13:45]
Tonci Grgin
Ok, after reviewing the report here's what we've come up with: o It is important to understand the changes that UAC has caused. o Installing the product using the MSI is a "system wide" install but you then try to start it as a user. This does not make sense. You would be better off using the -noinstall zip. It might be it will work the way you want. Basically, if you do this on Vista you won't be able to start the service unless you open the command prompt as an Administrator. o Even if Win 7 is RC1, we haven't added it to the roadmap yet. We will take the bugs with thanks but won't guarantee to fix them until we add Win 7 to our supported platforms. o What you're actually suggesting, as I see it, is for us to provide a "per-user" install option. This would be a good improvement. Is it so?
[26 May 2009 14:02]
Peter Laursen
Either I do not understand you or opposite. I want (always did) to install *as a service* (I only did the command line exercise because Miguel asked med to). That means that the service shall be available, even if no user is logged on (this is my *core understanding* of a Windows service). That is what the MSI+config wizard does. It works fine. But the (as of 5.1.29 new) options to specify the log do not work for me when specified in configuration. I have no indication that this is related to UAC at all (but do not exclude the possibility either). On this Win7 system the UAC settting is 'level 2 from bottom' (Win7 introduces a 4-level UAC setting opposite to Vista that has a 2-level (ON|OFF) only. I can try 'level 1 from bottom' what should be same as OFF if you want! (and besides I think (but beyood my expertise) in addition to using a command (text-based) interface building the server with the Windows API was another option - but I know I should not expect ti either!)
[26 May 2009 14:26]
Tonci Grgin
Maybe you're right... So far, all I can say is: "As service" means run as "SYSTEM", not "Administrator". There should be an error in Event log on your system though. I can't check as my perfectly legal Win7 turned on me asking for genuine notification, reactivation and all sorts of crap preventing me from accessing Control Panel items. So, can you please check if there is an entry in your event log describing the fact that log file could not be written to? If there is none, than that's the bug. I am also waiting on Reggie's opinion.
[26 May 2009 19:23]
Peter Laursen
I attach the error log
Attachment: Peter-PC.zip (application/zip, text), 3.36 KiB.
[26 May 2009 19:27]
Peter Laursen
this is suspicious "090521 23:20:35 InnoDB: Operating system error number 32 in a file operation. InnoDB: The error means that another program is using InnoDB's files. InnoDB: This might be a backup or antivirus software or another instance InnoDB: of MySQL. Please close it to get rid of this error." .. but I am not able to understand how such error could be recorded as an InnoDB error. But there is a long series of such records from a time that could be (but I am not sure) when I experimented with the log settings. I will try to turn UAC down to lowest possisble level as soon as I get time.
[26 May 2009 20:02]
Peter Laursen
Good catch Tonci! Turning UAC to lowest possible issue resolved this. I should have thought about it! This is *at least* a documentation issue - but I believe more than that!
[26 May 2009 20:03]
Peter Laursen
UAC settings in Win7
Attachment: uac.jpg (image/jpeg, text), 62.00 KiB.
[26 May 2009 20:04]
Peter Laursen
now file gets created
Attachment: yes.jpg (image/jpeg, text), 89.31 KiB.
[26 May 2009 21:22]
Peter Laursen
This is *not* a documentation issue. It is a bug! The server can create the error log without problem - also with UAC on. There is no reason why it should not then create the general log (and what about the slow log and the binary log?). I think Tonci gave a hint in a previous reply: On Windows file system operations by a service should be performed as a SYSTEM user and not as an ADMIN user!
[26 May 2009 21:42]
Peter Laursen
Please change status to 'Open' (at least).
[27 May 2009 7:06]
Tonci Grgin
Peter, I will not reopen the report for now as I really can't repeat the problem. However, as I said earlier, I'm still waiting on input from Reggie, meaning we're still monitoring the report regardless of the status.
[27 May 2009 17:40]
Vladislav Vaintroub
I tried to reproduce the error on my Win7 RC x64. with following lines in the .ini file log-output=FILE general_log=1 general_log_file=C:/bzr/mysqld.log It works just fine. If i change the value of the general_log_file to C:/mysqld.log it does not work without elevation and works fine with elevation. creating files in C:\ requires elevation. So far nothing Win7 specific. That database created with installer cannot be started without elevation (Peter has also run into this problem too) if IMO unfortunate but it is a known bug, which is tracked under Bug#38373.
[27 May 2009 18:53]
Peter Laursen
If this " ..that database created with installer cannot be started without elevation (Peter has also run into this problem too)" refer to something I have reported wihth Vista (I am not able to identify the exact report from this), I should make it clear that on Vista I always had UAC *OFF*. (I cannot live with the 'VirtualStore' 'per-user shadow folder' created with *ON*. This folder does not get created with the AUC setting I have used with Win7)
[27 May 2009 19:14]
Peter Laursen
I tried again with UAC set to '2nd lowest level' log-output=FILE general_log=1 general_log_file=C:\bzr\mysqld.log and log-output=FILE general_log=1 general_log_file=C:/bzr/mysqld.log ..(bzr folder was created in advance) and no file is created! :-) (if you can't smile in real world a few smileys might help! ;-) ) Error log only has recorded completely normal start/stop occurances like this 090527 21:03:17 [Note] Event Scheduler: Purging the queue. 0 events 090527 21:03:17 InnoDB: Starting shutdown... 090527 21:03:18 InnoDB: Shutdown completed; log sequence number 0 206679 090527 21:03:18 [Warning] Forcing shutdown of 1 plugins 090527 21:03:18 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: Shutdown complete I have no clue why it happens for me if not for you. Are you using the 5.1.34 64 bit server for Windows?
[27 May 2009 19:23]
Peter Laursen
I also noticed that this datadir=C:\bzr and datadir=C:/bzr .. is ignored! There is no valid MySQL data folder there but the server starts anyway!
[27 May 2009 19:26]
Peter Laursen
and redundant/conflicting specs raises no error and server starts (dont know if this is expected) log-output=FILE general_log=0 general_log=1 general_log_file=C:\bzr\mysqld.log general_log_file=C:\bzr\mysqld_more.log
[27 May 2009 19:35]
Peter Laursen
all those (that are not file system related) work fine: default-character-set=utf8 default-storage-engine=INNODB sql-mode="STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION"
[29 May 2009 9:35]
Vladislav Vaintroub
log-output=FILE general_log=1 general_log_file=C:/bzr/mysqld.log This worked on my computer, with no redundant conflicting settings, with already existing C:\bzr directory. I deliberately used forward slashes, backslash deso not work in this case, \b in the middle of the string is translated to escape sequence. What is wrong on your system I do not know. I think it could make sense to download procmon and look if mysqld at least tries to open the general_log_file. If not, I'd tend to blame other settings, possibly conflicting. SHOW VARIABLES LIKE '%log%' could sched some light into this.
[29 May 2009 9:53]
Peter Laursen
I don't know either why it is so consistently reproducable for me when not for you! One day probably the reason will be known or the problem will disappear with a OS or server reinstall or update. But I will try the advices. May take some days however. I have UAC 'on' on Win7 for the reason only that our own programs should be tested with that before Win7 final release. If not for that I would probably not use it at all (though the feature is much less annoying on Win7 than on Vista). What I am missing however is a clear statement from MySQL people writing here that they are using a 64 bit server running on a 64 bit Windows OS supporting UAC (Vista, Win2008, Win7) with UAC not totally turned off.
[29 May 2009 20:33]
Vladislav Vaintroub
Peter, In reply to : "What I am missing however is a clear statement from MySQL people writing here that they are using a 64 bit server running on a 64 bit Windows OS supporting UAC (Vista, Win2008, Win7) with UAC not totally turned off." I'm using Win7 x64 and run mysqld.exe built for x64 with UAC not totally turned off. I have tweaked UAC and set it to "do not dim my desktop". I'm also using Win2008 x64 and Win2008 R2 x64 and build and run x64 mysqld.exe. I used to run Vista x64 and prior to that I used XP x64 and Win2003 x64. And almost always have built and ran x64 mysqld.exe ;)
[29 May 2009 20:41]
Vladislav Vaintroub
However, for completeness I have to add I never used mysqld.exe on 64 bit Itanium Windows boxes - we do not have any here. AFAIK it won't even compile there.
[29 May 2009 21:06]
Peter Laursen
hehe .. wonderfull :-) FYI: We just experienced a problem what I think may be similar problem with our (SQLyog) program. You can refer to: http://www.webyog.com/blog/2009/05/29/sqlyog-81-rc3-has-been-released/ "If a file named ’sja’ or ’sja.exe’ existed in SQLyog ‘AppData’ folder, SJA failed to connect with SSH tunnel. A user reported that such ’shadow copy’ was created periodically. Issue is not fully understood (except that Windows looked for PLINK too in ‘AppData’) but the fix works!" Just as (with MySQL) my.ini is 'chained' or 'referred' from mysqld.exe, (wiht SQLyog) plink.exe is 'chained' or 'referred' from sja.exe. I found a 'mysqld' file in AppData that I defintely did not create. After deleting it it comes back to existence after some time. How it came there I do not know. Maybe some 'interaction' between UAC and third-party security software (I am using AVG). But my guess is that my.ini is (more or less) bypassed due to this weird 'mysqld' file + bugs in UAC + possible bugs in other softwares. I accept that there must be some system-specific issue here. But the Windows installation is fresh, the server installation is fresh too, the server config is created with the config wizard with no modification except for raising 'max-allowed-packet'. So sooner or later somebody else will get this problem I belive. I will try the proposals in previous reply, try to remove AVG and whathever I can think of! But time is sparse so it may take some days. "Can't repeat" is the correct classification with the current state of this report.
[29 May 2009 21:07]
Peter Laursen
'mysqld' file in 'AppData' - created several times. No clue why or how!
Attachment: mysqld.jpg (image/jpeg, text), 99.80 KiB.
[29 May 2009 21:08]
Peter Laursen
Correction. In this case file was not in 'AppData' by in my home/personal folder.
[29 May 2009 21:43]
Vladislav Vaintroub
I definitely never experienced an empty mysqld file, so I can't tell... Looks weird. But as I said, downloading procmon, setting up filter (process name = mysqld.exe) and looking what mysqld.exe is doing on startup can already tell a lot: if the correct my.ini was opened and whether correct log file was opened (or at least if there was an unsuccessful open attempt). If there was no attempt to open the file, 'show variables like '%log%' could reveal that general_log is off. Then you might switch the log on and with "set global general_log=1" see if queries afterwards are logged to the correct general_log_file. I myself had a situation that general log that was switched off. The reason was that I had general_log=ON in the my.ini file. Changing this to general_log=1 solved this problem. I have to admit I not to research further why ON did not work, I do not even know if it is supposed to;)
[31 May 2009 11:08]
Peter Laursen
It is crazy .. now it works. File id created and ProcMon reports every file system operation to the log folder as SUCCESS :-( No clue! Let us see what happens!
[31 May 2009 11:58]
Peter Laursen
also see: http://bugs.mysql.com/bug.php?id=45216
[1 Jun 2009 6:55]
Sveta Smirnova
Bug #45216 was marked as duplicate of this one.