Thread: File truncation within PostgresNode::issues_sql_like() wrong on Windows

Hi all,

As fairywren has proved a couple of days ago, it is not really a good
idea to rely on a file truncation to check for patterns in the logs of
the backend:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=fairywren&dt=2021-04-07%2013%3A29%3A28

Visibly, a logic based on the log file truncation fails on Windows
because of the concurrent access of the backend that outputs its logs
there.  In PostgresNode.pm, connect_ok() and connect_access() enforce
a rotation of the log file before restarting the server on Windows to
make sure that a given step does not find logs generated by a previous
test, but that's not the case of issues_sql_like().  Looking at the
existing tests using this routine (src/bin/scripts/), I have found on
test in 090_reindexdb.pl that could lead to a false positive.  The
test is marked in the patch attached, just for awareness.

Would there be any objections to change this routine so as we avoid
the file truncation on Windows?  The patch attached achieves that.

Any thoughts?
--
Michael

On 4/14/21 4:13 AM, Michael Paquier wrote:
> Hi all,
>
> As fairywren has proved a couple of days ago, it is not really a good
> idea to rely on a file truncation to check for patterns in the logs of
> the backend:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=fairywren&dt=2021-04-07%2013%3A29%3A28
>
> Visibly, a logic based on the log file truncation fails on Windows
> because of the concurrent access of the backend that outputs its logs
> there.  In PostgresNode.pm, connect_ok() and connect_access() enforce
> a rotation of the log file before restarting the server on Windows to
> make sure that a given step does not find logs generated by a previous
> test, but that's not the case of issues_sql_like().  Looking at the
> existing tests using this routine (src/bin/scripts/), I have found on
> test in 090_reindexdb.pl that could lead to a false positive.  The
> test is marked in the patch attached, just for awareness.
>
> Would there be any objections to change this routine so as we avoid
> the file truncation on Windows?  The patch attached achieves that.
>
> Any thoughts?


That seems rather heavy-handed. The buildfarm's approach is a bit
different. Essentially it seeks to the previous position of the log file
before reading contents. Here is its equivalent of slurp_file:


    use Fcntl qw(:seek);
    sub file_lines
    {
        my $filename = shift;
        my $filepos  = shift;
        my $handle;
        open($handle, '<', $filename) || croak "opening $filename: $!";
        seek($handle, $filepos, SEEK_SET) if $filepos;
        my @lines = <$handle>;
        close $handle;
        return @lines;
    }



A client wanting what's done in PostgresNode would do something like:


    my $logpos  = -s $logfile;
    do_some_stuff();
    my @lines = file_lines($logfile, $logpos);


This has the benefit of working the same on all platforms, and no
truncation, rotation, or restart is required.



cheers


andrew


--
Andrew Dunstan
EDB: https://www.enterprisedb.com

On Wed, Apr 14, 2021 at 05:10:41PM -0400, Andrew Dunstan wrote:
> That seems rather heavy-handed. The buildfarm's approach is a bit
> different. Essentially it seeks to the previous position of the log file
> before reading contents. Here is its equivalent of slurp_file:
>
>     use Fcntl qw(:seek);
>     sub file_lines
>     {
>         my $filename = shift;
>         my $filepos  = shift;
>         my $handle;
>         open($handle, '<', $filename) || croak "opening $filename: $!";
>         seek($handle, $filepos, SEEK_SET) if $filepos;
>         my @lines = <$handle>;
>         close $handle;
>         return @lines;
>     }

That's a bit surprising to see that you can safely open a file handle
with perl like that without using Win32API::File, and I would have
assumed that this would have conflicted with the backend redirecting
its output to stderr the same way as a truncation on Windows.

> A client wanting what's done in PostgresNode would do something like:
>
>     my $logpos  = -s $logfile;
>     do_some_stuff();
>     my @lines = file_lines($logfile, $logpos);
>
> This has the benefit of working the same on all platforms, and no
> truncation, rotation, or restart is required.

Jacob has suggested something like that a couple of days ago, but all
this code was not centralized yet in a single place.

For this code, the cleanest approach would be to extend slurp_file()
with an extra argument to seek the file before fetching its contents
based on a location given by the caller?  Looking at the docs of
Win32API::File, we'd need to use SetFilePointer() instead of seek().
--
Michael

On 4/14/21 8:10 PM, Michael Paquier wrote:
> On Wed, Apr 14, 2021 at 05:10:41PM -0400, Andrew Dunstan wrote:
>> That seems rather heavy-handed. The buildfarm's approach is a bit
>> different. Essentially it seeks to the previous position of the log file
>> before reading contents. Here is its equivalent of slurp_file:
>>
>>     use Fcntl qw(:seek);
>>     sub file_lines
>>     {
>>         my $filename = shift;
>>         my $filepos  = shift;
>>         my $handle;
>>         open($handle, '<', $filename) || croak "opening $filename: $!";
>>         seek($handle, $filepos, SEEK_SET) if $filepos;
>>         my @lines = <$handle>;
>>         close $handle;
>>         return @lines;
>>     }
> That's a bit surprising to see that you can safely open a file handle
> with perl like that without using Win32API::File, and I would have
> assumed that this would have conflicted with the backend redirecting
> its output to stderr the same way as a truncation on Windows.
>
>> A client wanting what's done in PostgresNode would do something like:
>>
>>     my $logpos  = -s $logfile;
>>     do_some_stuff();
>>     my @lines = file_lines($logfile, $logpos);
>>
>> This has the benefit of working the same on all platforms, and no
>> truncation, rotation, or restart is required.
> Jacob has suggested something like that a couple of days ago, but all
> this code was not centralized yet in a single place.
>
> For this code, the cleanest approach would be to extend slurp_file()
> with an extra argument to seek the file before fetching its contents
> based on a location given by the caller?  Looking at the docs of
> Win32API::File, we'd need to use SetFilePointer() instead of seek().



Well, let me try it on fairywren tomorrow. Since we manage this on the
buildfarm without any use at all of Win32API::File it might not be
necessary in TAP code either, particularly if we're not truncating the file.


cheers


andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

On Wed, Apr 14, 2021 at 09:26:19PM -0400, Andrew Dunstan wrote:
> Well, let me try it on fairywren tomorrow. Since we manage this on the
> buildfarm without any use at all of Win32API::File it might not be
> necessary in TAP code either, particularly if we're not truncating the file.

Thanks.  If that proves to not be necessary, +1 to remove this code.
I have been playing with this stuff, and the attached patch seems to
work properly on Windows.  On top of that, I have also tested the
non-Win32 path on an MSVC box to see that it was working, but my
environment is not really noisy usually with such compatibility
issues.
--
Michael

On 4/15/21 12:57 AM, Michael Paquier wrote:
> On Wed, Apr 14, 2021 at 09:26:19PM -0400, Andrew Dunstan wrote:
>> Well, let me try it on fairywren tomorrow. Since we manage this on the
>> buildfarm without any use at all of Win32API::File it might not be
>> necessary in TAP code either, particularly if we're not truncating the file.
> Thanks.  If that proves to not be necessary, +1 to remove this code.
> I have been playing with this stuff, and the attached patch seems to
> work properly on Windows.  On top of that, I have also tested the
> non-Win32 path on an MSVC box to see that it was working, but my
> environment is not really noisy usually with such compatibility
> issues.


Reviewing the history, I don't want to undo 114541d58e5. So I'm trying
your patch.


cheers


andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

On Thu, Apr 15, 2021 at 07:16:05AM -0400, Andrew Dunstan wrote:
> Reviewing the history, I don't want to undo 114541d58e5.

Maybe we could remove it, but that may be better as a separate
discussion if it is proving to not improve the situation, and I don't
really want to take any risks in destabilizing the buildfarm these
days.

> So I'm trying your patch.

Thanks!  If you need any help, please feel free to ping me.
--
Michael

On 4/15/21 8:36 PM, Michael Paquier wrote:
> On Thu, Apr 15, 2021 at 07:16:05AM -0400, Andrew Dunstan wrote:
>> Reviewing the history, I don't want to undo 114541d58e5.
> Maybe we could remove it, but that may be better as a separate
> discussion if it is proving to not improve the situation, and I don't 
> really want to take any risks in destabilizing the buildfarm these
> days.  
>
>> So I'm trying your patch.
> Thanks!  If you need any help, please feel free to ping me.



It's worked on fairywren, I will double check on drongo and if all is
well will commit.


cheers


andrew


--
Andrew Dunstan
EDB: https://www.enterprisedb.com

On Thu, Apr 15, 2021 at 09:12:52PM -0400, Andrew Dunstan wrote:
> It's worked on fairywren, I will double check on drongo and if all is
> well will commit.

Thanks Andrew.  For the archive's sake, this has been committed as of
3c5b068.

While reading the commit, I have noticed that you used SEEK_SET
instead of 0 as I did in my own patch.  That makes the code easier to
understand.  Could it be better to apply the same style to all the
perl scripts doing some seek() calls?  Please see the attached.
--
Michael

On 4/17/21 9:04 AM, Michael Paquier wrote:
> On Thu, Apr 15, 2021 at 09:12:52PM -0400, Andrew Dunstan wrote:
>> It's worked on fairywren, I will double check on drongo and if all is
>> well will commit.
> Thanks Andrew.  For the archive's sake, this has been committed as of
> 3c5b068.
>
> While reading the commit, I have noticed that you used SEEK_SET
> instead of 0 as I did in my own patch.  That makes the code easier to
> understand.  Could it be better to apply the same style to all the
> perl scripts doing some seek() calls?  Please see the attached.



Yes please, much better to use a symbolic name rather than a magic
number. I wouldn't bother backpatching it though.


cheers


andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

On Sat, Apr 17, 2021 at 09:55:47AM -0400, Andrew Dunstan wrote:
> Yes please, much better to use a symbolic name rather than a magic
> number.  I wouldn't bother backpatching it though.

Okay, done this way then.
--
Michael