MXS-1475 Add test case for @maxscale.cache.[use|populate]

Also extend logging.

maxscale-system-test/.gitignore

@@ -65,6 +65,7 @@ bug711
 bug729
 bug730
 bulk_insert
+cache_runtime
 ccrfilter
 cdc_client
 cdc_connector-prefix/

maxscale-system-test/CMakeLists.txt

@@ -536,9 +536,12 @@ add_test_script(masking_mysqltest masking_mysqltest_driver.sh masking_mysqltest
 
 add_test_script(masking_user masking_user.sh masking_mysqltest LABELS maskingfilter REPL_BACKEND)
 
-# Test of Cache filter
+# Test of Cache filter - basics
 add_test_script(cache_basic cache_basic.sh cache_basic LABELS cachefilter REPL_BACKEND)
 
+# Test of Cache filter - runtime configuration
+add_test_executable(cache_runtime.cpp cache_runtime cache_runtime LABELS cachefilter REPL_BACKEND)
+
 # Set utf8mb4 in the backend and restart Maxscale
 add_test_executable(mxs951_utfmb4.cpp mxs951_utfmb4 replication LABELS REPL_BACKEND)
 

maxscale-system-test/cache_runtime.cpp

@@ -0,0 +1,216 @@
+/*
+ * Copyright (c) 2016 MariaDB Corporation Ab
+ *
+ * Use of this software is governed by the Business Source License included
+ * in the LICENSE.TXT file and at www.mariadb.com/bsl11.
+ *
+ * Change Date: 2020-01-01
+ *
+ * On the date above, in accordance with the Business Source License, use
+ * of this software will be governed by version 2 or later of the General
+ * Public License.
+ */
+
+#include <iostream>
+#include <string>
+#include <vector>
+#include "testconnections.h"
+
+using namespace std;
+
+namespace
+{
+
+void drop(TestConnections& test)
+{
+    MYSQL* pMysql = test.maxscales->conn_rwsplit[0];
+
+    string stmt("DROP TABLE IF EXISTS cache_test");
+
+    cout << stmt << endl;
+    test.try_query(pMysql, stmt.c_str());
+}
+
+void create(TestConnections& test)
+{
+    drop(test);
+
+    MYSQL* pMysql = test.maxscales->conn_rwsplit[0];
+
+    string stmt("CREATE TABLE cache_test (a INT)");
+
+    cout << stmt << endl;
+    test.try_query(pMysql, stmt.c_str());
+}
+
+void insert(TestConnections& test)
+{
+    MYSQL* pMysql = test.maxscales->conn_rwsplit[0];
+
+    string stmt("INSERT INTO cache_test VALUES (1)");
+
+    cout << stmt << endl;
+    test.try_query(pMysql, stmt.c_str());
+}
+
+void update(TestConnections& test, int value)
+{
+    MYSQL* pMysql = test.maxscales->conn_rwsplit[0];
+
+    string stmt("UPDATE cache_test SET a=");
+    stmt += std::to_string(value);
+
+    cout << stmt << endl;
+    test.try_query(pMysql, stmt.c_str());
+}
+
+void select(TestConnections& test, int* pValue)
+{
+    MYSQL* pMysql = test.maxscales->conn_rwsplit[0];
+
+    string stmt("SELECT * FROM cache_test");
+
+    cout << stmt << endl;
+
+    if (mysql_query(pMysql, stmt.c_str()) == 0)
+    {
+        if (mysql_field_count(pMysql) != 0)
+        {
+            size_t nRows = 0;
+
+            do
+            {
+                MYSQL_RES* pRes = mysql_store_result(pMysql);
+                MYSQL_ROW row = mysql_fetch_row(pRes);
+                *pValue = atoi(row[0]);
+                mysql_free_result(pRes);
+                ++nRows;
+            }
+            while (mysql_next_result(pMysql) == 0);
+
+            test.assert(nRows == 1, "Unexpected number of rows: %u", nRows);
+        }
+    }
+    else
+    {
+        test.assert(false, "SELECT failed.");
+    }
+}
+
+namespace Cache
+{
+
+enum What
+{
+    POPULATE,
+    USE
+};
+
+}
+
+void set(TestConnections& test, Cache::What what, bool value)
+{
+    MYSQL* pMysql = test.maxscales->conn_rwsplit[0];
+
+    string stmt("SET @maxscale.cache.");
+    stmt += ((what == Cache::POPULATE) ? "populate" : "use");
+    stmt += "=";
+    stmt += (value ? "true" : "false");
+
+    cout << stmt << endl;
+    test.try_query(pMysql, stmt.c_str());
+}
+
+}
+
+
+namespace
+{
+
+void init(TestConnections& test)
+{
+    create(test);
+    insert(test);
+}
+
+void run(TestConnections& test)
+{
+    init(test);
+
+    MYSQL* pMysql = test.maxscales->conn_rwsplit[0];
+
+    int value;
+
+    // Let's populate the cache.
+    set(test, Cache::POPULATE, true);
+    set(test, Cache::USE, false);
+    select(test, &value);
+    test.assert(value == 1, "Initial value was not 1.");
+
+    // And update the real value.
+    update(test, 2); // Now the cache contains 1 and the db 2.
+
+    // With @maxscale.cache.use==false we should get the updated value.
+    set(test, Cache::POPULATE, false);
+    set(test, Cache::USE, false);
+    select(test, &value);
+    test.assert(value == 2, "The value received was not the latest one.");
+
+    // With @maxscale.cache.use==true we should get the old one, since
+    // it was not updated above as @maxscale.cache.populate==false.
+    set(test, Cache::POPULATE, false);
+    set(test, Cache::USE, true);
+    select(test, &value);
+    test.assert(value == 1, "The value received was not the populated one.");
+
+    // The hard_ttl is 8, so we sleep(10) seconds to ensure that TTL has passed.
+    cout << "Sleeping 10 seconds." << endl;
+    sleep(10);
+
+    // With @maxscale.cache.use==true we should now get the latest value.
+    // The value in the cache is stale, so it will be updated even if
+    // @maxscale.cache.populate==false.
+    set(test, Cache::POPULATE, false);
+    set(test, Cache::USE, true);
+    select(test, &value);
+    test.assert(value == 2, "The cache was not updated even if TTL was passed.");
+
+    // Let's update again
+    update(test, 3);
+
+    // And fetch again. Should still be 2, as the item in the cache is not stale.
+    set(test, Cache::POPULATE, false);
+    set(test, Cache::USE, true);
+    select(test, &value);
+    test.assert(value == 2, "New value %d, although the value in the cache is not stale.", value);
+
+    // Force an update.
+    set(test, Cache::POPULATE, true);
+    set(test, Cache::USE, false);
+    select(test, &value);
+    test.assert(value == 3, "Did not get new value.");
+
+    // And check that the cache indeed was updated, but update the DB first.
+    update(test, 4);
+
+    set(test, Cache::POPULATE, false);
+    set(test, Cache::USE, true);
+    select(test, &value);
+    test.assert(value == 3, "Got a newer value than expected.");
+}
+
+}
+
+int main(int argc, char* argv[])
+{
+    std::ios::sync_with_stdio(true);
+
+    TestConnections test(argc, argv);
+
+    if (test.maxscales->connect_rwsplit() == 0)
+    {
+        run(test);
+    }
+
+    return test.global_result;
+}

maxscale-system-test/cnf/maxscale.cnf.template.cache_runtime

@@ -0,0 +1,51 @@
+[maxscale]
+threads=###threads###
+log_warning=1
+
+[server1]
+type=server
+address=###node_server_IP_1###
+port=###node_server_port_1###
+protocol=MySQLBackend
+
+[MySQL-Monitor]
+type=monitor
+module=mysqlmon
+servers=server1
+user=maxskysql
+passwd=skysql
+monitor_interval=1000
+detect_stale_master=false
+
+[Cache]
+type=filter
+module=cache
+enabled=false
+hard_ttl=16
+soft_ttl=8
+debug=31
+
+[RWS]
+type=service
+router= readwritesplit
+servers=server1
+user=maxskysql
+passwd=skysql
+filters=Cache
+
+[RWS-Listener]
+type=listener
+service=RWS
+protocol=MySQLClient
+port=4006
+
+[CLI]
+type=service
+router=cli
+
+[CLI-Listener]
+type=listener
+service=CLI
+protocol=maxscaled
+#address=localhost
+socket=default

server/modules/filter/cache/cachefiltersession.cc

@@ -771,14 +771,15 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
     {
         uint32_t type_mask = qc_get_trx_type_mask(pPacket); // Note, only trx-related type mask
 
-        const char* zReason = NULL;
+        const char* zPrimary_reason = NULL;
+        const char* zSecondary_reason = "";
         const CACHE_CONFIG& config = m_pCache->config();
 
         if (qc_query_is_type(type_mask, QUERY_TYPE_BEGIN_TRX))
         {
             if (log_decisions())
             {
-                zReason = "transaction start";
+                zPrimary_reason = "transaction start";
             }
 
             // When a transaction is started, we initially assume it is read-only.
@@ -788,7 +789,7 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
         {
             if (log_decisions())
             {
-                zReason = "no transaction";
+                zPrimary_reason = "no transaction";
             }
             action = CACHE_USE_AND_POPULATE;
         }
@@ -798,7 +799,7 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
             {
                 if (log_decisions())
                 {
-                    zReason = "explicitly read-only transaction";
+                    zPrimary_reason = "explicitly read-only transaction";
                 }
                 action = CACHE_USE_AND_POPULATE;
             }
@@ -808,7 +809,7 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
 
                 if (log_decisions())
                 {
-                    zReason = "populating but not using cache inside read-only transactions";
+                    zPrimary_reason = "populating but not using cache inside read-only transactions";
                 }
                 action = CACHE_POPULATE;
             }
@@ -822,7 +823,7 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
             {
                 if (log_decisions())
                 {
-                    zReason = "ordinary transaction that has so far been read-only";
+                    zPrimary_reason = "ordinary transaction that has so far been read-only";
                 }
                 action = CACHE_USE_AND_POPULATE;
             }
@@ -833,7 +834,7 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
 
                 if (log_decisions())
                 {
-                    zReason =
+                    zPrimary_reason =
                         "populating but not using cache inside transaction that is not "
                         "explicitly read-only, but that has used only SELECTs sofar";
                 }
@@ -844,7 +845,7 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
         {
             if (log_decisions())
             {
-                zReason = "ordinary transaction with non-read statements";
+                zPrimary_reason = "ordinary transaction with non-read statements";
             }
         }
 
@@ -861,22 +862,22 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
                     if (qc_query_is_type(type_mask, QUERY_TYPE_USERVAR_READ))
                     {
                         action = CACHE_IGNORE;
-                        zReason = "user variables are read";
+                        zPrimary_reason = "user variables are read";
                     }
                     else if (qc_query_is_type(type_mask, QUERY_TYPE_SYSVAR_READ))
                     {
                         action = CACHE_IGNORE;
-                        zReason = "system variables are read";
+                        zPrimary_reason = "system variables are read";
                     }
                     else if (uses_non_cacheable_function(pPacket))
                     {
                         action = CACHE_IGNORE;
-                        zReason = "uses non-cacheable function";
+                        zPrimary_reason = "uses non-cacheable function";
                     }
                     else if (uses_non_cacheable_variable(pPacket))
                     {
                         action = CACHE_IGNORE;
-                        zReason = "uses non-cacheable variable";
+                        zPrimary_reason = "uses non-cacheable variable";
                     }
                 }
             }
@@ -889,26 +890,21 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
                 m_is_read_only = false;
 
                 action = CACHE_IGNORE;
-                zReason = "statement is not SELECT";
+                zPrimary_reason = "statement is not SELECT";
             }
         }
 
         if (action == CACHE_USE_AND_POPULATE)
         {
-            if (!m_use && !m_populate)
+            if (!m_use)
-            {
-                action = CACHE_IGNORE;
-                zReason = "usage and populating disabled";
-            }
-            else if (!m_use)
             {
                 action = CACHE_POPULATE;
-                zReason = "usage disabled";
+                zSecondary_reason = ", but usage disabled";
             }
             else if (!m_populate)
             {
                 action = CACHE_USE;
-                zReason = "populating disabled";
+                zSecondary_reason = ", but populating disabled";
             }
         }
         else if (action == CACHE_USE)
@@ -916,7 +912,7 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
             if (!m_use)
             {
                 action = CACHE_IGNORE;
-                zReason = "usage disabled";
+                zSecondary_reason = ", but usage disabled";
             }
         }
         else if (action == CACHE_POPULATE)
@@ -924,7 +920,7 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
             if (!m_populate)
             {
                 action = CACHE_IGNORE;
-                zReason = "populating disabled";
+                zSecondary_reason = ", but populating disabled";
             }
         }
 
@@ -941,18 +937,18 @@ CacheFilterSession::cache_action_t CacheFilterSession::get_cache_action(GWBUF* p
 
             if (length <= max_length)
             {
-                zFormat = "%s, \"%.*s\", %s.";
+                zFormat = "%s, \"%.*s\", %s%s.";
             }
             else
             {
-                zFormat = "%s, \"%.*s...\", %s.";
+                zFormat = "%s, \"%.*s...\", %s%s.";
                 length = max_length - 3; // strlen("...");
             }
 
             const char* zDecision = (action == CACHE_IGNORE) ? "IGNORE" : "CONSULT";
 
-            ss_dassert(zReason);
+            ss_dassert(zPrimary_reason);
-            MXS_NOTICE(zFormat, zDecision, length, pSql, zReason);
+            MXS_NOTICE(zFormat, zDecision, length, pSql, zPrimary_reason, zSecondary_reason);
         }
     }
     else
@@ -1075,6 +1071,10 @@ CacheFilterSession::routing_action_t CacheFilterSession::route_SELECT(cache_acti
         }
         else
         {
+            if (log_decisions())
+            {
+                MXS_NOTICE("Not found in cache, fetching data from server.");
+            }
             routing_action = ROUTING_CONTINUE;
         }
 
@@ -1086,11 +1086,20 @@ CacheFilterSession::routing_action_t CacheFilterSession::route_SELECT(cache_acti
             }
             else
             {
+                if (log_decisions())
+                {
+                    MXS_NOTICE("Neither populating, nor refreshing, fetching data "
+                               "but not adding to cache.");
+                }
                 m_state = CACHE_IGNORING_RESPONSE;
             }
         }
         else
         {
+            if (log_decisions())
+            {
+                MXS_NOTICE("Found in cache.");
+            }
             m_state = CACHE_EXPECTING_NOTHING;
             gwbuf_free(pPacket);
             DCB *dcb = m_pSession->client_dcb;