@@ -154,7 +154,16 @@ public function applyConfig(): void
154154 return ;
155155 }
156156
157+ // Per-phase profiling. One log line at the end pinpoints which phase
158+ // stalls when "Configuring Firewall" boot stage hangs (e.g. broken VPC,
159+ // DNS timeouts, slow ipset loads in module hooks).
160+ $ totalStart = hrtime (true );
161+ $ phases = [];
162+
163+ $ t = hrtime (true );
157164 $ this ->dropAllRules ();
165+ $ phases ['drop ' ] = $ this ->phaseElapsed ($ t );
166+
158167 if ($ this ->firewall_enable ) {
159168 // Check if any firewall rules exist in database
160169 // If no rules configured - allow all traffic (don't apply DROP at the end)
@@ -164,7 +173,9 @@ public function applyConfig(): void
164173 $ arr_command [] = $ this ->getIptablesInputRule ('' , '-m conntrack --ctstate ESTABLISHED,RELATED ' );
165174
166175 // Drop packets from known SIP scanners by User-Agent string match
176+ $ t = hrtime (true );
167177 $ this ->addSipScannerRules ($ arr_command );
178+ $ phases ['scanner ' ] = $ this ->phaseElapsed ($ t );
168179
169180 if ($ this ->maxReqSec > 0 ) {
170181 $ advancedSipRules = [
@@ -183,8 +194,13 @@ public function applyConfig(): void
183194 }
184195 // Add allowed services (regular subnets only, catch-all separated)
185196 $ catchAllCommands = [];
197+ $ t = hrtime (true );
186198 $ this ->addMainFirewallRules ($ arr_command , $ catchAllCommands );
199+ $ phases ['main ' ] = $ this ->phaseElapsed ($ t );
200+
201+ $ t = hrtime (true );
187202 $ this ->addAdditionalFirewallRules ($ arr_command );
203+ $ phases ['add ' ] = $ this ->phaseElapsed ($ t );
188204
189205 // Add firewall rules customisation
190206 $ arr_commands_custom = [];
@@ -197,25 +213,37 @@ public function applyConfig(): void
197213 $ cmd = "$ cat /etc/firewall_additional "
198214 . " | $ grep -v '|' | $ grep -v '&' "
199215 . " | $ grep '^iptables' | $ awk -F ';' '{print $1}' " ;
216+ $ t = hrtime (true );
200217 Processes::mwExec ($ cmd , $ arr_commands_custom );
218+ $ phases ['custom_read ' ] = $ this ->phaseElapsed ($ t );
201219
202220 // Execute regular subnet rules and SIP provider rules
221+ $ t = hrtime (true );
203222 Processes::mwExecCommands ($ arr_command , $ out , 'firewall ' );
223+ $ phases ['exec_main ' ] = $ this ->phaseElapsed ($ t );
224+
225+ $ t = hrtime (true );
204226 Processes::mwExecCommands ($ arr_commands_custom , $ out , 'firewall_additional ' );
227+ $ phases ['exec_custom ' ] = $ this ->phaseElapsed ($ t );
205228
206229 // Allow modules to inject custom iptables rules (e.g., ipset-based GeoIP filtering)
207230 // Positioned after explicit subnet ACCEPT and SIP provider rules, before catch-all ACCEPT
231+ $ t = hrtime (true );
208232 PBXConfModulesProvider::hookModulesMethod (SystemConfigInterface::ON_AFTER_IPTABLES_RELOAD );
233+ $ phases ['hooks ' ] = $ this ->phaseElapsed ($ t );
209234
210235 // Apply catch-all rules (0.0.0.0/0, ::/0) AFTER module hooks
211236 // This ensures GeoIP DROP rules take effect before the catch-all ACCEPT
212237 if (!empty ($ catchAllCommands )) {
238+ $ t = hrtime (true );
213239 Processes::mwExecCommands ($ catchAllCommands , $ out , 'firewall_catchall ' );
240+ $ phases ['catchall ' ] = $ this ->phaseElapsed ($ t );
214241 }
215242
216243 // Drop everything else - but ONLY if rules are configured
217244 // If no rules exist, allow all traffic to prevent lockout
218245 if ($ hasRules ) {
246+ $ t = hrtime (true );
219247 // IPv4 DROP
220248 $ dropCommand = $ this ->getIptablesInputRule ('' , '' , 'DROP ' );
221249 Processes::mwExec ($ dropCommand );
@@ -225,8 +253,37 @@ public function applyConfig(): void
225253 if (!empty ($ ip6tablesPath )) {
226254 Processes::mwExec ("$ ip6tablesPath -A INPUT -j DROP " );
227255 }
256+ $ phases ['drop_final ' ] = $ this ->phaseElapsed ($ t );
228257 }
229258 }
259+
260+ $ phases ['total ' ] = $ this ->phaseElapsed ($ totalStart );
261+ SystemMessages::sysLogMsg (__METHOD__ , 'firewall profile: ' . $ this ->formatPhases ($ phases ), LOG_INFO );
262+ }
263+
264+ /**
265+ * Returns elapsed seconds since a `hrtime(true)` reference, rounded to 2 decimals.
266+ *
267+ * Uses the monotonic clock so the measurement survives NTP step adjustments
268+ * that can fire during early boot.
269+ */
270+ private function phaseElapsed (int $ startNs ): float
271+ {
272+ return round ((hrtime (true ) - $ startNs ) / 1_000_000_000 , 2 );
273+ }
274+
275+ /**
276+ * Formats the phase timing map as a single-line `key=Vs key=Vs …` string.
277+ *
278+ * @param array<string, float> $phases
279+ */
280+ private function formatPhases (array $ phases ): string
281+ {
282+ $ parts = [];
283+ foreach ($ phases as $ name => $ seconds ) {
284+ $ parts [] = sprintf ('%s=%.2fs ' , $ name , $ seconds );
285+ }
286+ return implode (' ' , $ parts );
230287 }
231288
232289 /**
0 commit comments