Skip to content

[SPARK-47602][CORE][K8S][FOLLOWUP] Improve structure logging for isExecutorIdleTimedOut #45849

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
pan3793 wants to merge 1 commit into from
Closed

[SPARK-47602][CORE][K8S][FOLLOWUP] Improve structure logging for isExecutorIdleTimedOut #45849

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion common/utils/src/main/scala/org/apache/spark/internal/LogKey.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,8 @@ object LogKey extends Enumeration {
val MAX_SIZE = Value
val MIN_SIZE = Value
val REMOTE_ADDRESS = Value
val POD_ID = Value
val KUBERNETES_NAMESPACE = Value
val KUBERNETES_POD_NAME = Value
Copy link
Member Author

@pan3793 pan3793 Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

some thoughts for the KUBERNETES_ prefix, POD_ID should be identical but NAMESPACE does not.

for CONTAINER_ID, maybe we should change it to YARN_CONTAINER_ID too

Copy link
Contributor

@panbingkun panbingkun Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

KUBERNETES -> K8S ？

Copy link
Member

@gengliangwang gengliangwang Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point. I mentioned this in #45862

Copy link
Member Author

@pan3793 pan3793 Apr 6, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

thanks for providing a Guideline


type LogKey = Value
}
21 changes: 12 additions & 9 deletions common/utils/src/main/scala/org/apache/spark/internal/Logging.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -97,20 +97,23 @@ trait Logging {
}

implicit class LogStringContext(val sc: StringContext) {
def log(args: MDC*): MessageWithContext = {
def log(args: Any*): MessageWithContext = {
Copy link
Member Author

@pan3793 pan3793 Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@gengliangwang I'm not sure if there were discussions on the following case:

logInfo(log"MDC(LogKey.ABC, some_string) ${an_object} something")

Copy link
Contributor

@panbingkun panbingkun Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In fact, the above case has already been discussed
#45813

Copy link
Member Author

@pan3793 pan3793 Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, great, let hold on this one for a while

Copy link
Member

@gengliangwang gengliangwang Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah let's make every variable MDC for now. We can decide which context keys to show in the context by default once we got all the log keys.

Copy link
Member

@gengliangwang gengliangwang Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changing a log4j configuration will be much easier than debating in logging entries of the code base.

Copy link
Member Author

@pan3793 pan3793 Apr 6, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

let's make every variable MDC for now

if so, this might not be a good case for the 1st round migration, IMO it's critical to inject a string variable(a large JSON-like pod spec) to the error message

Copy link
Member

@gengliangwang gengliangwang Apr 6, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@pan3793 ok, we can skip this one

val processedParts = sc.parts.iterator
val sb = new StringBuilder(processedParts.next())
val context = new java.util.HashMap[String, String]()

args.foreach { mdc =>
sb.append(mdc.value.toString)
if (Logging.isStructuredLoggingEnabled) {
context.put(mdc.key.toString.toLowerCase(Locale.ROOT), mdc.value.toString)
}
args.foreach {
case mdc: MDC =>
sb.append(mdc.value.toString)
if (Logging.isStructuredLoggingEnabled) {
context.put(mdc.key.toString.toLowerCase(Locale.ROOT), mdc.value.toString)
}

if (processedParts.hasNext) {
sb.append(processedParts.next())
}
if (processedParts.hasNext) {
sb.append(processedParts.next())
}
case any: Any =>
sb.append(any)
}

MessageWithContext(sb.toString(), context)
Expand Down
6 changes: 4 additions & 2 deletions ...es/core/src/main/scala/org/apache/spark/scheduler/cluster/k8s/ExecutorPodsAllocator.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -533,8 +533,10 @@ class ExecutorPodsAllocator(
currentTime - creationTime > executorIdleTimeout
} catch {
case e: Exception =>
logError(log"Cannot get the creationTimestamp of the pod: " +
log"${MDC(LogKey.POD_ID, state.pod)}", e)
logError(log"Cannot get the creationTimestamp of the pod " +
log"${MDC(LogKey.KUBERNETES_POD_NAME, state.pod.getMetadata.getName)} in namespace " +
log"${MDC(LogKey.KUBERNETES_NAMESPACE, state.pod.getMetadata.getNamespace)}. " +
log"Resource details: ${state.pod}", e)
Copy link
Contributor

@panbingkun panbingkun Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will state.pod include state.pod.getMetadata?

Copy link
Member Author

@pan3793 pan3793 Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes, state.pod will output a large JSON-like string, it is not suitable for LogKey

Copy link
Contributor

@panbingkun panbingkun Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pod

public String toString() {
    return "Pod(apiVersion=" + this.getApiVersion() + ", kind=" + this.getKind() + ", metadata=" + this.getMetadata() + ", spec=" + this.getSpec() + ", status=" + this.getStatus() + ", additionalProperties=" + this.getAdditionalProperties() + ")";
  }

ObjectMeta

public String toString() {
    return "ObjectMeta(annotations=" + this.getAnnotations() + ", creationTimestamp=" + this.getCreationTimestamp() + ", deletionGracePeriodSeconds=" + this.getDeletionGracePeriodSeconds() + ", deletionTimestamp=" + this.getDeletionTimestamp() + ", finalizers=" + this.getFinalizers() + ", generateName=" + this.getGenerateName() + ", generation=" + this.getGeneration() + ", labels=" + this.getLabels() + ", managedFields=" + this.getManagedFields() + ", name=" + this.getName() + ", namespace=" + this.getNamespace() + ", ownerReferences=" + this.getOwnerReferences() + ", resourceVersion=" + this.getResourceVersion() + ", selfLink=" + this.getSelfLink() + ", uid=" + this.getUid() + ", additionalProperties=" + this.getAdditionalProperties() + ")";
  }

Copy link
Contributor

@panbingkun panbingkun Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@gengliangwang
I'm not sure if the current modification violates the original intention of the log, perhaps we just need a simple POD_ID -> POD

Copy link
Member

@gengliangwang gengliangwang Apr 3, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes a simple POD_ID -> POD sounds good. Having the extra POD name nad namespace in the log for quick search is also fine.

Copy link
Member Author

@pan3793 pan3793 Apr 6, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I read the K8s docs and found there is a UID concept, but TBH, it's rare to use it ...

Each object in your cluster has a Name that is unique for that type of resource. Every Kubernetes object also has a UID that is unique across your whole cluster.

https://kubernetes.io/docs/concepts/overview/working-with-objects/names/

the most common cases to identify a pod are

kubectl get pod <pod-name> --namespace <namespace>
kubectl describe pod <pod-name> --namespace <namespace>

true
}
}
Expand Down