[Tarantool-patches] [PATCH v4 4/4] crash: report crash data to the feedback server

[Vladislav Shpilevoy]

Thanks for the patch!

See 17 comments below.

On 10.12.2020 17:18, Cyrill Gorcunov wrote:
> We have a feedback server which gathers information about a running instnace.

1. instnace -> instance.

> While general info is enough for now we may loose a precious information about
> crashes (such as call backtrace which caused the issue, type of build and etc).
> 
> In the commit we add support of sending this kind of infomation to the feedback

2. infomation -> information.

It helps to write a commit message in an editor like Google Docs or your
local offline editor, and see all the highlighted errors, if you can't
get a spell checker working in vim or whatever you usually use.

> server. Internally we gather the reason of failure, pack it into base64 form
> and then run another tarantool instance which sends it out.
> 
> A typical report might look like
> 
>  | {
>  |   "crashdump": {
>  |     "version": "1",
>  |     "data": "eyJ1bmFtZSI6eyJzeXNuYW1lIjoiTGludXgiLCJyZWxlYXNlIjoiNS"
>  |             "45LjExLTEwMC5mYzMyLng4Nl82NCIsInZlcnNpb24iOiIjMSBTTVAg"
>  |             "VHVlIE5vdiAyNCAxOToxNjo1MyBVVEMgMjAyMCIsIm1hY2hpbmUiOi"
>  |             "J4ODZfNjQifSwiYnVpbGQiOnsidmVyc2lvbiI6IjIuNy4wLTgzLWc5"
>  |             "ZTg1MDM4ZmIiLCJjbWFrZV90eXBlIjoiTGludXgteDg2XzY0LURlYn"
>  |             "VnIn0sInNpZ25hbCI6eyJzaWdubyI6MTEsInNpX2NvZGUiOjAsInNp"
>  |             "X2FkZHIiOiIweDNlODAwMDVjOGE5IiwiYmFja3RyYWNlIjoiSXpBZ0"
>  |             "lEQjROak14WkRBeklHbHVJR055WVhOb1gyTnZiR3hsWTNRclltWUtJ"
>  |             "ekVnSURCNE5qTXlaV1JoSUdsdUlHTnlZWE5vWDNOcFoyNWhiRjlqWW"
>  |             "lzMU1Rb2pNaUFnTUhnM1pqRmtORGt5TXpsaE9UQWdhVzRnWm5WdWJH"
>  |             "OWphMlpwYkdVck5qQUtJek1nSURCNE4yWXhaRFE0WkdReFl6VmxJR2"
>  |             "x1SUdWd2IyeHNYM2RoYVhRck5XVUtJelFnSURCNE9ETTNOekV6SUds"
>  |             "dUlHVndiMnhzWDNCdmJHd3JPVGtLSXpVZ0lEQjRPRE5oWkRRNElHbH"
>  |             "VJR1YyWDNKMWJpczBPRGNLSXpZZ0lEQjROakJtTUdGbElHbHVJSFJo"
>  |             "Y21GdWRHOXZiRjlzZFdGZmNuVnVYM05qY21sd2RDc3hNemdLSXpjZ0"
>  |             "lEQjRORFEyTldZMUlHbHVJRzFoYVc0ck5XRmpDaU00SUNBd2VEZG1N"
>  |             "V1EwT0dObU56QTBNaUJwYmlCZlgyeHBZbU5mYzNSaGNuUmZiV0ZwYm"
>  |             "l0bU1nb2pPU0FnTUhnME5EUmhNR1VnYVc0Z1gzTjBZWEowS3pKbENn"
>  |             "PT0iLCJ0aW1lc3RhbXAiOiIyMDIwLTEyLTEwIDE3OjA4OjQyIE1TSyJ9fQ=="
>  |   }
>  | }
> 
> The `data` value is a single string I wrapped it for commit message only.
> When `data` is decoded it consists of
> 
>  | {
>  |   "uname": {
>  |     "sysname": "Linux",
>  |     "release": "5.9.11-100.fc32.x86_64",
>  |     "version": "#1 SMP Tue Nov 24 19:16:53 UTC 2020",
>  |     "machine": "x86_64"
>  |   },
>  |   "build": {
>  |     "version": "2.7.0-83-g9e85038fb",
>  |     "cmake_type": "Linux-x86_64-Debug"
>  |   },
>  |   "signal": {
>  |     "signo": 11,
>  |     "si_code": 0,
>  |     "si_addr": "0x3e80005c8a9",
>  |     "backtrace": "IzAgIDB4NjMxZDAzIGluIGNyYXNoX2NvbGxlY3QrYmYKIzEgID"
>  |                  "B4NjMyZWRhIGluIGNyYXNoX3NpZ25hbF9jYis1MQojMiAgMHg3ZjFkNDkyMzlhO"
>  |                  "TAgaW4gZnVubG9ja2ZpbGUrNjAKIzMgIDB4N2YxZDQ4ZGQxYzVlIGluIGVwb2xs"
>  |                  "X3dhaXQrNWUKIzQgIDB4ODM3NzEzIGluIGVwb2xsX3BvbGwrOTkKIzUgIDB4ODN"
>  |                  "hZDQ4IGluIGV2X3J1bis0ODcKIzYgIDB4NjBmMGFlIGluIHRhcmFudG9vbF9sdW"
>  |                  "FfcnVuX3NjcmlwdCsxMzgKIzcgIDB4NDQ2NWY1IGluIG1haW4rNWFjCiM4ICAwe"
>  |                  "DdmMWQ0OGNmNzA0MiBpbiBfX2xpYmNfc3RhcnRfbWFpbitmMgojOSAgMHg0NDRh"
>  |                  "MGUgaW4gX3N0YXJ0KzJlCg==",
>  |     "timestamp": "2020-12-10 17:08:42 MSK"
>  |   }
>  | }

3. And what is the reason you encode it all into base64 second time?

> The `backtrace` istself is encoded as base64 because of newline symbols
> (and may comprise some nonascii symbols as well).
> 
> There is no simple way to test this so I did it manually:
> 1) Run instance with
> 
> 	box.cfg{log_level = 8, feedback_host="127.0.0.1:1500"}
> 
> 2) Run listener shell as
> 
> 	while true ; do nc -l -p 1500 -c 'echo -e "HTTP/1.1 200 OK\n\n $(date)"'; done
> 
> 3) Send SIGSEGV
> 
> 	kill -11 `pidof tarantool`
> 
> Once SIGSEGV is delivered the crashinfo data is generated and sent out. For
> debug purpose this data is also printed to the terminal on debug log level.
> 
> Closes #5261
> 
> Signed-off-by: Cyrill Gorcunov <gorcunov at gmail.com>
> 
> @TarantoolBot document
> Title: Configuration update, allow to disable sending crash information
> 
> For better analisys of program crashes the information associated with

4. analisys -> analysis.

> the crash such as
> 
>  - utsname (similar to `uname -a` output except the network name)
>  - build information
>  - reason for a crash
>  - call backtrace
> 
> is sent to the feedback server. To disable it set `feedback_no_crashinfo`
> to `false`.

5. Doesn't the name look wrong to you? To disable something you propose
to set 'no' to 'false'. No_crashinfo = false. It is the same as
crashinfo = true. Vice versa.

I propose not to use 'no' in option names, as it is always confusing.
crashinfo = false means don't send anything, true means send.

> ---
>  src/box/lua/feedback_daemon.lua |   7 +
>  src/box/lua/load_cfg.lua        |   3 +
>  src/exports.h                   |   1 +
>  src/lib/core/CMakeLists.txt     |   2 +-
>  src/lib/core/crash.c            | 263 ++++++++++++++++++++++++++++++++
>  src/lib/core/crash.h            |  12 ++
>  src/main.cc                     |   1 +
>  test/box/admin.result           |   2 +
>  test/box/cfg.result             |   4 +
>  9 files changed, 294 insertions(+), 1 deletion(-)
> 
> diff --git a/src/box/lua/feedback_daemon.lua b/src/box/lua/feedback_daemon.lua
> index 1d39012ed..ae4d1a25f 100644
> --- a/src/box/lua/feedback_daemon.lua
> +++ b/src/box/lua/feedback_daemon.lua
> @@ -360,12 +361,18 @@ local function reload(self)
>      self:start()
>  end
>  
> +ffi.cdef[[
> +void
> +crash_cfg(void);
> +]]
> +
>  setmetatable(daemon, {
>      __index = {
>          set_feedback_params = function()
>              daemon.enabled  = box.cfg.feedback_enabled
>              daemon.host     = box.cfg.feedback_host
>              daemon.interval = box.cfg.feedback_interval
> +            ffi.C.crash_cfg()

6. I realized just now that your new option has nothing to do with
the feedback daemon except the option name and the URL.

You probably should configure it via Lua C, just like almost all
the other box.cfg options do.

>              reload(daemon)
>              return
>          end,
> diff --git a/src/lib/core/crash.c b/src/lib/core/crash.c
> index 9572a023c..06cc240a4 100644
> --- a/src/lib/core/crash.c
> +++ b/src/lib/core/crash.c
> @@ -7,16 +7,28 @@
>  #include <string.h>
>  #include <unistd.h>
>  #include <time.h>
> +#include <sys/types.h>
> +#include <sys/utsname.h>
>  
> +#include "third_party/base64.h"
> +#include "small/static.h"
>  #include "trivia/util.h"
>  #include "backtrace.h"
>  #include "crash.h"
> +#include "cfg.h"

7. By using 'cfg' here and linking with 'misc' you introduce a cyclic
dependency. Because 'cfg' module is a part of 'server' library.
'Server' depends on 'core', which has the new crash handling system.
Also you start depending on Lua here, because 'cfg' uses Lua inside.

In addition, 'cfg' depends on box, although implicitly. Because it
takes the config options from box.cfg. I suggest you to configure this
module like other modules - via crash_cfg_*() functions. Or pass
the options as arguments into one crash_cfg().

>  #include "say.h"
>  
>  #define pr_fmt(fmt)		"crash: " fmt
> +#define pr_debug(fmt, ...)	say_debug(pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_info(fmt, ...)	say_info(pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_err(fmt, ...)	say_error(pr_fmt(fmt), ##__VA_ARGS__)
>  #define pr_syserr(fmt, ...)	say_syserror(pr_fmt(fmt), ##__VA_ARGS__)
> +#define pr_crit(fmt, ...)	fprintf(stderr, pr_fmt(fmt) "\n", ##__VA_ARGS__)
>  #define pr_panic(fmt, ...)	panic(pr_fmt(fmt), ##__VA_ARGS__)
>  
> @@ -88,6 +104,72 @@ static struct crash_info {
>  #endif
>  } crash_info;
>  
> +static char tarantool_path[PATH_MAX];
> +static char feedback_host[2048];

8. I don't like that you just added +6KB to the process
size, not counting tons of other memory such as backtrace
buffer (+4KB), lots of 8 byte registers, and so on, when
we fight for each byte. At least +10KB in total. But I
have no a good idea how to fix it.

> +static bool send_crashinfo = true;
> +
> +static inline uint64_t
> +timespec_to_ns(struct timespec *ts)
> +{
> +	return (uint64_t)ts->tv_sec * 1000000000 + (uint64_t)ts->tv_nsec;
> +}
> @@ -126,6 +214,179 @@ crash_collect(int signo, siginfo_t *siginfo, void *ucontext)
>  	return cinfo;
>  }
>  
> +/**
> + * Report crash information to the feedback daemon
> + * (ie send it to feedback daemon).
> + */
> +static void
> +crash_report_feedback_daemon(struct crash_info *cinfo)
> +{
> +	/*
> +	 * Update to a new number if format get changed.
> +	 */
> +	static const int crashinfo_version = 1;

9. Why is it static? I suspect we discussed that at least 4
times ...

> +
> +	char *p = static_alloc(SMALL_STATIC_SIZE);
> +	char *e = &p[SMALL_STATIC_SIZE - 1];
> +	char *head = p;
> +	char *tail = &p[SMALL_STATIC_SIZE - 8];

10. Why -8?

> +
> +	/*
> +	 * Note that while we encode the report we
> +	 * intensively use a tail of the allocated
> +	 * buffer as a temporary store.
> +	 */
> +
> +#define snprintf_safe(fmt, ...)					\
> +	do {							\
> +		p += snprintf(p, e - p, fmt, ##__VA_ARGS__);	\
> +		if (p >= e)					\
> +			goto out;				\
> +	} while (0)
> +
> +	/*
> +	 * Lets reuse tail of the buffer as a temp space.
> +	 */
> +	struct utsname *uname_ptr = (void *)&tail[-sizeof(struct utsname)];
> +	if (p >= (char *)(void *)uname_ptr)

11. Why do you need double cast? I can't imagine that it does anything
except adds confusion.

> +		goto out;
> +
> +	if (uname(uname_ptr) != 0) {
> +		pr_syserr("uname call failed, ignore");
> +		memset(uname_ptr, 0, sizeof(struct utsname));
> +	}
> +
> +	snprintf_safe("{");

12. snprintf_safe uses memory [begin, e]. Where 'begin' is the initial
value of 'p'. 'uname_ptr' occupies [e - 7 - sizeof(*uname_ptr), e - 7].
Assume static size is 12KB, and sizeof(*uname_ptr) is 640.

[begin = 0,              snprintf                          e = 12287]
                                    [11640      uname        12280]

So snprintf and uname buffers intersect. If there is a big enough dump,
it will corrupt uname object.

Is it correct?

> +	snprintf_safe("\"uname\":{");
> +	snprintf_safe("\"sysname\":\"%s\",", uname_ptr->sysname);
> +	/*
> +	 * nodename might a sensitive information, skip.
> +	 */
> +	snprintf_safe("\"release\":\"%s\",", uname_ptr->release);
> +	snprintf_safe("\"version\":\"%s\",", uname_ptr->version);
> +	snprintf_safe("\"machine\":\"%s\"", uname_ptr->machine);
> +	snprintf_safe("},");
> +
> +	if (p >= (char *)(void *)uname_ptr)
> +		goto out;
> +
> +	snprintf_safe("\"build\":{");
> +	snprintf_safe("\"version\":\"%s\",", PACKAGE_VERSION);
> +	snprintf_safe("\"cmake_type\":\"%s\"", BUILD_INFO);
> +	snprintf_safe("},");
> +
> +	snprintf_safe("\"signal\":{");
> +	snprintf_safe("\"signo\":%d,", cinfo->signo);
> +	snprintf_safe("\"si_code\":%d,", cinfo->sicode);
> +	if (cinfo->signo == SIGSEGV) {
> +		if (cinfo->sicode == SEGV_MAPERR) {
> +			snprintf_safe("\"si_code_str\":\"%s\",",
> +				      "SEGV_MAPERR");
> +		} else if (cinfo->sicode == SEGV_ACCERR) {
> +			snprintf_safe("\"si_code_str\":\"%s\",",
> +				      "SEGV_ACCERR");
> +		}
> +		snprintf_safe("\"si_addr\":\"0x%llx\",",
> +			      (long long)cinfo->siaddr);
> +	}

13. Instead of using all these global many KB buffers you
could also create a pipe to the new process, which the
child would read as stdin from Lua, without any tiny limits
on how many KBs it can use. And do write() to it directly.

> +
> +#ifdef ENABLE_BACKTRACE
> +	/*
> +	 * The backtrace itself is encoded into base64 form
> +	 * since it might have arbitrary symbols not suitable
> +	 * for json encoding (newlines and etc).
> +	 */
> +	size_t bt_len = strlen(cinfo->backtrace_buf);
> +	size_t bt_elen = base64_bufsize(bt_len, BASE64_NOWRAP);
> +	char *bt_base64 = &tail[-bt_elen-8];
> +	if (p >= bt_base64)
> +		goto out;
> +	base64_encode(cinfo->backtrace_buf, bt_len,
> +		      bt_base64, bt_elen, BASE64_NOWRAP);
> +	bt_base64[bt_elen] = '\0';
> +	snprintf_safe("\"backtrace\":\"%s\",", bt_base64);
> +#endif
> +
> +	char *timestamp_rt_str = &tail[-128];
> +	if (p >= timestamp_rt_str)
> +		goto out;
> +	ns_to_localtime(cinfo->timestamp_rt, timestamp_rt_str, 128);

14. Why 128? And why is it hardcoded?

> +	snprintf_safe("\"timestamp\":\"%s\"", timestamp_rt_str);
> +	snprintf_safe("}");
> +	snprintf_safe("}");
> +
> +	size_t report_len = p - head;
> +	size_t report_elen = base64_bufsize(report_len, BASE64_NOWRAP);
> +
> +	char *report_base64 = &tail[-report_elen-8];

15. Why -8?

16. What if report_elen is bigger than *uname_ptr? Will you override
the output buffer even more?

> +	if (p >= report_base64)
> +		goto out;
> +	base64_encode(head, report_len, report_base64,
> +		      report_elen, BASE64_NOWRAP);
> +	report_base64[report_elen] = '\0';
> +
> +	/*
> +	 * Encoded report now sits at report_base64 position,
> +	 * at the tail of 'small' static buffer. Lets prepare
> +	 * the script to run (make sure the strings do not
> +	 * overlap).
> +	 */
> +	p = head;
> +	snprintf_safe("require(\'http.client\').post(\'%s\',"
> +		      "'{\"crashdump\":{\"version\":\"%d\","
> +		      "\"data\":", feedback_host,
> +		      crashinfo_version);
> +	if (report_base64 - p <= (long)(report_elen - 2))
> +		goto out;
> +	snprintf_safe("\"%s\"", report_base64);
> +	snprintf_safe("}}',{timeout=1}); os.exit(1);");
> +
> +	pr_debug("crashinfo script: %s", head);
> +
> +	char *exec_argv[4] = {
> +		[0] = tarantool_path,
> +		[1] = "-e",
> +		[2] = head,
> +		[3] = NULL,
> +	};
> +
> +	/*
> +	 * Can't use fork here because libev has own
> +	 * at_fork helpers with mutex where we might
> +	 * stuck (see popen code).
> +	 */
> +	pid_t pid = vfork();
> +	if (pid == 0) {
> +		/*
> +		 * The script must exit at the end but there
> +		 * is no simple way to make sure from inside
> +		 * of a signal crash handler. So just hope it
> +		 * is running fine.
> +		 */
> +		execve(exec_argv[0], exec_argv, NULL);
> +		pr_crit("exec(%s,[%s,%s,%s,NULL]) failed",
> +			exec_argv[0], exec_argv[0],
> +			exec_argv[1], exec_argv[2]);

17. What will happen if this tarantool also will crash? Will there
be an infinite chain of crashes? For instance, if we will have an
issue with curl again. Or somebody else will build with his own
curl leading to a crash on any usage, like it already happened one
time.

> +		_exit(1);
> +	} else if (pid < 0) {
> +		pr_crit("unable to vfork (errno %d)", errno);
> +	}