Shouldn't touchUpdatedAt use current_timestamp instead of time.Now?

[cmhakkim]

Hello!

Prerequisites

PostgreSQL database, a table and a related model with updatedAt timestamp.

Description

While debugging an issue I'm having with a transaction and create/update (likely my fault) I noticed that touchUpdatedAt uses time.Now when models are being updated. I think it's wrong, at least with PostgreSQL, because of three reasons:

1. A transaction already has a timestamp which you can get with select current_timestamp. It will return the same value during the whole transaction. That's what the newly inserted/updated rows will get if you use current_timestamp as a default or if you have some functions that automatically update the time upon modification. That time differs from time.Now.

2. There might be time difference between the application server and the database and I don't know about others' opinions but I would say the time on the database server should probably be the one to use.

3. When having a transaction one likely assumes all the updates would have the same timestamp as they were made simultaneously (although it's the transaction start time, not commit time) and with time.Now per create/update this is not the case.

So, instead of using time.Now you could simply modify the generated SQL to include current_timestamp for the created_at/updated_at row upon insertion/modification. Or, as a quick fix, you could replace the nowFunc with something like func(tx) { tx.RawQuery("select current_timestamp") ... } and use that as a value instead - at least when using transaction, because then the value could be cached in the transaction struct.

Steps to Reproduce the Problem

• Make a model
• Within a transaction:
  • Insert/update a load of entities in a loop
  • Perhaps have a small delay between database operations
  • Perhaps output the value of current_timestamp for your delight

Here's a demo:

docker-compose.yml

version: "3.7"

services:
  db:
    image: postgres:12-alpine
    environment:
      POSTGRES: touchupdatedat
      POSTGRES_USER: touchupdatedat
      POSTGRES_PASSWORD: touchupdatedat
    ports:
      - 9876:5432

database.yml

development:
  dialect: postgres
  database: touchupdatedat
  user: touchupdatedat
  password: touchupdatedat
  port: 9876
  host: 127.0.0.1
  pool: 5

go.mod

go 1.13

require (
	github.com/cockroachdb/cockroach-go v0.0.0-20190925194419-606b3d062051 // indirect
	github.com/fatih/color v1.7.0 // indirect
	github.com/gobuffalo/envy v1.7.1 // indirect
	github.com/gobuffalo/fizz v1.9.5 // indirect
	github.com/gobuffalo/genny v0.4.1 // indirect
	github.com/gobuffalo/nulls v0.1.0
	github.com/gobuffalo/pop v4.12.2+incompatible
	github.com/jackc/pgconn v1.1.0 // indirect
	github.com/mattn/go-colorable v0.1.4 // indirect
	github.com/mattn/go-isatty v0.0.10 // indirect
	golang.org/x/sync v0.0.0-20190911185100-cd5d95a43a6e // indirect
	gopkg.in/yaml.v2 v2.2.4 // indirect
)

main.go

import (
	"fmt"
	"time"

	"github.com/gobuffalo/pop"
)

type touchUpdatedAt struct {
	ID        int       `db:"id"`
	CreatedAt time.Time `db:"created_at"`
	UpdatedAt time.Time `db:"updated_at"`
	CreatedCT time.Time `db:"created_ct" rw:"r"`
	UpdatedCT time.Time `db:"updated_ct"`
}

func (touchUpdatedAt) TableName() string {
	return "touch_updated_at"
}

type currentTimestamp struct {
	Now time.Time `db:"now"`
}

const layout = "05.000000"

func main() {
	db, err := pop.Connect("development")
	if err != nil {
		panic(err)
	}

	{
		var ct currentTimestamp
		err = db.RawQuery(`select current_timestamp as now`).First(&ct)
		if err != nil {
			panic(err)
		}
		fmt.Printf("connected to db at %v\n", ct.Now.Format(layout))
	}

	err = db.RawQuery(`
		drop table if exists touch_updated_at
	`).Exec()
	if err != nil {
		panic(err)
	}

	err = db.RawQuery(`
		create table if not exists touch_updated_at (
			id bigserial primary key,
			created_at timestamptz not null,
			updated_at timestamptz not null,
			created_ct timestamptz not null default current_timestamp,
			updated_ct timestamptz not null default current_timestamp
		)
	`).Exec()
	if err != nil {
		panic(err)
	}

	err = db.RawQuery(`
		delete from touch_updated_at
	`).Exec()
	if err != nil {
		panic(err)
	}

	err = db.Transaction(func(tx *pop.Connection) (err error) {

		var ct currentTimestamp
		err = tx.RawQuery(`select current_timestamp as now`).First(&ct)
		if err != nil {
			return
		}
		fmt.Printf("transaction started at %v\ncreating: ", ct.Now.Format(layout))

		const n = 30

		rows := make([]touchUpdatedAt, n)
		i := 0
		for i < n {
			time.Sleep(50 * time.Millisecond)
			fmt.Printf(".")
			rows[i] = touchUpdatedAt{}
			err = tx.Create(&rows[i], "created_ct", "updated_ct")
			if err != nil {
				return fmt.Errorf("failed to create row %#v: %v", rows[i], err)
			}
			i++
		}

		fmt.Printf("done\nupdating: ")
		for i := range rows {
			time.Sleep(50 * time.Millisecond)
			fmt.Printf(".")
			err = tx.RawQuery(`UPDATE touch_updated_at SET updated_ct = current_timestamp WHERE id = ?`, rows[i].ID).Exec()
			if err != nil {
				return fmt.Errorf("failed to update row %#v: %v", rows[i], err)
			}
		}

		fmt.Printf("done\ncommit transaction\n")
		return
	})
	if err != nil {
		panic(err)
	}

	var rows []touchUpdatedAt
	err = db.Order(`id asc`).All(&rows)
	if err != nil {
		panic(err)
	}

	fmt.Println("id  createdAt updatedAt createdCT updatedCT")
	for _, row := range rows {
		fmt.Printf("%3d %v %v %v %v\n",
			row.ID,
			row.CreatedAt.Format(layout),
			row.UpdatedAt.Format(layout),
			row.CreatedCT.Format(layout),
			row.UpdatedCT.Format(layout))
	}
}

Simply docker-compose up, go build and go run ..

Expected Behavior

Because this happens within a transaction all the timestamps should be equal.

Actual Behavior

Timestamp values (created_at, updated_at) are all different although everything was executed inside a transaction while created_ct and updated_ct demonstrate what I expected would happen.

Info

Can be seen from go.mod. OS is macOS Catalina but it's irrelevant.