Expect script stopped showing output

bulletproof.rs · 04-14-2018, 05:56 PM

Hey guys,

I'm stuck with an issue for quite some time. I have made expect script to check port on cisco switch, run couple of commands in purpose of troubleshooting down access point on a port, but for some reason, it will not show all output, but script runs fine as it should.

It works like this, i call the expect script from bash script, with dns name of switch and port number where AP is located (2 arguments) and then it will login to that switch and execute commands. It will log all output to a file which bash script will cat to user and using different regex algorithms I've made, will show possible diagnosis. See expect script bellow.

Code:

#!/usr/bin/expect -f

set timeout -1
set send_human {.1 .3 1 .05 2}
set args [llength $argv]

set b64_enpass enpass
set b64_swpass password
set b64_swuser user

set enpass [exec echo $b64_enpass | base64 -d]
set swpass [exec echo $b64_swpass | base64 -d]
set swuser [exec echo $b64_swuser | base64 -d]

set host [lindex $argv 0]
set apport [lindex $argv 1]

exec clear >@ stdout
send_user "Trying to login to switch...\n"

stty echo

# ssh to router
stty -echo
log_user 0
spawn ssh -o "StrictHostKeyChecking=no" $swuser@$host

expect -re "password:" {
	send "$swpass\r"
	send_user "Logged into the switch, gathering info...\n"
}
log_file -a -noappend status.log
# enable mode and get answer
expect -re ">" {
	send "en\r"
}

expect -re "Password:" {
	send "$enpass\r"
}
#log_file -a -noappend status.log
expect -re "#" {
	send -h "sh pow in $apport\r"
}

expect {

	-re "marker." {
		puts "Port doesnt appear to exist..."
		expect -re "#" {send -h "term len 0\r"}
		expect -re "#" {send -h "sh pow in\r"}
		expect -re "#" {send -h "term no len\r"}
		expect -re "#" {send -h "exit\r"}
		log_file
		exit 8
	}
	-re "not supported" {
		exp_internal 0
		puts "Power inline doesnt appear to be supported..."
		expect -re "#" {send -h "term mon\r"}
		expect -re "#" {send -h "sh int $apport status\r"}
		expect -re "#" {send -h "conf t\r"}
		expect -re "#" {send -h "int $apport\r"}
		puts "Bouncing port..."
		expect -re "#" {send -h "shut\r"}
		sleep 3
		expect -re "#" {send -h "no shut\r"}
		sleep 5
		expect -re "#" {send -h "end\r"}
		sleep 1
		expect -re "#" {send -h "term no mon\r"}
		sleep 1
		expect -re "#" {send -h "exit\r"}
		sleep 1
		log_file
		exit 10
	}
	-re "AIR-CAP" {
		puts "AP seems to be online. Printing port status and CDP NEI"
		expect -re "#" {send "sh int $apport status\r"}
		expect -re "#" {send "sh cdp nei $apport\r"}
		expect -re "#" {send "exit\r"}
		log_file
		exit 12
	}
	
	-re "AP-" {
		puts "AP seems to be online. Printing port status and CDP NEI"
		expect -re "#" {send "sh int $apport status\r"}
		expect -re "#" {send "sh cdp nei $apport\r"}
		expect -re "#" {send "exit\r"}
		log_file
		exit 12
	}
	
	-re "Ieee PD" {
		puts "AP Is receiving power but doesn't seem good. Doing additional check"
		expect -re "#" {send -h "sh int $apport status\r"}
		expect -re "#" {send -h "conf t\r"}
		expect -re "#" {send -h "int $apport\r"}
		expect -re "#" {send -h "shut\r"}
		expect -re "#" {send -h "no shut\r"}
		expect -re "#" {send -h "end\r"}
		puts "Port bounced.. Waiting 15 seconds and checking again."
		sleep 15
		expect -re "#" {send -h "sh int $apport status\r"}
		expect -re "#" {send -h "exit\r"}
		log_file
		exit 14
	}
	-re "n/a" {
		puts "AP is not receiving power. Bouncing the port"
		expect -re "#" {send -h "conf t\r"}
		expect -re "#" {send -h "int $apport\r"}
		expect -re "#" {send -h "do term mon\r"}
		expect -re "#" {send -h "shut\r"}
		sleep 5
		expect -re "#" {send -h "no shut\r"}
		expect -re "#" {send -h "end\r"}
		puts "Port bounced... Running TDR Test after..."
		expect -re "#" {send -h "sh int $apport status\r"}
		expect -re "#" {send -h "test cable tdr int $apport\r"}
		exp_internal 1
		puts "TDR Test ran. Waiting 20 seconds to check results..."
		sleep 20
		expect -re "#" {send -h "term no mon\r"}
		sleep 2
		expect -re "#" {send -h "sh pow in $apport\r"}
		sleep 2
		expect -re "#" {send -h "sh int $apport status\r"}
		sleep 2
		expect -re "#" {send -h "sh cable tdr int $apport\r"}
		sleep 2
		expect -re "#" {send -h "exit\r"}
		log_file
		exit 16
	}
}

Script will stuck on random items after specific set of commands are ran, but for the example purposes, lets say if the expect is "n/a". Script will no longer log output after it runs "test cable tdr int $apport" command. It will continue to run commands in the background though since last line was from shell (#) but doesn't show it to me.

You've noticed that i've put exp_internal 1 after test command so i can see what's happening, but i still can't figure out why it stops catching output. I've even tried settings larger delays and even human style typing without gain.,

Here is output after exp_internal 1:

Code:

Trying to login to switch...
Logged into the switch, gathering info...
AP is not receiving power. Bouncing the port
Port bounced... Running TDR Test after...
TDR Test ran. Waiting 20 seconds to check results...
Gate keeper glob pattern for '#' is '#'. Activating booster.

expect: does "sh int Gi1\r\n002456: Apr 14 16:49:51 CDT: %SYS-5-CONFIG_I: Configured from console by user on vty0 (10.24.1.33)\r\ns-upc-2.s00267.us#sh int Gi1/0/34\r\n002457: Apr 14 16:49:53 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to down\r\ns-upc-2.s00267.us#sh int Gi1/0/34 status" (spawn_id exp4) match regular expression "#"? Gate "#"? gate=yes re=yes
expect: set expect_out(0,string) "#"
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) "sh int Gi1\r\n002456: Apr 14 16:49:51 CDT: %SYS-5-CONFIG_I: Configured from console by user on vty0 (10.24.1.33)\r\ns-upc-2.s00267.us#"
send: sending "term no mon\r" to { exp4 human_write: avg_arr=0.100000/0.300000  1/shape=1.000000  min=0.050000  max=2.000000
}
Gate keeper glob pattern for '#' is '#'. Activating booster.

expect: does "sh int Gi1/0/34\r\n002457: Apr 14 16:49:53 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to down\r\ns-upc-2.s00267.us#sh int Gi1/0/34 status" (spawn_id exp4) match regular expression "#"? Gate "#"? gate=yes re=yes
expect: set expect_out(0,string) "#"
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) "sh int Gi1/0/34\r\n002457: Apr 14 16:49:53 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to down\r\ns-upc-2.s00267.us#"
send: sending "sh pow in Gi1/0/34\r" to { exp4 human_write: avg_arr=0.100000/0.300000  1/shape=1.000000  min=0.050000  max=2.000000
}
Gate keeper glob pattern for '#' is '#'. Activating booster.

expect: does "sh int Gi1/0/34 status" (spawn_id exp4) match regular expression "#"? Gate "#"? gate=no

expect: does "sh int Gi1/0/34 status\r\n\r\nPort      Name               Status       Vlan       Duplex  Speed Type \r\nGi1/0/34  :: MPC521134548978 notconnect   25           auto   auto 10/100/1000BaseTX\r\ns-upc-2.s00267.us#test cable tdr int Gi1/0/34\r\nTDR test started on interface Gi1/0/34\r\nA TDR test can take a few seconds to run on an interface\r\nUse 'show cable-diagnostics tdr' to read the TDR results.\r\ns-upc-2.s00267.us#\r\n002458: Apr 14 16:50:01 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to up\r\ns-upc-2.s00267.us#\r\n002459: Apr 14 16:50:02 CDT: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/34, changed state to up\r\ns-upc-2.s00267.us#term no mon\r\ns-upc-2.s00267.us#sh pow in Gi1/0/34\r\nInterface Admin  Oper       Power   Device              Class Max\r\n                            (Watts)                            \r\n--------- ------ ---------- ------- ------------------- ----- ----\r\nGi1/0/34  auto   off        0.0     n/a                 n/a   30.0 \r\ns-upc-2.s00267.us#" (spawn_id exp4) match regular expression "#"? Gate "#"? gate=yes re=yes
expect: set expect_out(0,string) "#"
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) "sh int Gi1/0/34 status\r\n\r\nPort      Name               Status       Vlan       Duplex  Speed Type \r\nGi1/0/34  :: MPC521134548978 notconnect   25           auto   auto 10/100/1000BaseTX\r\ns-upc-2.s00267.us#"
send: sending "sh int Gi1/0/34 status\r" to { exp4 human_write: avg_arr=0.100000/0.300000  1/shape=1.000000  min=0.050000  max=2.000000
}
Gate keeper glob pattern for '#' is '#'. Activating booster.

expect: does "test cable tdr int Gi1/0/34\r\nTDR test started on interface Gi1/0/34\r\nA TDR test can take a few seconds to run on an interface\r\nUse 'show cable-diagnostics tdr' to read the TDR results.\r\ns-upc-2.s00267.us#\r\n002458: Apr 14 16:50:01 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to up\r\ns-upc-2.s00267.us#\r\n002459: Apr 14 16:50:02 CDT: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/34, changed state to up\r\ns-upc-2.s00267.us#term no mon\r\ns-upc-2.s00267.us#sh pow in Gi1/0/34\r\nInterface Admin  Oper       Power   Device              Class Max\r\n                            (Watts)                            \r\n--------- ------ ---------- ------- ------------------- ----- ----\r\nGi1/0/34  auto   off        0.0     n/a                 n/a   30.0 \r\ns-upc-2.s00267.us#" (spawn_id exp4) match regular expression "#"? Gate "#"? gate=yes re=yes
expect: set expect_out(0,string) "#"
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) "test cable tdr int Gi1/0/34\r\nTDR test started on interface Gi1/0/34\r\nA TDR test can take a few seconds to run on an interface\r\nUse 'show cable-diagnostics tdr' to read the TDR results.\r\ns-upc-2.s00267.us#"
send: sending "sh cable tdr int Gi1/0/34\r" to { exp4 human_write: avg_arr=0.100000/0.300000  1/shape=1.000000  min=0.050000  max=2.000000
}
Gate keeper glob pattern for '#' is '#'. Activating booster.

expect: does "\r\n002458: Apr 14 16:50:01 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to up\r\ns-upc-2.s00267.us#\r\n002459: Apr 14 16:50:02 CDT: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/34, changed state to up\r\ns-upc-2.s00267.us#term no mon\r\ns-upc-2.s00267.us#sh pow in Gi1/0/34\r\nInterface Admin  Oper       Power   Device              Class Max\r\n                            (Watts)                            \r\n--------- ------ ---------- ------- ------------------- ----- ----\r\nGi1/0/34  auto   off        0.0     n/a                 n/a   30.0 \r\ns-upc-2.s00267.us#" (spawn_id exp4) match regular expression "#"? Gate "#"? gate=yes re=yes
expect: set expect_out(0,string) "#"
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) "\r\n002458: Apr 14 16:50:01 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to up\r\ns-upc-2.s00267.us#"
send: sending "exit\r" to { exp4 human_write: avg_arr=0.100000/0.300000  1/shape=1.000000  min=0.050000  max=2.000000
}
tty_set: raw = 3, echo = 0

The actual output should ofcourse be:

Code:

s-upc-2.s00267.us#sh pow in Gi1/0/34
Interface Admin  Oper       Power   Device              Class Max
                            (Watts)
--------- ------ ---------- ------- ------------------- ----- ----
Gi1/0/34  auto   off        0.0     n/a                 n/a   30.0
s-upc-2.s00267.us#conf t
Enter configuration commands, one per line.  End with CNTL/Z.
s-upc-2.s00267.us(config)#int Gi1/0/34
s-upc-2.s00267.us(config-if)#do term mon
s-upc-2.s00267.us(config-if)#shut
s-upc-2.s00267.us(config-if)#no shut
s-upc-2.s00267.us(config-if)#end
s-upc-2.s00267.us#
002464: Apr 14 16:53:39 CDT: %LINK-5-CHANGED: Interface GigabitEthernet1/0/34, changed state to administratively down
002465: Apr 14 16:53:40 CDT: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/34, changed state to down
s-upc-2.s00267.us#
002466: Apr 14 16:53:40 CDT: %SYS-5-CONFIG_I: Configured from console by user on vty0 (172.17.180.37)
s-upc-2.s00267.us#
002467: Apr 14 16:53:42 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to down
s-upc-2.s00267.us#sh int Gi1/0/34 status

Port      Name               Status       Vlan       Duplex  Speed Type
Gi1/0/34  :: MPC521134548978 connected    25         a-full a-1000 10/100/1000BaseTX
s-upc-2.s00267.us#
002468: Apr 14 16:53:49 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to up
002469: Apr 14 16:53:50 CDT: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/34, changed state to up
s-upc-2.s00267.us#test cable tdr int Gi1/0/34
TDR test started on interface Gi1/0/34
A TDR test can take a few seconds to run on an interface
Use 'show cable-diagnostics tdr' to read the TDR results.
s-upc-2.s00267.us#term no mon
s-upc-2.s00267.us#sh pow in Gi1/0/34
Interface Admin  Oper       Power   Device              Class Max
                            (Watts)
--------- ------ ---------- ------- ------------------- ----- ----
Gi1/0/34  auto   off        0.0     n/a                 n/a   30.0
s-upc-2.s00267.us#sh int Gi1/0/34 status

Port      Name               Status       Vlan       Duplex  Speed Type
Gi1/0/34  :: MPC521134548978 connected    25         a-full a-1000 10/100/1000BaseTX
s-upc-2.s00267.us#sh cable tdr int Gi1/0/34
TDR test last run on: April 14 16:54:00

Interface Speed Local pair Pair length        Remote pair Pair status
--------- ----- ---------- ------------------ ----------- --------------------
Gi1/0/34  1000M Pair A     22   +/- 10 meters Pair A      Normal
                Pair B     22   +/- 10 meters Pair B      Normal
                Pair C     22   +/- 10 meters Pair C      Normal
                Pair D     22   +/- 10 meters Pair D      Normal
s-upc-2.s00267.us#exit

However, it will ALWAYS stuck here (but will continue to run commands in background, just stops logging the output) - of course, with exp_internal 0

Code:

s-upc-2.s00267.us>en
Password:
s-upc-2.s00267.us#sh pow in Gi1/0/34
Interface Admin  Oper       Power   Device              Class Max
                            (Watts)
--------- ------ ---------- ------- ------------------- ----- ----
Gi1/0/34  auto   off        0.0     n/a                 n/a   30.0
s-upc-2.s00267.us#conf t
Enter configuration commands, one per line.  End with CNTL/Z.
s-upc-2.s00267.us(config)#int Gi1/0/34
s-upc-2.s00267.us(config-if)#do term mon
s-upc-2.s00267.us(config-if)#shut
s-upc-2.s00267.us(config-if)#
002470: Apr 14 16:57:52 CDT: %LINK-5-CHANGED: Interface GigabitEthernet1/0/34, changed state to administratively down
002471: Apr 14 16:57:53 CDT: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/34, changed state to down
s-upc-2.s00267.us(config-if)#no shut
s-upc-2.s00267.us(config-if)#end
s-upc-2.s00267.us#sh int Gi1/0/3
002472: Apr 14 16:57:57 CDT: %SYS-5-CONFIG_I: Configured from console by user on vty0 (10.24.1.33)
s-upc-2.s00267.us#sh int Gi1/0/34 status

Port      Name               Status       Vlan       Duplex  Speed Type
Gi1/0/34  :: MPC521134548978 notconnect   25           auto   auto 10/100/1000BaseTX
s-upc-2.s00267.us#tes
002473: Apr 14 16:57:58 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to down
s-upc-2.s00267.us#test cable tdr int Gi1/0/34
TDR test started on interface Gi1/0/34
A TDR test can take a few seconds to run on an interface
Use 'show cable-diagnostics tdr' to read the TDR results.
s-upc-2.s00267.us#
002474: Apr 14 16:58:09 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to up
002475: Apr 14 16:58:10 CDT: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/34, changed state to up
s-upc-2.s00267.us#term no mon
s-upc-2.s00267.us#

Sorry for the long post but does anyone have any ideas why is it doing this?

rtmistler · 04-18-2018, 07:20 AM

I've never run expect scripts however can see the syntax to not be so crazy.

Meanwhile, this is a long time (?) script you've had which worked, and now one or two things are happening? Random lockups at various points? At least one deterministic point where it always fails?

For things like this I check and do a couple of things:

Try to find a recurring failure point and then focus on debugging that point.
Try to identify a change to an external influence, such as the environment, a system command, or file structure. I.e.
1. The environment may have changed, paths may have changed, a linked file may have changed.
2. A system command may have changed, by way of update, or another binary or library used in this whole process may have changed in a very subtle manner and this is causing some of the problems.
3. The paths for things in the system may have changed in some small way.
Next I figure out ways to increase my debug, and sometimes exponentially. For instance bash has the "set -xv" options, maybe more, which turn on debug and verbose output. You're using bash for part of this, turn that on. I don't know if expect has similar, but turn it on if you can.
Next, add debug like crazy. For instance if you're unsure about a path flow or if the script ever gets somewhere, put in outputs or prints which say "1", "2", "3", or "got here #1", "got here #2", and so forth.
Check the outcome of ALL commands or actions. Such as if you invoke cd, or grep, or a function internally in your script. Have it have a return value and check that value.

Hope this helps. I can see it is a lengthy, and therefore highly developed script, therefore it has some complexity, and therefore whatever is wrong is likely very subtle and hard to track down. I feel in that case, the difficult pill to swallow is to nearly go back to the point where you developed the original script and you validate every step of it to help you track down these problems. Meanwhile, if you do that, you then leave in all your debug hooks, and perhaps also you learn something about a flaw you had when you structured it originally, if that's the case. I know I have run into similar stuff. "Man! This script has ALWAYS worked!", so yes I've been there, just not for this specific case or language.

And unfortunately the only way I've been able to track odd ones like this down were to almost go back to basics, to really reinvent the script. Whereupon once I found the problem, I added a lot more reliability to the script based on what I learned.

bulletproof.rs · 04-18-2018, 04:01 PM

I'm still new with expect but as you noticed, syntax is quite easy and straightforward.

However, i have tried debugging along the way. Just like bash hase set -x expect has exp_internal 1. Script really runs just fine. Completely fine. It just stops receiving output from switch after some point after running couple of commands. I have no idea why and cannot figure it out.

It appears that it always gets stuck on one point, maybe script goes into some loop and it's trying to look for something specific and that is why it stops.
There are no external influences to this script. Switch commands are straightforward, there are no paths and files so there is no chance to mess something up on that side. Once it logs into the switch, pretty much commands need to flow on their own. If i make a mistake and input wrong port as argument, it will error out and break.

I will for sure start from scratch when spare time allows. And then add one by one feature to see where it goes wrong. My theory is that when it runs sh power inline for second time, it gets stuck on loop (maybe), causing script to stop receiving output from switch. But it's weird that it's not an actual loop. Script continues as normal and finishes with expected exit code that i impose.

Anyway, i will continue looking into this just wanted to see if someone had similar problem. It definitely is a bit complex and this is first expect script that i wrote to be this complex. No doubt that i messed something up.

jlinkels · 04-18-2018, 05:55 PM

As far as I can see Expect is sending command before it should do so.

In the trace with exp_internal 1 you send this:

Code:

send: sending "term no mon\r" to

Then the reply which is received is this:

Code:

sh int Gi1/0/34\r\n002457: Apr 14 16:49:53 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to down\r\ns-upc-2.s00267.us#

which is in reply to a shut command.
Likewise, this reply

Code:

test cable tdr int Gi1/0/34\r\nTDR test started on interface Gi1/0/34\r\nA TDR test can take a few seconds to run on an interface\r\nUse 'show cable-diagnostics tdr' to read the TDR results.\r\ns-upc-2.s00267.u

is received after you send

Code:

sh int Gi1/0/34 status\

So in this stage, sending and receiving are completely mixed up. Somewhere Expect received a prompt on which it is acting, but way too early.

In your example how it should be (I guess this is terminal output) I see a number of replies without commands being sent:
02464: Apr 14 16:53:39 CDT: %LINK-5-CHANGED: Interface GigabitEthernet1/0/34, changed state to administratively down
002465: Apr 14 16:53:40 CDT: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/34, changed state to down
s-upc-2.s00267.us#
002466: Apr 14 16:53:40 CDT: %SYS-5-CONFIG_I: Configured from console by user on vty0 (172.17.180.37)
s-upc-2.s00267.us#
002467: Apr 14 16:53:42 CDT: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/34, changed state to down

For you as human that is no problem, but Expect might get confused.

So how to debug this.

First, you could eliminate as many commands as possible. And see if the commands as such are being executed properly.
Secondly, insert insane long sleep times after each command so you are sure Expect had the time to answer.
And third (and that is part of the solution) you should analyze what exactly is replied by to switch to each command, and make your match string more specific.

In case where you get multiple lines with multiple '#' characters, take a specific part of your last line and combine it with the prompt to serve as match.

So, for example if you issue the command "no shut", wait until receive "changed state to up.*#" by setting the match string to that phrase.

The text behind set expect_out(buffer) is exactly what Expect received back. You can check on that an see if these are the proper replies on the string sent just before.

The line does "sh int Gi1/0/34\... shows you what Expect is trying to match.

jlinkels