Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Cannot Reproduce
-
None
-
None
-
None
-
None
Description
Hi,
I've been testing Mesos in the context of a framework I'm developing.
As part of the integration tests, I send SIGSTOP/SIGCONT randomly to processes, to simulate for example if they got blocked because of memory pressure or whatever.
While doing this, I encountered a situation where a task would remain in TASK_STAGING forever.
Here's the log when the slave is resumed with SIGCONT:
2020-01-16 09:43:29,797:45(0x7fbfd4ad9700):ZOO_ERROR@handle_socket_error_msg@1782: Socket [127.0.0.1:40125] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
2020-01-16 09:43:29,797:45(0x7fbfd4ad9700):ZOO_WARN@zookeeper_interest@1597: Exceeded deadline by 23153ms
2020-01-16 09:43:29,797:45(0x7fbfd4ad9700):ZOO_INFO@check_events@1764: initiated connection to server [127.0.0.1:33437]
I0116 09:43:29.798094 124 group.cpp:452] Lost connection to ZooKeeper, attempting to reconnect ...
I0116 09:43:29.798627 83 master.cpp:7083] Received register agent message from slave(1)@192.168.65.76:51553 (lhpcb008.london.quadraturecapital.com)
I0116 09:43:29.798707 83 master.cpp:7262] Registering agent at slave(1)@192.168.65.76:51553 (lhpcb008.london.quadraturecapital.com) with id 9886c82f-1c92-41d8-bc47-bfd614e669af-S4
I0116 09:43:29.798784 83 registrar.cpp:487] Applied 1 operations in 40710ns; attempting to update the registry
I0116 09:43:29.798921 83 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 11
I0116 09:43:29.799089 83 replica.cpp:541] Replica received write request for position 11 from __req_res__(54)@127.0.0.1:46799
I0116 09:43:29.799271 158 replica.cpp:541] Replica received write request for position 11 from __req_res__(56)@127.0.0.1:46799
2020-01-16 09:43:29,799:45(0x7fbfd4ad9700):ZOO_ERROR@handle_socket_error_msg@1800: Socket [127.0.0.1:33437] zk retcode=-112, errno=116(Stale file handle): sessionId=0x16fadbc14f50003 has expired.
I0116 09:43:29.799561 97 replica.cpp:541] Replica received write request for position 11 from __req_res__(55)@127.0.0.1:46799
I0116 09:43:29.799762 129 group.cpp:511] ZooKeeper session expired
I0116 09:43:29.799824 127 detector.cpp:152] Detected a new leader: None
I0116 09:43:29.799873 127 slave.cpp:1344] Lost leading master
I0116 09:43:29.799882 127 slave.cpp:1416] Detecting new master
I0116 09:43:29.799893 127 task_status_update_manager.cpp:181] Pausing sending task status updates
I0116 09:43:29.799898 127 status_update_manager_process.hpp:379] Pausing operation status update manager
I0116 09:43:29.800115 80 replica.cpp:695] Replica received learned notice for position 11 from log-network(1)@127.0.0.1:46799
I0116 09:43:29.800271 81 registrar.cpp:544] Successfully updated the registry in 1.467136ms
I0116 09:43:29.800348 81 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 12
I0116 09:43:29.800462 81 replica.cpp:541] Replica received write request for position 12 from __req_res__(57)@127.0.0.1:46799
I0116 09:43:29.800529 82 hierarchical.cpp:955] Added agent 9886c82f-1c92-41d8-bc47-bfd614e669af-S4 (lhpcb008.london.quadraturecapital.com) with cpus:4; mem:30844; disk:4096; ports:[31000-32000] (offered or allocated: {})
I0116 09:43:29.800549 84 master.cpp:7355] Registered agent 9886c82f-1c92-41d8-bc47-bfd614e669af-S4 at slave(1)@192.168.65.76:51553 (lhpcb008.london.quadraturecapital.com) with cpus:4; mem:30844; disk:4096; ports:[31000-32000]
2020-01-16 09:43:29,800:45(0x7fbfd72de700):ZOO_INFO@zookeeper_close@2579: Freeing zookeeper resources for sessionId=0x16fadbc14f50003
I0116 09:43:29.800671 81 master.cpp:10409] Sending offers [ 9886c82f-1c92-41d8-bc47-bfd614e669af-O67 ] to framework 9886c82f-1c92-41d8-bc47-bfd614e669af-0000 (gus) at scheduler-54f808ba-f696-49b8-99c6-3d821ee8ef8f@192.168.65.76:37061
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@log_env@753: Client environment:zookeeper.version=zookeeper C client 3.4.8
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@log_env@757: Client environment:host.name=lhpcb008
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@log_env@764: Client environment:os.name=Linux
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@log_env@765: Client environment:os.arch=4.15.0-72-generic
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@log_env@766: Client environment:os.version=#81-Ubuntu SMP Tue Nov 26 12:20:02 UTC 2019
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@log_env@774: Client environment:user.name=charles
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@log_env@782: Client environment:user.home=/home/charles
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@log_env@794: Client environment:user.dir=/scratch/charles/bazel_base/519e0914f77a57b1c958838821782354/sandbox/linux-sandbox/11837/execroot/__main__/bazel-out/k8-opt/bin/cpp/tests/integration_test_2.runfiles/__main__
2020-01-16 09:43:29,800:45(0x7fbfd62dc700):ZOO_INFO@zookeeper_init@827: Initiating client connection, host=127.0.0.1:44283,127.0.0.1:33437,127.0.0.1:40125 sessionTimeout=10000 watcher=0x7fbfe5632340 sessionId=0 sessionPasswd=<null> context=0x7fbfcc002f18 flags=0
W0116 09:43:29.801195 126 slave.cpp:1559] Ignoring registration message from master@127.0.0.1:46799 because it is not the expected master: None
Here's the task being received by the master:
I0116 09:43:29.839668 83 master.cpp:4287] Adding task gus:random_error_eventually_succeeds:job-2:05cfcdc4-11e3-cea2-51ab-003c5030a74d with resources mem(allocated: *):1024; cpus(allocated: *):1 of framework 9886c82f-1c92-41d8-bc47-bfd614e669af-0000 (gus) at scheduler-54f808ba-f696-49b8-99c6-3d821ee8ef8f@192.168.65.76:37061 on agent 9886c82f-1c92-41d8-bc47-bfd614e669af-S4 at slave(1)@192.168.65.76:51553 (lhpcb008.london.quadraturecapital.com)
It's forwarded to the slave:
I0116 09:43:29.839741 83 master.cpp:5714] Launching task gus:random_error_eventually_succeeds:job-2:05cfcdc4-11e3-cea2-51ab-003c5030a74d of framework 9886c82f-1c92-41d8-bc47-bfd614e669af-0000 (gus) at scheduler-54f808ba-f696-49b8-99c6-3d821ee8ef8f@192.168.65.76:37061 with resources [{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"}] on agent 9886c82f-1c92-41d8-bc47-bfd614e669af-S4 at slave(1)@192.168.65.76:51553 (lhpcb008.london.quadraturecapital.com) on new executor
I0116 09:43:29.840129 128 slave.cpp:2130] Got assigned task 'gus:random_error_eventually_succeeds:job-2:05cfcdc4-11e3-cea2-51ab-003c5030a74d' for framework 9886c82f-1c92-41d8-bc47-bfd614e669af-0000
But decides to ignore it:
W0116 09:43:29.840143 128 slave.cpp:2135] Agent ignoring running task 'gus:random_error_eventually_succeeds:job-2:05cfcdc4-11e3-cea2-51ab-003c5030a74d' because it was intended for old agent 9886c82f-1c92-41d8-bc47-bfd614e669af-S4
After that, all reconciliations returned the task as TASK_STAGING:
mesos_task_id {
value: "gus:random_error_eventually_succeeds:job-2:05cfcdc4-11e3-cea2-51ab-003c5030a74d"
}
state: TASK_STAGING
source: "SOURCE_MASTER"
reason: "REASON_RECONCILIATION"
message: "Reconciliation: Latest task state"
Unfortunately this test run has the logs from the various processes (Mesos masters and agents) intermingled so I can't easily extract them, although if necessary I can probably try and reproduce it.