[GOBBLIN-1930] Improve Multi-active related logs and metrics

[umustafi]

Dear Gobblin maintainers,

Please accept this PR. I understand that it will not be reviewed until I have checked off all the steps below!

JIRA

• My PR addresses the following Gobblin JIRA issues and references them in the PR title. For example, "[GOBBLIN-XXX] My Gobblin PR"
  • https://issues.apache.org/jira/browse/GOBBLIN-1930

Description

• Here are some details about my PR, including screenshots (if applicable):
  Improve logging and metrics around multi-active launch flow event handling to identify any missing events between the MysqlMultiActiveLeaseArbiter committing the launch event to the dagActionStore and the DagActionMonitor receiving events for processing. We want to be able to distinguish between the following cases of 

• events that are never received by the DagActionMonitor

• events incorrectly filtered out by the DagActionMonitor

• any failed submissions of dags to the DagManager either upon leader change or from the DagActionChangeMonitor

Tests

• My PR adds the following unit tests OR does not need testing for this extremely good reason:

Commits

• My commits all reference JIRA issues in their subject lines, and I have squashed multiple commits if they address the same issue. In addition, my commits follow the guidelines from "How to write a good git commit message":
  1. Subject is separated from body by a blank line
  2. Subject is limited to 50 characters
  3. Subject does not end with a period
  4. Subject uses the imperative mood ("add", not "adding")
  5. Body wraps at 72 characters
  6. Body explains "what" and "why", not "how"

[phet]

nice work--I HIGHLY support this finer-grained logging

[phet]

nit: this is no longer a prefix... but why anyway do you prefer to repeat so many times SMNames.GOBBLIN_SERVICE_PREFIX + "."?

[umustafi]

Ah good pt, updated to have the prefix contain SMNames.GOBBLIN_SERVICE_PREFIX + "." instead

[phet]

I guess there's the possibility I may be misremembering... and pursuing this needlessly... but my expectation is that a stacktrace would only be written when calling this form:

Logger::warn(String, Throwable)

if you call the form:

Logger::warn(String, Object, Object) // aka. Logger::warn(String, Object...)

are you certain it will print the ST, when the last arg is Throwable and there's no corresponding {} remaining for it in the initial String arg?

[umustafi]

There are two {} and the last one is for the throwable so it will print the getMessage. I updated all the methods to use Logger::warn(String, Throwable) thought to get full stack trace.

[phet]

wondering... couldn't this be a dagManager. metric? dagManager.failedLaunchEventsOn...?

[umustafi]

I want to be clear that this is a failure that occurs related to handling all dagAction related code changes and easily find them when they may originate from dagActionStoreMonitor, dagManager, or other locations. We also don't use a dagManager prefix for other dagManager metrics for some reason

[phet]

nit: too conversational. how about:

log.info("DagAction change ({}): {}", operation, dagAction)

(i.e. won't the resume/kill/launch be logged as dagAction.dagActionType)?

[umustafi]

I was thinking about unifying all the logs like this as well, let me make the change. I will add a bit more context in message but use this format.

[phet]

overall, this is minor... not wanting to press too hard here.

just observing that DagManagerHandling, not being an actual class name, seems a synonym for DagMgrWorking, DagMgrInAction, DagMgrDoingStuff, which is to say it's vague. even more, DM "doing stuff" is implied simply by the prefix DagMgr.

so if there is something you want to differentiate here, that's fine... but do make sure what that is is clearly stated, so a future maintainer knows whether the metric they wish to add belongs under DagMgr or your new prefix.

[umustafi]

Yes, I see what you're saying. I can't find a better way to differntiate this sub-class of dagManager code issues so I'll leave it as dagManager to avoid any confusion.

[phet]

looks great!

[Will-Lo]

Can we also add changes to make the flow execution ID based off the even timestamp so that flows can be tracked from scheduling -> completion? It becomes very hard to debug as we will need to create an additional logical mapping of intended executions to running flow executions

[codecov-commenter]

Codecov Report

Merging #3800 (afaedbe) into master (9b254b6) will decrease coverage by 0.03%.
The diff coverage is 34.54%.

@@             Coverage Diff              @@
##             master    #3800      +/-   ##
============================================
- Coverage     47.37%   47.35%   -0.03%     
- Complexity    10973    10975       +2     
============================================
  Files          2152     2152              
  Lines         85154    85176      +22     
  Branches       9470     9472       +2     
============================================
- Hits          40341    40333       -8     
- Misses        41155    41187      +32     
+ Partials       3658     3656       -2     

Files	Coverage Δ
...org/apache/gobblin/metrics/ServiceMetricNames.java	0.00% <ø> (ø)
...org/apache/gobblin/runtime/api/DagActionStore.java	86.66% <100.00%> (+2.05%)	⬆️
...e/gobblin/runtime/api/MultiActiveLeaseArbiter.java	70.00% <100.00%> (ø)
...apache/gobblin/runtime/metrics/RuntimeMetrics.java	0.00% <ø> (ø)
...rvice/modules/orchestration/DagManagerMetrics.java	78.57% <40.00%> (-1.81%)	⬇️
...vice/modules/orchestration/FlowTriggerHandler.java	21.90% <0.00%> (-0.22%)	⬇️
...blin/runtime/api/MysqlMultiActiveLeaseArbiter.java	75.29% <64.70%> (+0.09%)	⬆️
...in/service/modules/orchestration/Orchestrator.java	49.47% <14.28%> (-1.07%)	⬇️
...blin/service/modules/orchestration/DagManager.java	78.99% <10.00%> (-0.46%)	⬇️
...ervice/monitoring/DagActionStoreChangeMonitor.java	0.00% <0.00%> (ø)

... and 5 files with indirect coverage changes

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

[phet]

seems confusing that LeaseObtainedStatus.getFlowAction().getFlowExecutionId() returns a different value than what we're storing in the DagAction.getFlowExecutionId(). e.g. why not unify them by encapsulating the switcheroo to LeaseObtainedStatus.getEventTimestamp() inside the LeaseObtainedStatus.getFlowAction() call?

then, in that location I suggest a code comment explaining why it's helpful and safe to replace the original value w/ this one.

[phet]

each of the flowExecId updates uses the timestamp value that is also passed as the second arg to the LeasedToAnotherStatus or LeaseObtainedStatus ctor. seems potentially unnecessary for that object still to maintain both--do we want it to?

e.g. it could always implement:

long getEventTimestamp() {
  return this.dagAction.getFlowExecutionId();
}

[umustafi]

Fixed

[Will-Lo]

Do we still need this if we are using the event timetime millisecond, which should be synchronized across all hosts?

[umustafi]

Yes we do, the timestamp within leaseObtainedStatus is the agreed upon time that is synchronized across all hosts while the following param, eventTimeMillis (later called) triggerEventTimeMillis is local to the host and is only used for logging purposes to show us that we switch from local trigger to the synchronized trigger. Here we are just changing where it's being stored not the fact that we do update it.

[phet]

this would better belong as a method of the DagAction class defined on line 39

[umustafi]

this is included as a method of the class, it's static because it returns a new dagAction obj

[phet]

somewhat confusing, "which may be a different timestamp for the same..." - reword?

[umustafi]

tried to reword lmk what u think