2.2 rc.newwanip/rc.newwanipv6 package restart conflict
-
Upgraded to 2.2 today on my production box and of course I run a ton of packages =D… I came across that famous restart_packages bug that no one wants to talk about <grin>.. Looks like rc.newwanip/rc.newwanipv6 could be conflicting with each other on startup. None of my packages are starting up after a reboot, on the console you don't even see them starting.. Checking the log, it looks some have started a couple of times (search for bound in the log) and this concerns me:
php-fpm[6265]: /rc.start_packages: Skipping STARTing packages process because previous/another instance is already runningbecause of this, its not executing any scripts in /usr/local/etc/rc.d either
log
an 24 21:06:31 suricata: 24/1/2015 -- 21:06:31 - <error>-- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - error parsing signature "alert tcp $EXTERNAL_NET $HTTP_PORTS -> $HOME_NET any (msg:"ET WEB_CLIENT Possible Microsoft Internet Explorer Dynamic Object Tag/URLMON Sniffing Cross Domain Information Disclosure Attempt"; flow:established,to_client; content:"obj"; nocase; content:"data"; nocase; within:10; content:"file|3A|//127."; nocase; within:20; pcre:"/(obj.data|\object.data).+file\x3A\x2F\x2F127\x2E[0-9]/si"; reference:url,tools.cisco.com/security/center/viewAlert.x?alertId=19873; reference:url,tools.cisco.com/security/center/viewAlert.x?alertId=20610; reference:url,www.microsoft.com/technet/security/bulletin/ms10-035.mspx; reference:url,www.coresecurity.com/content/internet-explorer-dynamic-object-tag; reference:cve,2010-0255; reference:url,doc.emergingthreats.net/2011695; classtype:attempted-user; sid:2011695; rev:4;)" from file /usr/pbi/suricata-amd64/etc/suricata/suricata_43205_em2/rules/suricata.ru Jan 24 21:06:26 kernel: done. Jan 24 21:06:26 php-fpm[6265]: /rc.start_packages: Skipping STARTing packages process because previous/another instance is already running Jan 24 21:06:25 kernel: done. Jan 24 21:06:25 syslogd: kernel boot file is /boot/kernel/kernel Jan 24 21:06:25 syslogd: exiting on signal 15 Jan 24 21:06:25 kernel: done. Jan 24 21:06:25 kernel: done. Jan 24 21:06:25 php: rc.bootup: miniupnpd: Starting service on interface: lan Jan 24 21:06:25 php: rc.bootup: Creating rrd update script Jan 24 21:06:24 snmpd[7237]: disk_OS_get_disks: adding device 'ada0' to device list Jan 24 21:06:24 kernel: done. Jan 24 21:06:23 suricata: 24/1/2015 -- 21:06:23 - <error>-- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - error parsing signature "alert tcp $EXTERNAL_NET $HTTP_PORTS -> $HOME_NET any (msg:"ET WEB_CLIENT Possible Microsoft Internet Explorer Dynamic Object Tag/URLMON Sniffing Cross Domain Information Disclosure Attempt"; flow:established,to_client; content:"obj"; nocase; content:"data"; nocase; within:10; content:"file|3A|//127."; nocase; within:20; pcre:"/(obj.data|\object.data).+file\x3A\x2F\x2F127\x2E[0-9]/si"; reference:url,tools.cisco.com/security/center/viewAlert.x?alertId=19873; reference:url,tools.cisco.com/security/center/viewAlert.x?alertId=20610; reference:url,www.microsoft.com/technet/security/bulletin/ms10-035.mspx; reference:url,www.coresecurity.com/content/internet-explorer-dynamic-object-tag; reference:cve,2010-0255; reference:url,doc.emergingthreats.net/2011695; classtype:attempted-user; sid:2011695; rev:4;)" from file /usr/pbi/suricata-amd64/etc/suricata/suricata_39811_em3/rules/suricata.ru Jan 24 21:06:23 suricata: 24/1/2015 -- 21:06:23 - <error>-- [ERRCODE: SC_ERR_PCRE_COMPILE(5)] - pcre compile of ""/(obj.data|\object.data).+file\x3A\x2F\x2F127\x2E[0-9]/si"" failed at offset 11: missing opening brace after \o Jan 24 21:06:20 kernel: done. Jan 24 21:06:19 kernel: . Jan 24 21:06:06 kernel: . Jan 24 21:06:06 kernel: . Jan 24 21:06:03 suricata: 24/1/2015 -- 21:06:03 - <error>-- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - error parsing signature "alert http $EXTERNAL_NET $HTTP_PORTS -> $HOME_NET any (msg:"ET EXPLOIT libPNG - Width exceeds limit"; flow:established,from_server; content:"|0D 0A 0D 0A 89 50 4E 47 0D 0A 1A 0A|"; depth:8; byte_test:4,>,0x80000000,8,relative,big,string,hex; reference:url,www.securiteam.com/unixfocus/5ZP0C0KDPG.html; reference:url,doc.emergingthreats.net/bin/view/Main/2001191; classtype:misc-activity; sid:2001191; rev:14;)" from file /usr/pbi/suricata-amd64/etc/suricata/suricata_43205_em2/rules/suricata.rules at line 2821 Jan 24 21:06:03 suricata: 24/1/2015 -- 21:06:03 - <error>-- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - depth - 8 smaller than content length - 12 Jan 24 21:06:03 barnyard2[1750]: Writing PID "1750" to file "/var/run/barnyard2_em243205.pid" Jan 24 21:06:03 barnyard2[1750]: PID path stat checked out ok, PID path set to /var/run Jan 24 21:06:03 barnyard2[1750]: Daemon initialized, signaled parent pid: 96759 Jan 24 21:06:03 barnyard2[96759]: Daemon parent exiting Jan 24 21:06:03 barnyard2[96759]: Initializing daemon mode Jan 24 21:06:03 barnyard2[96759]: INFO database: Defaulting Reconnect sleep time to 5 second Jan 24 21:06:03 barnyard2[96759]: INFO database: Defaulting Reconnect/Transaction Error limit to 10 Jan 24 21:06:03 barnyard2[96759]: Log directory = /var/log/suricata/suricata_em243205 Jan 24 21:06:03 barnyard2[96759]: Barnyard2 spooler: Event cache size set to [4096] Jan 24 21:06:01 sshd[81458]: fatal: Write failed: Operation not permitted Jan 24 21:06:01 sshd[81458]: fatal: Write failed: Operation not permitted Jan 24 21:05:53 kernel: . Jan 24 21:05:52 ntopng: 1422151552|2|1|Host [68.172.210.112](/lua/host_details.lua?host=68.172.210.112&ifname=em3) is a flooder [342 new flows in the last 3 sec] Jan 24 21:05:51 barnyard2[96759]: ---------------------------- +[ Signature Suppress list ]+ Jan 24 21:05:51 barnyard2[96759]: +[No entry in Signature Suppress List]+ Jan 24 21:05:51 barnyard2[96759]: +[ Signature Suppress list ]+ ---------------------------- Jan 24 21:05:51 barnyard2[96759]: Found pid path directive (/var/run) Jan 24 21:05:51 barnyard2[96759]: Parsing config file "/usr/pbi/suricata-amd64/etc/suricata/suricata_43205_em2/barnyard2.conf" Jan 24 21:05:51 barnyard2[96759]: Initializing Output Plugins! Jan 24 21:05:51 barnyard2[96759]: Initializing Input Plugins! Jan 24 21:05:51 barnyard2[96759]: --== Initializing Barnyard2 ==-- Jan 24 21:05:51 barnyard2[96759]: Jan 24 21:05:51 barnyard2[96759]: Running in Continuous mode Jan 24 21:05:51 barnyard2[96759]: Found pid path directive (/var/run) Jan 24 21:05:51 SuricataStartup[96427]: Barnyard2 START for LAN(43205_em2)... Jan 24 21:05:51 php-fpm[12981]: /rc.dyndns.update: phpDynDNS (photo.stephenculhane.com): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:50 php-fpm[12981]: /rc.dyndns.update: phpDynDNS (95918): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:50 suricata: 24/1/2015 -- 21:05:50 - <notice>-- This is Suricata version 2.0.4 RELEASE Jan 24 21:05:49 SuricataStartup[91695]: Suricata START for LAN(43205_em2)... Jan 24 21:05:49 barnyard2[91323]: Writing PID "91323" to file "/var/run/barnyard2_em339811.pid" Jan 24 21:05:49 barnyard2[91323]: PID path stat checked out ok, PID path set to /var/run Jan 24 21:05:49 barnyard2[91323]: Daemon initialized, signaled parent pid: 42793 Jan 24 21:05:49 barnyard2[42793]: Daemon parent exiting Jan 24 21:05:49 barnyard2[42793]: Initializing daemon mode Jan 24 21:05:49 barnyard2[42793]: INFO database: Defaulting Reconnect sleep time to 5 second Jan 24 21:05:49 barnyard2[42793]: INFO database: Defaulting Reconnect/Transaction Error limit to 10 Jan 24 21:05:49 barnyard2[42793]: Log directory = /var/log/suricata/suricata_em339811 Jan 24 21:05:49 barnyard2[42793]: Barnyard2 spooler: Event cache size set to [4096] Jan 24 21:05:49 php-fpm[12981]: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:48 suricata: 24/1/2015 -- 21:05:48 - <error>-- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - error parsing signature "alert http $EXTERNAL_NET $HTTP_PORTS -> $HOME_NET any (msg:"ET EXPLOIT libPNG - Width exceeds limit"; flow:established,from_server; content:"|0D 0A 0D 0A 89 50 4E 47 0D 0A 1A 0A|"; depth:8; byte_test:4,>,0x80000000,8,relative,big,string,hex; reference:url,www.securiteam.com/unixfocus/5ZP0C0KDPG.html; reference:url,doc.emergingthreats.net/bin/view/Main/2001191; classtype:misc-activity; sid:2001191; rev:14;)" from file /usr/pbi/suricata-amd64/etc/suricata/suricata_39811_em3/rules/suricata.rules at line 2822 Jan 24 21:05:48 suricata: 24/1/2015 -- 21:05:48 - <error>-- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - depth - 8 smaller than content length - 12 Jan 24 21:05:48 php-fpm[12981]: /rc.dyndns.update: phpDynDNS (Home): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:47 php-fpm[12981]: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:46 php-fpm[12981]: /rc.dyndns.update: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:46 kernel: . Jan 24 21:05:44 check_reload_status: Updating all dyndns Jan 24 21:05:44 dhcpleases: kqueue error: unkown Jan 24 21:05:44 ntopng: [HTTPserver.cpp:379] ERROR: Unable to start HTTP server (IPv4) on port 3000 Jan 24 21:05:44 ntopng: [Geolocation.cpp:59] WARNING: Unable to read GeoIP database /usr/local/share/ntopng/httpdocs/geoip/GeoLiteCityv6.dat Jan 24 21:05:44 ntopng: [Geolocation.cpp:59] WARNING: Unable to read GeoIP database /usr/local/share/ntopng/httpdocs/geoip/GeoLiteCity.dat Jan 24 21:05:44 ntopng: [Geolocation.cpp:59] WARNING: Unable to read GeoIP database /usr/local/share/ntopng/httpdocs/geoip/GeoIPASNumv6.dat Jan 24 21:05:44 kernel: done. Jan 24 21:05:44 ntopng: [Geolocation.cpp:59] WARNING: Unable to read GeoIP database /usr/local/share/ntopng/httpdocs/geoip/GeoIPASNum.dat Jan 24 21:05:44 kernel: done. Jan 24 21:05:43 ntopng: [Geolocation.cpp:59] WARNING: Unable to read GeoIP database /usr/local/share/ntopng/httpdocs/geoip/GeoLiteCityv6.dat Jan 24 21:05:43 ntopng: [Geolocation.cpp:59] WARNING: Unable to read GeoIP database /usr/local/share/ntopng/httpdocs/geoip/GeoLiteCity.dat Jan 24 21:05:43 ntopng: [Geolocation.cpp:59] WARNING: Unable to read GeoIP database /usr/local/share/ntopng/httpdocs/geoip/GeoIPASNumv6.dat Jan 24 21:05:43 ntopng: [Geolocation.cpp:59] WARNING: Unable to read GeoIP database /usr/local/share/ntopng/httpdocs/geoip/GeoIPASNum.dat Jan 24 21:05:43 kernel: em3: promiscuous mode enabled Jan 24 21:05:43 kernel: em2: promiscuous mode enabled Jan 24 21:05:43 php: rc.bootup: ROUTING: setting IPv6 default route to fe80::201:5cff:fe33:5441%em3 Jan 24 21:05:43 kernel: em0_vlan10: promiscuous mode enabled Jan 24 21:05:43 php: rc.bootup: ROUTING: setting default route to 68.172.208.1 Jan 24 21:05:42 kernel: em0_vlan5: promiscuous mode enabled Jan 24 21:05:42 kernel: em0: promiscuous mode enabled Jan 24 21:05:42 kernel: Jan 24 21:05:41 kernel: done. Jan 24 21:05:40 upsd[52728]: User monuser@::1 logged into UPS [APC_Back-UPS_ES550] Jan 24 21:05:40 upsmon[55884]: Startup successful Jan 24 21:05:39 barnyard2[42793]: ---------------------------- +[ Signature Suppress list ]+ Jan 24 21:05:39 barnyard2[42793]: +[No entry in Signature Suppress List]+ Jan 24 21:05:39 barnyard2[42793]: +[ Signature Suppress list ]+ ---------------------------- Jan 24 21:05:39 barnyard2[42793]: Found pid path directive (/var/run) Jan 24 21:05:39 barnyard2[42793]: Parsing config file "/usr/pbi/suricata-amd64/etc/suricata/suricata_39811_em3/barnyard2.conf" Jan 24 21:05:39 barnyard2[42793]: Initializing Output Plugins! Jan 24 21:05:39 barnyard2[42793]: Initializing Input Plugins! Jan 24 21:05:39 barnyard2[42793]: --== Initializing Barnyard2 ==-- Jan 24 21:05:39 barnyard2[42793]: Jan 24 21:05:39 barnyard2[42793]: Running in Continuous mode Jan 24 21:05:39 barnyard2[42793]: Found pid path directive (/var/run) Jan 24 21:05:39 upsd[52728]: Startup successful Jan 24 21:05:39 upsd[48753]: Connected to UPS [APC_Back-UPS_ES550]: usbhid-ups-APC_Back-UPS_ES550 Jan 24 21:05:39 upsd[48753]: listening on 127.0.0.1 port 3493 Jan 24 21:05:39 upsd[48753]: listening on ::1 port 3493 Jan 24 21:05:39 usbhid-ups[48590]: Startup successful Jan 24 21:05:38 SuricataStartup[42550]: Barnyard2 START for WAN(39811_em3)... Jan 24 21:05:37 kernel: done. Jan 24 21:05:37 suricata: 24/1/2015 -- 21:05:37 - <notice>-- This is Suricata version 2.0.4 RELEASE Jan 24 21:05:36 SuricataStartup[26184]: Suricata START for WAN(39811_em3)... Jan 24 21:05:35 check_reload_status: Syncing firewall Jan 24 21:05:34 check_reload_status: Syncing firewall Jan 24 21:05:32 php-fpm[7112]: /rc.start_packages: [pfBlockerNG] Sync terminated during boot process. Jan 24 21:05:32 php-fpm[7112]: /rc.start_packages: [pfBlockerNG] Sync terminated during boot process. Jan 24 21:05:32 php-fpm[7112]: /rc.start_packages: [pfBlockerNG] Sync terminated during boot process. Jan 24 21:05:32 php-fpm[7112]: /rc.start_packages: [pfBlockerNG] Sync terminated during boot process. Jan 24 21:05:32 php-fpm[7112]: /rc.start_packages: [pfBlockerNG] Sync terminated during boot process. Jan 24 21:05:32 php-fpm[7112]: /rc.start_packages: [pfBlockerNG] Sync terminated during boot process. Jan 24 21:05:32 php-fpm[7112]: /rc.start_packages: Restarting/Starting all packages. Jan 24 21:05:32 php-fpm[7112]: /rc.newwanip: rc.newwanip: Info: starting on ovpns2. Jan 24 21:05:32 php-fpm[7112]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1. Jan 24 21:05:31 sshd[81458]: Accepted keyboard-interactive/pam for root from 192.168.0.101 port 7059 ssh2 Jan 24 21:05:31 check_reload_status: Starting packages Jan 24 21:05:31 php-fpm[7597]: /rc.newwanipv6: pfSense package system has detected an IP change or dynamic WAN reconnection - -> 2604:2000:2fc0:b0:1906:6a78:146:ba - Restarting packages. Jan 24 21:05:31 php-fpm[7597]: /rc.newwanipv6: Creating rrd update script Jan 24 21:05:30 check_reload_status: rc.newwanip starting ovpns2 Jan 24 21:05:30 kernel: ovpns2: link state changed to UP Jan 24 21:05:30 check_reload_status: rc.newwanip starting ovpns1 Jan 24 21:05:30 check_reload_status: Reloading filter Jan 24 21:05:30 kernel: ovpns1: link state changed to UP Jan 24 21:05:30 kernel: ovpns2: link state changed to DOWN Jan 24 21:05:30 check_reload_status: Reloading filter Jan 24 21:05:30 kernel: ovpns1: link state changed to DOWN Jan 24 21:05:30 kernel: Jan 24 21:05:29 php-fpm[7597]: /rc.newwanipv6: Resyncing OpenVPN instances for interface WAN. Jan 24 21:05:29 kernel: .. Jan 24 21:05:28 php-fpm[7597]: /rc.newwanipv6: phpDynDNS (photo.stephenculhane.com): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:27 php-fpm[7597]: /rc.newwanipv6: phpDynDNS (95918): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:26 php-fpm[7597]: /rc.newwanipv6: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:25 php-fpm[7597]: /rc.newwanipv6: phpDynDNS (Home): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:24 php-fpm[7597]: /rc.newwanipv6: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:23 php-fpm[7597]: /rc.newwanipv6: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry. Jan 24 21:05:20 php-fpm[7597]: /rc.newwanipv6: ROUTING: setting IPv6 default route to fe80::201:5cff:fe33:5441%em3 Jan 24 21:05:20 php-fpm[7597]: /rc.newwanipv6: ROUTING: setting default route to 68.0.0.1 Jan 24 21:05:20 php-fpm[30536]: /rc.newwanip: rc.newwanip: Info: starting on ovpns1. Jan 24 21:05:20 php-fpm[30536]: /rc.newwanip: rc.newwanip: Info: starting on ovpns2. Jan 24 21:05:20 php-fpm[7597]: /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1422151520] unbound[66431:0] error: bind: address already in use [1422151520] unbound[66431:0] fatal error: could not open ports' Jan 24 21:05:20 kernel: load_dn_sched dn_sched PRIO loaded Jan 24 21:05:20 kernel: load_dn_sched dn_sched WF2Q+ loaded Jan 24 21:05:20 kernel: load_dn_sched dn_sched RR loaded Jan 24 21:05:20 kernel: load_dn_sched dn_sched QFQ loaded Jan 24 21:05:20 kernel: load_dn_sched dn_sched FIFO loaded Jan 24 21:05:20 kernel: DUMMYNET 0 with IPv6 initialized (100409) Jan 24 21:05:19 php-fpm[7597]: /rc.newwanipv6: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1422151519] unbound[57995:0] error: bind: address already in use [1422151519] unbound[57995:0] fatal error: could not open ports' Jan 24 21:05:19 check_reload_status: rc.newwanip starting ovpns1 Jan 24 21:05:19 check_reload_status: rc.newwanip starting ovpns2 Jan 24 21:05:19 kernel: ovpns1: link state changed to UP Jan 24 21:05:19 kernel: Jan 24 21:05:19 kernel: pflog0: promiscuous mode enabled Jan 24 21:05:19 kernel: ovpns2: link state changed to UP Jan 24 21:05:19 check_reload_status: Linkup starting em2 Jan 24 21:05:19 kernel: em2: link state changed to UP Jan 24 21:05:19 kernel: tun2: changing name to 'ovpns2' Jan 24 21:05:18 kernel: tun1: changing name to 'ovpns1' Jan 24 21:05:18 kernel: Jan 24 21:05:18 php: rc.bootup: Resyncing OpenVPN instances. Jan 24 21:05:18 kernel: done. Jan 24 21:05:18 dhcpleases: Could not deliver signal HUP to process because its pidfile (/var/run/unbound.pid) does not exist, No such process. Jan 24 21:05:18 kernel: done. Jan 24 21:05:18 php: rc.bootup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1422151518] unbound[34879:0] error: bind: address already in use [1422151518] unbound[34879:0] fatal error: could not open ports' Jan 24 21:05:17 kernel: done. Jan 24 21:05:17 kernel: done. Jan 24 21:05:17 php: rc.bootup: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1422151517] unbound[25424:0] error: bind: address already in use [1422151517] unbound[25424:0] fatal error: could not open ports' Jan 24 21:05:17 php-fpm[7597]: /rc.newwanipv6: rc.newwanipv6: on (IP address: 2604:0:0:0:1906:0:0:ba) (interface: wan) (real interface: em3). Jan 24 21:05:17 php-fpm[7597]: /rc.newwanipv6: rc.newwanipv6: Info: starting on em3. Jan 24 21:05:17 php-fpm[7597]: /rc.newwanip: rc.newwanip: Info: starting on em3. Jan 24 21:05:16 kernel: done. Jan 24 21:05:16 rtsold: Starting dhcp6 client for interface wan(em3) Jan 24 21:05:16 rtsold: Recieved RA specifying route fe80::201:5cff:fe33:5441 for interface wan(em3) Jan 24 21:05:16 php: rc.bootup: Accept router advertisements on interface em3 Jan 24 21:05:16 check_reload_status: rc.newwanip starting em3 Jan 24 21:05:15 syslogd: sendto: Network is unreachable Jan 24 21:05:15 syslogd: sendto: Network is unreachable Jan 24 21:05:15 syslogd: sendto: Network is unreachable Jan 24 21:05:15 syslogd: sendto: Network is unreachable</notice></error></error></notice></error></error></error></error></error>For a temp fix, which would be better?
1:comment out the check in rc.stat_packages
2:comment out the function restart_packages() from rc.newwanip/rc.newwanipv6 (this is what i've done in the past)I went with option 2 for now since it has worked for me since 2.1.x</grin>