What does FreeNAS do to a pool every 5 minutes?

[FlyingBear]

I'm experimenting with virtualizing FreeNAS. On ESXI 6.7, FreeNAS 11.2-BETA3. The zpool is on an LSI 9210-8i in IT mode passed through: 8x8TB SAS in RAIDZ2 with mirrored 2x400GB S3700 SLOG (which isn't doing anything right now as I'm just copying data to an SMB share). All is well except for a curious set of errors (in ESXI's vmkernel.log) almost exactly every five minutes:

VSCSIFs: 3823: handle 8192(vscsi0:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS) - and 7 other similar messages in quick succession.

It's the same sequence of 8 invalid opcodes every time: 4d, 4d, b7, 37, 4d, 4d, b7, 37. This comprises two sequences of SCSI opcodes for LOG SENSE (twice), READ DEFECT DATA(12), and READ DEFECT DATA (10).

It would appear that FreeNAS is trying to read disk error data every five minutes. At first I thought that it must be S.M.A.R.T., but that's set for 30 minutes.

I'm curious if anyone knows what causes FreeNAS to do this, if it's possible to turn it off or change the interval, and what role it plays in data integrity. Even more curiously, after exactly an hour of uptime, these messages stopped. Most of this time (and way past the hour), I'm copying 3TB of incompressible data over 10Gbe to an SMB share, so the system is pretty loaded up.

I'd appreciate any ideas. Thanks!

 

[Chris Moore]

VSCSIFs: 3823: handle 8192(vscsi0:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS) - and 7 other similar messages in quick succession.

You may have configured something incorrectly. Have you looked at these resources regarding how to successfully virtualize FreeNAS?

"Absolutely must virtualize FreeNAS!" ... a guide to not completely losing your data.
https://forums.freenas.org/index.ph...ide-to-not-completely-losing-your-data.12714/

also a good resource:

Build Report: Node 304 + X10SDV-TLN4F [ESXi/FreeNAS AIO]
https://forums.freenas.org/index.ph...node-304-x10sdv-tln4f-esxi-freenas-aio.57116/

 

[FlyingBear]

Thank you. It is, of course, possible that I messed up somewhere. But I followed the instructions very carefully. It's an odd error, and a two more 0x4d errors have popped up since I started this thread exactly an hour apart. All the errors have been on the "2s" and "7s". I'd love to know what it is that FreeNAS tries to do every 5 minutes. That might lead me to a clue. The system continues to be under load, as I'm copying files to an SMB share at, on average, 275MB/s.

 

[snowfan84]

Hello. I have been running FreeNAS in a VM for years with ESXi 6.0. I just started to receive these messages as well after an upgrade to -
FreeNAS-11.2-RELEASE

There were no messages with the previous 11.1 version. The disks it is reporting against are VMDKs used to boot FreeNAS and Jail storage. SMART is disabled on these devices. It is not complaining about any of the HDD connected to the Passthrough controller.

2018-12-21T13:01:03.075Z cpu5:35434)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:01:03.075Z cpu6:35433)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:01:03.075Z cpu8:35430)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0xb7) from (vmm0:FreeNAS-11)
2018-12-21T13:01:03.075Z cpu5:35434)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x37) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.061Z cpu2:35434)VSCSIFs: 2235: handle 8195(vscsi1:1):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.061Z cpu2:35434)VSCSIFs: 2235: handle 8195(vscsi1:1):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.061Z cpu2:35434)VSCSIFs: 2235: handle 8193(vscsi0:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.061Z cpu2:35434)VSCSIFs: 2235: handle 8195(vscsi1:1):Invalid Opcode (0xb7) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.061Z cpu2:35434)VSCSIFs: 2235: handle 8193(vscsi0:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.061Z cpu2:35434)VSCSIFs: 2235: handle 8195(vscsi1:1):Invalid Opcode (0x37) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.061Z cpu2:35434)VSCSIFs: 2235: handle 8193(vscsi0:0):Invalid Opcode (0xb7) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.062Z cpu2:35434)VSCSIFs: 2235: handle 8193(vscsi0:0):Invalid Opcode (0x37) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.068Z cpu10:35433)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.068Z cpu10:35433)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.068Z cpu10:35433)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0xb7) from (vmm0:FreeNAS-11)
2018-12-21T13:06:03.068Z cpu10:35433)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x37) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.059Z cpu11:35434)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.059Z cpu11:35434)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.059Z cpu11:35434)VSCSIFs: 2235: handle 8195(vscsi1:1):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.059Z cpu11:35434)VSCSIFs: 2235: handle 8195(vscsi1:1):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.059Z cpu11:35434)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0xb7) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.059Z cpu11:35434)VSCSIFs: 2235: handle 8194(vscsi1:0):Invalid Opcode (0x37) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.059Z cpu11:35434)VSCSIFs: 2235: handle 8195(vscsi1:1):Invalid Opcode (0xb7) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.059Z cpu11:35434)VSCSIFs: 2235: handle 8195(vscsi1:1):Invalid Opcode (0x37) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.067Z cpu2:35433)VSCSIFs: 2235: handle 8193(vscsi0:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)
2018-12-21T13:11:03.067Z cpu2:35433)VSCSIFs: 2235: handle 8193(vscsi0:0):Invalid Opcode (0x4d) from (vmm0:FreeNAS-11)

 

[FlyingBear]

I'm gratified that I wasn't completely insane in having this problem. I never got to the bottom of it, and a number of other minor glitches made me abandon the VM route and go to bare iron.

I'm still very curious to know what FreeNAS, or maybe ESXi, does every five minutes.

 

[snowfan84]

I have experience in Enterprise Storage and recognize the SCSI commands you posted -
This comprises two sequences of SCSI opcodes for LOG SENSE (twice), READ DEFECT DATA(12), and READ DEFECT DATA (10).

FreeNAS is polling the disk devices for information including disk logging information and HDD defect data. Most likely (in my case) because these are VMDK virtual disks, they do not support the SCSI commands sent and we get the error.

I would think these SCSI commands should be used to retrieve hardware info - again SMART is disabled on these VMDK disks in my setup.

This seems to be a FreeNAS bug to me, introduced in 11.2...

 

[Chris Moore]

I have experience in Enterprise Storage and recognize the SCSI commands you posted -
This comprises two sequences of SCSI opcodes for LOG SENSE (twice), READ DEFECT DATA(12), and READ DEFECT DATA (10).

FreeNAS is polling the disk devices for information including disk logging information and HDD defect data. Most likely (in my case) because these are VMDK virtual disks, they do not support the SCSI commands sent and we get the error.

I would think these SCSI commands should be used to retrieve hardware info - again SMART is disabled on these VMDK disks in my setup.

This seems to be a FreeNAS bug to me, introduced in 11.2...

You should file a bug report on it. That way the developers can look into it. It is probably something they need to modify.

 

[FlyingBear]

Thank you. Eventually, I'd discovered the same thing, i.e. polling for disk info. In my case, I was using hardware passthrough, and expected those commands to work. I suppose that passthrough is not fully transparent.

 

[jgreco]

I have experience in Enterprise Storage and recognize the SCSI commands you posted -
This comprises two sequences of SCSI opcodes for LOG SENSE (twice), READ DEFECT DATA(12), and READ DEFECT DATA (10).

FreeNAS is polling the disk devices for information including disk logging information and HDD defect data. Most likely (in my case) because these are VMDK virtual disks, they do not support the SCSI commands sent and we get the error.

I would think these SCSI commands should be used to retrieve hardware info - again SMART is disabled on these VMDK disks in my setup.

This seems to be a FreeNAS bug to me, introduced in 11.2...

It isn't clear that polling an unsupported opcode is a bug. There's a valid case to be made that it's actually an ESXi bug because ESXi is logging an error when no error status exists. I'd still file a problem report with the goal of having one of the people familiar with recent changes looking at it to make sure there aren't bad side effects, and maybe creating a quirk flag for VMware virtual disks to suppress the issuing of those opcodes.

 

[snowfan84]

Thanks for the recommendation. I posted on the bug forum - https://forums.freenas.org/index.ph...-full-of-vscsi-invalid-opcode-messages.72206/

As I am new to this forum and created an account just to chat about this topic, please let me know if I am out of line with process.

Thanks!

 

[Chris Moore]

Thanks for the recommendation. I posted on the bug forum - https://forums.freenas.org/index.ph...-full-of-vscsi-invalid-opcode-messages.72206/

As I am new to this forum and created an account just to chat about this topic, please let me know if I am out of line with process.

Thanks!

Welcome to the forum.
I wouldn't say you are out of line. We can often help with the, 'how' questions, but if there is actually something broken, or it appears to be broken, we will suggest a bug report just to give the developers a chance to look into it. This new User Interface is certain to have growing pains.

 

[jgreco]

Thanks for the recommendation. I posted on the bug forum - https://forums.freenas.org/index.ph...-full-of-vscsi-invalid-opcode-messages.72206/

As I am new to this forum and created an account just to chat about this topic, please let me know if I am out of line with process.

Thanks!

I don't think the bug forum is actually visited by developers. It's been hit or miss over the years, mostly miss. As in -- I didn't even think to warn you (sorry).

If you log into your NAS and click "support", you will find the easiest way to enter the bug reporting system. Alternatively you may launch the web site at http://bugs.freenas.org

The forums are always fair ground to figure out whether these things are an issue, or PEBCAK, or can be safely ignored. Asking the question, especially a new question of the hasn't-been-asked-a-zillion-times variety, is better than stewing in frustration. You may not always get satisfaction, but usually at least an answer.

 

[snowfan84]

Thanks for the information. I was delayed by the holiday and opened Bug # 66927 to track this.

Checked again this morning and still seeing these messages every 5 minutes. I know we can filter them from the log in ESXi and am willing to do that if nothing else can be done.

Time well tell. Happy New Year!

-A