On Tue, Aug 4, 2009 at 11:23 AM, Michael Goldish<mgoldish@xxxxxxxxxx> wrote:
> Looks like there really are only 3 lines to read.
> Telnet is printing those lines, not windows. It's just indicating
> that it successfully connected. Windows is saying nothing.
>
> This is a little weird, because:
> - It can happen when the telnet server isn't running at all,
> but it seemed to be running fine when you connected manually.
> - It can happen when trying to connect to the wrong port, but I
> see you set the port to 23.
>
> It can also happen due to the short default timeout of 10 seconds.
> Windows can take longer than that to send something.
My manual observation also says that it does not take that much.
> Are you sure you increased the timeout? You only sent a log of 4
I increased the timeout and did not send the complete log. here are
the start and end of the complete log
12:26:44 INFO | Waiting for guest to be up...
12:26:44 INFO | DEBUG: in ssh_login ssh_prompt = C:\Users\Administrator>
12:26:44 INFO | DEBUG: in ssh_login timeout = 20
12:26:47 INFO | DEBUG: Printing data read by read_nonblocking from output:
12:26:47 INFO | DEBUG: data read from output is Trying 10.0.99.100...
12:26:47 INFO | telnet: connect to address 10.0.99.100: No route to host
12:26:47 INFO | telnet: Unable to connect to remote host: No route to host
<snip>
12:30:48 INFO | DEBUG: Printing accumulated data read from output done.
12:30:48 INFO | DEBUG: Printing data after filter:
12:30:48 INFO | DEBUG: filtered data is Escape character is '^]'.
12:30:48 INFO | DEBUG: Printing data after filter done:
12:30:50 ERROR| Test failed: Could not log into guest
> seconds (starting at 12:27:25). How long does
> read_until_output_matches() wait before it gives up?
Here is the complete code flow with parameters.
in kvm_tests.py
session = kvm_utils.wait_for(vm.ssh_login, 240, 0, 2)
which calls in kvm_utils.py
output = func()
This calls ssh_login() in kvm_vm.py with default parameters and the
default def is changed to have timeout 20 second instead of 10
seconds.
def ssh_login(self, timeout=20):
This calls the telnet which calls remote_login() in kvm_utils.py
if use_telnet:
session = kvm_utils.telnet(address, port, username, password,
prompt, timeout)
So timeout is 20 now. This calls remote_login
return remote_login(command, password, prompt, "\r\n", timeout)
PS: A dumb Question: Does "\r\n" have to do something with the failure ?
So timeout is still 20. The next call is
while True:
(match, text) = sub.read_until_last_line_matches(
[r"[Aa]re you sure", r"[Pp]assword:\s*$", r"^\s*[Ll]ogin:\s*$",
r"[Cc]onnection.*closed", r"[Cc]onnection.*refused", prompt],
timeout=timeout, internal_timeout=3.5)
which calls to
return self.read_until_output_matches(patterns, self.get_last_line,
timeout, internal_timeout,
print_func)
Hence this function waits for 20 seconds in each try. i think that is
good enough.
In my manual observation there is no delay between the above all the
lines printed. So this should not be an issue. I can bet that there is
not even a delay of 2 secs between these two lines:
Escape character is '^]'.
Welcome to Microsoft Telnet Service
But yes there is a very small delay(looks < 1 second), which should be
taken care by increased internal_timeout which i have increased to
around 3 seconds.
>
> ----- Original Message -----
> From: "sudhir kumar" <smalikphy@xxxxxxxxx>
> To: "kvm-devel" <kvm@xxxxxxxxxxxxxxx>
> Cc: "Lucas Meneghel Rodrigues" <mrodrigu@xxxxxxxxxx>, "Michael Goldish" <mgoldish@xxxxxxxxxx>, "Ryan Harper" <ryanh@xxxxxxxxxx>
> Sent: Tuesday, August 4, 2009 8:06:32 AM (GMT+0200) Auto-Detected
> Subject: [AUTOTEST]telnet login fails in win2k8 DC 64. here are debug and other info
>
> Hi,
> I am seeing a telnet failure in autotest to a win2k8 DC 64 bit guest.
> I have tried some debugging and came to a conclusion that
> read_nonblocking() is reading only 3 lines. let me first print the
> output of manual login
>
> # telnet -l Administrator 10.0.99.100 23
> Trying 10.0.99.100...
> Connected to ichigo-dom100.linuxperf9025.net (10.0.99.100).
> Escape character is '^]'.
> Welcome to Microsoft Telnet Service
>
> password:
>
> *===============================================================
> Microsoft Telnet Server.
> *===============================================================
> C:\Users\Administrator>
>
> Now autotest only reads the first 3 lines(upto Escape.....). It seems
> windows is doing something nasty here. I have put some debug prints in
> the code and here is the output. let me first put the code snippet
> from kvm_utils.py with added debug prints.
>
> def read_until_output_matches(self, patterns, filter=lambda(x):x,
> timeout=30.0, internal_timeout=3.0,
> print_func=None):
> <snip>
> end_time = time.time() + timeout
> while time.time() < end_time:
> # Read data from child
> newdata = self.read_nonblocking(internal_timeout)
> print("DEBUG: Printing data read by read_nonblocking from output:")
> print("DEBUG: data read from output is %s" % newdata)
> print("DEBUG: Printing data read by read_nonblocking from
> output done.")
> # Print it if necessary
> if print_func and newdata:
> map(print_func, newdata.splitlines())
> data += newdata
> print("DEBUG: Printing accumulated data read from output:")
> print("DEBUG: accumulated data read from output is %s" % data)
> print("DEBUG: Printing accumulated data read from output done.")
>
> done = False
> # Look for patterns
> print("DEBUG: Printing data after filter:")
> print("DEBUG: filtered data is %s" % filter(data))
> print("DEBUG: Printing data after filter done:")
> match = self.match_patterns(filter(data), patterns)
> if match != None:
> done = True
> # Check if child has died
> if self.poll() != None:
> logging.debug("Process terminated with status %d", self.poll())
> done = True
> # Are we done?
> if done: break
> <snip>
>
> Here is the output once the guest comes up.
>
> 12:27:25 INFO | DEBUG: Printing data read by read_nonblocking from output:
> 12:27:25 INFO | DEBUG: data read from output is Trying 10.0.99.100...
> 12:27:25 INFO | Connected to ichigo-dom100.linuxperf9025.net (10.0.99.100).
> 12:27:25 INFO | Escape character is '^]'.
> 12:27:25 INFO |
> 12:27:25 INFO | DEBUG: Printing data read by read_nonblocking from output done.
> 12:27:25 INFO | DEBUG: Printing accumulated data read from output:
> 12:27:25 INFO | DEBUG: accumulated data read from output is Trying
> 10.0.99.100...
> 12:27:25 INFO | Connected to ichigo-dom100.linuxperf9025.net (10.0.99.100).
> 12:27:25 INFO | Escape character is '^]'.
> 12:27:25 INFO |
> 12:27:25 INFO | DEBUG: Printing accumulated data read from output done.
> 12:27:25 INFO | DEBUG: Printing data after filter:
> 12:27:25 INFO | DEBUG: filtered data is Escape character is '^]'.
> 12:27:25 INFO | DEBUG: Printing data after filter done:
> 12:27:29 INFO | DEBUG: Printing data read by read_nonblocking from output:
> 12:27:29 INFO | DEBUG: data read from output is
> 12:27:29 INFO | DEBUG: Printing data read by read_nonblocking from output done.
> 12:27:29 INFO | DEBUG: Printing accumulated data read from output:
> 12:27:29 INFO | DEBUG: accumulated data read from output is Trying
> 10.0.99.100...
> 12:27:29 INFO | Connected to ichigo-dom100.linuxperf9025.net (10.0.99.100).
> 12:27:29 INFO | Escape character is '^]'.
> 12:27:29 INFO |
> 12:27:29 INFO | DEBUG: Printing accumulated data read from output done.
> 12:27:29 INFO | DEBUG: Printing data after filter:
> 12:27:29 INFO | DEBUG: filtered data is Escape character is '^]'.
> 12:27:29 INFO | DEBUG: Printing data after filter done:
>
> and so on... timeout elapses and test fails.
>
> I am not able to find out why read_nonblocking() is reading only 3
> lines. I have tried increasing the timeouts and internal_timeouts as
> well. But no luck.
>
> Here is how my kvm_tests.cfg looks like.
> # colorful prompt, so migration_test_command will fail, try with telnet
> ssh_prompt = "C:\Users\Administrator>"
> ssh_port = 23
> use_telnet = yes
> Any clues ?
>
> --
> Sudhir Kumar
>
--
Sudhir Kumar
--
To unsubscribe from this list: send the line "unsubscribe kvm" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
