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
Triage: Triaged: D3 (Medium)

[12 Jul 2008 11:10] Mark Leith
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.
[12 Jul 2008 12:58] Giuseppe Maxia
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).
[12 Jul 2008 17:02] Shane Bester
perhaps enable this only if the user has log_warnings=2 ?
[12 Jul 2008 23:37] Peter Gulutzan
This was due to a deliberate design decision.
[13 Jul 2008 10:15] Mark Leith
The design was wrong.
[23 Jul 2008 21:51] Brian Aker
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
[24 Jul 2008 8:32] Mark Leith
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.
[8 Aug 2008 20:42] Peter Gulutzan
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.
[29 Sep 2008 14:04] Bugs System
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).
[7 Oct 2008 17:22] Bugs System
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.
[7 Oct 2008 17:39] Kristofer Pettersson
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));
[15 Oct 2008 18:49] Peter Gulutzan
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.
[22 Oct 2008 13:05] Kristofer Pettersson
queued to bugteam trees
[10 Nov 2008 10:53] Bugs System
Pushed into 6.0.8-alpha  (revid:kristofer.pettersson@sun.com-20081007172013-uk7hu00x0j8kv8q1) (version source revid:kgeorge@mysql.com-20081021085131-2v86qbmg27inufx2) (pib:5)
[10 Nov 2008 11:37] Bugs System
Pushed into 5.1.30  (revid:kristofer.pettersson@sun.com-20081007172013-uk7hu00x0j8kv8q1) (version source revid:kgeorge@mysql.com-20081021080008-9xhs5h7niqdhfz4h) (pib:5)
[11 Nov 2008 16:05] Paul Dubois
The versions are actually 5.1.31, 6.0.9.
[12 Nov 2008 0:06] Paul Dubois
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.
[19 Jan 2009 11:28] Bugs System
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)
[19 Jan 2009 13:06] Bugs System
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)
[19 Jan 2009 16:12] Bugs System
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)