Why is the DEBUG trap executed more times than expected?

Question

The following code triggers the debug trap 3 times. I am however expecting only 2 executions - one for foo, the second for echo hello:

foo() {
    echo hello
}

set -T
trap 'echo oops' DEBUG
foo

Output:

oops
oops
oops
hello

Expected output:

oops
oops
hello

---

Bash versions tested:

GNU bash, version 4.3.30(1)-release (x86_64-unknown-linux-gnu)
GNU bash, version 4.4.19(1)-release (x86_64-pc-linux-gnu)
GNU bash, version 5.0.0(1)-alpha (x86_64-pc-linux-gnu)

I am pretty sure I just misunderstood the manual and that I am missing something really simple/obvious here.

Answer 1

tl;dr: Bash runs the debug trap one extra time when invoking a function to allow breaking on the function itself rather than its first command. Here's from the source code's execute_function used to invoke a bash function:

  /* Run the debug trap here so we can trap at the start of a function's
     execution rather than the execution of the body's first command. */

---

Source diving time

Here is the code that executes debug traps:

int run_debug_trap () {
/* (...) */
    trap_exit_value = _run_trap_internal (DEBUG_TRAP, "debug trap");

I put a breakpoint on that line, trap.c:1081 as of today, and had a look at the backtraces:

First instance

Breakpoint 1, run_debug_trap () at trap.c:1081
1081          trap_exit_value = _run_trap_internal (DEBUG_TRAP, "debug trap");
(gdb) where
#0  run_debug_trap () at trap.c:1081
#1  0x000055555559fd3d in execute_simple_command (simple_command=0x5555558aacc8, pipe_in=-1, pipe_out=-1, async=0, fds_to_close=0x555555899148) at execute_cmd.c:4056
#2  0x0000555555599fd7 in execute_command_internal (command=0x5555558aae08, asynchronous=0, pipe_in=-1, pipe_out=-1, fds_to_close=0x555555899148) at execute_cmd.c:807
#3  0x00005555555995c1 in execute_command (command=0x5555558aae08) at execute_cmd.c:405
#4  0x0000555555583c9e in reader_loop () at eval.c:180
#5  0x0000555555581794 in main (argc=2, argv=0x7fffffffe4d8, env=0x7fffffffe4f0) at shell.c:792
(gdb) up
#1  0x000055555559fd3d in execute_simple_command (simple_command=0x5555558aacc8, pipe_in=-1, pipe_out=-1, async=0, fds_to_close=0x555555899148) at execute_cmd.c:4056
4056      result = run_debug_trap ();

(gdb) print *simple_command->words->word
$3 = {word = 0x5555558a5268 "foo", flags = 0}

In other words, this is the simple command foo. So far so good.

Second instance

Breakpoint 1, run_debug_trap () at trap.c:1081
1081          trap_exit_value = _run_trap_internal (DEBUG_TRAP, "debug trap");
(gdb) where
#0  run_debug_trap () at trap.c:1081
#1  0x00005555555a170a in execute_function (var=0x5555558ab648, words=0x5555558aac28, flags=0, fds_to_close=0x555555899148, async=0, subshell=0) at execute_cmd.c:4787
#2  0x00005555555a1c68 in execute_builtin_or_function (words=0x5555558aac28, builtin=0x0, var=0x5555558ab648, redirects=0x0, fds_to_close=0x555555899148, flags=0) at execute_cmd.c:5030
#3  0x00005555555a0660 in execute_simple_command (simple_command=0x5555558aacc8, pipe_in=-1, pipe_out=-1, async=0, fds_to_close=0x555555899148) at execute_cmd.c:4330
#4  0x0000555555599fd7 in execute_command_internal (command=0x5555558aae08, asynchronous=0, pipe_in=-1, pipe_out=-1, fds_to_close=0x555555899148) at execute_cmd.c:807
#5  0x00005555555995c1 in execute_command (command=0x5555558aae08) at execute_cmd.c:405
#6  0x0000555555583c9e in reader_loop () at eval.c:180
#7  0x0000555555581794 in main (argc=2, argv=0x7fffffffe4d8, env=0x7fffffffe4f0) at shell.c:792

This is more interesting. We're still executing the simple command foo from before, but it's triggering again! Why though? Let's have a look at the call site, execute_cmd.c:4787:

  /* Run the debug trap here so we can trap at the start of a function's
     execution rather than the execution of the body's first command. */
  showing_function_line = 1;
  save_current = currently_executing_command;
  result = run_debug_trap ();

In other words, Bash appears to intentionally run the debug trap one additional time for the purpose of breaking on a function rather than its first command.

Third instance

Is unsurprisingly the function's echo command, so I won't include it.

Answer 2

I assume you understand that DEBUG trap enables running the command defined within its definition ( trap 'action' signal) before every other shell command and set -T enables the trap to all sub-shells and functions also. So once you set the trap you have three executions happening.

1. Call to the function foo, before which once the trap is fired resulting in first instance of the printing the string.
2. And then you have an echo oops command inside the trap definition where is echo is just another command, so before running it the trap is fired.
3. And the actual echo command in the trap producing the 3rd instance
4. And hello follows last after the complete trap execution is complete.

See the sequence when ran from the debug mode

$ bash -x script.sh
+ set -T
+ trap 'echo oops' DEBUG
++ echo oops                # <--- triggered by call to 'foo'
oops
+ foo
++ echo oops                # <--- triggered by call to 'echo oops' inside trap definition
oops
++ echo oops                # <--- result of the actual command to be run
oops
+ echo hello                # <--- result of the function call 'foo'
hello

Adding in more explanation to explain the sequence, imagine the DEBUG trap is fired before any shell function/commands are run. Let's breakdown it to the following. Understand that are two instructions/commands and two resulting actions for those commands

1. Call to foo is the first instruction, so a trap is fired and action echo oops is to be run now. Remember here foo is the trigger and echo oops is the action and we see it once for the first time.
2. Now the second instruction is the echo oops which triggers another action, so because of the trap, the echo oops is fired and then the actual instruction is done which also happens to do echo oops.