Yes, we recompiled ACS too.... Also we delete all snapshots... but we can do it for a while...
New snapshot created each days.. And the main issue - agent crash, not exception itself... Each RBD operations which cause exception in 20-30 minutes cause agent crash... 2015-11-03 11:09 GMT+02:00 Wido den Hollander <w...@42on.com>: > > > On 03-11-15 10:04, Voloshanenko Igor wrote: > > Wido, also minor issue with 0,2.0 java-rados > > > > Did you also re-compile CloudStack against the new rados-java? I still > think it's related to when the Agent starts cleaning up and there are > snapshots which need to be unprotected. > > In the meantime you might want to remove any existing RBD snapshots > using the RBD commands from Ceph, that might solve the problem. > > Wido > > > We still catch: > > > > -storage/ae1b6e5f-f5f4-4abe-aee3-084f2fe71876 > > 2015-11-02 11:41:14,958 WARN [cloud.agent.Agent] > > (agentRequest-Handler-4:null) Caught: > > java.lang.NegativeArraySizeException > > at com.ceph.rbd.RbdImage.snapList(Unknown Source) > > at > > > com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.deletePhysicalDisk(LibvirtStorageAdaptor.java:854) > > at > > > com.cloud.hypervisor.kvm.storage.LibvirtStoragePool.deletePhysicalDisk(LibvirtStoragePool.java:175) > > at > > > com.cloud.hypervisor.kvm.storage.KVMStorageProcessor.deleteVolume(KVMStorageProcessor.java:1206) > > at > > > com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:124) > > at > > > com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:57) > > at > > > com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1385) > > at com.cloud.agent.Agent.processRequest(Agent.java:503) > > at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:808) > > at com.cloud.utils.nio.Task.run(Task.java:84) > > at > > > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > > at > > > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > > at java.lang.Thread.run(Thread.java:745) > > > > Even with updated lib: > > > > root@ix1-c7-2:/usr/share/cloudstack-agent/lib# ls > > /usr/share/cloudstack-agent/lib | grep rados > > rados-0.2.0.jar > > > > 2015-11-03 11:01 GMT+02:00 Voloshanenko Igor > > <igor.voloshane...@gmail.com <mailto:igor.voloshane...@gmail.com>>: > > > > Wido, it's the main issue. No records at all... > > > > > > So, from last time: > > > > > > 2015-11-02 11:40:33,204 DEBUG > > [kvm.resource.LibvirtComputingResource] > > (agentRequest-Handler-2:null) Executing: /bin/bash -c free|grep > > Mem:|awk '{print $2}' > > 2015-11-02 11:40:33,207 DEBUG > > [kvm.resource.LibvirtComputingResource] > > (agentRequest-Handler-2:null) Execution is successful. > > 2015-11-02 11:40:35,316 DEBUG [cloud.agent.Agent] > > (agentRequest-Handler-4:null) Processing command: > > com.cloud.agent.api.GetVmStatsCommand > > 2015-11-02 11:40:35,867 INFO [cloud.agent.AgentShell] (main:null) > > Agent started > > 2015-11-02 11:40:35,868 INFO [cloud.agent.AgentShell] (main:null) > > Implementation Version is 4.5.1 > > > > So, almost alsways it's exception after RbdUnprotect then in approx > > . 20 minutes - crash.. > > Almost all the time - it's happen after GetVmStatsCommand or Disks > > stats... Possible that evil hiden into UpadteDiskInfo method... but > > i can;t find any bad code there ((( > > > > 2015-11-03 10:40 GMT+02:00 Wido den Hollander <w...@42on.com > > <mailto:w...@42on.com>>: > > > > > > > > On 03-11-15 01:54, Voloshanenko Igor wrote: > > > Thank you, Jason! > > > > > > Any advice, for troubleshooting.... > > > > > > I'm looking in code, and right now don;t see any bad things :( > > > > > > > Can you run the CloudStack Agent in DEBUG mode and then see > > after which > > lines in the logs it crashes? > > > > Wido > > > > > 2015-11-03 1:32 GMT+02:00 Jason Dillaman <dilla...@redhat.com > <mailto:dilla...@redhat.com> > > > <mailto:dilla...@redhat.com <mailto:dilla...@redhat.com>>>: > > > > > > Most likely not going to be related to 13045 since you > aren't > > > actively exporting an image diff. The most likely problem > is that > > > the RADOS IO context is being closed prior to closing the > RBD image. > > > > > > -- > > > > > > Jason Dillaman > > > > > > > > > ----- Original Message ----- > > > > > > > From: "Voloshanenko Igor" <igor.voloshane...@gmail.com > <mailto:igor.voloshane...@gmail.com> > > > <mailto:igor.voloshane...@gmail.com > > <mailto:igor.voloshane...@gmail.com>>> > > > > To: "Ceph Users" <ceph-users@lists.ceph.com > > <mailto:ceph-users@lists.ceph.com> > > > <mailto:ceph-users@lists.ceph.com > > <mailto:ceph-users@lists.ceph.com>>> > > > > Sent: Thursday, October 29, 2015 5:27:17 PM > > > > Subject: Re: [ceph-users] Cloudstack agent crashed JVM > with > > > exception in > > > > librbd > > > > > > > From all we analyzed - look like - it's this issue > > > > http://tracker.ceph.com/issues/13045 > > > > > > > PR: https://github.com/ceph/ceph/pull/6097 > > > > > > > Can anyone help us to confirm this? :) > > > > > > > 2015-10-29 23:13 GMT+02:00 Voloshanenko Igor < > > > igor.voloshane...@gmail.com > > <mailto:igor.voloshane...@gmail.com> > > <mailto:igor.voloshane...@gmail.com > > <mailto:igor.voloshane...@gmail.com>> > > > > > : > > > > > > > > Additional trace: > > > > > > > > > > > > #0 0x00007f30f9891cc9 in __GI_raise (sig=sig@entry=6) > at > > > > > ../nptl/sysdeps/unix/sysv/linux/raise.c:56 > > > > > > > > > #1 0x00007f30f98950d8 in __GI_abort () at abort.c:89 > > > > > > > > > #2 0x00007f30f87b36b5 in > > > __gnu_cxx::__verbose_terminate_handler() () from > > > > > /usr/lib/x86_64-linux-gnu/libstdc++.so.6 > > > > > > > > > #3 0x00007f30f87b1836 in ?? () from > > > > > /usr/lib/x86_64-linux-gnu/libstdc++.so.6 > > > > > > > > > #4 0x00007f30f87b1863 in std::terminate() () from > > > > > /usr/lib/x86_64-linux-gnu/libstdc++.so.6 > > > > > > > > > #5 0x00007f30f87b1aa2 in __cxa_throw () from > > > > > /usr/lib/x86_64-linux-gnu/libstdc++.so.6 > > > > > > > > > #6 0x00007f2fddb50778 in ceph::__ceph_assert_fail > > > > > (assertion=assertion@entry=0x7f2fdddeca05 "sub < > > m_subsys.size()", > > > > > > > > > file=file@entry=0x7f2fdddec9f0 "./log/SubsystemMap.h", > > > line=line@entry=62, > > > > > > > > > func=func@entry=0x7f2fdddedba0 > > > > > > > > > > > <_ZZN4ceph3log12SubsystemMap13should_gatherEjiE19__PRETTY_FUNCTION__> > > "bool > > > > > ceph::log::SubsystemMap::should_gather(unsigned int, > > int)") at > > > > > common/assert.cc:77 > > > > > > > > > #7 0x00007f2fdda1fed2 in > > ceph::log::SubsystemMap::should_gather > > > > > (level=<optimized out>, sub=<optimized out>, > > this=<optimized out>) > > > > > > > > > at ./log/SubsystemMap.h:62 > > > > > > > > > #8 0x00007f2fdda3b693 in > > ceph::log::SubsystemMap::should_gather > > > > > (this=<optimized out>, sub=<optimized out>, > > level=<optimized out>) > > > > > > > > > at ./log/SubsystemMap.h:61 > > > > > > > > > #9 0x00007f2fddd879be in ObjectCacher::flusher_entry > > > (this=0x7f2ff80b27a0) > > > > > at > > > > > osdc/ObjectCacher.cc:1527 > > > > > > > > > #10 0x00007f2fddd9851d in > > ObjectCacher::FlusherThread::entry > > > > > (this=<optimized > > > > > out>) at osdc/ObjectCacher.h:374 > > > > > > > > > #11 0x00007f30f9c28182 in start_thread > > (arg=0x7f2e1a7fc700) at > > > > > pthread_create.c:312 > > > > > > > > > #12 0x00007f30f995547d in clone () at > > > > > ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 > > > > > > > > > > > > 2015-10-29 17:38 GMT+02:00 Voloshanenko Igor < > > > igor.voloshane...@gmail.com > > <mailto:igor.voloshane...@gmail.com> > > <mailto:igor.voloshane...@gmail.com > > <mailto:igor.voloshane...@gmail.com>> > > > > > > > > > > > : > > > > > > > > > > > > > Hi Wido and all community. > > > > > > > > > > > > > > > > > > We catched very idiotic issue on our Cloudstack > > installation, > > > which > > > > > > related > > > > > > to ceph and possible to java-rados lib. > > > > > > > > > > > > > > > > > > So, we have constantly agent crashed (which cause > > very big > > > problem for > > > > > > us... > > > > > > ). > > > > > > > > > > > > > > > > > > When agent crashed - it's crash JVM. And no event in > > logs at all. > > > > > > > > > > > > > > > We enabled crush dump, and after crash we see next > > picture: > > > > > > > > > > > > > > > > > > #grep -A1 "Problematic frame" < /hs_err_pid30260.log > > > > > > > > > > > > > > > Problematic frame: > > > > > > > > > > > > > > > C [librbd.so.1.0.0+0x5d681] > > > > > > > > > > > > > > > > > > # gdb /usr/lib/librbd.so.1.0.0 > > /var/tmp/cores/jsvc.25526.0.core > > > > > > > > > > > > > > > (gdb) bt > > > > > > > > > > > > > > > ... > > > > > > > > > > > > > > > #7 0x00007f30b9a1fed2 in > > ceph::log::SubsystemMap::should_gather > > > > > > (level=<optimized out>, sub=<optimized out>, > > this=<optimized out>) > > > > > > > > > > > > > > > at ./log/SubsystemMap.h:62 > > > > > > > > > > > > > > > #8 0x00007f30b9a3b693 in > > ceph::log::SubsystemMap::should_gather > > > > > > (this=<optimized out>, sub=<optimized out>, > > level=<optimized out>) > > > > > > > > > > > > > > > at ./log/SubsystemMap.h:61 > > > > > > > > > > > > > > > #9 0x00007f30b9d879be in ObjectCacher::flusher_entry > > > > > > (this=0x7f2fb4017910) > > > > > > at > > > > > > osdc/ObjectCacher.cc:1527 > > > > > > > > > > > > > > > #10 0x00007f30b9d9851d in > > ObjectCacher::FlusherThread::entry > > > > > > (this=<optimized > > > > > > out>) at osdc/ObjectCacher.h:374 > > > > > > > > > > > > > > > > > > From ceph code, this part executed when flushing > cache > > > object... And we > > > > > > don;t > > > > > > understand why. Becasue we have absolutely different > > race > > > condition to > > > > > > reproduce it. > > > > > > > > > > > > > > > > > > As cloudstack have not good implementation yet of > > snapshot > > > lifecycle, > > > > > > sometime, it's happen, that some volumes already > > marked as > > > EXPUNGED in DB > > > > > > and then cloudstack try to delete bas Volume, before > > it's try to > > > > > > unprotect > > > > > > it. > > > > > > > > > > > > > > > > > > Sure, unprotecting fail, normal exception returned > > back (fail > > > because > > > > > > snap > > > > > > has childs... ) > > > > > > > > > > > > > > > > > > 2015-10-29 09:02:19,401 DEBUG > > [kvm.resource.KVMHAMonitor] > > > > > > (Thread-1304:null) > > > > > > Executing: > > > > > > > > > > > > /usr/share/cloudstack-common/scripts/vm/hypervisor/kvm/kvmheartbeat.sh > > > -i > > > > > > 10.44.253.13 -p /var/lib/libvirt/PRIMARY -m > > > > > > /mnt/93655746-a9ef-394d-95e9-6e62471dd39f -h > > 10.44.253.11 > > > > > > > > > > > > > > > 2015-10-29 09:02:19,412 DEBUG > > [kvm.resource.KVMHAMonitor] > > > > > > (Thread-1304:null) > > > > > > Execution is successful. > > > > > > > > > > > > > > > 2015-10-29 09:02:19,554 INFO > > [kvm.storage.LibvirtStorageAdaptor] > > > > > > (agentRequest-Handler-5:null) Unprotecting and > > Removing RBD > > > snapshots of > > > > > > image 6789/71b1e2e9-1985-45ca-9ab6-9e5016b86b7c > prior to > > > removing the > > > > > > image > > > > > > > > > > > > > > > 2015-10-29 09:02:19,571 DEBUG > > [kvm.storage.LibvirtStorageAdaptor] > > > > > > (agentRequest-Handler-5:null) Succesfully connected > > to Ceph > > > cluster at > > > > > > cephmon.anolim.net:6789 > > <http://cephmon.anolim.net:6789> <http://cephmon.anolim.net:6789 > > > > > > > > > > > > > > > > > 2015-10-29 09:02:19,608 DEBUG > > [kvm.storage.LibvirtStorageAdaptor] > > > > > > (agentRequest-Handler-5:null) Unprotecting snapshot > > > > > > > > > > > > cloudstack/71b1e2e9-1985-45ca-9ab6-9e5016b86b7c@cloudstack-base-snap > > > > > > > > > > > > > > > 2015-10-29 09:02:19,627 DEBUG > > [kvm.storage.KVMStorageProcessor] > > > > > > (agentRequest-Handler-5:null) Failed to delete > volume: > > > > > > com.cloud.utils.exception.CloudRuntimeException: > > > > > > com.ceph.rbd.RbdException: > > > > > > Failed to unprotect snapshot cloudstack-base-snap > > > > > > > > > > > > > > > 2015-10-29 09:02:19,628 DEBUG [cloud.agent.Agent] > > > > > > (agentRequest-Handler-5:null) Seq 4-1921583831: { > > Ans: , MgmtId: > > > > > > 161344838950, via: 4, Ver: v1, Flags: 10, > > > > > > > > > > > > [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: > > > > > > com.ceph.rbd.RbdException: Failed to unprotect > snapshot > > > > > > cloudstack-base-snap","wait":0}}] } > > > > > > > > > > > > > > > 2015-10-29 09:02:25,722 DEBUG [cloud.agent.Agent] > > > > > > (agentRequest-Handler-2:null) Processing command: > > > > > > com.cloud.agent.api.GetHostStatsCommand > > > > > > > > > > > > > > > 2015-10-29 09:02:25,722 DEBUG > > > [kvm.resource.LibvirtComputingResource] > > > > > > (agentRequest-Handler-2:null) Executing: /bin/bash -c > > > idle=$(top -b -n 1| > > > > > > awk -F, '/^[%]*[Cc]pu/{$0=$4; gsub(/[^0-9.,]+/,""); > > print }'); > > > echo $idle > > > > > > > > > > > > > > > 2015-10-29 09:02:26,249 DEBUG > > > [kvm.resource.LibvirtComputingResource] > > > > > > (agentRequest-Handler-2:null) Execution is > successful. > > > > > > > > > > > > > > > 2015-10-29 09:02:26,250 DEBUG > > > [kvm.resource.LibvirtComputingResource] > > > > > > (agentRequest-Handler-2:null) Executing: /bin/bash -c > > > freeMem=$(free|grep > > > > > > cache:|awk '{print $4}');echo $freeMem > > > > > > > > > > > > > > > 2015-10-29 09:02:26,254 DEBUG > > > [kvm.resource.LibvirtComputingResource] > > > > > > (agentRequest-Handler-2:null) Execution is > successful. > > > > > > > > > > > > > > > > > > BUT, after 20 minutes - agent crashed... If we > > remove all > > > childs and > > > > > > create > > > > > > conditions for cloudstack to delete volume - all OK > > - no agent > > > crash in > > > > > > 20 > > > > > > minutes... > > > > > > > > > > > > > > > > > > We can't connect this action - Volume delete with > agent > > > crashe... Also we > > > > > > don't understand why +- 20 minutes need to last, and > > only then > > > agent > > > > > > crashed... > > > > > > > > > > > > > > > > > > From logs, before crash - only GetVMStats... And > > then - agent > > > started... > > > > > > > > > > > > > > > > > > 2015-10-29 09:21:55,143 DEBUG [cloud.agent.Agent] > > > (UgentTask-5:null) > > > > > > Sending > > > > > > ping: Seq 4-1343: { Cmd , MgmtId: -1, via: 4, Ver: > > v1, Flags: 11, > > > > > > > > > > > > [{"com.cloud.agent.api.PingRoutingCommand":{"newStates":{},"_hostVmStateReport":{"i-881-1117-VM":{"state":"PowerOn","host":" > > > > > > cs2.anolim.net <http://cs2.anolim.net> > > <http://cs2.anolim.net> > > > "},"i-7-106-VM":{"state":"PowerOn","host":" cs2.anolim.net > <http://cs2.anolim.net> > > > <http://cs2.anolim.net> > > > > > > "},"i-1683-1984-VM":{"state":"PowerOn","host":" > cs2.anolim.net <http://cs2.anolim.net> > > > <http://cs2.anolim.net> > > > > > > "},"i-11-504-VM":{"state":"PowerOn","host":" > cs2.anolim.net <http://cs2.anolim.net> > > > <http://cs2.anolim.net> > > > > > > "},"i-325-616-VM":{"state":"PowerOn","host":" > cs2.anolim.net <http://cs2.anolim.net> > > > <http://cs2.anolim.net> > > > > > > "},"i-10-52-VM":{"state":"PowerOn","host":" > cs2.anolim.net <http://cs2.anolim.net> > > > <http://cs2.anolim.net> > > > > > > "},"i-941-1237-VM":{"state":"PowerOn","host":" > cs2.anolim.net <http://cs2.anolim.net> > > > <http://cs2.anolim.net> > > > > > > > > > > > > "}},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":4,"wait":0}}] > > > > > > } > > > > > > > > > > > > > > > 2015-10-29 09:21:55,149 DEBUG [cloud.agent.Agent] > > > (Agent-Handler-3:null) > > > > > > Received response: Seq 4-1343: { Ans: , MgmtId: > > 161344838950, > > > via: 4, > > > > > > Ver: > > > > > > v1, Flags: 100010, > > > > > > > > > > > > [{"com.cloud.agent.api.PingAnswer":{"_command":{"hostType":"Routing","hostId":4,"wait":0},"result":true,"wait":0}}] > > > > > > } > > > > > > > > > > > > > > > 2015-10-29 09:22:20,755 DEBUG [cloud.agent.Agent] > > > > > > (agentRequest-Handler-5:null) Processing command: > > > > > > com.cloud.agent.api.GetVmStatsCommand > > > > > > > > > > > > > > > 2015-10-29 09:23:02,630 INFO [cloud.agent.AgentShell] > > > (main:null) Agent > > > > > > started > > > > > > > > > > > > > > > 2015-10-29 09:23:02,632 INFO > > [cloud.agent.AgentShell] (main:null) > > > > > > Implementation Version is 4.3.2 > > > > > > > > > > > > > > > > > > Can you please give us direction to go deeper... As > > we dont > > > udnerstand > > > > > > what > > > > > > happened... > > > > > > > > > > > > > > > > > > Issue reproducing very easy: > > > > > > > > > > > > > > > > > > (to speed up delete process we set > > storage.cleanup.interval=10) > > > > > > > > > > > > > > > > > > 1. Create Volume > > > > > > > > > > > > > > > 2. Attach it to VM > > > > > > > > > > > > > > > 3. Create snapshot from this volume by hand on ceph > > > > > > > > > > > > > > > 4. Do snap_protect by hand on ceph for snap from > > previous step > > > > > > > > > > > > > > > 5. Create child via snap clone > > > > > > > > > > > > > > > 6. Deattach volume from VM and delete it > > > > > > > > > > > > > > > > > > Our problem - that this happen not in such lab > > situation, but > > > in real > > > > > > life... > > > > > > > > > > > > > > > > _______________________________________________ > > > > ceph-users mailing list > > > > ceph-users@lists.ceph.com > > <mailto:ceph-users@lists.ceph.com> > > <mailto:ceph-users@lists.ceph.com > > <mailto:ceph-users@lists.ceph.com>> > > > > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com > > > > > > > > > > > > > > > _______________________________________________ > > > ceph-users mailing list > > > ceph-users@lists.ceph.com <mailto:ceph-users@lists.ceph.com> > > > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com > > > > > _______________________________________________ > > ceph-users mailing list > > ceph-users@lists.ceph.com <mailto:ceph-users@lists.ceph.com> > > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com > > > > > > >
_______________________________________________ ceph-users mailing list ceph-users@lists.ceph.com http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
