Virtualized FreeNAS 11.2 ESXi 6.0 - vmkernel.log full of vscsi Invalid Opcode messages

[snowfan84]

Hi Team,

I have been running FreeNAS as a VM in ESXi 6.0 for years and it has been flawless. Recently, I upgraded to 11.2 and just discovered new messages showing up in the vmkernel.log of the host every 5 minutes that were not present in 11.1. The SCSI devices it is referring to are .VMDK disks used for Boot and Jails storage. There are no error messages seen to any of the HDD disks connected to the PCI Passthrough Controller (zpool).

Looking at the SCSI commands, they include 'Log Sense' and 'Read Defect Data'. Most likely, these commands are not supported by the VMDK virtual disks and throw this message instead. Curious as I had not seen this before on any previous version of FreeNAS.

Also note, SMART is disabled for these VMDK devices but is enabled for the HDD connected to the PCI Passthrough controller.

We have also started chatting about it - https://forums.freenas.org/index.ph...-to-a-pool-every-5-minutes.70574/#post-500044

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)

As I understand it, there is little to no impact from these messages but I am still puzzled as I hadn't seen any of these in previous versions. Is there anything that can be done to avoid sending these SCSI Commands to VMDK disks? Were there any changes made on this topic from the previous version 11.1?

If you'd like, I can set up another FreeNAS VM in a lab environment to test various versions - let me know.

Thanks for your time.
-Andy

 

[dlavigne]

Were you able to determine the reason for the messages?

If not, it may be worth reporting at bugs.freenas.org. If you do, post the issue number here.

 

[Chris Moore]

There was another discussion of this here:
https://forums.freenas.org/index.php?threads/what-does-freenas-do-to-a-pool-every-5-minutes.70574/
and @jgreco suggested opening a bug report.

 

[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