[
https://issues.apache.org/jira/browse/TEZ-3005?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15059346#comment-15059346
]
Bikas Saha commented on TEZ-3005:
---------------------------------
{noformat}
Error Message
expected:<KILLED> but was:<SUCCEEDED>
Stacktrace
java.lang.AssertionError: expected:<KILLED> but was:<SUCCEEDED>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:743)
at org.junit.Assert.assertEquals(Assert.java:118)
at org.junit.Assert.assertEquals(Assert.java:144)
at
org.apache.tez.dag.app.TestMockDAGAppMaster.testInternalPreemption(TestMockDAGAppMaster.java:211)
Standard Output
2015-12-16 01:33:57,215 INFO [Thread-309] client.TezClient
(TezClient.java:<init>(174)) - Tez Client Version: [ component=tez-api,
version=0.8.2-SNAPSHOT, revision=42ef63665644c80110fd542e832d8b1e2bb1404e,
SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git,
buildTime=20151216-0124 ]
2015-12-16 01:33:57,218 INFO [Thread-309] client.TezClient
(TezClient.java:start(394)) - Session mode. Starting session.
2015-12-16 01:33:57,219 INFO [Thread-309] client.TezClientUtils
(TezClientUtils.java:setupTezJarsLocalResources(164)) - Ignoring 'tez.lib.uris'
since 'tez.ignore.lib.uris' is set to true
2015-12-16 01:33:57,236 INFO [Thread-309] client.TezClient
(TezCommonUtils.java:createTezSystemStagingPath(122)) - Tez system stage
directory
file:/home/jenkins/jenkins-slave/workspace/Tez-Build-Hadoop-2.4/tez-dag/target/org.apache.tez.dag.app.TestMockDAGAppMaster-tmpDir/.tez/application_1450229637215_0001
doesn't exist and is created
2015-12-16 01:33:57,254 INFO [Thread-309] client.LocalClient
(LocalClient.java:createDAGAppMaster(332)) - DAGAppMaster thread has been
created
2015-12-16 01:33:57,260 INFO [Thread-309] client.LocalClient
(LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait
for 100ms...
2015-12-16 01:33:57,266 INFO [DAGAppMaster Thread] client.LocalClient
(LocalClient.java:run(282)) - Using working directory:
/home/jenkins/jenkins-slave/workspace/Tez-Build-Hadoop-2.4/tez-dag/target/org.apache.tez.dag.app.TestMockDAGAppMaster-tmpDir/.tez/application_1450229637215_0001_wd
2015-12-16 01:33:57,310 INFO [DAGAppMaster Thread] app.DAGAppMaster
(DAGAppMaster.java:<init>(364)) - Created DAGAppMaster for application
appattempt_1450229637215_0001_000000, versionInfo=[ component=tez-dag,
version=0.8.2-SNAPSHOT, revision=42ef63665644c80110fd542e832d8b1e2bb1404e,
SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git,
buildTime=20151216-0124 ]
2015-12-16 01:33:57,310 INFO [DAGAppMaster Thread] shim.HadoopShimsLoader
(HadoopShimsLoader.java:<init>(80)) - Trying to locate HadoopShimProvider for
hadoopVersion=2.4.0, majorVersion=2, minorVersion=4
2015-12-16 01:33:57,311 INFO [DAGAppMaster Thread] shim.HadoopShimsLoader
(HadoopShimsLoader.java:<init>(139)) - Picked HadoopShim
org.apache.tez.hadoop.shim.DefaultHadoopShim, providerName=null,
overrideProviderViaConfig=null, hadoopVersion=2.4.0, majorVersion=2,
minorVersion=4
2015-12-16 01:33:57,311 INFO [DAGAppMaster Thread] app.DAGAppMaster
(DAGAppMaster.java:serviceInit(437)) - AM Level configured TaskSchedulers:
[0:TezUber:null]
2015-12-16 01:33:57,311 INFO [DAGAppMaster Thread] app.DAGAppMaster
(DAGAppMaster.java:serviceInit(438)) - AM Level configured ContainerLaunchers:
[0:TezUber:null]
2015-12-16 01:33:57,312 INFO [DAGAppMaster Thread] app.DAGAppMaster
(DAGAppMaster.java:serviceInit(439)) - AM Level configured TaskCommunicators:
[0:TezUber:null]
2015-12-16 01:33:57,312 INFO [DAGAppMaster Thread] app.DAGAppMaster
(DAGAppMaster.java:serviceInit(448)) - Comparing client version with AM
version, clientVersion=0.8.2-SNAPSHOT, AMVersion=0.8.2-SNAPSHOT
2015-12-16 01:33:57,315 INFO [DAGAppMaster Thread] app.TaskCommunicatorManager
(TaskCommunicatorManager.java:createUberTaskCommunicator(169)) - Creating
Default Local Task Communicator
2015-12-16 01:33:57,316 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.rm.container.AMContainerEventType for class
org.apache.tez.dag.app.rm.container.AMContainerMap
2015-12-16 01:33:57,316 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.rm.node.AMNodeEventType for class
org.apache.tez.dag.app.rm.node.AMNodeTracker
2015-12-16 01:33:57,316 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class
org.apache.tez.dag.app.DAGAppMaster$DAGAppMasterEventHandler
2015-12-16 01:33:57,317 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.dag.event.DAGEventType for class
org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher
2015-12-16 01:33:57,317 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.dag.event.VertexEventType for class
org.apache.tez.dag.app.DAGAppMaster$VertexEventDispatcher
2015-12-16 01:33:57,317 INFO [DAGAppMaster Thread] app.DAGAppMaster
(DAGAppMaster.java:serviceInit(530)) - Using concurrent dispatcher: false
2015-12-16 01:33:57,318 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.dag.event.TaskEventType for class
org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher
2015-12-16 01:33:57,318 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class
org.apache.tez.dag.app.DAGAppMaster$TaskAttemptEventDispatcher
2015-12-16 01:33:57,318 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:registerAndCreateDispatcher(262)) - Registering class
org.apache.tez.dag.app.dag.event.SpeculatorEventType for independent dispatch
using: class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2015-12-16 01:33:57,318 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.dag.event.SpeculatorEventType for class
org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler
2015-12-16 01:33:57,320 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.rm.AMSchedulerEventType for class
org.apache.tez.dag.app.rm.TaskSchedulerManager
2015-12-16 01:33:57,322 INFO [DAGAppMaster Thread] common.AsyncDispatcher
(AsyncDispatcher.java:register(236)) - Registering class
org.apache.tez.dag.app.rm.ContainerLauncherEventType for class
org.apache.tez.dag.app.launcher.ContainerLauncherManager
2015-12-16 01:33:57,323 INFO [DAGAppMaster Thread] node.AMNodeTracker
(AMNodeTracker.java:serviceInit(74)) - blacklistDisablePercent is 33,
blacklistingEnabled: false, maxTaskFailuresPerNode: 10
2015-12-16 01:33:57,324 INFO [DAGAppMaster Thread] history.HistoryEventHandler
(HistoryEventHandler.java:serviceInit(57)) - Initializing HistoryEventHandler
withrecoveryEnabled=true,
historyServiceClassName=org.apache.tez.dag.history.logging.impl.SimpleHistoryLoggingService
2015-12-16 01:33:57,324 INFO [DAGAppMaster Thread]
impl.SimpleHistoryLoggingService
(SimpleHistoryLoggingService.java:serviceInit(66)) - Log file location for
SimpleHistoryLoggingService not specified, defaulting to
containerLogDir=/home/jenkins/jenkins-slave/workspace/Tez-Build-Hadoop-2.4/tez-dag/target/org.apache.tez.dag.app.TestMockDAGAppMaster-tmpDir/.tez/application_1450229637215_0001_wd/localmode-log-dir
2015-12-16 01:33:57,325 INFO [DAGAppMaster Thread]
impl.SimpleHistoryLoggingService
(SimpleHistoryLoggingService.java:serviceInit(88)) - Initializing
SimpleHistoryLoggingService,
logFileLocation=/home/jenkins/jenkins-slave/workspace/Tez-Build-Hadoop-2.4/tez-dag/target/org.apache.tez.dag.app.TestMockDAGAppMaster-tmpDir/.tez/application_1450229637215_0001_wd/localmode-log-dir/history.txt.appattempt_1450229637215_0001_000000,
maxErrors=10
2015-12-16 01:33:57,326 INFO [DAGAppMaster Thread] recovery.RecoveryService
(RecoveryService.java:serviceInit(123)) - RecoveryService initialized with
recoveryPath=file:/home/jenkins/jenkins-slave/workspace/Tez-Build-Hadoop-2.4/tez-dag/target/org.apache.tez.dag.app.TestMockDAGAppMaster-tmpDir/.tez/application_1450229637215_0001/recovery/0,
bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100
2015-12-16 01:33:57,327 INFO [DAGAppMaster Thread] history.HistoryEventHandler
(HistoryEventHandler.java:handleCriticalEvent(115)) -
[HISTORY][DAG:N/A][Event:AM_LAUNCHED]:
appAttemptId=appattempt_1450229637215_0001_000000, appSubmitTime=1450229637308,
launchTime=1450229637308
2015-12-16 01:33:57,353 INFO [ServiceThread:DAGClientRPCServer]
ipc.CallQueueManager (CallQueueManager.java:<init>(53)) - Using callQueue class
java.util.concurrent.LinkedBlockingQueue
2015-12-16 01:33:57,355 INFO [Socket Reader #1 for port 48594] ipc.Server
(Server.java:run(593)) - Starting Socket Reader #1 for port 48594
2015-12-16 01:33:57,361 INFO [IPC Server Responder] ipc.Server
(Server.java:run(815)) - IPC Server Responder: starting
2015-12-16 01:33:57,361 INFO [IPC Server listener on 48594] ipc.Server
(Server.java:run(662)) - IPC Server listener on 48594: starting
2015-12-16 01:33:57,362 INFO [ServiceThread:DAGClientRPCServer]
client.DAGClientServer (DAGClientServer.java:serviceStart(91)) - Instantiated
DAGClientRPCServer at asf907.gq1.ygridcore.net/67.195.81.151:48594
2015-12-16 01:33:57,384 INFO
[ServiceThread:org.apache.tez.dag.history.HistoryEventHandler]
impl.SimpleHistoryLoggingService
(SimpleHistoryLoggingService.java:serviceStart(95)) - Starting
SimpleHistoryLoggingService
2015-12-16 01:33:57,392 INFO [MockLauncher] app.MockDAGAppMaster
(MockDAGAppMaster.java:run(300)) - Waiting to go
2015-12-16 01:33:57,392 INFO [MockLauncher] app.MockDAGAppMaster
(MockDAGAppMaster.java:run(302)) - Signal to go
2015-12-16 01:33:57,392 INFO [Thread-309] client.LocalClient
(LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: INITED
2015-12-16 01:33:57,393 INFO [Thread-309] client.LocalClient
(LocalClient.java:startDAGAppMaster(240)) - DAGAppMaster is not startetd wait
for 100ms...
2015-12-16 01:33:57,393 INFO [Thread-309] client.LocalClient
(LocalClient.java:startDAGAppMaster(251)) - DAGAppMaster is not created wait
for 100ms...
2015-12-16 01:33:57,393 INFO
[ServiceThread:org.apache.tez.dag.app.rm.TaskSchedulerManager]
rm.TaskSchedulerManager
(TaskSchedulerManager.java:createUberTaskScheduler(427)) - Creating
TaskScheduler: Local TaskScheduler with clusterIdentifier=1450229637215
2015-12-16 01:33:57,395 INFO [DAGAppMaster Thread] history.HistoryEventHandler
(HistoryEventHandler.java:handleCriticalEvent(115)) -
[HISTORY][DAG:N/A][Event:AM_STARTED]:
appAttemptId=appattempt_1450229637215_0001_000000, startTime=1450229637395
2015-12-16 01:33:57,395 INFO [DAGAppMaster Thread] app.DAGAppMaster
(DAGAppMaster.java:serviceStart(1903)) - In Session mode. Waiting for DAG over
RPC
2015-12-16 01:33:57,493 INFO [Thread-309] client.LocalClient
(LocalClient.java:startDAGAppMaster(236)) - DAGAppMaster state: IDLE
2015-12-16 01:33:57,494 INFO [Thread-309] client.TezClient
(TezClient.java:start(428)) - The url to track the Tez Session: N/A
2015-12-16 01:33:57,494 INFO [Thread-309] client.TezClient
(TezClient.java:submitDAGSession(470)) - Submitting dag to TezSession,
sessionName=testMockAM, applicationId=application_1450229637215_0001,
dagName=testInternalPreemption
2015-12-16 01:33:57,503 INFO [IPC Server handler 0 on 48594] app.DAGAppMaster
(DAGAppMaster.java:submitDAGToAppMaster(1317)) - Starting DAG submitted via
RPC: testInternalPreemption
2015-12-16 01:33:57,504 INFO [IPC Server handler 0 on 48594] app.DAGAppMaster
(DAGAppMaster.java:createDAG(951)) - Merging AM credentials into DAG credentials
2015-12-16 01:33:57,518 INFO [IPC Server handler 0 on 48594] app.DAGAppMaster
(DAGAppMaster.java:generateDAGVizFile(1042)) - Generating DAG graphviz file,
dagId=dag_1450229637215_0001_1,
filePath=/home/jenkins/jenkins-slave/workspace/Tez-Build-Hadoop-2.4/tez-dag/target/org.apache.tez.dag.app.TestMockDAGAppMaster-tmpDir/.tez/application_1450229637215_0001_wd/localmode-log-dir/dag_1450229637215_0001_1.dot
2015-12-16 01:33:57,520 INFO [IPC Server handler 0 on 48594]
common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(183)) -
Redirecting log file based on addend: dag_1450229637215_0001_1
2015-12-16 01:33:57,520 WARN [IPC Server handler 0 on 48594]
common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(198)) - Not
configured with appender named: CLA. Cannot reconfigure logger output
2015-12-16 01:33:57,520 INFO [IPC Server handler 0 on 48594] app.DAGAppMaster
(DAGAppMaster.java:startDAG(2355)) - Running DAG: testInternalPreemption
2015-12-16 01:33:57 Running Dag: dag_1450229637215_0001_1
2015-12-16 01:33:57,533 INFO [IPC Server handler 0 on 48594]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:DAG_SUBMITTED]:
dagID=dag_1450229637215_0001_1, submitTime=1450229637504
2015-12-16 01:33:57,536 INFO [IPC Server handler 0 on 48594] impl.VertexImpl
(VertexImpl.java:<init>(927)) - Default container context for
vertex_1450229637215_0001_1_00 [A]=LocalResources: [[ name=tez-conf.pb,
value=resource { scheme: "file" port: -1 file:
"/home/jenkins/jenkins-slave/workspace/Tez-Build-Hadoop-2.4/tez-dag/target/org.apache.tez.dag.app.TestMockDAGAppMaster-tmpDir/.tez/application_1450229637215_0001/tez-conf.pb"
} size: 332 timestamp: 1450229637000 type: FILE visibility: APPLICATION],],
environment: [[ CLASSPATH=$PWD:$PWD/*:$HADOOP_CONF_DIR: ],[
LD_LIBRARY_PATH=$PWD:$PWD:$HADOOP_COMMON_HOME/lib/native/ ],],
credentials(token kinds): [tez.job,], javaOpts: -server
-Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN
-XX:+PrintGCDetails -verbose:gc -XX:+PrintGCTimeStamps -XX:+UseNUMA
-XX:+UseParallelGC
-Dlog4j.configuratorClass=org.apache.tez.common.TezLog4jConfigurator
-Dlog4j.configuration=tez-container-log4j.properties
-Dyarn.app.container.log.dir=<LOG_DIR> -Dtez.root.logger=INFO,CLA, vertex:
vertex_1450229637215_0001_1_00 [A], Default Resources=<memory:1024, vCores:1>
2015-12-16 01:33:57,537 INFO [IPC Server handler 0 on 48594] impl.VertexImpl
(VertexImpl.java:<init>(1015)) - Running vertex: vertex_1450229637215_0001_1_00
[A] : TaskScheduler=0:TezUber, ContainerLauncher=0:TezUber,
TaskCommunicator=0:TezUber
2015-12-16 01:33:57,537 INFO [IPC Server handler 0 on 48594] impl.DAGImpl
(DAGImpl.java:assignDAGScheduler(1581)) - Using DAG Scheduler:
org.apache.tez.dag.app.dag.impl.DAGSchedulerNaturalOrderControlled
2015-12-16 01:33:57,537 INFO [IPC Server handler 0 on 48594]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:DAG_INITIALIZED]:
dagID=dag_1450229637215_0001_1, initTime=1450229637537
2015-12-16 01:33:57,537 INFO [IPC Server handler 0 on 48594] impl.DAGImpl
(DAGImpl.java:handle(1158)) - dag_1450229637215_0001_1 transitioned from NEW to
INITED due to event DAG_INIT
2015-12-16 01:33:57,538 INFO [Dispatcher thread {Central}] impl.DAGImpl
(DAGImpl.java:transition(1753)) - Added additional resources : [[]] to classpath
2015-12-16 01:33:57,539 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:DAG_STARTED]:
dagID=dag_1450229637215_0001_1, startTime=1450229637539
2015-12-16 01:33:57,539 INFO [Dispatcher thread {Central}] impl.DAGImpl
(DAGImpl.java:handle(1158)) - dag_1450229637215_0001_1 transitioned from INITED
to RUNNING due to event DAG_START
2015-12-16 01:33:57,539 INFO [Dispatcher thread {Central}] impl.VertexImpl
(VertexImpl.java:assignVertexManager(2547)) - Setting vertexManager to
ImmediateStartVertexManager for vertex_1450229637215_0001_1_00 [A]
2015-12-16 01:33:57,540 INFO [Dispatcher thread {Central}] impl.VertexImpl
(VertexImpl.java:handleInitEvent(2738)) - Creating 1 tasks for vertex:
vertex_1450229637215_0001_1_00 [A]
2015-12-16 01:33:57,540 INFO [Dispatcher thread {Central}] impl.VertexImpl
(VertexImpl.java:handleInitEvent(2757)) - Directly initializing vertex:
vertex_1450229637215_0001_1_00 [A]
2015-12-16 01:33:57,540 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:VERTEX_CONFIGURE_DONE]:
vertexId=vertex_1450229637215_0001_1_00, reconfigureDoneTime=0, numTasks=1,
vertexLocationHint=null, edgeManagersCount=0, rootInputSpecUpdateCount=0,
setParallelismCalledFlag=false
2015-12-16 01:33:57,541 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:VERTEX_INITIALIZED]:
vertexName=A, vertexId=vertex_1450229637215_0001_1_00,
initRequestedTime=1450229637539, initedTime=1450229637541, numTasks=1,
processorName=Proc.class, additionalInputsCount=0, initGeneratedEventsCount=0
2015-12-16 01:33:57,541 INFO [Dispatcher thread {Central}] impl.VertexImpl
(VertexImpl.java:handle(1816)) - vertex_1450229637215_0001_1_00 [A]
transitioned from NEW to INITED due to event V_INIT
2015-12-16 01:33:57,542 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:VERTEX_STARTED]:
vertexId=vertex_1450229637215_0001_1_00, startRequestedTime=1450229637541,
startedTime=1450229637541
2015-12-16 01:33:57,542 INFO [Dispatcher thread {Central}] impl.VertexImpl
(VertexImpl.java:handle(1816)) - vertex_1450229637215_0001_1_00 [A]
transitioned from INITED to RUNNING due to event V_START
2015-12-16 01:33:57,543 INFO [App Shared Pool - #0]
impl.ImmediateStartVertexManager
(ImmediateStartVertexManager.java:scheduleTasks(100)) - Starting 1 in A
2015-12-16 01:33:57,544 INFO [Thread-309] client.TezClient
(TezClient.java:submitDAGSession(545)) - Submitted dag to TezSession,
sessionName=testMockAM, applicationId=application_1450229637215_0001,
dagName=testInternalPreemption
2015-12-16 01:33:57,547 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:TASK_STARTED]: vertexName=A,
taskId=task_1450229637215_0001_1_00_000000, scheduledTime=1450229637547,
launchTime=1450229637547
2015-12-16 01:33:57,548 INFO [Dispatcher thread {Central}]
impl.DAGSchedulerNaturalOrderControlled
(DAGSchedulerNaturalOrderControlled.java:scheduleTask(111)) - Scheduled vertex:
vertex_1450229637215_0001_1_00 [A]
2015-12-16 01:33:57,564 INFO [TaskSchedulerAppCallbackExecutor #0]
node.PerSourceNodeTracker (PerSourceNodeTracker.java:nodeSeen(70)) - Adding new
node 127.0.0.1:0 to nodeTracker 0
2015-12-16 01:33:57,566 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:N/A][Event:CONTAINER_LAUNCHED]:
containerId=container_1450229637215_0001_00_000001, launchTime=1450229637566
2015-12-16 01:33:57,568 INFO [Dispatcher thread {Central}] util.RackResolver
(RackResolver.java:coreResolve(109)) - Resolved 127.0.0.1 to /default-rack
2015-12-16 01:33:57,569 INFO [Dispatcher thread {Central}]
impl.TaskAttemptImpl (TaskAttemptImpl.java:transition(1322)) - TaskAttempt:
[attempt_1450229637215_0001_1_00_000000_0] started. Is using containerId:
[container_1450229637215_0001_00_000001] on NM: [127.0.0.1:0]
2015-12-16 01:33:57,569 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:TASK_ATTEMPT_STARTED]:
vertexName=A, taskAttemptId=attempt_1450229637215_0001_1_00_000000_0,
startTime=1450229637569, containerId=container_1450229637215_0001_00_000001,
nodeId=127.0.0.1:0
2015-12-16 01:33:57,618 INFO [MockLauncherExecutionThread [0]]
app.TezTaskCommunicatorImpl (TezTaskCommunicatorImpl.java:getTask(308)) -
Invalid task request with an empty containerContext or containerId
2015-12-16 01:33:57,622 INFO [Dispatcher thread {Central}]
container.AMContainerImpl (AMContainerImpl.java:transition(676)) - Container
container_1450229637215_0001_00_000001 exited with diagnostics set to Container
preempted internally
2015-12-16 01:33:57,623 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:CONTAINER_STOPPED]:
containerId=container_1450229637215_0001_00_000001, stoppedTime=1450229637622,
exitStatus=-1000
2015-12-16 01:33:57,624 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:TASK_ATTEMPT_FINISHED]:
vertexName=A, taskAttemptId=attempt_1450229637215_0001_1_00_000000_0,
creationTime=1450229637548, allocationTime=1450229637566,
startTime=1450229637569, finishTime=1450229637623, timeTaken=54,
status=SUCCEEDED, errorEnum=, diagnostics=
2015-12-16 01:33:57,626 INFO [Dispatcher thread {Central}] impl.TaskImpl
(TaskImpl.java:transition(1080)) - Task succeeded with attempt
attempt_1450229637215_0001_1_00_000000_0
2015-12-16 01:33:57,628 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:TASK_FINISHED]: vertexName=A,
taskId=task_1450229637215_0001_1_00_000000, startTime=1450229637569,
finishTime=1450229637626, timeTaken=57, status=SUCCEEDED,
successfulAttemptID=attempt_1450229637215_0001_1_00_000000_0, diagnostics=,
counters=Counters: 0
2015-12-16 01:33:57,629 INFO [Dispatcher thread {Central}] impl.VertexImpl
(VertexImpl.java:checkTasksForCompletion(2011)) - Task Completion:
vertex_1450229637215_0001_1_00 [A], tasks=1, failed=0, killed=0, success=1,
completed=1, commits=0, err=null
2015-12-16 01:33:57,629 INFO [Dispatcher thread {Central}] impl.VertexImpl
(VertexImpl.java:checkTasksForCompletion(2024)) - All tasks have succeeded,
vertex:vertex_1450229637215_0001_1_00 [A]
2015-12-16 01:33:57,632 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:VERTEX_FINISHED]: vertexName=A,
vertexId=vertex_1450229637215_0001_1_00, initRequestedTime=1450229637539,
initedTime=1450229637541, startRequestedTime=1450229637541,
startedTime=1450229637541, finishTime=1450229637629, timeTaken=88,
status=SUCCEEDED, diagnostics=, counters=Counters: 0,
vertexStats=firstTaskStartTime=1450229637569, firstTasksToStart=[
task_1450229637215_0001_1_00_000000 ], lastTaskFinishTime=1450229637623,
lastTasksToFinish=[ task_1450229637215_0001_1_00_000000 ], minTaskDuration=54,
maxTaskDuration=54, avgTaskDuration=54.0, numSuccessfulTasks=1,
shortestDurationTasks=[ task_1450229637215_0001_1_00_000000 ],
longestDurationTasks=[ task_1450229637215_0001_1_00_000000 ],
vertexTaskStats={numFailedTasks=0, numSucceededTasks=1,
numKilledTaskAttempts=0, numKilledTasks=0, numFailedTaskAttempts=0,
numCompletedTasks=1}
2015-12-16 01:33:57,632 INFO [Dispatcher thread {Central}] impl.VertexImpl
(VertexImpl.java:handle(1816)) - vertex_1450229637215_0001_1_00 [A]
transitioned from RUNNING to SUCCEEDED due to event V_TASK_COMPLETED
2015-12-16 01:33:57,633 INFO [Dispatcher thread {Central}] impl.DAGImpl
(DAGImpl.java:transition(1916)) - Vertex vertex_1450229637215_0001_1_00 [A]
completed., numCompletedVertices=1, numSuccessfulVertices=1,
numFailedVertices=0, numKilledVertices=0, numVertices=1
2015-12-16 01:33:57,633 INFO [Dispatcher thread {Central}] impl.DAGImpl
(DAGImpl.java:checkVerticesForCompletion(1249)) - Checking vertices for DAG
completion, numCompletedVertices=1, numSuccessfulVertices=1,
numFailedVertices=0, numKilledVertices=0, numVertices=1, commitInProgress=0,
terminationCause=null
2015-12-16 01:33:57,633 INFO [Dispatcher thread {Central}] impl.DAGImpl
(DAGImpl.java:commitOrFinish(1044)) - No output committers for vertex:
vertex_1450229637215_0001_1_00 [A]
2015-12-16 01:33:57,639 INFO [Dispatcher thread {Central}]
recovery.RecoveryService (RecoveryService.java:handle(324)) - DAG completed,
dagId=dag_1450229637215_0001_1, queueSize=0
2015-12-16 01:33:57,641 INFO [Dispatcher thread {Central}]
history.HistoryEventHandler (HistoryEventHandler.java:handleCriticalEvent(115))
- [HISTORY][DAG:dag_1450229637215_0001_1][Event:DAG_FINISHED]:
dagId=dag_1450229637215_0001_1, startTime=1450229637538,
finishTime=1450229637634, timeTaken=96, status=SUCCEEDED, diagnostics=,
counters=Counters: 4, org.apache.tez.common.counters.DAGCounter,
NUM_SUCCEEDED_TASKS=1, TOTAL_LAUNCHED_TASKS=1, AM_CPU_MILLISECONDS=80,
AM_GC_TIME_MILLIS=0
2015-12-16 01:33:57,642 INFO [Dispatcher thread {Central}] impl.DAGImpl
(DAGImpl.java:finished(1393)) - DAG: dag_1450229637215_0001_1 finished with
state: SUCCEEDED
2015-12-16 01:33:57,642 INFO [Dispatcher thread {Central}] impl.DAGImpl
(DAGImpl.java:handle(1158)) - dag_1450229637215_0001_1 transitioned from
RUNNING to SUCCEEDED due to event DAG_VERTEX_COMPLETED
2015-12-16 01:33:57 Completed Dag: dag_1450229637215_0001_1
2015-12-16 01:33:57,642 INFO [Dispatcher thread {Central}] app.DAGAppMaster
(DAGAppMaster.java:handle(718)) - DAG completed,
dagId=dag_1450229637215_0001_1, dagState=SUCCEEDED
2015-12-16 01:33:57,643 INFO [Dispatcher thread {Central}]
common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(183)) -
Redirecting log file based on addend: dag_1450229637215_0001_1_post
2015-12-16 01:33:57,643 WARN [Dispatcher thread {Central}]
common.TezUtilsInternal (TezUtilsInternal.java:updateLoggers(198)) - Not
configured with appender named: CLA. Cannot reconfigure logger output
2015-12-16 01:33:57,643 INFO [Dispatcher thread {Central}] app.DAGAppMaster
(DAGAppMaster.java:handle(766)) - Central Dispatcher queue size after DAG
completion, before cleanup: 0
2015-12-16 01:33:57,643 INFO [Dispatcher thread {Central}] app.DAGAppMaster
(DAGAppMaster.java:handle(768)) - Waiting for next DAG to be submitted.
2015-12-16 01:33:57,644 INFO [Thread-309] client.DAGClientImpl
(DAGClientImpl.java:log(605)) - DAG: State: SUCCEEDED Progress: 100%
TotalTasks: 1 Succeeded: 1 Running: 0 Failed: 0 Killed: 0
2015-12-16 01:33:57,644 INFO [Thread-309] client.DAGClientImpl
(DAGClientImpl.java:log(605)) - DAG completed. FinalState=SUCCEEDED
2015-12-16 01:33:57,644 INFO [Dispatcher thread {Central}] app.DAGAppMaster
(DAGAppMaster.java:handle(808)) - Cleaning up DAG: name=testInternalPreemption,
with id=dag_1450229637215_0001_1
2015-12-16 01:33:57,652 INFO [Dispatcher thread {Central}] app.DAGAppMaster
(DAGAppMaster.java:handle(818)) - Completed cleanup for DAG:
name=testInternalPreemption, with id=dag_1450229637215_0001_1
Standard Error
2015-12-16 01:33:57 Running Dag: dag_1450229637215_0001_1
2015-12-16 01:33:57 Completed Dag: dag_1450229637215_0001_1{noformat}
> TestMockDAGAppMaster.testInternalPreemption fails
> -------------------------------------------------
>
> Key: TEZ-3005
> URL: https://issues.apache.org/jira/browse/TEZ-3005
> Project: Apache Tez
> Issue Type: Sub-task
> Reporter: Jeff Zhang
>
> {code}
> testInternalPreemption(org.apache.tez.dag.app.TestMockDAGAppMaster) Time
> elapsed: 0.458 sec <<< FAILURE!
> java.lang.AssertionError: expected:<KILLED> but was:<SUCCEEDED>
> at org.junit.Assert.fail(Assert.java:88)
> at org.junit.Assert.failNotEquals(Assert.java:743)
> at org.junit.Assert.assertEquals(Assert.java:118)
> at org.junit.Assert.assertEquals(Assert.java:144)
> at
> org.apache.tez.dag.app.TestMockDAGAppMaster.testInternalPreemption(TestMockDAGAppMaster.java:211)
> {code}
> https://builds.apache.org/job/Tez-Build-Hadoop-2.4/226/console
> \cc [~bikassaha]
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
