-
Type:
Bug
-
Resolution: Incomplete
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: Build
-
Build
-
ALL
Some test logs contain a large number of blank lines. e.g. <http://buildlogs.mongodb.org/mci_0.9_windows_32/builds/33297/test/jsCore_compatibility_0/splitvector.js?mode=raw> (also attached to ticket).
~95% of lines in the above test output are blank:
rassi@laptop:~/work/mongo $ grep '^$' splitvector_js_test_output.txt | wc -l
3974
rassi@laptop:~/work/mongo $ wc -l splitvector_js_test_output.txt
4099 splitvector_js_test_output.txt
rassi@laptop:~/work/mongo $
The blank lines seem to appear after the test finishes:
2014-03-20T22:23:23.358+0000 [conn60] build index on: test.jstests_splitvector properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "test.jstests_splitvector" }
2014-03-20T22:23:23.358+0000 [conn60] added index to empty collection
2014-03-20T22:23:23.359+0000 [conn60] build index on: test.jstests_splitvector properties: { v: 1, key: { x: 1.0, y: -1.0, z: 1.0 }, name: "x_1_y_-1_z_1", ns: "test.jstests_splitvector" }
2014-03-20T22:23:23.359+0000 [conn60] added index to empty collection
2014-03-20T22:23:25.409+0000 [conn60] request split points lookup for chunk test.jstests_splitvector { : MinKey, : MaxKey, : MinKey } -->> { : MaxKey, : MinKey, : MaxKey }
test.jstests_splitvector
test.jstests_splitvector
PASSED
It looks like buildlogger.py is getting the blank lines from the shell stdout (it's entirely unclear why the shell would be generating them):
> db.logs.find({build_id:ObjectId("532b64add2a60f7ad7000543"),test_id:ObjectId("532b6a30d2a60f0511000b1f")}).sort({seq:1}).limit(1).skip(0).pretty()
{
"_id" : ObjectId("532b6a3fd2a60f0511000b9e"),
"build_id" : ObjectId("532b64add2a60f7ad7000543"),
"test_id" : ObjectId("532b6a30d2a60f0511000b1f"),
"lines" : [
[
ISODate("2014-03-20T22:22:40.401Z"),
"MongoDB shell version: 2.6.0-rc2-pre-"
],
[
ISODate("2014-03-20T22:22:40.454Z"),
"connecting to: 127.0.0.1:27999/test"
],
[
ISODate("2014-03-20T22:22:40.459Z"),
"D:\\data\\db/"
],
[
ISODate("2014-03-20T22:22:55.045Z"),
"test.jstests_splitvector"
]
],
"seq" : 1
}
> db.logs.find({build_id:ObjectId("532b64add2a60f7ad7000543"),test_id:ObjectId("532b6a30d2a60f0511000b1f")}).sort({seq:1}).limit(1).skip(1).pretty()
{
"_id" : ObjectId("532b6a5dd2a60f0566000b1c"),
"build_id" : ObjectId("532b64add2a60f7ad7000543"),
"test_id" : ObjectId("532b6a30d2a60f0511000b1f"),
"lines" : [
[
ISODate("2014-03-20T22:23:25.425Z"),
"test.jstests_splitvector"
]
],
"seq" : 2
}
> db.logs.find({build_id:ObjectId("532b64add2a60f7ad7000543"),test_id:ObjectId("532b6a30d2a60f0511000b1f")}).sort({seq:1}).limit(1).skip(i++).pretty()
{
"_id" : ObjectId("532b6a5dd2a60f067b00026d"),
"build_id" : ObjectId("532b64add2a60f7ad7000543"),
"test_id" : ObjectId("532b6a30d2a60f0511000b1f"),
"lines" : [
[
ISODate("2014-03-20T22:23:25.445Z"),
"test.jstests_splitvector"
],
[
ISODate("2014-03-20T22:23:25.445Z"),
"PASSED"
],
[
ISODate("2014-03-20T22:23:25.448Z"),
""
],
[
ISODate("2014-03-20T22:23:25.448Z"),
""
],
[
ISODate("2014-03-20T22:23:25.448Z"),
""
],
<snip>
This seems to affect ~1% of tests in buildlogger (that is, ~1% of tests contain at least 1000 blank lines):
> db.logs.aggregate([{$limit:100000},{$unwind:'$lines'},{$match:{"lines.1":""}},{$group:{_id:{build_id:'$build_id',test_id:'$test_id'},count:{$sum:1}}},{$match:{count:{$gt:1000}}}]).result.length
985