Fixes and verbose logging

res/Resource.cs

@@ -7,259 +7,309 @@ using System.Diagnostics;
 using System.Reflection;
 using System.Collections.Immutable;
 using System.Threading;
+using System.IO;
+using Microsoft.CodeAnalysis;
 
 
-namespace res
+namespace res;
+
+
+using ImmDefLoad = ImmutableQueue<(string name, Ref)>;
+
+public interface Res_old
 {
 
+}
 
-	using ImmDefLoad = ImmutableQueue<(string name, Ref)>;
+[DebuggerDisplay("Path = {path}")]
+public class Ref : lib.I_Serialize
+{
+	static public bool s_verboseLogging = true;
 
-	public interface Res_old
+	public string Filename =>path;
+
+	//For construction
+	public Ref()
+	{
+		path = "{set_from_ref_default_cons}";
+		if( s_verboseLogging ) log.info( $"Ref: {GetType().Name} {path}" );
+	}
+
+	public Ref( string filename )
+	{
+		path = filename;
+		if( s_verboseLogging ) log.info( $"Ref: {GetType().Name} {path}" );
+	}
+
+	virtual public void OnChange()
+	{
+	}
+
+	virtual internal void load()
 	{
 
 	}
 
-	[Serializable]
+	private string path = "{set_from_inline_cons}";
-	public class Ref : lib.I_Serialize
+}
+
+[Serializable]
+[DebuggerDisplay("Path = {path} / Res = {res}")]
+public class Ref<T> : Ref where T : class
+{
+	public T? res => m_res != null ? m_res : lookup();
+
+
+	public T? lookup()
 	{
-		public string Filename =>path;
+		m_res = Mgr.load<T>( Filename );
-
+		if( s_verboseLogging ) log.info( $"Ref.lookup {GetType().Name} {GetType().GenericTypeArguments[0]} path {Filename}" );
-		//For construction
+		return m_res;
-		public Ref()
-		{
-			path = "{UNSET_CONS}";
-		}
-
-		public Ref( string filename )
-		{
-			path = filename;
-		}
-
-		virtual public void OnSerialize()
-		{
-		}
-
-		virtual public void OnDeserialize( object enclosing )
-		{
-		}
-
-		virtual public void OnChange()
-		{
-		}
-
-		virtual internal void load()
-		{
-
-		}
-
-		private string path = "{UNSET_INLINE}";
 	}
 
-	[Serializable]
+	//For serialization
-	public class Ref<T> : Ref where T : class
+	public Ref()
+		:
+		base( "{set_from_ref<>_default_cons}" )
 	{
-		public T? res => m_res != null ? m_res : ( m_res = Mgr.load<T>( Filename ) );
+		if( s_verboseLogging ) log.info( $"Ref {GetType().Name} {GetType().GenericTypeArguments[0]} path {Filename}" );
+	}
 
-		//For serialization
+	public Ref( string filename )
-		public Ref()
+		:
-			:
+		base( filename )
-			base( "{unknown}" )
+	{
+		if( s_verboseLogging ) log.info( $"Ref {GetType().Name} {GetType().GenericTypeArguments[0]} path {Filename}" );
+	}
+
+	override internal void load()
+	{
+		m_res = Mgr.load<T>( Filename );
+		if( s_verboseLogging ) log.info( $"Ref.load {GetType().Name} {GetType().GenericTypeArguments[0]} path {Filename}" );
+	}
+
+	public object OnDeserialize( object enclosing )
+	{
+		return enclosing;
+	}
+
+	static public Ref<T> createAsset( T v, string path )
+	{
+		if( File.Exists( path ) )
 		{
+			log.warn( $"For {typeof(T).Name}, saving asset to {path}, but it already exists" );
+
+			var newPath = $"{path}_{DateTime.Now.ToShortDateString()}_{DateTime.Now.ToShortTimeString()}";
+
+			System.IO.File.Move(path, newPath );
+
+			log.warn( $"For {typeof(T).Name}, renamed to {newPath}" );
 		}
 
-		public Ref( string filename )
+		var newRef = new Ref<T>( path );
-			:
-			base( filename )
-		{
-		}
-
-		/*
-		public Ref( string filename, T res ) : base( filename )
-		{
-			m_res = res;
-		}
-		*/
-
-		override internal void load()
-		{
-			m_res = Mgr.load<T>( Filename );
-		}
-
-
-		[NonSerialized]
-		private T m_res;
 
+		return newRef;
 	}
 
 
+	[NonSerialized]
+	protected T m_res;
 
+}
 
-	public class Resource
+public class RefMemory<T> : Ref<T> where T : class
+{
+
+	//For serialization
+	public RefMemory( T res )
+		:
+		base( "{memory}" )
 	{
-		static public Mgr mgr;
+		m_res = res;
-
 	}
 
-
+	override internal void load()
-	/*
-	public class Loader<T>
 	{
-		static public T load( string filename )
-		{
-			Debug.Assert( false, "Specialize Loader for your type for file" );
-			return default(T);
-		}
-	}
-	*/
-
-	public delegate T Load<out T>( string filename );
-
-
-	class LoadHolder
-	{
-		internal virtual object load()
-		{
-			return null;
-		}
 	}
 
+}
 
-	class LoadHolder<T> : LoadHolder
+
+
+
+public class Resource
+{
+	static public Mgr mgr;
+
+}
+
+
+public delegate T Load<out T>( string filename );
+
+
+class LoadHolder
+{
+	internal virtual object load()
 	{
-		public LoadHolder( Load<T> fnLoad )
+		return null;
-		{
+	}
-			_fnLoad = fnLoad;
+}
-		}
 
-		public Load<T> _fnLoad;
 
-		internal override object load()
+class LoadHolder<T> : LoadHolder
-		{
+{
-			return load();
+	public LoadHolder( Load<T> fnLoad )
-		}
+	{
+		_fnLoad = fnLoad;
 	}
 
-	//generic classes make a new static per generic type
+	public Load<T> _fnLoad;
-	class ResCache<T> where T : class
+
+	internal override object load()
 	{
-		public static T s_default = default;
+		return load();
-		public static ImmutableDictionary<string, WeakReference<T>> s_cache = ImmutableDictionary<string, WeakReference<T>>.Empty;
+	}
+}
+
+public record class ResourceHolder<T>( WeakReference<T> weak, string Name, DateTime captured ) : imm.Recorded<ResourceHolder<T>>
+where T : class
+{
+
+}
+
+//generic classes make a new static per generic type
+class ResCache<T> where T : class
+{
+	public static T s_default = default;
+	public static ImmutableDictionary<string, ResourceHolder<T>> s_cache = ImmutableDictionary<string, ResourceHolder<T>>.Empty;
+}
+
+
+public class Mgr
+{
+	static public void startup()
+	{
+		Resource.mgr = new Mgr();
 	}
 
-
+	static public void register<T>( Load<T> loader )
-	public class Mgr
 	{
-		static public void startup()
+		Debug.Assert( !Resource.mgr.m_loaders.ContainsKey( typeof( T ) ) );
+
+		var lh = new LoadHolder<T>( loader );
+
+		ImmutableInterlocked.TryAdd( ref Resource.mgr.m_loaders, typeof( T ), lh );
+	}
+
+	//Register all subclasses of a particular type
+	//???? Should we just always do this?
+	static public void registerSub<T>()
+	{
+		registerSub( typeof(T) );
+	}
+
+	static public void registerSub( Type baseType )
+	{
+		log.info( $"Registering loader for {baseType.Name}" );
+
+		Type[] typeParams = new Type[1];
+		foreach( var mi in baseType.GetMethods() )
 		{
-			Resource.mgr = new Mgr();
+			if( mi.Name == "res_load" && mi.IsGenericMethod )
-		}
-
-		static public void register<T>( Load<T> loader )
-		{
-			Debug.Assert( !Resource.mgr.m_loaders.ContainsKey( typeof( T ) ) );
-
-			var lh = new LoadHolder<T>( loader );
-
-			ImmutableInterlocked.TryAdd( ref Resource.mgr.m_loaders, typeof( T ), lh );
-		}
-
-		//Register all subclasses of a particular type
-		//???? Should we just always do this?
-		static public void registerSub<T>()
-		{
-			registerSub( typeof(T) );
-		}
-
-		static public void registerSub( Type baseType )
-		{
-			log.info( $"Registering loader for {baseType.Name}" );
-
-			Type[] typeParams = new Type[1];
-			foreach( var mi in baseType.GetMethods() )
 			{
-				if( mi.Name == "res_load" && mi.IsGenericMethod )
+				foreach( var ass in AppDomain.CurrentDomain.GetAssemblies() )
 				{
-					foreach( var ass in AppDomain.CurrentDomain.GetAssemblies() )
+					foreach( var t in ass.GetTypes() )
 					{
-						foreach( var t in ass.GetTypes() )
+						if( !baseType.IsAssignableFrom( t ) )
-						{
+							continue;
-							if( !baseType.IsAssignableFrom( t ) )
-								continue;
 
-							log.debug( $"Making a loader for {t.Name}" );
+						log.debug( $"Making a loader for {t.Name}" );
 
-							typeParams[0] = t;
+						typeParams[0] = t;
-							var mi_ng = mi.MakeGenericMethod( typeParams );
+						var mi_ng = mi.MakeGenericMethod( typeParams );
 
-							var loadGenType = typeof( Load<> );
+						var loadGenType = typeof( Load<> );
 
-							var loadType = loadGenType.MakeGenericType( t );
+						var loadType = loadGenType.MakeGenericType( t );
 
-							var loader = Delegate.CreateDelegate( loadType, mi_ng );
+						var loader = Delegate.CreateDelegate( loadType, mi_ng );
 
-							var lhGenType = typeof( LoadHolder<> );
+						var lhGenType = typeof( LoadHolder<> );
 
-							var lhType = lhGenType.MakeGenericType( t );
+						var lhType = lhGenType.MakeGenericType( t );
 
-							var lh = Activator.CreateInstance( lhType, loader ) as LoadHolder;
+						var lh = Activator.CreateInstance( lhType, loader ) as LoadHolder;
 
-							ImmutableInterlocked.TryAdd( ref Resource.mgr.m_loaders, t, lh );
+						ImmutableInterlocked.TryAdd( ref Resource.mgr.m_loaders, t, lh );
-						}
 					}
-					return;
 				}
+				return;
 			}
 		}
+	}
 
 
-		static public Ref<T> lookup<T>( string filename ) where T : class
+	static public Ref<T> lookup<T>( string filename ) where T : class
+	{
+		return new Ref<T>( filename );
+	}
+
+	//*
+	static public Ref lookup( string filename, Type t )
+	{
+		return new Ref( filename );
+	}
+	//*/
+
+	// @@@ TODO Pass information through here
+	static public T? load<T>( string filename ) where T : class
+	{
+		if( ResCache<T>.s_cache.TryGetValue( filename, out var holder ) )
 		{
-			return new Ref<T>( filename );
-		}
 
-		//*
+			if( holder.weak.TryGetTarget( out var v ) )
-		static public Ref lookup( string filename, Type t )
-		{
-			return new Ref( filename );
-		}
-		//*/
-
-		static public T? load<T>( string filename ) where T : class
-		{
-			if( ResCache<T>.s_cache.TryGetValue( filename, out var wr ) )
 			{
-				if( wr.TryGetTarget( out var v ) )
+				return v;
-					return v;
-
-				log.info( $"{filename} was in cache, but its been dropped, reloading." );
 			}
 
-			log.warn( $"Block Loading {filename}." );
+			log.info( $"{filename} was in cache, but its been dropped, reloading." );
-
-			var newV = actualLoad<T>( filename );
-
-			return newV;
 		}
 
-		static public T actualLoad<T>( string filename ) where T : class
+		log.warn( $"Block Loading {filename}." );
+
+		var newV = actualLoad<T>( filename );
+
+		return newV;
+	}
+
+	static public T actualLoad<T>( string filename ) where T : class
+	{
+
+		lock(s_loading)
 		{
+
 			if( s_loading.TryGetValue( filename, out var evt ) )
 			{
-				evt.WaitOne();
 
-				if( ResCache<T>.s_cache.TryGetValue( filename, out var wr ) )
+				//var waiting = evt.WaitOne();
+
+
+				if( ResCache<T>.s_cache.TryGetValue( filename, out var holder ) )
 				{
-					if( wr.TryGetTarget( out var v ) )
+					if( holder.weak.TryGetTarget( out var v ) )
+					{
+						log.trace( $"{typeof(T).Name} loading {filename}" );
 						return v;
+					}
 
 					log.error( $"{filename} was in cache, but its been dropped, reloading." );
 				}
 			}
 
-			var evtNew = new AutoResetEvent( false );
+			//var evtNew = new AutoResetEvent( false );
 
-			if( ImmutableInterlocked.TryAdd( ref s_loading, filename, evtNew ) )
+			//if( ImmutableInterlocked.TryAdd( ref s_loading, filename, evtNew ) )
 			{
 				if( Resource.mgr.m_loaders.TryGetValue( typeof( T ), out var loaderGen ) )
 				{
@@ -269,14 +319,18 @@ namespace res
 
 					var weak = new WeakReference<T>( v );
 
-					var alreadyAdded = !ImmutableInterlocked.TryAdd( ref ResCache<T>.s_cache, filename, weak );
+					var holder = new ResourceHolder<T>( weak, $"", DateTime.Now ).Record();
 
-					evtNew.Set();
+					log.info( $"To {typeof(T).Name} add {filename}" );
+
+					var alreadyAdded = !ImmutableInterlocked.TryAdd( ref ResCache<T>.s_cache, filename, holder );
+
+					//evtNew.Set();
 
 					//Done loading
-					if( !ImmutableInterlocked.TryRemove( ref s_loading, filename, out var oldEvt ) )
+					//if( !ImmutableInterlocked.TryRemove( ref s_loading, filename, out var oldEvt ) )
 					{
-						log.error( $"Error removing loading event for {filename}" );
+						//log.error( $"Error removing loading event for {filename}" );
 					}
 
 					if( alreadyAdded )
@@ -294,49 +348,46 @@ namespace res
 				}
 			}
 
-			return actualLoad<T>( filename );
 		}
 
-		static object s_loadingLock = new object();
+		return actualLoad<T>( filename );
+	}
 
-		static ImmutableDictionary<string, AutoResetEvent> s_loading = ImmutableDictionary<string, AutoResetEvent>.Empty;
+	static object s_loadingLock = new object();
-		static ImmDefLoad s_deferredLoad = ImmDefLoad.Empty;
+
+	static ImmutableDictionary<string, AutoResetEvent> s_loading = ImmutableDictionary<string, AutoResetEvent>.Empty;
+	static ImmDefLoad s_deferredLoad = ImmDefLoad.Empty;
 
 
-		Mgr()
+	Mgr()
+	{
+		log.info( $"Creating Res.Mgr" );
+
+		var ts = new ThreadStart( deferredLoader );
+
+		m_deferredLoader = new Thread( ts );
+
+		m_deferredLoader.Start();
+	}
+
+	void deferredLoader()
+	{
+		while( true )
 		{
-			log.info( $"Creating Res.Mgr" );
+			Thread.Sleep( 1 );
 
-			var ts = new ThreadStart( deferredLoader );
+			if( ImmutableInterlocked.TryDequeue( ref s_deferredLoad, out var v ) )
-
-			m_deferredLoader = new Thread( ts );
-
-			m_deferredLoader.Start();
-		}
-
-		void deferredLoader()
-		{
-			while( true )
 			{
-				Thread.Sleep( 1 );
+				v.Item2.load();
-
-				if( ImmutableInterlocked.TryDequeue( ref s_deferredLoad, out var v ) )
-				{
-					v.Item2.load();
-				}
 			}
 		}
-
-
-
-		ImmutableDictionary<Type, LoadHolder> m_loaders = ImmutableDictionary<Type, LoadHolder>.Empty;
-
-		Thread m_deferredLoader;
-
 	}
 
 
 
+	ImmutableDictionary<Type, LoadHolder> m_loaders = ImmutableDictionary<Type, LoadHolder>.Empty;
 
+	Thread m_deferredLoader;
 
 }
+

ser/XmlFormatter2.cs

@@ -38,8 +38,8 @@ namespace lib
 
 	public interface I_Serialize
 	{
-		void OnSerialize();
+		void OnSerialize() {}
-		void OnDeserialize( object enclosing );
+		object OnDeserialize( object enclosing ) => this;
 	}
 
 	[Flags]
@@ -123,6 +123,8 @@ namespace lib
 
 	public class XmlFormatter2Cfg : Config
 	{
+		public bool VerboseLogging = true;
+
 		public Datastructure datastructure = Datastructure.Tree;
 
 		public int Version = 2;
@@ -286,6 +288,8 @@ namespace lib
 			{
 				TypeCode typeCode = Type.GetTypeCode( type );
 
+				if( _cfg.VerboseLogging ) log.info( $"{type.Name}.{name} {existing} {mi?.Name}" );
+
 				if( typeCode != TypeCode.Object )
 				{
 					return DeserializeConcrete( elem, mi, name, type );
@@ -302,11 +306,10 @@ namespace lib
 						{
 							object obj = DeserializeObject( elem, mi, type, existing );
 
-							if( obj is I_Serialize )
+							if( obj is I_Serialize iser )
 							{
-								var iser = obj as I_Serialize;
+								if( _cfg.VerboseLogging ) log.info( $"" );
-
+								obj = iser.OnDeserialize( null );
-								iser.OnDeserialize( null );
 							}
 
 							return obj;
@@ -320,7 +323,7 @@ namespace lib
 			}
 			catch( Exception ex )
 			{
-				log.warn( $"Caught exception fn {mi.Name} type {type.Name} of {ex.Message}" );
+				log.warn( $"Caught exception fn {mi?.Name} type {type?.Name} of {ex.Message}" );
 			}
 
 			return existing;
@@ -343,6 +346,8 @@ namespace lib
 
 		private object DeserializeConcrete( XmlElement elem, MemberInfo mi, string name, Type type )
 		{
+			if( _cfg.VerboseLogging ) log.info( $"" );
+
 			string val = "";
 
 			if( elem.HasAttribute( "v" ) )
@@ -425,6 +430,8 @@ namespace lib
 
 		private object HydrateObject( XmlElement elem, MemberInfo mi, Type finalType, object obj )
 		{
+			if( _cfg.VerboseLogging ) log.info( $"" );
+
 			if( obj is IList )
 			{
 				var list = obj as IList;
@@ -513,6 +520,8 @@ namespace lib
 
 		private object HydrateObjectOfNarrowType( XmlElement elem, MemberInfo mi, Type narrowType, object obj )
 		{
+			if( _cfg.VerboseLogging ) log.info( $"" );
+
 			var isImm = typeof(imm.Imm).IsAssignableFrom( narrowType );
 
 			XmlNodeList allChildren = elem.ChildNodes;
@@ -671,6 +680,7 @@ namespace lib
 
 		private object GetObjectForDeser( XmlElement elem, Type type, out Type finalType, object obj )
 		{
+
 			finalType = type;
 			if( elem.HasAttribute( "_.t" ) )
 			{
@@ -685,6 +695,8 @@ namespace lib
 
 			int refInt = refString.Length > 0 ? Convert.ToInt32( refString ) : -1;
 
+			if( _cfg.VerboseLogging ) log.info( $"{finalType?.Name}({type?.Name}) refInt {refInt} exitingObj = {obj?.ToString()}" );
+
 			obj = createObject( elem, finalType, refInt, obj );
 
 			return obj;
@@ -692,6 +704,8 @@ namespace lib
 
 		private object DeserializeList( XmlElement elem, MemberInfo mi, Type type, IList list )
 		{
+			if( _cfg.VerboseLogging ) log.info( $"" );
+
 			XmlNodeList arrNodeList = elem.ChildNodes;
 
 			Type t = list.GetType();
@@ -726,6 +740,7 @@ namespace lib
 				typeElem = typeof( KeyValuePair<,> ).MakeGenericType( type.GenericTypeArguments );
 			}
 
+			if( _cfg.VerboseLogging ) log.info( $"DserCol {type.GetType().Name} {typeElem.Name} into reflT {mi.ReflectedType.Name} declT {mi.DeclaringType.Name} {mi.Name}" );
 
 			string refString = elem.GetAttribute( "ref" );
 			int refInt = refString.Length > 0 ? Convert.ToInt32( refString ) : -1;
@@ -752,7 +767,9 @@ namespace lib
 							finalType = typeElem;
 					}
 
-					arr.SetValue( Deserialize( arrElem, mi, finalType, null ), i );
+					var arrItem = Deserialize( arrElem, mi, finalType, null );
+
+					arr.SetValue( arrItem, i );
 				}
 			}
 
@@ -768,6 +785,8 @@ namespace lib
 
 			var typeGen = Type.MakeGenericSignatureType( type );
 
+			if( _cfg.VerboseLogging ) log.info( $"TypeGen: {typeGen.Name}" );
+
 			if( type == typeof( ImmutableArray<> ).MakeGenericType( typeElem ) )
 			{
 				var genMeth = GetType().GetMethod( "MakeImmutableArray", BindingFlags.Instance | BindingFlags.Public | BindingFlags.NonPublic );
@@ -823,6 +842,8 @@ namespace lib
 
 		private object DeserializeArray( XmlElement elem, MemberInfo mi, Type type )
 		{
+			if( _cfg.VerboseLogging ) log.info( $"" );
+
 			Type typeElem = type.GetElementType();
 
 			string refString = elem.GetAttribute( "ref" );
@@ -866,11 +887,12 @@ namespace lib
 
 		private object createObject( XmlElement elem, Type type, int refInt, object existingObj )
 		{
+
 			TypeCode tc = Type.GetTypeCode( type );
 
 			if( _cfg.datastructure == Datastructure.Graph && refInt > 0 && m_alreadySerialized.ContainsKey( refInt ) )
 			{
-				//lib.log.info( "Reusing object for {0}", refInt );
+				if( _cfg.VerboseLogging ) log.info( $"Reuse object" );
 				return m_alreadySerialized[refInt];
 			}
 
@@ -880,6 +902,7 @@ namespace lib
 
 			if( isProxy )
 			{
+				if( _cfg.VerboseLogging ) log.info( $"use Proxy" );
 				object obj = null;
 
 				var tryType = type;
@@ -921,28 +944,41 @@ namespace lib
 				var isSubclass = type.IsSubclassOf( existingObjType ) || existingObjType.IsSubclassOf( type );
 
 				if( isSubclass )
+				{
+					if( _cfg.VerboseLogging ) log.info( $"Using existing obj {existingObj?.ToString()}" );
 					return existingObj;
+				}
 
 				// old
 				//if( type == existingObjType ) return existingObj;
 			}
 
 
+			if( typeof(res.Ref).IsAssignableFrom( type ) )
+			{
+				log.info( $"Ref time!" );
+			}
+
 			// THIRD create a new object
 			{
 				object obj = null;
 
 				try
 				{
+					if( _cfg.VerboseLogging ) log.info( $"Activator.CreateInstance" );
+
 					//Trying the nice way to creat objects first.
 					obj = Activator.CreateInstance( type );
 
+					if( _cfg.VerboseLogging ) log.info( $"Got obj {obj?.ToString()}" );
 				}
-				catch( Exception )
+				catch( Exception ex )
 				{
 					try
 					{
+						if( _cfg.VerboseLogging ) log.info( $"GetUninitializedObject" );
 						obj = System.Runtime.Serialization.FormatterServices.GetUninitializedObject( type );
+						if( _cfg.VerboseLogging ) log.info( $"Got obj {obj?.ToString()}" );
 					}
 					catch( Exception exInner )
 					{