Security run output (FreeNAS-9.2.1.3-RELEASE-x64)

[panz]

Received this email alert tonight; help me decode it, please (hardware: see my signature) :)

http://pastebin.com/pvSkMeWr

 

[dlavigne]

Looks like the system rebooted.... Any particular line you were concerned with?

 

[panz]

I didn't rebooted it: this is my concern :)

 

[ser_rhaegar]

If you didn't reboot the system sometime the day before the email was sent, you may find a reason for the reboot in the syslog from the .system dataset. Info might have been output to the log just before the reboot.

 

[dlavigne]

What's the output of last|grep boot ?

 

[panz]

What's the output of last|grep boot ?

Code:

last|grep boot
 
boot time          Mon Mar 24 21:07

 

[dlavigne]

That's when the system last booted, which makes sense given the boot messages in the alert. Anything in /var/log/messages that indicates why it rebooted (assuming you are saving logs to a dataset)?

 

[panz]

If you didn't reboot the system sometime the day before the email was sent, you may find a reason for the reboot in the syslog from the .system dataset. Info might have been output to the log just before the reboot.

I'm here

/mnt/storage/.system/syslog/log

Ho do I read the info you were writing about?

Here's the output of ls -lah

ls -lah
total 684
drwxr-xr-x 4 root wheel 39B Mar 24 03:01 .
drwxr-xr-x 3 root wheel 3B Mar 15 18:09 ..
-rw-r--r-- 1 root wheel 1B Mar 24 03:01 3ware_raid_alarms.today
-rw-r--r-- 1 root wheel 1B Mar 23 03:01 3ware_raid_alarms.yesterday
-rw------- 1 root wheel 35k Mar 24 21:10 auth.log
-rw------- 1 root wheel 241k Mar 24 21:11 cron
-rw------- 1 root wheel 22k Mar 22 23:00 cron.0.bz2
-rw------- 1 root wheel 21k Mar 20 14:00 cron.1.bz2
-rw------- 1 root wheel 13k Mar 24 03:01 dmesg.today
-rw------- 1 root wheel 2.5k Mar 22 03:01 dmesg.yesterday
-rw-r--r-- 1 root wheel 531B Mar 24 21:10 lpd-errs
-rw-r----- 1 root wheel 1.4k Mar 24 21:10 maillog
-rw-r----- 1 root wheel 796B Mar 24 00:00 maillog.0.bz2
-rw-r----- 1 root wheel 121B Mar 23 00:00 maillog.1.bz2
-rw-r----- 1 root wheel 560B Mar 22 00:00 maillog.2.bz2
-rw-r----- 1 root wheel 567B Mar 21 00:00 maillog.3.bz2
-rw-r----- 1 root wheel 118B Mar 20 00:00 maillog.4.bz2
-rw-r----- 1 root wheel 693B Mar 19 00:00 maillog.5.bz2
-rw-r----- 1 root wheel 562B Mar 18 00:00 maillog.6.bz2
-rw-r--r-- 1 root wheel 332k Mar 24 21:10 messages
-rw-r--r-- 1 root wheel 28k Mar 21 16:00 messages.0.bz2
-rw-r--r-- 1 root wheel 25k Mar 18 02:00 messages.1.bz2
-rw------- 1 root wheel 1.7k Mar 22 03:01 mount.today
-rw------- 1 root wheel 1.6k Mar 21 03:01 mount.yesterday
-rw-r--r-- 1 www www 625k Mar 24 21:10 nginx-access.log
-rw-r--r-- 1 www www 12k Mar 20 14:00 nginx-access.log.0.bz2
-rw-r--r-- 1 www www 0B Mar 15 18:04 nginx-error.log
-rw-r--r-- 1 root wheel 1.1k Mar 24 21:10 pbid.log
-rw------- 1 root wheel 0B Mar 16 03:01 pf.today
-rw-r----- 1 root network 531B Mar 24 21:10 ppp.log
drwxr-xr-x 2 root wheel 2B Mar 15 18:04 proftpd
drwxr-xr-x 2 root wheel 8B Mar 15 18:09 samba4
-rw------- 1 root wheel 531B Mar 24 21:10 security
-rw-r--r-- 1 root wheel 1.2k Mar 24 21:10 ups.log
-rw------- 1 root wheel 8.5k Mar 24 21:10 userlog
-rw-r--r-- 1 root wheel 394B Mar 24 21:10 utx.lastlogin
-rw-r--r-- 1 root wheel 4.7k Mar 24 21:10 utx.log
-rw-r--r-- 1 root wheel 0B Mar 15 18:04 wtmp
-rw------- 1 root wheel 531B Mar 24 21:10 xferlog

 

[dlavigne]

more /var/log/messages (use spacebar or pgdown key to scroll down through the pages)

 

[panz]

more /var/log/messages (use spacebar or pgdown key to scroll down through the pages)

NAS# more /var/log/messages

Mar 24 22:00:00 NAS newsyslog[8440]: logfile turned over due to size>100K
Mar 24 22:05:40 NAS smbd[8536]: [2014/03/24 22:05:40.418119, 0] ../source3/lib/util_sock.c:941(matchname)
Mar 24 22:05:40 NAS smbd[8536]: matchname: host name/name mismatch: 192.168.1.35 != (NULL)
Mar 24 22:05:40 NAS smbd[8536]: [2014/03/24 22:05:40.418258, 0] ../source3/lib/util_sock.c:1199(get_remote_hostname)
Mar 24 22:05:40 NAS smbd[8536]: matchname failed on 192.168.1.35
Mar 24 22:37:41 NAS smbd[8805]: [2014/03/24 22:37:41.983781, 0] ../source3/lib/util_sock.c:941(matchname)
Mar 24 22:37:41 NAS smbd[8805]: matchname: host name/name mismatch: 192.168.1.35 != (NULL)
Mar 24 22:37:41 NAS smbd[8805]: [2014/03/24 22:37:41.983925, 0] ../source3/lib/util_sock.c:1199(get_remote_hostname)
Mar 24 22:37:41 NAS smbd[8805]: matchname failed on 192.168.1.35

 

[dlavigne]

Looks like this bug: https://bugs.freenas.org/issues/4591.

 

[panz]

Oh yeah!

But that bug doesn't explain why the server rebooted. I can exclude defective parts, as I ran 12 days of Memtest86+ and HCI Memtest (1000%) with no errors. Motherboard and PSU have been thoroughly tested.

 

[dlavigne]

Sounds like some sort of resource exhaustion. Will be interesting to see what the culprit/solution to that bug turns out to be. It wouldn't hurt to add a comment to that bug, to see if there is some sort of commonality between your system and the bug reporter's system. Perhaps a network driver or some sysctl value hitting its max?

 

[panz]

Sounds like some sort of resource exhaustion. Will be interesting to see what the culprit/solution to that bug turns out to be. It wouldn't hurt to add a comment to that bug, to see if there is some sort of commonality between your system and the bug reporter's system. Perhaps a network driver or some sysctl value hitting its max?

Thanks, just done now!

 

[panz]

AGAIN!

Now I'm sure that FreeNAS didn't reboot, because one of the drives (da6) is doing a badblock test (and it is still running).

I can see an "USB hidmouse Device" in the logs... but I haven't a mouse.

[serial # stripped]

--
NAS.WORKGROUP kernel log messages:
> mps0: Firmware: 16.00.00.00, Driver: 16.00.00.00-fbsd
> ses0 at mps0 bus 0 scbus0 target 14 lun 0
> da0 at mps0 bus 0 scbus0 target 8 lun 0
> da0: Serial Number WD-
> da1 at mps0 bus 0 scbus0 target 9 lun 0
> da1: Serial Number WD-
> da2 at mps0 bus 0 scbus0 target 10 lun 0
> da2: Serial Number WD-
> da3 at mps0 bus 0 scbus0 target 11 lun 0
> da3: Serial Number WD-
> da4 at mps0 bus 0 scbus0 target 12 lun 0
> da5 at mps0 bus 0 scbus0 target 13 lun 0
> da6 at mps0 bus 0 scbus0 target 15 lun 0
> da6: <ATA WDC WD10JFCX-68N 1A01> Fixed Direct Access SCSI-6 device
> da6: Serial Number WD-
> da6: 600.000MB/s transfers
> da6: Command Queueing enabled
> da6: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
> da7 at umass-sim0 bus 0 scbus8 target 0 lun 0
> da7: <SanDisk Cruzer Blade 1.00> Removable Direct Access SCSI-2 device
> da7: Serial Number
> da7: 40.000MB/s transfers
> da7: 7629MB (15625216 512 byte sectors: 255H 63S/T 972C)
> da7: quirks=0x2<NO_6_BYTE>
> SMP: AP CPU #4 Launched!
> Timecounter "TSC-low" frequency 1650044390 Hz quality 1000
> ugen0.3: <Winbond Electronics Corp> at usbus0
> ums0: <Winbond Electronics Corp Hermon USB hidmouse Device, class 0/0, rev 1.10/0.01, addr 3> on usbus0
> ums0: 3 buttons and [Z] coordinates ID=0
> ukbd0: <Winbond Electronics Corp Hermon USB hidmouse Device, class 0/0, rev 1.10/0.01, addr 3> on usbus0
> kbd2 at ukbd0
> GEOM_ELI: Device da2p1.eli created.
> GEOM_ELI: Device da0p1.eli created.
> GEOM_ELI: Device da1p1.eli created.
> GEOM_ELI: Device da3p1.eli created.
> em1: promiscuous mode enabled
> lagg0: promiscuous mode enabled
> epair0a: Ethernet address: 02:c8:4e:00:09:0a
> epair0b: Ethernet address: 02:c8:4e:00:0a:0b
> em1: link state changed to DOWN
> lagg0: link state changed to DOWN
> lagg0: link state changed to UP
> em1: link state changed to UP
> epair1a: Ethernet address: 02:c0:c5:00:0a:0a
> epair1b: Ethernet address: 02:c0:c5:00:0b:0b
--

 

[ScottNZ]

Hi All,

I have a related question. The line I'm interested in is "em0: promiscuous mode enabled". Is this a normal occurrence?

(BTW, FreeNAS v9.2.1.3.5; hardware is in signature block.)

Thanks,
Scott