[GODRIVER-2364] A single InsertOne() API invocation causes unexpected two write operations Created: 01/Apr/22  Updated: 19/Apr/22  Resolved: 19/Apr/22

Status: Closed
Project: Go Driver
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Gary Tang Assignee: Benji Rewis (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File doublewrite.go    
Documentation Changes: Not Needed

 Description   

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")



 Comments   
Comment by Benji Rewis (Inactive) [ 19/Apr/22 ]

No worries, gctang20@gmail.com ! Happy to help out and glad you were able to find the underlying issue. Feel free to reopen this ticket or create new one if you find an issue.

Comment by Gary Tang [ 16/Apr/22 ]

Hello benji.rewis@mongodb.com, thank you for helping look into this. Your comment helped me looking into the probable background process, which I also had suspected. After I checked with a couple of other teams, it turns out there is indeed a background service that is polling this collection and updating the documents dynamically.

So it's a false alarm, not really an issue. 

I'm so sorry for the confusion, and thank you so much for looking into this and pointing to the right direction. 

Comment by Benji Rewis (Inactive) [ 12/Apr/22 ]

Hello again, gctang20@gmail.com! Very odd indeed. The first thing I’ll say is that because this extra operation you’re seeing happens in both mongosh and the Go driver, it’s unlikely that there’s strictly a bug in the Go driver here. Unless you consider retryable writes, the Go driver only sends one insert operation per call to the InsertOne method. And, that second, unexpected operation is an update that does not resemble the first insert, so it’s certainly not a retry of the original operation. I’ve modified your code slightly in doublewrite.go and can’t seem to find anything out of the ordinary (neither stoptime nor ongoing seems to change between two sequential find operations). Unrelatedly, if you'd like your documents to have named fields in the encoded BSON, you should use bson struct tags as I've done in my linked code as opposed to json ones.

Do you have any other processes running that are sending writes to your server? I see that the unexpected operation has no txnNumber (the expected insert has a txnNumber of 3), so it could be emanating from a separate process with no acquired session. It’s also interesting that this doesn’t happen on standalones; do you have a non-standard write preference or concern set on your Client? As far as only timestamps in the past being altered, the Go driver does almost no inspection of the contents of inserted documents, so I doubt that logic is coming from our side.

Apologies that I can’t be of more help here, but I have a feeling this issue is not coming from the driver. Let me know if you can provide any more info on the questions above.

Comment by Gary Tang [ 08/Apr/22 ]

Sure, here's the code:

 

func (accessor *Accessor) InsertIAlert(ctx context.Context, st *IData) error {

    coll := accessor.db.Collection(myCollection)

    if coll == nil

{         return fmt.Errorf("%w error getting collection", errDB)     }

   

 

    if _, err := coll.InsertOne(ctx, toAlert(st)); err != nil

{         return fmt.Errorf("%v failed in insertOne, %w", errDB, err)     }

   

 

    return nil 

}

 

func toAlert(st *IData) *iAlert {

    timeStamp := time.Unix(st.TimestampEvent, 0)

    return &iAlert{

        ID:       uuid.NewString(),

        Customer: st.Name,

        Provider: "in",

        Details: Details{

            AlertType:  isAlert,

            Importance: high,

            StartTime:  timeStamp,

            StopTime:   timeStamp,

            Ongoing:    strings.ToLower(st.Status) == "down", 

            Subobject: Subobject{

                Subobjectdos: Subobjectdos

{                     Hostaddress: st.Meta.TunnelDestination + "-" + st.Location + "-" + st.IfAlias,                 }

,  

            },  

        },  

    }   

}

            

type IData struct

{     MD5            string       `json:"md5"`     InterfacePath  string       `json:"interface_path"`     TimestampEvent int64        `json:"event_timestamp"`     Name          string       `json:"name"`     Location       string       `json:"node_name"`     Hostname       string       `json:"hostname"`     Devicename     string       `json:"device_name"`     DeviceID       int64        `json:"device_id"`     PortID         int64        `json:"port_id"`     IfAlias        string       `json:"if_alias"`      IfDescr        string       `json:"if_descr"`     IfIndex        string       `json:"if_index"`     IfName         string       `json:"if_name"`     Event          string       `json:"event"`     Status         string       `json:"status"`     Meta           GIntf `json:"meta"` }

       

    

type GIntf struct

{     Description       string `json:"description"`     Address           string `json:"ip"`     AddressV6         string `json:"ip_v6"`     TunnelSource      string `json:"tunnel_src"`     TunnelDestination string `json:"tunnel_dest"` }

   

 

 

type iAlert struct

{     ID       string     Customer string     Details     Provider string }

 

type Details struct

{     AlertType  string     StartTime  time.Time     StopTime   time.Time     Importance uint32     Ongoing    bool      Subobject }

 

type Subobject struct

{     Subobjectdos }

 

type Subobjectdos struct

{     Hostaddress string }
Comment by Esha Bhargava [ 04/Apr/22 ]

gctang20@gmail.com Thank you for reporting this issue. Can you please provide the code that's directly using the Go driver?

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