[
https://issues.apache.org/jira/browse/MESOS-5200?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15239816#comment-15239816
]
David Robinson commented on MESOS-5200:
---------------------------------------
This is a bit different from MESOS-1963. In this case exited() is not called
because there was no connection established to begin with. Here's a snippet
from the agent's log that shows the problem:
{noformat}
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0412 23:53:02.659906 49978 process.cpp:986] libprocess is initialized on
10.20.30.41:5051 for 24 cpus
I0412 23:53:02.660006 49978 logging.cpp:193] Logging to STDERR
I0412 23:53:02.660038 49978 main.cpp:223] Build: 2016-04-07 20:47:21 by
mockbuild
I0412 23:53:02.660048 49978 main.cpp:225] Version: 0.28.1-rc2
/sbin/init: invalid option -- -
Usage: init 0123456SsQqAaBbCcUu
E0412 23:53:02.663058 49978 shell.hpp:93] Command '/sbin/init --version'
failed; this is the output:
W0412 23:53:02.663101 49978 systemd.cpp:213] Failed to test command '/sbin/init
--version': Failed to execute '/sbin/init --version'; the command was either
not found or exited with a non-zero exit status: 1
I0412 23:53:02.663269 49978 containerizer.cpp:149] Using isolation:
cgroups/cpu,cgroups/mem,posix/disk,cgroups/perf_event,filesystem/posix
I0412 23:53:02.666448 49978 linux_launcher.cpp:101] Using
/sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
I0412 23:53:02.678097 49978 perf_event.cpp:71] Creating PerfEvent isolator
I0412 23:53:02.813138 49978 perf_event.cpp:109] PerfEvent isolator will profile
for 10secs every 1mins for events: { L1-dcache-load-misses, L1-dcache-loads,
L1-dcache-store-misses, L1-dcache-stores, LLC-load-misses, LLC-loads,
LLC-store-misses, LLC-stores, context-switches, cpu-migrations, cycles,
instructions, page-faults, stalled-cycles-backend, stalled-cycles-frontend,
task-clock }
I0412 23:53:02.815750 49978 main.cpp:328] Starting Mesos slave
I0412 23:53:02.816100 49984 slave.cpp:193] Slave started on 1)@10.20.30.41:5051
I0412 23:53:02.816126 49984 slave.cpp:194] Flags at startup: <removed>
I0412 23:53:02.816416 49984 slave.cpp:214] Moving slave process into its own
cgroup for subsystem: memory
I0412 23:53:02.820659 49984 slave.cpp:214] Moving slave process into its own
cgroup for subsystem: cpuacct
I0412 23:53:02.824148 49984 resources.cpp:572] Parsing resources as JSON
failed: cpus:24;mem:70247;ports:[31000-32000];disk:400000
Trying semicolon-delimited string format instead
I0412 23:53:02.824784 49984 slave.cpp:464] Slave resources: cpus(*):24;
mem(*):70247; ports(*):[31000-32000]; disk(*):400000
I0412 23:53:02.824846 49984 slave.cpp:472] Slave attributes: [ rack=rack1,
host=server-001 ]
I0412 23:53:02.824854 49984 slave.cpp:477] Slave hostname:
server-001.prod.twitter.com
I0412 23:53:02.827628 49993 state.cpp:58] Recovering state from
'/var/lib/mesos/meta'
I0412 23:53:02.827711 49984 slave.cpp:749] Successfully attached file
'/var/log/mesos/mesos-slave.log'
I0412 23:53:02.828263 49993 fetcher.cpp:81] Clearing fetcher cache
I0412 23:53:02.828385 49997 status_update_manager.cpp:200] Recovering status
update manager
I0412 23:53:02.828562 49979 containerizer.cpp:407] Recovering containerizer
I0412 23:53:02.830425 49980 provisioner.cpp:245] Provisioner recovery complete
I0412 23:53:02.830636 50000 slave.cpp:4565] Finished recovery
I0412 23:53:02.830945 50000 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:53:02.831030 49985 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:53:02.831082 49985 slave.cpp:796] New master detected at
[email protected]:5050
I0412 23:53:02.831085 49999 status_update_manager.cpp:174] Pausing sending
status updates
I0412 23:53:02.831219 49985 slave.cpp:821] No credentials provided. Attempting
to register without authentication
I0412 23:53:02.831240 49985 slave.cpp:832] Detecting new master
I0412 23:53:02.831496 50003 poll_socket.cpp:110] Socket error while connecting
I0412 23:53:02.831535 50003 process.cpp:1328] Failed to link, connect: Socket
error while connecting
E0412 23:53:02.831588 50003 process.cpp:1958] Failed to shutdown socket with fd
7: Transport endpoint is not connected
I0412 23:53:02.831640 49996 slave.cpp:3528] [email protected]:5050 exited
W0412 23:53:02.831670 49996 slave.cpp:3531] Master disconnected! Waiting for a
new master to be elected
I0412 23:53:04.381392 49985 slave.cpp:1321] Will retry registration in
1.174712274secs if necessary
I0412 23:53:04.381731 50003 poll_socket.cpp:110] Socket error while connecting
I0412 23:53:04.381779 50003 process.cpp:1650] Failed to send
'mesos.internal.ReregisterSlaveMessage' to '10.20.30.40:5050', connect: Socket
error while connecting
E0412 23:53:04.381817 50003 process.cpp:1958] Failed to shutdown socket with fd
7: Transport endpoint is not connected
I0412 23:53:05.557142 49996 slave.cpp:1321] Will retry registration in
917.34251ms if necessary
I0412 23:53:05.557443 50003 poll_socket.cpp:110] Socket error while connecting
I0412 23:53:05.557479 50003 process.cpp:1650] Failed to send
'mesos.internal.ReregisterSlaveMessage' to '10.20.30.40:5050', connect: Socket
error while connecting
E0412 23:53:05.557512 50003 process.cpp:1958] Failed to shutdown socket with fd
7: Transport endpoint is not connected
I0412 23:53:06.475718 49997 slave.cpp:1321] Will retry registration in
13.848557031secs if necessary
I0412 23:53:06.475955 50003 poll_socket.cpp:110] Socket error while connecting
I0412 23:53:06.475985 50003 process.cpp:1650] Failed to send
'mesos.internal.ReregisterSlaveMessage' to '10.20.30.40:5050', connect: Socket
error while connecting
E0412 23:53:06.476008 50003 process.cpp:1958] Failed to shutdown socket with fd
7: Transport endpoint is not connected
I0412 23:53:12.696146 49985 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:53:17.832080 49987 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:53:17.832159 49987 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:53:20.325412 49987 slave.cpp:1321] Will retry registration in
23.072185258secs if necessary
I0412 23:53:20.325523 50003 poll_socket.cpp:110] Socket error while connecting
I0412 23:53:20.325564 50003 process.cpp:1650] Failed to send
'mesos.internal.ReregisterSlaveMessage' to '10.20.30.40:5050', connect: Socket
error while connecting
E0412 23:53:20.325603 50003 process.cpp:1958] Failed to shutdown socket with fd
7: Transport endpoint is not connected
I0412 23:53:22.721534 49982 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:53:32.746141 49979 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:53:32.832667 49986 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:53:32.832731 49986 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:53:42.769896 49986 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:53:43.398363 49986 slave.cpp:1321] Will retry registration in
2.949747602secs if necessary
I0412 23:53:46.349140 49981 slave.cpp:1321] Will retry registration in
26.946306725secs if necessary
I0412 23:53:47.833734 49995 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:53:47.833823 49995 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:53:52.795567 49995 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:54:01.002315 49979 process.cpp:3136] Handling HTTP event for process
'metrics' with path: '/metrics/snapshot'
I0412 23:54:01.002447 49980 process.cpp:3136] Handling HTTP event for process
'monitor' with path: '/monitor/statistics.json'
I0412 23:54:02.821105 49999 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:54:02.826086 49981 slave.cpp:4374] Current disk usage 3.27%. Max
allowed age: 6.070797005046562days
I0412 23:54:02.834043 49981 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:54:02.834103 49981 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:54:12.844379 49981 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:54:13.296638 49992 slave.cpp:1321] Will retry registration in
59.188026766secs if necessary
I0412 23:54:13.305814 50001 slave.cpp:3482] Received ping from
slave-observer(3)@10.20.30.40:5050
I0412 23:54:13.306068 49992 slave.cpp:1071] Re-registered with master
[email protected]:5050
I0412 23:54:13.306112 49992 slave.cpp:1107] Forwarding total oversubscribed
resources
I0412 23:54:13.306120 49990 status_update_manager.cpp:181] Resuming sending
status updates
I0412 23:54:13.306308 49992 slave.cpp:2341] Updated checkpointed resources from
to
I0412 23:54:17.834607 50002 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:54:17.834707 49999 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:54:22.868903 49982 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:54:28.306063 49997 slave.cpp:3482] Received ping from
slave-observer(3)@10.20.30.40:5050
I0412 23:54:32.835927 49980 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:54:32.836007 49980 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:54:32.893705 49985 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:54:42.916491 49979 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:54:43.306737 49987 slave.cpp:3482] Received ping from
slave-observer(3)@10.20.30.40:5050
I0412 23:54:47.836699 49980 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:54:47.836778 49980 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:54:52.940803 49980 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
I0412 23:54:58.306947 49999 slave.cpp:3482] Received ping from
slave-observer(3)@10.20.30.40:5050
I0412 23:55:01.002145 49987 process.cpp:3136] Handling HTTP event for process
'metrics' with path: '/metrics/snapshot'
I0412 23:55:01.002187 49988 process.cpp:3136] Handling HTTP event for process
'monitor' with path: '/monitor/statistics.json'
I0412 23:55:02.826681 49979 slave.cpp:4374] Current disk usage 3.27%. Max
allowed age: 6.070795051374792days
I0412 23:55:02.837705 49979 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0412 23:55:02.837800 49982 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0412 23:55:02.969967 49986 process.cpp:3136] Handling HTTP event for process
'slave(1)' with path: '/slave(1)/health'
{noformat}
> agent->master messages use temporary TCP connections
> ----------------------------------------------------
>
> Key: MESOS-5200
> URL: https://issues.apache.org/jira/browse/MESOS-5200
> Project: Mesos
> Issue Type: Bug
> Reporter: David Robinson
>
> Background info: When an agent is started it starts a background task
> (libprocess process?) to detect the leading master. When the leading master
> is detected (or changes) the [SocketManager's link()
> method|https://github.com/apache/mesos/blob/master/3rdparty/libprocess/src/process.cpp#L1415]
> [is
> called|https://github.com/apache/mesos/blob/master/src/slave/slave.cpp#L942]
> and a TCP connection to the master is established. The connection is used by
> the agent to send messages to the master, and the master, upon receiving a
> RegisterSlaveMessage/ReregisterSlaveMessage, establishes another TCP
> connection back to the agent. Each TCP connection is uni-directional, the
> agent writes messages on one connection and reads messages from the other,
> and the master reads/writes from the opposite ends of the connections.
> If the initial TCP connection to the master fails to be established then
> temporary connections are used for all agent->master messages; each send()
> causes a new TCP connection to be setup, the message sent, then the
> connection torn down. If link() succeeds a persistent TCP connection is used
> instead.
> If agents do not use ZK to detect the master then the master detector
> "detects" the master immediately and attempts to connect immediately. The
> master may not be listening for connections at the time, or it could be
> overwhelmed w/ TCP connection attempts, therefore the initial TCP connection
> attempt fails. The agent does not attempt to establish a new persistent
> connection as link() is only called when a new master is detected, which only
> occurs once unless ZK is used.
> It's possible for agents to overwhelm a master w/ TCP connections such that
> agents cannot establish connections. When this occurs pong messages may not
> be received by the master so the master shuts down agents thus killing any
> tasks they were running. We have witnessed this scenario during scale/load
> tests at Twitter.
> The problem is trivial to reproduce: configure an agent to use a certain
> master (\-\-master=10.20.30.40:5050), start the agent, wait several minutes
> then start the master. All the agent->master messages will occur over
> temporary connections.
> The problem occurs less frequently in production because ZK is typically used
> for master detection and a master only registers in ZK after it has started
> listening on its socket. However, the scenario described above can also occur
> when ZK is used – a thundering herd of 10,000+ slaves establishing TCP
> connections to the master can result in some connection attempts failing and
> agents using temporary connections.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
