TCL/Expect - Output not showing up in buffer while expecting

Question

Alright, so I work for a telecom company for which I develop some automated tests for our products. I'm using TCL8.4 with Expect 5.44.1.15 as it was asked of me when I was hired. Most tests consist of interacting with our product's shell using telnet. So I've come up with the functions bellow:

    # ------------------------------------------------------------------------------
# Description: Launch telnet session with specified IP and port and assign
#              resulting spawned process ID to processIDRef upon success.
# 
#  Parameters:       ipAddr - in:  IPv4 address to connect with.
#                      port - in:  Port number to connect with.
#                    prompt - in:  String indicating a successfull connection.
#              processIDRef - out: Resulting spawned process identifier.
#
#      Return: Returns no significant value.  Throws exception on failure.
# ------------------------------------------------------------------------------
proc ::connections::telnet::Connect {ipAddr port prompt processIDRef} {
    # Print function name and parameters
    ::utils::PrintDebug [info level 0]

    # Parameter reference(s)
    upvar $processIDRef processID

    # Validate parameters
    if {![regexp -- {^((25[0-5]|2[0-4][0-9]|[01]?[0-9][0-9]?)(\.|$)){4}} $ipAddr]} {
        ::utils::Throw "Unsupported IP addresse format/value: \"$ipAddr\""

    } elseif {[string length $port] && !([string is integer $port] && $port >= 0)} {
        ::utils::Throw "Unsupported port number format/value: \"$port\""
    }

    # Spawn telnet session and expect prompt.
    if {![string length $port]} {
        # passing an empty string as port argument to telnet causes an error
        spawn telnet $ipAddr
    } else {
        spawn telnet $ipAddr $port
    }

    AddActiveSession $spawn_id

    Expect $spawn_id $prompt 30

    set processID $spawn_id
}

# ------------------------------------------------------------------------------
# Description: Close telnet session associated with processID.
# 
#  Parameters: processID - in: Spawned process identifier.
# 
#      Return: Returns no significant value.  Throws exception on failure.
# ------------------------------------------------------------------------------
proc ::connections::telnet::Disconnect {processID} {
    # Print function name and parameters
    ::utils::PrintDebug [info level 0]

    # Validate parameters
    if {![IsActiveSession $processID]} {
        ::utils::Throw "Unknown/Invalid processID: \"$processID\""
    }

    if {[::utils::IsProcessAlive $processID]} {
        # Open Telnet Prompt
        SendCommand $processID "\x1D" "" "telnet> " 10

        # Close telnet session
        SendCommand $processID "close" {\n} "Connection closed." 10

        # Remove from active sessions and close expect connection
        RemoveActiveSession $processID
        wait -i $processID
        close -i $processID

    } else {
        # Process is dead.
        RemoveActiveSession $processID
    }
}

# ------------------------------------------------------------------------------
# Description: Send command to process and expect response within alloted time.
#              Response can be collected inside a buffer if provided a reference.
# 
#  Parameters: processID - in: Spawnded process identifier.
#                command - in: String to be sent to process.
#             terminator - in: Character to append to command, signaling the 
#                              end of the command string for the interpreter.
#                 prompt - in: Regular Expression indicating end of command 
#                              execution.
#              timelimit - in: amount time we expect results before declaring
#                              failed execution.
#              bufferRef - out: Resulting command execution output.
#
#      Return: 1 if prompt was found within the timelimit, otherwise 
#              throws an exception.
# ------------------------------------------------------------------------------
proc ::connections::telnet::SendCommand {processID command terminator prompt timelimit {bufferRef ""}} {
    # Print function name and parameters
    ::utils::PrintDebug [info level 0]

    # Parameter reference(s)
    if {[string length $bufferRef]} {
        upvar $bufferRef buffer
    }
    set buffer ""

    # Set expect parameters
    set spawn_id $processID

    # Send command and expect results
    send -s "$command[subst $terminator]"
    Expect $processID $prompt $timelimit buffer
}

# ------------------------------------------------------------------------------
# Description: Expect response within alloted time.
#              Response can be collected inside a buffer if provided a reference.
# 
#  Parameters: processID - in: Spawnded process identifier.
#                 prompt - in: Regular Expression indicating end of command 
#                              execution.
#              timelimit - in: amount time we expect results before declaring
#                              failed execution.
#              bufferRef - out: Resulting command execution output.
#
#      Return: Returns no significant value.  Throws exception on failure.
# ------------------------------------------------------------------------------
proc ::connections::telnet::Expect {processID prompt timelimit {bufferRef ""}} {
    # Print function name and parameters
    ::utils::PrintDebug [info level 0]

    # Parameter reference(s)
    if {[string length $bufferRef]} {
        upvar $bufferRef buffer
    }
    set buffer ""

    # Validate parameters
    if {![IsActiveSession $processID]} {
        ::utils::Throw "Unknown/Invalid processID: \"$processID\""

    } elseif {!([string is integer $timelimit] && $timelimit >= 0)} {
        ::utils::Throw "Unsupported timeout format/value: \"$timelimit\""
    }

    # Set expect parameters
    set spawn_id $processID
    set timeout $timelimit

    # expect results
    expect {
        -re "$prompt" {
            # Command Successful
            if {[info exists expect_out(buffer)]} {
                append buffer $expect_out(buffer)
            }

            # Print Buffer to log file at least
            ::utils::PrintDebug $buffer
        }
        full_buffer {
            # expect_out(buffer) is full
            if {[string length $bufferRef]} {
                append buffer $expect_out(buffer)
            }
            exp_continue
        }
        timeout {
            # Timeout
            if {[info exists expect_out(buffer)]} {
                append buffer $expect_out(buffer)
            }

            # Print Buffer to log file at least
            ::utils::PrintDebug $buffer

            # Throw exception
            ::utils::Throw "Timed out while waiting for \"$prompt\"."
        }
        eof {
            # Process reached it's end
            if {[string length $bufferRef] && [info exists expect_out(buffer)]} {
                append buffer $expect_out(buffer)
            }

            # Print Buffer to log file at least
            ::utils::PrintDebug $buffer

            # Throw exception
            ::utils::Throw "Reached eof while waiting for \"$prompt\"."
        }
    }
}

Basically, you can use the functions as follows:

• ::connections::telnet::Connect
  • to connect to an IP and port using telnet and expect a certain prompt.
• ::connections::telnet::Disconnect
  • to close telnet.
• ::connections::telnet::SendCommand
  • To send a command through telnet and expect a certain prompt within the allotted amount of time.
• ::connections::telnet::Expect
  • To expect a certain prompt within the allotted amount of time without sending a command.

Problem:

There's a bug that occurs sometimes and I don't know what's causing it. Sometimes I use SendCommand and no output is stored in the expect buffer so obviously the function times out and throws an exception. Except that if I expect a second time then we can clearly see (in my logs) that the buffer does now indeed contain the output that I needed for the previous call not to timeout.

Here are some of my debug logs to show you what it looks like:

Feb/18/2015 18:16:17: ::connections::telnet::SendCommand exp5 {~ restart dispGates} {\n} {----.*> } 10 buffer

Feb/18/2015 18:16:17: Expect exp5 {----.*> } 10 buffer

Feb/18/2015 18:16:27: This is where the buffer content is logged, shouldn't be empty

Feb/18/2015 18:16:27: Timed out while waiting for "----.*> ".

...

Feb/18/2015 18:16:28: ::connections::telnet::SendCommand exp5 {~ *} {\n} {Connection closed by foreign host.} 30

Feb/18/2015 18:16:29: Expect exp5 {Connection closed by foreign host.} 30 buffer

THIS IS THE OUTPUT I WAS LOOKING FOR DURING THE LAST CALL TO EXPECT! You can clearly see both commands that I sent in this.

Feb/18/2015 18:16:30: ~ restart dispGates

            RST_GATE_INITIAL     OPEN

  HardwareSettleCompleteGate     OPEN

            HsiAvailableGate     CLOSED

    DiagnosticsAvailableGate     CLOSED

           FirmwareReadyGate     CLOSED

    CardCommsDriverReadyGate     CLOSED

     ShelfCommsAvailableGate     CLOSED

DataProvisioningCompletedGate CLOSED

Command completed at TUE JAN 07, 2003 - 23:53:38 (UTC)

----/restart> ~ * Connection closed by foreign host.

This can happen consistently when I'm attempting something new or it can happen intermittently with any of my existing functions. The command I am sending above has worked 10+ times within a couple of minutes before triggering this bug.

This is causing a lot of trouble for me and my colleagues and clients who use my packages. We have tens of thousands of lines of code using this and the problem is becoming more and more apparent now that more clients are using our test suits. re-writing in another language is the last of our options.

Workarounds:

So I tried increasing the timeout but that never works.

I also tried expecting twice in a row (in case the first one times out) but it didn't help even with a delay in between. It's like I have to leave the function calling ::connections::telnet::Expect before calling it again.

I developed a function to clear the program channel buffer and expect's buffer (because there wasn't one already included in the expect library it seems). Sometimes it helps and sometimes it doesn't. Even if it did help 100% of the time it wouldn't be a viable option to use every time we call send command because it slows down each command execution to at least 1 second execution time. Here it is:

# ------------------------------------------------------------------------------
# Description: Clears a process's channel buffer and expect_out(buffer).
#
#  Parameters: processID - in: Spawned process identifier.
#
#      Return: void - returns no signicant value.
# ------------------------------------------------------------------------------
proc ::utils::ClearBuffer {processID} {
    # Print function name and parameters
    PrintDebug [info level 0]

    # set expect parameters
    set spawn_id $processID
    set timeout 1

    catch {expect -re "thischainwillmostcertainlyneverappear"}
    catch {expect -re ".*"}
}

My plea:

Has anybody else encountered this issue?

Why wouldn't the output from my product suddenly not accumulate inside expect's buffer as always?

Are there any special characters that might tell expect to stop doing so?

Is there something else I'm doing wrong?

Any other suggestions for workarounds?

Thank you so much for your time.

Answer 1

Whenever I've fallen on this kind of issue with expect, I would first use the exp_internal command which dumps a lot of very usefull information about the state of the buffer and how/if the patterns are matched.