[
https://issues.apache.org/jira/browse/OOZIE-1939?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14081188#comment-14081188
]
Azrael commented on OOZIE-1939:
-------------------------------
Summarizing the work being done here:
1. Use Info as thread local object in XCommand.
{quote}
logInfo = XLog.Info().get();
or get rid of this and LogUtils.setLogInfo() should use XLog.Info().get()
instead of the logInfo in argument
{quote}
2. Make sure to reset after logInfo.setParameter.
{quote}
The main issue is in XLog.log(). XLog is shared across threads for same class.
So, in XLog.log(), prefix should be computed as
XLog.Info().get().createPrefix() which uses the thread local info and the log
info is set correctly
{quote}
If prefix is computed in XLog.log(), it might be performance issue. So, call
resetPrefix() after setting log info parameter.
{code}
XLog.Info.get().setParameter(DagXLogInfoService.ACTION, action.getId());
LOG = XLog.resetPrefix(LOG);
{code}
3. I added setLogInfo() in XCommand and call int in call() to set correct job
information in some log message(This is patch version 1). In XCommand.call(),
the log message before loadState() have the job(or action) information is set
by previous XCommand which is called by the same thread. It cause the incorrect
job information in Acquiring lock and Load state.
Here is example:
{code}
2014-07-31 11:39:30,899 DEBUG ActionStartXCommand:547 [pool-2-thread-1] -
USER[seoeun] GROUP[staff] TOKEN[] APP[test]
JOB[0000000-140731113925653-oozie-seoe-W]
ACTION[0000000-140731113925653-oozie-seoe-W@:start:] Acquired lock for
[0000000-140731113925653-oozie-seoe-W] in [action.start]
2014-07-31 11:39:30,900 DEBUG ActionStartXCommand:547 [pool-2-thread-1] -
USER[seoeun] GROUP[staff] TOKEN[] APP[test]
JOB[0000000-140731113925653-oozie-seoe-W]
ACTION[0000000-140731113925653-oozie-seoe-W@:start:] Load state for
[0000000-140731113925653-oozie-seoe-W]
2014-07-31 11:39:30,937 DEBUG ActionStartXCommand:547 [pool-2-thread-1] -
USER[seoeun] GROUP[staff] TOKEN[] APP[test]
JOB[0000000-140731113925653-oozie-seoe-W]
ACTION[0000000-140731113925653-oozie-seoe-W@shell-1] Execute command
[action.start] key [0000000-140731113925653-oozie-seoe-W]
{code}
It should be
{code}
2014-08-01 02:04:26,002 DEBUG ActionStartXCommand:547 [pool-2-thread-1] -
USER[seoeun] GROUP[staff] TOKEN[] APP[test]
JOB[0000000-140801020414703-oozie-seoe-W]
ACTION[0000000-140801020414703-oozie-seoe-W@shell-1] Acquired lock for
[0000000-140801020414703-oozie-seoe-W] in [action.start]
2014-08-01 02:04:26,002 DEBUG ActionStartXCommand:547 [pool-2-thread-1] -
USER[seoeun] GROUP[staff] TOKEN[] APP[test]
JOB[0000000-140801020414703-oozie-seoe-W]
ACTION[0000000-140801020414703-oozie-seoe-W@shell-1] Load state for
[0000000-140801020414703-oozie-seoe-W]
2014-08-01 02:04:26,018 DEBUG ActionStartXCommand:547 [pool-2-thread-1] -
USER[seoeun] GROUP[staff] TOKEN[] APP[test]
JOB[0000000-140801020414703-oozie-seoe-W]
ACTION[0000000-140801020414703-oozie-seoe-W@shell-1] Execute command
[action.start] key [0000000-140801020414703-oozie-seoe-W]
{code}
> Incorrect job information is set while logging
> ----------------------------------------------
>
> Key: OOZIE-1939
> URL: https://issues.apache.org/jira/browse/OOZIE-1939
> Project: Oozie
> Issue Type: Bug
> Reporter: Purshotam Shah
> Assignee: Azrael
> Attachments: OOZIE-1939.1.patch, OOZIE-1939.2.patch
>
>
> {code}
> 2014-07-16 17:28:06,422 DEBUG CoordChangeXCommand:545 [http-0.0.0.0-4443-5] -
> USER[hadoopqa] GROUP[users] TOKEN[] APP[coordB236]
> JOB[0011514-140716042555-oozie-oozi-C] ACTION[-] Acquired lock for
> [0011385-140716042555-oozie-oozi-C] in [coord_change]
> 2014-07-16 17:28:06,422 TRACE CoordChangeXCommand:548 [http-0.0.0.0-4443-5] -
> USER[hadoopqa] GROUP[users] TOKEN[] APP[coordB236]
> JOB[0011514-140716042555-oozie-oozi-C] ACTION[-] Load state for
> [0011385-140716042555-oozie-oozi-C]
> {code}
> {code}
> protected void loadState() throws CommandException {
> jpaService = Services.get().get(JPAService.class);
> if (jpaService == null) {
> LOG.error(ErrorCode.E0610);
> }
> try {
> coordJob =
> CoordJobQueryExecutor.getInstance().get(CoordJobQuery.GET_COORD_JOB_MATERIALIZE,
> jobId);
> prevStatus = coordJob.getStatus();
> }
> catch (JPAExecutorException jex) {
> throw new CommandException(jex);
> }
> // calculate start materialize and end materialize time
> calcMatdTime();
> LogUtils.setLogInfo(coordJob, logInfo);
> }
> {code}
> Most of the commands set jobinfo after loadstate, because of that few log
> statements ( like acquiring lock, load state) logs with previous jobinfo.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
