----- "sudhir kumar" <smalikphy@xxxxxxxxx> wrote:
> On Tue, Aug 4, 2009 at 5:01 PM, Michael Goldish<mgoldish@xxxxxxxxxx>
> wrote:
> > Maybe the problem is related to how you implemented TAP support in
> > your tree. You're obviously not using user mode networking because
> I do not understand what do you mean here. Yes the setup is a tap
> network and I can login into the guest using the same command
> manually. Here is the output
> # 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>
>
> > 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.
> Here is the command:
> 23:35:13 INFO | COMMAND: telnet -l Administrator 10.0.99.100 23
>
> So on further inspection the problem limits to that
> read_nonblocking()
> is reading only 3 lines. So the culprit may be the following code
> data = ""
> while True:
> r, w, x = select.select([self.fd], [], [], timeout)
> if self.fd in r:
> try:
> data += os.read(self.fd, 1024)
> except OSError:
> return data
> else:
> return data
> in this function. Since all the 5 lines(including last empty line) do
> not appear in one go it is possible that select() returns before the
> whole lines have been writen to the file pointed by fd and read()
> reads only those 3 lines(which looks to be less likely). I observe a
> slight delay in printing the lines. First 3 lines are printed in one
> go and the last two lines are printed after a very small(< 1 sec)
> time. What do you say? I will try by putting one more call to read()
> and see what happens.
I don't think that'll help because it's OK to get 3 lines, wait a little,
and then get 2 more lines. read_until_output_matches() calls
read_nonblocking() repeatedly to read output from the Telnet process, so
pauses in output from the process are OK.
I thought it was a good idea to print the login command because although
the IP is OK, maybe the port isn't, and in the logs we don't see what
port ssh_login() is actually trying to connect to.
> >
> > ----- 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
> >
>
>
>
> --
> 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
--
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
