[SERVER-11257] Js test output can contain incorrectly ordered timestamps across the different mongod's that it spawns Created: 17/Oct/13  Updated: 12/Jan/17  Resolved: 12/Jan/17

Status: Closed
Project: Core Server
Component/s: Testing Infrastructure
Affects Version/s: 2.5.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: sam.helman@10gen.com Assignee: DO NOT USE - Backlog - Test Infrastructure Group (TIG)
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-24263 Order of log output across processes ... Open
Operating System: ALL
Participants:

 Description   

A good example from buildbot, where there is 6-second time skew between the logs from the different mongod's:

http://buildlogs.mongodb.org/Nightly%20Linux%20RHEL%2064-bit/builds/712/test/recent%20failures/stale_clustered.js

 m31102| 2013-10-16T00:24:45.139-0400 [conn44] end connection 10.12.15.100:55716 (2 connections now open)
 m31102| 2013-10-16T00:24:45.139-0400 [initandlisten] connection accepted from 10.12.15.100:55742 #46 (3 connections now open)
 m31102| 2013-10-16T00:24:45.143-0400 [conn45] end connection 10.12.15.100:55717 (2 connections now open)
 m31102| 2013-10-16T00:24:45.143-0400 [initandlisten] connection accepted from 10.12.15.100:55743 #47 (3 connections now open)
 m31202| 2013-10-16T00:20:09.346-0400 [initandlisten] db version v2.5.3-pre-
 m31202| 2013-10-16T00:20:09.346-0400 [initandlisten] git version: 94ce941611abf2fd3826936a90d93b09e483d99c
 m31202| 2013-10-16T00:20:09.346-0400 [initandlisten] build info: Linux bs-rhel-57-64-2 2.6.18-274.el5xen #1 SMP Fri Jul 8 17:45:44 EDT 2011 x86_64 BOOST_LIB_VERSION=1_49
 m31202| 2013-10-16T00:20:09.346-0400 [initandlisten] allocator: tcmalloc
 m31202| 2013-10-16T00:20:09.346-0400 [initandlisten] options: { dbpath: "/data/db/clusteredstale-rs1-2", noprealloc: true, oplogSize: 40, port: 31202, replSet: "clusteredstale-rs1", rest: true, setParameter: [ "enableTestCommands=1" ], smallfiles: true }
 m31202| 2013-10-16T00:20:09.352-0400 [initandlisten] journal dir=/data/db/clusteredstale-rs1-2/journal
 m31202| 2013-10-16T00:20:09.352-0400 [initandlisten] recover : no journal files present, no recovery needed
 m31200| 2013-10-16T00:18:52.339-0400 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
 m31200| 2013-10-16T00:18:53.343-0400 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
 m31200| 2013-10-16T00:18:54.347-0400 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
 m31200| 2013-10-16T00:18:55.350-0400 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
 m31200| 2013-10-16T00:18:56.354-0400 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)

and another from MCI:

http://buildlogs.mongodb.org/mci_0.9_linux_64_duroff/builds/1357/test/sharding_0/authConnectionHook.js

 m29001| 2013-10-16T17:59:57.245+0000 [journal] journal REMAPPRIVATEVIEW done startedAt: 3 n:6 0ms
 m29002| 2013-10-16T18:01:22.093+0000 [journal] journal REMAPPRIVATEVIEW done startedAt: 1 n:3 0ms
 m30999| 2013-10-16T18:05:26.674+0000 [Balancer] trying reconnect to ip-10-149-6-32:29001
 m29000| 2013-10-16T17:59:49.324+0000 [conn9] command admin.$cmd command: { getlasterror: 1, fsync: 1 } ntoreturn:1 keyUpdates:0  reslen:95 28ms
 m29001| 2013-10-16T17:59:57.261+0000 [conn9] insert config.changelog ninserted:1 keyUpdates:0 locks(micros) w:226 0ms

The essential issue seems to be that the mongod's that the js tests spawn do not flush their stdout buffers in a way that the timestamps across the different mongod's match up. If you look at the logs, it is clear that the time skew occurs between logs from different mongod's (different colors in the logs).


Generated at Thu Feb 08 03:25:19 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.