PFSense 2.4.4 not responding at console and web interface CRITICAL BUG! HELP!

KOM

What is the point of your post? You haven't provided any details or anything at all.

john_wick

Critical bug in 2.3 branch when use virtualized pfsense (KVM)
The similar problem https://forum.netgate.com/topic/104013/pfsense-not-responding-at-console
Hardware
proliant dl380g8 (tryed diferent machines)
Newly instaled version without pakages
EIST disabled
NTP disabled
Configuration as in manual for proxmox https://docs.netgate.com/pfsense/en/latest/virtualization/virtualizing-pfsense-with-proxmox.html

What Points you need? I find three similar themes on forum without any idea Its no normal

KOM

@john_wick said in PFSense 2.4.4 not responding at console and web interface CRITICAL BUG! HELP!:

Critical bug in 2.3 bench

What's 2.3 bench??

Generally, and this is true for all IT troubleshooting, you need to provide details of your equipment, what you did with it, and what happened including any error messages or other output. People can't read your mind. The more detail you provide, the easier it will be to help you.

At this point I will bow out since I odn't have any KVM experience (I run under VMware).

john_wick

branch 2.3

Part of general system logs

Mar 22 13:53:20	kernel		calcru: runtime went backwards from 1224 usec to 1210 usec for pid 36681 (getty)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 1405 usec to 1389 usec for pid 36478 (getty)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 1198 usec to 1185 usec for pid 36353 (getty)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 1372 usec to 1356 usec for pid 36275 (getty)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 1674 usec to 1655 usec for pid 35977 (getty)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 514 usec to 508 usec for pid 87105 (minicron)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 229 usec to 226 usec for pid 86981 (minicron)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 3026 usec to 2992 usec for pid 86757 (minicron)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 37236 usec to 36819 usec for pid 86260 (minicron)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 264 usec to 261 usec for pid 85984 (minicron)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 20671773 usec to 20442862 usec for pid 51062 (radvd)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 871334 usec to 861644 usec for pid 44885 (cron)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 11487249 usec to 11362918 usec for pid 18202 (filterlog)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 275078 usec to 271996 usec for pid 12114 (sshd)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 869578 usec to 860058 usec for pid 10490 (dhclient)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 55279 usec to 54660 usec for pid 6932 (dhclient)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 15106770 usec to 14939504 usec for pid 388 (devd)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 4439449 usec to 4390280 usec for pid 23 (vnlru)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 4266353 usec to 4219084 usec for pid 22 (bufdaemon)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 10362820 usec to 10247997 usec for pid 22 (bufdaemon)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 4377567 usec to 4329044 usec for pid 21 (bufspacedaemon)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 16325 usec to 16142 usec for pid 20 (pagezero)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 5617427 usec to 5555304 usec for pid 18 (pagedaemon)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 152415 usec to 150723 usec for pid 17 (soaiod4)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 138540 usec to 137002 usec for pid 16 (soaiod3)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 138149 usec to 136617 usec for pid 9 (soaiod2)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 152800 usec to 151105 usec for pid 8 (soaiod1)
Mar 22 13:53:20	kernel		calcru: runtime went backwards from 66871881 usec to 66131613 usec for pid 7 (rand_harvestq)

john_wick

Gate system logs

Mar 3 09:46:55	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 5 23:05:35	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 5 23:05:37	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 8 20:42:49	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:50	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:50	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:51	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:51	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:52	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:52	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:53	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:53	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:54	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 8 20:42:56	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 10 01:23:05	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 10 01:23:09	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 11 09:18:11	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 11 09:18:13	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 13 16:09:48	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 13 16:09:50	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 16 08:55:05	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 16 08:55:07	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 16 11:54:48	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 16 11:54:50	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 16 17:49:32	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 16 17:49:34	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 16 16:58:31	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 16 16:58:35	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 18 14:08:07	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:08	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:09	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:09	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:10	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:10	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:11	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:11	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:12	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:12	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:13	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:13	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 18 14:08:16	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "
Mar 21 21:05:11	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 21 21:05:12	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 21 21:05:12	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 21 21:05:13	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 21 21:05:13	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 21 21:05:14	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 21 21:05:14	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 21 21:05:15	dpinger		WAN_DHCP 176.36.0.1: sendto error: 65
Mar 21 21:05:17	dpinger		send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 0 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 176.36.0.1 bind_addr 176.37.xxx.xxx identifier "WAN_DHCP "

stephenw10

You have titled this 2.4.4 but you're asking about the 2.3 branch, which is it?

Steve

stephenw10

And in another thread you're asking about 2.4.3...

john_wick

Hi Stephen I have this errors on both vesions in KVM (Proxmox) hypervisor(
updated version recently). I tryed disable NTP severs change NTP pools reinstall PFsense, cpu units change, Change timecounters without result

In virtualized OpNsense have similar kernel panic with filtellog flood but connection fall down (in PF works DHCP,NAT, etc.

Anytime when I needed acces to cli or web UI I have to suspend and resume VM. I think is temporary solution add to cronjob console comad №11(restart web configurator) with 30-60sec interval.
If this does not work to me IPfire firewall my reserve plan

Similar situations
https://forum.netgate.com/topic/130467/solved-pfsense-2-4-3-halts-with-calcru-messages-in-console/5

https://forum.netgate.com/topic/104013/pfsense-not-responding-at-console/7

stephenw10

So which pfSense version are you testing?

john_wick

Version of my test instalation 2.4.4-RELEASE-p2 (amd64)
Maybe need some logs or output?
I think is problem with webconfigurator how to add correct cron job comand like: 1 * * * * root etc/rc.restart_webgui ? This can work?

stephenw10

Ok, so how are you seeing that logs if you have no access to the GUI or console? Does it not fail immediately?

What are the results of: sysctl kern.timecounter

Steve

john_wick

[2.4.4-RELEASE][root@pfSense.localdomain]/root: sysctl kern.timecounter
kern.timecounter.tsc_shift: 1
kern.timecounter.smp_tsc_adjust: 0
kern.timecounter.smp_tsc: 0
kern.timecounter.invariant_tsc: 0
kern.timecounter.fast_gettime: 1
kern.timecounter.tick: 1
kern.timecounter.choice: i8254(0) ACPI-fast(900) HPET(950) TSC-low(800) dummy(-1000000)
kern.timecounter.hardware: HPET
kern.timecounter.alloweddeviation: 5
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.counter: 7474
kern.timecounter.tc.i8254.mask: 65535
kern.timecounter.tc.ACPI-fast.quality: 900
kern.timecounter.tc.ACPI-fast.frequency: 3579545
kern.timecounter.tc.ACPI-fast.counter: 12623953
kern.timecounter.tc.ACPI-fast.mask: 16777215
kern.timecounter.tc.HPET.quality: 950
kern.timecounter.tc.HPET.frequency: 100000000
kern.timecounter.tc.HPET.counter: 3428655973
kern.timecounter.tc.HPET.mask: 4294967295
kern.timecounter.tc.TSC-low.quality: 800
kern.timecounter.tc.TSC-low.frequency: 1199709078
kern.timecounter.tc.TSC-low.counter: 4238456201
kern.timecounter.tc.TSC-low.mask: 4294967295

stephenw10

You might try switching to one of the other timecounters:
sysctl kern.timecounter.hardware=ACPI-fast

You can add that in System Tunables if it fixes it.

Steve

john_wick

@stephenw10 When i suspend and resume Pfsense VM in Proxmox cli and web gui unfrozen + (have some kernel messages calcru) but it works and trafig hase go even webui/cli have not response. I conect fro my nat on 192.168.1.1
I have low trafic and load resources up to 30% max
Maybe need to try set maximum performance in bios? Irony in the situation that linux work more stable over bsd system in my test lab :(

stephenw10

You mean shutdown and restart or actually suspend?

john_wick

@stephenw10 Without reboot only suspend like pause/resume

stephenw10

Hmm, not sure I've ever tried that. Does it only show that error when you resume it?

john_wick

@stephenw10 said in PFSense 2.4.4 not responding at console and web interface CRITICAL BUG! HELP!:

You might try switching to one of the other timecounters:
sysctl kern.timecounter=ACPI-fast

You can add that in System Tunables if it fixes it.

Steve

alt timecounter

stephenw10

Sorry I missed a bit there, the sysctl should be kern.timecounter.hardware

Did you try it at the command line first?

Steve

john_wick

@stephenw10
Mostly yes. According to my observations, sometimes the calcru error enters the log not immediately, but at intervals after a pause. Basically, the console simply stops responding or responding via ssh and the web UI stops responding sometimes with a 502 bad gateway. Now I have installed sysctl kern.timecounter = ACPI-fast will reboot and look at the reaction. If I fail, I will try to improve performance and frequency.