Bug #25557263 'WAITING MAX 119 SEC FOR DISTRIBUTING'-SCHEMA DISTRIBUTION TIMEOUT

There is a possible race condition between the schema distribution
coordinator holding a ref-lock on its schema_object, and the
binlog-injector thread (participant-role) possibly being late
to unref-lock the same schema_object.

This could potentially result in another schema distr operation
getting a ref to the not-yet-released schema_object held
by the injector thread instead of having to create a new
schema_object as normally expected.

The SLOCK-bitmap, which keeps track of which participants
the coordinator is still waiting for, was set to 'all-1'
when created. However, it will be 'all-0' immediately before
the injector thread is about the release (unref) it.

Thus, if the coordinator managed to 're-get' this schema_object
before being released (and destructed) by the injector-thread,
we got a schema_object->slocks with 'all-0' instead of 'all-1'
as expected. - This caused a total breakdown of the schema
distribution protocol.

The fix is to move the schema_object->slock 'all-1' setting
from the creation of new schema_object() to the place where
the schema distr coordinator initate waiting for schema operations
to be distributed. This will cover both scenarios where we
either had to create a new schema_object, or we reuse an
existing not-yet-released schema object.

Author: Ole John Aske

mysql-test/suite/ndb/r/bug#24926009.result

@@ -1 +1,7 @@
+Bug#25557263
+
+Another variant of the 'WAITING MAX 119 SEC FOR DISTRIBUTING' timeout
+was sometimes provoked with this testcase. This time caused by
+a race condition between the schema changing client and the
+'coordinator' on the same mysqld.
 DROP DATABASE IF EXISTS tmp_db;

mysql-test/suite/ndb/t/bug#24926009.test

@@ -45,6 +45,46 @@ while ($1)
   dec $1;
 }
 
+--echo Bug#25557263
+--echo
+--echo Another variant of the 'WAITING MAX 119 SEC FOR DISTRIBUTING' timeout
+--echo was sometimes provoked with this testcase. This time caused by
+--echo a race condition between the schema changing client and the
+--echo 'coordinator' on the same mysqld.
+
+--connection server1
+set global debug='+d,ndb_binlog_schema_object_race';
+--connection server2
+set global debug='+d,ndb_binlog_schema_object_race';
+--connection server3
+set global debug='+d,ndb_binlog_schema_object_race';
+--connection server4
+set global debug='+d,ndb_binlog_schema_object_race';
+
+let $1=10;
+while ($1)
+{
+  --connection server1
+  send CREATE DATABASE IF NOT EXISTS tmp_db;
+  --connection server2
+  send CREATE DATABASE IF NOT EXISTS tmp_db;
+  --connection server3
+  send CREATE DATABASE IF NOT EXISTS tmp_db;
+  --connection server4
+  send CREATE DATABASE IF NOT EXISTS tmp_db;
+
+  --connection server1
+  reap;
+  --connection server2
+  reap;
+  --connection server3
+  reap;
+  --connection server4
+  reap;
+
+  dec $1;
+}
+
 --connection server1
 set global debug= @save_debug;
 --connection server2

sql/ha_ndbcluster_binlog.cc

@@ -1,5 +1,5 @@
 /*
-  Copyright (c) 2006, 2016, Oracle and/or its affiliates. All rights reserved.
+  Copyright (c) 2006, 2017, Oracle and/or its affiliates. All rights reserved.
 
    This program is free software; you can redistribute it and/or modify
    it under the terms of the GNU General Public License as published by
@@ -1820,6 +1820,23 @@ int ndbcluster_log_schema_op(THD *thd,
     char key[FN_REFLEN + 1];
     build_table_filename(key, sizeof(key) - 1, db, table_name, "", 0);
     ndb_schema_object= ndb_get_schema_object(key, true);
+
+    /**
+     * We will either get a newly created schema_object, or a 
+     * 'all-clear' schema_object completed but still referred
+     * by my binlog-injector-thread. In both cases there should
+     * be no outstanding SLOCK's.
+     * See also the 'ndb_binlog_schema_object_race' error injection.
+     */ 
+    DBUG_ASSERT(bitmap_is_clear_all(&ndb_schema_object->slock_bitmap));
+
+    /**
+     * Expect answer from all other nodes by default(those
+     * who are not subscribed will be filtered away by
+     * the Coordinator which keep track of such stuff)
+     */
+    bitmap_set_all(&ndb_schema_object->slock_bitmap);
+
     ndb_schema_object->table_id= ndb_table_id;
     ndb_schema_object->table_version= ndb_table_version;
 
@@ -2045,7 +2062,13 @@ int ndbcluster_log_schema_op(THD *thd,
   /*
     Wait for other mysqld's to acknowledge the table operation
   */
-  if (ndb_error == 0 && !bitmap_is_clear_all(&ndb_schema_object->slock_bitmap))
+  if (unlikely(ndb_error))
+  {
+    sql_print_error("NDB %s: distributing %s err: %u",
+                    type_str, ndb_schema_object->key,
+                    ndb_error->code);
+  }
+  else if (!bitmap_is_clear_all(&ndb_schema_object->slock_bitmap))
   {
     int max_timeout= DEFAULT_SYNC_TIMEOUT;
     pthread_mutex_lock(&ndb_schema_object->mutex);
@@ -2096,12 +2119,6 @@ int ndbcluster_log_schema_op(THD *thd,
     }
     pthread_mutex_unlock(&ndb_schema_object->mutex);
   }
-  else if (ndb_error)
-  {
-    sql_print_error("NDB %s: distributing %s err: %u",
-                    type_str, ndb_schema_object->key,
-                    ndb_error->code);
-  }
   else if (opt_ndb_extra_logging > 19)
   {
     sql_print_information("NDB %s: not waiting for distributing %s",
@@ -3089,6 +3106,22 @@ class Ndb_schema_event_handler {
     pthread_mutex_unlock(&ndb_schema_object->mutex);
     pthread_cond_signal(&ndb_schema_object->cond);
 
+    /**
+     * There is a possible race condition between this binlog-thread,
+     * which has not yet released its schema_object, and the
+     * coordinator which possibly release its reference
+     * to the same schema_object when signaled above.
+     *
+     * If the coordinator then starts yet another schema operation
+     * on the same schema / table, it will need a schema_object with
+     * the same key as the one already completed, and which this 
+     * thread still referrs. Thus, it will get this schema_object,
+     * instead of creating a new one as normally expected.
+     */
+    DBUG_EXECUTE_IF("ndb_binlog_schema_object_race",
+    {
+      NdbSleep_MilliSleep(10);
+    });
     ndb_free_schema_object(&ndb_schema_object);
     DBUG_VOID_RETURN;
   }

sql/ndb_schema_object.cc

@@ -1,5 +1,5 @@
 /*
-   Copyright (c) 2011, 2016, Oracle and/or its affiliates. All rights reserved.
+   Copyright (c) 2011, 2017, Oracle and/or its affiliates. All rights reserved.
 
    This program is free software; you can redistribute it and/or modify
    it under the terms of the GNU General Public License as published by
@@ -82,16 +82,14 @@ NDB_SCHEMA_OBJECT *ndb_get_schema_object(const char *key,
     if (my_hash_insert(&ndb_schema_objects.m_hash, (uchar*) ndb_schema_object))
     {
       my_free(ndb_schema_object);
+      ndb_schema_object= NULL;
       break;
     }
     pthread_mutex_init(&ndb_schema_object->mutex, MY_MUTEX_INIT_FAST);
     pthread_cond_init(&ndb_schema_object->cond, NULL);
     bitmap_init(&ndb_schema_object->slock_bitmap, ndb_schema_object->slock,
                 sizeof(ndb_schema_object->slock)*8, FALSE);
-    // Expect answer from all other nodes by default(those
-    // who are not subscribed will be filtered away by
-    // the Coordinator which keep track of that stuff)
-    bitmap_set_all(&ndb_schema_object->slock_bitmap);
+    //slock_bitmap is intially cleared due to 'ZEROFILL-malloc'
     break;
   }
   if (ndb_schema_object)
@@ -118,7 +116,7 @@ ndb_free_schema_object(NDB_SCHEMA_OBJECT **ndb_schema_object)
     pthread_cond_destroy(&(*ndb_schema_object)->cond);
     pthread_mutex_destroy(&(*ndb_schema_object)->mutex);
     my_free(*ndb_schema_object);
-    *ndb_schema_object= 0;
+    *ndb_schema_object= NULL;
   }
   else
   {