Collection sub-document not updating

Dominic_Grekov · 2024-05-05T14:02:09.447Z

I have a really odd case that I cannot find the source.

I had a replication set in production with version 4.0 and the C# driver 2.11.6
I migrated to version 7.0.5 and the C# driver 2.17.1

I have a collection (called Calendars) with many sub-documents. Here is the Calendar document
public class Calendar : IRepresentAnEntity
{
[BsonId(IdGenerator = typeof(CombGuidGenerator))]
public Guid Id { get; set; }
public Guid CompanyId { get; set; }
public int UTCOffset { get; set; }
public List Schedules { get; set; }
public List Groups { get; set; }
public List Services { get; set; }
public List Courses { get; set; }
public List Rooms { get; set; }
public List Events { get; set; }
public List Pictures { get; set; }
public List Questions { get; set; }

My issue is that when I update a Schedule it does not get persisted. I can add and remove without any problem, but cannot update an existing one. The update also works for any other sub-document except Schedule. This normally sounds like a coding error, but this has been working fine for years before I did the migration.

Another point is that it works well in dev with the same mongo db version and driver but it is a standalone.

Below is the code that is called with the update:
public void UpdateSchedules(Calendar calendar)
{
var query = Builders.Filter.Eq(x => x.CompanyId, calendar.CompanyId);
MongoDb.Calendars.UpdateOne(query, Builders.Update.Set(x => x.Schedules, calendar.Schedules), new UpdateOptions { IsUpsert = false });
}

After updating the profiling level, we can also see the write command in the log file.
e":{“clusterTime”:{“$timestamp”:{“t”:1714748960,“i”:2}},“signature”:{“hash”:{“$binary”:{“base64”:“yrxm+AfiHlyxQ7uak60Bat4krWw=”,“subType”:“0”}},“keyId”:7332545708794314759}},“$db”:“local”},“planSummary”:“COLLSCAN”,“cursorid”:7981273380601913824,“keysExamined”:0,“docsExamined”:1,“nBatches”:1,“numYields”:2,“nreturned”:1,“queryHash”:“ED62D921”,“planCacheKey”:“ED62D921”,“queryFramework”:“classic”,“reslen”:2673,“locks”:{“FeatureCompatibilityVersion”:{“acquireCount”:{“r”:3}},“Global”:{“acquireCount”:{“r”:3}}},“readConcern”:{“level”:“local”,“afterClusterTime”:{“$timestamp”:{“t”:0,“i”:1}},“provenance”:“clientSupplied”},“storage”:{},“cpuNanos”:238321,“remote”:“10.0.21.206:52656”,“protocol”:“op_msg”,“durationMillis”:0}}
{“t”:{“$date”:“2024-05-03T16:01:03.739+00:00”},“s”:“I”, “c”:“WRITE”, “id”:51803, “ctx”:“conn125”,“msg”:“Slow query”,“attr”:{“type”:“update”,“ns”:“bookings.calendars”,“command”:{“q”:{“CompanyId”:{“$binary”:{“base64”:“yDXw3vO4k0m406raAS1/dQ==”,“subType”:“3”}}},“u”:{“$set”:{“Schedules”:[{“_id”:{“$binary”:{“base64”:“SrwsqkMzjkKeiVp/cOxYFw==”,“subType”:“3”}},“GroupId”:{“$binary”:{“base64”:“41giQtdRTEWHMTFF4dcMww==”,“subType”:“3”}},“GroupName”:“Chris Dion”,“CourseId”:null,“CourseName”:“”,“RoomId”:null,“RoomName”:“”,“EventId”:null,“EventName”:“”,“Name”:“Chris - Wed”,“Type”:0,“DaysOfWeek”:4,“StartDay”:{“$date”:“2020-01-22T05:00:00.000Z”},“EndDay”:{“$date”:“2020-01-22T05:00:00.000Z”},“StartTime”:{“$date”:“2020-01-01T02:00:00.000Z”},“EndTime”:{“$date”:“2020-01-01T04:59:00.000Z”},“Registered”:0,“InsId”:null,“Ins”:null,“SubId”:null,“Sub”:null,“TimeZone”:null,“UTCOffset”:null,“Off”:false,“Archived”:false,“SyncId”:null},{“_id”:{“$binary”:{“base64”:“gWoXIMh5Y0KUah5KcR1C5A==”,“subType”:“3”}},“GroupId”:{“$binary”:{“base64”:“41giQtdRTEWHMTFF4dcMww==”,“subType”:“3”}},“GroupName”:“Chris Dion”,“CourseId”:null,“CourseName”:“”,“RoomId”:null,“RoomName”:“”,“EventId”:null,“EventName”:“”,“Name”:“Chris - Thurs 22”,“Type”:0,“DaysOfWeek”:8,“StartDay”:{“$date”:“2021-01-23T05:00:00.000Z”},“EndDay”:{“$date”:“2021-01-23T05:00:00.000Z”},“StartTime”:{“$date”:“2024-05-03T05:00:00.000Z”},“EndTime”:{“$date”:“2024-05-04T04:59:00.000Z”},“Registered”:0,“InsId”:null,“Ins”:null,“SubId”:null,“Sub”:null,“TimeZone”:null,“UTCOffset”:-5,“Off”:false,“Archived”:false,“SyncId”:null},{“_id”:{“$binary”:{“base64”:“HT5du1zPIkapmEV3qDZrRA==”,“subType”:“3”}},“GroupId”:{“$binary”:{“base64”:“gR2Sg466bE+fLAkeSiT7ug==”,“subType”:“3”}},“GroupName”:“Dennis”,“CourseId”:null,“CourseName”:“”,“RoomId”:null,“RoomName”:“”,“EventId”:null,“EventName”:“”,“Name”:“Dennis - Reg hours”,“Type”:2,“DaysOfWeek”:127,“StartDay”:{“$date”:“2020-07-07T05:00:00.000Z”},“EndDay”:{“$date”:“2020-07-31T05:00:00.000Z”},“StartTime”:{“$date”:“2020-07-07T13:00:00.000Z”},“EndTime”:{“$date”:“2020-07-08T02:00:00.000Z”},“Registered”:0,“InsId”:null,“Ins”:null,“SubId”:null,“Sub”:null,“TimeZone”:null,“UTCOffset”:null,“Off”:false,“Archived”:false,“SyncId”:null},{“_id”:{“$binary”:{“base64”:“Thxpr9MhyUWOd8UDWRXZfQ==”,“subType”:“3”}},“ScheduleGroupId”:{“$binary”:{“base64”:“0f3MigIRiECiVKvr1XaMQg==”,“subType”:“3”}},“GroupName”:“Erin”,“CourseId”:null,“CourseName”:“”,“RoomId”:null,“RoomName”:“”,“EventId”:null,“EventName”:“”,“Name”:“Erin - Regular Hours New”,“Type”:2,“DaysOfWeek”:127,“StartDay”:{“$date”:“2024-04-14T05:00:00.000Z”},“EndDay”:{“$date”:“2024-04-22T05:00:00.000Z”},“StartTime”:{“$date”:“2024-04-19T15:00:00.000Z”},“EndTime”:{“$date”:“2024-04-20T02:00:00.000Z”},“Registered”:0,“InsId”:null,“Ins”:null,“SubId”:null,“Sub”:null,“TimeZone”:null,“UTCOffset”:-5,“Off”:false,“Archived”:false,“SyncId”:null}]}},“multi”:false,“upsert”:false},“planSummary”:“IXSCAN { CompanyId: 1 }”,“totalOplogSlotDurationMicros”:146,“keysExamined”:1,“docsExamined”:1,“nMatched”:1,“nModified”:1,“nUpserted”:0,“keysInserted”:0,“keysDeleted”:0,“numYields”:0,“locks”:{“ParallelBatchWriterMode”:{“acquireCount”:{“r”:1}},“FeatureCompatibilityVersion”:{“acquireCount”:{“w”:1}},“ReplicationStateTransition”:{“acquireCount”:{“w”:1}},“Global”:{“acquireCount”:{“w”:1}},“Database”:{“acquireCount”:{“w”:1}},“Collection”:{“acquireCount”:{“w”:1}}},“flowControl”:{“acquireCount”:1},“readConcern”:{“level”:“local”,“provenance”:“implicitDefault”},“storage”:{},“cpuNanos”:665820,“remote”:“10.0.0.27:57445”,“durationMillis”:0}}

The replication is healthy with a primary and two secondaries. If I do an update from the console it is saving and replicating to secondaries.

Somehow, it seems that an Update on that collection / document from the code does not work in that replication configuration. Again, everything was also working fine before migrating to 7.0.5 with the 2.17.1 driver.

Any ideas?
Anything else I should be looking at?

Thanks!

James_Kovacs · 2024-05-08T23:15:13.898Z

Hi, @Dominic_Grekov,

Welcome to the MongoDB Community Forums. I understand that you updated your application from an earlier driver and server version to a later one and your UpdateSchedules method is no longer behaving as expected.

Examining the provided server log line, the update found one matching document and modified it.

“keysExamined”:1,“docsExamined”:1,“nMatched”:1,“nModified”:1,“nUpserted”:0,

As far as the server is concerned, the operation was completed successfully. When you are verifying that the document was updated, are you connecting to the primary node to query it? There is going to be a replication delay to secondaries, which can range from milliseconds to longer depending on how heavily loaded the cluster is.

I will note that the matching document was found using a COLLSCAN, which means that you don’t have an index defined on CompanyId. I would recommend defining an index if finding and updating calendars by CompanyId is a common operation in your application.

Hope that helps.

Sincerely,
James

Dominic_Grekov · 2024-05-09T22:50:45.701Z

Hi James,

Thanks for the looking into this.

Yes, I am connected to the primary. I do the update from the application, I see the log, I then retrieve the document and any change to that sub-document is not persisted.

Conversely, if I update from the primary and reload the page in the application I see that the sub-document has been updated.

Any ideas or tests I can run?

As for the indexes, I have one on the CompanyId. Why would a COLLSCAN be executed??

db.calendars.getIndexes()
[
{ v: 2, key: { _id: 1 }, name: ‘id’ },
{ v: 2, key: { CompanyId: 1 }, name: ‘CompanyIdx’ }
]