[jira] [Updated] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter

2013-11-14 Thread Stefan Bodewig (JIRA) 

 [ 
https://issues.apache.org/jira/browse/LOG4NET-376?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Stefan Bodewig updated LOG4NET-376:
---

Fix Version/s: (was: 1.2.12)

 Race condition in AbsoluteTimeDateFormatter
 ---

 Key: LOG4NET-376
 URL: https://issues.apache.org/jira/browse/LOG4NET-376
 Project: Log4net
  Issue Type: Bug
Affects Versions: 1.2.11
Reporter: Stuart Lange

 AbsoluteTimeDateFormatter's caching of the to the second timestamp string 
 is not thread-safe.  It is possible for one thread to clear the check (that 
 this timestamp matches the currently cached to the second timestamp), but 
 then end up using an incorrect to the second timestamp string if another 
 thread has changed it in the meantime.
 In our organization, we see this bug fairly regularly because we have a mix 
 of real time loggers that immediately write out log lines and batching 
 loggers that defer logging to a background task that runs every second.  We 
 therefore regularly see log lines where the timestamp is off by a second or 
 two.
 The following unit tests demonstrates the bug:
 [TestFixture]
 [Explicit]
 public class Log4netTimestampBug
 {
 /// summary
 /// This test demonstrates a bug with the log4net default time 
 formatter (Iso8601DateFormatter)
 /// where the logged timestamp can be seconds off from the actual 
 input timestamp
 /// The bug is caused to a race condition in the base class 
 AbsoluteTimeDateFormatter
 /// because this class caches the timestamp string to the second but 
 it is possible for
 /// the timestamp as written by a different thread to sneak in and 
 be used by another
 /// thread erroneously (the checking and usage of this string is not 
 done under a lock, only
 /// its modification) 
 /// /summary
 [Test]
 public void Test()
 {
 var now = DateTime.Now;
 var times = Enumerable.Range(1, 100).Select(i = 
 now.AddMilliseconds(i)).ToList();
 var sb1 = new StringBuilder();
 var sb2 = new StringBuilder();
 var task1 = Task.Run(() = WriteAllTheTimes(times, new 
 StringWriter(sb1)));
 var task2 = Task.Delay(50).ContinueWith(t = 
 WriteAllTheTimes(times, new StringWriter(sb2)));
 Task.WaitAll(task1, task2);
 var task1Strings = GetTimeStrings(sb1);
 var task2Strings = GetTimeStrings(sb2);
 var diffs = Enumerable.Range(0, times.Count).Where(i = 
 task1Strings[i] != task2Strings[i]).ToList();
 Console.WriteLine(found {0} instances where the formatted 
 timestamps are not the same, diffs.Count);
 Console.WriteLine();
 var diffToLookAt = diffs.FirstOrDefault(i = i - 10  0  i + 10 
  times.Count);
 if (diffToLookAt != 0)
 {
 Console.WriteLine(Example Diff:);
 Console.WriteLine();
 Console.WriteLine(Index Original TimestampTask 1 
 Format Task 2 Format);
 for (int i = diffToLookAt - 10; i  diffToLookAt + 10; i++)
 {
 Console.WriteLine({0,-7}   {1}   {2}   {3}   {4}, i, 
 times[i].ToString(-MM-dd HH:mm:ss,fff),
   task1Strings[i], task2Strings[i], i == 
 diffToLookAt ?  DIFF HERE  : );
 }
 }
 CollectionAssert.AreEqual(task1Strings, task2Strings);
 }
 private static Liststring GetTimeStrings(StringBuilder sb1)
 {
 return sb1.ToString().Split(new[] {'\r', '\n'}, 
 StringSplitOptions.RemoveEmptyEntries).ToList();
 }
 private static void WriteAllTheTimes(IEnumerableDateTime times,
  TextWriter writer)
 {
 var formatter = new Iso8601DateFormatter();
 foreach (var t in times)
 {
 formatter.FormatDate(t, writer);
 writer.WriteLine();
 }
 }
 }



--
This message was sent by Atlassian JIRA
(v6.1#6144)

[LOG4NET-405 Test Mail] [Unicode (UTF-8)] [Unicode (UTF-8)] UTF8: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
ASCII:   
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [US-ASCII] [Unicode (UTF-8)] ASCII: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
UTF8:
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [US-ASCII] [Unicode (UTF-8)] UTF8: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
UTF8:
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [US-ASCII] [US-ASCII] ASCII: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
UTF8:
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [US-ASCII] [US-ASCII] ASCII: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
ASCII:   
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [US-ASCII] [Unicode (UTF-8)] ASCII: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
ASCII:   
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [Unicode (UTF-8)] [Unicode (UTF-8)] ASCII: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
UTF8:
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [Unicode (UTF-8)] [Unicode (UTF-8)] UTF8: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
UTF8:
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [Unicode (UTF-8)] [US-ASCII] UTF8: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
UTF8:
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [Unicode (UTF-8)] [US-ASCII] UTF8: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
ASCII:   
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [Unicode (UTF-8)] [US-ASCII] ASCII: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
UTF8:
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [US-ASCII] [US-ASCII] UTF8: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
ASCII:   
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

[LOG4NET-405 Test Mail] [US-ASCII] [US-ASCII] UTF8: !#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

2013-11-14 Thread dpsenner 
UTF8:
!#$%'()*+,-./0123456789:;=?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~

AW: LOG4NET-405 (was Re: [VOTE] Release Log4Net 1.2.13 based on RC2)

2013-11-14 Thread Dominik Psenner 
 Thought of that too, but I decided to let it be in UTF8 cause its the
most
 compatible format nowadays whereas ASCII is somewhat antique. What do
you
 think?

IIUC ASCII would have been the implicit body encoding for log4net 
1.2.12 so when looking for a backwards compatible default this would be
the most natural choice.

I'm not sure whether setting the encoding to UTF8 triggers some sort of
different handling inside of the framweork's SMTP code even if the test
was pure ASCII.  If it doesn't, then I'm fine with UTF8.

Maybe we should send two messages with a body only containing ASCII
letters and compare the raw messages created with encoding set to ASCII
or UTF8 respectively.

Agreed. FWIW, I found this:

http://w3techs.com/technologies/overview/character_encoding/all

and checking a few of my Gmail's mails it seems they default to UTF8. I've
just spammed test messages, this is the code:

static void Main(string[] args)
{
MailAddress from = new
MailAddress(dpsen...@gmail.com);
MailAddress to = new
MailAddress(log4net-dev@logging.apache.org);
string host = smtp.gmail.com;
int port = 25;
NetworkCredential networkCredentials = new
NetworkCredential(f...@gmail.com, bar);
bool enableSsl = true;

Encoding[] subjectEncodings = new Encoding[] {
Encoding.ASCII, Encoding.UTF8 };
Encoding[] bodyEncodings = new Encoding[] {
Encoding.ASCII, Encoding.UTF8 };
Listbyte content = new Listbyte();
for (byte i = 0x20; i = 0x7F; i++)
content.Add(i);
string[] subjects = new string[] { ASCII:\t +
Encoding.ASCII.GetString(content.ToArray()), UTF8:\t +
Encoding.UTF8.GetString(content.ToArray()) };
string[] bodies = new string[] { ASCII:\t +
Encoding.ASCII.GetString(content.ToArray()), UTF8:\t +
Encoding.UTF8.GetString(content.ToArray()) };
foreach (Encoding subjectEncoding in
subjectEncodings)
{
foreach (Encoding bodyEncoding in
bodyEncodings)
{
foreach (string subject in subjects)
{
foreach(string body in
bodies)
{
Console.WriteLine(@
SubjectEncoding={0}
BodyEncoding=   {1}
Subject={2}
Body=   {3}, subjectEncoding.EncodingName,
bodyEncoding.EncodingName, subject, body);

SendMail(from, to,
string.Format([LOG4NET-405 Test Mail] [{0}] [{1}] {2},
subjectEncoding.EncodingName, bodyEncoding.EncodingName, subject),
subjectEncoding, body, bodyEncoding, host, port, networkCredentials,
enableSsl);
}
}
}
}
Console.ReadKey();
}

private static void SendMail(MailAddress from, MailAddress
to, string subject, Encoding subjectEncoding, string body, Encoding
bodyEncoding, string host, int port, NetworkCredential credentials = null,
bool enableSsl = true, SmtpDeliveryMethod deliveryMethod =
SmtpDeliveryMethod.Network)
{
try
{

ServicePointManager.ServerCertificateValidationCallback = new
RemoteCertificateValidationCallback(TrustAllCertificatesPolicy);
using (SmtpClient client = new
SmtpClient(host, port))
{
client.Timeout = 30 * 1000; // 10
seconds
// set properties
client.DeliveryMethod =
deliveryMethod;
client.EnableSsl = enableSsl;
client.UseDefaultCredentials =
(credentials == null);
client.Credentials = credentials;
// send message
using (MailMessage msg = new
MailMessage())
{
msg.From = from;
msg.To.Add(to);

msg.Body = body;
msg.BodyEncoding =
bodyEncoding;

msg.Subject = subject;

Re: LOG4NET-405 (was Re: [VOTE] Release Log4Net 1.2.13 based on RC2)

2013-11-14 Thread Stefan Bodewig 
On 2013-11-14, Dominik Psenner wrote:

 I'm not sure whether setting the encoding to UTF8 triggers some sort of
 different handling inside of the framweork's SMTP code even if the test
 was pure ASCII.  If it doesn't, then I'm fine with UTF8.

 and checking a few of my Gmail's mails it seems they default to UTF8. I've
 just spammed test messages, this is the code:

OK, looks as if the main difference was UTF8 yields base64 encoding
while ASCII yields quoted printable.  In general any MUA should be able
to deal with either and the difference likely is no big deal.  I can
live with keeping the default at UTF8.

Stefan