Диагностика

Контроллер и его задачи могут рассказать, что они делают: что тело пишет в лог, какая задача изменила состояние, чего ждёт закрытие и сколько задача шла после своей отмены. Ничто на этой странице не меняет того, куда уходит ошибка: об этом страница «Ошибки».

Разделы страницы по тому, что нужно приложению:

Что нужно приложению	Что это даёт	Раздел
То, что хотят сказать тело и движок, в логе	`ctx.log`, `Solo.debug`, `Job.debug`	«Логи»
Лог всех контроллеров	`Solo.observer`	«Наблюдение за всеми контроллерами»
Что держит `close()`, или задача, которая зависла	`pending`	«Что удерживает контроллер»
Задачи, которые шли дальше своей отмены	Отметка из `whenCancelled` в наблюдателе	«Почему отмена была долгой»

Строки под некоторыми блоками — то, что печатает код.

Логи

Три канала несут то, что хотят сказать тело и движок:

// Данные приложения для хуков логирования и наблюдателей.
ctx.log(('zoom', zoom));

// И собственная трасса движка, когда нужно посмотреть на очередь.
Solo.debug = print;

// И трасса ядра по каждой задаче: запуск, ошибки, отмена, исход.
Job.debug = print;

ctx.log(data) передаёт данные приложения хукам логирования и наблюдателям как есть, поэтому строку делает тот слушатель, которому она нужна. Solo.debug дополнительно трассирует очередь контроллера и его жизненный цикл. Запуск каждой задачи, её ошибки, дошедшую до неё отмену и исход трассирует Job.debug, канал ядра; обе стороны видны, когда включены оба канала.

По дороге ctx.log тоже ничего не зовёт. Там, где строку дорого собирать, логируйте колбэк, который её соберёт, а звать его или нет, пусть решает уровень:

// Строка, которую дорого собирать: логируем колбэк, а не строку.
ctx.log(() => 'zoom to $zoom on ${device.describe()}');

@override
void onLog(Job<Object?> job, Object? message) {
  if (!logger.isLoggable(Level.FINE)) return;
  logger.fine(message is Object? Function() ? message() : message);
}

Тело при этом логирует безусловно, а строку вместе с вызовом describe() собирают только там, где этот уровень кто-то слушает. В остальных местах сообщение так и остаётся замыканием, которое никто не позвал.

Наблюдение за всеми контроллерами

Приложению нужен лог всех контроллеров процесса, а не одного. Оно ставит наблюдателя при запуске:

final class LoggingObserver extends SoloObserver {
  @override
  void onStart(Solo<Object> solo, Job<Object?> job) => print('$job started');

  @override
  void onFinish(Solo<Object> solo, Job<Object?> job) =>
      print('$job finished ${job.outcome}');

  @override
  void onChange(Solo<Object> solo, SoloTransition<Object> transition) =>
      print('${transition.job ?? 'external'}: ${transition.current}');
}

void main() {
  Solo.observer = LoggingObserver();
}

Наблюдатель печатает то, что приложение положило в свои задачи и своё состояние: ключ и describe каждой задачи, её исход вместе с текстом ошибки и toString состояния. Когда лог уходит с устройства, в сервис отчётов о сбоях, наблюдатель печатает только то, что приложение решило отдать, например тип состояния вместо самого состояния.

SoloObserver рассказывают то же, что контроллерам: onStart, onFinish, onError, onLog, onChange и onClose от каждого контроллера процесса, а ещё onCreate. onUnanswered и onListenerError остаются только у контроллера.

Хук onChange получает SoloTransition: состояние до и после, job, которой принадлежит изменение, и revision, растущий на единицу за изменение, так что два перехода упорядочены даже когда хук поменял состояние ещё раз изнутри первого. В job лежит та задача, чей emit сделал изменение или чей обработчик состояния его вернул: для externalSetState там null, а когда изменение сделала дочерняя задача, это она сама, а не корневая, которой она принадлежит. Это поле отвечает на вопрос, кто изменил состояние, а снаружи движка это не выводится.

Наблюдатель вызывается перед одноимённым хуком контроллера. Каждый вызов независим; отсутствие super в хуке контроллера не отключает наблюдателя. Ошибка любого из них передаётся в текущую зону, не меняя исход задачи, не останавливая очередь и не препятствуя вызову второго хука. Исключение Cancelled, брошенное хуком, в зону не попадает и задачу не отменяет.

Наблюдатель только наблюдает. Его наличие никак не влияет на то, куда дальше пойдёт ошибка.

Что удерживает контроллер

close() ждёт работающую Job, а Job может не торопиться. Контроллер говорит, чего именно он ждёт:

unawaited(
  controller.close().timeout(
    const Duration(seconds: 5),
    onTimeout: () => log('closing is held by ${controller.pending}'),
  ),
);

Пока контроллер ждёт Job, pending возвращает SoloPendingJob, снимок этой Job:

Поле	Что говорит
`job`	`Job`, которую ждут
`phase`	чем она занята: `body`, `children`, `cleanup`
`cancellation`	отмена, которую она приняла, иначе `null`
`heldCancellation`	отмена, которую держит открытая секция `ctx.uncancellable`
`children`	сколько детей она ещё ждёт
`inUncancellableSection`	открыта ли такая секция
`cancellable`	принимает ли она отмену, которую может отклонить
`closing`	позвали ли у контроллера `close()`
`draining`	дренаж ли этот `close()`: тогда `Job` доработает до конца
`queued`	`Job`, стоящие за ней в очереди: они стартуют только после неё

Рядом с полями снимок считает и один свой ответ: SoloPendingJob.cancellationPending истинно, когда есть любая из двух отмен выше, принятая или придержанная. Job, у которой cancellable равно false, отклоняет те отмены, которые может отклонить, и тогда ждать нечего, сколько бы раз её ни просили остановиться.

Кроме Job, закрытие ждёт ещё двух вещей, и их pending тоже называет:

Дренаж ждёт ещё и очередь. Группа collect или accumulate стоит в ней, пока её не отпустит тайминг. Если Job в это время не работает, pending возвращает SoloPendingQueue, и в его jobs лежит то, что дренажу ещё предстоит запустить.
У SoloStream стрим закрывается после движка и ждёт, пока каждая подписка получит событие завершения. Подписка, оставленная на паузе, держит close(), хотя isFinished уже истинно, и тогда pending возвращает SoloPendingStream.

Печатаются все три одинаково, так что строке выше switch не нужен:

closing is held by SoloPending([stuck] in its body, closing, cancelled by Cancelled(closed))
closing is held by SoloPending(draining, 1 queued: [group])
closing is held by SoloPending(stream: a subscription has not taken its done event)

null говорит, что закрытие не держит ничто, о чём знает контроллер. Таймер читает pending между шагами закрытия, а синхронный хук посреди шага: onFinish последней Job и onClose видят null, хотя close() ещё не вернулся.

Снимок отвечает тому, кто спросил, а пример выше спрашивает на close(). О Job, которая зависла раньше, пока экран ещё открыт и никто ничего не закрывает, не спрашивает никто. Спросить, когда никто не просит, может наблюдатель: он заводит таймер, когда Job начинается, и снимает его, когда она кончилась:

final class Hangs extends SoloObserver {
  // Expando держит ключ слабо: таймер уходит вместе с задачей.
  final _timers = Expando<Timer>('hang');

  @override
  void onStart(Solo<Object> solo, Job<Object?> job) => _timers[job] = Timer(
    const Duration(seconds: 5),
    () => log('${job.key} is still running: ${solo.pending}'),
  );

  @override
  void onFinish(Solo<Object> solo, Job<Object?> job) => _timers[job]?.cancel();
}

Job, которая успела кончиться, снимает свой таймер сама и молчит. Ту, что не успела, строка называет в начале. Снимок рядом с именем снят с корневой Job, на которой стоит контроллер, и это та же самая Job, если только зависла не дочерняя:

stuck is still running: SoloPending([stuck] in its body)
held is still running: SoloPending([held] in its body, holding Cancelled(manual) back)

Таймер заводится на старте, потому что другого конца у зависания нет: onFinish для Job, которая не кончается, не придёт никогда. Рецепт раздела Почему отмена была долгой считает задержку как раз на onFinish и потому о зависании не скажет ничего.

Пять секунд говорят о предметной области, а не о движке: Job, которая открывает камеру, вполне может идти дольше, и число здесь то, с которого это приложение считает ожидание долгим.

Hangs только сообщает: Job, которую он назвал, продолжает идти. Job, которая должна остановиться на своём пределе, получает этот предел сама, enqueue(timeout: ...). Предел отменяет Job, и она кончается Cancelled(timeout), когда тело дойдёт до контрольной точки или вернётся. Тело, которое ждёт вызов голым await, не дойдёт ни до одной, пока вызов не вернётся, и очередь и close() всё это время ждут его. Такой вызов останавливает только его собственное средство — например, токен, который раздел «Срок задачи» на странице об отмене передаёт перемотке. ctx.abandonable вокруг вызова заканчивает ожидание, а вызов оставляет идти.

Снимок сообщает, а не ставит диагноз. Долгое ожидание не доказывает забытый ctx.abandonable. Тело внутри внешнего вызова, которого оно обязано дождаться, даёт тот же снимок, с фазой body. Ресурс, который освобождается долго, держит Job столько же, и тогда фаза cleanup. Фаза говорит, где Job, а не почему: пока работает тело, фаза body, чего бы оно ни ждало, и движок не гадает.

Почему отмена была долгой

SoloPendingJob отвечает, пока Job ещё работает. Вторая половина вопроса приходит потом и там, где никто не смотрит: какие задачи работали дальше, несмотря на отмену, которая должна была их остановить, и сколько.

Первая попытка

Наблюдатель видит оба конца задачи, поэтому меряет время между ними:

// Первая попытка: время жизни прячет отмену, после которой задача доработала.
final class SlowJobs extends SoloObserver {
  final _startedAt = Expando<DateTime>('start');

  @override
  void onStart(Solo<Object> solo, Job<Object?> job) =>
      _startedAt[job] = clock.now();

  @override
  void onFinish(Solo<Object> solo, Job<Object?> job) {
    final startedAt = _startedAt[job];
    if (startedAt == null) return;
    final ran = clock.now().difference(startedAt);
    if (ran > const Duration(milliseconds: 50)) {
      log('${job.key} ran ${ran.inMilliseconds} ms');
    }
  }
}

Время между onStart и onFinish равно времени жизни задачи. Задача, которая шла 300 мс, потому что работа занимает 300 мс, даёт ту же строку, что и задача, отменённая на десятой миллисекунде и всё равно доработавшая до конца. Искать стоит вторую, а эти два хука их не различают.

Отметка отмены

final class SlowCancellations extends SoloObserver {
  // Expando держит ключ слабо: запись уходит вместе с задачей,
  // и чистить нечего.
  final _markedAt = Expando<DateTime>('cancellation');

  @override
  void onStart(Solo<Object> solo, Job<Object?> job) {
    // whenCancelled срабатывает, когда Job приняла отмену, а не когда
    // позвали cancel(): сперва кончится секция ctx.uncancellable.
    job.whenCancelled((_) => _markedAt[job] = clock.now());
  }

  @override
  void onFinish(Solo<Object> solo, Job<Object?> job) {
    final markedAt = _markedAt[job];
    if (markedAt == null) return;
    final delay = clock.now().difference(markedAt);
    if (delay > const Duration(milliseconds: 50)) {
      log('${job.key} ran ${delay.inMilliseconds} ms past its cancellation');
    }
  }
}

Задачу, которую никто не отменял, не отмечают и не сообщают о ней, сколько бы она ни шла. Число считается от момента, когда Job приняла отмену, а не от cancel(), и до исхода, вместе с детьми и уборкой. Отмену, пришедшую, пока открыта секция ctx.uncancellable, Job принимает, когда секция кончается: секция на 100 мс, отменённая на десятой, даёт 0 мс, а вызвавший cancel или close ждал 90 мс.

Смотреть на число стоит ради одной конкретной ошибки. Тело, ждущее что-то долгое голым await, замечает отмену, только когда ожидание кончится, а тот же вызов через ctx.abandonable перестаёт ждать сразу, как и задержка, записанная через ctx.pause. Ожидание на 300 мс, отменённое на десятой:

как тело ждёт	число
`await Future.delayed(...)`	290 мс
`ctx.abandonable(() => Future.delayed(...))`	0 мс
`ctx.pause(...)`	0 мс

Строкой в логе станет только первая: две другие не дотягивают до 50 мс, с которых наблюдатель начинает сообщать.

Задача, отменённая до старта, не сообщает ничего: onStart для неё не зовут вовсе, значит регистрации и отметки не было. Замечать отмену было некому, и в контроллере под это попадает всё, что выброшено из очереди.

Наблюдатель читает clock.now(), а не DateTime.now(). Под fake_async первый идёт вместе с фальшивым временем, а второй стоит на месте, так что того же наблюдателя можно проверить тестом. Наблюдатель работает в приложении, поэтому package:clock идёт в его зависимости, а не в зависимости разработки; пакет этот без своих зависимостей, и fake_async и так от него зависит везде, где идут тесты.

Отмена, которая не доходит

final class StuckCancellations extends SoloObserver {
  final _timers = Expando<Timer>('cancellation');

  @override
  void onStart(Solo<Object> solo, Job<Object?> job) => job.whenCancelled(
    (_) => _timers[job] = Timer(
      const Duration(seconds: 5),
      () => log('${job.key} has not stopped: ${solo.pending}'),
    ),
  );

  @override
  void onFinish(Solo<Object> solo, Job<Object?> job) => _timers[job]?.cancel();
}

Отметку выше читают, когда Job кончается, и потому о самой долгой отмене из всех, о той, что не кончается, она как раз молчит. Здесь отметка становится таймером: whenCancelled его заводит, конец Job снимает, и остаётся ровно та Job, которую попросили остановиться, а она не остановилась:

ignores has not stopped: SoloPending([ignores] in its body, cancelled by Cancelled(manual))

Job, которую никто не отменял, здесь не заводит таймера, сколько бы ни работала: этот наблюдатель о неисполненной отмене, а не о долгой работе. Секция ctx.uncancellable придерживает отмену, которая пришла, пока она открыта, и whenCancelled сработает, когда секция закроется. Пять секунд идут с этого момента. Дочерняя Job, до которой отмена дошла от родительской, получает свою строку, и снимок в этой строке снова снят с корневой.

Solo.observer держит одного наблюдателя, а ставить с этой страницы пора уже четверых. SoloObserver.all складывает их в одного:

Solo.observer = SoloObserver.all([
  LoggingObserver(),
  Hangs(),
  SlowCancellations(),
  StuckCancellations(),
]);

Каждый хук идёт каждому из них в порядке списка, и каждый вызов сам по себе: тот, кто бросил исключение, отдаёт его в зону, а следующий всё равно вызывается. Если один и тот же наблюдатель в списке дважды, SoloObserver.all бросает ArgumentError.