Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-29861

Insert should report number of docs inserted or writeConcernError on error code 11602 (InterruptedDueToReplStateChange)

    • Type: Icon: Improvement Improvement
    • Resolution: Works as Designed
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Write Ops
    • Labels:
      None
    • Fully Compatible

      According to the docs and my understanding of relevant things (e.g. write concerns), I take the following to be true:

      Insert should always return the number of documents inserted ("n") that satisfied the write concern. (Where "always" implies that the original MongoDB server is still alive and reachable. If the server or network or etc. dies, then of course there's nothing left to report "n".)

      This should hold true especially when the repl set state changes because this is a common and useful event. Apps should expect the primary to go away, but they should also be guaranteed that MongoDB will cleanly terminate pending ops wrt the write concern (total server/network/etc. failure notwithstanding).

      If the aforementioned is not true, then perhaps there's no bug and https://docs.mongodb.com/manual/reference/command/insert/ just needs to be updated to reflect the real guarantees and return values. But presuming it's true, I put it to the test and found a problem: insert sometimes does not return the number of docs inserted (or a writeConcernError) on error code 11602 (InterruptedDueToReplStateChange).

      Setup:

      • MongoDB 3.4.4
      • 3-node repl set on my laptop
      • journaling filesystem (Mac HFS)
      • mgo driver @3f83fa
      • write concern: w:2, j:true

      Experiment:

      • Insert array of 100,000 docs (internally: array of 1,000 docs at a time)
      • While the insert is happening, run rs.stepDown(10,5) on the primary
      • Compare docs written ("n") from mgo vs. "nRemoved" from db.docs.remove({});

      Expect:

      Results:

      Results vary. First of all, there are 2 possible errors in the client (mgo): an EOF on the network socket (because Mongo kills connections on rs state change), or error code 11602 (InterruptedDueToReplStateChange).

      On EOF, there can't be any return write result (i.e. the documented output) because the connection is closed. I'm not sure if this a problem in mgo (not doing a final read?) or Mongo (killing the connection before sending a final write result?) Either way, the problem arises on occasion: mgo will report N docs written, but N + some random number of docs were actually written.

      The 2nd error condition is my focus. Mongo seems to gracefully kill the write op, but it does not always return the documented output. First, an example of when it works:

      {
        "n": 1000,
        "opTime": {
          "ts": {
            "$timestamp": {
              "t": 1498494120,
              "i": 5000
            }
          },
          "t": {
            "$numberLong": "202"
          }
        },
        "electionId": {
          "$oid": "7fffffff00000000000000ca"
        },
        "writeConcernError": {
          "code": 11602,
          "codeName": "InterruptedDueToReplStateChange",
          "errmsg": "operation was interrupted"
        },
        "ok": 1
      }
      

      That's a bsondump of the raw Go []byte (I hacked this into my local copy of mgo). That is what I'd expect every time; it matches the documented output (plus some other, undocumented fields).

      But sometimes the output is only:

      {
        "ok": 0,
        "errmsg": "operation was interrupted",
        "code": 11602,
        "codeName": "InterruptedDueToReplStateChange"
      }
      

      And in this particular case, mgo reports 14,000 docs written, but:

      rs0:PRIMARY> db.docs.remove({});
      WriteResult({ "nRemoved" : 14320 })
      

      The critical question: is MongoDB returning a write result with n=320? If yes, then it's a bug in mgo. I don't think this is the case because I'm writing the raw []byte from deep inside mgo before the data is returned up the call stack. Inside the mgo code here https://github.com/go-mgo/mgo/blob/v2-unstable/socket.go#L625, I added:

      fileNo++
      file := fmt.Sprintf("res-%d.bson", fileNo)
      ioutil.WriteFile(file, b, 0666)
      

      Then I bsondump the last file written, which is the doc shown above. Furthermore, this works most of the time, but sometimes it doesn't, which leads me to believe mgo is not missing a final read on the network connection; rather, Mongo is not sending a write result with n: 320 in the example above.

      If that's true, this is a show-stopping problem because it means an app cannot know, even with a write concern, how many docs were actually inserted. Moreover, the app might presume a wrong number (because it trusts the driver which doesn't know either), as in this case: 14,000 reported vs. 14,320 actual.

      Happy to provide more details, tweak my experiment, whatever. Time allowing, I'll automate the whole experiment so I can run it 1,000+ times to measure accurately the failure rate. Right now, doing it by hand, the rough estimate is 10-40% failure rate.

        1. test1.log
          72 kB
        2. test1-data.csv
          3 kB
        3. test2.log
          72 kB
        4. test2-data.csv
          3 kB

            Assignee:
            asya.kamsky@mongodb.com Asya Kamsky
            Reporter:
            dnichter Daniel Nichter
            Votes:
            6 Vote for this issue
            Watchers:
            19 Start watching this issue

              Created:
              Updated:
              Resolved: