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

MariaDB 10.2.11 breaks binary logging after nightly log cycle

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Duplicate
    • 10.2.11
    • 10.1.12
    • Scripts & Clients
    • None
    • FreeBSD 11.1

    Description

      After upgrading from 10.2.10 to 10.2.11, replication failed after the binary logs were cycled at 0000 in the morning. The slave processes show an error indicating that the master can not locate the new binary logs.

      show slave status\G
      		 
      ...
      		 
      Master_Log_File: mysql-bin.000611
      		 
      Read_Master_Log_Pos: 4
      		 
      Slave_IO_Running: No
      		 
      Slave_SQL_Running: Yes
      		 
      Last_IO_Errno: 1236
      		 
      Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'could not find next log; the first event 'mysql-bin.000609' at 73278354, the last event read from 'mysql-bin.000610' at 67998964, the last byte read from 'mysql-bin.000610' at 67999011.'
      		 
      Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it

      On the master server, a SHOW BINARY LOGS command only shows binary logs created before the upgrade...

      +------------------+-----------+
      		 
      | Log_name         | File_size |
      		 
      +------------------+-----------+
      		 
      | mysql-bin.000596 |  77618783 |
      		 
      | mysql-bin.000597 |  62336068 |
      		 
      | mysql-bin.000598 | 140566167 |
      		 
      | mysql-bin.000599 | 141528752 |
      		 
      | mysql-bin.000600 | 139638075 |
      		 
      | mysql-bin.000601 | 139803271 |
      		 
      | mysql-bin.000602 | 141700844 |
      		 
      | mysql-bin.000603 | 140429994 |
      		 
      | mysql-bin.000604 | 142377738 |
      		 
      | mysql-bin.000605 | 140429224 |
      		 
      | mysql-bin.000606 | 140052010 |
      		 
      | mysql-bin.000607 | 140098989 |
      		 
      | mysql-bin.000608 | 139437164 |
      		 
      | mysql-bin.000609 |  73278377 |
      		 
      | mysql-bin.000610 |  67999011 |
      		 
      +------------------+-----------+

      ...but the file system shows all binary logs.

      -rw-rw----  1 mysql  mysql   77618783 Nov 29 13:09 mysql-bin.000596
      		 
      -rw-rw----  1 mysql  mysql   62336068 Nov 30 00:00 mysql-bin.000597
      		 
      -rw-rw----  1 mysql  mysql  140566167 Dec  1 00:00 mysql-bin.000598
      		 
      -rw-rw----  1 mysql  mysql  141528752 Dec  2 00:00 mysql-bin.000599
      		 
      -rw-rw----  1 mysql  mysql  139638075 Dec  3 00:00 mysql-bin.000600
      		 
      -rw-rw----  1 mysql  mysql  139803271 Dec  4 00:00 mysql-bin.000601
      		 
      -rw-rw----  1 mysql  mysql  141700844 Dec  5 00:00 mysql-bin.000602
      		 
      -rw-rw----  1 mysql  mysql  140429994 Dec  6 00:00 mysql-bin.000603
      		 
      -rw-rw----  1 mysql  mysql  142377738 Dec  7 00:00 mysql-bin.000604
      		 
      -rw-rw----  1 mysql  mysql  140429224 Dec  8 00:00 mysql-bin.000605
      		 
      -rw-rw----  1 mysql  mysql  140052010 Dec  9 00:00 mysql-bin.000606
      		 
      -rw-rw----  1 mysql  mysql  140098989 Dec 10 00:00 mysql-bin.000607
      		 
      -rw-rw----  1 mysql  mysql  139437164 Dec 11 00:00 mysql-bin.000608
      		 
      -rw-rw----  1 mysql  mysql   73278377 Dec 11 12:09 mysql-bin.000609
      		 
      -rw-rw----  1 mysql  mysql   67999011 Dec 12 00:00 mysql-bin.000610
      		 
      -rw-rw----  1 mysql  mysql  139787598 Dec 13 00:00 mysql-bin.000611
      		 
      -rw-rw----  1 mysql  mysql   72954545 Dec 13 12:25 mysql-bin.000612
      		 
      -rw-rw----  1 mysql  mysql     765112 Dec 13 12:33 mysql-bin.000613
      		 
      -rw-rw----  1 mysql  mysql      81910 Dec 13 12:34 mysql-bin.000614
      		 
      -rw-rw----  1 mysql  mysql        358 Dec 13 12:34 mysql-bin.000615
      		 
      -rw-rw----  1 mysql  mysql       2953 Dec 13 12:34 mysql-bin.index

      In addition, running tail on the mysql-bin.index file only shows some of the binary logs created by 10.2.11 but not all of them and not any of the logs created by 10.2.10.

      ...
      		 
      Next activation : never
      		 
      ./mysql-bin.000612
      		 
      ./mysql-bin.000613
      		 
      ./mysql-bin.000614
      		 
      ./mysql-bin.000615

      Running a SHOW MASTER STATUS command on the master server does show the current log and the position is updated.

      show master status;
      		 
      +------------------+----------+--------------+------------------+
      		 
      | File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
      		 
      +------------------+----------+--------------+------------------+
      		 
      | mysql-bin.000615 |  1816938 |              |                  |
      		 
      +------------------+----------+--------------+------------------+

      It seems to me that parts of the system on the master are no longer tracking the binary logs properly.

      Attachments

        Issue Links

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. MDEV-14337 mysqld_safe may suppress error messages with --log-output=file

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-14714 mysqld writes status information on HUP signal into innodb data file, breaking it

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-14889 Server fails to start because of aria_log_control-file

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            View 6 older comments
            Elkin Andrei Elkin added a comment -

            Hi, Jason.

            It's very good of you that you managed to refine the problem description!
            If I understood it correctly your replication setup is actually circular between two servers.
            I conclude that seeing 'Slave I/O' errors in either server error logs.

            Presence of 'replicate-do-db' complicates the matter additionally.

            If I am right about the circular you can help us to help you in providing either server's:

            my.cnf, show-slave-status, full error log and the query when available; also
            the server messages to the syslog.

            As the bad things strike always at midnight I would think of the server event system that may trigger something. Could you please clear this out as well.

            Thanks and good luck!

            Andrei

            Elkin Andrei Elkin added a comment - Hi, Jason. It's very good of you that you managed to refine the problem description! If I understood it correctly your replication setup is actually circular between two servers. I conclude that seeing 'Slave I/O' errors in either server error logs. Presence of 'replicate-do-db' complicates the matter additionally. If I am right about the circular you can help us to help you in providing either server's: my.cnf, show-slave-status, full error log and the query when available; also the server messages to the syslog. As the bad things strike always at midnight I would think of the server event system that may trigger something. Could you please clear this out as well. Thanks and good luck! Andrei
            anubas Jason Stames added a comment -

            Andrei,

            I have added additional information to my previous post. Again, these exact configurations have worked without issue through quite a few 10.2.x upgrades in the past. Only the 10.2.11 upgrade has had any issue.

            anubas Jason Stames added a comment - Andrei, I have added additional information to my previous post. Again, these exact configurations have worked without issue through quite a few 10.2.x upgrades in the past. Only the 10.2.11 upgrade has had any issue.
            anubas Jason Stames added a comment - - edited

            A new version of the mariadb102-server package, mariadb102-server-10.2.11_1 was released on FreeBSD and includes a fix for MDEV-14337.

            Change log notes can be found here: https://svnweb.freebsd.org/ports/head/databases/mariadb102-server/?view=log

            I set up the development environment for another round of testing and so far, everything looks good. Manually running newsyslog, which sends a SIGHUP message to the mariadb process, does not break replication. A 'SHOW BINARY LOGS' command includes all the binary logs that I can see on the file system and at the bottom of the binary log index file. I'm going to let everything run over the weekend for good measure but the MDEV-14337 fix seems to have done the trick.

            Note to self: Link related bugs before closing.

            anubas Jason Stames added a comment - - edited A new version of the mariadb102-server package, mariadb102-server-10.2.11_1 was released on FreeBSD and includes a fix for MDEV-14337 . Change log notes can be found here: https://svnweb.freebsd.org/ports/head/databases/mariadb102-server/?view=log I set up the development environment for another round of testing and so far, everything looks good. Manually running newsyslog, which sends a SIGHUP message to the mariadb process, does not break replication. A 'SHOW BINARY LOGS' command includes all the binary logs that I can see on the file system and at the bottom of the binary log index file. I'm going to let everything run over the weekend for good measure but the MDEV-14337 fix seems to have done the trick. Note to self: Link related bugs before closing.
            serg Sergei Golubchik added a comment -

            Thanks! 10.2.12 is built and ready (but not reached all mirrors yet) and it includes the fix for MDEV-14337.

            If you confirm that the fix is working, we can close this bug as fixed in 10.2.12

            serg Sergei Golubchik added a comment - Thanks! 10.2.12 is built and ready (but not reached all mirrors yet) and it includes the fix for MDEV-14337 . If you confirm that the fix is working, we can close this bug as fixed in 10.2.12
            anubas Jason Stames added a comment -

            Issue resolution confirmed. Please close this bug.

            anubas Jason Stames added a comment - Issue resolution confirmed. Please close this bug.

            People

              serg Sergei Golubchik
              anubas Jason Stames
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.