Libvirt interactions hang web interface

Support
1

I've just updated to Foreman 1.7.3 and unsure if the update or some other
factor is causing issues but when I go to edit a host that's compute
resource is libvirt the web interface just hangs. I've noticed when I look
at the running processes under foreman user I see entries like this:

ssh <KVM host FQDN> sh -c 'if 'nc' -q 2>&1 | grep "requires an argument"
>/dev/null 2>&1; then ARG=-q0;else ARG=;fi;'nc' $ARG -U
/var/run/libvirt/libvirt-sock'

If I manually kill those processes the web interface begins to respond but
the virtual machine tab says the host couldn't be found and other pages
that rely on communicating with libvirt also fail.

I am able to to access the virsh console just fine as the foreman user. I
have noticed that sometimes attempts to execute a virsh command hang. I'm
unsure if this is an issue related to libvirt or where to even begin
debugging. I very much want to get rid of these libvirt systems as I'm
migrating to oVirt but until I can get the cycles to migrate everything I'm
stuck with libvirt and would like to ensure I can manage everything.

If I enable debug on the foreman side, below is what I get when the virsh
connection hangs.

Any suggestions?

Thanks,

  • Trey

$ LIBVIRT_DEBUG=1 virsh -c qemu+ssh://foreman@KVM_FQDN_OMIT/system list
2015-03-18 17:23:50.457+0000: 21710: info : libvirt version: 0.10.2,
package: 29.el6_5.12 (CentOS BuildSystem <http://bugs.centos.org>,
2014-09-01-13:44:02, c6b8.bsys.dev.centos.org)
2015-03-18 17:23:50.457+0000: 21710: debug : virInitialize:421 : register
drivers
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 :
driver=0x7fe1e92bf080 name=Test
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 :
registering Test as driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNetworkDriver:561 :
registering Test as network driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterInterfaceDriver:591
: registering Test as interface driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterStorageDriver:621 :
registering Test as storage driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDeviceMonitor:651 :
registering Test as device driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681 :
registering Test as secret driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNWFilterDriver:711
: registering Test as network filter driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 :
driver=0x7fe1e92c0640 name=ESX
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 :
registering ESX as driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterInterfaceDriver:591
: registering ESX as interface driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNetworkDriver:561 :
registering ESX as network driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterStorageDriver:621 :
registering ESX as storage driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDeviceMonitor:651 :
registering ESX as device driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681 :
registering ESX as secret driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNWFilterDriver:711
: registering ESX as network filter driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 :
driver=0x7fe1e92bfa20 name=remote
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 :
registering remote as driver 2
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNetworkDriver:561 :
registering remote as network driver 2
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterInterfaceDriver:591
: registering remote as interface driver 2
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterStorageDriver:621 :
registering remote as storage driver 2
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDeviceMonitor:651 :
registering remote as device driver 2
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681 :
registering remote as secret driver 2
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNWFilterDriver:711
: registering remote as network filter driver 2
2015-03-18 17:23:50.544+0000: 21710: debug :
virEventRegisterDefaultImpl:204 : registering default event implementation
2015-03-18 17:23:50.544+0000: 21710: debug : virEventPollAddHandle:111 :
Used 0 handle slots, adding at least 10 more
2015-03-18 17:23:50.545+0000: 21710: debug :
virEventPollInterruptLocked:697 : Skip interrupt, 0 0
2015-03-18 17:23:50.545+0000: 21710: debug : virEventPollAddHandle:136 :
EVENT_POLL_ADD_HANDLE: watch=1 fd=4 events=1 cb=0x7fe1e8ed3770 opaque=(nil)
ff=(nil)
2015-03-18 17:23:50.545+0000: 21710: debug : virEventRegisterImpl:177 :
addHandle=0x7fe1e8ed49f0 updateHandle=0x7fe1e8ed3a10
removeHandle=0x7fe1e8ed38c0 addTimeout=0x7fe1e8ed4820
updateTimeout=0x7fe1e8ed3b30 removeTimeout=0x7fe1e8ed37b0
2015-03-18 17:23:50.545+0000: 21710: debug : virConnectOpenAuth:1405 :
name=qemu+ssh://foreman@KVM_FQDN_OMIT/system, auth=0x7fe1e92befe0, flags=0
2015-03-18 17:23:50.545+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW:
obj=0x94db00 classname=virConnect
2015-03-18 17:23:50.545+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW:
obj=0x94dca0 classname=virConnectCloseCallbackData
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1127 : name
"qemu+ssh://foreman@KVM_FQDN_OMIT/system" to URI components:
scheme qemu+ssh
server KVM_FQDN_OMIT
user foreman
port 0
path /system

2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying driver 0
(Test) …
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1180 : driver 0 Test
returned DECLINED
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying driver 1
(ESX) …
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1180 : driver 1 ESX
returned DECLINED
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying driver 2
(remote) …
2015-03-18 17:23:50.545+0000: 21710: debug : doRemoteOpen:584 : proceeding
with name = qemu:///system
2015-03-18 17:23:50.546+0000: 21710: debug : doRemoteOpen:593 : Connecting
with transport 2
2015-03-18 17:23:50.546+0000: 21710: debug : virCommandRunAsync:2229 :
About to run LC_ALL=C PATH=/sbin:/bin:/usr/sbin:/usr/bin
HOME=/usr/share/foreman USER=foreman LOGNAME=foreman ssh -l foreman
KVM_FQDN_OMIT sh -c ''&#39;'if '&#39;'nc'&#39;' -q 2>&1 | grep "requires an
argument" >/dev/null 2>&1; then ARG=-q0;else ARG=;fi;'&#39;'nc'&#39;' $ARG -U
/var/run/libvirt/libvirt-sock'&#39;''
2015-03-18 17:23:50.547+0000: 21710: debug : virCommandRunAsync:2250 :
Command result 0, with PID 21712
2015-03-18 17:23:50.547+0000: 21710: debug : virFileClose:72 : Closed fd 7
2015-03-18 17:23:50.547+0000: 21710: debug : virFileClose:72 : Closed fd 9
2015-03-18 17:23:50.547+0000: 21710: debug : virNetSocketNew:147 :
localAddr=(nil) remoteAddr=(nil) fd=6 errfd=8 pid=21712
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW:
obj=0x94f1e0 classname=virNetSocket
2015-03-18 17:23:50.547+0000: 21710: debug : virNetSocketNew:204 :
RPC_SOCKET_NEW: sock=0x94f1e0 fd=6 errfd=8 pid=21712 localAddr=(null),
remoteAddr=(null)
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW:
obj=0x94de30 classname=virNetClient
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientNew:342 :
RPC_CLIENT_NEW: client=0x94de30 sock=0x94f1e0
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF:
obj=0x94de30
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF:
obj=0x94f1e0
2015-03-18 17:23:50.547+0000: 21710: debug :
virEventPollInterruptLocked:697 : Skip interrupt, 0 0
2015-03-18 17:23:50.547+0000: 21710: debug : virEventPollAddHandle:136 :
EVENT_POLL_ADD_HANDLE: watch=2 fd=6 events=1 cb=0x7fe1e8fc9350
opaque=0x94f1e0 ff=0x7fe1e8fc9740
2015-03-18 17:23:50.547+0000: 21710: debug : virKeepAliveNew:212 :
client=0x94de30, interval=-1, count=0
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW:
obj=0x94e280 classname=virKeepAlive
2015-03-18 17:23:50.547+0000: 21710: debug : virKeepAliveNew:236 :
RPC_KEEPALIVE_NEW: ka=0x94e280 client=0x94de30
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF:
obj=0x94de30
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF:
obj=0x94dca0
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW:
obj=0x94e310 classname=virNetClientProgram
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW:
obj=0x94e050 classname=virNetClientProgram
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF:
obj=0x94e310
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF:
obj=0x94e050
2015-03-18 17:23:50.547+0000: 21710: debug : doRemoteOpen:790 : Trying
authentication
2015-03-18 17:23:50.547+0000: 21710: debug : virNetMessageNew:45 :
msg=0x94f3b0 tracked=0
2015-03-18 17:23:50.547+0000: 21710: debug : virNetMessageEncodePayload:377
: Encode length as 28
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientSendInternal:1958
: RPC_CLIENT_MSG_TX_QUEUE: client=0x94de30 len=28 prog=536903814 vers=1
proc=66 type=0 status=0 serial=0
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientCallNew:1911 : New
call 0x94f170: msg=0x94f3b0, expectReply=1, nonBlock=0
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientIO:1718 : Outgoing
message prog=536903814 version=1 serial=0 proc=66 type=0 length=28
dispatch=(nil)
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientIO:1777 : We have
the buck head=0x94f170 call=0x94f170
2015-03-18 17:23:50.547+0000: 21710: debug : virEventPollUpdateHandle:146 :
EVENT_POLL_UPDATE_HANDLE: watch=2 events=0
2015-03-18 17:23:50.547+0000: 21710: debug :
virEventPollInterruptLocked:697 : Skip interrupt, 0 0
2015-03-18 17:23:50.548+0000: 21711: debug : virEventRunDefaultImpl:244 :
running default event implementation
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCleanupTimeouts:501 : Cleanup 0
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCleanupTimeouts:537 : Found 0 out of 0 timeout slots used,
releasing 0
2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollCleanupHandles:549
: Cleanup 2
2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollMakePollFDs:378 :
Prepare n=0 w=1, f=4 e=1 d=0
2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollMakePollFDs:378 :
Prepare n=1 w=2, f=6 e=0 d=0
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCalculateTimeout:320 : Calculate expiry of 0 timers
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCalculateTimeout:346 : Timeout at 0 due in -1 ms
2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollRunOnce:614 :
EVENT_POLL_RUN: nhandles=1 timeout=-1
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 3
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 4
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 5
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 6
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 8

2

Have you found a solution for that?

LZ

··· On Wed, Mar 18, 2015 at 10:29:26AM -0700, treydock wrote: > I've just updated to Foreman 1.7.3 and unsure if the update or some other > factor is causing issues but when I go to edit a host that's compute > resource is libvirt the web interface just hangs. I've noticed when I look > at the running processes under foreman user I see entries like this: > > ssh sh -c 'if 'nc' -q 2>&1 | grep "requires an argument" > >/dev/null 2>&1; then ARG=-q0;else ARG=;fi;'nc' $ARG -U > /var/run/libvirt/libvirt-sock' > > If I manually kill those processes the web interface begins to respond but > the virtual machine tab says the host couldn't be found and other pages > that rely on communicating with libvirt also fail. > > I am able to to access the virsh console just fine as the foreman user. I > have noticed that sometimes attempts to execute a virsh command hang. I'm > unsure if this is an issue related to libvirt or where to even begin > debugging. I very much want to get rid of these libvirt systems as I'm > migrating to oVirt but until I can get the cycles to migrate everything I'm > stuck with libvirt and would like to ensure I can manage everything. > > If I enable debug on the foreman side, below is what I get when the virsh > connection hangs. > > Any suggestions? > > Thanks, > - Trey > > $ LIBVIRT_DEBUG=1 virsh -c qemu+ssh://foreman@KVM_FQDN_OMIT/system list > 2015-03-18 17:23:50.457+0000: 21710: info : libvirt version: 0.10.2, > package: 29.el6_5.12 (CentOS BuildSystem , > 2014-09-01-13:44:02, c6b8.bsys.dev.centos.org) > 2015-03-18 17:23:50.457+0000: 21710: debug : virInitialize:421 : register > drivers > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 : > driver=0x7fe1e92bf080 name=Test > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 : > registering Test as driver 0 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNetworkDriver:561 : > registering Test as network driver 0 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterInterfaceDriver:591 > : registering Test as interface driver 0 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterStorageDriver:621 : > registering Test as storage driver 0 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDeviceMonitor:651 : > registering Test as device driver 0 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681 : > registering Test as secret driver 0 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNWFilterDriver:711 > : registering Test as network filter driver 0 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 : > driver=0x7fe1e92c0640 name=ESX > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 : > registering ESX as driver 1 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterInterfaceDriver:591 > : registering ESX as interface driver 1 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNetworkDriver:561 : > registering ESX as network driver 1 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterStorageDriver:621 : > registering ESX as storage driver 1 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDeviceMonitor:651 : > registering ESX as device driver 1 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681 : > registering ESX as secret driver 1 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNWFilterDriver:711 > : registering ESX as network filter driver 1 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 : > driver=0x7fe1e92bfa20 name=remote > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 : > registering remote as driver 2 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNetworkDriver:561 : > registering remote as network driver 2 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterInterfaceDriver:591 > : registering remote as interface driver 2 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterStorageDriver:621 : > registering remote as storage driver 2 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDeviceMonitor:651 : > registering remote as device driver 2 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681 : > registering remote as secret driver 2 > 2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterNWFilterDriver:711 > : registering remote as network filter driver 2 > 2015-03-18 17:23:50.544+0000: 21710: debug : > virEventRegisterDefaultImpl:204 : registering default event implementation > 2015-03-18 17:23:50.544+0000: 21710: debug : virEventPollAddHandle:111 : > Used 0 handle slots, adding at least 10 more > 2015-03-18 17:23:50.545+0000: 21710: debug : > virEventPollInterruptLocked:697 : Skip interrupt, 0 0 > 2015-03-18 17:23:50.545+0000: 21710: debug : virEventPollAddHandle:136 : > EVENT_POLL_ADD_HANDLE: watch=1 fd=4 events=1 cb=0x7fe1e8ed3770 opaque=(nil) > ff=(nil) > 2015-03-18 17:23:50.545+0000: 21710: debug : virEventRegisterImpl:177 : > addHandle=0x7fe1e8ed49f0 updateHandle=0x7fe1e8ed3a10 > removeHandle=0x7fe1e8ed38c0 addTimeout=0x7fe1e8ed4820 > updateTimeout=0x7fe1e8ed3b30 removeTimeout=0x7fe1e8ed37b0 > 2015-03-18 17:23:50.545+0000: 21710: debug : virConnectOpenAuth:1405 : > name=qemu+ssh://foreman@KVM_FQDN_OMIT/system, auth=0x7fe1e92befe0, flags=0 > 2015-03-18 17:23:50.545+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW: > obj=0x94db00 classname=virConnect > 2015-03-18 17:23:50.545+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW: > obj=0x94dca0 classname=virConnectCloseCallbackData > 2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1127 : name > "qemu+ssh://foreman@KVM_FQDN_OMIT/system" to URI components: > scheme qemu+ssh > server KVM_FQDN_OMIT > user foreman > port 0 > path /system > > 2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying driver 0 > (Test) ... > 2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1180 : driver 0 Test > returned DECLINED > 2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying driver 1 > (ESX) ... > 2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1180 : driver 1 ESX > returned DECLINED > 2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying driver 2 > (remote) ... > 2015-03-18 17:23:50.545+0000: 21710: debug : doRemoteOpen:584 : proceeding > with name = qemu:///system > 2015-03-18 17:23:50.546+0000: 21710: debug : doRemoteOpen:593 : Connecting > with transport 2 > 2015-03-18 17:23:50.546+0000: 21710: debug : virCommandRunAsync:2229 : > About to run LC_ALL=C PATH=/sbin:/bin:/usr/sbin:/usr/bin > HOME=/usr/share/foreman USER=foreman LOGNAME=foreman ssh -l foreman > KVM_FQDN_OMIT sh -c ''\''if '\''nc'\'' -q 2>&1 | grep "requires an > argument" >/dev/null 2>&1; then ARG=-q0;else ARG=;fi;'\''nc'\'' $ARG -U > /var/run/libvirt/libvirt-sock'\''' > 2015-03-18 17:23:50.547+0000: 21710: debug : virCommandRunAsync:2250 : > Command result 0, with PID 21712 > 2015-03-18 17:23:50.547+0000: 21710: debug : virFileClose:72 : Closed fd 7 > 2015-03-18 17:23:50.547+0000: 21710: debug : virFileClose:72 : Closed fd 9 > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetSocketNew:147 : > localAddr=(nil) remoteAddr=(nil) fd=6 errfd=8 pid=21712 > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW: > obj=0x94f1e0 classname=virNetSocket > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetSocketNew:204 : > RPC_SOCKET_NEW: sock=0x94f1e0 fd=6 errfd=8 pid=21712 localAddr=(null), > remoteAddr=(null) > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW: > obj=0x94de30 classname=virNetClient > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientNew:342 : > RPC_CLIENT_NEW: client=0x94de30 sock=0x94f1e0 > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF: > obj=0x94de30 > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF: > obj=0x94f1e0 > 2015-03-18 17:23:50.547+0000: 21710: debug : > virEventPollInterruptLocked:697 : Skip interrupt, 0 0 > 2015-03-18 17:23:50.547+0000: 21710: debug : virEventPollAddHandle:136 : > EVENT_POLL_ADD_HANDLE: watch=2 fd=6 events=1 cb=0x7fe1e8fc9350 > opaque=0x94f1e0 ff=0x7fe1e8fc9740 > 2015-03-18 17:23:50.547+0000: 21710: debug : virKeepAliveNew:212 : > client=0x94de30, interval=-1, count=0 > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW: > obj=0x94e280 classname=virKeepAlive > 2015-03-18 17:23:50.547+0000: 21710: debug : virKeepAliveNew:236 : > RPC_KEEPALIVE_NEW: ka=0x94e280 client=0x94de30 > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF: > obj=0x94de30 > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF: > obj=0x94dca0 > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW: > obj=0x94e310 classname=virNetClientProgram > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 : OBJECT_NEW: > obj=0x94e050 classname=virNetClientProgram > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF: > obj=0x94e310 > 2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 : OBJECT_REF: > obj=0x94e050 > 2015-03-18 17:23:50.547+0000: 21710: debug : doRemoteOpen:790 : Trying > authentication > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetMessageNew:45 : > msg=0x94f3b0 tracked=0 > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetMessageEncodePayload:377 > : Encode length as 28 > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientSendInternal:1958 > : RPC_CLIENT_MSG_TX_QUEUE: client=0x94de30 len=28 prog=536903814 vers=1 > proc=66 type=0 status=0 serial=0 > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientCallNew:1911 : New > call 0x94f170: msg=0x94f3b0, expectReply=1, nonBlock=0 > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientIO:1718 : Outgoing > message prog=536903814 version=1 serial=0 proc=66 type=0 length=28 > dispatch=(nil) > 2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientIO:1777 : We have > the buck head=0x94f170 call=0x94f170 > 2015-03-18 17:23:50.547+0000: 21710: debug : virEventPollUpdateHandle:146 : > EVENT_POLL_UPDATE_HANDLE: watch=2 events=0 > 2015-03-18 17:23:50.547+0000: 21710: debug : > virEventPollInterruptLocked:697 : Skip interrupt, 0 0 > 2015-03-18 17:23:50.548+0000: 21711: debug : virEventRunDefaultImpl:244 : > running default event implementation > 2015-03-18 17:23:50.548+0000: 21711: debug : > virEventPollCleanupTimeouts:501 : Cleanup 0 > 2015-03-18 17:23:50.548+0000: 21711: debug : > virEventPollCleanupTimeouts:537 : Found 0 out of 0 timeout slots used, > releasing 0 > 2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollCleanupHandles:549 > : Cleanup 2 > 2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollMakePollFDs:378 : > Prepare n=0 w=1, f=4 e=1 d=0 > 2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollMakePollFDs:378 : > Prepare n=1 w=2, f=6 e=0 d=0 > 2015-03-18 17:23:50.548+0000: 21711: debug : > virEventPollCalculateTimeout:320 : Calculate expiry of 0 timers > 2015-03-18 17:23:50.548+0000: 21711: debug : > virEventPollCalculateTimeout:346 : Timeout at 0 due in -1 ms > 2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollRunOnce:614 : > EVENT_POLL_RUN: nhandles=1 timeout=-1 > 2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 3 > 2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 4 > 2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 5 > 2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 6 > 2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd 8 > > -- > You received this message because you are subscribed to the Google Groups "Foreman users" group. > To unsubscribe from this group and stop receiving emails from it, send an email to foreman-users+unsubscribe@googlegroups.com. > To post to this group, send email to foreman-users@googlegroups.com. > Visit this group at http://groups.google.com/group/foreman-users. > For more options, visit https://groups.google.com/d/optout.

–
Later,
Lukas #lzap Zapletal

3

I have not. For now I've just avoided using these hosts in the web
interface.

  • Trey
··· On Fri, Apr 3, 2015 at 2:56 PM, Lukas Zapletal wrote:

Have you found a solution for that?

LZ

On Wed, Mar 18, 2015 at 10:29:26AM -0700, treydock wrote:

I’ve just updated to Foreman 1.7.3 and unsure if the update or some other
factor is causing issues but when I go to edit a host that’s compute
resource is libvirt the web interface just hangs. I’ve noticed when I
look
at the running processes under foreman user I see entries like this:

ssh sh -c 'if ‘nc’ -q 2>&1 | grep “requires an argument”

/dev/null 2>&1; then ARG=-q0;else ARG=;fi;‘nc’ $ARG -U
/var/run/libvirt/libvirt-sock’

If I manually kill those processes the web interface begins to respond
but
the virtual machine tab says the host couldn’t be found and other pages
that rely on communicating with libvirt also fail.

I am able to to access the virsh console just fine as the foreman user.
I
have noticed that sometimes attempts to execute a virsh command hang.
I’m
unsure if this is an issue related to libvirt or where to even begin
debugging. I very much want to get rid of these libvirt systems as I’m
migrating to oVirt but until I can get the cycles to migrate everything
I’m
stuck with libvirt and would like to ensure I can manage everything.

If I enable debug on the foreman side, below is what I get when the virsh
connection hangs.

Any suggestions?

Thanks,

  • Trey

$ LIBVIRT_DEBUG=1 virsh -c qemu+ssh://foreman@KVM_FQDN_OMIT/system list
2015-03-18 17:23:50.457+0000: 21710: info : libvirt version: 0.10.2,
package: 29.el6_5.12 (CentOS BuildSystem http://bugs.centos.org,
2014-09-01-13:44:02, c6b8.bsys.dev.centos.org)
2015-03-18 17:23:50.457+0000: 21710: debug : virInitialize:421 : register
drivers
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 :
driver=0x7fe1e92bf080 name=Test
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 :
registering Test as driver 0
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterNetworkDriver:561 :
registering Test as network driver 0
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterInterfaceDriver:591
: registering Test as interface driver 0
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterStorageDriver:621 :
registering Test as storage driver 0
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterDeviceMonitor:651 :
registering Test as device driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681
:
registering Test as secret driver 0
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterNWFilterDriver:711
: registering Test as network filter driver 0
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 :
driver=0x7fe1e92c0640 name=ESX
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 :
registering ESX as driver 1
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterInterfaceDriver:591
: registering ESX as interface driver 1
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterNetworkDriver:561 :
registering ESX as network driver 1
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterStorageDriver:621 :
registering ESX as storage driver 1
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterDeviceMonitor:651 :
registering ESX as device driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681
:
registering ESX as secret driver 1
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterNWFilterDriver:711
: registering ESX as network filter driver 1
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:729 :
driver=0x7fe1e92bfa20 name=remote
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterDriver:744 :
registering remote as driver 2
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterNetworkDriver:561 :
registering remote as network driver 2
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterInterfaceDriver:591
: registering remote as interface driver 2
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterStorageDriver:621 :
registering remote as storage driver 2
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterDeviceMonitor:651 :
registering remote as device driver 2
2015-03-18 17:23:50.544+0000: 21710: debug : virRegisterSecretDriver:681
:
registering remote as secret driver 2
2015-03-18 17:23:50.544+0000: 21710: debug :
virRegisterNWFilterDriver:711
: registering remote as network filter driver 2
2015-03-18 17:23:50.544+0000: 21710: debug :
virEventRegisterDefaultImpl:204 : registering default event
implementation
2015-03-18 17:23:50.544+0000: 21710: debug : virEventPollAddHandle:111 :
Used 0 handle slots, adding at least 10 more
2015-03-18 17:23:50.545+0000: 21710: debug :
virEventPollInterruptLocked:697 : Skip interrupt, 0 0
2015-03-18 17:23:50.545+0000: 21710: debug : virEventPollAddHandle:136 :
EVENT_POLL_ADD_HANDLE: watch=1 fd=4 events=1 cb=0x7fe1e8ed3770
opaque=(nil)
ff=(nil)
2015-03-18 17:23:50.545+0000: 21710: debug : virEventRegisterImpl:177 :
addHandle=0x7fe1e8ed49f0 updateHandle=0x7fe1e8ed3a10
removeHandle=0x7fe1e8ed38c0 addTimeout=0x7fe1e8ed4820
updateTimeout=0x7fe1e8ed3b30 removeTimeout=0x7fe1e8ed37b0
2015-03-18 17:23:50.545+0000: 21710: debug : virConnectOpenAuth:1405 :
name=qemu+ssh://foreman@KVM_FQDN_OMIT/system, auth=0x7fe1e92befe0,
flags=0
2015-03-18 17:23:50.545+0000: 21710: debug : virObjectNew:110 :
OBJECT_NEW:
obj=0x94db00 classname=virConnect
2015-03-18 17:23:50.545+0000: 21710: debug : virObjectNew:110 :
OBJECT_NEW:
obj=0x94dca0 classname=virConnectCloseCallbackData
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1127 : name
"qemu+ssh://foreman@KVM_FQDN_OMIT/system" to URI components:
scheme qemu+ssh
server KVM_FQDN_OMIT
user foreman
port 0
path /system

2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying
driver 0
(Test) …
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1180 : driver 0 Test
returned DECLINED
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying
driver 1
(ESX) …
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1180 : driver 1 ESX
returned DECLINED
2015-03-18 17:23:50.545+0000: 21710: debug : do_open:1174 : trying
driver 2
(remote) …
2015-03-18 17:23:50.545+0000: 21710: debug : doRemoteOpen:584 :
proceeding
with name = qemu:///system
2015-03-18 17:23:50.546+0000: 21710: debug : doRemoteOpen:593 :
Connecting
with transport 2
2015-03-18 17:23:50.546+0000: 21710: debug : virCommandRunAsync:2229 :
About to run LC_ALL=C PATH=/sbin:/bin:/usr/sbin:/usr/bin
HOME=/usr/share/foreman USER=foreman LOGNAME=foreman ssh -l foreman
KVM_FQDN_OMIT sh -c ‘’’‘if ‘’‘nc’’’ -q 2>&1 | grep “requires an
argument” >/dev/null 2>&1; then ARG=-q0;else ARG=;fi;’’‘nc’’’ $ARG -U
/var/run/libvirt/libvirt-sock’’’'
2015-03-18 17:23:50.547+0000: 21710: debug : virCommandRunAsync:2250 :
Command result 0, with PID 21712
2015-03-18 17:23:50.547+0000: 21710: debug : virFileClose:72 : Closed fd
7
2015-03-18 17:23:50.547+0000: 21710: debug : virFileClose:72 : Closed fd
9
2015-03-18 17:23:50.547+0000: 21710: debug : virNetSocketNew:147 :
localAddr=(nil) remoteAddr=(nil) fd=6 errfd=8 pid=21712
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 :
OBJECT_NEW:
obj=0x94f1e0 classname=virNetSocket
2015-03-18 17:23:50.547+0000: 21710: debug : virNetSocketNew:204 :
RPC_SOCKET_NEW: sock=0x94f1e0 fd=6 errfd=8 pid=21712 localAddr=(null),
remoteAddr=(null)
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 :
OBJECT_NEW:
obj=0x94de30 classname=virNetClient
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientNew:342 :
RPC_CLIENT_NEW: client=0x94de30 sock=0x94f1e0
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 :
OBJECT_REF:
obj=0x94de30
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 :
OBJECT_REF:
obj=0x94f1e0
2015-03-18 17:23:50.547+0000: 21710: debug :
virEventPollInterruptLocked:697 : Skip interrupt, 0 0
2015-03-18 17:23:50.547+0000: 21710: debug : virEventPollAddHandle:136 :
EVENT_POLL_ADD_HANDLE: watch=2 fd=6 events=1 cb=0x7fe1e8fc9350
opaque=0x94f1e0 ff=0x7fe1e8fc9740
2015-03-18 17:23:50.547+0000: 21710: debug : virKeepAliveNew:212 :
client=0x94de30, interval=-1, count=0
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 :
OBJECT_NEW:
obj=0x94e280 classname=virKeepAlive
2015-03-18 17:23:50.547+0000: 21710: debug : virKeepAliveNew:236 :
RPC_KEEPALIVE_NEW: ka=0x94e280 client=0x94de30
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 :
OBJECT_REF:
obj=0x94de30
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 :
OBJECT_REF:
obj=0x94dca0
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 :
OBJECT_NEW:
obj=0x94e310 classname=virNetClientProgram
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectNew:110 :
OBJECT_NEW:
obj=0x94e050 classname=virNetClientProgram
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 :
OBJECT_REF:
obj=0x94e310
2015-03-18 17:23:50.547+0000: 21710: debug : virObjectRef:168 :
OBJECT_REF:
obj=0x94e050
2015-03-18 17:23:50.547+0000: 21710: debug : doRemoteOpen:790 : Trying
authentication
2015-03-18 17:23:50.547+0000: 21710: debug : virNetMessageNew:45 :
msg=0x94f3b0 tracked=0
2015-03-18 17:23:50.547+0000: 21710: debug :
virNetMessageEncodePayload:377
: Encode length as 28
2015-03-18 17:23:50.547+0000: 21710: debug :
virNetClientSendInternal:1958
: RPC_CLIENT_MSG_TX_QUEUE: client=0x94de30 len=28 prog=536903814 vers=1
proc=66 type=0 status=0 serial=0
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientCallNew:1911 :
New
call 0x94f170: msg=0x94f3b0, expectReply=1, nonBlock=0
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientIO:1718 :
Outgoing
message prog=536903814 version=1 serial=0 proc=66 type=0 length=28
dispatch=(nil)
2015-03-18 17:23:50.547+0000: 21710: debug : virNetClientIO:1777 : We
have
the buck head=0x94f170 call=0x94f170
2015-03-18 17:23:50.547+0000: 21710: debug :
virEventPollUpdateHandle:146 :
EVENT_POLL_UPDATE_HANDLE: watch=2 events=0
2015-03-18 17:23:50.547+0000: 21710: debug :
virEventPollInterruptLocked:697 : Skip interrupt, 0 0
2015-03-18 17:23:50.548+0000: 21711: debug : virEventRunDefaultImpl:244 :
running default event implementation
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCleanupTimeouts:501 : Cleanup 0
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCleanupTimeouts:537 : Found 0 out of 0 timeout slots used,
releasing 0
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCleanupHandles:549
: Cleanup 2
2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollMakePollFDs:378
:
Prepare n=0 w=1, f=4 e=1 d=0
2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollMakePollFDs:378
:
Prepare n=1 w=2, f=6 e=0 d=0
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCalculateTimeout:320 : Calculate expiry of 0 timers
2015-03-18 17:23:50.548+0000: 21711: debug :
virEventPollCalculateTimeout:346 : Timeout at 0 due in -1 ms
2015-03-18 17:23:50.548+0000: 21711: debug : virEventPollRunOnce:614 :
EVENT_POLL_RUN: nhandles=1 timeout=-1
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd
3
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd
4
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd
5
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd
6
2015-03-18 17:23:50.549+0000: 21712: debug : virFileClose:72 : Closed fd
8

–
You received this message because you are subscribed to the Google
Groups “Foreman users” group.
To unsubscribe from this group and stop receiving emails from it, send
an email to foreman-users+unsubscribe@googlegroups.com.
To post to this group, send email to foreman-users@googlegroups.com.
Visit this group at http://groups.google.com/group/foreman-users.
For more options, visit https://groups.google.com/d/optout.

–
Later,
Lukas #lzap Zapletal

–
You received this message because you are subscribed to a topic in the
Google Groups “Foreman users” group.
To unsubscribe from this topic, visit
https://groups.google.com/d/topic/foreman-users/enO9TzFfihI/unsubscribe.
To unsubscribe from this group and all its topics, send an email to
foreman-users+unsubscribe@googlegroups.com.
To post to this group, send email to foreman-users@googlegroups.com.
Visit this group at http://groups.google.com/group/foreman-users.
For more options, visit https://groups.google.com/d/optout.

4

> I have not. For now I've just avoided using these hosts in the web
> interface.

When you do a manual ssh connection from the foreman server and foreman
user account, do you experience the same delay?

Ssh client/server is sometimes mis-configured in regards to DNS checking
or Kerberos causing long delays (tens of seconds to minutes) before
allowing you in.

··· -- Later, Lukas #lzap Zapletal
5

Sorry for delay, email got buried. This was solved. The libvirt host
still had a storage volume added that no longer existed (NFS). Somehow
this caused all virsh commands to hang. The mount was still in libvirt and
fstab and mounted but the NFS server had been decommissioned. Once I
forced unmount and removed from libvirt all virsh commands began working.

Thanks

  • Trey
··· On Apr 9, 2015 6:11 AM, "Lukas Zapletal" wrote:

I have not. For now I’ve just avoided using these hosts in the web
interface.

When you do a manual ssh connection from the foreman server and foreman
user account, do you experience the same delay?

Ssh client/server is sometimes mis-configured in regards to DNS checking
or Kerberos causing long delays (tens of seconds to minutes) before
allowing you in.

–
Later,
Lukas #lzap Zapletal

–
You received this message because you are subscribed to a topic in the
Google Groups “Foreman users” group.
To unsubscribe from this topic, visit
https://groups.google.com/d/topic/foreman-users/enO9TzFfihI/unsubscribe.
To unsubscribe from this group and all its topics, send an email to
foreman-users+unsubscribe@googlegroups.com.
To post to this group, send email to foreman-users@googlegroups.com.
Visit this group at http://groups.google.com/group/foreman-users.
For more options, visit https://groups.google.com/d/optout.

6

I am facing same issue with KVM in foreman/katello Version 3.0.1.
I identified it makes new proccess eg. connection when i refresh or open Virtual machne which is provisioned on KVM host in foreman UI.

IN KVM machine

sh -c if nc -q 2>&1 | grep "requires an argument" >/dev/null 2>&1; then ARG=-q0;else ARG=;fi;nc $ARG -U /var/run/libvirt/libvirt-sock

IN Foreman/Katello

ssh -l root -- kvm.server.local sh -c 'if 'nc' -q 2>&1 | grep "requires an argument" >/dev/null 2>&1; then ARG=-q0;else ARG=;fi;'nc' $ARG -U /var/run/libvirt/libvirt-sock'

The problem is it makes everytime new process if i refresh page same page with Virtual machne which is provisioned on KVM host in foreman UI. So they hangs and does not die or dissaper…

Ssh keys is in place. And foreman user can ssh into kvm machine as root.

Could you help me fix the problem?

7

Upgrade to 3.1 to fix the SSH connection leak errors:

Or apply that patch onto your instance. Report back if that helps!

8

Thank you, will do as soon as i can. I will let you know the result then.

9

Seems liks upgrade fixed this issue.

1 Like