in framework/service/src/main/java/org/apache/ofbiz/service/ServiceDispatcher.java [272:658]
public Map<String, Object> runSync(String localName, ModelService modelService, Map<String, ? extends Object> params, boolean validateOut)
throws ServiceAuthException, ServiceValidationException, GenericServiceException {
long serviceStartTime = System.currentTimeMillis();
Map<String, Object> result = new HashMap<>();
ServiceSemaphore lock = null;
Map<String, List<ServiceEcaRule>> eventMap = null;
Map<String, Object> ecaContext = null;
RunningService rs = null;
DispatchContext ctx = localContext.get(localName);
GenericEngine engine = null;
Transaction parentTransaction = null;
boolean isFailure = false;
boolean isError = false;
boolean beganTrans = false;
try {
// check for semaphore and acquire a lock
if ("wait".equals(modelService.getSemaphore()) || "fail".equals(modelService.getSemaphore())) {
lock = new ServiceSemaphore(delegator, modelService);
lock.acquire();
}
if (Debug.verboseOn() || modelService.isDebug()) {
if (Debug.verboseOn()) {
Debug.logVerbose("[ServiceDispatcher.runSync] : invoking service " + modelService.getName() + " [" + modelService.getLocation()
+ "/" + modelService.getInvoke() + "] (" + modelService.getEngineName() + ")", MODULE);
}
}
Map<String, Object> context = new HashMap<>();
if (params != null) {
context.putAll(params);
}
// check the locale
Locale locale = checkLocale(context);
// set up the running service log
rs = this.logService(localName, modelService, GenericEngine.SYNC_MODE);
// get eventMap once for all calls for speed, don't do event calls if it is null
eventMap = ServiceEcaUtil.getServiceEventMap(modelService.getName());
engine = this.getGenericEngine(modelService.getEngineName());
modelService.informIfDeprecated();
// set IN attributes with default-value as applicable
modelService.updateDefaultValues(context, ModelService.IN_PARAM);
if (modelService.isUseTransaction()) {
if (TransactionUtil.isTransactionInPlace()) {
// if a new transaction is needed, do it here; if not do nothing, just use current tx
if (modelService.isRequireNewTransaction()) {
parentTransaction = TransactionUtil.suspend();
if (TransactionUtil.isTransactionInPlace()) {
rs.setEndStamp();
throw new GenericTransactionException("In service " + modelService.getName()
+ " transaction is still in place after suspend, status is " + TransactionUtil.getStatusString());
}
// now start a new transaction
beganTrans = TransactionUtil.begin(modelService.getTransactionTimeout());
}
} else {
beganTrans = TransactionUtil.begin(modelService.getTransactionTimeout());
}
// enlist for XAResource debugging
if (beganTrans && TransactionUtil.debugResources()) {
DebugXaResource dxa = new DebugXaResource(modelService.getName());
try {
dxa.enlist();
} catch (Exception e) {
Debug.logError(e, MODULE);
}
}
}
try {
int lockRetriesRemaining = LOCK_RETRIES;
boolean needsLockRetry = false;
do {
// Ensure this is reset to false on each pass
needsLockRetry = false;
lockRetriesRemaining--;
// NOTE: general pattern here is to do everything up to the main service call, and retry it all if
//needed because those will be part of the same transaction and have been rolled back
// TODO: if there is an ECA called async or in a new transaction it won't get rolled back
//but will be called again, which means the service may complete multiple times! that would be for
//pre-invoke and earlier events only of course
// setup global transaction ECA listeners to execute later
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "global-rollback", ctx, context, result, isError, isFailure);
}
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "global-commit", ctx, context, result, isError, isFailure);
}
// pre-auth ECA
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "auth", ctx, context, result, isError, isFailure);
}
// check for pre-auth failure/errors
isFailure = ServiceUtil.isFailure(result);
isError = ServiceUtil.isError(result);
context = checkAuth(localName, context, modelService);
GenericValue userLogin = (GenericValue) context.get("userLogin");
if (modelService.isAuth() && userLogin == null && !modelService.getName().equals("SetTimeZoneFromBrowser")) {
rs.setEndStamp();
throw new ServiceAuthException("User authorization is required for this service: " + modelService.getName()
+ modelService.debugInfo());
}
// now that we have authed, if there is a userLogin, set the EE userIdentifier
if (userLogin != null && userLogin.getString("userLoginId") != null) {
GenericDelegator.pushUserIdentifier(userLogin.getString("userLoginId"));
}
// pre-validate ECA
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "in-validate", ctx, context, result, isError, isFailure);
}
// check for pre-validate failure/errors
isFailure = ServiceUtil.isFailure(result);
isError = ServiceUtil.isError(result);
// validate the context
if (modelService.isValidate() && !isError && !isFailure) {
try {
// FIXME without this line all simple test failed
context = ctx.makeValidContext(modelService.getName(), ModelService.IN_PARAM, context);
modelService.validate(getLocalDispatcher(localName), context, ModelService.IN_PARAM, locale);
} catch (ServiceValidationException e) {
Debug.logError(e, "Incoming context (in runSync : " + modelService.getName()
+ ") does not match expected requirements", MODULE);
rs.setEndStamp();
throw e;
}
}
// pre-invoke ECA
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "invoke", ctx, context, result, isError, isFailure);
}
// check for pre-invoke failure/errors
isFailure = ServiceUtil.isFailure(result);
isError = ServiceUtil.isError(result);
// ===== invoke the service =====
if (!isError && !isFailure) {
Map<String, Object> invokeResult = null;
invokeResult = engine.runSync(localName, modelService, context);
engine.sendCallbacks(modelService, context, invokeResult, GenericEngine.SYNC_MODE);
if (invokeResult != null) {
result.putAll(invokeResult);
} else {
Debug.logWarning("Service (in runSync : " + modelService.getName() + ") returns null result", MODULE);
}
}
// re-check the errors/failures
isFailure = ServiceUtil.isFailure(result);
isError = ServiceUtil.isError(result);
if (beganTrans) {
// crazy stuff here: see if there was a deadlock or other such error and if so retry...
// which we can ONLY do if we own the transaction!
String errMsg = ServiceUtil.getErrorMessage(result);
// look for the string DEADLOCK in an upper-cased error message; tested on: Derby, MySQL
// - Derby 10.2.2.0 deadlock string: "A lock could not be obtained due to a deadlock"
// - MySQL ? deadlock string: "Deadlock found when trying to get lock; try restarting transaction"
// - Postgres ? deadlock string: TODO
// - Other ? deadlock string: TODO
// TODO need testing in other databases because they all return different error messages for this!
// NOTE DEJ20070908 are there other things we need to check? I don't think so because these will
//be Entity Engine errors that will be caught and come back in an error message... IFF the
//service is written to not ignore it of course!
if (errMsg != null && errMsg.toUpperCase(Locale.getDefault()).indexOf("DEADLOCK") >= 0) {
// it's a deadlock! retry...
String retryMsg = "RETRYING SERVICE [" + modelService.getName() + "]: Deadlock error found in message [" + errMsg
+ "]; retry [" + (LOCK_RETRIES - lockRetriesRemaining) + "] of [" + LOCK_RETRIES + "]";
// make sure the old transaction is rolled back, and then start a new one
// if there is an exception in these things, let the big overall thing handle it
TransactionUtil.rollback(beganTrans, retryMsg, null);
beganTrans = TransactionUtil.begin(modelService.getTransactionTimeout());
// enlist for XAResource debugging
if (beganTrans && TransactionUtil.debugResources()) {
DebugXaResource dxa = new DebugXaResource(modelService.getName());
try {
dxa.enlist();
} catch (Exception e) {
Debug.logError(e, MODULE);
}
}
if (!beganTrans) {
// just log and let things roll through, will be considered an error and ECAs, etc will run according to that
Debug.logError("After rollback attempt for lock retry did not begin a new transaction!", MODULE);
} else {
// deadlocks can be resolved by retring immediately as conflicting operations in the other thread will have cleared
needsLockRetry = true;
// reset state variables
result = new HashMap<>();
isFailure = false;
isError = false;
Debug.logWarning(retryMsg, MODULE);
}
// look for lock wait timeout error, retry in a different way by running after the parent transaction finishes,
// ie attach to parent tx
// - Derby 10.2.2.0 lock wait timeout string: "A lock could not be obtained within the time requested"
// - MySQL ? lock wait timeout string: "Lock wait timeout exceeded; try restarting transaction"
//if (errMsg.indexOf("A lock could not be obtained within the time requested") >= 0
// || errMsg.indexOf("Lock wait timeout exceeded") >= 0) {
// TODO: add to run after parent tx
//}
}
}
} while (needsLockRetry && lockRetriesRemaining > 0);
// create a new context with the results to pass to ECA services; necessary because caller may reuse this context
ecaContext = new HashMap<>();
ecaContext.putAll(context);
// copy all results: don't worry parameters that aren't allowed won't be passed to the ECA services
ecaContext.putAll(result);
// setup default OUT values
modelService.updateDefaultValues(context, ModelService.OUT_PARAM);
// validate the result
if (modelService.isValidate() && validateOut) {
// pre-out-validate ECA
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "out-validate", ctx, ecaContext, result, isError, isFailure);
}
try {
result = ctx.makeValidContext(modelService.getName(), ModelService.OUT_PARAM, result);
modelService.validate(getLocalDispatcher(localName), result, ModelService.OUT_PARAM, locale);
} catch (ServiceValidationException e) {
rs.setEndStamp();
throw new GenericServiceException("Outgoing result (in runSync : " + modelService.getName()
+ ") does not match expected requirements", e);
}
}
// pre-commit ECA
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "commit", ctx, ecaContext, result, isError, isFailure);
}
// check for pre-commit failure/errors
isFailure = ServiceUtil.isFailure(result);
isError = ServiceUtil.isError(result);
// global-commit-post-run ECA, like global-commit but gets the context after the service is run
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "global-commit-post-run", ctx, ecaContext, result, isError, isFailure);
}
// check for failure and log on info level; this is used for debugging
if (isFailure) {
Debug.logWarning("Service Failure [" + modelService.getName() + "]: " + ServiceUtil.getErrorMessage(result), MODULE);
}
} catch (Throwable t) {
if (Debug.timingOn()) {
UtilTimer.closeTimer(localName + " / " + modelService.getName(), "Sync service failed...", MODULE);
}
String errMsg = "Service [" + modelService.getName() + "] threw an unexpected exception/error";
engine.sendCallbacks(modelService, context, t, GenericEngine.SYNC_MODE);
try {
TransactionUtil.rollback(beganTrans, errMsg, t);
} catch (GenericTransactionException te) {
Debug.logError(te, "Cannot rollback transaction", MODULE);
}
rs.setEndStamp();
if (t instanceof ServiceAuthException) {
throw (ServiceAuthException) t;
} else if (t instanceof ServiceValidationException) {
throw (ServiceValidationException) t;
} else if (t instanceof GenericServiceException) {
throw (GenericServiceException) t;
} else {
throw new GenericServiceException("Service [" + modelService.getName() + "] Failed" + modelService.debugInfo(), t);
}
} finally {
// if there was an error, rollback transaction, otherwise commit
if (isError) {
String errMsg = "Error in Service [" + modelService.getName() + "]: " + ServiceUtil.getErrorMessage(result);
Debug.logError(errMsg, MODULE);
// rollback the transaction
try {
TransactionUtil.rollback(beganTrans, errMsg, null);
} catch (GenericTransactionException e) {
Debug.logError(e, "Could not rollback transaction: " + e.toString(), MODULE);
}
} else {
// commit the transaction
try {
TransactionUtil.commit(beganTrans);
} catch (GenericTransactionException e) {
GenericDelegator.popUserIdentifier();
String errMsg = "Could not commit transaction for service [" + modelService.getName() + "] call";
Debug.logError(e, errMsg, MODULE);
if (e.getMessage() != null) {
errMsg = errMsg + ": " + e.getMessage();
}
rs.setEndStamp();
throw new GenericServiceException(errMsg);
}
}
// call notifications -- event is determined from the result (success, error, fail)
modelService.evalNotifications(this.getLocalContext(localName), context, result);
// clear out the EE userIdentifier
GenericDelegator.popUserIdentifier();
}
} catch (GenericTransactionException te) {
Debug.logError(te, "Problems with the transaction", MODULE);
rs.setEndStamp();
throw new GenericServiceException("Problems with the transaction.", te.getNested());
} finally {
if (lock != null) {
// release the semaphore lock
lock.release();
}
// resume the parent transaction
if (parentTransaction != null) {
try {
TransactionUtil.resume(parentTransaction);
} catch (GenericTransactionException ite) {
Debug.logWarning(ite, "Transaction error, not resumed", MODULE);
rs.setEndStamp();
throw new GenericServiceException("Resume transaction exception, see logs");
}
}
}
// pre-return ECA
if (eventMap != null) {
ServiceEcaUtil.evalRules(modelService.getName(), eventMap, "return", ctx, ecaContext, result, isError, isFailure);
}
rs.setEndStamp();
long timeToRun = System.currentTimeMillis() - serviceStartTime;
long showServiceDurationThreshold = UtilProperties.getPropertyAsLong("service", "showServiceDurationThreshold", 0);
long showSlowServiceThreshold = UtilProperties.getPropertyAsLong("service", "showSlowServiceThreshold", 1000);
if (Debug.timingOn() && timeToRun > showServiceDurationThreshold) {
Debug.logTiming("Sync service [" + localName + "/" + modelService.getName() + "] finished in [" + timeToRun + "] milliseconds", MODULE);
} else if (Debug.infoOn() && timeToRun > showSlowServiceThreshold) {
Debug.logTiming("Slow sync service execution detected: service [" + localName + "/" + modelService.getName() + "] finished in ["
+ timeToRun + "] milliseconds", MODULE);
}
if ((Debug.verboseOn() || modelService.isDebug()) && timeToRun > 50 && !modelService.isHideResultInLog()) {
// Sanity check - some service results can be multiple MB in size. Limit message size to 10K.
String resultStr = result.toString();
if (resultStr.length() > 10240) {
resultStr = resultStr.substring(0, 10226) + "...[truncated]";
}
if (Debug.verboseOn()) {
Debug.logVerbose("Sync service [" + localName + "/" + modelService.getName() + "] finished with response [" + resultStr
+ "]", MODULE);
}
}
if (modelService.getMetrics() != null) {
modelService.getMetrics().recordServiceRate(1, timeToRun);
}
return result;
}