Re: Auditing extension for PostgreSQL (Take 2)

On Wed, Apr 15, 2015 at 10:52 AM, Sawada Masahiko <sawada(dot)mshk(at)gmail(dot)com> wrote:
> On Wed, Apr 15, 2015 at 8:57 AM, David Steele <david(at)pgmasters(dot)net> wrote:
>> On 4/14/15 7:13 PM, Tatsuo Ishii wrote:
>>> This patch does not apply cleanly due to the moving of pgbench (patch
>>> to filelist.sgml failed).
>>
>> Thank you for pointing that out!
>>
>> Ironic that it was the commit directly after the one I was testing with
>> that broke the patch. It appears the end of the last CF is a very bad
>> time to be behind HEAD.
>>
>> Fixed in attached v8 patch.
>
> Thank you for updating the patch!
>
> I applied the patch and complied them successfully without WARNING.
>
> 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 hope that these messages helps you to address this problem.
> I will also try to address this.
>
> Regards,
>
> -------
> Sawada Masahiko

> I will also try to address this.

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.

Regards,

-------
Sawada Masahiko