TAP report parsing error: expected '<document start>', but found '<scalar>'

[andrew-m-leonard]

Describe the bug TAP report parsing error: expected '', but found '' https://ci.adoptopenjdk.net/job/Test_openjdk11_j9_sanity.openjdk_x86-64_linux_xl/363/console

20:05:32  TAP Reports Processing: START
20:05:32  Looking for TAP results report in workspace using pattern: **/*.tap
20:05:39  Saving reports...
20:05:39  Processing '/home/jenkins/.jenkins/jobs/Test_openjdk11_j9_sanity.openjdk_x86-64_linux_xl/builds/363/tap-master-files/openjdk-tests/TKG/test_output_16019215963274/TestTargetResult.tap'
20:05:39  Parsing TAP test result [/home/jenkins/.jenkins/jobs/Test_openjdk11_j9_sanity.openjdk_x86-64_linux_xl/builds/363/tap-master-files/openjdk-tests/TKG/test_output_16019215963274/TestTargetResult.tap].
20:05:39  org.tap4j.parser.ParserException: Error parsing TAP Stream: Error parsing YAML [ok 2 - jdk_lang_native_j9_win_0 # skip
20:05:39    ---
20:05:39  ok 3 - jdk_math_j9_0
20:05:39    ---
20:05:39  ok 4 - jdk_util_j9_0
20:05:39    ---
20:05:39  ok 5 - jdk11_tier1_cipher_0
20:05:39    ---
20:05:39  ok 6 - jdk11_tier1_buffer_0
20:05:39    ---
20:05:39  ok 7 - jdk11_tier1_iso8859_0
20:05:39    ---
20:05:39  ok 8 - jdk11_tier1_pack200_0
20:05:39    ---
20:05:39  ]: expected '<document start>', but found '<scalar>'
20:05:39   in 'string', line 2, column 3:
20:05:39        ---
20:05:39        ^
20:05:39  
20:05:39    at org.tap4j.parser.Tap13Parser.parseTapStream(Tap13Parser.java:257)
20:05:39    at org.tap4j.parser.Tap13Parser.parseFile(Tap13Parser.java:231)
20:05:39    at org.tap4j.plugin.TapParser.parse(TapParser.java:173)
20:05:39    at org.tap4j.plugin.TapPublisher.loadResults(TapPublisher.java:572)
20:05:39    at org.tap4j.plugin.TapPublisher.performImpl(TapPublisher.java:444)
20:05:39    at org.tap4j.plugin.TapPublisher.perform(TapPublisher.java:403)
20:05:39    at jenkins.tasks.SimpleBuildStep.perform(SimpleBuildStep.java:112)
20:05:39    at sun.reflect.GeneratedMethodAccessor19828.invoke(Unknown Source)
20:05:39    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
20:05:39    at java.lang.reflect.Method.invoke(Method.java:498)
20:05:39    at org.jenkinsci.plugins.workflow.steps.CoreStep$Execution.run(CoreStep.java:92)
20:05:39    at org.jenkinsci.plugins.workflow.steps.CoreStep$Execution.run(CoreStep.java:70)
20:05:39    at org.jenkinsci.plugins.workflow.steps.SynchronousNonBlockingStepExecution.lambda$start$0(SynchronousNonBlockingStepExecution.java:47)
20:05:39    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
20:05:39    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
20:05:39    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
20:05:39    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
20:05:39    at java.lang.Thread.run(Thread.java:748)
20:05:39  Caused by: org.tap4j.parser.ParserException: Error parsing YAML [ok 2 - jdk_lang_native_j9_win_0 # skip
20:05:39    ---
20:05:39  ok 3 - jdk_math_j9_0
20:05:39    ---
20:05:39  ok 4 - jdk_util_j9_0
20:05:39    ---
20:05:39  ok 5 - jdk11_tier1_cipher_0
20:05:39    ---
20:05:39  ok 6 - jdk11_tier1_buffer_0
20:05:39    ---
20:05:39  ok 7 - jdk11_tier1_iso8859_0
20:05:39    ---
20:05:39  ok 8 - jdk11_tier1_pack200_0
20:05:39    ---
20:05:39  ]: expected '<document start>', but found '<scalar>'
20:05:39   in 'string', line 2, column 3:
20:05:39        ---
20:05:39        ^
20:05:39  
20:05:39    at org.tap4j.parser.Tap13Parser.parseDiagnostics(Tap13Parser.java:469)
20:05:39    at org.tap4j.parser.Tap13Parser.onFinish(Tap13Parser.java:431)
20:05:39    at org.tap4j.parser.Tap13Parser.parseTapStream(Tap13Parser.java:255)
20:05:39    ... 17 more
20:05:39  Caused by: expected '<document start>', but found '<scalar>'
20:05:39   in 'string', line 2, column 3:
20:05:39        ---
20:05:39        ^
20:05:39  
20:05:39    at org.yaml.snakeyaml.parser.ParserImpl$ParseDocumentStart.produce(ParserImpl.java:225)
20:05:39    at org.yaml.snakeyaml.parser.ParserImpl.peekEvent(ParserImpl.java:158)
20:05:39    at org.yaml.snakeyaml.parser.ParserImpl.checkEvent(ParserImpl.java:148)
20:05:39    at org.yaml.snakeyaml.composer.Composer.getSingleNode(Composer.java:122)
20:05:39    at org.yaml.snakeyaml.constructor.BaseConstructor.getSingleData(BaseConstructor.java:150)
20:05:39    at org.yaml.snakeyaml.Yaml.loadFromReader(Yaml.java:490)
20:05:39    at org.yaml.snakeyaml.Yaml.load(Yaml.java:416)
20:05:39    at org.tap4j.parser.Tap13Parser.parseDiagnostics(Tap13Parser.java:459)
20:05:39    ... 19 more
20:05:39  TAP parse errors found in the build. Marking build as UNSTABLE
20:05:39  TAP Reports Processing: FINISH
[Pipeline] junit
20:05:39  Recording test results

To Reproduce Steps to reproduce the behavior (or Grinder rerun link): https://ci.adoptopenjdk.net/job/Grinder/parambuild/?TARGET=sanity.openjdk&CUSTOM_TARGET=&SDK_RESOURCE=upstream&VENDOR_TEST_SHAS=&JDK_BRANCH=openj9&TEST_FLAG=&VENDOR_TEST_DIRS=&ARTIFACTORY_REPO=&ARTIFACTORY_ROOT_DIR=&PLATFORM=x86-64_linux_xl&KEEP_REPORTDIR=true&PERSONAL_BUILD=false&ADOPTOPENJDK_REPO=https%3A%2F%2Fgithub.com%2FAdoptOpenJDK%2Fopenjdk-tests.git&JDK_IMPL=openj9&LABEL=&TKG_BRANCH=master&EXTRA_OPTIONS=&SSH_AGENT_CREDENTIAL=&IS_PARALLEL=false&CUSTOMIZED_SDK_URL=&BUILD_IDENTIFIER=&AUTO_DETECT=true&ADOPTOPENJDK_BRANCH=master&TKG_SHA=&ARTIFACTORY_SERVER=&CUSTOMIZED_SDK_URL_CREDENTIAL_ID=&OPENJDK_SHA=&KEEP_WORKSPACE=false&JDK_VERSION=11&BUILD_LIST=openjdk&USER_CREDENTIALS_ID=&UPSTREAM_JOB_NUMBER=706&ITERATIONS=1&VENDOR_TEST_REPOS=&JDK_REPO=https%3A%2F%2Fgithub.com%2Fibmruntimes%2Fopenj9-openjdk-jdk11&TIME_LIMIT=10&RELEASE_TAG=openj9-0.23.0&OPENJ9_BRANCH=master&OPENJ9_SHA=&JCK_GIT_REPO=&VENDOR_TEST_BRANCHES=&UPSTREAM_JOB_NAME=build-scripts%2Fjobs%2Fjdk11u%2Fjdk11u-linux-x64-openj9-linuxXL&OPENJ9_REPO=https%3A%2F%2Fgithub.com%2Feclipse%2Fopenj9.git&JVM_OPTIONS=&TKG_REPO=https%3A%2F%2Fgithub.com%2FAdoptOpenJDK%2FTKG.git

Expected behavior A clear and concise description of what you expected to happen.

Screenshots If applicable, add screenshots to help explain your problem.

Additional context Add any other context about the problem here.

[smlambert]

Looks like an error parsing output of a newly added test target (jdk_lang_native_j9_win_0)?

FYI @sophia-guo @renfeiw

[renfeiw]

Looks like it's a machine issue realted to a missing perl module: 20:13:17 Can't locate Time/HiRes.pm in @INC (@INC contains: /usr/local/lib64/perl5 /usr/local/share/perl5 /usr/lib64/perl5/vendor_perl /usr/share/perl5/vendor_perl /usr/lib64/perl5 /usr/share/perl5 .). We need this module to print out timestamp for tap output. It's supposed to come with perl, I will update the prerequisites to include it.

[sophia-guo]

Is test-ibmcloud-rhel6-x64-1 newly added? Are those newly added ibmcloud machine configured by Ansible?

[smlambert]

@sxa @Haroon-Khel - Can you answer @sophia-guo's question above? I think this issue needs to move to openjdk-infrastructure repo

[smlambert]

@renfeiw - I see that you have added perl is added to env checks in TKG and that this machine meets the prereqs criteria of perl 5.10.1 or above**, but interestingly does not contain HiRes.pm which seems to be included in other core Perl installations, perhaps we need to explicitly check (though that is certainly unexpected config).

14:11:41 perlVersion : 14:11:41
14:11:41 This is perl, v5.10.1 (*) built for x86_64-linux-thread-multi 14:11:41

[renfeiw]

Yes, we will explicitly add this module check in the machineInfo.

[Haroon-Khel]

@sophia-guo Yes that machine is newly added. I did run our ansible playbooks on the machine, as well as run a build and sanity test on it to make sure it was good to go.

@ShelleyLambert However I did need to explicitly install perl-Digest-SHA on the machine, and on test-ibmcloud-rhel7-x64-1, as per https://github.com/AdoptOpenJDK/openjdk-infrastructure/pull/1564. This solved an error I was getting while running a sanity test on the machine. Ive never had to install this package separately before. On RHEL, perl is installed via yum, so I guess perl-Digest-SHA isnt included in the core perl installation either

[sxa]

@smlambert @sophia-guo @renfeiw Just to be clear - is this definitely a newly added test (when did it come in?) which has a new prereq of the Time::HiRes module and that hasn't been required previously? Sounds superficially like the sort of thing that might be used more pervasively so just wanted to verify that, and if it's on some of the other machines how it got there :-)

[sxa]

@Haroon-Khel Can you check for this module on other machines as it would be good to confirm if this is machine specific? Unless Perl-SHA-Digest has a prereq of Time::HiRes the installation of it is unlikely to resolve this issue

[Haroon-Khel]

After a little check, I got:

Machines that have Time::HiRes test-softlayer-rhel74-x64-1 test-aws-rhel8-x64-1 build-marist-rhel77-s390x-1 build-softlayer-centos6-x64-1 test-godaddy-centos7-x64-1

Machines that do not have Time::HiRes test-softlayer-rhel69-x64-1

[Haroon-Khel]

I'll install Time::HiRes onto test-ibmcloud-rhel6-x64-1 and we can re run the test. If it passes, Ill add the package to the playbooks

[sxa]

Interesting that it got onto the RHEL7 boxes. Perhaps it's there by default on the version of perl supplied with RHEL7. test-softlayer-rhel69-x64-1 doesn't have the test tags on it so we would probably never have seen it on there previously.

[Haroon-Khel]

Rerunning the job, using a nightly jdk, in a grinder https://ci.adoptopenjdk.net/job/Grinder/4117/console

On a separate note, @ShelleyLambert I initially tried rerunning the job in a grinder by clicking Rerun in grinder and it failed here with the error

hudson.AbortException: Failed to copy artifacts from build-scripts/jobs/jdk11u/jdk11u-linux-x64-openj9-linuxXL with filter: **/*.tar.gz,**/*.tgz,**/*.zip,**/*.jar,**/*.Z

Does the Rerun in grinder functionality copy and rerun the build entirely? Or do some of the parameters not get copied over and need to be manually inputted?

[smlambert]

just as a note, @smlambert is the github id that I use (@ShelleyLambert is one autocreated for me by IBM that I will not see notifications for)

All tests use Time::HiRes, since we parse all test output and create TAP output for all tests. We have been doing this for some time without incident (which is why I assumed its part of core Perl installation). These tests are also not new, they are just reorganized into new test targets.

To answer @Haroon-Khel question in https://github.com/AdoptOpenJDK/openjdk-tests/issues/1998#issuecomment-705519313 "Rerun in Grinder" link copies the exact parameters used in the run you are copying it from. Someone running a Grinder should be aware that the upstream builds are deleted at a fast pace, so you would switch the SDK_RESOURCE from upstream to nightly to pick up the latest nightly build, since that upstream job will have already been deleted (unless you happen to be rerunning with a day or two of the failure).

Test pipelines do not build sdks, they take built sdks from various sources: SDK_RESOURCE=nightly pulls from Adopt APIv3 latest ea builds SDK_RESOURCE=releases pulls from Adopt APIv3 latest ga builds SDK_RESOURCE=upstream pulls from another job on the same CI server (as defined in UPSTREAM_JOB_NAME, UPSTREAM_JOB_NUMBER) SDK_RESOURCE=customized pulls from the location provided in CUSTOMIZED_SDK_URL

[Haroon-Khel]

Grinder, https://ci.adoptopenjdk.net/job/Grinder/4117/console, does not show the previous parsing error nor the missing Time::HiRes error. Ill go ahead and add the package to the rhel playbook

[sxa]

Since the associated PR has been merged and the machine now works I will close this issue.