logging

Author: rolfbjarne

src/Foundation/NSObject2.cs

@@ -19,6 +19,9 @@
 // OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
 // WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
 //
+#define LOGGING
+#define CONSISTENCY_CHECKS
+
 using System.Diagnostics.CodeAnalysis;
 using System.Reflection;
 using System.Collections.Generic;
@@ -76,6 +79,10 @@ struct NSObjectData {
 	}
 
 	class NSObjectDataHandle : CriticalHandle {
+#if LOGGING
+		static int counter;
+		public int ID = Interlocked.Increment (ref counter);
+#endif
 		bool invalidated;
 		public NSObjectDataHandle ()
 			: base (IntPtr.Zero)
@@ -88,11 +95,17 @@ public NSObjectDataHandle ()
 		public NSObjectDataHandle (IntPtr handle)
 			: base (handle)
 		{
+#if LOGGING
+			Runtime.NSLog ($"NSObjectDataHandle (0x{handle:x}): wrapped existing pointer");
+#endif
 		}
 
 		public void Invalidate ()
 		{
 			invalidated = true;
+#if LOGGING
+			Runtime.NSLog ($"NSObjectDataHandle.Invalidate (): invalidated 0x{handle:x}");
+#endif
 		}
 
 		public unsafe NSObjectData* Data {
@@ -108,10 +121,16 @@ protected override bool ReleaseHandle ()
 			if (handle != IntPtr.Zero) {
 				if (invalidated) {
 					// nothing to do here.
+#if LOGGING
+					Runtime.NSLog ($"NSObjectDataHandle.ReleaseHandle (): NOT released 0x{handle:x}; not owned");
+#endif
 				} else {
 					unsafe {
 						NativeMemory.Free ((void*) handle);
 					}
+#if LOGGING
+					Runtime.NSLog ($"NSObjectDataHandle.ReleaseHandle (): released 0x{handle:x}");
+#endif
 				}
 			}
 			handle = IntPtr.Zero;
@@ -169,14 +188,23 @@ unsafe NativeHandle handle {
 			var rv = AllocateData ().Data;
 
 			if (rv is null) {
+#if LOGGING
+				Runtime.NSLog ($"{GetType ().Name}.GetData (): id={objectId} no handle\n{Environment.StackTrace}");
+				throw new ObjectDisposedException ($"{GetType ().Name}.GetData (): id={objectId} No data???");
+#else
 				// Throwing an exception here is better than returning a null pointer, because that will crash the process when the pointer is dereferenced
 				// (and none of the callers can do anything useful with a null pointer anyway).
 				throw new ObjectDisposedException ($"This object (of type {GetType ().Name}) does not have a data pointer anymore, possibly because of a race condition. Please file a bug at https://github.com/dotnet/macios/issues.");
+#endif
 			}
 
 			return rv;
 		}
 
+#if LOGGING
+		static int objectIdCounter;
+		int objectId;
+#endif
 		unsafe NSObjectDataHandle AllocateData ()
 		{
 			var dh = data_handle;
@@ -191,6 +219,10 @@ unsafe NSObjectDataHandle AllocateData ()
 				return previousValue;
 			}
 
+#if LOGGING
+			objectId = Interlocked.Increment (ref objectIdCounter);
+			Runtime.NSLog ($"{GetType ().Name}.AllocateData () id={objectId} allocated 0x{((IntPtr) data.Data):x}");
+#endif
 			if (!Runtime.IsCoreCLR) // This condition (and the assignment to __handle_for_mono if applicable) is trimmed away by the linker.
 				__data_for_mono = data.Data;
 
@@ -1053,7 +1085,7 @@ void RecreateDataHandle ()
 			//   else does that, it's quite unlikely this instance will become resurrected a second time.
 			var previous_data = data_handle;
 			if (previous_data is null) {
-				var msg = $"This object (of type {GetType ().Name}) does not have an existing data pointer, possibly because of a race condition. Please file a bug at https://github.com/dotnet/macios/issues.");
+				var msg = $"This object (of type {GetType ().Name}) does not have an existing data pointer, possibly because of a race condition. Please file a bug at https://github.com/dotnet/macios/issues.";
 #if CONSISTENCY_CHECKS
 				throw new InvalidOperationException (msg);
 #else
@@ -1067,7 +1099,7 @@ void RecreateDataHandle ()
 			}
 
 			if (previous_data.IsInvalid) {
-				var msg = $"This object (of type {GetType ().Name}) does not have valid data pointer, possibly because of a race condition. Please file a bug at https://github.com/dotnet/macios/issues.");
+				var msg = $"This object (of type {GetType ().Name}) does not have valid data pointer, possibly because of a race condition. Please file a bug at https://github.com/dotnet/macios/issues.";
 #if CONSISTENCY_CHECKS
 				throw new InvalidOperationException (msg);
 #else
@@ -1076,6 +1108,9 @@ void RecreateDataHandle ()
 #endif
 			}
 
+#if LOGGING
+			Runtime.NSLog ($"{GetType ().Name}: id={objectId} previous value invalidated and disposed. Current flags: {flags}");
+#endif
 			previous_data.Invalidate ();
 			// Don't dispose previous_data, because another thread might be referencing it, and trying to access its pointer - which is still valid.
 			// The GC will dispose of previous_data when its not accessible anymore.