mesos-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Geoffroy Jabouley <geoffroy.jabou...@gmail.com>
Subject Re: Weird behavior when stopping the mesos master leader of a HA mesos cluster
Date Thu, 12 Mar 2015 08:34:57 GMT
Thanks Alex for your answer. I will have a look.

Would it be better to (cross-)post this discussion on the marathon mailing
list?

Anyway, the issue is "fixed" for 0.8.0, which is the version i'm using.

2015-03-11 22:18 GMT+01:00 Alex Rukletsov <alex@mesosphere.io>:

> Geoffroy,
>
> most probably you're hitting this bug:
> https://github.com/mesosphere/marathon/issues/1063. The problem is that
> Marathon can register instead of re-registering when a master fails
> over. From master point of view, it's a new framework, that's why the
> previous task is gone and a new one (that technically belongs to a new
> framework) is started. You can see that frameworks have two different IDs
> (check lines 11:31:40.055496 and 11:31:40.785038) in your example.
>
> Hope that helps,
> Alex
>
> On Tue, Mar 10, 2015 at 4:04 AM, Geoffroy Jabouley <
> geoffroy.jabouley@gmail.com> wrote:
>
>> Hello
>>
>> thanks for your interest. Following are the requested logs, which will
>> result in a pretty big mail.
>>
>> Mesos/Marathon are *NOT running inside docker*, we only use Docker as
>> our mesos containerizer.
>>
>> For reminder, here is the use case performed to get the logs file:
>>
>> --------------------------------
>>
>> Our cluster: 3 identical mesos nodes with:
>>     + zookeeper
>>     + docker 1.5
>>     + mesos master 0.21.1 configured in HA mode
>>     + mesos slave 0.21.1 configured with checkpointing, strict and
>> reconnect
>>     + marathon 0.8.0 configured in HA mode with checkpointing
>>
>> --------------------------------
>>
>> *Begin State: *
>> + the mesos cluster is up (3 machines)
>> + mesos master leader is 10.195.30.19
>> + marathon leader is 10.195.30.21
>> + 1 docker task (let's call it APPTASK) is running on slave 10.195.30.21
>>
>> *Action*: stop the mesos master leader process (sudo stop mesos-master)
>>
>> *Expected*: mesos master leader has changed, active tasks / frameworks
>> remain unchanged
>>
>> *End state: *
>> + mesos master leader *has changed, now 10.195.30.21*
>> + previously running APPTASK on the slave 10.195.30.21 has "disappear"
>> (not showing anymore on the mesos UI), but *docker container is still
>> running*
>> + a n*ew APPTASK is now running on slave 10.195.30.19*
>> + marathon framework "registration time" in mesos UI shows "Just now"
>> + marathon leader *has changed, now 10.195.30.20*
>>
>>
>> --------------------------------
>>
>> Now comes the 6 requested logs, which might contain interesting/relevant
>> information, but i as a newcomer to mesos it is hard to read...
>>
>>
>> *from previous MESOS master leader 10.195.30.19 <http://10.195.30.19>:*
>> W0310 11:31:28.310518 24289 logging.cpp:81] RAW: Received signal SIGTERM
>> from process 1 of user 0; exiting
>>
>>
>> *from new MESOS master leader 10.195.30.21 <http://10.195.30.21>:*
>> I0310 11:31:40.011545   922 detector.cpp:138] Detected a new leader:
>> (id='2')
>> I0310 11:31:40.011823   922 group.cpp:659] Trying to get
>> '/mesos/info_0000000002' in ZooKeeper
>> I0310 11:31:40.015496   915 network.hpp:424] ZooKeeper group memberships
>> changed
>> I0310 11:31:40.015847   915 group.cpp:659] Trying to get
>> '/mesos/log_replicas/0000000000' in ZooKeeper
>> I0310 11:31:40.016047   922 detector.cpp:433] A new leading master (UPID=
>> master@10.195.30.21:5050) is detected
>> I0310 11:31:40.016074   922 master.cpp:1263] The newly elected leader is
>> master@10.195.30.21:5050 with id 20150310-112310-354337546-5050-895
>> I0310 11:31:40.016089   922 master.cpp:1276] Elected as the leading
>> master!
>> I0310 11:31:40.016108   922 master.cpp:1094] Recovering from registrar
>> I0310 11:31:40.016188   918 registrar.cpp:313] Recovering registrar
>> I0310 11:31:40.016542   918 log.cpp:656] Attempting to start the writer
>> I0310 11:31:40.016918   918 replica.cpp:474] Replica received implicit
>> promise request with proposal 2
>> I0310 11:31:40.017503   915 group.cpp:659] Trying to get
>> '/mesos/log_replicas/0000000003' in ZooKeeper
>> I0310 11:31:40.017832   918 leveldb.cpp:306] Persisting metadata (8
>> bytes) to leveldb took 893672ns
>> I0310 11:31:40.017848   918 replica.cpp:342] Persisted promised to 2
>> I0310 11:31:40.018817   915 network.hpp:466] ZooKeeper group PIDs: {
>> log-replica(1)@10.195.30.20:5050, log-replica(1)@10.195.30.21:5050 }
>> I0310 11:31:40.023022   923 coordinator.cpp:230] Coordinator attemping to
>> fill missing position
>> I0310 11:31:40.023110   923 log.cpp:672] Writer started with ending
>> position 8
>> I0310 11:31:40.023293   923 leveldb.cpp:438] Reading position from
>> leveldb took 13195ns
>> I0310 11:31:40.023309   923 leveldb.cpp:438] Reading position from
>> leveldb took 3120ns
>> I0310 11:31:40.023619   922 registrar.cpp:346] Successfully fetched the
>> registry (610B) in 7.385856ms
>> I0310 11:31:40.023679   922 registrar.cpp:445] Applied 1 operations in
>> 9263ns; attempting to update the 'registry'
>> I0310 11:31:40.024238   922 log.cpp:680] Attempting to append 647 bytes
>> to the log
>> I0310 11:31:40.024279   923 coordinator.cpp:340] Coordinator attempting
>> to write APPEND action at position 9
>> I0310 11:31:40.024435   923 replica.cpp:508] Replica received write
>> request for position 9
>> I0310 11:31:40.025707   923 leveldb.cpp:343] Persisting action (666
>> bytes) to leveldb took 1.259338ms
>> I0310 11:31:40.025722   923 replica.cpp:676] Persisted action at 9
>> I0310 11:31:40.026074   923 replica.cpp:655] Replica received learned
>> notice for position 9
>> I0310 11:31:40.026495   923 leveldb.cpp:343] Persisting action (668
>> bytes) to leveldb took 404795ns
>> I0310 11:31:40.026507   923 replica.cpp:676] Persisted action at 9
>> I0310 11:31:40.026511   923 replica.cpp:661] Replica learned APPEND
>> action at position 9
>> I0310 11:31:40.026726   923 registrar.cpp:490] Successfully updated the
>> 'registry' in 3.029248ms
>> I0310 11:31:40.026765   923 registrar.cpp:376] Successfully recovered
>> registrar
>> I0310 11:31:40.026814   923 log.cpp:699] Attempting to truncate the log
>> to 9
>> I0310 11:31:40.026880   923 master.cpp:1121] Recovered 3 slaves from the
>> Registry (608B) ; allowing 1days for slaves to re-register
>> I0310 11:31:40.026897   923 coordinator.cpp:340] Coordinator attempting
>> to write TRUNCATE action at position 10
>> I0310 11:31:40.026988   923 replica.cpp:508] Replica received write
>> request for position 10
>> I0310 11:31:40.027640   923 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 641018ns
>> I0310 11:31:40.027652   923 replica.cpp:676] Persisted action at 10
>> I0310 11:31:40.030848   923 replica.cpp:655] Replica received learned
>> notice for position 10
>> I0310 11:31:40.031883   923 leveldb.cpp:343] Persisting action (18 bytes)
>> to leveldb took 1.008914ms
>> I0310 11:31:40.031963   923 leveldb.cpp:401] Deleting ~2 keys from
>> leveldb took 46724ns
>> I0310 11:31:40.031977   923 replica.cpp:676] Persisted action at 10
>> I0310 11:31:40.031986   923 replica.cpp:661] Replica learned TRUNCATE
>> action at position 10
>> I0310 11:31:40.055415   918 master.cpp:1383] Received registration
>> request for framework 'marathon' at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:40.055496   918 master.cpp:1447] Registering framework
>> 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:40.055642   919 hierarchical_allocator_process.hpp:329] Added
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:40.189151   919 master.cpp:3246] Re-registering slave
>> 20150310-112310-320783114-5050-24289-S1 at slave(1)@10.195.30.19:5051
>> (10.195.30.19)
>> I0310 11:31:40.189280   919 registrar.cpp:445] Applied 1 operations in
>> 15452ns; attempting to update the 'registry'
>> I0310 11:31:40.189949   919 log.cpp:680] Attempting to append 647 bytes
>> to the log
>> I0310 11:31:40.189978   919 coordinator.cpp:340] Coordinator attempting
>> to write APPEND action at position 11
>> I0310 11:31:40.190112   919 replica.cpp:508] Replica received write
>> request for position 11
>> I0310 11:31:40.190563   919 leveldb.cpp:343] Persisting action (666
>> bytes) to leveldb took 437440ns
>> I0310 11:31:40.190577   919 replica.cpp:676] Persisted action at 11
>> I0310 11:31:40.191249   921 replica.cpp:655] Replica received learned
>> notice for position 11
>> I0310 11:31:40.192159   921 leveldb.cpp:343] Persisting action (668
>> bytes) to leveldb took 892767ns
>> I0310 11:31:40.192178   921 replica.cpp:676] Persisted action at 11
>> I0310 11:31:40.192184   921 replica.cpp:661] Replica learned APPEND
>> action at position 11
>> I0310 11:31:40.192350   921 registrar.cpp:490] Successfully updated the
>> 'registry' in 3.0528ms
>> I0310 11:31:40.192387   919 log.cpp:699] Attempting to truncate the log
>> to 11
>> I0310 11:31:40.192415   919 coordinator.cpp:340] Coordinator attempting
>> to write TRUNCATE action at position 12
>> I0310 11:31:40.192539   915 replica.cpp:508] Replica received write
>> request for position 12
>> I0310 11:31:40.192600   921 master.cpp:3314] Re-registered slave
>> 20150310-112310-320783114-5050-24289-S1 at slave(1)@10.195.30.19:5051
>> (10.195.30.19) with ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148
>> I0310 11:31:40.192680   917 hierarchical_allocator_process.hpp:442] Added
>> slave 20150310-112310-320783114-5050-24289-S1 (10.195.30.19) with
>> ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961; disk(*):89148 (and
>> ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961; disk(*):89148
>> available)
>> I0310 11:31:40.192847   917 master.cpp:3843] Sending 1 offers to
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:40.193164   915 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 610664ns
>> I0310 11:31:40.193181   915 replica.cpp:676] Persisted action at 12
>> I0310 11:31:40.193568   915 replica.cpp:655] Replica received learned
>> notice for position 12
>> I0310 11:31:40.193948   915 leveldb.cpp:343] Persisting action (18 bytes)
>> to leveldb took 364062ns
>> I0310 11:31:40.193979   915 leveldb.cpp:401] Deleting ~2 keys from
>> leveldb took 12256ns
>> I0310 11:31:40.193985   915 replica.cpp:676] Persisted action at 12
>> I0310 11:31:40.193990   915 replica.cpp:661] Replica learned TRUNCATE
>> action at position 12
>> I0310 11:31:40.248615   915 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O0 ] on slave
>> 20150310-112310-320783114-5050-24289-S1 at slave(1)@10.195.30.19:5051
>> (10.195.30.19) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:40.248744   915 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148 (total allocatable: ports(*):[31000-32000, 80-443];
>> cpus(*):2; mem(*):6961; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S1 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:40.774416   915 master.cpp:3246] Re-registering slave
>> 20150310-112310-320783114-5050-24289-S2 at slave(1)@10.195.30.21:5051
>> (10.195.30.21)
>> I0310 11:31:40.774976   915 registrar.cpp:445] Applied 1 operations in
>> 42342ns; attempting to update the 'registry'
>> I0310 11:31:40.777273   921 log.cpp:680] Attempting to append 647 bytes
>> to the log
>> I0310 11:31:40.777436   921 coordinator.cpp:340] Coordinator attempting
>> to write APPEND action at position 13
>> I0310 11:31:40.777989   921 replica.cpp:508] Replica received write
>> request for position 13
>> I0310 11:31:40.779558   921 leveldb.cpp:343] Persisting action (666
>> bytes) to leveldb took 1.513714ms
>> I0310 11:31:40.779633   921 replica.cpp:676] Persisted action at 13
>> I0310 11:31:40.781821   919 replica.cpp:655] Replica received learned
>> notice for position 13
>> I0310 11:31:40.784417   919 leveldb.cpp:343] Persisting action (668
>> bytes) to leveldb took 2.542036ms
>> I0310 11:31:40.784446   919 replica.cpp:676] Persisted action at 13
>> I0310 11:31:40.784452   919 replica.cpp:661] Replica learned APPEND
>> action at position 13
>> I0310 11:31:40.784711   920 registrar.cpp:490] Successfully updated the
>> 'registry' in 9.68192ms
>> I0310 11:31:40.784762   917 log.cpp:699] Attempting to truncate the log
>> to 13
>> I0310 11:31:40.784808   920 coordinator.cpp:340] Coordinator attempting
>> to write TRUNCATE action at position 14
>> I0310 11:31:40.784865   917 master.hpp:877] Adding task
>> ffaas-backoffice-app-nopersist.cc399489-c70f-11e4-ab88-56847afe9799 with
>> resources cpus(*):0.1; mem(*):128; ports(*):[31000-31000] on slave
>> 20150310-112310-320783114-5050-24289-S2 (10.195.30.21)
>> I0310 11:31:40.784955   919 replica.cpp:508] Replica received write
>> request for position 14
>> W0310 11:31:40.785038   917 master.cpp:4468] Possibly orphaned task
>> ffaas-backoffice-app-nopersist.cc399489-c70f-11e4-ab88-56847afe9799 of
>> framework 20150310-112310-320783114-5050-24289-0000 running on slave
>> 20150310-112310-320783114-5050-24289-S2 at slave(1)@10.195.30.21:5051
>> (10.195.30.21)
>> I0310 11:31:40.785105   917 master.cpp:3314] Re-registered slave
>> 20150310-112310-320783114-5050-24289-S2 at slave(1)@10.195.30.21:5051
>> (10.195.30.21) with ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148
>> I0310 11:31:40.785162   920 hierarchical_allocator_process.hpp:442] Added
>> slave 20150310-112310-320783114-5050-24289-S2 (10.195.30.21) with
>> ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961; disk(*):89148 (and
>> ports(*):[80-443, 31001-32000]; cpus(*):1.9; mem(*):6833; disk(*):89148
>> available)
>> I0310 11:31:40.785679   921 master.cpp:3843] Sending 1 offers to
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:40.786429   919 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 1.454211ms
>> I0310 11:31:40.786455   919 replica.cpp:676] Persisted action at 14
>> I0310 11:31:40.786782   919 replica.cpp:655] Replica received learned
>> notice for position 14
>> I0310 11:31:40.787833   919 leveldb.cpp:343] Persisting action (18 bytes)
>> to leveldb took 1.027014ms
>> I0310 11:31:40.787873   919 leveldb.cpp:401] Deleting ~2 keys from
>> leveldb took 14085ns
>> I0310 11:31:40.787883   919 replica.cpp:676] Persisted action at 14
>> I0310 11:31:40.787889   919 replica.cpp:661] Replica learned TRUNCATE
>> action at position 14
>> I0310 11:31:40.792536   922 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O1 ] on slave
>> 20150310-112310-320783114-5050-24289-S2 at slave(1)@10.195.30.21:5051
>> (10.195.30.21) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:40.792670   922 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[80-443, 31001-32000]; cpus(*):1.9; mem(*):6833;
>> disk(*):89148 (total allocatable: ports(*):[80-443, 31001-32000];
>> cpus(*):1.9; mem(*):6833; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S2 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:40.819602   921 master.cpp:3246] Re-registering slave
>> 20150310-112310-320783114-5050-24289-S0 at slave(1)@10.195.30.20:5051
>> (10.195.30.20)
>> I0310 11:31:40.819736   921 registrar.cpp:445] Applied 1 operations in
>> 16656ns; attempting to update the 'registry'
>> I0310 11:31:40.820617   921 log.cpp:680] Attempting to append 647 bytes
>> to the log
>> I0310 11:31:40.820726   918 coordinator.cpp:340] Coordinator attempting
>> to write APPEND action at position 15
>> I0310 11:31:40.820938   918 replica.cpp:508] Replica received write
>> request for position 15
>> I0310 11:31:40.821641   918 leveldb.cpp:343] Persisting action (666
>> bytes) to leveldb took 670583ns
>> I0310 11:31:40.821663   918 replica.cpp:676] Persisted action at 15
>> I0310 11:31:40.822265   917 replica.cpp:655] Replica received learned
>> notice for position 15
>> I0310 11:31:40.823463   917 leveldb.cpp:343] Persisting action (668
>> bytes) to leveldb took 1.178687ms
>> I0310 11:31:40.823490   917 replica.cpp:676] Persisted action at 15
>> I0310 11:31:40.823498   917 replica.cpp:661] Replica learned APPEND
>> action at position 15
>> I0310 11:31:40.823755   917 registrar.cpp:490] Successfully updated the
>> 'registry' in 3.97696ms
>> I0310 11:31:40.823823   917 log.cpp:699] Attempting to truncate the log
>> to 15
>> I0310 11:31:40.824147   922 coordinator.cpp:340] Coordinator attempting
>> to write TRUNCATE action at position 16
>> I0310 11:31:40.824482   922 hierarchical_allocator_process.hpp:442] Added
>> slave 20150310-112310-320783114-5050-24289-S0 (10.195.30.20) with
>> ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961; disk(*):89148 (and
>> ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961; disk(*):89148
>> available)
>> I0310 11:31:40.824597   921 replica.cpp:508] Replica received write
>> request for position 16
>> I0310 11:31:40.824128   917 master.cpp:3314] Re-registered slave
>> 20150310-112310-320783114-5050-24289-S0 at slave(1)@10.195.30.20:5051
>> (10.195.30.20) with ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148
>> I0310 11:31:40.824975   917 master.cpp:3843] Sending 1 offers to
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:40.831900   921 leveldb.cpp:343] Persisting action (16 bytes)
>> to leveldb took 7.228682ms
>> I0310 11:31:40.832031   921 replica.cpp:676] Persisted action at 16
>> I0310 11:31:40.832456   917 replica.cpp:655] Replica received learned
>> notice for position 16
>> I0310 11:31:40.835178   917 leveldb.cpp:343] Persisting action (18 bytes)
>> to leveldb took 2.674392ms
>> I0310 11:31:40.835297   917 leveldb.cpp:401] Deleting ~2 keys from
>> leveldb took 45220ns
>> I0310 11:31:40.835322   917 replica.cpp:676] Persisted action at 16
>> I0310 11:31:40.835341   917 replica.cpp:661] Replica learned TRUNCATE
>> action at position 16
>> I0310 11:31:40.838281   923 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O2 ] on slave
>> 20150310-112310-320783114-5050-24289-S0 at slave(1)@10.195.30.20:5051
>> (10.195.30.20) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:40.838389   923 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148 (total allocatable: ports(*):[31000-32000, 80-443];
>> cpus(*):2; mem(*):6961; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S0 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:40.948725   919 http.cpp:344] HTTP request for
>> '/master/redirect'
>> I0310 11:31:41.479118   918 http.cpp:478] HTTP request for
>> '/master/state.json'
>> I0310 11:31:45.368074   918 master.cpp:3843] Sending 1 offers to
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:45.385144   917 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O3 ] on slave
>> 20150310-112310-320783114-5050-24289-S1 at slave(1)@10.195.30.19:5051
>> (10.195.30.19) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:45.385292   917 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148 (total allocatable: ports(*):[31000-32000, 80-443];
>> cpus(*):2; mem(*):6961; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S1 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:46.368450   917 master.cpp:3843] Sending 2 offers to
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:46.375222   920 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O4 ] on slave
>> 20150310-112310-320783114-5050-24289-S0 at slave(1)@10.195.30.20:5051
>> (10.195.30.20) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:46.375360   920 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O5 ] on slave
>> 20150310-112310-320783114-5050-24289-S2 at slave(1)@10.195.30.21:5051
>> (10.195.30.21) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:46.375530   920 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148 (total allocatable: ports(*):[31000-32000, 80-443];
>> cpus(*):2; mem(*):6961; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S0 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:46.375599   920 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[80-443, 31001-32000]; cpus(*):1.9; mem(*):6833;
>> disk(*):89148 (total allocatable: ports(*):[80-443, 31001-32000];
>> cpus(*):1.9; mem(*):6833; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S2 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:48.031230   915 http.cpp:478] HTTP request for
>> '/master/state.json'
>> I0310 11:31:51.374285   922 master.cpp:3843] Sending 1 offers to
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:51.379391   921 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O6 ] on slave
>> 20150310-112310-320783114-5050-24289-S1 at slave(1)@10.195.30.19:5051
>> (10.195.30.19) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:51.379487   921 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148 (total allocatable: ports(*):[31000-32000, 80-443];
>> cpus(*):2; mem(*):6961; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S1 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:51.482094   923 http.cpp:478] HTTP request for
>> '/master/state.json'
>> I0310 11:31:52.375326   917 master.cpp:3843] Sending 2 offers to
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:52.391376   919 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O7 ] on slave
>> 20150310-112310-320783114-5050-24289-S2 at slave(1)@10.195.30.21:5051
>> (10.195.30.21) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:52.391512   919 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[80-443, 31001-32000]; cpus(*):1.9; mem(*):6833;
>> disk(*):89148 (total allocatable: ports(*):[80-443, 31001-32000];
>> cpus(*):1.9; mem(*):6833; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S2 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:52.391659   921 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O8 ] on slave
>> 20150310-112310-320783114-5050-24289-S0 at slave(1)@10.195.30.20:5051
>> (10.195.30.20) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:52.391751   921 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[31000-32000, 80-443]; cpus(*):2; mem(*):6961;
>> disk(*):89148 (total allocatable: ports(*):[31000-32000, 80-443];
>> cpus(*):2; mem(*):6961; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S0 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:55.062060   918 master.cpp:3611] Performing explicit task
>> state reconciliation for 1 tasks of framework
>> 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:55.062588   919 master.cpp:3556] Performing implicit task
>> state reconciliation for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:56.140990   923 http.cpp:344] HTTP request for
>> '/master/redirect'
>> I0310 11:31:57.379288   918 master.cpp:3843] Sending 1 offers to
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:57.430888   918 master.cpp:2344] Processing reply for offers:
>> [ 20150310-112310-354337546-5050-895-O9 ] on slave
>> 20150310-112310-320783114-5050-24289-S1 at slave(1)@10.195.30.19:5051
>> (10.195.30.19) for framework 20150310-112310-354337546-5050-895-0000
>> (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771
>> I0310 11:31:57.431068   918 master.hpp:877] Adding task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 with
>> resources cpus(*):0.1; mem(*):128; ports(*):[31000-31000] on slave
>> 20150310-112310-320783114-5050-24289-S1 (10.195.30.19)
>> I0310 11:31:57.431089   918 master.cpp:2503] Launching task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000 (marathon) at
>> scheduler-c5ae752d-1ffe-40e2-a89b-41013050bec9@10.195.30.20:45771 with
>> resources cpus(*):0.1; mem(*):128; ports(*):[31000-31000] on slave
>> 20150310-112310-320783114-5050-24289-S1 at slave(1)@10.195.30.19:5051
>> (10.195.30.19)
>> I0310 11:31:57.431205   918 hierarchical_allocator_process.hpp:563]
>> Recovered ports(*):[80-443, 31001-32000]; cpus(*):1.9; mem(*):6833;
>> disk(*):89148 (total allocatable: ports(*):[80-443, 31001-32000];
>> cpus(*):1.9; mem(*):6833; disk(*):89148) on slave
>> 20150310-112310-320783114-5050-24289-S1 from framework
>> 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.682133   919 master.cpp:3446] Forwarding status update
>> TASK_RUNNING (UUID: 2afb200e-a172-49ec-b807-dc47ea381e1e) for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.682186   919 master.cpp:3418] Status update TASK_RUNNING
>> (UUID: 2afb200e-a172-49ec-b807-dc47ea381e1e) for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000 from slave
>> 20150310-112310-320783114-5050-24289-S1 at slave(1)@10.195.30.19:5051
>> (10.195.30.19)
>> I0310 11:31:57.682199   919 master.cpp:4693] Updating the latest state of
>> task ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000 to TASK_RUNNING
>>
>>
>> *from MESOS slave 10.195.30.21*
>> I0310 11:31:28.750200  1074 slave.cpp:2623] master@10.195.30.19:5050
>> exited
>> W0310 11:31:28.750249  1074 slave.cpp:2626] Master disconnected! Waiting
>> for a new master to be elected
>> I0310 11:31:40.012516  1075 detector.cpp:138] Detected a new leader:
>> (id='2')
>> I0310 11:31:40.012899  1073 group.cpp:659] Trying to get
>> '/mesos/info_0000000002' in ZooKeeper
>> I0310 11:31:40.017143  1072 detector.cpp:433] A new leading master (UPID=
>> master@10.195.30.21:5050) is detected
>> I0310 11:31:40.017408  1072 slave.cpp:602] New master detected at
>> master@10.195.30.21:5050
>> I0310 11:31:40.017546  1076 status_update_manager.cpp:171] Pausing
>> sending status updates
>> I0310 11:31:40.018673  1072 slave.cpp:627] No credentials provided.
>> Attempting to register without authentication
>> I0310 11:31:40.018689  1072 slave.cpp:638] Detecting new master
>> I0310 11:31:40.785364  1075 slave.cpp:824] Re-registered with master
>> master@10.195.30.21:5050
>> I0310 11:31:40.785398  1075 status_update_manager.cpp:178] Resuming
>> sending status updates
>> I0310 11:32:10.639506  1075 slave.cpp:3321] Current usage 12.27%. Max
>> allowed age: 5.441217749539572days
>>
>>
>> *from MESOS slave 10.195.30.19*
>> I0310 11:31:28.749577 24457 slave.cpp:2623] master@10.195.30.19:5050
>> exited
>> W0310 11:31:28.749604 24457 slave.cpp:2626] Master disconnected! Waiting
>> for a new master to be elected
>> I0310 11:31:40.013056 24462 detector.cpp:138] Detected a new leader:
>> (id='2')
>> I0310 11:31:40.013530 24458 group.cpp:659] Trying to get
>> '/mesos/info_0000000002' in ZooKeeper
>> I0310 11:31:40.015897 24458 detector.cpp:433] A new leading master (UPID=
>> master@10.195.30.21:5050) is detected
>> I0310 11:31:40.015976 24458 slave.cpp:602] New master detected at
>> master@10.195.30.21:5050
>> I0310 11:31:40.016027 24458 slave.cpp:627] No credentials provided.
>> Attempting to register without authentication
>> I0310 11:31:40.016075 24458 slave.cpp:638] Detecting new master
>> I0310 11:31:40.016091 24458 status_update_manager.cpp:171] Pausing
>> sending status updates
>> I0310 11:31:40.192397 24462 slave.cpp:824] Re-registered with master
>> master@10.195.30.21:5050
>> I0310 11:31:40.192437 24462 status_update_manager.cpp:178] Resuming
>> sending status updates
>> I0310 11:31:57.431139 24461 slave.cpp:1083] Got assigned task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 for
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.431479 24461 slave.cpp:1193] Launching task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 for
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.432144 24461 slave.cpp:3997] Launching executor
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000 in work directory
>> '/tmp/mesos/slaves/20150310-112310-320783114-5050-24289-S1/frameworks/20150310-112310-354337546-5050-895-0000/executors/ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799/runs/a8f9aba9-1bc7-4673-854e-82d9fdea8ca9'
>> I0310 11:31:57.432318 24461 slave.cpp:1316] Queuing task
>> 'ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799' for
>> executor
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework '20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.434217 24461 docker.cpp:927] Starting container
>> 'a8f9aba9-1bc7-4673-854e-82d9fdea8ca9' for task
>> 'ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799' (and
>> executor
>> 'ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799') of
>> framework '20150310-112310-354337546-5050-895-0000'
>> I0310 11:31:57.652439 24461 docker.cpp:633] Checkpointing pid 24573 to
>> '/tmp/mesos/meta/slaves/20150310-112310-320783114-5050-24289-S1/frameworks/20150310-112310-354337546-5050-895-0000/executors/ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799/runs/a8f9aba9-1bc7-4673-854e-82d9fdea8ca9/pids/forked.pid'
>> I0310 11:31:57.653270 24461 slave.cpp:2840] Monitoring executor
>> 'ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799' of
>> framework '20150310-112310-354337546-5050-895-0000' in container
>> 'a8f9aba9-1bc7-4673-854e-82d9fdea8ca9'
>> I0310 11:31:57.675488 24461 slave.cpp:1860] Got registration for executor
>> 'ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799' of
>> framework 20150310-112310-354337546-5050-895-0000 from executor(1)@
>> 10.195.30.19:56574
>> I0310 11:31:57.675696 24461 slave.cpp:1979] Flushing queued task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 for
>> executor
>> 'ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799' of
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.678129 24461 slave.cpp:2215] Handling status update
>> TASK_RUNNING (UUID: 2afb200e-a172-49ec-b807-dc47ea381e1e) for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000 from executor(1)@
>> 10.195.30.19:56574
>> I0310 11:31:57.678251 24461 status_update_manager.cpp:317] Received
>> status update TASK_RUNNING (UUID: 2afb200e-a172-49ec-b807-dc47ea381e1e) for
>> task ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.678411 24461 status_update_manager.hpp:346] Checkpointing
>> UPDATE for status update TASK_RUNNING (UUID:
>> 2afb200e-a172-49ec-b807-dc47ea381e1e) for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.681231 24461 slave.cpp:2458] Forwarding the update
>> TASK_RUNNING (UUID: 2afb200e-a172-49ec-b807-dc47ea381e1e) for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000 to
>> master@10.195.30.21:5050
>> I0310 11:31:57.681277 24461 slave.cpp:2391] Sending acknowledgement for
>> status update TASK_RUNNING (UUID: 2afb200e-a172-49ec-b807-dc47ea381e1e) for
>> task ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000 to executor(1)@
>> 10.195.30.19:56574
>> I0310 11:31:57.689007 24461 status_update_manager.cpp:389] Received
>> status update acknowledgement (UUID: 2afb200e-a172-49ec-b807-dc47ea381e1e)
>> for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.689028 24461 status_update_manager.hpp:346] Checkpointing
>> ACK for status update TASK_RUNNING (UUID:
>> 2afb200e-a172-49ec-b807-dc47ea381e1e) for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799 of
>> framework 20150310-112310-354337546-5050-895-0000
>> I0310 11:31:57.755231 24461 docker.cpp:1298] Updated 'cpu.shares' to 204
>> at
>> /sys/fs/cgroup/cpu/docker/e76080a071fa9cfb57e66df195c7650aee2f08cd9a23b81622a72e85d78f90b2
>> for container a8f9aba9-1bc7-4673-854e-82d9fdea8ca9
>> I0310 11:31:57.755570 24461 docker.cpp:1333] Updated
>> 'memory.soft_limit_in_bytes' to 160MB for container
>> a8f9aba9-1bc7-4673-854e-82d9fdea8ca9
>> I0310 11:31:57.756013 24461 docker.cpp:1359] Updated
>> 'memory.limit_in_bytes' to 160MB at
>> /sys/fs/cgroup/memory/docker/e76080a071fa9cfb57e66df195c7650aee2f08cd9a23b81622a72e85d78f90b2
>> for container a8f9aba9-1bc7-4673-854e-82d9fdea8ca9
>> I0310 11:32:10.680750 24459 slave.cpp:3321] Current usage 10.64%. Max
>> allowed age: 5.555425200437824days
>>
>>
>> *From previous Marathon leader 10.195.30.21 <http://10.195.30.21>:*
>> I0310 11:31:40.017248  1115 detector.cpp:138] Detected a new leader:
>> (id='2')
>> I0310 11:31:40.017334  1115 group.cpp:659] Trying to get
>> '/mesos/info_0000000002' in ZooKeeper
>> I0310 11:31:40.017727  1115 detector.cpp:433] A new leading master (UPID=
>> master@10.195.30.21:5050) is detected
>> [2015-03-10 11:31:40,017] WARN Disconnected
>> (mesosphere.marathon.MarathonScheduler:224)
>> [2015-03-10 11:31:40,019] INFO Abdicating
>> (mesosphere.marathon.MarathonSchedulerService:312)
>> [2015-03-10 11:31:40,019] INFO Defeat leadership
>> (mesosphere.marathon.MarathonSchedulerService:285)
>> [INFO] [03/10/2015 11:31:40.019]
>> [marathon-akka.actor.default-dispatcher-6] [akka://marathon/user/$b]
>> POSTing to all endpoints.
>> [INFO] [03/10/2015 11:31:40.019]
>> [marathon-akka.actor.default-dispatcher-5]
>> [akka://marathon/user/MarathonScheduler/$a] Suspending scheduler actor
>> [2015-03-10 11:31:40,021] INFO Stopping driver
>> (mesosphere.marathon.MarathonSchedulerService:221)
>> I0310 11:31:40.022001  1115 sched.cpp:1286] Asked to stop the driver
>> [2015-03-10 11:31:40,024] INFO Setting framework ID to
>> 20150310-112310-320783114-5050-24289-0000
>> (mesosphere.marathon.MarathonSchedulerService:73)
>> I0310 11:31:40.026274  1115 sched.cpp:234] New master detected at
>> master@10.195.30.21:5050
>> I0310 11:31:40.026418  1115 sched.cpp:242] No credentials provided.
>> Attempting to register without authentication
>> I0310 11:31:40.026458  1115 sched.cpp:752] Stopping framework
>> '20150310-112310-320783114-5050-24289-0000'
>> [2015-03-10 11:31:40,026] INFO Driver future completed. Executing
>> optional abdication command.
>> (mesosphere.marathon.MarathonSchedulerService:192)
>> [2015-03-10 11:31:40,032] INFO Defeated (Leader Interface)
>> (mesosphere.marathon.MarathonSchedulerService:246)
>> [2015-03-10 11:31:40,032] INFO Defeat leadership
>> (mesosphere.marathon.MarathonSchedulerService:285)
>> [2015-03-10 11:31:40,032] INFO Stopping driver
>> (mesosphere.marathon.MarathonSchedulerService:221)
>> I0310 11:31:40.032588  1107 sched.cpp:1286] Asked to stop the driver
>> [2015-03-10 11:31:40,033] INFO Will offer leadership after 500
>> milliseconds backoff (mesosphere.marathon.MarathonSchedulerService:334)
>> [2015-03-10 11:31:40,033] INFO Setting framework ID to
>> 20150310-112310-320783114-5050-24289-0000
>> (mesosphere.marathon.MarathonSchedulerService:73)
>> [2015-03-10 11:31:40,035] ERROR Current member ID member_0000000000 is
>> not a candidate for leader, current voting: [member_0000000001,
>> member_0000000002] (com.twitter.common.zookeeper.CandidateImpl:144)
>> [2015-03-10 11:31:40,552] INFO Using HA and therefore offering leadership
>> (mesosphere.marathon.MarathonSchedulerService:341)
>> [2015-03-10 11:31:40,563] INFO Set group member ID to member_0000000003
>> (com.twitter.common.zookeeper.Group:426)
>> [2015-03-10 11:31:40,565] ERROR Current member ID member_0000000000 is
>> not a candidate for leader, current voting: [member_0000000001,
>> member_0000000002, member_0000000003]
>> (com.twitter.common.zookeeper.CandidateImpl:144)
>> [2015-03-10 11:31:40,568] INFO Candidate
>> /marathon/leader/member_0000000003 waiting for the next leader election,
>> current voting: [member_0000000001, member_0000000002, member_0000000003]
>> (com.twitter.common.zookeeper.CandidateImpl:165)
>>
>>
>> *From new Marathon leader 10.195.30.20 <http://10.195.30.20>:*
>> [2015-03-10 11:31:40,029] INFO Candidate
>> /marathon/leader/member_0000000001 is now leader of group:
>> [member_0000000001, member_0000000002]
>> (com.twitter.common.zookeeper.CandidateImpl:152)
>> [2015-03-10 11:31:40,030] INFO Elected (Leader Interface)
>> (mesosphere.marathon.MarathonSchedulerService:253)
>> [2015-03-10 11:31:40,044] INFO Elect leadership
>> (mesosphere.marathon.MarathonSchedulerService:299)
>> [2015-03-10 11:31:40,044] INFO Running driver
>> (mesosphere.marathon.MarathonSchedulerService:184)
>> I0310 11:31:40.044770 22734 sched.cpp:137] Version: 0.21.1
>> 2015-03-10 11:31:40,045:22509(0x7fda83fff700):ZOO_INFO@log_env@712:
>> Client environment:zookeeper.version=zookeeper C client 3.4.5
>> 2015-03-10 11:31:40,045:22509(0x7fda83fff700):ZOO_INFO@log_env@716:
>> Client environment:host.name=srv-d2u-9-virtip20
>> 2015-03-10 11:31:40,045:22509(0x7fda83fff700):ZOO_INFO@log_env@723:
>> Client environment:os.name=Linux
>> 2015-03-10 11:31:40,045:22509(0x7fda83fff700):ZOO_INFO@log_env@724:
>> Client environment:os.arch=3.13.0-44-generic
>> 2015-03-10 11:31:40,045:22509(0x7fda83fff700):ZOO_INFO@log_env@725:
>> Client environment:os.version=#73-Ubuntu SMP Tue Dec 16 00:22:43 UTC 2014
>> 2015-03-10 11:31:40,046:22509(0x7fda83fff700):ZOO_INFO@log_env@733:
>> Client environment:user.name=(null)
>> 2015-03-10 11:31:40,046:22509(0x7fda83fff700):ZOO_INFO@log_env@741:
>> Client environment:user.home=/root
>> 2015-03-10 11:31:40,046:22509(0x7fda83fff700):ZOO_INFO@log_env@753:
>> Client environment:user.dir=/
>> 2015-03-10 11:31:40,046:22509(0x7fda83fff700):ZOO_INFO@zookeeper_init@786:
>> Initiating client connection, host=10.195.30.19:2181,10.195.30.20:2181,
>> 10.195.30.21:2181 sessionTimeout=10000 watcher=0x7fda9da9a6a0
>> sessionId=0 sessionPasswd=<null> context=0x7fdaa400dd10 flags=0
>> [2015-03-10 11:31:40,046] INFO Reset offerLeadership backoff
>> (mesosphere.marathon.MarathonSchedulerService:329)
>> 2015-03-10 11:31:40,047:22509(0x7fda816f2700):ZOO_INFO@check_events@1703:
>> initiated connection to server [10.195.30.19:2181]
>> 2015-03-10 11:31:40,049:22509(0x7fda816f2700):ZOO_INFO@check_events@1750:
>> session establishment complete on server [10.195.30.19:2181],
>> sessionId=0x14c0335ad7e000d, negotiated timeout=10000
>> I0310 11:31:40.049991 22645 group.cpp:313] Group process (group(1)@
>> 10.195.30.20:45771) connected to ZooKeeper
>> I0310 11:31:40.050012 22645 group.cpp:790] Syncing group operations:
>> queue size (joins, cancels, datas) = (0, 0, 0)
>> I0310 11:31:40.050024 22645 group.cpp:385] Trying to create path '/mesos'
>> in ZooKeeper
>> [INFO] [03/10/2015 11:31:40.047]
>> [marathon-akka.actor.default-dispatcher-2]
>> [akka://marathon/user/MarathonScheduler/$a] Starting scheduler actor
>> I0310 11:31:40.053429 22645 detector.cpp:138] Detected a new leader:
>> (id='2')
>> I0310 11:31:40.053530 22641 group.cpp:659] Trying to get
>> '/mesos/info_0000000002' in ZooKeeper
>> [2015-03-10 11:31:40,053] INFO Migration successfully applied for version
>> Version(0, 8, 0) (mesosphere.marathon.state.Migration:69)
>> I0310 11:31:40.054226 22640 detector.cpp:433] A new leading master (UPID=
>> master@10.195.30.21:5050) is detected
>> I0310 11:31:40.054281 22640 sched.cpp:234] New master detected at
>> master@10.195.30.21:5050
>> I0310 11:31:40.054352 22640 sched.cpp:242] No credentials provided.
>> Attempting to register without authentication
>> I0310 11:31:40.055160 22640 sched.cpp:408] Framework registered with
>> 20150310-112310-354337546-5050-895-0000
>> [2015-03-10 11:31:40,056] INFO Registered as
>> 20150310-112310-354337546-5050-895-0000 to master
>> '20150310-112310-354337546-5050-895'
>> (mesosphere.marathon.MarathonScheduler:72)
>> [2015-03-10 11:31:40,063] INFO Stored framework ID
>> '20150310-112310-354337546-5050-895-0000'
>> (mesosphere.mesos.util.FrameworkIdUtil:49)
>> [INFO] [03/10/2015 11:31:40.065]
>> [marathon-akka.actor.default-dispatcher-6]
>> [akka://marathon/user/MarathonScheduler/$a] Scheduler actor ready
>> [INFO] [03/10/2015 11:31:40.067]
>> [marathon-akka.actor.default-dispatcher-7] [akka://marathon/user/$b]
>> POSTing to all endpoints.
>> ...
>> ...
>> ...
>> [2015-03-10 11:31:55,052] INFO Syncing tasks for all apps
>> (mesosphere.marathon.SchedulerActions:403)
>> [INFO] [03/10/2015 11:31:55.053]
>> [marathon-akka.actor.default-dispatcher-10] [akka://marathon/deadLetters]
>> Message [mesosphere.marathon.MarathonSchedulerActor$TasksReconciled$] from
>> Actor[akka://marathon/user/MarathonScheduler/$a#1562989663] to
>> Actor[akka://marathon/deadLetters] was not delivered. [1] dead letters
>> encountered. This logging can be turned off or adjusted with configuration
>> settings 'akka.log-dead-letters' and
>> 'akka.log-dead-letters-during-shutdown'.
>> [2015-03-10 11:31:55,054] INFO Requesting task reconciliation with the
>> Mesos master (mesosphere.marathon.SchedulerActions:430)
>> [2015-03-10 11:31:55,064] INFO Received status update for task
>> ffaas-backoffice-app-nopersist.cc399489-c70f-11e4-ab88-56847afe9799:
>> TASK_LOST (Reconciliation: Task is unknown to the slave)
>> (mesosphere.marathon.MarathonScheduler:148)
>> [2015-03-10 11:31:55,069] INFO Need to scale
>> /ffaas-backoffice-app-nopersist from 0 up to 1 instances
>> (mesosphere.marathon.SchedulerActions:488)
>> [2015-03-10 11:31:55,069] INFO Queueing 1 new tasks for
>> /ffaas-backoffice-app-nopersist (0 queued)
>> (mesosphere.marathon.SchedulerActions:494)
>> [2015-03-10 11:31:55,069] INFO Task
>> ffaas-backoffice-app-nopersist.cc399489-c70f-11e4-ab88-56847afe9799
>> expunged and removed from TaskTracker
>> (mesosphere.marathon.tasks.TaskTracker:107)
>> [2015-03-10 11:31:55,070] INFO Sending event notification.
>> (mesosphere.marathon.MarathonScheduler:262)
>> [INFO] [03/10/2015 11:31:55.072]
>> [marathon-akka.actor.default-dispatcher-7] [akka://marathon/user/$b]
>> POSTing to all endpoints.
>> [2015-03-10 11:31:55,073] INFO Need to scale
>> /ffaas-backoffice-app-nopersist from 0 up to 1 instances
>> (mesosphere.marathon.SchedulerActions:488)
>> [2015-03-10 11:31:55,074] INFO Already queued 1 tasks for
>> /ffaas-backoffice-app-nopersist. Not scaling.
>> (mesosphere.marathon.SchedulerActions:498)
>> ...
>> ...
>> ...
>> [2015-03-10 11:31:57,682] INFO Received status update for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799:
>> TASK_RUNNING () (mesosphere.marathon.MarathonScheduler:148)
>> [2015-03-10 11:31:57,694] INFO Sending event notification.
>> (mesosphere.marathon.MarathonScheduler:262)
>> [INFO] [03/10/2015 11:31:57.694]
>> [marathon-akka.actor.default-dispatcher-11] [akka://marathon/user/$b]
>> POSTing to all endpoints.
>> ...
>> ...
>> ...
>> [2015-03-10 11:36:55,047] INFO Expunging orphaned tasks from store
>> (mesosphere.marathon.tasks.TaskTracker:170)
>> [INFO] [03/10/2015 11:36:55.050]
>> [marathon-akka.actor.default-dispatcher-2] [akka://marathon/deadLetters]
>> Message [mesosphere.marathon.MarathonSchedulerActor$TasksReconciled$] from
>> Actor[akka://marathon/user/MarathonScheduler/$a#1562989663] to
>> Actor[akka://marathon/deadLetters] was not delivered. [2] dead letters
>> encountered. This logging can be turned off or adjusted with configuration
>> settings 'akka.log-dead-letters' and
>> 'akka.log-dead-letters-during-shutdown'.
>> [2015-03-10 11:36:55,057] INFO Syncing tasks for all apps
>> (mesosphere.marathon.SchedulerActions:403)
>> [2015-03-10 11:36:55,058] INFO Requesting task reconciliation with the
>> Mesos master (mesosphere.marathon.SchedulerActions:430)
>> [2015-03-10 11:36:55,063] INFO Received status update for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799:
>> TASK_RUNNING (Reconciliation: Latest task state)
>> (mesosphere.marathon.MarathonScheduler:148)
>> [2015-03-10 11:36:55,065] INFO Received status update for task
>> ffaas-backoffice-app-nopersist.ad9b55a7-c710-11e4-83a7-56847afe9799:
>> TASK_RUNNING (Reconciliation: Latest task state)
>> (mesosphere.marathon.MarathonScheduler:148)
>> [2015-03-10 11:36:55,066] INFO Already running 1 instances of
>> /ffaas-backoffice-app-nopersist. Not scaling.
>> (mesosphere.marathon.SchedulerActions:512)
>>
>>
>>
>> -- End of logs
>>
>>
>>
>> 2015-03-10 10:25 GMT+01:00 Adam Bordelon <adam@mesosphere.io>:
>>
>>> This is certainly not the expected/desired behavior when failing over a
>>> mesos master in HA mode. In addition to the master logs Alex requested, can
>>> you also provide relevant portions of the slave logs for these tasks? If
>>> the slave processes themselves never failed over, checkpointing and slave
>>> recovery should be irrelevant. Are you running the mesos-slave itself
>>> inside a Docker, or any other non-traditional setup?
>>>
>>> FYI, --checkpoint defaults to true (and is removed in 0.22), --recover
>>> defaults to "reconnect", and --strict defaults to true, so none of those
>>> are necessary.
>>>
>>> On Fri, Mar 6, 2015 at 10:09 AM, Alex Rukletsov <alex@mesosphere.io>
>>> wrote:
>>>
>>>> Geoffroy,
>>>>
>>>> could you please provide master logs (both from killed and taking over
>>>> masters)?
>>>>
>>>> On Fri, Mar 6, 2015 at 4:26 AM, Geoffroy Jabouley <
>>>> geoffroy.jabouley@gmail.com> wrote:
>>>>
>>>>> Hello
>>>>>
>>>>> we are facing some unexpecting issues when testing high availability
>>>>> behaviors of our mesos cluster.
>>>>>
>>>>> *Our use case:*
>>>>>
>>>>> *State*: the mesos cluster is up (3 machines), 1 docker task is
>>>>> running on each slave (started from marathon)
>>>>>
>>>>> *Action*: stop the mesos master leader process
>>>>>
>>>>> *Expected*: mesos master leader has changed, *active tasks remain
>>>>> unchanged*
>>>>>
>>>>> *Seen*: mesos master leader has changed, *all active tasks are now
>>>>> FAILED but docker containers are still running*, marathon detects
>>>>> FAILED tasks and starts new tasks. We end with 2 docker containers running
>>>>> on each machine, but only one is linked to a RUNNING mesos task.
>>>>>
>>>>>
>>>>> Is the seen behavior correct?
>>>>>
>>>>> Have we misunderstood the high availability concept? We thought that
>>>>> doing this use case would not have any impact on the current cluster state
>>>>> (except leader re-election)
>>>>>
>>>>> Thanks in advance for your help
>>>>> Regards
>>>>>
>>>>> ---------------------------------------------------
>>>>>
>>>>> our setup is the following:
>>>>> 3 identical mesos nodes with:
>>>>>     + zookeeper
>>>>>     + docker 1.5
>>>>>     + mesos master 0.21.1 configured in HA mode
>>>>>     + mesos slave 0.21.1 configured with checkpointing, strict and
>>>>> reconnect
>>>>>     + marathon 0.8.0 configured in HA mode with checkpointing
>>>>>
>>>>> ---------------------------------------------------
>>>>>
>>>>> Command lines:
>>>>>
>>>>>
>>>>> *mesos-master*usr/sbin/mesos-master --zk=zk://10.195.30.19:2181,
>>>>> 10.195.30.20:2181,10.195.30.21:2181/mesos --port=5050
>>>>> --cluster=ECP_FFaaS_Cluster --hostname=10.195.30.19 --ip=10.195.30.19
>>>>> --quorum=2 --slave_reregister_timeout=1days --work_dir=/var/lib/mesos
>>>>>
>>>>> *mesos-slave*
>>>>> /usr/sbin/mesos-slave --master=zk://10.195.30.19:2181,
>>>>> 10.195.30.20:2181,10.195.30.21:2181/mesos --checkpoint
>>>>> --containerizers=docker,mesos --executor_registration_timeout=5mins
>>>>> --hostname=10.195.30.19 --ip=10.195.30.19
>>>>> --isolation=cgroups/cpu,cgroups/mem --recover=reconnect
>>>>> --recovery_timeout=120mins --strict --resources=ports:[31000-32000,80,443]
>>>>>
>>>>> *marathon*
>>>>> java -Djava.library.path=/usr/local/lib:/usr/lib:/usr/lib64
>>>>> -Djava.util.logging.SimpleFormatter.format=%2$s%5$s%6$s%n -Xmx512m -cp
>>>>> /usr/bin/marathon mesosphere.marathon.Main --local_port_max 32000
>>>>> --local_port_min 31000 --task_launch_timeout 300000 --http_port 8080
>>>>> --hostname 10.195.30.19 --event_subscriber http_callback --ha --https_port
>>>>> 8443 --checkpoint --zk zk://10.195.30.19:2181,10.195.30.20:2181,
>>>>> 10.195.30.21:2181/marathon --master zk://10.195.30.19:2181,
>>>>> 10.195.30.20:2181,10.195.30.21:2181/mesos
>>>>>
>>>>
>>>>
>>>
>>
>

Mime
View raw message