Re: Auditing extension for PostgreSQL (Take 2) - Mailing list pgsql-hackers

On Thu, Apr 16, 2015 at 2:34 AM, David Steele <david@pgmasters.net> wrote:
> On 4/15/15 11:30 AM, Sawada Masahiko wrote:
>> On Wed, Apr 15, 2015 at 10:52 AM, Sawada Masahiko <sawada.mshk@gmail.com> wrote:
>>> I tested v8 patch with CURSOR case I mentioned before, and got
>>> segmentation fault again.
>>> Here are log messages in my environment,
>>>
>>> =# select test();
>>>  LOG:  server process (PID 29730) was terminated by signal 11:
>>> Segmentation fault
>>> DETAIL:  Failed process was running: select test();
>>> LOG:  terminating any other active server processes
>>> WARNING:  terminating connection because of crash of another server process
>>> DETAIL:  The postmaster has commanded this server process to roll back
>>> the current transaction and exit, because another server process
>>> exited abnormally and possibly corrupted shared memory.
>>> HINT:  In a moment you should be able to reconnect to the database and
>>> repeat your command.
>>> FATAL:  the database system is in recovery mode
>>
>> I investigated this problem and inform you my result here.
>>
>> When we execute test() function I mentioned, the three stack items in
>> total are stored into auditEventStack.
>> The two of them are freed by stack_pop() -> stack_free() (i.g,
>> stack_free() is called by stack_pop()).
>> One of them is freed by PortalDrop() -> .. ->
>> MemoryContextDeleteChildren() -> ... -> stack_free().
>> And it is freed at the same time as deleting pg_audit memory context,
>> and stack will be completely empty.
>>
>> But after freeing all items, finish_xact_command() function could call
>> PortalDrop(), so ExecutorEnd() function could be called again.
>> pg_audit has ExecutorEnd_hook, so postgres tries to free that item.. SEGV.
>>
>> In my environment, the following change fixes it.
>>
>> --- pg_audit.c.org    2015-04-15 14:21:07.541866525 +0900
>> +++ pg_audit.c    2015-04-15 11:36:53.758877339 +0900
>> @@ -1291,7 +1291,7 @@
>>          standard_ExecutorEnd(queryDesc);
>>
>>      /* Pop the audit event off the stack */
>> -    if (!internalStatement)
>> +    if (!internalStatement && auditEventStack != NULL)
>>      {
>>          stack_pop(auditEventStack->stackId);
>>      }
>>
>> It might be good idea to add Assert() at before calling stack_pop().
>>
>> I'm not sure this change is exactly correct, but I hope this
>> information helps you.
>
> I appreciate you taking the time to look - this is the same conclusion I
> came to.  I also hardened another area that I thought might be vulnerable.
>
> I've seen this problem with explicit cursors before (and fixed it in
> another place a while ago).  The memory context that is current in
> ExecutorStart is freed before ExecutorEnd is called only in this case as
> far as I can tell.  I'm not sure this is very consistent behavior.
>
> I have attached patch v9 which fixes this issue as you suggested, but
> I'm not completely satisfied with it.  It seems like there could be an
> unintentional pop from the stack in a case of deeper nesting.  This
> might not be possible but it's hard to disprove.
>
> I'll think about it some more, but meanwhile this patch addresses the
> present issue.

Thank you for updating the patch.

One question about regarding since v7 (or later) patch is;
What is the different between OBJECT logging and SESSION logging?

I used v9 patch with "pg_audit.log_relation = on", and got quite
similar but different log as follows.

=# select * from hoge, bar where hoge.col = bar.col;
NOTICE:  AUDIT: OBJECT,8,1,READ,SELECT,TABLE,public.hoge,"select *
from hoge, bar where hoge.col = bar.col;"
NOTICE:  AUDIT: SESSION,8,1,READ,SELECT,TABLE,public.hoge,"select *
from hoge, bar where hoge.col = bar.col;"
NOTICE:  AUDIT: OBJECT,8,1,READ,SELECT,TABLE,public.bar,"select * from
hoge, bar where hoge.col = bar.col;"
NOTICE:  AUDIT: SESSION,8,1,READ,SELECT,TABLE,public.bar,"select *
from hoge, bar where hoge.col = bar.col;"

The behaviour of SESSION log is similar to OBJECT log now, and SESSION
log per session (i.g, pg_audit.log_relation = off) is also similar to
'log_statement = all'. (enhancing log_statement might be enough)
So I couldn't understand needs of SESSION log.

Regards,

-------
Sawada Masahiko