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.....
> 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
