Skip to content

Commit

Permalink
Simplify logging in boot sequence (#2003)
Browse files Browse the repository at this point in the history 
* Use ILogger instead of SnLog in strtup sequence (part 1).

* Use ILogger: DistributedIndexingActivityQueue, startup.

* Use ILogger instead of SnLog in startup sequence (part 3).

* Use ILogger instead of SnLog in startup sequence (part 4).

* Refactor: comments removed.

* Do not echo console message to sntrace unconditionally.

* Use ILogger instead of SnLog in startup sequence (part 5).

* refactor

---------

Co-authored-by: Miklós Tóth <tusmester@gmail.com>
  • Loading branch information
@kavics @tusmester
kavics and tusmester committed Jan 8, 2024
1 parent 7d0334c commit 24d35de
Show file tree
Hide file tree
Showing 13 changed files with 162 additions and 91 deletions.
27 changes: 20 additions & 7 deletions src/ContentRepository/LoggingSettings.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,9 @@
using System.Collections.Generic;
using System.Linq;
using System.Threading;
using STT=System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.DependencyInjection;
using STT =System.Threading.Tasks;
using SenseNet.Communication.Messaging;
using SenseNet.Configuration;
using SenseNet.ContentRepository.Schema;
Expand Down Expand Up @@ -91,17 +93,15 @@ public static void UpdateCategoriesBySettings()
category.Enabled = value ?? _basicCategories[category.Name];
}

SnLog.WriteInformation("Trace settings were updated (from settings).", EventId.RepositoryRuntime,
properties: SnTrace.Categories.ToDictionary(c => c.Name, c => (object)c.Enabled.ToString()));
WriteInformation("settings");
}

public static void ConfigureCategories()
{
foreach (var category in SnTrace.Categories)
category.Enabled = Tracing.StartupTraceCategories.Contains(category.Name);

SnLog.WriteInformation("Trace settings were updated (from configuration).", EventId.RepositoryRuntime,
properties: SnTrace.Categories.ToDictionary(c => c.Name, c => (object)c.Enabled.ToString()));
WriteInformation("configuration");

UpdateBasicCategories();
}
Expand All @@ -127,14 +127,27 @@ internal static void UpdateCategories(string[] categoryNames)

UpdateBasicCategories();

SnLog.WriteInformation("Trace settings were updated (from assembly).", EventId.RepositoryRuntime,
properties: SnTrace.Categories.ToDictionary(c => c.Name, c => (object)c.Enabled.ToString()));
WriteInformation("assembly");
}

private static void UpdateBasicCategories()
{
_basicCategories = SnTrace.Categories.ToDictionary(c => c.Name, c => c.Enabled);
}

private static void WriteInformation(string source)
{
var logger = Providers.Instance?.Services.GetService<ILogger<LoggingSettings>>();
logger?.LogInformation($"Trace settings were updated (from {source}). " +
$"Enabled: {CategoriesToString(true)}. " +
$"Disabled: {CategoriesToString(false)}");
}
private static string CategoriesToString(bool isEnabled)
{
return string.Join(", ", SnTrace.Categories
.Where(x => x.Enabled == isEnabled)
.Select(x => x.Name));
}
}
}
}
119 changes: 64 additions & 55 deletions src/ContentRepository/RepositoryInstance.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,13 +8,15 @@
using System.IO;
using System.Threading;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using SenseNet.Communication.Messaging;
using SenseNet.Configuration;
using SenseNet.ContentRepository.Schema;
using SenseNet.ContentRepository.Storage.Security;
using SenseNet.Search.Querying;
using SenseNet.TaskManagement.Core;
using SenseNet.Tools;
using EventId = SenseNet.Diagnostics.EventId;

namespace SenseNet.ContentRepository
{
Expand Down Expand Up @@ -70,14 +72,15 @@ public class StartupInfo
/// Gets the started up instance or null.
/// </summary>
public static RepositoryInstance Instance { get { return _instance; } }

public TextWriter Console => _settings?.Console;

private RepositoryInstance()
{
_startupInfo = new StartupInfo { Starting = DateTime.UtcNow };
}

private ILogger<RepositoryInstance> _logger;
private static bool _started;
internal static RepositoryInstance Start(RepositoryStartSettings settings)
{
Expand All @@ -90,6 +93,7 @@ internal static RepositoryInstance Start(RepositoryStartSettings settings)
var instance = new RepositoryInstance();
instance._settings = new RepositoryStartSettings.ImmutableRepositoryStartSettings(settings);
_instance = instance;
_instance._logger = instance._settings.Services.GetService<ILogger<RepositoryInstance>>();
try
{
instance.DoStart();
Expand All @@ -107,9 +111,9 @@ internal static RepositoryInstance Start(RepositoryStartSettings settings)
}
internal void DoStart()
{
ConsoleWriteLine();
ConsoleWriteLine("Starting Repository...");
ConsoleWriteLine();
ConsoleWriteLine(false);
ConsoleWriteLine(true, "Starting Repository.");
ConsoleWriteLine(false);

LoggingSettings.SnTraceConfigurator.ConfigureCategories();
if (_settings.TraceCategories != null)
Expand Down Expand Up @@ -138,16 +142,15 @@ internal void DoStart()

// We have to log the access provider here because it cannot be logged
// during creation as it would lead to a circular reference.
SnLog.WriteInformation($"AccessProvider created: {AccessProvider.Current?.GetType().FullName}");

_logger.LogInformation($"AccessProvider created: {AccessProvider.Current?.GetType().FullName}");
using (new SystemAccount())
StartManagers();

LoggingSettings.SnTraceConfigurator.UpdateCategoriesBySettings();

ConsoleWriteLine();
ConsoleWriteLine("Repository has started.");
ConsoleWriteLine();
ConsoleWriteLine(false);
ConsoleWriteLine(true, "Repository has started.");
ConsoleWriteLine(false);

_startupInfo.Started = DateTime.UtcNow;
}
Expand All @@ -159,13 +162,13 @@ public void StartIndexingEngine()
{
if (IndexingEngineIsRunning)
{
ConsoleWrite("IndexingEngine has already started.");
ConsoleWrite(true, "IndexingEngine has already started.");
return;
}
ConsoleWriteLine("Starting IndexingEngine:");
ConsoleWriteLine(true, "Starting IndexingEngine.");
Providers.Instance.IndexManager.StartAsync(_settings.Console, CancellationToken.None).GetAwaiter().GetResult();
Providers.Instance.SearchManager.SearchEngine.SetIndexingInfo(ContentTypeManager.Instance.IndexingInfo);
ConsoleWriteLine("IndexingEngine has started.");
ConsoleWriteLine(true, "IndexingEngine has started.");
}

private bool _workflowEngineIsRunning;
Expand All @@ -176,21 +179,23 @@ public void StartWorkflowEngine()
{
if (_workflowEngineIsRunning)
{
ConsoleWrite("Workflow engine has already started.");
ConsoleWrite(true, "Workflow engine has already started.");
return;
}
ConsoleWrite("Starting Workflow subsystem ... ");
ConsoleWrite(false, "Starting Workflow subsystem ... ");
var t = TypeResolver.GetType("SenseNet.Workflow.InstanceManager", false);
if (t != null)
{
var m = t.GetMethod("StartWorkflowSystem", BindingFlags.Static | BindingFlags.Public);
m.Invoke(null, new object[0]);
_workflowEngineIsRunning = true;
ConsoleWriteLine("ok.");
ConsoleWriteLine(false, "ok.");
SnTrace.System.Write("Workflow subsystem started.");
}
else
{
ConsoleWriteLine("NOT STARTED");
ConsoleWriteLine(false, "NOT STARTED");
SnTrace.System.Write("Workflow subsystem NOT STARTED.");
}
}

Expand All @@ -203,25 +208,25 @@ private void LoadAssemblies(bool isWebContext)

if (!isWebContext)
{
ConsoleWriteLine("Loading Assemblies from ", localBin, ":");
ConsoleWriteLine(false, "Loading Assemblies from ", localBin, ":");
asmNames = TypeResolver.LoadAssembliesFrom(localBin);
foreach (string name in asmNames)
ConsoleWriteLine(" ", name);
ConsoleWriteLine(false, " ", name);
}

_startupInfo.ReferencedAssemblies = GetLoadedAsmNames().Except(_startupInfo.AssembliesBeforeStart).ToArray();

ConsoleWriteLine("Loading Assemblies from ", pluginsPath, ":");
ConsoleWriteLine(false, "Loading Assemblies from ", pluginsPath, ":");
asmNames = TypeResolver.LoadAssembliesFrom(pluginsPath);
_startupInfo.Plugins = GetLoadedAsmNames().Except(_startupInfo.AssembliesBeforeStart).Except(_startupInfo.ReferencedAssemblies).ToArray();

if (_settings.Console == null)
return;

foreach (string name in asmNames)
ConsoleWriteLine(" ", name);
ConsoleWriteLine("Ok.");
ConsoleWriteLine();
ConsoleWriteLine(false, " ", name);
ConsoleWriteLine(false, "Ok.");
ConsoleWriteLine(false);
}
private IEnumerable<string> GetLoadedAsmNames()
{
Expand All @@ -234,63 +239,68 @@ private void StartManagers()

try
{
ConsoleWrite("Initializing cache ... ");
ConsoleWrite(false, "Initializing cache ... ");
dummy = Cache.Count;

// Log this, because logging is switched off when creating the cache provider
// to avoid circular reference.
SnLog.WriteInformation($"CacheProvider created: {Cache.Instance?.GetType().FullName}");
ConsoleWriteLine("ok.");
_logger.LogInformation($"CacheProvider created: {Cache.Instance?.GetType().FullName}");
ConsoleWriteLine(false, "ok.");
SnTrace.System.Write("Cache initialized.");

ConsoleWrite("Starting message channel ... ");
ConsoleWrite(false, "Starting message channel ... ");
channel = Providers.Instance.ClusterChannelProvider;
channel.StartAsync(CancellationToken.None).GetAwaiter().GetResult();

ConsoleWriteLine("ok.");
SnLog.WriteInformation($"Message channel {channel.GetType().FullName} started." +
ConsoleWriteLine(false, "ok.");
_logger.LogInformation($"Message channel started: {channel.GetType().FullName}. " +
$"Instance id: {channel.ClusterMemberInfo.InstanceID}");

ConsoleWrite("Sending greeting message ... ");
ConsoleWrite(false, "Sending greeting message ... ");
new PingMessage(new string[0]).SendAsync(CancellationToken.None).GetAwaiter().GetResult();
ConsoleWriteLine("ok.");
ConsoleWriteLine(false, "ok.");
SnTrace.System.Write("Greeting message sent (PingMessage).");

ConsoleWrite("Starting NodeType system ... ");
ConsoleWrite(false, "Starting NodeType system ... ");
dummy = Providers.Instance.StorageSchema.NodeTypes[0];
ConsoleWriteLine("ok.");
ConsoleWriteLine(false, "ok.");
SnTrace.System.Write("NodeType system started.");

ConsoleWrite("Starting ContentType system ... ");
ConsoleWrite(false, "Starting ContentType system ... ");
dummy = ContentType.GetByName("GenericContent");
ConsoleWriteLine("ok.");
ConsoleWriteLine(false, "ok.");
SnTrace.System.Write("ContentType system started.");

ConsoleWrite("Starting AccessProvider ... ");
ConsoleWrite(false, "Starting AccessProvider ... ");
dummy = User.Current;
ConsoleWriteLine("ok.");
ConsoleWriteLine(false, "ok.");
SnTrace.System.Write("AccessProvider started.");

SnQuery.SetPermissionFilterFactory(Providers.Instance.PermissionFilterFactory);

if (_settings.StartIndexingEngine)
StartIndexingEngine();
else
ConsoleWriteLine("IndexingEngine is not started.");
ConsoleWriteLine(true, "IndexingEngine is not started.");

// switch on message processing after IndexingEngine was started.
channel.AllowMessageProcessing = true;

if (_settings.StartWorkflowEngine)
StartWorkflowEngine();
else
ConsoleWriteLine("Workflow subsystem is not started.");
ConsoleWriteLine(true, "Workflow subsystem is not started.");

ConsoleWrite("Loading string resources ... ");
ConsoleWrite(false, "Loading string resources ... ");
dummy = SenseNetResourceManager.Current;
ConsoleWriteLine("ok.");
ConsoleWriteLine(false, "ok.");
SnTrace.System.Write("String resources loaded.");

_serviceInstances = _settings.Services.GetServices<ISnService>().ToList();

foreach (var service in _serviceInstances)
{
service.Start();
ConsoleWriteLine("Service started: ", service.GetType().Name);
ConsoleWriteLine(true, "Service started: " + service.GetType().Name);
}

// register this application in the task management component
Expand Down Expand Up @@ -322,11 +332,9 @@ private static void InitializeLogger()
SnTrace.SnTracers.AddRange(tracers);
}

SnLog.WriteInformation("Loggers and tracers initialized.", properties: new Dictionary<string, object>
{
{ "Loggers", SnLog.Instance?.GetType().Name },
{ "Tracers", string.Join(", ", SnTrace.SnTracers.Select(snt => snt?.GetType().Name)) }
});
SnTrace.System.Write("Loggers and tracers initialized. " +
$"Loggers: {SnLog.Instance?.GetType().Name}. " +
$"Tracers: {string.Join(", ", SnTrace.SnTracers.Select(snt => snt?.GetType().Name))}");
}

private void RegisterAppdomainEventHandlers()
Expand Down Expand Up @@ -390,9 +398,9 @@ internal static void Shutdown()

SnTrace.Repository.Write("Sending a goodbye message.");

_instance.ConsoleWriteLine();
_instance.ConsoleWriteLine(false);

_instance.ConsoleWriteLine("Sending a goodbye message...");
_instance.ConsoleWriteLine(true, "Sending a goodbye message.");
var channel = Providers.Instance.ClusterChannelProvider;
channel.ClusterMemberInfo.NeedToRecover = false;
var pingMessage = new PingMessage();
Expand Down Expand Up @@ -421,26 +429,27 @@ internal static void Shutdown()
SnTrace.Repository.Write(msg);
SnTrace.Flush();

_instance.ConsoleWriteLine(msg);
_instance.ConsoleWriteLine();
_instance.ConsoleWriteLine(false, msg);
_instance.ConsoleWriteLine(false);
SnLog.WriteInformation(msg);

_instance = null;
_started = false;
}
}

public void ConsoleWrite(params string[] text)
public void ConsoleWrite(bool trace, params string[] text)
{
foreach (var s in text)
{
SnTrace.System.Write(s);
if(trace)
SnTrace.System.Write(s);
_settings.Console?.Write(s);
}
}
public void ConsoleWriteLine(params string[] text)
public void ConsoleWriteLine(bool trace, params string[] text)
{
ConsoleWrite(text);
ConsoleWrite(trace, text);
_settings.Console?.WriteLine();
}

Expand Down
8 changes: 7 additions & 1 deletion src/ContentRepository/Schema/ContentTypeManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,9 @@
using SenseNet.Search.Indexing;
using SenseNet.Tools;
using STT=System.Threading.Tasks;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using EventId = SenseNet.Diagnostics.EventId;

namespace SenseNet.ContentRepository.Schema
{
Expand Down Expand Up @@ -49,6 +52,7 @@ public override STT.Task DoActionAsync(bool onRemote, bool isFromMe, Cancellatio
private static bool _initializing = false;

private const string ContentTypeManagerProviderKey = "ContentTypeManager";
private ILogger<ContentTypeManager> _logger;

[Obsolete("Use Instace instead.")]
public static ContentTypeManager Current => Instance;
Expand All @@ -71,7 +75,7 @@ public static ContentTypeManager Instance
contentTypeManager = ctm;
_initializing = false;
Providers.Instance.SetProvider(ContentTypeManagerProviderKey, ctm);
SnLog.WriteInformation("ContentTypeManager created. Content types: " + ctm._contentTypes.Count);
contentTypeManager._logger.LogInformation("ContentTypeManager created. Content types: " + ctm._contentTypes.Count);
}
}
}
Expand Down Expand Up @@ -149,6 +153,8 @@ private static void Node_AnyContentListDeleted(object sender, EventArgs e)

private void Initialize()
{
_logger = Providers.Instance.Services.GetRequiredService<ILogger<ContentTypeManager>>();

using (new SenseNet.ContentRepository.Storage.Security.SystemAccount())
{
_contentPaths = new Dictionary<string, string>();
Expand Down
Loading

0 comments on commit 24d35de

Please sign in to comment.