This discussion has been locked.

You can no longer post new replies to this discussion. If you have a question you can start a new discussion

CPU spikes on XG115 r3 running as ASG Software license ...

Escape75 over 1 year ago

I don't recall seeing these before updating to 9.715-4 ...

(I have also recently upgraded from 4GB to 8GB RAM, but why would that cause anything like this)

They appear spaced evenly every 3 hours, and always start 10 after, so for example 17:10:00 ...

(These are not traffic related, normally I've seen this box average 2% over the span of a few days)

This thread was automatically locked due to age.

Top Replies

Escape75 over 1 year ago in reply to Vivek Jagad +1 verified

Whatever it was, it now seems to be resolved ... I have rebooted, and did a touch /forcefsck as well as cleared log files and also did a postgresql rebuild. Thank you for your time!

Parents

0 Vivek Jagad over 1 year ago

Hello Escape75 ,

Thank you for reaching out to the community, I'd suggest the following articles, Please refer them to narrow down the situation:
1.) A guide to recording UTM process usage using atop.
2.) Understanding “top” and “atop” command in FW/UTM.

Thanks & Regards,
_______________________________________________________________

Vivek Jagad | Team Lead, Technical Support, Global Customer Experience

Log a Support Case | Sophos Service Guide
Best Practices – Support Case | Security Advisories
Compare Sophos next-gen Firewall | Fortune Favors the prepared
Sophos Community | Product Documentation | Sophos Techvids | SMS
If a post solves your question please use the 'Verify Answer' button.
Cancel
Vote Up 0 Vote Down

Cancel
0 Escape75 over 1 year ago in reply to Vivek Jagad

Ok I think I captured what is happening ...

It seems to be mdw.plx, now I will have to find out what that means ...
Cancel
Vote Up 0 Vote Down

Cancel
0 Escape75 over 1 year ago in reply to Escape75

The weekly graph illustrates how this issue started a few days ago ...

I have also confirmed the issue was not cause by memory upgrade, as the upgrade happened before the spikes started as seen by the memory usage drop form 50% to 25% ...
Cancel
Vote Up 0 Vote Down

Cancel
0 Vivek Jagad over 1 year ago in reply to Escape75

Hi Escape75 ,

mdw.plx is the middleware taking 99% of CPU

Check the following in the shell:
1.) ls -lah /var/storage/cores
2.) tail -f /var/log/mdw-debug.log
3.) tail -f /var/log/confd.log
4.) also you can try restating that service: /etc/init.d/mdw restart

And additionally check your DNS settings, this could lead to due misconfiguration as well. Also try fine tuning the rules and groups.

Thanks & Regards,
_______________________________________________________________

Vivek Jagad | Team Lead, Technical Support, Global Customer Experience

Log a Support Case | Sophos Service Guide
Best Practices – Support Case | Security Advisories
Compare Sophos next-gen Firewall | Fortune Favors the prepared
Sophos Community | Product Documentation | Sophos Techvids | SMS
If a post solves your question please use the 'Verify Answer' button.
Cancel
Vote Up 0 Vote Down

Cancel

0 Escape75 over 1 year ago in reply to Vivek Jagad

Thank you for your troubleshooting notes, here's what I have noticed:

1) There is nothing in /var/storage/cores ...

2) I captured /var/log/mdw-debug.log just before and during the spike ... see below

3) Also captured /var/log/confd.log just before and during the spike ... see below

4) A restart of mdw didn't help.

There's nothing incorrect with my DNS, just one availability group with 2 DNS servers, no request routing, etc.

There has been no configuration changes done recently,- around the time this has started, so I do not think it's due to configuration.

/var/log/confd.log

2023:06:01-11:09:16 escape75 confd[3435]: I main::top-level:562() => id="310c" severity="info" sys="System" sub="confd" name="node changed" node="notifications->reboot_reason" value="{'0' => 'Rebooted by Up2Date'}" oldvalue="{'0' => ''}" user="system" srcip="127.0.0.1" sid="6d9dfc0409d35471ee12ef918d3d4431ec020b418b10f06887c9100343a9b250" facility="system" client="auisys.plx" pid="27041"
2023:06:01-11:09:16 escape75 confd[3435]: I main::cleanup_changelog:998() => id="3100" severity="info" sys="System" sub="confd" name="trimmed version 96 from changelog"
2023:06:01-11:09:16 escape75 confd[3435]: I main::cleanup_changelog:998() => id="3100" severity="info" sys="System" sub="confd" name="trimmed version 97 from changelog"
2023:06:01-11:09:17 escape75 confd[3435]: I main::top-level:779() => id="310n" severity="info" sys="System" sub="confd" name="applied changes" user="system" srcip="127.0.0.1" sid="6d9dfc0409d35471ee12ef918d3d4431ec020b418b10f06887c9100343a9b250" facility="system" client="auisys.plx" pid="27041" version="99" storage="/cfg"
2023:06:01-11:09:32 escape75 confd[3435]: I main::top-level:779() => id="310n" severity="info" sys="System" sub="confd" name="applied changes" user="system" srcip="127.0.0.1" sid="d45ea54c97805a621f9577b74023cf7a6203410c47282e55e591695aceb8756a" facility="system" client="confd-client.pl" pid="27110" version="100" storage="/cfg"
2023:06:01-11:09:38 escape75 confd[3435]: I main::top-level:562() => id="310c" severity="info" sys="System" sub="confd" name="node changed" node="notifications->reboot_reason" value="{'0' => ''}" oldvalue="{'0' => 'Rebooted by Up2Date'}" user="system" srcip="127.0.0.1" sid="121d8388ea1b8a82cd02c1cfb7f0de2c68da24b8ef345cc15bc3046b55b44ded" facility="system" client="auisys.plx" pid="27162"
2023:06:01-11:09:38 escape75 confd[3435]: I main::top-level:779() => id="310n" severity="info" sys="System" sub="confd" name="applied changes" user="system" srcip="127.0.0.1" sid="121d8388ea1b8a82cd02c1cfb7f0de2c68da24b8ef345cc15bc3046b55b44ded" facility="system" client="auisys.plx" pid="27162" version="101" storage="/cfg"

/var/log/mdw-debug.log

2023:06:01-11:09:17 escape75 middleware[18811]: T main::top-level:213() => starting cycle 14, caught 1 signals
2023:06:01-11:09:17 escape75 middleware[18811]: T core::Config::Changed:198() => configversion=99
2023:06:01-11:09:17 escape75 middleware[18811]: T core::Config::Changed:208() => nodes=1 objects=0 triggers=0
2023:06:01-11:09:17 escape75 middleware[18811]: T core::Config::load:351() => modules=1,1
2023:06:01-11:09:17 escape75 middleware[18811]: D core::Config::load:359() => notifications.obj (notifications->reboot_reason.conf)
2023:06:01-11:09:17 escape75 middleware[18811]: D utils::Exec::ForkingSystem:209() => CHILD 1 FORK 27054 /usr/sbin/postmap /etc/postfix/clientauth
2023:06:01-11:09:17 escape75 middleware[18811]: D utils::Exec::ForkingSystem:209() => CHILD 2 FORK 27055 /etc/init.d/postfix reload
2023:06:01-11:09:17 escape75 middleware[18811]: D utils::Exec::SystemCall:99() => /usr/local/bin/ct -D -p udp --state NOT_SEEN_REPLY
2023:06:01-11:09:17 escape75 middleware[18811]: T modules::ipset::deleteUnused:342() => auto#=5/682 confd#=1/341
2023:06:01-11:09:17 escape75 middleware[18811]: T main::top-level:275() => cycle 14 waiting for 2 children
2023:06:01-11:09:19 escape75 middleware[18811]: D utils::Exec::BuryChildren:250() => CHILD 2 EXIT 27054 /usr/sbin/postmap /etc/postfix/clientauth
2023:06:01-11:09:19 escape75 middleware[18811]: T main::top-level:275() => cycle 14 waiting for 1 children
2023:06:01-11:09:20 escape75 middleware[18811]: :: Reloading Postfix..done
2023:06:01-11:09:20 escape75 middleware[18811]: D utils::Exec::BuryChildren:250() => CHILD 1 EXIT 27055 /etc/init.d/postfix reload
2023:06:01-11:09:20 escape75 middleware[18811]: T main::top-level:264() => ending cycle 14, caught 0 signals, 0 children still running
2023:06:01-11:09:32 escape75 middleware[18811]: T main::top-level:213() => starting cycle 15, caught 1 signals
2023:06:01-11:09:33 escape75 middleware[18811]: T core::Config::Changed:198() => configversion=100
2023:06:01-11:09:33 escape75 middleware[18811]: T core::Config::Changed:208() => nodes=0 objects=0 triggers=1
2023:06:01-11:09:33 escape75 middleware[18811]: T core::Config::load:351() => modules=1,14
2023:06:01-11:09:33 escape75 middleware[18811]: D core::Config::load:359() => aptp.obj (afc.trigger)
2023:06:01-11:09:33 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(afc_aptp)
2023:06:01-11:10:19 escape75 middleware[18811]: D core::Config::load:359() => dns.obj (aptp.obj)
2023:06:01-11:10:19 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(dns_route)
2023:06:01-11:10:19 escape75 middleware[18811]: D utils::Exec::ForkingSystem:209() => CHILD 1 FORK 27245 /var/mdw/scripts/named reload
2023:06:01-11:10:19 escape75 middleware[18811]: D core::Config::load:359() => afc.obj (aptp.obj,afc.trigger)
2023:06:01-11:10:19 escape75 middleware[18811]: D core::Config::ConfdCall:553() => get_static_data(afc,applications.ph)
2023:06:01-11:10:19 escape75 middleware[18811]: :: Sending SIGHUP to DNS Proxy
2023:06:01-11:10:19 escape75 middleware[18811]: [ ok ]
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => get_static_data(afc,groups.ph)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => get_product_details()
2023:06:01-11:10:20 escape75 middleware[18811]: D utils::Exec::BuryChildren:250() => CHILD 1 EXIT 27245 /var/mdw/scripts/named reload
2023:06:01-11:10:20 escape75 middleware[18811]: D utils::Exec::ForkingSystem:209() => CHILD 1 FORK 27249 /var/mdw/scripts/afc restart
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::load:359() => http.obj (afc.obj)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(http)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(auth_backend)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(http_profile)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => get_static_data(ca,certdata.ph)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => get_license_info()
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => get_system_version()
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::load:359() => up2date.obj (afc.obj,aptp.obj,http.obj)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(up2date-download)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => iaas_deployment()
2023:06:01-11:10:20 escape75 middleware[18811]: T modules::up2date::load:109() => iaas_deployment=
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(up2date-pattern)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(clientless_vpn)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => get_static_data(ca,certdata.ph)
2023:06:01-11:10:20 escape75 middleware[18811]: D utils::Exec::SystemCall:99() => /usr/bin/openssl c_rehash -compat /etc/ssl/certs
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::load:359() => executive_report.obj (http.obj)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(exec_report)
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::load:359() => uplink.obj (dns.obj)
2023:06:01-11:10:20 escape75 middleware[18811]: D utils::Exec::System:128() => /sbin/lsmod
2023:06:01-11:10:20 escape75 middleware[18811]: D core::Config::load:359() => afc.adapter.obj (afc.obj)
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::load:359() => http.adapter.obj (http.obj)
2023:06:01-11:10:21 escape75 middleware[18811]: D utils::Exec::System:128() => /sbin/lsmod
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::load:359() => uplink.adapter.obj (uplink.obj)
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::load:359() => up2date.adapter.obj (up2date.obj)
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::load:359() => ips.adapter.obj (http.obj)
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(ips)
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(WirelessSecurity)
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::ConfdCall:553() => may(throttle_ips)
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::ConfdCall:553() => check_ips_bundle_is_present()
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::ConfdCall:553() => check_ips_bundle_is_present()
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::ConfdCall:553() => check_ips_bundle_is_present()
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::load:359() => geoip.adapter.obj (up2date.obj)
2023:06:01-11:10:21 escape75 middleware[18811]: D core::Config::load:359() => tproxy.adapter.obj (http.obj)
2023:06:01-11:10:21 escape75 middleware[18811]: T core::Config::load:394() => core::Config: wrote crontab
2023:06:01-11:10:21 escape75 middleware[18811]: D utils::Exec::SystemCall:99() => /usr/local/bin/ct -D -p udp --state NOT_SEEN_REPLY
2023:06:01-11:10:21 escape75 middleware[18811]: D utils::Exec::ForkingSystem:209() => CHILD 2 FORK 27299 /usr/local/bin/ipt_clear_confirmed.sh
2023:06:01-11:10:22 escape75 middleware[18811]: T modules::ipset::deleteUnused:342() => auto#=5/682 confd#=1/341
2023:06:01-11:10:22 escape75 middleware[18811]: D utils::Exec::BuryChildren:250() => CHILD 2 EXIT 27299 /usr/local/bin/ipt_clear_confirmed.sh
2023:06:01-11:10:22 escape75 middleware[18811]: T main::top-level:264() => ending cycle 15, caught 1 signals, 1 children still running
2023:06:01-11:10:22 escape75 middleware[18811]: T main::top-level:213() => starting cycle 16, caught 1 signals
2023:06:01-11:10:22 escape75 middleware[18811]: T core::Config::Changed:198() => configversion=101
2023:06:01-11:10:22 escape75 middleware[18811]: T core::Config::Changed:208() => nodes=1 objects=0 triggers=0
2023:06:01-11:10:22 escape75 middleware[18811]: T core::Config::load:351() => modules=1,1
2023:06:01-11:10:22 escape75 middleware[18811]: D core::Config::load:359() => notifications.obj (notifications->reboot_reason.conf)
2023:06:01-11:10:22 escape75 middleware[18811]: D utils::Exec::ForkingSystem:209() => CHILD 2 FORK 27303 /usr/sbin/postmap /etc/postfix/clientauth
2023:06:01-11:10:22 escape75 middleware[18811]: D utils::Exec::ForkingSystem:209() => CHILD 3 FORK 27304 /etc/init.d/postfix reload
2023:06:01-11:10:22 escape75 middleware[18811]: D utils::Exec::SystemCall:99() => /usr/local/bin/ct -D -p udp --state NOT_SEEN_REPLY
2023:06:01-11:10:22 escape75 middleware[18811]: :: Stopping /usr/sbin/afcd:: Reloading Postfix..done
2023:06:01-11:10:22 escape75 middleware[18811]: T modules::ipset::deleteUnused:342() => auto#=5/682 confd#=1/341
2023:06:01-11:10:22 escape75 middleware[18811]: T main::top-level:275() => cycle 16 waiting for 3 children
2023:06:01-11:10:22 escape75 middleware[18811]: :: Starting /usr/sbin/afcd..done
2023:06:01-11:10:22 escape75 middleware[18811]: D utils::Exec::BuryChildren:250() => CHILD 3 EXIT 27249 /var/mdw/scripts/afc restart
2023:06:01-11:10:22 escape75 middleware[18811]: T main::top-level:275() => cycle 16 waiting for 2 children
2023:06:01-11:10:22 escape75 middleware[18811]: ..done
2023:06:01-11:10:24 escape75 middleware[18811]: D utils::Exec::BuryChildren:250() => CHILD 2 EXIT 27303 /usr/sbin/postmap /etc/postfix/clientauth
2023:06:01-11:10:24 escape75 middleware[18811]: T main::top-level:275() => cycle 16 waiting for 1 children
2023:06:01-11:10:25 escape75 middleware[18811]: ..done
2023:06:01-11:10:25 escape75 middleware[18811]: D utils::Exec::BuryChildren:250() => CHILD 1 EXIT 27304 /etc/init.d/postfix reload
2023:06:01-11:10:25 escape75 middleware[18811]: T main::top-level:264() => ending cycle 16, caught 0 signals, 0 children still running

Reply