[8.270][BUG][NOT A BUG] frequent restarts of IM/P2P classifier

Here is the mdw.log for some of the same time periods today:
2011:11:21-09:40:27 asgbeta middleware[7240]: T core::Config::load:266() => modules=2,4
2011:11:21-09:40:29 asgbeta middleware[7240]: T main::top-level:235() => ending cycle 1, caught 0 signals, 0 children still running
2011:11:21-09:56:40 asgbeta middleware[9502]: T main::top-level:62() => MiddleWare starting
2011:11:21-09:56:44 asgbeta middleware[9502]: T main::top-level:188() => starting cycle 0, caught 0 signals
[..]
2011:11:21-09:56:44 asgbeta middleware[9502]: T core::Config::Changed:132() => 
2011:11:21-10:19:01 asgbeta middleware[9502]: T main::top-level:235() => ending cycle 2, caught 0 signals, 0 children still running
2011:11:21-10:17:01 asgbeta middleware[12137]: T main::top-level:62() => MiddleWare starting

mdw restarts repeatedly, but the log files do not show why this is happening.
Are there any "segfault" messages in kernel.log ?

I wonder if this isn't the same issue as I keep having: http://www.astaro.org/astaro-beta-versions/asg-8-300-public-beta/40120-8-270-bug-open-snort-continuously-restarts.html

Yes, same issue (mdw restarts repeatedly), but the root cause as to why it is happening seems to be different.

There are no segfaults in the kernel.log, just this repeating over and over:

2011:11:23-06:06:47 asgbeta kernel: [148134.187942] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-06:06:47 asgbeta kernel: [148134.210987] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-06:06:47 asgbeta kernel: [148134.214912] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-06:27:08 asgbeta kernel: [149349.883190] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-06:27:08 asgbeta kernel: [149349.887132] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-06:27:08 asgbeta kernel: [149349.890925] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-06:27:09 asgbeta kernel: [149350.274830] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-06:27:09 asgbeta kernel: [149350.279733] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-06:27:09 asgbeta kernel: [149350.283694] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-06:47:29 asgbeta kernel: [150565.369114] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-06:47:29 asgbeta kernel: [150565.389215] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-06:47:29 asgbeta kernel: [150565.393267] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-06:47:30 asgbeta kernel: [150565.807820] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-06:47:30 asgbeta kernel: [150565.813228] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-06:47:30 asgbeta kernel: [150565.817086] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-07:14:20 asgbeta kernel: [152170.469726] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-07:14:20 asgbeta kernel: [152170.474094] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-07:14:20 asgbeta kernel: [152170.477901] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-07:14:20 asgbeta kernel: [152170.872519] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-07:14:20 asgbeta kernel: [152170.877125] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-07:14:20 asgbeta kernel: [152170.880926] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-07:34:10 asgbeta kernel: [153355.172996] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-07:34:10 asgbeta kernel: [153355.176954] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-07:34:10 asgbeta kernel: [153355.180962] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-07:34:10 asgbeta kernel: [153355.563222] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-07:34:10 asgbeta kernel: [153355.567920] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-07:34:10 asgbeta kernel: [153355.572302] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-07:54:01 asgbeta kernel: [154540.504638] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-07:54:01 asgbeta kernel: [154540.508937] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-07:54:01 asgbeta kernel: [154540.512816] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-07:54:01 asgbeta kernel: [154540.882981] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-07:54:01 asgbeta kernel: [154540.887765] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-07:54:01 asgbeta kernel: [154540.891613] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-08:11:51 asgbeta kernel: [155605.602959] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-08:11:51 asgbeta kernel: [155605.606462] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-08:11:51 asgbeta kernel: [155605.610463] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-08:11:52 asgbeta kernel: [155605.992214] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-08:11:52 asgbeta kernel: [155605.996909] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-08:11:52 asgbeta kernel: [155606.001174] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-08:36:12 asgbeta kernel: [157060.649000] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-08:36:12 asgbeta kernel: [157060.652895] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-08:36:12 asgbeta kernel: [157060.656837] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-08:36:12 asgbeta kernel: [157061.188190] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-08:36:12 asgbeta kernel: [157061.208235] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-08:36:12 asgbeta kernel: [157061.212234] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-08:54:03 asgbeta kernel: [158126.171743] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-08:54:03 asgbeta kernel: [158126.175764] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-08:54:03 asgbeta kernel: [158126.179714] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-08:54:03 asgbeta kernel: [158126.548161] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-08:54:03 asgbeta kernel: [158126.553753] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-08:54:03 asgbeta kernel: [158126.557624] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-09:11:53 asgbeta kernel: [159191.731481] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-09:11:53 asgbeta kernel: [159191.736117] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-09:11:53 asgbeta kernel: [159191.739928] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-09:11:54 asgbeta kernel: [159192.119100] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-09:11:54 asgbeta kernel: [159192.123854] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-09:11:54 asgbeta kernel: [159192.127703] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-09:31:43 asgbeta kernel: [160376.166817] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-09:31:43 asgbeta kernel: [160376.171228] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-09:31:43 asgbeta kernel: [160376.175783] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-09:31:44 asgbeta kernel: [160376.564945] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-09:31:44 asgbeta kernel: [160376.569236] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-09:31:44 asgbeta kernel: [160376.573079] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-10:00:35 asgbeta kernel: [162102.244973] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-10:00:35 asgbeta kernel: [162102.248223] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-10:00:35 asgbeta kernel: [162102.252211] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-10:00:35 asgbeta kernel: [162102.625108] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-10:00:35 asgbeta kernel: [162102.629936] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-10:00:35 asgbeta kernel: [162102.634065] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2011:11:23-10:31:26 asgbeta kernel: [163947.286331] e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-10:31:26 asgbeta kernel: [163947.290361] ADDRCONF(NETDEV_UP): eth0: link is not ready
2011:11:23-10:31:26 asgbeta kernel: [163947.294217] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
2011:11:23-10:31:26 asgbeta kernel: [163947.665980] e1000: eth1: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
2011:11:23-10:31:26 asgbeta kernel: [163947.670860] ADDRCONF(NETDEV_UP): eth1: link is not ready
2011:11:23-10:31:26 asgbeta kernel: [163947.674692] ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
asgbeta:/root #

I am open to giving access to my beta system if needed... I don't use it for anything production.

I am open to giving access to my beta system if needed... I don't use it for anything production.

I had a look at you box.  The mdw restarts are triggered by the "timewarp" check -- it seems your time is going forwards/backwards by aboud 5 minutes from time to time.

I'll look into what may be causing this, but afaics so far this is not an asg bug, but related to your installation/setup.

In the past week on an lightly used system, I received the restart email notification one time.

I had a look at you box.  The mdw restarts are triggered by the "timewarp" check -- it seems your time is going forwards/backwards by aboud 5 minutes from time to time.

I'll look into what may be causing this, but afaics so far this is not an asg bug, but related to your installation/setup.

Thanks for pointing this out.

Turns out my vsphere host didn't have DNS servers configured (Not sure how I missed that over a year ago.. lol).. so my ntp service wasn't able to resolve hostnames.

Long story short, my vsphere host time was off by 6 minutes. And during the VM creation the "time synchronization" with host was enabled.. so I guess the vm tools were fighting with the ntp client in ASG to keep the right time. I didn't have sync enabled for my production 8.2 VM, so the issue never appeared there.

All fixed now, ntp working in vsphere, and I will re-enable all the services in ASG to see if it happens anymore.

Thanks again for pointing out the time issue.

Got an email on IM/P2P restart today.  Found this in kernel.log


brk:/var/log # cat kernel.log
2011:11:30-16:05:00 brk kernel: [115580.210622] afcd[12911]: segfault at 6d6f6b ip 00000000f74219e6 sp 00000000f35171b0 error 4 in vineyard.so[f73e3000+50000]


Here is afcd.log - starts after the crash time.


brk:/var/log # cat afc.log
2011:11:30-16:05:20 brk afcd[8026]: _afc_cfg_file_plugin_parse: 549 protocols registered
2011:11:30-16:05:20 brk afcd[8026]: loaded plugin '/var/sec/chroot-afc/lib/afc/vineyard.so'
2011:11:30-16:05:20 brk afcd[8026]: _afc_cfg_file_plugin_parse: 549 protocols registered
2011:11:30-16:05:20 brk afcd[8027]: AFC ready.
2011:11:30-16:05:58 brk afcd[8027]: connid 21: Vineyard library did not see the start of the tcp connection
2011:11:30-16:05:58 brk afcd[8027]: Nov 30, 2011; 16:05:58 - : protocol = 6, src ip = 192.168.1.107, src port = 59192, dst ip = 209.85.145.139, dst port = 80

Here is system.log (not that it is helpful)


2011:11:30-16:04:57 brk dhclient: DHCPREQUEST on eth1 to 10.239.2.1 port 67
2011:11:30-16:05:01 brk /usr/sbin/cron[7996]: (root) CMD (   /usr/local/bin/reporter/system-reporter.pl)
2011:11:30-16:05:08 brk dhclient: DHCPREQUEST on eth1 to 10.239.2.1 port 67

Found this in kernel.log
2011:11:30-16:05:00 brk kernel: [115580.210622] afcd[12911]: segfault at 6d6f6b ip 00000000f74219e6 sp 00000000f35171b0 error 4 in vineyard.so[f73e3000+50000]

There should be a core file (afcd.***) in /var/storage/cores.
Please consider sending it to fwestphal@astaro.com . Thanks.
You can compress it using e.g. "bzip2 afcd*" to reduce the size before sending.

I found 5 cores.  Will compress and send.