Skip Menu |

This queue is for tickets about the Log-Dispatch-Win32EventLog CPAN distribution.

Report information
The Basics
Id: 29290
Status: open
Priority: 0/
Queue: Log-Dispatch-Win32EventLog

People
Owner: dland [...] cpan.org
Requestors: jcasadonte [...] northbound-train.com
Cc:
AdminCc:

Bug Information
Severity: Important
Broken in: 0.13
Fixed in: (no value)



Subject: "Free to wrong pool" error
I got the following error while using Log::Dispatch::Win32EventLog Free to wrong pool 1f84a70 not 332bb0 at D:/product/perl/site/lib/Win32/EventLog.pm line 110 during global destruction. ============ This seems to be connected to threading somehow. The following nonsense script reproduces the error: #!perl -w use strict; use threads; use Log::Dispatch::File; use Log::Dispatch::Handle; use Log::Dispatch::Screen; use Log::Dispatch::Win32EventLog; $| = !0; my($logger) = Log::Dispatch->new; $logger->add(Log::Dispatch::Screen->new(name => 'console', min_level => 'debug', max_level => 'info', stderr => 0)); $logger->add(Log::Dispatch::Screen->new(name => 'stderr', min_level => 'notice', stderr => 1)); # comment this out and the program runs fine $logger->add(Log::Dispatch::Win32EventLog->new(name => 'event_log', min_level => 'notice', source => 'RmCtl')); # uncomment the thread bit to get the program to crash foreach my $level (qw(debug info notice warning error)) { logit($level); # my($thread) = threads->new(\&logit, $level, 5); $thread->join; } sub logit { my($level, $sleep) = @_; print time . " ($level) "; sleep(rand($sleep) + 1) if $sleep; $logger->log(level => $level, message => "[\U$level\E] test message (" . time . ")\n"); } ============ Output with the program run as above: D:\>perl logtest.pl 1189448714 (debug) [DEBUG] test message (1189448714) 1189448714 (info) [INFO] test message (1189448714) 1189448714 (notice) [NOTICE] test message (1189448714) 1189448714 (warning) [WARNING] test message (1189448714) 1189448714 (error) [ERROR] test message (1189448714) Output with the first logit() commented out, and the threads->new uncommented: D:\>perl logtest.pl 1189448750 (debug) [DEBUG] test message (1189448751) Free to wrong pool 19a1568 not 334280 at D:/product/perl/site/lib/Win32/EventLog .pm line 110 during global destruction. (which, interestingly, shouldn't even be called, as both debug and info are below the minimum level.) And finally, output with the threads on but the call to set up the Log::Dispatch::Win32EventLog commented out: D:\>perl logtest.pl 1189448850 (debug) [DEBUG] test message (1189448855) 1189448855 (info) [INFO] test message (1189448860) 1189448860 (notice) [NOTICE] test message (1189448864) 1189448864 (warning) [WARNING] test message (1189448868) 1189448868 (error) [ERROR] test message (1189448872) ============ This is perl, v5.8.7 built for MSWin32-x86-multi-thread (with 14 registered patches, see perl -V for more detail) Copyright 1987-2005, Larry Wall Binary build 815 [211909] provided by ActiveState http://www.ActiveState.com ActiveState is a division of Sophos. Built Nov 2 2005 08:44:52 ============ OS: Win XP Pro SP 2 ============ The above error results in the following message in the Application log: Faulting application perl.exe, version 5.8.7.815, faulting module perl58.dll, version 5.8.7.815, fault address 0x00089af4. ============ Let me know if there's anything else I can provide to help track this down.
Subject: Re: [rt.cpan.org #29290] "Free to wrong pool" error
Date: Mon, 10 Sep 2007 23:00:28 +0200
To: bug-Log-Dispatch-Win32EventLog [...] rt.cpan.org
From: David Landgren <david [...] landgren.net>
Joe Casadonte via RT wrote: Show quoted text
> Mon Sep 10 14:30:43 2007: Request 29290 was acted upon. > Transaction: Ticket created by JoeCasadonte > Queue: Log-Dispatch-Win32EventLog > Subject: "Free to wrong pool" error > Broken in: 0.13 > Severity: Important > Owner: Nobody > Requestors: jcasadonte@northbound-train.com > Status: new > Ticket <URL: http://rt.cpan.org/Ticket/Display.html?id=29290 > > > > I got the following error while using Log::Dispatch::Win32EventLog > > Free to wrong pool 1f84a70 not 332bb0 at > D:/product/perl/site/lib/Win32/EventLog.pm line 110 during global > destruction.
[...] Show quoted text
> This is perl, v5.8.7 built for MSWin32-x86-multi-thread > (with 14 registered patches, see perl -V for more detail)
5.8.7 is getting on a bit, especially since 5.8.8 has proved itself to be very solid. There has been a lot of work done to enhance threads.pm. I would first recommend trying to bring that up to date. A *lot* of threads bugs have been fixed in recent months. Can you try it out on a test machine to see if it clears up the error? Thanks, David
From: jcasadonte [...] northbound-train.com
David, Show quoted text
> 5.8.7 is getting on a bit, especially since 5.8.8 has proved itself to > be very solid. > > There has been a lot of work done to enhance threads.pm. I would first > recommend trying to bring that up to date. A *lot* of threads bugs have > been fixed in recent months. Can you try it out on a test machine to see > if it clears up the error?
Thanks for the quick response! I can try out 5.8.8 on the test script, but upgrading to it unfortunately (silently) breaks my app, so it may not be a near-term solution for me. Will report back tomorrow. joe
On Mon Sep 10 18:59:18 2007, JoeCasadonte wrote: Show quoted text
> David, >
> > 5.8.7 is getting on a bit, especially since 5.8.8 has proved itself to > > be very solid. > > > > There has been a lot of work done to enhance threads.pm. I would first > > recommend trying to bring that up to date. A *lot* of threads bugs have > > been fixed in recent months. Can you try it out on a test machine to
see Show quoted text
> > if it clears up the error?
> > Thanks for the quick response! I can try out 5.8.8 on the test script, > but upgrading to it unfortunately (silently) breaks my app, so it may > not be a near-term solution for me. Will report back tomorrow.
Hmmm, just tried it out myself, and the problem still exists with the latest AS 5.8.8 (build 819). I shall investigate further, but I don't know how fast I will be. I know next to zero about threads (their implementation and Free to wrong pool errors and suchlike). David
From: jcasadonte [...] northbound-train.com
On Tue Sep 18 10:13:10 2007, DLAND wrote: Show quoted text
> Hmmm, just tried it out myself, and the problem still exists with the > latest AS 5.8.8 (build 819). > > I shall investigate further, but I don't know how fast I will be. I know > next to zero about threads (their implementation and Free to wrong pool > errors and suchlike).
Sorry I wasn't able to try it out before you got to it; it was on my todo list, just hadn't bubbled up to the top. I don't know a thing about Perl internals, but if there's anything I can do to help, please let me know via the ticket. And I understand about response time on this -- I get what I pay for. Thanks for the help! joe
Hello, some good news. The code is blowing up on a CloseEventLog call in Win32/Eventlog.pm. If I patch the code to defer the closing of the handle to the event log until the end of the program, the error goes away: --- EventLog.pm.orig Sat Sep 17 22:36:34 2005 +++ EventLog.pm Wed Sep 19 08:47:12 2007 @@ -105,9 +105,19 @@ return BackupEventLog($self->{handle}, $file); } +{ + my @defer_close; + sub _defer_close { + push @defer_close, @_; + } + END { + CloseEventLog($_) for @defer_close; + } +} + sub Close { my $self = shift; - CloseEventLog($self->{handle}); + _defer_close($self->{handle}); $self->{handle} = 0; } However, I have no idea of the ramifications that this may cause. I'll take it up with the author (Jan Dubois, I think), for another opinion. Later, David