Skip to content

TEZ-4039: Tez should inject dag id, query id into MDC - #98

Merged
abstractdog merged 6 commits into
apache:masterfrom
abstractdog:TEZ-4039
Oct 26, 2022
Merged

TEZ-4039: Tez should inject dag id, query id into MDC#98
abstractdog merged 6 commits into
apache:masterfrom
abstractdog:TEZ-4039

Conversation

@abstractdog

Copy link
Copy Markdown
Contributor

No description provided.

*/
@ConfigurationScope(Scope.AM)
@ConfigurationProperty
public static final String TEZ_LOG_PATTERN_LAYOUT_AM = TEZ_PREFIX + "log.pattern.layout.am";

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Use TEZ_AM_PREFIX instead?

*/
@ConfigurationScope(Scope.AM)
@ConfigurationProperty
public static final String TEZ_LOG_PATTERN_LAYOUT_TASK = TEZ_PREFIX + "log.pattern.layout.task";

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Use TEZ_TASK_PREFIX instead?

* By this option, user can easily override the logging pattern which is applied in
* TezContainerLogAppender in tasks, regardless of the environmental settings.
*/
@ConfigurationScope(Scope.AM)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Scope should be Vertex since this task specific config

public static final String TEZ_MDC_CUSTOM_KEYS_DEFAULT = "";

/**
* Comma separated list of keys, which can used for defining keys in Configuration. Tez will try

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

nit: list of values?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

no, these are still keys, but keys in Configuration

tez.mdc.custom.keys=queryId
tez.mdc.custom.keys.values.from=hive.query.id <- here we are

I'm trying to clarify this in javadoc

public static final String TEZ_MDC_CUSTOM_KEYS_DEFAULT = "";

/**
* Comma separated list of keys, which can used for defining keys in Configuration. Tez will try

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

nit: list of values?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

(same comment as above)


/**
* NonClonableHashtable is a special class for hacking the log4j MDC context. By design, log4j's
* MDC uses a ThreadLocalMap, which clones parent thread's context before propagating it to child

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Isn't this configurable via isThreadContextMapInheritable system property?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

unfortunately, isThreadContextMapInheritable is slightly different from what I needed:

Set the system property `log4j2.isThreadContextMapInheritable` to `true` to enable child threads to inherit the Thread Context Map.

this is used for inheritance, which is needed, child thread inherits parent's context, this is fine, the problem is that it inherits and clones the map, which is against my implementation...
my implementation makes it possible to define a global MDC context in DAGAppMaster and TezChild in the main thread, and all threads inherit that, but when a new dag (DAGAppMaster) or task attempt (TezChild) comes, modifying the global thread's context should have an effect on all threads' context, but with cloning, it won't have:
https://github.com/apache/log4j/blob/trunk/src/main/java/org/apache/log4j/helpers/ThreadLocalMap.java#L34-L41

instead, I choose to define 1 context in the main thread and propagating it to all child threads (which is automatic due to ThreadLocalMap behavior by default), but I only need to init the logging context once for every dag/taskattempt. Without cloning, a single change will change the MDC contents of all threads in the JVM.

@abstractdog

Copy link
Copy Markdown
ContributorAuthor

thanks for the review @prasanthj, I tried to address everything you mentioned

@tez-yetus

This comment was marked as outdated.

@tez-yetus

This comment was marked as outdated.

@tez-yetus

This comment was marked as outdated.

@tez-yetus

This comment was marked as outdated.

@tez-yetus

This comment was marked as outdated.

*/
@ConfigurationScope(Scope.VERTEX)
@ConfigurationProperty
public static final String TEZ_LOG_PATTERN_LAYOUT_TASK = TEZ_TASK_PREFIX + "log.pattern.layout";

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Is there any default value for this? (e.g If the user wants to reset it back to old value)

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

good catch, user should be able to turn this off by setting it to an empty string, I'm reflecting this in the configuration

patternConfig.set(TezConfiguration.TEZ_TASK_LOG_LEVEL, "debug");
patternConfig.set(TezConfiguration.TEZ_LOG_PATTERN_LAYOUT_AM,
"%d{ISO8601} [%p] [%t (queryId=%X{queryId} dag=%X{dagId})] |%c{2}|: %m%n");
patternConfig.set(TezConfiguration.TEZ_LOG_PATTERN_LAYOUT_TASK,

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Can you check for the case when the value can be reset back to original value? Plz refer to my comment earlier in TezConfiguration.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

yeah, added testcase

mdcContext.set(new NonClonableHashtable<String, String>());

try {
final Constructor<?>[] constructors = org.apache.log4j.MDC.class.getDeclaredConstructors();

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

log4j or slf4j?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

log4j, intentionally, the whole hack implemented in this method is log4j specific

// don't want to fail on incorrect mdc key settings, but warn in app logs
if (mdcKey.isEmpty() || mdcKeysValuesFrom.length < i + 1) {
LOG.warn("cannot set mdc key: {}", mdcKey);
break;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Did you mean break or continue here?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

if we hit this it means that mdcKey is most probably empty, so we had:

tez.mdc.custom.keys=

as it's very unlikely that the user set something like this:

tez.mdc.custom.keys=,something_which_matters

if we split string by commas and find empty string, it makes no sense to loop further, or at least I cannot figure out a valid use-case

@rbalamohanrbalamohan left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Left minor comments.

@abstractdog

abstractdog commented Oct 24, 2022

Copy link
Copy Markdown
ContributorAuthor

Left minor comments.

thanks a lot, fixed in https://github.com/apache/tez/pull/98/commits/01adba3cfca7bbd27d6bbacbbd9bb3041d03ab3cplease let me know if you're fine with them (and my comments)

@tez-yetus

This comment was marked as outdated.

@tez-yetus

Copy link
Copy Markdown

🎊 +1 overall

VoteSubsystemRuntimeComment
+0 🆗reexec36m 3sDocker mode activated.
_ Prechecks _
+1 💚dupname0m 0sNo case conflicting files found.
+1 💚@author0m 0sThe patch does not contain any @author tags.
+1 💚test4tests0m 0sThe patch appears to include 2 new or modified test files.
_ master Compile Tests _
+0 🆗mvndep5m 51sMaven dependency ordering for branch
+1 💚mvninstall10m 13smaster passed
+1 💚compile3m 51smaster passed with JDK Ubuntu-11.0.16+8-post-Ubuntu-0ubuntu120.04
+1 💚compile3m 50smaster passed with JDK Private Build-1.8.0_342-8u342-b07-0ubuntu1~20.04-b07
+1 💚checkstyle3m 37smaster passed
+1 💚javadoc3m 51smaster passed with JDK Ubuntu-11.0.16+8-post-Ubuntu-0ubuntu120.04
+1 💚javadoc3m 36smaster passed with JDK Private Build-1.8.0_342-8u342-b07-0ubuntu1~20.04-b07
+0 🆗spotbugs1m 3sUsed deprecated FindBugs config; considering switching to SpotBugs.
+1 💚findbugs6m 0smaster passed
_ Patch Compile Tests _
+0 🆗mvndep0m 10sMaven dependency ordering for patch
+1 💚mvninstall1m 46sthe patch passed
+1 💚compile1m 54sthe patch passed with JDK Ubuntu-11.0.16+8-post-Ubuntu-0ubuntu120.04
+1 💚javac1m 54sthe patch passed
+1 💚compile1m 41sthe patch passed with JDK Private Build-1.8.0_342-8u342-b07-0ubuntu1~20.04-b07
+1 💚javac1m 41sthe patch passed
+1 💚checkstyle0m 14sThe patch passed checkstyle in tez-api
+1 💚checkstyle0m 13sThe patch passed checkstyle in tez-common
+1 💚checkstyle0m 14sThe patch passed checkstyle in tez-runtime-internals
+1 💚checkstyle0m 22stez-dag: The patch generated 0 new + 51 unchanged - 1 fixed = 51 total (was 52)
+1 💚checkstyle0m 15sThe patch passed checkstyle in tez-tests
+1 💚whitespace0m 0sThe patch has no whitespace issues.
+1 💚javadoc1m 39sthe patch passed with JDK Ubuntu-11.0.16+8-post-Ubuntu-0ubuntu120.04
+1 💚javadoc1m 35sthe patch passed with JDK Private Build-1.8.0_342-8u342-b07-0ubuntu1~20.04-b07
+1 💚findbugs4m 12sthe patch passed
_ Other Tests _
+1 💚unit2m 19stez-api in the patch passed.
+1 💚unit0m 30stez-common in the patch passed.
+1 💚unit0m 39stez-runtime-internals in the patch passed.
+1 💚unit5m 20stez-dag in the patch passed.
+1 💚unit39m 35stez-tests in the patch passed.
+1 💚asflicense1m 18sThe patch does not generate ASF License warnings.
142m 58s
SubsystemReport/Notes
DockerClientAPI=1.41 ServerAPI=1.41 base: https://ci-hadoop.apache.org/job/tez-multibranch/job/PR-98/10/artifact/out/Dockerfile
GITHUB PR#98
JIRA IssueTEZ-4039
Optional Testsdupname asflicense javac javadoc unit spotbugs findbugs checkstyle compile
unameLinux 7f925c3d5f80 4.15.0-191-generic #202-Ubuntu SMP Thu Aug 4 01:49:29 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
Build toolmaven
Personalitypersonality/tez.sh
git revisionmaster / fc5b6e9
Default JavaPrivate Build-1.8.0_342-8u342-b07-0ubuntu1~20.04-b07
Multi-JDK versions/usr/lib/jvm/java-11-openjdk-amd64:Ubuntu-11.0.16+8-post-Ubuntu-0ubuntu120.04 /usr/lib/jvm/java-8-openjdk-amd64:Private Build-1.8.0_342-8u342-b07-0ubuntu1~20.04-b07
Test Resultshttps://ci-hadoop.apache.org/job/tez-multibranch/job/PR-98/10/testReport/
Max. process+thread count1383 (vs. ulimit of 5500)
modulesC: tez-api tez-common tez-runtime-internals tez-dag tez-tests U: .
Console outputhttps://ci-hadoop.apache.org/job/tez-multibranch/job/PR-98/10/console
versionsgit=2.25.1 maven=3.6.3 findbugs=3.0.1
Powered byApache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

@rbalamohan

Copy link
Copy Markdown
Contributor

LGTM. +1

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants

@abstractdog@tez-yetus@rbalamohan@prasanthj