[Expectperl-discuss] No match, but the pattern is there in debug output

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

I'm very confused by this.  I wrote a Perl-expect script that talks
to Cisco routers, and it works great for me under NetBSD 1.5 and Linux
(RH 6.2), Perl 5.005_02 and 5.005_03.  Someone else trying to use it
reported that it would time out halfway, claiming it couldn't see the
router's prompt.  The strange thing is that the script matched the router
prompt three times previously, and when you look at the debug output,
you can see the router's prompt as the last thing in the buffer.

Can anyone make suggestions on how to debug this?  The first thing
I looked at was environment - I forgot to ask the person what version
of Perl he's using, but he's tried Expect 1.11 (the one I developed
the script under) as well as 1.13 and 1.14, and IO::Tty 0.04 and 0.05,
no difference.

Here's my script's basic debug output:

aclmaker.pl: sent CR, received { terminal length 0 ! restore old setting
cs3mc-lab-e0a# }
aclmaker.pl: sent CR, received {
cs3mc-lab-e0a# }
aclmaker.pl: found Cisco prompt: cs3mc-lab-e0a#
aclmaker.pl: sending { show term | inc Len } to router...
aclmaker.pl: matched pattern#1: ^Length: (\d+) lines, Width: (\d+) columns
aclmaker.pl: null send string, skipping send...
aclmaker.pl: matched pattern#1: ^cs3mc-lab-e0a(\(\S+\))?#
aclmaker.pl: sending { terminal length 0 ! acl-boris.pl } to router...
aclmaker.pl: matched pattern#1: ^cs3mc-lab-e0a(\(\S+\))?#
aclmaker.pl: sending { terminal width  0 ! acl-boris.pl } to router...
aclmaker.pl: matched pattern#1: ^cs3mc-lab-e0a(\(\S+\))?#
aclmaker.pl: sending { show running-config ! downloading... } to router...
aclmaker.pl: failed to get match { ^cs3mc-lab-e0a(\(\S+\))?# } on command:
        show running-config ! downloading...
aclmaker.pl: sent closing commands { ^Z / terminal length 0 / terminal
width 80 }

Note that it matches the pattern for the router command line three
times, then sends "show running-config" and is looking for another
router prompt so it'll know where the end of the config output is.
When the user turned on Expect verbose debugging, he sent me this
output:

[...]
Waiting for new data (5 seconds)...
handle id(3): new data.
handle id(3): read 509 byte(s).

handle id(3): Does `...
+---------------------------------------------+\r\012        |
|\r\012        |     ********** W A R N I N G **********     |\r\012
|                                             |\r\012        |  This system
is private and is RESTRICTED   |\r\012        |  to authorized users only.
Unauthorized    |\r\012        |  attempts CAN BE TRACED, and those
|\r\012        |  responsible will be PROSECUTED.            |\r\012
|  If you are not authorized, PISS OFF! |\r\012        |
|\r\012
+---------------------------------------------+\r\012\r\012\r\012^C\r\012!
\r\012line con 0\r\012 exec-timeout 15 0\r\012 password 7
0123456789ABCD\r\012 login\r\012 transport input none\r\012line aux 0\r\012
exec-timeout 15 0\r\012 password 7 0123456789ABCD\r\012 login\r\012line vty
0 4\r\012 no exec\r\012 exec-timeout 15 0\r\012 no login\r\012 transport
input none\r\012!\r\012!\r\012end\r\012
\r\012cs3mc-lab-e0a#'
match:
  pattern #1: -re `^cs3mc-lab-e0a(\\(\S+\))?#'? No.

Waiting for new data (4 seconds)...
TIMEOUT

Well, there's the "\r\012cs3mc-lab-e0a#", the same thing that matched
previously. When I look at the debug output of the script when I use it,
it looks the same, except that in my environment the string is printed
as "\r\ncs3mc-lab-e0a#".

I don't think the problem is multi-line matching - my program doesn't
touch $Expect::Multiline_Matching and if I set it to 0 it fails on the
first match try.  However, the big difference between the early commands
that matched and the one that failed is that the latter produces hundreds
of lines of output, while the successful commands produced either 30-40
lines (the "show term") or none at all (the two "set term" commands) except
for the router's prompt.

Since I don't have access to the user's environment, I'm at a loss as
to how to debug this further.  Can anyone make suggestions on what to
tweak or what else to try?  If you want to look at the program, it's
over at:

   http://prdownloads.sourceforge.net/cosi-nms/aclmaker-perl-1.01.txt

Many thanks,

	-- Ed