Bug 233450 - [hyper-v] HV_KVP[2093]: Operation failed OP = 4, error = 0x16
Summary: [hyper-v] HV_KVP[2093]: Operation failed OP = 4, error = 0x16
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: CURRENT
Hardware: amd64 Any
: --- Affects Many People
Assignee: freebsd-virtualization mailing list
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-11-23 19:44 UTC by Michael
Modified: 2018-12-18 15:55 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Michael 2018-11-23 19:44:21 UTC
/var/log/messages
-----------------
Nov 23 20:07:32 f12rw kernel: Copyright (c) 1992-2018 The FreeBSD Project.
Nov 23 20:07:32 f12rw kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
Nov 23 20:07:32 f12rw kernel: 	The Regents of the University of California. All rights reserved.
Nov 23 20:07:32 f12rw kernel: FreeBSD is a registered trademark of The FreeBSD Foundation.
Nov 23 20:07:32 f12rw kernel: FreeBSD 13.0-CURRENT #0 8b2e2bba54f(master)-dirty: Fri Nov 23 19:54:26 EET 2018
Nov 23 20:07:32 f12rw kernel:     root@f12rw.local.lan:/usr/obj/usr/src/amd64.amd64/sys/GENERIC-NODBG amd64
Nov 23 20:07:32 f12rw kernel: FreeBSD clang version 6.0.1 (tags/RELEASE_601/final 335540) (based on LLVM 6.0.1)
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x3f0000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x1000000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x10000000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x20000000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x40000000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x80000000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x9e8000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x8800000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x18000000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x30000000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0x60000000000
Nov 23 20:07:32 f12rw kernel: SRAT: Ignoring memory at addr 0xc0000000000
Nov 23 20:07:32 f12rw kernel: VT(efifb): resolution 1024x768
Nov 23 20:07:32 f12rw kernel: Hyper-V Version: 10.0.17763 [SP0]
Nov 23 20:07:32 f12rw kernel:   Features=0x2e7f<VPRUNTIME,TMREFCNT,SYNIC,SYNTM,APIC,HYPERCALL,VPINDEX,REFTSC,IDLE,TMFREQ>
Nov 23 20:07:32 f12rw kernel:   PM Features=0x0 [C2]
Nov 23 20:07:32 f12rw kernel:   Features3=0xbed7b2<DEBUG,XMMHC,IDLE,NUMA,TMFREQ,SYNCMC,CRASH,NPIEP>
Nov 23 20:07:32 f12rw kernel: Timecounter "Hyper-V" frequency 10000000 Hz quality 2000
Nov 23 20:07:32 f12rw kernel: module_register: cannot register pci/ixv from kernel; already loaded from if_ixv.ko
Nov 23 20:07:32 f12rw kernel: Module pci/ixv failed to register: 17
Nov 23 20:07:32 f12rw kernel: CPU: Intel(R) Xeon(R) CPU E5-2690 v3 @ 2.60GHz (2597.00-MHz K8-class CPU)
Nov 23 20:07:32 f12rw kernel:   Origin="GenuineIntel"  Id=0x306f2  Family=0x6  Model=0x3f  Stepping=2
Nov 23 20:07:32 f12rw kernel:   Features=0x1f83fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE,SSE2,SS,HTT>
Nov 23 20:07:32 f12rw kernel:   Features2=0xfeda3203<SSE3,PCLMULQDQ,SSSE3,FMA,CX16,PCID,SSE4.1,SSE4.2,MOVBE,POPCNT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND,HV>
Nov 23 20:07:32 f12rw kernel:   AMD Features=0x2c100800<SYSCALL,NX,Page1GB,RDTSCP,LM>
Nov 23 20:07:32 f12rw kernel:   AMD Features2=0x21<LAHF,ABM>
Nov 23 20:07:32 f12rw kernel:   Structured Extended Features=0x27a9<FSGSBASE,BMI1,AVX2,SMEP,BMI2,ERMS,INVPCID,NFPUSG>
Nov 23 20:07:32 f12rw kernel:   Structured Extended Features3=0xbc000000<IBPB,STIBP,L1DFL,ARCH_CAP,SSBD>
Nov 23 20:07:32 f12rw kernel:   XSAVE Features=0x1<XSAVEOPT>
Nov 23 20:07:32 f12rw kernel:   IA32_ARCH_CAPS=0x4<RSBA>
Nov 23 20:07:32 f12rw kernel: Hypervisor: Origin = "Microsoft Hv"
Nov 23 20:07:32 f12rw kernel: real memory  = 16777216000 (16000 MB)
Nov 23 20:07:32 f12rw kernel: avail memory = 16249954304 (15497 MB)
Nov 23 20:07:32 f12rw kernel: Event timer "LAPIC" quality 100
Nov 23 20:07:32 f12rw kernel: ACPI APIC Table: <VRTUAL MICROSFT>
Nov 23 20:07:32 f12rw kernel: FreeBSD/SMP: Multiprocessor System Detected: 8 CPUs
Nov 23 20:07:32 f12rw kernel: FreeBSD/SMP: 1 package(s) x 4 core(s) x 2 hardware threads
Nov 23 20:07:32 f12rw kernel: random: unblocking device.
Nov 23 20:07:32 f12rw kernel: ioapic0 <Version 1.1> irqs 0-23 on motherboard
Nov 23 20:07:32 f12rw kernel: Launching APs: 5 6 7 2 3 1 4
Nov 23 20:07:32 f12rw kernel: Timecounter "Hyper-V-TSC" frequency 10000000 Hz quality 3000
Nov 23 20:07:32 f12rw kernel: random: entropy device external interface
Nov 23 20:07:32 f12rw kernel: kbd0 at kbdmux0
Nov 23 20:07:32 f12rw kernel: module_register_init: MOD_LOAD (vesa, 0xffffffff811df190, 0) error 19
Nov 23 20:07:32 f12rw kernel: random: registering fast source Intel Secure Key RNG
Nov 23 20:07:32 f12rw kernel: random: fast provider: "Intel Secure Key RNG"
Nov 23 20:07:32 f12rw kernel: netmap: loaded module
Nov 23 20:07:32 f12rw kernel: [ath_hal] loaded
Nov 23 20:07:32 f12rw kernel: nexus0
Nov 23 20:07:32 f12rw kernel: efirtc0: <EFI Realtime Clock> on motherboard
Nov 23 20:07:32 f12rw kernel: efirtc0: registered as a time-of-day clock, resolution 1.000000s
Nov 23 20:07:32 f12rw kernel: cryptosoft0: <software crypto> on motherboard
Nov 23 20:07:32 f12rw kernel: acpi0: <VRTUAL MICROSFT> on motherboard
Nov 23 20:07:32 f12rw kernel: atrtc0: <AT realtime clock> port 0x70-0x71 irq 8 on acpi0
Nov 23 20:07:32 f12rw kernel: atrtc0: registered as a time-of-day clock, resolution 1.000000s
Nov 23 20:07:32 f12rw kernel: Event timer "RTC" frequency 32768 Hz quality 0
Nov 23 20:07:32 f12rw kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
Nov 23 20:07:32 f12rw kernel: acpi_timer0: <32-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
Nov 23 20:07:32 f12rw kernel: cpu0: <ACPI CPU> on acpi0
Nov 23 20:07:32 f12rw kernel: acpi_syscontainer0: <System Container> iomem 0xf8000000-0xffffffff,0xfe0000000-0xfffffffff on acpi0
Nov 23 20:07:32 f12rw kernel: vmbus0: <Hyper-V Vmbus> on acpi_syscontainer0
Nov 23 20:07:32 f12rw kernel: vmbus_res0: <Hyper-V Vmbus Resource> irq 5 on acpi0
Nov 23 20:07:32 f12rw kernel: Timecounters tick every 10.000 msec
Nov 23 20:07:32 f12rw kernel: ipfw2 (+ipv6) initialized, divert enabled, nat enabled, default to deny, logging disabled
Nov 23 20:07:32 f12rw kernel: DUMMYNET 0xfffff801fc0b00c0 with IPv6 initialized (100409)
Nov 23 20:07:32 f12rw kernel: load_dn_sched dn_sched RR loaded
Nov 23 20:07:32 f12rw kernel: load_dn_sched dn_sched WF2Q+ loaded
Nov 23 20:07:32 f12rw kernel: load_dn_sched dn_sched FIFO loaded
Nov 23 20:07:32 f12rw kernel: load_dn_sched dn_sched FQ_CODEL loaded
Nov 23 20:07:32 f12rw kernel: load_dn_sched dn_sched FQ_PIE loaded
Nov 23 20:07:32 f12rw kernel: load_dn_sched dn_sched PRIO loaded
Nov 23 20:07:32 f12rw kernel: load_dn_sched dn_sched QFQ loaded
Nov 23 20:07:32 f12rw kernel: load_dn_aqm dn_aqm CODEL loaded
Nov 23 20:07:32 f12rw kernel: load_dn_aqm dn_aqm PIE loaded
Nov 23 20:07:32 f12rw kernel: usb_needs_explore_all: no devclass
Nov 23 20:07:32 f12rw kernel: vmbus0: version 3.0
Nov 23 20:07:32 f12rw kernel: hvet0: <Hyper-V event timer> on vmbus0
Nov 23 20:07:32 f12rw kernel: Event timer "Hyper-V" frequency 10000000 Hz quality 1000
Nov 23 20:07:32 f12rw kernel: hvkbd0: <Hyper-V KBD> on vmbus0
Nov 23 20:07:32 f12rw kernel: hvheartbeat0: <Hyper-V Heartbeat> on vmbus0
Nov 23 20:07:32 f12rw kernel: hvkvp0: <Hyper-V KVP> on vmbus0
Nov 23 20:07:32 f12rw kernel: hvshutdown0: <Hyper-V Shutdown> on vmbus0
Nov 23 20:07:32 f12rw kernel: hvtimesync0: <Hyper-V Timesync> on vmbus0
Nov 23 20:07:32 f12rw kernel: hvtimesync0: RTT
Nov 23 20:07:32 f12rw kernel: hvvss0: <Hyper-V VSS> on vmbus0
Nov 23 20:07:32 f12rw kernel: storvsc0: <Hyper-V SCSI> on vmbus0
Nov 23 20:07:32 f12rw kernel: hn0: <Hyper-V Network Interface> on vmbus0
Nov 23 20:07:32 f12rw kernel: da0 at storvsc0 bus 0 scbus0 target 0 lun 0
Nov 23 20:07:32 f12rw kernel: da0: <Msft Virtual Disk 1.0> Fixed Direct Access SPC-3 SCSI device
Nov 23 20:07:32 f12rw kernel: da0: 300.000MB/s transfers
Nov 23 20:07:32 f12rw kernel: da0: Command Queueing enabled
Nov 23 20:07:32 f12rw kernel: da0: 61440MB (125829120 512 byte sectors)
Nov 23 20:07:32 f12rw kernel: da1 at storvsc0 bus 0 scbus0 target 0 lun 1
Nov 23 20:07:32 f12rw kernel: da1: <Msft Virtual Disk 1.0> Fixed Direct Access SPC-3 SCSI device
Nov 23 20:07:32 f12rw kernel: da1: 300.000MB/s transfers
Nov 23 20:07:32 f12rw kernel: da1: Command Queueing enabled
Nov 23 20:07:32 f12rw kernel: da1: 409600MB (838860800 512 byte sectors)
Nov 23 20:07:32 f12rw kernel: da2 at storvsc0 bus 0 scbus0 target 0 lun 2
Nov 23 20:07:32 f12rw kernel: da2: <Msft Virtual Disk 1.0> Fixed Direct Access SPC-3 SCSI device
Nov 23 20:07:32 f12rw kernel: da2: 300.000MB/s transfers
Nov 23 20:07:32 f12rw kernel: da2: Command Queueing enabled
Nov 23 20:07:32 f12rw kernel: da2: 40960MB (83886080 512 byte sectors)
Nov 23 20:07:32 f12rw kernel: da3 at storvsc0 bus 0 scbus0 target 0 lun 3
Nov 23 20:07:32 f12rw kernel: da3: <Msft Virtual Disk 1.0> Fixed Direct Access SPC-3 SCSI device
Nov 23 20:07:32 f12rw kernel: da3: 300.000MB/s transfers
Nov 23 20:07:32 f12rw kernel: da3: Command Queueing enabled
Nov 23 20:07:32 f12rw kernel: da3: 40960MB (83886080 512 byte sectors)
Nov 23 20:07:32 f12rw kernel: hn0: Ethernet address: 00:15:5d:00:8a:09
Nov 23 20:07:32 f12rw kernel: hn0: link state changed to UP
Nov 23 20:07:32 f12rw kernel: hn1: <Hyper-V Network Interface> on vmbus0
Nov 23 20:07:32 f12rw kernel: hn1: Ethernet address: 00:15:5d:00:8a:0a
Nov 23 20:07:32 f12rw kernel: hn1: link state changed to UP
Nov 23 20:07:32 f12rw kernel: hn2: <Hyper-V Network Interface> on vmbus0
Nov 23 20:07:32 f12rw kernel: hn2: Ethernet address: 00:15:5d:00:8a:0b
Nov 23 20:07:32 f12rw kernel: hn2: link state changed to UP
Nov 23 20:07:32 f12rw kernel: hn3: <Hyper-V Network Interface> on vmbus0
Nov 23 20:07:32 f12rw kernel: hn3: Ethernet address: 00:15:5d:00:8a:0c
Nov 23 20:07:32 f12rw kernel: hn3: link state changed to UP
Nov 23 20:07:32 f12rw kernel: hn4: <Hyper-V Network Interface> on vmbus0
Nov 23 20:07:32 f12rw kernel: hn4: Ethernet address: 00:15:5d:00:8a:0d
Nov 23 20:07:32 f12rw kernel: hn4: link state changed to UP
Nov 23 20:07:32 f12rw kernel: hn5: <Hyper-V Network Interface> on vmbus0
Nov 23 20:07:32 f12rw kernel: hn5: Ethernet address: 00:15:5d:00:8a:0e
Nov 23 20:07:32 f12rw kernel: hn5: link state changed to UP
Nov 23 20:07:32 f12rw kernel: Trying to mount root from ufs:/dev/da0p2 [rw]...
Nov 23 20:07:32 f12rw kernel: lo0: link state changed to UP
...
-//- cut -//-
...
Nov 23 20:07:36 f12rw HV_KVP[2093]: Operation failed OP = 4, error = 0x16
Nov 23 20:07:37 f12rw kernel: tun1: link state changed to UP
Nov 23 20:07:37 f12rw kernel: tun2: link state changed to UP
Nov 23 20:07:47 f12rw HV_KVP[2093]: Operation failed OP = 4, error = 0x16
Nov 23 20:07:50 f12rw kernel: tun3: link state changed to UP
Nov 23 20:07:57 f12rw HV_KVP[2093]: Operation failed OP = 4, error = 0x16
Nov 23 20:08:27 f12rw syslogd: last message repeated 3 times
Nov 23 20:10:31 f12rw syslogd: last message repeated 12 times
Nov 23 20:20:27 f12rw syslogd: last message repeated 58 times
Nov 23 20:30:23 f12rw syslogd: last message repeated 58 times
Nov 23 20:37:35 f12rw syslogd: last message repeated 42 times
Nov 23 20:37:37 f12rw kernel: tun3: link state changed to DOWN
Nov 23 20:37:45 f12rw kernel: tun3: link state changed to UP
Nov 23 20:37:45 f12rw HV_KVP[2093]: Operation failed OP = 4, error = 0x16
Nov 23 20:38:16 f12rw syslogd: last message repeated 3 times
Nov 23 20:40:19 f12rw syslogd: last message repeated 12 times
Nov 23 20:49:03 f12rw syslogd: last message repeated 51 times
------------------------------------------------------------------
root@f12rw:/etc# ps ax | grep hv_kvp
 2093  -  Is     0:17.39 /usr/sbin/hv_kvp_daemon
------------------------------------------------------------------
/etc/fstab
----------
/dev/da0p2      /               ufs                     rw                              1       1
/dev/da0p3      none            swap                    sw                              0       0
/dev/ufs/cache1 /squid-z        ufs                     rw,async,noatime,nosuid         0       2
/dev/ufs/cache2 /squid-c        ufs                     rw,async,noatime,nosuid         0       2
/dev/ufs/cache3 /var/run/squid  ufs                     rw,async                        1       1
------------------------------------------------------------------

Hyper-V host Windows server 2019 17763.134
FreeBSD-CURRENT Hyper-V guest v9.0 age 2
Comment 1 Michael 2018-12-17 08:35:12 UTC
Making a "control point" is also not possible - the process is stopped at 9% and hangs forever, without the ability to cancel it, with a similar error:
--------------------------
HV_VSS[2107]: error: 16.
--------------------------
The incomplete process of creating a control point is removed by shutting down the guest FreeBSD system, which also cannot completely shut down the VM, and then rebooting the hypervisor.
Comment 2 Michael 2018-12-18 15:55:58 UTC
Solving these problems my self (I do not know, right or wrong).
----------
HV_KVP[2093]: Operation failed OP = 4, error = 0x16

   Whis error caused the assignment of a set of aliases to the network interface hn5 (more than 600 aliases, there is a need for this).

ifconfig_hn5="inet 192.168.161.1 netmask 255.255.255.0"
ifconfig_hn5_alias0="inet 192.168.161.10 netmask 255.255.255.0"
...
ifconfig_hn5_alias671="inet 192.168.166.121 netmask 255.255.255.0"
----------

  The creation of a "checkpoint" was made possible by changing the /etc/fstab file to this content:
/dev/gptid/f128c6be-c6f9-11e8-8d73-00155d001667 /              ufs  rw,async 1 1
/dev/gptid/f12a47e0-c6f9-11e8-8d73-00155d001667 none           swap sw,async 0 0
/dev/gptid/43a175c5-cd5c-11e8-95fa-00155d008b13 /squid-z       ufs  rw,async 1 1
/dev/gptid/4b2ef9e6-d7c5-11e8-ad3c-00155d008b13 /squid-c       ufs  rw,async 1 1
/dev/gptid/fc8fsa17-b1a7-11e8-a21d-00155d008b13 /var/run/squid ufs  rw,async 1 1


But when the creation of the control point starts the message
----------
kernel: (da0:storvsc0:0:0:0): WRITE(10). CDB: 2a 00 02 c8 ec 68 00 00 40 00
kernel: (da0:storvsc0:0:0:0): CAM status: SCSI Status Error
kernel: (da0:storvsc0:0:0:0): SCSI status: Check Condition
kernel: (da0:storvsc0:0:0:0): SCSI sense: UNIT ATTENTION asc:3f,2 (Changed operating definition)
kernel: (da0:storvsc0:0:0:0): Retrying command (per sense data)
kernel: (da1:storvsc0:0:0:1): WRITE(10). CDB: 2a 00 25 24 cd e8 00 00 40 00
kernel: (da1:storvsc0:0:0:1): CAM status: SCSI Status Error
kernel: (da1:storvsc0:0:0:1): SCSI status: Check Condition
kernel: (da1:storvsc0:0:0:1): SCSI sense: UNIT ATTENTION asc:3f,2 (Changed operating definition)
kernel: (da1:storvsc0:0:0:1): Retrying command (per sense data)
----------
appears. When the creation of the control point ends
----------
kernel: (da1:storvsc0:0:0:1): WRITE(10). CDB: 2a 00 25 24 cd a8 00 00 40 00
kernel: (da1:storvsc0:0:0:1): CAM status: SCSI Status Error
kernel: (da1:storvsc0:0:0:1): SCSI status: Check Condition
kernel: (da1:storvsc0:0:0:1): SCSI sense: UNIT ATTENTION asc:3f,2 (Changed operating definition)
kernel: (da1:storvsc0:0:0:1): Retrying command (per sense data)
kernel: (da0:storvsc0:0:0:0): WRITE(10). CDB: 2a 00 02 c8 ec 68 00 00 40 00
kernel: (da0:storvsc0:0:0:0): CAM status: SCSI Status Error
kernel: (da0:storvsc0:0:0:0): SCSI status: Check Condition
kernel: (da0:storvsc0:0:0:0): SCSI sense: UNIT ATTENTION asc:3f,2 (Changed operating definition)
kernel: (da0:storvsc0:0:0:0): Retrying command (per sense data)
----------