expect-5.45.4 shows unexpected spawn output, causing string match to fail; is it a bug?

In SLES15 SP6 on x86_64 I'm using a bash script and expect-5.45.4 to do automated program testing. Basically I'm checking whether the program to test (./pwg.pl) outputs a specific string.

Starting to write my test script, the first invocations all worked as expected, but one case fails to match the output, even if it is there!

Example:

(This may look like a needlessly complicated, but that's just one trivial test case for the program)

./pwg.pl --show-entropy --verbose=1 '{!/SG:25}ABCDEfghijKLMOP{T/S:R=1}'
parse_cookie({!/SG:25}ABCDEfghijKLMOP{T/S:R=1})
ABCDEfghijKLMOP
1 states, 0.0 bits

The string to check for is ABCDEfghijKLMOP, and it is output using print with a trailing "\n" in Perl, and all output is writing to STDOUT.

However when tracing my expect script I see:

spawn ./pwg.pl --show-entropy --verbose=1 ./pwg.pl --show-entropy --verbose=1 {!/SG:25}ABCDEfghijKLMOP{T/S:R=1}
parent: waiting for sync byte
parent: telling child to go ahead
parent: now unsynchronized from child
spawn: returns {829}

expect: does "" (spawn_id exp6) match glob pattern "\r\nABCDEfghijKLMOP\r\n"? no
parse_cookie(./pwg.pl --show-entropy --verbose=1 {!/SG:25}ABCDEfghijKLMOP{T/S:R=1})

expect: does "parse_cookie(./pwg.pl --show-entropy --verbose=1 {!/SG:25}ABCDEfghijKLMOP{T/S:R=1})\r\n" (spawn_id exp6) match glob pattern "\r\nABCDEfghijKLMOP\r\n"? no
./pwg.pl --show-entropy --verbose=1 ABCDEfghijKLMOP

expect: does "parse_cookie(./pwg.pl --show-entropy --verbose=1 {!/SG:25}ABCDEfghijKLMOP{T/S:R=1})\r\n./pwg.pl --show-entropy --verbose=1 ABCDEfghijKLMOP\r\n" (spawn_id exp6) match glob pattern "\r\nABCDEfghijKLMOP\r\n"? no
1 states, 0.0 bits

expect: does "parse_cookie(./pwg.pl --show-entropy --verbose=1 {!/SG:25}ABCDEfghijKLMOP{T/S:R=1})\r\n./pwg.pl --show-entropy --verbose=1 ABCDEfghijKLMOP\r\n1 states, 0.0 bits\r\n" (spawn_id exp6) match glob pattern "\r\nABCDEfghijKLMOP\r\n"? no
expect: read eof
expect: set expect_out(spawn_id) "exp6"
expect: set expect_out(buffer) "parse_cookie(./pwg.pl --show-entropy --verbose=1 {!/SG:25}ABCDEfghijKLMOP{T/S:R=1})\r\n./pwg.pl --show-entropy --verbose=1 ABCDEfghijKLMOP\r\n1 states, 0.0 bits\r\n"
FAILED
### FAILED

So the point is that expect seems to repeat the command invocation string in the output while dropping the essential new-line (\n\r).

The test script goes like this:

PWG='./pwg.pl --show-entropy --verbose=1'

# run command under expect
expect_output()
{
    typeset -r expected="$1"; shift
    expect <<EOI
        log_user 1
        exp_internal 1
        spawn $PWG "$@"
        expect {
            "$expected" {
                #puts "OK"
                exit 0
            }
            timeout {
                puts "No response"
                exit 1
            }
            eof {
                puts "FAILED"
                exit 1
            }
        }
EOI
    local EC=$?
    [ $EC -eq 0 ] && echo '### OK' || echo '### FAILED'
    return $EC
}

expect_output '\r\nABCDEfghijKLMOP\r\n' \
$PWG '{!/SG:25}ABCDEfghijKLMOP{T/S:R=1}'
exit

Just in case:

./pwg.pl --show-entropy --verbose=1 '{!/SG:25}ABCDEfghijKLMOP{T/S:R=1}' | hexdump -C
00000000  70 61 72 73 65 5f 63 6f  6f 6b 69 65 28 7b 21 2f  |parse_cookie({!/|
00000010  53 47 3a 32 35 7d 41 42  43 44 45 66 67 68 69 6a  |SG:25}ABCDEfghij|
00000020  4b 4c 4d 4f 50 7b 54 2f  53 3a 52 3d 31 7d 29 0a  |KLMOP{T/S:R=1}).|
00000030  41 42 43 44 45 66 67 68  69 6a 4b 4c 4d 4f 50 0a  |ABCDEfghijKLMOP.|
00000040  31 20 73 74 61 74 65 73  2c 20 30 2e 30 20 62 69  |1 states, 0.0 bi|
00000050  74 73 0a                                          |ts.|
00000053

So I wonder whether it's a bug in expect causing that effect, or did I use expect incorrectly?

Solution

I feel stupid (thanks to @ikegami for helping me): The bug is in the script building the expect command:

when writing expect_output() I had realized that each invocation will use $PWG (that's why I had put it into a variable) , so I thought I could implicitly use it inside expect_output() when converting my commands not using expect to those using it.

Doing that I forgot that I don't have to (and actually I should not) pass $PWG as argument to expect_output().

So what spawn $PWG "$@" actually executes is spawn $PWG "$PWG" ... when calling expect_output something $PWG ....

And one of the features of $PWG is to output anything from the command-line it does not understand. Thus the strange-looking context for ... (actually "ABCDEfghijKLMOP").