a few hundreds of messages from PF peg the cpu to 100% - SOLVED see #14

[franco]

Maybe I missed this several times but what messages are we talking about exactly? Is this normalized to the point where we just assume "these messages" are a given and we need to fix the console accordingly? Why not chase these messages and mute them, or find the root cause?


Cheers,
Franco

[thelittleblackbird]

I though i explained that in my post :(

Maybe I missed this several times but what messages are we talking about exactly? Is this normalized to the point where we just assume "these messages" are a given and we need to fix the console accordingly? Why not chase these messages and mute them, or find the root cause?


Cheers,
Franco

the messages are regular pf messages about the status of the incoming packet, or when a new entry is inserted in the connections table, you can see some excerpts of the messages here:

https://forum.opnsense.org/index.php?action=dlattach;attach=56244

The root cause is just some packets with some problems in the wire, as u can see in the link, they are the typical status messages, nothing out of the ordinary, just a FW doing its job. The problem is when those messages are beyond some threshold and then start consuming cpu cycles because the default config push them into the serial console.

And this is when i would like to know if this serial output could be disabled because is taking a lot of cycles for almost nothing, because the dmesg buffer is still getting the status output.

[franco]

Thanks, seeing it now. Pasting here for reference:

> pf: loose state match: pf: BAD state: TCP in wire:
> pf: ICMP error message too short (ip6)
> pf: OK ICMP 1:1
> pf: State failure on:
> pf: BAD state: TCP out wire:

So first of all this isn't normal. Looks like corruption on the wire. Bad cables?

Secondly, these are all logged under PF_DEBUG_MISC, which means that's set under Firewall: Settings: Advanced: Debug. If you select "urgent" or "none" these should go away easily. The default these days is supposed to be "urgent", but in some cases it default to "none". I can fix that.

Looking at the code at some point the default was "misc" indeed: https://github.com/opnsense/core/commit/269b8b789


Cheers,
Franco

[Seimus]

If its a corruption on the wire, then the CRC counter possibly should increase. So try to check your Error Interface counters.

Otherwise it can be caused by asymmetry.

Similar to
https://github.com/opnsense/core/issues/10346

Regards,
S.

[thelittleblackbird]

Secondly, these are all logged under PF_DEBUG_MISC, which means that's set under Firewall: Settings: Advanced: Debug. If you select "urgent" or "none" these should go away easily. The default these days is supposed to be "urgent", but in some cases it default to "none". I can fix that.

Looking at the code at some point the default was "misc" indeed: https://github.com/opnsense/core/commit/269b8b789

This setting is only for changing the verbosity of the FW, but this is in my opinion not the root cause here.

Just to focus the discussion --> the problem is that when the FW log is sent to the serial console it can set the CPU to 100% because the PacketFilter tries to send a log message through a 115kbps interface, a few hundreds of messages per second is enough to trigger this effect in my installation. And more important, this is independent of the power of the processor.

Changing the verbosity of the kernel (because PF is executed in an irq context) will certainly mitigate the problem, but this is not addressing the issue. On top of that, i think reducing the verbosity is not a good solution because logs analysis is often a first line of defence to see if something unusual is happening

[thelittleblackbird]

So first of all this isn't normal. Looks like corruption on the wire. Bad cables?

If its a corruption on the wire, then the CRC counter possibly should increase. So try to check your Error Interface counters.

errors logged by the HW or PF due to CRC are always 0 or 1 to maximum, the uptime is counted in tens of weeks.

you can check the previous investigations of this thread here:
https://forum.opnsense.org/index.php?topic=52224.0

Otherwise it can be caused by asymmetry.

Similar to
https://github.com/opnsense/core/issues/10346

yes, I can recognize the error and i am pretty sure it is happening to me too. I didnt give it importance because i thought it was a problem with a saturation test and those errors / RST packets could be due to duplicates or out-or-order.

But honestly, even if the errors are real and real problems are happening, i expect the FW to be able to cope with those situations, please remember that we are speaking about a 350mbps line. I expect the HW to cope with the "regular problems" with several 1gpbs interfaces maxing the transmission out.

[franco]

> Just to focus the discussion

No, you focus here please: if you don't want "misc" don't set "misc".

If you change the scope to the console, which happens to be a serial console, for output that is not needed for operation just turn it off. At least use the default, which is "urgent", which works for hundreds of thousands of users.


Cheers,
Franco

[thelittleblackbird]

> Just to focus the discussion

No, you focus here please: if you don't want "misc" don't set "misc".

If you change the scope to the console, which happens to be a serial console, for output that is not needed for operation just turn it off. At least use the default, which is "urgent", which works for hundreds of thousands of users.


Cheers,
Franco

I think i didnt explain myself. -> setting this variable also mute the FW to the dmesg buffer afaik, this could be undesired because the logging capabilities could be affected.

I dont want to touch the logging capabilities/verbosity, i only want not to log to the serial console.

[franco]

All "misc" -> "urgent" does is mute the "misc" messages you said will kill your console.


Cheers,
Franco

[thelittleblackbird]

All "misc" -> "urgent" does is mute the "misc" messages you said will kill your console.


Cheers,
Franco

nobody is denying that, the messages will disappear from the console because it will not be outputted by PF....

[Patrick M. Hausen]

@franco I guess their intention is not to log to the console at all - which can become a bottleneck for all kinds of debug logging if a serial device.

I guess everyone who ever entered "term moni" followed by "debug <something>" into Cisco IOS followed by a near heart attack and a drive to the data centre knows the feeling ;-)

If I am not mistaken a serial console should not be blocking the kernel messaging if proper hardware handshaking is configured and DCD is down, i.e. no device is connected to the serial port. I'd have to ask Deciso if this state from the OPNsense OS' point of view is in effect if nothing is connected to the builtin USB-serial converter. Or what happens if there is a USB host connected to the USB console port of OPNsense but there is no cu/minicom/tip/... process on the host side holding the device open. Interesting.

Kind regards,
Patrick