title: Weird now() time difference with Postgres triggers
body: <p>In a Postgres 10.10 database, I have a table <code>table1</code> , and an <code>AFTER INSERT</code> trigger on <code>table1</code> for <code>table2</code>:</p>
  
  <pre><code>CREATE TABLE table1 (
      id SERIAL PRIMARY KEY,
      -- other cols
      created_at timestamp with time zone NOT NULL,
      updated_at timestamp with time zone NOT NULL
  );
  
  CREATE UNIQUE INDEX table1_pkey ON table1(id int4_ops);
  
  CREATE TABLE table2 (
      id SERIAL PRIMARY KEY,
      table1_id integer NOT NULL REFERENCES table1(id) ON UPDATE CASCADE,
      -- other cols (not used in query)
      created_at timestamp with time zone NOT NULL,
      updated_at timestamp with time zone NOT NULL
  );
  
  CREATE UNIQUE INDEX table2_pkey ON table2(id int4_ops);
  </code></pre>
  
  <p>This query is executed on application start:</p>
  
  <pre><code>CREATE OR REPLACE FUNCTION after_insert_table1()
  RETURNS trigger AS
  $$
  BEGIN
      INSERT INTO table2 (table1_id, ..., created_at, updated_at)
      VALUES (NEW.id, ..., 'now', 'now');
  RETURN NEW;
  END;
  $$
  LANGUAGE 'plpgsql';
  
  DROP TRIGGER IF EXISTS after_insert_table1 ON "table1";
  
  CREATE TRIGGER after_insert_table1
  AFTER INSERT ON "table1"
  FOR EACH ROW 
  EXECUTE PROCEDURE after_insert_table1();      
  </code></pre>
  
  <p>I noticed some <code>created_at</code> and <code>updated_at</code> values on <code>table2</code> are different to <code>table1</code>. In fact, <code>table2</code> has mostly older values.</p>
  
  <p>Here are 10 sequential entries, which show the difference jumping around a huge amount within a few minutes:</p>
  
  <pre><code>|table1_id|table1_created            |table2_created               |diff            |
  |---------|--------------------------|-----------------------------|----------------|
  |2000     |2019-11-07 22:29:47.245+00|2019-11-07 19:51:09.727021+00|-02:38:37.517979|
  |2001     |2019-11-07 22:30:02.256+00|2019-11-07 13:18:29.45962+00 |-09:11:32.79638 |
  |2002     |2019-11-07 22:30:43.021+00|2019-11-07 13:44:12.099577+00|-08:46:30.921423|
  |2003     |2019-11-07 22:31:00.794+00|2019-11-07 19:51:09.727021+00|-02:39:51.066979|
  |2004     |2019-11-07 22:31:11.315+00|2019-11-07 13:18:29.45962+00 |-09:12:41.85538 |
  |2005     |2019-11-07 22:31:27.234+00|2019-11-07 13:44:12.099577+00|-08:47:15.134423|
  |2006     |2019-11-07 22:31:47.436+00|2019-11-07 13:18:29.45962+00 |-09:13:17.97638 |
  |2007     |2019-11-07 22:33:19.484+00|2019-11-07 17:22:48.129063+00|-05:10:31.354937|
  |2008     |2019-11-07 22:33:51.607+00|2019-11-07 19:51:09.727021+00|-02:42:41.879979|
  |2009     |2019-11-07 22:34:28.786+00|2019-11-07 13:18:29.45962+00 |-09:15:59.32638 |
  |2010     |2019-11-07 22:36:50.242+00|2019-11-07 13:18:29.45962+00 |-09:18:20.78238 |
  </code></pre>
  
  <p>Sequential entries have similar differences (mostly negative/mostly positive), and similar orders of magnitude (mostly minutes vs mostly hours) within the sequence, though there are exceptions</p>
  
  <p>Here are the top 5 largest positive differences:</p>
  
  <pre><code>|table1_id|table1_created            |table2_created               |diff            |
  |---------|--------------------------|-----------------------------|----------------|
  |1630     |2019-10-25 21:12:14.971+00|2019-10-26 00:52:09.376+00   |03:39:54.405    |
  |950      |2019-09-16 12:36:07.185+00|2019-09-16 14:07:35.504+00   |01:31:28.319    |
  |1677     |2019-10-26 22:19:12.087+00|2019-10-26 23:38:34.102+00   |01:19:22.015    |
  |58       |2018-12-08 20:11:20.306+00|2018-12-08 21:06:42.246+00   |00:55:21.94     |
  |171      |2018-12-17 22:24:57.691+00|2018-12-17 23:16:05.992+00   |00:51:08.301    |
  </code></pre>
  
  <p>Here are the top 5 largest negative differences:</p>
  
  <pre><code>|table1_id|table1_created            |table2_created               |diff            |
  |---------|--------------------------|-----------------------------|----------------|
  |1427     |2019-10-15 16:03:43.641+00|2019-10-14 17:59:41.57749+00 |-22:04:02.06351 |
  |1426     |2019-10-15 13:26:07.314+00|2019-10-14 18:00:50.930513+00|-19:25:16.383487|
  |1424     |2019-10-15 13:13:44.092+00|2019-10-14 18:00:50.930513+00|-19:12:53.161487|
  |4416     |2020-01-11 00:15:03.751+00|2020-01-10 08:43:19.668399+00|-15:31:44.082601|
  |4420     |2020-01-11 01:58:32.541+00|2020-01-10 11:04:19.288023+00|-14:54:13.252977|
  </code></pre>
  
  <p>Negative differences outnumber positive differences 10x. The database timezone is UTC. </p>
  
  <p><code>table2.table1_id</code> is a foreign key, so it should be impossible to insert before insert on <code>table1</code> completes.</p>
  
  <p><code>table1.created_at</code> is set by Sequelize, using option <code>timestamps: true</code> on the model.</p>
  
  <p>When a row is inserted into <code>table1</code>, it's done inside a transaction. From the documentation I can find, triggers are executed inside the same transaction, so I can't think of a reason for this.</p>
  
  <p>I can fix the issue by changing my trigger to use <code>NEW.created_at</code> instead of 'now', but I'm curious if anyone has any idea what the cause of this bug is?</p>
  
  <p>Here is the query used to produce the above difference tables:</p>
  
  <pre><code>SELECT
      table1.id AS table1_id,
      table1.created_at AS table1_created,
      table2.created_at AS table2_created,
      (table2.created_at - table1.created_at) AS diff
  FROM table1
  INNER JOIN table2   ON 
      table2.table1_id = table1.id AND (
          (table2.created_at - table1.created_at) &gt; '2 min' OR 
          (table1.created_at - table2.created_at) &gt; '2 min')
  ORDER BY diff;
  </code></pre>