Generation of output.xml fails

[Michael Wowro]

Hi there,

robotframework-maven-plugin: 1.0.6

robotframework: 2.8.1

 

Due to necessary workarounds our testsuite executes tons of keywords (due to many loops).

It seems that the generation of output.xml of Robot Framework isn't stable anymore when exceeding some size. Many non-deterministic bugs with different symptoms appear: generation of output.xml stops without closing tags; the generated output.xml mixed the order of tags and isn't wellformed anymore; ...

I tried it with removeKeywords, but that reduced only the size of the log.html. BTW the following paragraph suggests that all outputs (including output.xml) were reduced in size if one uses removeKeywords:

http://robotframework.googlecode.com/svn/trunk/doc/userguide/RobotFrameworkUserGuide.html#removing-keywords-from-outputs

 

I haven't found another option to reduce the size of output.xml here: http://code.google.com/p/robotframework/source/browse/src/robot/run.py?name=2.8.1

Is there an approach to overcome that showstopper?

Thanks in advance,
Yours Michael

[Tatu Aalto]

Ugh

If you do not need the output file, you can disable the output file generation [1] from command line.  If i recall correctly it should be also possible from Maven plugin.

-Tatu
[1] http://robotframework.googlecode.com/hg/doc/userguide/RobotFrameworkUserGuide.html?r=2.8.1#output-file

--
You received this message because you are subscribed to the Google Groups "robotframework-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to robotframework-u...@googlegroups.com.
To post to this group, send email to robotframe...@googlegroups.com.
Visit this group at http://groups.google.com/group/robotframework-users.
For more options, visit https://groups.google.com/groups/opt_out.

[Markus Bernhardt]

Hi Michael,

Set the Output file Name to: "NONE"

This should switch off all log output. 

Cheers

Markus

[Kevin O.]

Other options include running with loglevel WARN and moving some of the work to Python/Java, etc. In a library keyword you have more control over what is logged.

[Jussi Malinen]

Hi!

I am curious as to what size causes problems in output.xml? That would be a pretty major bug, what ever the limit.

I occasionally deal with output.xmls that are several gigabytes, but I don't think I have seen one going above 10gb… I think at 4gb you hit the maximum file size for FAT32, so that could also be a cause for problems in some cases.

The remove keywords option removes the keywords from the output.xml, when using reboot for post processing: http://robotframework.googlecode.com/hg/doc/userguide/RobotFrameworkUserGuide.html?r=2.8.1#removing-keywords-from-outputs

So the solution I suggest:

First tell us how to reproduce the stability problem you have encountered and we will fix that.
Then configure your pybot run to only generate the output.xml (so --log NONE --report NONE). This makes it so that pybot will never read (or hold in memory) the output.xml it has generated. So you won't run into memory problems.
Then run rebot command and remove the keywords from a new output and generate log and report based on that.

- Jussi

[Markus Bernhardt]

Hi Jussi,

because I still have a valid NDA with the company where Michael works, I could have a look at the corrupt output xml.

The problem is not that the file or parts of it are truncated, but that invalid nested XML content is produced.

Normally the output looks like (shortened):

<test>

  <kw type="teardown" name="Teardown Of TF 17.4">

  </kw>

  <doc>Doku:

  </doc>

  <tags>

    <tag>Env1</tag>

    <tag>Env2</tag>

    <tag>Env3</tag>

  </tags>

  <status status="PASS" critical="yes" endtime="20130918 14:59:27.033" starttime="20130918 14:58:10.713"></status>

</test>

This changes sometimes to (shortened):

<test>

  <kw type="teardown" name="Teardown Of TF 17.5">

  <doc>Doku:

  </doc>

  <tags>

    <tag><status status="PASS" endtime="20130918 15:01:45.676" starttime="20130918 15:01:40.115">Dev</status>

    </tag>

</kw>

    <tag>Env1</tag>

    <tag>Env2</tag>

    <tag>Env3</tag>

  </tags>

  <status status="FAIL" critical="yes" endtime="20130918 15:01:45.675" starttime="20130918 14:59:39.482">Test timeout 2 minutes exceeded.</status>

</test>

That XML is not well formed. The </kw> element comes to late. Looks like a race condition to me, especially because it happens on a timeout.

Does that help anything?

Cheers,

Markus

[Jussi Malinen]

Hi!

Version 1.0.6 of Maven plugin is a bit old. Does this happen with Robot Framework Maven Plugin 1.2?

If this is still an issue, could you provide specific instructions or better yet, a runnable example on how to replicate this?

We do use for loops and timeouts a lot with one customer, with massive outputs, and don't get this.. so I would need some more specific instructions.

Cheers,
Jussi

[Michael Wowro]

Hi all,

thank you all for your input.
An update of the robotframwork-maven-plugin hasn't solved our problem.

After analysing the broken output.xml's we found, that all of the problems are in relationship to exceeded testcase-timeout:
As one example a testcase that exceeds a testcase-timeout looks like that:

Testcase 1.1
[Timeout] 2min
Any Keywords
[Teardown] Any Keyword

The xml of that testcase was missing the end tag </kw> for <kw type="teardown" name="Any Keyword"> and it was also missing the preceding <status> element.
Both of them were found in the succeeding testcase at an apparently random position, destroying the wellformedness of this testcase and the xml as a whole.

Unfortunately I wasn't able to reproduce the bug (also because it happens non-deterministic) but removing the testcase-timeout should solve our problem.
Unfortunately the bug shows only in a certain state of our AUT and at the moment I can't verify if my assumption is correct.

Can you please show me the lib in RF, that's responsible for the generation of output.xml?

Thanks,
Yours Michael

[Jussi Malinen]

Well, the source is in: https://code.google.com/p/robotframework/source/browse/#hg%2Fsrc%2Frobot%2Foutput

But there are a lot of test material that uses the timeout and I have never seen this. This would suggest that there may be something very specific to your environment that is causing this.

I think you should first look the answers to these questions:

What libraries and/or listeners do you use? Do you know if any of them are threaded? Do they directly access any robot framework modules?

Cheers,
Jussi

[karniemi]

Hi,

we just hit into a similar problem with robot 2.7.7 & python 2.7.3 (no maven involved), but in our case the output.xml isn't that huge, only 10s on KBs.

In one occurrence, the output looked like this:
--------------
<kw type="kw" name="${out}, ${err} = SSHLibrary.Execute Command"
    timeout="">
    <doc>Executes command on remote host over existing SSH
        connection and returns stdout and/or stderr.</doc>
    <arguments>
        <arg>${command}</arg>
        <arg>both</arg>
    </arguments>
    <msg timestamp="20131104 07:03:17.340" level="INFO">Executing
        command 'xxxxxxxxxxxxxxxxxxxxxxxx'
    </msg>
    <msg timestamp="20131104 07:03:25.116" level="INFO">${out} =
        xxxxxx
        xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
        xxxxxxxxxxxxxxxxxxxxx
        xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
    </msg>
    <msg timestamp="20131104 07:03:25.117" level="INFO">${err} = </msg>
    <status status="PASS" endtime="20131104 07:03:17.340"
        starttime="20131104 07:00:45.132"></status>
</kw>
<kw type="kw" name="BuiltIn.Log" timeout="">
    <doc>Logs the given message with the given level.</doc>
    <arguments>
        <arg>${out}</arg>
    </arguments>
    <msg timestamp="20131104 07:03:33.313" level="INFO">
        <msg timestamp="20131104 07:05:25.505" level="FAIL">Keyword
            timeout 5 minutes exceeded.</msg>
        <status status="FAIL" endtime="20131104 07:05:25.850"
            starttime="20131104 07:03:25.118"></status>
</kw>
---------------------

• So in the "middle" of logging that ${out}, a timeout msg was produced...and the end tag for the original msg is missing.
• Oddly the previous KW had ended 2mins earlier...as if that BuiltIn.log would last for >2mins...

In another case, the err messages from the suites Libraries' initialization were produced at the wrong place:

-----------------------

                           <kw type="kw" name="${out}, ${err} = SSHLibrary.Execute Command"
                                timeout="">
                                <doc>Executes command on remote host over existing SSH
                                    connection and returns stdout and/or stderr.</doc>
                                <arguments>
                                    <arg>${command}</arg>
                                    <arg>both</arg>
                                </arguments>
                                <msg timestamp="20131104 15:40:38.653" level="INFO">Executing
                                    command 'xxxxxxxxxxxxxxxxxxxx'
                                </msg>
                                <msg timestamp="20131104 15:40:45.285" level="INFO">${out} =
                                    xxxxxxxx
                                    xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
                                    xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
                                    xxxxxxxxxxxxxxxxxxxxxxxxxx
                                </msg>
                                <msg timestamp="20131104 15:40:45.285" level="INFO">${err} = </msg>
                                <status status="PASS" endtime="20131104 15:40:38.654"
                                    starttime="20131104 15:38:43.565"></status>
                            </kw>
                            <kw type="kw" name="BuiltIn.Log" timeout="">
                                <doc>Logs the given message with the given level.</doc>
                                <arguments>
                                    <arg>${out}</arg>
                                </arguments>
                                <msg timestamp="20131104 15:40:51.888" level="INFO">
                                    <errors>
                                        <msg timestamp="20131104 15:38:15.812" level="ERROR">Error in file
                                            'xxxxxxxxxxxxxxxxxxxxxxxxxxxxx'
                                            in table 'Variables': Setting variable '${TEST_RAND_NAME}'
                                            failed: Non-existing variable '${TEST_NAME}'.</msg>
                                        <msg timestamp="20131104 15:38:15.963" level="ERROR">Error in file
                                            'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx'
                                            in table 'Variables': Setting variable
                                            '${xxxxxxxxxxxxxxx} ${EMPTY}' failed: Invalid variable
                                            name '${xxxxxxxxxxxxxxxx} ${EMPTY}'.</msg>
                                        <msg timestamp="20131104 15:38:15.964" level="ERROR">Error in file
                                            'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx'
                                            in table 'Variables': Setting variable
                                            '${LOCAL_WORK_DIR_PATH} ${EMPTY}' failed: Invalid variable
                                            name '${LOCAL_WORK_DIR_PATH} ${EMPTY}'.</msg>
                                        <msg timestamp="20131104 15:38:16.910" level="ERROR">Error in file
                                            'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx'
                                            in table 'Setting': Variable file '../conf/env_setup.py' does
                                            not exist.</msg>
                                    </errors>
</robot>

-------------------------

[Markus Bernhardt]

Hi,

I think this was fixed in robot 2.8. Could you upgrade and test again?

Cheers,

Markus

[Sandeep Vaidya]

This may be of help to some:

$ robot --version
Robot Framework 3.0.2 (Python 2.7.5 on linux2)

Jenkins Robot Framework Plugin: 1.6.4


I was getting similar parsing errors when running RF tests through jenkins:

Robot results publisher started...
-Parsing output xml:
Failed!
java.io.IOException: Parsing of output xml failed!


....
...

Caused by: com.ctc.wstx.exc.WstxParsingException: Unexpected close tag </robot>; expected </doc>.
 at [row,col {unknown-source}]: [4238,7]

I deleted the robot results directory. The runs are now successful