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

wsrep_debug only logs DDL information on originating node

Details

    Description

      When wsrep_debug is enabled, Galera Cluster logs more verbose information to the error log.

      For example, when DDL is executed on a particular node, the node logs some information like this:

      160222 15:30:44 [Note] WSREP: TO BEGIN: -1, 0 : ALTER ONLINE TABLE test_table DROP KEY str
      160222 15:30:44 [Note] WSREP: TO BEGIN: 1100033, 2
      160222 15:30:44 [Note] WSREP: TO END: 1100033, 2 : ALTER ONLINE TABLE test_table DROP KEY str
      160222 15:30:44 [Note] WSREP: Set WSREPXid for InnoDB:  fbeb045d-b94f-11e5-8504-4ae80b892690:1100033
      160222 15:30:44 [Note] WSREP: TO END: 1100033, update seqno
      160222 15:30:44 [Note] WSREP: TO END: 1100033

      However, when wsrep_OSU_method is set to TOI and the DDL command is replicated to the other nodes in the cluster, those other nodes do not log anything about the DDL to their error logs, even if wsrep_debug is enabled on those other nodes.

      It would be useful to see some kind of information in the error logs about replicated DDL when wsrep_debug is ON. The main use case is when trying to track exactly what DDL is being replicated to other nodes.

      Attachments

        There are no Sub-Tasks for this issue.

        Activity

          GeoffMontee Even though DDLs, replicated under TOI, show up in the error log, they
          are received on the other nodes just like any other update. So, IIUC, there is no trivial way
          to distinguish them from other updates. Said that, they are always logged in general log
          (if enabled). Wouldn't that be sufficient for your use case?

          nirbhay_c Nirbhay Choubey (Inactive) added a comment - GeoffMontee Even though DDLs, replicated under TOI, show up in the error log, they are received on the other nodes just like any other update. So, IIUC, there is no trivial way to distinguish them from other updates. Said that, they are always logged in general log (if enabled). Wouldn't that be sufficient for your use case?

          Hi nirbhay_c,

          I was hoping the logs would have some Galera-specific information that the general log doesn't contain, such as the server that sent the DDL.

          The problem that I am debugging is that a user's cluster seems to be executing DDL statements twice. I can see the duplicate DDL statements in SHOW ENGINE INNODB STATUS and SHOW FULL PROCESSLIST, so the general log would only confirm what I already know: that the statements are being executed twice.

          What I was actually hoping for was a way to determine where the duplicate DDL statements are coming from. For example, maybe log entries like this:

          For DDL executed locally:

          160222 15:30:44 [Note] WSREP: DDL executed locally: ALTER ONLINE TABLE test_table DROP KEY str
          160222 15:30:44 [Note] WSREP: TO BEGIN: -1, 0 : ALTER ONLINE TABLE test_table DROP KEY str
          160222 15:30:44 [Note] WSREP: TO BEGIN: 1100033, 2
          160222 15:30:44 [Note] WSREP: TO END: 1100033, 2 : ALTER ONLINE TABLE test_table DROP KEY str
          160222 15:30:44 [Note] WSREP: Set WSREPXid for InnoDB:  fbeb045d-b94f-11e5-8504-4ae80b892690:1100033
          160222 15:30:44 [Note] WSREP: TO END: 1100033, update seqno
          160222 15:30:44 [Note] WSREP: TO END: 1100033

          For DDL received from another node:

           
          160222 15:30:44 [Note] WSREP: DDL received from node1: ALTER ONLINE TABLE test_table DROP KEY str
          160222 15:30:44 [Note] WSREP: TO BEGIN: -1, 0 : ALTER ONLINE TABLE test_table DROP KEY str
          160222 15:30:44 [Note] WSREP: TO BEGIN: 1100033, 2
          160222 15:30:44 [Note] WSREP: TO END: 1100033, 2 : ALTER ONLINE TABLE test_table DROP KEY str
          160222 15:30:44 [Note] WSREP: Set WSREPXid for InnoDB:  fbeb045d-b94f-11e5-8504-4ae80b892690:1100033
          160222 15:30:44 [Note] WSREP: TO END: 1100033, update seqno
          160222 15:30:44 [Note] WSREP: TO END: 1100033

          Maybe I can find the information that I need in the binary log instead.

          GeoffMontee Geoff Montee (Inactive) added a comment - Hi nirbhay_c , I was hoping the logs would have some Galera-specific information that the general log doesn't contain, such as the server that sent the DDL. The problem that I am debugging is that a user's cluster seems to be executing DDL statements twice. I can see the duplicate DDL statements in SHOW ENGINE INNODB STATUS and SHOW FULL PROCESSLIST, so the general log would only confirm what I already know: that the statements are being executed twice. What I was actually hoping for was a way to determine where the duplicate DDL statements are coming from. For example, maybe log entries like this: For DDL executed locally: 160222 15:30:44 [Note] WSREP: DDL executed locally: ALTER ONLINE TABLE test_table DROP KEY str 160222 15:30:44 [Note] WSREP: TO BEGIN: -1, 0 : ALTER ONLINE TABLE test_table DROP KEY str 160222 15:30:44 [Note] WSREP: TO BEGIN: 1100033, 2 160222 15:30:44 [Note] WSREP: TO END: 1100033, 2 : ALTER ONLINE TABLE test_table DROP KEY str 160222 15:30:44 [Note] WSREP: Set WSREPXid for InnoDB: fbeb045d-b94f-11e5-8504-4ae80b892690:1100033 160222 15:30:44 [Note] WSREP: TO END: 1100033, update seqno 160222 15:30:44 [Note] WSREP: TO END: 1100033 For DDL received from another node: 160222 15:30:44 [Note] WSREP: DDL received from node1: ALTER ONLINE TABLE test_table DROP KEY str 160222 15:30:44 [Note] WSREP: TO BEGIN: -1, 0 : ALTER ONLINE TABLE test_table DROP KEY str 160222 15:30:44 [Note] WSREP: TO BEGIN: 1100033, 2 160222 15:30:44 [Note] WSREP: TO END: 1100033, 2 : ALTER ONLINE TABLE test_table DROP KEY str 160222 15:30:44 [Note] WSREP: Set WSREPXid for InnoDB: fbeb045d-b94f-11e5-8504-4ae80b892690:1100033 160222 15:30:44 [Note] WSREP: TO END: 1100033, update seqno 160222 15:30:44 [Note] WSREP: TO END: 1100033 Maybe I can find the information that I need in the binary log instead.

          Example of output:

          2021-05-11  7:43:49 2 [Note] WSREP: Apply TOI Begin: DROP TABLE child
          2021-05-11  7:43:49 2 [Note] WSREP: Apply TO END: 20: DROP TABLE child
          

          jplindst Jan Lindström (Inactive) added a comment - Example of output: 2021-05-11 7:43:49 2 [Note] WSREP: Apply TOI Begin: DROP TABLE child 2021-05-11 7:43:49 2 [Note] WSREP: Apply TO END: 20: DROP TABLE child
          jplindst Jan Lindström (Inactive) added a comment - ralf.gebhardt@mariadb.com Only wsrep_debug=1

          1 == SERVER

          jplindst Jan Lindström (Inactive) added a comment - 1 == SERVER

          People

            jplindst Jan Lindström (Inactive)
            GeoffMontee Geoff Montee (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            6 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.