|
Aaron, sorry it's taken me a while to get back to this. I have found two
workarounds in Groovy as described previously and have not seen any issues.
The first workaround of checking for every match instead of a single match
for the key might be slower than needs to be but seems to work as does
explicitly defining all script variables which is the proper thing.
Variables not defined are in a Binding that can be altered outside the
scope they were originally used, so in a multithreaded script, all bets are
off.
My best guess is that my issues were due to the key variable leaking out of
the scope I thought it was in, but I have not had a chance to test it.
Also, I think this is only an issue with Groovy code run in a script
environment so the issue should vanish if run as compiled classes.
Please close the issue and thank you for your help and patience.
Steve
|
|
Hi Steven,
Let me know if there's more to discuss here. Otherwise I'll plan to close out the ticket.
|
|
Ok, have you tried to fix the test and is there still an issue?
|
|
Aaron,
I have not confirmed this, but I think the method variables in the
closure of the for loop (line 74) are not thread-safe unless declared with
"def" or the type. Groovy does not have "final" like would be needed for
anonymous classes om Java, but it is conceivable that without the def
variables outside the closure do not have the semantics a final variable
would. Changing line 72 to include def would be the change.
This does not explain why there error is not seen when both boolean
parameters to update are true. This just may be a timing issue.
Steve
|
|
Hi Steven,
Ok can you run that debugging and send the output? It's pretty clear that mongod is getting the wrong "i" values. (Both the sniffer and mongod logging are reporting incorrect i's.) So I'd suggest adding some debugging to your script to figure out how this is happening.
|
|
The value of i is not changed after it is set within a single iteration of
the loop. The error goes away if the delay is increased. That seems to
indicate either an issue in the driver or the server or possibly in the
implementation of Groovy. Perhaps adding something like:
def temp = i
...
if (i != temp)
{ exit(1) }
or follow the line:
rec = [i:i, key: (String)"$chr"] as BasicDBObject
with:
query = [i:i]
and make the corresponding change to the update statement:
result = it.update(query, setrec , true)
might be convincing.
There is also a static trace method in DBApiLayer that looks like it can be
used to output the request sent to the driver but before the driver
actually sends the request.
|
|
Hi Steven,
As I mentioned it seems like a client side issue. Maybe you can add some debugging to your script to verify what the client is sending, and the values of your 'i' variables?
|
|
Yes, that is the expected error. If you increase the sleep time the error
goes away. Ideas?
|
|
Hi Steve,
I ran the test with your modified upsert function. I am seeing the same behavior, where the client sends an unexpected upsert request:
Data:
> db.belmont.find( {key:'a' })
|
{ "_id" : ObjectId("5009acb73a3c2e71463af2a0"), "i" : 113, "key" : "a" }
|
{ "_id" : ObjectId("5009acb73a3c2e71463af2c0"), "i" : 130, "key" : "a" }
|
{ "_id" : ObjectId("5009acb73a3c2e71463af337"), "i" : 190, "key" : "a" }
|
{ "_id" : ObjectId("5009acb73a3c2e71463af3fe"), "i" : 289, "key" : "a" }
|
{ "_id" : ObjectId("5009acb73a3c2e71463af426"), "i" : 306, "key" : "a" }
|
{ "_id" : ObjectId("5009acb83a3c2e71463af4e0"), "i" : 400, "key" : "a" }
|
{ "_id" : ObjectId("5009acb83a3c2e71463af5eb"), "i" : 514, "key" : "a" }
|
{ "_id" : ObjectId("5009acb83a3c2e71463af60a"), "i" : 530, "key" : "a" }
|
Mongosniff log:
127.0.0.1:52419 -->> 127.0.0.1:27017 mass.belmont 83 bytes id:1d2 466
|
update flags:1 q:{ i: 119 } o:{ $set: { i: 113, key: "a" } }
|
Mongod debug log:
Fri Jul 20 12:08:39 [conn1] update mass.belmont query: { i: 119 } update: { $set: { i: 113, key: "a" } } fastmodinsert:1 0ms
|
|
|
Aaron,
Have you had a chance to look at this again. As you can see from lines 72
and 74, the value of i does not change inside the loop. Also as pointed
out, even if wire traffic (using netshark or a similar tool) shows the
correct number of each update being sent (observing from the client side, I
believe), an incorrect number of records are inserted.
Were you able to run the second version of the script. I suspect the
results for mongosniff would be more akin to: db.arlington.update(
{
i:1992 }
,
{ i:1994, key:'b' }
, ... );
where 1992 is the expected value of i and 'a' is the expected key for the
record.
I'll try to get more help on the details of the java driver to see if
there is something there I should be looking for.
Steve
|
|
Also, I too hastily copied the java code to groovy. The upsert definition
should be:
def upsert(CountDownLatch latch, colls, charFn) {
def rv = []
DOC_COUNT = 2000
colls.each { coll ->
rv.add({
for (int i = 0; i < DOC_COUNT; i++) {
coll
{
def chr = charFn(it.name);
rec = [i:i, key: (String)"$chr"] as BasicDBObject
def setrec = [$set: rec] as BasicDBObject
it.DB.requestStart()
result = it.update([i:i] as BasicDBObject, setrec ,
true, false);
//result = it.insert(rec);
if (result.error != null) println result
it.DB.requestDone();
sleep(00) }
}
// println("total # of documents after inserting " + DOC_COUNT + "
docs (should be " + (DOC_COUNT) + ") " + coll.getCount());
latch.countDown();
});
}
return rv;
}
requestStart and requestDone made no difference
The key should now be 'a' or 'b' for arlington and belmont, respectively
|
|
I was running mongod, the client, and mongosniff on the same machine and pointed mongosniff at the loopback network interface.
|
|
The query and update object should have the same value for i (lines 72 and
74). Are you running mongosniff on the client, server or both?
|
|
Hi Steven,
I ran the script and saw counts != 2000. Running mongosniff it looks like your test script is sending many update operations like the following:
update flags:1 q:
{ i: 1992 }
o:
{ i: 1994, key: "c" }
This is equivalent to
db.arlington.update(
{ i:1992 }
,
{ i:1994, key:'c' }
, ... );
Do you expect your test script to generate update operations that look like this, where the 'i' value in the query part of the update does not match the 'i' value in the update document?
You can run mongosniff yourself as follows:
mongosniff --source NET <interface>
<interface> might be something like eth0, it should be the interface your mongod machine or client machine is sending data on. You may need to use sudo to run mongosniff.
|
|
Aaron,
Were you able to run the groovy script? Let me know if you need any help.
Steve
|
|
Aaron,
I think I've narrowed down the culprit somewhat by testing the groovy
code with some different variations.
1) I checked the wire traffic – equal number of arlington/belmont so
problem may not be on driver side. The actual commands look correct, but
I suppose there are connection keys that could be corrupt
2) If the update is replaced with insert, the number of records is
consistently correct, but the documents themselves sometimes end up in the
wrong place
3) If inserting, the first record in one of the tables is consistently
incorrect [2.0.5]. I just updated to 2.0.6 and this is no longer
consistent in this way, but there are still errors.
4) if inserting, the misinserted items have the same $oid as the
corresponding item in the proper table (same timestamp, machine, inc)
5) db.requestStart/Done does not seem to make a difference
6) Fails frequently [1 in 1000]: result = myCollection.update([i:i] as
BasicDBObject, rec , true, false);
Fails infrequently [1 in 10000]: result = myCollection.update([i:i] as
BasicDBObject, setrec , true, true);
i.e. Checking for multiple matches makes a significant difference even
though there should be only one match. I have not tested whether declaring
i to be unique makes a difference.
The table jumping alone does not seem like it would account for all the
errors I see, namely the data corruption. I just saw in the docs that
upserts may lead to field re-ordering. This is the type of operation I
would expect might cause what look to be frame-shift errors. Block
re-ordering is another type of operation I would suspect.
I have not dug to deeply into the c++ yet, but I think client.cpp is front
end for networked requests. Yes? Do you know how the requests are queued
and processed?
Steve
|
|
Aaron,
I added the line: Logger.getLogger( "com.mongodb.TRACE"
).setLevel(Level.FINEST);
to the start of the script, set the delay to 0, and counted the instances
of each table name in the output. There were 2000 messages for each of the
tables so I don't think the problem is on the driver side, at least up to
the "_connector.say" call. Each of the tables, however was just short of
2000 records.
|
|
Aaron,
I haven't had time to reproduce the logs, but I have a barebones test
that I think reproduces the error.
There is a sleep statement on line 74 for 15ms.With that delay I see errors
in the count of records inserted into the two collections. Increasing over
50ms and the count is as expected.
Line 93 has additional collections from a different database. You can
uncomment this line and fix the parens and see that records intended for
one database actually end up in the other (key string case differs between
dbs).
Line 73 has an alternative to the simple update with a $set command. Using
this alternative also exhibits the same behavior.
The names of collections are the same across databases, but I have changed
those to be different and still see errors.
Hope this helps.
|
|
Hi Steven. Can you attach the log you are referring to?
|
|
Hi Aaron,
I just started mongo with objcheck and started simultaneous loads on the
collections on a fresh store. I do not see anything reported as errors,
but I do see lines showing fastmodinserts being made with the wrong data
Things to note:
1) The "swaps" seen in logs are from collections with similar table names.
I.e. Collection1.foo and Collection2.foo where "foo" is the actual name of
the table. This may just be coincidence since I only use a handful of
distinct table names
2) Not all "swaps" are logged
3) The only logged inserts are swaps
|
|
Hi Steven,
Another thing to try is to run mongod with the --objcheck option while you are inserting to a fresh database. This performs validation on insert and will help us determine if you're running into a client side issue.
|
|
From a single web server, yes, all instances share the same
com.mongodb.Mongo connection.
One use, however, is to have multiple webservers handle different batches
of commands. Those web servers will all connect to the same mongodb server
instance
|
|
Hi Steven,
I think Bryan was specifically asking whether all queries are made through a single instance of com.mongodb.Mongo. Could you let us know?
|
|
Bryan,
Yes, all requests are through a single connection instance - for the most
part. On a single machine all db calls share the same instance, but on
different machines the connections, of course, are not shared. I would not
expect the number of client connections to the server to be the issue.
|
|
Hi Steven,
In your use of the Java driver, are you making all queries through a single instance of com.mongodb.Mongo? The Mongo object is thread safe and maintains a connection pool to the database, so you only need to have one instance of the class to handle all your requests. Here a link for a bit more info:
http://www.mongodb.org/display/DOCS/Java+Driver+Concurrency
|
|
Can you give a scenario where interleaving might happen? I don't think
that is possible with my setup as each batch is in its own thread, but I
can also look closer at how web connections are (re)used.
|
|
Hi Steven,
Each of those test scripts runs in a single threaded shell. The tests are run simultaneously from different shells to generate simultaneous writes to different databases.
What I mean by interleaving is a situation where two writers are sending messages on a connection and the connection does not get a list of messages in sequence but instead some bytes of one message, some bytes of another message, some more bytes of the first message, etc. So the messages get mixed up with each other.
|
|
Hi Aaron,
I am little confused by the code. The while loops are run in separate
threads? Can you describe what you mean by interleaving?
I am inserting into multiple collections in a single request but within
the same database while concurrently doing the same in another
database/collection set. With serial insertions into 2 databases with 3
collections each for 250k docs per collection and each doc contains a 4k
field. I see no troubles with just java. I have not had time to try the
gmongo wrapper, but it looks like it just delegates to the java driver. I
have not looked closely and the monkey patching, though.
So far I have only tried inserts and no upserts which may modify an
existing doc which does occur in my actual data. I'll also try loading one
collection with actual data. My real data may be in any language
(Japanese, Korean, Russian, etc) and my have been converted from MS Word
documents, so perhaps it is in the documents.
|
|
Hi Steven,
I also read and validated the contents of the documents. Here are the two test scripts I ran (they require the development version of the mongo shell, but I ran them against the 2.0.4 version of mongod).
c = db.getSisterDB( "foo" ).c;
|
c.drop();
|
|
docs = [];
|
for( i = 0; i < 1000; ++i ) {
|
docs.push( { a:0 } );
|
}
|
|
while( 1 ) {
|
c.insert( docs );
|
}
|
c = db.getSisterDB( "bar" ).c;
|
c.drop();
|
|
docs = [];
|
for( i = 0; i < 1000; ++i ) {
|
docs.push( { a:1 } );
|
}
|
|
while( 1 ) {
|
c.insert( docs );
|
}
|
If you have two threads sharing a connection it's important to make sure that the messages sent by these threads aren't being interleaved. Interleaving could definitely cause invalid documents and the appearance of documents in incorrect namespaces.
|
|
With the errors I see, db.repair does not report errors. For example, of
the handful of databases with errors, only one reports BSONElement type
errors in the log and only its collections report validation errors.
Repair on that collection worked, but removed about 20% of the records in
one collection. The majority of the incorrect records are still present
For each collection, validation reports deleted records but delete is never
called. Is this normal?
More details to see if we can find the difference:
java driver: 2.7.3
gmongo: 0.9.5
groovy: 1.8.4
All threads share the same connection. Can you share your test code or add
it to the tests on git. I can not readily make a simple copy of my code or
data. I will also start with the QuickTour.java code (
https://github.com/mongodb/mongo-java-driver/blob/master/examples/QuickTour.java)
to build tests that emulate my use. I think that might be easier than
dissecting the code I already know fails.
I have looked back at the google group and there are issues with data
corrruption going back to pre 1.8.6 and as recently as 2.0.x but I could
not find any resolutions.
|
|
Hi Steven,
Last night the jira system we use had an outage, and it looks like the comment you added to this ticket may have been lost. Could you please re post your message? Thanks.
|
|
Hi Steven,
Yep, I was inserting concurrently to the same mongod from two different clients. I inserted about 10 million documents and then did a repair with no errors.
|
|
I'll see if I can reproduce it with a setup simpler than the one I
currently have – groovy/GMongo called through a web interface. I am also
seeing the same issue in 2.0.6. Are you inserting concurrently?
Previously, I had stated that the changes seemed to happen even if only
one database was receiving inserts, but with 2.0.6 I have only seen errors
when multiple databases were in use at roughly the same time. The writes
are independent so I can not tell if they are truly concurrent. Roughly,
with two threads making periodic inserts of about 200 records each, I see
errors at a rate of about 1 in 1000 after 100k inserts
Regarding valgrind, I intended to mention earlier that I think chasing down
the BSON error itself may not be that fruitful. My guess is somewhere there
is pointer that is not pointing to the proper buffer and the first visible
manifestation is the assertion error on the string memory.
|
|
Hi Steven,
I did a quick search for the valgrind assertion you encountered and didn't find any references to it. So I'm not sure whether the issue has been resolved in the current 3.7.0 valgrind release.
The validate command does not do a full validation, and the nonzero deletedCount you reported is normal. (The unused space in your collection is being reported as "deleted".)
I also did a test with mongo 2.0.4 where I did batch inserts to two collections in separate databases and did not experience any of the problems you have described.
I think it would make sense to get some client code that demonstrates this issue, to attempt to rule out a client / driver side issue.
|
|
Aaron,
What version of valgrind do you recommend. I am running CentOS 6.2 with
the latest packaged version, 3.6.0 and trying to avoid installing
non-packaged apps. Also, the error is not that the BSON string size is
incorrect. This is just a symptom of the larger problem that is occurring
elsewhere and the type you might see if there were an incorrect block move,
reuse of an uncleared buffer, incorrect pointer offset, etc
After the crash I ran repairDatabase. Attached is a snippet from mongod
log. Elided sections before and after are "recursive lock" messages for
the collections. Is there any way other than databaseRepair to verify the
integrity of the mongo data files?
I have run db.foo.validate(
{full:true}
) on the databases and no errors are
reported (
{..., valid:true, errors:[], ok:1}
). Perhaps it is part of
normal operation, but validate does show non-zero deletedCount, but I do
not delete any documents. Databases without any inserts have a
deletedCount = 1 and deletedSize= 8016, for example.
Currently I am batch inserting docs into collection A and started a
concurrent batch insert into collection B in a different database. A
handful of docs that should be in collection A are now in collection B. In
both collections the inserts are done periodically, i.e. a couple hundred
inserts pause, more inserts, etc.
...
Mon Jun 4 17:25:26 [conn5] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: meetup.venues top: { opid: 2061, active: true, lockType: "write", waitingForLock: false, secs_running: 12, op: "query", ns: "meetup", query:
{ repairDatabase: 1.0 }
, client: "127.0.0.1:38735", desc: "conn", threadId: "0x7f4ab09f5700", connectionId: 5, msg: "index: (3/3) btree-middle", numYields: 0 }
Mon Jun 4 17:25:26 [conn5] Assertion: 10334:Invalid BSONObj size: 0 (0x00000000) first element: EOO
0x5846c2 0x5080e3 0x86ebcf 0x86ed78 0x947c5a 0x8860c4 0x88edca 0x88fcd1 0x5e31db 0x5e36fd 0x850c8c 0x852995 0x8542e9 0x8bd43d 0x9810f2 0x97cdce 0x97e03d 0x941525 0x9433fe 0x889767
/usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x112) [0x5846c2]
/usr/bin/mongod(_ZNK5mongo7BSONObj14_assertInvalidEv+0x473) [0x5080e3]
/usr/bin/mongod(_ZN5mongo19CoveredIndexMatcher7matchesERKNS_7BSONObjERKNS_7DiskLocEPNS_12MatchDetailsEb+0x15f) [0x86ebcf]
/usr/bin/mongod(_ZN5mongo19CoveredIndexMatcher14matchesCurrentEPNS_6CursorEPNS_12MatchDetailsE+0xa8) [0x86ed78]
/usr/bin/mongod(_ZN5mongo14processGetMoreEPKcixRNS_5CurOpEiRb+0x3da) [0x947c5a]
/usr/bin/mongod(_ZN5mongo15receivedGetMoreERNS_10DbResponseERNS_7MessageERNS_5CurOpE+0x1b4) [0x8860c4]
/usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0xf5a) [0x88edca]
/usr/bin/mongod(_ZN5mongo14DBDirectClient4callERNS_7MessageES2_bPSs+0x81) [0x88fcd1]
/usr/bin/mongod(_ZN5mongo14DBClientCursor11requestMoreEv+0x35b) [0x5e31db]
/usr/bin/mongod(_ZN5mongo14DBClientCursor4moreEv+0x4d) [0x5e36fd]
/usr/bin/mongod(_ZN5mongo6Cloner4copyEPKcS2_bbbbbbNS_5QueryE+0x7cc) [0x850c8c]
/usr/bin/mongod(_ZN5mongo6Cloner2goEPKcRSsRKSsbbbbbbPi+0x1665) [0x852995]
/usr/bin/mongod(_ZN5mongo9cloneFromEPKcRSsRKSsbbbbbbPi+0x59) [0x8542e9]
/usr/bin/mongod(_ZN5mongo14repairDatabaseESsRSsbb+0x4cd) [0x8bd43d]
/usr/bin/mongod(_ZN5mongo17CmdRepairDatabase3runERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x282) [0x9810f2]
/usr/bin/mongod(_ZN5mongo11execCommandEPNS_7CommandERNS_6ClientEiPKcRNS_7BSONObjERNS_14BSONObjBuilderEb+0xb5e) [0x97cdce]
/usr/bin/mongod(_ZN5mongo12_runCommandsEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi+0x6fd) [0x97e03d]
/usr/bin/mongod(_ZN5mongo11runCommandsEPKcRNS_7BSONObjERNS_5CurOpERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi+0x35) [0x941525]
/usr/bin/mongod(ZN5mongo8runQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1+0x172e) [0x9433fe]
/usr/bin/mongod() [0x889767]
Mon Jun 4 17:25:26 [conn5] getmore meetup.venues cursorid:6577276361443070346 exception: Invalid BSONObj size: 0 (0x00000000) first element: EOO code:10334 reslen:20 36ms
Mon Jun 4 17:25:26 [conn5] build index meetup.venues
{ _id: 1 }
Mon Jun 4 17:25:27 [conn5] build index done 199999 records 0.749 secs
Mon Jun 4 17:25:27 [conn5] build index meetup.growth
{ _id: 1 }
Mon Jun 4 17:25:27 [conn5] build index done 1 records 0 secs
Mon Jun 4 17:25:27 [conn5] warning: ClientCursor::yield can't unlock b/c of recursive lock ns: meetup.events top: { opid: 2061, active: true, lockType: "write", waitingForLock: false, secs_running: 13, op: "query", ns: "meetup", query:
{ repairDatabase: 1.0 }
, client: "127.0.0.1:38735", desc: "conn", threadId: "0x7f4ab09f5700", connectionId: 5, msg: "index: (3/3) btree-middle", numYields: 0 }
...
|
|
Hi Steven,
The most recent stack trace you reported can result from corrupt data files. We can help diagnose the issue if you provide code to reproduce it or you upgrade valgrind and report the output of the upgraded version.
|
|
After applying repairDatabase to each database I was able to resume using
mongo instance. I am, however, seeing instances of mis-inserts.
private def _database(dbname, mongo=null) {
def defer =
{
def host = mongo ?: 'localhost'
def opts = new MongoOptions()
opts.connectionsPerHost = 5
opts.threadsAllowedToBlockForConnectionMultiplier = 10
opts.autoConnectRetry = true
new GMongo(new ServerAddress(host), opts)
}
// server instance is either the shared instantiated instance in the
application context
// with name "MONGO" or a new instance created with the defer closure
// that is saved in the app context with the name "MONGO"
server = getBindingDeferred("MONGO", defer) //
server.getDB(dbname)
}
for each database a map of the collection accessors is created. Something
like this:
def database1() {
db = _database("database1")
[ "collection_1": db.getCollection("collection_1"),
"collection_2": db.getCollection("collection_2"),
...
]
}
and so on for each database. The desired collection object is then used to
get or put documents.
Note: Instead of instantiating each collection object, the maps could by
dynamic, e.g.
["collection_1":
{ c -> c.call(db.getCollection("collection_1"))}
, ...]
and instead of database1().collection_1, database1().collection_1(c) where
c is a closure taking the actual collection object. This should preclude
any chance of a shared collection object being misused, but I do not think
it is related to documents in the wrong database.
|
|
Forgot to answer that – no geolocation queries
|
|
Hi Steven,
I think verbose logging will log the update after it finishes, so if you get a crash before the update finishes it won't be logged. What I'm particularly interested in is whether the query/match part of your update uses your geoLocation field, or another geo field. Do you know if your application is capable of doing this?
Also, could you send the log from the second crash? Thanks.
|
|
Aaron,
The update is to one of four collections, but I do not have application
logging on the upserts. Is there a way to increase verbosity in mongod
logging to show the collection names and key? Although all incoming
records should have a key, it is possible the key might be missing so the
upsert comparison would be on a null. Might this cause this problem?
|
|
Hi Steven - is it possible the query part of the update operation that caused this crash was a geo query of some kind? Is there a way you can tell what the update operation was (perhaps through app server logging)?
|
|
Hi Steven - Could you send the log for the second crash as well? Thanks
|
|
Erik,
I gave up on 1.8.x and have now started using 2.0.5. I have not seen the
errors I observed before, but I did get my first server crash while
inserting. Attached is the tail of the log. Connections are from
JMongoBrowser (10.0.0.73) and from a servlet (10.0.0.107) that is the front
end to a number of groovy scripts.
Sidenote: As I was writing this I noticed mongod crashed again. A curious
coincidence is that the connection number for the error here is 2^6 + 1 and
the connection number for the current crash is 2^7 + 1. Are connections
allocated in batches of size divisible by some power of 2?
Sun Jun 3 00:23:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 00:28:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 00:33:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 00:38:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 00:43:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 00:48:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 00:53:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 00:58:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 01:03:54 [clientcursormon] mem (MB) res:187 virt:3527 mapped:1424
Sun Jun 3 01:07:43 [initandlisten] connection accepted from 10.0.0.107:36050 #25
Sun Jun 3 01:08:11 [initandlisten] connection accepted from 10.0.0.73:3270 #26
Sun Jun 3 01:08:52 [conn25] update meetup.venues query:
{ muid: 2689611 }
update: { $set: { muid: 2689611, name: "Clapham Common", geoLocation: [ 51.457584, -0.145065 ], address_1: "SW4 9DE", city: "London", country: "gb", email: "", tags: {} } } fastmodinsert:1 109ms
Sun Jun 3 01:08:54 [clientcursormon] mem (MB) res:190 virt:3529 mapped:1424
Sun Jun 3 01:10:32 [initandlisten] connection accepted from 10.0.0.107:36065 #27
Sun Jun 3 01:13:54 [clientcursormon] mem (MB) res:190 virt:3530 mapped:1424
Sun Jun 3 01:15:16 [initandlisten] connection accepted from 10.0.0.107:36082 #28
Sun Jun 3 01:18:54 [clientcursormon] mem (MB) res:193 virt:3531 mapped:1424
Sun Jun 3 01:20:42 [initandlisten] connection accepted from 10.0.0.107:36094 #29
Sun Jun 3 01:23:54 [clientcursormon] mem (MB) res:192 virt:3532 mapped:1424
Sun Jun 3 01:25:52 [conn17] command admin.$cmd command:
{ listDatabases: 1 }
ntoreturn:1 reslen:449 142ms
Sun Jun 3 01:25:52 [conn29] update meetup.venues query:
{ muid: 986287 }
update: { $set: { muid: 986287, name: "Dock B, Belmont Harbor North", zip: "60613", geoLocation: [ 41.95193, -87.644076 ], state: "IL", address_1: "3256 North Recreation Drive", city: "Chicago", country: "us", email: "", tags: {} } } 144ms
Sun Jun 3 01:28:54 [clientcursormon] mem (MB) res:199 virt:3532 mapped:1424
Sun Jun 3 01:33:54 [clientcursormon] mem (MB) res:205 virt:3532 mapped:1424
Sun Jun 3 01:38:52 [conn29] update meetup.venues query:
{ muid: 949106 }
update: { $set: { muid: 949106, name: "Town Tavern", zip: "20009", geoLocation: [ 38.920329, -77.041555 ], state: "DC", address_1: "2323 18th St. NW", city: "Washington", country: "us", email: "", phone: "202.387.8696", tags: {} } } 409ms
Sun Jun 3 01:38:54 [clientcursormon] mem (MB) res:213 virt:3532 mapped:1424
Sun Jun 3 01:43:52 [conn29] update meetup.venues query:
{ muid: 686784 }
update: { $set: { muid: 686784, name: "The Magic Castle", zip: "90028", geoLocation: [ 34.10456, -118.341816 ], state: "CA", address_1: "7001 Franklin Ave", city: "Hollywood", country: "us", email: "", phone: "323-851-3313", tags: {} } } 170ms
Sun Jun 3 01:43:54 [clientcursormon] mem (MB) res:221 virt:3532 mapped:1424
Sun Jun 3 01:48:54 [clientcursormon] mem (MB) res:228 virt:3532 mapped:1424
Sun Jun 3 01:53:54 [clientcursormon] mem (MB) res:233 virt:3532 mapped:1424
Sun Jun 3 01:58:54 [clientcursormon] mem (MB) res:241 virt:3532 mapped:1424
Sun Jun 3 02:03:54 [clientcursormon] mem (MB) res:248 virt:3532 mapped:1424
Sun Jun 3 02:08:54 [clientcursormon] mem (MB) res:255 virt:3532 mapped:1424
Sun Jun 3 02:13:54 [clientcursormon] mem (MB) res:259 virt:3532 mapped:1424
Sun Jun 3 02:15:18 [initandlisten] connection accepted from 10.0.0.107:36253 #30
Sun Jun 3 02:18:54 [clientcursormon] mem (MB) res:268 virt:3533 mapped:1424
Sun Jun 3 02:23:54 [clientcursormon] mem (MB) res:277 virt:3533 mapped:1424
Sun Jun 3 02:28:54 [clientcursormon] mem (MB) res:281 virt:3533 mapped:1424
Sun Jun 3 02:33:54 [clientcursormon] mem (MB) res:289 virt:3533 mapped:1424
Sun Jun 3 02:38:54 [clientcursormon] mem (MB) res:298 virt:3533 mapped:1424
Sun Jun 3 02:43:54 [clientcursormon] mem (MB) res:300 virt:3533 mapped:1424
Sun Jun 3 02:48:54 [clientcursormon] mem (MB) res:301 virt:3533 mapped:1424
Sun Jun 3 02:53:54 [clientcursormon] mem (MB) res:300 virt:3533 mapped:1424
Sun Jun 3 02:58:54 [clientcursormon] mem (MB) res:301 virt:3533 mapped:1424
Sun Jun 3 03:01:17 [conn29] update meetup.venues query:
{ muid: 882419 }
update: { $set: { muid: 882419, name: "Winter Park Amtrak Station", zip: "32789", geoLocation: [ 28.597743, -81.350183 ], state: "FL", address_1: "150 E Morse Blvd.", city: "Winter Park", country: "us", email: "", tags: {} } } 132ms
Sun Jun 3 03:03:54 [clientcursormon] mem (MB) res:309 virt:3533 mapped:1424
Sun Jun 3 03:08:54 [clientcursormon] mem (MB) res:318 virt:3533 mapped:1424
Sun Jun 3 03:12:52 [conn29] update meetup.venues query:
{ muid: 768739 }
update: { $set: { muid: 768739, name: "West Steps, State Capitol", zip: "95814", geoLocation: [ 38.574906, -121.486617 ], state: "CA", address_1: "Capitol Ave", city: "Sacramento", country: "us", email: "", tags: {} } } 444ms
Sun Jun 3 03:13:54 [clientcursormon] mem (MB) res:323 virt:3533 mapped:1424
Sun Jun 3 03:15:16 [initandlisten] connection accepted from 10.0.0.107:36448 #31
Sun Jun 3 03:18:52 [conn29] update meetup.venues query:
{ muid: 7450672 }
update: { $set: { muid: 7450672, name: "DB Bistro Moderne", zip: "33131", geoLocation: [ 25.770935, -80.189453 ], state: "FL", address_1: "255 Biscayne Blvd Way (at the JW Marriott Marquis)", city: "Miami", country: "us", email: "", tags: {} } } 160ms
Sun Jun 3 03:18:52 [conn29] update meetup.groups query:
{ muid: "288434" }
update: { $set: { muid: "288434", geoLocation: [ 25.75, -80.2699966431 ], topics: {}, urlname: "Miami-Wine-Tasters", name: "Miami Wine Tasters" } } moved:1 252ms
Sun Jun 3 03:18:55 [clientcursormon] mem (MB) res:330 virt:3534 mapped:1424
Sun Jun 3 03:23:55 [clientcursormon] mem (MB) res:337 virt:3534 mapped:1424
Sun Jun 3 03:27:51 [conn29] update meetup.groups query:
{ muid: "1670903" }
update: { $set: { muid: "1670903", geoLocation: [ 53.5099983215, -113.629997253 ], topics: {}, urlname: "Calgary-Vavasaur-and-Womanition", name: "Calgary - Vavasaur and Womanition" } } 116ms
Sun Jun 3 03:28:55 [clientcursormon] mem (MB) res:341 virt:3534 mapped:1424
Sun Jun 3 03:33:55 [clientcursormon] mem (MB) res:345 virt:3534 mapped:1424
Sun Jun 3 03:38:55 [clientcursormon] mem (MB) res:351 virt:3534 mapped:1424
Sun Jun 3 03:42:15 [conn29] update meetup.venues query:
{ muid: 7147862 }
update: { $set: { muid: 7147862, name: "Le Commensal", geoLocation: [ 45.515549, -73.564651 ], state: "QC", address_1: "1720 St-Denis", city: "Montr�al", country: "ca", email: "", tags: {} } } 165ms
Sun Jun 3 03:43:55 [clientcursormon] mem (MB) res:355 virt:3534 mapped:1424
Sun Jun 3 03:48:55 [clientcursormon] mem (MB) res:362 virt:3534 mapped:1424
Sun Jun 3 03:53:55 [clientcursormon] mem (MB) res:362 virt:3534 mapped:1424
Sun Jun 3 03:58:55 [clientcursormon] mem (MB) res:364 virt:3534 mapped:1424
Sun Jun 3 04:03:55 [clientcursormon] mem (MB) res:364 virt:3534 mapped:1424
Sun Jun 3 04:08:55 [clientcursormon] mem (MB) res:364 virt:3534 mapped:1424
Sun Jun 3 04:12:20 [initandlisten] connection accepted from 10.0.0.107:36644 #32
Sun Jun 3 04:13:55 [clientcursormon] mem (MB) res:362 virt:3535 mapped:1424
Sun Jun 3 04:15:28 [initandlisten] connection accepted from 10.0.0.107:36657 #33
Sun Jun 3 04:18:55 [clientcursormon] mem (MB) res:364 virt:3536 mapped:1424
Sun Jun 3 04:23:55 [clientcursormon] mem (MB) res:364 virt:3536 mapped:1424
Sun Jun 3 04:25:52 [conn32] update meetup.groups query:
{ muid: "2997162" }
update: { $set: { muid: "2997162", geoLocation: [ 41.5, -81.66999816889999 ], topics: {}, urlname: "UrbanCode", name: "UrbanCoders" } } moved:1 371ms
Sun Jun 3 04:28:55 [clientcursormon] mem (MB) res:369 virt:3536 mapped:1424
Sun Jun 3 04:33:55 [clientcursormon] mem (MB) res:373 virt:3536 mapped:1424
Sun Jun 3 04:38:55 [clientcursormon] mem (MB) res:373 virt:3536 mapped:1424
Sun Jun 3 04:43:55 [clientcursormon] mem (MB) res:373 virt:3536 mapped:1424
Sun Jun 3 04:48:55 [clientcursormon] mem (MB) res:373 virt:3536 mapped:1424
Sun Jun 3 04:53:55 [clientcursormon] mem (MB) res:373 virt:3536 mapped:1424
Sun Jun 3 04:58:55 [clientcursormon] mem (MB) res:374 virt:3536 mapped:1424
Sun Jun 3 05:03:55 [clientcursormon] mem (MB) res:375 virt:3536 mapped:1424
Sun Jun 3 05:08:55 [clientcursormon] mem (MB) res:379 virt:3536 mapped:1424
Sun Jun 3 05:13:55 [clientcursormon] mem (MB) res:380 virt:3536 mapped:1424
Sun Jun 3 05:15:18 [initandlisten] connection accepted from 10.0.0.107:36834 #34
Sun Jun 3 05:18:55 [clientcursormon] mem (MB) res:378 virt:3537 mapped:1424
Sun Jun 3 05:23:55 [clientcursormon] mem (MB) res:383 virt:3537 mapped:1424
Sun Jun 3 05:28:55 [clientcursormon] mem (MB) res:379 virt:3537 mapped:1424
Sun Jun 3 05:33:55 [clientcursormon] mem (MB) res:381 virt:3537 mapped:1424
Sun Jun 3 05:38:55 [clientcursormon] mem (MB) res:383 virt:3537 mapped:1424
Sun Jun 3 05:43:55 [clientcursormon] mem (MB) res:386 virt:3537 mapped:1424
Sun Jun 3 05:48:55 [clientcursormon] mem (MB) res:388 virt:3537 mapped:1424
Sun Jun 3 05:53:55 [clientcursormon] mem (MB) res:387 virt:3537 mapped:1424
Sun Jun 3 05:58:55 [clientcursormon] mem (MB) res:390 virt:3537 mapped:1424
Sun Jun 3 06:03:55 [clientcursormon] mem (MB) res:390 virt:3537 mapped:1424
Sun Jun 3 06:08:55 [clientcursormon] mem (MB) res:393 virt:3537 mapped:1424
Sun Jun 3 06:13:55 [clientcursormon] mem (MB) res:393 virt:3537 mapped:1424
Sun Jun 3 06:15:18 [initandlisten] connection accepted from 10.0.0.107:37039 #35
Sun Jun 3 06:18:55 [clientcursormon] mem (MB) res:394 virt:3538 mapped:1424
Sun Jun 3 06:23:55 [clientcursormon] mem (MB) res:394 virt:3538 mapped:1424
Sun Jun 3 06:28:55 [clientcursormon] mem (MB) res:394 virt:3538 mapped:1424
Sun Jun 3 06:33:56 [clientcursormon] mem (MB) res:394 virt:3538 mapped:1424
Sun Jun 3 06:38:56 [clientcursormon] mem (MB) res:395 virt:3538 mapped:1424
Sun Jun 3 06:43:56 [clientcursormon] mem (MB) res:395 virt:3538 mapped:1424
Sun Jun 3 06:48:56 [clientcursormon] mem (MB) res:395 virt:3538 mapped:1424
Sun Jun 3 06:53:56 [clientcursormon] mem (MB) res:396 virt:3538 mapped:1424
Sun Jun 3 06:58:56 [clientcursormon] mem (MB) res:398 virt:3538 mapped:1424
Sun Jun 3 07:03:56 [clientcursormon] mem (MB) res:397 virt:3538 mapped:1424
Sun Jun 3 07:08:56 [clientcursormon] mem (MB) res:399 virt:3538 mapped:1424
Sun Jun 3 07:13:56 [clientcursormon] mem (MB) res:399 virt:3538 mapped:1424
Sun Jun 3 07:15:17 [initandlisten] connection accepted from 10.0.0.107:37234 #36
Sun Jun 3 07:18:56 [clientcursormon] mem (MB) res:405 virt:3539 mapped:1424
Sun Jun 3 07:23:56 [clientcursormon] mem (MB) res:406 virt:3539 mapped:1424
Sun Jun 3 07:28:56 [clientcursormon] mem (MB) res:407 virt:3539 mapped:1424
Sun Jun 3 07:33:56 [clientcursormon] mem (MB) res:405 virt:3539 mapped:1424
Sun Jun 3 07:38:56 [clientcursormon] mem (MB) res:408 virt:3539 mapped:1424
Sun Jun 3 07:43:56 [clientcursormon] mem (MB) res:407 virt:3539 mapped:1424
Sun Jun 3 07:45:52 [conn32] update meetup.groups query:
{ muid: "1658754" }
update: { $set: { muid: "1658754", geoLocation: [ 41.7700004578, -88.1500015259 ], topics: {}, urlname: "The-Spiritual-Forum", name: "The Spiritual Forum" } } 277ms
Sun Jun 3 07:48:56 [clientcursormon] mem (MB) res:407 virt:3539 mapped:1424
Sun Jun 3 07:53:56 [clientcursormon] mem (MB) res:408 virt:3539 mapped:1424
Sun Jun 3 07:58:56 [clientcursormon] mem (MB) res:409 virt:3539 mapped:1424
Sun Jun 3 08:03:56 [clientcursormon] mem (MB) res:411 virt:3539 mapped:1424
Sun Jun 3 08:08:56 [clientcursormon] mem (MB) res:408 virt:3539 mapped:1424
Sun Jun 3 08:13:56 [clientcursormon] mem (MB) res:412 virt:3539 mapped:1424
Sun Jun 3 08:15:22 [initandlisten] connection accepted from 10.0.0.107:37432 #37
Sun Jun 3 08:18:56 [clientcursormon] mem (MB) res:408 virt:3540 mapped:1424
Sun Jun 3 08:23:56 [clientcursormon] mem (MB) res:409 virt:3540 mapped:1424
Sun Jun 3 08:28:56 [clientcursormon] mem (MB) res:409 virt:3540 mapped:1424
Sun Jun 3 08:33:56 [clientcursormon] mem (MB) res:408 virt:3540 mapped:1424
Sun Jun 3 08:38:56 [clientcursormon] mem (MB) res:409 virt:3540 mapped:1424
Sun Jun 3 08:43:56 [clientcursormon] mem (MB) res:410 virt:3540 mapped:1424
Sun Jun 3 08:48:56 [clientcursormon] mem (MB) res:412 virt:3540 mapped:1424
Sun Jun 3 08:53:56 [clientcursormon] mem (MB) res:409 virt:3540 mapped:1424
Sun Jun 3 08:58:56 [clientcursormon] mem (MB) res:411 virt:3540 mapped:1424
Sun Jun 3 09:03:56 [clientcursormon] mem (MB) res:413 virt:3540 mapped:1424
Sun Jun 3 09:08:56 [clientcursormon] mem (MB) res:411 virt:3540 mapped:1424
Sun Jun 3 09:13:56 [clientcursormon] mem (MB) res:413 virt:3540 mapped:1424
Sun Jun 3 09:15:28 [initandlisten] connection accepted from 10.0.0.107:37635 #38
Sun Jun 3 09:18:56 [clientcursormon] mem (MB) res:417 virt:3541 mapped:1424
Sun Jun 3 09:23:56 [clientcursormon] mem (MB) res:416 virt:3541 mapped:1424
Sun Jun 3 09:28:56 [clientcursormon] mem (MB) res:417 virt:3541 mapped:1424
Sun Jun 3 09:33:56 [clientcursormon] mem (MB) res:415 virt:3541 mapped:1424
Sun Jun 3 09:38:56 [clientcursormon] mem (MB) res:415 virt:3541 mapped:1424
Sun Jun 3 09:43:56 [clientcursormon] mem (MB) res:416 virt:3541 mapped:1424
Sun Jun 3 09:48:56 [clientcursormon] mem (MB) res:415 virt:3541 mapped:1424
Sun Jun 3 09:53:56 [clientcursormon] mem (MB) res:417 virt:3541 mapped:1424
Sun Jun 3 09:58:56 [clientcursormon] mem (MB) res:419 virt:3541 mapped:1424
Sun Jun 3 10:03:57 [clientcursormon] mem (MB) res:417 virt:3541 mapped:1424
Sun Jun 3 10:08:57 [clientcursormon] mem (MB) res:420 virt:3541 mapped:1424
Sun Jun 3 10:13:57 [clientcursormon] mem (MB) res:419 virt:3541 mapped:1424
Sun Jun 3 10:15:21 [initandlisten] connection accepted from 10.0.0.107:37801 #39
Sun Jun 3 10:18:57 [clientcursormon] mem (MB) res:419 virt:3542 mapped:1424
Sun Jun 3 10:23:57 [clientcursormon] mem (MB) res:418 virt:3542 mapped:1424
Sun Jun 3 10:28:57 [clientcursormon] mem (MB) res:419 virt:3542 mapped:1424
Sun Jun 3 10:33:57 [clientcursormon] mem (MB) res:419 virt:3542 mapped:1424
Sun Jun 3 10:38:57 [clientcursormon] mem (MB) res:423 virt:3542 mapped:1424
Sun Jun 3 10:43:57 [clientcursormon] mem (MB) res:423 virt:3542 mapped:1424
Sun Jun 3 10:48:57 [clientcursormon] mem (MB) res:425 virt:3542 mapped:1424
Sun Jun 3 10:53:57 [clientcursormon] mem (MB) res:424 virt:3542 mapped:1424
Sun Jun 3 10:58:57 [clientcursormon] mem (MB) res:424 virt:3542 mapped:1424
Sun Jun 3 11:03:57 [clientcursormon] mem (MB) res:426 virt:3542 mapped:1424
Sun Jun 3 11:08:57 [clientcursormon] mem (MB) res:424 virt:3542 mapped:1424
Sun Jun 3 11:13:57 [clientcursormon] mem (MB) res:424 virt:3542 mapped:1424
Sun Jun 3 11:15:19 [initandlisten] connection accepted from 10.0.0.107:37948 #40
Sun Jun 3 11:18:57 [clientcursormon] mem (MB) res:425 virt:3543 mapped:1424
Sun Jun 3 11:23:57 [clientcursormon] mem (MB) res:427 virt:3543 mapped:1424
Sun Jun 3 11:28:57 [clientcursormon] mem (MB) res:424 virt:3543 mapped:1424
Sun Jun 3 11:33:57 [clientcursormon] mem (MB) res:427 virt:3543 mapped:1424
Sun Jun 3 11:38:57 [clientcursormon] mem (MB) res:425 virt:3543 mapped:1424
Sun Jun 3 11:43:57 [clientcursormon] mem (MB) res:428 virt:3543 mapped:1424
Sun Jun 3 11:48:57 [clientcursormon] mem (MB) res:426 virt:3543 mapped:1424
Sun Jun 3 11:53:57 [clientcursormon] mem (MB) res:429 virt:3543 mapped:1424
Sun Jun 3 11:58:57 [clientcursormon] mem (MB) res:428 virt:3543 mapped:1424
Sun Jun 3 12:03:57 [clientcursormon] mem (MB) res:430 virt:3543 mapped:1424
Sun Jun 3 12:08:57 [clientcursormon] mem (MB) res:428 virt:3543 mapped:1424
Sun Jun 3 12:13:57 [clientcursormon] mem (MB) res:432 virt:3543 mapped:1424
Sun Jun 3 12:15:24 [initandlisten] connection accepted from 10.0.0.107:38148 #41
Sun Jun 3 12:18:57 [clientcursormon] mem (MB) res:430 virt:3544 mapped:1424
Sun Jun 3 12:23:57 [clientcursormon] mem (MB) res:431 virt:3544 mapped:1424
Sun Jun 3 12:28:57 [clientcursormon] mem (MB) res:430 virt:3544 mapped:1424
Sun Jun 3 12:33:57 [clientcursormon] mem (MB) res:430 virt:3544 mapped:1424
Sun Jun 3 12:38:57 [clientcursormon] mem (MB) res:433 virt:3544 mapped:1424
Sun Jun 3 12:43:57 [clientcursormon] mem (MB) res:432 virt:3544 mapped:1424
Sun Jun 3 12:48:57 [clientcursormon] mem (MB) res:431 virt:3544 mapped:1424
Sun Jun 3 12:53:57 [clientcursormon] mem (MB) res:431 virt:3544 mapped:1424
Sun Jun 3 12:58:57 [clientcursormon] mem (MB) res:432 virt:3544 mapped:1424
Sun Jun 3 13:03:57 [clientcursormon] mem (MB) res:434 virt:3544 mapped:1424
Sun Jun 3 13:08:57 [clientcursormon] mem (MB) res:434 virt:3544 mapped:1424
Sun Jun 3 13:13:57 [clientcursormon] mem (MB) res:434 virt:3544 mapped:1424
Sun Jun 3 13:15:24 [initandlisten] connection accepted from 10.0.0.107:38323 #42
Sun Jun 3 13:18:57 [clientcursormon] mem (MB) res:434 virt:3545 mapped:1424
Sun Jun 3 13:23:58 [clientcursormon] mem (MB) res:434 virt:3545 mapped:1424
Sun Jun 3 13:28:58 [clientcursormon] mem (MB) res:433 virt:3545 mapped:1424
Sun Jun 3 13:33:58 [clientcursormon] mem (MB) res:435 virt:3545 mapped:1424
Sun Jun 3 13:38:58 [clientcursormon] mem (MB) res:434 virt:3545 mapped:1424
Sun Jun 3 13:43:58 [clientcursormon] mem (MB) res:433 virt:3545 mapped:1424
Sun Jun 3 13:48:58 [clientcursormon] mem (MB) res:433 virt:3545 mapped:1424
Sun Jun 3 13:53:58 [clientcursormon] mem (MB) res:433 virt:3545 mapped:1424
Sun Jun 3 13:58:58 [clientcursormon] mem (MB) res:433 virt:3545 mapped:1424
Sun Jun 3 14:03:58 [clientcursormon] mem (MB) res:433 virt:3545 mapped:1424
Sun Jun 3 14:05:55 [initandlisten] connection accepted from 10.0.0.107:38451 #43
Sun Jun 3 14:08:58 [clientcursormon] mem (MB) res:433 virt:3546 mapped:1424
Sun Jun 3 14:13:58 [clientcursormon] mem (MB) res:435 virt:3546 mapped:1424
Sun Jun 3 14:15:19 [initandlisten] connection accepted from 10.0.0.107:38483 #44
Sun Jun 3 14:15:20 [initandlisten] connection accepted from 10.0.0.107:38484 #45
Sun Jun 3 14:15:20 [conn45] update meetup.groups query:
{ fbid: "253591661347566", id: "415615495145181" }
update: { $set: { fbid: "253591661347566", id: "415615495145181", graph: { id: "253591661347566_415615495145181", from:
{ name: "Pam Bass Rowell", id: "650285760" }
, to: { data: {} }, message: "When is the feed going to be repaired? I finally tried going back and unfollowing and refollowing all that I follow, but I am afraid I am missing some. ", type: "status", created_time: "2012-06-03T17:27:14+0000", updated_time: "2012-06-03T17:27:14+0000", comments: { data: {} }, properties: {}, actions: {} } } } fastmodinsert:1 338ms
Sun Jun 3 14:15:58 [clientcursormon] mem (MB) res:552 virt:3548 mapped:1424
Sun Jun 3 14:20:58 [clientcursormon] mem (MB) res:437 virt:3548 mapped:1424
Sun Jun 3 14:25:58 [clientcursormon] mem (MB) res:436 virt:3548 mapped:1424
Sun Jun 3 14:30:58 [clientcursormon] mem (MB) res:434 virt:3548 mapped:1424
Sun Jun 3 14:35:58 [clientcursormon] mem (MB) res:436 virt:3548 mapped:1424
Sun Jun 3 14:40:58 [clientcursormon] mem (MB) res:437 virt:3548 mapped:1424
Sun Jun 3 14:45:58 [clientcursormon] mem (MB) res:437 virt:3548 mapped:1424
Sun Jun 3 14:50:58 [clientcursormon] mem (MB) res:436 virt:3548 mapped:1424
Sun Jun 3 14:55:58 [clientcursormon] mem (MB) res:437 virt:3548 mapped:1424
Sun Jun 3 15:00:58 [clientcursormon] mem (MB) res:436 virt:3548 mapped:1424
Sun Jun 3 15:05:58 [clientcursormon] mem (MB) res:436 virt:3548 mapped:1424
Sun Jun 3 15:10:58 [clientcursormon] mem (MB) res:438 virt:3548 mapped:1424
Sun Jun 3 15:15:29 [initandlisten] connection accepted from 10.0.0.107:38668 #46
Sun Jun 3 15:15:58 [clientcursormon] mem (MB) res:440 virt:3549 mapped:1424
Sun Jun 3 15:20:58 [clientcursormon] mem (MB) res:439 virt:3549 mapped:1424
Sun Jun 3 15:25:58 [clientcursormon] mem (MB) res:438 virt:3549 mapped:1424
Sun Jun 3 15:30:58 [clientcursormon] mem (MB) res:437 virt:3549 mapped:1424
Sun Jun 3 15:35:58 [clientcursormon] mem (MB) res:439 virt:3549 mapped:1424
Sun Jun 3 15:40:58 [clientcursormon] mem (MB) res:439 virt:3549 mapped:1424
Sun Jun 3 15:45:58 [clientcursormon] mem (MB) res:440 virt:3549 mapped:1424
Sun Jun 3 15:50:58 [clientcursormon] mem (MB) res:438 virt:3549 mapped:1424
Sun Jun 3 15:55:58 [clientcursormon] mem (MB) res:438 virt:3549 mapped:1424
Sun Jun 3 16:00:58 [clientcursormon] mem (MB) res:437 virt:3549 mapped:1424
Sun Jun 3 16:05:58 [clientcursormon] mem (MB) res:439 virt:3549 mapped:1424
Sun Jun 3 16:10:58 [clientcursormon] mem (MB) res:440 virt:3549 mapped:1424
Sun Jun 3 16:15:21 [initandlisten] connection accepted from 10.0.0.107:38838 #47
Sun Jun 3 16:15:58 [clientcursormon] mem (MB) res:445 virt:3550 mapped:1424
Sun Jun 3 16:20:58 [clientcursormon] mem (MB) res:438 virt:3550 mapped:1424
Sun Jun 3 16:25:58 [clientcursormon] mem (MB) res:441 virt:3550 mapped:1424
Sun Jun 3 16:30:58 [clientcursormon] mem (MB) res:439 virt:3550 mapped:1424
Sun Jun 3 16:35:58 [clientcursormon] mem (MB) res:441 virt:3550 mapped:1424
Sun Jun 3 16:40:58 [clientcursormon] mem (MB) res:441 virt:3550 mapped:1424
Sun Jun 3 16:45:59 [clientcursormon] mem (MB) res:440 virt:3550 mapped:1424
Sun Jun 3 16:50:59 [clientcursormon] mem (MB) res:438 virt:3550 mapped:1424
Sun Jun 3 16:55:59 [clientcursormon] mem (MB) res:439 virt:3550 mapped:1424
Sun Jun 3 17:00:59 [clientcursormon] mem (MB) res:439 virt:3550 mapped:1424
Sun Jun 3 17:05:59 [clientcursormon] mem (MB) res:439 virt:3550 mapped:1424
Sun Jun 3 17:10:59 [clientcursormon] mem (MB) res:440 virt:3550 mapped:1424
Sun Jun 3 17:15:25 [initandlisten] connection accepted from 10.0.0.107:39001 #48
Sun Jun 3 17:15:59 [clientcursormon] mem (MB) res:443 virt:3551 mapped:1424
Sun Jun 3 17:20:59 [clientcursormon] mem (MB) res:442 virt:3551 mapped:1424
Sun Jun 3 17:25:59 [clientcursormon] mem (MB) res:440 virt:3551 mapped:1424
Sun Jun 3 17:30:59 [clientcursormon] mem (MB) res:441 virt:3551 mapped:1424
Sun Jun 3 17:35:59 [clientcursormon] mem (MB) res:441 virt:3551 mapped:1424
Sun Jun 3 17:40:59 [clientcursormon] mem (MB) res:442 virt:3551 mapped:1424
Sun Jun 3 17:45:59 [clientcursormon] mem (MB) res:442 virt:3551 mapped:1424
Sun Jun 3 17:50:59 [clientcursormon] mem (MB) res:440 virt:3551 mapped:1424
Sun Jun 3 17:55:59 [clientcursormon] mem (MB) res:442 virt:3551 mapped:1424
Sun Jun 3 18:00:59 [clientcursormon] mem (MB) res:442 virt:3551 mapped:1424
Sun Jun 3 18:05:59 [clientcursormon] mem (MB) res:440 virt:3551 mapped:1424
Sun Jun 3 18:10:59 [clientcursormon] mem (MB) res:442 virt:3551 mapped:1424
Sun Jun 3 18:15:23 [initandlisten] connection accepted from 10.0.0.107:39223 #49
Sun Jun 3 18:15:59 [clientcursormon] mem (MB) res:446 virt:3553 mapped:1424
Sun Jun 3 18:20:59 [clientcursormon] mem (MB) res:442 virt:3553 mapped:1424
Sun Jun 3 18:25:59 [clientcursormon] mem (MB) res:442 virt:3553 mapped:1424
Sun Jun 3 18:30:59 [clientcursormon] mem (MB) res:442 virt:3553 mapped:1424
Sun Jun 3 18:35:59 [clientcursormon] mem (MB) res:441 virt:3553 mapped:1424
Sun Jun 3 18:40:59 [clientcursormon] mem (MB) res:442 virt:3553 mapped:1424
Sun Jun 3 18:45:59 [clientcursormon] mem (MB) res:443 virt:3553 mapped:1424
Sun Jun 3 18:50:59 [clientcursormon] mem (MB) res:445 virt:3553 mapped:1424
Sun Jun 3 18:55:59 [clientcursormon] mem (MB) res:444 virt:3553 mapped:1424
Sun Jun 3 19:00:59 [clientcursormon] mem (MB) res:443 virt:3553 mapped:1424
Sun Jun 3 19:05:59 [clientcursormon] mem (MB) res:444 virt:3553 mapped:1424
Sun Jun 3 19:10:59 [clientcursormon] mem (MB) res:445 virt:3553 mapped:1424
Sun Jun 3 19:15:28 [initandlisten] connection accepted from 10.0.0.107:39387 #50
Sun Jun 3 19:15:59 [clientcursormon] mem (MB) res:446 virt:3554 mapped:1424
Sun Jun 3 19:20:59 [clientcursormon] mem (MB) res:443 virt:3554 mapped:1424
Sun Jun 3 19:25:59 [clientcursormon] mem (MB) res:443 virt:3554 mapped:1424
Sun Jun 3 19:30:59 [clientcursormon] mem (MB) res:446 virt:3554 mapped:1424
Sun Jun 3 19:35:59 [clientcursormon] mem (MB) res:444 virt:3554 mapped:1424
Sun Jun 3 19:40:59 [clientcursormon] mem (MB) res:444 virt:3554 mapped:1424
Sun Jun 3 19:45:59 [clientcursormon] mem (MB) res:446 virt:3554 mapped:1424
Sun Jun 3 19:50:59 [clientcursormon] mem (MB) res:445 virt:3554 mapped:1424
Sun Jun 3 19:56:00 [clientcursormon] mem (MB) res:446 virt:3554 mapped:1424
Sun Jun 3 20:01:00 [clientcursormon] mem (MB) res:445 virt:3554 mapped:1424
Sun Jun 3 20:06:00 [clientcursormon] mem (MB) res:447 virt:3554 mapped:1424
Sun Jun 3 20:11:00 [clientcursormon] mem (MB) res:447 virt:3554 mapped:1424
Sun Jun 3 20:15:23 [initandlisten] connection accepted from 10.0.0.107:39545 #51
Sun Jun 3 20:16:00 [clientcursormon] mem (MB) res:451 virt:3555 mapped:1424
Sun Jun 3 20:21:00 [clientcursormon] mem (MB) res:447 virt:3555 mapped:1424
Sun Jun 3 20:26:00 [clientcursormon] mem (MB) res:446 virt:3555 mapped:1424
Sun Jun 3 20:31:00 [clientcursormon] mem (MB) res:445 virt:3555 mapped:1424
Sun Jun 3 20:36:00 [clientcursormon] mem (MB) res:445 virt:3555 mapped:1424
Sun Jun 3 20:41:00 [clientcursormon] mem (MB) res:446 virt:3555 mapped:1424
Sun Jun 3 20:46:00 [clientcursormon] mem (MB) res:446 virt:3555 mapped:1424
Sun Jun 3 20:51:00 [clientcursormon] mem (MB) res:445 virt:3555 mapped:1424
Sun Jun 3 20:56:00 [clientcursormon] mem (MB) res:445 virt:3555 mapped:1424
Sun Jun 3 21:01:00 [clientcursormon] mem (MB) res:447 virt:3555 mapped:1424
Sun Jun 3 21:06:00 [clientcursormon] mem (MB) res:446 virt:3555 mapped:1424
Sun Jun 3 21:11:00 [clientcursormon] mem (MB) res:446 virt:3555 mapped:1424
Sun Jun 3 21:15:22 [initandlisten] connection accepted from 10.0.0.107:39705 #52
Sun Jun 3 21:16:00 [clientcursormon] mem (MB) res:451 virt:3556 mapped:1424
Sun Jun 3 21:21:00 [clientcursormon] mem (MB) res:446 virt:3556 mapped:1424
Sun Jun 3 21:26:00 [clientcursormon] mem (MB) res:449 virt:3556 mapped:1424
Sun Jun 3 21:31:00 [clientcursormon] mem (MB) res:448 virt:3556 mapped:1424
Sun Jun 3 21:36:00 [clientcursormon] mem (MB) res:448 virt:3556 mapped:1424
Sun Jun 3 21:41:00 [clientcursormon] mem (MB) res:449 virt:3556 mapped:1424
Sun Jun 3 21:43:35 [initandlisten] connection accepted from 10.0.0.107:39808 #53
Sun Jun 3 21:43:35 [conn53] build index meetup.growth
{ _id: 1 }
Sun Jun 3 21:43:35 [conn53] build index done 0 records 0 secs
Sun Jun 3 21:44:09 [initandlisten] connection accepted from 10.0.0.73:2829 #54
Sun Jun 3 21:46:00 [clientcursormon] mem (MB) res:447 virt:3558 mapped:1424
Sun Jun 3 21:51:00 [clientcursormon] mem (MB) res:449 virt:3558 mapped:1424
Sun Jun 3 21:51:49 [initandlisten] connection accepted from 10.0.0.107:39830 #55
Sun Jun 3 21:55:27 [initandlisten] connection accepted from 10.0.0.107:39838 #56
Sun Jun 3 21:56:00 [clientcursormon] mem (MB) res:450 virt:3560 mapped:1424
Sun Jun 3 21:56:36 [initandlisten] connection accepted from 10.0.0.107:39842 #57
Sun Jun 3 21:57:05 [initandlisten] connection accepted from 10.0.0.107:39845 #58
Sun Jun 3 21:57:48 [initandlisten] connection accepted from 10.0.0.73:3084 #59
Sun Jun 3 22:01:00 [clientcursormon] mem (MB) res:432 virt:3563 mapped:1424
Sun Jun 3 22:06:00 [clientcursormon] mem (MB) res:432 virt:3563 mapped:1424
Sun Jun 3 22:11:00 [clientcursormon] mem (MB) res:433 virt:3563 mapped:1424
Sun Jun 3 22:15:25 [initandlisten] connection accepted from 10.0.0.107:40346 #60
Sun Jun 3 22:16:00 [clientcursormon] mem (MB) res:435 virt:3564 mapped:1424
Sun Jun 3 22:21:00 [clientcursormon] mem (MB) res:432 virt:3564 mapped:1424
Sun Jun 3 22:26:00 [clientcursormon] mem (MB) res:432 virt:3564 mapped:1424
Sun Jun 3 22:30:19 [initandlisten] connection accepted from 10.0.0.107:40483 #61
Sun Jun 3 22:30:23 [conn61] build index songkick.events
{ _id: 1 }
Sun Jun 3 22:30:23 [conn61] build index done 0 records 0 secs
Sun Jun 3 22:30:23 [conn61] info: creating collection songkick.events on add index
Sun Jun 3 22:30:23 [conn61] build index songkick.events
{ skid: 1 }
Sun Jun 3 22:30:23 [conn61] build index done 0 records 0 secs
Sun Jun 3 22:30:23 [conn61] build index songkick.venues
{ _id: 1 }
Sun Jun 3 22:30:23 [conn61] build index done 0 records 0 secs
Sun Jun 3 22:30:23 [conn61] info: creating collection songkick.venues on add index
Sun Jun 3 22:30:23 [conn61] build index songkick.venues
{ skid: 1 }
Sun Jun 3 22:30:23 [conn61] build index done 0 records 0 secs
Sun Jun 3 22:30:57 [initandlisten] connection accepted from 10.0.0.73:3711 #62
Sun Jun 3 22:31:00 [clientcursormon] mem (MB) res:432 virt:3566 mapped:1424
Sun Jun 3 22:31:12 [initandlisten] connection accepted from 10.0.0.107:40508 #63
Sun Jun 3 22:31:23 [initandlisten] connection accepted from 10.0.0.73:3719 #64
Sun Jun 3 22:32:03 [initandlisten] connection accepted from 10.0.0.107:40523 #65
Sun Jun 3 22:32:03 Invalid access at address: 0x7f05c23a746f
Sun Jun 3 22:32:03 Got signal: 11 (Segmentation fault).
Sun Jun 3 22:32:03 Backtrace:
0xa95df9 0xa9651c 0x3d4800f4a0 0x86eb14 0x86ed78 0x9794dc 0x8c9a96 0x8d9930 0x8d9f86 0x8ddc3e 0x8df5f5 0x8dfaf0 0x8e1bcd 0x95f542 0x9642d5 0x88d63c 0x88efdf 0xaa0cc8 0x638997 0x3d480077f1
/usr/bin/mongod(_ZN5mongo10abruptQuitEi+0x3a9) [0xa95df9]
/usr/bin/mongod(_ZN5mongo24abruptQuitWithAddrSignalEiP7siginfoPv+0x22c) [0xa9651c]
/lib64/libpthread.so.0() [0x3d4800f4a0]
/usr/bin/mongod(_ZN5mongo19CoveredIndexMatcher7matchesERKNS_7BSONObjERKNS_7DiskLocEPNS_12MatchDetailsEb+0xa4) [0x86eb14]
/usr/bin/mongod(_ZN5mongo19CoveredIndexMatcher14matchesCurrentEPNS_6CursorEPNS_12MatchDetailsE+0xa8) [0x86ed78]
/usr/bin/mongod(_ZN5mongo8UpdateOp4nextEv+0x1ac) [0x9794dc]
/usr/bin/mongod(_ZN5mongo12QueryPlanSet6Runner6nextOpERNS_7QueryOpE+0x56) [0x8c9a96]
/usr/bin/mongod(_ZN5mongo12QueryPlanSet6Runner4nextEv+0x110) [0x8d9930]
/usr/bin/mongod(_ZN5mongo12QueryPlanSet6Runner22runUntilFirstCompletesEv+0x56) [0x8d9f86]
/usr/bin/mongod(_ZN5mongo12QueryPlanSet5runOpERNS_7QueryOpE+0x11e) [0x8ddc3e]
/usr/bin/mongod(_ZN5mongo16MultiPlanScanner9runOpOnceERNS_7QueryOpE+0x525) [0x8df5f5]
/usr/bin/mongod(_ZN5mongo11MultiCursor10nextClauseEv+0x70) [0x8dfaf0]
/usr/bin/mongod(_ZN5mongo11MultiCursorC1EPKcRKNS_7BSONObjES5_N5boost10shared_ptrINS0_8CursorOpEEEb+0x20d) [0x8e1bcd]
/usr/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0x372) [0x95f542]
/usr/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x125) [0x9642d5]
/usr/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x46c) [0x88d63c]
/usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x116f) [0x88efdf]
/usr/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x78) [0xaa0cc8]
/usr/bin/mongod(_ZN5mongo3pms9threadRunEPNS_13MessagingPortE+0x287) [0x638997]
/lib64/libpthread.so.0() [0x3d480077f1]
Logstream::get called in uninitialized state
Sun Jun 3 22:32:03 ERROR: Client::~Client _context should be null but is not; client:conn
Logstream::get called in uninitialized state
Sun Jun 3 22:32:03 ERROR: Client::shutdown not called: conn
|
|
Do you have the corresponding server logs from your BSON errors this afternoon? I would like to see them.
|
|
I am no long inserting anything into mongo so I am not sure I can produce
any new logs. I may have some old logs.
Here is a recent example of a BSON error received after iterating a
collection of about 580k documents. The error happened after reading 218325
documents. I was able to read the remainder after skipping 218300
documents. The string size translates to ASCII "ts\0\0". I am using driver
version 2.7.3
May 13, 2012 6:54:53 PM com.mongodb.DBPortPool gotError
WARNING: emptying DBPortPool to mongodb.hierweb.com:27017 b/c of error
org.bson.BSONException: bad string size: 1953693696
at
org.bson.BasicBSONDecoder$BSONInput.readUTF8String(BasicBSONDecoder.java:456)
at
org.bson.BasicBSONDecoder.decodeElement(BasicBSONDecoder.java:155)
at
org.bson.BasicBSONDecoder.decodeElement(BasicBSONDecoder.java:206)
at org.bson.BasicBSONDecoder._decode(BasicBSONDecoder.java:79)
at org.bson.BasicBSONDecoder.decode(BasicBSONDecoder.java:57)
at com.mongodb.DefaultDBDecoder.decode(DefaultDBDecoder.java:56)
at com.mongodb.Response.<init>(Response.java:66)
at com.mongodb.DBPort.go(DBPort.java:128)
at com.mongodb.DBPort.call(DBPort.java:79)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:218)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:189)
at com.mongodb.DBApiLayer$Result._advance(DBApiLayer.java:452)
at com.mongodb.DBApiLayer$Result.hasNext(DBApiLayer.java:418)
at com.mongodb.DBCursor._hasNext(DBCursor.java:509)
at com.mongodb.DBCursor.hasNext(DBCursor.java:529)
at
org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:1375)
at
org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:1349)
at org.codehaus.groovy.runtime.dgm$142.doMethodInvoke(Unknown
Source)
at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1054)
at
groovy.lang.ExpandoMetaClass.invokeMethod(ExpandoMetaClass.java:1110)
at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:884)
at
org.codehaus.groovy.runtime.callsite.PerInstancePojoMetaClassSite.call(PerInstancePojoMetaClassSite.java:35)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)
at common.queryCollection(common.groovy:278)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSite.invoke(PogoMetaMethodSite.java:226)
at
org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:52)
at common.queryCollection(common.groovy)
at common$queryCollection.call(Unknown Source)
at Facebook$_eachWall_closure12.doCall(Facebook.groovy:162)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
at
org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:272)
at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:884)
at
org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.call(PogoMetaClassSite.java:39)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)
at Facebook.wall(Facebook.groovy:170)
at Facebook$wall.callCurrent(Unknown Source)
at Facebook.eachWall(Facebook.groovy:161)
at Facebook$eachWall.call(Unknown Source)
at
Script6$_recover_wall_closure3_closure10.doCall(Script6.groovy:105)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
at
org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:272)
at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:884)
at groovy.lang.Closure.call(Closure.java:410)
at groovy.lang.Closure.call(Closure.java:423)
at
org.codehaus.groovy.runtime.DefaultGroovyMethods.withWriter(DefaultGroovyMethods.java:16122)
at
org.codehaus.groovy.runtime.DefaultGroovyMethods.withWriter(DefaultGroovyMethods.java:15977)
at org.codehaus.groovy.runtime.dgm$904.invoke(Unknown Source)
at
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:271)
at
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:53)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)
at Script6$_recover_wall_closure3.doCall(Script6.groovy:104)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90)
at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:233)
at
org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:272)
at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:884)
at groovy.lang.Closure.call(Closure.java:410)
at groovy.lang.Closure.call(Closure.java:423)
at
org.codehaus.groovy.runtime.DefaultGroovyMethods.step(DefaultGroovyMethods.java:12626)
at org.codehaus.groovy.runtime.dgm$722.invoke(Unknown Source)
at
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoMetaMethodSiteNoUnwrapNoCoerce.invoke(PojoMetaMethodSite.java:271)
at
org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:53)
at
org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:42)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:108)
at
org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:124)
at Script6.recover_wall(Script6.groovy:101)
at Script6.run(Script6.groovy:54)
at
org.codehaus.groovy.jsr223.GroovyScriptEngineImpl.eval(GroovyScriptEngineImpl.java:315)
at
org.codehaus.groovy.jsr223.GroovyScriptEngineImpl.eval(GroovyScriptEngineImpl.java:111)
at
org.codehaus.groovy.jsr223.GroovyScriptEngineImpl.eval(GroovyScriptEngineImpl.java:103)
at
javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:195)
at com.hierweb.mdt.ScriptHandler.handle(ScriptHandler.java:206)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:113)
at org.eclipse.jetty.server.Server.handle(Server.java:338)
at
org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:568)
at
org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:995)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:560)
at
org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:222)
at
org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:403)
at
org.eclipse.jetty.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:474)
at
org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:437)
at java.lang.Thread.run(Thread.java:662)
The comment in BasicBSONDecoder right before the size check makes me think
this problem has been around for a while and this is just a workaround
masking the actual cause of corruption.
Reading the same collection, this time running from the Netbeans debugger I
get this error after reading ~57k documents:
May 13, 2012 8:33:05 PM com.mongodb.DBPortPool gotError
WARNING: emptying DBPortPool to mongodb.hierweb.com:27017 b/c of error
java.lang.ArrayIndexOutOfBoundsException
at java.lang.System.arraycopy(Native Method)
at org.bson.BasicBSONDecoder$BSONInput._need(BasicBSONDecoder.java:318)
at org.bson.BasicBSONDecoder$BSONInput.read(BasicBSONDecoder.java:366)
at org.bson.BasicBSONDecoder$BSONInput.readCStr(BasicBSONDecoder.java:407)
at org.bson.BasicBSONDecoder.decodeElement(BasicBSONDecoder.java:123)
at org.bson.BasicBSONDecoder._decode(BasicBSONDecoder.java:79)
at org.bson.BasicBSONDecoder.decode(BasicBSONDecoder.java:57)
at com.mongodb.DefaultDBDecoder.decode(DefaultDBDecoder.java:56)
at com.mongodb.Response.<init>(Response.java:66)
at com.mongodb.DBPort.go(DBPort.java:128)
at com.mongodb.DBPort.call(DBPort.java:79)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:218)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:189)
at com.mongodb.DBApiLayer$Result._advance(DBApiLayer.java:452)
at com.mongodb.DBApiLayer$Result.hasNext(DBApiLayer.java:418)
at com.mongodb.DBCursor._hasNext(DBCursor.java:509)
at com.mongodb.DBCursor.hasNext(DBCursor.java:529)
at
org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:1375)
at
org.codehaus.groovy.runtime.DefaultGroovyMethods.each(DefaultGroovyMethods.java:1349)
No changes were made to the collection or the code
|
|
Thanks for the general overview. Attach some logs and some sample insert code, with some sample documents, and I'll try to set something up locally to reproduce.
|
|
Must have hit tab or enter at the wrong time..
Hi Eric,
I have reproduced it multiple time 
The general procedure is
a) create multiple collections giving each collections an easily
distinguished id name field, e.g. aid, bid, did
b) insert records into all – probably on the order of 100k. The
documents I work with have a very wide range in size from hundred of bytes
to tens of kilobytes. Think tweets to word docs converted to html. Insert
the collections
c) select documents from collection A having bid or did fields and
repeat for B and D collections
There error rate seems to be around 1 in 10000 for my data and my
suspicion is that that rate is a function of the mix of my data not a fixed
periodicity. Also, because the data seems to be intact data from some
record, it seems either a read or write frameshift has occurred in such a
way the location corresponding to BSON size is actually some part of this
other data.
I did not update valgrind, but I am more inclined to believe its output
than to attribute the error to monitoring tool.
|
|
Hi Steven,
I totally believe Valgrind's output telling us that Valgrind is crashing. I'm hoping that an upgrade will give us more useful output to help diagnose the bug in mongo code.
Can you please attach a server log showing the time when you inserted the records and when you ran tests to detect the issue (seeing the BSON errors and extremely long strings would also be good)? Also, provide an example of your code that you are using to insert using the Java driver. I would like to attempt to reproduce this on my own setup.
|
|
Hi Eric,
I have reproduced it multiple time 
I did not update valgrind, but I am more inclined to believe the its
output than to attribute the error to monitoring tool.
|
|
Hi Steven,
Is this still reproducible? Did you try upgrading Valgrind?
|
|
I restarted with a fresh set collections and can not readily switch to a
corrupt backup. Perhaps it is related, but also observe beam.smp from
erlang/couchbase (erl 5.8.5):
Apr 17 19:39:48 localhost kernel: beam.smp[1929]: segfault at 0 ip
00000000004ac8bb sp 00007fb39fcbcc10 error 6 in beam.smp[400000+1c6000]
Apr 17 19:39:50 localhost abrt[2619]: saved core dump of pid 1899
(/usr/lib64/erlang/erts-5.8.5/bin/beam.smp) to
/var/spool/abrt/ccpp-2012-04-17-19:39:48-1899.new/coredump (129990656 bytes)
The reported reason is 'Process /sbin/readahead was killed by signal 11
(SIGSEGV)'
|
|
This line:
Memcheck: mc_malloc_wrappers.c:113 (add_to_freed_queue): Assertion 'VG_(free_queue_volume) >= 0' failed.
|
means that valgrind hit an assertion and crashed. It could be due to memory corruption or it could be due to bugs in Valgrind. Can you upgrade valgrind to the current version and try again?
|
|
Tad, I've run full validate on problem collections. If it reports
{ok:1}
, the collection may still be corrupted. Dropping indexes or running the compact command does not fix the problem. In the worst case scenario, db.repairDatabase results in total data loss of that collection.
|
|
Attached is the valgrind output from restarting mongod after observing corrupted collections
|
|
Can you run db.foo.validate(
{full:true}
) on all the databases that are showing this problem? Also, if an index is being used in a query that is returning bad results or generating errors in the log, is it possible to rebuild the index and see if that fixes the problem? What is valgrind telling you?
|
Generated at Thu Feb 08 03:09:27 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.