Re: BUG #14322: Possible inconsistent behavior with timestamp_to_str()

On Fri, Sep 9, 2016 at 8:02 PM, Keith <keith(at)keithf4(dot)com> wrote:

>
>
> On Fri, Sep 9, 2016 at 8:02 PM, Andres Freund <andres(at)anarazel(dot)de> wrote:
>
>> On 2016-09-09 23:54:48 +0000, keith(at)keithf4(dot)com wrote:
>> > 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.
>>
>> Uh. You can't just call timestamptz_to_str() on a NULL value. The datum
>> doesn't have to have any meaningful value if it's null.
>>
>>
>> > 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.
>>
>> I don't think there's an issue here. The datum value isn't guaranteed
>> to be initialized if the value is null, and I think that's what you're
>> seeing here.
>>
>> Greetings,
>>
>> Andres Freund
>>
>
> Understood. Just confused me for a while and wanted to make sure it wasn't
> a real issue. Thanks!
>
> Keith
>

Ok, this may be more of an actual issue than I thought. It seems that, even
if all variables to the timestamptz_to_str() function have a valid value
set, if it is called multiple times in the same statement, it keeps the
first value for all following occurrences. Belows is an example. I kept
getting zero for the difference between these two timestamps and it was
confusing the hell out of me until I did a debug output of the actual query
being run. You can see if I swap the two values around, it keeps the same
timestamp value of the first occurrence each time. I also output the
variable values to ensure they're valid.

My code:
resetStringInfo(&buf);
appendStringInfo(&buf, "SELECT round(EXTRACT('epoch' FROM age('%s', '%s'))
/ EXTRACT('epoch' FROM '%s'::interval))::int"
, timestamptz_to_str(last_partition_timestamp),
timestamptz_to_str(current_partition_timestamp), partition_interval);
elog(DEBUG1, "getting premade: %s, last_partition_timestamp: %ld,
current_partition_timestamp: %ld", buf.data, last_partition_timestamp,
current_partition_timestamp);

resetStringInfo(&buf);
appendStringInfo(&buf, "SELECT round(EXTRACT('epoch' FROM age('%s', '%s'))
/ EXTRACT('epoch' FROM '%s'::interval))::int"
, timestamptz_to_str(current_partition_timestamp),
timestamptz_to_str(last_partition_timestamp), partition_interval);
elog(DEBUG1, "getting premade: %s, last_partition_timestamp: %ld,
current_partition_timestamp: %ld", buf.data, last_partition_timestamp,
current_partition_timestamp);

Log output:
2016-09-13 16:01:02 EDT [] [16417]: [24-1] user=,db=,e=00000 DEBUG:
getting premade: SELECT round(EXTRACT('epoch' FROM age('2016-09-23
00:00:00-04', '2016-09-23 00:00:00-04')) / EXTRACT('epoch' FROM '1
day'::interval))::int, last_partition_timestamp: 527918400000000,
current_partition_timestamp: 527227200000000
2016-09-13 16:01:02 EDT [] [16417]: [25-1] user=,db=,e=00000 DEBUG:
getting premade: SELECT round(EXTRACT('epoch' FROM age('2016-09-15
00:00:00-04', '2016-09-15 00:00:00-04')) / EXTRACT('epoch' FROM '1
day'::interval))::int, last_partition_timestamp: 527918400000000,
current_partition_timestamp: 527227200000000

Keith