MySQL Bugs: #38066: Events log 'note' level messages by default in the error log

Bug #38066	Events log 'note' level messages by default in the error log
Submitted:	12 Jul 2008 11:10	Modified:	12 Nov 2008 0:06
Reporter:	Mark Leith	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S2 (Serious)
Version:	5.1.26	OS:	Any
Assigned to:	Kristofer Pettersson	CPU Architecture:	Any

Description:
The event scheduler logs 'note' level messages in the error log by default (even without setting log-warnings=2 for instance). 

080712 10:48:44 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] executed successfully in thread 47333.
080712 11:03:29 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] started in thread 47335.
080712 11:03:43 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] executed successfully in thread 47335.
080712 11:18:29 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] started in thread 47336.
080712 11:18:38 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] executed successfully in thread 47336.
080712 11:33:29 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] started in thread 47337.
080712 11:33:42 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] executed successfully in thread 47337.
080712 11:48:29 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] started in thread 47338.
080712 11:48:40 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] executed successfully in thread 47338.
080712 12:03:29 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] started in thread 47340.
080712 12:03:48 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] executed successfully in thread 47340.
080712 12:18:29 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] started in thread 47341.
080712 12:18:38 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] executed successfully in thread 47341.
080712 12:33:29 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] started in thread 47342.
080712 12:33:44 [Note] Event Scheduler: [root@localhost].[empdata.update_support_employees] executed successfully in thread 47342.

They are logged every time the event fires, so if you create an events with low intervals, and/or you have more than one events scheduled reguilarly, the error log will grow needlessly, be hard to search and will take a lot more disk space than is necessary.

How to repeat:
o turn on the event scheduler
o create an event to run every 1 minute
o monitor the error log

Suggested fix:
Do not log 'note' level messages in the error log by default, either log these messages when 'log-warnings=2', or add a new variable - log-notes - which should be set to 1 for these kinds of messages.

How to repeat.

(1)
start the server with "event-scheduler=1"

(2)
for E in `seq 1 1000` ; do \
  mysql test -e "create event e$E on schedule every 1 second do set @a =1" ;\
done

(3)
Wait one hour. The error log is now more than 700MB

(4)
Crash the server
prepare q from 'select 1 from dual where @@server_id'; 
execute q;
# thanks to Bug#32124

(5)
Look at the error log. Try to find the crashing info.

*** THIS IS NOT A FEATURE REQUEST ***
Logging the events to the error log seriously impairs usability and troubleshooting (think of MySQL Support Team work, for example).

perhaps enable this only if the user has log_warnings=2 ?

This was due to a deliberate design decision.

The design was wrong.

Hi!

A decision that was made two years ago might no longer be relevant under the current state of the server (and the current state of messages). 

I am not going to tell you what to do, but I would suggest keeping an open mind as to what should be done today.

Cheers,
  -Brian

Given Brian's comments, I am actually going to set this back to being a bug again - given the push back from internal (and now external) people. 

I am still advocating adding the successful execution messages to log-warnings > 1.

It's accepted that this is a bug.
The suggested fix for this bug is:
MySQL will not log event handling start/stop (this is a change).
MySQL will log only unsuccessful statements (statements
which end with an error) ('end' means 'end of event's
entire sql_statement' which may be compound) (this is a change).
MySQL will pay no attention to log_warnings (as before).
MySQL will pay no attention to any global or per-event parm (as before).
Turning off logging is not possible (as before).
The effect of the change is that messages like
080805 11:14:51 [Note] Event Scheduler: ... started in thread ...
080805 11:14:51 [Note] Event Scheduler: ... executed successfully ...
will not go to the error log.
Sergei Golubchik suggested the fix as above.
Andrey Hristov had no opinion. Peter Gulutzan applauded.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/54661

2745 Kristofer Pettersson	2008-09-29
      Bug#38066 Events log 'note' level messages by default in the error log
      
      The event scheduler logged start-, stop-execution messages in the error log
      on lowest log-warning level which would lead to very large log files in 
      a short time.
      
      This patch changes this behavior so that these messages only are logged if
      the log-warning level is high enough (>1).

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/55620

2758 Kristofer Pettersson	2008-10-07
      Bug#38066 Events log 'note' level messages by default in the error log
            
      The event scheduler logged start-, stop-execution messages in the error log
      on lowest log-warning level which would lead to very large log files in 
      a short time.
          
      This patch changes this behavior so that no start-/stop-messages are logged.
      Log messages stating successful execution are also removed.

failed miserably to combine change set comments with actual change set with committing from OpenSolaris for unknown reason. Here is the diff to the above change set:

=== modified file 'sql/event_scheduler.cc'
--- sql/event_scheduler.cc	2007-11-14 11:25:43 +0000
+++ sql/event_scheduler.cc	2008-10-07 17:20:13 +0000
@@ -301,12 +301,6 @@
     goto end;
   }
 
-  sql_print_information("Event Scheduler: "
-                        "[%s].[%s.%s] started in thread %lu.",
-                        job_data.definer.str,
-                        job_data.dbname.str, job_data.name.str,
-                        thd->thread_id);
-
   thd->enable_slow_log= TRUE;
 
   res= job_data.execute(thd, event->dropped);
@@ -318,13 +312,6 @@
                           "[%s].[%s.%s] event execution failed.",
                           job_data.definer.str,
                           job_data.dbname.str, job_data.name.str);
-  else
-    sql_print_information("Event Scheduler: "
-                          "[%s].[%s.%s] executed successfully in thread %lu.",
-                          job_data.definer.str,
-                          job_data.dbname.str, job_data.name.str,
-                          thd->thread_id);
-
 end:
   DBUG_PRINT("info", ("Done with Event %s.%s", event->dbname.str,
              event->name.str));

The following is an amendment of the comment of 2008-08-08.
The differences are:
(a) removal of "MySQL will not log event handling start/stop"
(b) changing "error" to "error or warning"

It's accepted that this is a bug.
The suggested fix for this bug is:
MySQL will log only unsuccessful or require-explanation statements (statements
which end with an error or warning) ('end' means 'end of event's
entire sql_statement' which may be compound) (this is a change).
MySQL will pay no attention to log_warnings (as before).
MySQL will pay no attention to any global or per-event parm (as before).
Turning off logging is not possible (as before).
The effect of the change is that messages like
080805 11:14:51 [Note] Event Scheduler: ... started in thread ...
080805 11:14:51 [Note] Event Scheduler: ... executed successfully ...
will not go to the error log.
Sergei Golubchik suggested the fix as above.
Andrey Hristov had no opinion. Peter Gulutzan applauded.

queued to bugteam trees

Pushed into 6.0.8-alpha  (revid:kristofer.pettersson@sun.com-20081007172013-uk7hu00x0j8kv8q1) (version source revid:kgeorge@mysql.com-20081021085131-2v86qbmg27inufx2) (pib:5)

Pushed into 5.1.30  (revid:kristofer.pettersson@sun.com-20081007172013-uk7hu00x0j8kv8q1) (version source revid:kgeorge@mysql.com-20081021080008-9xhs5h7niqdhfz4h) (pib:5)

The versions are actually 5.1.31, 6.0.9.

Noted in 5.1.31, 6.0.9 changelogs.

The Event Scheduler no longer logs started in thread or executed
successfully messages to the error log.

Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090108105244-8opp3i85jw0uj5ib) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)

Pushed into 5.1.31-ndb-6.3.21 (revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (version source revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)

Pushed into 5.1.31-ndb-6.4.1 (revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (version source revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)