Strange xml (Sax) parsing exception
Pico Geyer
I ran into an ugly exception while running pybot.
I think it might have started shortly after upgrading to 2.6.1 (from
2.5 ish) but I'm not 100% sure.
So I'm running my test with TRACE level debugging and this is the error I get:
[ ERROR ] Unexpected error: SAXParseException:
/usr/home/pico/dev/XTF/Tests/output.xml:1149:4: not well-formed
(invalid token)
Traceback (most recent call last):
File "/usr/local/lib/python2.7/site-packages/robot/__init__.py",
line 88, in _execute
suite = method(*datasources, **options)
File "/usr/local/lib/python2.7/site-packages/robot/__init__.py",
line 131, in run
ResultWriter(settings).write_robot_results(output)
File "/usr/local/lib/python2.7/site-packages/robot/result/resultwriter.py",
line 50, in write_robot_results
LogBuilder(self).build()
File "/usr/local/lib/python2.7/site-packages/robot/result/builders.py",
line 89, in build
self._context.data_model.set_settings(self._get_settings())
File "/usr/local/lib/python2.7/site-packages/robot/result/resultwriter.py",
line 37, in data_model
self._data_model = parser.parse(self._data_sources[0])
File "/usr/local/lib/python2.7/site-packages/robot/result/outputparser.py",
line 33, in parse
return self._parse_fileobj(outputfile)
File "/usr/local/lib/python2.7/site-packages/robot/result/outputparser.py",
line 36, in _parse_fileobj
sax.parse(outputfile, self)
File "/usr/local/lib/python2.7/xml/sax/__init__.py", line 33, in parse
parser.parse(source)
File "/usr/local/lib/python2.7/xml/sax/expatreader.py", line 107, in parse
xmlreader.IncrementalParser.parse(self, source)
File "/usr/local/lib/python2.7/xml/sax/xmlreader.py", line 123, in parse
self.feed(buffer)
File "/usr/local/lib/python2.7/xml/sax/expatreader.py", line 211, in feed
self._err_handler.fatalError(exc)
File "/usr/local/lib/python2.7/xml/sax/handler.py", line 38, in fatalError
raise exception
So I went and looked at the output.xml to see why SAX can't parse it.
This is what the offending line(s) looks like:
<msg<msg timestamp="20110908 18:14:49.759" level="INFO">Executing
command '/management/cgi-bin/netconf -r'</msg>
timestamp="20110908 18:14:49.759" level="DEBUG">[chan 2] EOF received (2)</msg>
Looks like two threads were writing to the file at the same time?
Here's the output with a little more context:
<kw type="kw" name="${netconf output} = SSHLibrary.Execute Command" timeout="">
<doc>Executes command on remote host over existing SSH connection and
returns stdout and/or stderr.</doc>
<arguments>
<arg>/management/cgi-bin/netconf -r</arg>
</arguments>
<msg timestamp="20110908 18:14:36.973" level="TRACE">Arguments: [
u'/management/cgi-bin/netconf -r' ]</msg>
<msg timestamp="20110908 18:14:36.973" level="DEBUG">[chan 2] Max
packet in: 34816 bytes</msg>
<msg timestamp="20110908 18:14:36.976" level="DEBUG">[chan 2] Max
packet out: 32768 bytes</msg>
<msg timestamp="20110908 18:14:36.976" level="INFO">Secsh channel 2
opened.</msg>
<msg timestamp="20110908 18:14:37.109" level="DEBUG">[chan 2] Sesch
channel 2 request ok</msg>
<msg<msg timestamp="20110908 18:14:49.759" level="INFO">Executing
command '/management/cgi-bin/netconf -r'</msg>
timestamp="20110908 18:14:49.759" level="DEBUG">[chan 2] EOF received (2)</msg>
<msg timestamp="20110908 18:14:49.760" level="TRACE">Return:
'Recreated configuration ok'</msg>
<msg timestamp="20110908 18:14:49.760" level="INFO">${netconf output}
= Recreated configuration ok</msg>
<status status="PASS" endtime="20110908 18:14:49.760"
starttime="20110908 18:14:36.972"></status>
</kw>
Does this look like a bug?
Possibly something the SSHLibrary is doing wrong?
I'll try to extract this code from my larger test framework to see if
I can reproduce it in a simpler test.
But in the mean time, any suggestions?
Thanks and regards,
Pico
Pico Geyer
> I can reproduce it in a simpler test.
Ok, well it seems reproducing it in a simpler test was *way* easier
than I thought.
Just edit the SSH_Test.txt and edit the T1 test.
Replace the hostname, username and password with something you can test with.
Then run the test with pybot -L debug SSH_Test.txt or
pybot -L trace SSH_Test.txt
And I'm hoping you'll get an exception similar to the one above.
Thanks again,
Pico
Pekka Klärck
>> I'll try to extract this code from my larger test framework to see if
>> I can reproduce it in a simpler test.
>
> Ok, well it seems reproducing it in a simpler test was *way* easier
> than I thought.
Do you get the error every time? I tried this and got the following
error when I executed your test for the first time but since then
everything has succeeded.
[ ERROR ] Unexpected error: IOError: close() called during concurrent
operation on the same file object.
Traceback (most recent call last):
File "/home/peke/Devel/robotframework/src/robot/__init__.py", line
88, in _execute
suite = method(*datasources, **options)
File "/home/peke/Devel/robotframework/src/robot/__init__.py", line 128, in run
output.close(suite)
File "/home/peke/Devel/robotframework/src/robot/output/output.py",
line 53, in close
self._xmllogger.close()
File "/home/peke/Devel/robotframework/src/robot/output/xmllogger.py",
line 46, in close
self._writer.close()
File "/home/peke/Devel/robotframework/src/robot/utils/abstractxmlwriter.py",
line 64, in close
self._close()
File "/home/peke/Devel/robotframework/src/robot/utils/abstractxmlwriter.py",
line 69, in _close
self._output.close()
Based on the error message the root cause seems to be the same as in
your case. If you didn't get the error with RF 2.5.x then I guess the
bug is in Robot but SSHLibrary seems to trigger this somehow.
Unfortunately debugging is pretty hard if I cannot reproduce this
again.
Cheers,
.peke
--
Agile Tester/Developer/Consultant :: http://eliga.fi
Lead Developer of Robot Framework :: http://robotframework.org
Pekka Klärck
>
> I ran into an ugly exception while running pybot.
> I think it might have started shortly after upgrading to 2.6.1 (from
> 2.5 ish) but I'm not 100% sure.
After a little bit more investigation I finally understood whats causing this:
1) SSHLibrary uses Paramiko tool internally on Python,
2) Paramiko uses Python's `logging` module internally in threads,
3) Robot Framework 2.6 automatically collects messages logged by
`logging` into its log file (issue 455 [1]),
4) Logging in threads easily causing problems like this (see e.g.
issue 893 [2]).
I submitted issue 950 [3] about the problem and believe it can be
fixed for the 2.6.2 release. I think the best approach is just
ignoring log messages coming from non-main threads. That's
unfortunately slightly backwards incompatible, but corrupted output
files is a much bigger problem. We have already before advised library
writes to communicate with the framework only from the main thread and
now that is just enforced.
Thanks for the report Pico and thanks especially for providing an
example to reproduce the problem with. I just realized the same root
cause has most likely caused also issue 947 [4].
[1] http://code.google.com/p/robotframework/issues/detail?id=455
[2] http://code.google.com/p/robotframework/issues/detail?id=893
[3] http://code.google.com/p/robotframework/issues/detail?id=950
[4] http://code.google.com/p/robotframework/issues/detail?id=947