Sometimes one record from the set does not get into the database using EF Core and TimescaleDB

Question

I faced pretty strange behavior in my tests, when only one record from the set is not added to the database and this happens from time to time, not always.

Heres logs:

Postgres:

2022-04-29 16:25:28.685 UTC [1914] LOG:  statement: DISCARD ALL
2022-04-29 16:25:28.685 UTC [1914] LOG:  statement: BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED
2022-04-29 16:25:28.686 UTC [1914] LOG:  execute <unnamed>: INSERT INTO timeeventsdata (sourceid, timestamp, eventid, jsondata, latitude, longitude, type)
    VALUES ($1, $2, $3, $4, $5, $6, $7)
2022-04-29 16:25:28.686 UTC [1914] DETAIL:  parameters: $1 = 'f5ec254d-0072-421c-b852-fedb349a98a0', $2 = '2022-01-19 16:25:28.682781+00', $3 = 'e90d7770-766a-4109-96b3-b8264ec754f9', $4 = '{"DataId":2}', $5 = '0.0001', $6 = '0.0001', $7 = 'double'
2022-04-29 16:25:28.788 UTC [1914] LOG:  statement: COMMIT

Entity Framework Core:

info: 4/29/2022 19:25:28.683 CoreEventId.ContextInitialized[10403] (Microsoft.EntityFrameworkCore.Infrastructure) 
          Entity Framework Core 6.0.1 initialized 'TimescaleContext' using provider 'Npgsql.EntityFrameworkCore.PostgreSQL:6.0.3+94d0a8eaeb9cf5af6ce55a9e59153c1a1be3244f' with options: SensitiveDataLoggingEnabled DetailedErrorsEnabled 
dbug: 4/29/2022 19:25:28.683 CoreEventId.StartedTracking[10806] (Microsoft.EntityFrameworkCore.ChangeTracking) 
          Context 'TimescaleContext' started tracking 'TimeEventData' entity with key '{SourceId: f5ec254d-0072-421c-b852-fedb349a98a0, Timestamp: 01/19/2022 16:25:28 +00:00}'.
dbug: 4/29/2022 19:25:28.683 CoreEventId.SaveChangesStarting[10004] (Microsoft.EntityFrameworkCore.Update) 
          SaveChanges starting for 'TimescaleContext'.
dbug: 4/29/2022 19:25:28.683 CoreEventId.DetectChangesStarting[10800] (Microsoft.EntityFrameworkCore.ChangeTracking) 
          DetectChanges starting for 'TimescaleContext'.
dbug: 4/29/2022 19:25:28.683 CoreEventId.DetectChangesCompleted[10801] (Microsoft.EntityFrameworkCore.ChangeTracking) 
          DetectChanges completed for 'TimescaleContext'.
dbug: 4/29/2022 19:25:28.683 RelationalEventId.ConnectionOpening[20000] (Microsoft.EntityFrameworkCore.Database.Connection) 
          Opening connection to database 'timescale-test-database' on server ''.
dbug: 4/29/2022 19:25:28.683 RelationalEventId.ConnectionOpened[20001] (Microsoft.EntityFrameworkCore.Database.Connection) 
          Opened connection to database 'timescale-test-database' on server 'tcp://localhost:5432'.
dbug: 4/29/2022 19:25:28.683 RelationalEventId.TransactionStarting[20209] (Microsoft.EntityFrameworkCore.Database.Transaction) 
          Beginning transaction with isolation level 'Unspecified'.
dbug: 4/29/2022 19:25:28.683 RelationalEventId.TransactionStarted[20200] (Microsoft.EntityFrameworkCore.Database.Transaction) 
          Began transaction with isolation level 'ReadCommitted'.
dbug: 4/29/2022 19:25:28.683 RelationalEventId.CommandCreating[20103] (Microsoft.EntityFrameworkCore.Database.Command) 
          Creating DbCommand for 'ExecuteReader'.
dbug: 4/29/2022 19:25:28.684 RelationalEventId.CommandCreated[20104] (Microsoft.EntityFrameworkCore.Database.Command) 
          Created DbCommand for 'ExecuteReader' (0ms).
dbug: 4/29/2022 19:25:28.684 RelationalEventId.CommandExecuting[20100] (Microsoft.EntityFrameworkCore.Database.Command) 
          Executing DbCommand [Parameters=[@p0='f5ec254d-0072-421c-b852-fedb349a98a0', @p1='2022-01-19T16:25:28.6827816+00:00' (DbType = DateTime), @p2='e90d7770-766a-4109-96b3-b8264ec754f9', @p3='{"DataId":2}' (Nullable = false) (DbType = Object), @p4='0.0001' (Nullable = true), @p5='0.0001' (Nullable = true), @p6='double' (Nullable = false)], CommandType='Text', CommandTimeout='30']
          INSERT INTO timeeventsdata (sourceid, timestamp, eventid, jsondata, latitude, longitude, type)
          VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6);
info: 4/29/2022 19:25:28.788 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
          Executed DbCommand (104ms) [Parameters=[@p0='f5ec254d-0072-421c-b852-fedb349a98a0', @p1='2022-01-19T16:25:28.6827816+00:00' (DbType = DateTime), @p2='e90d7770-766a-4109-96b3-b8264ec754f9', @p3='{"DataId":2}' (Nullable = false) (DbType = Object), @p4='0.0001' (Nullable = true), @p5='0.0001' (Nullable = true), @p6='double' (Nullable = false)], CommandType='Text', CommandTimeout='30']
          INSERT INTO timeeventsdata (sourceid, timestamp, eventid, jsondata, latitude, longitude, type)
          VALUES (@p0, @p1, @p2, @p3, @p4, @p5, @p6);
dbug: 4/29/2022 19:25:28.788 RelationalEventId.DataReaderDisposing[20300] (Microsoft.EntityFrameworkCore.Database.Command) 
          A data reader was disposed.
dbug: 4/29/2022 19:25:28.788 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction) 
          Committing transaction.
dbug: 4/29/2022 19:25:28.792 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction) 
          Committed transaction.
dbug: 4/29/2022 19:25:28.792 RelationalEventId.ConnectionClosing[20002] (Microsoft.EntityFrameworkCore.Database.Connection) 
          Closing connection to database 'timescale-test-database' on server 'tcp://localhost:5432'.
dbug: 4/29/2022 19:25:28.792 RelationalEventId.ConnectionClosed[20003] (Microsoft.EntityFrameworkCore.Database.Connection) 
          Closed connection to database 'timescale-test-database' on server ''.
dbug: 4/29/2022 19:25:28.792 RelationalEventId.TransactionDisposed[20204] (Microsoft.EntityFrameworkCore.Database.Transaction) 
          Disposing transaction.
dbug: 4/29/2022 19:25:28.792 CoreEventId.StateChanged[10807] (Microsoft.EntityFrameworkCore.ChangeTracking) 
          The 'TimeEventData' entity with key '{SourceId: f5ec254d-0072-421c-b852-fedb349a98a0, Timestamp: 01/19/2022 16:25:28 +00:00}' tracked by 'TimescaleContext' changed state from 'Added' to 'Unchanged'.
dbug: 4/29/2022 19:25:28.792 CoreEventId.SaveChangesCompleted[10005] (Microsoft.EntityFrameworkCore.Update) 
          SaveChanges completed for 'TimescaleContext' with 1 entities written to the database.

Heres my code, which is used to add data to test database

public async Task AddTimeEventDataToDatabaseAsync(DbModels.TimeEventData timeEventDataToSave,
       bool withCompressingChunk)
{
            await SharedResource.Semaphore.WaitAsync();

            try
            {
                await using var ctx = new TimescaleContext(DefaultOptions);

                await ctx.TimeEventsData.AddAsync(timeEventDataToSave);
                await ctx.SaveChangesAsync();

                if (withCompressingChunk)
                {
                    await ctx.CompressChunkAsync(SharedResource.HypertableName, timeEventDataToSave.Timestamp);
                }
            }
            finally
            {
                SharedResource.Semaphore.Release();
            }
}

One of tests methods which fails

[Theory]
[InlineData(1)]
[InlineData(5)]
[InlineData(10)]
[InlineData(20)]
public async Task UpdateTimeEventDataFromCompressedChunkOkTest(int itemsToCreate)
{
            // Arrange
            var sourceId = Guid.NewGuid();
            var eventId = Guid.NewGuid();

            var timeEventsDataToCompressedChunk = new List<DbModels.TimeEventData>();
            for (int i = 0; i < itemsToCreate; i++)
            {
                var timestamp = DateTimeOffset.UtcNow.AddDays(DatabaseFixture.AdjustForChunkInPast * i);

                DbModels.TimeEventData timeEventDataToCompressedChunk = DatabaseFixture.CreateTimeEventData(sourceId, eventId, timestamp, i + 1);
                timeEventsDataToCompressedChunk.Add(timeEventDataToCompressedChunk);

                await _fixture.AddTimeEventDataToDatabaseAsync(timeEventDataToCompressedChunk, true);
            }

            var updatedTimeEventsData = new List<CoreModels.TimeEventData>();
            foreach (var timeEventDataToCompressedChunk in timeEventsDataToCompressedChunk)
            {
                string updatedJsonData = "{\"test\": \"test\"}";

                var updatedTimeEventData = new CoreModels.TimeEventData(timeEventDataToCompressedChunk.SourceId,
                    timeEventDataToCompressedChunk.EventId,
                    timeEventDataToCompressedChunk.Longitude,
                    timeEventDataToCompressedChunk.Latitude,
                    timeEventDataToCompressedChunk.Timestamp,
                    timeEventDataToCompressedChunk.Type,
                    updatedJsonData);

                updatedTimeEventsData.Add(updatedTimeEventData);
            }

            // Act
            foreach (var updatedTimeEventData in updatedTimeEventsData)
            {
                await _repository.UpdateTimeEventDataAsync(updatedTimeEventData);
            }

            // Assert
            List<CoreModels.TimeEventData> storedTimeEventsDataAfterUpdating =
                await _repository.GetTimeEventsDataBySourceIdAsync(sourceId);

            DatabaseFixture.AssertTimeEventsData(storedTimeEventsDataAfterUpdating, updatedTimeEventsData);
}

ChangeTracker.DebugView.LongView after AddAsync and SaveChangesAsync show next:

TimeEventData {SourceId: f5ec254d-0072-421c-b852-fedb349a98a0, Timestamp: 01/19/2022 16:25:28 +00:00} Added
      SourceId: 'f5ec254d-0072-421c-b852-fedb349a98a0' PK
      Timestamp: '1/19/2022 4:25:28 PM +00:00' PK
      EventId: 'e90d7770-766a-4109-96b3-b8264ec754f9'
      JsonData: '{"DataId":2}'
      Latitude: 0.0001
      Longitude: 0.0001
      Type: 'double'

TimeEventData {SourceId: f5ec254d-0072-421c-b852-fedb349a98a0, Timestamp: 01/19/2022 16:25:28 +00:00} Unchanged
      SourceId: 'f5ec254d-0072-421c-b852-fedb349a98a0' PK
      Timestamp: '1/19/2022 4:25:28 PM +00:00' PK
      EventId: 'e90d7770-766a-4109-96b3-b8264ec754f9'
      JsonData: '{"DataId":2}'
      Latitude: 0.0001
      Longitude: 0.0001
      Type: 'double'

But entity doesn't get into database and test fails on trying update:

TimeEventsStorage.Tests.Database.TimeEventDataRepositoryTests.UpdateTimeEventDataFromCompressedChunkOkTest(itemsToCreate: 10)
   Source: TimeEventDataRepositoryTests.cs line 909
   Duration: 3 sec

  Message: 
    TimeEventsStorage.Core.Exceptions.TimeEventsStorageNotFoundException : Time event data with [SourceId: f5ec254d-0072-421c-b852-fedb349a98a0 and Timestamp: 1/19/2022 4:25:28 PM +00:00] is not exist!

  Stack Trace: 
    TimeEventDataRepository.UpdateTimeEventDataAsync(TimeEventData updatedTimeEventData) line 281
    TimeEventDataRepositoryTests.UpdateTimeEventDataFromCompressedChunkOkTest(Int32 itemsToCreate) line 945
    --- End of stack trace from previous location ---

I set breakpoints after adding data before updating, and there really is a case where 5 records should have been recorded, but 4 in the database...

The most interesting thing is that there are 5 chunks, i.e. perhaps the record should have been recorded, a chunk was already created for it, but there is no record itself.

I use next packages:

"Microsoft.EntityFrameworkCore" Version="6.0.1"

"Npgsql.EntityFrameworkCore.PostgreSQL" Version="6.0.3"

Heres my docker-compose.yml for database.

  timescaledb:
    image: "timescale/timescaledb:latest-pg14"
    container_name: timescaledb
    ports:
      - 5432:5432
    restart: always
    volumes:
      - ./timescaledb-data:/var/lib/postgresql/data/
    command: >
     postgres
       -c logging_collector=on
       -c log_statement=all
    environment:
      POSTGRES_USER: "postgres"
      POSTGRES_PASSWORD: "postgres"

What is wrong? Is that a bug in EF Core or TimescaleDB or in my code?

UPDATE 10.05.2022:

Added minimum code to reproduce this bug. Reproduced bug only one time today...

I was thinking, maybe problem was related to TRUNCATE function, which is used to clean up hypertable after every test, so I added another method to cleaning up hypertable with calling drop_chunks timescaledb function too.

@jjanes Yeah, but record isn't in db at all. More interesting thing, what TimescaleDB created chunk for disappeared record, which means, what data was inserted or tried to be inserted. — Artur Safiullin, Apr 30 '22 at 15:40

Artur Safiullin · Answer 1 · 2022-05-11T01:05:41.383

Answering to @louis-ricci. I was wrong when I wrote that there were no other errors besides those that occur when trying to update or delete an entity, but they cannot find the entity itself in the database. So, in one of the tests, I met a deadlock when trying to clear the hypertable after the test with this method.

Here 1 of 36 tests fall just because one of n entities wasn't in hypertable. No deadlock occured.

And here I set breakpoint and checked database.

So here answers on your guesses.

Here is the implementation of the repository methods, as you can see, I work with models through the DbSet<TimeEventData> interface, which means that EF Core generates sql itself and creates a transaction to insert data into the hypertable.
I configured the table via IEntityTypeConfiguration<TimeEventData> here using Fluent API.
All requests that EF Core sends to database are logged using ITestOutputHelper and DbContext settings in a certain way here and such method as EnableDetailedErrors() and EnableSensitiveDataLogging().

In my updated code, which is not presented in the repository, I made all SQL queries in transaction blocks (now SaveChangesAsync is only one save point of the transaction), and I also use the TimescaleDB drop_chunks function here, instead of TRUNCATE TABLE to clear the data from hypertable. After these changes, my tests stopped falling and have not been falling for three days.

Therefore, I believe that most likely there is some kind of error associated with calling the TRUNCATE TABLE function, which in a very rare case leads to a deadlock.

However, I still don't understand the moment when an data which is second or penultimate in the collection is not written to the hypertable. And all the logs say that the data should have been recorded, even a chunk was created for it...

Therefore, I will leave this repository to someone, who wants to understand what the reason is.

Louis Ricci · Answer 2 · 2022-05-10T17:54:49.727

1

edit here's a few more guesses

Your test code uses "await _fixture.Add..." (for the insert) then "_repository.Update..." (for the update) then "await _repository.Get..." (for the assert). Is there some difference between _fixture and _repository that could be causing the problem?
The model seems to have a composite primary key (SourceId, Timestamp). EF doesn't handle composite keys by default (using the model [Key] annotation), you have to use the Fluent API. Maybe this setup (or lack of setup) is causing the random failures.
this doesn't seem to be the case since everything is being logged/traced Your "AddTimeEventDataToDatabaseAsync" has a Try ... Finally block with no Catch. If you want to figure out why your code is randomly, some of the time, failing you should add a Catch and log/throw the (hopefully) enlightening exception.

edited May 10 '22 at 17:54

answered May 10 '22 at 14:29

Louis Ricci

20,804
5
48
62

If `AddTimeEventDataToDatabaseAsync` or other method throws exception I'll see it in test output. I also log all EF Core calls to test output and Postgres to file. As I wrote above, tests fail not because some exception was throwed, but 1 of n records doesn't get to db. – Artur Safiullin May 10 '22 at 14:55
@ArturSafiullin - I added a couple more guesses as to the problem. Is the record that fails to save always the first or always the last record , or is that random too? – Louis Ricci May 10 '22 at 17:55
Usually the penultimate, sometimes the second. I have not seen that the first or the last one was not added. In the logs on the screenshots above, the second one was not added. There is one oddity that if at least one test falls, then several more are more likely to fall. But in all cases, the error is due to the fact that one of the n records was not added, so it could not be updated or deleted. At the moment I can't reproduce the error to throw off the full test logs. – Artur Safiullin May 10 '22 at 18:51

Sometimes one record from the set does not get into the database using EF Core and TimescaleDB

2 Answers2