diff --git a/.gitignore b/.gitignore index 5c454b95..2bd7bf95 100644 --- a/.gitignore +++ b/.gitignore @@ -5,4 +5,5 @@ obj/ .idea/ pluralkit.conf -pluralkit.*.conf \ No newline at end of file +pluralkit.*.conf +logs/ \ No newline at end of file diff --git a/PluralKit.Bot/Bot.cs b/PluralKit.Bot/Bot.cs index 57f100cd..36edb58a 100644 --- a/PluralKit.Bot/Bot.cs +++ b/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 { @@ -26,6 +31,15 @@ namespace PluralKit.Bot Console.WriteLine("Starting PluralKit..."); 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()) { @@ -42,59 +56,76 @@ namespace PluralKit.Bot Console.WriteLine("- Connecting to Discord..."); var client = services.GetRequiredService() as DiscordShardedClient; await client.LoginAsync(TokenType.Bot, botConfig.Token); - await client.StartAsync(); Console.WriteLine("- Initializing bot..."); await services.GetRequiredService().Init(); + + await client.StartAsync(); - await Task.Delay(-1); + try + { + await Task.Delay(-1, token.Token); + } + catch (TaskCanceledException) { } // We'll just exit normally + Console.WriteLine("- Shutting down..."); } } } public ServiceProvider BuildServiceProvider() => new ServiceCollection() - .AddTransient(_ => _config.GetSection("PluralKit").Get() ?? new CoreConfig()) - .AddTransient(_ => _config.GetSection("PluralKit").GetSection("Bot").Get() ?? new BotConfig()) - - .AddTransient(svc => new DbConnectionFactory(svc.GetRequiredService().Database)) - - .AddSingleton() - .AddSingleton() + .AddTransient(_ => _config.GetSection("PluralKit").Get() ?? new CoreConfig()) + .AddTransient(_ => _config.GetSection("PluralKit").GetSection("Bot").Get() ?? new BotConfig()) - .AddTransient(_ => new CommandService(new CommandServiceConfig + .AddTransient(svc => new DbConnectionFactory(svc.GetRequiredService().Database)) + + .AddSingleton() + .AddSingleton() + + .AddTransient(_ => new CommandService(new CommandServiceConfig + { + CaseSensitiveCommands = false, + QuotationMarkAliasMap = new Dictionary { - CaseSensitiveCommands = false, - QuotationMarkAliasMap = new Dictionary - { - {'"', '"'}, - {'\'', '\''}, - {'‘', '’'}, - {'“', '”'}, - {'„', '‟'}, - }, - DefaultRunMode = RunMode.Async - })) - .AddTransient() - .AddTransient() - .AddTransient() - .AddTransient() - - .AddSingleton() - - .AddTransient() - .AddTransient() - .AddTransient() - .AddTransient() - - .AddSingleton(svc => - { - var cfg = svc.GetRequiredService(); - var builder = AppMetrics.CreateDefaultBuilder(); - if (cfg.InfluxUrl != null && cfg.InfluxDb != null) - builder.Report.ToInfluxDb(cfg.InfluxUrl, cfg.InfluxDb); - return builder.Build(); - }) - .AddSingleton() + {'"', '"'}, + {'\'', '\''}, + {'‘', '’'}, + {'“', '”'}, + {'„', '‟'}, + }, + DefaultRunMode = RunMode.Async + })) + .AddTransient() + .AddTransient() + .AddTransient() + .AddTransient() + + .AddSingleton() + + .AddTransient() + .AddTransient() + .AddTransient() + .AddTransient() + + .AddSingleton(svc => + { + var cfg = svc.GetRequiredService(); + var builder = AppMetrics.CreateDefaultBuilder(); + if (cfg.InfluxUrl != null && cfg.InfluxDb != null) + builder.Report.ToInfluxDb(cfg.InfluxUrl, cfg.InfluxDb); + return builder.Build(); + }) + .AddSingleton() + + .AddSingleton(svc => new LoggerConfiguration() + .ConfigureForNodaTime(DateTimeZoneProviders.Tzdb) + .WriteTo.File( + new CompactJsonFormatter(), + (svc.GetRequiredService().LogDir ?? "logs") + "/pluralkit.bot.log", + rollingInterval: RollingInterval.Day, + flushToDiskInterval: TimeSpan.FromSeconds(10), + buffered: true) + .WriteTo.Console(theme: AnsiConsoleTheme.Code) + .CreateLogger()) .BuildServiceProvider(); } @@ -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(); } 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) @@ -207,7 +242,7 @@ namespace PluralKit.Bot // Ignore system messages (member joined, message pinned, etc) var arg = _arg as SocketUserMessage; if (arg == null) return; - + // Ignore bot messages if (arg.Author.IsBot || arg.Author.IsWebhook) return; @@ -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); } diff --git a/PluralKit.Bot/PluralKit.Bot.csproj b/PluralKit.Bot/PluralKit.Bot.csproj index 75aed6c6..059f28ea 100644 --- a/PluralKit.Bot/PluralKit.Bot.csproj +++ b/PluralKit.Bot/PluralKit.Bot.csproj @@ -15,6 +15,10 @@ + + + + diff --git a/PluralKit.Bot/Services/LogChannelService.cs b/PluralKit.Bot/Services/LogChannelService.cs index 966320a3..939dad2d 100644 --- a/PluralKit.Bot/Services/LogChannelService.cs +++ b/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(); } 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); } } } \ No newline at end of file diff --git a/PluralKit.Bot/Services/PeriodicStatCollector.cs b/PluralKit.Bot/Services/PeriodicStatCollector.cs index 8d81a74f..a1c98451 100644 --- a/PluralKit.Bot/Services/PeriodicStatCollector.cs +++ b/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(); } 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()); } } } \ No newline at end of file diff --git a/PluralKit.Bot/Services/ProxyService.cs b/PluralKit.Bot/Services/ProxyService.cs index 1fba8630..a8aa2f53 100644 --- a/PluralKit.Bot/Services/ProxyService.cs +++ b/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(); } private ProxyMatch GetProxyTagMatch(string message, IEnumerable 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; diff --git a/PluralKit.Core/CoreConfig.cs b/PluralKit.Core/CoreConfig.cs index 9c5d5df8..1ffd3205 100644 --- a/PluralKit.Core/CoreConfig.cs +++ b/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; } } } \ No newline at end of file diff --git a/PluralKit.Core/DataFiles.cs b/PluralKit.Core/DataFiles.cs index 38799b3d..346ab224 100644 --- a/PluralKit.Core/DataFiles.cs +++ b/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(); } public async Task ExportSystem(PKSystem system) @@ -131,6 +134,8 @@ namespace PluralKit.Bot await _members.Save(member); } + + _logger.Information("Imported system {System}", system.Id); // TODO: import switches, too? diff --git a/PluralKit.Core/PluralKit.Core.csproj b/PluralKit.Core/PluralKit.Core.csproj index 7f82a50e..0d2c4a76 100644 --- a/PluralKit.Core/PluralKit.Core.csproj +++ b/PluralKit.Core/PluralKit.Core.csproj @@ -19,6 +19,7 @@ + diff --git a/PluralKit.Core/Stores.cs b/PluralKit.Core/Stores.cs index f664059d..e42e49ef 100644 --- a/PluralKit.Core/Stores.cs +++ b/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(); } public async Task 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("insert into systems (hid, name) values (@Hid, @Name) returning *", new { Hid = hid, Name = systemName }); + system = await conn.QuerySingleAsync("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 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> 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(); } public async Task Create(PKSystem system, string name) { // TODO: handle collision var hid = Utils.GenerateHid(); - + + PKMember member; using (var conn = await _conn.Obtain()) - return await conn.QuerySingleAsync("insert into members (hid, system, name) values (@Hid, @SystemId, @Name) returning *", new { + member = await conn.QuerySingleAsync("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 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 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(); } 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 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 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(); } - public async Task RegisterSwitch(PKSystem system, IEnumerable members) + public async Task RegisterSwitch(PKSystem system, ICollection 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 Count() diff --git a/docker-compose.yml b/docker-compose.yml index 8adae190..905de2e1 100644 --- a/docker-compose.yml +++ b/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 diff --git a/docs/4-privacy-policy.md b/docs/4-privacy-policy.md index a7210020..9d481ecc 100644 --- a/docs/4-privacy-policy.md +++ b/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...