[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: |
|
| Documentation Changes: | Not Needed |
| Description |
1 SummaryI 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.23Topo: replica set
2 How to ReproduceSteps 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 BackgroundIt 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 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? |