Log potentially long select calls

Potentially long select calls on user spaces tend to be dangerous.

A critical log entry containing the current stack traceback is created
upon potentially long 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][2].

1. tarantool/tarantool#7064
2. tarantool/tarantool#7131

Part of #276

CHANGELOG.md

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

README.md

@@ -54,7 +54,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, {first = 2})
 res
 ---
 - metadata:
@@ -426,6 +426,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 a critical log entry will be skipped
+    on potentially long `select`, see [avoiding full scan](https://github.com/tarantool/crud/blob/master/doc/select.md#avoiding-full-scan).
   * `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
@@ -448,7 +450,7 @@ Each condition is a table `{operator, field-identifier, value}`:
 **Example:**
 
 ```lua
-crud.select('customers', {{'<=', 'age', 35}})
+crud.select('customers', {{'<=', 'age', 35}}, {first = 10})
 ---
 - metadata:
   - {'name': 'id', 'type': 'unsigned'}
@@ -472,8 +474,10 @@ See more examples of select queries [here.](https://github.com/tarantool/crud/bl
 ### Pairs
 
 You can iterate across a distributed space using the `crud.pairs` function.
-Its arguments are the same as [`crud.select`](#select) arguments,
-but negative `first` values aren't allowed.
+Its arguments are the same as [`crud.select`](#select) arguments except
+`fullscan` (it does not exist because `crud.pairs` does not generate a critical
+log entry on potentially long requests) and negative `first` values aren't
+allowed.
 User could pass use_tomap flag (false by default) to iterate over flat tuples or objects.
 
 **Example:**
@@ -573,15 +577,15 @@ Returns true or nil with error.
 **Example:**
 
 ```lua
-#crud.select('customers', {{'<=', 'age', 35}})
+#crud.select('customers', {{'<=', 'age', 35}}, {first = 10})
 ---
 - 1
 ...
 crud.truncate('customers', {timeout = 2})
 ---
 - true
 ...
-#crud.select('customers', {{'<=', 'age', 35}})
+#crud.select('customers', {{'<=', 'age', 35}}, {first = 10})
 ---
 - 0
 ...
@@ -609,7 +613,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,125 @@
+-- Mostly it's a copy-paste from tarantool/tarantool log.lua:
+-- https://github.com/tarantool/tarantool/blob/29654ffe3638e5a218dd32f1788830ff05c1c05c/src/lua/log.lua
+--
+-- We have three reasons for the copy-paste:
+-- 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/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_enabled = true
+
+local function ratelimit_enable()
+    ratelimit_enabled = true
+end
+
+local function ratelimit_disable()
+    ratelimit_enabled = false
+end
+
+local Ratelimit = {
+    interval = 60,
+    burst = 10,
+    emitted = 0,
+    suppressed = 0,
+    start = 0,
+}
+
+local function ratelimit_new(object)
+    return Ratelimit:new(object)
+end
+
+function Ratelimit:new(object)
+    object = object or {}
+    setmetatable(object, self)
+    self.__index = self
+    return object
+end
+
+function Ratelimit:check()
+    if not ratelimit_enabled then
+        return 0, true
+    end
+
+    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 {
+    new = ratelimit_new,
+    enable = ratelimit_enable,
+    disable = ratelimit_disable,
+}

crud/select/compat/common.lua

@@ -1,6 +1,28 @@
+local ratelimit = require('crud.ratelimit')
+local check_select_safety_rl = ratelimit.new()
+
 local common = {}
 
 common.SELECT_FUNC_NAME = '_crud.select_on_storage'
 common.DEFAULT_BATCH_SIZE = 100
 
+common.check_select_safety = function(space_name, plan, opts)
+    if opts.fullscan == true then
+        return
+    end
+
+    if opts.first ~= nil and math.abs(opts.first) <= 1000 then
+        return
+    end
+
+    local iter = plan.tarantool_iter
+    if iter == box.index.EQ or iter == box.index.REQ then
+        return
+    end
+
+    local rl = check_select_safety_rl
+    local traceback = debug.traceback()
+    rl:log_crit("Potentially long select from space '%s'\n %s", space_name, traceback)
+end
+
 return common

crud/select/compat/select.lua

@@ -180,6 +180,7 @@ local function build_select_iterator(space_name, user_conditions, opts)
     return {
         tuples_limit = tuples_limit,
         merger = merger,
+        plan = plan,
         space_format = filtered_space_format,
     }
 end
@@ -252,14 +253,16 @@ 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',
     })
 
     opts = opts or {}
@@ -292,6 +295,7 @@ local function select_module_call_xc(space_name, user_conditions, opts)
     if err ~= nil then
         return nil, err
     end
+    common.check_select_safety(space_name, iter.plan, opts)
 
     local tuples = {}
 

crud/select/compat/select_old.lua

@@ -332,6 +332,7 @@ local function select_module_call_xc(space_name, user_conditions, opts)
     if err ~= nil then
         return nil, err
     end
+    common.check_select_safety(space_name, iter.plan, opts)
 
     local tuples = {}
 
@@ -366,14 +367,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)

doc/pairs.md

@@ -1,7 +1,8 @@
 # Pairs examples
 
 With ``crud.pairs``, you can iterate across a distributed space.  
-The arguments are the same as [``crud.select``](https://github.com/tarantool/crud/blob/master/doc/select.md), except of the ``use_tomap`` parameter.  
+The arguments are the same as [``crud.select``](https://github.com/tarantool/crud/blob/master/doc/select.md) arguments except ``fullscan`` (it does not exist because ``crud.pairs`` does not generate a critical log entry on potentially long requests) and negative ``first`` values aren't allowed.
+User could pass ``use_tomap`` flag (false by default) to iterate over flat tuples or objects.
 Below are examples that may help you.
 Examples schema is similar to the [select documentation](select.md/#examples-space-format)