PHP Fatal Error

stephenw10

Actually identically the same error?

Is that the first time the UPS experienced some sort of incident?

Steve

asv345h

@stephenw10
Oops, line #6 is different. I've only seen this error this one time. Not the UPS, but what is 'notify_monitor'?

-rick

[04-Mar-2023 18:18:12 US/Eastern] PHP Fatal error:  Uncaught TypeError: fwrite(): Argument #1 ($stream) must be of type resource, bool given in /etc/inc/config.lib.inc:172
Stack trace:
#0 /etc/inc/config.lib.inc(172): fwrite(false, 'a:40:{s:7:"vers...')
#1 /etc/inc/config.lib.inc(147): generate_config_cache(Array)
#2 /etc/inc/config.inc(141): parse_config()
#3 /etc/inc/gwlb.inc(25): require_once('/etc/inc/config...')
#4 /etc/inc/functions.inc(35): require_once('/etc/inc/gwlb.i...')
#5 /etc/inc/notices.inc(26): require_once('/etc/inc/functi...')
#6 /usr/local/bin/notify_monitor.php(24): include_once('/etc/inc/notice...')
#7 {main}
  thrown in /etc/inc/config.lib.inc on line 172
[04-Mar-2023 18:18:12 US/Eastern] PHP Fatal error:  Uncaught ValueError: Path cannot be empty in /etc/inc/notices.inc:101
Stack trace:
#0 /etc/inc/notices.inc(101): fopen('', 'w')
#1 /etc/inc/config.lib.inc(1162): file_notice('phperror', 'PHP ERROR: Type...', 'PHP errors')
#2 [internal function]: pfSense_clear_globals()
#3 {main}
  thrown in /etc/inc/notices.inc on line 101

stephenw10

Ok, that looks like it was triggered by a gateway alarm. Do you see that logged at that time?

jimp

@asv345h said in PHP Fatal Error:

Oops, line #6 is different. I've only seen this error this one time. Not the UPS, but what is 'notify_monitor'?

notify_monitor.php is the script that runs in the background to send queued SMTP notifications

asv345h

So, during that time I was doing some maintenance and had pulled the WAN cable so there were plenty of gateway alarms firing. I also don't have SMTP notification turned on. Here's a combined log of the relevant events around that time. The gateway logs are missing because I had not yet enabled them for remote logging.

-rick

"2023-03-04T18:18:08.000-05:00","apcupsd-ups[69397]: Startup successful"
"2023-03-04T18:18:08.000-05:00","upsmon[68380]: Communications with UPS APC_UPS lost"
"2023-03-04T18:18:08.000-05:00","upsmon[68380]: UPS [APC_UPS]: connect failed: Connection failure: Connection refused"
"2023-03-04T18:18:08.000-05:00","upsmon[68380]: Startup successful"
"2023-03-04T18:18:08.000-05:00","php-fpm[4765]: /rc.start_packages: Starting service nut"
"2023-03-04T18:18:08.000-05:00","php-fpm[4765]: /rc.start_packages: Restarting/Starting all packages."
"2023-03-04T18:18:09.000-05:00","upsd[98528]: Startup successful"
"2023-03-04T18:18:09.000-05:00","upsd[98528]: Connected to UPS [APC_UPS]: apcupsd-ups-APC_UPS"
"2023-03-04T18:18:09.000-05:00","upsd[98528]: listening on ::1 port 3493"
"2023-03-04T18:18:09.000-05:00","upsd[98528]: listening on 127.0.0.1 port 3493"
"2023-03-04T18:18:11.000-05:00","upsmon[68380]: upsmon parent: read"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: #6 /usr/local/bin/notify_monitor.php(24): include_once('/etc/inc/notice...')"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: #5 /etc/inc/notices.inc(26): require_once('/etc/inc/functi...')"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: #7 {main}"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]:   thrown"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: #3 /etc/inc/gwlb.inc(25): require_once('/etc/inc/config...')"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: #0 /etc/inc/config.lib.inc(172): fwrite(false, 'a:40:{s:7:""vers...')"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: #1 /etc/inc/config.lib.inc(147): generate_config_cache(Array)"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: Stack trace:"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: #4 /etc/inc/functions.inc(35): require_once('/etc/inc/gwlb.i...')"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: notify_monitor.php: PHP ERROR: Type: 1, File: /etc/inc/config.lib.inc, Line: 172, Message: Uncaught TypeError: fwrite(): Argument #1 ($stream) must be of type resource, bool given in /etc/inc/config.lib.inc:172"
"2023-03-04T18:18:12.000-05:00","php-cgi[17145]: #2 /etc/inc/config.inc(141): parse_config()"
"2023-03-04T18:18:12.000-05:00","apcupsd-ups[2771]: Startup successful"
"2023-03-04T18:18:12.000-05:00","upsmon[936]: UPS [APC_UPS]: connect failed: Connection failure: Connection refused"
"2023-03-04T18:18:12.000-05:00","upsmon[936]: Communications with UPS APC_UPS lost"
"2023-03-04T18:18:12.000-05:00","upsmon[936]: Startup successful"
"2023-03-04T18:18:13.000-05:00","check_reload_status[399]: Syncing firewall"
"2023-03-04T18:18:13.000-05:00","php-fpm[4765]: /rc.start_packages: Beginning configuration backup to https://acb.netgate.com/save"
"2023-03-04T18:18:13.000-05:00","php-fpm[4765]: /rc.start_packages: Configuration Change: (system): syslog-ng: Settings saved"
"2023-03-04T18:18:13.000-05:00","upsd[33956]: Startup successful"
"2023-03-04T18:18:13.000-05:00","upsd[33956]: Connected to UPS [APC_UPS]: apcupsd-ups-APC_UPS"
"2023-03-04T18:18:13.000-05:00","upsd[33956]: listening on 127.0.0.1 port 3493"
"2023-03-04T18:18:13.000-05:00","upsd[33956]: listening on ::1 port 3493"
"2023-03-04T18:18:17.000-05:00","upsmon[936]: Communications with UPS APC_UPS established"
"2023-03-04T18:18:17.000-05:00","upsd[33956]: User local-monitor@::1 logged into UPS [APC_UPS]"

stephenw10

Ok, you may not be running Nut but you are running apcupsd. I assume you have email notifications set? If you disable it the errors stop?

asv345h

@stephenw10
No, just running nut. I have a server running apcupsd and have pfsense running nut in "remote apcupsd" mode.

I don't use email notifications. However, the "Disable SNMP Notifications" is NOT checked and the config fields are all blank. Should disable be checked?

So, this is the only error of this type that I have seen in my 10+ years of running pfsense and I thought it might be a bug.

stephenw10

It is a bug of some sort. We just need to narrow down where it is. So, yes, try disabling the notifications and see if that stops the error reappearing.

asv345h

@stephenw10
Alright, I post back if error returns. Thanks for the help.

-rick

jimp

For the error to happen there, an fopen function has to fail to open a file for writing in /tmp/.

It's not clear why, though, since it could be one of several things, including (but not limited to):

/tmp is full
If /tmp is a RAM disk, there may not be sufficient RAM to create a new file in the FS
If /tmp is on an SSD/MMC/HDD, the filesystem holding /tmp has a problem (e.g. UFS and needs fsck run several times, or ZFS and needs a scrub)
If /tmp is on an SSD/MMC/HDD, the disk or controller may have stopped responding to commands (disk or controller physical issue, maybe controller driver issue, etc.)

The problem here is that if it is a disk issue the logs may not be helpful unless you pipe syslog to a remote network host. If there is a problem with the disk it can't log that to the disk when a problem occurs. It might print a message to the console, though, but it depends on what happened.

I've tried a few different ways to see if multiple processes competing to write the same file all at once could trigger this kind of error but so far I haven't had any luck drawing it out.

asv345h

@jimp
My hardware is a ng-6100 with pfsense pre-installed. Looks like plenty of space at the moment.

I stream syslog to a remote server and have the logs. I searched for "/tmp" but got no hits. A search for "mmc" only found this: kernel: mmc0: <MMC/SD bus> on sdhci_pci0, but that was 4 days after the exception. Is there another search term I should try?

-rick

Screenshot 2023-03-09 at 9.46.19 AM.png

stephenw10

Mmm, nothing obviously wrong there. Seems like it's unable to write the file for some other reason.

wralb

I'm seeing the exact same error from time to time as @asv345h since upgrading to 23.01 . I'm also running an ng-6100 running 23.01 (for info, I have a APC UPS plugged in to a USB port). Everything was fine for a year before the upgrade.

Here is an example:

FreeBSD 14.0-CURRENT #0 plus-RELENG_23_01-n256037-6e914874a5e: Fri Feb 10 20:30:29 UTC 2023     root@freebsd:/var/jenkins/workspace/pfSense-Plus-snapshots-23_01-main/obj/amd64/VDZvZksF/var/jenkins/workspace/pfSense-Plus-snapshots-23_01-main/sources/FreeBS

Crash report details:

PHP Errors:
[07-Mar-2023 11:26:53 Europe/London] PHP Fatal error:  Uncaught TypeError: fwrite(): Argument #1 ($stream) must be of type resource, bool given in /etc/inc/config.lib.inc:172
Stack trace:
#0 /etc/inc/config.lib.inc(172): fwrite(false, 'a:44:{s:7:"vers...')
#1 /etc/inc/config.lib.inc(147): generate_config_cache(Array)
#2 /etc/inc/config.inc(141): parse_config()
#3 /etc/inc/gwlb.inc(25): require_once('/etc/inc/config...')
#4 /etc/inc/functions.inc(35): require_once('/etc/inc/gwlb.i...')
#5 /etc/inc/notices.inc(26): require_once('/etc/inc/functi...')
#6 /usr/local/bin/notify_monitor.php(24): include_once('/etc/inc/notice...')
#7 {main}
  thrown in /etc/inc/config.lib.inc on line 172
[07-Mar-2023 11:26:53 Europe/London] PHP Fatal error:  Uncaught ValueError: Path cannot be empty in /etc/inc/notices.inc:101
Stack trace:
#0 /etc/inc/notices.inc(101): fopen('', 'w')
#1 /etc/inc/config.lib.inc(1162): file_notice('phperror', 'PHP ERROR: Type...', 'PHP errors')
#2 [internal function]: pfSense_clear_globals()
#3 {main}
  thrown in /etc/inc/notices.inc on line 101

The timing of the error correlates closely with a gateway event:

Mar  7 11:26:36 pfsense dpinger[88905]: exiting on signal 15
Mar  7 11:26:36 pfsense dpinger[90399]: send_interval 500ms  loss_interval 2000ms  time_period 60000ms  report_interval 0ms  data_len 1  alert_interval 1000ms  latency_alarm 1000ms  loss_alarm 50%  dest_addr 86.25.176.1  bind_addr 86.25.183.166  identifier "WAN_DHCP "
Mar  7 11:26:39 pfsense dpinger[90399]: exiting on signal 15
Mar  7 11:26:39 pfsense dpinger[16144]: send_interval 500ms  loss_interval 2000ms  time_period 60000ms  report_interval 0ms  data_len 1  alert_interval 1000ms  latency_alarm 1000ms  loss_alarm 50%  dest_addr 86.25.176.1  bind_addr 86.25.183.166  identifier "WAN_DHCP "
Mar  7 11:26:46 pfsense dpinger[16144]: exiting on signal 15
Mar  7 11:26:46 pfsense dpinger[57987]: send_interval 500ms  loss_interval 2000ms  time_period 60000ms  report_interval 0ms  data_len 1  alert_interval 1000ms  latency_alarm 1000ms  loss_alarm 50%  dest_addr 86.25.176.1  bind_addr 86.25.183.166  identifier "WAN_DHCP "

File system is ZFS with plenty of space and /tmp showing 480KB of 6.5GB used.

Overlord

I have the same issue on all of my pfSense boxes - after the Upgrade to 23.01

stephenw10

The exact same pair of php errors?

This? https://redmine.pfsense.org/issues/14061

Is there some common config all your installs share?

akghetto

Any update on this error? I started getting it tonight.

My main drive is defintely not full...

[23.01-RELEASE][admin@host.domain]/root: df -h
Filesystem                     Size    Used   Avail Capacity  Mounted on
/dev/ufsid/59b7f3af0adccc14    100G    2.6G     89G     3%    /
devfs                          1.0K    1.0K      0B   100%    /dev
tmpfs                          4.0M    196K    3.8M     5%    /var/run
devfs                          1.0K    1.0K      0B   100%    /var/dhcpd/dev

//edit: nevermind... found patch c5faa351c1ef6d4555478a7f50b3a16ece7e0b2a on redmine. Sorry for the thread bump.

jacksnack2

Same issue here. Seen this error twice after upgrading to 2.7.0 on July 1st.

I also see references to Nut Package (which is installed).

I applied the patch as referenced above, I'll report back with results.

jacksnack2

I just received this error again this morning. Patch has been applied at last posting date.

stephenw10

What error exactly?

jacksnack2

@stephenw10

Please see the error listed at the top of the post.

America/New_York] PHP Fatal error:  Uncaught TypeError: fwrite(): Argument #1 ($stream) must be of type resource, bool given in /etc/inc/config.lib.inc:172