diff --git a/bin/code_work_spawner.dart b/bin/code_work_spawner.dart index a2b6852..7eaf156 100644 --- a/bin/code_work_spawner.dart +++ b/bin/code_work_spawner.dart @@ -92,12 +92,17 @@ class _CodeWorkSpawnerCommandRunner extends CommandRunner { ); for (final project in config.projects.values) { final repoDirectory = Directory(project.path); + final eventSource = project.issueAssistant.eventSource; logger.info( 'project=${project.key} ' 'repo=${project.repo} ' 'path=${project.path} ' 'exists=${await repoDirectory.exists()} ' - 'enabled=${project.issueAssistant.enabled}', + 'enabled=${project.issueAssistant.enabled} ' + 'tracker_provider=${project.provider.name} ' + 'scm_provider=${project.scm.provider.name} ' + 'event_source=${_eventSourceKindValue(eventSource.type)}' + '${_cliEventSourceSettings(eventSource)}', ); } final app = await IssueAssistantApp.open( @@ -121,6 +126,39 @@ class _CodeWorkSpawnerCommandRunner extends CommandRunner { } } +String _cliEventSourceSettings(IssueEventSourceConfig eventSource) { + return switch (eventSource) { + PollingIssueEventSourceConfig(:final pollInterval) => + ' poll_interval=$pollInterval', + ChannelIssueEventSourceConfig( + :final reconciliation, + :final reconcileInterval, + ) => + ' reconciliation=${_reconciliationKindValue(reconciliation)} ' + 'reconcile_interval=$reconcileInterval', + }; +} + +String _eventSourceKindValue(IssueTrackerEventSourceKind value) { + return switch (value) { + IssueTrackerEventSourceKind.ghPolling => 'gh/polling', + IssueTrackerEventSourceKind.glabPolling => 'glab/polling', + IssueTrackerEventSourceKind.teaPolling => 'tea/polling', + IssueTrackerEventSourceKind.opPolling => 'op/polling', + IssueTrackerEventSourceKind.ghGosmee => 'gh/gosmee', + IssueTrackerEventSourceKind.glabGosmee => 'glab/gosmee', + IssueTrackerEventSourceKind.ghWebhookForward => 'gh/webhook-forward', + IssueTrackerEventSourceKind.teaGosmee => 'tea/gosmee', + }; +} + +String _reconciliationKindValue(IssueTrackerReconciliationKind value) { + return switch (value) { + IssueTrackerReconciliationKind.startupOnly => 'startup-only', + IssueTrackerReconciliationKind.continuous => 'continuous', + }; +} + class _InitConfigCommand extends Command { @override String get name => 'init-config'; diff --git a/lib/src/core/issue_assistant_app.dart b/lib/src/core/issue_assistant_app.dart index f5756b8..8dd2254 100644 --- a/lib/src/core/issue_assistant_app.dart +++ b/lib/src/core/issue_assistant_app.dart @@ -69,6 +69,7 @@ class IssueAssistantApp { database: database, issueTrackerClient: issueTrackerClient, issueEventSource: RoutedIssueEventSource( + logger: _logger, sources: { IssueTrackerEventSourceKind.ghPolling: pollingIssueEventSource, IssueTrackerEventSourceKind.glabPolling: pollingIssueEventSource, diff --git a/lib/src/issue_tracker/client.dart b/lib/src/issue_tracker/client.dart index 1816cc9..1175dc2 100644 --- a/lib/src/issue_tracker/client.dart +++ b/lib/src/issue_tracker/client.dart @@ -253,6 +253,9 @@ class IssueTrackerClient { required RepositorySlug repo, required String url, }) async { + _logger.debug( + 'gitea webhook create repo=${repo.fullName} url=$url events=issues,issue_comment', + ); final json = await _runGiteaJson( method: 'POST', path: _buildApiPath(repo, ['hooks']), @@ -277,6 +280,9 @@ class IssueTrackerClient { required RepositorySlug repo, required String url, }) async { + _logger.debug( + 'github webhook create repo=${repo.fullName} url=$url events=issues,issue_comment', + ); final json = await _runGhJson([ 'api', '-X', @@ -307,6 +313,9 @@ class IssueTrackerClient { required String trackerProject, required String url, }) async { + _logger.debug( + 'gitlab webhook create repo=$trackerProject url=$url events=issues,note', + ); final json = await _runGlabJson([ 'api', '-X', @@ -333,6 +342,9 @@ class IssueTrackerClient { required RepositorySlug repo, required int webhookId, }) async { + _logger.debug( + 'github webhook delete repo=${repo.fullName} webhook_id=$webhookId', + ); await _runGhJson([ 'api', '-X', @@ -345,6 +357,9 @@ class IssueTrackerClient { required RepositorySlug repo, required int webhookId, }) async { + _logger.debug( + 'gitea webhook delete repo=${repo.fullName} webhook_id=$webhookId', + ); await _runGiteaJson( method: 'DELETE', path: _buildApiPath(repo, ['hooks', '$webhookId']), @@ -355,6 +370,9 @@ class IssueTrackerClient { required String trackerProject, required int webhookId, }) async { + _logger.debug( + 'gitlab webhook delete repo=$trackerProject webhook_id=$webhookId', + ); await _runGlabJson([ 'api', '-X', @@ -991,6 +1009,9 @@ class IssueTrackerClient { environment['CWS_GITEA_INSECURE']?.trim() ?? environment['GITEA_INSECURE']?.trim(); if (host != null && host.isNotEmpty && token != null && token.isNotEmpty) { + _logger.debug( + 'gitea config source=env host=$host insecure=${_parseBooleanFlag(insecureValue)}', + ); return _GiteaConfig( host: Uri.parse(host), token: token, @@ -1003,6 +1024,10 @@ class IssueTrackerClient { environment['GITEA_LOGIN']?.trim() ?? environment['TEA_LOGIN']?.trim(); final configPath = _teaConfigPath(environment); + _logger.debug( + 'gitea config source=tea config_path=$configPath ' + 'requested_login=${loginName ?? "(default)"}', + ); final file = File(configPath); if (!await file.exists()) { throw const FileSystemException( @@ -1035,6 +1060,11 @@ class IssueTrackerClient { ); } + _logger.debug( + 'gitea config source=tea host=$loginHost ' + 'login=${selectedLogin["name"]?.toString().trim() ?? "(unnamed)"} ' + 'insecure=${_parseBooleanFlag(selectedLogin["insecure"]?.toString())}', + ); return _GiteaConfig( host: Uri.parse(loginHost), token: loginToken, diff --git a/lib/src/issue_tracker/issue_event_source/base.dart b/lib/src/issue_tracker/issue_event_source/base.dart index e91ca8e..cc2c259 100644 --- a/lib/src/issue_tracker/issue_event_source/base.dart +++ b/lib/src/issue_tracker/issue_event_source/base.dart @@ -38,19 +38,27 @@ abstract class IssueEventSource { } class RoutedIssueEventSource implements IssueEventSource { - RoutedIssueEventSource({required this.sources}); + RoutedIssueEventSource({required this.sources, required AppLogger logger}) + : _logger = logger; final Map sources; + final AppLogger _logger; @override Future run({ required List projects, required IssueEventBatchHandler onBatch, }) async { + for (final project in projects) { + _log(_routeLogMessage(project)); + } final startupReconcileProjects = projects .where(_shouldRunStartupReconciliation) .toList(growable: false); if (startupReconcileProjects.isNotEmpty) { + _log( + 'route startup_reconciliation projects=${startupReconcileProjects.map((project) => project.key).join(",")}', + ); await sources[IssueTrackerEventSourceKind.ghPolling]!.runOnce( projects: startupReconcileProjects, onBatch: onBatch, @@ -72,15 +80,21 @@ class RoutedIssueEventSource implements IssueEventSource { } } + final routedEntries = projectsBySource.entries + .where((entry) => entry.value.isNotEmpty) + .toList(growable: false); + for (final entry in routedEntries) { + _log( + 'route source=${_eventSourceKindValue(entry.key)} ' + 'projects=${entry.value.map((project) => project.key).join(",")}', + ); + } + await Future.wait( - projectsBySource.entries - .where((entry) => entry.value.isNotEmpty) - .map( - (entry) => sources[entry.key]!.run( - projects: entry.value, - onBatch: onBatch, - ), - ), + routedEntries.map( + (entry) => + sources[entry.key]!.run(projects: entry.value, onBatch: onBatch), + ), ); } @@ -89,6 +103,9 @@ class RoutedIssueEventSource implements IssueEventSource { required List projects, required IssueEventBatchHandler onBatch, }) { + for (final project in projects) { + _log('run_once ${_routeLogMessage(project)}'); + } return sources[IssueTrackerEventSourceKind.ghPolling]!.runOnce( projects: projects, onBatch: onBatch, @@ -146,6 +163,37 @@ class RoutedIssueEventSource implements IssueEventSource { (project.issueAssistant.eventSource as ChannelIssueEventSourceConfig) .reconciliation == IssueTrackerReconciliationKind.continuous; + + String _routeLogMessage(ProjectConfig project) { + final eventSource = project.issueAssistant.eventSource; + final routedSources = _registeredSourcesFor( + project, + ).map(_eventSourceKindValue).join(','); + return 'route project=${project.key} ' + 'provider=${project.provider.name} ' + 'event_source=${_eventSourceKindValue(eventSource.type)} ' + 'startup_reconciliation=${_shouldRunStartupReconciliation(project)} ' + 'continuous_reconciliation=${_shouldRunContinuousReconciliation(project)} ' + '${_eventSourceSettings(eventSource)} ' + 'routed_sources=$routedSources'; + } + + String _eventSourceSettings(IssueEventSourceConfig eventSource) { + return switch (eventSource) { + PollingIssueEventSourceConfig(:final pollInterval) => + 'poll_interval=$pollInterval', + ChannelIssueEventSourceConfig( + :final reconciliation, + :final reconcileInterval, + ) => + 'reconciliation=${_reconciliationKindValue(reconciliation)} ' + 'reconcile_interval=$reconcileInterval', + }; + } + + void _log(String message) { + _logger.info(message); + } } class PollingIssueEventSource implements IssueEventSource { @@ -493,3 +541,23 @@ class _ProjectPollState { DateTime nextDueAt; bool isRunning = false; } + +String _eventSourceKindValue(IssueTrackerEventSourceKind value) { + return switch (value) { + IssueTrackerEventSourceKind.ghPolling => 'gh/polling', + IssueTrackerEventSourceKind.glabPolling => 'glab/polling', + IssueTrackerEventSourceKind.teaPolling => 'tea/polling', + IssueTrackerEventSourceKind.opPolling => 'op/polling', + IssueTrackerEventSourceKind.ghGosmee => 'gh/gosmee', + IssueTrackerEventSourceKind.glabGosmee => 'glab/gosmee', + IssueTrackerEventSourceKind.ghWebhookForward => 'gh/webhook-forward', + IssueTrackerEventSourceKind.teaGosmee => 'tea/gosmee', + }; +} + +String _reconciliationKindValue(IssueTrackerReconciliationKind value) { + return switch (value) { + IssueTrackerReconciliationKind.startupOnly => 'startup-only', + IssueTrackerReconciliationKind.continuous => 'continuous', + }; +} diff --git a/lib/src/issue_tracker/issue_event_source/gitea_gosmee.dart b/lib/src/issue_tracker/issue_event_source/gitea_gosmee.dart index fa7425d..9fd78d2 100644 --- a/lib/src/issue_tracker/issue_event_source/gitea_gosmee.dart +++ b/lib/src/issue_tracker/issue_event_source/gitea_gosmee.dart @@ -60,6 +60,10 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { _runCompleter = completer; final server = await HttpServer.bind(InternetAddress.loopbackIPv4, 0); _server = server; + _log( + 'gitea/gosmee starting projects=${giteaProjects.length} ' + 'keys=${giteaProjects.map((project) => project.key).join(",")}', + ); final repoToProject = { for (final project in giteaProjects) project.repo: project, }; @@ -88,64 +92,83 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { '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.requiredRepoSlug, - 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 commandExecutor.start(gosmeeCommand, [ - 'client', - publicUrl, - localUrl, - ]); - _gosmeeProcesses[project.key] = process; - _pipeProcessLogs( - project: project, - stream: process.stdout, - level: 'stdout', - ); - _pipeProcessLogs( - project: project, - stream: process.stderr, - level: 'stderr', - ); - unawaited( - process.exitCode.then((exitCode) { - _gosmeeProcesses.remove(project.key); - _log( - 'gitea/gosmee process project=${project.key} exit_code=$exitCode', - ); - if (!_isClosing && !completer.isCompleted) { - completer.completeError( - StateError( - 'gosmee client exited for project=${project.key} ' - 'with code $exitCode.', - ), - ); - } - }), - ); - } - try { + for (final project in giteaProjects) { + var setupStep = 'create_channel'; + try { + _log( + 'gitea/gosmee project=${project.key} setup_start ' + 'repo=${project.repo} local_url=$localUrl', + ); + _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', + ); + setupStep = 'register_webhook'; + final webhookId = await issueTrackerClient.createGiteaIssueWebhook( + repo: project.requiredRepoSlug, + url: publicUrl, + ); + _webhookIdsByProject[project.key] = webhookId; + _log( + 'gitea/gosmee project=${project.key} webhook_registered ' + 'webhook_id=$webhookId repo=${project.repo}', + ); + setupStep = 'start_client'; + _log( + 'gitea/gosmee project=${project.key} start_client ' + 'command="$gosmeeCommand client $publicUrl $localUrl"', + ); + final process = await commandExecutor.start(gosmeeCommand, [ + 'client', + publicUrl, + localUrl, + ]); + _gosmeeProcesses[project.key] = process; + _pipeProcessLogs( + project: project, + stream: process.stdout, + level: 'stdout', + ); + _pipeProcessLogs( + project: project, + stream: process.stderr, + level: 'stderr', + ); + unawaited( + process.exitCode.then((exitCode) { + _gosmeeProcesses.remove(project.key); + _log( + 'gitea/gosmee process project=${project.key} exit_code=$exitCode', + ); + if (!_isClosing && !completer.isCompleted) { + completer.completeError( + StateError( + 'gosmee client exited for project=${project.key} ' + 'with code $exitCode.', + ), + ); + } + }), + ); + _log( + 'gitea/gosmee project=${project.key} setup_complete ' + 'repo=${project.repo}', + ); + } catch (error, stackTrace) { + _logError( + 'gitea/gosmee project=${project.key} setup_failed ' + 'step=$setupStep error=$error', + ); + Error.throwWithStackTrace(error, stackTrace); + } + } + await completer.future; } finally { await close(); @@ -223,6 +246,10 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { required Map repoToProject, required IssueEventBatchHandler onBatch, }) async { + _logDebug( + 'gitea/gosmee webhook request method=${request.method} ' + 'path=${request.uri.path} event=${request.headers.value("X-Gitea-Event") ?? "(missing)"}', + ); if (request.method != 'POST') { _log( 'gitea/gosmee webhook ignored method=${request.method} ' @@ -295,6 +322,11 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { '--new-url', localUrl, ]); + _logDebug( + 'gitea/gosmee channel_command_result local_url=$localUrl ' + 'exit_code=${result.exitCode} stdout=${_summarizeText(result.stdout.toString())} ' + 'stderr=${_summarizeText(result.stderr.toString())}', + ); if (result.exitCode != 0) { throw ProcessException( gosmeeCommand, @@ -411,9 +443,21 @@ class GiteaGosmeeIssueEventSource implements IssueEventSource { _logger.info(message); } + void _logDebug(String message) { + _logger.debug(message); + } + void _logError(String message) { _logger.error(message); } + + String _summarizeText(String value) { + final singleLine = value.trim().replaceAll(RegExp(r'\s+'), ' '); + if (singleLine.length <= 240) { + return singleLine.isEmpty ? '(empty)' : singleLine; + } + return '${singleLine.substring(0, 240)}...'; + } } class _QueuedGiteaIssue { diff --git a/lib/src/issue_tracker/issue_event_source/github_gosmee.dart b/lib/src/issue_tracker/issue_event_source/github_gosmee.dart index 26008ad..eec4e19 100644 --- a/lib/src/issue_tracker/issue_event_source/github_gosmee.dart +++ b/lib/src/issue_tracker/issue_event_source/github_gosmee.dart @@ -60,6 +60,10 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { _runCompleter = completer; final server = await HttpServer.bind(InternetAddress.loopbackIPv4, 0); _server = server; + _log( + 'github/gosmee starting projects=${githubProjects.length} ' + 'keys=${githubProjects.map((project) => project.key).join(",")}', + ); final repoToProject = { for (final project in githubProjects) project.repo: project, }; @@ -88,64 +92,83 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { '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.requiredRepoSlug, - 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 commandExecutor.start(gosmeeCommand, [ - 'client', - publicUrl, - localUrl, - ]); - _gosmeeProcesses[project.key] = process; - _pipeProcessLogs( - project: project, - stream: process.stdout, - level: 'stdout', - ); - _pipeProcessLogs( - project: project, - stream: process.stderr, - level: 'stderr', - ); - unawaited( - process.exitCode.then((exitCode) { - _gosmeeProcesses.remove(project.key); - _log( - 'github/gosmee process project=${project.key} exit_code=$exitCode', - ); - if (!_isClosing && !completer.isCompleted) { - completer.completeError( - StateError( - 'gosmee client exited for project=${project.key} ' - 'with code $exitCode.', - ), - ); - } - }), - ); - } - try { + for (final project in githubProjects) { + var setupStep = 'create_channel'; + try { + _log( + 'github/gosmee project=${project.key} setup_start ' + 'repo=${project.repo} local_url=$localUrl', + ); + _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', + ); + setupStep = 'register_webhook'; + final webhookId = await issueTrackerClient.createGitHubIssueWebhook( + repo: project.requiredRepoSlug, + url: publicUrl, + ); + _webhookIdsByProject[project.key] = webhookId; + _log( + 'github/gosmee project=${project.key} webhook_registered ' + 'webhook_id=$webhookId repo=${project.repo}', + ); + setupStep = 'start_client'; + _log( + 'github/gosmee project=${project.key} start_client ' + 'command="$gosmeeCommand client $publicUrl $localUrl"', + ); + final process = await commandExecutor.start(gosmeeCommand, [ + 'client', + publicUrl, + localUrl, + ]); + _gosmeeProcesses[project.key] = process; + _pipeProcessLogs( + project: project, + stream: process.stdout, + level: 'stdout', + ); + _pipeProcessLogs( + project: project, + stream: process.stderr, + level: 'stderr', + ); + unawaited( + process.exitCode.then((exitCode) { + _gosmeeProcesses.remove(project.key); + _log( + 'github/gosmee process project=${project.key} exit_code=$exitCode', + ); + if (!_isClosing && !completer.isCompleted) { + completer.completeError( + StateError( + 'gosmee client exited for project=${project.key} ' + 'with code $exitCode.', + ), + ); + } + }), + ); + _log( + 'github/gosmee project=${project.key} setup_complete ' + 'repo=${project.repo}', + ); + } catch (error, stackTrace) { + _logError( + 'github/gosmee project=${project.key} setup_failed ' + 'step=$setupStep error=$error', + ); + Error.throwWithStackTrace(error, stackTrace); + } + } + await completer.future; } finally { await close(); @@ -223,6 +246,10 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { required Map repoToProject, required IssueEventBatchHandler onBatch, }) async { + _logDebug( + 'github/gosmee webhook request method=${request.method} ' + 'path=${request.uri.path} event=${request.headers.value("X-GitHub-Event") ?? "(missing)"}', + ); if (request.method != 'POST') { _log( 'github/gosmee webhook ignored method=${request.method} ' @@ -295,6 +322,11 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { '--new-url', localUrl, ]); + _logDebug( + 'github/gosmee channel_command_result local_url=$localUrl ' + 'exit_code=${result.exitCode} stdout=${_summarizeText(result.stdout.toString())} ' + 'stderr=${_summarizeText(result.stderr.toString())}', + ); if (result.exitCode != 0) { throw ProcessException( gosmeeCommand, @@ -411,7 +443,17 @@ class GitHubGosmeeIssueEventSource implements IssueEventSource { void _log(String message) => _logger.info(message); + void _logDebug(String message) => _logger.debug(message); + void _logError(String message) => _logger.error(message); + + String _summarizeText(String value) { + final singleLine = value.trim().replaceAll(RegExp(r'\s+'), ' '); + if (singleLine.length <= 240) { + return singleLine.isEmpty ? '(empty)' : singleLine; + } + return '${singleLine.substring(0, 240)}...'; + } } class _QueuedGitHubIssue { diff --git a/lib/src/issue_tracker/issue_event_source/github_webhook_forward.dart b/lib/src/issue_tracker/issue_event_source/github_webhook_forward.dart index 5c43115..824f4a9 100644 --- a/lib/src/issue_tracker/issue_event_source/github_webhook_forward.dart +++ b/lib/src/issue_tracker/issue_event_source/github_webhook_forward.dart @@ -54,6 +54,10 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { _runCompleter = completer; final server = await HttpServer.bind(InternetAddress.loopbackIPv4, 0); _server = server; + _log( + 'github/webhook-forward starting projects=${githubProjects.length} ' + 'keys=${githubProjects.map((project) => project.key).join(",")}', + ); final repoToProject = { for (final project in githubProjects) project.repo: project, }; @@ -79,50 +83,66 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { '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 commandExecutor - .start(issueTrackerClient.ghCommand, [ - 'webhook', - 'forward', - '--events=issues,issue_comment', - '--repo=${project.repo}', - '--url=$url', - ]); - _forwardProcesses[project.key] = process; - _pipeProcessLogs( - project: project, - stream: process.stdout, - level: 'stdout', - ); - _pipeProcessLogs( - project: project, - stream: process.stderr, - level: 'stderr', - ); - unawaited( - process.exitCode.then((exitCode) { - _forwardProcesses.remove(project.key); - _log( - 'github/webhook-forward process project=${project.key} ' - 'exit_code=$exitCode', - ); - if (!_isClosing && !completer.isCompleted) { - completer.completeError( - StateError( - 'gh webhook forward exited for project=${project.key} ' - 'with code $exitCode.', - ), - ); - } - }), - ); - } - try { + for (final project in githubProjects) { + try { + _log( + 'github/webhook-forward project=${project.key} setup_start ' + 'repo=${project.repo} local_url=$url', + ); + _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 commandExecutor + .start(issueTrackerClient.ghCommand, [ + 'webhook', + 'forward', + '--events=issues,issue_comment', + '--repo=${project.repo}', + '--url=$url', + ]); + _forwardProcesses[project.key] = process; + _pipeProcessLogs( + project: project, + stream: process.stdout, + level: 'stdout', + ); + _pipeProcessLogs( + project: project, + stream: process.stderr, + level: 'stderr', + ); + unawaited( + process.exitCode.then((exitCode) { + _forwardProcesses.remove(project.key); + _log( + 'github/webhook-forward process project=${project.key} ' + 'exit_code=$exitCode', + ); + if (!_isClosing && !completer.isCompleted) { + completer.completeError( + StateError( + 'gh webhook forward exited for project=${project.key} ' + 'with code $exitCode.', + ), + ); + } + }), + ); + _log( + 'github/webhook-forward project=${project.key} setup_complete ' + 'repo=${project.repo}', + ); + } catch (error, stackTrace) { + _logError( + 'github/webhook-forward project=${project.key} setup_failed ' + 'step=start_forwarder error=$error', + ); + Error.throwWithStackTrace(error, stackTrace); + } + } + await completer.future; } finally { await close(); @@ -179,6 +199,10 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { required Map repoToProject, required IssueEventBatchHandler onBatch, }) async { + _logDebug( + 'github/webhook-forward webhook request method=${request.method} ' + 'path=${request.uri.path} event=${request.headers.value("X-GitHub-Event") ?? "(missing)"}', + ); if (request.method != 'POST') { _log( 'github/webhook-forward webhook ignored method=${request.method} ' @@ -321,6 +345,10 @@ class GitHubWebhookForwardIssueEventSource implements IssueEventSource { _logger.info(message); } + void _logDebug(String message) { + _logger.debug(message); + } + void _logError(String message) { _logger.error(message); } diff --git a/lib/src/issue_tracker/issue_event_source/gitlab_gosmee.dart b/lib/src/issue_tracker/issue_event_source/gitlab_gosmee.dart index bea89d9..662b8c1 100644 --- a/lib/src/issue_tracker/issue_event_source/gitlab_gosmee.dart +++ b/lib/src/issue_tracker/issue_event_source/gitlab_gosmee.dart @@ -58,6 +58,10 @@ class GitLabGosmeeIssueEventSource implements IssueEventSource { _runCompleter = completer; final server = await HttpServer.bind(InternetAddress.loopbackIPv4, 0); _server = server; + _log( + 'gitlab/gosmee starting projects=${gitLabProjects.length} ' + 'keys=${gitLabProjects.map((project) => project.key).join(",")}', + ); final repoToProject = { for (final project in gitLabProjects) project.repo: project, }; @@ -86,64 +90,83 @@ class GitLabGosmeeIssueEventSource implements IssueEventSource { 'gitlab/gosmee listening local_url=$localUrl ' 'projects=${gitLabProjects.map((project) => project.key).join(",")}', ); - for (final project in gitLabProjects) { - _log( - 'gitlab/gosmee project=${project.key} create_channel ' - 'command="$gosmeeCommand --output json client --new-url $localUrl"', - ); - final publicUrl = await _createGosmeeChannelUrl(localUrl); - _log( - 'gitlab/gosmee project=${project.key} channel_ready ' - 'public_url=$publicUrl local_url=$localUrl', - ); - final webhookId = await issueTrackerClient.createGitLabIssueWebhook( - trackerProject: project.repo, - url: publicUrl, - ); - _webhookIdsByProject[project.key] = webhookId; - _log( - 'gitlab/gosmee project=${project.key} webhook_registered ' - 'webhook_id=$webhookId repo=${project.repo}', - ); - _log( - 'gitlab/gosmee project=${project.key} start_client ' - 'command="$gosmeeCommand client $publicUrl $localUrl"', - ); - final process = await commandExecutor.start(gosmeeCommand, [ - 'client', - publicUrl, - localUrl, - ]); - _gosmeeProcesses[project.key] = process; - _pipeProcessLogs( - project: project, - stream: process.stdout, - level: 'stdout', - ); - _pipeProcessLogs( - project: project, - stream: process.stderr, - level: 'stderr', - ); - unawaited( - process.exitCode.then((exitCode) { - _gosmeeProcesses.remove(project.key); - _log( - 'gitlab/gosmee process project=${project.key} exit_code=$exitCode', - ); - if (!_isClosing && !completer.isCompleted) { - completer.completeError( - StateError( - 'gosmee client exited for project=${project.key} ' - 'with code $exitCode.', - ), - ); - } - }), - ); - } - try { + for (final project in gitLabProjects) { + var setupStep = 'create_channel'; + try { + _log( + 'gitlab/gosmee project=${project.key} setup_start ' + 'repo=${project.repo} local_url=$localUrl', + ); + _log( + 'gitlab/gosmee project=${project.key} create_channel ' + 'command="$gosmeeCommand --output json client --new-url $localUrl"', + ); + final publicUrl = await _createGosmeeChannelUrl(localUrl); + _log( + 'gitlab/gosmee project=${project.key} channel_ready ' + 'public_url=$publicUrl local_url=$localUrl', + ); + setupStep = 'register_webhook'; + final webhookId = await issueTrackerClient.createGitLabIssueWebhook( + trackerProject: project.repo, + url: publicUrl, + ); + _webhookIdsByProject[project.key] = webhookId; + _log( + 'gitlab/gosmee project=${project.key} webhook_registered ' + 'webhook_id=$webhookId repo=${project.repo}', + ); + setupStep = 'start_client'; + _log( + 'gitlab/gosmee project=${project.key} start_client ' + 'command="$gosmeeCommand client $publicUrl $localUrl"', + ); + final process = await commandExecutor.start(gosmeeCommand, [ + 'client', + publicUrl, + localUrl, + ]); + _gosmeeProcesses[project.key] = process; + _pipeProcessLogs( + project: project, + stream: process.stdout, + level: 'stdout', + ); + _pipeProcessLogs( + project: project, + stream: process.stderr, + level: 'stderr', + ); + unawaited( + process.exitCode.then((exitCode) { + _gosmeeProcesses.remove(project.key); + _log( + 'gitlab/gosmee process project=${project.key} exit_code=$exitCode', + ); + if (!_isClosing && !completer.isCompleted) { + completer.completeError( + StateError( + 'gosmee client exited for project=${project.key} ' + 'with code $exitCode.', + ), + ); + } + }), + ); + _log( + 'gitlab/gosmee project=${project.key} setup_complete ' + 'repo=${project.repo}', + ); + } catch (error, stackTrace) { + _logError( + 'gitlab/gosmee project=${project.key} setup_failed ' + 'step=$setupStep error=$error', + ); + Error.throwWithStackTrace(error, stackTrace); + } + } + await completer.future; } finally { await close(); @@ -221,6 +244,10 @@ class GitLabGosmeeIssueEventSource implements IssueEventSource { required Map repoToProject, required IssueEventBatchHandler onBatch, }) async { + _logDebug( + 'gitlab/gosmee webhook request method=${request.method} ' + 'path=${request.uri.path} event=${request.headers.value("X-Gitlab-Event") ?? "(missing)"}', + ); if (request.method != 'POST') { _log( 'gitlab/gosmee webhook ignored method=${request.method} ' @@ -333,6 +360,11 @@ class GitLabGosmeeIssueEventSource implements IssueEventSource { '--new-url', localUrl, ]); + _logDebug( + 'gitlab/gosmee channel_command_result local_url=$localUrl ' + 'exit_code=${result.exitCode} stdout=${_summarizeText(result.stdout.toString())} ' + 'stderr=${_summarizeText(result.stderr.toString())}', + ); if (result.exitCode != 0) { throw ProcessException( gosmeeCommand, @@ -449,7 +481,17 @@ class GitLabGosmeeIssueEventSource implements IssueEventSource { void _log(String message) => _logger.info(message); + void _logDebug(String message) => _logger.debug(message); + void _logError(String message) => _logger.error(message); + + String _summarizeText(String value) { + final singleLine = value.trim().replaceAll(RegExp(r'\s+'), ' '); + if (singleLine.length <= 240) { + return singleLine.isEmpty ? '(empty)' : singleLine; + } + return '${singleLine.substring(0, 240)}...'; + } } class _QueuedGitLabIssue { diff --git a/test/issue_event_source/github_gosmee_test.dart b/test/issue_event_source/github_gosmee_test.dart index 2f10267..0d2a846 100644 --- a/test/issue_event_source/github_gosmee_test.dart +++ b/test/issue_event_source/github_gosmee_test.dart @@ -123,6 +123,13 @@ projects: responderRunner: fakeResponderRunner(), commandExecutor: fakeExternalCommandExecutor(), ); + final records = []; + void captureLog(AppLogRecord record) { + records.add(record); + } + + AppLogger.addListener(captureLog); + addTearDown(() => AppLogger.removeListener(captureLog)); // When the long-running app starts and receives the forwarded webhook. final runFuture = app.run(); @@ -168,6 +175,47 @@ projects: ), isTrue, ); + expect( + records.any( + (record) => record.message.contains( + 'route project=sample provider=github event_source=gh/gosmee', + ), + ), + isTrue, + ); + expect( + records.any( + (record) => + record.message.contains('route source=gh/gosmee projects=sample'), + ), + isTrue, + ); + expect( + records.any( + (record) => record.message.contains( + 'github/gosmee project=sample setup_start', + ), + ), + isTrue, + ); + expect( + records.any( + (record) => + record.level == AppLogLevel.debug && + record.message.contains('github/gosmee channel_command_result'), + ), + isTrue, + ); + expect( + records.any( + (record) => + record.level == AppLogLevel.debug && + record.message.contains( + 'github webhook create repo=owner/sample', + ), + ), + isTrue, + ); }); }); } diff --git a/test/issue_event_source/gitlab_gosmee_test.dart b/test/issue_event_source/gitlab_gosmee_test.dart index 133e601..10a2f7e 100644 --- a/test/issue_event_source/gitlab_gosmee_test.dart +++ b/test/issue_event_source/gitlab_gosmee_test.dart @@ -137,6 +137,13 @@ projects: responderRunner: fakeResponderRunner(), commandExecutor: fakeExternalCommandExecutor(), ); + final records = []; + void captureLog(AppLogRecord record) { + records.add(record); + } + + AppLogger.addListener(captureLog); + addTearDown(() => AppLogger.removeListener(captureLog)); // When the long-running app starts and receives the forwarded webhook. final runFuture = app.run(); @@ -186,6 +193,48 @@ projects: ), isTrue, ); + expect( + records.any( + (record) => record.message.contains( + 'route project=sample provider=gitlab event_source=glab/gosmee', + ), + ), + isTrue, + ); + expect( + records.any( + (record) => record.message.contains( + 'route source=glab/gosmee projects=sample', + ), + ), + isTrue, + ); + expect( + records.any( + (record) => record.message.contains( + 'gitlab/gosmee project=sample setup_start', + ), + ), + isTrue, + ); + expect( + records.any( + (record) => + record.level == AppLogLevel.debug && + record.message.contains('gitlab/gosmee channel_command_result'), + ), + isTrue, + ); + expect( + records.any( + (record) => + record.level == AppLogLevel.debug && + record.message.contains( + 'gitlab webhook create repo=group/subgroup/sample', + ), + ), + isTrue, + ); }); }); } diff --git a/test/issue_event_source/gosmee_test.dart b/test/issue_event_source/gosmee_test.dart index dd5aafd..95d5979 100644 --- a/test/issue_event_source/gosmee_test.dart +++ b/test/issue_event_source/gosmee_test.dart @@ -132,6 +132,13 @@ CWS_GITEA_TOKEN=test-token responderRunner: fakeResponderRunner(), commandExecutor: fakeExternalCommandExecutor(), ); + final records = []; + void captureLog(AppLogRecord record) { + records.add(record); + } + + AppLogger.addListener(captureLog); + addTearDown(() => AppLogger.removeListener(captureLog)); // When the long-running app starts and receives the forwarded webhook. final runFuture = app.run(); @@ -163,6 +170,46 @@ CWS_GITEA_TOKEN=test-token 'https://gosmee.example.test/sample', ); expect(giteaServer.deletedWebhookIds, contains(81)); + expect( + records.any( + (record) => record.message.contains( + 'route project=sample provider=gitea event_source=tea/gosmee', + ), + ), + isTrue, + ); + expect( + records.any( + (record) => record.message.contains( + 'route source=tea/gosmee projects=sample', + ), + ), + isTrue, + ); + expect( + records.any( + (record) => record.message.contains( + 'gitea/gosmee project=sample setup_start', + ), + ), + isTrue, + ); + expect( + records.any( + (record) => + record.level == AppLogLevel.debug && + record.message.contains('gitea/gosmee channel_command_result'), + ), + isTrue, + ); + expect( + records.any( + (record) => + record.level == AppLogLevel.debug && + record.message.contains('gitea config source=env'), + ), + isTrue, + ); }); /// ```gherkin diff --git a/test/issue_event_source/routed_issue_event_source_test.dart b/test/issue_event_source/routed_issue_event_source_test.dart index b16f6e8..9d32de3 100644 --- a/test/issue_event_source/routed_issue_event_source_test.dart +++ b/test/issue_event_source/routed_issue_event_source_test.dart @@ -24,6 +24,7 @@ void main() { final polling = _RecordingIssueEventSource(); final webhookForward = _RecordingIssueEventSource(); final routed = RoutedIssueEventSource( + logger: AppLogger('test.routed_issue_event_source'), sources: { IssueTrackerEventSourceKind.ghPolling: polling, IssueTrackerEventSourceKind.teaPolling: polling, @@ -63,6 +64,7 @@ void main() { final polling = _RecordingIssueEventSource(); final webhookForward = _RecordingIssueEventSource(); final routed = RoutedIssueEventSource( + logger: AppLogger('test.routed_issue_event_source'), sources: { IssueTrackerEventSourceKind.ghPolling: polling, IssueTrackerEventSourceKind.teaPolling: polling, diff --git a/test/issue_tracker_client_test.dart b/test/issue_tracker_client_test.dart index aaa5524..78bf318 100644 --- a/test/issue_tracker_client_test.dart +++ b/test/issue_tracker_client_test.dart @@ -517,6 +517,7 @@ logins: ..write('[]'); await request.response.close(); }); + final serverHost = server.address.host; _configureGiteaTestEnvironment(server); final logMessages = []; void listener(AppLogRecord record) { @@ -555,6 +556,12 @@ logins: } // And the tracker logger records the timed out request. + expect( + logMessages, + contains( + allOf(contains('gitea config source=env'), contains(serverHost)), + ), + ); expect( logMessages, contains(