Reconnected slaves not sending resource offers?

[Thomas Petr <tp...@hubspot.com>]

Hi there,

Some of our Mesos slaves (running version 0.23) got into a strange state
last week. A networking blip from ~20:59 to ~21:03 in AWS caused a number
of slaves to lose connectivity to the Mesos master:

I0421 21:00:46.351019 85618 slave.cpp:3077] No pings from master
received within 75secs
I0421 21:00:46.355203 85594 status_update_manager.cpp:176] Pausing
sending status updates
I0421 21:00:46.355406 85622 slave.cpp:673] Re-detecting master
I0421 21:00:46.355630 85622 slave.cpp:720] Detecting new master
I0421 21:00:46.356101 85603 status_update_manager.cpp:176] Pausing
sending status updates
I0421 21:00:46.356115 85622 slave.cpp:684] New master detected at
master@172.16.22.2:5050
I0421 21:00:46.357239 85622 slave.cpp:709] No credentials provided.
Attempting to register without authentication
I0421 21:00:46.357364 85622 slave.cpp:720] Detecting new master

These slaves were shut down and removed by the master, and their
corresponding tasks were all marked as TASK_LOST:

I0421 21:01:01.355435 17076 master.cpp:241] Shutting down slave
20151116-203245-4077719724-5050-17017-S208 due to health check timeout
W0421 21:01:01.355556 17076 master.cpp:3913] Shutting down slave
20151116-203245-4077719724-5050-17017-S208 at
slave(1)@172.16.3.103:5051 (lively-rice) with message 'health check
timed out'
I0421 21:01:01.355660 17076 master.cpp:4974] Removing slave
20151116-203245-4077719724-5050-17017-S208 at
slave(1)@172.16.3.103:5051 (lively-rice): health check timed out
...snip...
I0421 21:01:01.498541 17073 master.cpp:5079] Removed slave
20151116-203245-4077719724-5050-17017-S208 (lively-rice): health check
timed out
I0421 21:01:01.501723 17073 master.cpp:5102] Notifying framework sy3x4
(sy3x4) at scheduler-6a46b6f2-ccf8-416b-b8ba-7bef99576197@172.16.40.17:38483
of lost slave 20151116-203245-4077719724-5050-17017-S208 (lively-rice)
after recovering

The networking issues eventually clear up. The slaves attempt to
re-register with the master, but are shut down due to the master having
removed them:

I0421 21:03:13.789948 85612 slave.cpp:606] Slave asked to shut down by
master@172.16.22.2:5050 because 'health check timed out'
I0421 21:03:13.791801 85612 slave.cpp:1946] Asked to shut down
framework sy3x4 by master@172.16.22.2:5050
I0421 21:03:13.791960 85612 slave.cpp:1971] Shutting down framework sy3x4
I0421 21:03:13.793388 85612 slave.cpp:3667] Shutting down executor
'4ki18' of framework sy3x4
I0421 21:03:13.793678 85612 slave.cpp:3667] Shutting down executor
'8cjp8' of framework sy3x4
I0421 21:03:13.793822 85612 slave.cpp:3667] Shutting down executor
't4ila' of framework sy3x4
I0421 21:03:13.794312 85612 slave.cpp:3667] Shutting down executor
'1al5a' of framework sy3x4
I0421 21:03:13.794628 85612 slave.cpp:3667] Shutting down executor
'i4qp9' of framework sy3x4
...snip...
I0421 21:03:13.820853 85612 slave.cpp:606] Slave asked to shut down by
master@172.16.22.2:5050 because 'Slave attempted to re-register after
removal'
I0421 21:03:13.821146 85612 slave.cpp:1946] Asked to shut down
framework sy3x4 by master@172.16.22.2:5050
W0421 21:03:13.821462 85612 slave.cpp:1967] Ignoring shutdown
framework sy3x4 because it is terminating
...snip...
I0421 21:03:19.281539 85617 slave.cpp:606] Slave asked to shut down by
master@172.16.22.2:5050 because 'Executor exited message from unknown
slave'
I0421 21:03:19.281738 85617 slave.cpp:1946] Asked to shut down
framework sy3x4 by master@172.16.22.2:5050
W0421 21:03:19.281782 85617 slave.cpp:1967] Ignoring shutdown
framework sy3x4 because it is terminating
...snip...
I0421 21:03:23.154587 85619 slave.cpp:564] Slave terminating

Monit starts up the mesos-slave process again, and the affected slaves
successfully register with the master with new slave IDs:

2016-04-21 21:03:31,210:53195(0x7ff160eb8700):ZOO_INFO@check_events@1750:
session establishment complete on server [172.16.5.8:2181],
sessionId=0x1751d0ed4b004cbb, negotiated timeout=10000
I0421 21:03:31.210914 53209 group.cpp:313] Group process
(group(1)@172.16.3.103:5051) connected to ZooKeeper
I0421 21:03:31.210963 53209 group.cpp:787] Syncing group operations:
queue size (joins, cancels, datas) = (0, 0, 0)
I0421 21:03:31.210979 53209 group.cpp:385] Trying to create path
'/mesos/mesos_prod_3x4' in ZooKeeper
I0421 21:03:31.212005 53198 state.cpp:36] Recovering state from
'/usr/share/hubspot/mesos/meta'
I0421 21:03:31.213176 53198 state.cpp:79] Failed to find the latest
slave from '/usr/share/hubspot/mesos/meta'
I0421 21:03:31.213376 53198 status_update_manager.cpp:202] Recovering
status update manager
...snip...
I0421 21:03:31.228364 53229 status_update_manager.cpp:176] Pausing
sending status updates
I0421 21:03:31.228436 53218 slave.cpp:684] New master detected at
master@172.16.22.2:5050
I0421 21:03:31.228768 53218 slave.cpp:709] No credentials provided.
Attempting to register without authentication
I0421 21:03:31.228844 53218 slave.cpp:720] Detecting new master
I0421 21:03:31.228996 53218 slave.cpp:4193] Received oversubscribable
resources  from the resource estimator
I0421 21:03:31.229069 53214 cgroups.cpp:1415] Successfully froze
cgroup /cgroup/freezer/mesos/89e71e43-c7ea-4a86-a2b9-f528e8bb0346
after 3.120896ms
I0421 21:03:31.230046 53211 cgroups.cpp:1444] Successfullly thawed
cgroup /cgroup/freezer/mesos/2efbe99b-6b36-411e-b351-af670398b4ae
after 2.013952ms
I0421 21:03:31.230401 53196 cgroups.cpp:1444] Successfullly thawed
cgroup /cgroup/freezer/mesos/5daaa7d5-ffb7-45b6-bd90-30343f90a3c4
after 2.036992ms
I0421 21:03:31.231226 53220 cgroups.cpp:2399] Thawing cgroup
/cgroup/freezer/mesos/89e71e43-c7ea-4a86-a2b9-f528e8bb0346
I0421 21:03:31.233616 53217 cgroups.cpp:1444] Successfullly thawed
cgroup /cgroup/freezer/mesos/89e71e43-c7ea-4a86-a2b9-f528e8bb0346
after 2.216192ms
I0421 21:03:32.016067 53204 slave.cpp:859] Registered with master
master@172.16.22.2:5050; given slave ID
20151116-203437-35000492-5050-17068-S70
I0421 21:03:32.016317 53215 status_update_manager.cpp:183] Resuming
sending status updates

Everything makes perfect sense up to this point. The slaves appear to be
online and connected to the cluster, but we quickly noticed that these
slaves were not sending resource offers to the master. This seemed
especially wrong because these slave had recently started up and had no
tasks running on them.

The only thing that ended up fixing the situation was bouncing our
scheduler (~10 minutes after the restarted slaves joined the cluster) --
the act of failing over the framework appeared to "recover" the missing
resources:

I0421 21:13:13.806171 17072 hierarchical.hpp:761] Recovered
mem(*):217609; cpus(*):210; ports(*):[2048-3048]; disk(*):639829
(total: mem(*):217609; cpus(*):210; ports(*):[2048-3048];
disk(*):639829, allocated: ) on slave
20151116-203437-35000492-5050-17068-S70 from framework sy3x4

I assume this situation isn't expected -- does anyone have an insight into
this?

Thanks,
Tom

Re: Reconnected slaves not sending resource offers?

[Thomas Petr <tp...@hubspot.com>]

Ah, thanks for the clarification. I can't find any logs from the framework
indicating that we got the initial offer, so it looks like it could have
been dropped. We haven't set --offer-timeout on our masters, so your
explanation makes sense. Thanks!

On Mon, Apr 25, 2016 at 4:17 PM, Vinod Kone <vi...@apache.org> wrote:

>
> I0421 21:03:32.014999 17071 master.cpp:4290] Sending 1 offers to
>> framework sy3x4 (sy3x4) at
>> scheduler-6bb2bcf0-d060-4072-a25b-917d8007fb1c@172.16.13.243:56861
>>
>
> This shows that the slaves resources were sent to a framework. Looks like
> the framework is holding on to the offer for a long time?
>
>
>> I0421 21:03:32.019800 17076 hierarchical.hpp:588] Slave
>> 20151116-203437-35000492-5050-17068-S70 (lively-rice) updated with
>> oversubscribed resources  (total: mem(*):217609; cpus(*):210;
>> ports(*):[2048-3048]; disk(*):639829, allocated: mem(*):217609;
>> cpus(*):210; ports(*):[2048-3048]; disk(*):639829)
>>
>
> This says that from the view point of master/allocator, all the resources
> are allocated. This is because the framework hasn't replied to the offer.
> Did the framework receive the offer or was it dropped by the network due to
> the networking issues?
>
>

Re: Reconnected slaves not sending resource offers?

[Vinod Kone <vi...@apache.org>]

> I0421 21:03:32.014999 17071 master.cpp:4290] Sending 1 offers to
> framework sy3x4 (sy3x4) at
> scheduler-6bb2bcf0-d060-4072-a25b-917d8007fb1c@172.16.13.243:56861
>

This shows that the slaves resources were sent to a framework. Looks like
the framework is holding on to the offer for a long time?


> I0421 21:03:32.019800 17076 hierarchical.hpp:588] Slave
> 20151116-203437-35000492-5050-17068-S70 (lively-rice) updated with
> oversubscribed resources  (total: mem(*):217609; cpus(*):210;
> ports(*):[2048-3048]; disk(*):639829, allocated: mem(*):217609;
> cpus(*):210; ports(*):[2048-3048]; disk(*):639829)
>

This says that from the view point of master/allocator, all the resources
are allocated. This is because the framework hasn't replied to the offer.
Did the framework receive the offer or was it dropped by the network due to
the networking issues?

Re: Reconnected slaves not sending resource offers?

[Thomas Petr <tp...@hubspot.com>]

I0421 21:03:32.014533 17073 hierarchical.hpp:528] Added slave
20151116-203437-35000492-5050-17068-S70 (lively-rice) with mem(*):217609;
cpus(*):210; ports(*):[2048-3048]; disk(*):639829 (allocated: )
I0421 21:03:32.014529 17072 master.cpp:3395] Registered slave
20151116-203437-35000492-5050-17068-S70 at slave(1)@172.16.3.103:5051
(lively-rice) with mem(*):217609; cpus(*):210; ports(*):[2048-3048];
disk(*):639829
I0421 21:03:32.014673 17076 coordinator.cpp:340] Coordinator attempting to
write TRUNCATE action at position 4102
I0421 21:03:32.014945 17069 replica.cpp:511] Replica received write request
for position 4102
I0421 21:03:32.014999 17071 master.cpp:4290] Sending 1 offers to framework
sy3x4 (sy3x4) at
scheduler-6bb2bcf0-d060-4072-a25b-917d8007fb1c@172.16.13.243:56861
I0421 21:03:32.015379 17069 leveldb.cpp:343] Persisting action (18 bytes)
to leveldb took 345429ns
I0421 21:03:32.015403 17069 replica.cpp:679] Persisted action at 4102
I0421 21:03:32.017308 17073 replica.cpp:658] Replica received learned
notice for position 4102
I0421 21:03:32.017627 17073 leveldb.cpp:343] Persisting action (20 bytes)
to leveldb took 292089ns
I0421 21:03:32.017665 17073 leveldb.cpp:401] Deleting ~2 keys from leveldb
took 14004ns
I0421 21:03:32.017681 17073 replica.cpp:679] Persisted action at 4102
I0421 21:03:32.017693 17073 replica.cpp:664] Replica learned TRUNCATE
action at position 4102
I0421 21:03:32.019726 17076 master.cpp:3687] Received update of slave
20151116-203437-35000492-5050-17068-S70 at slave(1)@172.16.3.103:5051
(lively-rice) with total oversubscribed resources
I0421 21:03:32.019800 17076 hierarchical.hpp:588] Slave
20151116-203437-35000492-5050-17068-S70 (lively-rice) updated with
oversubscribed resources  (total: mem(*):217609; cpus(*):210;
ports(*):[2048-3048]; disk(*):639829, allocated: mem(*):217609;
cpus(*):210; ports(*):[2048-3048]; disk(*):639829)

(no other mentions of lively-rice or the slave ID for 10 minutes until we
bounce our scheduler at 21:13...)

I0421 21:13:13.806171 17072 hierarchical.hpp:761] Recovered mem(*):217609;
cpus(*):210; ports(*):[2048-3048]; disk(*):639829 (total: mem(*):217609;
cpus(*):210; ports(*):[2048-3048]; disk(*):639829, allocated: ) on slave
20151116-203437-35000492-5050-17068-S70 from framework sy3x4
I0421 21:13:15.749594 17075 hierarchical.hpp:761] Recovered mem(*):217609;
cpus(*):210; ports(*):[2048-3048]; disk(*):639829 (total: mem(*):217609;
cpus(*):210; ports(*):[2048-3048]; disk(*):639829, allocated: ) on slave
20151116-203437-35000492-5050-17068-S70 from framework sy3x4
I0421 21:14:52.761143 17075 master.cpp:2505] Processing ACCEPT call for
offers: [ 20151116-203437-35000492-5050-17068-O116800466 ] on slave
20151116-203437-35000492-5050-17068-S70 at slave(1)@172.16.3.103:5051 (
lively-rice.iad02.hubspot-networks.net) for framework sy3x4 (sy3x4) at
scheduler-7dda7817-66f1-4b8e-a5dd-9744aea52cba@172.16.40.17:53645

We were originally concerned about the log line at 21:03:32.019800 (where
it says that all the slave's resources were allocated) but I think it's
saying that all the resources on the slave are available as revocable
resources. Am I understanding that correctly?

Thanks,
Tom

On Mon, Apr 25, 2016 at 3:06 PM, Vinod Kone <vi...@apache.org> wrote:

>
> On Mon, Apr 25, 2016 at 8:40 AM, Thomas Petr <tp...@hubspot.com> wrote:
>
>> The only thing that ended up fixing the situation was bouncing our
>> scheduler (~10 minutes after the restarted slaves joined the cluster) --
>> the act of failing over the framework appeared to "recover" the missing
>> resources:
>>
>
> What do the master logs say when the slave is registered with a new id?
>

Re: Reconnected slaves not sending resource offers?

[Vinod Kone <vi...@apache.org>]

On Mon, Apr 25, 2016 at 8:40 AM, Thomas Petr <tp...@hubspot.com> wrote:

> The only thing that ended up fixing the situation was bouncing our
> scheduler (~10 minutes after the restarted slaves joined the cluster) --
> the act of failing over the framework appeared to "recover" the missing
> resources:
>

What do the master logs say when the slave is registered with a new id?