log4net mysteriously stops logging

Thread view:

Enable EMail Alerts

Start New Thread

Thread rating:

RobinS - 19 Mar 2008 02:07 GMT

I have sent a message to the apache listserver, but thought I would ask
here, too, just in case anyone has seen this problem.

I am using log4net to do logging in my .Net 2.0 application. I am using the
most current version.

It's been working great (AFAIK), but today a couple of the QA people noticed
that at some point while running our application, it stops logging. You have
to close the app and restart it and the logging will restart.

They tried deleting all the log files (we create 1MB files, and keep 5 of
them) and it still happens. I haven't managed to recreate the problem, but
one of the other developers has, and he stepped through the calls to the
logging, and it appears to work fine, but doesn't log the information.

This does not happen to all users, and while it is completely reproducible
by the (2) QA folks, it doesn't happen to me, and is intermittent with my
coworker.

There's only one other case where I've seen this -- I was trying to put
logging in a click event in a user control, and MessageBox statements would
work, but the logging wouldn't. I decided it was a quirk and removed the
logging. Now I'm wondering.

Has anybody else ever experienced this problem, or do you have any ideas how
I could debug it?

I'd appreciate any advice or suggestions you may have.

Thanks,
RobinS.
GoldMail.com

Reply to this Message

Jeroen Mostert - 19 Mar 2008 20:30 GMT

> I have sent a message to the apache listserver, but thought I would ask
> here, too, just in case anyone has seen this problem.

That's not very nice. Do you stop strangers in the street too, asking them
if they've ever seen a rash like the one that appeared on your buttocks? No,
you wait for your doctor to come back with results. Suppose the apache folks
will shortly tell you exactly what's wrong, or maybe they already have --
then I will have wasted a lot of time typing this up.

Fortunately my time's not that valuable.

> I am using log4net to do logging in my .Net 2.0 application. I am using
> the most current version.

That would be 1.2.10. Let's not be datist here.

log4net questions are really not appropriate for any language-specific
group. Followup-to .general, which is at least mildly more suitable.

> It's been working great (AFAIK), but today a couple of the QA people
> noticed that at some point while running our application, it stops
[quoted text clipped - 6 lines]
> calls to the logging, and it appears to work fine, but doesn't log the
> information.

Step harder!

I mean, you have the source and a reproducible problem. It doesn't get any
better than that. Compile a debug version and use that. Eventually you get
to the point where log4net physically writes to the file, or you don't. If
you don't, there's your problem. If you do, there's your problem again, but
subtler. If the problem is not reproducible with the debug version, you've
got a heisenbug and that sucks, but at least you've again got a chance for
determining the problem. (Try compiling your own release version too, in
case it's a compiler bug.)

Also, turn on log4net's internal debug logging. Even without that, it will
usually complain if it can't log. See the FAQ for more information.

> This does not happen to all users, and while it is completely
> reproducible by the (2) QA folks, it doesn't happen to me, and is
> intermittent with my coworker.

Verily, it has the hallmarks of a synchronization problem, though it's
impossible to tell for sure. To pin down the reproducible circumstances, you
could try comparing machine specs (especially single-core vs. multicore), OS
versions and .NET Framework versions ("2.0" encompasses a few different
"steppings" of the runtime; compre the the versions of mscorwks.dll in
%WINDIR%\Microsoft.NET\Framework\v2.0.50727).

> Has anybody else ever experienced this problem, or do you have any ideas
> how I could debug it?

We've got tons of apps on a lot of servers that log with 1.2.10 (and have
with earlier versions), almost all using RollingFileAppender. None of them
has ever experienced a problem like this. Whenever logging was missing it
would invariably turn out that:

- some dolt misconfigured it;
- some dolt managed to start a second instance that tried to write to the
same file, causing a spurious file to appear; or
- some dolt forgot the default logging file sizes, and the files would wrap
around at 10 MB.

Nothing resembling a stop in mid-service.

Signature

Reply to this Message

RobinS - 21 Mar 2008 17:25 GMT

>> I have sent a message to the apache listserver, but thought I would ask
>> here, too, just in case anyone has seen this problem.
[quoted text clipped - 5 lines]
> have --
> then I will have wasted a lot of time typing this up.

Thanks, but I have been hanging around in this group long enough to know
that if I got an answer from the Apache list, I would post it here
immediately, so that (1) people would know how I solved the problem, and (2)
people here would know the problem was solved. I posted it to both because
I'm desperate, I've seen log4net q's here, and the people here are
exceptionally smart.

> Fortunately my time's not that valuable.

LOL. Fortunate for me.

>> I am using log4net to do logging in my .Net 2.0 application. I am using
>> the most current version.
>>
> That would be 1.2.10. Let's not be datist here.

I am using version 1.2.10. Is that better? ;-)

> log4net questions are really not appropriate for any language-specific
> group. Followup-to .general, which is at least mildly more suitable.

More people hang out in the language groups. Did I mention that I'm
desperate?

>> It's been working great (AFAIK), but today a couple of the QA people
>> noticed that at some point while running our application, it stops
[quoted text clipped - 17 lines]
> chance for determining the problem. (Try compiling your own release
> version too, in case it's a compiler bug.)

I can't reproduce the problem or I would already have done that. I'm going
to install VS2008 on one of my QA people's computers today and try this.
Nothing crashes; it just stops logging.

> Also, turn on log4net's internal debug logging. Even without that, it will
> usually complain if it can't log. See the FAQ for more information.

I did that, frankly hoping for something with the word "FAILED" in it (no
such luck). It did make the problem go away though. (And yes, I realize
release a version of software with debugging enabled is a bad idea, and no,
I wouldn't do it.)

I did not set the logging up, so I am basically floundering around in the
dark here.

I do see a lot of this kind of thing:

It starts with this:

log4net: log4net assembly [log4net, Version=1.2.10.0, Culture=neutral,
PublicKeyToken=1b44e1d426115821]. Loaded from
[C:\Users\Jeanne\AppData\Local\Apps\2.0\EM6ZCA9H.ZH3\2YEVW4GX.TD1\gmst..tion_e84b302e57430172_0003.0002_8a24dc44b8cff001\log4net.dll].
(.NET Runtime [2.0.50727.1433] on Microsoft Windows NT 6.0.6001 Service Pack
1, v.668)

log4net: DefaultRepositorySelector: defaultRepositoryType
[log4net.Repository.Hierarchy.Hierarchy]

log4net: DefaultRepositorySelector: Creating repository for assembly
[GMStudio, Version=3.1.0.0, Culture=neutral, PublicKeyToken=null]

log4net: DefaultRepositorySelector: Assembly [GMStudio, Version=3.1.0.0,
Culture=neutral, PublicKeyToken=null] Loaded From
[C:\Users\Jeanne\AppData\Local\Apps\2.0\EM6ZCA9H.ZH3\2YEVW4GX.TD1\gmst..tion_e84b302e57430172_0003.0002_8a24dc44b8cff001\GMStudio.exe]

log4net: DefaultRepositorySelector: Assembly [GMStudio, Version=3.1.0.0,
Culture=neutral, PublicKeyToken=null] does not have a RepositoryAttribute
specified.

log4net: DefaultRepositorySelector: Assembly [GMStudio, Version=3.1.0.0,
Culture=neutral, PublicKeyToken=null] using repository
[log4net-default-repository] and repository type
[log4net.Repository.Hierarchy.Hierarchy]

log4net: DefaultRepositorySelector: Creating repository
[log4net-default-repository] using type
[log4net.Repository.Hierarchy.Hierarchy]

It creates the appender and sets the properties of it.

It then does this for every dll:

log4net: DefaultRepositorySelector: Creating repository for assembly
[GMLibrary, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]

log4net: DefaultRepositorySelector: Assembly [GMLibrary, Version=1.0.0.0,
Culture=neutral, PublicKeyToken=null] Loaded From
[C:\Users\Jeanne\AppData\Local\Apps\2.0\EM6ZCA9H.ZH3\2YEVW4GX.TD1\gmst..tion_e84b302e57430172_0003.0002_8a24dc44b8cff001\GMLibrary.dll]

log4net: DefaultRepositorySelector: Assembly [GMLibrary, Version=1.0.0.0,
Culture=neutral, PublicKeyToken=null] does not have a RepositoryAttribute
specified.

log4net: DefaultRepositorySelector: Assembly [GMLibrary, Version=1.0.0.0,
Culture=neutral, PublicKeyToken=null] using repository
[log4net-default-repository] and repository type
[log4net.Repository.Hierarchy.Hierarchy]

log4net: DefaultRepositorySelector: repository [log4net-default-repository]
already exists, using repository type
[log4net.Repository.Hierarchy.Hierarchy]

***It actually does that a lot. So do I have some problem with not having
something defined that I should? We start the logging first thing in the
application.

And then I see this also after the disposal of some sound objects:

log4net: Hierarchy: Shutdown called on Hierarchy
[log4net-default-repository]
log4net: Logger: No appenders could be found for logger [GMSound.SoundUtils]
repository [log4net-default-repository]
log4net: Logger: Please initialize the log4net system properly.

after which is shows the CurrentAppDomain, basedirectory, etc. I get this
error for 1 class and two forms, but not for any of the other classes or
forms.

We define the reference to the logging the same way throughout our
application, like this:

ILog log =
LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

Does that matter?

>> This does not happen to all users, and while it is completely
>> reproducible by the (2) QA folks, it doesn't happen to me, and is
[quoted text clipped - 6 lines]
> few different "steppings" of the runtime; compre the the versions of
> mscorwks.dll in %WINDIR%\Microsoft.NET\Framework\v2.0.50727).

I will look at that today. Most of the machines are fairly new (w/i last 6
months), and are dual core.

>> Has anybody else ever experienced this problem, or do you have any ideas
>> how I could debug it?
[quoted text clipped - 11 lines]
>
> Nothing resembling a stop in mid-service.

Here is my configuration file. So am I a dolt? Or rather, was the guy who
set it up a dolt, and I'm just perpetuating his doltness?

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender" >
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date %-5level %logger (%L) [%ndc] -
%message%newline" />
</layout>
</appender>
<appender name="RollingLogFileAppender"
type="log4net.Appender.RollingFileAppender">
<file value="GoldMailLog.txt" />
<staticLogFileName value="true" />
<appendToFile value="true" />
<rollingStyle value="Size" />
<maxSizeRollBackups value="5" />
<maximumFileSize value="1MB" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern
value="GMLog#%date;%-5level;%logger(%L);%message#End%newline" />
</layout>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="ConsoleAppender" />
<appender-ref ref="RollingLogFileAppender" />
</root>
</log4net>

Thanks for any help or advice you can provide. If you're ever in the San
Francisco Bay Area, I'll buy you a dish of Rice-a-Roni. (No, they don't
really serve it anywhere.)

RobinS.
GoldMail.com

Reply to this Message

Rate this thread:

log4net mysteriously stops logging

Free Magazines