Skip to content

Commit b2ad688

Browse files
mblandmbland
authored
Merge pull request #28 from mbland/stack-trace
Improve stack trace API, add stack traces to FATAL log conditions
2 parents 7416a7a + 965782d commit b2ad688

File tree

9 files changed

+232
-39
lines changed

9 files changed

+232
-39
lines changed

‎go-core.bash‎

Lines changed: 23 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -141,16 +141,36 @@ declare _GO_SEARCH_PATHS=("$_GO_CORE_DIR/libexec")
141141

142142
# Prints the stack trace at the point of the call.
143143
#
144+
# If supplied, the `skip_callers` argument should be a positive integer (i.e. 1
145+
# or greater) to remove the caller (and possibly the caller's caller, and so on)
146+
# from the resulting stack trace.
147+
#
144148
# Arguments:
145-
# omit_caller: If set, this function's caller is removed from the output
149+
# skip_callers: The number of callers to skip over when printing the stack
146150
@go.print_stack_trace() {
147-
local start_index="${1:+2}"
151+
local skip_callers="$1"
152+
local result=0
148153
local i
149154

150-
for ((i=${start_index:-1}; i != ${#FUNCNAME[@]}; ++i)); do
155+
if [[ -n "$skip_callers" && ! "$skip_callers" =~ ^[1-9][0-9]*$ ]]; then
156+
@go.printf '%s argument %s not a positive integer; printing full stack\n' \
157+
"$FUNCNAME" "'$skip_callers'" >&2
158+
result=1
159+
elif [[ "$skip_callers" -ge "${#FUNCNAME[@]}" ]]; then
160+
@go.printf '%s argument %d exceeds stack size %d; printing full stack\n' \
161+
"$FUNCNAME" "$skip_callers" "$((${#FUNCNAME[@]} - 1))" >&2
162+
result=1
163+
fi
164+
165+
if [[ "$result" -ne '0' ]]; then
166+
skip_callers=0
167+
fi
168+
169+
for ((i=$skip_callers + 1; i != ${#FUNCNAME[@]}; ++i)); do
151170
@go.printf ' %s:%s %s\n' "${BASH_SOURCE[$i]}" "${BASH_LINENO[$((i-1))]}" \
152171
"${FUNCNAME[$i]}"
153172
done
173+
return "$result"
154174
}
155175

156176
# Main driver of ./go script functionality.

‎lib/internal/use‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -91,7 +91,7 @@ for __go_module_name in "$@"; do
9191

9292
if [[ ! -f "$__go_module_file" ]]; then
9393
@go.printf 'ERROR: Module %s not found at:\n' "$__go_module_name" >&2
94-
@go.print_stack_trace omit_caller >&2
94+
@go.print_stack_trace 1 >&2
9595
exit 1
9696
fi
9797
fi
@@ -100,7 +100,7 @@ for __go_module_name in "$@"; do
100100
if ! . "$__go_module_file"; then
101101
@go.printf 'ERROR: Failed to import %s module from %s at:\n' \
102102
"$__go_module_name" "$__go_module_file" >&2
103-
@go.print_stack_trace omit_caller >&2
103+
@go.print_stack_trace 1 >&2
104104
exit 1
105105
fi
106106
done

‎lib/log‎

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -96,6 +96,9 @@ declare __GO_LOG_LEVELS_FORMATTED=()
9696
# Set by @go.critical_section_{begin,end}
9797
declare __GO_CRITICAL_SECTION=0
9898

99+
# DO NOT EDIT: Determines number of stack trace levels to skip for FATAL logs.
100+
declare __GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS=1
101+
99102
# Outputs a single log line that may contain terminal control characters.
100103
#
101104
# Usage:
@@ -171,7 +174,8 @@ declare __GO_CRITICAL_SECTION=0
171174

172175
printf "$formatted_log_level ${args[*]}$close_code\n" >&"$level_fd"
173176

174-
if [[ "$log_level" == FATAL ]]; then
177+
if [[ "$log_level" == 'FATAL' ]]; then
178+
@go.print_stack_trace "$__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS" >&2
175179
exit "$exit_status"
176180
fi
177181
return "$exit_status"
@@ -190,18 +194,21 @@ declare __GO_CRITICAL_SECTION=0
190194
local log_level="$1"
191195
local format_code="$2"
192196
local level_fd="${3:-1}"
197+
((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
193198

194199
if [[ -n "$__GO_LOG_INIT" ]]; then
195-
@go.log 'FATAL' "Can't set logging level $log_level; already initialized"
200+
@go.log FATAL "Can't set logging level $log_level; already initialized"
196201
elif [[ "$level_fd" != 'keep' && ! "$level_fd" =~ ^[1-9]+[0-9]*$ ]]; then
197202
@go.log FATAL "File descriptor $level_fd for $log_level must be > 0"
198203
elif ! echo -n 2>/dev/null >&"$level_fd"; then
199204
@go.log FATAL "File descriptor $level_fd for $log_level isn't open"
200205
fi
206+
((--__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
201207

202208
local __go_log_level_index=0
203209
if ! _@go.log_level_index "$log_level"; then
204210
if [[ "$format_code" == 'keep' || "$level_fd" == 'keep' ]]; then
211+
((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
205212
@go.log FATAL "Can't keep defaults for nonexistent log level $log_level"
206213
fi
207214
_GO_LOG_LEVELS+=("$log_level")
@@ -270,6 +277,7 @@ declare __GO_CRITICAL_SECTION=0
270277

271278
if [[ "$exit_status" -ne '0' ]]; then
272279
if [[ "$__GO_CRITICAL_SECTION" -ne '0' ]]; then
280+
((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
273281
@go.log FATAL "$exit_status" "$cmd_string"
274282
fi
275283
@go.log ERROR "$exit_status" "$cmd_string"
@@ -312,17 +320,20 @@ declare __GO_CRITICAL_SECTION=0
312320

313321
@go.log START Project setup in "$_GO_ROOTDIR"
314322

323+
((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
315324
if [[ ! -f "$setup_script" ]]; then
316325
@go.log FATAL "Create $setup_script before invoking $FUNCNAME."
317326
elif [[ ! -x "$setup_script" ]]; then
318327
@go.log FATAL "$setup_script is not executable."
319328
fi
329+
((--__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
320330

321331
@go.log RUN "${setup_script#$_GO_ROOTDIR/}" "$@"
322332
_@go.run_command_script "$setup_script" "$@"
323333
setup_status="$?"
324334

325335
if [[ "$setup_status" -ne '0' ]]; then
336+
((++__GO_LOG_FATAL_STACK_TRACE_SKIP_CALLERS))
326337
@go.log FATAL "$setup_status" "Project setup failed"
327338
fi
328339

‎tests/core/print-stack-trace.bats‎

Lines changed: 44 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@ teardown() {
1313
}
1414

1515
@test "$SUITE: stack trace from top level of main ./go script without caller" {
16-
create_test_go_script '@go.print_stack_trace omit_caller'
16+
create_test_go_script '@go.print_stack_trace 1'
1717
run "$TEST_GO_SCRIPT"
1818
assert_success ''
1919
}
@@ -35,13 +35,45 @@ teardown() {
3535
@test "$SUITE: omit function caller from stack trace" {
3636
create_test_go_script \
3737
'print_stack() {' \
38-
" @go.print_stack_trace omit_caller" \
38+
" @go.print_stack_trace 1" \
3939
'}' \
4040
'print_stack'
4141
run "$TEST_GO_SCRIPT"
4242
assert_success " $TEST_GO_SCRIPT:6 main"
4343
}
4444

45+
@test "$SUITE: bad skip_callers argument prints entire trace" {
46+
create_test_go_script \
47+
'print_stack() {' \
48+
" @go.print_stack_trace foobar" \
49+
'}' \
50+
'print_stack'
51+
run "$TEST_GO_SCRIPT"
52+
53+
local error_msg=("@go.print_stack_trace argument 'foobar' not a positive"
54+
'integer; printing full stack')
55+
assert_failure
56+
assert_line_equals 0 "${error_msg[*]}"
57+
assert_line_equals 1 " $TEST_GO_SCRIPT:4 print_stack"
58+
assert_line_equals 2 " $TEST_GO_SCRIPT:6 main"
59+
}
60+
61+
@test "$SUITE: skipping too many callers prints entire trace" {
62+
create_test_go_script \
63+
'print_stack() {' \
64+
" @go.print_stack_trace 100" \
65+
'}' \
66+
'print_stack'
67+
run "$TEST_GO_SCRIPT"
68+
69+
local error_msg=('@go.print_stack_trace argument 100 exceeds stack size 2;'
70+
'printing full stack')
71+
assert_failure
72+
assert_line_equals 0 "${error_msg[*]}"
73+
assert_line_equals 1 " $TEST_GO_SCRIPT:4 print_stack"
74+
assert_line_equals 2 " $TEST_GO_SCRIPT:6 main"
75+
}
76+
4577
@test "$SUITE: stack trace from subcommand script" {
4678
create_test_go_script '@go "$@"'
4779
create_test_command_script 'foo' \
@@ -51,20 +83,19 @@ teardown() {
5183
'foo_func'
5284
create_test_command_script 'foo.d/bar' \
5385
'bar_func() {' \
54-
' @go.print_stack_trace omit_caller' \
86+
' @go.print_stack_trace 1' \
5587
'}' \
5688
'bar_func'
5789

5890
run "$TEST_GO_SCRIPT" foo
59-
60-
local go_core_pattern="$_GO_CORE_DIR/go-core.bash:[0-9]+"
6191
assert_success
62-
assert_line_equals 0 " $TEST_GO_SCRIPTS_DIR/foo.d/bar:5 source"
63-
assert_line_matches 1 " $go_core_pattern _@go.run_command_script"
64-
assert_line_matches 2 " $go_core_pattern @go"
65-
assert_line_equals 3 " $TEST_GO_SCRIPTS_DIR/foo:3 foo_func"
66-
assert_line_equals 4 " $TEST_GO_SCRIPTS_DIR/foo:5 source"
67-
assert_line_matches 5 " $go_core_pattern _@go.run_command_script"
68-
assert_line_matches 6 " $go_core_pattern @go"
69-
assert_line_equals 7 " $TEST_GO_SCRIPT:3 main"
92+
set_go_core_stack_trace_components
93+
94+
local IFS=$'\n'
95+
assert_lines_equal " $TEST_GO_SCRIPTS_DIR/foo.d/bar:5 source" \
96+
"${GO_CORE_STACK_TRACE_COMPONENTS[@]}" \
97+
" $TEST_GO_SCRIPTS_DIR/foo:3 foo_func" \
98+
" $TEST_GO_SCRIPTS_DIR/foo:5 source" \
99+
"${GO_CORE_STACK_TRACE_COMPONENTS[@]}" \
100+
" $TEST_GO_SCRIPT:3 main"
70101
}

‎tests/environment.bash‎

Lines changed: 89 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -81,3 +81,92 @@ create_parent_and_subcommands() {
8181
remove_test_go_rootdir() {
8282
remove_bats_test_dirs
8383
}
84+
85+
# Get the stack trace of a line from a file or function as it would appear in
86+
# @go.print_stack_trace output.
87+
#
88+
# Arguments:
89+
# haystack_file: File containing the line
90+
# function_name: Function in which the line appears, 'main', or 'source'
91+
# needle_line: Line for which to produce a stack trace line
92+
stack_trace_item() {
93+
# Seriously, it's faster to create a script containing a `for` or `while read`
94+
# loop over a file and run it as a new process than it is to run it in-process
95+
# under Bats. Haven't yet figured out why.
96+
create_bats_test_script 'stack-trace-item' \
97+
"$(declare -f __stack_trace_item_impl)" \
98+
'__stack_trace_item_impl "$@"'
99+
"$BATS_TEST_ROOTDIR/stack-trace-item" "$@"
100+
}
101+
102+
log_command_stack_trace_item() {
103+
if [[ -z "$LOG_COMMAND_STACK_TRACE_ITEM" ]]; then
104+
export LOG_COMMAND_STACK_TRACE_ITEM="$(stack_trace_item \
105+
"$_GO_CORE_DIR/lib/log" '@go.log_command' ' "${args[@]}"')"
106+
fi
107+
echo "$LOG_COMMAND_STACK_TRACE_ITEM"
108+
}
109+
110+
# Call this before using "${GO_CORE_STACK_TRACE_COMPONENTS[@]}" to inject
111+
# entries from go-core.bash into your expected stack trace output.
112+
set_go_core_stack_trace_components() {
113+
local go_core_file="$_GO_CORE_DIR/go-core.bash"
114+
local stack_item
115+
local IFS=$'\n'
116+
117+
if [[ "${#GO_CORE_STACK_TRACE_COMPONENTS[@]}" -eq '0' ]]; then
118+
create_test_go_script '@go "$@"'
119+
create_test_command_script 'print-stack-trace' '@go.print_stack_trace'
120+
121+
for stack_item in $("$TEST_GO_SCRIPT" 'print-stack-trace'); do
122+
if [[ "$stack_item" =~ $go_core_file ]]; then
123+
GO_CORE_STACK_TRACE_COMPONENTS+=("$stack_item")
124+
elif [[ "${#_GO_CORE_STACK_TRACE_COMPONENTS[@]}" -ne '0' ]]; then
125+
return
126+
fi
127+
done
128+
export GO_CORE_STACK_TRACE_COMPONENTS
129+
fi
130+
}
131+
132+
__stack_trace_item_impl() {
133+
local haystack_file="$1"
134+
local function_name="$2"
135+
local function_pattern="^$function_name\\(\\) ?{\$"
136+
local needle="$3"
137+
local skip
138+
local inside_function
139+
local lineno=0
140+
local line
141+
local result=1
142+
143+
if [[ "$function_name" == 'main' || "$function_name" == 'source' ]]; then
144+
inside_function='false'
145+
fi
146+
147+
local IFS=$'\n'
148+
while read -r line; do
149+
((++lineno))
150+
if [[ -n "$skip" ]]; then
151+
if [[ "$line" == '}' ]]; then
152+
skip=
153+
fi
154+
elif [[ -z "$inside_function" && "$line" =~ $function_pattern ]]; then
155+
inside_function='true'
156+
elif [[ "$line" =~ ()\ {$ ]]; then
157+
skip='true'
158+
elif [[ "$inside_function" == 'true' && "$line" == '}' ]]; then
159+
break
160+
elif [[ "$line" == "$needle" ]]; then
161+
result=0
162+
break
163+
fi
164+
done <"$haystack_file"
165+
166+
if [[ "$result" -eq '0' ]]; then
167+
echo " $haystack_file:$lineno $function_name"
168+
else
169+
printf "ERROR: Line not found in $function_name: \"$needle\"\nat:\n" >&2
170+
fi
171+
return "$result"
172+
}

‎tests/log/add-update.bats‎

Lines changed: 12 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -15,31 +15,38 @@ teardown() {
1515
'@go.add_or_update_log_level INFO keep keep'
1616
assert_failure
1717
assert_log_equals INFO 'Hello, World!' \
18-
FATAL "Can't set logging level INFO; already initialized"
18+
FATAL "Can't set logging level INFO; already initialized" \
19+
" $TEST_GO_SCRIPT:5 main"
1920
}
2021

2122
@test "$SUITE: fail if file descriptor isn't a positive integer" {
2223
run_log_script '@go.add_or_update_log_level INFO keep 0'
2324
assert_failure
24-
assert_log_equals FATAL "File descriptor 0 for INFO must be > 0"
25+
assert_log_equals FATAL "File descriptor 0 for INFO must be > 0" \
26+
" $TEST_GO_SCRIPT:4 main"
2527
}
2628

2729
@test "$SUITE: fail if file descriptor isn't open" {
2830
run_log_script '@go.add_or_update_log_level INFO keep 27'
2931
assert_failure
30-
assert_log_equals FATAL "File descriptor 27 for INFO isn't open"
32+
assert_log_equals FATAL "File descriptor 27 for INFO isn't open" \
33+
" $TEST_GO_SCRIPT:4 main"
3134
}
3235

3336
@test "$SUITE: fail if keeping the format code for a nonexistent level" {
3437
run_log_script '@go.add_or_update_log_level FOOBAR keep 1'
3538
assert_failure
36-
assert_log_equals FATAL "Can't keep defaults for nonexistent log level FOOBAR"
39+
assert_log_equals \
40+
FATAL "Can't keep defaults for nonexistent log level FOOBAR" \
41+
" $TEST_GO_SCRIPT:4 main"
3742
}
3843

3944
@test "$SUITE: fail if keeping the file descriptor for a nonexistent level" {
4045
run_log_script "@go.add_or_update_log_level FOOBAR '$INFO_FORMAT' keep"
4146
assert_failure
42-
assert_log_equals FATAL "Can't keep defaults for nonexistent log level FOOBAR"
47+
assert_log_equals \
48+
FATAL "Can't keep defaults for nonexistent log level FOOBAR" \
49+
" $TEST_GO_SCRIPT:4 main"
4350
}
4451

4552
@test "$SUITE: add new log level" {

0 commit comments

Comments
 (0)