BUG #14322: Possible inconsistent behavior with timestamp_to_str()

The following bug has been logged on the website:

Bug reference: 14322
Logged by: Keith Fiske
Email address: keith(at)keithf4(dot)com
PostgreSQL version: 9.5.4
Operating system: Ubuntu 16.04
Description:

It seems when I call timestamp_to_str() on a non-null value then call it on
a null value in the same statement, it returns the previous non-null value.
I've included the code and debug lines from where I encountered this when
testing my app.

I use SPI to retrieve the values:

appendStringInfo(&buf, "SELECT sub_min::timestamptz, sub_max::timestamptz
FROM %s.check_subpartition_limits('%s.%s', 'time')", partman_schema,
parent_schemaname, parent_tablename);
ret = SPI_execute(buf.data, true, 1);
sub_timestamp_min = DatumGetTimestampTz(SPI_getbinval(SPI_tuptable->vals[0],
SPI_tuptable->tupdesc, 1, &sub_timestamp_min_isnull));
sub_timestamp_max = DatumGetTimestampTz(SPI_getbinval(SPI_tuptable->vals[0],
SPI_tuptable->tupdesc, 2, &sub_timestamp_max_isnull));

Querying the table normally, can see it returns nulls:

keith(at)keith=# select * from
partman.check_subpartition_limits('partman_test.time_taptest_table',
'time');
sub_min | sub_max
---------+---------
«NULL» | «NULL»
(1 row)

elog(DEBUG1, "sub_timestamp_min: %s, sub_timestamp_min_isnull: %d,
sub_timestamp_max: %ld, sub_timestamp_max_isnull: %d"
, timestamptz_to_str(sub_timestamp_min), sub_timestamp_min_isnull,
sub_timestamp_max, sub_timestamp_max_isnull);
elog(DEBUG1, "run_maint before loop: current_partition_timestamp: %s,
premade_count: %d, sub_timestamp_min: %s, sub_timestamp_max: %s"
, timestamptz_to_str(current_partition_timestamp), premade_count,
timestamptz_to_str(sub_timestamp_min),
timestamptz_to_str(sub_timestamp_max));
elog(DEBUG1, "run_maint before loop2: premade_count: %d, sub_timestamp_min:
%s, sub_timestamp_max: %s"
, premade_count, timestamptz_to_str(sub_timestamp_min),
timestamptz_to_str(sub_timestamp_max));

Can see the initial debug line, things are normal. Next line
current_partition_timestamp is returned along with the sub values which are
then equal to current_partition_timestamp. Removing
current_partition_timestamp from the same statement in the following line
things return as expected.

2016-09-09 17:38:15 EDT [] [9828]: [29-1] user=,db=,e=00000 DEBUG:
sub_timestamp_min: 1999-12-31 19:00:00-05, sub_timestamp_min_isnull: 1,
sub_timestamp_max: 0, sub_timestamp_max_isnull: 1
2016-09-09 17:38:15 EDT [] [9828]: [30-1] user=,db=,e=00000 DEBUG:
run_maint before loop: current_partition_timestamp: 2016-09-11 00:00:00-04,
premade_count: 0, sub_timestamp_min: 2016-09-11 00:00:00-04,
sub_timestamp_max: 2016-09-11 00:00:00-04
2016-09-09 17:38:15 EDT [] [9828]: [31-1] user=,db=,e=00000 DEBUG:
run_maint before loop2: premade_count: 0, sub_timestamp_min: 1999-12-31
19:00:00-05, sub_timestamp_max: 1999-12-31 19:00:00-05

I know I should always check for a null return from SPI before operating on
a value, and I do before I actually use those values. But I had them in my
debug lines where checking for whether they're null before outputting to
debug didn't seem to matter and it was really confusing me why the values
were returning recent timestamp values when I was pretty sure they were
null. Not sure if this can just be chalked up to undefined behavior when
dealing with nulls or it's an actual problem, so figured I'd report it.