Examples with RequestId com.google.gerrit.server.logging.RequestId used on opensource projects

Example 1 with RequestId

use of com.google.gerrit.server.logging.RequestId in project gerrit by GerritCodeReview.

the class ReceiveCommits method processCommands.

ReceiveCommitsResult processCommands(Collection<ReceiveCommand> commands, MultiProgressMonitor progress) throws StorageException {
    checkState(!used, "Tried to re-use a ReceiveCommits objects that is single-use only");
    long start = TimeUtil.nowNanos();
    parsePushOptions();
    String clientProvidedDeadlineValue = Iterables.getLast(pushOptions.get("deadline"), /* defaultValue= */
    null);
    int commandCount = commands.size();
    try (TraceContext traceContext = TraceContext.newTrace(tracePushOption.isPresent(), tracePushOption.orElse(null), (tagName, traceId) -> addMessage(tagName + ": " + traceId));
        PerformanceLogContext performanceLogContext = new PerformanceLogContext(config, performanceLoggers);
        TraceTimer traceTimer = newTimer("processCommands", Metadata.builder().resourceCount(commandCount))) {
        RequestInfo requestInfo = RequestInfo.builder(RequestInfo.RequestType.GIT_RECEIVE, user, traceContext).project(project.getNameKey()).build();
        requestListeners.runEach(l -> l.onRequest(requestInfo));
        traceContext.addTag(RequestId.Type.RECEIVE_ID, new RequestId(project.getNameKey().get()));
        // Log the push options here, rather than in parsePushOptions(), so that they are included
        // into the trace if tracing is enabled.
        logger.atFine().log("push options: %s", receivePack.getPushOptions());
        Task commandProgress = progress.beginSubTask("refs", UNKNOWN);
        commands = commands.stream().map(c -> wrapReceiveCommand(c, commandProgress)).collect(toList());
        try (RequestStateContext requestStateContext = RequestStateContext.open().addRequestStateProvider(progress).addRequestStateProvider(deadlineCheckerFactory.create(start, requestInfo, clientProvidedDeadlineValue))) {
            processCommandsUnsafe(commands, progress);
            rejectRemaining(commands, INTERNAL_SERVER_ERROR);
        } catch (InvalidDeadlineException e) {
            rejectRemaining(commands, e.getMessage());
        } catch (RuntimeException e) {
            Optional<RequestCancelledException> requestCancelledException = RequestCancelledException.getFromCausalChain(e);
            if (!requestCancelledException.isPresent()) {
                Throwables.throwIfUnchecked(e);
            }
            cancellationMetrics.countCancelledRequest(requestInfo, requestCancelledException.get().getCancellationReason());
            StringBuilder msg = new StringBuilder(requestCancelledException.get().formatCancellationReason());
            if (requestCancelledException.get().getCancellationMessage().isPresent()) {
                msg.append(String.format(" (%s)", requestCancelledException.get().getCancellationMessage().get()));
            }
            rejectRemaining(commands, msg.toString());
        }
        // This sends error messages before the 'done' string of the progress monitor is sent.
        // Currently, the test framework relies on this ordering to understand if pushes completed
        // successfully.
        sendErrorMessages();
        commandProgress.end();
        loggingTags = traceContext.getTags();
        logger.atFine().log("Processing commands done.");
    }
    progress.end();
    return result.build();
}

Example 2 with RequestId

use of com.google.gerrit.server.logging.RequestId in project gerrit by GerritCodeReview.

the class MergeOp method merge.

/**
 * Merges the given change.
 *
 * <p>Depending on the server configuration, more changes may be affected, e.g. by submission of a
 * topic or via superproject subscriptions. All affected changes are integrated using the projects
 * integration strategy.
 *
 * @param change the change to be merged.
 * @param caller the identity of the caller
 * @param checkSubmitRules whether the prolog submit rules should be evaluated
 * @param submitInput parameters regarding the merge
 * @throws RestApiException if an error occurred.
 * @throws PermissionBackendException if permissions can't be checked
 * @throws IOException an error occurred reading from NoteDb.
 * @return the merged change
 */
public Change merge(Change change, IdentifiedUser caller, boolean checkSubmitRules, SubmitInput submitInput, boolean dryrun) throws RestApiException, UpdateException, IOException, ConfigInvalidException, PermissionBackendException {
    this.submitInput = submitInput;
    this.notify = notifyResolver.resolve(firstNonNull(submitInput.notify, NotifyHandling.ALL), submitInput.notifyDetails);
    this.dryrun = dryrun;
    this.caller = caller;
    this.ts = TimeUtil.now();
    this.submissionId = new SubmissionId(change);
    try (TraceContext traceContext = TraceContext.open().addTag(RequestId.Type.SUBMISSION_ID, new RequestId(submissionId.toString()))) {
        openRepoManager();
        logger.atFine().log("Beginning integration of %s", change);
        try {
            ChangeSet indexBackedChangeSet = mergeSuperSet.setMergeOpRepoManager(orm).completeChangeSet(change, caller, /* includingTopicClosure= */
            false);
            if (!indexBackedChangeSet.ids().contains(change.getId())) {
                // indexBackedChangeSet contains only open changes, if the change is missing in this set
                // it might be that the change was concurrently submitted in the meantime.
                change = changeDataFactory.create(change).reloadChange();
                if (!change.isNew()) {
                    throw new ResourceConflictException("change is " + ChangeUtil.status(change));
                }
                throw new IllegalStateException(String.format("change %s missing from %s", change.getId(), indexBackedChangeSet));
            }
            if (indexBackedChangeSet.furtherHiddenChanges()) {
                throw new AuthException("A change to be submitted with " + change.getId() + " is not visible");
            }
            logger.atFine().log("Calculated to merge %s", indexBackedChangeSet);
            // Reload ChangeSet so that we don't rely on (potentially) stale index data for merging
            ChangeSet noteDbChangeSet = reloadChanges(indexBackedChangeSet);
            // At this point, any change that isn't new can be filtered out since they were only here
            // in the first place due to stale index.
            List<ChangeData> filteredChanges = new ArrayList<>();
            for (ChangeData changeData : noteDbChangeSet.changes()) {
                if (!changeData.change().getStatus().equals(Status.NEW)) {
                    logger.atFine().log("Change %s has status %s due to stale index, so it is skipped during submit", changeData.getId(), changeData.change().getStatus().name());
                    continue;
                }
                filteredChanges.add(changeData);
            }
            // There are no hidden changes (or else we would have thrown AuthException above).
            ChangeSet filteredNoteDbChangeSet = new ChangeSet(filteredChanges, /* hiddenChanges= */
            ImmutableList.of());
            // Count cross-project submissions outside of the retry loop. The chance of a single project
            // failing increases with the number of projects, so the failure count would be inflated if
            // this metric were incremented inside of integrateIntoHistory.
            int projects = filteredNoteDbChangeSet.projects().size();
            if (projects > 1) {
                topicMetrics.topicSubmissions.increment();
            }
            SubmissionExecutor submissionExecutor = new SubmissionExecutor(dryrun, superprojectUpdateSubmissionListeners);
            RetryTracker retryTracker = new RetryTracker();
            retryHelper.changeUpdate("integrateIntoHistory", updateFactory -> {
                long attempt = retryTracker.lastAttemptNumber + 1;
                boolean isRetry = attempt > 1;
                if (isRetry) {
                    logger.atFine().log("Retrying, attempt #%d; skipping merged changes", attempt);
                    this.ts = TimeUtil.now();
                    openRepoManager();
                }
                this.commitStatus = new CommitStatus(filteredNoteDbChangeSet, isRetry);
                if (checkSubmitRules) {
                    logger.atFine().log("Checking submit rules and state");
                    checkSubmitRulesAndState(filteredNoteDbChangeSet, isRetry);
                } else {
                    logger.atFine().log("Bypassing submit rules");
                    bypassSubmitRulesAndRequirements(filteredNoteDbChangeSet);
                }
                integrateIntoHistory(filteredNoteDbChangeSet, submissionExecutor);
                return null;
            }).listener(retryTracker).defaultTimeoutMultiplier(filteredNoteDbChangeSet.projects().size() * 2).retryOn(t -> t instanceof RuntimeException).call();
            submissionExecutor.afterExecutions(orm);
            if (projects > 1) {
                topicMetrics.topicSubmissionsCompleted.increment();
            }
            // (e.g. caller provided a change that was already merged).
            return updatedChanges.containsKey(change.getId()) ? updatedChanges.get(change.getId()) : change;
        } catch (IOException e) {
            // Anything before the merge attempt is an error
            throw new StorageException(e);
        }
    }
}

Example 3 with RequestId

use of com.google.gerrit.server.logging.RequestId in project gerrit by GerritCodeReview.

the class RetryHelper method execute.

/**
 * Executes an action and records the number of attempts and the timeout as metrics.
 *
 * @param actionType the type of the action
 * @param action the action which should be executed and retried on failure
 * @param opts options for retrying the action on failure
 * @param exceptionPredicate predicate to control on which exception the action should be retried
 * @return the result of executing the action
 * @throws Exception any error or exception that made the action fail, callers are expected to
 *     catch and inspect this Throwable to decide carefully whether it should be re-thrown
 */
<T> T execute(String actionType, Action<T> action, Options opts, Predicate<Throwable> exceptionPredicate) throws Exception {
    MetricListener listener = new MetricListener();
    try (TraceContext traceContext = TraceContext.open()) {
        RetryerBuilder<T> retryerBuilder = createRetryerBuilder(actionType, opts, t -> {
            // retried (e.g. LockFailure). The retry has good chances to succeed.
            if (exceptionPredicate.test(t)) {
                return true;
            }
            String actionName = opts.actionName().orElse("N/A");
            // Exception hooks may identify additional exceptions for retry.
            if (exceptionHooks.stream().anyMatch(h -> h.shouldRetry(actionType, actionName, t))) {
                return true;
            }
            // of the failure. If a trace was already done there is no need to retry.
            if (retryWithTraceOnFailure && opts.retryWithTrace().isPresent() && opts.retryWithTrace().get().test(t)) {
                // skipped.
                if (exceptionHooks.stream().anyMatch(h -> h.skipRetryWithTrace(actionType, actionName, t))) {
                    return false;
                }
                String cause = formatCause(t);
                if (!TraceContext.isTracing()) {
                    String traceId = "retry-on-failure-" + new RequestId();
                    traceContext.addTag(RequestId.Type.TRACE_ID, traceId).forceLogging();
                    logger.atWarning().withCause(t).log("AutoRetry: %s failed, retry with tracing enabled (cause = %s)", actionName, cause);
                    opts.onAutoTrace().ifPresent(c -> c.accept(traceId));
                    metrics.autoRetryCount.increment(actionType, actionName, cause);
                    return true;
                }
                // A non-recoverable failure occurred. We retried the operation with tracing
                // enabled and it failed again. Log the failure so that admin can see if it
                // differs from the failure that triggered the retry.
                logger.atWarning().withCause(t).log("AutoRetry: auto-retry of %s has failed (cause = %s)", actionName, cause);
                metrics.failuresOnAutoRetryCount.increment(actionType, actionName, cause);
                return false;
            }
            return false;
        });
        retryerBuilder.withRetryListener(listener);
        return executeWithTimeoutCount(actionType, action, opts, retryerBuilder.build(), listener);
    } finally {
        if (listener.getAttemptCount() > 1) {
            logger.atWarning().log("%s was attempted %d times", actionType, listener.getAttemptCount());
            metrics.attemptCounts.incrementBy(actionType, opts.actionName().orElse("N/A"), listener.getOriginalCause().map(this::formatCause).orElse("_unknown"), listener.getAttemptCount() - 1);
        }
    }
}