junit-plugin icon indicating copy to clipboard operation
junit-plugin copied to clipboard

...[truncated 135494 chars]...

Open brianjmurrell opened this issue 4 years ago • 15 comments

I'm not making much sense of the explanation of this option:

Retain long standard output/error: If checked, any standard output or error from a test suite will be retained in the test results after the build completes. (This refers only to additional messages printed to console, not to a failure stack trace). Such output is always kept if the test failed, but by default lengthy output from passing tests is truncated to save space...

Is that saying that that option only applies to passing tests and that failing tests should always have full output and not have ...[truncated 135494 chars]... in the middle of it's Standard Output section in the JUnit results?

IOW, I should never see ...[truncated 135494 chars]... in a failing test result, correct? If correct, then this issue is to report that I do see that even in failing test results.

brianjmurrell avatar Dec 02 '20 13:12 brianjmurrell

I should add, and maybe this is a separate ticket, but it's super annoying that the tail after the ...[truncated 135494 chars]... is displayed literally instead of interpreting the \ns:

21:40:01 DEBUG| [stdout] [1,0]<stdout>:Instance 1: starting format of SCM (dcpm:/mnt/daos1)
21:40:01 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:01.556730 instance_storage.go:107: /mnt/daos0 (dcpm) needs format: true
21:40:01 DEBUG| [stdout] [1,0]<stdout>:Instance 0: starting format of SCM (dcpm:/mnt/daos0)
21:40:12 DEBUG| [stdout] [1,3]<stdout>:Instance 0: finished format of SCM (dcpm:/mnt/daos0)
21:40:12 DEBUG| [stdout] [1,2]<stdout>:Instance 0: finished format of
...[truncated 135494 chars]...
g superblock\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DAOS I/O Server instance 1 storage ready\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:13.976631 instance_superblock.go:107: /mnt/daos1: checking superblock\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:13.977071 instance_superblock.go:111: /mnt/daos0: needs superblock (doesn\'t exist)\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:13.977124 instance_superblock.go:136: idx 0 createSuperblock()\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:13.977129 instance_superblock.go:111: /mnt/daos1: needs superblock (doesn\'t exist)\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:13.977195 instance_superblock.go:136: idx 1 createSuperblock()\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:13.977621 instance_superblock.go:166: creating /mnt/daos0/superblock: (rank: NilRank, uuid: a2d362ee-3d70-48b9-8240-95e881a84267)\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:13.977683 instance_superblock.go:166: creating /mnt/daos1/superblock: (rank: NilRank, uuid: 8c3bda34-7bc0-4b27-8f5e-f15d8f6ba682)\n21:40:13 DEBUG| [stdout] [1,0]<stdout>:DEBUG 21:40:13.978129 database.go:345: system db start: isReplica: true, isBootstrap: true

brianjmurrell avatar Dec 02 '20 13:12 brianjmurrell

Now that I look a bit more, this seems to be filed in Jenkins' Jira also.

Looking at the code, the trimming does not not appear to be conditional on the testing passing or failing:

https://github.com/jenkinsci/junit-plugin/blob/5f7513baff89516cd7217ea39101ad67116cd059/src/main/java/hudson/tasks/junit/CaseResult.java#L150-L152

There's no condition there for passing/failing.

brianjmurrell avatar Dec 02 '20 13:12 brianjmurrell

Ahhh. Looks like the code for handling the ...[truncated 135494 chars]... is actually in https://github.com/jenkinsci/junit-plugin/blob/5f7513baff89516cd7217ea39101ad67116cd059/src/main/java/hudson/tasks/junit/CaseResult.java#L193-L202 so it looks like that despite the documentation saying that failing results are not truncated, it seems they are truncated when > 100,000 bytes. Is that correct?

brianjmurrell avatar Dec 03 '20 01:12 brianjmurrell

The issue is that there’s large performance impact of storing huge stack traces I believe, as they can be kept in memory and shown on pages

@jglick probably knows more

timja avatar Dec 03 '20 07:12 timja

Yes if you are using the built-in test storage,, giant test stdout/err is going to become giant CDATA blocks in XML and giant Strings in Java heap and cause terrible performance problems loading the build record, as well as a lot of disk usage. Do not care so much about how long the HTML for that test result page is.

jglick avatar Dec 03 '20 13:12 jglick

But having a limit even for failed test results, which needs to be disabled by using Retain long standard output/error -- the result of which is to not truncate even passing results just exacerbates the whole performance issue. It forces people to have all (failed and passing) results with full stdout/stderr just so that they can get full stdout/stderr on failed runs.

Truncating output on failed runs can mean the difference between having the data needed to fix a bug or not, so truncating it can be very debilitating so for some installations it's important to not truncate. But achieving that shouldn't mean having the performance impact of having all runs without truncated output.

The only two choices available (all runs with full output or failed runs with truncated output) are far too far apart to be workable.

As an aside, the documentation is simply wrong when it says Such output is always kept if the test failed. It's not. It's still subject to a threshold.

brianjmurrell avatar Dec 03 '20 17:12 brianjmurrell

Also: if you are in fact using another storage system, like an RDB :tada:, it may be perfectly reasonable to just dump a few megs of text into a test result whether passing or failing: $JENKINS_HOME/builds/ would be no bigger, result summaries should be the same speed to load (I hope!), and the text should never be loaded into RAM unless and until you display that test case details page, and then promptly garbage-collected (again, needs to be verified).

jglick avatar Dec 03 '20 18:12 jglick

$JENKINS_HOME/builds/ would be no bigger

Extra disk use of (ideally only failing) builds to store the data needed to fix a bug is the least of my concern, and money well spent. Wasting disk space for the same on successful builds I am little less happy about.

But I am also concerned about RAM. If I am not using RDB (do you mean Ceph for this?) for storage and am just using the file system (i.e. the default storage mechanism) why is the impact on RAM different?

Is there anything specific about using RDB with Jenkins? Is there any documentation about it, why I would want to use it, etc.?

brianjmurrell avatar Dec 03 '20 19:12 brianjmurrell

money well spent. Wasting disk space for the same on successful builds I am little less happy about.

Understood. I was just trying to give some historical background for why the plugin imposes caps on text block length: because the simplistic built-in storage system scales poorly, and it seemed preferable to lose some potentially helpful diagnostic information than to risk having the whole server crash because one user peeked at an unstable build.

why is the impact on RAM different?

IIRC the whole junitResults.xml file will be parsed into in-heap objects when using the default storage. There is no such thing as random access here (barring weird hacks like implementing a limited XML parser and saving byte offsets into the XML file). By contrast, when information about a particular test case can be obtained via a SQL query on demand, there is no need to load all of the data for all of the test results in the build into memory at once. (Again I am not sure offhand that the new storage actually does this properly, but it should if not.)

Is there anything specific about using RDB with Jenkins? Is there any documentation about it

Still experimental AFAIK; @timja can direct you to current docs.

jglick avatar Dec 03 '20 23:12 jglick

https://plugins.jenkins.io/junit-sql-storage/

IIRC the whole junitResults.xml file will be parsed into in-heap objects when using the default storage. There is no such thing as random access here (barring weird hacks like implementing a limited XML parser and saving byte offsets into the XML file). By contrast, when information about a particular test case can be obtained via a SQL query on demand, there is no need to load all of the data for all of the test results in the build into memory at once. (Again I am not sure offhand that the new storage actually does this properly, but it should if not.)

Certain parts are optimised, but if you ask for a suite result you get everything in the suite... Pages like test results table will do that.

It should be better than before but may need more optimising.

The objects are very interlinked and context isn't passed around in the API as it's expected each child object has a link to it's parent that's already populated...

You can see the implemented APIs in this class: https://github.com/jenkinsci/junit-plugin/blob/master/src/main/java/io/jenkins/plugins/junit/storage/TestResultImpl.java

timja avatar Dec 04 '20 08:12 timja

I was just trying to give some historical background for why the plugin imposes caps on text block length: because the simplistic built-in storage system scales poorly, and it seemed preferable to lose some potentially helpful diagnostic information than to risk having the whole server crash because one user peeked at an unstable build.

Also understood. But the fact still remains that there is no middle ground where one can choose to have the full output for (only) failed tests but allow the truncation of passing results. Currently if one wants the full output on failed results one is required to take full output on passing results also.

So can we direct this ticket about adding that middle ground?

brianjmurrell avatar Dec 09 '20 12:12 brianjmurrell

And update the current documentation to actually be what the plugin does, and that's to truncate all results, passing or failing, but just to different degrees.

brianjmurrell avatar Dec 09 '20 12:12 brianjmurrell

both is fine with me, contributions welcome. Especially documentation fixes

timja avatar Dec 09 '20 13:12 timja

Really, 105 characters?!

image

Also, how did it know that omitting those 105 characters would %$@# me the hardest? .. It really seems to be able to locate exactly the things I care about in order to surgically omit.

TeamSPoon avatar Sep 07 '21 11:09 TeamSPoon

This issue is a monumental facepalm :man_facepalming:.

So there's this underlying architectural limitation that causes the system to maybe crash due to the use of a non-scalable mechanism to deliver the results.

Instead of fixing this architectural limitation in the project, you've got behavior in here that prevents people from being able to rely on the tool to do the only thing that it's supposed to do well which is deliver test results.

Not only that, but it's an issue that doesn't show up so that when we test the system initially for proof of concept, it looks fine. The dealbreaking issue only crops up later.

This is how you tank a software project. By shoving a critical bug under the rug. What a shame.

I was starting to look into a way to make ANSI escape codes work in these results. However it's pretty clear now that if we can't even get rid of this truncation in the first place, it wouldn't be worth trying.

unphased avatar Dec 07 '21 17:12 unphased

This should be partially addressed by https://github.com/jenkinsci/junit-plugin/pull/601, which replaces the keepLongStdio boolean property with stdioRetention. This property can be set to one of three values:

  • none - Long output from all tests is truncated
  • failed - Long output from failed tests is kept in its entirety, long output from passing tests is truncated
  • all - Long output from all tests is kept in its entirety

Note that if your test output is stored exclusively in a separate file (e.g., if you're using Maven and you've configured it with redirectTestOutputToFile set to true), then truncation may still take place. Specifically, if stdioRetention = 'all' or stdioRetention = 'failed' and the test has failed, then all files less than 1MB in size will be retained completely, but files 1MB and larger will be truncated and only the first and last 50KB will be retained. And, if stdioRetention = 'none' or stdioRetention = 'failed' and the test has passed, then files 1KB and larger will be truncated and only the first and last 500 bytes will be retained.

This matches the prior behavior for this scenario, and is done intentionally to avoid breaking environments where the plugin is already configured with keepLongStdio = true (see CaseResult::possiblyTrimStdio from the commit directly before #601 was merged).

C0urante avatar Jan 31 '24 22:01 C0urante