feat: improve debug logging

bin/code_work_spawner.dart

@@ -92,12 +92,17 @@ class _CodeWorkSpawnerCommandRunner extends CommandRunner<void> {
     );
     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<void> {
   }
 }
 
+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<void> {
   @override
   String get name => 'init-config';

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,

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,

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<IssueTrackerEventSourceKind, IssueEventSource> sources;
+  final AppLogger _logger;
 
   @override
   Future<void> run({
     required List<ProjectConfig> 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
+      routedEntries.map(
-          .where((entry) => entry.value.isNotEmpty)
+        (entry) =>
-          .map(
+            sources[entry.key]!.run(projects: entry.value, onBatch: onBatch),
-            (entry) => sources[entry.key]!.run(
+      ),
-              projects: entry.value,
-              onBatch: onBatch,
-            ),
-          ),
     );
   }
 
@@ -89,6 +103,9 @@ class RoutedIssueEventSource implements IssueEventSource {
     required List<ProjectConfig> 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',
+  };
+}

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<String, ProjectConfig> 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 {

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<String, ProjectConfig> 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 {

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<String, ProjectConfig> 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);
   }

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<String, ProjectConfig> 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 {

test/issue_event_source/github_gosmee_test.dart

@@ -123,6 +123,13 @@ projects:
         responderRunner: fakeResponderRunner(),
         commandExecutor: fakeExternalCommandExecutor(),
       );
+      final records = <AppLogRecord>[];
+      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,
+      );
     });
   });
 }

test/issue_event_source/gitlab_gosmee_test.dart

@@ -137,6 +137,13 @@ projects:
         responderRunner: fakeResponderRunner(),
         commandExecutor: fakeExternalCommandExecutor(),
       );
+      final records = <AppLogRecord>[];
+      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,
+      );
     });
   });
 }

test/issue_event_source/gosmee_test.dart

@@ -132,6 +132,13 @@ CWS_GITEA_TOKEN=test-token
         responderRunner: fakeResponderRunner(),
         commandExecutor: fakeExternalCommandExecutor(),
       );
+      final records = <AppLogRecord>[];
+      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

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,

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 = <String>[];
         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(