[SERVER-1782] Data loss after $set Created: 12/Sep/10  Updated: 12/Jul/16  Resolved: 03/Nov/10

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 1.6.2
Fix Version/s: 1.6.5

Type: Bug Priority: Major - P3
Reporter: Heiko Weible Assignee: Mathias Stearn
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows + Linux


Issue Links:
Related
is related to SERVER-1347 Using $set with large integer Closed
Operating System: ALL
Participants:

 Description   

To reproduce the bug, I run these 3 commands:

db.bugtest.insert(

{ _id: ObjectId("4c8d156f6709000000001176")}

);
db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801200000": "Test 01" }

});
db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801210000": "Test 02" }

});

I expect this object:

{ _id: ObjectId("4c8d156f6709000000001176"), "babca304b2c79a6801200000": "Test 01", "babca304b2c79a6801210000": "Test 02"}

Instead, "babca304b2c79a6801200000": "Test 01" is missing:

{ "_id" : ObjectId("4c8d156f6709000000001176"), "babca304b2c79a6801210000" : "Test 02" }

 Comments   
Comment by Mathias Stearn [ 03/Nov/10 ]

I've backported the changes to 1.7.x that fix this issue. You can build from git v1.6 branch now or wait until tomorrow's nightly.

Comment by Mathias Stearn [ 01/Nov/10 ]

I have reproduced the issue on windows. It doesn't effect linux or the 1.7.x branch on windows. I'll try to isolate the issue.

Comment by Eliot Horowitz (Inactive) [ 15/Sep/10 ]

@mathias - can you try to reproduce on windows

Comment by Ulrich Ahrendt [ 14/Sep/10 ]

I can reproduce this on Windows 7 (32bit) + 1.6.2:

> db.bugtest.drop()
true
> db.bugtest.insert(

{ _id: ObjectId("4c8d156f6709000000001176")}

);
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801200000": "Test 01" }

});
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801210000": "Test 02" }

});
> printjson( db.bugtest.findOne() )
{
"_id" : ObjectId("4c8d156f6709000000001176"),
"babca304b2c79a6801210000" : "Test 02"
}

On my Linux server (64bit) it works fine:

> db.bugtest.drop() ;
false
> db.bugtest.insert(

{ _id: ObjectId("4c8d156f6709000000001176")}

);
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801200000": "Test 01" }

});
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801210000": "Test 02" }

});
> printjson( db.bugtest.findOne() )
{
"_id" : ObjectId("4c8d156f6709000000001176"),
"babca304b2c79a6801200000" : "Test 01",
"babca304b2c79a6801210000" : "Test 02"
}

Comment by Heiko Weible [ 13/Sep/10 ]

Here is the output of the linux version.
(it's on our staging server, so there are some background processes that also hit the database)

81-89-110-253:~ # mongo
MongoDB shell version: 1.6.2
connecting to: test
> use TestDB
switched to db TestDB
> db.bugtest.drop()
true
> db.bugtest.insert(

{ _id: ObjectId("4c8d156f6709000000001176")}

);
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801200000": "Test 01" }

});
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801210000": "Test 02" }

});
> printjson( db.bugtest.findOne() )
{
"_id" : ObjectId("4c8d156f6709000000001176"),
"babca304b2c79a6801210000" : "Test 02"
}
>

Mon Sep 13 13:10:13 MongoDB starting : pid=13611 port=27017 dbpath=/var/data 32-bit

Mon Sep 13 13:10:13 db version v1.6.2, pdfile version 4.5
Mon Sep 13 13:10:13 git version: aef371ecf5d2a824f16ccdc3b745f3702165602f
Mon Sep 13 13:10:13 sys info: Linux domU-12-31-39-01-70-B4 2.6.21.7-2.fc8xen #1 SMP Fri Feb 15 12:39:36 EST 2008 i686 BOOST_LIB_VERSION=1_37
Mon Sep 13 13:10:13 [initandlisten] query: local.system.namespaces

{ name: /^local.temp./ }

Mon Sep 13 13:10:13 [initandlisten] Accessing: local for the first time
Mon Sep 13 13:10:13 [initandlisten] used cursor: 0x9b072f8
Mon Sep 13 13:10:13 [initandlisten] query local.system.namespaces reslen:36 nreturned:0 1ms
Mon Sep 13 13:10:13 [initandlisten] enter repairDatabases (to check pdfile version #)
Mon Sep 13 13:10:13 [initandlisten] MediaNetwork
Mon Sep 13 13:10:13 [initandlisten] Accessing: MediaNetwork for the first time
Mon Sep 13 13:10:13 [initandlisten] TestDB
Mon Sep 13 13:10:13 [initandlisten] Accessing: TestDB for the first time
Mon Sep 13 13:10:13 [initandlisten] done repairDatabases
Mon Sep 13 13:10:13 [initandlisten] waiting for connections on port 27017
Mon Sep 13 13:10:13 [initandlisten] fd limit hard:1024 soft:1024 max conn: 819
Mon Sep 13 13:10:13 [websvr] web admin interface listening on port 28017
Mon Sep 13 13:10:13 [websvr] fd limit hard:1024 soft:1024 max conn: 819
Mon Sep 13 13:10:24 [initandlisten] connection accepted from 127.0.0.1:59390 #1
Mon Sep 13 13:10:24 [conn1] query: admin.$cmd

{ whatsmyuri: 1 }

Mon Sep 13 13:10:24 [conn1] run command admin.$cmd

{ whatsmyuri: 1 }

Mon Sep 13 13:10:24 [conn1] query admin.$cmd ntoreturn:1 command:

{ whatsmyuri: 1 }

reslen:78 2ms
Mon Sep 13 13:10:44 [initandlisten] connection accepted from 127.0.0.1:43915 #2
Mon Sep 13 13:10:44 [conn2] query: MediaNetwork.Provider{ query:

{ EMail: "jensgarling@web.de" }

, orderby: {} }
Mon Sep 13 13:10:44 [conn2] Accessing: MediaNetwork for the first time
Mon Sep 13 13:10:45 [conn2] used cursor: 0x9b05f80
Mon Sep 13 13:10:45 [conn2] query MediaNetwork.Provider ntoreturn:1 reslen:6183 nreturned:1 51ms
Mon Sep 13 13:10:45 [conn2] query: MediaNetwork.Provider{ query:

{ UniqueName: "JensGarling" }

, orderby: {} }
Mon Sep 13 13:10:45 [conn2] used cursor: 0x9b05e50
Mon Sep 13 13:10:45 [conn2] query MediaNetwork.Provider ntoreturn:1 reslen:6183 nreturned:1 0ms
Mon Sep 13 13:10:45 [conn2] query: MediaNetwork.Provider{ query: { _id:

{ $in: [ ObjectId('a1022802b5dce6627f130000'), ObjectId('2cbff801b5dce6627f1b0000'), ObjectId('efd55902b5dce6c934000000'), ObjectId('c2019402b5dce6480d140000') ] }

}, orderby:

{ Roles: 1 }

}
Mon Sep 13 13:10:45 [conn2] running multiple plans
Mon Sep 13 13:10:45 [conn2] used cursor: 0x9b1f958
Mon Sep 13 13:10:45 [conn2] query MediaNetwork.Provider ntoreturn:2147483647 scanAndOrder reslen:7839 nreturned:3 0ms
Mon Sep 13 13:11:01 [conn1] query: TestDB.$cmd

{ drop: "bugtest" }

Mon Sep 13 13:11:01 [conn1] run command TestDB.$cmd

{ drop: "bugtest" }

Mon Sep 13 13:11:01 [conn1] Accessing: TestDB for the first time
Mon Sep 13 13:11:01 [conn1] CMD: drop TestDB.bugtest
Mon Sep 13 13:11:01 [conn1] dropCollection: TestDB.bugtest
Mon Sep 13 13:11:01 [conn1] d->nIndexes was 1
create collection TestDB.$freelist {}
dropIndexes done
Mon Sep 13 13:11:01 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ drop: "bugtest" }

reslen:137 115ms
Mon Sep 13 13:11:02 [conn2] query: MediaNetwork.LogEntry{ query: {}, orderby:

{ $natural: -1 }

}
Mon Sep 13 13:11:02 [conn2] used cursor: 0x9b08088
Mon Sep 13 13:11:02 [conn2] query MediaNetwork.LogEntry ntoreturn:25 reslen:1601 nreturned:25 14ms
Mon Sep 13 13:11:12 [conn1] New namespace: TestDB.bugtest
reset extent was:TestDB.bugtest now:TestDB.bugtest
adding _id index for collection TestDB.bugtest
Mon Sep 13 13:11:12 [conn1] building new index on

{ _id: 1 }

for TestDB.bugtest
Mon Sep 13 13:11:12 [conn1] Buildindex TestDB.bugtest idxNo:0 { name: "id", ns: "TestDB.bugtest", key:

{ _id: 1 }

}
mem info: before index start vsize: 633 resident: 36 mapped: 544
Mon Sep 13 13:11:12 [conn1] external sort root: /var/data/_tmp/esort.1284376272.1432903929/
mem info: before final sort vsize: 633 resident: 36 mapped: 544
mem info: after final sort vsize: 633 resident: 36 mapped: 544
Mon Sep 13 13:11:12 [conn1] external sort used : 0 files in 0 secs
Mon Sep 13 13:11:12 [conn1] New namespace: TestDB.bugtest.$id
reset extent was:TestDB.bugtest.$id now:TestDB.bugtest.$id
done building bottom layer, going to commit
Mon Sep 13 13:11:12 [conn1] fastBuildIndex dupsToDrop:0
Mon Sep 13 13:11:12 [conn1] done for 0 records 0secs
Mon Sep 13 13:11:12 [conn1] insert TestDB.bugtest 0ms
Mon Sep 13 13:11:12 [conn1] query: TestDB.$cmd

{ getlasterror: 1.0 }

Mon Sep 13 13:11:12 [conn1] run command TestDB.$cmd

{ getlasterror: 1.0 }

Mon Sep 13 13:11:12 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ getlasterror: 1.0 }

reslen:65 0ms
Mon Sep 13 13:11:13 [DataFileSync] flushing mmap took 16ms for 7 files
Mon Sep 13 13:11:22 [conn1] update TestDB.bugtest query:

{ _id: ObjectId('4c8d156f6709000000001176') }

update: { $set:

{ babca304b2c79a6801200000: "Test 01" }

} byid 0ms
Mon Sep 13 13:11:22 [conn1] query: TestDB.$cmd

{ getlasterror: 1.0 }

Mon Sep 13 13:11:22 [conn1] run command TestDB.$cmd

{ getlasterror: 1.0 }

Mon Sep 13 13:11:22 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ getlasterror: 1.0 }

reslen:83 0ms
Mon Sep 13 13:11:23 [conn2] query: MediaNetwork.Provider{ query:

{ _id: ObjectId('1d25e901b5dce6627f040000') }

, orderby: {} }
Mon Sep 13 13:11:23 [conn2] query MediaNetwork.Provider ntoreturn:1 idhack reslen:6183 0ms
Mon Sep 13 13:11:30 [conn1] update TestDB.bugtest query:

{ _id: ObjectId('4c8d156f6709000000001176') }

update: { $set:

{ babca304b2c79a6801210000: "Test 02" }

} byid 0ms
Mon Sep 13 13:11:30 [conn1] query: TestDB.$cmd

{ getlasterror: 1.0 }

Mon Sep 13 13:11:30 [conn1] run command TestDB.$cmd

{ getlasterror: 1.0 }

Mon Sep 13 13:11:30 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ getlasterror: 1.0 }

reslen:83 0ms
Mon Sep 13 13:11:44 [conn1] query: TestDB.bugtest{}
Mon Sep 13 13:11:44 [conn1] used cursor: 0x9b1c6f8
Mon Sep 13 13:11:44 [conn1] query TestDB.bugtest ntoreturn:1 reslen:96 nreturned:1 0ms
Mon Sep 13 13:11:44 [conn1] query: TestDB.$cmd

{ getlasterror: 1.0 }

Mon Sep 13 13:11:44 [conn1] run command TestDB.$cmd

{ getlasterror: 1.0 }

Mon Sep 13 13:11:44 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ getlasterror: 1.0 }

reslen:65 0ms

It's the 32-bit version of mongo. Have you tried a 32-bit version in your tests?
I just created a clean VMWare image with a clean, fresh install of Windows XP and a fresh install of mongodb.
The problem appears in this environment as well.

Comment by Eliot Horowitz (Inactive) [ 13/Sep/10 ]

Can you send the same info for linux?

Have tried 1.6.2 on various platforms and its working fine.

Comment by Heiko Weible [ 12/Sep/10 ]

Wow, that reply was incredibly quick!

The problem happens every single time on my machine.
I run these commands:

C:\Programme\MongoDB\bin>mongo
MongoDB shell version: 1.6.2
connecting to: test
> use TestDB
switched to db TestDB
> db.bugtest.drop()
true
> db.bugtest.insert(

{ _id: ObjectId("4c8d156f6709000000001176")}

);
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801200000": "Test 01" }

});
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801210000": "Test 02" }

});
> printjson( db.bugtest.findOne() )
{
"_id" : ObjectId("4c8d156f6709000000001176"),
"babca304b2c79a6801210000" : "Test 02"
}
>

Here's the output of mongod:

C:\Programme\MongoDB\bin>mongod -vvvvvvvv
Sun Sep 12 21:47:50 MongoDB starting : pid=8940 port=27017 dbpath=/data/db/ 32-bit

Sun Sep 12 21:47:50 db version v1.6.2, pdfile version 4.5
Sun Sep 12 21:47:50 git version: aef371ecf5d2a824f16ccdc3b745f3702165602f
Sun Sep 12 21:47:50 sys info: windows (5, 1, 2600, 2, 'Service Pack 3') BOOST_LIB_VERSION=1_35
Sun Sep 12 21:47:50 [initandlisten] query: local.system.namespaces

{ name: /^local.temp./ }

Sun Sep 12 21:47:50 [initandlisten] Accessing: local for the first time
Sun Sep 12 21:47:50 [initandlisten] used cursor: 00714298
Sun Sep 12 21:47:50 [initandlisten] query local.system.namespaces reslen:36 nreturned:0 0ms
Sun Sep 12 21:47:50 [initandlisten] enter repairDatabases (to check pdfile version #)
Sun Sep 12 21:47:50 [initandlisten] MediaNetwork
Sun Sep 12 21:47:50 [initandlisten] Accessing: MediaNetwork for the first time
Sun Sep 12 21:47:50 [initandlisten] MongoExtensionsTest
Sun Sep 12 21:47:50 [initandlisten] Accessing: MongoExtensionsTest for the first time
Sun Sep 12 21:47:50 [initandlisten] NormTests
Sun Sep 12 21:47:50 [initandlisten] Accessing: NormTests for the first time
Sun Sep 12 21:47:50 [initandlisten] test
Sun Sep 12 21:47:50 [initandlisten] Accessing: test for the first time
Sun Sep 12 21:47:50 [initandlisten] TestDatabase
Sun Sep 12 21:47:50 [initandlisten] Accessing: TestDatabase for the first time
Sun Sep 12 21:47:50 [initandlisten] TestDB
Sun Sep 12 21:47:50 [initandlisten] Accessing: TestDB for the first time
Sun Sep 12 21:47:50 [initandlisten] Timeline
Sun Sep 12 21:47:50 [initandlisten] Accessing: Timeline for the first time
Sun Sep 12 21:47:50 [initandlisten] done repairDatabases
Sun Sep 12 21:47:50 [initandlisten] waiting for connections on port 27017
Sun Sep 12 21:47:50 [websvr] web admin interface listening on port 28017
Sun Sep 12 21:48:16 [initandlisten] connection accepted from 127.0.0.1:19283 #1
Sun Sep 12 21:48:16 [conn1] query: TestDB.$cmd

{ drop: "bugtest" }

Sun Sep 12 21:48:16 [conn1] run command TestDB.$cmd

{ drop: "bugtest" }

Sun Sep 12 21:48:16 [conn1] Accessing: TestDB for the first time
Sun Sep 12 21:48:16 [conn1] CMD: drop TestDB.bugtest
Sun Sep 12 21:48:16 [conn1] dropCollection: TestDB.bugtest
Sun Sep 12 21:48:16 [conn1] d->nIndexes was 1
dropIndexes done
Sun Sep 12 21:48:16 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ drop: "bugtest" }

reslen:137 0ms
Sun Sep 12 21:48:25 [conn1] New namespace: TestDB.bugtest
reset extent was:TestDB.bugtest now:TestDB.bugtest
adding _id index for collection TestDB.bugtest
Sun Sep 12 21:48:25 [conn1] building new index on

{ _id: 1 }

for TestDB.bugtest
Sun Sep 12 21:48:25 [conn1] Buildindex TestDB.bugtest idxNo:0 { name: "id", ns: "TestDB.bugtest", key:

{ _id: 1 }

}
mem info: before index start vsize: 103 resident: 19 mapped: 80
Sun Sep 12 21:48:25 [conn1] external sort root: /data/db/_tmp/esort.1284320905.26500/
mem info: before final sort vsize: 103 resident: 19 mapped: 80
mem info: after final sort vsize: 103 resident: 19 mapped: 80
Sun Sep 12 21:48:25 [conn1] external sort used : 0 files in 0 secs
Sun Sep 12 21:48:25 [conn1] New namespace: TestDB.bugtest.$id
reset extent was:TestDB.bugtest.$id now:TestDB.bugtest.$id
done building bottom layer, going to commit
Sun Sep 12 21:48:25 [conn1] fastBuildIndex dupsToDrop:0
Sun Sep 12 21:48:25 [conn1] done for 0 records 0secs
Sun Sep 12 21:48:25 [conn1] insert TestDB.bugtest 15ms
Sun Sep 12 21:48:25 [conn1] query: TestDB.$cmd

{ getlasterror: 1.0 }

Sun Sep 12 21:48:25 [conn1] run command TestDB.$cmd

{ getlasterror: 1.0 }

Sun Sep 12 21:48:25 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ getlasterror: 1.0 }

reslen:65 0ms
Sun Sep 12 21:48:28 [conn1] update TestDB.bugtest query:

{ _id: ObjectId('4c8d156f6709000000001176') }

update: { $set:

{ babca304b2c79a6801200000: "Test 01" }

} byid 0ms
Sun Sep 12 21:48:28 [conn1] query: TestDB.$cmd

{ getlasterror: 1.0 }

Sun Sep 12 21:48:28 [conn1] run command TestDB.$cmd

{ getlasterror: 1.0 }

Sun Sep 12 21:48:28 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ getlasterror: 1.0 }

reslen:83 0ms
Sun Sep 12 21:48:30 [conn1] update TestDB.bugtest query:

{ _id: ObjectId('4c8d156f6709000000001176') }

update: { $set:

{ babca304b2c79a6801210000: "Test 02" }

} byid 0ms
Sun Sep 12 21:48:30 [conn1] query: TestDB.$cmd

{ getlasterror: 1.0 }

Sun Sep 12 21:48:30 [conn1] run command TestDB.$cmd

{ getlasterror: 1.0 }

Sun Sep 12 21:48:30 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ getlasterror: 1.0 }

reslen:83 0ms
Sun Sep 12 21:48:31 [conn1] query: TestDB.bugtest{}
Sun Sep 12 21:48:31 [conn1] used cursor: 007265F0
Sun Sep 12 21:48:31 [conn1] query TestDB.bugtest ntoreturn:1 reslen:96 nreturned:1 0ms
Sun Sep 12 21:48:31 [conn1] query: TestDB.$cmd

{ getlasterror: 1.0 }

Sun Sep 12 21:48:31 [conn1] run command TestDB.$cmd

{ getlasterror: 1.0 }

Sun Sep 12 21:48:31 [conn1] query TestDB.$cmd ntoreturn:1 command:

{ getlasterror: 1.0 }

reslen:65 0ms

The same thing is happening using the Linux version.

Comment by Eliot Horowitz (Inactive) [ 12/Sep/10 ]

I tried on a number of versions including 1.6.2 but can't reproduce
Can you send a script you used or a log file that helps reproduce if you can

> db.bugtest.drop()
false
> db.bugtest.insert(

{ _id: ObjectId("4c8d156f6709000000001176")}

);
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801200000": "Test 01" }

});
> db.bugtest.update(

{ _id: ObjectId("4c8d156f6709000000001176") }

, { $set:

{ "babca304b2c79a6801210000": "Test 02" }

});
> printjson( db.bugtest.findOne() )
{
"_id" : ObjectId("4c8d156f6709000000001176"),
"babca304b2c79a6801200000" : "Test 01",
"babca304b2c79a6801210000" : "Test 02"
}
>

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