[SERVER-60487] Test logs consist of 3 lines (starting/pid/finished) on enterprise-rhel-80-64-bit* build variant Created: 06/Oct/21  Updated: 29/Oct/23  Resolved: 06/Oct/21

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 5.2.0

Type: Bug Priority: Major - P3
Reporter: Sviatlana Zuiko Assignee: Robert Guo (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Problem/Incident
Backwards Compatibility: Fully Compatible
Backport Requested:
v5.1
Participants:

 Description   

Failed execution task
Successful test consists of 3 lines:

[2021/10/06 10:49:18.931] [js_test:3_upgrade_replset] Starting JSTest jstests/multiVersion/genericSetFCVUsage/3_upgrade_replset.js...
[2021/10/06 10:49:18.931] PATH=/data/mci/2e566072cd8ee4ec281b7cf062a3582c/src:/data/multiversion:/data/mci/2e566072cd8ee4ec281b7cf062a3582c/src/dist-test/bin:/data/mci/2e566072cd8ee4ec281b7cf062a3582c/venv/bin:/home/ec2-user/.local/bin:/home/ec2-user/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/opt/node/bin:/opt/node/bin:/data/multiversion INSTALL_DIR=/data/mci/2e566072cd8ee4ec281b7cf062a3582c/src/dist-test/bin /data/mci/2e566072cd8ee4ec281b7cf062a3582c/src/dist-test/bin/mongo --eval 'TestData = new Object(); TestData["auth"] = true; TestData["authMechanism"] = "SCRAM-SHA-1"; TestData["keyFile"] = "jstests/libs/authTestsKey"; TestData["keyFileData"] = "Thiskeyisonlyforrunningthesuitewithauthenticationdontuseitinanytestsdirectly"; TestData["minPort"] = 20270; TestData["maxPort"] = 20499; TestData["peerPids"] = []; TestData["alwaysUseLogFiles"] = false; TestData["failIfUnterminatedProcesses"] = true; TestData["implicitlyShardOnCreateCollectionOnly"] = false; TestData["isMainTest"] = true; TestData["numTestClients"] = 1; TestData["backupOnRestartDir"] = null; TestData["enableMajorityReadConcern"] = true; TestData["mixedBinVersions"] = ""; TestData["noJournal"] = false; TestData["storageEngine"] = "wiredTiger"; TestData["storageEngineCacheSizeGB"] = "1"; TestData["testName"] = "3_upgrade_replset"; TestData["transportLayer"] = ""; TestData["wiredTigerCollectionConfigString"] = ""; TestData["wiredTigerEngineConfigString"] = ""; TestData["wiredTigerIndexConfigString"] = ""; TestData["inEvergreen"] = true; TestData["evergreenTaskId"] = "mongodb_mongo_master_enterprise_rhel_80_64_bit_single_task_baseline_multiversion_auth_0_enterprise_rhel_80_64_bit_single_task_baseline_e4ebcccefb481fac9109417610828c2360149191_21_10_06_07_30_20"; TestData["setParameters"] = new Object(); TestData["setParameters"]["logComponentVerbosity"] = new Object(); TestData["setParameters"]["logComponentVerbosity"]["replication"] = new Object(); TestData["setParameters"]["logComponentVerbosity"]["replication"]["election"] = 4; TestData["setParameters"]["logComponentVerbosity"]["replication"]["heartbeats"] = 2; TestData["setParameters"]["logComponentVerbosity"]["replication"]["initialSync"] = 2; TestData["setParameters"]["logComponentVerbosity"]["replication"]["rollback"] = 2; TestData["setParameters"]["logComponentVerbosity"]["sharding"] = new Object(); TestData["setParameters"]["logComponentVerbosity"]["sharding"]["migration"] = 2; TestData["setParameters"]["logComponentVerbosity"]["storage"] = new Object(); TestData["setParameters"]["logComponentVerbosity"]["storage"]["recovery"] = 2; TestData["setParameters"]["logComponentVerbosity"]["transaction"] = 4; TestData["setParameters"]["logComponentVerbosity"]["tenantMigration"] = 4; TestData["setParameters"]["reshardingMinimumOperationDurationMillis"] = 5000; TestData["setParametersMongos"] = new Object(); TestData["setParametersMongos"]["logComponentVerbosity"] = new Object(); TestData["setParametersMongos"]["logComponentVerbosity"]["transaction"] = 3; TestData["setParametersMongocryptd"] = new Object(); TestData["undoRecorderPath"] = null; TestData["transactionLifetimeLimitSeconds"] = 86400; MongoRunner.dataDir = "/data/db/job1/mongorunner"; MongoRunner.dataPath = "/data/db/job1/mongorunner/"; load('"'"'jstests/libs/override_methods/validate_collections_on_shutdown.js'"'"');; load('"'"'jstests/libs/override_methods/check_uuids_consistent_across_cluster.js'"'"');; load('"'"'jstests/libs/override_methods/check_indexes_consistent_across_cluster.js'"'"');; load('"'"'jstests/libs/override_methods/check_orphans_are_deleted.js'"'"');; load('"'"'jstests/libs/override_methods/implicitly_retry_on_background_op_in_progress.js'"'"');; (function() { Timestamp.prototype.toString = function() { throw new Error("Cannot toString timestamps. Consider using timestampCmp() for comparison or tojson(<variable>) for output."); } })();' --authenticationDatabase=local --authenticationMechanism=SCRAM-SHA-1 --nodb --password=Thiskeyisonlyforrunningthesuitewithauthenticationdontuseitinanytestsdirectly --username=__system jstests/multiVersion/genericSetFCVUsage/3_upgrade_replset.js
[2021/10/06 10:49:18.949] [js_test:3_upgrade_replset] JSTest jstests/multiVersion/genericSetFCVUsage/3_upgrade_replset.js started with pid 28412.
[2021/10/06 10:51:13.425] [js_test:3_upgrade_replset] JSTest jstests/multiVersion/genericSetFCVUsage/3_upgrade_replset.js finished.

Luckily, 3_upgrade_replset.js test logs are present in all job logs.

Same is true for failed test - it consists of 2 lines (Starting/pid):

[2021/10/06 10:51:13.489] [js_test:remove_invalid_index_options] Starting JSTest jstests/multiVersion/remove_invalid_index_options.js...
[2021/10/06 10:51:13.489] PATH=/data/mci/2e566072cd8ee4ec281b7cf062a3582c/src:/data/multiversion:/data/mci/2e566072cd8ee4ec281b7cf062a3582c/src/dist-test/bin:/data/mci/2e566072cd8ee4ec281b7cf062a3582c/venv/bin:/home/ec2-user/.local/bin:/home/ec2-user/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/opt/node/bin:/opt/node/bin:/data/multiversion INSTALL_DIR=/data/mci/2e566072cd8ee4ec281b7cf062a3582c/src/dist-test/bin /data/mci/2e566072cd8ee4ec281b7cf062a3582c/src/dist-test/bin/mongo --eval 'TestData = new Object(); TestData["auth"] = true; TestData["authMechanism"] = "SCRAM-SHA-1"; TestData["keyFile"] = "jstests/libs/authTestsKey"; TestData["keyFileData"] = "Thiskeyisonlyforrunningthesuitewithauthenticationdontuseitinanytestsdirectly"; TestData["minPort"] = 20270; TestData["maxPort"] = 20499; TestData["peerPids"] = []; TestData["alwaysUseLogFiles"] = false; TestData["failIfUnterminatedProcesses"] = true; TestData["implicitlyShardOnCreateCollectionOnly"] = false; TestData["isMainTest"] = true; TestData["numTestClients"] = 1; TestData["backupOnRestartDir"] = null; TestData["enableMajorityReadConcern"] = true; TestData["mixedBinVersions"] = ""; TestData["noJournal"] = false; TestData["storageEngine"] = "wiredTiger"; TestData["storageEngineCacheSizeGB"] = "1"; TestData["testName"] = "remove_invalid_index_options"; TestData["transportLayer"] = ""; TestData["wiredTigerCollectionConfigString"] = ""; TestData["wiredTigerEngineConfigString"] = ""; TestData["wiredTigerIndexConfigString"] = ""; TestData["inEvergreen"] = true; TestData["evergreenTaskId"] = "mongodb_mongo_master_enterprise_rhel_80_64_bit_single_task_baseline_multiversion_auth_0_enterprise_rhel_80_64_bit_single_task_baseline_e4ebcccefb481fac9109417610828c2360149191_21_10_06_07_30_20"; TestData["setParameters"] = new Object(); TestData["setParameters"]["logComponentVerbosity"] = new Object(); TestData["setParameters"]["logComponentVerbosity"]["replication"] = new Object(); TestData["setParameters"]["logComponentVerbosity"]["replication"]["election"] = 4; TestData["setParameters"]["logComponentVerbosity"]["replication"]["heartbeats"] = 2; TestData["setParameters"]["logComponentVerbosity"]["replication"]["initialSync"] = 2; TestData["setParameters"]["logComponentVerbosity"]["replication"]["rollback"] = 2; TestData["setParameters"]["logComponentVerbosity"]["sharding"] = new Object(); TestData["setParameters"]["logComponentVerbosity"]["sharding"]["migration"] = 2; TestData["setParameters"]["logComponentVerbosity"]["storage"] = new Object(); TestData["setParameters"]["logComponentVerbosity"]["storage"]["recovery"] = 2; TestData["setParameters"]["logComponentVerbosity"]["transaction"] = 4; TestData["setParameters"]["logComponentVerbosity"]["tenantMigration"] = 4; TestData["setParameters"]["reshardingMinimumOperationDurationMillis"] = 5000; TestData["setParametersMongos"] = new Object(); TestData["setParametersMongos"]["logComponentVerbosity"] = new Object(); TestData["setParametersMongos"]["logComponentVerbosity"]["transaction"] = 3; TestData["setParametersMongocryptd"] = new Object(); TestData["undoRecorderPath"] = null; TestData["transactionLifetimeLimitSeconds"] = 86400; MongoRunner.dataDir = "/data/db/job1/mongorunner"; MongoRunner.dataPath = "/data/db/job1/mongorunner/"; load('"'"'jstests/libs/override_methods/validate_collections_on_shutdown.js'"'"');; load('"'"'jstests/libs/override_methods/check_uuids_consistent_across_cluster.js'"'"');; load('"'"'jstests/libs/override_methods/check_indexes_consistent_across_cluster.js'"'"');; load('"'"'jstests/libs/override_methods/check_orphans_are_deleted.js'"'"');; load('"'"'jstests/libs/override_methods/implicitly_retry_on_background_op_in_progress.js'"'"');; (function() { Timestamp.prototype.toString = function() { throw new Error("Cannot toString timestamps. Consider using timestampCmp() for comparison or tojson(<variable>) for output."); } })();' --authenticationDatabase=local --authenticationMechanism=SCRAM-SHA-1 --nodb --password=Thiskeyisonlyforrunningthesuitewithauthenticationdontuseitinanytestsdirectly --username=__system jstests/multiVersion/remove_invalid_index_options.js
[2021/10/06 10:51:13.507] [js_test:remove_invalid_index_options] JSTest jstests/multiVersion/remove_invalid_index_options.js started with pid 7501.

Luckily, there's a workaround - failed test logs could be found in all job logs.



 Comments   
Comment by Robert Guo (Inactive) [ 06/Oct/21 ]

first bad commit:
https://github.com/mongodb/mongo/commit/cf6da1848adeee1ef16f3ef5f26327669f493120

first good commit:
https://github.com/mongodb/mongo/commit/de8b58214880e0b61d01fecb7e5d8b7abbdb8c27

Comment by Githook User [ 06/Oct/21 ]

Author:

{'name': 'Robert Guo', 'email': 'robert.guo@mongodb.com'}

Message: SERVER-60487 fix test name for JSTest testcase
Branch: master
https://github.com/mongodb/mongo/commit/de8b58214880e0b61d01fecb7e5d8b7abbdb8c27

Comment by Sviatlana Zuiko [ 06/Oct/21 ]

Also, it looks like tests endpoint has broken links to test logs either:

[
  {
    "test_id": "615d81c3ae22bd8ad1ef53e1",
    "task_id": "mongodb_mongo_master_enterprise_rhel_80_64_bit_single_task_baseline_multiversion_auth_0_enterprise_rhel_80_64_bit_single_task_baseline_e4ebcccefb481fac9109417610828c2360149191_21_10_06_07_30_20",
    "execution": 0,
    "status": "fail",
    "test_file": "jstests/multiVersion/remove_invalid_index_options.js",
    "display_test_name": null,
    "group_id": "1",
    "logs": {
      "url": "https://evergreen.mongodb.com/test_log/mongodb_mongo_master_enterprise_rhel_80_64_bit_single_task_baseline_multiversion_auth_0_enterprise_rhel_80_64_bit_single_task_baseline_e4ebcccefb481fac9109417610828c2360149191_21_10_06_07_30_20/0?test_name=d6046032-f419-4dd9-b64e-13c3ec86667d\u0026group_id=1#L0",
      "url_raw": "https://evergreen.mongodb.com/test_log/mongodb_mongo_master_enterprise_rhel_80_64_bit_single_task_baseline_multiversion_auth_0_enterprise_rhel_80_64_bit_single_task_baseline_e4ebcccefb481fac9109417610828c2360149191_21_10_06_07_30_20/0?test_name=d6046032-f419-4dd9-b64e-13c3ec86667d\u0026group_id=1\u0026text=true",
      "url_lobster": "https://evergreen.mongodb.com/lobster/evergreen/test/mongodb_mongo_master_enterprise_rhel_80_64_bit_single_task_baseline_multiversion_auth_0_enterprise_rhel_80_64_bit_single_task_baseline_e4ebcccefb481fac9109417610828c2360149191_21_10_06_07_30_20/0/d6046032-f419-4dd9-b64e-13c3ec86667d/1#shareLine=0",
      "line_num": 0
    },
    "exit_code": 253,
    "start_time": "2021-10-06T10:51:13.487347712Z",
    "end_time": "2021-10-06T10:51:24.763273984Z",
    "duration": 11.275926351547241
  }
]

If you try to open logs.url, it will show up an empty page. While if you substitute \u0026 to & the test log opens

Generated at Thu Feb 08 05:49:55 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.