-
Type: Bug
-
Resolution: Duplicate
-
Priority: Major - P3
-
None
-
Affects Version/s: 2.5.2
-
Component/s: Testing Infrastructure
-
None
-
ALL
A good example from buildbot, where there is 6-second time skew between the logs from the different mongod's:
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:
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).
- duplicates
-
SERVER-24263 Order of log output across processes started by the mongo shell and resmoke.py depends on thread scheduling
- Backlog