-
Type:
Bug
-
Resolution: Done
-
Priority:
Critical - P2
-
Affects Version/s: 2.7.3
-
Component/s: API, Cluster Management
-
None
-
Environment:Java 2.6, Mongo Java Driver 2.7.3, Mac OS X 10.7, MongoDB 2.0.4 64-bit
-
None
-
None
-
None
-
None
-
None
-
None
-
None
We're trying to tail the oplog for any changes to a very slow-moving collection. We have observed that to properly establish a tailable cursor it does initially have to return at least one result. However, with these collections that process can take a long time. Possibly days in some cases. In the meantime, we have to retry our query in a loop, creating a new cursor each time. But those empty cursors don't close explicitly by calling close(). We have to wait for them to time out.
The core section of our code is below, largely inspired by the example in the Mongo Java driver itself (https://github.com/mongodb/mongo-java-driver/blob/master/examples/ReadOplog.java) and the Worknik open source tools (https://github.com/wordnik/wordnik-oss/blob/master/modules/mongo-admin-utils/src/main/java/com/wordnik/system/mongodb/OplogTailThread.java).
public void run ( ) { BSONTimestamp ts = initialTs; DBObject criteria = null; while ( !isStopRequested() ) { DBCursor cursor = null; try { criteria = new BasicDBObject("ns", namespace); if ( ts != null ) { criteria.put("ts", new BasicDBObject("$gt", ts)); } while ( !isStopRequested() ) { log.debug("Trying to get tailable cursor for oplog matching {}", criteria); cursor = oplog.find(criteria); cursor.addOption(Bytes.QUERYOPTION_TAILABLE); cursor.addOption(Bytes.QUERYOPTION_AWAITDATA); if ( cursor.hasNext() ) { break; } try { cursor.close(); } catch ( Exception e ) { log.error("Exception trying to close cursor", e);} // <-- this close doesn't work // Until you get a cursor that has something the hasNext() won't block, so we introduce our own sleep Thread.sleep(2000); } while ( !isStopRequested() ) { // Double loop so that we retry when !cursor.hasNext() while ( cursor.hasNext() ) { DBObject op = cursor.next(); ts = (BSONTimestamp)op.get("ts"); log.debug("Found new oplog entry matching {}: {}", criteria, op); try { // Do something interesting with the op l.onNewOperation(op); } catch ( Exception e ) { log.error("Exception handling oplog entry matching {}: {}", criteria, op); } } } } catch ( MongoException.CursorNotFound e ) { // This exception is expected from time to time when the cursor expires log.debug("Cursor expired while tailing oplog", e); } catch ( Exception e ) { log.error("Exception tailing oplog with criteria " + criteria, e); } try { cursor.close(); } catch ( Exception e ) { log.error("Exception trying to close cursor", e);} } }
Looking into DBCursor.close() it looks like it's testing the type of the internal rep and returning fast if it's not a Result. If I look at db.runCommand(
{cursorInfo:1}) while our code is executing I see total cursors growing with each time through the first loop. Of course they eventually timeout, but we can build up a lot of cursors in the 10 minutes that takes.
I'm guessing, though haven't verified, that when that initial query returns no results _it isn't a Result and so close() does nothing. But elsewhere the logic to close exhausted cursors is noticing that this cursor is tailable and so not closing it even though hasNext() returns false.
public void close() { if ( _it instanceof Result ) ((Result)_it).close(); }