Boot hang at Configuring Firewall stage when network is unreachable (no per-phase visibility)

[jorikfon]

Summary

On AWS with a mis-configured VPC, the Configuring Firewall SystemLoader stage hung for 224.36 s during boot. The root cause in that particular installation was networking (broken VPC), but the architectural problem is that IptablesConf::applyConfig() performs ~60 sequential exec(iptables) calls + module hooks + syslog without any decomposition. From console output and /storage/usbdisk1/mikopbx/log/system/messages it is impossible to tell which phase actually stalled.

This issue tracks the bug (single stage can silently consume ~4 minutes of boot time on a broken network) and the diagnostics work needed to localise it on the next problematic host. The actual remediation per-phase will land in follow-up issues once we have a real profile.

Reproduction

1. Provision a MikoPBX instance in a VPC where outbound DNS / Sentry / NTP egress is blocked or routed to a black hole.
2. Boot the system.
3. Observe the SystemLoader output — the Configuring Firewall stage takes ≫ 1 s. On the affected host it took 224.36 s.

Before this issue’s diagnostic work, neither console output nor system/messages reveals which sub-phase of applyConfig() was responsible.

Hypotheses (to be disambiguated by phase profiling)

1. DNS lookup inside iptables -s <fqdn> when SipHosts contains hostnames (15–30 s timeout each).
2. Sentry / outbound HTTP calls inside SystemMessages::sysLogMsg() when the security group blocks egress.
3. Module hooks (onAfterIptablesReload) — ipset loads of large GeoIP lists.
4. fork+exec × 60 on burstable EC2 with depleted CPU credits.
5. iptables-nft backend overhead / lazy kernel module autoload.

Affected code

• src/Core/System/Configs/IptablesConf.php — applyConfig().

What has been done (commit 41157ead6 on develop)

Per-phase profiling via hrtime(true) (monotonic clock, NTP-step immune). One INFO-level syslog line is emitted at the end of applyConfig():

firewall profile: drop=Xs scanner=Xs main=Xs add=Xs custom_read=Xs exec_main=Xs exec_custom=Xs hooks=Xs catchall=Xs drop_final=Xs total=Xs

• Behaviour unchanged. Pure observability.
• Profile is written only when System::canManageFirewall() is true. Docker and capability-less LXC stay silent (early return — no work, no log).
• The line is written on both boot (SystemLoader) and runtime reload (IptablesConf::reloadFirewall() — inherits since it calls applyConfig() internally).

Reference: sessions/tasks/h-diagnose-firewall-config-phases.md in the repo (task brief and approach).

Out of scope for this issue

To be filed as separate follow-up issues once a real-world firewall profile line is captured:

• Replace N×exec(iptables) with iptables-restore batching to cut the cost of the exec_main phase.
• Wrap SystemMessages::sysLogMsg / Sentry transport with non-blocking I/O so broken egress cannot stall the boot stage.
• Pre-resolve FQDN-based SipHosts with a short timeout before passing them to iptables.

Acceptance criteria

• A real-world firewall profile: … line is captured from a host that exhibited the slow boot.
• The dominant phase is identified from that line.
• A follow-up issue is opened that targets the actual fix for the identified phase.

---

Резюме (RU)

На инсталляции в AWS с некорректно настроенным VPC стейдж Configuring Firewall во время загрузки занял 224.36 с. Корневая причина в конкретном кейсе оказалась сетевой (сломанный VPC), но архитектурная проблема — в том, что IptablesConf::applyConfig() выполняет ~60 последовательных exec(iptables) плюс хуки модулей плюс syslog без какой-либо декомпозиции. Из консольного вывода и system/messages понять, какая именно фаза подвисла, невозможно.

Issue фиксирует сам факт бага (один стейдж может молча сожрать ~4 минуты бута при сломанной сети) и диагностическую работу, нужную, чтобы локализовать виновника на следующей проблемной инсталляции. Реальное лечение по конкретной фазе — в follow-up issue после первого профиля с боевого хоста.

Воспроизведение

1. Подготовить MikoPBX в VPC, где заблокирован исходящий DNS / Sentry / NTP.
2. Загрузить систему.
3. Стейдж Configuring Firewall отрабатывает дольше секунды — на проблемном хосте 224.36 с.

До этой задачи ни консольный вывод, ни system/messages не показывают, какая подфаза applyConfig() ответственна.

Гипотезы (профайлинг разводит их)

1. DNS-lookup внутри iptables -s <fqdn> при FQDN в SipHosts (15–30 с таймаут каждый).
2. Sentry / исходящие HTTP-вызовы внутри SystemMessages::sysLogMsg() при заблокированной security group.
3. Хуки модулей (onAfterIptablesReload) — ipset-загрузка больших списков (GeoIP).
4. fork+exec × 60 на burstable EC2 с исчерпанным CPU credit pool.
5. iptables-nft backend overhead / lazy autoload модулей ядра.

Затронутый код

• src/Core/System/Configs/IptablesConf.php — applyConfig().

Что уже сделано (коммит 41157ead6 на develop)

Профайлинг по фазам через hrtime(true) (монотонный таймер, не сбрасывается NTP-коррекциями). По завершении applyConfig() в syslog (LOG_INFO) пишется одна строка:

firewall profile: drop=Xs scanner=Xs main=Xs add=Xs custom_read=Xs exec_main=Xs exec_custom=Xs hooks=Xs catchall=Xs drop_final=Xs total=Xs

• Поведение не меняется. Только наблюдаемость.
• Профиль пишется только если System::canManageFirewall() возвращает true. Docker и LXC без CAP_NET_ADMIN молчат (ранний return — нет работы, нет лога).
• Работает и при бутстейдже, и при runtime reload (IptablesConf::reloadFirewall() зовёт applyConfig()).

Ссылка: sessions/tasks/h-diagnose-firewall-config-phases.md в репозитории.

Вне рамок этого issue

Под отдельные follow-up issue после реального профиля:

• Заменить N×exec(iptables) на батч через iptables-restore, чтобы сократить стоимость фазы exec_main.
• Обернуть SystemMessages::sysLogMsg / Sentry-транспорт неблокирующим I/O — чтобы сломанная сеть не вешала бут.
• Резолвить FQDN из SipHosts заранее, с коротким таймаутом, до передачи в iptables.

Критерии закрытия

• С проблемного хоста снята реальная строка firewall profile: ….
• Из этой строки определена доминирующая фаза.
• Открыт follow-up issue с фиксом конкретной выявленной фазы.