Project

General

Profile

Bug #73441

Prevent setting vfs.zfs.arc_max to lower than vfs.zfs.arc_min

Added by Ton S almost 3 years ago. Updated over 2 years ago.

Status:
Done
Priority:
No priority
Assignee:
Vladimir Vinogradenko
Category:
Middleware
Target version:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
No
Needs Doc:
No
Needs Merging:
No
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

When in the legacy interface a VM is started I get the following error mesage (the VM was created in a previous vesion of Freenas):

[2019/02/03 11:23:57] (INFO) VMService.__set_guest_vmemory():901 - ===> Setting ARC FROM: 17667395584 TO: 17130524672
[2019/02/03 11:23:57] (DEBUG) VMService.run():179 - ====> NIC_ATTACH: ix0
[2019/02/03 11:23:57] (DEBUG) VMService.run():264 - Starting bhyve: bhyve -A -H -w -c 1 -m 512 -s 0:0,hostbridge -s 31,lpc -l com1,/dev/nmdm13A -l bootrom,/usr/local/share/uefi-firmware/BHYVE_UEFI.fd -s 3,e1000,tap19,mac=00:A0:98:13:88:1F -s 4:0,virtio-blk,/dev/zvol/Tank/VM/sysman 13_sysman
[2019/02/03 11:23:57] (DEBUG) VMService.run():286 - sysman: vm_reinit: Device busy
[2019/02/03 11:23:57] (INFO) VMService.run():311 - ===> Error VM: sysman ID: 13 BHYVE_CODE: 4
[2019/02/03 11:23:57] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:23:57] (DEBUG) VMService.__teardown_guest_vmemory():338 - ===> Give back guest memory to ARC: -16056782848
[2019/02/03 11:23:57] (WARNING) application.call_method():189 - Exception while calling vm.start(*['13'])
Traceback (most recent call last):
File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 161, in call_method
result = await self.middleware.call_method(self, message)
File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1109, in call_method
return await self._call(message['method'], serviceobj, methodobj, params, app=app, io_thread=False)
File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1049, in call
return await methodobj(*args)
File "/usr/local/lib/python3.6/site-packages/middlewared/schema.py", line 664, in nf
return await f(*args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/vm.py", line 1132, in start
await self._manager.start(vm)
File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/vm.py", line 61, in start
list(done)[0].result()
File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/vm.py", line 312, in run
await self.
_teardown_guest_vmemory(self.vm['id'])
File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/vm.py", line 339, in __teardown_guest_vmemory
sysctl.filter('vfs.zfs.arc_max')[0].value = new_arc_max
TypeError: Invalid argument
[2019/02/03 11:23:57] (DEBUG) middlewared.logger.CrashReporting.report():103 - Sending a crash report...
[2019/02/03 11:23:57] (DEBUG) raven.base.Client.send_remote():716 - Sending message of length 3986 to https://sentry.ixsystems.com/api/2/store/
[2019/02/03 11:23:57] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.

The behaviour from the new GUI is similar, I only see more messages in the log about running without bhyve process:

[2019/02/03 11:27:12] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:13] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:17] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:22] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:27] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:29] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:32] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:33] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:34] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:34] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:34] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:34] (INFO) VMService.__set_guest_vmemory():901 - ===> Setting ARC FROM: 17130524672 TO: 16593653760
[2019/02/03 11:27:34] (DEBUG) VMService.run():179 - ====> NIC_ATTACH: ix0
[2019/02/03 11:27:34] (DEBUG) VMService.run():264 - Starting bhyve: bhyve -A -H -w -c 1 -m 512 -s 0:0,hostbridge -s 31,lpc -l com1,/dev/nmdm13A -l bootrom,/usr/local/share/uefi-firmware/BHYVE_UEFI.fd -s 3,e1000,tap20,mac=00:A0:98:13:88:1F -s 4:0,virtio-blk,/dev/zvol/Tank/VM/sysman 13_sysman
[2019/02/03 11:27:34] (DEBUG) VMService.run():286 - sysman: vm_reinit: Device busy
[2019/02/03 11:27:34] (INFO) VMService.run():311 - ===> Error VM: sysman ID: 13 BHYVE_CODE: 4
[2019/02/03 11:27:34] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:34] (DEBUG) VMService.__teardown_guest_vmemory():338 - ===> Give back guest memory to ARC: -15519911936
[2019/02/03 11:27:34] (WARNING) application.call_method():189 - Exception while calling vm.start(*[13, {'overcommit': True}])
Traceback (most recent call last):
File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 161, in call_method
result = await self.middleware.call_method(self, message)
File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1109, in call_method
return await self._call(message['method'], serviceobj, methodobj, params, app=app, io_thread=False)
File "/usr/local/lib/python3.6/site-packages/middlewared/main.py", line 1049, in call
return await methodobj(*args)
File "/usr/local/lib/python3.6/site-packages/middlewared/schema.py", line 664, in nf
return await f(*args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/vm.py", line 1132, in start
await self._manager.start(vm)
File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/vm.py", line 61, in start
list(done)[0].result()
File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/vm.py", line 312, in run
await self.
_teardown_guest_vmemory(self.vm['id'])
File "/usr/local/lib/python3.6/site-packages/middlewared/plugins/vm.py", line 339, in __teardown_guest_vmemory
sysctl.filter('vfs.zfs.arc_max')[0].value = new_arc_max
TypeError: Invalid argument
[2019/02/03 11:27:34] (DEBUG) middlewared.logger.CrashReporting.report():103 - Sending a crash report...
[2019/02/03 11:27:34] (DEBUG) raven.base.Client.send_remote():716 - Sending message of length 4116 to https://sentry.ixsystems.com/api/2/store/
[2019/02/03 11:27:37] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.
[2019/02/03 11:27:42] (ERROR) VMService.running():438 - ===> VMM sysman is running without bhyve process.


Related issues

Has duplicate FreeNAS - Bug #73011: Errors from VM manager after upgrade to 11.2 U1 (from 11.1) and very slow diskClosed
Copied to FreeNAS - Bug #73729: VM does not startDone

History

#1 Updated by Dru Lavigne almost 3 years ago

  • Assignee changed from Release Council to Vladimir Vinogradenko
  • Private changed from No to Yes

#2 Updated by Vladimir Vinogradenko almost 3 years ago

  • Status changed from Unscreened to In Progress

Ton, the error message for starting VM is

vm_reinit: Device busy

Which can mean some resource conflict.

In this ticket we'll handle stack trace being shown instead of error.

#3 Updated by Vladimir Vinogradenko almost 3 years ago

Acceptance Criteria

Start a VM. Ensure it is running.

On the host machine run the following command:

python -c "import sysctl; sysctl.filter('vfs.zfs.arc_max')[0].value = sysctl.filter('vfs.zfs.arc_min')[0].value" 

Then stop the VM and inspect the end of /var/log/middleware.log. No stack trace like above should appear after

===> Stopping VM: ... ID: ...

#4 Updated by Ton S almost 3 years ago

When I run the python command I get the following error:

Traceback (most recent call last):
File "<string>", line 1, in <module>
TypeError: Operation not permitted

#5 Updated by Bug Clerk almost 3 years ago

#6 Updated by Vladimir Vinogradenko almost 3 years ago

Ton, you don't need to run this command, this is for out QA department.

But "Operation not permitted" is an interesting error, did you ran this as root?

#7 Updated by Dru Lavigne almost 3 years ago

  • Target version changed from Backlog to 11.2-U3

#8 Updated by Bug Clerk almost 3 years ago

  • Status changed from In Progress to Ready for Testing

#9 Updated by Dru Lavigne almost 3 years ago

  • File deleted (debug-freenas-20190203122903.tgz)

#10 Updated by Dru Lavigne almost 3 years ago

  • Subject changed from VM does not start to Prevent setting vfs.zfs.arc_max to lower than vfs.zfs.arc_min
  • Private changed from Yes to No
  • Needs Doc changed from Yes to No
  • Needs Merging changed from Yes to No

#11 Updated by Vladimir Vinogradenko almost 3 years ago

  • Has duplicate Bug #73011: Errors from VM manager after upgrade to 11.2 U1 (from 11.1) and very slow disk added

#14 Avatar?id=55038&size=24x24 Updated by Zackary Welch over 2 years ago

  • Status changed from Ready for Testing to Passed Testing
  • Needs QA changed from Yes to No

I am unable to set vfs.zfs.arc_max lower than vfs.zfs.arc_min, and I see no related sysctl error in /var/log/middlewared.log.

#16 Updated by Dru Lavigne over 2 years ago

  • Status changed from Passed Testing to Done

Also available in: Atom PDF