[UIMA-4812] UIMA-AS: fix CasManager.defineCasPool() was called twice by the same Analysis Engine

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 2.8.1AS
• Component/s: Async Scaleout
• Assignee: Jaroslaw Cwiklik
• Reporter: Jaroslaw Cwiklik
• Created: 01/Mar/16 19:19
• Updated: 03/Mar/16 20:39
• Resolved: 03/Mar/16 20:39

Description

The UIMA-AS initializes AE instances sequentially each in a separate thread. It appears that AE initialization proceeds even if a previous thread had an error. Code in question is in UimaAsThreadFactory.run().
The scenario
12:06:33.379 - 22: org.apache.uima.aae.UimaAsThreadFactory$1.UimaAsThreadFactory.run(): INFO: Controller: Meeting Detector TAE Initializing AE instance on Thread Id: 22
12:06:33.392 - 22: org.apache.uima.analysis_engine.impl.AggregateAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Detector TAE] initialization begin
12:06:33.469 - 22: org.apache.uima.analysis_engine.asb.impl.ASB_impl.initialize: CONFIG: ASB initialization begin
12:06:33.470 - 22: org.apache.uima.analysis_engine.asb.impl.ASB_impl.initialize: CONFIG: ASB initialization successful
12:06:33.472 - 22: org.apache.uima.resource.impl.ConfigurationManager_impl.declareParameters: CONFIG: Parameter "Patterns" in context /RoomNumber/ = "[\b[0-4]\d-[0-2]\d\d\b, \b[G1-4][NS]-[A-Z]\d\d\b, \bJ[1\
2]-[A-Z]\d\d\b]"
12:06:33.472 - 22: org.apache.uima.resource.impl.ConfigurationManager_impl.declareParameters: CONFIG: Parameter "Locations" in context /RoomNumber/ = "[Watson - Yorktown, Watson - Hawthorne I, Watson - Haw\
thorne II]"
12:06:33.473 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Room Number Annotator] initialization begin
12:06:33.478 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Room Number Annotator] initialization successful
12:06:33.482 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [TutorialDateTime Annotator] initialization begin
12:06:33.490 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [TutorialDateTime Annotator] initialization successful
12:06:33.490 - 22: org.apache.uima.resource.impl.ConfigurationManager_impl.declareParameters: CONFIG: Parameter "WindowSize" in context /Meeting/ = "200"
12:06:33.491 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Annotator] initialization begin
12:06:33.492 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Annotator] initialization successful
12:06:33.493 - 22: org.apache.uima.resource.impl.ConfigurationManager_impl.declareParameters: CONFIG: Parameter "ActionAfterCasMultiplier" in context /_FlowController/ = "dropIfNewCasProduced"
12:06:33.497 - 22: org.apache.uima.analysis_engine.impl.AggregateAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Detector TAE] initialization successful
12:06:33.498 - 22: org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.initialize: CONFIG: - Initializing Async Primitive Service. Number of Worker Threads: 1
12:06:33.498 - 22: org.apache.uima.aae.AsynchAECasManager_impl.initialize: CONFIG: Primary CAS Pool Size: 1 Context: PrimitiveAEService Initial Cas Heap Size:500000 cells. Supports Incoming Service Request\
s.
12:06:33.717 - 22: org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.postInitialize: INFO: ********* Initialized the Controller. Meeting Detector TAE Ready To Process. ********
12:06:33.719 - 1: org.apache.uima.adapter.jms.activemq.SpringContainerDeployer.doStartListeners: INFO: Controller: Meeting Detector TAE Starting Listener on Endpoint: queue://MeetingDetectorTaeQueue Select\
or: Command=2000 OR Command=2002 Broker: ssl://XXXXXX:61617?transport.needClientAuth=false
12:06:34.416 - 1: org.apache.uima.adapter.jms.activemq.SpringContainerDeployer.doStartListeners: INFO: Controller: Meeting Detector TAE Starting Listener on Endpoint: queue://MeetingDetectorTaeQueue Select\
or: Command=2001 Broker: ssl://XXXXXX:61617?transport.needClientAuth=false
12:07:04.422 - 22: org.apache.uima.adapter.jms.activemq.UimaDefaultMessageListenerContainer.handleListenerSetupFailure: WARNING: Uima AS Service:Meeting Detector TAE Listener Unable To Connect To Broker: s\
sl://XXXXX:61617?transport.needClientAuth=false Retrying ...
12:07:04.424 - 23: org.apache.uima.adapter.jms.activemq.UimaDefaultMessageListenerContainer.handleListenerSetupFailure: WARNING: Uima AS Service:Meeting Detector TAE Listener Unable To Connect To Broker: s\
sl://XXXXXX:61617?transport.needClientAuth=false Retrying ...
12:07:04.425 - 22: org.apache.uima.aae.UimaAsThreadFactory$1.UimaAsThreadFactory.run(): INFO: Controller: Meeting Detector TAE --------------- Process Thread ID:22 EXITING
12:07:04.426 - 25: org.apache.uima.aae.UimaAsThreadFactory$1.UimaAsThreadFactory.run(): INFO: Controller: Meeting Detector TAE Initializing AE instance on Thread Id: 25
12:07:04.426 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Room Number Annotator] destroyed.
12:07:04.426 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [TutorialDateTime Annotator] destroyed.
12:07:04.427 - 22: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Annotator] destroyed.
12:07:04.427 - 22: org.apache.uima.analysis_engine.impl.AggregateAnalysisEngine_impl.destroy: CONFIG: AnalysisEngine [Meeting Detector TAE] destroyed.
12:07:04.427 - 22: org.apache.uima.aae.UimaAsThreadFactory$1.UimaAsThreadFactory.run(): INFO: Controller: Meeting Detector TAE --------------- AE destroy() Method Call Returned ID:22
12:07:04.473 - 25: org.apache.uima.analysis_engine.impl.AggregateAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Detector TAE] initialization begin
12:07:04.515 - 25: org.apache.uima.analysis_engine.asb.impl.ASB_impl.initialize: CONFIG: ASB initialization begin
12:07:04.515 - 25: org.apache.uima.analysis_engine.asb.impl.ASB_impl.initialize: CONFIG: ASB initialization successful
12:07:04.516 - 25: org.apache.uima.resource.impl.ConfigurationManager_impl.declareParameters: CONFIG: Parameter "Patterns" in context /RoomNumber/ = "[\b[0-4]\d-[0-2]\d\d\b, \b[G1-4][NS]-[A-Z]\d\d\b, \bJ[1\
2]-[A-Z]\d\d\b]"
12:07:04.516 - 25: org.apache.uima.resource.impl.ConfigurationManager_impl.declareParameters: CONFIG: Parameter "Locations" in context /RoomNumber/ = "[Watson - Yorktown, Watson - Hawthorne I, Watson - Haw\
thorne II]"
12:07:04.523 - 25: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Room Number Annotator] initialization begin
12:07:04.525 - 25: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Room Number Annotator] initialization successful
12:07:04.528 - 25: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [TutorialDateTime Annotator] initialization begin
12:07:04.528 - 25: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [TutorialDateTime Annotator] initialization successful
12:07:04.529 - 25: org.apache.uima.resource.impl.ConfigurationManager_impl.declareParameters: CONFIG: Parameter "WindowSize" in context /Meeting/ = "200"
12:07:04.536 - 25: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Annotator] initialization begin
12:07:04.537 - 25: org.apache.uima.analysis_engine.impl.PrimitiveAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Annotator] initialization successful
12:07:04.537 - 25: org.apache.uima.resource.impl.ConfigurationManager_impl.declareParameters: CONFIG: Parameter "ActionAfterCasMultiplier" in context /_FlowController/ = "dropIfNewCasProduced"
12:07:04.538 - 25: org.apache.uima.analysis_engine.impl.AggregateAnalysisEngine_impl.initialize: CONFIG: AnalysisEngine [Meeting Detector TAE] initialization successful
12:07:04.539 - 25: org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.initialize: CONFIG: - Initializing Async Primitive Service. Number of Worker Threads: 1
12:07:04.546 - 25: org.apache.uima.aae.AsynchAECasManager_impl.initialize: CONFIG: Primary CAS Pool Size: 1 Context: PrimitiveAEService Initial Cas Heap Size:500000 cells. Supports Incoming Service Request\
s.
12:07:04.547 - 25: org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.postInitialize: WARNING: Service: Meeting Detector TAE Runtime Exception
12:07:04.547 - 25: org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.postInitialize: WARNING:
org.apache.uima.UIMARuntimeException: The method CasManager.defineCasPool() was called twice by the same Analysis Engine (PrimitiveAEService).
at org.apache.uima.resource.impl.CasManager_impl.defineCasPool(CasManager_impl.java:244)
at org.apache.uima.resource.impl.CasManager_impl.defineCasPool(CasManager_impl.java:214)
at org.apache.uima.aae.EECasManager_impl.defineCasPool(EECasManager_impl.java:63)
at org.apache.uima.aae.AsynchAECasManager_impl.initialize(AsynchAECasManager_impl.java:101)
at org.apache.uima.aae.AsynchAECasManager_impl.initialize(AsynchAECasManager_impl.java:83)
at org.apache.uima.aae.AsynchAECasManager_impl.initialize(AsynchAECasManager_impl.java:79)
at org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.postInitialize(PrimitiveAnalysisEngineController_impl.java:312)
at org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.initializeAnalysisEngine(PrimitiveAnalysisEngineController_impl.java:220)
at org.apache.uima.aae.UimaAsThreadFactory$1.run(UimaAsThreadFactory.java:119)
at java.lang.Thread.run(Thread.java:780)

12:07:04.561 - 25: org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.postInitialize: WARNING: Service: Meeting Detector TAE Runtime Exception
12:07:04.562 - 25: org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.postInitialize: WARNING:
org.apache.uima.aae.error.AsynchAEException: org.apache.uima.UIMARuntimeException: The method CasManager.defineCasPool() was called twice by the same Analysis Engine (PrimitiveAEService).
at org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.postInitialize(PrimitiveAnalysisEngineController_impl.java:342)
at org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.initializeAnalysisEngine(PrimitiveAnalysisEngineController_impl.java:220)
at org.apache.uima.aae.UimaAsThreadFactory$1.run(UimaAsThreadFactory.java:119)
at java.lang.Thread.run(Thread.java:780)
Caused by: org.apache.uima.UIMARuntimeException: The method CasManager.defineCasPool() was called twice by the same Analysis Engine (PrimitiveAEService).
at org.apache.uima.resource.impl.CasManager_impl.defineCasPool(CasManager_impl.java:244)
at org.apache.uima.resource.impl.CasManager_impl.defineCasPool(CasManager_impl.java:214)
at org.apache.uima.aae.EECasManager_impl.defineCasPool(EECasManager_impl.java:63)
at org.apache.uima.aae.AsynchAECasManager_impl.initialize(AsynchAECasManager_impl.java:101)
at org.apache.uima.aae.AsynchAECasManager_impl.initialize(AsynchAECasManager_impl.java:83)
at org.apache.uima.aae.AsynchAECasManager_impl.initialize(AsynchAECasManager_impl.java:79)
at org.apache.uima.aae.controller.PrimitiveAnalysisEngineController_impl.postInitialize(PrimitiveAnalysisEngineController_impl.java:312)
... 3 more

The UimaAsThreadFactory should check the status of the controller to determine if initialization of subsequent thread should proceed.