git/list[1] front-page[2] threads[3] people[4] search[5] about
 

[PATCH v1 07/25] structured-logging: t0420 basic tests

From
Ggit@jeffhostetler.com <git@jeffhostetler.com>
Date
Jul 13, 2018, 16:56 UTC
Message-ID
<20180713165621.52017-8-git@jeffhostetler.com>
In-Reply-To
<20180713165621.52017-1-git@jeffhostetler.com>
From: Jeff Hostetler <jeffhost@microsoft.com>

Add structured logging prereq definition "SLOG" to test-lib.sh. Create t0420 test script with some basic tests.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 t/t0420-structured-logging.sh | 143 ++++++++++++++++++++++++++++++++++++++++++
 t/t0420/parse_json.perl       |  52 +++++++++++++++
 t/test-lib.sh                 |   1 +
 3 files changed, 196 insertions(+)
 create mode 100755 t/t0420-structured-logging.sh
 create mode 100644 t/t0420/parse_json.perl
diff --git a/t/t0420-structured-logging.sh b/t/t0420-structured-logging.sh
new file mode 100755
index 0000000..a594af3
--- /dev/null
+++ b/t/t0420-structured-logging.sh
@@ -0,0 +1,143 @@
+#!/bin/sh
+
+test_description='structured logging tests'
+
+. ./test-lib.sh
+
+if ! test_have_prereq SLOG
+then
+	skip_all='skipping structured logging tests'
+	test_done
+fi
+
+LOGFILE=$TRASH_DIRECTORY/test.log
+
+test_expect_success 'setup' '
+	test_commit hello &&
+	cat >key_cmd_start <<-\EOF &&
+	"event":"cmd_start"
+	EOF
+	cat >key_cmd_exit <<-\EOF &&
+	"event":"cmd_exit"
+	EOF
+	cat >key_exit_code_0 <<-\EOF &&
+	"exit_code":0
+	EOF
+	cat >key_exit_code_129 <<-\EOF &&
+	"exit_code":129
+	EOF
+	git config --local slog.pretty false &&
+	git config --local slog.path "$LOGFILE"
+'
+
+test_expect_success 'basic events' '
+	test_when_finished "rm \"$LOGFILE\"" &&
+	git status >/dev/null &&
+	grep -f key_cmd_start "$LOGFILE" &&
+	grep -f key_cmd_exit "$LOGFILE" &&
+	grep -f key_exit_code_0 "$LOGFILE"
+'
+
+test_expect_success 'basic error code and message' '
+	test_when_finished "rm \"$LOGFILE\" event_exit" &&
+	test_expect_code 129 git status --xyzzy >/dev/null 2>/dev/null &&
+	grep -f key_cmd_exit "$LOGFILE" >event_exit &&
+	grep -f key_exit_code_129 event_exit &&
+	grep "\"errors\":" event_exit
+'
+
+test_lazy_prereq PERLJSON '
+	perl -MJSON -e "exit 0"
+'
+
+# Let perl parse the resulting JSON and dump it out.
+#
+# Since the output contains PIDs, SIDs, clock values, and the full path to
+# git[.exe] we cannot have a HEREDOC with the expected result, so we look
+# for a few key fields.
+#
+test_expect_success PERLJSON 'parse JSON for basic command' '
+	test_when_finished "rm \"$LOGFILE\" event_exit" &&
+	git status >/dev/null &&
+
+	grep -f key_cmd_exit "$LOGFILE" >event_exit &&
+
+	perl "$TEST_DIRECTORY"/t0420/parse_json.perl <event_exit >parsed_exit &&
+
+	grep "row\[0\]\.version\.slog 0" <parsed_exit &&
+	grep "row\[0\]\.argv\[1\] status" <parsed_exit &&
+	grep "row\[0\]\.event cmd_exit" <parsed_exit &&
+	grep "row\[0\]\.result\.exit_code 0" <parsed_exit &&
+	grep "row\[0\]\.command status" <parsed_exit
+'
+
+test_expect_success PERLJSON 'parse JSON for branch command/sub-command' '
+	test_when_finished "rm \"$LOGFILE\" event_exit" &&
+	git branch -v >/dev/null &&
+	git branch --all >/dev/null &&
+	git branch new_branch >/dev/null &&
+
+	grep -f key_cmd_exit "$LOGFILE" >event_exit &&
+
+	perl "$TEST_DIRECTORY"/t0420/parse_json.perl <event_exit >parsed_exit &&
+
+	grep "row\[0\]\.version\.slog 0" <parsed_exit &&
+	grep "row\[0\]\.argv\[1\] branch" <parsed_exit &&
+	grep "row\[0\]\.argv\[2\] -v" <parsed_exit &&
+	grep "row\[0\]\.event cmd_exit" <parsed_exit &&
+	grep "row\[0\]\.result\.exit_code 0" <parsed_exit &&
+	grep "row\[0\]\.command branch" <parsed_exit &&
+	grep "row\[0\]\.sub_command list" <parsed_exit &&
+
+	grep "row\[1\]\.argv\[1\] branch" <parsed_exit &&
+	grep "row\[1\]\.argv\[2\] --all" <parsed_exit &&
+	grep "row\[1\]\.event cmd_exit" <parsed_exit &&
+	grep "row\[1\]\.result\.exit_code 0" <parsed_exit &&
+	grep "row\[1\]\.command branch" <parsed_exit &&
+	grep "row\[1\]\.sub_command list" <parsed_exit &&
+
+	grep "row\[2\]\.argv\[1\] branch" <parsed_exit &&
+	grep "row\[2\]\.argv\[2\] new_branch" <parsed_exit &&
+	grep "row\[2\]\.event cmd_exit" <parsed_exit &&
+	grep "row\[2\]\.result\.exit_code 0" <parsed_exit &&
+	grep "row\[2\]\.command branch" <parsed_exit &&
+	grep "row\[2\]\.sub_command create" <parsed_exit
+'
+
+test_expect_success PERLJSON 'parse JSON for checkout command' '
+	test_when_finished "rm \"$LOGFILE\" event_exit" &&
+	git checkout new_branch >/dev/null &&
+	git checkout master >/dev/null &&
+	git checkout -- hello.t >/dev/null &&
+
+	grep -f key_cmd_exit "$LOGFILE" >event_exit &&
+
+	perl "$TEST_DIRECTORY"/t0420/parse_json.perl <event_exit >parsed_exit &&
+
+	grep "row\[0\]\.version\.slog 0" <parsed_exit &&
+	grep "row\[0\]\.argv\[1\] checkout" <parsed_exit &&
+	grep "row\[0\]\.argv\[2\] new_branch" <parsed_exit &&
+	grep "row\[0\]\.event cmd_exit" <parsed_exit &&
+	grep "row\[0\]\.result\.exit_code 0" <parsed_exit &&
+	grep "row\[0\]\.command checkout" <parsed_exit &&
+	grep "row\[0\]\.sub_command switch_branch" <parsed_exit &&
+
+	grep "row\[1\]\.version\.slog 0" <parsed_exit &&
+	grep "row\[1\]\.argv\[1\] checkout" <parsed_exit &&
+	grep "row\[1\]\.argv\[2\] master" <parsed_exit &&
+	grep "row\[1\]\.event cmd_exit" <parsed_exit &&
+	grep "row\[1\]\.result\.exit_code 0" <parsed_exit &&
+	grep "row\[1\]\.command checkout" <parsed_exit &&
+	grep "row\[1\]\.sub_command switch_branch" <parsed_exit &&
+
+	grep "row\[2\]\.version\.slog 0" <parsed_exit &&
+	grep "row\[2\]\.argv\[1\] checkout" <parsed_exit &&
+	grep "row\[2\]\.argv\[2\] --" <parsed_exit &&
+	grep "row\[2\]\.argv\[3\] hello.t" <parsed_exit &&
+	grep "row\[2\]\.event cmd_exit" <parsed_exit &&
+	grep "row\[2\]\.result\.exit_code 0" <parsed_exit &&
+	grep "row\[2\]\.command checkout" <parsed_exit &&
+	grep "row\[2\]\.sub_command path" <parsed_exit
+'
+
+test_done
diff --git a/t/t0420/parse_json.perl b/t/t0420/parse_json.perl
new file mode 100644
index 0000000..ca4e5bf
--- /dev/null
+++ b/t/t0420/parse_json.perl
@@ -0,0 +1,52 @@
+#!/usr/bin/perl
+use strict;
+use warnings;
+use JSON;
+
+sub dump_array {
+    my ($label_in, $ary_ref) = @_;
+    my @ary = @$ary_ref;
+
+    for ( my $i = 0; $i <= $#{ $ary_ref }; $i++ )
+    {
+	my $label = "$label_in\[$i\]";
+	dump_item($label, $ary[$i]);
+    }
+}
+
+sub dump_hash {
+    my ($label_in, $obj_ref) = @_;
+    my %obj = %$obj_ref;
+
+    foreach my $k (sort keys %obj) {
+	my $label = (length($label_in) > 0) ? "$label_in.$k" : "$k";
+	my $value = $obj{$k};
+
+	dump_item($label, $value);
+    }
+}
+
+sub dump_item {
+    my ($label_in, $value) = @_;
+    if (ref($value) eq 'ARRAY') {
+	print "$label_in array\n";
+	dump_array($label_in, $value);
+    } elsif (ref($value) eq 'HASH') {
+	print "$label_in hash\n";
+	dump_hash($label_in, $value);
+    } elsif (defined $value) {
+	print "$label_in $value\n";
+    } else {
+	print "$label_in null\n";
+    }
+}
+
+my $row = 0;
+while (<>) {
+    my $data = decode_json( $_ );
+    my $label = "row[$row]";
+
+    dump_hash($label, $data);
+    $row++;
+}
+
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 2831570..3d38bc7 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -1071,6 +1071,7 @@ test -n "$USE_LIBPCRE1$USE_LIBPCRE2" && test_set_prereq PCRE
 test -n "$USE_LIBPCRE1" && test_set_prereq LIBPCRE1
 test -n "$USE_LIBPCRE2" && test_set_prereq LIBPCRE2
 test -z "$NO_GETTEXT" && test_set_prereq GETTEXT
+test -z "$STRUCTURED_LOGGING" || test_set_prereq SLOG
 
 # Can we rely on git's output in the C locale?
 if test -n "$GETTEXT_POISON"
-- 
2.9.3
Previous: git@jeffhostetler.comNext: git@jeffhostetler.com
Message 10 of 38 in “RFC: structured logging”
  1. 00/25 RFC: structured logginggit@jeffhostetler.com, Jul 13, 2018
  2. 01/25 structured-logging: design documentgit@jeffhostetler.com, Jul 13, 2018
  3. Simon RuderichJul 14, 2018
  4. Ben PeartAug 3, 2018
  5. Jeff HostetlerAug 9, 2018
  6. Jonathan NiederAug 21, 2018
  7. 04/25 structured-logging: add session-id to log eventsgit@jeffhostetler.com, Jul 13, 2018
  8. 06/25 structured-logging: set sub_command field for checkout commandgit@jeffhostetler.com, Jul 13, 2018
  9. 08/25 structured-logging: add detail-event facilitygit@jeffhostetler.com, Jul 13, 2018
  10. 07/25 structured-logging: t0420 basic testsgit@jeffhostetler.com, Jul 13, 2018
  11. 10/25 structured-logging: add timer facilitygit@jeffhostetler.com, Jul 13, 2018
  12. 12/25 structured-logging: add timer around do_write_indexgit@jeffhostetler.com, Jul 13, 2018
  13. 14/25 structured-logging: add timer around preload_indexgit@jeffhostetler.com, Jul 13, 2018
  14. 16/25 structured-logging: add aux-data facilitygit@jeffhostetler.com, Jul 13, 2018
  15. 17/25 structured-logging: add aux-data for index sizegit@jeffhostetler.com, Jul 13, 2018
  16. 19/25 structured-logging: t0420 tests for aux-datagit@jeffhostetler.com, Jul 13, 2018
  17. 18/25 structured-logging: add aux-data for size of sparse-checkout filegit@jeffhostetler.com, Jul 13, 2018
  18. 20/25 structured-logging: add structured logging to remote-curlgit@jeffhostetler.com, Jul 13, 2018
  19. 23/25 structured-logging: t0420 tests for child process detail eventsgit@jeffhostetler.com, Jul 13, 2018
  20. 21/25 structured-logging: add detail-events for child processesgit@jeffhostetler.com, Jul 13, 2018
  21. 25/25 structured-logging: add config data facilitygit@jeffhostetler.com, Jul 13, 2018
  22. 22/25 structured-logging: add child process classificationgit@jeffhostetler.com, Jul 13, 2018
  23. 24/25 structured-logging: t0420 tests for interacitve child_summarygit@jeffhostetler.com, Jul 13, 2018
  24. 15/25 structured-logging: t0420 tests for timersgit@jeffhostetler.com, Jul 13, 2018
  25. 13/25 structured-logging: add timer around wt-status functionsgit@jeffhostetler.com, Jul 13, 2018
  26. 11/25 structured-logging: add timer around do_read_indexgit@jeffhostetler.com, Jul 13, 2018
  27. 09/25 structured-logging: add detail-event for lazy_init_name_hashgit@jeffhostetler.com, Jul 13, 2018
  28. 05/25 structured-logging: set sub_command field for branch commandgit@jeffhostetler.com, Jul 13, 2018
  29. 03/25 structured-logging: add structured logging frameworkgit@jeffhostetler.com, Jul 13, 2018
  30. SZEDER GáborJul 26, 2018
  31. Jeff HostetlerJul 27, 2018
  32. Jonathan NiederAug 21, 2018
  33. 02/25 structured-logging: add STRUCTURED_LOGGING=1 to Makefilegit@jeffhostetler.com, Jul 13, 2018
  34. Jonathan NiederAug 21, 2018
  35. David LangJul 13, 2018
  36. Jeff HostetlerJul 16, 2018
  37. Junio C HamanoAug 28, 2018
  38. Jeff HostetlerAug 28, 2018

Read the whole thread, see it on lore, or plain text.

$ cat FOOTERMessages come from the public archive at lore.kernel.org/git, fetched every hour. The front page is chosen and written each morning by an AI editor and can be wrong; the threads themselves are the record. About and API. For agents: an MCP server at https://gitlist.dev/mcp, and any thread, story or person page as Markdown by adding .md to its URL (or sending Accept: text/markdown). Details in /llms.txt.