[JAVA-907] cursor not found on server Created: 31/Jul/13  Updated: 16/Sep/13  Resolved: 16/Sep/13

Status: Closed
Project: Java Driver
Component/s: Connection Management
Affects Version/s: 2.2
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: Rafael Valenzuela Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Mongo version :2.2.3
Num of object is a 47110.
Driver mongodb is a 2.9.3
Pentaho PDI: 4.4.0



 Description   

Jul 31, 2013 10:34:37 AM com.mongodb.DBPortPool gotError
WARNING: emptying DBPortPool to ec2-54-216-117-46.eu-west-1.compute.amazonaws.com/10.208.48.102:27017 b/c of error
java.net.SocketException: Connection timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
at org.bson.io.Bits.readFully(Bits.java:46)
at org.bson.io.Bits.readFully(Bits.java:33)
at org.bson.io.Bits.readFully(Bits.java:28)
at com.mongodb.Response.<init>(Response.java:40)
at com.mongodb.DBPort.go(DBPort.java:124)
at com.mongodb.DBPort.call(DBPort.java:74)
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:283)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:256)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:225)
at com.mongodb.DBApiLayer$Result._advance(DBApiLayer.java:431)
at com.mongodb.DBApiLayer$Result.hasNext(DBApiLayer.java:400)
at com.mongodb.DBCursor._hasNext(DBCursor.java:464)
at com.mongodb.DBCursor.hasNext(DBCursor.java:484)
at org.pentaho.di.trans.steps.mongodbinput.MongoDbInput.processRow(MongoDbInput.java:77)
at org.pentaho.di.trans.step.RunThread.run(RunThread.java:50)
at java.lang.Thread.run(Thread.java:662)
ERROR 31-07 10:34:37,118 - Data - Unexpected error
ERROR 31-07 10:34:37,120 - Data - com.mongodb.MongoException$Network: can't call something : ec2-54-216-117-46.eu-west-1.compute.amazonaws.com/10.208.48.102:27017/ETL
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:292)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:256)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:225)
at com.mongodb.DBApiLayer$Result._advance(DBApiLayer.java:431)
at com.mongodb.DBApiLayer$Result.hasNext(DBApiLayer.java:400)
at com.mongodb.DBCursor._hasNext(DBCursor.java:464)
at com.mongodb.DBCursor.hasNext(DBCursor.java:484)
at org.pentaho.di.trans.steps.mongodbinput.MongoDbInput.processRow(MongoDbInput.java:77)
at org.pentaho.di.trans.step.RunThread.run(RunThread.java:50)
at java.lang.Thread.run(Thread.java:662)
Caused by: java.net.SocketException: Connection timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
at org.bson.io.Bits.readFully(Bits.java:46)
at org.bson.io.Bits.readFully(Bits.java:33)
at org.bson.io.Bits.readFully(Bits.java:28)
at com.mongodb.Response.<init>(Response.java:40)
at com.mongodb.DBPort.go(DBPort.java:124)
at com.mongodb.DBPort.call(DBPort.java:74)
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:283)
... 9 more



 Comments   
Comment by Rafael Valenzuela [ 16/Sep/13 ]

One more time Thanks for your time and Great job !!!

Comment by Jeffrey Yemin [ 16/Sep/13 ]

OK, glad to hear it.

Comment by Rafael Valenzuela [ 16/Sep/13 ]

Hi Jeff
Your solution works,
thanks

Comment by Jeffrey Yemin [ 08/Aug/13 ]

Can you explain what you mean by "create a replicase"? Did you mean "create a replica set"? If so, I don't think that a replica set will help you.

As an experiment, to see if this is just an expected cursor timeout due to slow processing on the client side, can you set the no-timeout flag on the cursor, like:

   cursor.addOption(com.mongodb.Bytes.QUERYOPTION_NOTIMEOUT)

before starting to iterate?

Thanks,
Jeff

Comment by Rafael Valenzuela [ 08/Aug/13 ]

Hi Jeff,
Any news? do you think the problem, is a net latency problem?

Comment by Rafael Valenzuela [ 05/Aug/13 ]

Hi Jeff,
I'm change the driver, my driver version is 2.11.2 http://driver-downloads.mongodb.org/java/index.html
But the same error:
ERROR 05-08 07:49:31,709 - Data - Unexpected error
ERROR 05-08 07:49:31,711 - Data - com.mongodb.MongoException$CursorNotFound: cursor 2831446445178273807 not found on server ec2-54-216-117-46.eu-west-1.compute.amazonaws.com/10.208.48.102:27017
at com.mongodb.DBApiLayer$Result.init(DBApiLayer.java:363)
at com.mongodb.DBApiLayer$Result._advance(DBApiLayer.java:429)
at com.mongodb.DBApiLayer$Result.hasNext(DBApiLayer.java:396)
at com.mongodb.DBCursor._hasNext(DBCursor.java:464)
at com.mongodb.DBCursor.hasNext(DBCursor.java:484)
at org.pentaho.di.trans.steps.mongodbinput.MongoDbInput.processRow(MongoDbInput.java:77)
at org.pentaho.di.trans.step.RunThread.run(RunThread.java:50)
at java.lang.Thread.run(Thread.java:662)
This is my lib folder:
rw-rr- 1 root root 292815 Jun 13 14:56 avro-1.6.2.jar
rw-rr- 1 root root 1643492 Jun 13 14:56 aws-java-sdk-1.0.008.jar
rw-rr- 1 root root 1809743 Jun 13 14:56 cassandra-all-1.0.8.jar
rw-rr- 1 root root 862366 Jun 13 14:56 cassandra-thrift-1.0.8.jar
rw-rr- 1 root root 41123 Jun 13 14:56 commons-cli-1.2.jar
rw-rr- 1 root root 305001 Jun 13 14:56 commons-httpclient-3.1.jar
rw-rr- 1 root root 1114265 Jun 13 14:56 guava-r08.jar
rw-rr- 1 root root 96046 Jun 13 14:56 high-scale-lib-1.1.2.jar
rw-rr- 1 root root 171939 Jun 13 14:56 jackson-core-asl-1.5.2.jar
rw-rr- 1 root root 484439 Jun 13 14:56 jackson-mapper-asl-1.5.2.jar
rw-rr- 1 root root 417141 Jun 13 14:56 jets3t-0.7.4.jar
rw-rr- 1 root root 87325 Jun 13 14:56 jline-0.9.94.jar
rw-rr- 1 root root 16046 Jun 13 14:56 json-simple-1.1.jar
rw-rr- 1 root root 295890 Jun 13 14:56 libthrift-0.6.jar
rw-rr- 1 root root 417896 Jun 19 11:08 mongo-java-driver-2.11.2.jar
rw-rr- 1 root root 291561 Jun 13 14:56 mongo-java-driver-2.7.2.jar.old
rw-rr- 1 root root 110557 Jun 13 14:56 oozie-client-3.1.3-incubating.jar
rw-rr- 1 root root 1221064 Jun 13 14:56 oozie-core-3.1.3-incubating.jar
rw-rr- 1 root root 54094 Jun 13 14:56 pentaho-hadoop-shims-api-TRUNK-SNAPSHOT.jar
rw-rr- 1 root root 14234 Jun 13 14:56 pentaho-s3-vfs-TRUNK-SNAPSHOT.jar
rw-rr- 1 root root 232121 Jun 13 14:56 snakeyaml-1.6.jar
rw-rr- 1 root root 7188 Jun 13 14:56 xmlpull-1.1.3.1.jar
rw-rr- 1 root root 24956 Jun 13 14:56 xpp3_min-1.1.4c.jar
rw-rr- 1 root root 481672 Jun 13 14:56 xstream-1.4.2.jar

Do you think that create a replicase can be fix this problem?

Comment by Rafael Valenzuela [ 02/Aug/13 ]

Hi Jeff,
Thanks for your time,
Yes it's the same ETL, i'll change the mongodb java driver and I'll do a test.

Comment by Jeffrey Yemin [ 02/Aug/13 ]

Hi Rafael,

The report of "cursor 0" is a bug that was fixed in the 2.11.0 release (see JAVA-772). There is an actual cursor id that is not being found on the server, it's just not logged properly.

How does the CursorNotFound exception from the comment related to the SocketException from the original description? These seems to be two different stack traces.

Comment by Rafael Valenzuela [ 31/Jul/13 ]

Hi Jeff,
Of course and so sorry my fault:
ERROR 31-07 14:26:01,702 - Data - com.mongodb.MongoException$CursorNotFound: cursor 0 not found on server ec2-54-216-117-46.eu-west-1.compute.amazonaws.com/10.208.48.102:27017
at com.mongodb.DBApiLayer$Result.init(DBApiLayer.java:373)
at com.mongodb.DBApiLayer$Result._advance(DBApiLayer.java:433)
at com.mongodb.DBApiLayer$Result.hasNext(DBApiLayer.java:400)
at com.mongodb.DBCursor._hasNext(DBCursor.java:464)
at com.mongodb.DBCursor.hasNext(DBCursor.java:484)
at org.pentaho.di.trans.steps.mongodbinput.MongoDbInput.processRow(MongoDbInput.java:77)
at org.pentaho.di.trans.step.RunThread.run(RunThread.java:50)
at java.lang.Thread.run(Thread.java:662)
This error happen in Amazon instance and the local environment.
this is a collections stadisticts
{
"ns" : "tapsmart.locators",
"count" : 4507811,
"size" : 328211160,
"avgObjSize" : 72.80943233866726,
"storageSize" : 428990464,
"numExtents" : 17,
"nindexes" : 2,
"lastExtentSize" : 113979392,
"paddingFactor" : 1,
"systemFlags" : 1,
"userFlags" : 0,
"totalIndexSize" : 264411840,
"indexSizes" :

{ "_id_" : 146268640, "loc_" : 118143200 }

,
"ok" : 1
}
and
"ns" : "ETL.etl2013072220",
"count" : 23334,
"size" : 9572816,
"avgObjSize" : 410.2518213765321,
"storageSize" : 16875520,
"numExtents" : 6,
"nindexes" : 1,
"lastExtentSize" : 8495104,
"paddingFactor" : 1,
"systemFlags" : 1,
"userFlags" : 0,
"totalIndexSize" : 997472,
"indexSizes" :

{ "_id_" : 997472 }

,
"ok" : 1
}

i'm using :
*Pentaho Data Integration :4.0.4 Stable
*Mongo version :2.2.3
*driver mongodb is a 2.9.3
*the query is db.locators.find() and db.etl2013072220.find()
*the socketTimeout is a default (// default - never time out //$NON-NLS-1$);
One more time so sorry for the log was a error

Comment by Jeffrey Yemin [ 31/Jul/13 ]

Hi Rafael,

Can you explain the title of this report? I don't see anything in the stack trace about cursor not found.

We usually see connection time outs like this with improperly indexed queries combined with short socket timeout settings. What have you set socketTimeout to in MongoOptions? What query are you running and what is the query plan for it, as reported by explain?

Generated at Thu Feb 08 08:53:21 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.