log: Add stack trace to FATAL output

Also makes use of the `skip_callers` argument to `@go.print_stack_trace`
to ensure that the functions in this module will not appear in the stack
trace themselves whenever they invoke `@go.log FATAL`.

Author: mbland

lib/log

@@ -96,6 +96,9 @@ declare __GO_LOG_LEVELS_FORMATTED=()
 # Set by @go.critical_section_{begin,end}
 declare __GO_CRITICAL_SECTION=0
 
+# DO NOT EDIT: Determines number of stack trace levels to skip for FATAL logs.
+declare __GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS=1
+
 # Outputs a single log line that may contain terminal control characters.
 #
 # Usage:
@@ -171,7 +174,8 @@ declare __GO_CRITICAL_SECTION=0
 
   printf "$formatted_log_level ${args[*]}$close_code\n" >&"$level_fd"
 
-  if [[ "$log_level" == FATAL ]]; then
+  if [[ "$log_level" == 'FATAL' ]]; then
+    @go.print_stack_trace "$__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS" >&2
     exit "$exit_status"
   fi
   return "$exit_status"
@@ -190,18 +194,21 @@ declare __GO_CRITICAL_SECTION=0
   local log_level="$1"
   local format_code="$2"
   local level_fd="${3:-1}"
+  ((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
 
   if [[ -n "$__GO_LOG_INIT" ]]; then
-    @go.log 'FATAL' "Can't set logging level $log_level; already initialized"
+    @go.log FATAL "Can't set logging level $log_level; already initialized"
   elif [[ "$level_fd" != 'keep' && ! "$level_fd" =~ ^[1-9]+[0-9]*$ ]]; then
     @go.log FATAL "File descriptor $level_fd for $log_level must be > 0"
   elif ! echo -n 2>/dev/null >&"$level_fd"; then
     @go.log FATAL "File descriptor $level_fd for $log_level isn't open"
   fi
+  ((--__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
 
   local __go_log_level_index=0
   if ! _@go.log_level_index "$log_level"; then
     if [[ "$format_code" == 'keep' || "$level_fd" == 'keep' ]]; then
+      ((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
       @go.log FATAL "Can't keep defaults for nonexistent log level $log_level"
     fi
     _GO_LOG_LEVELS+=("$log_level")
@@ -270,6 +277,7 @@ declare __GO_CRITICAL_SECTION=0
 
   if [[ "$exit_status" -ne '0' ]]; then
     if [[ "$__GO_CRITICAL_SECTION" -ne '0' ]]; then
+      ((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
       @go.log FATAL "$exit_status" "$cmd_string"
     fi
     @go.log ERROR "$exit_status" "$cmd_string"
@@ -312,17 +320,20 @@ declare __GO_CRITICAL_SECTION=0
 
   @go.log START Project setup in "$_GO_ROOTDIR"
 
+  ((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
   if [[ ! -f "$setup_script" ]]; then
     @go.log FATAL "Create $setup_script before invoking $FUNCNAME."
   elif  [[ ! -x "$setup_script" ]]; then
     @go.log FATAL "$setup_script is not executable."
   fi
+  ((--__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
 
   @go.log RUN "${setup_script#$_GO_ROOTDIR/}" "$@"
   _@go.run_command_script "$setup_script" "$@"
   setup_status="$?"
 
   if [[ "$setup_status" -ne '0' ]]; then
+    ((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
     @go.log FATAL "$setup_status" "Project setup failed"
   fi
 

tests/log/add-update.bats

@@ -15,31 +15,38 @@ teardown() {
     '@go.add_or_update_log_level INFO keep keep'
   assert_failure
   assert_log_equals INFO 'Hello, World!' \
-    FATAL "Can't set logging level INFO; already initialized"
+    FATAL "Can't set logging level INFO; already initialized" \
+    "  $TEST_GO_SCRIPT:5 main"
 }
 
 @test "$SUITE: fail if file descriptor isn't a positive integer" {
   run_log_script '@go.add_or_update_log_level INFO keep 0'
   assert_failure
-  assert_log_equals FATAL "File descriptor 0 for INFO must be > 0"
+  assert_log_equals FATAL "File descriptor 0 for INFO must be > 0" \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
 @test "$SUITE: fail if file descriptor isn't open" {
   run_log_script '@go.add_or_update_log_level INFO keep 27'
   assert_failure
-  assert_log_equals FATAL "File descriptor 27 for INFO isn't open"
+  assert_log_equals FATAL "File descriptor 27 for INFO isn't open" \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
 @test "$SUITE: fail if keeping the format code for a nonexistent level" {
   run_log_script '@go.add_or_update_log_level FOOBAR keep 1'
   assert_failure
-  assert_log_equals FATAL "Can't keep defaults for nonexistent log level FOOBAR"
+  assert_log_equals \
+    FATAL "Can't keep defaults for nonexistent log level FOOBAR" \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
 @test "$SUITE: fail if keeping the file descriptor for a nonexistent level" {
   run_log_script "@go.add_or_update_log_level FOOBAR '$INFO_FORMAT' keep"
   assert_failure
-  assert_log_equals FATAL "Can't keep defaults for nonexistent log level FOOBAR"
+  assert_log_equals \
+    FATAL "Can't keep defaults for nonexistent log level FOOBAR" \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
 @test "$SUITE: add new log level" {

tests/log/log-command.bats

@@ -29,7 +29,8 @@ teardown() {
     '@go.critical_section_end'
   assert_failure
   assert_log_equals RUN 'failing_function foo bar baz' \
-    FATAL 'failing_function foo bar baz (exit status 127)'
+    FATAL 'failing_function foo bar baz (exit status 127)' \
+    "  $TEST_GO_SCRIPT:6 main"
 }
 
 @test "$SUITE: log single failing command without executing during dry run" {
@@ -79,7 +80,8 @@ teardown() {
   assert_log_equals RUN 'echo Hello, World!' \
     'Hello, World!' \
     RUN "failing_function foo bar baz" \
-    FATAL 'failing_function foo bar baz (exit status 127)'
+    FATAL 'failing_function foo bar baz (exit status 127)' \
+    "  $TEST_GO_SCRIPT:7 main"
 }
 
 @test "$SUITE: log multiple commands without executing during dry run" {
@@ -179,7 +181,8 @@ teardown() {
     RUN 'echo Hello, World!' \
     'Hello, World!' \
     RUN 'failing_function foo bar baz' \
-    FATAL 'failing_function foo bar baz (exit status 127)'
+    FATAL 'failing_function foo bar baz (exit status 127)' \
+    "  $TEST_GO_SCRIPT:12 main"
 }
 
 @test "$SUITE: critical section counter does not go below zero" {
@@ -200,7 +203,8 @@ teardown() {
     RUN 'failing_function foo bar baz' \
     ERROR 'failing_function foo bar baz (exit status 127)' \
     RUN 'failing_function foo bar baz' \
-    FATAL 'failing_function foo bar baz (exit status 127)'
+    FATAL 'failing_function foo bar baz (exit status 127)' \
+    "  $TEST_GO_SCRIPT:12 main"
 }
 
 @test "$SUITE: log and run command script using @go" {
@@ -228,9 +232,14 @@ teardown() {
 
   run test-go foo bar baz
   assert_failure
+  set_go_core_stack_trace_components
   assert_log_equals RUN 'test-go project-command-script foo bar baz' \
     RUN 'failing_function foo bar baz' \
-    FATAL 'failing_function foo bar baz (exit status 127)'
+    FATAL 'failing_function foo bar baz (exit status 127)' \
+    "  $TEST_GO_SCRIPTS_DIR/project-command-script:3 source" \
+    "${GO_CORE_STACK_TRACE_COMPONENTS[@]}" \
+    "$(log_command_stack_trace_item)" \
+    "  $TEST_GO_SCRIPT:5 main"
 }
 
 @test "$SUITE: critical section in command script applies to parent script" {
@@ -246,7 +255,12 @@ teardown() {
 
   run test-go foo bar baz
   assert_failure
+  set_go_core_stack_trace_components
   assert_log_equals RUN 'test-go project-command-script foo bar baz' \
     RUN 'failing_function foo bar baz' \
-    FATAL 'failing_function foo bar baz (exit status 127)'
+    FATAL 'failing_function foo bar baz (exit status 127)' \
+    "  $TEST_GO_SCRIPTS_DIR/project-command-script:4 source" \
+    "${GO_CORE_STACK_TRACE_COMPONENTS[@]}" \
+    "$(log_command_stack_trace_item)" \
+    "  $TEST_GO_SCRIPT:4 main"
 }

tests/log/main.bats

@@ -53,7 +53,8 @@ teardown() {
     '  @go.log INFO This line should be unreachable.' \
     'fi'
   assert_failure
-  assert_log_equals FATAL 'Hello, World!'
+  assert_log_equals FATAL 'Hello, World!' \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
 @test "$SUITE: show status on FATAL if supplied" {
@@ -62,7 +63,8 @@ teardown() {
     '  @go.log INFO This line should be unreachable.' \
     'fi'
   assert_failure
-  assert_log_equals FATAL 'Hello, World! (exit status 127)'
+  assert_log_equals FATAL 'Hello, World! (exit status 127)' \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
 @test "$SUITE: exit with error if num format codes != num log levels" {

tests/log/setup-project.bats

@@ -10,8 +10,11 @@ teardown() {
 @test "$SUITE: fail if no 'setup' script exists" {
   run_log_script '@go.setup_project setup Hello, World!'
   assert_failure
+
+  local setup_script="$TEST_GO_SCRIPTS_DIR/setup"
   assert_log_equals START "Project setup in $TEST_GO_ROOTDIR" \
-    FATAL "Create $TEST_GO_SCRIPTS_DIR/setup before invoking @go.setup_project."
+    FATAL "Create $setup_script before invoking @go.setup_project." \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
 @test "$SUITE: fail if the 'setup' script isn't executable" {
@@ -25,7 +28,8 @@ teardown() {
   run_log_script '@go.setup_project setup Hello, World!'
   assert_failure
   assert_log_equals START "Project setup in $TEST_GO_ROOTDIR" \
-    FATAL "$TEST_GO_SCRIPTS_DIR/setup is not executable."
+    FATAL "$TEST_GO_SCRIPTS_DIR/setup is not executable." \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
 @test "$SUITE: setup project successfully using ./go script directly" {
@@ -60,23 +64,38 @@ teardown() {
     INFO   "Run \`$TEST_GO_SCRIPT help\` to see the available commands."
 }
 
-@test "$SUITE: setup fails" {
+@test "$SUITE: setup fails due to @go.log ERROR" {
   create_test_command_script 'setup' '@go.log ERROR 127 "$@"'
   run_log_script '@go.setup_project setup foo bar baz'
   assert_failure
+  set_go_core_stack_trace_components
   assert_log_equals START "Project setup in $TEST_GO_ROOTDIR" \
     RUN    "${TEST_GO_SCRIPTS_RELATIVE_DIR}/setup foo bar baz" \
     ERROR  'foo bar baz (exit status 127)' \
-    FATAL  'Project setup failed (exit status 127)'
+    FATAL  'Project setup failed (exit status 127)' \
+    "  $TEST_GO_SCRIPT:4 main"
 }
 
-@test "$SUITE: Bash setup script exits directly" {
+@test "$SUITE: Bash setup script exits directly due to @go.log FATAL" {
   # Note that the "Project setup failed" message doesn't appear, because the
   # `setup` script was executed in the same Bash process.
   create_test_command_script 'setup' '@go.log FATAL 127 "$@"'
   run_log_script '@go.setup_project setup foo bar baz'
   assert_failure
+
+  local setup_project_stack_trace_item="$(stack_trace_item \
+    "$_GO_CORE_DIR/lib/log" '@go.setup_project' \
+    '  _@go.run_command_script "$setup_script" "$@"')"
+  local run_command_script_stack_trace_item
+
+  set_go_core_stack_trace_components
+  run_command_script_stack_trace_item="${GO_CORE_STACK_TRACE_COMPONENTS[0]}"
+
   assert_log_equals START "Project setup in $TEST_GO_ROOTDIR" \
     RUN    "${TEST_GO_SCRIPTS_RELATIVE_DIR}/setup foo bar baz" \
-    FATAL  'foo bar baz (exit status 127)'
+    FATAL  'foo bar baz (exit status 127)' \
+    "  $TEST_GO_SCRIPTS_DIR/setup:2 source" \
+    "$run_command_script_stack_trace_item" \
+    "$setup_project_stack_trace_item" \
+    "  $TEST_GO_SCRIPT:4 main"
 }