Re: [PATCH v1 03/25] structured-logging: add structured logging framework

[Jonathan Nieder <jrnieder@gmail.com>]

Jeff Hostetler wrote:

[...]
> --- a/compat/mingw.h
> +++ b/compat/mingw.h
> @@ -144,8 +144,15 @@ static inline int fcntl(int fd, int cmd, ...)
>  	errno = EINVAL;
>  	return -1;
>  }
> +
>  /* bash cannot reliably detect negative return codes as failure */
> +#if defined(STRUCTURED_LOGGING)

Git usually spells this as #ifdef.

> +#include "structured-logging.h"
> +#define exit(code) exit(strlog_exit_code((code) & 0xff))
> +#else
>  #define exit(code) exit((code) & 0xff)
> +#endif

This is hard to follow, since it only makes sense in combination with
the corresponding code in git-compat-util.h.  Can they be defined
together?  If not, can they have comments to make it easier to know to
edit one too when editing the other?

[...]
> --- a/git-compat-util.h
> +++ b/git-compat-util.h
> @@ -1239,4 +1239,13 @@ extern void unleak_memory(const void *ptr, size_t len);
>  #define UNLEAK(var) do {} while (0)
>  #endif
>  
> +#include "structured-logging.h"

Is this #include needed?  Usually git-compat-util.h only defines C
standard library functions or utilities that are used everywhere.

[...]
> --- a/git.c
> +++ b/git.c
[...]
> @@ -700,7 +701,7 @@ static int run_argv(int *argcp, const char ***argv)
>  	return done_alias;
>  }
>  
> -int cmd_main(int argc, const char **argv)
> +static int real_cmd_main(int argc, const char **argv)
>  {
>  	const char *cmd;
>  	int done_help = 0;
> @@ -779,3 +780,8 @@ int cmd_main(int argc, const char **argv)
>  
>  	return 1;
>  }
> +
> +int cmd_main(int argc, const char **argv)
> +{
> +	return slog_wrap_main(real_cmd_main, argc, argv);
> +}

Can real_cmd_main get a different name, describing what it does?

[...]
> --- a/structured-logging.c
> +++ b/structured-logging.c
> @@ -1,3 +1,10 @@
[...]
> +static uint64_t my__start_time;
> +static uint64_t my__exit_time;
> +static int my__is_config_loaded;
> +static int my__is_enabled;
> +static int my__is_pretty;
> +static int my__signal;
> +static int my__exit_code;
> +static int my__pid;
> +static int my__wrote_start_event;
> +static int my__log_fd = -1;

Please don't use this my__ notation.  The inconsistency with the rest
of Git makes the code feel out of place and provides an impediment to
smooth reading.

[...]
> +static void emit_start_event(void)
> +{
> +	struct json_writer jw = JSON_WRITER_INIT;
> +
> +	/* build "cmd_start" event message */
> +	jw_object_begin(&jw, my__is_pretty);
> +	{
> +		jw_object_string(&jw, "event", "cmd_start");
> +		jw_object_intmax(&jw, "clock_us", (intmax_t)my__start_time);
> +		jw_object_intmax(&jw, "pid", (intmax_t)my__pid);

The use of blocks here is unexpected and makes me wonder what kind of
macro wizardry is going on.  Perhaps this is idiomatic for the
json-writer API; if so, can you add an example to json-writer.h to
help the next surprised reader?

That said, I think

	json_object_begin(&jw, ...);

	json_object_string(...
	json_object_int(...
	...

	json_object_begin_inline_array(&jw, "argv");
	for (k = 0; k < argv.argc; k++)
		json_object_string(...
	json_object_end(&jw);

	json_object_end(&jw);

is still readable and less unexpected.

[...]
> +static void emit_exit_event(void)
> +{
> +	struct json_writer jw = JSON_WRITER_INIT;
> +	uint64_t atexit_time = getnanotime() / 1000;
> +
> +	/* close unterminated forms */

What are unterminated forms?

> +	if (my__errors.json.len)
> +		jw_end(&my__errors);
[...]
> +int slog_default_config(const char *key, const char *value)
> +{
> +	const char *sub;
> +
> +	/*
> +	 * git_default_config() calls slog_default_config() with "slog.*"
> +	 * k/v pairs.  git_default_config() MAY or MAY NOT be called when
> +	 * cmd_<command>() calls git_config().

No need to shout.

[...]
> +/*
> + * If cmd_<command>() did not cause slog_default_config() to be called
> + * during git_config(), we try to lookup our config settings the first
> + * time we actually need them.
> + *
> + * (We do this rather than using read_early_config() at initialization
> + * because we want any "-c key=value" arguments to be included.)
> + */

Which function is initialization referring to here?

Lazy loading in order to guarantee loading after a different subsystem
sounds a bit fragile, so I wonder if we can make the sequencing more
explicit.

Stopping here.  I still like where this is going, but some aspects of
the coding style are making it hard to see the forest for the trees.
Perhaps some more details about API in the design doc would help.

Thanks and hope that helps,
Jonathan