I see the following error in my mongodb river setup - Exception while looping in cursor

[dharshanr]

.mongodirector.com}]
[2014-10-24 18:09:20,178][INFO ][river.mongodb ] Server: SG-Test-3788.servers.mongodirector.com - 27017
[2014-10-24 18:09:20,178][INFO ][river.mongodb ] Server: SG-Test-3789.servers.mongodirector.com - 27017
[2014-10-24 18:09:20,178][TRACE][river.mongodb ] mongoOptionsSettings: {secondary_read_preference=false}
[2014-10-24 18:09:20,178][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river account_10
[2014-10-24 18:09:20,182][DEBUG][river.mongodb.util ] setRiverStatus called with account_10 - RUNNING
[2014-10-24 18:09:20,186][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [SG-Test-3788.servers.mongodirector.com], port [27017]
[2014-10-24 18:09:20,186][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [SG-Test-3789.servers.mongodirector.com], port [27017]
[2014-10-24 18:09:20,186][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[2.0.1] - hash[445c35a] - time[2014-07-30T14:08:26Z]
[2014-10-24 18:09:20,186][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [false], drop_collection [false], include_c
ollection [], throttlesize [5000], gridfs [false], filter [null], db [account_10], collection [contacts], script [null], indexing to [account_10]/[contacts]
[2014-10-24 18:09:20,188][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: admin - authenticated: false
[2014-10-24 18:09:20,188][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with admin
[2014-10-24 18:09:20,201][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] authenticateCommand: { "serverUsed" : "SG-Test-3788.servers.mongodirector.com:27017" , "dbname" : "ad
min" , "user" : "admin" , "ok" : 1.0} - isAuthenticated: true
[2014-10-24 18:09:20,201][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Found admin database
[2014-10-24 18:09:20,201][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] About to execute: { "serverStatus" : 1 , "asserts" : 0 , "backgroundFlushing" : 0 , "connections" : 0
, "cursors" : 0 , "dur" : 0 , "extra_info" : 0 , "globalLock" : 0 , "indexCounters" : 0 , "locks" : 0 , "metrics" : 0 , "network" : 0 , "opcounters" : 0 , "opcountersRepl" : 0 , "
recordStats" : 0 , "repl" : 0}
[2014-10-24 18:09:20,202][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Command executed return : { "serverUsed" : "SG-Test-3788.servers.mongodirector.com:27017" , "host" :
"ip-10-11-170-101" , "version" : "2.6.4" , "process" : "mongod" , "pid" : 3656 , "uptime" : 72472.0 , "uptimeMillis" : 72472062 , "uptimeEstimate" : 71528.0 , "localTime" : { "$dat
e" : "2014-10-24T18:09:20.205Z"} , "ok" : 1.0}
[2014-10-24 18:09:20,202][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB version - 2.6.4
[2014-10-24 18:09:20,202][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] serverStatus: { "serverUsed" : "SG-Test-3788.servers.mongodirector.com:27017" , "host" : "ip-10-11-17
0-101" , "version" : "2.6.4" , "process" : "mongod" , "pid" : 3656 , "uptime" : 72472.0 , "uptimeMillis" : 72472062 , "uptimeEstimate" : 71528.0 , "localTime" : { "$date" : "2014-1
0-24T18:09:20.205Z"} , "ok" : 1.0}
[2014-10-24 18:09:20,202][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] process: mongod
[2014-10-24 18:09:20,203][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Not mongos
[2014-10-24 18:09:20,204][INFO ][org.elasticsearch.river.mongodb.Slurper] Authenticate admin with admin
[2014-10-24 18:09:20,217][INFO ][org.elasticsearch.river.mongodb.Slurper] MongoDBRiver is beginning initial import of account_10.contacts
[2014-10-24 18:09:20,219][INFO ][org.elasticsearch.river.mongodb.Slurper] Collection contacts - count: 1
[2014-10-24 18:09:20,219][INFO ][org.elasticsearch.river.mongodb.Slurper] Number documents indexed: 1
[2014-10-24 18:09:20,230][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] setLastTimestamp [account_10] [account_10.contacts] [Timestamp.BSON(ts={ "$ts" : 1414174160 , "$inc"
: 57})]
[2014-10-24 18:09:20,658][WARN ][org.elasticsearch.river.mongodb.Slurper] Exception while looping in cursor
com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool
at com.mongodb.ConcurrentPool.acquirePermit(ConcurrentPool.java:172)
at com.mongodb.ConcurrentPool.get(ConcurrentPool.java:112)
at com.mongodb.PooledConnectionProvider.get(PooledConnectionProvider.java:75)
at com.mongodb.DefaultServer.getConnection(DefaultServer.java:61)
at com.mongodb.BaseCluster$WrappedServer.getConnection(BaseCluster.java:248)
at com.mongodb.DBTCPConnector$MyPort.getConnection(DBTCPConnector.java:503)
at com.mongodb.DBTCPConnector$MyPort.get(DBTCPConnector.java:434)
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:286)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:271)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:237)
at com.mongodb.QueryResultIterator.getMore(QueryResultIterator.java:137)
at com.mongodb.QueryResultIterator.hasNext(QueryResultIterator.java:127)
at com.mongodb.DBCursor._hasNext(DBCursor.java:551)
at com.mongodb.DBCursor.hasNext(DBCursor.java:571)
at org.elasticsearch.river.mongodb.Slurper.run(Slurper.java:125)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1325)
at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:414)
at com.mongodb.ConcurrentPool.acquirePermit(ConcurrentPool.java:166)
... 15 more

[ankon]

At this point the slurper will have stopped, and no longer process incoming data.

Some questions: Does this happen reproducibly? How many rivers are you using?

[linusyong]

I had this problem, resolved by slowing down the slurper:

    "index": {
        "name": "users",
        "type": "user",
        "throttle_size": 10,
        "bulk_size": 3,
        "bulk": {
                "actions": 25,
                "concurrent_requests": 3
        }
    }

[derEremit]

Hi, @linusyong
I'm having a similar problem, but as these "advanced" options have no more explanation than "you can set this option" i really don't know what you did to slow down the slurper?

[EthanLeo-Kafka]

I got a similar problem, it occurred in JUnit Test. So, How to resolve that?

[yitao]

@windrunners
if you use asynchronous code in your junit test,then may be show this exception.
you should let main thread sleep long time to avoid this.
you can try this ,like:
//other thread running code
try {
Thread.sleep(10000000);
} catch (InterruptedException e) {
e.printStackTrace();
}