Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-7484

Log Time not consistent with InnoDB errors nor with MySQL error log time format

        Details

          Description

          After troubleshooting various InnoDB errors, we noticed there was a difference in the log time formats for the InnoDB errors versus the normal error log entries.

          Here are 2 examples:

          150114 16:12:31 [Note] InnoDB: Initializing buffer pool, size = 512.0M
150114 16:12:31 [Note] InnoDB: Completed initialization of buffer pool
150114 16:12:31 [Note] InnoDB: Highest supported file format is Barracuda.
150114 16:12:32 [Note] InnoDB: 128 rollback segment(s) are active.
150114 16:12:32 [Note] InnoDB: Waiting for purge to start
150114 16:12:32 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-70.0 started; log sequence number 8733880113
2015-01-14 16:12:32 7f552c9f8700 InnoDB: Loading buffer pool(s) from .//ib_buffer_pool
2015-01-14 16:12:32 7f552c9f8700 InnoDB: Cannot open './/ib_buffer_pool' for reading: No such file or directory
150114 16:12:32 [Note] Plugin 'FEEDBACK' is disabled.
150114 16:12:32 [ERROR] Failed to create a socket for IPv6 '::': errno: 97.
150114 16:12:32 [Note] Server socket created on IP: '0.0.0.0'.
150114 16:12:32 [Note] Event Scheduler: Loaded 0 events
150114 16:12:32 [Note] /usr/sbin/mysqld: ready for connections.

          150115 19:05:14 [Note] InnoDB: Completed initialization of buffer pool
150115 19:05:14 [Note] InnoDB: Highest supported file format is Barracuda.
2015-01-15 19:05:15 468c  InnoDB: Operating system error number 2 in a file operation.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
150115 19:05:15 [ERROR] InnoDB: Could not find a valid tablespace file for 'test/t'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
150115 19:05:15 [ERROR] InnoDB: Tablespace open failed for '"test"."t"', ignored.
150115 19:05:15 [Note] InnoDB: 128 rollback segment(s) are active.
150115 19:05:15 [Note] InnoDB: Waiting for purge to start

          Long story short, we basically have "2015-01-15 19:05:15" versus "150115 19:05:15".

          The former appears to be what should be correct. This will make reading the error log more consistent, more readable, and in line with how MySQL performs this, as of 5.6.8 or 5.6.9 (and how InnoDB internal errors were already handled). Being consistent will be better for error log parsers as well.

          What needs to change in order to fix this are 2 lines in "sql/log.cc", in function "print_buffer_to_file()", lines 7954 and 7955.

          One needs to replace this:

          fprintf(stderr, "%02d%02d%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
        start->tm_year % 100,

          With:

          fprintf(stderr, "%d-%02d-%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
        start->tm_year + 1900,

          I would like for this to be my first MariaDB patch/code contribution, if accepted, and if possible!

          However, I'm not sure what steps I need to take from here.

          Here is my diff:

          Here is DIFF output:

          c:\mysql\mariadb-10.0.15\sql>diff log.cc log.cc.orig.cc
7954,7955c7954,7955
<   fprintf(stderr, "%d-%02d-%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
<                 start->tm_year + 1900,
---
>   fprintf(stderr, "%02d%02d%02d %2d:%02d:%02d [%s] %.*s%.*s\n",
>           start->tm_year % 100,

          Btw, I also re-compiled MariaDB and tested, and it works great:

          2015-01-16 22:53:24 [Note] Plugin 'FEEDBACK' is disabled.
2015-01-16 22:53:24 [Note] Server socket created on IP: '::'.
2015-01-16 22:53:24 [Note] Event Scheduler: Loaded 0 events
2015-01-16 22:53:24 [Note] mysqld: ready for connections.

          Please advise what I need to do in order to have this be my first contribution.

            Gliffy Diagrams

              Attachments

                Activity

                Ascending order - Click to sort in descending order
                8 older comments
                Hide
                Permalink
                danblack Daniel Black added a comment -

                From the comments of Jan ( https://github.com/MariaDB/server/pull/26#issuecomment-78431087 )

                Perhaps the following could be cherry-picked in:

                https://github.com/openquery/mariadb-server/commit/f7aad0b1156ce32995175fb7bb21b3fa00ab4fbd

                https://github.com/MariaDB/server/pull/26/files#diff-00fad7ccb1419e6cb1f05e3db6e76f06R126

                https://github.com/openquery/mariadb-server/commit/f7aad0b1156ce32995175fb7bb21b3fa00ab4fbd

                Show
                danblack Daniel Black added a comment - From the comments of Jan ( https://github.com/MariaDB/server/pull/26#issuecomment-78431087 ) Perhaps the following could be cherry-picked in: https://github.com/openquery/mariadb-server/commit/f7aad0b1156ce32995175fb7bb21b3fa00ab4fbd https://github.com/MariaDB/server/pull/26/files#diff-00fad7ccb1419e6cb1f05e3db6e76f06R126 https://github.com/openquery/mariadb-server/commit/f7aad0b1156ce32995175fb7bb21b3fa00ab4fbd
                Hide
                Permalink
                serg Sergei Golubchik added a comment - - edited

                I agree with Daniel Black about removing second timestamp.

                I don't like having a pid in the log, I cannot see what useful purpose it can serve. Having thread id is better. Or neither.

                I think it's ok to fix innodb to use YYYY-MM-DD and to remove the second timestamp, but I wouldn't add a new column (pid or thread id) to the log in a GA release.

                Perhaps it'd be safer to do all changes to log formats only in 10.1

                Show
                serg Sergei Golubchik added a comment - - edited I agree with Daniel Black about removing second timestamp. I don't like having a pid in the log, I cannot see what useful purpose it can serve. Having thread id is better. Or neither. I think it's ok to fix innodb to use YYYY-MM-DD and to remove the second timestamp, but I wouldn't add a new column (pid or thread id) to the log in a GA release. Perhaps it'd be safer to do all changes to log formats only in 10.1
                Hide
                Permalink
                jplindst Jan Lindström added a comment -

                Decided to do all changes to log formats only in 10.1

                Show
                jplindst Jan Lindström added a comment - Decided to do all changes to log formats only in 10.1
                Hide
                Permalink
                jplindst Jan Lindström added a comment -

                http://lists.askmonty.org/pipermail/commits/2015-May/007942.html

                Show
                jplindst Jan Lindström added a comment - http://lists.askmonty.org/pipermail/commits/2015-May/007942.html
                Hide
                Permalink
                jplindst Jan Lindström added a comment -

                commit 59815a268b37a9859c31d6add4546f4c6a7ef6aa
                Author: Jan Lindström <jan.lindstrom@mariadb.com>
                Date: Fri May 22 08:24:59 2015 +0300

                MDEV-7484: Log Time not consistent with InnoDB errors nor with MySQL error log time format

                Show
                jplindst Jan Lindström added a comment - commit 59815a268b37a9859c31d6add4546f4c6a7ef6aa Author: Jan Lindström <jan.lindstrom@mariadb.com> Date: Fri May 22 08:24:59 2015 +0300 MDEV-7484 : Log Time not consistent with InnoDB errors nor with MySQL error log time format

                  People

                  • Assignee:
                    jplindst Jan Lindström
                    Reporter:
                    ccalender Chris Calender
                  • Votes:
                    1 Vote for this issue
                    Watchers:
                    7 Start watching this issue

                    Dates

                    • Created:
                      Updated:
                      Resolved:

                      Time Tracking

                      Estimated:
                      Original Estimate - Not Specified
                      Not Specified
                      Remaining:
                      Remaining Estimate - 0 minutes
                      0m
                      Logged:
                      Time Spent - 30 minutes
                      30m