[jira] [Updated] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter
[
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.13)
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
Fix For: 1.2.13, 1.3.0
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)
[jira] [Updated] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter
[
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: 1.2.13
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
Fix For: 1.2.13, 1.3.0
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)
[jira] [Updated] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter
[
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: 1.3.0
1.2.13
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
Fix For: 1.2.13, 1.3.0
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)
[jira] [Updated] (LOG4NET-376) Race condition in AbsoluteTimeDateFormatter
[
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)
