Return-Path: X-Original-To: apmail-logging-log4net-user-archive@www.apache.org Delivered-To: apmail-logging-log4net-user-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 7D542BDF8 for ; Thu, 12 Jan 2012 13:09:30 +0000 (UTC) Received: (qmail 91639 invoked by uid 500); 12 Jan 2012 13:09:22 -0000 Delivered-To: apmail-logging-log4net-user-archive@logging.apache.org Received: (qmail 90798 invoked by uid 500); 12 Jan 2012 13:08:55 -0000 Mailing-List: contact log4net-user-help@logging.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: Reply-To: "Log4NET User" List-Id: Delivered-To: mailing list log4net-user@logging.apache.org Received: (qmail 90756 invoked by uid 99); 12 Jan 2012 13:08:44 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 12 Jan 2012 13:08:44 +0000 X-ASF-Spam-Status: No, hits=4.7 required=5.0 tests=FREEMAIL_FORGED_REPLYTO,HTML_MESSAGE,RCVD_IN_DNSWL_NONE,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: local policy) Received: from [72.30.239.139] (HELO nm32-vm3.bullet.mail.bf1.yahoo.com) (72.30.239.139) by apache.org (qpsmtpd/0.29) with SMTP; Thu, 12 Jan 2012 13:08:34 +0000 Received: from [98.139.212.144] by nm32.bullet.mail.bf1.yahoo.com with NNFMP; 12 Jan 2012 13:08:12 -0000 Received: from [98.139.212.233] by tm1.bullet.mail.bf1.yahoo.com with NNFMP; 12 Jan 2012 13:08:12 -0000 Received: from [127.0.0.1] by omp1042.mail.bf1.yahoo.com with NNFMP; 12 Jan 2012 13:08:12 -0000 X-Yahoo-Newman-Property: ymail-3 X-Yahoo-Newman-Id: 533362.10983.bm@omp1042.mail.bf1.yahoo.com Received: (qmail 15420 invoked by uid 60001); 12 Jan 2012 13:08:12 -0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s1024; t=1326373692; bh=1RLgf6Ghd+to3ydtvKCW+p/Xu5WrlshrF5EKSuJSG+I=; h=X-YMail-OSG:Received:X-Mailer:References:Message-ID:Date:From:Reply-To:Subject:To:In-Reply-To:MIME-Version:Content-Type; b=aXjGX2T31CSB63T+3vFSbKYqIWPbog7YVEIkJm6GWAeV+KoSN4jON7GkUD85Anx19A2zSkdcSC0SUrf0ZJRcrvkgxE5sikuxV06koAorrtpH3pnknUd4iuOU4NDWmo/VhJLmtwVGO2cnv6YJpG1KC10jXIXBcl9GqU9/Qy9NKIo= DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=s1024; d=yahoo.com; h=X-YMail-OSG:Received:X-Mailer:References:Message-ID:Date:From:Reply-To:Subject:To:In-Reply-To:MIME-Version:Content-Type; b=XVO/4q3T3A59GVmE0SxgrO9mVPZ2HPLE/R2XLfXK3pnca3pwwt7Jlg9Dzqkv6m09ixHuXkPEb3M0NKqossyfnWJ7mDeZqF117+7Xt2JFsuDwZ3BzN7XY2y+rROtMt6s+miQIp2+Uz56XG1j5OIFj1yO4VMQBDgBFlhSoOKkYiyY=; X-YMail-OSG: EVQFu2sVM1lH00X3adjhwvO.LE3aBgcjkwmcB_ChPpq2W8N cWN8uxfWzBb8626NgxEn_Joit97gy8EdbHamtCor6M05BQlHXP0pRGN6ISdn D8GoPS4733RAcqNjQDPNxoA4lYogDTptIZD4TGGiSAV0Ldpz3_M7YuWvTxFx C5SlsZp6BfRTgFdwsi1tL2iSvVl.BPeLdxn5tEhHEcoAxKQojqxe_cemb3FN xdumFxuMhLoHeUUYgCIIy2_.Hk7njoWV4gSjIMiCnHhIXQ9JvEiFLgnRrGdU dNLJ5iL_b.Qq_d5FD4SBirci8UammUoKB60drhJE4DpiMzaq8prl3hyT8TAk dMxg830Eblugu60YLZfvCxUMwGsv4Xm3GvO_XzNZ2NMX92L.SzwhuMYasbyu SlNFYvDs.o.vQmlmDkAETccpjZgK4nT4vviqm_UY.eAsxfF.q4Flnh5XewlO zdZlqwRyJxqLrEJfx97UcAb2v5odl73eIMeWotdOVJl_XrZPM0nV7ZQXeMn6 YsTjBARsBqvQ8m1o.IxaBdYkl3Vd5PBmubxiGBPM- Received: from [98.229.35.107] by web161604.mail.bf1.yahoo.com via HTTP; Thu, 12 Jan 2012 05:08:12 PST X-Mailer: YahooMailWebService/0.8.115.331698 References: <7D22795796674073B1141A4CD5FE301B@jscottPC> Message-ID: <1326373692.95517.YahooMailNeo@web161604.mail.bf1.yahoo.com> Date: Thu, 12 Jan 2012 05:08:12 -0800 (PST) From: Todd Reply-To: Todd Subject: Re: Logger in ASP.NET stops after a few hours, won't restart until app is cycled To: Log4NET User In-Reply-To: <7D22795796674073B1141A4CD5FE301B@jscottPC> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="397762125-735817651-1326373692=:95517" X-Virus-Checked: Checked by ClamAV on apache.org --397762125-735817651-1326373692=:95517 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Hi Jim.=0A=C2=A0=0AWhat you're saying makes a lot of sense to me. I wasted = two days troubleshooting what turned out to be a permissions issue last wee= k because I wasn't aware that log4net would disable the appender upon conne= ction error. I was trying to log in a web app's startup, which runs under t= he pool's identity (I know that NOW) and in the global error handler which = was executing under the user's impersonated identity (which did have permis= sion). Because the pool had no permission to the database, I got nothing, e= ven for the user, and this was really hard to figure out.=0A=C2=A0=0AYou're= suggesting a solution that might work well in real world scenarios where e= verything isn't perfect. A connections to a DB could drop momentarily and t= hat probably shouldn't mean game over. I might want to see an entry indicat= ing previous failures, though. That would help troubleshooting, especially = if it's able to flush previous entries.=0A=C2=A0=0AI'm surprised there's an= y application blocking. I assume log4net was returning immediately and proc= essing requests on a background thread.=0A =0A=0A__________________________= ______=0A From: Jim Scott =0ATo: log4net-user@logging= .apache.org =0ASent: Wednesday, January 11, 2012 7:58 PM=0ASubject: Re: Log= ger in ASP.NET stops after a few hours, won't restart until app is cycled= =0A =0A=0A =0AFYI, here is the enhancements that I suggested back in Jan, = 2011 that I was =0Areferring to in my last email. =0A=0AI have been using t= he AdoNetAppender for a while now and =0Ahave a few issues with it. =0A1)I= f the database that it logs to goes offline it will =0Astop logging message= s until the application is restarted =0A=C2=B7You can overcome that issue = by setting ReconnectOnError but the problem with that is that if the datab= ase is still offline it will block your program thread until it times out = every time it tries to flush the events. =0A2)Since the =0AAdoNetAppender= derives from BufferAppenderSkeleton it buffers events before =0Awriting to= the DB. Not a bad idea unless you want to monitor the DB for =0Aexceptions= in real-time. So let=E2=80=99s say I set the default buffer size to 20 =0A= events. If I am monitoring the DB I won=E2=80=99t see any of the exceptions= till it hits =0Athe buffer size of 20 events. =0A=C2=B7The fix for me is t= o set the buffer to 1 event so that I get real-time results when an except= ion happens. However I am not taking advantage of buffering the events so = that the application thread returns quicker and writes to the DB less freq= uent. =0AHere is the behavior I want. =0A1)Set by default buffer size to 1= 00 =0A2)Set a buffer flush interval to 60 =0Aseconds =0A3)Set retry logic f= or DB connection in the event that the =0ADB is unavailable and cache the l= og events being written =0A=C2=A0 =0ASo here is an example of how it would= =0Awork. =0A=C2=A0 =0AWrite an exception to AdoNetAppender =0AEvent is bu= ffered =0AIf buffer exceeds 100 events or 60 seconds has elapsed =0Athe buf= fer will be flushed =0AIf the appender is unable to talk to the DB it marks= the =0Aconnection as failed and caches the events locally =0ANext write at= tempts looks to see if the retry time has =0Abeen exceeded and if so attemp= ts to write buffer to DB =0AAlso =0Aany local events previously cached from= a failure will be written as =0Awell. =0A=C2=A0 =0ASo now I am back to us= ing a buffer =0AI now see any exceptions at most 60 seconds after they =0Ah= appen =0AIf the DB goes down I now have retry logic for =0Aattempting to wr= ite the events (key is not every attempt so the application is =0Anot being= blocked on every write) =0A=C2=A0 =0ANow not being entirely familiar with= the source for =0ALog4Net I attempted to add these features and have it wo= rking. However not sure =0Aif my approach is the approach you would take fo= r including in your source. =0A=C2=A0 =0AIf anyone likes the features lis= ted above I would be =0Ahappy to provide the source changes. I did this by = creating a AdoNetAppenderEx =0Aclass that looks just like the AdoNetAppende= r but with my additions. =0A=C2=A0 =0AHowever I personally think the conc= ept of flushing =0Aevents on an interval should be coded up higher in the B= ufferAppenderSkeleton as =0Athe issue I don=E2=80=99t like is having to wai= t till the number of buffered events is =0Aexceeded. Would be nice to speci= fy another threshold for buffered events to be =0Atime based. =0A=C2=A0 = =0AThe retry logic however for the DB is essential but =0Adon=E2=80=99t wan= t it happening on every write but rather a retry after X seconds has =0Aela= psed since the last failed connection. --397762125-735817651-1326373692=:95517 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable
Hi Jim.
 
What you're saying makes a lot of= sense to me. I wasted two days troubleshooting what turned out to be a per= missions issue last week because I wasn't aware that log4net would disable = the appender upon connection error. I was trying to log in a web app's star= tup, which runs under the pool's identity (I know that NOW) and in the glob= al error handler which was executing under the user's impersonated identity= (which did have permission). Because the pool had no permission to the dat= abase, I got nothing, even for the user, and this was really hard to figure= out.
 
You're suggestin= g a solution that might work well in real world scenarios where everything = isn't perfect. A connections to a DB could drop momentarily and that probably shouldn't mean game over. I might want to see an entry indicating= previous failures, though. That would help troubleshooting, especially if = it's able to flush previous entries.
 
I'm surprised there's any application blocking. I assume log= 4net was returning immediately and processing requests on a background thre= ad.

From: Jim Scott <jscott@infoco= nex.com>
To: log4net-user@logging.apache.org
Sent: Wednesday, January 11, 2012 7:58 PM
Subject: Re: Logger in ASP.NET stops after = a few hours, won't restart until app is cycled

=0A
=0A =0A =0A=0A=0A=
=0A
=0A
=0A
FYI, here is the enhancem= ents that I suggested back in Jan, 2011 that I was =0Areferring to in my la= st email.
=0A
 
=0A
=0A
I have been using the AdoNetAppender for a while now and =0Ahave a few i= ssues with it.
=0A
=0A
1)<= font face=3D"Times New Roman"> If the databa= se that it logs to goes offline it will =0Astop logging messages until the = application is restarted
=0A
=0A
=C2=B7 You can overcome that issue by setting =0A ReconnectOnError = but the problem with that is that if the database is still =0A offline it = will block your program thread until it times out every time it =0A tries = to flush the events.
=0A
=0A
2) Since the =0AAdoNetAppender derives from Buff= erAppenderSkeleton it buffers events before =0Awriting to the DB. Not a bad= idea unless you want to monitor the DB for =0Aexceptions in real-time. So = let=E2=80=99s say I set the default buffer size to 20 =0Aevents. If I am mo= nitoring the DB I won=E2=80=99t see any of the exceptions till it hits =0At= he buffer size of 20 events.
=0A
=0A
=C2=B7 The fix for me is to set the buffer to 1 event so that =0A = I get real-time results when an exception happens. However I am not taking = =0A advantage of buffering the events so that the application thread retur= ns =0A quicker and writes to the DB less frequent.
=0A
Here is the behavior I want.
=0A
=0A
1) <= /span>Set by default buffer size to = 100
=0A
2) <= span>Set a buffer flush interval to 60 =0A= seconds
=0A
3) Set retry logic for DB connection i= n the event that the =0ADB is unavailable and cache the log events being wr= itten
=0A
 
=0A
= =0A
So here is an example of how it would = =0Awork.
=0A
 
=0A
=0A
Write an exception to AdoNetAppender<= /div>=0A
Event is buffered=0A
If buffer exceeds 100 events or 60 sec= onds has elapsed =0Athe buffer will be flushed
=0A
If the appender is unable to talk to the DB it ma= rks the =0Aconnection as failed and caches the events locally=
=0A
Next write attempts looks to see i= f the retry time has =0Abeen exceeded and if so attempts to write buffer to= DB
=0A
Also =0Aany local events previously cached from a = failure will be written as =0Awell.
=0A
 
=0A
=0A
So now I am back to using a buf= fer
=0A
I now see any exc= eptions at most 60 seconds after they =0Ahappen
=0A
If the DB goes down I now have retry logic for = =0Aattempting to write the events (key is not every attempt so the applicat= ion is =0Anot being blocked on every write)
=0A
=0A
 
=0A
Now not being entirely familiar with the source for =0ALog4Net I attemp= ted to add these features and have it working. However not sure =0Aif my ap= proach is the approach you would take for including in your source. =0A
=0A
 
=0A
=0A
If anyone likes the features listed above I would be =0Ahappy t= o provide the source changes. I did this by creating a AdoNetAppenderEx =0A= class that looks just like the AdoNetAppender but with my additions. =0A
=0A
 
=0A
=0A
However I personally think the concept of flushing =0Aevents o= n an interval should be coded up higher in the BufferAppenderSkeleton as = =0Athe issue I don=E2=80=99t like is having to wait till the number of buff= ered events is =0Aexceeded. Would be nice to specify another threshold for = buffered events to be =0Atime based.
=0A
 =0A
=0A
The retry logic however= for the DB is essential but =0Adon=E2=80=99t want it happening on every wr= ite but rather a retry after X seconds has =0Aelapsed since the last failed= connection.
=0A
=0A
 
<= /div>
=0A


--397762125-735817651-1326373692=:95517--