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:
None 
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
Description:
http://dev.mysql.com/doc/refman/5.1/en/query-log.html;

"As of MySQL 5.1.29, --log and -l are deprecated: Use --general_log to enable the general query log, and optionally --general_log_file=file_name to specify a log file name. --general_log takes an optional argument of 1 or 0 to enable or disable the log."

I tried both inserting (in the [mysqld] section of my.ini)

general_log = 1

and 

general_log = 1
general_log_file = c:\mylog.log

.. restarted server and executed a few trivial queries.  I do not find any log file created (in /datadir and c:\ respectively) with either.

Also after "SET GLOBAL general_log = 'ON';" and excuting a few statements I do not find any log file. 

Additionally "SELECT VERSION();" returns "5.1.34-community" (*not* ... 'log')

How to repeat:
See above.

additionally an excerpt from the .ini (a rather trivial one created by the config wizard): 

[mysqld]

general_log = 1
general_log_file = c:\mylog.log -- NOTE: I tried both with and without this

# The TCP/IP Port the MySQL Server will listen on
port=3306

#Path to installation directory. All paths are usually resolved relative to this.
basedir="C:/Program Files/MySQL/MySQL Server 5.1/"

#Path to the database root
datadir="C:/ProgramData/MySQL/MySQL Server 5.1/Data/"

.. etc

Suggested fix:
I did this exercise in order to reply to a question asked to me in another report I posted.  I am not able to answer this question as I cannot get any log file from where I need to get the information!
[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.