Question

1
Replies
321
Views
Gerald Sasaoka (GERALDHMSA)
HMSA

HMSA
US
GERALDHMSA Member since 2013 15 posts
HMSA
Posted: September 8, 2015
Last activity: September 9, 2015
Posted: 8 Sep 2015 20:00 EDT
Last activity: 9 Sep 2015 2:45 EDT
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

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

System Administration Upgrades User Experience
Moderation Team has archived post, This thread is closed to future replies. Content and links will no longer be updated. If you have the same/similar Question, please write a new Question.