Vista - Re: log4net mysteriously stops logging

More comments inline...

"Jeroen Mostert" <jmostert@xxxxxx> wrote in message
news:47e56bef$0$14342$e4fe514c@xxxxxx<snip resolved issues>

I don't understand this: "my call only retrieves a logger *once*". We have
the definition of [log] defined at the top of the class, not in each method
that uses it. So is this a problem, because it's doing
GetCurrentMethod().DeclaringType? As I said before, I inherited this, so I'm
not sure if it's even right.

Here is the startup for our log4net; this is in Program.cs.

private static void Configlog4net()
{

string appDataFolder = ConfigManager.GetValue("LogFilePath");
string configFilePath = Path.Combine(appDataFolder,
"Log4netConfig.xml");

FileInfo configFile = new FileInfo(configFilePath);

if (!configFile.Exists)
{
//if they don't already have a config file, go find it and copy it
string logPath = Path.Combine(Application.StartupPath,
"Log4netConfig.xml");
if (File.Exists(logPath))
{
try
{
File.Copy(logPath, configFile.FullName);
XmlDocument document = new XmlDocument();
document.Load(configFile.FullName);
foreach (XmlNode node in
document.GetElementsByTagName("file"))
{
node.Attributes.GetNamedItem("value").Value =
Path.Combine(appDataFolder, "GoldMailLog.txt");
break;
}
document.Save(configFile.FullName);
}
catch (Exception ex)
{
throw ex;
}
}
else
{
throw new Exception("Could not find logging configuration
file.");
}
}
XmlConfigurator.Configure(configFile);
}

Here's some of the debugging stuff from log4net at startup:

log4net: XmlConfigurator: configuring repository
[log4net-default-repository] using file
[C:\Users\Jeanne\Documents\GoldMail\Log4netConfig.xml]
log4net: XmlConfigurator: configuring repository
[log4net-default-repository] using stream
log4net: XmlConfigurator: loading XML configuration
log4net: XmlConfigurator: Configuring Repository
[log4net-default-repository]
log4net: XmlHierarchyConfigurator: Configuration update mode [Merge].
log4net: XmlHierarchyConfigurator: Logger [root] Level string is [DEBUG].
log4net: XmlHierarchyConfigurator: Logger [root] level set to
[name="DEBUG",value=30000].
log4net: XmlHierarchyConfigurator: Loading Appender [ConsoleAppender] type:
[log4net.Appender.ConsoleAppender]
log4net: PatternParser: Converter [message] Option [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [newline] Option [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: XmlHierarchyConfigurator: Setting Property [ConversionPattern] to
String value [%date %-5level %logger (%L) [%ndc] - %message%newline]
log4net: PatternParser: Converter [date] Option [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [literal] Option [ ] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [level] Option [] Format
[min=5,max=2147483647,leftAlign=True]
log4net: PatternParser: Converter [literal] Option [ ] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [logger] Option [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [literal] Option [ (] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [L] Option [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [literal] Option [) [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [ndc] Option [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [literal] Option [] - ] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [message] Option [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: PatternParser: Converter [newline] Option [] Format
[min=-1,max=2147483647,leftAlign=False]
log4net: XmlHierarchyConfigurator: Setting Property [Layout] to object
[log4net.Layout.PatternLayout]
log4net: XmlHierarchyConfigurator: Created Appender [ConsoleAppender]
log4net: XmlHierarchyConfigurator: Adding appender named [ConsoleAppender]
to logger [root].
log4net: XmlHierarchyConfigurator: Loading Appender [RollingLogFileAppender]
type: [log4net.Appender.RollingFileAppender]
log4net: XmlHierarchyConfigurator: Setting Property [File] to String value
[C:\Users\Jeanne\Documents\GoldMail\GoldMailLog.txt]
log4net: XmlHierarchyConfigurator: Setting Property [StaticLogFileName] to
Boolean value [True]
(it goes on...)
Unfortunately, the debugging doesn't have any time stamps in it, so I can't
tie it to the actual log to see what it is doing. These are the debugging
statements right before the heirarchy shutdown was called.

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

log4net: DefaultRepositorySelector: Assembly [GMSound, 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_8d1f3aa9ab6946c1\GMSound.dll]

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

log4net: DefaultRepositorySelector: Assembly [GMSound, Version=3.1.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]
FMT: fmt
FRMTLEN: 16
Data:data
FMT: fmt
FRMTLEN: 16
Data:data

I have no idea what those last 6 lines are from or what they mean. Our
GMSound project has a lot of DirectX stuff in it, and a lot of objects
created and disposed; I'm not sure that's relevant, but thought I'd mention
it just in case.

I'm not using ConfigureAndWatch, I'm just using Configure. And none of the
AssemblyInfo.cs files access or reference log4net.

Any idea how I can figure out where in the code it's messing up my logging?
Is it probably in the GMSound project, since that's the last one that does
the whole "does not have a RespositoryAttribute..." stuff before the logging
gets shut down?

I can't imagine any external application writing to the config file. Would
it have to be something we have developed? Since the log files go to a
company-specific folder, wouldn't it be incredibly odd for someone else to
be writing to the same log? You can't run our app twice; we have implemented
the single-instance stuff.

Whenever what file changed? The configuration file doesn't change once the
user has run the application once. The QA person actually deleted the entire
folder and re-ran the application (which recreated the config file) and
tried again, and still has the problem.

Thanks for your help. I appreciate it.

RobinS.
GoldMail.com

RobinS wrote:<snip>Oh, my bad. I assumed it was done in each method individually, what with the
..GetCurrentMethod() call. But of course this even works as part of a field
initializer -- the "current method" will be the constructor. My assumptions
made an ass out of me.

Ignore this, then.
<snip>
OK, nothing special here either.
^ Note this. ^
^ Now note this! ^

It's using the *file that you're logging to* as the configuration file,
which quite obviously fails. Interesting, eh?

Now, why does it reconfigure itself, and why is it using the wrong file for
that? I have no idea, honestly. I pulled apart the source but found no
obvious wrongdoing.

At this point I would pull out a debugger and set a breakpoint on
log4net.Config.XmlConfigurator.Configure(ILoggerRepository, FileInfo), but
that demands a reproducible environment.

<snip>It might be, though it's unlikely. If there's some kind of error invoking
native DirectX stuff it could cause memory corruption, though corruption of
the kind where log4net spontaneously reconfigures itself with a wrong file
is hard to imagine (that said, stranger things have happened).
Curiouser and curiouser.
It's certainly a possibility.

OK, at this point things are so weird that I can't offer any more help
unless you paid for a flight and put me behind a computer with a debugger.

Set a breakpoint on the method I mentioned. The first call will be the
regular startup call; the second one should be the culprit and the stack
trace should be interesting. That's assuming that the debug version still
exhibits the problem. If it doesn't, then you may very well have memory
corruption on your hands, or a CLR bug, neither of which are fun.

To investigate *that*, you might try running your application with Managed
Debugging Assistants (MDAs) enabled. It will run much, much slower, but it
will also include lots of checks. There's a good article on them here:
http://msdn2.microsoft.com/en-us/magazine/cc163606.aspx

If you can't install VS on the target computer, you can simply use the
native debuggers (ntsd.exe is installed with every copy of Windows). These
have very limited support for managed code, but they will allow you to see
the MDA output.

--
J.

"Jeroen Mostert" <jmostert@xxxxxx> wrote in message
news:47e6956f$0$14355$e4fe514c@xxxxxx<snip>
Thanks very much, I will check it out and see what I can do. The other thing
that occurred to me is I can put in some trace statements, and they will
write to the debug log for log4net (because the trace statements are
redirected to a file), and using that I may be able to figure out *where*
it's happening.

That, and stepping through the code and using the breakpoint you
recommended.

I assume I can get the code for log4net from their website?

Thanks again for the advice and help. I'll report back when I solve the
problem.

RobinS.
GoldMail.lcom

"RobinS" <robins@xxxxxx> wrote in message
news:MqednVV_C__Go3ranZ2dnUVZ_sednZ2d@xxxxxxJust a follow-up. I attached the code for log4net, and found that we were,
indeed shutting down log4net, and starting it back up and passing it the
wrong file. The filename was pulled out of a config file we have, and it was
retrieving the wrong item. So as I suspected, it was our own darn fault.

Thanks for your help, Jeroen.

RobinS.
GoldMail.com

RobinS wrote:I'm happy your problem is solved and sad that it wasn't something more
interesting. Life is such an ambivalent affair...

--
J.

"Jeroen Mostert" <jmostert@xxxxxx> wrote in message
news:47f9bbd1$0$14343$e4fe514c@xxxxxxI have enough other problems to keep life interesting. I inherited some of
the weirdest code that transfers files up to a server using web services
that I've ever seen. The guy who wrote it is no longer with the company, so
I get the joy of figuring out why he did it the way he did it, and fixing
it. It's a good thing I like a challenge.

RobinS.