feat(cli) improve logging messages

* better consistency with capitals/non-capitals/formats/style
* prevent stop/reload/restart from double-logging when using conf_loader
  twice
* reduce logging info about executables to `debug` level

kong/cmd/health.lua

@@ -37,7 +37,7 @@ local function execute(args)
   log("") -- line jump
 
   assert(count > 0, "Kong is not running at "..conf.prefix)
-  assert(count == pl_tablex.size(pids), "Some services are not running at "..conf.prefix)
+  assert(count == pl_tablex.size(pids), "some services are not running at "..conf.prefix)
 
   log("Kong is healthy at %s", conf.prefix)
 end

kong/cmd/quit.lua

@@ -8,10 +8,12 @@ local kill = require "kong.cmd.utils.kill"
 local log = require "kong.cmd.utils.log"
 
 local function execute(args)
+  log.disable()
   -- retrieve default prefix or use given one
   local default_conf = assert(conf_loader(nil, {
     prefix = args.prefix
   }))
+  log.enable()
   assert(pl_path.exists(default_conf.prefix),
          "no such prefix: "..default_conf.prefix)
 
@@ -21,7 +23,7 @@ local function execute(args)
   -- try graceful shutdown (QUIT)
   assert(nginx_signals.quit(conf))
 
-  log.verbose("waiting for Nginx to finish processing requests...")
+  log.verbose("waiting for nginx to finish processing requests")
 
   local tstart = ngx.time()
   local texp, running = tstart + math.max(args.timeout, 1) -- min 1s timeout
@@ -31,7 +33,7 @@ local function execute(args)
   until not running or ngx.time() >= texp
 
   if running then
-    log.verbose("Nginx is still running at %s, forcing shutdown", conf.prefix)
+    log.verbose("nginx is still running at %s, forcing shutdown", conf.prefix)
     assert(nginx_signals.stop(conf))
   end
 
@@ -41,7 +43,7 @@ local function execute(args)
     assert(dnsmasq_signals.stop(conf))
   end
 
-  log("Stopped (gracefully)")
+  log("Kong stopped (gracefully)")
 end
 
 local lapp = [[

kong/cmd/reload.lua

@@ -8,10 +8,12 @@ local pl_path = require "pl.path"
 local log = require "kong.cmd.utils.log"
 
 local function execute(args)
+  log.disable()
   -- retrieve prefix or use given one
   local default_conf = assert(conf_loader(args.conf, {
     prefix = args.prefix
   }))
+  log.enable()
   assert(pl_path.exists(default_conf.prefix),
          "no such prefix: "..default_conf.prefix)
 
@@ -23,7 +25,7 @@ local function execute(args)
   end
   assert(serf_signals.start(conf, DAOFactory(conf)))
   assert(nginx_signals.reload(conf))
-  log("Reloaded")
+  log("Kong reloaded")
 end
 
 local lapp = [[

kong/cmd/start.lua

@@ -19,7 +19,7 @@ local function execute(args)
   end
   assert(serf_signals.start(conf, dao))
   assert(nginx_signals.start(conf))
-  log("Started")
+  log("Kong started")
 end
 
 local lapp = [[

kong/cmd/stop.lua

@@ -7,10 +7,12 @@ local pl_path = require "pl.path"
 local log = require "kong.cmd.utils.log"
 
 local function execute(args)
-  -- retrieve default prefix or use given one
+  log.disable()
+  -- only to retrieve the default prefix or use given one
   local default_conf = assert(conf_loader(nil, {
     prefix = args.prefix
   }))
+  log.enable()
   assert(pl_path.exists(default_conf.prefix),
          "no such prefix: "..default_conf.prefix)
 
@@ -21,7 +23,7 @@ local function execute(args)
   if conf.dnsmasq then
     assert(dnsmasq_signals.stop(conf))
   end
-  log("Stopped")
+  log("Kong stopped")
 end
 
 local lapp = [[

kong/cmd/utils/dnsmasq_signals.lua

@@ -19,7 +19,7 @@ local dnsmasq_search_paths = {
 }
 
 local function find_dnsmasq_bin()
-  log.verbose("searching for 'dnsmasq' executable...")
+  log.debug("searching for 'dnsmasq' executable")
 
   local found
   for _, path in ipairs(dnsmasq_search_paths) do
@@ -38,7 +38,7 @@ local function find_dnsmasq_bin()
     return nil, "could not find 'dnsmasq' executable"
   end
 
-  log.verbose("found 'dnsmasq' executable at %s", found)
+  log.debug("found 'dnsmasq' executable at %s", found)
 
   return found
 end

kong/cmd/utils/log.lua

@@ -13,6 +13,7 @@ for k, v in pairs(_LEVELS) do
 end
 
 local log_lvl = _LEVELS.info
+local old_lvl
 
 local _M = {
   levels = _LEVELS
@@ -24,6 +25,18 @@ function _M.set_lvl(lvl)
   end
 end
 
+function _M.disable()
+  if not old_lvl then
+    old_lvl = log_lvl
+    log_lvl = _LEVELS.quiet
+  end
+end
+
+function _M.enable()
+  log_lvl = old_lvl or log_lvl
+  old_lvl = nil
+end
+
 local function log(lvl, ...)
   local format
   local args = {...}

kong/cmd/utils/nginx_signals.lua

@@ -33,10 +33,10 @@ end
 
 local function send_signal(pid_path, signal)
   if not pl_path.exists(pid_path) then
-    return nil, "could not get Nginx pid (is Nginx running in this prefix?)"
+    return nil, "could not get nginx pid (is Nginx running in this prefix?)"
   end
 
-  log.verbose("sending %s signal to Nginx running at %s", signal, pid_path)
+  log.verbose("sending %s signal to nginx running at %s", signal, pid_path)
 
   local code = kill.kill(pid_path, "-s "..signal)
   if code ~= 0 then return nil, "could not send signal" end
@@ -47,14 +47,14 @@ end
 local _M = {}
 
 local function find_nginx_bin()
-  log.verbose("searching for OpenResty 'nginx' executable...")
+  log.debug("searching for OpenResty 'nginx' executable")
 
   local found
   for _, path in ipairs(nginx_search_paths) do
     local path_to_check = pl_path.join(path, nginx_bin_name)
     if is_openresty(path_to_check) then
       found = path_to_check
-      log.verbose("found OpenResty 'nginx' executable at %s", found)
+      log.debug("found OpenResty 'nginx' executable at %s", found)
       break
     end
   end
@@ -72,7 +72,7 @@ function _M.start(kong_conf)
   if not nginx_bin then return nil, err end
 
   if kill.is_running(kong_conf.nginx_pid) then
-    return nil, "Nginx is already running in "..kong_conf.prefix
+    return nil, "nginx is already running in "..kong_conf.prefix
   end
 
   local cmd = fmt("%s -p %s -c %s", nginx_bin, kong_conf.prefix, "nginx.conf")
@@ -82,6 +82,8 @@ function _M.start(kong_conf)
   local ok, _, _, stderr = pl_utils.executeex(cmd)
   if not ok then return nil, stderr end
 
+  log.debug("nginx started")
+
   return true
 end
 

kong/cmd/utils/prefix_handler.lua

@@ -73,14 +73,14 @@ local function is_openresty(bin_path)
 end
 
 local function find_resty_bin()
-  log.verbose("searching for OpenResty 'resty' executable...")
+  log.debug("searching for OpenResty 'resty' executable")
 
   local found
   for _, path in ipairs(resty_search_paths) do
     local path_to_check = pl_path.join(path, resty_bin_name)
     if is_openresty(path_to_check) then
       found = path_to_check
-      log.verbose("found OpenResty 'resty' executable at %s", found)
+      log.debug("found OpenResty 'resty' executable at %s", found)
       break
     end
   end
@@ -103,7 +103,7 @@ local function gen_default_ssl_cert(kong_config)
   local ssl_cert_csr = kong_config.ssl_cert_csr_default
 
   if not pl_path.exists(ssl_cert) and not pl_path.exists(ssl_cert_key) then
-    log.verbose("auto-generating default SSL certificate and key...")
+    log.verbose("generating default SSL certificate and key")
 
     local passphrase = utils.random_string()
     local commands = {
@@ -208,7 +208,7 @@ local function prepare_prefix(kong_config, nginx_custom_template_path)
   local ok, _, _, stderr = pl_utils.executeex("touch "..kong_config.nginx_acc_logs)
   if not ok then return nil, stderr end
 
-  log.verbose("saving Serf identifier in %s", kong_config.serf_node_id)
+  log.verbose("saving serf identifier to %s", kong_config.serf_node_id)
   if not pl_path.exists(kong_config.serf_node_id) then
     local id = utils.get_hostname().."_"..kong_config.cluster_listen.."_"..utils.random_string()
     pl_file.write(kong_config.serf_node_id, id)
@@ -217,15 +217,15 @@ local function prepare_prefix(kong_config, nginx_custom_template_path)
   local resty_bin, err = find_resty_bin()
   if not resty_bin then return nil, err end
 
-  log.verbose("saving Serf shell script handler in %s", kong_config.serf_event)
+  log.verbose("saving serf shell script handler to %s", kong_config.serf_event)
   local script = fmt(script_template, "127.0.0.1", kong_config.admin_port, resty_bin)
   pl_file.write(kong_config.serf_event, script)
   local ok, _, _, stderr = pl_utils.executeex("chmod +x "..kong_config.serf_event)
   if not ok then return nil, stderr end
 
   -- generate default SSL certs if needed
   if kong_config.ssl and not kong_config.ssl_cert and not kong_config.ssl_cert_key then
-    log.verbose("using default SSL certificate and key")
+    log.verbose("SSL enabled, no custom certificate set: using default certificate")
     local ok, err = gen_default_ssl_cert(kong_config)
     if not ok then return nil, err end
     kong_config.ssl_cert = kong_config.ssl_cert_default

kong/cmd/utils/serf_signals.lua

@@ -18,15 +18,15 @@ local serf_compatible = version.set(unpack(meta._DEPENDENCIES.serf))
 local start_timeout = 5
 
 local function check_serf_bin(kong_config)
-  log.verbose("checking 'serf' executable from 'serf_path' config setting...")
+  log.debug("checking 'serf' executable from 'serf_path' config setting")
 
   local cmd = fmt("%s version", kong_config.serf_path)
   local ok, _, stdout = pl_utils.executeex(cmd)
   log.debug("%s: '%s'", cmd, pl_stringx.splitlines(stdout)[1])
   if ok and stdout then
     local version_match = stdout:match(serf_version_pattern)
     if not version_match or not serf_compatible:matches(version_match) then
-      return nil, "incompatible Serf found. Kong requires version "..
+      return nil, "incompatible serf found. Kong requires version "..
                   tostring(serf_compatible)..", got "..version_match
     end
     return true
@@ -40,10 +40,10 @@ local _M = {}
 function _M.start(kong_config, dao)
   -- is Serf already running in this prefix?
   if kill.is_running(kong_config.serf_pid) then
-    log.verbose("Serf agent already running at %s", kong_config.serf_pid)
+    log.verbose("serf agent already running at %s", kong_config.serf_pid)
     return true
   else
-    log.verbose("Serf agent not running, deleting %s", kong_config.serf_pid)
+    log.verbose("serf agent not running, deleting %s", kong_config.serf_pid)
     pl_file.delete(kong_config.serf_pid)
   end
 
@@ -69,13 +69,13 @@ function _M.start(kong_config, dao)
                             kong_config.serf_path, tostring(args),
                             kong_config.serf_log, kong_config.serf_pid)
 
-  log.debug("starting Serf agent: %s", cmd)
+  log.debug("starting serf agent: %s", cmd)
 
   -- start Serf agent
   local ok = pl_utils.execute(cmd)
   if not ok then return nil end
 
-  log.verbose("waiting for Serf agent to be running...")
+  log.verbose("waiting for serf agent to be running")
 
   -- ensure started (just an improved version of previous Serf service)
   local tstart = ngx.time()
@@ -91,37 +91,40 @@ function _M.start(kong_config, dao)
     local tlogs = pl_stringx.split(logs, "\n")
     local err = string.gsub(tlogs[#tlogs-1], "==> ", "")
     err = pl_stringx.strip(err)
-    return nil, "could not start Serf: "..err
+    return nil, "could not start serf: "..err
   end
 
+  log.verbose("serf agent started")
+
   -- cleanup current node from cluster to prevent inconsistency of data
   local ok, err = serf:cleanup()
   if not ok then return nil, err end
 
-  log.verbose("auto-joining Serf cluster...")
+  log.verbose("auto-joining serf cluster")
   local ok, err = serf:autojoin()
   if not ok then return nil, err end
 
-  log.verbose("adding node to Serf cluster (in datastore)...")
+  log.verbose("registering serf node in datastore")
   local ok, err = serf:add_node()
   if not ok then return nil, err end
 
+  log.verbose("cluster joined and node registered in datastore")
+
   return true
 end
 
 function _M.stop(kong_config, dao)
-  log.info("leaving cluster")
-
+  log.verbose("leaving serf cluster")
   local serf = Serf.new(kong_config, dao)
-
-  log.verbose("invoking Serf leave")
   serf:leave()
+  log.verbose("left serf cluster")
 
-  log.verbose("stopping Serf agent at %s", kong_config.serf_pid)
+  log.verbose("stopping serf agent at %s", kong_config.serf_pid)
   local code = kill.kill(kong_config.serf_pid, "-15") --SIGTERM
   if code == 256 then -- If no error is returned
     pl_file.delete(kong_config.serf_pid)
   end
+  log.verbose("serf agent stopped")
   return true
 end
 

kong/serf.lua

@@ -97,19 +97,20 @@ function Serf:autojoin()
   local nodes, err = self.dao.nodes:find_all()
   if err then return nil, tostring(err)
   elseif #nodes == 0 then
-    log.info("No other Kong nodes were found in the cluster")
+    log.verbose("no other nodes found in the cluster")
   else
     -- Sort by newest to oldest (although by TTL would be a better sort)
     table.sort(nodes, function(a, b) return a.created_at > b.created_at end)
 
     local joined
     for _, v in ipairs(nodes) do
       if self:join_node(v.cluster_listening_address) then
-        log("Successfully auto-joined %s", v.cluster_listening_address)
+        log.verbose("successfully joined cluster at %s", v.cluster_listening_address)
         joined = true
         break
       else
-        log.warn("could not join %s, if the node does not exist anymore it will be automatically purged", v.cluster_listening_address)
+        log.warn("could not join cluster at %s, if the node does not exist "..
+                 "anymore it will be purged automatically", v.cluster_listening_address)
       end
     end
     if not joined then
@@ -151,7 +152,7 @@ function Serf:event(t_payload)
 
   if #payload > 512 then
     -- Serf can't send a payload greater than 512 bytes
-    return nil, "Encoded payload is "..#payload.." and exceeds the limit of 512 bytes!"
+    return nil, "encoded payload is "..#payload.." and exceeds the limit of 512 bytes!"
   end
 
   return self:invoke_signal("event -coalesce=false", " kong '"..payload.."'")