[SERVER-8284] After re-starting mongod, logs gets filled with messages during IndexRebuild Created: 22/Jan/13  Updated: 11/Jul/16  Resolved: 07/Feb/13

Status: Closed
Project: Core Server
Component/s: Index Maintenance
Affects Version/s: 2.3.2
Fix Version/s: 2.4.0-rc1

Type: Bug Priority: Major - P3
Reporter: Alvin Richards (Inactive) Assignee: Kristina Chodorow (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

1. Create a text index
2. During the creation, kill the mongod process
3. Re-start the mongod process
4. Observe the messages

Participants:

 Description   

Problem:
After a restart of mongod the logs gets filled with the following messages

5.510 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:51:55.864 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:51:56.218 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:51:56.571 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:51:59.743 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:52:00.003 [IndexRebuilder] 		Index: (1/3) External Sort Progress: 1143000/21633992	5%
Tue Jan 22 22:52:00.092 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:52:00.419 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:52:00.779 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:52:01.141 [IndexRebuilder] warning Listener::getElapsedTimeMillis returning 0ms
Tue Jan 22 22:52:0

Workaround:
None



 Comments   
Comment by auto [ 07/Feb/13 ]

Author:

{u'date': u'2013-02-01T18:39:51Z', u'email': u'kristina@10gen.com', u'name': u'Kristina'}

Message: SERVER-8284 Turn off access warning during index rebuilds
Branch: master
https://github.com/mongodb/mongo/commit/2862a34f292335574a96d0a13390aec1011590f4

Comment by Eric Milkie [ 25/Jan/13 ]

The messages are happening because we do not set up the elapsed timer until we start to listen for incoming connections, since we use select() to run the timer.
We need the timer during index builds because the record-in-RAM caching needs it. With the timer out of service, the record-in-RAM caching still works, but might be degraded if initial index builds take longer than 90 seconds. We can probably suppress these messages during initial index builds because they are benign in this case.

Not being able to connect to mongod is by design; no "waiting for incoming connections" message has appeared in the log yet, and this is the same behaviour as when a journal restore happens, or a journal file preallocation happens. No connections are allowed until these tasks are complete. (A rollback happens after we start listening, but this is perhaps behavior that ought to occur before listening starts)

Comment by Alvin Richards (Inactive) [ 22/Jan/13 ]

As a side effect as these message are added to the log, you cannot connect through the shell to the mongod, get the following

 
vero:LaCie$ mongo
MongoDB shell version: 2.3.2
connecting to: test
Tue Jan 22 22:56:36.443 javascript execution failed src/mongo/shell/mongo.js:112 couldn't connect to server 127.0.0.1:27017
db = new Mongo().getDB( url );
     ^

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