updatedAt is set before createdAt date and time when creating records

[pbolduc]

Describe the bug

When creating items, I have noticed the updatedAt property is slightly before the createdAt. I see there are a few factors that may contribute to this.

1. The database defaults these columns to CURRENT_TIMESTAMP which will set them to the database server's time
2. The Timestamps mixin has before insert/update handlers that set the corresponding fields to the micro service server's time
3. When deploying on a real kubernetes cluster with multiple nodes, there can be time drift between servers.

select 'expected' as status, count(*) from "object" where "createdAt" <= "updatedAt"
union
select 'unexpected' as status, count(*) from "object" where "createdAt" > "updatedAt"

select "createdAt", "updatedAt" from "object"  where "createdAt" > "updatedAt" order by "createdAt" LIMIT 5

Version Number

To Reproduce

Steps to reproduce the behavior:

1. Go to '...'
2. Click on '....'
3. Scroll down to '....'
4. See error

Expected behavior

The created and updated timestamps should have a consistent source on a single record so that createdAt <= updatedAt is always true. If using the mixin, be sure get the date once and then assign to the fields, avoid getting the current date twice or the updated date may be slightly larger than the created.

Bad

    async $beforeInsert(queryContext) {
      await super.$beforeInsert(queryContext);
      this.createdAt = new Date().toISOString();
      this.updatedAt = new Date().toISOString();
    }

Better

    async $beforeInsert(queryContext) {
      await super.$beforeInsert(queryContext);
      this.createdAt = this.updatedAt = new Date().toISOString();
    }

Screenshots

Desktop (please complete the following information):

• OS: [e.g. iOS]
• Browser [e.g. chrome, safari]
• Version [e.g. 22]

Smartphone (please complete the following information):

• Device: [e.g. iPhone6]
• OS: [e.g. iOS8.1]
• Browser [e.g. stock browser, safari]
• Version [e.g. 22]

Additional context

[jujaga]

Quickly taking a look at the mixin, it looks like $beforeInsert only writes to createdAt, and $beforeUpdate only writes to updatedAt. Both should not get triggered at the exact same time. If this is due to machine time drift, there isn't going to be much we can do about this. Theoretically we could have the mixin do a read on the original data and do another temporal check, but that would be introducing a non-insignificant performance penalty as it'd be needing to read the database (perhaps multiple times depending on the transaction) before performing an update operation.

CreatedAt should only ever be written once in the original insert operation; it shouldn't be getting edited at any point in the future; all other timestamp related changes should be changing updatedAt only when there are update events to that record.

[pbolduc]

I'd suggest since the updatedAt is NOT NULL, just assign it in the service and dont let the database default it. I am not sure why updatedAt is not null with a default, but the updatedBy can be nullable.

What is happening now:

1. Mixin sets created date to pod's node time X
2. Insert occurs, updatedAt is null and not specified in the INSERT call and the database defaults it to the database's node's time Y.

Logically, if the times were exactly sync'ed, the createdAt would have a value of X and the updatedAt a value of Y where Y is slightly ahead of the created at. It would be illogical that the updatedAt should be after the createdAt cause the record was never updated. This is the point of these fields.

For created records (never been updated), if updatedAt is NOT NULL, it should have the exact same time as createdAt, or allow updatedAt to be nullable and created records would only have a createdAt and updatedAt would be null. What is the point of the audit fields if you cant trust the values to be consistent?

[pbolduc]

If this is due to machine time drift

Can you explain why else the values would be different?

[pbolduc]

Theoretically we could have the mixin do a read on the original data and do another temporal check

why? on insert set the values for createdAt AND updatedAt. On update, set updatedAt. Simple.

[jujaga]

why? on insert set the values for createdAt AND updatedAt. On update, set updatedAt. Simple.

This is not something that is part of the database design, and not something we will be doing. The DB design is supposed to only ever write to createdAt once > this record would indicate when the record first came into existence. At this point in time, updatedAt needs to be null, as this was a creation operation, NOT an update operation. Subsequent update operations that would change a subset of that row's values would write to the updatedAt column as well. If it is the first update, it would change from null, to some time value. If there's an existing time value, it's overwritten.

That being said, there is definitely something wrong going on at the moment, as the above behavior is not what is actually happening at this time, and appears to be affecting all tables. We did a quick debug trace of just a createObject operation, and the $beforeUpdate mixin function was never ran (it shouldn't be anyways as this is just creating a new object). Something else is the root cause.

[pbolduc]

I checked with the administrator of the OpenShift environment, see the devops-operations channel on rocket chat. They indicated the max error in time in the nodes currently is 0.5 - 0.6 seconds.

[pbolduc]

why? on insert set the values for createdAt AND updatedAt. On update, set updatedAt. Simple.

The DB design is supposed to only ever write to createdAt once > this record would indicate when the record first came into existence. At this point in time, updatedAt needs to be null

It is NULL in the Javascript model, but because knex does not genreate an INSERT statement with all the null columns, the INSERT SQL generated does not include the column. Because you default it here to the current date and time. This causes the table defintion to be:

CREATE TABLE IF NOT EXISTS public.object
(
    id uuid NOT NULL,
    path character varying(1024) COLLATE pg_catalog."default" NOT NULL,
    public boolean NOT NULL DEFAULT false,
    active boolean NOT NULL DEFAULT true,
    "createdBy" character varying(255) COLLATE pg_catalog."default" DEFAULT '00000000-0000-0000-0000-000000000000'::character varying,
    "createdAt" timestamp with time zone DEFAULT CURRENT_TIMESTAMP,
    "updatedBy" character varying(255) COLLATE pg_catalog."default",
    "updatedAt" timestamp with time zone DEFAULT CURRENT_TIMESTAMP,
    "bucketId" uuid,
    CONSTRAINT object_pkey PRIMARY KEY (id),
    CONSTRAINT object_bucketid_foreign FOREIGN KEY ("bucketId")
        REFERENCES public.bucket ("bucketId") MATCH SIMPLE
        ON UPDATE CASCADE
        ON DELETE CASCADE
)

Since the column has a DEFAULT CURRENT_TIMESTAMP, the database automatically sets the value to the database server's time on insert.

I tried to be helpful but it is clear you dont understand the issue. This is really not a critical issue, more of an annoyance. I am fine with you closing this issue as "wont fix".

[jujaga]

Looks like we need to change out the updatedAt CURRENT_TIMESTAMP to be default to null. This may have been an underlying bug from the extremely early days. Will chat over with team on Monday and evaluate potential next steps for remediation.

[pbolduc]

I have seen bugs like this before. I worked on another project where a record is added with an active date from the API server. On the database server, there was a view that returned all the active records. Due to the API server vs the database server time, in testing when the tester added a record and the api tried to query it back right way, it always came back as not found. The API server's time was slightly faster than the database, so when the record is added being active "now", according to the database, it wasn't active quite yet. So you have to be careful in these cases.

[jujaga]

Addressed in #168 - insert operations only write createdAt date now; updatedAt should be null until there is an update operation to that row.