From 9ae02a6f4be36ae1f9c632b111d3e42f5bd9baa9 Mon Sep 17 00:00:00 2001 From: insleker Date: Wed, 8 Apr 2026 21:57:17 +0800 Subject: [PATCH] feat: switch logging to logger for #22 Replace the plain logging backend with a color-capable logger adapter so CLI output is easier to scan, and add richer gosmee/webhook-forward diagnostics so tracker and forwarding failures can be debugged from logs. --- bin/code_work_spawner.dart | 14 +- lib/code_work_spawner.dart | 1 + lib/src/app_logger.dart | 206 ++++++++++++ lib/src/config_schema.g.dart | 317 ++++++++++++++++++ lib/src/issue_assistant_app.dart | 4 +- lib/src/issue_event_source/base.dart | 6 +- lib/src/issue_event_source/gitea_gosmee.dart | 65 +++- lib/src/issue_event_source/github_gosmee.dart | 53 ++- .../github_webhook_forward.dart | 33 +- pubspec.yaml | 2 +- .../webhook_forward_test.dart | 20 +- ...ssue_assistant_app_run_once_core_test.dart | 12 +- test/issue_assistant_app_run_retry_test.dart | 12 +- 13 files changed, 686 insertions(+), 59 deletions(-) create mode 100644 lib/src/app_logger.dart create mode 100644 lib/src/config_schema.g.dart diff --git a/bin/code_work_spawner.dart b/bin/code_work_spawner.dart index f8ccf84..0c5e495 100644 --- a/bin/code_work_spawner.dart +++ b/bin/code_work_spawner.dart @@ -3,7 +3,6 @@ import 'dart:io'; import 'package:args/args.dart'; import 'package:args/command_runner.dart'; import 'package:code_work_spawner/code_work_spawner.dart'; -import 'package:logging/logging.dart'; Future main(List arguments) async { _configureLogging(); @@ -73,7 +72,7 @@ class _CodeWorkSpawnerCommandRunner extends CommandRunner { } final config = await AppConfig.load(topLevelResults['config'] as String); - final logger = Logger('code_work_spawner.cli'); + final logger = AppLogger('code_work_spawner.cli'); logger.info( 'loaded config=${config.configPath} ' 'projects=${config.projects.length} ' @@ -162,11 +161,8 @@ class _InitConfigCommand extends Command { } void _configureLogging() { - hierarchicalLoggingEnabled = true; - Logger.root.level = Level.INFO; - Logger.root.onRecord.listen((record) { - stdout.writeln( - '[${record.loggerName}] ${record.level.name}: ${record.message}', - ); - }); + AppLogger.configure( + minimumLevel: AppLogLevel.info, + useColors: stdout.hasTerminal, + ); } diff --git a/lib/code_work_spawner.dart b/lib/code_work_spawner.dart index c67d03a..5bb59a3 100644 --- a/lib/code_work_spawner.dart +++ b/lib/code_work_spawner.dart @@ -1,6 +1,7 @@ export 'src/comment_templates.dart'; export 'src/config.dart'; export 'src/database.dart'; +export 'src/app_logger.dart'; export 'src/issue_event_source/base.dart'; export 'src/issue_tracker_client.dart'; export 'src/issue_assistant_app.dart'; diff --git a/lib/src/app_logger.dart b/lib/src/app_logger.dart new file mode 100644 index 0000000..c78f59b --- /dev/null +++ b/lib/src/app_logger.dart @@ -0,0 +1,206 @@ +import 'dart:convert'; + +import 'package:logger/web.dart' as logger; + +typedef AppLogListener = void Function(AppLogRecord record); + +enum AppLogLevel { trace, debug, info, warning, error, fatal } + +class AppLogRecord { + const AppLogRecord({ + required this.loggerName, + required this.level, + required this.message, + required this.time, + this.error, + this.stackTrace, + }); + + final String loggerName; + final AppLogLevel level; + final String message; + final DateTime time; + final Object? error; + final StackTrace? stackTrace; +} + +class AppLogger { + AppLogger(this.name); + + static final Set _listeners = {}; + static logger.Logger? _backend; + static AppLogLevel _minimumLevel = AppLogLevel.info; + static bool _useColors = false; + + final String name; + + static AppLogLevel get minimumLevel => _minimumLevel; + + static void configure({ + AppLogLevel minimumLevel = AppLogLevel.info, + bool useColors = true, + }) { + _minimumLevel = minimumLevel; + _useColors = useColors; + _backend = _createBackend(); + } + + static void addListener(AppLogListener listener) { + _listeners.add(listener); + } + + static bool removeListener(AppLogListener listener) { + return _listeners.remove(listener); + } + + void trace(String message, {Object? error, StackTrace? stackTrace}) { + _log(AppLogLevel.trace, message, error: error, stackTrace: stackTrace); + } + + void debug(String message, {Object? error, StackTrace? stackTrace}) { + _log(AppLogLevel.debug, message, error: error, stackTrace: stackTrace); + } + + void info(String message, {Object? error, StackTrace? stackTrace}) { + _log(AppLogLevel.info, message, error: error, stackTrace: stackTrace); + } + + void warning(String message, {Object? error, StackTrace? stackTrace}) { + _log(AppLogLevel.warning, message, error: error, stackTrace: stackTrace); + } + + void error(String message, {Object? error, StackTrace? stackTrace}) { + _log(AppLogLevel.error, message, error: error, stackTrace: stackTrace); + } + + void fatal(String message, {Object? error, StackTrace? stackTrace}) { + _log(AppLogLevel.fatal, message, error: error, stackTrace: stackTrace); + } + + void severe(String message, {Object? error, StackTrace? stackTrace}) { + error == null && stackTrace == null + ? this.error(message) + : this.error(message, error: error, stackTrace: stackTrace); + } + + void _log( + AppLogLevel level, + String message, { + Object? error, + StackTrace? stackTrace, + }) { + final record = AppLogRecord( + loggerName: name, + level: level, + message: message, + time: DateTime.now(), + error: error, + stackTrace: stackTrace, + ); + for (final listener in _listeners) { + listener(record); + } + (_backend ??= _createBackend()).log( + _mapLevel(level), + record, + error: error, + stackTrace: stackTrace, + ); + } + + static logger.Logger _createBackend() { + return logger.Logger( + level: _mapLevel(_minimumLevel), + printer: _AppLogPrinter(useColors: _useColors), + ); + } + + static logger.Level _mapLevel(AppLogLevel level) { + switch (level) { + case AppLogLevel.trace: + return logger.Level.trace; + case AppLogLevel.debug: + return logger.Level.debug; + case AppLogLevel.info: + return logger.Level.info; + case AppLogLevel.warning: + return logger.Level.warning; + case AppLogLevel.error: + return logger.Level.error; + case AppLogLevel.fatal: + return logger.Level.fatal; + } + } +} + +class _AppLogPrinter extends logger.LogPrinter { + _AppLogPrinter({required bool useColors}) : _useColors = useColors; + + final bool _useColors; + + static final Map _levelColors = { + AppLogLevel.trace: logger.AnsiColor.fg(logger.AnsiColor.grey(0.5)), + AppLogLevel.debug: const logger.AnsiColor.none(), + AppLogLevel.info: const logger.AnsiColor.fg(39), + AppLogLevel.warning: const logger.AnsiColor.fg(214), + AppLogLevel.error: const logger.AnsiColor.fg(196), + AppLogLevel.fatal: const logger.AnsiColor.fg(199), + }; + + @override + List log(logger.LogEvent event) { + final record = event.message is AppLogRecord + ? event.message as AppLogRecord + : AppLogRecord( + loggerName: 'app', + level: AppLogLevel.info, + message: event.message.toString(), + time: event.time, + error: event.error, + stackTrace: event.stackTrace, + ); + final prefix = '[${record.loggerName}] ${_labelFor(record.level)}: '; + final lines = [ + for (final line in const LineSplitter().convert(record.message)) + _applyColor(record.level, '$prefix$line'), + ]; + if (record.message.isEmpty) { + lines.add(_applyColor(record.level, prefix.trimRight())); + } + if (record.error != null) { + lines.add(_applyColor(record.level, '$prefix${record.error}')); + } + if (record.stackTrace != null) { + lines.addAll( + const LineSplitter() + .convert(record.stackTrace.toString()) + .map((line) => _applyColor(record.level, '$prefix$line')), + ); + } + return lines; + } + + String _applyColor(AppLogLevel level, String text) { + if (!_useColors) { + return text; + } + return (_levelColors[level] ?? const logger.AnsiColor.none())(text); + } + + String _labelFor(AppLogLevel level) { + switch (level) { + case AppLogLevel.trace: + return 'TRACE'; + case AppLogLevel.debug: + return 'DEBUG'; + case AppLogLevel.info: + return 'INFO'; + case AppLogLevel.warning: + return 'WARN'; + case AppLogLevel.error: + return 'ERROR'; + case AppLogLevel.fatal: + return 'FATAL'; + } + } +} diff --git a/lib/src/config_schema.g.dart b/lib/src/config_schema.g.dart new file mode 100644 index 0000000..3ba0b71 --- /dev/null +++ b/lib/src/config_schema.g.dart @@ -0,0 +1,317 @@ +// GENERATED CODE - DO NOT MODIFY BY HAND + +part of 'config_schema.dart'; + +// ************************************************************************** +// JsonSerializableGenerator +// ************************************************************************** + +AppConfigDocument _$AppConfigDocumentFromJson(Map json) => + $checkedCreate('AppConfigDocument', json, ($checkedConvert) { + $checkKeys( + json, + allowedKeys: const ['dataDir', 'worktreeDir', 'defaults', 'projects'], + ); + final val = AppConfigDocument( + dataDir: $checkedConvert('dataDir', (v) => v as String?), + worktreeDir: $checkedConvert('worktreeDir', (v) => v as String?), + defaults: $checkedConvert( + 'defaults', + (v) => v == null + ? null + : AppConfigDefaultsDocument.fromJson(v as Map), + ), + projects: $checkedConvert( + 'projects', + (v) => (v as Map?)?.map( + (k, e) => MapEntry( + k, + ProjectConfigDocument.fromJson(e as Map), + ), + ), + ), + ); + return val; + }); + +Map _$AppConfigDocumentToJson(AppConfigDocument instance) => + { + 'dataDir': ?instance.dataDir, + 'worktreeDir': ?instance.worktreeDir, + 'defaults': ?instance.defaults?.toJson(), + 'projects': ?instance.projects?.map((k, e) => MapEntry(k, e.toJson())), + }; + +AppConfigDefaultsDocument _$AppConfigDefaultsDocumentFromJson( + Map json, +) => $checkedCreate('AppConfigDefaultsDocument', json, ($checkedConvert) { + $checkKeys(json, allowedKeys: const ['issueAssistant']); + final val = AppConfigDefaultsDocument( + issueAssistant: $checkedConvert( + 'issueAssistant', + (v) => v == null + ? null + : IssueAssistantConfigDocument.fromJson(v as Map), + ), + ); + return val; +}); + +Map _$AppConfigDefaultsDocumentToJson( + AppConfigDefaultsDocument instance, +) => {'issueAssistant': ?instance.issueAssistant?.toJson()}; + +ProjectConfigDocument _$ProjectConfigDocumentFromJson( + Map json, +) => $checkedCreate('ProjectConfigDocument', json, ($checkedConvert) { + $checkKeys( + json, + allowedKeys: const [ + 'provider', + 'repo', + 'path', + 'defaultBranch', + 'sessionPrefix', + 'issueAssistant', + ], + ); + final val = ProjectConfigDocument( + provider: $checkedConvert( + 'provider', + (v) => $enumDecodeNullable(_$IssueTrackerProviderEnumMap, v), + ), + repo: $checkedConvert('repo', (v) => v as String?), + path: $checkedConvert('path', (v) => v as String?), + defaultBranch: $checkedConvert('defaultBranch', (v) => v as String?), + sessionPrefix: $checkedConvert('sessionPrefix', (v) => v as String?), + issueAssistant: $checkedConvert( + 'issueAssistant', + (v) => v == null + ? null + : IssueAssistantConfigDocument.fromJson(v as Map), + ), + ); + return val; +}); + +Map _$ProjectConfigDocumentToJson( + ProjectConfigDocument instance, +) => { + 'provider': ?_$IssueTrackerProviderEnumMap[instance.provider], + 'repo': ?instance.repo, + 'path': ?instance.path, + 'defaultBranch': ?instance.defaultBranch, + 'sessionPrefix': ?instance.sessionPrefix, + 'issueAssistant': ?instance.issueAssistant?.toJson(), +}; + +const _$IssueTrackerProviderEnumMap = { + IssueTrackerProvider.github: 'github', + IssueTrackerProvider.gitea: 'gitea', +}; + +IssueAssistantConfigDocument _$IssueAssistantConfigDocumentFromJson( + Map json, +) => $checkedCreate('IssueAssistantConfigDocument', json, ($checkedConvert) { + $checkKeys( + json, + allowedKeys: const [ + 'enabled', + 'eventSource', + 'pollInterval', + 'maxConcurrentIssues', + 'mentionTriggers', + 'prompt', + 'responders', + 'capabilities', + 'notifications', + 'commentTag', + 'commentPrefixTemplate', + 'commentFooterTemplate', + ], + ); + final val = IssueAssistantConfigDocument( + enabled: $checkedConvert('enabled', (v) => v as bool?), + eventSource: $checkedConvert( + 'eventSource', + (v) => $enumDecodeNullable(_$IssueAssistantEventSourceKindEnumMap, v), + ), + pollInterval: $checkedConvert('pollInterval', (v) => v as String?), + maxConcurrentIssues: $checkedConvert( + 'maxConcurrentIssues', + (v) => (v as num?)?.toInt(), + ), + mentionTriggers: $checkedConvert( + 'mentionTriggers', + (v) => (v as List?)?.map((e) => e as String).toList(), + ), + prompt: $checkedConvert('prompt', (v) => v as String?), + responders: $checkedConvert( + 'responders', + (v) => (v as List?) + ?.map( + (e) => + CliResponderConfigDocument.fromJson(e as Map), + ) + .toList(), + ), + capabilities: $checkedConvert( + 'capabilities', + (v) => (v as List?) + ?.map((e) => $enumDecode(_$AssistantCapabilityEnumMap, e)) + .toList(), + ), + notifications: $checkedConvert( + 'notifications', + (v) => (v as List?) + ?.map( + (e) => + NotificationConfigDocument.fromJson(e as Map), + ) + .toList(), + ), + commentTag: $checkedConvert('commentTag', (v) => v as String?), + commentPrefixTemplate: $checkedConvert( + 'commentPrefixTemplate', + (v) => v as String?, + ), + commentFooterTemplate: $checkedConvert( + 'commentFooterTemplate', + (v) => v as String?, + ), + ); + return val; +}); + +Map _$IssueAssistantConfigDocumentToJson( + IssueAssistantConfigDocument instance, +) => { + 'enabled': ?instance.enabled, + 'eventSource': ?_$IssueAssistantEventSourceKindEnumMap[instance.eventSource], + 'pollInterval': ?instance.pollInterval, + 'maxConcurrentIssues': ?instance.maxConcurrentIssues, + 'mentionTriggers': ?instance.mentionTriggers, + 'prompt': ?instance.prompt, + 'responders': ?instance.responders?.map((e) => e.toJson()).toList(), + 'capabilities': ?instance.capabilities + ?.map((e) => _$AssistantCapabilityEnumMap[e]!) + .toList(), + 'notifications': ?instance.notifications?.map((e) => e.toJson()).toList(), + 'commentTag': ?instance.commentTag, + 'commentPrefixTemplate': ?instance.commentPrefixTemplate, + 'commentFooterTemplate': ?instance.commentFooterTemplate, +}; + +const _$IssueAssistantEventSourceKindEnumMap = { + IssueAssistantEventSourceKind.ghPolling: 'gh/polling', + IssueAssistantEventSourceKind.teaPolling: 'tea/polling', + IssueAssistantEventSourceKind.ghGosmee: 'gh/gosmee', + IssueAssistantEventSourceKind.ghWebhookForward: 'gh/webhook-forward', + IssueAssistantEventSourceKind.teaGosmee: 'tea/gosmee', +}; + +const _$AssistantCapabilityEnumMap = { + AssistantCapability.planning: 'planning', + AssistantCapability.bugVerification: 'bug_verification', +}; + +CliResponderConfigDocument _$CliResponderConfigDocumentFromJson( + Map json, +) => $checkedCreate('CliResponderConfigDocument', json, ($checkedConvert) { + $checkKeys( + json, + allowedKeys: const [ + 'id', + 'command', + 'args', + 'env', + 'stdinTemplate', + 'timeout', + ], + ); + final val = CliResponderConfigDocument( + id: $checkedConvert('id', (v) => v as String?), + command: $checkedConvert('command', (v) => v as String?), + args: $checkedConvert( + 'args', + (v) => (v as List?)?.map((e) => e as String).toList(), + ), + env: $checkedConvert( + 'env', + (v) => + (v as Map?)?.map((k, e) => MapEntry(k, e as String)), + ), + stdinTemplate: $checkedConvert('stdinTemplate', (v) => v as String?), + timeout: $checkedConvert('timeout', (v) => v as String?), + ); + return val; +}); + +Map _$CliResponderConfigDocumentToJson( + CliResponderConfigDocument instance, +) => { + 'id': ?instance.id, + 'command': ?instance.command, + 'args': ?instance.args, + 'env': ?instance.env, + 'stdinTemplate': ?instance.stdinTemplate, + 'timeout': ?instance.timeout, +}; + +NotificationConfigDocument _$NotificationConfigDocumentFromJson( + Map json, +) => $checkedCreate('NotificationConfigDocument', json, ($checkedConvert) { + $checkKeys( + json, + allowedKeys: const [ + 'type', + 'enabled', + 'events', + 'webhookUrl', + 'username', + 'avatarUrl', + ], + ); + final val = NotificationConfigDocument( + type: $checkedConvert( + 'type', + (v) => $enumDecodeNullable(_$NotificationTypeEnumMap, v), + ), + enabled: $checkedConvert('enabled', (v) => v as bool?), + events: $checkedConvert( + 'events', + (v) => (v as List?) + ?.map((e) => $enumDecode(_$NotificationEventEnumMap, e)) + .toList(), + ), + webhookUrl: $checkedConvert('webhookUrl', (v) => v as String?), + username: $checkedConvert('username', (v) => v as String?), + avatarUrl: $checkedConvert('avatarUrl', (v) => v as String?), + ); + return val; +}); + +Map _$NotificationConfigDocumentToJson( + NotificationConfigDocument instance, +) => { + 'type': ?_$NotificationTypeEnumMap[instance.type], + 'enabled': ?instance.enabled, + 'events': ?instance.events + ?.map((e) => _$NotificationEventEnumMap[e]!) + .toList(), + 'webhookUrl': ?instance.webhookUrl, + 'username': ?instance.username, + 'avatarUrl': ?instance.avatarUrl, +}; + +const _$NotificationTypeEnumMap = { + NotificationType.discordWebhook: 'discordWebhook', + NotificationType.desktop: 'desktop', +}; + +const _$NotificationEventEnumMap = { + NotificationEvent.mentionDetected: 'mention_detected', + NotificationEvent.replyPosted: 'reply_posted', + NotificationEvent.noReply: 'no_reply', + NotificationEvent.responderFailed: 'responder_failed', +}; diff --git a/lib/src/issue_assistant_app.dart b/lib/src/issue_assistant_app.dart index 628afbc..4d54bc0 100644 --- a/lib/src/issue_assistant_app.dart +++ b/lib/src/issue_assistant_app.dart @@ -2,8 +2,8 @@ import 'dart:async'; import 'dart:convert'; import 'package:crypto/crypto.dart'; -import 'package:logging/logging.dart'; +import 'app_logger.dart'; import 'cli_responder.dart'; import 'config.dart'; import 'database.dart'; @@ -16,7 +16,7 @@ import 'notifier.dart'; import 'workspace_manager.dart'; class IssueAssistantApp { - static final Logger _logger = Logger('code_work_spawner.app'); + static final AppLogger _logger = AppLogger('code_work_spawner.app'); IssueAssistantApp._({ required this.config, diff --git a/lib/src/issue_event_source/base.dart b/lib/src/issue_event_source/base.dart index d228365..e1cdc78 100644 --- a/lib/src/issue_event_source/base.dart +++ b/lib/src/issue_event_source/base.dart @@ -2,8 +2,8 @@ import 'dart:async'; import 'dart:io'; import 'package:github/github.dart'; -import 'package:logging/logging.dart'; +import '../app_logger.dart'; import '../config.dart'; import '../database.dart'; import '../issue_tracker_client.dart'; @@ -129,14 +129,14 @@ class PollingIssueEventSource implements IssueEventSource { PollingIssueEventSource({ required this.database, required this.issueTrackerClient, - required Logger logger, + required AppLogger logger, }) : _logger = logger; static const Duration _pollCoalescingWindow = Duration(seconds: 2); final AppDatabase database; final IssueTrackerClient issueTrackerClient; - final Logger _logger; + final AppLogger _logger; final Map _projectPollStates = {}; final Set> _activePolls = >{}; Timer? _schedulerTimer; diff --git a/lib/src/issue_event_source/gitea_gosmee.dart b/lib/src/issue_event_source/gitea_gosmee.dart index b82783b..e2bacc4 100644 --- a/lib/src/issue_event_source/gitea_gosmee.dart +++ b/lib/src/issue_event_source/gitea_gosmee.dart @@ -3,8 +3,8 @@ import 'dart:convert'; import 'dart:io'; import 'package:github/github.dart'; -import 'package:logging/logging.dart'; +import '../app_logger.dart'; import '../config.dart'; import '../issue_tracker_client.dart'; import 'base.dart'; @@ -13,14 +13,14 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { GiteaGosmeeIssueEventSource({ required this.issueTrackerClient, required this.gosmeeCommand, - required Logger logger, + required AppLogger logger, }) : _logger = logger; static const Duration _webhookCoalescingWindow = Duration(milliseconds: 500); final IssueTrackerClient issueTrackerClient; final String gosmeeCommand; - final Logger _logger; + final AppLogger _logger; final Map _queuedIssues = {}; final Set> _activeDispatches = >{}; final Map _gosmeeProcesses = {}; @@ -80,13 +80,33 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { final localUrl = 'http://${server.address.address}:${server.port}/gitea/webhooks'; + _log( + 'gitea/gosmee listening local_url=$localUrl ' + 'projects=${giteaProjects.map((project) => project.key).join(",")}', + ); for (final project in giteaProjects) { + _log( + 'gitea/gosmee project=${project.key} create_channel ' + 'command="$gosmeeCommand --output json client --new-url $localUrl"', + ); final publicUrl = await _createGosmeeChannelUrl(localUrl); + _log( + 'gitea/gosmee project=${project.key} channel_ready ' + 'public_url=$publicUrl local_url=$localUrl', + ); final webhookId = await issueTrackerClient.createGiteaIssueWebhook( repo: project.repoSlug, url: publicUrl, ); _webhookIdsByProject[project.key] = webhookId; + _log( + 'gitea/gosmee project=${project.key} webhook_registered ' + 'webhook_id=$webhookId repo=${project.repo}', + ); + _log( + 'gitea/gosmee project=${project.key} start_client ' + 'command="$gosmeeCommand client $publicUrl $localUrl"', + ); final process = await Process.start(gosmeeCommand, [ 'client', publicUrl, @@ -170,6 +190,10 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { _webhookIdsByProject.clear(); for (final entry in webhookIds.entries) { try { + _log( + 'gitea/gosmee project=${entry.key} webhook_delete ' + 'webhook_id=${entry.value}', + ); await issueTrackerClient.deleteGiteaWebhook( repo: _repoSlugsByProject[entry.key]!, webhookId: entry.value, @@ -196,6 +220,10 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { required IssueEventBatchHandler onBatch, }) async { if (request.method != 'POST') { + _log( + 'gitea/gosmee webhook ignored method=${request.method} ' + 'path=${request.uri.path}', + ); request.response ..statusCode = HttpStatus.methodNotAllowed ..write('Only POST is supported.'); @@ -215,6 +243,7 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { : null; final project = fullName == null ? null : repoToProject[fullName]; final issueNode = payload['issue']; + final action = payload['action']?.toString() ?? 'unknown'; if (project != null && issueNode is Map && (issueNode['pull_request'] == null)) { @@ -222,6 +251,10 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { project.repoSlug, issueNode, ); + _log( + 'gitea/gosmee webhook accepted project=${project.key} ' + 'repo=$fullName action=$action issue=${issue.number} state=${issue.state}', + ); if (issue.state == 'open') { _queuedIssues['${project.key}#${issue.number}'] = _QueuedGiteaIssue( project: project, @@ -230,6 +263,13 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { ); _scheduleFlush(); } + } else { + _log( + 'gitea/gosmee webhook ignored repo=${fullName ?? "(missing)"} ' + 'action=$action matched_project=${project != null} ' + 'has_issue=${issueNode is Map} ' + 'is_pull_request=${issueNode is Map && issueNode["pull_request"] != null}', + ); } request.response.statusCode = HttpStatus.accepted; @@ -263,6 +303,9 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { if (stdoutText.isEmpty) { throw const FormatException('gosmee did not print a public URL.'); } + _log( + 'gitea/gosmee channel_raw_output local_url=$localUrl stdout=$stdoutText', + ); try { final decodedJson = jsonDecode(stdoutText); if (decodedJson is Map) { @@ -350,12 +393,14 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { required Stream> stream, required String level, }) { - utf8.decoder - .bind(stream) - .transform(const LineSplitter()) - .listen( - (line) => _log('gitea/gosmee project=${project.key} $level=$line'), - ); + utf8.decoder.bind(stream).transform(const LineSplitter()).listen((line) { + final message = 'gitea/gosmee project=${project.key} $level=$line'; + if (level == 'stderr') { + _logError(message); + return; + } + _log(message); + }); } void _log(String message) { @@ -363,7 +408,7 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { } void _logError(String message) { - _logger.warning(message); + _logger.error(message); } } diff --git a/lib/src/issue_event_source/github_gosmee.dart b/lib/src/issue_event_source/github_gosmee.dart index 59ff444..1249764 100644 --- a/lib/src/issue_event_source/github_gosmee.dart +++ b/lib/src/issue_event_source/github_gosmee.dart @@ -3,8 +3,8 @@ import 'dart:convert'; import 'dart:io'; import 'package:github/github.dart'; -import 'package:logging/logging.dart'; +import '../app_logger.dart'; import '../config.dart'; import '../issue_tracker_client.dart'; import 'base.dart'; @@ -13,14 +13,14 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { GitHubGosmeeIssueEventSource({ required this.issueTrackerClient, required this.gosmeeCommand, - required Logger logger, + required AppLogger logger, }) : _logger = logger; static const Duration _webhookCoalescingWindow = Duration(milliseconds: 500); final IssueTrackerClient issueTrackerClient; final String gosmeeCommand; - final Logger _logger; + final AppLogger _logger; final Map _queuedIssues = {}; final Set> _activeDispatches = >{}; final Map _gosmeeProcesses = {}; @@ -80,13 +80,33 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { final localUrl = 'http://${server.address.address}:${server.port}/github/webhooks'; + _log( + 'github/gosmee listening local_url=$localUrl ' + 'projects=${githubProjects.map((project) => project.key).join(",")}', + ); for (final project in githubProjects) { + _log( + 'github/gosmee project=${project.key} create_channel ' + 'command="$gosmeeCommand --output json client --new-url $localUrl"', + ); final publicUrl = await _createGosmeeChannelUrl(localUrl); + _log( + 'github/gosmee project=${project.key} channel_ready ' + 'public_url=$publicUrl local_url=$localUrl', + ); final webhookId = await issueTrackerClient.createGitHubIssueWebhook( repo: project.repoSlug, url: publicUrl, ); _webhookIdsByProject[project.key] = webhookId; + _log( + 'github/gosmee project=${project.key} webhook_registered ' + 'webhook_id=$webhookId repo=${project.repo}', + ); + _log( + 'github/gosmee project=${project.key} start_client ' + 'command="$gosmeeCommand client $publicUrl $localUrl"', + ); final process = await Process.start(gosmeeCommand, [ 'client', publicUrl, @@ -170,6 +190,10 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { _webhookIdsByProject.clear(); for (final entry in webhookIds.entries) { try { + _log( + 'github/gosmee project=${entry.key} webhook_delete ' + 'webhook_id=${entry.value}', + ); await issueTrackerClient.deleteGitHubWebhook( repo: _repoSlugsByProject[entry.key]!, webhookId: entry.value, @@ -196,6 +220,10 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { required IssueEventBatchHandler onBatch, }) async { if (request.method != 'POST') { + _log( + 'github/gosmee webhook ignored method=${request.method} ' + 'path=${request.uri.path}', + ); request.response ..statusCode = HttpStatus.methodNotAllowed ..write('Only POST is supported.'); @@ -215,6 +243,7 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { : null; final project = fullName == null ? null : repoToProject[fullName]; final issueNode = payload['issue']; + final action = payload['action']?.toString() ?? 'unknown'; if (project != null && issueNode is Map && (issueNode['pull_request'] == null)) { @@ -222,6 +251,10 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { project.repoSlug, issueNode, ); + _log( + 'github/gosmee webhook accepted project=${project.key} ' + 'repo=$fullName action=$action issue=${issue.number} state=${issue.state}', + ); if (issue.state == 'open') { _queuedIssues['${project.key}#${issue.number}'] = _QueuedGitHubIssue( project: project, @@ -230,6 +263,13 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { ); _scheduleFlush(); } + } else { + _log( + 'github/gosmee webhook ignored repo=${fullName ?? "(missing)"} ' + 'action=$action matched_project=${project != null} ' + 'has_issue=${issueNode is Map} ' + 'is_pull_request=${issueNode is Map && issueNode["pull_request"] != null}', + ); } request.response.statusCode = HttpStatus.accepted; @@ -264,6 +304,9 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { if (stdoutText.isEmpty) { throw const FormatException('gosmee did not print a public URL.'); } + _log( + 'github/gosmee channel_raw_output local_url=$localUrl stdout=$stdoutText', + ); try { final decoded = jsonDecode(stdoutText); @@ -355,7 +398,7 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { utf8.decoder.bind(stream).transform(const LineSplitter()).listen((line) { final message = 'github/gosmee project=${project.key} $level=$line'; if (level == 'stderr') { - _logger.severe(message); + _logger.error(message); } else { _logger.info(message); } @@ -364,7 +407,7 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { void _log(String message) => _logger.info(message); - void _logError(String message) => _logger.severe(message); + void _logError(String message) => _logger.error(message); } class _QueuedGitHubIssue { diff --git a/lib/src/issue_event_source/github_webhook_forward.dart b/lib/src/issue_event_source/github_webhook_forward.dart index a1347c3..7d5aed7 100644 --- a/lib/src/issue_event_source/github_webhook_forward.dart +++ b/lib/src/issue_event_source/github_webhook_forward.dart @@ -2,8 +2,7 @@ import 'dart:async'; import 'dart:convert'; import 'dart:io'; -import 'package:logging/logging.dart'; - +import '../app_logger.dart'; import '../config.dart'; import '../issue_tracker_client.dart'; import 'base.dart'; @@ -11,13 +10,13 @@ import 'base.dart'; class GitHubWebhookForwardIssueEventSource implements IssueEventSource { GitHubWebhookForwardIssueEventSource({ required this.issueTrackerClient, - required Logger logger, + required AppLogger logger, }) : _logger = logger; static const Duration _webhookCoalescingWindow = Duration(milliseconds: 500); final IssueTrackerClient issueTrackerClient; - final Logger _logger; + final AppLogger _logger; final Map _queuedIssues = {}; final Set> _activeDispatches = >{}; final Map _forwardProcesses = {}; @@ -72,7 +71,15 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { final url = 'http://${server.address.address}:${server.port}/github/webhooks'; + _log( + 'github/webhook-forward listening local_url=$url ' + 'projects=${githubProjects.map((project) => project.key).join(",")}', + ); for (final project in githubProjects) { + _log( + 'github/webhook-forward project=${project.key} start_forwarder ' + 'command="${issueTrackerClient.ghCommand} webhook forward --events=issues,issue_comment --repo=${project.repo} --url=$url"', + ); final process = await Process.start(issueTrackerClient.ghCommand, [ 'webhook', 'forward', @@ -168,6 +175,10 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { required IssueEventBatchHandler onBatch, }) async { if (request.method != 'POST') { + _log( + 'github/webhook-forward webhook ignored method=${request.method} ' + 'path=${request.uri.path}', + ); request.response ..statusCode = HttpStatus.methodNotAllowed ..write('Only POST is supported.'); @@ -187,6 +198,7 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { : null; final project = fullName == null ? null : repoToProject[fullName]; final issueNode = payload['issue']; + final action = payload['action']?.toString() ?? 'unknown'; if (project != null && issueNode is Map && (issueNode['pull_request'] == null)) { @@ -194,6 +206,10 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { project.repoSlug, issueNode, ); + _log( + 'github/webhook-forward webhook accepted project=${project.key} ' + 'repo=$fullName action=$action issue=${issue.number} state=${issue.state}', + ); if (issue.state == 'open') { _queuedIssues['${project.key}#${issue.number}'] = _QueuedWebhookIssue( project: project, @@ -202,6 +218,13 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { ); _scheduleFlush(); } + } else { + _log( + 'github/webhook-forward webhook ignored repo=${fullName ?? "(missing)"} ' + 'action=$action matched_project=${project != null} ' + 'has_issue=${issueNode is Map} ' + 'is_pull_request=${issueNode is Map && issueNode["pull_request"] != null}', + ); } request.response.statusCode = HttpStatus.accepted; @@ -294,7 +317,7 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { } void _logError(String message) { - _logger.severe(message); + _logger.error(message); } } diff --git a/pubspec.yaml b/pubspec.yaml index 2bb4bfb..2fd05f9 100644 --- a/pubspec.yaml +++ b/pubspec.yaml @@ -17,7 +17,7 @@ dependencies: yaml: ^3.1.3 result_dart: ^2.1.1 dotenv: ^4.2.0 - logging: ^1.3.0 + logger: ^2.6.2 meta: ^1.16.0 github: ^9.25.0 git: ^2.3.2 diff --git a/test/issue_assistant_app_run/webhook_forward_test.dart b/test/issue_assistant_app_run/webhook_forward_test.dart index b010b93..2e9c85b 100644 --- a/test/issue_assistant_app_run/webhook_forward_test.dart +++ b/test/issue_assistant_app_run/webhook_forward_test.dart @@ -3,7 +3,6 @@ import 'dart:io'; import 'package:code_work_spawner/code_work_spawner.dart'; import 'package:drift/drift.dart' show driftRuntimeOptions; -import 'package:logging/logging.dart'; import 'package:path/path.dart' as p; import 'package:test/test.dart'; @@ -140,7 +139,7 @@ projects: /// And a gh script that writes a webhook creation failure to stderr while forwarding /// And an orchestrator-style config that uses gh/webhook-forward /// When the long-running app starts and webhook-forward emits that stderr line - /// Then the app logs the webhook-forward stderr message at severe level + /// Then the app logs the webhook-forward stderr message at error level /// ``` test('Log webhook forward stderr at error level', () async { // Given a temporary project checkout that can be used as the local repo path. @@ -193,10 +192,12 @@ projects: databasePath: p.join(sandbox.path, 'state.sqlite3'), ghCommand: ghScript.path, ); - final records = []; - final previousLevel = Logger.root.level; - Logger.root.level = Level.ALL; - final subscription = Logger.root.onRecord.listen(records.add); + final records = []; + void captureLog(AppLogRecord record) { + records.add(record); + } + + AppLogger.addListener(captureLog); // When the long-running app starts and webhook-forward emits that stderr line. final runFuture = app.run(); @@ -210,14 +211,13 @@ projects: } await app.close(); await runFuture; - await subscription.cancel(); - Logger.root.level = previousLevel; + AppLogger.removeListener(captureLog); - // Then the app logs the webhook-forward stderr message at severe level. + // Then the app logs the webhook-forward stderr message at error level. expect( records.any( (record) => - record.level == Level.SEVERE && + record.level == AppLogLevel.error && record.message.contains( 'stderr=Error: error creating webhook: HTTP 422: Validation Failed', ), diff --git a/test/issue_assistant_app_run_once_core_test.dart b/test/issue_assistant_app_run_once_core_test.dart index 850a7c6..38dbccc 100644 --- a/test/issue_assistant_app_run_once_core_test.dart +++ b/test/issue_assistant_app_run_once_core_test.dart @@ -2,7 +2,6 @@ import 'dart:io'; import 'package:code_work_spawner/code_work_spawner.dart'; import 'package:drift/drift.dart' show driftRuntimeOptions; -import 'package:logging/logging.dart'; import 'package:path/path.dart' as p; import 'package:test/test.dart'; @@ -300,16 +299,15 @@ projects: ghCommand: ghScript.path, ); final logMessages = []; - final previousLevel = Logger.root.level; - Logger.root.level = Level.INFO; - final subscription = Logger.root.onRecord.listen((record) { + void captureLog(AppLogRecord record) { logMessages.add(record.message); - }); + } + + AppLogger.addListener(captureLog); // When the app processes one polling cycle while app logs are captured. await app.runOnce(); - await subscription.cancel(); - Logger.root.level = previousLevel; + AppLogger.removeListener(captureLog); await app.close(); // Then the application logs include the responder stdout payload. diff --git a/test/issue_assistant_app_run_retry_test.dart b/test/issue_assistant_app_run_retry_test.dart index c0a40be..f6ed8e4 100644 --- a/test/issue_assistant_app_run_retry_test.dart +++ b/test/issue_assistant_app_run_retry_test.dart @@ -3,7 +3,6 @@ import 'dart:io'; import 'package:code_work_spawner/code_work_spawner.dart'; import 'package:drift/drift.dart' show driftRuntimeOptions; -import 'package:logging/logging.dart'; import 'package:path/path.dart' as p; import 'package:test/test.dart'; @@ -85,11 +84,11 @@ projects: ghCommand: ghScript.path, ); final logMessages = []; - final previousLevel = Logger.root.level; - Logger.root.level = Level.INFO; - final subscription = Logger.root.onRecord.listen((record) { + void captureLog(AppLogRecord record) { logMessages.add(record.message); - }); + } + + AppLogger.addListener(captureLog); // When the long-running app starts and enough time passes for a retry. final runFuture = app.run(); @@ -114,8 +113,7 @@ projects: } await app.close(); await runFuture; - await subscription.cancel(); - Logger.root.level = previousLevel; + AppLogger.removeListener(captureLog); // Then the app logs the failed poll without stopping entirely. expect(