Js test output can contain incorrectly ordered timestamps across the different mongod's that it spawns

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Duplicate
    • Priority: Major - P3
    • None
    • Affects Version/s: 2.5.2
    • Component/s: Testing Infrastructure
    • None
    • ALL
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      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).

            Assignee:
            DO NOT USE - Backlog - Test Infrastructure Group (TIG)
            Reporter:
            sam.helman@10gen.com
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: