A problem with MongoDB 2.4.1

[Aleksey Izmailov]

Hey guys,

I'm using Mongeez on MongoDB 2.2.3 (Linux), and it works perfectly well. I was a happy liquibase user for SQL DBs and Mongeez feels just right at home!

I ran into an issue trying to upgrade my MongoDB to 2.4.1. I would get this Mongeez exception:

2013-03-27 13:44:51,851 INFO [org.mongeez.reader.FilesetXMLReader] - Num of changefiles 1

com.mongodb.MongoException: Unknown index plugin 'changeSetExecution' in index { type: "changeSetExecution", file: 1, changeId: 1, author: 1, resourcePath: 1 }

at com.mongodb.CommandResult.getException(CommandResult.java:100)

at com.mongodb.CommandResult.throwOnError(CommandResult.java:134)

at com.mongodb.DBTCPConnector._checkWriteError(DBTCPConnector.java:142)

at com.mongodb.DBTCPConnector.say(DBTCPConnector.java:183)

at com.mongodb.DBTCPConnector.say(DBTCPConnector.java:155)

at com.mongodb.DBApiLayer$MyCollection.insert(DBApiLayer.java:270)

at com.mongodb.DBApiLayer$MyCollection.createIndex(DBApiLayer.java:365)

at com.mongodb.DBCollection.createIndex(DBCollection.java:484)

at com.mongodb.DBCollection.ensureIndex(DBCollection.java:560)

at com.mongodb.DBCollection.ensureIndex(DBCollection.java:511)

at org.mongeez.dao.MongeezDao.ensureChangeSetExecutionIndex(MongeezDao.java:92)

at org.mongeez.dao.MongeezDao.configure(MongeezDao.java:48)

at org.mongeez.dao.MongeezDao.<init>(MongeezDao.java:42)

at org.mongeez.ChangeSetExecutor.<init>(ChangeSetExecutor.java:34)

at org.mongeez.Mongeez.process(Mongeez.java:41)

at wws.db.schema.migration.DbSchemaMigration$.run(DbSchemaMigration.scala:26)

at .<init>(<console>:14)

at .<clinit>(<console>)

at .<init>(<console>:7)

at .<clinit>(<console>)

at $print(<console>)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:601)

at scala.tools.nsc.interpreter.IMain$ReadEvalPrint.call(IMain.scala:731)

at scala.tools.nsc.interpreter.IMain$Request.loadAndRun(IMain.scala:980)

at scala.tools.nsc.interpreter.IMain.loadAndRunReq$1(IMain.scala:570)

at scala.tools.nsc.interpreter.IMain.interpret(IMain.scala:601)

at scala.tools.nsc.interpreter.IMain.interpret(IMain.scala:565)

at scala.tools.nsc.interpreter.ILoop.reallyInterpret$1(ILoop.scala:745)

at scala.tools.nsc.interpreter.ILoop.interpretStartingWith(ILoop.scala:790)

at scala.tools.nsc.interpreter.ILoop.command(ILoop.scala:702)

at scala.tools.nsc.interpreter.ILoop.processLine$1(ILoop.scala:566)

at scala.tools.nsc.interpreter.ILoop.innerLoop$1(ILoop.scala:573)

at scala.tools.nsc.interpreter.ILoop.loop(ILoop.scala:576)

at scala.tools.nsc.interpreter.ILoop$$anonfun$process$1.apply$mcZ$sp(ILoop.scala:867)

at scala.tools.nsc.interpreter.ILoop$$anonfun$process$1.apply(ILoop.scala:822)

at scala.tools.nsc.interpreter.ILoop$$anonfun$process$1.apply(ILoop.scala:822)

at scala.tools.nsc.util.ScalaClassLoader$.savingContextLoader(ScalaClassLoader.scala:135)

at scala.tools.nsc.interpreter.ILoop.process(ILoop.scala:822)

at scala.tools.nsc.interpreter.ILoop.main(ILoop.scala:889)

at xsbt.ConsoleInterface.run(ConsoleInterface.scala:57)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:601)

at sbt.compiler.AnalyzingCompiler.call(AnalyzingCompiler.scala:73)

at sbt.compiler.AnalyzingCompiler.console(AnalyzingCompiler.scala:64)

at sbt.Console.console0$1(Console.scala:23)

at sbt.Console$$anonfun$apply$2$$anonfun$apply$1.apply$mcV$sp(Console.scala:24)

at sbt.TrapExit$.executeMain$1(TrapExit.scala:33)

at sbt.TrapExit$$anon$1.run(TrapExit.scala:42)

In MongoDB logs I get:

Wed Mar 27 14:23:15.211 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:122 nreturned:0 reslen:20 0ms

Wed Mar 27 14:24:15.057 [DataFileSync] flushing mmaps took 1ms  for 2 files

Wed Mar 27 14:24:15.211 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:128 nreturned:0 reslen:20 0ms

Wed Mar 27 14:24:28.424 [initandlisten] connection accepted from 127.0.0.1:36310 #1 (1 connection now open)

Wed Mar 27 14:24:28.425 [conn1] run command admin.$cmd { isMaster: 1 }

Wed Mar 27 14:24:28.425 [conn1] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0  reslen:115 0ms

Wed Mar 27 14:24:28.432 [conn1] opening db:  wws

Wed Mar 27 14:24:28.432 [conn1] update wws.mongeez query: { type: { $exists: false } } update: { $set: { type: "changeSetExecution" } } nscanned:0 nupdated:0 keyUpdates:0 locks(micros) w:208 0ms

Wed Mar 27 14:24:28.432 [conn1] run command wws.$cmd { getlasterror: 1 }

Wed Mar 27 14:24:28.432 [conn1] command wws.$cmd command: { getlasterror: 1 } ntoreturn:1 keyUpdates:0  reslen:85 0ms

Wed Mar 27 14:24:28.434 [conn1] query wws.mongeez query: { type: "configuration" } ntoreturn:1 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:55 nreturned:0 reslen:20 0ms

Wed Mar 27 14:24:28.435 [conn1] run command wws.$cmd { count: "mongeez", query: {} }

Wed Mar 27 14:24:28.435 [conn1] command wws.$cmd command: { count: "mongeez", query: {} } ntoreturn:1 keyUpdates:0 locks(micros) r:17 reslen:58 0ms

Wed Mar 27 14:24:28.436 [FileAllocator] allocating new datafile /var/lib/mongodb/wws.ns, filling with zeroes...

Wed Mar 27 14:24:28.436 [FileAllocator] creating directory /var/lib/mongodb/_tmp

Wed Mar 27 14:24:28.436 [FileAllocator] flushing directory /var/lib/mongodb

Wed Mar 27 14:24:28.493 [FileAllocator] flushing directory /var/lib/mongodb

Wed Mar 27 14:24:28.510 [FileAllocator] done allocating datafile /var/lib/mongodb/wws.ns, size: 16MB,  took 0.017 secs

Wed Mar 27 14:24:28.510 [FileAllocator] allocating new datafile /var/lib/mongodb/wws.0, filling with zeroes...

Wed Mar 27 14:24:28.523 [FileAllocator] flushing directory /var/lib/mongodb

Wed Mar 27 14:24:28.543 [FileAllocator] done allocating datafile /var/lib/mongodb/wws.0, size: 64MB,  took 0.033 secs

Wed Mar 27 14:24:28.544 [FileAllocator] allocating new datafile /var/lib/mongodb/wws.1, filling with zeroes...

Wed Mar 27 14:24:28.544 [FileAllocator] flushing directory /var/lib/mongodb

Wed Mar 27 14:24:28.544 [conn1] allocExtent wws.mongeez size 4352 0

Wed Mar 27 14:24:28.544 [conn1] adding _id index for collection wws.mongeez

Wed Mar 27 14:24:28.545 [conn1] allocExtent wws.system.indexes size 3584 0

Wed Mar 27 14:24:28.545 [conn1] New namespace: wws.system.indexes

Wed Mar 27 14:24:28.545 [conn1] allocExtent wws.system.namespaces size 2048 0

Wed Mar 27 14:24:28.545 [conn1] New namespace: wws.system.namespaces

Wed Mar 27 14:24:28.545 [conn1] build index wws.mongeez { _id: 1 }

Wed Mar 27 14:24:28.545 [conn1] external sort root: /var/lib/mongodb/_tmp/esort.1364408668.0/

Wed Mar 27 14:24:28.545 [conn1] external sort used : 0 files  in 0 secs

Wed Mar 27 14:24:28.546 [conn1] allocExtent wws.mongeez.$_id_ size 36864 0

Wed Mar 27 14:24:28.546 [conn1] New namespace: wws.mongeez.$_id_

Wed Mar 27 14:24:28.546 [conn1] done building bottom layer, going to commit

Wed Mar 27 14:24:28.546 [conn1] build index done.  scanned 0 total records. 0 secs

Wed Mar 27 14:24:28.546 [conn1] New namespace: wws.mongeez

Wed Mar 27 14:24:28.546 [conn1] insert wws.mongeez ninserted:1 keyUpdates:0 locks(micros) w:109882 109ms

Wed Mar 27 14:24:28.546 [conn1] run command wws.$cmd { getlasterror: 1 }

Wed Mar 27 14:24:28.546 [conn1] command wws.$cmd command: { getlasterror: 1 } ntoreturn:1 keyUpdates:0  reslen:67 0ms

Wed Mar 27 14:24:28.550 [conn1] query wws.system.indexes query: { name: "type_changeSetExecution_file_1_changeId_1_author_1_resourcePath_1", ns: "wws.mongeez", key: { type: "changeSetExecution", file: 1, changeId: 1, author: 1, resourcePath: 1 } } ntoreturn:1 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:104 nreturned:0 reslen:20 0ms

Wed Mar 27 14:24:28.550 [conn1] User Assertion: 16734:Unknown index plugin 'changeSetExecution' in index { type: "changeSetExecution", file: 1, changeId: 1, author: 1, resourcePath: 1 }

Wed Mar 27 14:24:28.550 [conn1] insert wws.system.indexes keyUpdates:0 exception: Unknown index plugin 'changeSetExecution' in index { type: "changeSetExecution", file: 1, changeId: 1, author: 1, resourcePath: 1 } code:16734 locks(micros) w:138 0ms

Wed Mar 27 14:24:28.550 [conn1] run command wws.$cmd { getlasterror: 1 }

Wed Mar 27 14:24:28.550 [conn1] command wws.$cmd command: { getlasterror: 1 } ntoreturn:1 keyUpdates:0  reslen:213 0ms

Wed Mar 27 14:24:28.575 [FileAllocator] done allocating datafile /var/lib/mongodb/wws.1, size: 128MB,  took 0.03 secs

Wed Mar 27 14:24:28.575 [journal] lsn set 178520

Wed Mar 27 14:25:15.057 [DataFileSync] flushing mmaps took 1ms  for 4 files

Wed Mar 27 14:25:15.212 [TTLMonitor] query local.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:127 nreturned:0 reslen:20 0ms

Wed Mar 27 14:25:15.212 [TTLMonitor] query wws.system.indexes query: { expireAfterSeconds: { $exists: true } } ntoreturn:0 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:59 nreturned:0 reslen:20 0ms

Tried on different Linux machines as an upgrade and as a new install with/without DB to no avail.

I wonder if it's a bug in MongoDB, Mongeez, or I'm doing something wrong. It's does not seem to be affected by what exactly I'm trying to do with db (insert some data), so the later is less probable.

Any ideas would be appreciated ;)

[Aleksey Izmailov]

Oh, I think I get it.
Mongeez tries to create an index here:

 private void ensureChangeSetExecutionIndex() {
        BasicDBObject keys = new BasicDBObject();
        keys.append("type", RecordType.changeSetExecution.name());
        for (ChangeSetAttribute attribute : changeSetAttributes) {
            keys.append(attribute.name(), 1);
        }
        getMongeezCollection().ensureIndex(keys);
    }

and an index type == "changeSetExecution" which is none of supported index types in MongoDB
(http://docs.mongodb.org/manual/reference/method/db.collection.ensureIndex/).
Somehow earlier versions of Mongo were more relaxed about it and would let you create this index:

>
> version()
version: 2.2.3
null
> db.mongeez.getIndexes()
[
    {
        "v" : 1,
        "key" : {
            "_id" : 1
        },
        "ns" : "wws.mongeez",
        "name" : "_id_"
    },
    {
        "v" : 1,

        "key" : {
            "type" : "changeSetExecution",
            "file" : 1,
            "changeId" : 1,
            "author" : 1,
            "resourcePath" : 1

        },
        "ns" : "wws.mongeez",
        "name" : "type_changeSetExecution_file_1_changeId_1_author_1_resourcePath_1"
    }
]
>

And sure enough in release notes (http://docs.mongodb.org/manual/release-notes/2.4/) they say:

"Improved Validation of Index Types

Before 2.4, mongod would create an ascending scalar index (e.g. { a : 1 }) when users attempted to create an index of a type that did not exist. Creating an index of an invalid index type will generate an error in 2.4."

I guess there is a 1 liner fix ;).

Thanks

[Aleksey Izmailov]

Oops, now trying to submit a pull request I found this:

https://github.com/secondmarket/mongeez/pull/25

Someone already fixed it :)

Thanks guys

[Oleksii Iepishkin]

Aleksey,

Try 0.9.3 version. Please let me know if it works for you.

thanks!