Question

1
Replies
313
Views
GERALDHMSA Member since 2013 15 posts
HMSA
Posted: September 8, 2015
Last activity: September 9, 2015
Closed
Solved

Redindex Elastic Search PRPC 7.1.7 fails with RequestorLockException

We are attempting to reindex a production volume database in our sandbox environment.

1. When I login with my own credentials and launch reindexing, I get exceptions and finally heap dump with OO memory.

2. When I login as Administrator@pega.com reindexing completes without exceptions.

What makes the Administrator@pega.com account behave differently than my own account?

Below are message excerpts from the pega log when using my own account.

Reindexing started 10:45

2015-09-08 10:45:44,193 [.PRPCWorkManager : 0] [  STANDARD] [     PegaRULES:07.10] (          internal.async.Agent) INFO    - System date: Tue Sep 08 10:45:44 HST 2015 Total memory: 5,368,709,120 Free memory: 962,250,912 Requestor Count: 16 Shared Pages memory usage: 0%

 

1st Exception

2015-09-08 10:54:05,064 [    WebContainer : 5] [          ] [                    ] (ngineinterface.service.HttpAPI) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12  - fe80:0:0:0:45b1:3947:f5d8:791f%12: com.pega.pegarules.pub.context.RequestorLockException
com.pega.pegarules.pub.context.RequestorLockException: Unable to synchronize on requestor H92C50BE39E1BD2A35B8846F7467CD64E within 120 seconds: (thisThread = WebContainer : 5) (originally locked by = WebContainer : 0) (finally locked by = (unknown))

 

2015-09-08 10:53:47,517 [    WebContainer : 2] [          ] [                    ] (ngineinterface.service.HttpAPI) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12  - fe80:0:0:0:45b1:3947:f5d8:791f%12: com.pega.pegarules.pub.context.RequestorLockException
com.pega.pegarules.pub.context.RequestorLockException: Unable to synchronize on requestor H92C50BE39E1BD2A35B8846F7467CD64E within 120 seconds: (thisThread = WebContainer : 2) (originally locked by = WebContainer : 8) (finally locked by = WebContainer : 9)

 

2015-09-08 10:53:34,610 [    WebContainer : 6] [          ] [                    ] (.timers.EnvironmentDiagnostics) INFO  hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12  - --- Thread Dump Starts ---
Full Java thread dump with locks info
"P=165184:O=0:CT" Id=1 in TIMED_WAITING (running in native)
BlockedCount : 6, BlockedTime : -1, WaitedCount : 189, WaitedTime : -1
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:876)
    at com.ibm.ws.runtime.WsServerImpl.main(WsServerImpl.java:679)
    at com.ibm.ws.runtime.WsServer.main(WsServer.java:59)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
    at java.lang.reflect.Method.invoke(Method.java:611)
    at com.ibm.wsspi.bootstrap.WSLauncher.launchMain(WSLauncher.java:213)
    at com.ibm.wsspi.bootstrap.WSLauncher.main(WSLauncher.java:93)
    at com.ibm.wsspi.bootstrap.WSLauncher.run(WSLauncher.java:74)
    at org.eclipse.core.internal.runtime.PlatformActivator$1.run(PlatformActivator.java:78)
    at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:92)
    at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:68)
    at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:400)
    at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:177)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
    at java.lang.reflect.Method.invoke(Method.java:611)
    at org.eclipse.core.launcher.Main.invokeFramework(Main.java:340)
    at org.eclipse.core.launcher.Main.basicRun(Main.java:282)
    at org.eclipse.core.launcher.Main.run(Main.java:981)
    at com.ibm.wsspi.bootstrap.WSPreLauncher.launchEclipse(WSPreLauncher.java:341)
    at com.ibm.wsspi.bootstrap.WSPreLauncher.main(WSPreLauncher.java:111)

    Locked synchronizers: count = 0

 

2015-09-08 11:02:00,442 [   WebContainer : 10] [          ] [                    ] (.timers.EnvironmentDiagnostics) INFO  hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12  - --- Thread Dump Starts ---
Full Java thread dump with locks info
"P=165184:O=0:CT" Id=1 in TIMED_WAITING (running in native)
BlockedCount : 6, BlockedTime : -1, WaitedCount : 189, WaitedTime : -1
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:876)
    at com.ibm.ws.runtime.WsServerImpl.main(WsServerImpl.java:679)
    at com.ibm.ws.runtime.WsServer.main(WsServer.java:59)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
    at java.lang.reflect.Method.invoke(Method.java:611)
    at com.ibm.wsspi.bootstrap.WSLauncher.launchMain(WSLauncher.java:213)
    at com.ibm.wsspi.bootstrap.WSLauncher.main(WSLauncher.java:93)
    at com.ibm.wsspi.bootstrap.WSLauncher.run(WSLauncher.java:74)
    at org.eclipse.core.internal.runtime.PlatformActivator$1.run(PlatformActivator.java:78)
    at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:92)
    at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:68)
    at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:400)
    at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:177)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
    at java.lang.reflect.Method.invoke(Method.java:611)
    at org.eclipse.core.launcher.Main.invokeFramework(Main.java:340)
    at org.eclipse.core.launcher.Main.basicRun(Main.java:282)
    at org.eclipse.core.launcher.Main.run(Main.java:981)
    at com.ibm.wsspi.bootstrap.WSPreLauncher.launchEclipse(WSPreLauncher.java:341)
    at com.ibm.wsspi.bootstrap.WSPreLauncher.main(WSPreLauncher.java:111)

    Locked synchronizers: count = 0

 

2015-09-08 11:02:00,535 [   WebContainer : 10] [          ] [                    ] (ngineinterface.service.HttpAPI) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12  - fe80:0:0:0:45b1:3947:f5d8:791f%12: com.pega.pegarules.pub.context.RequestorLockException
com.pega.pegarules.pub.context.RequestorLockException: Unable to synchronize on requestor H92C50BE39E1BD2A35B8846F7467CD64E within 120 seconds: (thisThread = WebContainer : 10) (originally locked by = WebContainer : 9) (finally locked by = WebContainer : 7)
at com.pega.pegarules.session.internal.PRSessionProviderImpl.getLockOnRequestor(PRSessionProviderImpl.java:1359)

Get a bunch of these:
2015-09-08 11:02:04,770 [.PRPCWorkManager : 3] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: IllegalIndexShardStateException[[work][0] CurrentState[CLOSED] operation only allowed when started/recovering, origin [PRIMARY]]
2015-09-08 11:02:04,770 [.PRPCWorkManager : 3] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: IllegalIndexShardStateException[[work][0] CurrentState[CLOSED] operation only allowed when started/recovering, origin [PRIMARY]]
2015-09-08 11:02:04,770 [.PRPCWorkManager : 3] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: IllegalIndexShardStateException[[work][0] CurrentState[CLOSED] operation only allowed when started/recovering, origin [PRIMARY]]
2015-09-08 11:02:04,770 [.PRPCWorkManager : 3] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: IllegalIndexShardStateException[[work][0] CurrentState[CLOSED] operation only allowed when started/recovering, origin [PRIMARY]]
2015-09-08 11:02:04,770 [.PRPCWorkManager : 3] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: IllegalIndexShardStateException[[work][0] CurrentState[CLOSED] operation only allowed when started/recovering, origin [PRIMARY]]
2015-09-08 11:02:04,770 [.PRPCWorkManager : 3] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: IllegalIndexShardStateException[[work][0] CurrentState[CLOSED] operation only allowed when started/recovering, origin [PRIMARY]]
2015-09-08 11:02:04,770 [.PRPCWorkManager : 3] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: IllegalIndexShardStateException[[work][0] CurrentState[CLOSED] operation only allowed when started/recovering, origin [PRIMARY]]

 

2015-09-08 11:02:05,004 [   WebContainer : 13] [TABTHREAD0] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12 hm05603 -
java.lang.NullPointerException
at com.pega.pegarules.search.internal.es.AbstractIndexer.getIndexStatus(AbstractIndexer.java:356)
at com.pegarules.generated.activity.ra_action_pzlpftsmanagerreindexstatus_c92d7fd46adf0fe40325e2c893412d4b.step2_circum0(ra_action_pzlpftsmanagerreindexstatus_c92d7fd46adf0fe40325e2c893412d4b.java:259)
at com.pegarules.generated.activity.ra_action_pzlpftsmanagerreindexstatus_c92d7fd46adf0fe40325e2c893412d4b.perform(ra_action_pzlpftsmanagerreindexstatus_c92d7fd46adf0fe40325e2c893412d4b.java:92)

 

2015-09-08 11:02:05,379 [   WebContainer : 13] [TABTHREAD0] [ CRMService:01.03.01] (     pegarules.pub.PRException) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12 hm05603 - Problem during PRException.setStatus:
com.pega.pegarules.pub.clipboard.InvalidParameterException: cannot be null.  Details: Invalid value for aMessageId passed to com.pega.pegarules.session.internal.mgmt.ProcessingStatusImpl.set(int, String, String)

2015-09-08 11:02:05,379 [    WebContainer : 4] [TABTHREAD0] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12 hm05603 -
java.lang.NullPointerException

 

2015-09-08 11:02:05,379 [    WebContainer : 4] [TABTHREAD0] [ CRMService:01.03.01] (     pegarules.pub.PRException) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12 hm05603 - Problem during PRException.setStatus:
com.pega.pegarules.pub.clipboard.InvalidParameterException: cannot be null.  Details: Invalid value for aMessageId passed to com.pega.pegarules.session.internal.mgmt.ProcessingStatusImpl.set(int, String, String)

 

2015-09-08 11:02:05,426 [    WebContainer : 1] [TABTHREAD0] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12 hm05603 -
java.lang.NullPointerException

2015-09-08 11:02:05,426 [    WebContainer : 1] [TABTHREAD0] [ CRMService:01.03.01] (     pegarules.pub.PRException) ERROR hon11250.corp.hmsa.com|fe80:0:0:0:45b1:3947:f5d8:791f%12 hm05603 - Problem during PRException.setStatus:
com.pega.pegarules.pub.clipboard.InvalidParameterException: cannot be null.  Details: Invalid value for aMessageId passed to com.pega.pegarules.session.internal.mgmt.ProcessingStatusImpl.set(int, String, String)

2015-09-08 11:02:05,426 [.PRPCWorkManager : 1] [  STANDARD] [     PegaRULES:07.10] (          internal.async.Agent) INFO    - System date: Tue Sep 08 11:02:05 HST 2015 Total memory: 5,368,709,120 Free memory: 265,692,624 Requestor Count: 16 Shared Pages memory usage: 0%

Get a bunch of these:

2015-09-08 11:06:00,865 [.PRPCWorkManager : 2] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: UnavailableShardsException[[work][0] [1] shardIt, [0] active : Timeout waiting for [1m], request: com.pega.elasticsearch.action.bulk.BulkShardRequest@4f504f50]
2015-09-08 11:06:00,865 [.PRPCWorkManager : 2] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: UnavailableShardsException[[work][0] [1] shardIt, [0] active : Timeout waiting for [1m], request: com.pega.elasticsearch.action.bulk.BulkShardRequest@4f504f50]
2015-09-08 11:06:00,865 [.PRPCWorkManager : 2] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: UnavailableShardsException[[work][0] [1] shardIt, [0] active : Timeout waiting for [1m], request: com.pega.elasticsearch.action.bulk.BulkShardRequest@4f504f50]
2015-09-08 11:06:00,865 [.PRPCWorkManager : 2] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: UnavailableShardsException[[work][0] [1] shardIt, [0] active : Timeout waiting for [1m], request: com.pega.elasticsearch.action.bulk.BulkShardRequest@4f504f50]
2015-09-08 11:06:00,865 [.PRPCWorkManager : 2] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: UnavailableShardsException[[work][0] [1] shardIt, [0] active : Timeout waiting for [1m], request: com.pega.elasticsearch.action.bulk.BulkShardRequest@4f504f50]
2015-09-08 11:06:00,865 [.PRPCWorkManager : 2] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) WARN   hm05603 - Failed to index entry in batch: UnavailableShardsException[[work][0] [1] shardIt, [0] active : Timeout waiting for [1m], request: com.pega.elasticsearch.action.bulk.BulkShardRequest@4f504f50]

2015-09-08 11:12:06,742 [.PRPCWorkManager : 1] [  STANDARD] [     PegaRULES:07.10] (          internal.async.Agent) INFO    - System date: Tue Sep 08 11:12:06 HST 2015 Total memory: 5,368,709,120 Free memory: 160,837,544 Requestor Count: 15 Shared Pages memory usage: 0%

2015-09-08 11:12:35,305 [.PRPCWorkManager : 3] [  STANDARD] [ CRMService:01.03.01] (   internal.es.AbstractIndexer) ERROR  hm05603 - Unhandled exception: Java heap space
java.lang.OutOfMemoryError
:
Java heap space
at

Also start getting many of the below popup when on the Search landing page while reindexing appears to be in progress:

ReindexNetworkError.png

Low-Code App Development Upgrades System Administration User Interface
Moderation Team has archived post
Share this page LinkedIn