For making it more clear here are the timoeout debug prints
14:31:04 INFO | ('DEBUG: timeout in read_until_output_matches =%d', 30)
14:31:04 INFO | ('DEBUG: internal_timeout in read_until_output_matches
=%d', 3.5)
{sorry with little syntax typo :( }
On Tue, Aug 4, 2009 at 12:12 PM, sudhir kumar<smalikphy@xxxxxxxxx> wrote:
> 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
>
--
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
