Re: [AUTOTEST]telnet login fails in win2k8 DC 64. here are debug and other info
On Tue, Aug 4, 2009 at 11:23 AM, Michael Goldishmgold...@redhat.com 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 smalik...@gmail.com To: kvm-devel kvm@vger.kernel.org Cc: Lucas Meneghel Rodrigues mrodr...@redhat.com, Michael Goldish mgold...@redhat.com, Ryan Harper ry...@us.ibm.com 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
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 kumarsmalik...@gmail.com wrote:
On Tue, Aug 4, 2009 at 11:23 AM, Michael Goldishmgold...@redhat.com 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 smalik...@gmail.com
To: kvm-devel kvm@vger.kernel.org
Cc: Lucas Meneghel Rodrigues mrodr...@redhat.com, Michael Goldish
mgold...@redhat.com, Ryan Harper ry...@us.ibm.com
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
Re: [AUTOTEST]telnet login fails in win2k8 DC 64. here are debug and other info
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 smalik...@gmail.com
To: Michael Goldish mgold...@redhat.com
Cc: Lucas Meneghel Rodrigues mrodr...@redhat.com, Ryan Harper
ry...@us.ibm.com, kvm-devel kvm@vger.kernel.org
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 kumarsmalik...@gmail.com wrote:
On Tue, Aug 4, 2009 at 11:23 AM, Michael Goldishmgold...@redhat.com 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 smalik...@gmail.com
To: kvm-devel kvm@vger.kernel.org
Cc: Lucas Meneghel Rodrigues mrodr...@redhat.com, Michael Goldish
mgold...@redhat.com, Ryan Harper ry...@us.ibm.com
Sent: Tuesday, August 4, 2009 8:06:32 AM (GMT+0200) Auto-Detected
Subject: [AUTOTEST]telnet login
Re: [AUTOTEST]telnet login fails in win2k8 DC 64. here are debug and other info
On Tue, Aug 4, 2009 at 5:01 PM, Michael Goldishmgold...@redhat.com 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.
- Original Message -
From: sudhir kumar smalik...@gmail.com
To: Michael Goldish mgold...@redhat.com
Cc: Lucas Meneghel Rodrigues mrodr...@redhat.com, Ryan Harper
ry...@us.ibm.com, kvm-devel kvm@vger.kernel.org
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 kumarsmalik...@gmail.com wrote:
On Tue, Aug 4, 2009 at 11:23 AM, Michael Goldishmgold...@redhat.com 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 =
Re: [AUTOTEST]telnet login fails in win2k8 DC 64. here are debug and other info
On Tue, Aug 4, 2009 at 10:06 PM, Michael Goldishmgold...@redhat.com wrote:
- sudhir kumar smalik...@gmail.com wrote:
On Tue, Aug 4, 2009 at 5:01 PM, Michael Goldishmgold...@redhat.com
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 smalik...@gmail.com
To: Michael Goldish mgold...@redhat.com
Cc: Lucas Meneghel Rodrigues mrodr...@redhat.com, Ryan Harper
ry...@us.ibm.com, kvm-devel kvm@vger.kernel.org
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 kumarsmalik...@gmail.com
wrote:
On Tue, Aug 4, 2009 at 11:23 AM, Michael
Goldishmgold...@redhat.com 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
Re: [AUTOTEST]telnet login fails in win2k8 DC 64. here are debug and other info
- sudhir kumar smalik...@gmail.com wrote:
On Tue, Aug 4, 2009 at 10:06 PM, Michael Goldishmgold...@redhat.com
wrote:
- sudhir kumar smalik...@gmail.com wrote:
On Tue, Aug 4, 2009 at 5:01 PM, Michael
Goldishmgold...@redhat.com
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 smalik...@gmail.com
To: Michael Goldish mgold...@redhat.com
Cc: Lucas Meneghel Rodrigues mrodr...@redhat.com, Ryan
Harper
ry...@us.ibm.com, kvm-devel kvm@vger.kernel.org
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
kumarsmalik...@gmail.com
wrote:
On Tue, Aug 4, 2009 at 11:23 AM, Michael
Goldishmgold...@redhat.com 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
[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 -- To unsubscribe from this list: send the line unsubscribe kvm in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [AUTOTEST]telnet login fails in win2k8 DC 64. here are debug and other info
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. Are you sure you increased the timeout? You only sent a log of 4 seconds (starting at 12:27:25). How long does read_until_output_matches() wait before it gives up? - Original Message - From: sudhir kumar smalik...@gmail.com To: kvm-devel kvm@vger.kernel.org Cc: Lucas Meneghel Rodrigues mrodr...@redhat.com, Michael Goldish mgold...@redhat.com, Ryan Harper ry...@us.ibm.com 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.
