FreeBSD 10 & default_vsz_limit causing reboots?

Rick Romero

15 Sep 2015 15 Sep '15

3:52 p.m.

Ok,

So this is really more of an observation than anything else.

I had a FreeBSD 10.1 server that was running great. Some SSL issue came up, or I upgrade Dovecot in ports - something occurred and the machine started rebooting randomly. It would run for 2 weeks, then reboot. It might run for 5 days and then reboot. So I started doing more FreeBSD upgrades, thinking it was a kernel issue. The reboots only increased.

This weekend I started thinking I might actually be having hardware issues. But, since I don't have easy physical access to the box and it's REALLY under loaded, I figured what the hell and upraded to 10.2 on Sunday. I think it rebooted 4 times after that on Sunday, and then another 2 times Monday morning.

Its worth noting that while I have crash dumps enabled, they don't seem to be occurring. So hardware is still a possibility.

After the 2nd Monday morning reboot, I started to wonder if there was some sort of process issue. Besides the OS upgrades - I had been monitoring the Dovecot logs for when the process limits are reached, and increasing them. It's a 'big' box, and load is typically between .30 and .50. CPUs aren't overtaxed, and most of the memory is dedicated to ZFS. The reboots are so short, I've only received one 'down' alert due to them. So it's a conerning issue, but not really impacting production.

On a whim I changed my default_vsz_limit (as I had been increasing every other limit but that) from 384M to 512M. The system hasn't rebooted in 24hours.

Now that could be a coincidence, but I thought I'd at least put it out there.

If you see anything weird in my dovecot config, let me know - My config was originally vpopmail, but over time I've migrated to SQL-only.

root@romulus:/usr/local/etc/dovecot # dovecot -n # 2.2.18: /usr/local/etc/dovecot/dovecot.conf # OS: FreeBSD 10.2-RELEASE amd64 auth_master_user_separator = * auth_mechanisms = plain login auth_username_translation = %@ auth_verbose = yes default_login_user = dovecot default_vsz_limit = 512 M disable_plaintext_auth = no first_valid_gid = 89 first_valid_uid = 89 last_valid_gid = 89 last_valid_uid = 89 log_path = /dev/stderr login_greeting = Ready. login_trusted_networks = 172.16.100.0/24 mail_fsync = never mail_plugins = " quota zlib stats" mail_privileged_group = mail namespace compat { alias_for = hidden = yes inbox = no list = no location = prefix = INBOX. separator = . } namespace inbox { inbox = yes location = prefix = separator = . } passdb { args = /usr/local/etc/dovecot/dovecot-master-sql.conf driver = sql master = yes pass = yes } passdb { args = /usr/local/etc/dovecot/dovecot-sql.conf driver = sql } plugin { quota = maildir quota_rule = Trash:storage=+10%% stats_refresh = 30 secs stats_track_cmds = yes } protocols = imap pop3 service anvil { client_limit = 3175 } service auth { client_limit = 3684 unix_listener auth-master { mode = 0600 } } service imap-login { process_limit = 1536 process_min_avail = 25 service_count = 1 } service imap-postlogin { executable = script-login rawlog /usr/local/etc/dovecot/lastauth-imap.sh user = vpopmail } service imap { executable = /usr/local/libexec/dovecot/imap imap-postlogin process_limit = 1536 } service pop-postlogin { executable = script-login /usr/local/etc/dovecot/lastauth-pop.sh user = vpopmail } service pop3-login { process_limit = 1536 process_min_avail = 15 service_count = 1 } service pop3 { executable = /usr/local/libexec/dovecot/pop3 pop-postlogin } service stats { fifo_listener stats-mail { mode = 0600 user = vpopmail } } shutdown_clients = no ssl_cert =

Show replies by date

Remko Lodder

15 Sep 15 Sep

7:06 p.m.

Hi,

...

Op 15 september 2015 om 14:52 schreef Rick Romero rick@havokmon.com:

Ok,

So this is really more of an observation than anything else.

I had a FreeBSD 10.1 server that was running great. Some SSL issue came up, or I upgrade Dovecot in ports - something occurred and the machine started rebooting randomly. It would run for 2 weeks, then reboot. It might run for 5 days and then reboot. So I started doing more FreeBSD upgrades, thinking it was a kernel issue. The reboots only increased.

This weekend I started thinking I might actually be having hardware issues. But, since I don't have easy physical access to the box and it's REALLY under loaded, I figured what the hell and upraded to 10.2 on Sunday. I think it rebooted 4 times after that on Sunday, and then another 2 times Monday morning.

Its worth noting that while I have crash dumps enabled, they don't seem to be occurring. So hardware is still a possibility.

Jumping in at some point here, as FreeBSD dev I run most of my servers on FreeBSD. All my mailservers are running FreeBSD. My customer backend servers run Dovecot on FreeBSD. we have a few hundred mailboxes (not that many). I upgrade all my packages and system whenever there are updates and I figured out whether they are OK or not. That means that I most likely do more upgrades then you do at the moment.

I never ever had the symptoms you describe nor did I need to tweak settings.

Given this is a "FreeBSD"box crashing I thought I should reply. I think you need to contact the FreeBSD devs (other then me) to ask what is going on. Perhaps you can do a backtrace on the dump to see what was going on. If you installed panicmail (a tool by Colin Percival) it will automatically create an informative email which describes the issue more or less ..

Please poke me offline when I can help you more with that.

Cheers Remko(@FreeBSD.org)

...

After the 2nd Monday morning reboot, I started to wonder if there was some sort of process issue. Besides the OS upgrades - I had been monitoring the Dovecot logs for when the process limits are reached, and increasing them. It's a 'big' box, and load is typically between .30 and .50. CPUs aren't overtaxed, and most of the memory is dedicated to ZFS. The reboots are so short, I've only received one 'down' alert due to them. So it's a conerning issue, but not really impacting production.

On a whim I changed my default_vsz_limit (as I had been increasing every other limit but that) from 384M to 512M. The system hasn't rebooted in 24hours.

Now that could be a coincidence, but I thought I'd at least put it out there.

If you see anything weird in my dovecot config, let me know - My config was originally vpopmail, but over time I've migrated to SQL-only.

root@romulus:/usr/local/etc/dovecot # dovecot -n # 2.2.18: /usr/local/etc/dovecot/dovecot.conf # OS: FreeBSD 10.2-RELEASE amd64 auth_master_user_separator = * auth_mechanisms = plain login auth_username_translation = %@ auth_verbose = yes default_login_user = dovecot default_vsz_limit = 512 M disable_plaintext_auth = no first_valid_gid = 89 first_valid_uid = 89 last_valid_gid = 89 last_valid_uid = 89 log_path = /dev/stderr login_greeting = Ready. login_trusted_networks = 172.16.100.0/24 mail_fsync = never mail_plugins = " quota zlib stats" mail_privileged_group = mail namespace compat { alias_for = hidden = yes inbox = no list = no location = prefix = INBOX. separator = . } namespace inbox { inbox = yes location = prefix = separator = . } passdb { args = /usr/local/etc/dovecot/dovecot-master-sql.conf driver = sql master = yes pass = yes } passdb { args = /usr/local/etc/dovecot/dovecot-sql.conf driver = sql } plugin { quota = maildir quota_rule = Trash:storage=+10%% stats_refresh = 30 secs stats_track_cmds = yes } protocols = imap pop3 service anvil { client_limit = 3175 } service auth { client_limit = 3684 unix_listener auth-master { mode = 0600 } } service imap-login { process_limit = 1536 process_min_avail = 25 service_count = 1 } service imap-postlogin { executable = script-login rawlog /usr/local/etc/dovecot/lastauth-imap.sh user = vpopmail } service imap { executable = /usr/local/libexec/dovecot/imap imap-postlogin process_limit = 1536 } service pop-postlogin { executable = script-login /usr/local/etc/dovecot/lastauth-pop.sh user = vpopmail } service pop3-login { process_limit = 1536 process_min_avail = 15 service_count = 1 } service pop3 { executable = /usr/local/libexec/dovecot/pop3 pop-postlogin } service stats { fifo_listener stats-mail { mode = 0600 user = vpopmail } } shutdown_clients = no ssl_cert =

Rick Romero

24 Sep 24 Sep

4:26 p.m.

Update. Only a single reboot has occurred since changing defalt_vsz_limit from 384M to 512M. It would seem that something the users are doing is causing that virtual memory size to be exceeded (possibly a mailbox search?), and when that occurs Dovecot/FreeBSD is not handling the event as smoothly as expected.

Here's my dmesg for more basic info. Sep 17 11:25:39 romulus syslogd: kernel boot file is /boot/kernel/kernel Sep 17 11:25:39 romulus kernel: Copyright (c) 1992-2015 The FreeBSD Project. Sep 17 11:25:39 romulus kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 Sep 17 11:25:39 romulus kernel: The Regents of the University of California. All rights reserved. Sep 17 11:25:39 romulus kernel: FreeBSD is a registered trademark of The FreeBSD Foundation. Sep 17 11:25:39 romulus kernel: FreeBSD 10.2-RELEASE #0 r286666: Wed Aug 12 15:26:37 UTC 2015 Sep 17 11:25:39 romulus kernel: root@releng1.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC amd64 Sep 17 11:25:39 romulus kernel: FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512 Sep 17 11:25:39 romulus kernel: CPU: Intel(R) Xeon(R) CPU E5462 @ 2.80GHz (2800.15-MHz K8-class CPU) Sep 17 11:25:39 romulus kernel: Origin="GenuineIntel" Id=0x1067a Family=0x6 Model=0x17 Stepping=10 Sep 17 11:25:39 romulus kernel: Features=0xbfebfbff Sep 17 11:25:39 romulus kernel: Features2=0xc0ce3bd Sep 17 11:25:39 romulus kernel: AMD Features=0x20100800 Sep 17 11:25:39 romulus kernel: AMD Features2=0x1<LAHF> Sep 17 11:25:39 romulus kernel: VT-x: (disabled in BIOS) HLT,PAUSE Sep 17 11:25:39 romulus kernel: TSC: P-state invariant, performance statistics Sep 17 11:25:39 romulus kernel: real memory = 34359738368 (32768 MB) Sep 17 11:25:39 romulus kernel: avail memory = 33300127744 (31757 MB) Sep 17 11:25:39 romulus kernel: Event timer "LAPIC" quality 400 Sep 17 11:25:39 romulus kernel: ACPI APIC Table: <PTLTD APIC > Sep 17 11:25:39 romulus kernel: FreeBSD/SMP: Multiprocessor System Detected: 8 CPUs Sep 17 11:25:39 romulus kernel: FreeBSD/SMP: 2 package(s) x 4 core(s) Sep 17 11:25:39 romulus kernel: cpu0 (BSP): APIC ID: 0 Sep 17 11:25:39 romulus kernel: cpu1 (AP): APIC ID: 1 Sep 17 11:25:39 romulus kernel: cpu2 (AP): APIC ID: 2 Sep 17 11:25:39 romulus kernel: cpu3 (AP): APIC ID: 3 Sep 17 11:25:39 romulus kernel: cpu4 (AP): APIC ID: 4 Sep 17 11:25:39 romulus kernel: cpu5 (AP): APIC ID: 5 Sep 17 11:25:39 romulus kernel: cpu6 (AP): APIC ID: 6 Sep 17 11:25:39 romulus kernel: cpu7 (AP): APIC ID: 7 Sep 17 11:25:39 romulus kernel: ioapic0 irqs 0-23 on motherboard Sep 17 11:25:39 romulus kernel: ioapic1 irqs 24-47 on motherboard Sep 17 11:25:39 romulus kernel: ioapic2 irqs 48-71 on motherboard Sep 17 11:25:39 romulus kernel: random: initialized Sep 17 11:25:39 romulus kernel: kbd1 at kbdmux0 Sep 17 11:25:39 romulus kernel: acpi0: <PTLTD XSDT> on motherboard Sep 17 11:25:39 romulus kernel: acpi0: Power Button (fixed) Sep 17 11:25:39 romulus kernel: unknown: I/O range not supported Sep 17 11:25:39 romulus kernel: cpu0: <ACPI CPU> on acpi0 Sep 17 11:25:39 romulus kernel: cpu1: <ACPI CPU> on acpi0 Sep 17 11:25:39 romulus kernel: cpu2: <ACPI CPU> on acpi0 Sep 17 11:25:39 romulus kernel: cpu3: <ACPI CPU> on acpi0 Sep 17 11:25:39 romulus kernel: cpu4: <ACPI CPU> on acpi0 Sep 17 11:25:39 romulus kernel: cpu5: <ACPI CPU> on acpi0 Sep 17 11:25:39 romulus kernel: cpu6: <ACPI CPU> on acpi0 Sep 17 11:25:39 romulus kernel: cpu7: <ACPI CPU> on acpi0 Sep 17 11:25:39 romulus kernel: hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff irq 0,8 on acpi0 Sep 17 11:25:39 romulus kernel: Timecounter "HPET" frequency 14318180 Hz quality 950 Sep 17 11:25:39 romulus kernel: Event timer "HPET" frequency 14318180 Hz quality 350 Sep 17 11:25:39 romulus kernel: Event timer "HPET1" frequency 14318180 Hz quality 340 Sep 17 11:25:39 romulus kernel: Event timer "HPET2" frequency 14318180 Hz quality 340 Sep 17 11:25:39 romulus kernel: atrtc0: <AT realtime clock> port 0x70-0x71 on acpi0 Sep 17 11:25:39 romulus kernel: Event timer "RTC" frequency 32768 Hz quality 0 Sep 17 11:25:39 romulus kernel: attimer0: <AT timer> port 0x40-0x43,0x50-0x53 on acpi0 Sep 17 11:25:39 romulus kernel: Timecounter "i8254" frequency 1193182 Hz quality 0 Sep 17 11:25:39 romulus kernel: Event timer "i8254" frequency 1193182 Hz quality 100 Sep 17 11:25:39 romulus kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 900 Sep 17 11:25:39 romulus kernel: acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0 Sep 17 11:25:39 romulus kernel: pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0 Sep 17 11:25:39 romulus kernel: pci0: <ACPI PCI bus> on pcib0 Sep 17 11:25:39 romulus kernel: pcib1: <ACPI PCI-PCI bridge> irq 48 at device 1.0 on pci0 Sep 17 11:25:39 romulus kernel: pci1: <ACPI PCI bus> on pcib1 Sep 17 11:25:39 romulus kernel: mps0: port 0x2000-0x20ff mem 0xd8240000-0xd824ffff,0xd8200000-0xd823ffff irq 48 at device 0.0 on pci1 Sep 17 11:25:39 romulus kernel: mps0: Firmware: 19.00.00.00, Driver: 20.00.00.00-fbsd Sep 17 11:25:39 romulus kernel: mps0: IOCCapabilities: 5285c Sep 17 11:25:39 romulus kernel: pcib2: <ACPI PCI-PCI bridge> irq 50 at device 3.0 on pci0 Sep 17 11:25:39 romulus kernel: pci2: <ACPI PCI bus> on pcib2 Sep 17 11:25:39 romulus kernel: pcib3: <ACPI PCI-PCI bridge> irq 52 at device 5.0 on pci0 Sep 17 11:25:39 romulus kernel: pci3: <ACPI PCI bus> on pcib3 Sep 17 11:25:39 romulus kernel: pcib4: <ACPI PCI-PCI bridge> irq 54 at device 7.0 on pci0 Sep 17 11:25:39 romulus kernel: pci4: <ACPI PCI bus> on pcib4 Sep 17 11:25:39 romulus kernel: pcib5: <ACPI PCI-PCI bridge> irq 54 at device 0.0 on pci4 Sep 17 11:25:39 romulus kernel: pci5: <ACPI PCI bus> on pcib5 Sep 17 11:25:39 romulus kernel: pcib6: <ACPI PCI-PCI bridge> irq 54 at device 0.0 on pci5 Sep 17 11:25:39 romulus kernel: pci6: <ACPI PCI bus> on pcib6 Sep 17 11:25:39 romulus kernel: mfi0: port 0x3000-0x30ff mem 0xd8440000-0xd847ffff,0xd8400000-0xd843ffff irq 54 at device 0.0 on pci6 Sep 17 11:25:39 romulus kernel: mfi0: Using MSI Sep 17 11:25:39 romulus kernel: mfi0: Megaraid SAS driver Ver 4.23 Sep 17 11:25:39 romulus kernel: mfi0: FW MaxCmds = 1008, limiting to 128 Sep 17 11:25:39 romulus kernel: pcib7: <ACPI PCI-PCI bridge> at device 0.3 on pci4 Sep 17 11:25:39 romulus kernel: pci7: <ACPI PCI bus> on pcib7 Sep 17 11:25:39 romulus kernel: pcib8: <ACPI PCI-PCI bridge> irq 56 at device 9.0 on pci0 Sep 17 11:25:39 romulus kernel: pci8: <ACPI PCI bus> on pcib8 Sep 17 11:25:39 romulus kernel: igb0: port 0x4000-0x401f mem 0xd8540000-0xd855ffff,0xd8520000-0xd853ffff,0xd8500000-0xd8503fff irq 56 at device 0.0 on pci8 Sep 17 11:25:39 romulus kernel: igb0: Using MSIX interrupts with 5 vectors Sep 17 11:25:39 romulus kernel: igb0: Ethernet address: 00:30:48:ca:21:f6 Sep 17 11:25:39 romulus kernel: igb0: Bound queue 0 to cpu 0 Sep 17 11:25:39 romulus kernel: igb0: Bound queue 1 to cpu 1 Sep 17 11:25:39 romulus kernel: igb0: Bound queue 2 to cpu 2 Sep 17 11:25:39 romulus kernel: igb0: Bound queue 3 to cpu 3 Sep 17 11:25:39 romulus kernel: igb1: port 0x4020-0x403f mem 0xd8580000-0xd859ffff,0xd8560000-0xd857ffff,0xd8504000-0xd8507fff irq 70 at device 0.1 on pci8 Sep 17 11:25:39 romulus kernel: igb1: Using MSIX interrupts with 5 vectors Sep 17 11:25:39 romulus kernel: igb1: Ethernet address: 00:30:48:ca:21:f7 Sep 17 11:25:39 romulus kernel: igb1: Bound queue 0 to cpu 4 Sep 17 11:25:39 romulus kernel: igb1: Bound queue 1 to cpu 5 Sep 17 11:25:39 romulus kernel: igb1: Bound queue 2 to cpu 6 Sep 17 11:25:39 romulus kernel: igb1: Bound queue 3 to cpu 7 Sep 17 11:25:39 romulus kernel: pcib9: <ACPI PCI-PCI bridge> irq 16 at device 28.0 on pci0 Sep 17 11:25:39 romulus kernel: pci9: <ACPI PCI bus> on pcib9 Sep 17 11:25:39 romulus kernel: uhci0: port 0x1800-0x181f irq 20 at device 29.0 on pci0 Sep 17 11:25:39 romulus kernel: usbus0 on uhci0 Sep 17 11:25:39 romulus kernel: uhci1: port 0x1820-0x183f irq 21 at device 29.1 on pci0 Sep 17 11:25:39 romulus kernel: usbus1 on uhci1 Sep 17 11:25:39 romulus kernel: uhci2: port 0x1840-0x185f irq 22 at device 29.2 on pci0 Sep 17 11:25:39 romulus kernel: usbus2 on uhci2 Sep 17 11:25:39 romulus kernel: ehci0: mem 0xd8704000-0xd87043ff irq 23 at device 29.7 on pci0 Sep 17 11:25:39 romulus kernel: usbus3: EHCI version 1.0 Sep 17 11:25:39 romulus kernel: usbus3 on ehci0 Sep 17 11:25:39 romulus kernel: pcib10: <ACPI PCI-PCI bridge> at device 30.0 on pci0 Sep 17 11:25:39 romulus kernel: pci10: <ACPI PCI bus> on pcib10 Sep 17 11:25:39 romulus kernel: vgapci0: <VGA-compatible display> port 0x5000-0x50ff mem 0xd0000000-0xd7ffffff,0xd8600000-0xd860ffff irq 18 at device 1.0 on pci10 Sep 17 11:25:39 romulus kernel: vgapci0: Boot video device Sep 17 11:25:39 romulus kernel: isab0: <PCI-ISA bridge> at device 31.0 on pci0 Sep 17 11:25:39 romulus kernel: isa0: <ISA bus> on isab0 Sep 17 11:25:39 romulus kernel: atapci0: port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x1860-0x186f at device 31.2 on pci0 Sep 17 11:25:39 romulus kernel: ata0: <ATA channel> at channel 0 on atapci0 Sep 17 11:25:39 romulus kernel: ata1: <ATA channel> at channel 1 on atapci0 Sep 17 11:25:39 romulus kernel: acpi_button0: <Power Button> on acpi0 Sep 17 11:25:39 romulus kernel: atkbdc0: port 0x60,0x64 irq 1 on acpi0 Sep 17 11:25:39 romulus kernel: atkbd0: <AT Keyboard> irq 1 on atkbdc0 Sep 17 11:25:39 romulus kernel: kbd0 at atkbd0 Sep 17 11:25:39 romulus kernel: atkbd0: [GIANT-LOCKED] Sep 17 11:25:39 romulus kernel: uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 Sep 17 11:25:39 romulus kernel: uart1: <16550 or compatible> port 0x2f8-0x2ff irq 3 on acpi0 Sep 17 11:25:39 romulus kernel: fdc0: <floppy drive controller> port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0 Sep 17 11:25:39 romulus kernel: orm0: <ISA Option ROM> at iomem 0xc0000-0xcafff on isa0 Sep 17 11:25:39 romulus kernel: sc0: <System console> at flags 0x100 on isa0 Sep 17 11:25:39 romulus kernel: sc0: VGA <16 virtual consoles, flags=0x300> Sep 17 11:25:39 romulus kernel: vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 Sep 17 11:25:39 romulus kernel: ppc0: cannot reserve I/O port range Sep 17 11:25:39 romulus kernel: est0: <Enhanced SpeedStep Frequency Control> on cpu0 Sep 17 11:25:39 romulus kernel: est: CPU supports Enhanced Speedstep, but is not recognized. Sep 17 11:25:39 romulus kernel: est: cpu_vendor GenuineIntel, msr 719071906000719 Sep 17 11:25:39 romulus kernel: device_attach: est0 attach returned 6 Sep 17 11:25:39 romulus kernel: est1: <Enhanced SpeedStep Frequency Control> on cpu1 Sep 17 11:25:39 romulus kernel: est: CPU supports Enhanced Speedstep, but is not recognized. Sep 17 11:25:39 romulus kernel: est: cpu_vendor GenuineIntel, msr 719071906000719 Sep 17 11:25:39 romulus kernel: device_attach: est1 attach returned 6 Sep 17 11:25:39 romulus kernel: est2: <Enhanced SpeedStep Frequency Control> on cpu2 Sep 17 11:25:39 romulus kernel: est: CPU supports Enhanced Speedstep, but is not recognized. Sep 17 11:25:39 romulus kernel: est: cpu_vendor GenuineIntel, msr 719071906000719 Sep 17 11:25:39 romulus kernel: device_attach: est2 attach returned 6 Sep 17 11:25:39 romulus kernel: est3: <Enhanced SpeedStep Frequency Control> on cpu3 Sep 17 11:25:39 romulus kernel: est: CPU supports Enhanced Speedstep, but is not recognized. Sep 17 11:25:39 romulus kernel: est: cpu_vendor GenuineIntel, msr 719071906000719 Sep 17 11:25:39 romulus kernel: device_attach: est3 attach returned 6 Sep 17 11:25:39 romulus kernel: est4: <Enhanced SpeedStep Frequency Control> on cpu4 Sep 17 11:25:39 romulus kernel: est: CPU supports Enhanced Speedstep, but is not recognized. Sep 17 11:25:39 romulus kernel: est: cpu_vendor GenuineIntel, msr 719071906000719 Sep 17 11:25:39 romulus kernel: device_attach: est4 attach returned 6 Sep 17 11:25:39 romulus kernel: est5: <Enhanced SpeedStep Frequency Control> on cpu5 Sep 17 11:25:39 romulus kernel: est: CPU supports Enhanced Speedstep, but is not recognized. Sep 17 11:25:39 romulus kernel: est: cpu_vendor GenuineIntel, msr 719071906000719 Sep 17 11:25:39 romulus kernel: device_attach: est5 attach returned 6 Sep 17 11:25:39 romulus kernel: est6: <Enhanced SpeedStep Frequency Control> on cpu6 Sep 17 11:25:39 romulus kernel: est: CPU supports Enhanced Speedstep, but is not recognized. Sep 17 11:25:39 romulus kernel: est: cpu_vendor GenuineIntel, msr 719071906000719 Sep 17 11:25:39 romulus kernel: device_attach: est6 attach returned 6 Sep 17 11:25:39 romulus kernel: est7: <Enhanced SpeedStep Frequency Control> on cpu7 Sep 17 11:25:39 romulus kernel: est: CPU supports Enhanced Speedstep, but is not recognized. Sep 17 11:25:39 romulus kernel: est: cpu_vendor GenuineIntel, msr 719071906000719 Sep 17 11:25:39 romulus kernel: device_attach: est7 attach returned 6 Sep 17 11:25:39 romulus kernel: mfi0: 200232 (495457679s/0x0020/info) - Shutdown command received from host Sep 17 11:25:39 romulus kernel: mfi0: 200233 (boot + 3s/0x0020/info) - Firmware initialization started (PCI ID 0060/1000/1006/1000) Sep 17 11:25:39 romulus kernel: mfi0: 200234 (boot + 3s/0x0020/info) - Firmware version 1.40.342-1650 Sep 17 11:25:39 romulus kernel: mfi0: 200235 (boot + 4s/0x0008/info) - Battery Present Sep 17 11:25:39 romulus kernel: mfi0: 200236 (boot + 5s/0x0020/info) - Board Revision Sep 17 11:25:39 romulus kernel: mfi0: 200237 (boot + 31s/0x0010/info) - Connector External B Port (loc=3 sasMux=0x0) is active Sep 17 11:25:39 romulus kernel: mfi0: 200238 (boot + 31s/0x0010/info) - Connector Int.Ports 4-7 (loc=2 sasMux=0x1) is active Sep 17 11:25:39 romulus kernel: mfi0: 200239 (boot + 31s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Sep 17 11:25:39 romulus kernel: mfi0: 200240 (boot + 31s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Info: enclPd=ffff, scsiType=0, portMap=04, sasAddr=2e327a7b9c92a5a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200241 (boot + 31s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Sep 17 11:25:39 romulus kernel: mfi0: 200242 (boot + 31s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Info: enclPd=ffff, scsiType=0, portMap=05, sasAddr=2c41917f8d8c88a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200243 (boot + 31s/0x0002/info) - Inserted: PD 20(e0xff/s32) Sep 17 11:25:39 romulus kernel: mfi0: 200244 (boot + 31s/0x0002/info) - Inserted: PD 20(e0xff/s32) Info: enclPd=ffff, scsiType=0, portMap=06, sasAddr=db373556649cb3bd,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200245 (boot + 31s/0x0002/info) - Inserted: PD 21(e0xff/s33) Sep 17 11:25:39 romulus kernel: mfi0: 200246 (boot + 31s/0x0002/info) - Inserted: PD 21(e0xff/s33) Info: enclPd=ffff, scsiType=0, portMap=07, sasAddr=db37355566a2b2b9,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200247 (495457736s/0x0020/info) - Time established as 09/13/15 11:08:56; (51 seconds since power on) Sep 17 11:25:39 romulus kernel: mfi0: 200248 (495457771s/0x0008/info) - Battery temperature is normal Sep 17 11:25:39 romulus kernel: mfi0: 200249 (495457771s/0x0008/info) - Battery relearn will start in 4 days Sep 17 11:25:39 romulus kernel: mfi0: 200250 (boot + 3s/0x0020/info) - Firmware initialization started (PCI ID 0060/1000/1006/1000) Sep 17 11:25:39 romulus kernel: mfi0: 200251 (boot + 3s/0x0020/info) - Firmware version 1.40.342-1650 Sep 17 11:25:39 romulus kernel: mfi0: 200252 (boot + 4s/0x0008/info) - Battery Present Sep 17 11:25:39 romulus kernel: mfi0: 200253 (boot + 5s/0x0020/info) - Board Revision Sep 17 11:25:39 romulus kernel: mfi0: 200254 (boot + 33s/0x0010/info) - Connector External B Port (loc=3 sasMux=0x0) is active Sep 17 11:25:39 romulus kernel: mfi0: 200255 (boot + 33s/0x0010/info) - Connector Int.Ports 4-7 (loc=2 sasMux=0x1) is active Sep 17 11:25:39 romulus kernel: mfi0: 200256 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Sep 17 11:25:39 romulus kernel: mfi0: 200257 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Info: enclPd=ffff, scsiType=0, portMap=04, sasAddr=2e327a7b9c92a5a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200258 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Sep 17 11:25:39 romulus kernel: mfi0: 200259 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Info: enclPd=ffff, scsiType=0, portMap=05, sasAddr=2c41917f8d8c88a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200260 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Sep 17 11:25:39 romulus kernel: mfi0: 200261 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Info: enclPd=ffff, scsiType=0, portMap=06, sasAddr=db373556649cb3bd,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200262 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Sep 17 11:25:39 romulus kernel: mfi0: 200263 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Info: enclPd=ffff, scsiType=0, portMap=07, sasAddr=db37355566a2b2b9,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200264 (495467062s/0x0020/info) - Time established as 09/13/15 13:44:22; (51 seconds since power on) Sep 17 11:25:39 romulus kernel: mfi0: 200265 (495467099s/0x0008/info) - Battery temperature is normal Sep 17 11:25:39 romulus kernel: mfi0: 200266 (495467099s/0x0008/info) - Battery relearn will start in 4 days Sep 17 11:25:39 romulus kernel: mfi0: 200267 (495525274s/0x0008/info) - Battery started charging Sep 17 11:25:39 romulus kernel: mfi0: 200268 (boot + 3s/0x0020/info) - Firmware initialization started (PCI ID 0060/1000/1006/1000) Sep 17 11:25:39 romulus kernel: mfi0: 200269 (boot + 3s/0x0020/info) - Firmware version 1.40.342-1650 Sep 17 11:25:39 romulus kernel: mfi0: 200270 (boot + 4s/0x0008/info) - Battery Present Sep 17 11:25:39 romulus kernel: mfi0: 200271 (boot + 5s/0x0020/info) - Board Revision Sep 17 11:25:39 romulus kernel: mfi0: 200272 (boot + 33s/0x0010/info) - Connector External B Port (loc=3 sasMux=0x0) is active Sep 17 11:25:39 romulus kernel: mfi0: 200273 (boot + 33s/0x0010/info) - Connector Int.Ports 4-7 (loc=2 sasMux=0x1) is active Sep 17 11:25:39 romulus kernel: mfi0: 200274 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Sep 17 11:25:39 romulus kernel: mfi0: 200275 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Info: enclPd=ffff, scsiType=0, portMap=04, sasAddr=2e327a7b9c92a5a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200276 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Sep 17 11:25:39 romulus kernel: mfi0: 200277 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Info: enclPd=ffff, scsiType=0, portMap=05, sasAddr=2c41917f8d8c88a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200278 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Sep 17 11:25:39 romulus kernel: mfi0: 200279 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Info: enclPd=ffff, scsiType=0, portMap=06, sasAddr=db373556649cb3bd,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200280 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Sep 17 11:25:39 romulus kernel: mfi0: 200281 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Info: enclPd=ffff, scsiType=0, portMap=07, sasAddr=db37355566a2b2b9,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200282 (boot + 43s/0x0020/info) - Cache data recovered successfully Sep 17 11:25:39 romulus kernel: mfi0: 200283 (495526581s/0x0020/info) - Time established as 09/14/15 6:16:21; (49 seconds since power on) Sep 17 11:25:39 romulus kernel: mfi0: 200284 (495526620s/0x0008/info) - Battery started charging Sep 17 11:25:39 romulus kernel: mfi0: 200285 (495526620s/0x0008/info) - Battery temperature is normal Sep 17 11:25:39 romulus kernel: mfi0: 200286 (495526620s/0x0008/info) - Battery relearn will start in 4 days Sep 17 11:25:39 romulus kernel: mfi0: 200287 (495526685s/0x0008/info) - Battery charge complete Sep 17 11:25:39 romulus kernel: mfi0: 200288 (boot + 3s/0x0020/info) - Firmware initialization started (PCI ID 0060/1000/1006/1000) Sep 17 11:25:39 romulus kernel: mfi0: 200289 (boot + 3s/0x0020/info) - Firmware version 1.40.342-1650 Sep 17 11:25:39 romulus kernel: mfi0: 200290 (boot + 4s/0x0008/info) - Battery Present Sep 17 11:25:39 romulus kernel: mfi0: 200291 (boot + 5s/0x0020/info) - Board Revision Sep 17 11:25:39 romulus kernel: mfi0: 200292 (boot + 33s/0x0010/info) - Connector External B Port (loc=3 sasMux=0x0) is active Sep 17 11:25:39 romulus kernel: mfi0: 200293 (boot + 33s/0x0010/info) - Connector Int.Ports 4-7 (loc=2 sasMux=0x1) is active Sep 17 11:25:39 romulus kernel: mfi0: 200294 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Sep 17 11:25:39 romulus kernel: mfi0: 200295 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Info: enclPd=ffff, scsiType=0, portMap=04, sasAddr=2e327a7b9c92a5a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200296 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Sep 17 11:25:39 romulus kernel: mfi0: 200297 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Info: enclPd=ffff, scsiType=0, portMap=05, sasAddr=2c41917f8d8c88a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200298 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Sep 17 11:25:39 romulus kernel: mfi0: 200299 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Info: enclPd=ffff, scsiType=0, portMap=06, sasAddr=db373556649cb3bd,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200300 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Sep 17 11:25:39 romulus kernel: mfi0: 200301 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Info: enclPd=ffff, scsiType=0, portMap=07, sasAddr=db37355566a2b2b9,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200302 (495527955s/0x0020/info) - Time established as 09/14/15 6:39:15; (51 seconds since power on) Sep 17 11:25:39 romulus kernel: mfi0: 200303 (495527992s/0x0008/info) - Battery temperature is normal Sep 17 11:25:39 romulus kernel: mfi0: 200304 (495527992s/0x0008/info) - Battery relearn will start in 4 days Sep 17 11:25:39 romulus kernel: mfi0: 200305 (boot + 3s/0x0020/info) - Firmware initialization started (PCI ID 0060/1000/1006/1000) Sep 17 11:25:39 romulus kernel: mfi0: 200306 (boot + 3s/0x0020/info) - Firmware version 1.40.342-1650 Sep 17 11:25:39 romulus kernel: mfi0: 200307 (boot + 4s/0x0008/info) - Battery Present Sep 17 11:25:39 romulus kernel: mfi0: 200308 (boot + 5s/0x0020/info) - Board Revision Sep 17 11:25:39 romulus kernel: mfi0: 200309 (boot + 33s/0x0010/info) - Connector External B Port (loc=3 sasMux=0x0) is active Sep 17 11:25:39 romulus kernel: mfi0: 200310 (boot + 33s/0x0010/info) - Connector Int.Ports 4-7 (loc=2 sasMux=0x1) is active Sep 17 11:25:39 romulus kernel: mfi0: 200311 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Sep 17 11:25:39 romulus kernel: mfi0: 200312 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Info: enclPd=ffff, scsiType=0, portMap=04, sasAddr=2e327a7b9c92a5a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200313 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Sep 17 11:25:39 romulus kernel: mfi0: 200314 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Info: enclPd=ffff, scsiType=0, portMap=05, sasAddr=2c41917f8d8c88a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200315 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Sep 17 11:25:39 romulus kernel: mfi0: 200316 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Info: enclPd=ffff, scsiType=0, portMap=06, sasAddr=db373556649cb3bd,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200317 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Sep 17 11:25:39 romulus kernel: mfi0: 200318 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Info: enclPd=ffff, scsiType=0, portMap=07, sasAddr=db37355566a2b2b9,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200319 (boot + 43s/0x0020/info) - Cache data recovered successfully Sep 17 11:25:39 romulus kernel: mfi0: 200320 (495531691s/0x0020/info) - Time established as 09/14/15 7:41:31; (49 seconds since power on) Sep 17 11:25:39 romulus kernel: mfi0: 200321 (495531730s/0x0008/info) - Battery temperature is normal Sep 17 11:25:39 romulus kernel: mfi0: 200322 (495531730s/0x0008/info) - Battery relearn will start in 4 days Sep 17 11:25:39 romulus kernel: mfi0: 200323 (boot + 3s/0x0020/info) - Firmware initialization started (PCI ID 0060/1000/1006/1000) Sep 17 11:25:39 romulus kernel: mfi0: 200324 (boot + 3s/0x0020/info) - Firmware version 1.40.342-1650 Sep 17 11:25:39 romulus kernel: mfi0: 200325 (boot + 4s/0x0008/info) - Battery Present Sep 17 11:25:39 romulus kernel: mfi0: 200326 (boot + 5s/0x0020/info) - Board Revision Sep 17 11:25:39 romulus kernel: mfi0: 200327 (boot + 33s/0x0010/info) - Connector External B Port (loc=3 sasMux=0x0) is active Sep 17 11:25:39 romulus kernel: mfi0: 200328 (boot + 33s/0x0010/info) - Connector Int.Ports 4-7 (loc=2 sasMux=0x1) is active Sep 17 11:25:39 romulus kernel: mfi0: 200329 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Sep 17 11:25:39 romulus kernel: mfi0: 200330 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Info: enclPd=ffff, scsiType=0, portMap=04, sasAddr=2e327a7b9c92a5a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200331 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Sep 17 11:25:39 romulus kernel: mfi0: 200332 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Info: enclPd=ffff, scsiType=0, portMap=05, sasAddr=2c41917f8d8c88a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200333 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Sep 17 11:25:39 romulus kernel: mfi0: 200334 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Info: enclPd=ffff, scsiType=0, portMap=06, sasAddr=db373556649cb3bd,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200335 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Sep 17 11:25:39 romulus kernel: mfi0: 200336 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Info: enclPd=ffff, scsiType=0, portMap=07, sasAddr=db37355566a2b2b9,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200337 (boot + 44s/0x0020/info) - Cache data recovered successfully Sep 17 11:25:39 romulus kernel: mfi0: 200338 (495539802s/0x0020/info) - Time established as 09/14/15 9:56:42; (50 seconds since power on) Sep 17 11:25:39 romulus kernel: mfi0: 200339 (495539840s/0x0008/info) - Battery temperature is normal Sep 17 11:25:39 romulus kernel: mfi0: 200340 (495539840s/0x0008/info) - Battery relearn will start in 4 days Sep 17 11:25:39 romulus kernel: mfi0: 200341 (495614135s/0x0008/info) - Battery relearn will start in 2 day Sep 17 11:25:39 romulus kernel: mfi0: 200342 (495700520s/0x0008/info) - Battery relearn will start in 1 day Sep 17 11:25:39 romulus kernel: mfi0: 200343 (495763895s/0x0008/info) - Battery started charging Sep 17 11:25:39 romulus kernel: mfi0: 200344 (495765390s/0x0008/info) - Battery charge complete Sep 17 11:25:39 romulus kernel: mfi0: 200345 (495768900s/0x0008/info) - Battery relearn will start in 5 hours Sep 17 11:25:39 romulus kernel: mfi0: 200346 (495786970s/0x0008/info) - Battery relearn pending: Battery is under charge Sep 17 11:25:39 romulus kernel: mfi0: 200347 (495786970s/0x0008/info) - Battery relearn started Sep 17 11:25:39 romulus kernel: mfi0: 200348 (495786970s/0x0008/WARN) - BBU disabled; changing WB virtual disks to WT, Forced WB VDs are not affected Sep 17 11:25:39 romulus kernel: mfi0: 200349 (495786970s/0x0001/info) - Policy change on VD 00/0 to [ID=00,dcp=01,ccp=00,ap=0,dc=2,dbgi=0] from [ID=00,dcp=01,ccp=01,ap=0,dc=2,dbgi=0] Sep 17 11:25:39 romulus kernel: mfi0: 200350 (495786970s/0x0001/info) - Policy change on VD 01/1 to [ID=01,dcp=01,ccp=00,ap=0,dc=1,dbgi=0] from [ID=01,dcp=01,ccp=01,ap=0,dc=1,dbgi=0] Sep 17 11:25:39 romulus kernel: mfi0: 200351 (495787035s/0x0008/info) - Battery is discharging Sep 17 11:25:39 romulus kernel: mfi0: 200352 (495787035s/0x0008/info) - Battery relearn in progress Sep 17 11:25:39 romulus kernel: mfi0: 200353 (495794965s/0x0008/info) - Battery relearn completed Sep 17 11:25:39 romulus kernel: mfi0: 200354 (495795030s/0x0008/info) - Battery started charging Sep 17 11:25:39 romulus kernel: mfi0: 200355 (boot + 3s/0x0020/info) - Firmware initialization started (PCI ID 0060/1000/1006/1000) Sep 17 11:25:39 romulus kernel: mfi0: 200356 (boot + 3s/0x0020/info) - Firmware version 1.40.342-1650 Sep 17 11:25:39 romulus kernel: mfi0: 200357 (boot + 4s/0x0008/info) - Battery Present Sep 17 11:25:39 romulus kernel: mfi0: 200358 (boot + 5s/0x0020/info) - Board Revision Sep 17 11:25:39 romulus kernel: mfi0: 200359 (boot + 33s/0x0010/info) - Connector External B Port (loc=3 sasMux=0x0) is active Sep 17 11:25:39 romulus kernel: mfi0: 200360 (boot + 33s/0x0010/info) - Connector Int.Ports 4-7 (loc=2 sasMux=0x1) is active Sep 17 11:25:39 romulus kernel: mfi0: 200361 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Sep 17 11:25:39 romulus kernel: mfi0: 200362 (boot + 33s/0x0002/info) - Inserted: PD 1e(e0xff/s30) Info: enclPd=ffff, scsiType=0, portMap=04, sasAddr=2e327a7b9c92a5a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200363 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Sep 17 11:25:39 romulus kernel: mfi0: 200364 (boot + 33s/0x0002/info) - Inserted: PD 1f(e0xff/s31) Info: enclPd=ffff, scsiType=0, portMap=05, sasAddr=2c41917f8d8c88a2,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200365 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Sep 17 11:25:39 romulus kernel: mfi0: 200366 (boot + 33s/0x0002/info) - Inserted: PD 20(e0xff/s32) Info: enclPd=ffff, scsiType=0, portMap=06, sasAddr=db373556649cb3bd,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200367 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Sep 17 11:25:39 romulus kernel: mfi0: 200368 (boot + 33s/0x0002/info) - Inserted: PD 21(e0xff/s33) Info: enclPd=ffff, scsiType=0, portMap=07, sasAddr=db37355566a2b2b9,0000000000000000 Sep 17 11:25:39 romulus kernel: mfi0: 200369 (495804262s/0x0020/info) - Time established as 09/17/15 11:24:22; (51 seconds since power on) Sep 17 11:25:39 romulus kernel: mfi0: 200370 (495804299s/0x0008/info) - Battery started charging Sep 17 11:25:39 romulus kernel: mfi0: 200371 (495804299s/0x0008/info) - Battery temperature is normal Sep 17 11:25:39 romulus kernel: mfi0: 200372 (495804299s/0x0008/WARN) - BBU disabled; changing WB virtual disks to WT, Forced WB VDs are not affected Sep 17 11:25:39 romulus kernel: mfi0: 200373 (495804299s/0x0001/info) - Policy change on VD 00/0 to [ID=00,dcp=01,ccp=00,ap=0,dc=2,dbgi=0] from [ID=00,dcp=01,ccp=01,ap=0,dc=2,dbgi=0] Sep 17 11:25:39 romulus kernel: mfi0: 200374 (495804299s/0x0001/info) - Policy change on VD 01/1 to [ID=01,dcp=01,ccp=00,ap=0,dc=1,dbgi=0] from [ID=01,dcp=01,ccp=01,ap=0,dc=1,dbgi=0] Sep 17 11:25:39 romulus kernel: random: unblocking device. Sep 17 11:25:39 romulus kernel: usbus0: 12Mbps Full Speed USB v1.0 Sep 17 11:25:39 romulus kernel: Timecounters tick every 1.000 msec Sep 17 11:25:39 romulus kernel: usbus1: 12Mbps Full Speed USB v1.0 Sep 17 11:25:39 romulus kernel: usbus2: 12Mbps Full Speed USB v1.0 Sep 17 11:25:39 romulus kernel: usbus3: 480Mbps High Speed USB v2.0 Sep 17 11:25:39 romulus kernel: ugen1.1: <Intel> at usbus1 Sep 17 11:25:39 romulus kernel: uhub0: on usbus1 Sep 17 11:25:39 romulus kernel: ugen0.1: <Intel> at usbus0 Sep 17 11:25:39 romulus kernel: uhub1: on usbus0 Sep 17 11:25:39 romulus kernel: ugen3.1: <Intel> at usbus3 Sep 17 11:25:39 romulus kernel: uhub2: on usbus3 Sep 17 11:25:39 romulus kernel: ugen2.1: <Intel> at usbus2 Sep 17 11:25:39 romulus kernel: uhub3: on usbus2 Sep 17 11:25:39 romulus kernel: mfid0 on mfi0 Sep 17 11:25:39 romulus kernel: mfid0: 475136MB (973078528 sectors) RAID volume (no label) is optimal Sep 17 11:25:39 romulus kernel: mfid1 on mfi0 Sep 17 11:25:39 romulus kernel: mfid1: 59392MB (121634816 sectors) RAID volume (no label) is optimal Sep 17 11:25:39 romulus kernel: uhub0: 2 ports with 2 removable, self powered Sep 17 11:25:39 romulus kernel: uhub1: 2 ports with 2 removable, self powered Sep 17 11:25:39 romulus kernel: uhub3: 2 ports with 2 removable, self powered Sep 17 11:25:39 romulus kernel: mps0: SAS Address for SATA device = 6f8376497abfc6b5 Sep 17 11:25:39 romulus kernel: mps0: SAS Address for SATA device = 6f8376567bc1d3c3 Sep 17 11:25:39 romulus kernel: mps0: SAS Address for SATA device = 6f8376528dc0d1c0 Sep 17 11:25:39 romulus kernel: mps0: SAS Address from SATA device = 6f8376497abfc6b5 Sep 17 11:25:39 romulus kernel: mps0: SAS Address from SATA device = 6f8376567bc1d3c3 Sep 17 11:25:39 romulus kernel: mps0: SAS Address from SATA device = 6f8376528dc0d1c0 Sep 17 11:25:39 romulus kernel: da0 at mps0 bus 0 scbus0 target 0 lun 0 Sep 17 11:25:39 romulus kernel: da1 at mps0 bus 0 scbus0 target 1 lun 0 Sep 17 11:25:39 romulus kernel: da1: <ATA Crucial_CT512MX1 MU02> Fixed Direct Access SPC-4 SCSI device Sep 17 11:25:39 romulus kernel: da0: <ATA Crucial_CT512MX1 MU02> Fixed Direct Access SPC-4 SCSI device Sep 17 11:25:39 romulus kernel: da0: Serial Number 14170C183476 Sep 17 11:25:39 romulus kernel: da0: 600.000MB/s transfers Sep 17 11:25:39 romulus kernel: da0: Command Queueing enabled Sep 17 11:25:39 romulus kernel: da0: 488386MB (1000215216 512 byte sectors: 255H 63S/T 62260C) Sep 17 11:25:39 romulus kernel: da2 at mps0 bus 0 scbus0 target 2 lun 0 Sep 17 11:25:39 romulus kernel: da1: Serial Number 14080C1E46EC Sep 17 11:25:39 romulus kernel: da1: 600.000MB/s transfers Sep 17 11:25:39 romulus kernel: da1: Command Queueing enabled Sep 17 11:25:39 romulus kernel: da1: 488386MB (1000215216 512 byte sectors: 255H 63S/T 62260C) Sep 17 11:25:39 romulus kernel: da2: <ATA Crucial_CT512MX1 MU02> Fixed Direct Access SPC-4 SCSI device Sep 17 11:25:39 romulus kernel: da2: Serial Number 14170C1AF5BA Sep 17 11:25:39 romulus kernel: da2: 600.000MB/s transfers Sep 17 11:25:39 romulus kernel: da2: Command Queueing enabled Sep 17 11:25:39 romulus kernel: da2: 488386MB (1000215216 512 byte sectors: 255H 63S/T 62260C) Sep 17 11:25:39 romulus kernel: ada0 at ata0 bus 0 scbus1 target 0 lun 0 Sep 17 11:25:39 romulus kernel: ada0: <TS32GSSD370 N1114B> ACS-2 ATA SATA 3.x device Sep 17 11:25:39 romulus kernel: ada0: Serial Number B976030532 Sep 17 11:25:39 romulus kernel: ada0: 150.000MB/s transfers (SATA, UDMA5, PIO 1024bytes) Sep 17 11:25:39 romulus kernel: ada0: 30533MB (62533296 512 byte sectors: 16H 63S/T 16383C) Sep 17 11:25:39 romulus kernel: ada0: Previously was known as ad0 Sep 17 11:25:39 romulus kernel: SMP: AP CPU #2 Launched! Sep 17 11:25:39 romulus kernel: SMP: AP CPU #6 Launched! Sep 17 11:25:39 romulus kernel: SMP: AP CPU #4 Launched! Sep 17 11:25:39 romulus kernel: SMP: AP CPU #1 Launched! Sep 17 11:25:39 romulus kernel: SMP: AP CPU #3 Launched! Sep 17 11:25:39 romulus kernel: SMP: AP CPU #7 Launched! Sep 17 11:25:39 romulus kernel: SMP: AP CPU #5 Launched! Sep 17 11:25:39 romulus kernel: Timecounter "TSC-low" frequency 1400075561 Hz quality 1000 Sep 17 11:25:39 romulus kernel: Root mount waiting for: usbus3 Sep 17 11:25:39 romulus kernel: uhub2: 6 ports with 6 removable, self powered Sep 17 11:25:39 romulus kernel: Trying to mount root from ufs:/dev/mfid0p2 [rw]... Sep 17 11:25:39 romulus kernel: WARNING: / was not properly dismounted Sep 17 11:25:39 romulus kernel: WARNING: /: mount pending error: blocks 8 files 1 Sep 17 11:25:39 romulus kernel: ZFS filesystem version: 5 Sep 17 11:25:39 romulus kernel: ZFS storage pool version: features support (5000)

Quoting Rick Romero rick@havokmon.com:

...

Ok,

So this is really more of an observation than anything else.

I had a FreeBSD 10.1 server that was running great. Some SSL issue came up, or I upgrade Dovecot in ports - something occurred and the machine started rebooting randomly. It would run for 2 weeks, then reboot. It might run for 5 days and then reboot. So I started doing more FreeBSD upgrades, thinking it was a kernel issue. The reboots only increased.

This weekend I started thinking I might actually be having hardware issues. But, since I don't have easy physical access to the box and it's REALLY under loaded, I figured what the hell and upraded to 10.2 on Sunday. I think it rebooted 4 times after that on Sunday, and then another 2 times Monday morning.

Its worth noting that while I have crash dumps enabled, they don't seem to be occurring. So hardware is still a possibility.

After the 2nd Monday morning reboot, I started to wonder if there was some sort of process issue. Besides the OS upgrades - I had been monitoring the Dovecot logs for when the process limits are reached, and increasing them. It's a 'big' box, and load is typically between .30 and .50. CPUs aren't overtaxed, and most of the memory is dedicated to ZFS. The reboots are so short, I've only received one 'down' alert due to them. So it's a conerning issue, but not really impacting production.

On a whim I changed my default_vsz_limit (as I had been increasing every other limit but that) from 384M to 512M. The system hasn't rebooted in 24hours.

Now that could be a coincidence, but I thought I'd at least put it out there.

If you see anything weird in my dovecot config, let me know - My config was originally vpopmail, but over time I've migrated to SQL-only.

root@romulus:/usr/local/etc/dovecot # dovecot -n # 2.2.18: /usr/local/etc/dovecot/dovecot.conf # OS: FreeBSD 10.2-RELEASE amd64 auth_master_user_separator = * auth_mechanisms = plain login auth_username_translation = %@ auth_verbose = yes default_login_user = dovecot default_vsz_limit = 512 M disable_plaintext_auth = no first_valid_gid = 89 first_valid_uid = 89 last_valid_gid = 89 last_valid_uid = 89 log_path = /dev/stderr login_greeting = Ready. login_trusted_networks = 172.16.100.0/24 mail_fsync = never mail_plugins = " quota zlib stats" mail_privileged_group = mail namespace compat { alias_for = hidden = yes inbox = no list = no location = prefix = INBOX. separator = . } namespace inbox { inbox = yes location = prefix = separator = . } passdb { args = /usr/local/etc/dovecot/dovecot-master-sql.conf driver = sql master = yes pass = yes } passdb { args = /usr/local/etc/dovecot/dovecot-sql.conf driver = sql } plugin { quota = maildir quota_rule = Trash:storage=+10%% stats_refresh = 30 secs stats_track_cmds = yes } protocols = imap pop3 service anvil { client_limit = 3175 } service auth { client_limit = 3684 unix_listener auth-master { mode = 0600 } } service imap-login { process_limit = 1536 process_min_avail = 25 service_count = 1 } service imap-postlogin { executable = script-login rawlog /usr/local/etc/dovecot/lastauth-imap.sh user = vpopmail } service imap { executable = /usr/local/libexec/dovecot/imap imap-postlogin process_limit = 1536 } service pop-postlogin { executable = script-login /usr/local/etc/dovecot/lastauth-pop.sh user = vpopmail } service pop3-login { process_limit = 1536 process_min_avail = 15 service_count = 1 } service pop3 { executable = /usr/local/libexec/dovecot/pop3 pop-postlogin } service stats { fifo_listener stats-mail { mode = 0600 user = vpopmail } } shutdown_clients = no ssl_cert =

Timo Sirainen

9:58 p.m.

On 24 Sep 2015, at 16:26, Rick Romero rick@havokmon.com wrote:

...

Update. Only a single reboot has occurred since changing defalt_vsz_limit from 384M to 512M. It would seem that something the users are doing is causing that virtual memory size to be exceeded (possibly a mailbox search?), and when that occurs Dovecot/FreeBSD is not handling the event as smoothly as expected.

I could maybe understand that a system might reboot in some conditions when it runs out of memory, but you're doing the exact opposite of avoiding that by increasing the vsz limit. It just means that the system is potentially going to use even more memory. And wouldn't FreeBSD have something similar to Linux's out-of-memory killer?

I think either your hardware is broken or FreeBSD has some serious bug, and a hardware problem seems more likely to me.

Rick Romero

10:36 p.m.

Quoting Timo Sirainen tss@iki.fi:

...

On 24 Sep 2015, at 16:26, Rick Romero rick@havokmon.com wrote:

...
Update. Only a single reboot has occurred since changing defalt_vsz_limit from 384M to 512M. It would seem that something the users are doing is causing that virtual memory size to be exceeded (possibly a mailbox search?), and when that occurs Dovecot/FreeBSD is not handling the event as smoothly as expected.

I could maybe understand that a system might reboot in some conditions when it runs out of memory, but you're doing the exact opposite of avoiding that by increasing the vsz limit. It just means that the system is potentially going to use even more memory. And wouldn't FreeBSD have something similar to Linux's out-of-memory killer? I think either your hardware is broken or FreeBSD has some serious bug, and a hardware problem seems more likely to me.

I was thinking along the lines of the process kill handling (? I don't know what actually occurs when the limit is reached - I'm assuming a thread is terminated) was triggering something odd in FreeBSD.

Activity/Usage has increased with the frequency of reboots, at least until I changed that parameter. User acitivty is the same, reboots have decreased dramatically (Just 1 since the change 9/14). While I wouldn't rule it out, it seems to me that it's less likely to be a hardware problem if I've simply provided MORE memory to a process (or set of processes) to avoid the issue...

This is my current 'top' output. It's not that the system is actually running low on memory, so I had no heisitation increasing the vsz limit. last pid: 59072; load averages: 0.30, 0.29, 0.32 up 7+03:02:34 14:27:59 1265 processes:1 running, 1264 sleeping CPU: 2.6% user, 0.0% nice, 1.4% system, 0.2% interrupt, 95.9% idle Mem: 3326M Active, 2210M Inact, 25G Wired, 8828K Cache, 1655M Buf, 1000M Free ARC: 20G Total, 14G MFU, 4646M MRU, 3845K Anon, 621M Header, 1216M Other Swap: 4096M Total, 4096M Free

Now, it's entirely possible that the user(s) who were eating all my server resources stopped using the system at the same time I increased the vsz limit, but that seems unlikely.

I'm leaning towards a FreeBSD issue of some sort - but I thought this might be a more approprate place as I have no hard data, I'm not sure what other software might use a similar vsz limit process/check that could trigger the oddity, and I just wanted it documented somewhere. :) Rick

Timo Sirainen

10:42 p.m.

On 24 Sep 2015, at 22:36, Rick Romero rick@havokmon.com wrote:

...

Quoting Timo Sirainen mailto:tss@iki.fi>:

...
On 24 Sep 2015, at 16:26, Rick Romero mailto:rick@havokmon.com> wrote:

...
Update. Only a single reboot has occurred since changing defalt_vsz_limit from 384M to 512M. It would seem that something the users are doing is causing that virtual memory size to be exceeded (possibly a mailbox search?), and when that occurs Dovecot/FreeBSD is not handling the event as smoothly as expected.

I could maybe understand that a system might reboot in some conditions when it runs out of memory, but you're doing the exact opposite of avoiding that by increasing the vsz limit. It just means that the system is potentially going to use even more memory. And wouldn't FreeBSD have something similar to Linux's out-of-memory killer? I think either your hardware is broken or FreeBSD has some serious bug, and a hardware problem seems more likely to me.

I was thinking along the lines of the process kill handling (? I don't know what actually occurs when the limit is reached - I'm assuming a thread is terminated) was triggering something odd in FreeBSD.

Yeah. That would fit into the "serious FreeBSD bug" category. If a limit is reached, kernel is supposed to send SIGKILL to the process.

3357

Age (days ago)

3357

Last active (days ago)

List overview

5 comments

3 participants

participants (3)

Remko Lodder
Rick Romero
Timo Sirainen