feat(db) better CLI logging during migrations

* new infos() method from connector to retrieve user-facing info + DB
  version
* move `KONG_TEST_PG_*` env vars to be global since unit tests also
  connect to PostgreSQL, but now actually make a query (for
  `server_version`)
* distinguish pending and executed migrations in CLI logs

.ci/run_tests.sh

@@ -4,9 +4,6 @@ set -e
 export BUSTED_ARGS="-o gtest -v --exclude-tags=flaky,ipv6"
 
 if [ "$KONG_TEST_DATABASE" == "postgres" ]; then
-    export KONG_TEST_PG_DATABASE=travis
-    export KONG_TEST_PG_USER=postgres
-    export KONG_TEST_PG_DATABASE=travis
     export TEST_CMD="bin/busted $BUSTED_ARGS,cassandra"
 elif [ "$KONG_TEST_DATABASE" == "cassandra" ]; then
     export KONG_TEST_CASSANDRA_KEYSPACE=kong_tests

.travis.yml

@@ -30,6 +30,8 @@ env:
     - OPENRESTY=$OPENRESTY_BASE
     - DOWNLOAD_CACHE=$HOME/download-cache
     - INSTALL_CACHE=$HOME/install-cache
+    - KONG_TEST_PG_DATABASE=travis
+    - KONG_TEST_PG_USER=postgres
     - JOBS=2
   matrix:
     - KONG_TEST_DATABASE=postgres TEST_SUITE=integration

kong/db/init.lua

@@ -97,6 +97,7 @@ function DB.new(kong_config, strategy)
     connector  = connector,
     strategy   = strategy,
     errors     = errors,
+    infos      = connector:infos(),
     kong_config = kong_config,
   }
 
@@ -120,7 +121,7 @@ end
 
 
 local function prefix_err(self, err)
-  return "[" .. self.strategy .. " error] " .. err
+  return "[" .. self.infos.strategy .. " error] " .. err
 end
 
 
@@ -142,6 +143,8 @@ function DB:init_connector()
     return nil, prefix_err(self, err)
   end
 
+  self.infos = self.connector:infos()
+
   return ok
 end
 
@@ -524,14 +527,14 @@ do
 
 
   function DB:schema_state()
-    log.verbose("loading subsystems migrations...")
+    log.debug("loading subsystems migrations...")
 
     local subsystems, err = load_subsystems(self, self.kong_config.loaded_plugins)
     if not subsystems then
       return nil, prefix_err(self, err)
     end
 
-    log.verbose("retrieving database schema state...")
+    log.verbose("retrieving %s schema state...", self.infos.db_desc)
 
     local ok, err = self.connector:connect_migrations({ no_keyspace = true })
     if not ok then
@@ -658,7 +661,7 @@ do
   function DB:schema_bootstrap()
     local ok, err = self.connector:connect_migrations({ no_keyspace = true })
     if not ok then
-      return nil, err
+      return nil, prefix_err(self, err)
     end
 
     local ok, err = self.connector:schema_bootstrap(self.kong_config,
@@ -716,10 +719,11 @@ do
     local mig_helpers = MigrationHelpers.new(self.connector)
 
     local n_migrations = 0
+    local n_pending = 0
 
     for _, t in ipairs(migrations) do
-      -- TODO: for database/keyspace <db_name/keyspace_name>
-      log("migrating %s...", t.subsystem)
+      log("migrating %s on %s '%s'...", t.subsystem, self.infos.db_desc,
+          self.infos.db_name)
 
       for _, mig in ipairs(t.migrations) do
         local ok, mod = utils.load_module_if_exists(t.namespace .. "." ..
@@ -749,10 +753,12 @@ do
                                 mig.name, err)
           end
 
+
           local state = "executed"
           if strategy_migration.teardown then
             -- this migration has a teardown step for later
             state = "pending"
+            n_pending = n_pending + 1
           end
 
           local ok, err = self.connector:record_migration(t.subsystem,
@@ -784,17 +790,31 @@ do
             return nil, fmt_err(self, "failed to record migration '%s': %s",
                                 mig.name, err)
           end
+
+          n_pending = math.max(n_pending - 1, 0)
         end
 
-        log("%s migrated up to: %s", t.subsystem, mig.name)
+        log("%s migrated up to: %s %s", t.subsystem, mig.name,
+            strategy_migration.teardown
+            and not run_teardown and "(pending)" or "(executed)")
 
         n_migrations = n_migrations + 1
       end
     end
 
-    log("%d migration%s executed", n_migrations,
+    log("%d migration%s processed", n_migrations,
         n_migrations > 1 and "s" or "")
 
+    local n_executed = n_migrations - n_pending
+
+    if n_executed > 0 then
+      log("%d executed", n_executed)
+    end
+
+    if n_pending > 0 then
+      log("%d pending", n_pending)
+    end
+
     if run_up then
       ok, err = self.connector:post_run_up_migrations()
       if not ok then

kong/db/strategies/cassandra/connector.lua

@@ -102,8 +102,8 @@ function CassandraConnector.new(kong_config)
 end
 
 
-local function extract_major(release_version)
-  return string.match(release_version, "^(%d+)%.%d")
+local function extract_major_minor(release_version)
+  return string.match(release_version, "^((%d+)%.%d+)")
 end
 
 
@@ -125,33 +125,47 @@ function CassandraConnector:init()
   end
 
   local major_version
+  local major_minor_version
 
   for i = 1, #peers do
     local release_version = peers[i].release_version
     if not release_version then
       return nil, "no release_version for peer " .. peers[i].host
     end
 
-    local peer_major_version = tonumber(extract_major(release_version))
-    if not peer_major_version then
+    local major_minor, major = extract_major_minor(release_version)
+    major = tonumber(major)
+    if not major_minor or not major then
       return nil, "failed to extract major version for peer " .. peers[i].host
                   .. " with version: " .. tostring(peers[i].release_version)
     end
 
     if i == 1 then
-      major_version = peer_major_version
+      major_version = major
+      major_minor_version = major_minor
 
-    elseif peer_major_version ~= major_version then
+    elseif major ~= major_version then
       return nil, "different major versions detected"
     end
   end
 
   self.major_version = major_version
+  self.major_minor_version = major_minor_version
 
   return true
 end
 
 
+function CassandraConnector:infos()
+  return {
+    strategy = "Cassandra",
+    db_name = self.keyspace,
+    db_desc = "keyspace",
+    db_ver = self.major_minor_version or "unknown",
+  }
+end
+
+
 function CassandraConnector:connect()
   if self.connection then
     return true
@@ -430,7 +444,7 @@ function CassandraConnector:setup_locks(default_ttl, no_schema_consensus)
     return nil, err
   end
 
-  log.verbose("creating 'locks' table if not existing...")
+  log.debug("creating 'locks' table if not existing...")
 
   local cql = string.format([[
     CREATE TABLE IF NOT EXISTS locks(
@@ -445,7 +459,7 @@ function CassandraConnector:setup_locks(default_ttl, no_schema_consensus)
     return nil, err
   end
 
-  log.verbose("successfully created 'locks' table")
+  log.debug("successfully created 'locks' table")
 
   if not no_schema_consensus then
     -- called from tests, ignored when called from bootstrapping, since
@@ -641,8 +655,8 @@ do
 
     -- create keyspace if not exists
 
-    log.verbose("creating '%s' keyspace if not existing...",
-                kong_config.cassandra_keyspace)
+    log.debug("creating '%s' keyspace if not existing...",
+              kong_config.cassandra_keyspace)
 
     local res, err = self.connection:execute(string.format([[
       CREATE KEYSPACE IF NOT EXISTS %q
@@ -652,8 +666,8 @@ do
       return nil, err
     end
 
-    log("successfully created '%s' keyspace",
-        kong_config.cassandra_keyspace)
+    log.debug("successfully created '%s' keyspace",
+              kong_config.cassandra_keyspace)
 
     local ok, err = self.connection:change_keyspace(kong_config.cassandra_keyspace)
     if not ok then
@@ -662,7 +676,7 @@ do
 
     -- create schema meta table if not exists
 
-    log.verbose("creating 'schema_meta' table if not existing...")
+    log.debug("creating 'schema_meta' table if not existing...")
 
     local res, err = self.connection:execute([[
       CREATE TABLE IF NOT EXISTS schema_meta(
@@ -679,7 +693,7 @@ do
       return nil, err
     end
 
-    log.verbose("successfully created 'schema_meta' table")
+    log.debug("successfully created 'schema_meta' table")
 
     ok, err = self:setup_locks(default_locks_ttl, true) -- no schema consensus
     if not ok then

kong/db/strategies/connector.lua

@@ -16,6 +16,11 @@ function Connector:init_worker()
 end
 
 
+function Connector:infos()
+  error(fmt("infos() not implemented for '%s' strategy", self.database))
+end
+
+
 function Connector:connect()
   error(fmt("connect() not implemented for '%s' strategy", self.database))
 end

kong/db/strategies/postgres/connector.lua

@@ -182,6 +182,31 @@ local _mt = {}
 _mt.__index = _mt
 
 
+local function extract_major_minor(release_version)
+  return string.match(release_version, "^(%d+%.%d+)")
+end
+
+
+function _mt:init()
+  local res, err = self:query("SHOW server_version;")
+  if not res then
+    return nil, "failed to retrieve server_version: " .. err
+  end
+
+  if #res < 1 or not res[1].server_version then
+    return nil, "failed to retrieve server_version"
+  end
+
+  self.major_minor_version = extract_major_minor(res[1].server_version)
+  if not self.major_minor_version then
+    return nil, "failed to extract major.minor version from '" ..
+                res[1].server_version .. "'"
+  end
+
+  return true
+end
+
+
 function _mt:init_worker(strategies)
   if ngx.worker.id() == 0 then
     local graph
@@ -244,6 +269,16 @@ function _mt:init_worker(strategies)
 end
 
 
+function _mt:infos()
+  return {
+    strategy = "PostgreSQL",
+    db_name = self.config.database,
+    db_desc = "database",
+    db_ver = self.major_minor_version or "unknown",
+  }
+end
+
+
 function _mt:connect()
   if self.connection and self.connection.sock then
     return true

spec/01-unit/003-prefix_handler_spec.lua

@@ -429,7 +429,10 @@ describe("NGINX conf compiler", function()
       }))
       assert.equal("foobar", conf.pg_database)
       assert(prefix_handler.prepare_prefix(conf))
-      local in_prefix_kong_conf = assert(conf_loader(tmp_config.kong_env))
+      local in_prefix_kong_conf = assert(conf_loader(tmp_config.kong_env, {
+        pg_database = "foobar",
+        prefix = tmp_config.prefix,
+      }))
       assert.same(conf, in_prefix_kong_conf)
     end)
     it("writes custom plugins in Kong conf", function()