[JAVA-383] cursor.count() is positive, but cursor.hasNext() returns false Created: 17/Jun/11  Updated: 25/Jun/13  Resolved: 24/Oct/11

Status: Closed
Project: Java Driver
Component/s: API
Affects Version/s: 2.5.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Joseph Wang Assignee: Antoine Girbal
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Resin app server on linux


Attachments: Text File FinancialIndexTableUpdater.java    

 Description   

From the logs, it seems to indicate that we get count of 8. However, cursor.hasNext() is false.

Bad
===
2011-06-16 23:50:15,156 INFO [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: start update on Jun 16, 2011 23:50:15 last updated Jun 15, 2011 23:48:43
2011-06-16 23:50:15,156 INFO [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: find 8 entries on Jun 16, 2011 23:50:15
2011-06-16 23:50:15,182 ERROR [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: bad query result for mortgage armindex20110616234917
2011-06-16 23:50:15,183 INFO [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: end update on Jun 16, 2011 23:50:15 size=8 table timestamp Jun 15, 2011 23:48:43

Good
====
2011-06-17 00:05:15,156 INFO [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: start update on Jun 17, 2011 00:05:15 last updated Jun 15, 2011 23:48:43
2011-06-17 00:05:15,156 INFO [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: find 8 entries on Jun 17, 2011 00:05:15
2011-06-17 00:05:15,157 DEBUG [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: updates 1MOLIBOR .190
2011-06-17 00:05:15,157 DEBUG [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: updates 2YRUST .410
2011-06-17 00:05:15,157 DEBUG [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: updates 6MOLIBOR .390
2011-06-17 00:05:15,157 DEBUG [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: updates COFI 1.359
2011-06-17 00:05:15,157 DEBUG [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: updates LIBOR .720
2011-06-17 00:05:15,157 DEBUG [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: updates MTA .190
2011-06-17 00:05:15,157 DEBUG [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: updates PRIME 3.250
2011-06-17 00:05:15,157 DEBUG [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: updates UST .180
2011-06-17 00:05:15,157 INFO [Timer-0] com.leadpoint.syndication.db.mongo.mortgage.FinancialIndexTableUpdater - FinancialIndexTableUpdater: end update on Jun 17, 2011 00:05:15 size=8 table timestamp Jun 16, 2011 23:49:17



 Comments   
Comment by Antoine Girbal [ 17/Jun/11 ]

Most likely it is not a java issue, but a race condition due to replication.
Do you still have issue if you do both:

  • the client inserting docs uses safe writes, then notifies
  • the client processing docs doesnt use slaveOk

In terms of solution, either:

  • dont use slaveok
  • add a delay before processing, like 5min. Gracefully handle in case docs still not there (if replication stalled)

thx
AG

Comment by Knut Forkalsrud [ 17/Jun/11 ]

This process runs every 15 minutes, but there is new data only once per day. The error case happens very intermittently, once per month or two.
The setup is that one app (app A) creates a new collection and inserts all 8 documents. It then signals another app (app B) on a different machine that the collection is ready. App B then proceeds to load all documents.

The error must also be very transient. This only happens once within a few minutes of the collection's creation. When the process runs again 15 minutes later all the data is perfectly fine and everything completes normally. There are no updates or anything like that happening to the collection. It says the same after the initial insert.

The query is rather straight forward (in the attached java file). One thing to be aware of is that the "isValid()" check on the FinancialIndex object depends only on the object itself. The constructor is

	public FinancialIndex(BasicDBObject obj) {
		this.indexName = obj.getString(INDEX_NAME_FIELD_NAME);
		this.price = obj.getDouble(PRICE_FIELD_NAME);
 
		if (this.indexName != null && this.indexName.length() > 0 && this.price > 0.0d) {
			this.isValid = true;
		}
	}

They all have a valid name and price, at least as soon as we run the query manually, or the second time it runs.

Since we run with replica set and slave queries are OK it is possible that this could have something to do with replication. If somehow metadata about a collection are available before the data within the collection.

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