You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Ian Young <iy...@ratespecial.com> on 2014/05/21 03:21:19 UTC
console proxy times out
So I got the console proxy working via HTTPS (by managing my own "
realhostip.com" DNS) last week and everything was working fine. Today, all
of a sudden, the console proxy stopped working again. The browser says,
"Connecting to 192-168-100-159.realhostip.com..." and eventually times out.
I tried to restart it and it went into a "Stopping" state that never
completed and the Agent State was "Disconnected." I could not shut down
the VM using virsh or with "kill -9" because libvirtd kept saying, "cannot
acquire state change lock," so I gracefully shut down the remaining
instances and rebooted the entire management server/hypervisor. Start over.
When it came back up, the SSVM and console proxy started but the virtual
router was stopped. I was able to manually start it from the UI. The
console proxy still times out when I try to access it from a browser. I
don't see any errors in the management or agent logs, just this:
2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request] (catalina-exec-10:null) Seq
1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
virthost1.redacted.com), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
}
2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-3:null) Seq 1-2130378876: Processing: { Ans: ,
MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
}
2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request] (catalina-exec-10:null) Seq
1-2130378876: Received: { Ans: , MgmtId: 55157049428734, via: 1, Ver: v1,
Flags: 10, { GetVncPortAnswer } }
2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
(catalina-exec-10:null) Port info 192.168.100.6
2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
(catalina-exec-10:null) Parse host info returned from executing
GetVNCPortCommand. host info: 192.168.100.6
2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
(catalina-exec-10:null) Compose console url:
https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
(catalina-exec-10:null) the console url is ::
<html><title>r-4-VM</title><frameset><frame src="
https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
"></frame></frameset></html>
2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: { Cmd ,
MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
If I try to restart the system VMs with cloudstack-sysvmadm, it says:
Stopping and starting 1 secondary storage vm(s)...
curl: (7) couldn't connect to host
ERROR: Failed to stop secondary storage vm with id 1
Done stopping and starting secondary storage vm(s)
Stopping and starting 1 console proxy vm(s)...
curl: (7) couldn't connect to host
ERROR: Failed to stop console proxy vm with id 2
Done stopping and starting console proxy vm(s) .
Stopping and starting 1 running routing vm(s)...
curl: (7) couldn't connect to host
2
Done restarting router(s).
I notice there are now four entries for the same management server in the
mshost table, and they all are in an "Up" state and the "removed" field is
NULL. What's wrong with this system?
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
I'm still getting a lot of these, though.
2014-05-23 10:52:27,908 INFO [c.c.h.HighAvailabilityManagerImpl]
(HA-Worker-3:ctx-838a6dc4 work-873) HA on VM[ConsoleProxy|v-2-VM]
2014-05-23 10:52:27,908 INFO [c.c.h.HighAvailabilityManagerImpl]
(HA-Worker-3:ctx-838a6dc4 work-873) VM VM[ConsoleProxy|v-2-VM] has been
changed. Current State = Running Previous State = Starting last updated =
571 previous updated = 568
2014-05-23 10:52:27,908 INFO [c.c.h.HighAvailabilityManagerImpl]
(HA-Worker-3:ctx-838a6dc4 work-873) Completed
HAWork[873-HA-2-Starting-Investigating]
On Fri, May 23, 2014 at 10:50 AM, Ian Young <iy...@ratespecial.com> wrote:
> I destroyed the SSVM and then tried hacking the database to make
> CloudStack realize that the console proxy is in fact stopped.
>
> mysql> update vm_instance set state='Stopped' where name='v-2-VM';
> mysql> update host set status='Up' where name='v-2-VM';
>
> Now they're both running and I can see the console. There's got to be a
> better way to use this system without having to reboot or hack the database
> daily.
>
>
> On Fri, May 23, 2014 at 10:42 AM, Ian Young <iy...@ratespecial.com>wrote:
>
>> Also, is this normal? Every time the server is rebooted, it adds another
>> record to the mshost table but the "removed" field is always NULL.
>>
>> http://pastebin.com/q5zDCu4b
>>
>>
>> On Fri, May 23, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com>wrote:
>>
>>> The SSVM is stopped. If I try to start it, it complains about
>>> insufficient capacity. CPU? RAM? I have plenty of both available.
>>>
>>> 2014-05-23 10:36:51,196 DEBUG [c.c.d.FirstFitPlanner]
>>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Listing clusters in order of
>>> aggregate capacity, that have (atleast one host with) enough CPU and RAM
>>> capacity under this Pod: 1
>>> 2014-05-23 10:36:51,198 DEBUG [c.c.d.FirstFitPlanner]
>>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Removing from the clusterId list
>>> these clusters from avoid set: [1]
>>> 2014-05-23 10:36:51,198 DEBUG [c.c.d.FirstFitPlanner]
>>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) No clusters found after removing
>>> disabled clusters and clusters in avoid list, returning.
>>> 2014-05-23 10:36:51,201 DEBUG [c.c.c.CapacityManagerImpl]
>>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) VM state transitted from
>>> :Starting to Stopped with event: OperationFailedvm's original host id: 1
>>> new host id: null host id before state transition: null
>>> 2014-05-23 10:36:51,201 WARN [c.c.s.s.SecondaryStorageManagerImpl]
>>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Exception while trying to start
>>> secondary storage vm
>>> com.cloud.exception.InsufficientServerCapacityException: Unable to
>>> create a deployment for VM[SecondaryStorageVm|s-1-VM]Scope=interface
>>> com.cloud.dc.DataCenter; id=1
>>>
>>>
>>> On Fri, May 23, 2014 at 10:35 AM, Ian Young <iy...@ratespecial.com>wrote:
>>>
>>>> I rebooted it and now it's in an even more broken state. It's
>>>> repeatedly trying to stop the console proxy but can't because its state is
>>>> "Starting." Here is an excerpt from the management log:
>>>>
>>>> http://pastebin.com/FiaDzKXb
>>>>
>>>> The agent log keeps repeating these messages:
>>>>
>>>> http://pastebin.com/yDidSbrz
>>>>
>>>> What's wrong with it?
>>>>
>>>>
>>>> On Thu, May 22, 2014 at 12:55 PM, Ian Young <iy...@ratespecial.com>wrote:
>>>>
>>>>> I wonder if something is wrong with the NFS mount. I see this error
>>>>> periodically in /var/log/messages even though I have set the Domain in
>>>>> /etc/idmapd.conf to the host's FQDN:
>>>>>
>>>>> May 20 19:30:22 virthost1 rpc.idmapd[1790]: nss_getpwnam: name '0'
>>>>> does not map into domain 'redacted.com'
>>>>> May 20 19:36:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0'
>>>>> does not map into domain 'redacted.com'
>>>>> May 20 19:44:35 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0'
>>>>> does not map into domain 'redacted.com'
>>>>> May 21 10:21:25 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0'
>>>>> does not map into domain 'redacted.com'
>>>>> May 21 12:46:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0'
>>>>> does not map into domain 'redacted.com'
>>>>> May 21 13:52:42 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0'
>>>>> does not map into domain 'redacted.com'
>>>>> May 21 13:55:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>>>> does not map into domain 'redacted.com'
>>>>> May 21 20:31:51 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>>>> does not map into domain 'redacted.com'
>>>>> May 22 10:14:18 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0'
>>>>> does not map into domain 'redacted.com'
>>>>> May 22 10:18:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>>>> does not map into domain 'redacted.com'
>>>>> May 22 10:19:23 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0'
>>>>> does not map into domain 'redacted.com'
>>>>> May 22 10:25:16 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>>>> does not map into domain 'redacted.com'
>>>>>
>>>>> name '107' just started appearing in the log yesterday, which looks
>>>>> unusual. Up until then, the error was always name '0'.
>>>>>
>>>>>
>>>>> On Thu, May 22, 2014 at 11:15 AM, Andrija Panic <
>>>>> andrija.panic@gmail.com> wrote:
>>>>>
>>>>>> I have observed this kind of problems ("process blocked for more than
>>>>>> xx
>>>>>> sec...") when I had access with storage - check your disks, smartctl
>>>>>> etc...
>>>>>> best
>>>>>>
>>>>>> Sent from Google Nexus 4
>>>>>> On May 22, 2014 7:49 PM, "Ian Young" <iy...@ratespecial.com> wrote:
>>>>>>
>>>>>> > And this is in /var/log/messages right before that event:
>>>>>> >
>>>>>> > May 22 10:16:07 virthost1 kernel: INFO: task qemu-kvm:2971 blocked
>>>>>> for more
>>>>>> > than 120 seconds.
>>>>>> > May 22 10:16:07 virthost1 kernel: Not tainted
>>>>>> > 2.6.32-431.11.2.el6.x86_64 #1
>>>>>> > May 22 10:16:07 virthost1 kernel: "echo 0 >
>>>>>> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>>>>> > May 22 10:16:07 virthost1 kernel: qemu-kvm D 0000000000000002
>>>>>> 0
>>>>>> > 2971 1 0x00000080
>>>>>> > May 22 10:16:07 virthost1 kernel: ffff8810724e9be8 0000000000000082
>>>>>> > 0000000000000000 ffff88106b6529d8
>>>>>> > May 22 10:16:07 virthost1 kernel: ffff880871b3e8d8 ffff880871b3e8f0
>>>>>> > ffffffff8100bb8e ffff8810724e9be8
>>>>>> > May 22 10:16:07 virthost1 kernel: ffff881073525058 ffff8810724e9fd8
>>>>>> > 000000000000fbc8 ffff881073525058
>>>>>> > May 22 10:16:07 virthost1 kernel: Call Trace:
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100bb8e>] ?
>>>>>> > apic_timer_interrupt+0xe/0x20
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810555ef>] ?
>>>>>> > mutex_spin_on_owner+0x9f/0xc0
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152969e>]
>>>>>> > __mutex_lock_slowpath+0x13e/0x180
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152953b>]
>>>>>> mutex_lock+0x2b/0x50
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c2cf>]
>>>>>> > memory_access_ok+0x7f/0xc0 [vhost_net]
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021d89c>]
>>>>>> > vhost_dev_ioctl+0x2ec/0xa50 [vhost_net]
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c411>] ?
>>>>>> > vhost_work_flush+0xe1/0x120 [vhost_net]
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122db91>] ?
>>>>>> > avc_has_perm+0x71/0x90
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021f11a>]
>>>>>> > vhost_net_ioctl+0x7a/0x5d0 [vhost_net]
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122f914>] ?
>>>>>> > inode_has_perm+0x54/0xa0
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa01a28b7>] ?
>>>>>> > kvm_vcpu_ioctl+0x1e7/0x580 [kvm]
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8108b14e>] ?
>>>>>> > send_signal+0x3e/0x90
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119dc12>]
>>>>>> vfs_ioctl+0x22/0xa0
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119ddb4>]
>>>>>> > do_vfs_ioctl+0x84/0x580
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119e331>]
>>>>>> sys_ioctl+0x81/0xa0
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810e1e4e>] ?
>>>>>> > __audit_syscall_exit+0x25e/0x290
>>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100b072>]
>>>>>> > system_call_fastpath+0x16/0x1b
>>>>>> >
>>>>>> >
>>>>>> > On Thu, May 22, 2014 at 10:39 AM, Ian Young <iyoung@ratespecial.com
>>>>>> >
>>>>>> > wrote:
>>>>>> >
>>>>>> > > The console proxy became unavailable again yesterday afternoon.
>>>>>> I could
>>>>>> > > SSH into it via its link local address and nothing seemed to be
>>>>>> wrong
>>>>>> > > inside the VM itself. However, the qemu-kvm process for that VM
>>>>>> was at
>>>>>> > > almost 100% CPU. Inside the VM, the CPU usage was minimal and
>>>>>> the java
>>>>>> > > process was running and listening on port 443. So there seems to
>>>>>> be
>>>>>> > > something wrong with it down at the KVM/QEMU level. It's weird
>>>>>> how this
>>>>>> > > keeps happening to the console proxy only and not any of the
>>>>>> other VMs.
>>>>>> > I
>>>>>> > > tried to reboot it from the management UI and after about 15
>>>>>> minutes, it
>>>>>> > > finally did. Now the console proxy is working but I don't know
>>>>>> how long
>>>>>> > it
>>>>>> > > will last before it breaks again. I found this in libvirtd.log,
>>>>>> which
>>>>>> > > corresponds with the time the console proxy rebooted:
>>>>>> > >
>>>>>> > > 2014-05-22 17:17:04.362+0000: 25195: info : libvirt version:
>>>>>> 0.10.2,
>>>>>> > > package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
>>>>>> > > 2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
>>>>>> > > 2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 :
>>>>>> internal
>>>>>> > > error End of file from monitor
>>>>>> > >
>>>>>> > >
>>>>>> > > On Wed, May 21, 2014 at 2:07 PM, Ian Young <
>>>>>> iyoung@ratespecial.com>
>>>>>> > wrote:
>>>>>> > >
>>>>>> > >> I built and installed a libvirt 1.04 package from the Fedora src
>>>>>> rpm.
>>>>>> > It
>>>>>> > >> installed fine inside a test VM but installing it on the real
>>>>>> hypervisor
>>>>>> > >> was a bad idea and I doubt I'll be pursuing it further. All VMs
>>>>>> > promptly
>>>>>> > >> stopped and this appeared in libvirtd.log:
>>>>>> > >>
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version:
>>>>>> 1.0.4,
>>>>>> > >> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>>> virDriverLoadModule:72 :
>>>>>> > >> Module
>>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so
>>>>>> > not
>>>>>> > >> accessible
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>>> virDriverLoadModule:72 :
>>>>>> > >> Module
>>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so
>>>>>> > not
>>>>>> > >> accessible
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>>> virDriverLoadModule:72 :
>>>>>> > >> Module
>>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so
>>>>>> > not
>>>>>> > >> accessible
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>>> virDriverLoadModule:72 :
>>>>>> > >> Module
>>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so not
>>>>>> > >> accessible
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>>> virDriverLoadModule:72 :
>>>>>> > >> Module
>>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so
>>>>>> > not
>>>>>> > >> accessible
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>>> virDriverLoadModule:72 :
>>>>>> > >> Module
>>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so
>>>>>> > not
>>>>>> > >> accessible
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>>> virDriverLoadModule:72 :
>>>>>> > >> Module
>>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so not
>>>>>> > >> accessible
>>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>>> virDriverLoadModule:72 :
>>>>>> > >> Module
>>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so not
>>>>>> > >> accessible
>>>>>> > >> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no
>>>>>> > connection
>>>>>> > >> driver available for qemu:///system
>>>>>> > >> 2014-05-21 20:36:49.472+0000: 23567: error :
>>>>>> virNetSocketReadWire:1370 :
>>>>>> > >> End of file while reading data: Input/output error
>>>>>> > >> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no
>>>>>> > connection
>>>>>> > >> driver available for lxc:///
>>>>>> > >> 2014-05-21 20:36:49.474+0000: 23567: error :
>>>>>> virNetSocketReadWire:1370 :
>>>>>> > >> End of file while reading data: Input/output error
>>>>>> > >> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no
>>>>>> > connection
>>>>>> > >> driver available for qemu:///system
>>>>>> > >> 2014-05-21 20:36:49.476+0000: 23567: error :
>>>>>> virNetSocketReadWire:1370 :
>>>>>> > >> End of file while reading data: Input/output error
>>>>>> > >> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no
>>>>>> > connection
>>>>>> > >> driver available for qemu:///system
>>>>>> > >> 2014-05-21 20:36:49.678+0000: 23567: error :
>>>>>> virNetSocketReadWire:1370 :
>>>>>> > >> End of file while reading data: Input/output error
>>>>>> > >> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no
>>>>>> > connection
>>>>>> > >> driver available for qemu:///system
>>>>>> > >> 2014-05-21 20:36:49.682+0000: 23567: error :
>>>>>> virNetSocketReadWire:1370 :
>>>>>> > >> End of file while reading data: Input/output error
>>>>>> > >>
>>>>>> > >>
>>>>>> > >> On Wed, May 21, 2014 at 10:45 AM, Ian Young <
>>>>>> iyoung@ratespecial.com
>>>>>> > >wrote:
>>>>>> > >>
>>>>>> > >>> I was able to get it working by following these steps:
>>>>>> > >>>
>>>>>> > >>> 1. stop all instances
>>>>>> > >>> 2. service cloudstack-management stop
>>>>>> > >>> 3. service cloudstack-agent stop
>>>>>> > >>> 4. virsh shutdown {domain} (for each of the system VMs)
>>>>>> > >>> 5. service libvirtd stop
>>>>>> > >>> 6. umount primary and secondary
>>>>>> > >>> 7. reboot
>>>>>> > >>>
>>>>>> > >>> The console proxy is working again. I expect it will probably
>>>>>> break
>>>>>> > >>> again in a day or two. I have a feeling it's a result of this
>>>>>> libvirtd
>>>>>> > >>> bug, since I've seen the "cannot acquire state change lock"
>>>>>> several
>>>>>> > times.
>>>>>> > >>>
>>>>>> > >>> https://bugs.launchpad.net/nova/+bug/1254872
>>>>>> > >>>
>>>>>> > >>> I might try building my own libvirtd 1.0.3 for EL6.
>>>>>> > >>>
>>>>>> > >>>
>>>>>> > >>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <
>>>>>> iyoung@ratespecial.com
>>>>>> > >wrote:
>>>>>> > >>>
>>>>>> > >>>> So I got the console proxy working via HTTPS (by managing my
>>>>>> own "
>>>>>> > >>>> realhostip.com" DNS) last week and everything was working
>>>>>> fine.
>>>>>> > >>>> Today, all of a sudden, the console proxy stopped working
>>>>>> again. The
>>>>>> > >>>> browser says, "Connecting to
>>>>>> 192-168-100-159.realhostip.com..." and
>>>>>> > >>>> eventually times out. I tried to restart it and it went into a
>>>>>> > "Stopping"
>>>>>> > >>>> state that never completed and the Agent State was
>>>>>> "Disconnected." I
>>>>>> > could
>>>>>> > >>>> not shut down the VM using virsh or with "kill -9" because
>>>>>> libvirtd
>>>>>> > kept
>>>>>> > >>>> saying, "cannot acquire state change lock," so I gracefully
>>>>>> shut down
>>>>>> > the
>>>>>> > >>>> remaining instances and rebooted the entire management
>>>>>> > server/hypervisor.
>>>>>> > >>>> Start over.
>>>>>> > >>>>
>>>>>> > >>>> When it came back up, the SSVM and console proxy started but
>>>>>> the
>>>>>> > >>>> virtual router was stopped. I was able to manually start it
>>>>>> from the
>>>>>> > UI.
>>>>>> > >>>> The console proxy still times out when I try to access it
>>>>>> from a
>>>>>> > browser.
>>>>>> > >>>> I don't see any errors in the management or agent logs, just
>>>>>> this:
>>>>>> > >>>>
>>>>>> > >>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request]
>>>>>> > (catalina-exec-10:null)
>>>>>> > >>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734,
>>>>>> via: 1(
>>>>>> > >>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
>>>>>> > >>>>
>>>>>> >
>>>>>> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
>>>>>> > >>>> }
>>>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>>>>> > >>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: {
>>>>>> Ans: ,
>>>>>> > >>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
>>>>>> > >>>>
>>>>>> >
>>>>>> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
>>>>>> > >>>> }
>>>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>>>>> > (catalina-exec-10:null)
>>>>>> > >>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734,
>>>>>> via: 1,
>>>>>> > Ver:
>>>>>> > >>>> v1, Flags: 10, { GetVncPortAnswer } }
>>>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
>>>>>> > >>>> (catalina-exec-10:null) Port info 192.168.100.6
>>>>>> > >>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
>>>>>> > >>>> (catalina-exec-10:null) Parse host info returned from executing
>>>>>> > >>>> GetVNCPortCommand. host info: 192.168.100.6
>>>>>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>>>>> > >>>> (catalina-exec-10:null) Compose console url:
>>>>>> > >>>>
>>>>>> >
>>>>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>>>>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>>>>> > >>>> (catalina-exec-10:null) the console url is ::
>>>>>> > >>>> <html><title>r-4-VM</title><frameset><frame src="
>>>>>> > >>>>
>>>>>> >
>>>>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>>>>> > >>>> "></frame></frameset></html>
>>>>>> > >>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
>>>>>> > >>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq
>>>>>> 2-545: {
>>>>>> > Cmd ,
>>>>>> > >>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>>>>>> > >>>>
>>>>>> >
>>>>>> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
>>>>>> > >>>> \"connections\": []\n}","wait":0}}] }
>>>>>> > >>>>
>>>>>> > >>>> If I try to restart the system VMs with cloudstack-sysvmadm,
>>>>>> it says:
>>>>>> > >>>>
>>>>>> > >>>> Stopping and starting 1 secondary storage vm(s)...
>>>>>> > >>>> curl: (7) couldn't connect to host
>>>>>> > >>>> ERROR: Failed to stop secondary storage vm with id 1
>>>>>> > >>>>
>>>>>> > >>>> Done stopping and starting secondary storage vm(s)
>>>>>> > >>>>
>>>>>> > >>>> Stopping and starting 1 console proxy vm(s)...
>>>>>> > >>>> curl: (7) couldn't connect to host
>>>>>> > >>>> ERROR: Failed to stop console proxy vm with id 2
>>>>>> > >>>>
>>>>>> > >>>> Done stopping and starting console proxy vm(s) .
>>>>>> > >>>>
>>>>>> > >>>> Stopping and starting 1 running routing vm(s)...
>>>>>> > >>>> curl: (7) couldn't connect to host
>>>>>> > >>>> 2
>>>>>> > >>>> Done restarting router(s).
>>>>>> > >>>>
>>>>>> > >>>> I notice there are now four entries for the same management
>>>>>> server in
>>>>>> > >>>> the mshost table, and they all are in an "Up" state and the
>>>>>> "removed"
>>>>>> > field
>>>>>> > >>>> is NULL. What's wrong with this system?
>>>>>> > >>>>
>>>>>> > >>>
>>>>>> > >>>
>>>>>> > >>
>>>>>> > >
>>>>>> >
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>>
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
I destroyed the SSVM and then tried hacking the database to make CloudStack
realize that the console proxy is in fact stopped.
mysql> update vm_instance set state='Stopped' where name='v-2-VM';
mysql> update host set status='Up' where name='v-2-VM';
Now they're both running and I can see the console. There's got to be a
better way to use this system without having to reboot or hack the database
daily.
On Fri, May 23, 2014 at 10:42 AM, Ian Young <iy...@ratespecial.com> wrote:
> Also, is this normal? Every time the server is rebooted, it adds another
> record to the mshost table but the "removed" field is always NULL.
>
> http://pastebin.com/q5zDCu4b
>
>
> On Fri, May 23, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com>wrote:
>
>> The SSVM is stopped. If I try to start it, it complains about
>> insufficient capacity. CPU? RAM? I have plenty of both available.
>>
>> 2014-05-23 10:36:51,196 DEBUG [c.c.d.FirstFitPlanner]
>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Listing clusters in order of
>> aggregate capacity, that have (atleast one host with) enough CPU and RAM
>> capacity under this Pod: 1
>> 2014-05-23 10:36:51,198 DEBUG [c.c.d.FirstFitPlanner]
>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Removing from the clusterId list
>> these clusters from avoid set: [1]
>> 2014-05-23 10:36:51,198 DEBUG [c.c.d.FirstFitPlanner]
>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) No clusters found after removing
>> disabled clusters and clusters in avoid list, returning.
>> 2014-05-23 10:36:51,201 DEBUG [c.c.c.CapacityManagerImpl]
>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) VM state transitted from
>> :Starting to Stopped with event: OperationFailedvm's original host id: 1
>> new host id: null host id before state transition: null
>> 2014-05-23 10:36:51,201 WARN [c.c.s.s.SecondaryStorageManagerImpl]
>> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Exception while trying to start
>> secondary storage vm
>> com.cloud.exception.InsufficientServerCapacityException: Unable to create
>> a deployment for VM[SecondaryStorageVm|s-1-VM]Scope=interface
>> com.cloud.dc.DataCenter; id=1
>>
>>
>> On Fri, May 23, 2014 at 10:35 AM, Ian Young <iy...@ratespecial.com>wrote:
>>
>>> I rebooted it and now it's in an even more broken state. It's
>>> repeatedly trying to stop the console proxy but can't because its state is
>>> "Starting." Here is an excerpt from the management log:
>>>
>>> http://pastebin.com/FiaDzKXb
>>>
>>> The agent log keeps repeating these messages:
>>>
>>> http://pastebin.com/yDidSbrz
>>>
>>> What's wrong with it?
>>>
>>>
>>> On Thu, May 22, 2014 at 12:55 PM, Ian Young <iy...@ratespecial.com>wrote:
>>>
>>>> I wonder if something is wrong with the NFS mount. I see this error
>>>> periodically in /var/log/messages even though I have set the Domain in
>>>> /etc/idmapd.conf to the host's FQDN:
>>>>
>>>> May 20 19:30:22 virthost1 rpc.idmapd[1790]: nss_getpwnam: name '0' does
>>>> not map into domain 'redacted.com'
>>>> May 20 19:36:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>>> not map into domain 'redacted.com'
>>>> May 20 19:44:35 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>>> not map into domain 'redacted.com'
>>>> May 21 10:21:25 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>>> not map into domain 'redacted.com'
>>>> May 21 12:46:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>>> not map into domain 'redacted.com'
>>>> May 21 13:52:42 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>>> not map into domain 'redacted.com'
>>>> May 21 13:55:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>>> does not map into domain 'redacted.com'
>>>> May 21 20:31:51 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>>> does not map into domain 'redacted.com'
>>>> May 22 10:14:18 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>>> not map into domain 'redacted.com'
>>>> May 22 10:18:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>>> does not map into domain 'redacted.com'
>>>> May 22 10:19:23 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>>> not map into domain 'redacted.com'
>>>> May 22 10:25:16 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>>> does not map into domain 'redacted.com'
>>>>
>>>> name '107' just started appearing in the log yesterday, which looks
>>>> unusual. Up until then, the error was always name '0'.
>>>>
>>>>
>>>> On Thu, May 22, 2014 at 11:15 AM, Andrija Panic <
>>>> andrija.panic@gmail.com> wrote:
>>>>
>>>>> I have observed this kind of problems ("process blocked for more than
>>>>> xx
>>>>> sec...") when I had access with storage - check your disks, smartctl
>>>>> etc...
>>>>> best
>>>>>
>>>>> Sent from Google Nexus 4
>>>>> On May 22, 2014 7:49 PM, "Ian Young" <iy...@ratespecial.com> wrote:
>>>>>
>>>>> > And this is in /var/log/messages right before that event:
>>>>> >
>>>>> > May 22 10:16:07 virthost1 kernel: INFO: task qemu-kvm:2971 blocked
>>>>> for more
>>>>> > than 120 seconds.
>>>>> > May 22 10:16:07 virthost1 kernel: Not tainted
>>>>> > 2.6.32-431.11.2.el6.x86_64 #1
>>>>> > May 22 10:16:07 virthost1 kernel: "echo 0 >
>>>>> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>>>> > May 22 10:16:07 virthost1 kernel: qemu-kvm D 0000000000000002
>>>>> 0
>>>>> > 2971 1 0x00000080
>>>>> > May 22 10:16:07 virthost1 kernel: ffff8810724e9be8 0000000000000082
>>>>> > 0000000000000000 ffff88106b6529d8
>>>>> > May 22 10:16:07 virthost1 kernel: ffff880871b3e8d8 ffff880871b3e8f0
>>>>> > ffffffff8100bb8e ffff8810724e9be8
>>>>> > May 22 10:16:07 virthost1 kernel: ffff881073525058 ffff8810724e9fd8
>>>>> > 000000000000fbc8 ffff881073525058
>>>>> > May 22 10:16:07 virthost1 kernel: Call Trace:
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100bb8e>] ?
>>>>> > apic_timer_interrupt+0xe/0x20
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810555ef>] ?
>>>>> > mutex_spin_on_owner+0x9f/0xc0
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152969e>]
>>>>> > __mutex_lock_slowpath+0x13e/0x180
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152953b>]
>>>>> mutex_lock+0x2b/0x50
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c2cf>]
>>>>> > memory_access_ok+0x7f/0xc0 [vhost_net]
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021d89c>]
>>>>> > vhost_dev_ioctl+0x2ec/0xa50 [vhost_net]
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c411>] ?
>>>>> > vhost_work_flush+0xe1/0x120 [vhost_net]
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122db91>] ?
>>>>> > avc_has_perm+0x71/0x90
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021f11a>]
>>>>> > vhost_net_ioctl+0x7a/0x5d0 [vhost_net]
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122f914>] ?
>>>>> > inode_has_perm+0x54/0xa0
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa01a28b7>] ?
>>>>> > kvm_vcpu_ioctl+0x1e7/0x580 [kvm]
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8108b14e>] ?
>>>>> > send_signal+0x3e/0x90
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119dc12>]
>>>>> vfs_ioctl+0x22/0xa0
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119ddb4>]
>>>>> > do_vfs_ioctl+0x84/0x580
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119e331>]
>>>>> sys_ioctl+0x81/0xa0
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810e1e4e>] ?
>>>>> > __audit_syscall_exit+0x25e/0x290
>>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100b072>]
>>>>> > system_call_fastpath+0x16/0x1b
>>>>> >
>>>>> >
>>>>> > On Thu, May 22, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com>
>>>>> > wrote:
>>>>> >
>>>>> > > The console proxy became unavailable again yesterday afternoon. I
>>>>> could
>>>>> > > SSH into it via its link local address and nothing seemed to be
>>>>> wrong
>>>>> > > inside the VM itself. However, the qemu-kvm process for that VM
>>>>> was at
>>>>> > > almost 100% CPU. Inside the VM, the CPU usage was minimal and the
>>>>> java
>>>>> > > process was running and listening on port 443. So there seems to
>>>>> be
>>>>> > > something wrong with it down at the KVM/QEMU level. It's weird
>>>>> how this
>>>>> > > keeps happening to the console proxy only and not any of the other
>>>>> VMs.
>>>>> > I
>>>>> > > tried to reboot it from the management UI and after about 15
>>>>> minutes, it
>>>>> > > finally did. Now the console proxy is working but I don't know
>>>>> how long
>>>>> > it
>>>>> > > will last before it breaks again. I found this in libvirtd.log,
>>>>> which
>>>>> > > corresponds with the time the console proxy rebooted:
>>>>> > >
>>>>> > > 2014-05-22 17:17:04.362+0000: 25195: info : libvirt version:
>>>>> 0.10.2,
>>>>> > > package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
>>>>> > > 2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
>>>>> > > 2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 :
>>>>> internal
>>>>> > > error End of file from monitor
>>>>> > >
>>>>> > >
>>>>> > > On Wed, May 21, 2014 at 2:07 PM, Ian Young <iyoung@ratespecial.com
>>>>> >
>>>>> > wrote:
>>>>> > >
>>>>> > >> I built and installed a libvirt 1.04 package from the Fedora src
>>>>> rpm.
>>>>> > It
>>>>> > >> installed fine inside a test VM but installing it on the real
>>>>> hypervisor
>>>>> > >> was a bad idea and I doubt I'll be pursuing it further. All VMs
>>>>> > promptly
>>>>> > >> stopped and this appeared in libvirtd.log:
>>>>> > >>
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version:
>>>>> 1.0.4,
>>>>> > >> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>> virDriverLoadModule:72 :
>>>>> > >> Module
>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so
>>>>> > not
>>>>> > >> accessible
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>> virDriverLoadModule:72 :
>>>>> > >> Module
>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so
>>>>> > not
>>>>> > >> accessible
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>> virDriverLoadModule:72 :
>>>>> > >> Module
>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so
>>>>> > not
>>>>> > >> accessible
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>> virDriverLoadModule:72 :
>>>>> > >> Module
>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so not
>>>>> > >> accessible
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>> virDriverLoadModule:72 :
>>>>> > >> Module
>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so
>>>>> > not
>>>>> > >> accessible
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>> virDriverLoadModule:72 :
>>>>> > >> Module
>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so
>>>>> > not
>>>>> > >> accessible
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>> virDriverLoadModule:72 :
>>>>> > >> Module
>>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so not
>>>>> > >> accessible
>>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>>> virDriverLoadModule:72 :
>>>>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so
>>>>> not
>>>>> > >> accessible
>>>>> > >> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no
>>>>> > connection
>>>>> > >> driver available for qemu:///system
>>>>> > >> 2014-05-21 20:36:49.472+0000: 23567: error :
>>>>> virNetSocketReadWire:1370 :
>>>>> > >> End of file while reading data: Input/output error
>>>>> > >> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no
>>>>> > connection
>>>>> > >> driver available for lxc:///
>>>>> > >> 2014-05-21 20:36:49.474+0000: 23567: error :
>>>>> virNetSocketReadWire:1370 :
>>>>> > >> End of file while reading data: Input/output error
>>>>> > >> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no
>>>>> > connection
>>>>> > >> driver available for qemu:///system
>>>>> > >> 2014-05-21 20:36:49.476+0000: 23567: error :
>>>>> virNetSocketReadWire:1370 :
>>>>> > >> End of file while reading data: Input/output error
>>>>> > >> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no
>>>>> > connection
>>>>> > >> driver available for qemu:///system
>>>>> > >> 2014-05-21 20:36:49.678+0000: 23567: error :
>>>>> virNetSocketReadWire:1370 :
>>>>> > >> End of file while reading data: Input/output error
>>>>> > >> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no
>>>>> > connection
>>>>> > >> driver available for qemu:///system
>>>>> > >> 2014-05-21 20:36:49.682+0000: 23567: error :
>>>>> virNetSocketReadWire:1370 :
>>>>> > >> End of file while reading data: Input/output error
>>>>> > >>
>>>>> > >>
>>>>> > >> On Wed, May 21, 2014 at 10:45 AM, Ian Young <
>>>>> iyoung@ratespecial.com
>>>>> > >wrote:
>>>>> > >>
>>>>> > >>> I was able to get it working by following these steps:
>>>>> > >>>
>>>>> > >>> 1. stop all instances
>>>>> > >>> 2. service cloudstack-management stop
>>>>> > >>> 3. service cloudstack-agent stop
>>>>> > >>> 4. virsh shutdown {domain} (for each of the system VMs)
>>>>> > >>> 5. service libvirtd stop
>>>>> > >>> 6. umount primary and secondary
>>>>> > >>> 7. reboot
>>>>> > >>>
>>>>> > >>> The console proxy is working again. I expect it will probably
>>>>> break
>>>>> > >>> again in a day or two. I have a feeling it's a result of this
>>>>> libvirtd
>>>>> > >>> bug, since I've seen the "cannot acquire state change lock"
>>>>> several
>>>>> > times.
>>>>> > >>>
>>>>> > >>> https://bugs.launchpad.net/nova/+bug/1254872
>>>>> > >>>
>>>>> > >>> I might try building my own libvirtd 1.0.3 for EL6.
>>>>> > >>>
>>>>> > >>>
>>>>> > >>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <
>>>>> iyoung@ratespecial.com
>>>>> > >wrote:
>>>>> > >>>
>>>>> > >>>> So I got the console proxy working via HTTPS (by managing my
>>>>> own "
>>>>> > >>>> realhostip.com" DNS) last week and everything was working fine.
>>>>> > >>>> Today, all of a sudden, the console proxy stopped working
>>>>> again. The
>>>>> > >>>> browser says, "Connecting to 192-168-100-159.realhostip.com..."
>>>>> and
>>>>> > >>>> eventually times out. I tried to restart it and it went into a
>>>>> > "Stopping"
>>>>> > >>>> state that never completed and the Agent State was
>>>>> "Disconnected." I
>>>>> > could
>>>>> > >>>> not shut down the VM using virsh or with "kill -9" because
>>>>> libvirtd
>>>>> > kept
>>>>> > >>>> saying, "cannot acquire state change lock," so I gracefully
>>>>> shut down
>>>>> > the
>>>>> > >>>> remaining instances and rebooted the entire management
>>>>> > server/hypervisor.
>>>>> > >>>> Start over.
>>>>> > >>>>
>>>>> > >>>> When it came back up, the SSVM and console proxy started but the
>>>>> > >>>> virtual router was stopped. I was able to manually start it
>>>>> from the
>>>>> > UI.
>>>>> > >>>> The console proxy still times out when I try to access it from
>>>>> a
>>>>> > browser.
>>>>> > >>>> I don't see any errors in the management or agent logs, just
>>>>> this:
>>>>> > >>>>
>>>>> > >>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request]
>>>>> > (catalina-exec-10:null)
>>>>> > >>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via:
>>>>> 1(
>>>>> > >>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
>>>>> > >>>>
>>>>> >
>>>>> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
>>>>> > >>>> }
>>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>>>> > >>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: {
>>>>> Ans: ,
>>>>> > >>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
>>>>> > >>>>
>>>>> >
>>>>> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
>>>>> > >>>> }
>>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>>>> > (catalina-exec-10:null)
>>>>> > >>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734,
>>>>> via: 1,
>>>>> > Ver:
>>>>> > >>>> v1, Flags: 10, { GetVncPortAnswer } }
>>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
>>>>> > >>>> (catalina-exec-10:null) Port info 192.168.100.6
>>>>> > >>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
>>>>> > >>>> (catalina-exec-10:null) Parse host info returned from executing
>>>>> > >>>> GetVNCPortCommand. host info: 192.168.100.6
>>>>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>>>> > >>>> (catalina-exec-10:null) Compose console url:
>>>>> > >>>>
>>>>> >
>>>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>>>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>>>> > >>>> (catalina-exec-10:null) the console url is ::
>>>>> > >>>> <html><title>r-4-VM</title><frameset><frame src="
>>>>> > >>>>
>>>>> >
>>>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>>>> > >>>> "></frame></frameset></html>
>>>>> > >>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
>>>>> > >>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545:
>>>>> {
>>>>> > Cmd ,
>>>>> > >>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>>>>> > >>>>
>>>>> >
>>>>> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
>>>>> > >>>> \"connections\": []\n}","wait":0}}] }
>>>>> > >>>>
>>>>> > >>>> If I try to restart the system VMs with cloudstack-sysvmadm, it
>>>>> says:
>>>>> > >>>>
>>>>> > >>>> Stopping and starting 1 secondary storage vm(s)...
>>>>> > >>>> curl: (7) couldn't connect to host
>>>>> > >>>> ERROR: Failed to stop secondary storage vm with id 1
>>>>> > >>>>
>>>>> > >>>> Done stopping and starting secondary storage vm(s)
>>>>> > >>>>
>>>>> > >>>> Stopping and starting 1 console proxy vm(s)...
>>>>> > >>>> curl: (7) couldn't connect to host
>>>>> > >>>> ERROR: Failed to stop console proxy vm with id 2
>>>>> > >>>>
>>>>> > >>>> Done stopping and starting console proxy vm(s) .
>>>>> > >>>>
>>>>> > >>>> Stopping and starting 1 running routing vm(s)...
>>>>> > >>>> curl: (7) couldn't connect to host
>>>>> > >>>> 2
>>>>> > >>>> Done restarting router(s).
>>>>> > >>>>
>>>>> > >>>> I notice there are now four entries for the same management
>>>>> server in
>>>>> > >>>> the mshost table, and they all are in an "Up" state and the
>>>>> "removed"
>>>>> > field
>>>>> > >>>> is NULL. What's wrong with this system?
>>>>> > >>>>
>>>>> > >>>
>>>>> > >>>
>>>>> > >>
>>>>> > >
>>>>> >
>>>>>
>>>>
>>>>
>>>
>>
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
Also, is this normal? Every time the server is rebooted, it adds another
record to the mshost table but the "removed" field is always NULL.
http://pastebin.com/q5zDCu4b
On Fri, May 23, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com> wrote:
> The SSVM is stopped. If I try to start it, it complains about
> insufficient capacity. CPU? RAM? I have plenty of both available.
>
> 2014-05-23 10:36:51,196 DEBUG [c.c.d.FirstFitPlanner]
> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Listing clusters in order of
> aggregate capacity, that have (atleast one host with) enough CPU and RAM
> capacity under this Pod: 1
> 2014-05-23 10:36:51,198 DEBUG [c.c.d.FirstFitPlanner]
> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Removing from the clusterId list
> these clusters from avoid set: [1]
> 2014-05-23 10:36:51,198 DEBUG [c.c.d.FirstFitPlanner]
> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) No clusters found after removing
> disabled clusters and clusters in avoid list, returning.
> 2014-05-23 10:36:51,201 DEBUG [c.c.c.CapacityManagerImpl]
> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) VM state transitted from
> :Starting to Stopped with event: OperationFailedvm's original host id: 1
> new host id: null host id before state transition: null
> 2014-05-23 10:36:51,201 WARN [c.c.s.s.SecondaryStorageManagerImpl]
> (Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Exception while trying to start
> secondary storage vm
> com.cloud.exception.InsufficientServerCapacityException: Unable to create
> a deployment for VM[SecondaryStorageVm|s-1-VM]Scope=interface
> com.cloud.dc.DataCenter; id=1
>
>
> On Fri, May 23, 2014 at 10:35 AM, Ian Young <iy...@ratespecial.com>wrote:
>
>> I rebooted it and now it's in an even more broken state. It's repeatedly
>> trying to stop the console proxy but can't because its state is "Starting."
>> Here is an excerpt from the management log:
>>
>> http://pastebin.com/FiaDzKXb
>>
>> The agent log keeps repeating these messages:
>>
>> http://pastebin.com/yDidSbrz
>>
>> What's wrong with it?
>>
>>
>> On Thu, May 22, 2014 at 12:55 PM, Ian Young <iy...@ratespecial.com>wrote:
>>
>>> I wonder if something is wrong with the NFS mount. I see this error
>>> periodically in /var/log/messages even though I have set the Domain in
>>> /etc/idmapd.conf to the host's FQDN:
>>>
>>> May 20 19:30:22 virthost1 rpc.idmapd[1790]: nss_getpwnam: name '0' does
>>> not map into domain 'redacted.com'
>>> May 20 19:36:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>> not map into domain 'redacted.com'
>>> May 20 19:44:35 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>> not map into domain 'redacted.com'
>>> May 21 10:21:25 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>> not map into domain 'redacted.com'
>>> May 21 12:46:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>> not map into domain 'redacted.com'
>>> May 21 13:52:42 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>> not map into domain 'redacted.com'
>>> May 21 13:55:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>> does not map into domain 'redacted.com'
>>> May 21 20:31:51 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>> does not map into domain 'redacted.com'
>>> May 22 10:14:18 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>> not map into domain 'redacted.com'
>>> May 22 10:18:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>> does not map into domain 'redacted.com'
>>> May 22 10:19:23 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>>> not map into domain 'redacted.com'
>>> May 22 10:25:16 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107'
>>> does not map into domain 'redacted.com'
>>>
>>> name '107' just started appearing in the log yesterday, which looks
>>> unusual. Up until then, the error was always name '0'.
>>>
>>>
>>> On Thu, May 22, 2014 at 11:15 AM, Andrija Panic <andrija.panic@gmail.com
>>> > wrote:
>>>
>>>> I have observed this kind of problems ("process blocked for more than xx
>>>> sec...") when I had access with storage - check your disks, smartctl
>>>> etc...
>>>> best
>>>>
>>>> Sent from Google Nexus 4
>>>> On May 22, 2014 7:49 PM, "Ian Young" <iy...@ratespecial.com> wrote:
>>>>
>>>> > And this is in /var/log/messages right before that event:
>>>> >
>>>> > May 22 10:16:07 virthost1 kernel: INFO: task qemu-kvm:2971 blocked
>>>> for more
>>>> > than 120 seconds.
>>>> > May 22 10:16:07 virthost1 kernel: Not tainted
>>>> > 2.6.32-431.11.2.el6.x86_64 #1
>>>> > May 22 10:16:07 virthost1 kernel: "echo 0 >
>>>> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>>> > May 22 10:16:07 virthost1 kernel: qemu-kvm D 0000000000000002
>>>> 0
>>>> > 2971 1 0x00000080
>>>> > May 22 10:16:07 virthost1 kernel: ffff8810724e9be8 0000000000000082
>>>> > 0000000000000000 ffff88106b6529d8
>>>> > May 22 10:16:07 virthost1 kernel: ffff880871b3e8d8 ffff880871b3e8f0
>>>> > ffffffff8100bb8e ffff8810724e9be8
>>>> > May 22 10:16:07 virthost1 kernel: ffff881073525058 ffff8810724e9fd8
>>>> > 000000000000fbc8 ffff881073525058
>>>> > May 22 10:16:07 virthost1 kernel: Call Trace:
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100bb8e>] ?
>>>> > apic_timer_interrupt+0xe/0x20
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810555ef>] ?
>>>> > mutex_spin_on_owner+0x9f/0xc0
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152969e>]
>>>> > __mutex_lock_slowpath+0x13e/0x180
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152953b>]
>>>> mutex_lock+0x2b/0x50
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c2cf>]
>>>> > memory_access_ok+0x7f/0xc0 [vhost_net]
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021d89c>]
>>>> > vhost_dev_ioctl+0x2ec/0xa50 [vhost_net]
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c411>] ?
>>>> > vhost_work_flush+0xe1/0x120 [vhost_net]
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122db91>] ?
>>>> > avc_has_perm+0x71/0x90
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021f11a>]
>>>> > vhost_net_ioctl+0x7a/0x5d0 [vhost_net]
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122f914>] ?
>>>> > inode_has_perm+0x54/0xa0
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa01a28b7>] ?
>>>> > kvm_vcpu_ioctl+0x1e7/0x580 [kvm]
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8108b14e>] ?
>>>> > send_signal+0x3e/0x90
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119dc12>]
>>>> vfs_ioctl+0x22/0xa0
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119ddb4>]
>>>> > do_vfs_ioctl+0x84/0x580
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119e331>]
>>>> sys_ioctl+0x81/0xa0
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810e1e4e>] ?
>>>> > __audit_syscall_exit+0x25e/0x290
>>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100b072>]
>>>> > system_call_fastpath+0x16/0x1b
>>>> >
>>>> >
>>>> > On Thu, May 22, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com>
>>>> > wrote:
>>>> >
>>>> > > The console proxy became unavailable again yesterday afternoon. I
>>>> could
>>>> > > SSH into it via its link local address and nothing seemed to be
>>>> wrong
>>>> > > inside the VM itself. However, the qemu-kvm process for that VM
>>>> was at
>>>> > > almost 100% CPU. Inside the VM, the CPU usage was minimal and the
>>>> java
>>>> > > process was running and listening on port 443. So there seems to be
>>>> > > something wrong with it down at the KVM/QEMU level. It's weird how
>>>> this
>>>> > > keeps happening to the console proxy only and not any of the other
>>>> VMs.
>>>> > I
>>>> > > tried to reboot it from the management UI and after about 15
>>>> minutes, it
>>>> > > finally did. Now the console proxy is working but I don't know how
>>>> long
>>>> > it
>>>> > > will last before it breaks again. I found this in libvirtd.log,
>>>> which
>>>> > > corresponds with the time the console proxy rebooted:
>>>> > >
>>>> > > 2014-05-22 17:17:04.362+0000: 25195: info : libvirt version: 0.10.2,
>>>> > > package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
>>>> > > 2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
>>>> > > 2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 :
>>>> internal
>>>> > > error End of file from monitor
>>>> > >
>>>> > >
>>>> > > On Wed, May 21, 2014 at 2:07 PM, Ian Young <iy...@ratespecial.com>
>>>> > wrote:
>>>> > >
>>>> > >> I built and installed a libvirt 1.04 package from the Fedora src
>>>> rpm.
>>>> > It
>>>> > >> installed fine inside a test VM but installing it on the real
>>>> hypervisor
>>>> > >> was a bad idea and I doubt I'll be pursuing it further. All VMs
>>>> > promptly
>>>> > >> stopped and this appeared in libvirtd.log:
>>>> > >>
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version: 1.0.4,
>>>> > >> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>> virDriverLoadModule:72 :
>>>> > >> Module
>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so
>>>> > not
>>>> > >> accessible
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>> virDriverLoadModule:72 :
>>>> > >> Module
>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so
>>>> > not
>>>> > >> accessible
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>> virDriverLoadModule:72 :
>>>> > >> Module
>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so
>>>> > not
>>>> > >> accessible
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>> virDriverLoadModule:72 :
>>>> > >> Module
>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so not
>>>> > >> accessible
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>> virDriverLoadModule:72 :
>>>> > >> Module
>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so
>>>> > not
>>>> > >> accessible
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>> virDriverLoadModule:72 :
>>>> > >> Module
>>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so
>>>> > not
>>>> > >> accessible
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>> virDriverLoadModule:72 :
>>>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so
>>>> not
>>>> > >> accessible
>>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>>> virDriverLoadModule:72 :
>>>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so
>>>> not
>>>> > >> accessible
>>>> > >> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no
>>>> > connection
>>>> > >> driver available for qemu:///system
>>>> > >> 2014-05-21 20:36:49.472+0000: 23567: error :
>>>> virNetSocketReadWire:1370 :
>>>> > >> End of file while reading data: Input/output error
>>>> > >> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no
>>>> > connection
>>>> > >> driver available for lxc:///
>>>> > >> 2014-05-21 20:36:49.474+0000: 23567: error :
>>>> virNetSocketReadWire:1370 :
>>>> > >> End of file while reading data: Input/output error
>>>> > >> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no
>>>> > connection
>>>> > >> driver available for qemu:///system
>>>> > >> 2014-05-21 20:36:49.476+0000: 23567: error :
>>>> virNetSocketReadWire:1370 :
>>>> > >> End of file while reading data: Input/output error
>>>> > >> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no
>>>> > connection
>>>> > >> driver available for qemu:///system
>>>> > >> 2014-05-21 20:36:49.678+0000: 23567: error :
>>>> virNetSocketReadWire:1370 :
>>>> > >> End of file while reading data: Input/output error
>>>> > >> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no
>>>> > connection
>>>> > >> driver available for qemu:///system
>>>> > >> 2014-05-21 20:36:49.682+0000: 23567: error :
>>>> virNetSocketReadWire:1370 :
>>>> > >> End of file while reading data: Input/output error
>>>> > >>
>>>> > >>
>>>> > >> On Wed, May 21, 2014 at 10:45 AM, Ian Young <
>>>> iyoung@ratespecial.com
>>>> > >wrote:
>>>> > >>
>>>> > >>> I was able to get it working by following these steps:
>>>> > >>>
>>>> > >>> 1. stop all instances
>>>> > >>> 2. service cloudstack-management stop
>>>> > >>> 3. service cloudstack-agent stop
>>>> > >>> 4. virsh shutdown {domain} (for each of the system VMs)
>>>> > >>> 5. service libvirtd stop
>>>> > >>> 6. umount primary and secondary
>>>> > >>> 7. reboot
>>>> > >>>
>>>> > >>> The console proxy is working again. I expect it will probably
>>>> break
>>>> > >>> again in a day or two. I have a feeling it's a result of this
>>>> libvirtd
>>>> > >>> bug, since I've seen the "cannot acquire state change lock"
>>>> several
>>>> > times.
>>>> > >>>
>>>> > >>> https://bugs.launchpad.net/nova/+bug/1254872
>>>> > >>>
>>>> > >>> I might try building my own libvirtd 1.0.3 for EL6.
>>>> > >>>
>>>> > >>>
>>>> > >>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <
>>>> iyoung@ratespecial.com
>>>> > >wrote:
>>>> > >>>
>>>> > >>>> So I got the console proxy working via HTTPS (by managing my own
>>>> "
>>>> > >>>> realhostip.com" DNS) last week and everything was working fine.
>>>> > >>>> Today, all of a sudden, the console proxy stopped working
>>>> again. The
>>>> > >>>> browser says, "Connecting to 192-168-100-159.realhostip.com..."
>>>> and
>>>> > >>>> eventually times out. I tried to restart it and it went into a
>>>> > "Stopping"
>>>> > >>>> state that never completed and the Agent State was
>>>> "Disconnected." I
>>>> > could
>>>> > >>>> not shut down the VM using virsh or with "kill -9" because
>>>> libvirtd
>>>> > kept
>>>> > >>>> saying, "cannot acquire state change lock," so I gracefully shut
>>>> down
>>>> > the
>>>> > >>>> remaining instances and rebooted the entire management
>>>> > server/hypervisor.
>>>> > >>>> Start over.
>>>> > >>>>
>>>> > >>>> When it came back up, the SSVM and console proxy started but the
>>>> > >>>> virtual router was stopped. I was able to manually start it
>>>> from the
>>>> > UI.
>>>> > >>>> The console proxy still times out when I try to access it from a
>>>> > browser.
>>>> > >>>> I don't see any errors in the management or agent logs, just
>>>> this:
>>>> > >>>>
>>>> > >>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request]
>>>> > (catalina-exec-10:null)
>>>> > >>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via:
>>>> 1(
>>>> > >>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
>>>> > >>>>
>>>> >
>>>> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
>>>> > >>>> }
>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>>> > >>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: {
>>>> Ans: ,
>>>> > >>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
>>>> > >>>>
>>>> >
>>>> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
>>>> > >>>> }
>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>>> > (catalina-exec-10:null)
>>>> > >>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734,
>>>> via: 1,
>>>> > Ver:
>>>> > >>>> v1, Flags: 10, { GetVncPortAnswer } }
>>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
>>>> > >>>> (catalina-exec-10:null) Port info 192.168.100.6
>>>> > >>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
>>>> > >>>> (catalina-exec-10:null) Parse host info returned from executing
>>>> > >>>> GetVNCPortCommand. host info: 192.168.100.6
>>>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>>> > >>>> (catalina-exec-10:null) Compose console url:
>>>> > >>>>
>>>> >
>>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>>> > >>>> (catalina-exec-10:null) the console url is ::
>>>> > >>>> <html><title>r-4-VM</title><frameset><frame src="
>>>> > >>>>
>>>> >
>>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>>> > >>>> "></frame></frameset></html>
>>>> > >>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
>>>> > >>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545:
>>>> {
>>>> > Cmd ,
>>>> > >>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>>>> > >>>>
>>>> >
>>>> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
>>>> > >>>> \"connections\": []\n}","wait":0}}] }
>>>> > >>>>
>>>> > >>>> If I try to restart the system VMs with cloudstack-sysvmadm, it
>>>> says:
>>>> > >>>>
>>>> > >>>> Stopping and starting 1 secondary storage vm(s)...
>>>> > >>>> curl: (7) couldn't connect to host
>>>> > >>>> ERROR: Failed to stop secondary storage vm with id 1
>>>> > >>>>
>>>> > >>>> Done stopping and starting secondary storage vm(s)
>>>> > >>>>
>>>> > >>>> Stopping and starting 1 console proxy vm(s)...
>>>> > >>>> curl: (7) couldn't connect to host
>>>> > >>>> ERROR: Failed to stop console proxy vm with id 2
>>>> > >>>>
>>>> > >>>> Done stopping and starting console proxy vm(s) .
>>>> > >>>>
>>>> > >>>> Stopping and starting 1 running routing vm(s)...
>>>> > >>>> curl: (7) couldn't connect to host
>>>> > >>>> 2
>>>> > >>>> Done restarting router(s).
>>>> > >>>>
>>>> > >>>> I notice there are now four entries for the same management
>>>> server in
>>>> > >>>> the mshost table, and they all are in an "Up" state and the
>>>> "removed"
>>>> > field
>>>> > >>>> is NULL. What's wrong with this system?
>>>> > >>>>
>>>> > >>>
>>>> > >>>
>>>> > >>
>>>> > >
>>>> >
>>>>
>>>
>>>
>>
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
The SSVM is stopped. If I try to start it, it complains about insufficient
capacity. CPU? RAM? I have plenty of both available.
2014-05-23 10:36:51,196 DEBUG [c.c.d.FirstFitPlanner]
(Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Listing clusters in order of
aggregate capacity, that have (atleast one host with) enough CPU and RAM
capacity under this Pod: 1
2014-05-23 10:36:51,198 DEBUG [c.c.d.FirstFitPlanner]
(Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Removing from the clusterId list
these clusters from avoid set: [1]
2014-05-23 10:36:51,198 DEBUG [c.c.d.FirstFitPlanner]
(Job-Executor-2:ctx-ababac38 ctx-0906d3c3) No clusters found after removing
disabled clusters and clusters in avoid list, returning.
2014-05-23 10:36:51,201 DEBUG [c.c.c.CapacityManagerImpl]
(Job-Executor-2:ctx-ababac38 ctx-0906d3c3) VM state transitted from
:Starting to Stopped with event: OperationFailedvm's original host id: 1
new host id: null host id before state transition: null
2014-05-23 10:36:51,201 WARN [c.c.s.s.SecondaryStorageManagerImpl]
(Job-Executor-2:ctx-ababac38 ctx-0906d3c3) Exception while trying to start
secondary storage vm
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[SecondaryStorageVm|s-1-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
On Fri, May 23, 2014 at 10:35 AM, Ian Young <iy...@ratespecial.com> wrote:
> I rebooted it and now it's in an even more broken state. It's repeatedly
> trying to stop the console proxy but can't because its state is "Starting."
> Here is an excerpt from the management log:
>
> http://pastebin.com/FiaDzKXb
>
> The agent log keeps repeating these messages:
>
> http://pastebin.com/yDidSbrz
>
> What's wrong with it?
>
>
> On Thu, May 22, 2014 at 12:55 PM, Ian Young <iy...@ratespecial.com>wrote:
>
>> I wonder if something is wrong with the NFS mount. I see this error
>> periodically in /var/log/messages even though I have set the Domain in
>> /etc/idmapd.conf to the host's FQDN:
>>
>> May 20 19:30:22 virthost1 rpc.idmapd[1790]: nss_getpwnam: name '0' does
>> not map into domain 'redacted.com'
>> May 20 19:36:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>> not map into domain 'redacted.com'
>> May 20 19:44:35 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>> not map into domain 'redacted.com'
>> May 21 10:21:25 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>> not map into domain 'redacted.com'
>> May 21 12:46:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>> not map into domain 'redacted.com'
>> May 21 13:52:42 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>> not map into domain 'redacted.com'
>> May 21 13:55:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
>> not map into domain 'redacted.com'
>> May 21 20:31:51 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
>> not map into domain 'redacted.com'
>> May 22 10:14:18 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>> not map into domain 'redacted.com'
>> May 22 10:18:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
>> not map into domain 'redacted.com'
>> May 22 10:19:23 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
>> not map into domain 'redacted.com'
>> May 22 10:25:16 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
>> not map into domain 'redacted.com'
>>
>> name '107' just started appearing in the log yesterday, which looks
>> unusual. Up until then, the error was always name '0'.
>>
>>
>> On Thu, May 22, 2014 at 11:15 AM, Andrija Panic <an...@gmail.com>wrote:
>>
>>> I have observed this kind of problems ("process blocked for more than xx
>>> sec...") when I had access with storage - check your disks, smartctl
>>> etc...
>>> best
>>>
>>> Sent from Google Nexus 4
>>> On May 22, 2014 7:49 PM, "Ian Young" <iy...@ratespecial.com> wrote:
>>>
>>> > And this is in /var/log/messages right before that event:
>>> >
>>> > May 22 10:16:07 virthost1 kernel: INFO: task qemu-kvm:2971 blocked for
>>> more
>>> > than 120 seconds.
>>> > May 22 10:16:07 virthost1 kernel: Not tainted
>>> > 2.6.32-431.11.2.el6.x86_64 #1
>>> > May 22 10:16:07 virthost1 kernel: "echo 0 >
>>> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>> > May 22 10:16:07 virthost1 kernel: qemu-kvm D 0000000000000002
>>> 0
>>> > 2971 1 0x00000080
>>> > May 22 10:16:07 virthost1 kernel: ffff8810724e9be8 0000000000000082
>>> > 0000000000000000 ffff88106b6529d8
>>> > May 22 10:16:07 virthost1 kernel: ffff880871b3e8d8 ffff880871b3e8f0
>>> > ffffffff8100bb8e ffff8810724e9be8
>>> > May 22 10:16:07 virthost1 kernel: ffff881073525058 ffff8810724e9fd8
>>> > 000000000000fbc8 ffff881073525058
>>> > May 22 10:16:07 virthost1 kernel: Call Trace:
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100bb8e>] ?
>>> > apic_timer_interrupt+0xe/0x20
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810555ef>] ?
>>> > mutex_spin_on_owner+0x9f/0xc0
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152969e>]
>>> > __mutex_lock_slowpath+0x13e/0x180
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152953b>]
>>> mutex_lock+0x2b/0x50
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c2cf>]
>>> > memory_access_ok+0x7f/0xc0 [vhost_net]
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021d89c>]
>>> > vhost_dev_ioctl+0x2ec/0xa50 [vhost_net]
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c411>] ?
>>> > vhost_work_flush+0xe1/0x120 [vhost_net]
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122db91>] ?
>>> > avc_has_perm+0x71/0x90
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021f11a>]
>>> > vhost_net_ioctl+0x7a/0x5d0 [vhost_net]
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122f914>] ?
>>> > inode_has_perm+0x54/0xa0
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa01a28b7>] ?
>>> > kvm_vcpu_ioctl+0x1e7/0x580 [kvm]
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8108b14e>] ?
>>> > send_signal+0x3e/0x90
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119dc12>]
>>> vfs_ioctl+0x22/0xa0
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119ddb4>]
>>> > do_vfs_ioctl+0x84/0x580
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119e331>]
>>> sys_ioctl+0x81/0xa0
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810e1e4e>] ?
>>> > __audit_syscall_exit+0x25e/0x290
>>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100b072>]
>>> > system_call_fastpath+0x16/0x1b
>>> >
>>> >
>>> > On Thu, May 22, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com>
>>> > wrote:
>>> >
>>> > > The console proxy became unavailable again yesterday afternoon. I
>>> could
>>> > > SSH into it via its link local address and nothing seemed to be wrong
>>> > > inside the VM itself. However, the qemu-kvm process for that VM was
>>> at
>>> > > almost 100% CPU. Inside the VM, the CPU usage was minimal and the
>>> java
>>> > > process was running and listening on port 443. So there seems to be
>>> > > something wrong with it down at the KVM/QEMU level. It's weird how
>>> this
>>> > > keeps happening to the console proxy only and not any of the other
>>> VMs.
>>> > I
>>> > > tried to reboot it from the management UI and after about 15
>>> minutes, it
>>> > > finally did. Now the console proxy is working but I don't know how
>>> long
>>> > it
>>> > > will last before it breaks again. I found this in libvirtd.log,
>>> which
>>> > > corresponds with the time the console proxy rebooted:
>>> > >
>>> > > 2014-05-22 17:17:04.362+0000: 25195: info : libvirt version: 0.10.2,
>>> > > package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
>>> > > 2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
>>> > > 2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 :
>>> internal
>>> > > error End of file from monitor
>>> > >
>>> > >
>>> > > On Wed, May 21, 2014 at 2:07 PM, Ian Young <iy...@ratespecial.com>
>>> > wrote:
>>> > >
>>> > >> I built and installed a libvirt 1.04 package from the Fedora src
>>> rpm.
>>> > It
>>> > >> installed fine inside a test VM but installing it on the real
>>> hypervisor
>>> > >> was a bad idea and I doubt I'll be pursuing it further. All VMs
>>> > promptly
>>> > >> stopped and this appeared in libvirtd.log:
>>> > >>
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version: 1.0.4,
>>> > >> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>> virDriverLoadModule:72 :
>>> > >> Module
>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so
>>> > not
>>> > >> accessible
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>> virDriverLoadModule:72 :
>>> > >> Module
>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so
>>> > not
>>> > >> accessible
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>> virDriverLoadModule:72 :
>>> > >> Module
>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so
>>> > not
>>> > >> accessible
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>> virDriverLoadModule:72 :
>>> > >> Module
>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so not
>>> > >> accessible
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>> virDriverLoadModule:72 :
>>> > >> Module
>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so
>>> > not
>>> > >> accessible
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>> virDriverLoadModule:72 :
>>> > >> Module
>>> /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so
>>> > not
>>> > >> accessible
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>> virDriverLoadModule:72 :
>>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so
>>> not
>>> > >> accessible
>>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>>> virDriverLoadModule:72 :
>>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so
>>> not
>>> > >> accessible
>>> > >> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no
>>> > connection
>>> > >> driver available for qemu:///system
>>> > >> 2014-05-21 20:36:49.472+0000: 23567: error :
>>> virNetSocketReadWire:1370 :
>>> > >> End of file while reading data: Input/output error
>>> > >> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no
>>> > connection
>>> > >> driver available for lxc:///
>>> > >> 2014-05-21 20:36:49.474+0000: 23567: error :
>>> virNetSocketReadWire:1370 :
>>> > >> End of file while reading data: Input/output error
>>> > >> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no
>>> > connection
>>> > >> driver available for qemu:///system
>>> > >> 2014-05-21 20:36:49.476+0000: 23567: error :
>>> virNetSocketReadWire:1370 :
>>> > >> End of file while reading data: Input/output error
>>> > >> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no
>>> > connection
>>> > >> driver available for qemu:///system
>>> > >> 2014-05-21 20:36:49.678+0000: 23567: error :
>>> virNetSocketReadWire:1370 :
>>> > >> End of file while reading data: Input/output error
>>> > >> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no
>>> > connection
>>> > >> driver available for qemu:///system
>>> > >> 2014-05-21 20:36:49.682+0000: 23567: error :
>>> virNetSocketReadWire:1370 :
>>> > >> End of file while reading data: Input/output error
>>> > >>
>>> > >>
>>> > >> On Wed, May 21, 2014 at 10:45 AM, Ian Young <iyoung@ratespecial.com
>>> > >wrote:
>>> > >>
>>> > >>> I was able to get it working by following these steps:
>>> > >>>
>>> > >>> 1. stop all instances
>>> > >>> 2. service cloudstack-management stop
>>> > >>> 3. service cloudstack-agent stop
>>> > >>> 4. virsh shutdown {domain} (for each of the system VMs)
>>> > >>> 5. service libvirtd stop
>>> > >>> 6. umount primary and secondary
>>> > >>> 7. reboot
>>> > >>>
>>> > >>> The console proxy is working again. I expect it will probably
>>> break
>>> > >>> again in a day or two. I have a feeling it's a result of this
>>> libvirtd
>>> > >>> bug, since I've seen the "cannot acquire state change lock" several
>>> > times.
>>> > >>>
>>> > >>> https://bugs.launchpad.net/nova/+bug/1254872
>>> > >>>
>>> > >>> I might try building my own libvirtd 1.0.3 for EL6.
>>> > >>>
>>> > >>>
>>> > >>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <iyoung@ratespecial.com
>>> > >wrote:
>>> > >>>
>>> > >>>> So I got the console proxy working via HTTPS (by managing my own "
>>> > >>>> realhostip.com" DNS) last week and everything was working fine.
>>> > >>>> Today, all of a sudden, the console proxy stopped working again.
>>> The
>>> > >>>> browser says, "Connecting to 192-168-100-159.realhostip.com..."
>>> and
>>> > >>>> eventually times out. I tried to restart it and it went into a
>>> > "Stopping"
>>> > >>>> state that never completed and the Agent State was
>>> "Disconnected." I
>>> > could
>>> > >>>> not shut down the VM using virsh or with "kill -9" because
>>> libvirtd
>>> > kept
>>> > >>>> saying, "cannot acquire state change lock," so I gracefully shut
>>> down
>>> > the
>>> > >>>> remaining instances and rebooted the entire management
>>> > server/hypervisor.
>>> > >>>> Start over.
>>> > >>>>
>>> > >>>> When it came back up, the SSVM and console proxy started but the
>>> > >>>> virtual router was stopped. I was able to manually start it from
>>> the
>>> > UI.
>>> > >>>> The console proxy still times out when I try to access it from a
>>> > browser.
>>> > >>>> I don't see any errors in the management or agent logs, just
>>> this:
>>> > >>>>
>>> > >>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request]
>>> > (catalina-exec-10:null)
>>> > >>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
>>> > >>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
>>> > >>>>
>>> >
>>> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
>>> > >>>> }
>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>> > >>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: {
>>> Ans: ,
>>> > >>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
>>> > >>>>
>>> >
>>> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
>>> > >>>> }
>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>> > (catalina-exec-10:null)
>>> > >>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734,
>>> via: 1,
>>> > Ver:
>>> > >>>> v1, Flags: 10, { GetVncPortAnswer } }
>>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
>>> > >>>> (catalina-exec-10:null) Port info 192.168.100.6
>>> > >>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
>>> > >>>> (catalina-exec-10:null) Parse host info returned from executing
>>> > >>>> GetVNCPortCommand. host info: 192.168.100.6
>>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>> > >>>> (catalina-exec-10:null) Compose console url:
>>> > >>>>
>>> >
>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>> > >>>> (catalina-exec-10:null) the console url is ::
>>> > >>>> <html><title>r-4-VM</title><frameset><frame src="
>>> > >>>>
>>> >
>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>> > >>>> "></frame></frameset></html>
>>> > >>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
>>> > >>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: {
>>> > Cmd ,
>>> > >>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>>> > >>>>
>>> >
>>> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
>>> > >>>> \"connections\": []\n}","wait":0}}] }
>>> > >>>>
>>> > >>>> If I try to restart the system VMs with cloudstack-sysvmadm, it
>>> says:
>>> > >>>>
>>> > >>>> Stopping and starting 1 secondary storage vm(s)...
>>> > >>>> curl: (7) couldn't connect to host
>>> > >>>> ERROR: Failed to stop secondary storage vm with id 1
>>> > >>>>
>>> > >>>> Done stopping and starting secondary storage vm(s)
>>> > >>>>
>>> > >>>> Stopping and starting 1 console proxy vm(s)...
>>> > >>>> curl: (7) couldn't connect to host
>>> > >>>> ERROR: Failed to stop console proxy vm with id 2
>>> > >>>>
>>> > >>>> Done stopping and starting console proxy vm(s) .
>>> > >>>>
>>> > >>>> Stopping and starting 1 running routing vm(s)...
>>> > >>>> curl: (7) couldn't connect to host
>>> > >>>> 2
>>> > >>>> Done restarting router(s).
>>> > >>>>
>>> > >>>> I notice there are now four entries for the same management
>>> server in
>>> > >>>> the mshost table, and they all are in an "Up" state and the
>>> "removed"
>>> > field
>>> > >>>> is NULL. What's wrong with this system?
>>> > >>>>
>>> > >>>
>>> > >>>
>>> > >>
>>> > >
>>> >
>>>
>>
>>
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
I rebooted it and now it's in an even more broken state. It's repeatedly
trying to stop the console proxy but can't because its state is "Starting."
Here is an excerpt from the management log:
http://pastebin.com/FiaDzKXb
The agent log keeps repeating these messages:
http://pastebin.com/yDidSbrz
What's wrong with it?
On Thu, May 22, 2014 at 12:55 PM, Ian Young <iy...@ratespecial.com> wrote:
> I wonder if something is wrong with the NFS mount. I see this error
> periodically in /var/log/messages even though I have set the Domain in
> /etc/idmapd.conf to the host's FQDN:
>
> May 20 19:30:22 virthost1 rpc.idmapd[1790]: nss_getpwnam: name '0' does
> not map into domain 'redacted.com'
> May 20 19:36:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
> not map into domain 'redacted.com'
> May 20 19:44:35 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
> not map into domain 'redacted.com'
> May 21 10:21:25 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
> not map into domain 'redacted.com'
> May 21 12:46:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
> not map into domain 'redacted.com'
> May 21 13:52:42 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
> not map into domain 'redacted.com'
> May 21 13:55:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
> not map into domain 'redacted.com'
> May 21 20:31:51 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
> not map into domain 'redacted.com'
> May 22 10:14:18 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
> not map into domain 'redacted.com'
> May 22 10:18:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
> not map into domain 'redacted.com'
> May 22 10:19:23 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does
> not map into domain 'redacted.com'
> May 22 10:25:16 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
> not map into domain 'redacted.com'
>
> name '107' just started appearing in the log yesterday, which looks
> unusual. Up until then, the error was always name '0'.
>
>
> On Thu, May 22, 2014 at 11:15 AM, Andrija Panic <an...@gmail.com>wrote:
>
>> I have observed this kind of problems ("process blocked for more than xx
>> sec...") when I had access with storage - check your disks, smartctl
>> etc...
>> best
>>
>> Sent from Google Nexus 4
>> On May 22, 2014 7:49 PM, "Ian Young" <iy...@ratespecial.com> wrote:
>>
>> > And this is in /var/log/messages right before that event:
>> >
>> > May 22 10:16:07 virthost1 kernel: INFO: task qemu-kvm:2971 blocked for
>> more
>> > than 120 seconds.
>> > May 22 10:16:07 virthost1 kernel: Not tainted
>> > 2.6.32-431.11.2.el6.x86_64 #1
>> > May 22 10:16:07 virthost1 kernel: "echo 0 >
>> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> > May 22 10:16:07 virthost1 kernel: qemu-kvm D 0000000000000002 0
>> > 2971 1 0x00000080
>> > May 22 10:16:07 virthost1 kernel: ffff8810724e9be8 0000000000000082
>> > 0000000000000000 ffff88106b6529d8
>> > May 22 10:16:07 virthost1 kernel: ffff880871b3e8d8 ffff880871b3e8f0
>> > ffffffff8100bb8e ffff8810724e9be8
>> > May 22 10:16:07 virthost1 kernel: ffff881073525058 ffff8810724e9fd8
>> > 000000000000fbc8 ffff881073525058
>> > May 22 10:16:07 virthost1 kernel: Call Trace:
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100bb8e>] ?
>> > apic_timer_interrupt+0xe/0x20
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810555ef>] ?
>> > mutex_spin_on_owner+0x9f/0xc0
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152969e>]
>> > __mutex_lock_slowpath+0x13e/0x180
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152953b>]
>> mutex_lock+0x2b/0x50
>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c2cf>]
>> > memory_access_ok+0x7f/0xc0 [vhost_net]
>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021d89c>]
>> > vhost_dev_ioctl+0x2ec/0xa50 [vhost_net]
>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c411>] ?
>> > vhost_work_flush+0xe1/0x120 [vhost_net]
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122db91>] ?
>> > avc_has_perm+0x71/0x90
>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021f11a>]
>> > vhost_net_ioctl+0x7a/0x5d0 [vhost_net]
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122f914>] ?
>> > inode_has_perm+0x54/0xa0
>> > May 22 10:16:07 virthost1 kernel: [<ffffffffa01a28b7>] ?
>> > kvm_vcpu_ioctl+0x1e7/0x580 [kvm]
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8108b14e>] ?
>> > send_signal+0x3e/0x90
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119dc12>]
>> vfs_ioctl+0x22/0xa0
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119ddb4>]
>> > do_vfs_ioctl+0x84/0x580
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119e331>]
>> sys_ioctl+0x81/0xa0
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff810e1e4e>] ?
>> > __audit_syscall_exit+0x25e/0x290
>> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100b072>]
>> > system_call_fastpath+0x16/0x1b
>> >
>> >
>> > On Thu, May 22, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com>
>> > wrote:
>> >
>> > > The console proxy became unavailable again yesterday afternoon. I
>> could
>> > > SSH into it via its link local address and nothing seemed to be wrong
>> > > inside the VM itself. However, the qemu-kvm process for that VM was
>> at
>> > > almost 100% CPU. Inside the VM, the CPU usage was minimal and the
>> java
>> > > process was running and listening on port 443. So there seems to be
>> > > something wrong with it down at the KVM/QEMU level. It's weird how
>> this
>> > > keeps happening to the console proxy only and not any of the other
>> VMs.
>> > I
>> > > tried to reboot it from the management UI and after about 15 minutes,
>> it
>> > > finally did. Now the console proxy is working but I don't know how
>> long
>> > it
>> > > will last before it breaks again. I found this in libvirtd.log, which
>> > > corresponds with the time the console proxy rebooted:
>> > >
>> > > 2014-05-22 17:17:04.362+0000: 25195: info : libvirt version: 0.10.2,
>> > > package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
>> > > 2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
>> > > 2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 :
>> internal
>> > > error End of file from monitor
>> > >
>> > >
>> > > On Wed, May 21, 2014 at 2:07 PM, Ian Young <iy...@ratespecial.com>
>> > wrote:
>> > >
>> > >> I built and installed a libvirt 1.04 package from the Fedora src rpm.
>> > It
>> > >> installed fine inside a test VM but installing it on the real
>> hypervisor
>> > >> was a bad idea and I doubt I'll be pursuing it further. All VMs
>> > promptly
>> > >> stopped and this appeared in libvirtd.log:
>> > >>
>> > >> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version: 1.0.4,
>> > >> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>> virDriverLoadModule:72 :
>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so
>> > not
>> > >> accessible
>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>> virDriverLoadModule:72 :
>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so
>> > not
>> > >> accessible
>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>> virDriverLoadModule:72 :
>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so
>> > not
>> > >> accessible
>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>> virDriverLoadModule:72 :
>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so
>> not
>> > >> accessible
>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>> virDriverLoadModule:72 :
>> > >> Module
>> /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so
>> > not
>> > >> accessible
>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>> virDriverLoadModule:72 :
>> > >> Module
>> /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so
>> > not
>> > >> accessible
>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>> virDriverLoadModule:72 :
>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so
>> not
>> > >> accessible
>> > >> 2014-05-21 20:36:19.260+0000: 23567: warning :
>> virDriverLoadModule:72 :
>> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so not
>> > >> accessible
>> > >> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no
>> > connection
>> > >> driver available for qemu:///system
>> > >> 2014-05-21 20:36:49.472+0000: 23567: error :
>> virNetSocketReadWire:1370 :
>> > >> End of file while reading data: Input/output error
>> > >> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no
>> > connection
>> > >> driver available for lxc:///
>> > >> 2014-05-21 20:36:49.474+0000: 23567: error :
>> virNetSocketReadWire:1370 :
>> > >> End of file while reading data: Input/output error
>> > >> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no
>> > connection
>> > >> driver available for qemu:///system
>> > >> 2014-05-21 20:36:49.476+0000: 23567: error :
>> virNetSocketReadWire:1370 :
>> > >> End of file while reading data: Input/output error
>> > >> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no
>> > connection
>> > >> driver available for qemu:///system
>> > >> 2014-05-21 20:36:49.678+0000: 23567: error :
>> virNetSocketReadWire:1370 :
>> > >> End of file while reading data: Input/output error
>> > >> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no
>> > connection
>> > >> driver available for qemu:///system
>> > >> 2014-05-21 20:36:49.682+0000: 23567: error :
>> virNetSocketReadWire:1370 :
>> > >> End of file while reading data: Input/output error
>> > >>
>> > >>
>> > >> On Wed, May 21, 2014 at 10:45 AM, Ian Young <iyoung@ratespecial.com
>> > >wrote:
>> > >>
>> > >>> I was able to get it working by following these steps:
>> > >>>
>> > >>> 1. stop all instances
>> > >>> 2. service cloudstack-management stop
>> > >>> 3. service cloudstack-agent stop
>> > >>> 4. virsh shutdown {domain} (for each of the system VMs)
>> > >>> 5. service libvirtd stop
>> > >>> 6. umount primary and secondary
>> > >>> 7. reboot
>> > >>>
>> > >>> The console proxy is working again. I expect it will probably break
>> > >>> again in a day or two. I have a feeling it's a result of this
>> libvirtd
>> > >>> bug, since I've seen the "cannot acquire state change lock" several
>> > times.
>> > >>>
>> > >>> https://bugs.launchpad.net/nova/+bug/1254872
>> > >>>
>> > >>> I might try building my own libvirtd 1.0.3 for EL6.
>> > >>>
>> > >>>
>> > >>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <iyoung@ratespecial.com
>> > >wrote:
>> > >>>
>> > >>>> So I got the console proxy working via HTTPS (by managing my own "
>> > >>>> realhostip.com" DNS) last week and everything was working fine.
>> > >>>> Today, all of a sudden, the console proxy stopped working again.
>> The
>> > >>>> browser says, "Connecting to 192-168-100-159.realhostip.com..." and
>> > >>>> eventually times out. I tried to restart it and it went into a
>> > "Stopping"
>> > >>>> state that never completed and the Agent State was "Disconnected."
>> I
>> > could
>> > >>>> not shut down the VM using virsh or with "kill -9" because libvirtd
>> > kept
>> > >>>> saying, "cannot acquire state change lock," so I gracefully shut
>> down
>> > the
>> > >>>> remaining instances and rebooted the entire management
>> > server/hypervisor.
>> > >>>> Start over.
>> > >>>>
>> > >>>> When it came back up, the SSVM and console proxy started but the
>> > >>>> virtual router was stopped. I was able to manually start it from
>> the
>> > UI.
>> > >>>> The console proxy still times out when I try to access it from a
>> > browser.
>> > >>>> I don't see any errors in the management or agent logs, just this:
>> > >>>>
>> > >>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request]
>> > (catalina-exec-10:null)
>> > >>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
>> > >>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
>> > >>>>
>> >
>> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
>> > >>>> }
>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>> > >>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: {
>> Ans: ,
>> > >>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
>> > >>>>
>> >
>> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
>> > >>>> }
>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>> > (catalina-exec-10:null)
>> > >>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734, via:
>> 1,
>> > Ver:
>> > >>>> v1, Flags: 10, { GetVncPortAnswer } }
>> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
>> > >>>> (catalina-exec-10:null) Port info 192.168.100.6
>> > >>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
>> > >>>> (catalina-exec-10:null) Parse host info returned from executing
>> > >>>> GetVNCPortCommand. host info: 192.168.100.6
>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>> > >>>> (catalina-exec-10:null) Compose console url:
>> > >>>>
>> >
>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>> > >>>> (catalina-exec-10:null) the console url is ::
>> > >>>> <html><title>r-4-VM</title><frameset><frame src="
>> > >>>>
>> >
>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>> > >>>> "></frame></frameset></html>
>> > >>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
>> > >>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: {
>> > Cmd ,
>> > >>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>> > >>>>
>> >
>> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
>> > >>>> \"connections\": []\n}","wait":0}}] }
>> > >>>>
>> > >>>> If I try to restart the system VMs with cloudstack-sysvmadm, it
>> says:
>> > >>>>
>> > >>>> Stopping and starting 1 secondary storage vm(s)...
>> > >>>> curl: (7) couldn't connect to host
>> > >>>> ERROR: Failed to stop secondary storage vm with id 1
>> > >>>>
>> > >>>> Done stopping and starting secondary storage vm(s)
>> > >>>>
>> > >>>> Stopping and starting 1 console proxy vm(s)...
>> > >>>> curl: (7) couldn't connect to host
>> > >>>> ERROR: Failed to stop console proxy vm with id 2
>> > >>>>
>> > >>>> Done stopping and starting console proxy vm(s) .
>> > >>>>
>> > >>>> Stopping and starting 1 running routing vm(s)...
>> > >>>> curl: (7) couldn't connect to host
>> > >>>> 2
>> > >>>> Done restarting router(s).
>> > >>>>
>> > >>>> I notice there are now four entries for the same management server
>> in
>> > >>>> the mshost table, and they all are in an "Up" state and the
>> "removed"
>> > field
>> > >>>> is NULL. What's wrong with this system?
>> > >>>>
>> > >>>
>> > >>>
>> > >>
>> > >
>> >
>>
>
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
I wonder if something is wrong with the NFS mount. I see this error
periodically in /var/log/messages even though I have set the Domain in
/etc/idmapd.conf to the host's FQDN:
May 20 19:30:22 virthost1 rpc.idmapd[1790]: nss_getpwnam: name '0' does not
map into domain 'redacted.com'
May 20 19:36:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does not
map into domain 'redacted.com'
May 20 19:44:35 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does not
map into domain 'redacted.com'
May 21 10:21:25 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does not
map into domain 'redacted.com'
May 21 12:46:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does not
map into domain 'redacted.com'
May 21 13:52:42 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does not
map into domain 'redacted.com'
May 21 13:55:20 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
not map into domain 'redacted.com'
May 21 20:31:51 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
not map into domain 'redacted.com'
May 22 10:14:18 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does not
map into domain 'redacted.com'
May 22 10:18:40 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
not map into domain 'redacted.com'
May 22 10:19:23 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '0' does not
map into domain 'redacted.com'
May 22 10:25:16 virthost1 rpc.idmapd[1731]: nss_getpwnam: name '107' does
not map into domain 'redacted.com'
name '107' just started appearing in the log yesterday, which looks
unusual. Up until then, the error was always name '0'.
On Thu, May 22, 2014 at 11:15 AM, Andrija Panic <an...@gmail.com>wrote:
> I have observed this kind of problems ("process blocked for more than xx
> sec...") when I had access with storage - check your disks, smartctl
> etc...
> best
>
> Sent from Google Nexus 4
> On May 22, 2014 7:49 PM, "Ian Young" <iy...@ratespecial.com> wrote:
>
> > And this is in /var/log/messages right before that event:
> >
> > May 22 10:16:07 virthost1 kernel: INFO: task qemu-kvm:2971 blocked for
> more
> > than 120 seconds.
> > May 22 10:16:07 virthost1 kernel: Not tainted
> > 2.6.32-431.11.2.el6.x86_64 #1
> > May 22 10:16:07 virthost1 kernel: "echo 0 >
> > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > May 22 10:16:07 virthost1 kernel: qemu-kvm D 0000000000000002 0
> > 2971 1 0x00000080
> > May 22 10:16:07 virthost1 kernel: ffff8810724e9be8 0000000000000082
> > 0000000000000000 ffff88106b6529d8
> > May 22 10:16:07 virthost1 kernel: ffff880871b3e8d8 ffff880871b3e8f0
> > ffffffff8100bb8e ffff8810724e9be8
> > May 22 10:16:07 virthost1 kernel: ffff881073525058 ffff8810724e9fd8
> > 000000000000fbc8 ffff881073525058
> > May 22 10:16:07 virthost1 kernel: Call Trace:
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100bb8e>] ?
> > apic_timer_interrupt+0xe/0x20
> > May 22 10:16:07 virthost1 kernel: [<ffffffff810555ef>] ?
> > mutex_spin_on_owner+0x9f/0xc0
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152969e>]
> > __mutex_lock_slowpath+0x13e/0x180
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8152953b>]
> mutex_lock+0x2b/0x50
> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c2cf>]
> > memory_access_ok+0x7f/0xc0 [vhost_net]
> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021d89c>]
> > vhost_dev_ioctl+0x2ec/0xa50 [vhost_net]
> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021c411>] ?
> > vhost_work_flush+0xe1/0x120 [vhost_net]
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122db91>] ?
> > avc_has_perm+0x71/0x90
> > May 22 10:16:07 virthost1 kernel: [<ffffffffa021f11a>]
> > vhost_net_ioctl+0x7a/0x5d0 [vhost_net]
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8122f914>] ?
> > inode_has_perm+0x54/0xa0
> > May 22 10:16:07 virthost1 kernel: [<ffffffffa01a28b7>] ?
> > kvm_vcpu_ioctl+0x1e7/0x580 [kvm]
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8108b14e>] ?
> > send_signal+0x3e/0x90
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119dc12>]
> vfs_ioctl+0x22/0xa0
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119ddb4>]
> > do_vfs_ioctl+0x84/0x580
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8119e331>]
> sys_ioctl+0x81/0xa0
> > May 22 10:16:07 virthost1 kernel: [<ffffffff810e1e4e>] ?
> > __audit_syscall_exit+0x25e/0x290
> > May 22 10:16:07 virthost1 kernel: [<ffffffff8100b072>]
> > system_call_fastpath+0x16/0x1b
> >
> >
> > On Thu, May 22, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com>
> > wrote:
> >
> > > The console proxy became unavailable again yesterday afternoon. I
> could
> > > SSH into it via its link local address and nothing seemed to be wrong
> > > inside the VM itself. However, the qemu-kvm process for that VM was at
> > > almost 100% CPU. Inside the VM, the CPU usage was minimal and the java
> > > process was running and listening on port 443. So there seems to be
> > > something wrong with it down at the KVM/QEMU level. It's weird how
> this
> > > keeps happening to the console proxy only and not any of the other VMs.
> > I
> > > tried to reboot it from the management UI and after about 15 minutes,
> it
> > > finally did. Now the console proxy is working but I don't know how
> long
> > it
> > > will last before it breaks again. I found this in libvirtd.log, which
> > > corresponds with the time the console proxy rebooted:
> > >
> > > 2014-05-22 17:17:04.362+0000: 25195: info : libvirt version: 0.10.2,
> > > package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
> > > 2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
> > > 2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 :
> internal
> > > error End of file from monitor
> > >
> > >
> > > On Wed, May 21, 2014 at 2:07 PM, Ian Young <iy...@ratespecial.com>
> > wrote:
> > >
> > >> I built and installed a libvirt 1.04 package from the Fedora src rpm.
> > It
> > >> installed fine inside a test VM but installing it on the real
> hypervisor
> > >> was a bad idea and I doubt I'll be pursuing it further. All VMs
> > promptly
> > >> stopped and this appeared in libvirtd.log:
> > >>
> > >> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version: 1.0.4,
> > >> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
> > >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72
> :
> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so
> > not
> > >> accessible
> > >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72
> :
> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so
> > not
> > >> accessible
> > >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72
> :
> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so
> > not
> > >> accessible
> > >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72
> :
> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so
> not
> > >> accessible
> > >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72
> :
> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so
> > not
> > >> accessible
> > >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72
> :
> > >> Module
> /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so
> > not
> > >> accessible
> > >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72
> :
> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so not
> > >> accessible
> > >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72
> :
> > >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so not
> > >> accessible
> > >> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no
> > connection
> > >> driver available for qemu:///system
> > >> 2014-05-21 20:36:49.472+0000: 23567: error :
> virNetSocketReadWire:1370 :
> > >> End of file while reading data: Input/output error
> > >> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no
> > connection
> > >> driver available for lxc:///
> > >> 2014-05-21 20:36:49.474+0000: 23567: error :
> virNetSocketReadWire:1370 :
> > >> End of file while reading data: Input/output error
> > >> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no
> > connection
> > >> driver available for qemu:///system
> > >> 2014-05-21 20:36:49.476+0000: 23567: error :
> virNetSocketReadWire:1370 :
> > >> End of file while reading data: Input/output error
> > >> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no
> > connection
> > >> driver available for qemu:///system
> > >> 2014-05-21 20:36:49.678+0000: 23567: error :
> virNetSocketReadWire:1370 :
> > >> End of file while reading data: Input/output error
> > >> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no
> > connection
> > >> driver available for qemu:///system
> > >> 2014-05-21 20:36:49.682+0000: 23567: error :
> virNetSocketReadWire:1370 :
> > >> End of file while reading data: Input/output error
> > >>
> > >>
> > >> On Wed, May 21, 2014 at 10:45 AM, Ian Young <iyoung@ratespecial.com
> > >wrote:
> > >>
> > >>> I was able to get it working by following these steps:
> > >>>
> > >>> 1. stop all instances
> > >>> 2. service cloudstack-management stop
> > >>> 3. service cloudstack-agent stop
> > >>> 4. virsh shutdown {domain} (for each of the system VMs)
> > >>> 5. service libvirtd stop
> > >>> 6. umount primary and secondary
> > >>> 7. reboot
> > >>>
> > >>> The console proxy is working again. I expect it will probably break
> > >>> again in a day or two. I have a feeling it's a result of this
> libvirtd
> > >>> bug, since I've seen the "cannot acquire state change lock" several
> > times.
> > >>>
> > >>> https://bugs.launchpad.net/nova/+bug/1254872
> > >>>
> > >>> I might try building my own libvirtd 1.0.3 for EL6.
> > >>>
> > >>>
> > >>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <iyoung@ratespecial.com
> > >wrote:
> > >>>
> > >>>> So I got the console proxy working via HTTPS (by managing my own "
> > >>>> realhostip.com" DNS) last week and everything was working fine.
> > >>>> Today, all of a sudden, the console proxy stopped working again.
> The
> > >>>> browser says, "Connecting to 192-168-100-159.realhostip.com..." and
> > >>>> eventually times out. I tried to restart it and it went into a
> > "Stopping"
> > >>>> state that never completed and the Agent State was "Disconnected."
> I
> > could
> > >>>> not shut down the VM using virsh or with "kill -9" because libvirtd
> > kept
> > >>>> saying, "cannot acquire state change lock," so I gracefully shut
> down
> > the
> > >>>> remaining instances and rebooted the entire management
> > server/hypervisor.
> > >>>> Start over.
> > >>>>
> > >>>> When it came back up, the SSVM and console proxy started but the
> > >>>> virtual router was stopped. I was able to manually start it from
> the
> > UI.
> > >>>> The console proxy still times out when I try to access it from a
> > browser.
> > >>>> I don't see any errors in the management or agent logs, just this:
> > >>>>
> > >>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request]
> > (catalina-exec-10:null)
> > >>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
> > >>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
> > >>>>
> >
> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
> > >>>> }
> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
> > >>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: { Ans:
> ,
> > >>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
> > >>>>
> >
> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
> > >>>> }
> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
> > (catalina-exec-10:null)
> > >>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734, via:
> 1,
> > Ver:
> > >>>> v1, Flags: 10, { GetVncPortAnswer } }
> > >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
> > >>>> (catalina-exec-10:null) Port info 192.168.100.6
> > >>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
> > >>>> (catalina-exec-10:null) Parse host info returned from executing
> > >>>> GetVNCPortCommand. host info: 192.168.100.6
> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
> > >>>> (catalina-exec-10:null) Compose console url:
> > >>>>
> >
> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
> > >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
> > >>>> (catalina-exec-10:null) the console url is ::
> > >>>> <html><title>r-4-VM</title><frameset><frame src="
> > >>>>
> >
> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
> > >>>> "></frame></frameset></html>
> > >>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
> > >>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: {
> > Cmd ,
> > >>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> > >>>>
> >
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> > >>>> \"connections\": []\n}","wait":0}}] }
> > >>>>
> > >>>> If I try to restart the system VMs with cloudstack-sysvmadm, it
> says:
> > >>>>
> > >>>> Stopping and starting 1 secondary storage vm(s)...
> > >>>> curl: (7) couldn't connect to host
> > >>>> ERROR: Failed to stop secondary storage vm with id 1
> > >>>>
> > >>>> Done stopping and starting secondary storage vm(s)
> > >>>>
> > >>>> Stopping and starting 1 console proxy vm(s)...
> > >>>> curl: (7) couldn't connect to host
> > >>>> ERROR: Failed to stop console proxy vm with id 2
> > >>>>
> > >>>> Done stopping and starting console proxy vm(s) .
> > >>>>
> > >>>> Stopping and starting 1 running routing vm(s)...
> > >>>> curl: (7) couldn't connect to host
> > >>>> 2
> > >>>> Done restarting router(s).
> > >>>>
> > >>>> I notice there are now four entries for the same management server
> in
> > >>>> the mshost table, and they all are in an "Up" state and the
> "removed"
> > field
> > >>>> is NULL. What's wrong with this system?
> > >>>>
> > >>>
> > >>>
> > >>
> > >
> >
>
Re: console proxy times out
Posted by Andrija Panic <an...@gmail.com>.
I have observed this kind of problems ("process blocked for more than xx
sec...") when I had access with storage - check your disks, smartctl etc...
best
Sent from Google Nexus 4
On May 22, 2014 7:49 PM, "Ian Young" <iy...@ratespecial.com> wrote:
> And this is in /var/log/messages right before that event:
>
> May 22 10:16:07 virthost1 kernel: INFO: task qemu-kvm:2971 blocked for more
> than 120 seconds.
> May 22 10:16:07 virthost1 kernel: Not tainted
> 2.6.32-431.11.2.el6.x86_64 #1
> May 22 10:16:07 virthost1 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> May 22 10:16:07 virthost1 kernel: qemu-kvm D 0000000000000002 0
> 2971 1 0x00000080
> May 22 10:16:07 virthost1 kernel: ffff8810724e9be8 0000000000000082
> 0000000000000000 ffff88106b6529d8
> May 22 10:16:07 virthost1 kernel: ffff880871b3e8d8 ffff880871b3e8f0
> ffffffff8100bb8e ffff8810724e9be8
> May 22 10:16:07 virthost1 kernel: ffff881073525058 ffff8810724e9fd8
> 000000000000fbc8 ffff881073525058
> May 22 10:16:07 virthost1 kernel: Call Trace:
> May 22 10:16:07 virthost1 kernel: [<ffffffff8100bb8e>] ?
> apic_timer_interrupt+0xe/0x20
> May 22 10:16:07 virthost1 kernel: [<ffffffff810555ef>] ?
> mutex_spin_on_owner+0x9f/0xc0
> May 22 10:16:07 virthost1 kernel: [<ffffffff8152969e>]
> __mutex_lock_slowpath+0x13e/0x180
> May 22 10:16:07 virthost1 kernel: [<ffffffff8152953b>] mutex_lock+0x2b/0x50
> May 22 10:16:07 virthost1 kernel: [<ffffffffa021c2cf>]
> memory_access_ok+0x7f/0xc0 [vhost_net]
> May 22 10:16:07 virthost1 kernel: [<ffffffffa021d89c>]
> vhost_dev_ioctl+0x2ec/0xa50 [vhost_net]
> May 22 10:16:07 virthost1 kernel: [<ffffffffa021c411>] ?
> vhost_work_flush+0xe1/0x120 [vhost_net]
> May 22 10:16:07 virthost1 kernel: [<ffffffff8122db91>] ?
> avc_has_perm+0x71/0x90
> May 22 10:16:07 virthost1 kernel: [<ffffffffa021f11a>]
> vhost_net_ioctl+0x7a/0x5d0 [vhost_net]
> May 22 10:16:07 virthost1 kernel: [<ffffffff8122f914>] ?
> inode_has_perm+0x54/0xa0
> May 22 10:16:07 virthost1 kernel: [<ffffffffa01a28b7>] ?
> kvm_vcpu_ioctl+0x1e7/0x580 [kvm]
> May 22 10:16:07 virthost1 kernel: [<ffffffff8108b14e>] ?
> send_signal+0x3e/0x90
> May 22 10:16:07 virthost1 kernel: [<ffffffff8119dc12>] vfs_ioctl+0x22/0xa0
> May 22 10:16:07 virthost1 kernel: [<ffffffff8119ddb4>]
> do_vfs_ioctl+0x84/0x580
> May 22 10:16:07 virthost1 kernel: [<ffffffff8119e331>] sys_ioctl+0x81/0xa0
> May 22 10:16:07 virthost1 kernel: [<ffffffff810e1e4e>] ?
> __audit_syscall_exit+0x25e/0x290
> May 22 10:16:07 virthost1 kernel: [<ffffffff8100b072>]
> system_call_fastpath+0x16/0x1b
>
>
> On Thu, May 22, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com>
> wrote:
>
> > The console proxy became unavailable again yesterday afternoon. I could
> > SSH into it via its link local address and nothing seemed to be wrong
> > inside the VM itself. However, the qemu-kvm process for that VM was at
> > almost 100% CPU. Inside the VM, the CPU usage was minimal and the java
> > process was running and listening on port 443. So there seems to be
> > something wrong with it down at the KVM/QEMU level. It's weird how this
> > keeps happening to the console proxy only and not any of the other VMs.
> I
> > tried to reboot it from the management UI and after about 15 minutes, it
> > finally did. Now the console proxy is working but I don't know how long
> it
> > will last before it breaks again. I found this in libvirtd.log, which
> > corresponds with the time the console proxy rebooted:
> >
> > 2014-05-22 17:17:04.362+0000: 25195: info : libvirt version: 0.10.2,
> > package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
> > 2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
> > 2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 : internal
> > error End of file from monitor
> >
> >
> > On Wed, May 21, 2014 at 2:07 PM, Ian Young <iy...@ratespecial.com>
> wrote:
> >
> >> I built and installed a libvirt 1.04 package from the Fedora src rpm.
> It
> >> installed fine inside a test VM but installing it on the real hypervisor
> >> was a bad idea and I doubt I'll be pursuing it further. All VMs
> promptly
> >> stopped and this appeared in libvirtd.log:
> >>
> >> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version: 1.0.4,
> >> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
> >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so
> not
> >> accessible
> >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so
> not
> >> accessible
> >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so
> not
> >> accessible
> >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so not
> >> accessible
> >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so
> not
> >> accessible
> >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so
> not
> >> accessible
> >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so not
> >> accessible
> >> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> >> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so not
> >> accessible
> >> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no
> connection
> >> driver available for qemu:///system
> >> 2014-05-21 20:36:49.472+0000: 23567: error : virNetSocketReadWire:1370 :
> >> End of file while reading data: Input/output error
> >> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no
> connection
> >> driver available for lxc:///
> >> 2014-05-21 20:36:49.474+0000: 23567: error : virNetSocketReadWire:1370 :
> >> End of file while reading data: Input/output error
> >> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no
> connection
> >> driver available for qemu:///system
> >> 2014-05-21 20:36:49.476+0000: 23567: error : virNetSocketReadWire:1370 :
> >> End of file while reading data: Input/output error
> >> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no
> connection
> >> driver available for qemu:///system
> >> 2014-05-21 20:36:49.678+0000: 23567: error : virNetSocketReadWire:1370 :
> >> End of file while reading data: Input/output error
> >> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no
> connection
> >> driver available for qemu:///system
> >> 2014-05-21 20:36:49.682+0000: 23567: error : virNetSocketReadWire:1370 :
> >> End of file while reading data: Input/output error
> >>
> >>
> >> On Wed, May 21, 2014 at 10:45 AM, Ian Young <iyoung@ratespecial.com
> >wrote:
> >>
> >>> I was able to get it working by following these steps:
> >>>
> >>> 1. stop all instances
> >>> 2. service cloudstack-management stop
> >>> 3. service cloudstack-agent stop
> >>> 4. virsh shutdown {domain} (for each of the system VMs)
> >>> 5. service libvirtd stop
> >>> 6. umount primary and secondary
> >>> 7. reboot
> >>>
> >>> The console proxy is working again. I expect it will probably break
> >>> again in a day or two. I have a feeling it's a result of this libvirtd
> >>> bug, since I've seen the "cannot acquire state change lock" several
> times.
> >>>
> >>> https://bugs.launchpad.net/nova/+bug/1254872
> >>>
> >>> I might try building my own libvirtd 1.0.3 for EL6.
> >>>
> >>>
> >>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <iyoung@ratespecial.com
> >wrote:
> >>>
> >>>> So I got the console proxy working via HTTPS (by managing my own "
> >>>> realhostip.com" DNS) last week and everything was working fine.
> >>>> Today, all of a sudden, the console proxy stopped working again. The
> >>>> browser says, "Connecting to 192-168-100-159.realhostip.com..." and
> >>>> eventually times out. I tried to restart it and it went into a
> "Stopping"
> >>>> state that never completed and the Agent State was "Disconnected." I
> could
> >>>> not shut down the VM using virsh or with "kill -9" because libvirtd
> kept
> >>>> saying, "cannot acquire state change lock," so I gracefully shut down
> the
> >>>> remaining instances and rebooted the entire management
> server/hypervisor.
> >>>> Start over.
> >>>>
> >>>> When it came back up, the SSVM and console proxy started but the
> >>>> virtual router was stopped. I was able to manually start it from the
> UI.
> >>>> The console proxy still times out when I try to access it from a
> browser.
> >>>> I don't see any errors in the management or agent logs, just this:
> >>>>
> >>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request]
> (catalina-exec-10:null)
> >>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
> >>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
> >>>>
> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
> >>>> }
> >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
> >>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: { Ans: ,
> >>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
> >>>>
> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
> >>>> }
> >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
> (catalina-exec-10:null)
> >>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734, via: 1,
> Ver:
> >>>> v1, Flags: 10, { GetVncPortAnswer } }
> >>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
> >>>> (catalina-exec-10:null) Port info 192.168.100.6
> >>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
> >>>> (catalina-exec-10:null) Parse host info returned from executing
> >>>> GetVNCPortCommand. host info: 192.168.100.6
> >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
> >>>> (catalina-exec-10:null) Compose console url:
> >>>>
> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
> >>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
> >>>> (catalina-exec-10:null) the console url is ::
> >>>> <html><title>r-4-VM</title><frameset><frame src="
> >>>>
> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
> >>>> "></frame></frameset></html>
> >>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
> >>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: {
> Cmd ,
> >>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> >>>>
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> >>>> \"connections\": []\n}","wait":0}}] }
> >>>>
> >>>> If I try to restart the system VMs with cloudstack-sysvmadm, it says:
> >>>>
> >>>> Stopping and starting 1 secondary storage vm(s)...
> >>>> curl: (7) couldn't connect to host
> >>>> ERROR: Failed to stop secondary storage vm with id 1
> >>>>
> >>>> Done stopping and starting secondary storage vm(s)
> >>>>
> >>>> Stopping and starting 1 console proxy vm(s)...
> >>>> curl: (7) couldn't connect to host
> >>>> ERROR: Failed to stop console proxy vm with id 2
> >>>>
> >>>> Done stopping and starting console proxy vm(s) .
> >>>>
> >>>> Stopping and starting 1 running routing vm(s)...
> >>>> curl: (7) couldn't connect to host
> >>>> 2
> >>>> Done restarting router(s).
> >>>>
> >>>> I notice there are now four entries for the same management server in
> >>>> the mshost table, and they all are in an "Up" state and the "removed"
> field
> >>>> is NULL. What's wrong with this system?
> >>>>
> >>>
> >>>
> >>
> >
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
And this is in /var/log/messages right before that event:
May 22 10:16:07 virthost1 kernel: INFO: task qemu-kvm:2971 blocked for more
than 120 seconds.
May 22 10:16:07 virthost1 kernel: Not tainted
2.6.32-431.11.2.el6.x86_64 #1
May 22 10:16:07 virthost1 kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 22 10:16:07 virthost1 kernel: qemu-kvm D 0000000000000002 0
2971 1 0x00000080
May 22 10:16:07 virthost1 kernel: ffff8810724e9be8 0000000000000082
0000000000000000 ffff88106b6529d8
May 22 10:16:07 virthost1 kernel: ffff880871b3e8d8 ffff880871b3e8f0
ffffffff8100bb8e ffff8810724e9be8
May 22 10:16:07 virthost1 kernel: ffff881073525058 ffff8810724e9fd8
000000000000fbc8 ffff881073525058
May 22 10:16:07 virthost1 kernel: Call Trace:
May 22 10:16:07 virthost1 kernel: [<ffffffff8100bb8e>] ?
apic_timer_interrupt+0xe/0x20
May 22 10:16:07 virthost1 kernel: [<ffffffff810555ef>] ?
mutex_spin_on_owner+0x9f/0xc0
May 22 10:16:07 virthost1 kernel: [<ffffffff8152969e>]
__mutex_lock_slowpath+0x13e/0x180
May 22 10:16:07 virthost1 kernel: [<ffffffff8152953b>] mutex_lock+0x2b/0x50
May 22 10:16:07 virthost1 kernel: [<ffffffffa021c2cf>]
memory_access_ok+0x7f/0xc0 [vhost_net]
May 22 10:16:07 virthost1 kernel: [<ffffffffa021d89c>]
vhost_dev_ioctl+0x2ec/0xa50 [vhost_net]
May 22 10:16:07 virthost1 kernel: [<ffffffffa021c411>] ?
vhost_work_flush+0xe1/0x120 [vhost_net]
May 22 10:16:07 virthost1 kernel: [<ffffffff8122db91>] ?
avc_has_perm+0x71/0x90
May 22 10:16:07 virthost1 kernel: [<ffffffffa021f11a>]
vhost_net_ioctl+0x7a/0x5d0 [vhost_net]
May 22 10:16:07 virthost1 kernel: [<ffffffff8122f914>] ?
inode_has_perm+0x54/0xa0
May 22 10:16:07 virthost1 kernel: [<ffffffffa01a28b7>] ?
kvm_vcpu_ioctl+0x1e7/0x580 [kvm]
May 22 10:16:07 virthost1 kernel: [<ffffffff8108b14e>] ?
send_signal+0x3e/0x90
May 22 10:16:07 virthost1 kernel: [<ffffffff8119dc12>] vfs_ioctl+0x22/0xa0
May 22 10:16:07 virthost1 kernel: [<ffffffff8119ddb4>]
do_vfs_ioctl+0x84/0x580
May 22 10:16:07 virthost1 kernel: [<ffffffff8119e331>] sys_ioctl+0x81/0xa0
May 22 10:16:07 virthost1 kernel: [<ffffffff810e1e4e>] ?
__audit_syscall_exit+0x25e/0x290
May 22 10:16:07 virthost1 kernel: [<ffffffff8100b072>]
system_call_fastpath+0x16/0x1b
On Thu, May 22, 2014 at 10:39 AM, Ian Young <iy...@ratespecial.com> wrote:
> The console proxy became unavailable again yesterday afternoon. I could
> SSH into it via its link local address and nothing seemed to be wrong
> inside the VM itself. However, the qemu-kvm process for that VM was at
> almost 100% CPU. Inside the VM, the CPU usage was minimal and the java
> process was running and listening on port 443. So there seems to be
> something wrong with it down at the KVM/QEMU level. It's weird how this
> keeps happening to the console proxy only and not any of the other VMs. I
> tried to reboot it from the management UI and after about 15 minutes, it
> finally did. Now the console proxy is working but I don't know how long it
> will last before it breaks again. I found this in libvirtd.log, which
> corresponds with the time the console proxy rebooted:
>
> 2014-05-22 17:17:04.362+0000: 25195: info : libvirt version: 0.10.2,
> package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
> 2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
> 2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 : internal
> error End of file from monitor
>
>
> On Wed, May 21, 2014 at 2:07 PM, Ian Young <iy...@ratespecial.com> wrote:
>
>> I built and installed a libvirt 1.04 package from the Fedora src rpm. It
>> installed fine inside a test VM but installing it on the real hypervisor
>> was a bad idea and I doubt I'll be pursuing it further. All VMs promptly
>> stopped and this appeared in libvirtd.log:
>>
>> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version: 1.0.4,
>> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
>> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
>> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so not
>> accessible
>> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
>> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so not
>> accessible
>> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
>> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so not
>> accessible
>> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
>> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so not
>> accessible
>> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
>> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so not
>> accessible
>> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
>> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so not
>> accessible
>> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
>> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so not
>> accessible
>> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
>> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so not
>> accessible
>> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no connection
>> driver available for qemu:///system
>> 2014-05-21 20:36:49.472+0000: 23567: error : virNetSocketReadWire:1370 :
>> End of file while reading data: Input/output error
>> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no connection
>> driver available for lxc:///
>> 2014-05-21 20:36:49.474+0000: 23567: error : virNetSocketReadWire:1370 :
>> End of file while reading data: Input/output error
>> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no connection
>> driver available for qemu:///system
>> 2014-05-21 20:36:49.476+0000: 23567: error : virNetSocketReadWire:1370 :
>> End of file while reading data: Input/output error
>> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no connection
>> driver available for qemu:///system
>> 2014-05-21 20:36:49.678+0000: 23567: error : virNetSocketReadWire:1370 :
>> End of file while reading data: Input/output error
>> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no connection
>> driver available for qemu:///system
>> 2014-05-21 20:36:49.682+0000: 23567: error : virNetSocketReadWire:1370 :
>> End of file while reading data: Input/output error
>>
>>
>> On Wed, May 21, 2014 at 10:45 AM, Ian Young <iy...@ratespecial.com>wrote:
>>
>>> I was able to get it working by following these steps:
>>>
>>> 1. stop all instances
>>> 2. service cloudstack-management stop
>>> 3. service cloudstack-agent stop
>>> 4. virsh shutdown {domain} (for each of the system VMs)
>>> 5. service libvirtd stop
>>> 6. umount primary and secondary
>>> 7. reboot
>>>
>>> The console proxy is working again. I expect it will probably break
>>> again in a day or two. I have a feeling it's a result of this libvirtd
>>> bug, since I've seen the "cannot acquire state change lock" several times.
>>>
>>> https://bugs.launchpad.net/nova/+bug/1254872
>>>
>>> I might try building my own libvirtd 1.0.3 for EL6.
>>>
>>>
>>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <iy...@ratespecial.com>wrote:
>>>
>>>> So I got the console proxy working via HTTPS (by managing my own "
>>>> realhostip.com" DNS) last week and everything was working fine.
>>>> Today, all of a sudden, the console proxy stopped working again. The
>>>> browser says, "Connecting to 192-168-100-159.realhostip.com..." and
>>>> eventually times out. I tried to restart it and it went into a "Stopping"
>>>> state that never completed and the Agent State was "Disconnected." I could
>>>> not shut down the VM using virsh or with "kill -9" because libvirtd kept
>>>> saying, "cannot acquire state change lock," so I gracefully shut down the
>>>> remaining instances and rebooted the entire management server/hypervisor.
>>>> Start over.
>>>>
>>>> When it came back up, the SSVM and console proxy started but the
>>>> virtual router was stopped. I was able to manually start it from the UI.
>>>> The console proxy still times out when I try to access it from a browser.
>>>> I don't see any errors in the management or agent logs, just this:
>>>>
>>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request] (catalina-exec-10:null)
>>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
>>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
>>>> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
>>>> }
>>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: { Ans: ,
>>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
>>>> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
>>>> }
>>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request] (catalina-exec-10:null)
>>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734, via: 1, Ver:
>>>> v1, Flags: 10, { GetVncPortAnswer } }
>>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
>>>> (catalina-exec-10:null) Port info 192.168.100.6
>>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
>>>> (catalina-exec-10:null) Parse host info returned from executing
>>>> GetVNCPortCommand. host info: 192.168.100.6
>>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>>> (catalina-exec-10:null) Compose console url:
>>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>>> (catalina-exec-10:null) the console url is ::
>>>> <html><title>r-4-VM</title><frameset><frame src="
>>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>>> "></frame></frameset></html>
>>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
>>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: { Cmd ,
>>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>>>> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
>>>> \"connections\": []\n}","wait":0}}] }
>>>>
>>>> If I try to restart the system VMs with cloudstack-sysvmadm, it says:
>>>>
>>>> Stopping and starting 1 secondary storage vm(s)...
>>>> curl: (7) couldn't connect to host
>>>> ERROR: Failed to stop secondary storage vm with id 1
>>>>
>>>> Done stopping and starting secondary storage vm(s)
>>>>
>>>> Stopping and starting 1 console proxy vm(s)...
>>>> curl: (7) couldn't connect to host
>>>> ERROR: Failed to stop console proxy vm with id 2
>>>>
>>>> Done stopping and starting console proxy vm(s) .
>>>>
>>>> Stopping and starting 1 running routing vm(s)...
>>>> curl: (7) couldn't connect to host
>>>> 2
>>>> Done restarting router(s).
>>>>
>>>> I notice there are now four entries for the same management server in
>>>> the mshost table, and they all are in an "Up" state and the "removed" field
>>>> is NULL. What's wrong with this system?
>>>>
>>>
>>>
>>
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
The console proxy became unavailable again yesterday afternoon. I could
SSH into it via its link local address and nothing seemed to be wrong
inside the VM itself. However, the qemu-kvm process for that VM was at
almost 100% CPU. Inside the VM, the CPU usage was minimal and the java
process was running and listening on port 443. So there seems to be
something wrong with it down at the KVM/QEMU level. It's weird how this
keeps happening to the console proxy only and not any of the other VMs. I
tried to reboot it from the management UI and after about 15 minutes, it
finally did. Now the console proxy is working but I don't know how long it
will last before it breaks again. I found this in libvirtd.log, which
corresponds with the time the console proxy rebooted:
2014-05-22 17:17:04.362+0000: 25195: info : libvirt version: 0.10.2,
package: 29.el6_5.7 (CentOS BuildSystem <http://bugs.centos.org>,
2014-04-07-07:42:04, c6b9.bsys.dev.centos.org)
2014-05-22 17:17:04.362+0000: 25195: error : qemuMonitorIO:614 : internal
error End of file from monitor
On Wed, May 21, 2014 at 2:07 PM, Ian Young <iy...@ratespecial.com> wrote:
> I built and installed a libvirt 1.04 package from the Fedora src rpm. It
> installed fine inside a test VM but installing it on the real hypervisor
> was a bad idea and I doubt I'll be pursuing it further. All VMs promptly
> stopped and this appeared in libvirtd.log:
>
> 2014-05-21 20:36:19.260+0000: 23567: info : libvirt version: 1.0.4,
> package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so not
> accessible
> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so not
> accessible
> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so not
> accessible
> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so not
> accessible
> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so not
> accessible
> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so not
> accessible
> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so not
> accessible
> 2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
> Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so not
> accessible
> 2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no connection
> driver available for qemu:///system
> 2014-05-21 20:36:49.472+0000: 23567: error : virNetSocketReadWire:1370 :
> End of file while reading data: Input/output error
> 2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no connection
> driver available for lxc:///
> 2014-05-21 20:36:49.474+0000: 23567: error : virNetSocketReadWire:1370 :
> End of file while reading data: Input/output error
> 2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no connection
> driver available for qemu:///system
> 2014-05-21 20:36:49.476+0000: 23567: error : virNetSocketReadWire:1370 :
> End of file while reading data: Input/output error
> 2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no connection
> driver available for qemu:///system
> 2014-05-21 20:36:49.678+0000: 23567: error : virNetSocketReadWire:1370 :
> End of file while reading data: Input/output error
> 2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no connection
> driver available for qemu:///system
> 2014-05-21 20:36:49.682+0000: 23567: error : virNetSocketReadWire:1370 :
> End of file while reading data: Input/output error
>
>
> On Wed, May 21, 2014 at 10:45 AM, Ian Young <iy...@ratespecial.com>wrote:
>
>> I was able to get it working by following these steps:
>>
>> 1. stop all instances
>> 2. service cloudstack-management stop
>> 3. service cloudstack-agent stop
>> 4. virsh shutdown {domain} (for each of the system VMs)
>> 5. service libvirtd stop
>> 6. umount primary and secondary
>> 7. reboot
>>
>> The console proxy is working again. I expect it will probably break
>> again in a day or two. I have a feeling it's a result of this libvirtd
>> bug, since I've seen the "cannot acquire state change lock" several times.
>>
>> https://bugs.launchpad.net/nova/+bug/1254872
>>
>> I might try building my own libvirtd 1.0.3 for EL6.
>>
>>
>> On Tue, May 20, 2014 at 6:21 PM, Ian Young <iy...@ratespecial.com>wrote:
>>
>>> So I got the console proxy working via HTTPS (by managing my own "
>>> realhostip.com" DNS) last week and everything was working fine. Today,
>>> all of a sudden, the console proxy stopped working again. The browser
>>> says, "Connecting to 192-168-100-159.realhostip.com..." and eventually
>>> times out. I tried to restart it and it went into a "Stopping" state that
>>> never completed and the Agent State was "Disconnected." I could not shut
>>> down the VM using virsh or with "kill -9" because libvirtd kept saying,
>>> "cannot acquire state change lock," so I gracefully shut down the remaining
>>> instances and rebooted the entire management server/hypervisor. Start over.
>>>
>>> When it came back up, the SSVM and console proxy started but the virtual
>>> router was stopped. I was able to manually start it from the UI. The
>>> console proxy still times out when I try to access it from a browser. I
>>> don't see any errors in the management or agent logs, just this:
>>>
>>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request] (catalina-exec-10:null)
>>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
>>> virthost1.redacted.com), Ver: v1, Flags: 100011,
>>> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
>>> }
>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: { Ans: ,
>>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
>>> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
>>> }
>>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request] (catalina-exec-10:null)
>>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734, via: 1, Ver:
>>> v1, Flags: 10, { GetVncPortAnswer } }
>>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
>>> (catalina-exec-10:null) Port info 192.168.100.6
>>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
>>> (catalina-exec-10:null) Parse host info returned from executing
>>> GetVNCPortCommand. host info: 192.168.100.6
>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>> (catalina-exec-10:null) Compose console url:
>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>>> (catalina-exec-10:null) the console url is ::
>>> <html><title>r-4-VM</title><frameset><frame src="
>>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>>> "></frame></frameset></html>
>>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
>>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: { Cmd ,
>>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>>> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
>>> \"connections\": []\n}","wait":0}}] }
>>>
>>> If I try to restart the system VMs with cloudstack-sysvmadm, it says:
>>>
>>> Stopping and starting 1 secondary storage vm(s)...
>>> curl: (7) couldn't connect to host
>>> ERROR: Failed to stop secondary storage vm with id 1
>>>
>>> Done stopping and starting secondary storage vm(s)
>>>
>>> Stopping and starting 1 console proxy vm(s)...
>>> curl: (7) couldn't connect to host
>>> ERROR: Failed to stop console proxy vm with id 2
>>>
>>> Done stopping and starting console proxy vm(s) .
>>>
>>> Stopping and starting 1 running routing vm(s)...
>>> curl: (7) couldn't connect to host
>>> 2
>>> Done restarting router(s).
>>>
>>> I notice there are now four entries for the same management server in
>>> the mshost table, and they all are in an "Up" state and the "removed" field
>>> is NULL. What's wrong with this system?
>>>
>>
>>
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
I built and installed a libvirt 1.04 package from the Fedora src rpm. It
installed fine inside a test VM but installing it on the real hypervisor
was a bad idea and I doubt I'll be pursuing it further. All VMs promptly
stopped and this appeared in libvirtd.log:
2014-05-21 20:36:19.260+0000: 23567: info : libvirt version: 1.0.4,
package: 1.el6 (Unknown, 2014-05-21-11:36:09, redacted.com)
2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
Module /usr/lib64/libvirt/connection-driver/libvirt_driver_network.so not
accessible
2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
Module /usr/lib64/libvirt/connection-driver/libvirt_driver_storage.so not
accessible
2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nodedev.so not
accessible
2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
Module /usr/lib64/libvirt/connection-driver/libvirt_driver_secret.so not
accessible
2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so not
accessible
2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
Module /usr/lib64/libvirt/connection-driver/libvirt_driver_interface.so not
accessible
2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
Module /usr/lib64/libvirt/connection-driver/libvirt_driver_qemu.so not
accessible
2014-05-21 20:36:19.260+0000: 23567: warning : virDriverLoadModule:72 :
Module /usr/lib64/libvirt/connection-driver/libvirt_driver_lxc.so not
accessible
2014-05-21 20:36:49.471+0000: 23570: error : do_open:1220 : no connection
driver available for qemu:///system
2014-05-21 20:36:49.472+0000: 23567: error : virNetSocketReadWire:1370 :
End of file while reading data: Input/output error
2014-05-21 20:36:49.473+0000: 23571: error : do_open:1220 : no connection
driver available for lxc:///
2014-05-21 20:36:49.474+0000: 23567: error : virNetSocketReadWire:1370 :
End of file while reading data: Input/output error
2014-05-21 20:36:49.475+0000: 23568: error : do_open:1220 : no connection
driver available for qemu:///system
2014-05-21 20:36:49.476+0000: 23567: error : virNetSocketReadWire:1370 :
End of file while reading data: Input/output error
2014-05-21 20:36:49.678+0000: 23575: error : do_open:1220 : no connection
driver available for qemu:///system
2014-05-21 20:36:49.678+0000: 23567: error : virNetSocketReadWire:1370 :
End of file while reading data: Input/output error
2014-05-21 20:36:49.681+0000: 23572: error : do_open:1220 : no connection
driver available for qemu:///system
2014-05-21 20:36:49.682+0000: 23567: error : virNetSocketReadWire:1370 :
End of file while reading data: Input/output error
On Wed, May 21, 2014 at 10:45 AM, Ian Young <iy...@ratespecial.com> wrote:
> I was able to get it working by following these steps:
>
> 1. stop all instances
> 2. service cloudstack-management stop
> 3. service cloudstack-agent stop
> 4. virsh shutdown {domain} (for each of the system VMs)
> 5. service libvirtd stop
> 6. umount primary and secondary
> 7. reboot
>
> The console proxy is working again. I expect it will probably break again
> in a day or two. I have a feeling it's a result of this libvirtd bug,
> since I've seen the "cannot acquire state change lock" several times.
>
> https://bugs.launchpad.net/nova/+bug/1254872
>
> I might try building my own libvirtd 1.0.3 for EL6.
>
>
> On Tue, May 20, 2014 at 6:21 PM, Ian Young <iy...@ratespecial.com> wrote:
>
>> So I got the console proxy working via HTTPS (by managing my own "
>> realhostip.com" DNS) last week and everything was working fine. Today,
>> all of a sudden, the console proxy stopped working again. The browser
>> says, "Connecting to 192-168-100-159.realhostip.com..." and eventually
>> times out. I tried to restart it and it went into a "Stopping" state that
>> never completed and the Agent State was "Disconnected." I could not shut
>> down the VM using virsh or with "kill -9" because libvirtd kept saying,
>> "cannot acquire state change lock," so I gracefully shut down the remaining
>> instances and rebooted the entire management server/hypervisor. Start over.
>>
>> When it came back up, the SSVM and console proxy started but the virtual
>> router was stopped. I was able to manually start it from the UI. The
>> console proxy still times out when I try to access it from a browser. I
>> don't see any errors in the management or agent logs, just this:
>>
>> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request] (catalina-exec-10:null)
>> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
>> virthost1.redacted.com), Ver: v1, Flags: 100011,
>> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
>> }
>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
>> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: { Ans: ,
>> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
>> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
>> }
>> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request] (catalina-exec-10:null)
>> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734, via: 1, Ver:
>> v1, Flags: 10, { GetVncPortAnswer } }
>> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
>> (catalina-exec-10:null) Port info 192.168.100.6
>> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
>> (catalina-exec-10:null) Parse host info returned from executing
>> GetVNCPortCommand. host info: 192.168.100.6
>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>> (catalina-exec-10:null) Compose console url:
>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
>> (catalina-exec-10:null) the console url is ::
>> <html><title>r-4-VM</title><frameset><frame src="
>> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
>> "></frame></frameset></html>
>> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
>> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: { Cmd ,
>> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
>> \"connections\": []\n}","wait":0}}] }
>>
>> If I try to restart the system VMs with cloudstack-sysvmadm, it says:
>>
>> Stopping and starting 1 secondary storage vm(s)...
>> curl: (7) couldn't connect to host
>> ERROR: Failed to stop secondary storage vm with id 1
>>
>> Done stopping and starting secondary storage vm(s)
>>
>> Stopping and starting 1 console proxy vm(s)...
>> curl: (7) couldn't connect to host
>> ERROR: Failed to stop console proxy vm with id 2
>>
>> Done stopping and starting console proxy vm(s) .
>>
>> Stopping and starting 1 running routing vm(s)...
>> curl: (7) couldn't connect to host
>> 2
>> Done restarting router(s).
>>
>> I notice there are now four entries for the same management server in the
>> mshost table, and they all are in an "Up" state and the "removed" field is
>> NULL. What's wrong with this system?
>>
>
>
Re: console proxy times out
Posted by Ian Young <iy...@ratespecial.com>.
I was able to get it working by following these steps:
1. stop all instances
2. service cloudstack-management stop
3. service cloudstack-agent stop
4. virsh shutdown {domain} (for each of the system VMs)
5. service libvirtd stop
6. umount primary and secondary
7. reboot
The console proxy is working again. I expect it will probably break again
in a day or two. I have a feeling it's a result of this libvirtd bug,
since I've seen the "cannot acquire state change lock" several times.
https://bugs.launchpad.net/nova/+bug/1254872
I might try building my own libvirtd 1.0.3 for EL6.
On Tue, May 20, 2014 at 6:21 PM, Ian Young <iy...@ratespecial.com> wrote:
> So I got the console proxy working via HTTPS (by managing my own "
> realhostip.com" DNS) last week and everything was working fine. Today,
> all of a sudden, the console proxy stopped working again. The browser
> says, "Connecting to 192-168-100-159.realhostip.com..." and eventually
> times out. I tried to restart it and it went into a "Stopping" state that
> never completed and the Agent State was "Disconnected." I could not shut
> down the VM using virsh or with "kill -9" because libvirtd kept saying,
> "cannot acquire state change lock," so I gracefully shut down the remaining
> instances and rebooted the entire management server/hypervisor. Start over.
>
> When it came back up, the SSVM and console proxy started but the virtual
> router was stopped. I was able to manually start it from the UI. The
> console proxy still times out when I try to access it from a browser. I
> don't see any errors in the management or agent logs, just this:
>
> 2014-05-20 18:04:27,632 DEBUG [c.c.a.t.Request] (catalina-exec-10:null)
> Seq 1-2130378876: Sending { Cmd , MgmtId: 55157049428734, via: 1(
> virthost1.redacted.com), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.GetVncPortCommand":{"id":4,"name":"r-4-VM","wait":0}}]
> }
> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-3:null) Seq 1-2130378876: Processing: { Ans: ,
> MgmtId: 55157049428734, via: 1, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.GetVncPortAnswer":{"address":"192.168.100.6","port":5902,"result":true,"wait":0}}]
> }
> 2014-05-20 18:04:27,684 DEBUG [c.c.a.t.Request] (catalina-exec-10:null)
> Seq 1-2130378876: Received: { Ans: , MgmtId: 55157049428734, via: 1, Ver:
> v1, Flags: 10, { GetVncPortAnswer } }
> 2014-05-20 18:04:27,684 DEBUG [c.c.s.ConsoleProxyServlet]
> (catalina-exec-10:null) Port info 192.168.100.6
> 2014-05-20 18:04:27,684 INFO [c.c.s.ConsoleProxyServlet]
> (catalina-exec-10:null) Parse host info returned from executing
> GetVNCPortCommand. host info: 192.168.100.6
> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
> (catalina-exec-10:null) Compose console url:
> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
> 2014-05-20 18:04:27,686 DEBUG [c.c.s.ConsoleProxyServlet]
> (catalina-exec-10:null) the console url is ::
> <html><title>r-4-VM</title><frameset><frame src="
> https://192-168-100-159.realhostip.com/ajax?token=CsPhU4m_R2ZoLIdXOtjo3y3humnQN20wt5fSPjbZOHtRh7nli7tiq0ZiWUuwCVIn7VwF6503ziEqCRejlRsVcsyQcUfemTRXlhAOpJUyRugyCuTjmbUIX3EY1cHnFMKwF8FXXZr_PgwyXGPEoOHhkdRgsyRiczbk_Unuh4KmRngATr0FPCLtqhwIMpnbLSYwpnFDz65k9lEJmK6IlXYKVpWXg2rpVEsQvaNlulrZdhMQ7qUbacn82EG43OY8nmwm1SYB8TrUFH5Btb1RHpJm9A
> "></frame></frameset></html>
> 2014-05-20 18:04:29,216 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-4:null) SeqA 2-545: Processing Seq 2-545: { Cmd ,
> MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
>
> If I try to restart the system VMs with cloudstack-sysvmadm, it says:
>
> Stopping and starting 1 secondary storage vm(s)...
> curl: (7) couldn't connect to host
> ERROR: Failed to stop secondary storage vm with id 1
>
> Done stopping and starting secondary storage vm(s)
>
> Stopping and starting 1 console proxy vm(s)...
> curl: (7) couldn't connect to host
> ERROR: Failed to stop console proxy vm with id 2
>
> Done stopping and starting console proxy vm(s) .
>
> Stopping and starting 1 running routing vm(s)...
> curl: (7) couldn't connect to host
> 2
> Done restarting router(s).
>
> I notice there are now four entries for the same management server in the
> mshost table, and they all are in an "Up" state and the "removed" field is
> NULL. What's wrong with this system?
>