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

On Tue, Sep 13, 2016 at 4:16 PM, Keith Fiske <keith(at)omniti(dot)com> wrote:

>
>
>
> 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
>

So think I found a fix for it for now using timestamp_out() instead (saw it
referenced in the timestamptz_to_str() source). Just makes the string
building more complicated

appendStringInfo(&buf, "SELECT round(EXTRACT('epoch' FROM age('%s', '%s'))
/ EXTRACT('epoch' FROM '%s'::interval))::int"
, DatumGetCString(DirectFunctionCall1(timestamp_out,
TimestampTzGetDatum(last_partition_timestamp)))
, DatumGetCString(DirectFunctionCall1(timestamp_out,
TimestampTzGetDatum(current_partition_timestamp)))
, partition_interval);

Looking through the code it seems all calls to timestamp_to_str() only
reference it once per statement. I don't see any reason why you shouldn't
be able to call this function more than once at a time, though. Makes cases
where you need text output of timestamps a lot easier to build.