Log empty or nil select calls

Empty or nil select calls on user spaces tend to be dangerous.

A critical log entry containing the current stack traceback is created
upon empty or nil select calls — a user can explicitly request a full
scan though by passing fullscan = true to select's options table
argument in which a case a log entry will not be created.

Tarantool has a similar implementation[1].

1. tarantool/tarantool#7064

Closes #276

Author: oleg-jukovec

CHANGELOG.md

@@ -10,6 +10,10 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 ### Added
 
 ### Changed
+* Behaviour of empty or nil select calls: a critical log entry containing the
+  current stack traceback is created upon such function calls — a user can
+  explicitly request a full scan though by passing fullscan=true to select's
+  options table argument in which a case a log entry will not be created (#276).
 
 ### Fixed
 

README.md

@@ -25,7 +25,7 @@ It can be used to convert received tuples to objects via `crud.unflatten_rows` f
 For example:
 
 ```lua
-res, err = crud.select('customers')
+res, err = crud.select('customers', nil, {fullscan = true})
 res
 ---
 - metadata:
@@ -395,6 +395,8 @@ where:
      if full primary key equal condition is specified
   * `timeout` (`?number`) - `vshard.call` timeout (in seconds)
   * `fields` (`?table`) - field names for getting only a subset of fields
+  * `fullscan` (`?boolean`) - if `true` then critical log entry will be skipped
+    on empty or nil `select`
   * `mode` (`?string`, `read` or `write`) - if `write` is specified then `select` is
     performed on master
   * `prefer_replica` (`?boolean`) - if `true` then the preferred target is one of
@@ -578,7 +580,7 @@ Returns number or nil with error.
 Using `memtx`:
 
 ```lua
-#crud.select('customers')
+#crud.select('customers', nil, {fullscan = true})
 ---
 - 5
 ...

crud/ratelimit.lua

@@ -0,0 +1,102 @@
+-- Mostly it's a copy-paste from tarantool/src/lua/log.lua. We have three
+-- reasons:
+-- 1. Tarantool has not log.crit() (a function for logging with CRIT level).
+-- 2. Only new versions of Tarantool have Ratelimit type.
+-- 3. We want own copy of Ratelimit in case the implementation in Tarantool
+-- changes. Less pain between Tarantool versions.
+local ffi = require('ffi')
+
+local S_CRIT = ffi.C.S_CRIT
+local S_WARN = ffi.C.S_WARN
+
+local function say(level, fmt, ...)
+    if ffi.C.log_level < level then
+        -- don't waste cycles on debug.getinfo()
+        return
+    end
+    local type_fmt = type(fmt)
+    local format = "%s"
+    if select('#', ...) ~= 0 then
+        local stat
+        stat, fmt = pcall(string.format, fmt, ...)
+        if not stat then
+            error(fmt, 3)
+        end
+    elseif type_fmt == 'table' then
+        -- An implementation in Tarantool supports encoding a table in JSON,
+        -- but it requires more dependencies from FFI. So we just deleted it
+		-- because we don't need such encoding in the module.
+        error("table not supported", 3)
+    elseif type_fmt ~= 'string' then
+        fmt = tostring(fmt)
+    end
+
+    local debug = require('debug')
+    local frame = debug.getinfo(3, "Sl")
+    local line, file = 0, 'eval'
+    if type(frame) == 'table' then
+        line = frame.currentline or 0
+        file = frame.short_src or frame.src or 'eval'
+    end
+
+    ffi.C._say(level, file, line, nil, format, fmt)
+end
+
+local Ratelimit = {
+    interval = 60,
+    burst = 10,
+    emitted = 0,
+    suppressed = 0,
+    start = 0,
+}
+
+function Ratelimit:new(object)
+    object = object or {}
+    setmetatable(object, self)
+    self.__index = self
+    return object
+end
+
+function Ratelimit:check()
+    local clock = require('clock')
+
+    local now = clock.monotonic()
+    local saved_suppressed = 0
+    if now > self.start + self.interval then
+        saved_suppressed = self.suppressed
+        self.suppressed = 0
+        self.emitted = 0
+        self.start = now
+    end
+
+    if self.emitted < self.burst then
+        self.emitted = self.emitted + 1
+        return saved_suppressed, true
+    end
+    self.suppressed = self.suppressed + 1
+    return saved_suppressed, false
+end
+
+function Ratelimit:log_check(lvl)
+    local suppressed, ok = self:check()
+    if lvl >= S_WARN and suppressed > 0 then
+        say(S_WARN, '%d messages suppressed due to rate limiting', suppressed)
+    end
+    return ok
+end
+
+function Ratelimit:log(lvl, fmt, ...)
+    if self:log_check(lvl) then
+        say(lvl, fmt, ...)
+    end
+end
+
+local function log_ratelimited_closure(lvl)
+    return function(self, fmt, ...)
+        self:log(lvl, fmt, ...)
+    end
+end
+
+Ratelimit.log_crit = log_ratelimited_closure(S_CRIT)
+
+return Ratelimit

crud/select/compat/common.lua

@@ -1,6 +1,20 @@
+local ratelimit = require('crud.ratelimit')
+local check_select_args_rl = ratelimit:new()
+
 local common = {}
 
 common.SELECT_FUNC_NAME = '_crud.select_on_storage'
 common.DEFAULT_BATCH_SIZE = 100
 
+common.check_select_args = function(space_name, user_conditions, opts)
+    local rl = check_select_args_rl
+    local uc = user_conditions
+
+    if (uc == nil or (type(uc) == 'table' and next(uc) == nil)) and
+       (opts == nil or not opts.fullscan) then
+        rl:log_crit("empty or nil `select` call on user space=%s\n %s",
+                    space_name, debug.traceback())
+    end
+end
+
 return common

crud/select/compat/select.lua

@@ -193,6 +193,7 @@ function select_module.pairs(space_name, user_conditions, opts)
         bucket_id = '?number|cdata',
         force_map_call = '?boolean',
         fields = '?table',
+        fullscan = '?boolean',
 
         mode = '?vshard_call_mode',
         prefer_replica = '?boolean',
@@ -252,15 +253,18 @@ local function select_module_call_xc(space_name, user_conditions, opts)
     checks('string', '?table', {
         after = '?table|cdata',
         first = '?number',
-        timeout = '?number',
         batch_size = '?number',
         bucket_id = '?number|cdata',
         force_map_call = '?boolean',
         fields = '?table',
+        fullscan = '?boolean',
+
+        mode = '?vshard_call_mode',
         prefer_replica = '?boolean',
         balance = '?boolean',
-        mode = '?vshard_call_mode',
+        timeout = '?number',
     })
+    common.check_select_args(space_name, user_conditions, opts)
 
     opts = opts or {}
 

crud/select/compat/select_old.lua

@@ -225,6 +225,7 @@ function select_module.pairs(space_name, user_conditions, opts)
         bucket_id = '?number|cdata',
         force_map_call = '?boolean',
         fields = '?table',
+        fullscan = '?boolean',
 
         mode = '?vshard_call_mode',
         prefer_replica = '?boolean',
@@ -302,6 +303,7 @@ end
 
 local function select_module_call_xc(space_name, user_conditions, opts)
     dev_checks('string', '?table', '?table')
+    common.check_select_args(space_name, user_conditions, opts)
 
     opts = opts or {}
 
@@ -366,14 +368,16 @@ function select_module.call(space_name, user_conditions, opts)
     checks('string', '?table', {
         after = '?table',
         first = '?number',
-        timeout = '?number',
         batch_size = '?number',
         bucket_id = '?number|cdata',
         force_map_call = '?boolean',
         fields = '?table',
+        fullscan = '?boolean',
+
+        mode = '?vshard_call_mode',
         prefer_replica = '?boolean',
         balance = '?boolean',
-        mode = '?vshard_call_mode',
+        timeout = '?number',
     })
 
     return sharding.wrap_method(select_module_call_xc, space_name, user_conditions, opts)

test/integration/read_calls_strategies_test.lua

@@ -78,7 +78,8 @@ pgroup.test_select = function(g)
     local _, err = g.cluster.main_server.net_box:call('crud.select', {'customers', nil, {
         mode = g.params.mode,
         balance = g.params.balance,
-        prefer_replica = g.params.prefer_replica
+        prefer_replica = g.params.prefer_replica,
+        fullscan = true,
     }})
     t.assert_equals(err, nil)
     local vshard_calls = g.get_vshard_calls('call_impl')

test/integration/reload_test.lua

@@ -93,7 +93,7 @@ function g.test_router()
 
     g.highload_fiber:cancel()
 
-    local result, err = g.router.net_box:call('crud.select', {'customers'})
+    local result, err = g.router.net_box:call('crud.select', {'customers', nil, {fullscan = true}})
     t.assert_equals(err, nil)
     t.assert_items_include(result.rows, g.insertions_passed)
 end
@@ -122,7 +122,7 @@ function g.test_storage()
 
     g.highload_fiber:cancel()
 
-    local result, err = g.router.net_box:call('crud.select', {'customers'})
+    local result, err = g.router.net_box:call('crud.select', {'customers', nil, {fullscan = true}})
     t.assert_equals(err, nil)
     t.assert_items_include(result.rows, g.insertions_passed)
 end