Data Inconsistency with MongoDB using mongo-go-driver

Question

FindOneAndReplace may or may not replace the document in MongoDB. The response indicates that the operation succeeded, but looking into MongoDB it was not updated at all.

The MongoDB server version is MongoDB server version: 3.2.0 This bug is reproducible in Ubuntu 16.04 and macOS Mojave. The target host is Azure CosmosDB.

The driver version is mongo-go-driver@v0.0.17

func (s *Service) DeleteFileMetadata(ctx context.Context, req *pb.DocumentRequest) (*pb.DocumentResponse, error) {
    log.Println("[INFO] Requesting DeleteFileMetadata service")

    if ok := isStateAvailable(); !ok {
        log.Printf("[ERROR] %s\n", errServiceUnavailable.Error())
        return nil, status.Error(codes.Unavailable, errServiceUnavailable.Error())
    }

    if err := refreshMongoDBConnection(mongoDBWriter, &conf.DocumentDB.Writer); err != nil {
        log.Printf("[ERROR] %s\n", err.Error())
        return nil, status.Error(codes.Internal, err.Error())
    }

    if req == nil {
        log.Printf("[ERROR] %s\n", errNilRequest.Error())
        return nil, status.Error(codes.InvalidArgument, errNilRequest.Error())
    }

    fileMetadataParameters := req.GetFileMetadataParameters()
    if fileMetadataParameters == nil || fileMetadataParameters.GetDuid() == "" {

        log.Printf("[ERROR] %s\n", errInvalidFileMetadataParameters.Error())
        return nil, status.Error(codes.InvalidArgument, errInvalidFileMetadataParameters.Error())
    }

    if err := ValidateDUID(fileMetadataParameters.GetDuid()); err != nil {
        log.Printf("[ERROR] %s\n", err.Error())
        return nil, status.Error(codes.InvalidArgument, err.Error())
    }

    if err := ValidateUUID(fileMetadataParameters.GetUuid()); err != nil {
        log.Printf("[ERROR] %s\n", err.Error())
        return nil, status.Error(codes.InvalidArgument, err.Error())
    }

    if err := ValidateFUID(fileMetadataParameters.GetFuid()); err != nil {
        log.Printf("[ERROR] %s\n", err.Error())
        return nil, status.Error(codes.InvalidArgument, err.Error())
    }

    if fileMetadataParameters.Media > pb.FileType_VIDEO {
        return nil, status.Error(codes.InvalidArgument, errMediaType.Error())
    }

    log.Printf("[INFO] FileMetadataParameters: \n%v\n\n", pretty.Sprint(req.GetFileMetadataParameters()))

    // Get the specific lock if it already exists, else make the lock
    lock, _ := duidClientLocker.LoadOrStore(fileMetadataParameters.GetDuid(), &sync.RWMutex{})
    // Lock
    lock.(*sync.RWMutex).Lock()
    // Unlock before the function exits
    defer lock.(*sync.RWMutex).Unlock()

    collection := mongoDBWriter.Database(conf.DocumentDB.Name).Collection(conf.DocumentDB.Collection)

    // Find all MongoDB documents for the specific uuid
    filter := bson.NewDocument(
        bson.EC.String("duid", fileMetadataParameters.GetDuid()),
        bson.EC.String("uuid", fileMetadataParameters.GetUuid()),
    )
    bsonResult := collection.FindOne(context.Background(), filter)
    if bsonResult == nil {
        log.Printf("[ERROR] FindOne: %s\n", errNoDocumentFound.Error())
        return nil, status.Error(codes.InvalidArgument, errNoDocumentFound.Error())
    }
    documentToUpdate := &pb.Document{}
    if err := bsonResult.Decode(documentToUpdate); err != nil {
        log.Printf("[ERROR] Document not found, duid: %s - uuid: %s - err: %s\n",
            fileMetadataParameters.GetDuid(), fileMetadataParameters.GetUuid(), err.Error())

        return nil, status.Errorf(codes.InvalidArgument,
            "Document not found, duid: %s - uuid: %s",
            fileMetadataParameters.GetDuid(), fileMetadataParameters.GetUuid())
    }

    log.Printf("[INFO] Document to update: \n%s\n\n", pretty.Sprint(documentToUpdate))

    switch fileMetadataParameters.Media {
    case pb.FileType_FILE:
        delete(documentToUpdate.GetFileUrlsMap(), fileMetadataParameters.GetFuid())
    case pb.FileType_AUDIO:
        delete(documentToUpdate.GetAudioUrlsMap(), fileMetadataParameters.GetFuid())
    case pb.FileType_IMAGE:
        delete(documentToUpdate.GetImageUrlsMap(), fileMetadataParameters.GetFuid())
    case pb.FileType_VIDEO:
        delete(documentToUpdate.GetVideoUrlsMap(), fileMetadataParameters.GetFuid())
    default:
        return nil, status.Error(codes.InvalidArgument, errMediaType.Error())
    }
    documentToUpdate.UpdateTimestamp = time.Now().UTC().Unix()

    // option to return the the document after update
    option := findopt.ReplaceOneBundle{}
    result := collection.FindOneAndReplace(context.Background(), filter, documentToUpdate,
        option.ReturnDocument(mongoopt.After))

    // Extract the updated MongoDB document
    if result == nil {
        log.Printf("[ERROR] Extracting updated document, duid: %s - uuid: %s\n",
            documentToUpdate.GetDuid(), documentToUpdate.GetUuid())

        return nil, status.Errorf(codes.Internal,
            "Extracting updated document duid: %s - uuid: %s",
            documentToUpdate.GetDuid(), documentToUpdate.GetUuid())
    }

    document := &pb.Document{}
    if err := result.Decode(document); err != nil {
        log.Printf("[ERROR] %s\n", err.Error())
        return nil, status.Errorf(codes.Internal, err.Error())
    }

    log.Printf("[INFO] Updated document: \n%s\n\n", pretty.Sprint(document))
    log.Printf("[INFO] Success deleting file metadata in document, duid: %s - uuid: %s - fuid: %s\n",
        document.GetDuid(), document.GetUuid(), fileMetadataParameters.GetFuid())

    return &pb.DocumentResponse{
        Status:  &pb.DocumentResponse_Code{Code: uint32(codes.OK)},
        Message: codes.OK.String(),
        Data:    document,
    }, nil
}

I expect that response reflects the actual state of the data in the MongoDB server.

Let us say I want to delete a filemetadata with fuid of 05ce38e7-a29a-485f-bf20-eef3501867f0

I get this response indicating that it was deleted. The response was decoded from result := collection.FindOneAndReplace(context.Background(), filter, documentToUpdate, option.ReturnDocument(mongoopt.After))

 ImageUrlsMap:         {217706a5-2f88-4eb2-8a93-c1426c5ac944: "https://hwscdevstorage.blob.core.windows.net/images/hulkgif.png",
                        4ff30392-8ec8-45a4-ba94-5e22c4a686df: "https://hwscdevstorage.blob.core.windows.net/images/Rotating_earth_(large).gif"},
 AudioUrlsMap:         {4ff30392-8ec8-45a4-ba94-5e22c4a686df: "https://hwscdevstorage.blob.core.windows.net/audios/Milad Hosseini - Deli Asheghetam [128].mp3",
                        8fe5fea7-f683-4198-8c94-f27601a5e2d0: "https://hwscdevstorage.blob.core.windows.net/audios/Seger_Conga_CaboMexico_Tag_Acousonde_20140313_112313_8000_3_BreedingMigrating.wav"},
 VideoUrlsMap:         {4ff30392-8ec8-45a4-ba94-5e22c4a686de: "https://hwscdevstorage.blob.core.windows.net/videos/videoplayback.wmv",
                        4ff30392-8ec8-45a4-ba94-5e22c4a686df: "https://hwscdevstorage.blob.core.windows.net/videos/videoplayback.mp4",
                        e525ca9c-9813-4286-abda-8bd0eb6e94b4: "https://hwscdevstorage.blob.core.windows.net/videos/pusheen.mp4"},
 FileUrlsMap:          {13df1afa-4eee-470e-b9e2-60b2a7584994: "https://hwscdevstorage.blob.core.windows.net/videos/videoplayback.wmv",
                        4ff30392-8ec8-45a4-ba94-5e22c4a686df: "https://hwscdevstorage.blob.core.windows.net/videos/videoplayback.mp4",
                        b7a16e10-ac03-468f-9b6d-dcc684d1147f: "https://hwscdevstorage.blob.core.windows.net/videos/pusheen.mp4"},
 RecordTimestamp:      1514764800,
 CreateTimestamp:      1539831496,
 UpdateTimestamp:      1546183549,
 IsPublic:             true,
 XXX_NoUnkeyedLiteral: {},
 XXX_unrecognized:     [],
 XXX_sizecache:        0}

2018/12/30 07:25:49 [INFO] Success deleting file metadata in document, duid: 1ChHfmKs8GX7D1XVf61lwVdisWf - uuid: 0XXXXSNJG0MQJHBF4QX1EFD6Y3 - fuid: 05ce38e7-a29a-485f-bf20-eef3501867f0

But if I go to Azure CosmosDB or in my local server, it is still there. screenshot

It is very random when it happens. Sometimes it actually does the job. I do not see any race condition because I lock the document for writing. This was working fine a month ago using https://godoc.org/github.com/mongodb/mongo-go-driver/mongo — faraonc, Dec 30 '18 at 15:57
I just recently optimized my GRPC server. It runs all of my unit test from 5 minutes to less than a minute now. I am reading something about burst writes from https://dzone.com/articles/mongodb-replication-lag-and — faraonc, Dec 30 '18 at 16:12
You mention testing on a local MongoDB server as well as Cosmos. Cosmos' MongoDB API is a server implementation imitating the MongoDB API but the behaviour may differ. To clarify the scope of your question, can you confirm if you get the expected results on your local MongoDB server or if this problem is specific to Cosmos API? Also what version of the MongoDB Go Driver are you using? — Stennie, Dec 31 '18 at 06:45
@Stennie It happens for both CosmosDB and locally. I am currently using mongodb/mongo-go-driver@v0.0.17. I will try the 0.1.0 tonight. — faraonc, Dec 31 '18 at 06:54
If the problem is reproducible with both server implementations, I would suggest editing your question to reflect a single environment you want to test against. The MongoDB Go Driver isn't tested with CosmosDB, so you are likely to get more help getting your implementation working with a MongoDB server first. You should also edit your question to include the specific version of MongoDB server you are testing with. — Stennie, Dec 31 '18 at 07:00
Hm, could you please put together a [minimal, complete and verifyable example (often referred to as MCVE)](https://stackoverflow.com/help/mcve)? It is easier to find out what goes wrong with the bare minimum of code which produces the behavior you want to get rid of. — Markus W Mahlberg, Jan 01 '19 at 12:14
@MarkusWMahlberg Hi, I am still in the process of upgrading to 0.1.0. We will find out soon. — faraonc, Jan 02 '19 at 02:36

score 0 · Accepted Answer · answered Jan 02 '19 at 08:48

0

Unable to reproduce bug in MongoDB Server 3.4

answered Jan 02 '19 at 08:48

faraonc

61
1
6

Data Inconsistency with MongoDB using mongo-go-driver

1 Answers1