1 Summary

I wrote a piece of golang code to insert a document by using insertOne() API, however, two field values of the values of the newly inserted document were incorrect.

 

This problem was recreated through mongosh CLI as well.

 

The problem is that a single db.arboralerts.insertOne() command produced two write operations while the second write operation was clearly unwanted? And it's the second write operation that created incorrect result. I wonder where the second write/modify operation came from. I wonder who issued the second write op that's definitely unwanted.

 

Golang Mongodb driver version: 1.8.4

MongoDB server version: 3.6.23

Topo: replica set

 

 

 

2 How to Reproduce

Steps to reproduce. If possible, please include a Short, Self Contained, Correct (Compilable), Example.

 

1) issue an insertOne()

 

rs0 [primary] attacklogger> db.arboralerts.insertOne(

...   {   

.....     id: '25e4593f-5341-4c4c-934e-2c3112c14213',

.....     customer: 'SP_SICHUANMO',

.....     details: {

.......       alerttype: 'intf_status',

.......       starttime: ISODate("2021-12-04T06:09:13.000Z"),

.......       stoptime: ISODate("2021-12-04T06:09:14.000Z"),

.......       importance: Long("2"),

.......       ongoing: true,

.......       subobject: {

.........         subobjectdos:

{ ...........           hostaddress: '195.244.198.98-lcy-SP_BWIN_GRE-TE_GIB-0000333' ...........         }

   

.........       }   

.......     },  

.....     provider: 'ifstatnotif'

.....   }   

... 

... )

{   acknowledged: true,   insertedId: ObjectId("6244bc7cf20ab78056db86d4") }

 

2) Immediately issued the following query, and got correct result

rs0 [primary] attacklogger> db.arboralerts.find({ "details.alerttype": /intf/ })

[

  {

    _id: ObjectId("6244bc7cf20ab78056db86d4"),

    id: '25e4593f-5341-4c4c-934e-2c3112c14213',

    customer: 'SP_SICHUANMO',

    details: {

      alerttype: 'intf_status',

      starttime: ISODate("2021-12-04T06:09:13.000Z"),

      stoptime: ISODate("2021-12-04T06:09:14.000Z"),

      importance: Long("2"),

      ongoing: true,

      subobject: {

        subobjectdos:

{           hostaddress: '195.244.198.98-lcy-SP_BWIN_GRE-TE_GIB-0000333'         }

   

      }   

    },  

    provider: 'ifstatnotif'

  }

]

 

3) However, continued to issue the same query in two seconds, and as shown below, the returned query result became incorrect, where 'ongoing' was changed from 'true' to 'false' and 'stoptime' got changed from ISODate("2021-12-04T06:09:14.000Z"), to ISODate("2021-12-04T07:09:13.000Z").

rs0 [primary] attacklogger> db.arboralerts.find({ "details.alerttype": /intf/ })

[

  {

    _id: ObjectId("6244bc7cf20ab78056db86d4"),

    id: '25e4593f-5341-4c4c-934e-2c3112c14213',

    customer: 'SP_SICHUANMO',

    details: {

      alerttype: 'intf_status',

      starttime: ISODate("2021-12-04T06:09:13.000Z"),

      stoptime: ISODate("2021-12-04T07:09:13.000Z"),

      importance: Long("2"),

      ongoing: false,

      subobject: {

        subobjectdos:

{           hostaddress: '195.244.198.98-lcy-SP_BWIN_GRE-TE_GIB-0000333'         }

      }

    },

    provider: 'ifstatnotif'

  }

]

 

4) I then checked oplog. It showed two ops were incurred. Why did the above db.arboralerts.insertOne() command produced two write operations while the second write operation was clearly unwanted? And it's the second write operation that created incorrect result.

 

rs0 [direct: primary] local> db.oplog.rs.find({ "wall":

{ $gte: ISODate("2022-03-30T20:24:00.000Z") }

, ns: "attacklogger.arboralerts" })

[

 

{     ts: Timestamp(\{ t: 1648671868, i: 5 }

),

    t: Long("25"),

    h: Long("-1732375391739529287"),

    v: 2,

    op: 'i',

    ns: 'attacklogger.arboralerts',

    ui: UUID("89a562fc-c301-4908-abde-5aec99a37405"),

    wall: ISODate("2022-03-30T20:24:28.977Z"),

    lsid:

{       id: UUID("a6e50a9b-de68-40d0-a6c7-8f8c6d307e3a"),       uid: Binary(Buffer.from("5e749eb669bcd1cd41cb3edec0f640c4462283c91bd22fda79c04a0c9bfba5bf", "hex"), 0)     }

,

    txnNumber: Long("3"),

    stmtId: 0,

    prevOpTime: { ts: Timestamp(

{ t: 0, i: 0 }

), t: Long("-1") },

    o: {

      _id: ObjectId("6244bc7cf20ab78056db86d4"),

      id: '25e4593f-5341-4c4c-934e-2c3112c14213',

      customer: 'SP_SICHUANMO',

      details: {

        alerttype: 'intf_status',

        starttime: ISODate("2021-12-04T06:09:13.000Z"),

        stoptime: ISODate("2021-12-04T06:09:14.000Z"),

        importance: Long("2"),

        ongoing: true,

        subobject: {

          subobjectdos:

{             hostaddress: '195.244.198.98-lcy-SP_BWIN_GRE-TE_GIB-0000333'           }

        }

      },

      provider: 'ifstatnotif'

    }

  },

  { ### <------------- this op was unexpected, I wonder who issued this op?

    ts: Timestamp({ t: 1648671878, i: 5 }),

    t: Long("25"),

    h: Long("8243783122415082031"),

    v: 2,

    op: 'u',

    ns: 'attacklogger.arboralerts',

    ui: UUID("89a562fc-c301-4908-abde-5aec99a37405"),

    o2:

{ _id: ObjectId("6244bc7cf20ab78056db86d4") }

,

    wall: ISODate("2022-03-30T20:24:38.559Z"),

    o: {

      '$v': 1,

      '$set': {

        'details.ongoing': false,           

        'details.stoptime': ISODate("2021-12-04T07:09:13.000Z")

      }

    }

  }

]

 

Additional Background

It doesn't happen with standalone mongodb server. 

It doesn't happen with insertion of a document with timestamp (for starttime/stoptime) being recent or future timestamps such as. ISODate("2025-12-04T06:09:13.000Z")