Add basic logging framework

.gitignore

@@ -6,3 +6,4 @@ obj/
 
 pluralkit.conf
 pluralkit.*.conf
+logs/

PluralKit.Bot/Bot.cs

@@ -11,7 +11,12 @@ using Discord.Commands;
 using Discord.WebSocket;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
+using NodaTime;
 using Sentry;
+using Serilog;
+using Serilog.Core;
+using Serilog.Formatting.Compact;
+using Serilog.Sinks.SystemConsole.Themes;
 
 namespace PluralKit.Bot
 {
@@ -27,6 +32,15 @@ namespace PluralKit.Bot
             
             InitUtils.Init();
 
+            // Set up a CancellationToken and a SIGINT hook to properly dispose of things when the app is closed
+            // The Task.Delay line will throw/exit (forgot which) and the stack and using statements will properly unwind
+            var token = new CancellationTokenSource();
+            Console.CancelKeyPress += delegate(object e, ConsoleCancelEventArgs args)
+            {
+                args.Cancel = true;
+                token.Cancel();
+            };
+            
             using (var services = BuildServiceProvider())
             {
                 var coreConfig = services.GetRequiredService<CoreConfig>();
@@ -42,12 +56,18 @@ namespace PluralKit.Bot
                     Console.WriteLine("- Connecting to Discord...");
                     var client = services.GetRequiredService<IDiscordClient>() as DiscordShardedClient;
                     await client.LoginAsync(TokenType.Bot, botConfig.Token);
-                    await client.StartAsync();
 
                     Console.WriteLine("- Initializing bot...");
                     await services.GetRequiredService<Bot>().Init();
                     
-                    await Task.Delay(-1);
+                    await client.StartAsync();
+
+                    try
+                    {
+                        await Task.Delay(-1, token.Token);
+                    }
+                    catch (TaskCanceledException) { } // We'll just exit normally
+                    Console.WriteLine("- Shutting down...");
                 }
             }
         }
@@ -96,6 +116,17 @@ namespace PluralKit.Bot
             })
             .AddSingleton<PeriodicStatCollector>()
 
+            .AddSingleton<ILogger>(svc => new LoggerConfiguration()
+                .ConfigureForNodaTime(DateTimeZoneProviders.Tzdb)
+                .WriteTo.File(
+                    new CompactJsonFormatter(),
+                        (svc.GetRequiredService<CoreConfig>().LogDir ?? "logs") + "/pluralkit.bot.log",
+                        rollingInterval: RollingInterval.Day,
+                        flushToDiskInterval: TimeSpan.FromSeconds(10),
+                        buffered: true)
+                    .WriteTo.Console(theme: AnsiConsoleTheme.Code)
+                    .CreateLogger())
+                
                 .BuildServiceProvider();
     }
     class Bot
@@ -107,8 +138,9 @@ namespace PluralKit.Bot
         private Timer _updateTimer;
         private IMetrics _metrics;
         private PeriodicStatCollector _collector;
+        private ILogger _logger;
 
-        public Bot(IServiceProvider services, IDiscordClient client, CommandService commands, ProxyService proxy, IMetrics metrics, PeriodicStatCollector collector)
+        public Bot(IServiceProvider services, IDiscordClient client, CommandService commands, ProxyService proxy, IMetrics metrics, PeriodicStatCollector collector, ILogger logger)
         {
             this._services = services;
             this._client = client as DiscordShardedClient;
@@ -116,6 +148,7 @@ namespace PluralKit.Bot
             this._proxy = proxy;
             _metrics = metrics;
             _collector = collector;
+            _logger = logger.ForContext<Bot>();
         }
 
         public async Task Init()
@@ -141,12 +174,14 @@ namespace PluralKit.Bot
             await _client.SetGameAsync($"pk;help | in {_client.Guilds.Count} servers");
             
             await _collector.CollectStats();
+            
+            _logger.Information("Submitted metrics to backend");
             await Task.WhenAll(((IMetricsRoot) _metrics).ReportRunner.RunAllAsync());
         }
 
         private async Task ShardReady(DiscordSocketClient shardClient)
         {
-
+            _logger.Information("Shard {Shard} connected", shardClient.ShardId);
             Console.WriteLine($"Shard #{shardClient.ShardId} connected to {shardClient.Guilds.Sum(g => g.Channels.Count)} channels in {shardClient.Guilds.Count} guilds.");
 
             if (shardClient.ShardId == 0)
@@ -243,6 +278,7 @@ namespace PluralKit.Bot
 
         private void HandleRuntimeError(Exception e)
         {
+            _logger.Error(e, "Exception in bot event handler");
             SentrySdk.CaptureException(e);
             Console.Error.WriteLine(e);
         }

PluralKit.Bot/PluralKit.Bot.csproj

@@ -15,6 +15,10 @@
       <PackageReference Include="Discord.Net.WebSocket" Version="2.0.1" />
       <PackageReference Include="Humanizer.Core" Version="2.6.2" />
       <PackageReference Include="Sentry" Version="2.0.0-beta2" />
+      <PackageReference Include="Serilog.Formatting.Compact" Version="1.0.0" />
+      <PackageReference Include="Serilog.NodaTime" Version="1.0.0" />
+      <PackageReference Include="Serilog.Sinks.Console" Version="3.1.1" />
+      <PackageReference Include="Serilog.Sinks.File" Version="4.0.0" />
       <PackageReference Include="SixLabors.ImageSharp" Version="1.0.0-beta0006" />
     </ItemGroup>
 

PluralKit.Bot/Services/LogChannelService.cs

@@ -1,6 +1,7 @@
 using System.Threading.Tasks;
 using Dapper;
 using Discord;
+using Serilog;
 
 namespace PluralKit.Bot {
     public class ServerDefinition {
@@ -12,12 +13,14 @@ namespace PluralKit.Bot {
         private IDiscordClient _client;
         private DbConnectionFactory _conn;
         private EmbedService _embed;
+        private ILogger _logger;
 
-        public LogChannelService(IDiscordClient client, DbConnectionFactory conn, EmbedService embed)
+        public LogChannelService(IDiscordClient client, DbConnectionFactory conn, EmbedService embed, ILogger logger)
         {
             this._client = client;
             this._conn = conn;
             this._embed = embed;
+            _logger = logger.ForContext<LogChannelService>();
         }
 
         public async Task LogMessage(PKSystem system, PKMember member, ulong messageId, IGuildChannel originalChannel, IUser sender, string content) {
@@ -53,6 +56,8 @@ namespace PluralKit.Bot {
                     "insert into servers (id, log_channel) values (@Id, @LogChannel) on conflict (id) do update set log_channel = @LogChannel",
                     def);
             }
+            
+            _logger.Information("Set guild {} log channel to {Channel}", guild.Id, newLogChannel?.Id);
         }
     }
 }

PluralKit.Bot/Services/PeriodicStatCollector.cs

@@ -1,10 +1,13 @@
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Threading.Tasks;
 using App.Metrics;
 using Discord;
 using Discord.WebSocket;
+using NodaTime.Extensions;
 using PluralKit.Core;
+using Serilog;
 
 namespace PluralKit.Bot
 {
@@ -18,7 +21,9 @@ namespace PluralKit.Bot
         private SwitchStore _switches;
         private MessageStore _messages;
 
-        public PeriodicStatCollector(IDiscordClient client, IMetrics metrics, SystemStore systems, MemberStore members, SwitchStore switches, MessageStore messages)
+        private ILogger _logger;
+
+        public PeriodicStatCollector(IDiscordClient client, IMetrics metrics, SystemStore systems, MemberStore members, SwitchStore switches, MessageStore messages, ILogger logger)
         {
             _client = (DiscordShardedClient) client;
             _metrics = metrics;
@@ -26,10 +31,14 @@ namespace PluralKit.Bot
             _members = members;
             _switches = switches;
             _messages = messages;
+            _logger = logger.ForContext<PeriodicStatCollector>();
         }
 
         public async Task CollectStats()
         {
+            var stopwatch = new Stopwatch();
+            stopwatch.Start();
+            
             // Aggregate guild/channel stats
             _metrics.Measure.Gauge.SetValue(BotMetrics.Guilds, _client.Guilds.Count);
             _metrics.Measure.Gauge.SetValue(BotMetrics.Channels, _client.Guilds.Sum(g => g.TextChannels.Count));
@@ -52,6 +61,9 @@ namespace PluralKit.Bot
             _metrics.Measure.Gauge.SetValue(CoreMetrics.MemberCount, await _members.Count());
             _metrics.Measure.Gauge.SetValue(CoreMetrics.SwitchCount, await _switches.Count());
             _metrics.Measure.Gauge.SetValue(CoreMetrics.MessageCount, await _messages.Count());
+
+            stopwatch.Stop();
+            _logger.Information("Updated metrics in {Time}", stopwatch.ElapsedDuration());
         }
     }
 }

PluralKit.Bot/Services/ProxyService.cs

@@ -10,6 +10,7 @@ using Discord;
 using Discord.Net;
 using Discord.Webhook;
 using Discord.WebSocket;
+using Serilog;
 
 namespace PluralKit.Bot
 {
@@ -30,21 +31,23 @@ namespace PluralKit.Bot
     class ProxyService {
         private IDiscordClient _client;
         private DbConnectionFactory _conn;
-        private LogChannelService _logger;
+        private LogChannelService _logChannel;
         private WebhookCacheService _webhookCache;
         private MessageStore _messageStorage;
         private EmbedService _embeds;
         private IMetrics _metrics;
+        private ILogger _logger;
         
-        public ProxyService(IDiscordClient client, WebhookCacheService webhookCache, DbConnectionFactory conn, LogChannelService logger, MessageStore messageStorage, EmbedService embeds, IMetrics metrics)
+        public ProxyService(IDiscordClient client, WebhookCacheService webhookCache, DbConnectionFactory conn, LogChannelService logChannel, MessageStore messageStorage, EmbedService embeds, IMetrics metrics, ILogger logger)
         {
             _client = client;
             _webhookCache = webhookCache;
             _conn = conn;
-            _logger = logger;
+            _logChannel = logChannel;
             _messageStorage = messageStorage;
             _embeds = embeds;
             _metrics = metrics;
+            _logger = logger.ForContext<ProxyService>();
         }
 
         private ProxyMatch GetProxyTagMatch(string message, IEnumerable<ProxyDatabaseResult> potentials)
@@ -108,7 +111,7 @@ namespace PluralKit.Bot
 
             // Store the message in the database, and log it in the log channel (if applicable)
             await _messageStorage.Store(message.Author.Id, hookMessageId, message.Channel.Id, match.Member);
-            await _logger.LogMessage(match.System, match.Member, hookMessageId, message.Channel as IGuildChannel, message.Author, match.InnerText);
+            await _logChannel.LogMessage(match.System, match.Member, hookMessageId, message.Channel as IGuildChannel, message.Author, match.InnerText);
 
             // Wait a second or so before deleting the original message
             await Task.Delay(1000);
@@ -177,11 +180,15 @@ namespace PluralKit.Bot
                     messageId = await client.SendMessageAsync(text, username: username, avatarUrl: avatarUrl);
                 }
                 
+                _logger.Information("Invoked webhook {Webhook} in channel {Channel}", webhook.Id, webhook.Channel);
+
                 // Log it in the metrics
                 _metrics.Measure.Meter.Mark(BotMetrics.MessagesProxied, "success");
             }
-            catch (HttpException)
+            catch (HttpException e)
             {
+                _logger.Warning(e, "Error invoking webhook {Webhook} in channel {Channel}", webhook.Id, webhook.ChannelId);
+                
                 // Log failure in metrics and rethrow (we still need to cancel everything else)
                 _metrics.Measure.Meter.Mark(BotMetrics.MessagesProxied, "failure");
                 throw;

PluralKit.Core/CoreConfig.cs

@@ -6,5 +6,6 @@ namespace PluralKit
         public string SentryUrl { get; set; }
         public string InfluxUrl { get; set; }
         public string InfluxDb { get; set; }
+        public string LogDir { get; set; }
     }
 }

PluralKit.Core/DataFiles.cs

@@ -3,6 +3,7 @@ using System.Linq;
 using System.Threading.Tasks;
 using Newtonsoft.Json;
 using NodaTime;
+using Serilog;
 
 namespace PluralKit.Bot
 {
@@ -11,12 +12,14 @@ namespace PluralKit.Bot
         private SystemStore _systems;
         private MemberStore _members;
         private SwitchStore _switches;
+        private ILogger _logger;
 
-        public DataFileService(SystemStore systems, MemberStore members, SwitchStore switches)
+        public DataFileService(SystemStore systems, MemberStore members, SwitchStore switches, ILogger logger)
         {
             _systems = systems;
             _members = members;
             _switches = switches;
+            _logger = logger.ForContext<DataFileService>();
         }
 
         public async Task<DataFileSystem> ExportSystem(PKSystem system)
@@ -132,6 +135,8 @@ namespace PluralKit.Bot
                 await _members.Save(member);
             }
             
+            _logger.Information("Imported system {System}", system.Id);
+
             // TODO: import switches, too?
 
             result.System = system;

PluralKit.Core/PluralKit.Core.csproj

@@ -19,6 +19,7 @@
       <PackageReference Include="NodaTime.Serialization.JsonNet" Version="2.2.0" />
       <PackageReference Include="Npgsql" Version="4.0.6" />
       <PackageReference Include="Npgsql.NodaTime" Version="4.0.6" />
+      <PackageReference Include="Serilog" Version="2.8.0" />
     </ItemGroup>
 
     <ItemGroup>

PluralKit.Core/Stores.cs

@@ -1,23 +1,32 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Threading.Tasks;
+using App.Metrics.Logging;
 using Dapper;
 using NodaTime;
+using Serilog;
 
 namespace PluralKit {
     public class SystemStore {
         private DbConnectionFactory _conn;
+        private ILogger _logger;
 
-        public SystemStore(DbConnectionFactory conn) {
+        public SystemStore(DbConnectionFactory conn, ILogger logger)
+        {
             this._conn = conn;
+            _logger = logger.ForContext<SystemStore>();
         }
         
         public async Task<PKSystem> Create(string systemName = null) {
             // TODO: handle HID collision case
             var hid = Utils.GenerateHid();
 
+            PKSystem system;
             using (var conn = await _conn.Obtain())
-                return await conn.QuerySingleAsync<PKSystem>("insert into systems (hid, name) values (@Hid, @Name) returning *", new { Hid = hid, Name = systemName });
+                system = await conn.QuerySingleAsync<PKSystem>("insert into systems (hid, name) values (@Hid, @Name) returning *", new { Hid = hid, Name = systemName });
+            
+            _logger.Information("Created system {System}", system.Id);
+            return system;
         }
 
         public async Task Link(PKSystem system, ulong accountId) {
@@ -25,11 +34,15 @@ namespace PluralKit {
             // This is used in import/export, although the pk;link command checks for this case beforehand
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("insert into accounts (uid, system) values (@Id, @SystemId) on conflict do nothing", new { Id = accountId, SystemId = system.Id });
+            
+            _logger.Information("Linked system {System} to account {Account}", system.Id, accountId);
         }
         
         public async Task Unlink(PKSystem system, ulong accountId) {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("delete from accounts where uid = @Id and system = @SystemId", new { Id = accountId, SystemId = system.Id });
+            
+            _logger.Information("Unlinked system {System} from account {Account}", system.Id, accountId);
         }
 
         public async Task<PKSystem> GetByAccount(ulong accountId) {
@@ -56,11 +69,14 @@ namespace PluralKit {
         public async Task Save(PKSystem system) {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("update systems set name = @Name, description = @Description, tag = @Tag, avatar_url = @AvatarUrl, token = @Token, ui_tz = @UiTz where id = @Id", system);
+            
+            _logger.Information("Updated system {@System}", system);
         }
 
         public async Task Delete(PKSystem system) {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("delete from systems where id = @Id", system);
+            _logger.Information("Deleted system {System}", system.Id);
         }        
 
         public async Task<IEnumerable<ulong>> GetLinkedAccountIds(PKSystem system)
@@ -78,21 +94,28 @@ namespace PluralKit {
 
     public class MemberStore {
         private DbConnectionFactory _conn;
+        private ILogger _logger;
 
-        public MemberStore(DbConnectionFactory conn) {
+        public MemberStore(DbConnectionFactory conn, ILogger logger)
+        {
             this._conn = conn;
+            _logger = logger.ForContext<MemberStore>();
         }
 
         public async Task<PKMember> Create(PKSystem system, string name) {
             // TODO: handle collision
             var hid = Utils.GenerateHid();
 
+            PKMember member;
             using (var conn = await _conn.Obtain())
-                return await conn.QuerySingleAsync<PKMember>("insert into members (hid, system, name) values (@Hid, @SystemId, @Name) returning *", new {
+                member = await conn.QuerySingleAsync<PKMember>("insert into members (hid, system, name) values (@Hid, @SystemId, @Name) returning *", new {
                     Hid = hid,
                     SystemID = system.Id,
                     Name = name
                 });
+            
+            _logger.Information("Created member {Member}", member.Id);
+            return member;
         }
 
         public async Task<PKMember> GetByHid(string hid) {
@@ -122,11 +145,15 @@ namespace PluralKit {
         public async Task Save(PKMember member) {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("update members set name = @Name, description = @Description, color = @Color, avatar_url = @AvatarUrl, birthday = @Birthday, pronouns = @Pronouns, prefix = @Prefix, suffix = @Suffix where id = @Id", member);
+            
+            _logger.Information("Updated member {@Member}", member);
         }
 
         public async Task Delete(PKMember member) {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("delete from members where id = @Id", member);
+            
+            _logger.Information("Deleted member {@Member}", member);
         }
 
         public async Task<int> MessageCount(PKMember member)
@@ -163,9 +190,12 @@ namespace PluralKit {
         }
 
         private DbConnectionFactory _conn;
+        private ILogger _logger;
 
-        public MessageStore(DbConnectionFactory conn) {
+        public MessageStore(DbConnectionFactory conn, ILogger logger)
+        {
             this._conn = conn;
+            _logger = logger.ForContext<MessageStore>();
         }
 
         public async Task Store(ulong senderId, ulong messageId, ulong channelId, PKMember member) {
@@ -176,6 +206,8 @@ namespace PluralKit {
                     MemberId = member.Id,
                     SenderId = senderId
                 });      
+            
+            _logger.Information("Stored message {Message} in channel {Channel}", messageId, channelId);
         }
 
         public async Task<StoredMessage> Get(ulong id)
@@ -192,6 +224,8 @@ namespace PluralKit {
         public async Task Delete(ulong id) {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("delete from messages where mid = @Id", new { Id = id });
+            
+            _logger.Information("Deleted message {Message}", id);
         }
         
         public async Task<ulong> Count()
@@ -204,13 +238,15 @@ namespace PluralKit {
     public class SwitchStore
     {
         private DbConnectionFactory _conn;
+        private ILogger _logger;
 
-        public SwitchStore(DbConnectionFactory conn)
+        public SwitchStore(DbConnectionFactory conn, ILogger logger)
         {
             _conn = conn;
+            _logger = logger.ForContext<SwitchStore>();
         }
 
-        public async Task RegisterSwitch(PKSystem system, IEnumerable<PKMember> members)
+        public async Task RegisterSwitch(PKSystem system, ICollection<PKMember> members)
         {
             // Use a transaction here since we're doing multiple executed commands in one
             using (var conn = await _conn.Obtain())
@@ -231,6 +267,8 @@ namespace PluralKit {
                 
                 // Finally we commit the tx, since the using block will otherwise rollback it
                 tx.Commit();
+                
+                _logger.Information("Registered switch {Switch} in system {System} with members {@Members}", sw.Id, system.Id, members.Select(m => m.Id));
             }
         }
 
@@ -264,12 +302,16 @@ namespace PluralKit {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("update switches set timestamp = @Time where id = @Id",
                     new {Time = time, Id = sw.Id});
+            
+            _logger.Information("Moved switch {Switch} to {Time}", sw.Id, time);
         }
 
         public async Task DeleteSwitch(PKSwitch sw)
         {
             using (var conn = await _conn.Obtain())
                 await conn.ExecuteAsync("delete from switches where id = @Id", new {Id = sw.Id});
+            
+            _logger.Information("Deleted switch {Switch}");
         }
         
         public async Task<ulong> Count()

docker-compose.yml

@@ -7,8 +7,10 @@ services:
       - "PluralKit:Database=Host=db;Username=postgres;Password=postgres;Database=postgres"
       - "PluralKit:InfluxUrl=http://influx:8086"
       - "PluralKit:InfluxDb=pluralkit"
+      - "PluralKit:LogDir=/var/log/pluralkit"
     volumes:
       - "./pluralkit.conf:/app/pluralkit.conf:ro"
+      - "/var/log/pluralkit:/var/log/pluralkit"
     links:
       - db
       - influx

docs/4-privacy-policy.md

@@ -13,7 +13,9 @@ This is the data PluralKit collects indefinitely:
 * Information *you give the bot* (eg. system/member profiles, switch history, linked accounts, etc)
 * Metadata about proxied messages (sender account ID, sender system/member, timestamp)
 * Aggregate anonymous usage metrics (eg. gateway events received/second, messages proxied/second, commands executed/second)
+  * This is visible on [https://stats.pluralkit.me/](https://stats.pluralkit.me/)
 * Nightly database backups of the above information
+* High-level logs of actions taken on the bot (eg. systems created or deleted, switches logged, etc)
 
 This is the data PluralKit does *not* collect:
 * Anything not listed above, including...