Skip to main content

This content is closed to future replies and is no longer being maintained or updated.
Links may no longer function. If you have a similar request, please write a new post.

Question

 Gerald Sasaoka (GERALDHMSA) HMSA
HMSA
US
GERALDHMSA Member since 2013 15 posts
HMSA
Posted: Sep 8, 2015
Last activity: Sep 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 [email protected] reindexing completes without exceptions.

What makes the [email protected] 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

Show More

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 [email protected] reindexing completes without exceptions.

What makes the [email protected] 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| Proprietary information hidden%12  - Proprietary information hidden%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| Proprietary information hidden%12  - Proprietary information hidden%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| Proprietary information hidden%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| Proprietary information hidden%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| Proprietary information hidden%12  - Proprietary information hidden%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| Proprietary information hidden%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| Proprietary information hidden%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| Proprietary information hidden%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| Proprietary information hidden%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| Proprietary information hidden%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| Proprietary information hidden%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


Show Less
To see attachments, please log in.
Updates System Administration User Experience

Posted: 9 years ago
Posted: 9 Sep 2015 2:45 EDT
Rajiv Nistala (nistr) Senior Manager - Engineering
Pegasystems
IN

Some more details are required to understand this issue. Kindly share the following

1) Number of nodes in this cluster

2) Dump of the pr_sys_statusnodes table

3) Are you doing anything else apart from re-index on the search landing page?

4) How much time did it take when "[email protected]" operator performed indexing?

5) Does the error come immediately or after some indexing has happened?

6) Does it happen only at a particular time of the day?

7) Full logs are needed to understand the details

8) Is this always reproducible?

9) Please enable debug logging on the class com.pega.pegarules.search.internal.es.AbstractIndexer and start re-indexing and share the logs once reproducible

10) Please share the requestor ID of the session, which initiated indexing, as seen on the clipboard (pxRequestor.pzRequestorId)

11) Please share the node name and ID from where indexing was initiated (pxProcess.pxSystemNode and pxProcess.pxSystemNodeID)

To see attachments, please log in.

We'd prefer it if you saw us at our best.

Pega Collaboration Center has detected you are using a browser which may prevent you from experiencing the site as intended. To improve your experience, please update your browser.

Close Deprecation Notice