ServiceFabric Managed Identity Token Service has debug console logging on

[johncrim]

Describe the bug
The problem is that all activity in the ManagedIdentityService is logged with high verbosity, and there doesn't appear to be a way to turn down the verbosity, since this is a system-provided /internal/not user configured service.

There are several problems with this:

1. It makes it much harder to view/watch important log output from other services, eg using:

journalctl -f -u servicefabric # Follow SF log

2. Log files written eg to VM (and possibly replicated to Azure blob storage) are unnecessarily verbose and large due to this setting
3. There may be some unnecessary performance drag due to this logging. MITS may not commonly be used heavily compared to user-installed services, but it could be depending on usage patterns of MITS.

Area/Component:
ManagedIdentityService

To Reproduce

1. Setup a ServiceFabric (classic) cluster on Linux - we use Ubuntu
2. Add ManagedIdentity support to an app as described here:
   https://learn.microsoft.com/en-us/azure/service-fabric/configure-existing-cluster-enable-managed-identity-token-service
   and here:
   https://learn.microsoft.com/en-us/azure/service-fabric/how-to-deploy-service-fabric-application-user-assigned-managed-identity
   The app needs to call the Managed Identity Service eg to get an access token for accessing other Azure services
3. Deploy the app and exercise it a little, to trigger requests to the Managed Identity Service
4. Watch the service fabric log output, either using:

systemctl status servicefabric -n 400

or

journalctl -f -u servicefabric

Note the verbosity of log output from the dotnet /MITS.Code.Current/ManagedIdentityTokenService.dll process, and how it obscures output from other SF services.

Expected behavior
Debug output from system services should be reasonably spare by default, though it would be nice to have a way to enable verbose or debug logging in the MITS if/when problems are encountered and debugging is useful.

Observed behavior:

(Private data redacted from console output)

User1@my-vms0000000:~$ systemctl status servicefabric -n 400
● servicefabric.service - ServiceFabric Daemon
     Loaded: loaded (/etc/systemd/system/servicefabric.service; disabled; vendor preset: enabled)
     Active: active (running) since Tue 2024-11-05 04:46:03 UTC; 15h ago
   Main PID: 16902 (starthost.sh)
      Tasks: 586 (limit: 9516)
     Memory: 4.2G
     CGroup: /system.slice/servicefabric.service
             ├─16902 /bin/bash /opt/microsoft/servicefabric/bin/starthost.sh
             ├─17042 /opt/microsoft/servicefabric/bin/FabricHost -c -skipfabricsetup
             ├─17105 dotnet FabricCAS.dll
             ├─17106 dotnet FabricDCA.dll
             ├─17186 /opt/microsoft/servicefabric/bin/Fabric/Fabric.Code/Fabric
             ├─17738 /opt/microsoft/servicefabric/bin/Fabric/Fabric.Code/FabricGateway.exe localhost:51557
             ├─19693 /data/sfroot/_App/__FabricSystem_App4294967295/FileStoreService.Code.Current/FileStoreService.exe
             ├─19877 /data/sfroot/_App/__FabricSystem_App4294967295/RM.Code.Current/FabricRM.exe
             ├─26294 bash /data/sfroot/_App/__FabricSystem_App4294967295/MITS.Code.Current/TokenService.sh
             ├─26296 dotnet /data/sfroot/_App/__FabricSystem_App4294967295/MITS.Code.Current/ManagedIdentityTokenService.dll
             ├─26343 bash /data/sfroot/_App/__FabricSystem_App4294967295/US.Code.Current/FabricUS.sh
             ├─26345 dotnet /data/sfroot/_App/__FabricSystem_App4294967295/US.Code.Current/FabricUS.dll
             ├─26353 /data/sfroot/_App/__FabricSystem_App4294967295/DnsService.Code.Current/FabricDnsService.exe

Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[1]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Execution plan of resource filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[1]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Execution plan of action filters (in the following order): Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000)
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[1]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Execution plan of exception filters (in the following order): None
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[1]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Execution plan of result filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: System.Fabric.ManagedIdentity.TokenService.Authentication.AuthenticationHandler[8]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       AuthenticationScheme: SFMICombinedAuthentication was successfully authenticated.
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[1]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Authorization was successful.
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[1]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Executing controller factory for controller System.Fabric.ManagedIdentity.TokenService.TokenController (ManagedIdentityTokenService)
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Executed controller factory for controller System.Fabric.ManagedIdentity.TokenService.TokenController (ManagedIdentityTokenService)
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder[22]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Attempting to bind parameter 'apiVersion' of type 'System.String' ...
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinder[44]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Attempting to bind parameter 'apiVersion' of type 'System.String' using the name 'api-version' in request data ...
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinder[45]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Done attempting to bind parameter 'apiVersion' of type 'System.String'.
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder[23]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Done attempting to bind parameter 'apiVersion' of type 'System.String'.
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder[26]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Attempting to validate the bound parameter 'apiVersion' of type 'System.String' ...
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder[27]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Done attempting to validate the bound parameter 'apiVersion' of type 'System.String'.
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder[22]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Attempting to bind parameter 'principalId' of type 'System.String' ...
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinder[44]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Attempting to bind parameter 'principalId' of type 'System.String' using the name '' in request data ...
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinder[16]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Could not find a value in the request with name '' for binding parameter 'principalId' of type 'System.String'.
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.Binders.SimpleTypeModelBinder[45]
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]:       Done attempting to bind parameter 'principalId' of type 'System.String'.
Nov 05 20:02:49 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder[23]

User1@my-vms0000000:~$ journalctl -f -u servicefabric
-- Logs begin at Tue 2024-11-05 04:40:24 UTC. --
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[2]
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]:       Connection id "0HN7TB37NKMNG" stopped.
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[10]
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]:       Connection id "0HN7TB37NKMNH" disconnecting.
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Server.Kestrel.Connections[2]
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]:       Connection id "0HN7TB37NKMNH" stopped.
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]:       Connection id "0HN7TB37NKMNG" sending FIN because: "The Socket transport's send loop completed gracefully."
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]: dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]
Nov 05 05:16:46 my-vms0000000 starthost.sh[26296]:       Connection id "0HN7TB37NKMNH" sending FIN because: "The Socket transport's send loop completed gracefully."
...

Service Fabric Runtime Version:
10.1.2308.1

Environment:

• Azure
• OS: Ubuntu 20.04
• Version 10.1.2308.1
• .NET 6 and 8.0.10

---

Assignees: /cc @microsoft/service-fabric-triage

[johncrim]

@dragav - hope you don't mind me notifying you, since you've replied to SF MSI issues in the past, and SF issues don't seem to be getting triaged by anyone.

[dragav]

@amenarde please see above, looks like something is off with MITS on Linux (not sure what is Xin's GH alias).

[amenarde]

Hi @johncrim I think this is a bug. We see that the log level is set to DEBUG in the Managed Identity Token Service's Kestrel server. This appears hardcoded, so we will aim to disable this in the next service fabric release. In the meantime, we will see if there is a way to disable it without code change.

[johncrim]

Thanks @amenarde - that's what I figured.

Certainly the default should be WARN (since much of ASP.NET is still unhelpfully verbose at the INFO level), but it would be nice to have a way to override the logging level if that was ever helpful (since the MSI service is a black box otherwise).