From 1ffeffce412ea4939b7a8159b4825225e71d3853 Mon Sep 17 00:00:00 2001 From: Levi Broderick Date: Wed, 22 Jul 2020 22:24:22 -0700 Subject: [PATCH 1/7] Add BinaryFormatter auditing EventSource --- ...em.Runtime.Serialization.Formatters.csproj | 1 + .../Formatters/Binary/BinaryFormatter.Core.cs | 21 +- .../Binary/BinaryFormatterEventSource.cs | 158 +++++++++++ .../Formatters/Binary/BinaryObjectInfo.cs | 7 +- .../tests/BinaryFormatterEventSourceTests.cs | 254 ++++++++++++++++++ ...time.Serialization.Formatters.Tests.csproj | 1 + 6 files changed, 437 insertions(+), 5 deletions(-) create mode 100644 src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs create mode 100644 src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System.Runtime.Serialization.Formatters.csproj b/src/libraries/System.Runtime.Serialization.Formatters/src/System.Runtime.Serialization.Formatters.csproj index dba845f2eeb90a..124a497c463795 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/src/System.Runtime.Serialization.Formatters.csproj +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System.Runtime.Serialization.Formatters.csproj @@ -61,6 +61,7 @@ + diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatter.Core.cs b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatter.Core.cs index 95f281f6339782..bcea27073810ce 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatter.Core.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatter.Core.cs @@ -39,6 +39,7 @@ public object Deserialize(Stream serializationStream) }; try { + BinaryFormatterEventSource.Log.DeserializationStarted(); var parser = new BinaryParser(serializationStream, reader); return reader.Deserialize(parser); } @@ -50,6 +51,10 @@ public object Deserialize(Stream serializationStream) { throw new SerializationException(SR.Serialization_CorruptedStream, e); } + finally + { + BinaryFormatterEventSource.Log.DeserializationEnded(); + } } [Obsolete(Obsoletions.BinaryFormatterMessage, DiagnosticId = Obsoletions.BinaryFormatterDiagId, UrlFormat = Obsoletions.SharedUrlFormat)] @@ -73,10 +78,18 @@ public void Serialize(Stream serializationStream, object graph) _assemblyFormat = _assemblyFormat, }; - var sow = new ObjectWriter(_surrogates, _context, formatterEnums, _binder); - BinaryFormatterWriter binaryWriter = new BinaryFormatterWriter(serializationStream, sow, _typeFormat); - sow.Serialize(graph, binaryWriter); - _crossAppDomainArray = sow._crossAppDomainArray; + try + { + BinaryFormatterEventSource.Log.SerializationStarted(); + var sow = new ObjectWriter(_surrogates, _context, formatterEnums, _binder); + BinaryFormatterWriter binaryWriter = new BinaryFormatterWriter(serializationStream, sow, _typeFormat); + sow.Serialize(graph, binaryWriter); + _crossAppDomainArray = sow._crossAppDomainArray; + } + finally + { + BinaryFormatterEventSource.Log.SerializationEnded(); + } } } } diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs new file mode 100644 index 00000000000000..9afcf959e62dfd --- /dev/null +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs @@ -0,0 +1,158 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Threading; + +namespace System.Runtime.Serialization.Formatters.Binary +{ + [EventSource( + Name = "System.Runtime.Serialization.Formatters.Binary.BinaryFormatterEventSource", + LocalizationResources = "FxResources.System.Runtime.Serialization.Formatters.SR")] + internal sealed class BinaryFormatterEventSource : EventSource + { + private const int EventId_SerializationStarted = 10; + private const int EventId_SerializationEnded = 11; + private const int EventId_SerializingObject = 12; + private const int EventId_DeserializationStarted = 20; + private const int EventId_DeserializationEnded = 21; + private const int EventId_DeserializingObject = 22; + + // Used to keep track of whether a write operation is in progress. It's + // possible the listener itself uses BinaryFormatter to write to a log, + // and if this is the case we suppress our own logging events so that we + // enter an infinite recursion scenario. + private static readonly AsyncLocal _writeInProgress = new AsyncLocal(); + + public static readonly BinaryFormatterEventSource Log = new BinaryFormatterEventSource(); + + private BinaryFormatterEventSource() + { + } + + [Event(EventId_SerializationStarted, Opcode = EventOpcode.Start, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] + public void SerializationStarted() + { + if (IsEnabled(EventLevel.Informational, Keywords.Serialization) && !_writeInProgress.Value) + { + try + { + _writeInProgress.Value = true; + WriteEvent(EventId_SerializationStarted); + } + finally + { + _writeInProgress.Value = false; + } + } + } + + [Event(EventId_SerializationEnded, Opcode = EventOpcode.Stop, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] + public void SerializationEnded() + { + if (IsEnabled(EventLevel.Informational, Keywords.Serialization) && !_writeInProgress.Value) + { + try + { + _writeInProgress.Value = true; + WriteEvent(EventId_SerializationEnded); + } + finally + { + _writeInProgress.Value = false; + } + } + } + + [NonEvent] + public void SerializingObject(Type type) + { + Debug.Assert(type != null); + + if (IsEnabled(EventLevel.Informational, Keywords.Serialization) && !_writeInProgress.Value) + { + try + { + _writeInProgress.Value = true; + SerializingObject(type.AssemblyQualifiedName); + } + finally + { + _writeInProgress.Value = false; + } + } + } + + [Event(EventId_SerializingObject, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] + private void SerializingObject(string? typeName) + { + WriteEvent(EventId_SerializingObject, typeName); + } + + [Event(EventId_DeserializationStarted, Opcode = EventOpcode.Start, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] + public void DeserializationStarted() + { + if (IsEnabled(EventLevel.Informational, Keywords.Deserialization) && !_writeInProgress.Value) + { + try + { + _writeInProgress.Value = true; + WriteEvent(EventId_DeserializationStarted); + } + finally + { + _writeInProgress.Value = false; + } + } + } + + [Event(EventId_DeserializationEnded, Opcode = EventOpcode.Stop, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] + public void DeserializationEnded() + { + if (IsEnabled(EventLevel.Informational, Keywords.Deserialization) && !_writeInProgress.Value) + { + try + { + _writeInProgress.Value = true; + WriteEvent(EventId_DeserializationEnded); + } + finally + { + _writeInProgress.Value = false; + } + } + } + + [NonEvent] + public void DeserializingObject(Type type) + { + Debug.Assert(type != null); + + if (IsEnabled(EventLevel.Informational, Keywords.Deserialization) && !_writeInProgress.Value) + { + try + { + _writeInProgress.Value = true; + DeserializingObject(type.AssemblyQualifiedName); + } + finally + { + _writeInProgress.Value = false; + } + } + } + + [Event(EventId_DeserializingObject, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] + private void DeserializingObject(string? typeName) + { + WriteEvent(EventId_DeserializingObject, typeName); + } + + public class Keywords + { + public const EventKeywords Serialization = (EventKeywords)1; + public const EventKeywords Deserialization = (EventKeywords)2; + } + } +} diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryObjectInfo.cs b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryObjectInfo.cs index c87d6a6fad6034..64f4e6ddcd830d 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryObjectInfo.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryObjectInfo.cs @@ -268,8 +268,11 @@ private void InitMemberInfo() internal string GetAssemblyString() => _binderAssemblyString ?? _cache._assemblyString; - private void InvokeSerializationBinder(SerializationBinder? binder) => + private void InvokeSerializationBinder(SerializationBinder? binder) + { + BinaryFormatterEventSource.Log.SerializingObject(_objectType!); binder?.BindToName(_objectType!, out _binderAssemblyString, out _binderTypeName); + } internal void GetMemberInfo(out string[]? outMemberNames, out Type[]? outMemberTypes, out object?[]? outMemberData) { @@ -392,6 +395,8 @@ internal void Init(Type? objectType, string[] memberNames, Type[]? memberTypes, private void InitReadConstructor(Type objectType, ISurrogateSelector? surrogateSelector, StreamingContext context) { + BinaryFormatterEventSource.Log.DeserializingObject(objectType); + if (objectType.IsArray) { InitNoMembers(); diff --git a/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs b/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs new file mode 100644 index 00000000000000..6d89ae32791fca --- /dev/null +++ b/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs @@ -0,0 +1,254 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Collections.Generic; +using System.Diagnostics.Tracing; +using System.IO; +using System.Linq; +using System.Runtime.Serialization.Formatters.Binary; +using System.Threading; +using Xunit; + +namespace System.Runtime.Serialization.Formatters.Tests +{ + [ConditionalClass(typeof(PlatformDetection), nameof(PlatformDetection.IsBinaryFormatterSupported))] + public static class BinaryFormatterEventSourceTests + { + private const string BinaryFormatterEventSourceName = "System.Runtime.Serialization.Formatters.Binary.BinaryFormatterEventSource"; + + [Fact] + public static void RecordsSerialization() + { + LoggingEventListener listener = new LoggingEventListener(); + + BinaryFormatter formatter = new BinaryFormatter(); + formatter.Serialize(Stream.Null, CreatePerson()); + listener.Dispose(); + + string[] expected = new string[] + { + "SerializationStarted [Start, 00000001]: ", + "SerializingObject [Info, 00000001]: " + typeof(Person).AssemblyQualifiedName, + "SerializingObject [Info, 00000001]: " + typeof(Address).AssemblyQualifiedName, + "SerializationEnded [Stop, 00000001]: ", + }; + + Assert.Equal(expected, listener.Log); + } + + [Fact] + public static void RecordsDeserialization() + { + MemoryStream ms = new MemoryStream(); + BinaryFormatter formatter = new BinaryFormatter(); + formatter.Serialize(ms, CreatePerson()); + ms.Position = 0; + + LoggingEventListener listener = new LoggingEventListener(); + formatter.Deserialize(ms); + listener.Dispose(); + + string[] expected = new string[] + { + "DeserializationStarted [Start, 00000002]: ", + "DeserializingObject [Info, 00000002]: " + typeof(Person).AssemblyQualifiedName, + "DeserializingObject [Info, 00000002]: " + typeof(Address).AssemblyQualifiedName, + "DeserializationEnded [Stop, 00000002]: ", + }; + + Assert.Equal(expected, listener.Log); + } + + [Fact] + public static void RecordsNestedSerializationCalls() + { + // First, serialization + + LoggingEventListener listener = new LoggingEventListener(); + + MemoryStream ms = new MemoryStream(); + BinaryFormatter formatter = new BinaryFormatter(); + formatter.Serialize(ms, new ClassWithNestedDeserialization()); + ms.Position = 0; + + string[] expected = new string[] + { + "SerializationStarted [Start, 00000001]: ", + "SerializingObject [Info, 00000001]: " + typeof(ClassWithNestedDeserialization).AssemblyQualifiedName, + "SerializationStarted [Start, 00000001]: ", + "SerializingObject [Info, 00000001]: " + typeof(Address).AssemblyQualifiedName, + "SerializationEnded [Stop, 00000001]: ", + "SerializationEnded [Stop, 00000001]: ", + }; + + Assert.Equal(expected, listener.Log); + listener.Log.Clear(); + + // Then, deserialization + + ms.Position = 0; + formatter.Deserialize(ms); + listener.Dispose(); + + expected = new string[] + { + "DeserializationStarted [Start, 00000002]: ", + "DeserializingObject [Info, 00000002]: " + typeof(ClassWithNestedDeserialization).AssemblyQualifiedName, + "DeserializationStarted [Start, 00000002]: ", + "DeserializingObject [Info, 00000002]: " + typeof(Address).AssemblyQualifiedName, + "DeserializationEnded [Stop, 00000002]: ", + "DeserializationEnded [Stop, 00000002]: ", + }; + + Assert.Equal(expected, listener.Log); + } + + [Fact] + public static void DoesNotRecordRecursiveSerializationPerformedByEventListener() + { + // First, serialization + + LoggingEventListener listener = new LoggingEventListener(); + listener.EventWritten += (source, args) => listener.Log.Add("Callback fired."); + listener.EventWritten += (source, args) => new BinaryFormatter().Serialize(Stream.Null, CreatePerson()); + + MemoryStream ms = new MemoryStream(); + BinaryFormatter formatter = new BinaryFormatter(); + formatter.Serialize(ms, CreatePerson()); + ms.Position = 0; + + string[] expected = new string[] + { + "SerializationStarted [Start, 00000001]: ", + "Callback fired.", + "SerializingObject [Info, 00000001]: " + typeof(Person).AssemblyQualifiedName, + "Callback fired.", + "SerializingObject [Info, 00000001]: " + typeof(Address).AssemblyQualifiedName, + "Callback fired.", + "SerializationEnded [Stop, 00000001]: ", + "Callback fired.", + }; + + Assert.Equal(expected, listener.Log); + listener.Log.Clear(); + + // Then, deserialization + + ms.Position = 0; + formatter.Deserialize(ms); + listener.Dispose(); + + expected = new string[] + { + "DeserializationStarted [Start, 00000002]: ", + "Callback fired.", + "DeserializingObject [Info, 00000002]: " + typeof(Person).AssemblyQualifiedName, + "Callback fired.", + "DeserializingObject [Info, 00000002]: " + typeof(Address).AssemblyQualifiedName, + "Callback fired.", + "DeserializationEnded [Stop, 00000002]: ", + "Callback fired.", + }; + + Assert.Equal(expected, listener.Log); + } + + private static Person CreatePerson() + { + return new Person() + { + Name = "Some Chap", + HomeAddress = new Address() + { + Street = "123 Anywhere Ln", + City = "Anywhere ST 00000 United States" + } + }; + } + + private sealed class LoggingEventListener : EventListener + { + private readonly Thread _activeThread = Thread.CurrentThread; + internal readonly List Log = new List(); + + private void AddToLog(FormattableString message) + { + Log.Add(FormattableString.Invariant(message)); + } + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == BinaryFormatterEventSourceName) + { + EnableEvents(eventSource, EventLevel.Verbose); + } + + base.OnEventSourceCreated(eventSource); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + // The test project is parallelized. We want to filter to only events that fired + // on the current thread, otherwise we could throw off the test results. + + if (Thread.CurrentThread != _activeThread) + { + return; + } + + AddToLog($"{eventData.EventName} [{eventData.Opcode}, {(int)eventData.Keywords & int.MaxValue:X8}]: {ParsePayload(eventData.Payload)}"); + base.OnEventWritten(eventData); + } + + private static string ParsePayload(IReadOnlyCollection collection) + { + if (collection?.Count > 0) + { + return string.Join("; ", collection.Select(o => o?.ToString() ?? "")); + } + else + { + return ""; + } + } + } + + [Serializable] + private class Person + { + public string Name { get; set; } + public Address HomeAddress { get; set; } + } + + [Serializable] + private class Address + { + public string Street { get; set; } + public string City { get; set; } + } + + [Serializable] + public class ClassWithNestedDeserialization : ISerializable + { + public ClassWithNestedDeserialization() + { + } + + protected ClassWithNestedDeserialization(SerializationInfo info, StreamingContext context) + { + byte[] serializedData = (byte[])info.GetValue("SomeField", typeof(byte[])); + MemoryStream ms = new MemoryStream(serializedData); + BinaryFormatter formatter = new BinaryFormatter(); + formatter.Deserialize(ms); // should deserialize an 'Address' instance + } + + public void GetObjectData(SerializationInfo info, StreamingContext context) + { + MemoryStream ms = new MemoryStream(); + BinaryFormatter formatter = new BinaryFormatter(); + formatter.Serialize(ms, new Address()); + info.AddValue("SomeField", ms.ToArray()); + } + } + } +} diff --git a/src/libraries/System.Runtime.Serialization.Formatters/tests/System.Runtime.Serialization.Formatters.Tests.csproj b/src/libraries/System.Runtime.Serialization.Formatters/tests/System.Runtime.Serialization.Formatters.Tests.csproj index 7e37cb04eed79f..0e60cd212ab42a 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/tests/System.Runtime.Serialization.Formatters.Tests.csproj +++ b/src/libraries/System.Runtime.Serialization.Formatters/tests/System.Runtime.Serialization.Formatters.Tests.csproj @@ -5,6 +5,7 @@ $(NetCoreAppCurrent)-Windows_NT;$(NetCoreAppCurrent)-FreeBSD;$(NetCoreAppCurrent)-illumos;$(NetCoreAppCurrent)-Solaris;$(NetCoreAppCurrent)-Linux;$(NetCoreAppCurrent)-OSX;$(NetCoreAppCurrent)-iOS;$(NetCoreAppCurrent)-tvOS;net48 + From 3fb9e02d254c63bf4ad43287e9f262f804ef85b7 Mon Sep 17 00:00:00 2001 From: Levi Broderick Date: Wed, 29 Jul 2020 10:44:51 -0700 Subject: [PATCH 2/7] PR feedback: rename Started -> Start, Ended -> Stop --- .../Formatters/Binary/BinaryFormatter.Core.cs | 8 ++--- .../Binary/BinaryFormatterEventSource.cs | 32 +++++++++---------- .../tests/BinaryFormatterEventSourceTests.cs | 32 +++++++++---------- 3 files changed, 36 insertions(+), 36 deletions(-) diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatter.Core.cs b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatter.Core.cs index bcea27073810ce..939b78ad9535dc 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatter.Core.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatter.Core.cs @@ -39,7 +39,7 @@ public object Deserialize(Stream serializationStream) }; try { - BinaryFormatterEventSource.Log.DeserializationStarted(); + BinaryFormatterEventSource.Log.DeserializationStart(); var parser = new BinaryParser(serializationStream, reader); return reader.Deserialize(parser); } @@ -53,7 +53,7 @@ public object Deserialize(Stream serializationStream) } finally { - BinaryFormatterEventSource.Log.DeserializationEnded(); + BinaryFormatterEventSource.Log.DeserializationStop(); } } @@ -80,7 +80,7 @@ public void Serialize(Stream serializationStream, object graph) try { - BinaryFormatterEventSource.Log.SerializationStarted(); + BinaryFormatterEventSource.Log.SerializationStart(); var sow = new ObjectWriter(_surrogates, _context, formatterEnums, _binder); BinaryFormatterWriter binaryWriter = new BinaryFormatterWriter(serializationStream, sow, _typeFormat); sow.Serialize(graph, binaryWriter); @@ -88,7 +88,7 @@ public void Serialize(Stream serializationStream, object graph) } finally { - BinaryFormatterEventSource.Log.SerializationEnded(); + BinaryFormatterEventSource.Log.SerializationStop(); } } } diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs index 9afcf959e62dfd..05780d1aef715c 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs @@ -12,11 +12,11 @@ namespace System.Runtime.Serialization.Formatters.Binary LocalizationResources = "FxResources.System.Runtime.Serialization.Formatters.SR")] internal sealed class BinaryFormatterEventSource : EventSource { - private const int EventId_SerializationStarted = 10; - private const int EventId_SerializationEnded = 11; + private const int EventId_SerializationStart = 10; + private const int EventId_SerializationStop = 11; private const int EventId_SerializingObject = 12; - private const int EventId_DeserializationStarted = 20; - private const int EventId_DeserializationEnded = 21; + private const int EventId_DeserializationStart = 20; + private const int EventId_DeserializationStop = 21; private const int EventId_DeserializingObject = 22; // Used to keep track of whether a write operation is in progress. It's @@ -31,15 +31,15 @@ private BinaryFormatterEventSource() { } - [Event(EventId_SerializationStarted, Opcode = EventOpcode.Start, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] - public void SerializationStarted() + [Event(EventId_SerializationStart, Opcode = EventOpcode.Start, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] + public void SerializationStart() { if (IsEnabled(EventLevel.Informational, Keywords.Serialization) && !_writeInProgress.Value) { try { _writeInProgress.Value = true; - WriteEvent(EventId_SerializationStarted); + WriteEvent(EventId_SerializationStart); } finally { @@ -48,15 +48,15 @@ public void SerializationStarted() } } - [Event(EventId_SerializationEnded, Opcode = EventOpcode.Stop, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] - public void SerializationEnded() + [Event(EventId_SerializationStop, Opcode = EventOpcode.Stop, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] + public void SerializationStop() { if (IsEnabled(EventLevel.Informational, Keywords.Serialization) && !_writeInProgress.Value) { try { _writeInProgress.Value = true; - WriteEvent(EventId_SerializationEnded); + WriteEvent(EventId_SerializationStop); } finally { @@ -90,15 +90,15 @@ private void SerializingObject(string? typeName) WriteEvent(EventId_SerializingObject, typeName); } - [Event(EventId_DeserializationStarted, Opcode = EventOpcode.Start, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] - public void DeserializationStarted() + [Event(EventId_DeserializationStart, Opcode = EventOpcode.Start, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] + public void DeserializationStart() { if (IsEnabled(EventLevel.Informational, Keywords.Deserialization) && !_writeInProgress.Value) { try { _writeInProgress.Value = true; - WriteEvent(EventId_DeserializationStarted); + WriteEvent(EventId_DeserializationStart); } finally { @@ -107,15 +107,15 @@ public void DeserializationStarted() } } - [Event(EventId_DeserializationEnded, Opcode = EventOpcode.Stop, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] - public void DeserializationEnded() + [Event(EventId_DeserializationStop, Opcode = EventOpcode.Stop, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] + public void DeserializationStop() { if (IsEnabled(EventLevel.Informational, Keywords.Deserialization) && !_writeInProgress.Value) { try { _writeInProgress.Value = true; - WriteEvent(EventId_DeserializationEnded); + WriteEvent(EventId_DeserializationStop); } finally { diff --git a/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs b/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs index 6d89ae32791fca..d7c86bdd7daefc 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs @@ -27,10 +27,10 @@ public static void RecordsSerialization() string[] expected = new string[] { - "SerializationStarted [Start, 00000001]: ", + "SerializationStart [Start, 00000001]: ", "SerializingObject [Info, 00000001]: " + typeof(Person).AssemblyQualifiedName, "SerializingObject [Info, 00000001]: " + typeof(Address).AssemblyQualifiedName, - "SerializationEnded [Stop, 00000001]: ", + "SerializationStop [Stop, 00000001]: ", }; Assert.Equal(expected, listener.Log); @@ -50,10 +50,10 @@ public static void RecordsDeserialization() string[] expected = new string[] { - "DeserializationStarted [Start, 00000002]: ", + "DeserializationStart [Start, 00000002]: ", "DeserializingObject [Info, 00000002]: " + typeof(Person).AssemblyQualifiedName, "DeserializingObject [Info, 00000002]: " + typeof(Address).AssemblyQualifiedName, - "DeserializationEnded [Stop, 00000002]: ", + "DeserializationStop [Stop, 00000002]: ", }; Assert.Equal(expected, listener.Log); @@ -73,12 +73,12 @@ public static void RecordsNestedSerializationCalls() string[] expected = new string[] { - "SerializationStarted [Start, 00000001]: ", + "SerializationStart [Start, 00000001]: ", "SerializingObject [Info, 00000001]: " + typeof(ClassWithNestedDeserialization).AssemblyQualifiedName, - "SerializationStarted [Start, 00000001]: ", + "SerializationStart [Start, 00000001]: ", "SerializingObject [Info, 00000001]: " + typeof(Address).AssemblyQualifiedName, - "SerializationEnded [Stop, 00000001]: ", - "SerializationEnded [Stop, 00000001]: ", + "SerializationStop [Stop, 00000001]: ", + "SerializationStop [Stop, 00000001]: ", }; Assert.Equal(expected, listener.Log); @@ -92,12 +92,12 @@ public static void RecordsNestedSerializationCalls() expected = new string[] { - "DeserializationStarted [Start, 00000002]: ", + "DeserializationStart [Start, 00000002]: ", "DeserializingObject [Info, 00000002]: " + typeof(ClassWithNestedDeserialization).AssemblyQualifiedName, - "DeserializationStarted [Start, 00000002]: ", + "DeserializationStart [Start, 00000002]: ", "DeserializingObject [Info, 00000002]: " + typeof(Address).AssemblyQualifiedName, - "DeserializationEnded [Stop, 00000002]: ", - "DeserializationEnded [Stop, 00000002]: ", + "DeserializationStop [Stop, 00000002]: ", + "DeserializationStop [Stop, 00000002]: ", }; Assert.Equal(expected, listener.Log); @@ -119,13 +119,13 @@ public static void DoesNotRecordRecursiveSerializationPerformedByEventListener() string[] expected = new string[] { - "SerializationStarted [Start, 00000001]: ", + "SerializationStart [Start, 00000001]: ", "Callback fired.", "SerializingObject [Info, 00000001]: " + typeof(Person).AssemblyQualifiedName, "Callback fired.", "SerializingObject [Info, 00000001]: " + typeof(Address).AssemblyQualifiedName, "Callback fired.", - "SerializationEnded [Stop, 00000001]: ", + "SerializationStop [Stop, 00000001]: ", "Callback fired.", }; @@ -140,13 +140,13 @@ public static void DoesNotRecordRecursiveSerializationPerformedByEventListener() expected = new string[] { - "DeserializationStarted [Start, 00000002]: ", + "DeserializationStart [Start, 00000002]: ", "Callback fired.", "DeserializingObject [Info, 00000002]: " + typeof(Person).AssemblyQualifiedName, "Callback fired.", "DeserializingObject [Info, 00000002]: " + typeof(Address).AssemblyQualifiedName, "Callback fired.", - "DeserializationEnded [Stop, 00000002]: ", + "DeserializationStop [Stop, 00000002]: ", "Callback fired.", }; From a99f7cf33ceeb70cfd3e67d717578a58a255a108 Mon Sep 17 00:00:00 2001 From: Levi Broderick Date: Wed, 29 Jul 2020 10:47:06 -0700 Subject: [PATCH 3/7] PR feedback: remove EventSource localization --- .../Formatters/Binary/BinaryFormatterEventSource.cs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs index 05780d1aef715c..1331c75b09d40f 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs @@ -8,8 +8,7 @@ namespace System.Runtime.Serialization.Formatters.Binary { [EventSource( - Name = "System.Runtime.Serialization.Formatters.Binary.BinaryFormatterEventSource", - LocalizationResources = "FxResources.System.Runtime.Serialization.Formatters.SR")] + Name = "System.Runtime.Serialization.Formatters.Binary.BinaryFormatterEventSource")] internal sealed class BinaryFormatterEventSource : EventSource { private const int EventId_SerializationStart = 10; From 8b8cc85b52c6716192c587f8b682288a26c36b6d Mon Sep 17 00:00:00 2001 From: Levi Broderick Date: Wed, 29 Jul 2020 10:50:09 -0700 Subject: [PATCH 4/7] PR feedback: remove anti-recursion checks --- .../Binary/BinaryFormatterEventSource.cs | 79 +++---------------- .../tests/BinaryFormatterEventSourceTests.cs | 50 ------------ 2 files changed, 12 insertions(+), 117 deletions(-) diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs index 1331c75b09d40f..5f89298f5ec15c 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs @@ -3,7 +3,6 @@ using System.Diagnostics; using System.Diagnostics.Tracing; -using System.Threading; namespace System.Runtime.Serialization.Formatters.Binary { @@ -18,12 +17,6 @@ internal sealed class BinaryFormatterEventSource : EventSource private const int EventId_DeserializationStop = 21; private const int EventId_DeserializingObject = 22; - // Used to keep track of whether a write operation is in progress. It's - // possible the listener itself uses BinaryFormatter to write to a log, - // and if this is the case we suppress our own logging events so that we - // enter an infinite recursion scenario. - private static readonly AsyncLocal _writeInProgress = new AsyncLocal(); - public static readonly BinaryFormatterEventSource Log = new BinaryFormatterEventSource(); private BinaryFormatterEventSource() @@ -33,34 +26,18 @@ private BinaryFormatterEventSource() [Event(EventId_SerializationStart, Opcode = EventOpcode.Start, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] public void SerializationStart() { - if (IsEnabled(EventLevel.Informational, Keywords.Serialization) && !_writeInProgress.Value) + if (IsEnabled(EventLevel.Informational, Keywords.Serialization)) { - try - { - _writeInProgress.Value = true; - WriteEvent(EventId_SerializationStart); - } - finally - { - _writeInProgress.Value = false; - } + WriteEvent(EventId_SerializationStart); } } [Event(EventId_SerializationStop, Opcode = EventOpcode.Stop, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] public void SerializationStop() { - if (IsEnabled(EventLevel.Informational, Keywords.Serialization) && !_writeInProgress.Value) + if (IsEnabled(EventLevel.Informational, Keywords.Serialization)) { - try - { - _writeInProgress.Value = true; - WriteEvent(EventId_SerializationStop); - } - finally - { - _writeInProgress.Value = false; - } + WriteEvent(EventId_SerializationStop); } } @@ -69,17 +46,9 @@ public void SerializingObject(Type type) { Debug.Assert(type != null); - if (IsEnabled(EventLevel.Informational, Keywords.Serialization) && !_writeInProgress.Value) + if (IsEnabled(EventLevel.Informational, Keywords.Serialization)) { - try - { - _writeInProgress.Value = true; - SerializingObject(type.AssemblyQualifiedName); - } - finally - { - _writeInProgress.Value = false; - } + SerializingObject(type.AssemblyQualifiedName); } } @@ -92,34 +61,18 @@ private void SerializingObject(string? typeName) [Event(EventId_DeserializationStart, Opcode = EventOpcode.Start, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] public void DeserializationStart() { - if (IsEnabled(EventLevel.Informational, Keywords.Deserialization) && !_writeInProgress.Value) + if (IsEnabled(EventLevel.Informational, Keywords.Deserialization)) { - try - { - _writeInProgress.Value = true; - WriteEvent(EventId_DeserializationStart); - } - finally - { - _writeInProgress.Value = false; - } + WriteEvent(EventId_DeserializationStart); } } [Event(EventId_DeserializationStop, Opcode = EventOpcode.Stop, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] public void DeserializationStop() { - if (IsEnabled(EventLevel.Informational, Keywords.Deserialization) && !_writeInProgress.Value) + if (IsEnabled(EventLevel.Informational, Keywords.Deserialization)) { - try - { - _writeInProgress.Value = true; - WriteEvent(EventId_DeserializationStop); - } - finally - { - _writeInProgress.Value = false; - } + WriteEvent(EventId_DeserializationStop); } } @@ -128,17 +81,9 @@ public void DeserializingObject(Type type) { Debug.Assert(type != null); - if (IsEnabled(EventLevel.Informational, Keywords.Deserialization) && !_writeInProgress.Value) + if (IsEnabled(EventLevel.Informational, Keywords.Deserialization)) { - try - { - _writeInProgress.Value = true; - DeserializingObject(type.AssemblyQualifiedName); - } - finally - { - _writeInProgress.Value = false; - } + DeserializingObject(type.AssemblyQualifiedName); } } diff --git a/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs b/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs index d7c86bdd7daefc..8c76cb307ee7d3 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs @@ -103,56 +103,6 @@ public static void RecordsNestedSerializationCalls() Assert.Equal(expected, listener.Log); } - [Fact] - public static void DoesNotRecordRecursiveSerializationPerformedByEventListener() - { - // First, serialization - - LoggingEventListener listener = new LoggingEventListener(); - listener.EventWritten += (source, args) => listener.Log.Add("Callback fired."); - listener.EventWritten += (source, args) => new BinaryFormatter().Serialize(Stream.Null, CreatePerson()); - - MemoryStream ms = new MemoryStream(); - BinaryFormatter formatter = new BinaryFormatter(); - formatter.Serialize(ms, CreatePerson()); - ms.Position = 0; - - string[] expected = new string[] - { - "SerializationStart [Start, 00000001]: ", - "Callback fired.", - "SerializingObject [Info, 00000001]: " + typeof(Person).AssemblyQualifiedName, - "Callback fired.", - "SerializingObject [Info, 00000001]: " + typeof(Address).AssemblyQualifiedName, - "Callback fired.", - "SerializationStop [Stop, 00000001]: ", - "Callback fired.", - }; - - Assert.Equal(expected, listener.Log); - listener.Log.Clear(); - - // Then, deserialization - - ms.Position = 0; - formatter.Deserialize(ms); - listener.Dispose(); - - expected = new string[] - { - "DeserializationStart [Start, 00000002]: ", - "Callback fired.", - "DeserializingObject [Info, 00000002]: " + typeof(Person).AssemblyQualifiedName, - "Callback fired.", - "DeserializingObject [Info, 00000002]: " + typeof(Address).AssemblyQualifiedName, - "Callback fired.", - "DeserializationStop [Stop, 00000002]: ", - "Callback fired.", - }; - - Assert.Equal(expected, listener.Log); - } - private static Person CreatePerson() { return new Person() From 6bb4f3207324ceb270a10865f109c9779cb6b073 Mon Sep 17 00:00:00 2001 From: Levi Broderick Date: Wed, 29 Jul 2020 11:10:11 -0700 Subject: [PATCH 5/7] PR feedback: fix erroneous .csproj conditions --- .../System.Runtime.Serialization.Formatters.Tests.csproj | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Runtime.Serialization.Formatters/tests/System.Runtime.Serialization.Formatters.Tests.csproj b/src/libraries/System.Runtime.Serialization.Formatters/tests/System.Runtime.Serialization.Formatters.Tests.csproj index 0e60cd212ab42a..f8621423828977 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/tests/System.Runtime.Serialization.Formatters.Tests.csproj +++ b/src/libraries/System.Runtime.Serialization.Formatters/tests/System.Runtime.Serialization.Formatters.Tests.csproj @@ -5,7 +5,6 @@ $(NetCoreAppCurrent)-Windows_NT;$(NetCoreAppCurrent)-FreeBSD;$(NetCoreAppCurrent)-illumos;$(NetCoreAppCurrent)-Solaris;$(NetCoreAppCurrent)-Linux;$(NetCoreAppCurrent)-OSX;$(NetCoreAppCurrent)-iOS;$(NetCoreAppCurrent)-tvOS;net48 - @@ -17,7 +16,6 @@ - @@ -34,6 +32,10 @@ + + + + From 7d53f573a8a0c8e8ca6156a94b30aec4749353b4 Mon Sep 17 00:00:00 2001 From: Levi Broderick Date: Wed, 29 Jul 2020 11:28:19 -0700 Subject: [PATCH 6/7] PR feedback: clarify listener dispose / log capture --- .../tests/BinaryFormatterEventSourceTests.cs | 38 ++++++++++++------- 1 file changed, 25 insertions(+), 13 deletions(-) diff --git a/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs b/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs index 8c76cb307ee7d3..805b1ad4df4815 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/tests/BinaryFormatterEventSourceTests.cs @@ -19,11 +19,11 @@ public static class BinaryFormatterEventSourceTests [Fact] public static void RecordsSerialization() { - LoggingEventListener listener = new LoggingEventListener(); + using LoggingEventListener listener = new LoggingEventListener(); BinaryFormatter formatter = new BinaryFormatter(); formatter.Serialize(Stream.Null, CreatePerson()); - listener.Dispose(); + string[] capturedLog = listener.CaptureLog(); string[] expected = new string[] { @@ -33,7 +33,7 @@ public static void RecordsSerialization() "SerializationStop [Stop, 00000001]: ", }; - Assert.Equal(expected, listener.Log); + Assert.Equal(expected, capturedLog); } [Fact] @@ -44,9 +44,9 @@ public static void RecordsDeserialization() formatter.Serialize(ms, CreatePerson()); ms.Position = 0; - LoggingEventListener listener = new LoggingEventListener(); + using LoggingEventListener listener = new LoggingEventListener(); formatter.Deserialize(ms); - listener.Dispose(); + string[] capturedLog = listener.CaptureLog(); string[] expected = new string[] { @@ -56,7 +56,7 @@ public static void RecordsDeserialization() "DeserializationStop [Stop, 00000002]: ", }; - Assert.Equal(expected, listener.Log); + Assert.Equal(expected, capturedLog); } [Fact] @@ -64,11 +64,12 @@ public static void RecordsNestedSerializationCalls() { // First, serialization - LoggingEventListener listener = new LoggingEventListener(); + using LoggingEventListener listener = new LoggingEventListener(); MemoryStream ms = new MemoryStream(); BinaryFormatter formatter = new BinaryFormatter(); formatter.Serialize(ms, new ClassWithNestedDeserialization()); + string[] capturedLog = listener.CaptureLog(); ms.Position = 0; string[] expected = new string[] @@ -81,14 +82,14 @@ public static void RecordsNestedSerializationCalls() "SerializationStop [Stop, 00000001]: ", }; - Assert.Equal(expected, listener.Log); - listener.Log.Clear(); + Assert.Equal(expected, capturedLog); + listener.ClearLog(); // Then, deserialization ms.Position = 0; formatter.Deserialize(ms); - listener.Dispose(); + capturedLog = listener.CaptureLog(); expected = new string[] { @@ -100,7 +101,7 @@ public static void RecordsNestedSerializationCalls() "DeserializationStop [Stop, 00000002]: ", }; - Assert.Equal(expected, listener.Log); + Assert.Equal(expected, capturedLog); } private static Person CreatePerson() @@ -119,11 +120,22 @@ private static Person CreatePerson() private sealed class LoggingEventListener : EventListener { private readonly Thread _activeThread = Thread.CurrentThread; - internal readonly List Log = new List(); + private readonly List _log = new List(); private void AddToLog(FormattableString message) { - Log.Add(FormattableString.Invariant(message)); + _log.Add(FormattableString.Invariant(message)); + } + + // Captures the current log + public string[] CaptureLog() + { + return _log.ToArray(); + } + + public void ClearLog() + { + _log.Clear(); } protected override void OnEventSourceCreated(EventSource eventSource) From d033375cb68b005ad6db3b74b8816755741a9e38 Mon Sep 17 00:00:00 2001 From: Levi Broderick Date: Wed, 29 Jul 2020 11:31:53 -0700 Subject: [PATCH 7/7] PR feedback: mark Start events as recursive --- .../Formatters/Binary/BinaryFormatterEventSource.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs index 5f89298f5ec15c..ca8efd4c0978a9 100644 --- a/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs +++ b/src/libraries/System.Runtime.Serialization.Formatters/src/System/Runtime/Serialization/Formatters/Binary/BinaryFormatterEventSource.cs @@ -23,7 +23,7 @@ private BinaryFormatterEventSource() { } - [Event(EventId_SerializationStart, Opcode = EventOpcode.Start, Keywords = Keywords.Serialization, Level = EventLevel.Informational)] + [Event(EventId_SerializationStart, Opcode = EventOpcode.Start, Keywords = Keywords.Serialization, Level = EventLevel.Informational, ActivityOptions = EventActivityOptions.Recursive)] public void SerializationStart() { if (IsEnabled(EventLevel.Informational, Keywords.Serialization)) @@ -58,7 +58,7 @@ private void SerializingObject(string? typeName) WriteEvent(EventId_SerializingObject, typeName); } - [Event(EventId_DeserializationStart, Opcode = EventOpcode.Start, Keywords = Keywords.Deserialization, Level = EventLevel.Informational)] + [Event(EventId_DeserializationStart, Opcode = EventOpcode.Start, Keywords = Keywords.Deserialization, Level = EventLevel.Informational, ActivityOptions = EventActivityOptions.Recursive)] public void DeserializationStart() { if (IsEnabled(EventLevel.Informational, Keywords.Deserialization))