[
https://issues.apache.org/jira/browse/SAMZA-1359?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jagadish updated SAMZA-1359:
----------------------------
Description:
At LinkedIn, we have observed that there are phantom notifications
corresponding to containers not being actively managed by Samza. We should
improve our AppMaster's logic to be resilient to these phantom notifications.
Currently, we take actions based on these notifications - for example, we
increment the number of failed containers, mark the job health to be false etc.
These actions cause false alerts to be fired and automated remediations based
on these alerts. At LinkedIn, this has affected our ability to do upgrades on
the Samza cluster because several jobs have to be restarted owing to these
phantom notifications.
Here's the investigation during an upgrade and a rolling bounce of the Samza
ResourceManagers.
1. Samza starts container 13 on a certain host for this job.
{code}
2017-06-07 19:46:20.226 [Container Allocator Thread] YarnContainerRunner [INFO]
Claimed container ID 13 for container container_1490916233553_1471_01_000016 on
node hostname_masked19956masked_host
(http://hostname_masked19956masked_host:8042/node/containerlogs/container_1490916233553_1471_01_000016).
{code}
2. Yarn reports that container 13 is lost due to a failure of its NodeManager
on the host at which the container was running.
{code}
2017-06-09 06:14:40.398 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Container completed from RM ContainerStatus:
[ContainerId: container_1490916233553_1471_01_000016, State: COMPLETE,
Diagnostics: Container released on a *lost* node, ExitStatus: -100, ]
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Completed container had ID: 13
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Removing container ID 13 from completed
containers
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Matching container ID found 13
org.apache.samza.clustermanager.SamzaResource@e4e2d63a
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Got an exit code of -100. This means that container
container_1490916233553_1471_01_000016 was killed by YARN, either due to being
released by the application master or being 'lost' due to node failures etc. or
due to preemption by the RM
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Released container container_1490916233553_1471_01_000016 was assigned
task group ID 13. Requesting a refactor container for the task group.
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] SamzaResourceRequest
[INFO] Resource Request created for 13 on ANY_HOST at 1496988880401
{code}
3. Samza makes a request to Yarn for restarting container 13 on a different
host.
{code}
2017-06-09 06:14:40.402 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Requesting resources on ANY_HOST for
container 13
2017-06-09 06:14:40.402 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Making a request for ANY_HOST ANY_HOST
2017-06-09 06:14:42.400 [AMRM Heartbeater thread] AMRMClientImpl [INFO]
Received new token for : hostname_masked19939masked_host:1158
2017-06-09 06:14:42.401 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Container allocated from RM on
hostname_masked19939masked_host
2017-06-09 06:14:42.401 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Container allocated from RM on hostname_masked19939masked_host
2017-06-09 06:14:42.401 [AMRM Callback Handler Thread] ResourceRequestState
[INFO] Host affinity not enabled. Saving the samzaResource
container_1490916233553_1471_01_000027 in the buffer for ANY_HOST
2017-06-09 06:14:44.310 [Container Allocator Thread] YarnClusterResourceManager
[INFO] Cancelling request SamzaResourceRequest{numCores=1, memoryMB=4000,
preferredHost='ANY_HOST', requestID='f74a8fcf-be17-42eb-8824-1c32b4504933',
containerID=13, requestTimestampMs=1496988880401}
2017-06-09 06:14:44.310 [Container Allocator Thread] AbstractContainerAllocator
[INFO] Found available resources on ANY_HOST. Assigning request for
container_id 13 with timestamp 1496988880401 to resource
container_1490916233553_1471_01_000027
2017-06-09 06:14:44.310 [Container Allocator Thread] YarnClusterResourceManager
[INFO] Received launch request for 13 on hostname
hostname_masked19939masked_host
2017-06-09 06:14:44.310 [Container Allocator Thread] YarnContainerRunner [INFO]
Got available container ID (13) for container: Container: [ContainerId:
container_1490916233553_1471_01_000027, NodeId:
hostname_masked19939masked_host:1158, NodeHttpAddress:
hostname_masked19939masked_host:8042, Resource: <memory:4096, vCores:1>,
Priority: 0, Token: Token { kind: ContainerToken, service: 10.149.196.44:1158
}, ]
{code}
4. Container 13 is re-started and runs on a different host
{code}
2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner [INFO]
In runContainer in util: fwkPath= ;cmdPath=./__package/;jobLib=
2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner [INFO]
Container ID 13 using command ./__package//bin/run-container.sh
2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner [INFO]
Container ID 13 using environment variables:
hostname_masked1348masked_host
hostname_masked1355masked_host
hostname_masked20440masked_host
{code}
5. A cluster wide upgrade happens and the machines in the cluster have to be
bounced. We typically do a rolling bounce on the RM to give an opportunity for
the passive RM to take ownership. RM failover happens and state is re-synced
from the passive to the active RM. Samza's AppMaster (which had a previous
connection to the active RM) resyncs it's state from the other RM.
{code}
2017-06-14 23:18:20.281 [AMRM Heartbeater thread] RetryInvocationHandler [INFO]
Exception while invoking allocate of class
ApplicationMasterProtocolPBClientImpl over yarn-prod-ltx1-samza-rm-2. Trying to
fail over immediately.
java.net.ConnectException: Call From
hostname_masked19958masked_host/10.149.196.108 to
hostname_masked1348masked_host:8030 failed on connection exception:
java.net.ConnectException: Connection refused; For more details see:
http://wiki.apache.org/hadoop/ConnectionRefused
2017-06-14 23:19:39.203 [AMRM Heartbeater thread] AMRMClientImpl [WARN]
ApplicationMaster is out of sync with ResourceManager, hence resyncing.
{code}
6. A phantom notification (duplicate) is received for the same container (Note
the same container ID: container_1490916233553_1471_01_000016). This
notification declares that the container exited with code 154.
{code}
Get a Container killed by RM error with non zero exit code 154
2017-06-14 23:19:39.211 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Container completed from RM ContainerStatus:
[ContainerId: container_1490916233553_1471_01_000016, State: COMPLETE,
Diagnostics: Container Killed by ResourceManager
Container exited with a non-zero exit code 154
, ExitStatus: 154, ]
2017-06-14 23:19:39.212 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Completed container had ID: -1
2017-06-14 23:19:39.212 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] No matching container id found for
SamzaResourceStatus{resourceID='container_1490916233553_1471_01_000016',
diagnostics='Container Killed by ResourceManager
Container exited with a non-zero exit code 154
', exitCode=154}
2017-06-14 23:19:39.212 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Container failed for some reason. Let's start it again
2017-06-14 23:19:39.212 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Container container_1490916233553_1471_01_000016 failed with exit code .
154 - Container Killed by ResourceManager
Container exited with a non-zero exit code 154
containerID is -1
{code}
7. We take an action based on this phantom notification (and reset job health,
other metrics). This causes automated false-alerts, and remediation to kick in.
All jobs in the cluster have to be restarted now.
*What scenarios on the Node Manager side trigger the phantom notification?*
We have observed that if a node manager is re-started after a failure, NM
recovery kicks in and tries to take ownership of containers it was managing in
its previous run. In some cases, the container could have been killed / exited
before the node manager comes back up. This would result in a timeout in the NM
recovery process.
Here are the relevant logs :
a. NM is killed due to some errors and auto re-started. It was down from 06:01
to 06:17.
{code}
06:17:29,470 [INFO] [main] util.LogAdapter.info(LogAdapter.java:45) -
STARTUP_MSG:
/************************************************************
STARTUP_MSG: Starting NodeManager
STARTUP_MSG: host = hostname_masked19956masked_host/10.149.196.106
STARTUP_MSG: args = []
STARTUP_MSG: version = 2.7.3
{code}
b. NM recovery kicks in trying to own previous containers
{code}
2017-06-09 06:17:32,899 [INFO] [main]
containermanager.ContainerManagerImpl.recoverContainer(ContainerManagerImpl.java:307)
- Recovering container_1490916233553_1471_01_000016 in state LAUNCHED with
exit code -1000
2017-06-09 06:17:33,115 [INFO] [main]
containermanager.ContainerManagerImpl.waitForRecoveredContainers
2017-06-09 06:17:33,274 [INFO] [AsyncDispatcher event handler]
application.ApplicationImpl$InitContainerTransition.transition(ApplicationImpl.java:304)
- Adding container_1490916233553_1471_01_000016 to application
application_1490916233553_1471
2017-06-09 06:17:33,387 [INFO] [AsyncDispatcher event handler]
container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
container_1490916233553_1471_01_000016 transitioned from LOCALIZING to LOCALIZED
2017-06-09 06:17:33,427 [INFO] [ContainersLauncher #39]
nodemanager.ContainerExecutor.reacquireContainer(ContainerExecutor.java:181) -
Reacquiring container_1490916233553_1471_01_000016 with pid 23848
reqcquireing pid
2017-06-09 06:17:33,449 [INFO] [AsyncDispatcher event handler]
container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
container_1490916233553_1471_01_000016 transitioned from LOCALIZED to RUNNING
2017-06-09 06:17:35,094 Sending diagnostics
[container_1490916233553_1471_01_000016, CreateTime: 1496864777558, State:
RUNNING, Capability: <memory:4096, vCores:1>, Diagnostics: , ExitStatus: -1000,
Priority: 0]
{code}
c. Recovery times out because the container already exited (due to an unrelated
error)
{code}
2017-06-09 06:17:35,592 [WARN] [ContainersLauncher #39]
util.CgroupsLCEResourcesHandler.checkAndDeleteCgroup(CgroupsLCEResourcesHandler.java:324)
- Failed to read cgroup tasks file.
java.io.FileNotFoundException:
/cgroup/cpu/restrain.slice/container_1490916233553_1471_01_000016/tasks (No
such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at
org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.checkAndDeleteCgroup(CgroupsLCEResourcesHandler.java:308)
at
org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.deleteCgroup(CgroupsLCEResourcesHandler.java:339)
at
org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.clearLimits(CgroupsLCEResourcesHandler.java:388)
at
org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.postExecute(CgroupsLCEResourcesHandler.java:402)
at
org.apache.hadoop.yarn.server.nodemanager.LinuxContainerExecutor.reacquireContainer(LinuxContainerExecutor.java:354)
at
org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:83)
at
org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:46)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2017-06-09 06:17:36,608 [ERROR] [ContainersLauncher #39]
launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:88) -
Unable to recover container container_1490916233553_1471_01_000016
java.io.IOException: Timeout while waiting for exit code from
container_1490916233553_1471_01_000016
at
org.apache.hadoop.yarn.server.nodemanager.ContainerExecutor.reacquireContainer(ContainerExecutor.java:202)
at
org.apache.hadoop.yarn.server.nodemanager.LinuxContainerExecutor.reacquireContainer(LinuxContainerExecutor.java:352)
at
org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:83)
at
org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:46)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2017-06-09 06:17:37,223 [INFO] [AsyncDispatcher event handler]
launcher.ContainerLaunch.cleanupContainer(ContainerLaunch.java:370) - Cleaning
up container container_1490916233553_1471_01_000016
2017-06-09 06:17:37,465 [INFO] [AsyncDispatcher event handler]
container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
container_1490916233553_1471_01_000016 transitioned from KILLING to
EXITED_WITH_FAILURE
2017-06-09 06:17:37,493 [INFO] [AsyncDispatcher event handler]
container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
container_1477351569246_0429_02_000129 transitioned from EXITED_WITH_FAILURE to
DONE
2017-06-09 06:17:37,493 [WARN] [AsyncDispatcher event handler]
nodemanager.NMAuditLogger.logFailure(NMAuditLogger.java:150) -
USER=samza-trust-repartition OPERATION=Container Finished - Failed
TARGET=ContainerImpl RESULT=FAILURE DESCRIPTION=Container failed with
state: EXITED_WITH_FAILURE APPID=application_1490916233553_1471
CONTAINERID=container_1490916233553_1471_01_000016
{code}
d. When an RM fail over happens, and the state is re-synced from the passive to
the active RM triggering a phantom notification.
was:
At LinkedIn, we have observed that there are phantom notifications
corresponding to containers not being actively managed by Samza. We should
improve our AppMaster's logic to be resilient to these phantom notifications.
Currently, we take actions based on these notifications - for example, we
increment the number of failed containers, mark the job health to be false etc.
These actions cause false alerts to be fired and automated remediations based
on these alerts. At LinkedIn, this has affected our ability to do upgrades on
the Samza cluster because several jobs have to be restarted owing to these
phantom notifications.
Here's the investigation during an upgrade and a rolling bounce of the Samza
ResourceManagers.
1. Samza starts container 13 on a certain host for this job.
{code}
2017-06-07 19:46:20.226 [Container Allocator Thread] YarnContainerRunner [INFO]
Claimed container ID 13 for container container_1490916233553_1471_01_000016 on
node ltx1-app19956.prod.linkedin.com
(http://ltx1-app19956.prod.linkedin.com:8042/node/containerlogs/container_1490916233553_1471_01_000016).
{code}
2. Yarn reports that container 13 is lost due to a failure of its NodeManager
on the host at which the container was running.
{code}
2017-06-09 06:14:40.398 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Container completed from RM ContainerStatus:
[ContainerId: container_1490916233553_1471_01_000016, State: COMPLETE,
Diagnostics: Container released on a *lost* node, ExitStatus: -100, ]
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Completed container had ID: 13
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Removing container ID 13 from completed
containers
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Matching container ID found 13
org.apache.samza.clustermanager.SamzaResource@e4e2d63a
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Got an exit code of -100. This means that container
container_1490916233553_1471_01_000016 was killed by YARN, either due to being
released by the application master or being 'lost' due to node failures etc. or
due to preemption by the RM
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Released container container_1490916233553_1471_01_000016 was assigned
task group ID 13. Requesting a refactor container for the task group.
2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] SamzaResourceRequest
[INFO] Resource Request created for 13 on ANY_HOST at 1496988880401
{code}
3. Samza makes a request to Yarn for restarting container 13 on a different
host.
{code}
2017-06-09 06:14:40.402 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Requesting resources on ANY_HOST for
container 13
2017-06-09 06:14:40.402 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Making a request for ANY_HOST ANY_HOST
2017-06-09 06:14:42.400 [AMRM Heartbeater thread] AMRMClientImpl [INFO]
Received new token for : ltx1-app19939.prod.linkedin.com:1158
2017-06-09 06:14:42.401 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Container allocated from RM on
ltx1-app19939.prod.linkedin.com
2017-06-09 06:14:42.401 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Container allocated from RM on ltx1-app19939.prod.linkedin.com
2017-06-09 06:14:42.401 [AMRM Callback Handler Thread] ResourceRequestState
[INFO] Host affinity not enabled. Saving the samzaResource
container_1490916233553_1471_01_000027 in the buffer for ANY_HOST
2017-06-09 06:14:44.310 [Container Allocator Thread] YarnClusterResourceManager
[INFO] Cancelling request SamzaResourceRequest{numCores=1, memoryMB=4000,
preferredHost='ANY_HOST', requestID='f74a8fcf-be17-42eb-8824-1c32b4504933',
containerID=13, requestTimestampMs=1496988880401}
2017-06-09 06:14:44.310 [Container Allocator Thread] AbstractContainerAllocator
[INFO] Found available resources on ANY_HOST. Assigning request for
container_id 13 with timestamp 1496988880401 to resource
container_1490916233553_1471_01_000027
2017-06-09 06:14:44.310 [Container Allocator Thread] YarnClusterResourceManager
[INFO] Received launch request for 13 on hostname
ltx1-app19939.prod.linkedin.com
2017-06-09 06:14:44.310 [Container Allocator Thread] YarnContainerRunner [INFO]
Got available container ID (13) for container: Container: [ContainerId:
container_1490916233553_1471_01_000027, NodeId:
ltx1-app19939.prod.linkedin.com:1158, NodeHttpAddress:
ltx1-app19939.prod.linkedin.com:8042, Resource: <memory:4096, vCores:1>,
Priority: 0, Token: Token { kind: ContainerToken, service: 10.149.196.44:1158
}, ]
{code}
4. Container 13 is re-started and runs on a different host
{code}
2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner [INFO]
In runContainer in util: fwkPath= ;cmdPath=./__package/;jobLib=
2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner [INFO]
Container ID 13 using command ./__package//bin/run-container.sh
2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner [INFO]
Container ID 13 using environment variables:
ltx1-app1348.prod.linkedin.com
ltx1-app1355.prod.linkedin.com
ltx1-app20440.prod.linkedin.com
{code}
5. A cluster wide upgrade happens and the machines in the cluster have to be
bounced. We typically do a rolling bounce on the RM to give an opportunity for
the passive RM to take ownership. RM failover happens and state is re-synced
from the passive to the active RM. Samza's AppMaster (which had a previous
connection to the active RM) resyncs it's state from the other RM.
{code}
2017-06-14 23:18:20.281 [AMRM Heartbeater thread] RetryInvocationHandler [INFO]
Exception while invoking allocate of class
ApplicationMasterProtocolPBClientImpl over yarn-prod-ltx1-samza-rm-2. Trying to
fail over immediately.
java.net.ConnectException: Call From
ltx1-app19958.prod.linkedin.com/10.149.196.108 to
ltx1-app1348.prod.linkedin.com:8030 failed on connection exception:
java.net.ConnectException: Connection refused; For more details see:
http://wiki.apache.org/hadoop/ConnectionRefused
2017-06-14 23:19:39.203 [AMRM Heartbeater thread] AMRMClientImpl [WARN]
ApplicationMaster is out of sync with ResourceManager, hence resyncing.
{code}
6. A phantom notification (duplicate) is received for the same container (Note
the same container ID: container_1490916233553_1471_01_000016). This
notification declares that the container exited with code 154.
{code}
Get a Container killed by RM error with non zero exit code 154
2017-06-14 23:19:39.211 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Container completed from RM ContainerStatus:
[ContainerId: container_1490916233553_1471_01_000016, State: COMPLETE,
Diagnostics: Container Killed by ResourceManager
Container exited with a non-zero exit code 154
, ExitStatus: 154, ]
2017-06-14 23:19:39.212 [AMRM Callback Handler Thread]
YarnClusterResourceManager [INFO] Completed container had ID: -1
2017-06-14 23:19:39.212 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] No matching container id found for
SamzaResourceStatus{resourceID='container_1490916233553_1471_01_000016',
diagnostics='Container Killed by ResourceManager
Container exited with a non-zero exit code 154
', exitCode=154}
2017-06-14 23:19:39.212 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Container failed for some reason. Let's start it again
2017-06-14 23:19:39.212 [AMRM Callback Handler Thread] ContainerProcessManager
[INFO] Container container_1490916233553_1471_01_000016 failed with exit code .
154 - Container Killed by ResourceManager
Container exited with a non-zero exit code 154
containerID is -1
{code}
7. We take an action based on this phantom notification (and reset job health,
other metrics). This causes automated false-alerts, and remediation to kick in.
All jobs in the cluster have to be restarted now.
*What scenarios on the Node Manager side trigger the phantom notification?*
We have observed that if a node manager is re-started after a failure, NM
recovery kicks in and tries to take ownership of containers it was managing in
its previous run. In some cases, the container could have been killed / exited
before the node manager comes back up. This would result in a timeout in the NM
recovery process.
Here are the relevant logs :
a. NM is killed due to some errors and auto re-started. It was down from 06:01
to 06:17.
{code}
06:17:29,470 [INFO] [main] util.LogAdapter.info(LogAdapter.java:45) -
STARTUP_MSG:
/************************************************************
STARTUP_MSG: Starting NodeManager
STARTUP_MSG: host = ltx1-app19956.prod.linkedin.com/10.149.196.106
STARTUP_MSG: args = []
STARTUP_MSG: version = 2.7.3
{code}
b. NM recovery kicks in trying to own previous containers
{code}
2017-06-09 06:17:32,899 [INFO] [main]
containermanager.ContainerManagerImpl.recoverContainer(ContainerManagerImpl.java:307)
- Recovering container_1490916233553_1471_01_000016 in state LAUNCHED with
exit code -1000
2017-06-09 06:17:33,115 [INFO] [main]
containermanager.ContainerManagerImpl.waitForRecoveredContainers
2017-06-09 06:17:33,274 [INFO] [AsyncDispatcher event handler]
application.ApplicationImpl$InitContainerTransition.transition(ApplicationImpl.java:304)
- Adding container_1490916233553_1471_01_000016 to application
application_1490916233553_1471
2017-06-09 06:17:33,387 [INFO] [AsyncDispatcher event handler]
container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
container_1490916233553_1471_01_000016 transitioned from LOCALIZING to LOCALIZED
2017-06-09 06:17:33,427 [INFO] [ContainersLauncher #39]
nodemanager.ContainerExecutor.reacquireContainer(ContainerExecutor.java:181) -
Reacquiring container_1490916233553_1471_01_000016 with pid 23848
reqcquireing pid
2017-06-09 06:17:33,449 [INFO] [AsyncDispatcher event handler]
container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
container_1490916233553_1471_01_000016 transitioned from LOCALIZED to RUNNING
2017-06-09 06:17:35,094 Sending diagnostics
[container_1490916233553_1471_01_000016, CreateTime: 1496864777558, State:
RUNNING, Capability: <memory:4096, vCores:1>, Diagnostics: , ExitStatus: -1000,
Priority: 0]
{code}
c. Recovery times out because the container already exited (due to an unrelated
error)
{code}
2017-06-09 06:17:35,592 [WARN] [ContainersLauncher #39]
util.CgroupsLCEResourcesHandler.checkAndDeleteCgroup(CgroupsLCEResourcesHandler.java:324)
- Failed to read cgroup tasks file.
java.io.FileNotFoundException:
/cgroup/cpu/restrain.slice/container_1490916233553_1471_01_000016/tasks (No
such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at java.io.FileInputStream.<init>(FileInputStream.java:93)
at
org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.checkAndDeleteCgroup(CgroupsLCEResourcesHandler.java:308)
at
org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.deleteCgroup(CgroupsLCEResourcesHandler.java:339)
at
org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.clearLimits(CgroupsLCEResourcesHandler.java:388)
at
org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.postExecute(CgroupsLCEResourcesHandler.java:402)
at
org.apache.hadoop.yarn.server.nodemanager.LinuxContainerExecutor.reacquireContainer(LinuxContainerExecutor.java:354)
at
org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:83)
at
org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:46)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2017-06-09 06:17:36,608 [ERROR] [ContainersLauncher #39]
launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:88) -
Unable to recover container container_1490916233553_1471_01_000016
java.io.IOException: Timeout while waiting for exit code from
container_1490916233553_1471_01_000016
at
org.apache.hadoop.yarn.server.nodemanager.ContainerExecutor.reacquireContainer(ContainerExecutor.java:202)
at
org.apache.hadoop.yarn.server.nodemanager.LinuxContainerExecutor.reacquireContainer(LinuxContainerExecutor.java:352)
at
org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:83)
at
org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:46)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2017-06-09 06:17:37,223 [INFO] [AsyncDispatcher event handler]
launcher.ContainerLaunch.cleanupContainer(ContainerLaunch.java:370) - Cleaning
up container container_1490916233553_1471_01_000016
2017-06-09 06:17:37,465 [INFO] [AsyncDispatcher event handler]
container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
container_1490916233553_1471_01_000016 transitioned from KILLING to
EXITED_WITH_FAILURE
2017-06-09 06:17:37,493 [INFO] [AsyncDispatcher event handler]
container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
container_1477351569246_0429_02_000129 transitioned from EXITED_WITH_FAILURE to
DONE
2017-06-09 06:17:37,493 [WARN] [AsyncDispatcher event handler]
nodemanager.NMAuditLogger.logFailure(NMAuditLogger.java:150) -
USER=samza-trust-repartition OPERATION=Container Finished - Failed
TARGET=ContainerImpl RESULT=FAILURE DESCRIPTION=Container failed with
state: EXITED_WITH_FAILURE APPID=application_1490916233553_1471
CONTAINERID=container_1490916233553_1471_01_000016
{code}
d. When an RM fail over happens, and the state is re-synced from the passive to
the active RM triggering a phantom notification.
> Handle phantom container notifications cleanly during RM fail-over
> ------------------------------------------------------------------
>
> Key: SAMZA-1359
> URL: https://issues.apache.org/jira/browse/SAMZA-1359
> Project: Samza
> Issue Type: Bug
> Reporter: Jagadish
> Assignee: Jagadish
>
> At LinkedIn, we have observed that there are phantom notifications
> corresponding to containers not being actively managed by Samza. We should
> improve our AppMaster's logic to be resilient to these phantom notifications.
> Currently, we take actions based on these notifications - for example, we
> increment the number of failed containers, mark the job health to be false
> etc. These actions cause false alerts to be fired and automated remediations
> based on these alerts. At LinkedIn, this has affected our ability to do
> upgrades on the Samza cluster because several jobs have to be restarted owing
> to these phantom notifications.
> Here's the investigation during an upgrade and a rolling bounce of the Samza
> ResourceManagers.
> 1. Samza starts container 13 on a certain host for this job.
> {code}
> 2017-06-07 19:46:20.226 [Container Allocator Thread] YarnContainerRunner
> [INFO] Claimed container ID 13 for container
> container_1490916233553_1471_01_000016 on node
> hostname_masked19956masked_host
> (http://hostname_masked19956masked_host:8042/node/containerlogs/container_1490916233553_1471_01_000016).
> {code}
> 2. Yarn reports that container 13 is lost due to a failure of its NodeManager
> on the host at which the container was running.
> {code}
> 2017-06-09 06:14:40.398 [AMRM Callback Handler Thread]
> YarnClusterResourceManager [INFO] Container completed from RM
> ContainerStatus: [ContainerId: container_1490916233553_1471_01_000016, State:
> COMPLETE, Diagnostics: Container released on a *lost* node, ExitStatus: -100,
> ]
> 2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
> YarnClusterResourceManager [INFO] Completed container had ID: 13
> 2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
> YarnClusterResourceManager [INFO] Removing container ID 13 from completed
> containers
> 2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
> ContainerProcessManager [INFO] Matching container ID found 13
> org.apache.samza.clustermanager.SamzaResource@e4e2d63a
> 2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
> ContainerProcessManager [INFO] Got an exit code of -100. This means that
> container container_1490916233553_1471_01_000016 was killed by YARN, either
> due to being released by the application master or being 'lost' due to node
> failures etc. or due to preemption by the RM
> 2017-06-09 06:14:40.401 [AMRM Callback Handler Thread]
> ContainerProcessManager [INFO] Released container
> container_1490916233553_1471_01_000016 was assigned task group ID 13.
> Requesting a refactor container for the task group.
> 2017-06-09 06:14:40.401 [AMRM Callback Handler Thread] SamzaResourceRequest
> [INFO] Resource Request created for 13 on ANY_HOST at 1496988880401
> {code}
> 3. Samza makes a request to Yarn for restarting container 13 on a different
> host.
> {code}
> 2017-06-09 06:14:40.402 [AMRM Callback Handler Thread]
> YarnClusterResourceManager [INFO] Requesting resources on ANY_HOST for
> container 13
> 2017-06-09 06:14:40.402 [AMRM Callback Handler Thread]
> YarnClusterResourceManager [INFO] Making a request for ANY_HOST ANY_HOST
> 2017-06-09 06:14:42.400 [AMRM Heartbeater thread] AMRMClientImpl [INFO]
> Received new token for : hostname_masked19939masked_host:1158
> 2017-06-09 06:14:42.401 [AMRM Callback Handler Thread]
> YarnClusterResourceManager [INFO] Container allocated from RM on
> hostname_masked19939masked_host
> 2017-06-09 06:14:42.401 [AMRM Callback Handler Thread]
> ContainerProcessManager [INFO] Container allocated from RM on
> hostname_masked19939masked_host
> 2017-06-09 06:14:42.401 [AMRM Callback Handler Thread] ResourceRequestState
> [INFO] Host affinity not enabled. Saving the samzaResource
> container_1490916233553_1471_01_000027 in the buffer for ANY_HOST
> 2017-06-09 06:14:44.310 [Container Allocator Thread]
> YarnClusterResourceManager [INFO] Cancelling request
> SamzaResourceRequest{numCores=1, memoryMB=4000, preferredHost='ANY_HOST',
> requestID='f74a8fcf-be17-42eb-8824-1c32b4504933', containerID=13,
> requestTimestampMs=1496988880401}
> 2017-06-09 06:14:44.310 [Container Allocator Thread]
> AbstractContainerAllocator [INFO] Found available resources on ANY_HOST.
> Assigning request for container_id 13 with timestamp 1496988880401 to
> resource container_1490916233553_1471_01_000027
> 2017-06-09 06:14:44.310 [Container Allocator Thread]
> YarnClusterResourceManager [INFO] Received launch request for 13 on hostname
> hostname_masked19939masked_host
> 2017-06-09 06:14:44.310 [Container Allocator Thread] YarnContainerRunner
> [INFO] Got available container ID (13) for container: Container:
> [ContainerId: container_1490916233553_1471_01_000027, NodeId:
> hostname_masked19939masked_host:1158, NodeHttpAddress:
> hostname_masked19939masked_host:8042, Resource: <memory:4096, vCores:1>,
> Priority: 0, Token: Token { kind: ContainerToken, service: 10.149.196.44:1158
> }, ]
> {code}
> 4. Container 13 is re-started and runs on a different host
> {code}
> 2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner
> [INFO] In runContainer in util: fwkPath= ;cmdPath=./__package/;jobLib=
> 2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner
> [INFO] Container ID 13 using command ./__package//bin/run-container.sh
> 2017-06-09 06:14:44.311 [Container Allocator Thread] YarnContainerRunner
> [INFO] Container ID 13 using environment variables:
> hostname_masked1348masked_host
> hostname_masked1355masked_host
> hostname_masked20440masked_host
> {code}
> 5. A cluster wide upgrade happens and the machines in the cluster have to be
> bounced. We typically do a rolling bounce on the RM to give an opportunity
> for the passive RM to take ownership. RM failover happens and state is
> re-synced from the passive to the active RM. Samza's AppMaster (which had a
> previous connection to the active RM) resyncs it's state from the other RM.
> {code}
> 2017-06-14 23:18:20.281 [AMRM Heartbeater thread] RetryInvocationHandler
> [INFO] Exception while invoking allocate of class
> ApplicationMasterProtocolPBClientImpl over yarn-prod-ltx1-samza-rm-2. Trying
> to fail over immediately.
> java.net.ConnectException: Call From
> hostname_masked19958masked_host/10.149.196.108 to
> hostname_masked1348masked_host:8030 failed on connection exception:
> java.net.ConnectException: Connection refused; For more details see:
> http://wiki.apache.org/hadoop/ConnectionRefused
> 2017-06-14 23:19:39.203 [AMRM Heartbeater thread] AMRMClientImpl [WARN]
> ApplicationMaster is out of sync with ResourceManager, hence resyncing.
> {code}
> 6. A phantom notification (duplicate) is received for the same container
> (Note the same container ID: container_1490916233553_1471_01_000016). This
> notification declares that the container exited with code 154.
> {code}
> Get a Container killed by RM error with non zero exit code 154
> 2017-06-14 23:19:39.211 [AMRM Callback Handler Thread]
> YarnClusterResourceManager [INFO] Container completed from RM
> ContainerStatus: [ContainerId: container_1490916233553_1471_01_000016, State:
> COMPLETE, Diagnostics: Container Killed by ResourceManager
> Container exited with a non-zero exit code 154
> , ExitStatus: 154, ]
> 2017-06-14 23:19:39.212 [AMRM Callback Handler Thread]
> YarnClusterResourceManager [INFO] Completed container had ID: -1
> 2017-06-14 23:19:39.212 [AMRM Callback Handler Thread]
> ContainerProcessManager [INFO] No matching container id found for
> SamzaResourceStatus{resourceID='container_1490916233553_1471_01_000016',
> diagnostics='Container Killed by ResourceManager
> Container exited with a non-zero exit code 154
> ', exitCode=154}
> 2017-06-14 23:19:39.212 [AMRM Callback Handler Thread]
> ContainerProcessManager [INFO] Container failed for some reason. Let's start
> it again
> 2017-06-14 23:19:39.212 [AMRM Callback Handler Thread]
> ContainerProcessManager [INFO] Container
> container_1490916233553_1471_01_000016 failed with exit code . 154 -
> Container Killed by ResourceManager
> Container exited with a non-zero exit code 154
> containerID is -1
> {code}
> 7. We take an action based on this phantom notification (and reset job
> health, other metrics). This causes automated false-alerts, and remediation
> to kick in. All jobs in the cluster have to be restarted now.
> *What scenarios on the Node Manager side trigger the phantom notification?*
> We have observed that if a node manager is re-started after a failure, NM
> recovery kicks in and tries to take ownership of containers it was managing
> in its previous run. In some cases, the container could have been killed /
> exited before the node manager comes back up. This would result in a timeout
> in the NM recovery process.
> Here are the relevant logs :
> a. NM is killed due to some errors and auto re-started. It was down from
> 06:01 to 06:17.
> {code}
> 06:17:29,470 [INFO] [main] util.LogAdapter.info(LogAdapter.java:45) -
> STARTUP_MSG:
> /************************************************************
> STARTUP_MSG: Starting NodeManager
> STARTUP_MSG: host = hostname_masked19956masked_host/10.149.196.106
> STARTUP_MSG: args = []
> STARTUP_MSG: version = 2.7.3
> {code}
> b. NM recovery kicks in trying to own previous containers
> {code}
> 2017-06-09 06:17:32,899 [INFO] [main]
> containermanager.ContainerManagerImpl.recoverContainer(ContainerManagerImpl.java:307)
> - Recovering container_1490916233553_1471_01_000016 in state LAUNCHED with
> exit code -1000
> 2017-06-09 06:17:33,115 [INFO] [main]
> containermanager.ContainerManagerImpl.waitForRecoveredContainers
> 2017-06-09 06:17:33,274 [INFO] [AsyncDispatcher event handler]
> application.ApplicationImpl$InitContainerTransition.transition(ApplicationImpl.java:304)
> - Adding container_1490916233553_1471_01_000016 to application
> application_1490916233553_1471
> 2017-06-09 06:17:33,387 [INFO] [AsyncDispatcher event handler]
> container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
> container_1490916233553_1471_01_000016 transitioned from LOCALIZING to
> LOCALIZED
> 2017-06-09 06:17:33,427 [INFO] [ContainersLauncher #39]
> nodemanager.ContainerExecutor.reacquireContainer(ContainerExecutor.java:181)
> - Reacquiring container_1490916233553_1471_01_000016 with pid 23848
> reqcquireing pid
> 2017-06-09 06:17:33,449 [INFO] [AsyncDispatcher event handler]
> container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
> container_1490916233553_1471_01_000016 transitioned from LOCALIZED to RUNNING
> 2017-06-09 06:17:35,094 Sending diagnostics
> [container_1490916233553_1471_01_000016, CreateTime: 1496864777558, State:
> RUNNING, Capability: <memory:4096, vCores:1>, Diagnostics: , ExitStatus:
> -1000, Priority: 0]
> {code}
> c. Recovery times out because the container already exited (due to an
> unrelated error)
> {code}
> 2017-06-09 06:17:35,592 [WARN] [ContainersLauncher #39]
> util.CgroupsLCEResourcesHandler.checkAndDeleteCgroup(CgroupsLCEResourcesHandler.java:324)
> - Failed to read cgroup tasks file.
> java.io.FileNotFoundException:
> /cgroup/cpu/restrain.slice/container_1490916233553_1471_01_000016/tasks (No
> such file or directory)
> at java.io.FileInputStream.open0(Native Method)
> at java.io.FileInputStream.open(FileInputStream.java:195)
> at java.io.FileInputStream.<init>(FileInputStream.java:138)
> at java.io.FileInputStream.<init>(FileInputStream.java:93)
> at
> org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.checkAndDeleteCgroup(CgroupsLCEResourcesHandler.java:308)
> at
> org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.deleteCgroup(CgroupsLCEResourcesHandler.java:339)
> at
> org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.clearLimits(CgroupsLCEResourcesHandler.java:388)
> at
> org.apache.hadoop.yarn.server.nodemanager.util.CgroupsLCEResourcesHandler.postExecute(CgroupsLCEResourcesHandler.java:402)
> at
> org.apache.hadoop.yarn.server.nodemanager.LinuxContainerExecutor.reacquireContainer(LinuxContainerExecutor.java:354)
> at
> org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:83)
> at
> org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:46)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> 2017-06-09 06:17:36,608 [ERROR] [ContainersLauncher #39]
> launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:88) -
> Unable to recover container container_1490916233553_1471_01_000016
> java.io.IOException: Timeout while waiting for exit code from
> container_1490916233553_1471_01_000016
> at
> org.apache.hadoop.yarn.server.nodemanager.ContainerExecutor.reacquireContainer(ContainerExecutor.java:202)
> at
> org.apache.hadoop.yarn.server.nodemanager.LinuxContainerExecutor.reacquireContainer(LinuxContainerExecutor.java:352)
> at
> org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:83)
> at
> org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.RecoveredContainerLaunch.call(RecoveredContainerLaunch.java:46)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> 2017-06-09 06:17:37,223 [INFO] [AsyncDispatcher event handler]
> launcher.ContainerLaunch.cleanupContainer(ContainerLaunch.java:370) -
> Cleaning up container container_1490916233553_1471_01_000016
> 2017-06-09 06:17:37,465 [INFO] [AsyncDispatcher event handler]
> container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
> container_1490916233553_1471_01_000016 transitioned from KILLING to
> EXITED_WITH_FAILURE
> 2017-06-09 06:17:37,493 [INFO] [AsyncDispatcher event handler]
> container.ContainerImpl.handle(ContainerImpl.java:1135) - Container
> container_1477351569246_0429_02_000129 transitioned from EXITED_WITH_FAILURE
> to DONE
> 2017-06-09 06:17:37,493 [WARN] [AsyncDispatcher event handler]
> nodemanager.NMAuditLogger.logFailure(NMAuditLogger.java:150) -
> USER=samza-trust-repartition OPERATION=Container Finished - Failed
> TARGET=ContainerImpl RESULT=FAILURE DESCRIPTION=Container failed with
> state: EXITED_WITH_FAILURE APPID=application_1490916233553_1471
> CONTAINERID=container_1490916233553_1471_01_000016
> {code}
> d. When an RM fail over happens, and the state is re-synced from the passive
> to the active RM triggering a phantom notification.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
