----- "sudhir kumar" <smalikphy@xxxxxxxxx> wrote:
> On Tue, Aug 4, 2009 at 10:06 PM, Michael Goldish<mgoldish@xxxxxxxxxx>
> wrote:
> >
> > ----- "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.
> At this point my head is out of thoughts. Even putting a time.sleep()
> before os.read() does not print any more lines. double read()
> statement causes an indefinite wait after the telnet server starts
> running in the guest. I am clueless now. Anyone else who faced the
> same problem?
> /me beats his head.....
Like I said, the problem is not likely to be in
read_until_output_matches() or read_nonblocking(). It's normal for
read() to cause an indefinite wait because it's a blocking function,
so when there's nothing to read, it waits.
time.sleep() shouldn't help either because there's simply nothing
more to read.
If I were you, I'd add a little debug print in remote_login(), to
print the command used to log in, just to make sure the command you
run by hand equals the command used by autotest.
Simply add 'print "COMMAND: " + command' to the top of remote_login()
and then run the test again and look at the logs.
> > 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
> >
>
>
>
> --
> 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
