search

tschroedter / idasen-desk-rest-api

MIT License
0 stars 0 forks source link

Log file grows swiftly #6

Open 7orlum opened 2 years ago

7orlum commented 2 years ago

The program creates 2 log files:

idasen-desk.log
idasen-desk-rest-api.log

I can stop loging into idasen-desk-rest-api.log by editing appSettings.json

  "Logging": {
    "LogLevel": {
      "Default": "None",
      "System": "None",
      "Microsoft": "None"
    },

But how could I stop logging into idasen-desk.log? It grows too swiftly with default settings, in my case it has grown up to 1 GB for one month, it becames a problem.

7orlum commented 2 years ago

And the second much less significant problem is that even if I set LogLevel to None, the program still writes about 16 lines into idasen-desk-rest-api.log at startup. Maybe you could change this behavior with minimal effort?

7orlum commented 2 years ago

I've got 1 GB of logs for today and I think I know why. DeskManager couldn't initialize for some reason and DeskManagerRegistrations.CreateRealDeskManager() tried to repeat it in infinite loop in idasen-desk-rest-api-main\src\Idasen.RESTAPI\Desks\DeskManagerRegistrations.cs line 30:

            while ( ! ( DeskManager is { Result: true } ) )
            {
                DeskManager = Task.Run ( async ( ) => await manager.Initialise ( )
                                                                   .ConfigureAwait ( false ) ) ;
            }

Repeating log text:

[2022-07-10 12:29:36.4093 DBG] [LogAspect] (0048091427) Idasen.BluetoothLE.Linak.DeskProvider.Initialize("Desk",250635178951455,600) (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4102 DBG] [LogAspect] (0064034196) Idasen.BluetoothLE.Linak.DeskDetector.Initialize("Desk",250635178951455,600) (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4111 DBG] [LogAspect] (0038369207) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitorWithExpiry.set_TimeOut("00:10:00") (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4120 INF] TimeOut = 00:10:00 (at Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitorWithExpiry.set_TimeOut(System.TimeSpan))
[2022-07-10 12:29:36.4128 DBG] [LogAspect] (0038369207) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitorWithExpiry.get_DeviceUpdated() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4137 DBG] [LogAspect] (0020302098) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitor.get_DeviceUpdated() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4151 DBG] [LogAspect] (0038369207) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitorWithExpiry.get_DeviceDiscovered() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4160 DBG] [LogAspect] (0020302098) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitor.get_DeviceDiscovered() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4174 DBG] [LogAspect] (0038369207) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitorWithExpiry.get_DeviceNameUpdated() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4183 DBG] [LogAspect] (0020302098) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitor.get_DeviceNameUpdated() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4200 DBG] [LogAspect] (0038369207) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitorWithExpiry.get_DeviceNameUpdated() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4209 DBG] [LogAspect] (0020302098) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitor.get_DeviceNameUpdated() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4228 DBG] [LogAspect] (0064034196) Idasen.BluetoothLE.Linak.DeskDetector.get_DeskDetected() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4245 DBG] Failed to convert object 'System.Threading.CancellationToken' to json - Message: 'Serialization and deserialization of 'System.IntPtr' instances are not supported. Path: $.WaitHandle.Handle.' (at Idasen.Aop.InvocationToTextConverter.DumpObject(System.Object))
[2022-07-10 12:29:36.4255 DBG] [LogAspect] (0048091427) Idasen.BluetoothLE.Linak.DeskProvider.TryGetDesk(System.Threading.CancellationToken) (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4265 DBG] [LogAspect] (0064034196) Idasen.BluetoothLE.Linak.DeskDetector.Start() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4274 DBG] [LogAspect] (0010459752) Idasen.BluetoothLE.Linak.Desk.Dispose() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4283 DBG] [LogAspect] (0000094552) Idasen.BluetoothLE.Linak.DeskConnector.Dispose() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4292 DBG] [LogAspect] (0048908843) Idasen.BluetoothLE.Core.ServicesDiscovery.Device.Dispose() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4301 DBG] [LogAspect] (0013735571) Idasen.BluetoothLE.Core.ServicesDiscovery.Wrappers.BluetoothLeDeviceWrapper.Dispose() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4310 DBG] [LogAspect] (0007884578) Idasen.BluetoothLE.Core.ServicesDiscovery.GattServicesProvider.Dispose() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4318 DBG] [LogAspect] (0018701810) Idasen.BluetoothLE.Core.ServicesDiscovery.GattServicesDictionary.Dispose() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4328 DBG] [LogAspect] (0002136267) Idasen.BluetoothLE.Core.ServicesDiscovery.GattServicesDictionary.Dispose() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4338 ERR] Failed to detect desk (at Idasen.BluetoothLE.Linak.DeskProvider+<TryGetDesk>d__1.MoveNext())
System.NullReferenceException: Object reference not set to an instance of an object.
   at Idasen.BluetoothLE.Core.ServicesDiscovery.Wrappers.BluetoothLeDeviceWrapper.Dispose()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.Aop.Aspects.LogAspect.Intercept(IInvocation invocation)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.BluetoothLE.Core.ServicesDiscovery.Device.Dispose()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.Aop.Aspects.LogAspect.Intercept(IInvocation invocation)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.BluetoothLE.Linak.DeskConnector.Dispose()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.Aop.Aspects.LogAspect.Intercept(IInvocation invocation)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.BluetoothLE.Linak.Desk.Dispose()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.Aop.Aspects.LogAspect.Intercept(IInvocation invocation)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.BluetoothLE.Linak.DeskDetector.Start()
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.Aop.Aspects.LogAspect.Intercept(IInvocation invocation)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Idasen.BluetoothLE.Linak.DeskProvider.TryGetDesk(CancellationToken token)
[2022-07-10 12:29:36.4376 DBG] [LogAspect] (0064034196) Idasen.BluetoothLE.Linak.DeskDetector.Stop() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4386 DBG] [LogAspect] (0038369207) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitorWithExpiry.Stop() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4395 DBG] [LogAspect] (0020302098) Idasen.BluetoothLE.Core.DevicesDiscovery.DeviceMonitor.Stop() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4404 DBG] [LogAspect] (0032704527) Idasen.BluetoothLE.Core.DevicesDiscovery.Watcher.Stop() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4414 DBG] [LogAspect] (0055618365) Idasen.BluetoothLE.Core.DevicesDiscovery.Wrapper.get_Status() (at Idasen.Aop.Aspects.LogAspect.Intercept(Castle.DynamicProxy.IInvocation))
[2022-07-10 12:29:36.4423 INF] Failed to find desk: Desk (at Idasen.RESTAPI.Desks.DeskManager+<FindDesk>d__11.MoveNext())
7orlum commented 2 years ago

I've noted it after Idasen.RestApi.exe process ate 8 GB of system memory

tschroedter commented 2 years ago

Hi,

I'll try to make the idasen-rest-api.log configurable so that you can set a file size limit, max. files kept and so on... Basically add the SeriLog to the configuration file. This will allow you to change the log level and have rolling files.

In regards to DeskManagerRegistrations, maybe it should only try once and fail. This would most likely fix the memory leak. It looks like something is not disposed.

I'll have a look when I have a bit of free time.

PS: You can have a look at the develop branch.

7orlum commented 2 years ago
  1. It looks like your code runs several manager.Initialise() tasks in parallel. I would change the lines 
                DeskManager = Task.Run ( async ( ) => await manager.Initialise ( )
                                                               .ConfigureAwait ( false ) ) ;

    to

                DeskManager = manager.Initialise().Wait() ;

    Therefore, there will be no need for DeskManager?.Dispose();

  2. To follow Microsoft convention, it is better to rename method Initialise() to InitialiseAsync()
  3. There is a deeper problem. Let's look at a case like this:
    1. I do an API call, GetHeight for example
    2. GetHeight invokes CreateRealDeskManager()
    3. CreateRealDeskManager() invokes manager.Initialise() in the infinite loop above, but manager.Initialise() always failures for some reason
    4. The program sticks inside this infinite loop because DeskManager.Ready will be always equal to False
    5. I will never get an answer to the API call Consider please a way for CreateRealDeskManager() to return an uninitialized DeskManager if it fails to connect to a desk in several attempts. If the DeskManager is not initialized, the program should try to re-initialize it during the next API call. It will also allow the program to recover an unexpectedly lost desk connection.
tschroedter commented 1 year ago

Hi,

I haven't had time to test my fixes for the issues above. They are fixed in the develop branch but I'm still working on supporting multiple user configurations. Hope I get this into a stable state in the next few days.