Re: Auditing extension for PostgreSQL (Take 2)

On Thu, Apr 16, 2015 at 2:34 AM, David Steele <david(at)pgmasters(dot)net> wrote:
> On 4/15/15 11:30 AM, Sawada Masahiko wrote:
>> On Wed, Apr 15, 2015 at 10:52 AM, Sawada Masahiko <sawada(dot)mshk(at)gmail(dot)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