On 11-09-15 14:43, Dmytro Shevchenko wrote:
Thanks a lot Wido! Any chance to find out why management server
decided
that it lost connection to agent after that exceptions? It's not so
critical as this bug with 16 snapshots, but during last week we catch
situation when Agent failed unprotect snapshot, rise exception and
this
is was a reason of disconnection a bit later after that. (It is not
clear why CS decided remove that volume, it was template with one
'gold'
snapshot with several active clones)
No, I didn't look at CS at all. I just spend the day improving the
RADOS
bindings.
Wido
On 09/11/2015 03:20 PM, Wido den Hollander wrote:
On 11-09-15 10:19, Wido den Hollander wrote:
On 10-09-15 23:15, Andrija Panic wrote:
Wido,
could you folow maybe what my colegue Dmytro just sent ?
Yes, seems logical.
Its not only matter of question fixing rados-java (16 snaps limit)
- it
seems that for any RBD exception, ACS will freak out...
No, a RbdException will be caught, but the Rados Bindings shouldn't
throw NegativeArraySizeException in any case.
That's the main problem.
Seems to be fixed with this commit:
https://github.com/ceph/rados-java/commit/5584f3961c95d998d2a9eff947a5b7b4d4ba0b64
Just tested it with 256 snapshots:
-------------------------------------------------------
T E S T S
-------------------------------------------------------
Running com.ceph.rbd.TestRbd
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed:
521.014 sec
Results :
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
The bindings should now be capable of listing more then 16 snapshots.
You can build the bindings manually and replace rados.jar on your
running systems.
For 4.6 I'll try to get the updated rados-java included.
Wido
Wido
THx
On 10 September 2015 at 17:06, Dmytro Shevchenko <
dmytro.shevche...@safeswisscloud.com> wrote:
Hello everyone, some clarification about this. Configuration:
CS: 4.5.1
Primary storage: Ceph
Actually we have 2 separate bugs:
1. When you remove some volume with more then 16 snapshots
(doesn't
matter
destroyed or active - they always present on Ceph), on next
storage
garbage
collector cycle it invoke 'deletePhysicalDisk' from
LibvirtStorageAdaptor.java. On line 854 we calling list snapshots
from
external rados-java library and getting exception.
https://github.com/apache/cloudstack/blob/4.5.1/plugins/hypervisors/kvm/src/com/cloud/hypervisor/kvm/storage/LibvirtStorageAdaptor.java#L854
This exception do not catching in current function, but Agent DO
NOT CRASH
at this moment and continue working fine. Agent form proper
answer to
server and send it, text in answer - java stack trace. Log from
Agent side:
2015-09-10 02:32:35,312 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-4:null) Trying to fetch storage pool
33ebaf83-5d09-3038-b63b-742e759a
992e from libvirt
2015-09-10 02:32:35,431 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-4:null) Attempting to remove volume
4c6a2092-056c-4446-a2ca-d6bba9f7f
7f8 from pool 33ebaf83-5d09-3038-b63b-742e759a992e
2015-09-10 02:32:35,431 INFO [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-4:null) Unprotecting and Removing RBD
snapshots of
image cloudstack-storage
/4c6a2092-056c-4446-a2ca-d6bba9f7f7f8 prior to removing the image
2015-09-10 02:32:35,436 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-4:null) Succesfully connected to Ceph
cluster
at
10.10.1.26:6789
2015-09-10 02:32:35,454 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-4:null) Fetching list of snapshots of RBD
image
cloudstack-storage/4c6a2092
-056c-4446-a2ca-d6bba9f7f7f8
2015-09-10 02:32:35,457 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)
2015-09-10 02:32:35,458 DEBUG [cloud.agent.Agent]
(agentRequest-Handler-4:null) Seq 1-1743737480722513946: { Ans: ,
MgmtId:
90520739779588, via: 1, Ver: v1,
Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":false,"details":"java.lang.NegativeArraySizeException\n\tat
com.ceph.rbd.RbdImage.snapList(Unknown Sourc
e)\n\tat
com.cloud.hypervisor.kvm.storage.LibvirtStorageAdaptor.deletePhysicalDisk(LibvirtStorageAdaptor.java:854)\n\tat
com.cloud.hypervisor.kvm.storage.Lib
virtStoragePool.deletePhysicalDisk(LibvirtStoragePool.java:175)\n\tat
com.cloud.hypervisor.kvm.storage.KVMStorageProcessor.deleteVolume(KVMStorageProcessor.j
ava:1206)\n\tat
com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:124)\n\tat
com.cloud.storage.re.....
so this volume and it snapshots never will be removed.
2. Second bug. Experimentally it has been found that after 50
minutes we
had exception on Agent, for some unknown reason Management server
decided
about it lost connection to this agent, start HA process and start
Agent
process again.
Log on Agent side:
2015-09-10 02:57:12,664 DEBUG
[kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-2:null) Executing: /bin/bash -c free|grep
Mem:|awk
'{print $2}'
2015-09-10 02:57:12,667 DEBUG
[kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-2:null) Execution is successful.
2015-09-10 02:57:40,502 DEBUG
[kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_
group.py get_rule_logs_for_vms
2015-09-10 02:57:40,572 DEBUG
[kvm.resource.LibvirtComputingResource]
(UgentTask-5:null) Execution is successful.
2015-09-10 02:57:54,135 INFO [cloud.agent.AgentShell] (main:null)
Agent
started
2015-09-10 02:57:54,136 INFO [cloud.agent.AgentShell] (main:null)
Implementation Version is 4.5.1
2015-09-10 02:57:54,138 INFO [cloud.agent.AgentShell] (main:null)
agent.properties found at /etc/cloudstack/agent/agent.properties
.....
Log on Server side:
2015-09-10 02:57:53,710 INFO [c.c.a.m.AgentManagerImpl]
(AgentTaskPool-1:ctx-2127ada4) Investigating why host 1 has
disconnected
with event AgentDisconnecte
d
2015-09-10 02:57:53,714 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentTaskPool-1:ctx-2127ada4) checking if agent (1) is alive
2015-09-10 02:57:53,723 DEBUG [c.c.a.t.Request]
(AgentTaskPool-1:ctx-2127ada4) Seq 1-1743737480722513988:
Sending {
Cmd ,
MgmtId: 90520739779588, via: 1(ix1
-c7-2), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.CheckHealthCommand":{"wait":50}}] }
2015-09-10 02:57:53,724 INFO [c.c.a.m.AgentAttache]
(AgentTaskPool-1:ctx-2127ada4) Seq 1-1743737480722513988:
Unable to
send
due to Resource [Host:1] is unr
eachable: Host 1: Channel is closed
2015-09-10 02:57:53,724 DEBUG [c.c.a.m.AgentAttache]
(AgentTaskPool-1:ctx-2127ada4) Seq 1-1743737480722513988:
Cancelling.
2015-09-10 02:57:53,724 WARN [c.c.a.m.AgentManagerImpl]
(AgentTaskPool-1:ctx-2127ada4) Resource [Host:1] is unreachable:
Host 1:
Channel is closed
2015-09-10 02:57:53,728 DEBUG [c.c.h.HighAvailabilityManagerImpl]
(AgentTaskPool-1:ctx-2127ada4) SimpleInvestigator unable to
determine the
state of the host
. Moving on.
it's look like connection problem, but it appear only when we have
this
RBD exception on agent side and only with this node. I tried to
play with
"storage.cleanup.interval" parameter and set it to 5 minutes,
now we
getting exception on agent side every 5min, but disconnects still
happening
every 50min and I can't find out why.
On 09/10/2015 03:21 PM, Andrija Panic wrote:
Thx Wido,
I will have my colegue Igor and Dmytro join with details on this.
I agree we need fix upstream, that is the main purpose from our
side!
With this temp fix, we just avoid agent crashing (agent somehow
restarts
again fine :) ) but VMs also go down on that host, at least some
of them.
Do you see any lifecycle/workflow issue, if we implement deleting
SNAP
from CEPH after you SNAP a volume in ACS and sucsssfully move to
Secondary
NFS - or perhaps only delete SNAP from CEPH as a part of actuall
SNAP
deletion (when you manually or via scheduled snapshots, delete
snapshot
from DB and NFS) ? Maybe second option is better, I dont know how
you guys
handle this for regular NFS as primary storage etc...
Any guidance is most welcomed, and our team will try to code all
this.
Thx Wido again
On 10 September 2015 at 14:14, Wido den Hollander <w...@widodh.nl
<mailto:w...@widodh.nl>> wrote:
On 10-09-15 14:07, Andrija Panic wrote:
> Wido,
>
> part of code where you want to delete some volume,
checks if
volume is type
> RBD - and then tries to list snapshots, delete
snapshtos, and
finally
> remove image. Here first step- Listing snapshtos-
fails, if
there are more
> than 16 snapshtos present - number 16 is hardcoded in
elsewhere
part of
> code and throws RBD exception...then agent crashes... and
then
VMs goe down
> etc.
>
Hmmm, that seems like a bug in rados-java indeed. I don't
know if
there
is a release of rados-java where this is fixed in.
Looking at the code of rados-java it should, but I'm not
100%
certain.
> So our current way as quick fix is to invoke external
script
which will
> also list and remove all snapshtos, but will not fail.
>
Yes, but we should fix it upstream. I understand that you
will use a
temp script to clean up everything.
> I'm not sure why is there 16 as the hardcoded limit -
will
try
to provide
> part of code where this is present...we can increase this
number
but it
> doesn make any sense (from 16 to i.e. 200), since we
still
have
lot of
> garbage left on CEPH (snapshtos that were removed in ACS
(DB and
Secondary
> NFS) - but not removed from CEPH. And in my understanding
this
needs to be
> implemented, so we dont catch any exceptions that I
originally
described...
>
> Any thoughts on this ?
>
A cleanup script for now should be OK indeed. Afterwards
the
Java code
should be able to do this.
You can try manually by using rados-java and fix that.
This is the part where the listing is done:
https://github.com/ceph/rados-java/blob/master/src/main/java/com/ceph/rbd/RbdImage.java
Wido
> Thx for input!
>
> On 10 September 2015 at 13:56, Wido den Hollander
<w...@widodh.nl <mailto:w...@widodh.nl>> wrote:
>
>>
>>
>> On 10-09-15 12:17, Andrija Panic wrote:
>>> We are testing some [dirty?] patch on our dev system
and we
shall soon
>>> share it for review.
>>>
>>> Basically, we are using external python script that is
invoked
in some
>> part
>>> of code execution to delete needed CEPH snapshots
and then
after that
>>> proceeds with volume deleteion etc...
>>>
>>
>> That shouldn't be required. The Java bindings for
librbd and
librados
>> should be able to remove the snapshots.
>>
>> There is no need to invoke external code, this can
all be
handled in Java.
>>
>>> On 10 September 2015 at 11:26, Andrija Panic
<andrija.pa...@gmail.com <mailto:andrija.pa...@gmail.com>>
>>> wrote:
>>>
>>>> Eh, OK. Thx for the info.
>>>>
>>>> BTW why is 16 snapshot limits hardcoded - any
reason for
that ?
>>>>
>>>> Not cleaning snapshots on CEPH and trying to delete
volume
after having
>>>> more than 16 snapshtos in CEPH = Agent crashing on KVM
side...and some
>> VMs
>>>> being rebooted etc - which means downtime :|
>>>>
>>>> Thanks,
>>>>
>>>> On 9 September 2015 at 22:05, Simon Weller <
swel...@ena.com
<mailto:swel...@ena.com>> wrote:
>>>>
>>>>> Andrija,
>>>>>
>>>>> The Ceph snapshot deletion is not currently
implemented.
>>>>>
>>>>> See:
https://issues.apache.org/jira/browse/CLOUDSTACK-8302
>>>>>
>>>>> - Si
>>>>>
>>>>> ________________________________________
>>>>> From: Andrija Panic<andrija.pa...@gmail.com>
>>>>> Sent: Wednesday, September 9, 2015 3:03 PM
>>>>> To:dev@cloudstack.apache.org
<mailto:dev@cloudstack.apache.org>;
us...@cloudstack.apache.org
<mailto:us...@cloudstack.apache.org>
>>>>> Subject: ACS 4.5 - volume snapshots NOT removed
from CEPH
(only from
>>>>> Secondaryt NFS and DB)
>>>>>
>>>>> Hi folks,
>>>>>
>>>>> we enounter issue in ACS 4.5.1 (perhaps other
versions
also
affected) -
>>>>> when we delete some snapshot (volume snapshot) in
ACS,
ACS
marks it as
>>>>> deleted in DB, deletes from NFS Secondary Storage but
fails
to delete
>>>>> snapshot on CEPH primary storage (doesn even try to
delete
it AFAIK)
>>>>>
>>>>> So we end up having 5 live snapshots in DB (just
example)
but actually
>> in
>>>>> CEPH there are more than i.e. 16 snapshots.
>>>>>
>>>>> More of the issue, when ACS agent tries to obtain
list of
snapshots
>> from
>>>>> CEPH for some volume or so - if number of
snapshots is
over
16, it
>> raises
>>>>> exception (and perhaps this is the reason Agent
crashed for
us - need
>> to
>>>>> check with my colegues who are investigatin this in
details). This
>> number
>>>>> 16 is for whatever reasons hardcoded in ACS code.
>>>>>
>>>>> Wondering if anyone experienced this, or have any
info
- we
plan to
>> try to
>>>>> fix this, and I will inlcude my dev colegues here,
but we
might need
>> some
>>>>> help at least for guidance or-
>>>>>
>>>>> Any help is really apreaciated or at list
confirmation
that
this is
>> known
>>>>> issue etc.
>>>>>
>>>>> Thanks,
>>>>>
>>>>> --
>>>>>
>>>>> Andrija Panić
>>>>>
>>>>
>>>>
>>>>
>>>> --
>>>>
>>>> Andrija Panić
>>>>
>>>
>>>
>>>
>>
>
>
>
--
Andrija Panić
--
---
Best regards
Dmytro Shevchenko
dshevchenko.m...@gmail.com
skype: demonsh_mk
+380(66)2426648
