Maybe the problem is related to how you implemented TAP support in
your tree. You're obviously not using user mode networking because
the guest's IP address is 10.0.99.100. I'm not sure exactly what the
problem is, so can you print the connection command in remote_login()?
Add something like 'print "COMMAND: " + command' at the top of the
function, and that might help us figure out what's wrong.
----- Original Message -----
From: "sudhir kumar" <smalikphy@xxxxxxxxx>
To: "Michael Goldish" <mgoldish@xxxxxxxxxx>
Cc: "Lucas Meneghel Rodrigues" <mrodrigu@xxxxxxxxxx>, "Ryan Harper" <ryanh@xxxxxxxxxx>, "kvm-devel" <kvm@xxxxxxxxxxxxxxx>
Sent: Tuesday, August 4, 2009 9:43:42 AM (GMT+0200) Auto-Detected
Subject: Re: [AUTOTEST]telnet login fails in win2k8 DC 64. here are debug and other info
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
