Bug 1643813

Summary: Managing tags fails with ConcurrentModificationException
Product: Red Hat Enterprise Virtualization Manager Reporter: Germano Veit Michel <gveitmic>
Component: ovirt-engineAssignee: Dana <delfassy>
Status: CLOSED ERRATA QA Contact: Liran Rotenberg <lrotenbe>
Severity: high Docs Contact:
Priority: unspecified    
Version: 4.2.6CC: lsvaty, mgoldboi, mperina, Rhev-m-bugs
Target Milestone: ovirt-4.3.0Keywords: ZStream
Target Release: 4.3.0   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: ovirt-engine-4.3.0_alpha Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1651132 (view as bug list) Environment:
Last Closed: 2019-05-08 12:38:47 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1651132    

Description Germano Veit Michel 2018-10-29 04:20:54 UTC
Description of problem:

Apparently 2 POST at the same time to manage VM tags, can result in java.util.ConcurrentModificationException.

[22/Oct/2018:15:03:02 +0200] "POST /ovirt-engine/api/vms/a6928c53-ed11-4d6f-afb0-63add888bb49/tags HTTP/1.1" 201 242
[22/Oct/2018:15:03:02 +0200] "POST /ovirt-engine/api/vms/a6928c53-ed11-4d6f-afb0-63add888bb49/tags HTTP/1.1" 500 128

So the second POST returned 500. Engine logs:

2018-10-22 15:03:02,937+02 ERROR [org.ovirt.engine.core.bll.GetAllTagsQuery] (default task-47) [34996d5c-4ebc-4eee-9f14-c67d3980158d] Exception: java.util.ConcurrentModificationException
        at java.util.HashMap$HashIterator.nextNode(HashMap.java:1442) [rt.jar:1.8.0_181]
        at java.util.HashMap$ValueIterator.next(HashMap.java:1471) [rt.jar:1.8.0_181]
        at org.ovirt.engine.core.utils.collections.CopyOnAccessMap.values(CopyOnAccessMap.java:155) [utils.jar:]
        at org.ovirt.engine.core.bll.TagsDirector.getAllTags(TagsDirector.java:334) [bll.jar:]
        at org.ovirt.engine.core.bll.GetAllTagsQuery.executeQueryCommand(GetAllTagsQuery.java:19) [bll.jar:]
        at org.ovirt.engine.core.bll.QueriesCommandBase.executeCommand(QueriesCommandBase.java:106) [bll.jar:]
        at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33) [dal.jar:]
        at org.ovirt.engine.core.bll.executor.DefaultBackendQueryExecutor.execute(DefaultBackendQueryExecutor.java:14) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runQueryImpl(Backend.java:538) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runQuery(Backend.java:507) [bll.jar:]
        at sun.reflect.GeneratedMethodAccessor71.invoke(Unknown Source) [:1.8.0_181]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)

Other interesting logs around that time are:

1) Adding a new tag to the system:

2018-10-22 15:03:02,935+02 INFO  [org.ovirt.engine.core.bll.AddTagCommand] (default task-5) [ef7535d4-1212-403d-bcd2-45b3c284cfa2] Running command: AddTagCommand internal: false. Entities affected :  ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group TAG_MANAGEMENT with role type ADMIN

2) Adding the just added tag to another VM

2018-10-22 15:03:03,136+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-17) [b25ad432-606f-4dff-80f0-2fe2f71ca099] EVENT_ID: USER_ATTACH_TAG_TO_VM(440), Tag xyz was attached to VM(s) abc by admin@internal-authz.

Version-Release number of selected component (if applicable):
rhvm-4.2.6.4-0.1.el7ev.noarch
ovirt-engine-restapi-4.2.6.4-0.1.el7ev.noarch

How reproducible:
- Randomly on customer site, apparently its rare given the number of calls.
- Did not reproduce in our labs

Steps to Reproduce:
- 2 thread python script adding and removing 2 tags in a loop did not reproduce it after 30min running.

Comment 3 Dana 2018-11-13 13:30:19 UTC
I wasn't able to reproduce the bug, but I added a fix that should solve this issue

Comment 5 Liran Rotenberg 2018-12-20 17:19:58 UTC
Verified on:
ovirt-engine-4.3.0-0.4.master.20181218200623.gitf1f0e41.el7.noarch
ovirt-engine-restapi-4.3.0-0.4.master.20181218200623.gitf1f0e41.el7.noarch

Steps:
1. Have a VM that has 4 tags assigned to it
2. Execute Jan's script against such VM: https://gist.github.com/jan-zmeskal/48585a5dbbef5b52cb28faac67a0a161
3. Keep it running for 30 or more minutes
4. Make sure that no error was raised during the script's execution
5. grep engine.log for "java.util.ConcurrentModificationException"

Results:
No exception were when running the script for 1 hour. 
No Error with "java.util.ConcurrentModificationException" were in the engine log.

Comment 7 errata-xmlrpc 2019-05-08 12:38:47 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2019:1085