POE, log4perl and sqlite

[Antti Linno]

Good day.

I'm using a bit modified Sungo's TCP server (Using SocketFactory and
ReadWrite). I'm using a plain Log4perl, not POE::Log4perl. Yesterday I
got a crash with sqlite database lock.

So basically I have 2 questions:

1) Do POE's sessions run in parallel? (ok, this might be obvious, but
I have to be sure :) This might explain the database lock, as parallel
session could write at the same time. Oddly this crash
happens rarely.
2) Does POE::Component::Log4perl cure this problem?

If there is no cure, will there be a problem with file based logging?
I can switch from SQL to grep based search.

Thanks,
Antti

[p...@perlmeister.com]

On Mon, 15 Oct 2012, Antti Linno wrote:

> 1) Do POE's sessions run in parallel? (ok, this might be obvious, but
> I have to be sure :) This might explain the database lock, as parallel
> session could write at the same time. Oddly this crash
> happens rarely.

Is using the database spawning multiple processes within POE? POE by
itself is single-process-single-threaded, but some components spawn
multiple processes, like this one:

http://cpansearch.perl.org/src/XANTUS/POE-Component-EasyDBI-1.23/lib/POE/Component/EasyDBI/SubProcess.pm

If you have multiple processes within POE, then I guess getting a SQLite
locked situation is possible.

> 2) Does POE::Component::Log4perl cure this problem?

This component is just a thin wrapper around Log4perl, and doesn't do
much except provide an easy to use POE-like interface.

If you're using a single-process-single-threaded POE application,
Log4perl won't have issues with multiple writes to a file. If you have
multiple processes, there's easy ways to avoid overlapping writes, as
outlined in the Log4perl FAQ:

http://search.cpan.org/dist/Log-Log4perl/lib/Log/Log4perl/FAQ.pm#How_can_I_synchronize_access_to_an_appender?

--
-- Mike

Mike Schilli
p...@perlmeister.com

[Antti Linno]

First of all, I have to apologise. Still no pastebin.

But a general tree would be something like that.

Main POE module, imported submodule1, imported submodule2. All 3
modules open the same logger conf and use the same sqlite file to
append the log. Theoretically the log file could be locked, if all 3
or even 2 modules try to write at the same time.
What would be the nice and tidy thing to do? Initialize logger in main
POE module and pass it to submodules?

I'm amazed, that lockups happens once in a blue moon. Maybe load is
still not that big, that events per second are low.

Thank you for your time.

[Antti Linno]

Thank you for your kind interest.

The pastebins:

log4perl.conf http://pastebin.com/nY4twgjS
main file http://pastebin.com/ruYsu2qt
application logic http://pastebin.com/hMyyBJ0U
database interaction http://pastebin.com/Cq7d4geK

As you can see, all the perl files are logging, main and application
import database functions. I have snipped the application and database
somewhat, but you could see the main structure and how I am doing the
logging.

Greetings.

On Thu, Oct 18, 2012 at 4:19 PM, Rocco Caputo <rca...@pobox.com> wrote:

> On Oct 18, 2012, at 07:58, Antti Linno wrote:
>
>> First of all, I have to apologise. Still no pastebin.
>

> We have to apologize, too. You're asking questions about code we cannot see. This impairs our ability to provide satisfying answers.

>
>> But a general tree would be something like that.
>>
>> Main POE module, imported submodule1, imported submodule2. All 3
>> modules open the same logger conf and use the same sqlite file to
>> append the log. Theoretically the log file could be locked, if all 3
>> or even 2 modules try to write at the same time.
>

> No. As others have said, POE doesn't pre-empt. Under ordinary circumstances, we expect all three modules to call Log::Log4perl sequentially rather than concurrently. We don't expect Log::Log4perl suffer from lock contention.
>
> It's very likely that something extraordinary is happening as a result of code we cannot see. Others have already outlined the most likely reasons for the symptoms you described. I hope you understand that's the best we can do without your cooperation.

>
>> What would be the nice and tidy thing to do? Initialize logger in main
>> POE module and pass it to submodules?
>

> That's such a good question that Log::Log4perl already answers it:
>
> "Why Log::Log4perl->get_logger and not Log::Log4perl->new? We don't want to create a new object every time. Usually in OO-Programming, you create an object once and use the reference to it to call its methods. However, this requires that you pass around the object to all functions and the last thing we want is pollute each and every function/method we're using with a handle to the Logger:
>
> [example omitted]
>
> "Instead, if a function/method wants a reference to the logger, it just calls the Logger's static get_logger($category) method to obtain a reference to the one and only possible logger object of a certain category. That's called a singleton if you're a Gamma fan."
>
> That quote is from http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm#Initialize_via_a_configuration_file
>
> --
> Rocco Caputo <rca...@pobox.com>

[Antti Linno]

Ok, thanks for suggestion. No select is taking place, unless I do it
manually and via sqlite client. The crash occurred in the middle of
the night, so my interference can be ruled out :D
Maybe I should move to a file based logging as this seems more robust.

Thank you all for your time.

On Fri, Oct 19, 2012 at 3:46 PM, Rocco Caputo <rca...@pobox.com> wrote:
> Every module seems to be re-initializing your logger. I don't know if it's harmful in your situation, but it's not recommended. Wherever you call Log::Log4perl::init($log_conf) try Log::Log4perl->init_once($log_conf) instead. See: http://search.cpan.org/~mschilli/Log-Log4perl-1.38/lib/Log/Log4perl.pm#Initialize_once_and_only_once
>
> Offhand I don't see anything else that would lock your log database. Maybe another program is locking it in SELECT? If that's true, the queries are taking too long for the bot to wait. Maybe you could optimize the table indexes so the queries complete in time.
>
> --
> Rocco Caputo <rca...@pobox.com>