Issue with PostgreSQL: 'now' keeps returning same old value

Question

I have an old web app, the relevant current stack is: Java 8, Tomcat 7, Apache Commons DBCP 2.1, Spring 2.5 (for transactions), iBatis, PostgreSQL 9.2 with postgresql-9.4.1208.jar

Part of the code inserts new records in incidents table, where the field begin_date (timestamp(3) with time zone) is a creation timestamp, filled with now:

    insert into incidents
    (...., begin_date,    )
    values
    (..., 'now' ....)

All this is executed via iBatis, transactions managed programatically via Spring, connections acquired via DBCP pool. The webapp (actually a pair, clientside and backoffice, who share most of the code and jars) has been working since years.

Lately, perhaps after some libraries updates and reorganization (nothing important, it seemed), I've been experiencing (intermitent, hard to reproduce) some nasty problem: now seems to freeze, and it begins returning the same "old" value. Then, many records appear with the same creation timestamp, hours or days ago:

db=# select 'now'::timestamptz;
        timestamp
-------------------------
 2016-06-10 21:59:03.637+00

db=#  select rid,begin_date from incidents order by rid desc limit 6;
  rid  |         begin_date
-------+----------------------------
 85059 | 2016-06-08 00:11:06.503+00
 85058 | 2016-06-08 00:11:06.503+00
 85057 | 2016-06-08 00:11:06.503+00
 85056 | 2016-06-08 00:11:06.503+00
 85055 | 2016-06-08 00:11:06.503+00
 85054 | 2016-06-08 00:11:06.503+00

(All the above records were actually created minutes before 2016-06-10 21:50)

How can this happen? It might be some problem related with transactions and/or connection pooling, but I can't figure out what. I know that 'now()' is an alias of transaction_timestamp(), it returns the time at the start of the transaction. This would suggest that a transaction was not properly closed, and the records inserts above were written (unintentionally) in a single long transaction. But this looks rather incredible to me.

First, I can insert a new record (via the webapp) and, using a psql console, I see that it has been written with the same begin_date (if the transaction were uncommited, I should not see the new record, I have the default serialization level).

Furthermore, the pg_stat_activity view only shows idle connections.

Any cues?

Answer 1

There's the constant (special timestamp value) 'now'.
And there's the function now().

The fact that you are mixing them freely suggests that you are unaware of the all-important difference. The manual:

Special Values

PostgreSQL supports several special date/time input values for convenience, as shown in Table 8-13. The values infinity and -infinity are specially represented inside the system and will be displayed unchanged; but the others are simply notational shorthands that will be converted to ordinary date/time values when read. (In particular, now and related strings are converted to a specific time value as soon as they are read.) All of these values need to be enclosed in single quotes when used as constants in SQL commands.

Bold emphasis mine.

And (like you mentioned yourself already), but quoting the manual:

now() is a traditional PostgreSQL equivalent to transaction_timestamp().

And:

transaction_timestamp() is equivalent to CURRENT_TIMESTAMP

There is more, read the whole chapter.

Now (no pun intended), since you are using the special value instead of the function, you get a different (unexpected for you) behavior with prepared statements.

Consider this demo:

test=# BEGIN;
BEGIN
test=# PREPARE foo AS
test-# SELECT timestamptz 'now' AS now_constant, now() AS now_function;
PREPARE
test=# EXECUTE foo;
         now_constant          |         now_function
-------------------------------+-------------------------------
 2016-06-11 03:09:05.622783+02 | 2016-06-11 03:09:05.622783+02 -- identical
(1 row)

test=# commit;
COMMIT
test=# EXECUTE foo;
         now_constant          |         now_function
-------------------------------+------------------------------
 2016-06-11 03:09:05.622783+02 | 2016-06-11 03:10:00.92488+02  -- different!
(1 row)

While you run both in the same transaction, 'now' and now() produce the same value. But a prepared statement is designed to last for the duration of your session (possibly across many transactions). Next time you execute the prepared statement, you'll see the difference.

In other words: 'now' implements "early binding", while now() implements "late binding".

You may have introduced prepared statements and / or connection pooling (which can preserve prepared statements for a longer period of time) - both generally good ideas. But the hidden problem in your INSERT now starts kicking.

The "idle connections" you see indicate as much: connections stay open, preserving prepared statements.

In short: Use now().

Alternatively, set the column default of begin_date to now() (not 'now'!) and don't mention the column in the INSERT. Your "creation timestamp" is saved automatically.