Return-Path: X-Original-To: apmail-mesos-issues-archive@minotaur.apache.org Delivered-To: apmail-mesos-issues-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 19B8818E01 for ; Tue, 25 Aug 2015 22:36:46 +0000 (UTC) Received: (qmail 18242 invoked by uid 500); 25 Aug 2015 22:36:46 -0000 Delivered-To: apmail-mesos-issues-archive@mesos.apache.org Received: (qmail 18211 invoked by uid 500); 25 Aug 2015 22:36:46 -0000 Mailing-List: contact issues-help@mesos.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@mesos.apache.org Delivered-To: mailing list issues@mesos.apache.org Received: (qmail 18200 invoked by uid 99); 25 Aug 2015 22:36:45 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 25 Aug 2015 22:36:45 +0000 Date: Tue, 25 Aug 2015 22:36:45 +0000 (UTC) From: "Anand Mazumdar (JIRA)" To: issues@mesos.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Assigned] (MESOS-3311) SlaveTest.HTTPSchedulerSlaveRestart MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/MESOS-3311?page=3Dcom.atlassia= n.jira.plugin.system.issuetabpanels:all-tabpanel ] Anand Mazumdar reassigned MESOS-3311: ------------------------------------- Assignee: Anand Mazumdar > SlaveTest.HTTPSchedulerSlaveRestart > ----------------------------------- > > Key: MESOS-3311 > URL: https://issues.apache.org/jira/browse/MESOS-3311 > Project: Mesos > Issue Type: Bug > Components: test > Affects Versions: 0.24.0 > Environment: https://builds.apache.org/job/Mesos/COMPILER=3Dclang= ,CONFIGURATION=3D--verbose%20--enable-libevent%20--enable-ssl,OS=3Dubuntu:1= 4.04,label_exp=3Ddocker%7C%7CHadoop/729/consoleFull > Reporter: Vinod Kone > Assignee: Anand Mazumdar > Labels: flaky-test > > Observed on ASF CI > {code} > [ RUN ] SlaveTest.HTTPSchedulerSlaveRestart > Using temporary directory '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_CXyDr= A' > I0825 22:07:36.809872 27610 leveldb.cpp:176] Opened db in 3.751801ms > I0825 22:07:36.811115 27610 leveldb.cpp:183] Compacted db in 1.2194ms > I0825 22:07:36.811175 27610 leveldb.cpp:198] Created db iterator in 30669= ns > I0825 22:07:36.811197 27610 leveldb.cpp:204] Seeked to beginning of db in= 7829ns > I0825 22:07:36.811208 27610 leveldb.cpp:273] Iterated through 0 keys in t= he db in 6017ns > I0825 22:07:36.811245 27610 replica.cpp:744] Replica recovered with log p= ositions 0 -> 0 with 1 holes and 0 unlearned > I0825 22:07:36.811722 27638 recover.cpp:449] Starting replica recovery > I0825 22:07:36.811980 27638 recover.cpp:475] Replica is in EMPTY status > I0825 22:07:36.813033 27641 replica.cpp:641] Replica in EMPTY status rece= ived a broadcasted recover request > I0825 22:07:36.813355 27635 recover.cpp:195] Received a recover response = from a replica in EMPTY status > I0825 22:07:36.813756 27628 recover.cpp:566] Updating replica status to S= TARTING > I0825 22:07:36.814434 27636 leveldb.cpp:306] Persisting metadata (8 bytes= ) to leveldb took 570160ns > I0825 22:07:36.814471 27636 replica.cpp:323] Persisted replica status to = STARTING > I0825 22:07:36.814743 27642 recover.cpp:475] Replica is in STARTING statu= s > I0825 22:07:36.814965 27638 master.cpp:378] Master 20150825-220736-234885= 548-51219-27610 (09c6504e3a31) started on 172.17.0.14:51219 > I0825 22:07:36.814999 27638 master.cpp:380] Flags at startup: --acls=3D""= --allocation_interval=3D"1secs" --allocator=3D"HierarchicalDRF" --authenti= cate=3D"true" --authenticate_slaves=3D"true" --authenticators=3D"crammd5" -= -authorizers=3D"local" --credentials=3D"/tmp/SlaveTest_HTTPSchedulerSlaveRe= start_CXyDrA/credentials" --framework_sorter=3D"drf" --help=3D"false" --ini= tialize_driver_logging=3D"true" --log_auto_initialize=3D"true" --logbufsecs= =3D"0" --logging_level=3D"INFO" --max_slave_ping_timeouts=3D"5" --quiet=3D"= false" --recovery_slave_removal_limit=3D"100%" --registry=3D"replicated_log= " --registry_fetch_timeout=3D"1mins" --registry_store_timeout=3D"25secs" --= registry_strict=3D"true" --root_submissions=3D"true" --slave_ping_timeout= =3D"15secs" --slave_reregister_timeout=3D"10mins" --user_sorter=3D"drf" --v= ersion=3D"false" --webui_dir=3D"/mesos/mesos-0.25.0/_inst/share/mesos/webui= " --work_dir=3D"/tmp/SlaveTest_HTTPSchedulerSlaveRestart_CXyDrA/master" --z= k_session_timeout=3D"10secs" > I0825 22:07:36.815347 27638 master.cpp:425] Master only allowing authenti= cated frameworks to register > I0825 22:07:36.815371 27638 master.cpp:430] Master only allowing authenti= cated slaves to register > I0825 22:07:36.815402 27638 credentials.hpp:37] Loading credentials for a= uthentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_CXyDrA/credent= ials' > I0825 22:07:36.815634 27632 replica.cpp:641] Replica in STARTING status r= eceived a broadcasted recover request > I0825 22:07:36.815752 27638 master.cpp:469] Using default 'crammd5' authe= nticator > I0825 22:07:36.815904 27638 master.cpp:506] Authorization enabled > I0825 22:07:36.815979 27643 recover.cpp:195] Received a recover response = from a replica in STARTING status > I0825 22:07:36.816185 27637 whitelist_watcher.cpp:79] No whitelist given > I0825 22:07:36.816186 27641 hierarchical.hpp:346] Initialized hierarchica= l allocator process > I0825 22:07:36.816519 27630 recover.cpp:566] Updating replica status to V= OTING > I0825 22:07:36.817258 27639 leveldb.cpp:306] Persisting metadata (8 bytes= ) to leveldb took 475231ns > I0825 22:07:36.817296 27639 replica.cpp:323] Persisted replica status to = VOTING > I0825 22:07:36.817420 27637 master.cpp:1525] The newly elected leader is = master@172.17.0.14:51219 with id 20150825-220736-234885548-51219-27610 > I0825 22:07:36.817467 27637 master.cpp:1538] Elected as the leading maste= r! > I0825 22:07:36.817483 27637 master.cpp:1308] Recovering from registrar > I0825 22:07:36.817509 27635 recover.cpp:580] Successfully joined the Paxo= s group > I0825 22:07:36.817708 27633 registrar.cpp:311] Recovering registrar > I0825 22:07:36.817844 27635 recover.cpp:464] Recover process terminated > I0825 22:07:36.818439 27631 log.cpp:661] Attempting to start the writer > I0825 22:07:36.819694 27636 replica.cpp:477] Replica received implicit pr= omise request with proposal 1 > I0825 22:07:36.820133 27636 leveldb.cpp:306] Persisting metadata (8 bytes= ) to leveldb took 421255ns > I0825 22:07:36.820168 27636 replica.cpp:345] Persisted promised to 1 > I0825 22:07:36.820804 27630 coordinator.cpp:231] Coordinator attemping to= fill missing position > I0825 22:07:36.822105 27638 replica.cpp:378] Replica received explicit pr= omise request for position 0 with proposal 2 > I0825 22:07:36.822597 27638 leveldb.cpp:343] Persisting action (8 bytes) = to leveldb took 468065ns > I0825 22:07:36.822625 27638 replica.cpp:679] Persisted action at 0 > I0825 22:07:36.823737 27637 replica.cpp:511] Replica received write reque= st for position 0 > I0825 22:07:36.823796 27637 leveldb.cpp:438] Reading position from leveld= b took 39603ns > I0825 22:07:36.824267 27637 leveldb.cpp:343] Persisting action (14 bytes)= to leveldb took 446655ns > I0825 22:07:36.824296 27637 replica.cpp:679] Persisted action at 0 > I0825 22:07:36.824961 27634 replica.cpp:658] Replica received learned not= ice for position 0 > I0825 22:07:36.825340 27634 leveldb.cpp:343] Persisting action (16 bytes)= to leveldb took 362236ns > I0825 22:07:36.825369 27634 replica.cpp:679] Persisted action at 0 > I0825 22:07:36.825388 27634 replica.cpp:664] Replica learned NOP action a= t position 0 > I0825 22:07:36.825975 27642 log.cpp:677] Writer started with ending posit= ion 0 > I0825 22:07:36.826997 27628 leveldb.cpp:438] Reading position from leveld= b took 56us > I0825 22:07:36.829946 27639 registrar.cpp:344] Successfully fetched the r= egistry (0B) in 12.187136ms > I0825 22:07:36.830077 27639 registrar.cpp:443] Applied 1 operations in 40= 874ns; attempting to update the 'registry' > I0825 22:07:36.832870 27635 log.cpp:685] Attempting to append 174 bytes t= o the log > I0825 22:07:36.833088 27641 coordinator.cpp:341] Coordinator attempting t= o write APPEND action at position 1 > I0825 22:07:36.833845 27636 replica.cpp:511] Replica received write reque= st for position 1 > I0825 22:07:36.834293 27636 leveldb.cpp:343] Persisting action (193 bytes= ) to leveldb took 425175ns > I0825 22:07:36.834324 27636 replica.cpp:679] Persisted action at 1 > I0825 22:07:36.835077 27643 replica.cpp:658] Replica received learned not= ice for position 1 > I0825 22:07:36.835500 27643 leveldb.cpp:343] Persisting action (195 bytes= ) to leveldb took 404831ns > I0825 22:07:36.835532 27643 replica.cpp:679] Persisted action at 1 > I0825 22:07:36.835574 27643 replica.cpp:664] Replica learned APPEND actio= n at position 1 > I0825 22:07:36.836545 27643 registrar.cpp:488] Successfully updated the '= registry' in 6.393088ms > I0825 22:07:36.836707 27643 registrar.cpp:374] Successfully recovered reg= istrar > I0825 22:07:36.836874 27639 log.cpp:704] Attempting to truncate the log t= o 1 > I0825 22:07:36.837174 27632 master.cpp:1335] Recovered 0 slaves from the = Registry (135B) ; allowing 10mins for slaves to re-register > I0825 22:07:36.837291 27634 coordinator.cpp:341] Coordinator attempting t= o write TRUNCATE action at position 2 > I0825 22:07:36.838249 27639 replica.cpp:511] Replica received write reque= st for position 2 > I0825 22:07:36.838685 27639 leveldb.cpp:343] Persisting action (16 bytes)= to leveldb took 412214ns > I0825 22:07:36.838716 27639 replica.cpp:679] Persisted action at 2 > I0825 22:07:36.839735 27628 replica.cpp:658] Replica received learned not= ice for position 2 > I0825 22:07:36.840304 27628 leveldb.cpp:343] Persisting action (18 bytes)= to leveldb took 547841ns > I0825 22:07:36.840375 27628 leveldb.cpp:401] Deleting ~1 keys from leveld= b took 51256ns > I0825 22:07:36.840401 27628 replica.cpp:679] Persisted action at 2 > I0825 22:07:36.840428 27628 replica.cpp:664] Replica learned TRUNCATE act= ion at position 2 > I0825 22:07:36.849371 27610 containerizer.cpp:143] Using isolation: posix= /cpu,posix/mem,filesystem/posix > I0825 22:07:36.856500 27633 slave.cpp:190] Slave started on 286)@172.17.0= .14:51219 > I0825 22:07:36.856541 27633 slave.cpp:191] Flags at startup: --appc_store= _dir=3D"/tmp/mesos/store/appc" --authenticatee=3D"crammd5" --cgroups_cpu_en= able_pids_and_tids_count=3D"false" --cgroups_enable_cfs=3D"false" --cgroups= _hierarchy=3D"/sys/fs/cgroup" --cgroups_limit_swap=3D"false" --cgroups_root= =3D"mesos" --container_disk_watch_interval=3D"15secs" --containerizers=3D"m= esos" --credential=3D"/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/crede= ntial" --default_role=3D"*" --disk_watch_interval=3D"1mins" --docker=3D"doc= ker" --docker_kill_orphans=3D"true" --docker_remove_delay=3D"6hrs" --docker= _socket=3D"/var/run/docker.sock" --docker_stop_timeout=3D"0ns" --enforce_co= ntainer_disk_quota=3D"false" --executor_registration_timeout=3D"1mins" --ex= ecutor_shutdown_grace_period=3D"5secs" --fetcher_cache_dir=3D"/tmp/SlaveTes= t_HTTPSchedulerSlaveRestart_ukkA8L/fetch" --fetcher_cache_size=3D"2GB" --fr= ameworks_home=3D"" --gc_delay=3D"1weeks" --gc_disk_headroom=3D"0.1" --hadoo= p_home=3D"" --help=3D"false" --initialize_driver_logging=3D"true" --isolati= on=3D"posix/cpu,posix/mem" --launcher_dir=3D"/mesos/mesos-0.25.0/_build/src= " --logbufsecs=3D"0" --logging_level=3D"INFO" --oversubscribed_resources_in= terval=3D"15secs" --perf_duration=3D"10secs" --perf_interval=3D"1mins" --qo= s_correction_interval_min=3D"0ns" --quiet=3D"false" --recover=3D"reconnect"= --recovery_timeout=3D"15mins" --registration_backoff_factor=3D"10ms" --res= ource_monitoring_interval=3D"1secs" --resources=3D"cpus:2;mem:1024;disk:102= 4;ports:[31000-32000]" --revocable_cpu_low_priority=3D"true" --sandbox_dire= ctory=3D"/mnt/mesos/sandbox" --strict=3D"true" --switch_user=3D"true" --ver= sion=3D"false" --work_dir=3D"/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8= L" > I0825 22:07:36.857074 27633 credentials.hpp:85] Loading credential for au= thentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/credenti= al' > I0825 22:07:36.857275 27633 slave.cpp:321] Slave using credential for: te= st-principal > I0825 22:07:36.857822 27633 slave.cpp:354] Slave resources: cpus(*):2; me= m(*):1024; disk(*):1024; ports(*):[31000-32000] > I0825 22:07:36.857936 27633 slave.cpp:384] Slave hostname: 09c6504e3a31 > I0825 22:07:36.857959 27633 slave.cpp:389] Slave checkpoint: true > I0825 22:07:36.858886 27637 state.cpp:54] Recovering state from '/tmp/Sla= veTest_HTTPSchedulerSlaveRestart_ukkA8L/meta' > I0825 22:07:36.859130 27638 status_update_manager.cpp:202] Recovering sta= tus update manager > I0825 22:07:36.859465 27636 containerizer.cpp:379] Recovering containeriz= er > I0825 22:07:36.860631 27634 slave.cpp:4069] Finished recovery > I0825 22:07:36.861034 27634 slave.cpp:4226] Querying resource estimator f= or oversubscribable resources > I0825 22:07:36.861239 27643 status_update_manager.cpp:176] Pausing sendin= g status updates > I0825 22:07:36.861240 27634 slave.cpp:684] New master detected at master@= 172.17.0.14:51219 > I0825 22:07:36.861322 27634 slave.cpp:747] Authenticating with master mas= ter@172.17.0.14:51219 > I0825 22:07:36.861343 27634 slave.cpp:752] Using default CRAM-MD5 authent= icatee > I0825 22:07:36.861450 27634 slave.cpp:720] Detecting new master > I0825 22:07:36.861495 27628 authenticatee.cpp:115] Creating new client SA= SL connection > I0825 22:07:36.861569 27634 slave.cpp:4240] Received oversubscribable res= ources from the resource estimator > I0825 22:07:36.861716 27632 master.cpp:4694] Authenticating slave(286)@17= 2.17.0.14:51219 > I0825 22:07:36.861799 27629 authenticator.cpp:407] Starting authenticatio= n session for crammd5_authenticatee(665)@172.17.0.14:51219 > I0825 22:07:36.862045 27642 authenticator.cpp:92] Creating new server SAS= L connection > I0825 22:07:36.862308 27635 authenticatee.cpp:206] Received SASL authenti= cation mechanisms: CRAM-MD5 > I0825 22:07:36.862337 27635 authenticatee.cpp:232] Attempting to authenti= cate with mechanism 'CRAM-MD5' > I0825 22:07:36.862421 27629 authenticator.cpp:197] Received SASL authenti= cation start > I0825 22:07:36.862478 27629 authenticator.cpp:319] Authentication require= s more steps > I0825 22:07:36.862579 27633 authenticatee.cpp:252] Received SASL authenti= cation step > I0825 22:07:36.862679 27628 authenticator.cpp:225] Received SASL authenti= cation step > I0825 22:07:36.862707 27628 auxprop.cpp:102] Request to lookup properties= for user: 'test-principal' realm: '09c6504e3a31' server FQDN: '09c6504e3a3= 1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: false=20 > I0825 22:07:36.862717 27628 auxprop.cpp:174] Looking up auxiliary propert= y '*userPassword' > I0825 22:07:36.862754 27628 auxprop.cpp:174] Looking up auxiliary propert= y '*cmusaslsecretCRAM-MD5' > I0825 22:07:36.862785 27628 auxprop.cpp:102] Request to lookup properties= for user: 'test-principal' realm: '09c6504e3a31' server FQDN: '09c6504e3a3= 1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: true=20 > I0825 22:07:36.862797 27628 auxprop.cpp:124] Skipping auxiliary property = '*userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true > I0825 22:07:36.862802 27628 auxprop.cpp:124] Skipping auxiliary property = '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true > I0825 22:07:36.862817 27628 authenticator.cpp:311] Authentication success > I0825 22:07:36.862884 27629 authenticatee.cpp:292] Authentication success > I0825 22:07:36.862921 27630 master.cpp:4724] Successfully authenticated p= rincipal 'test-principal' at slave(286)@172.17.0.14:51219 > I0825 22:07:36.862969 27642 authenticator.cpp:425] Authentication session= cleanup for crammd5_authenticatee(665)@172.17.0.14:51219 > I0825 22:07:36.863139 27639 slave.cpp:815] Successfully authenticated wit= h master master@172.17.0.14:51219 > I0825 22:07:36.863256 27639 slave.cpp:1209] Will retry registration in 15= .028678ms if necessary > I0825 22:07:36.863382 27643 master.cpp:3636] Registering slave at slave(2= 86)@172.17.0.14:51219 (09c6504e3a31) with id 20150825-220736-234885548-5121= 9-27610-S0 > I0825 22:07:36.863899 27610 sched.cpp:164] Version: 0.25.0 > I0825 22:07:36.863940 27636 registrar.cpp:443] Applied 1 operations in 94= 492ns; attempting to update the 'registry' > I0825 22:07:36.864670 27632 sched.cpp:262] New master detected at master@= 172.17.0.14:51219 > I0825 22:07:36.864790 27632 sched.cpp:318] Authenticating with master mas= ter@172.17.0.14:51219 > I0825 22:07:36.864821 27632 sched.cpp:325] Using default CRAM-MD5 authent= icatee > I0825 22:07:36.865095 27637 authenticatee.cpp:115] Creating new client SA= SL connection > I0825 22:07:36.865453 27643 master.cpp:4694] Authenticating scheduler-6c5= ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219 > I0825 22:07:36.865603 27629 authenticator.cpp:407] Starting authenticatio= n session for crammd5_authenticatee(666)@172.17.0.14:51219 > I0825 22:07:36.865840 27638 authenticator.cpp:92] Creating new server SAS= L connection > I0825 22:07:36.866217 27630 authenticatee.cpp:206] Received SASL authenti= cation mechanisms: CRAM-MD5 > I0825 22:07:36.866260 27630 authenticatee.cpp:232] Attempting to authenti= cate with mechanism 'CRAM-MD5' > I0825 22:07:36.866433 27639 authenticator.cpp:197] Received SASL authenti= cation start > I0825 22:07:36.866513 27639 authenticator.cpp:319] Authentication require= s more steps > I0825 22:07:36.866710 27630 authenticatee.cpp:252] Received SASL authenti= cation step > I0825 22:07:36.866999 27638 authenticator.cpp:225] Received SASL authenti= cation step > I0825 22:07:36.867051 27638 auxprop.cpp:102] Request to lookup properties= for user: 'test-principal' realm: '09c6504e3a31' server FQDN: '09c6504e3a3= 1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: false=20 > I0825 22:07:36.867077 27638 auxprop.cpp:174] Looking up auxiliary propert= y '*userPassword' > I0825 22:07:36.867130 27638 auxprop.cpp:174] Looking up auxiliary propert= y '*cmusaslsecretCRAM-MD5' > I0825 22:07:36.867162 27638 auxprop.cpp:102] Request to lookup properties= for user: 'test-principal' realm: '09c6504e3a31' server FQDN: '09c6504e3a3= 1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: true=20 > I0825 22:07:36.867175 27638 auxprop.cpp:124] Skipping auxiliary property = '*userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true > I0825 22:07:36.867183 27638 auxprop.cpp:124] Skipping auxiliary property = '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true > I0825 22:07:36.867202 27638 authenticator.cpp:311] Authentication success > I0825 22:07:36.867426 27636 authenticatee.cpp:292] Authentication success > I0825 22:07:36.867434 27633 authenticator.cpp:425] Authentication session= cleanup for crammd5_authenticatee(666)@172.17.0.14:51219 > I0825 22:07:36.867627 27630 master.cpp:4724] Successfully authenticated p= rincipal 'test-principal' at scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55= @172.17.0.14:51219 > I0825 22:07:36.867951 27641 sched.cpp:407] Successfully authenticated wit= h master master@172.17.0.14:51219 > I0825 22:07:36.867986 27641 sched.cpp:713] Sending SUBSCRIBE call to mast= er@172.17.0.14:51219 > I0825 22:07:36.868114 27641 sched.cpp:746] Will retry registration in 1.3= 52726078secs if necessary > I0825 22:07:36.868233 27634 log.cpp:685] Attempting to append 344 bytes t= o the log > I0825 22:07:36.868268 27638 master.cpp:2094] Received SUBSCRIBE call for = framework 'default' at scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.1= 7.0.14:51219 > I0825 22:07:36.868305 27638 master.cpp:1564] Authorizing framework princi= pal 'test-principal' to receive offers for role '*' > I0825 22:07:36.868373 27631 coordinator.cpp:341] Coordinator attempting t= o write APPEND action at position 3 > I0825 22:07:36.868614 27642 master.cpp:2164] Subscribing framework defaul= t with checkpointing enabled and capabilities [ ] > I0825 22:07:36.868999 27643 hierarchical.hpp:391] Added framework 2015082= 5-220736-234885548-51219-27610-0000 > I0825 22:07:36.869030 27643 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:36.869046 27643 hierarchical.hpp:910] Performed allocation fo= r 0 slaves in 34654ns > I0825 22:07:36.869215 27631 sched.cpp:640] Framework registered with 2015= 0825-220736-234885548-51219-27610-0000 > I0825 22:07:36.869215 27643 replica.cpp:511] Replica received write reque= st for position 3 > I0825 22:07:36.869268 27631 sched.cpp:654] Scheduler::registered took 299= 76ns > I0825 22:07:36.869453 27643 leveldb.cpp:343] Persisting action (363 bytes= ) to leveldb took 181689ns > I0825 22:07:36.869477 27643 replica.cpp:679] Persisted action at 3 > I0825 22:07:36.870075 27629 replica.cpp:658] Replica received learned not= ice for position 3 > I0825 22:07:36.870542 27629 leveldb.cpp:343] Persisting action (365 bytes= ) to leveldb took 469081ns > I0825 22:07:36.870589 27629 replica.cpp:679] Persisted action at 3 > I0825 22:07:36.870622 27629 replica.cpp:664] Replica learned APPEND actio= n at position 3 > I0825 22:07:36.872133 27632 registrar.cpp:488] Successfully updated the '= registry' in 8.113152ms > I0825 22:07:36.872354 27639 log.cpp:704] Attempting to truncate the log t= o 3 > I0825 22:07:36.872470 27632 coordinator.cpp:341] Coordinator attempting t= o write TRUNCATE action at position 4 > I0825 22:07:36.872879 27637 slave.cpp:3058] Received ping from slave-obse= rver(274)@172.17.0.14:51219 > I0825 22:07:36.873015 27636 master.cpp:3699] Registered slave 20150825-22= 0736-234885548-51219-27610-S0 at slave(286)@172.17.0.14:51219 (09c6504e3a31= ) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I0825 22:07:36.873180 27637 slave.cpp:859] Registered with master master@= 172.17.0.14:51219; given slave ID 20150825-220736-234885548-51219-27610-S0 > I0825 22:07:36.873219 27637 fetcher.cpp:77] Clearing fetcher cache > I0825 22:07:36.873410 27634 status_update_manager.cpp:183] Resuming sendi= ng status updates > I0825 22:07:36.873379 27628 hierarchical.hpp:542] Added slave 20150825-22= 0736-234885548-51219-27610-S0 (09c6504e3a31) with cpus(*):2; mem(*):1024; d= isk(*):1024; ports(*):[31000-32000] (allocated: ) > I0825 22:07:36.873482 27642 replica.cpp:511] Replica received write reque= st for position 4 > I0825 22:07:36.873661 27637 slave.cpp:882] Checkpointing SlaveInfo to '/t= mp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta/slaves/20150825-220736-2= 34885548-51219-27610-S0/slave.info' > I0825 22:07:36.874042 27642 leveldb.cpp:343] Persisting action (16 bytes)= to leveldb took 538208ns > I0825 22:07:36.874078 27642 replica.cpp:679] Persisted action at 4 > I0825 22:07:36.874196 27628 hierarchical.hpp:928] Performed allocation fo= r slave 20150825-220736-234885548-51219-27610-S0 in 739900ns > I0825 22:07:36.874204 27637 slave.cpp:918] Forwarding total oversubscribe= d resources=20 > I0825 22:07:36.874824 27635 master.cpp:4613] Sending 1 offers to framewor= k 20150825-220736-234885548-51219-27610-0000 (default) at scheduler-6c5ddcd= b-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219 > I0825 22:07:36.874958 27639 replica.cpp:658] Replica received learned not= ice for position 4 > I0825 22:07:36.875074 27635 master.cpp:3998] Received update of slave 201= 50825-220736-234885548-51219-27610-S0 at slave(286)@172.17.0.14:51219 (09c6= 504e3a31) with total oversubscribed resources=20 > I0825 22:07:36.875485 27636 sched.cpp:803] Scheduler::resourceOffers took= 243089ns > I0825 22:07:36.875450 27638 hierarchical.hpp:602] Slave 20150825-220736-2= 34885548-51219-27610-S0 (09c6504e3a31) updated with oversubscribed resource= s (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], al= located: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) > I0825 22:07:36.875495 27639 leveldb.cpp:343] Persisting action (18 bytes)= to leveldb took 462264ns > I0825 22:07:36.875643 27639 leveldb.cpp:401] Deleting ~2 keys from leveld= b took 109856ns > I0825 22:07:36.875682 27639 replica.cpp:679] Persisted action at 4 > I0825 22:07:36.875717 27639 replica.cpp:664] Replica learned TRUNCATE act= ion at position 4 > I0825 22:07:36.876045 27638 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:36.876072 27638 hierarchical.hpp:928] Performed allocation fo= r slave 20150825-220736-234885548-51219-27610-S0 in 541099ns > I0825 22:07:36.879416 27639 master.cpp:2739] Processing ACCEPT call for o= ffers: [ 20150825-220736-234885548-51219-27610-O0 ] on slave 20150825-22073= 6-234885548-51219-27610-S0 at slave(286)@172.17.0.14:51219 (09c6504e3a31) f= or framework 20150825-220736-234885548-51219-27610-0000 (default) at schedu= ler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219 > I0825 22:07:36.879475 27639 master.cpp:2570] Authorizing framework princi= pal 'test-principal' to launch task b89d1df8-f2fb-44be-8f60-9352cf32a79d as= user 'mesos' > I0825 22:07:36.880975 27639 master.hpp:170] Adding task b89d1df8-f2fb-44b= e-8f60-9352cf32a79d with resources cpus(*):2; mem(*):1024; disk(*):1024; po= rts(*):[31000-32000] on slave 20150825-220736-234885548-51219-27610-S0 (09c= 6504e3a31) > I0825 22:07:36.881124 27639 master.cpp:3069] Launching task b89d1df8-f2fb= -44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-= 0000 (default) at scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.1= 4:51219 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[3100= 0-32000] on slave 20150825-220736-234885548-51219-27610-S0 at slave(286)@17= 2.17.0.14:51219 (09c6504e3a31) > I0825 22:07:36.882314 27636 slave.cpp:1249] Got assigned task b89d1df8-f2= fb-44be-8f60-9352cf32a79d for framework 20150825-220736-234885548-51219-276= 10-0000 > I0825 22:07:36.882470 27636 slave.cpp:4720] Checkpointing FrameworkInfo t= o '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta/slaves/20150825-220= 736-234885548-51219-27610-S0/frameworks/20150825-220736-234885548-51219-276= 10-0000/framework.info' > I0825 22:07:36.882984 27636 slave.cpp:4731] Checkpointing framework pid '= @0.0.0.0:0' to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta/slaves= /20150825-220736-234885548-51219-27610-S0/frameworks/20150825-220736-234885= 548-51219-27610-0000/framework.pid' > I0825 22:07:36.884068 27636 slave.cpp:1365] Launching task b89d1df8-f2fb-= 44be-8f60-9352cf32a79d for framework 20150825-220736-234885548-51219-27610-= 0000 > I0825 22:07:36.895586 27636 slave.cpp:5156] Checkpointing ExecutorInfo to= '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta/slaves/20150825-2207= 36-234885548-51219-27610-S0/frameworks/20150825-220736-234885548-51219-2761= 0-0000/executors/b89d1df8-f2fb-44be-8f60-9352cf32a79d/executor.info' > I0825 22:07:36.896765 27636 slave.cpp:4799] Launching executor b89d1df8-f= 2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-276= 10-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/Slave= Test_HTTPSchedulerSlaveRestart_ukkA8L/slaves/20150825-220736-234885548-5121= 9-27610-S0/frameworks/20150825-220736-234885548-51219-27610-0000/executors/= b89d1df8-f2fb-44be-8f60-9352cf32a79d/runs/1499299a-93dd-4982-9249-ad0e19d1c= 06c' > I0825 22:07:36.897374 27643 containerizer.cpp:633] Starting container '14= 99299a-93dd-4982-9249-ad0e19d1c06c' for executor 'b89d1df8-f2fb-44be-8f60-9= 352cf32a79d' of framework '20150825-220736-234885548-51219-27610-0000' > I0825 22:07:36.897414 27636 slave.cpp:5179] Checkpointing TaskInfo to '/t= mp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta/slaves/20150825-220736-2= 34885548-51219-27610-S0/frameworks/20150825-220736-234885548-51219-27610-00= 00/executors/b89d1df8-f2fb-44be-8f60-9352cf32a79d/runs/1499299a-93dd-4982-9= 249-ad0e19d1c06c/tasks/b89d1df8-f2fb-44be-8f60-9352cf32a79d/task.info' > I0825 22:07:36.897974 27636 slave.cpp:1583] Queuing task 'b89d1df8-f2fb-4= 4be-8f60-9352cf32a79d' for executor b89d1df8-f2fb-44be-8f60-9352cf32a79d of= framework '20150825-220736-234885548-51219-27610-0000 > I0825 22:07:36.898123 27636 slave.cpp:637] Successfully attached file '/t= mp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/slaves/20150825-220736-234885= 548-51219-27610-S0/frameworks/20150825-220736-234885548-51219-27610-0000/ex= ecutors/b89d1df8-f2fb-44be-8f60-9352cf32a79d/runs/1499299a-93dd-4982-9249-a= d0e19d1c06c' > I0825 22:07:36.902439 27641 launcher.cpp:131] Forked child with pid '2326= ' for container '1499299a-93dd-4982-9249-ad0e19d1c06c' > I0825 22:07:36.902752 27641 containerizer.cpp:855] Checkpointing executor= 's forked pid 2326 to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta= /slaves/20150825-220736-234885548-51219-27610-S0/frameworks/20150825-220736= -234885548-51219-27610-0000/executors/b89d1df8-f2fb-44be-8f60-9352cf32a79d/= runs/1499299a-93dd-4982-9249-ad0e19d1c06c/pids/forked.pid' > WARNING: Logging before InitGoogleLogging() is written to STDERR > I0825 22:07:37.029348 2340 process.cpp:1012] libprocess is initialized o= n 172.17.0.14:42774 for 16 cpus > I0825 22:07:37.030342 2340 logging.cpp:177] Logging to STDERR > I0825 22:07:37.032822 2340 exec.cpp:133] Version: 0.25.0 > I0825 22:07:37.038837 2355 exec.cpp:183] Executor started at: executor(1= )@172.17.0.14:42774 with pid 2340 > I0825 22:07:37.041252 27638 slave.cpp:2358] Got registration for executor= 'b89d1df8-f2fb-44be-8f60-9352cf32a79d' of framework 20150825-220736-234885= 548-51219-27610-0000 from executor(1)@172.17.0.14:42774 > I0825 22:07:37.041371 27638 slave.cpp:2444] Checkpointing executor pid 'e= xecutor(1)@172.17.0.14:42774' to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_= ukkA8L/meta/slaves/20150825-220736-234885548-51219-27610-S0/frameworks/2015= 0825-220736-234885548-51219-27610-0000/executors/b89d1df8-f2fb-44be-8f60-93= 52cf32a79d/runs/1499299a-93dd-4982-9249-ad0e19d1c06c/pids/libprocess.pid' > I0825 22:07:37.044067 27634 slave.cpp:1739] Sending queued task 'b89d1df8= -f2fb-44be-8f60-9352cf32a79d' to executor 'b89d1df8-f2fb-44be-8f60-9352cf32= a79d' of framework 20150825-220736-234885548-51219-27610-0000 > I0825 22:07:37.044256 2358 exec.cpp:207] Executor registered on slave 20= 150825-220736-234885548-51219-27610-S0 > I0825 22:07:37.046058 2358 exec.cpp:219] Executor::registered took 23908= 3ns > Registered executor on 09c6504e3a31 > Starting task b89d1df8-f2fb-44be-8f60-9352cf32a79d > I0825 22:07:37.046394 2358 exec.cpp:294] Executor asked to run task 'b89= d1df8-f2fb-44be-8f60-9352cf32a79d' > I0825 22:07:37.046493 2358 exec.cpp:303] Executor::launchTask took 84034= ns > sh -c 'sleep 1000' > Forked command at 2371 > I0825 22:07:37.049942 2366 exec.cpp:516] Executor sending status update = TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8= -f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-2= 7610-0000 > I0825 22:07:37.050977 27635 slave.cpp:2696] Handling status update TASK_R= UNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-= 44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-0= 000 from executor(1)@172.17.0.14:42774 > I0825 22:07:37.051316 27632 status_update_manager.cpp:322] Received statu= s update TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task= b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-23488554= 8-51219-27610-0000 > I0825 22:07:37.051379 27632 status_update_manager.cpp:499] Creating Statu= sUpdate stream for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 2= 0150825-220736-234885548-51219-27610-0000 > I0825 22:07:37.052251 27632 status_update_manager.cpp:826] Checkpointing = UPDATE for status update TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56= a0894e) for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825= -220736-234885548-51219-27610-0000 > I0825 22:07:37.053840 27632 status_update_manager.cpp:376] Forwarding upd= ate TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d= 1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-512= 19-27610-0000 to the slave > I0825 22:07:37.054127 27642 slave.cpp:2975] Forwarding the update TASK_RU= NNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-4= 4be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-00= 00 to master@172.17.0.14:51219 > I0825 22:07:37.054364 27642 slave.cpp:2899] Status update manager success= fully handled status update TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6df= b56a0894e) for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150= 825-220736-234885548-51219-27610-0000 > I0825 22:07:37.054407 27642 slave.cpp:2905] Sending acknowledgement for s= tatus update TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for = task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-2348= 85548-51219-27610-0000 to executor(1)@172.17.0.14:42774 > I0825 22:07:37.054469 27635 master.cpp:4069] Status update TASK_RUNNING (= UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-44be-8f6= 0-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-0000 from= slave 20150825-220736-234885548-51219-27610-S0 at slave(286)@172.17.0.14:5= 1219 (09c6504e3a31) > I0825 22:07:37.054519 27635 master.cpp:4108] Forwarding status update TAS= K_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2= fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-2761= 0-0000 > I0825 22:07:37.054743 27635 master.cpp:5576] Updating the latest state of= task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234= 885548-51219-27610-0000 to TASK_RUNNING > I0825 22:07:37.055011 27641 sched.cpp:910] Scheduler::statusUpdate took 1= 69426ns > I0825 22:07:37.055639 27634 master.cpp:3398] Processing ACKNOWLEDGE call = 98c4a799-ad82-497d-be1e-6dfb56a0894e for task b89d1df8-f2fb-44be-8f60-9352c= f32a79d of framework 20150825-220736-234885548-51219-27610-0000 (default) a= t scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219 on slave= 20150825-220736-234885548-51219-27610-S0 > I0825 22:07:37.055665 2359 exec.cpp:340] Executor received status update= acknowledgement 98c4a799-ad82-497d-be1e-6dfb56a0894e for task b89d1df8-f2f= b-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-27610= -0000 > I0825 22:07:37.055886 27640 slave.cpp:564] Slave terminating > I0825 22:07:37.056210 27634 master.cpp:1012] Slave 20150825-220736-234885= 548-51219-27610-S0 at slave(286)@172.17.0.14:51219 (09c6504e3a31) disconnec= ted > I0825 22:07:37.056257 27634 master.cpp:2415] Disconnecting slave 20150825= -220736-234885548-51219-27610-S0 at slave(286)@172.17.0.14:51219 (09c6504e3= a31) > I0825 22:07:37.056339 27634 master.cpp:2434] Deactivating slave 20150825-= 220736-234885548-51219-27610-S0 at slave(286)@172.17.0.14:51219 (09c6504e3a= 31) > I0825 22:07:37.056675 27643 hierarchical.hpp:635] Slave 20150825-220736-2= 34885548-51219-27610-S0 deactivated > I0825 22:07:37.059391 27610 containerizer.cpp:143] Using isolation: posix= /cpu,posix/mem,filesystem/posix > I0825 22:07:37.066619 27641 slave.cpp:190] Slave started on 287)@172.17.0= .14:51219 > I0825 22:07:37.066668 27641 slave.cpp:191] Flags at startup: --appc_store= _dir=3D"/tmp/mesos/store/appc" --authenticatee=3D"crammd5" --cgroups_cpu_en= able_pids_and_tids_count=3D"false" --cgroups_enable_cfs=3D"false" --cgroups= _hierarchy=3D"/sys/fs/cgroup" --cgroups_limit_swap=3D"false" --cgroups_root= =3D"mesos" --container_disk_watch_interval=3D"15secs" --containerizers=3D"m= esos" --credential=3D"/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/crede= ntial" --default_role=3D"*" --disk_watch_interval=3D"1mins" --docker=3D"doc= ker" --docker_kill_orphans=3D"true" --docker_remove_delay=3D"6hrs" --docker= _socket=3D"/var/run/docker.sock" --docker_stop_timeout=3D"0ns" --enforce_co= ntainer_disk_quota=3D"false" --executor_registration_timeout=3D"1mins" --ex= ecutor_shutdown_grace_period=3D"5secs" --fetcher_cache_dir=3D"/tmp/SlaveTes= t_HTTPSchedulerSlaveRestart_ukkA8L/fetch" --fetcher_cache_size=3D"2GB" --fr= ameworks_home=3D"" --gc_delay=3D"1weeks" --gc_disk_headroom=3D"0.1" --hadoo= p_home=3D"" --help=3D"false" --initialize_driver_logging=3D"true" --isolati= on=3D"posix/cpu,posix/mem" --launcher_dir=3D"/mesos/mesos-0.25.0/_build/src= " --logbufsecs=3D"0" --logging_level=3D"INFO" --oversubscribed_resources_in= terval=3D"15secs" --perf_duration=3D"10secs" --perf_interval=3D"1mins" --qo= s_correction_interval_min=3D"0ns" --quiet=3D"false" --recover=3D"reconnect"= --recovery_timeout=3D"15mins" --registration_backoff_factor=3D"10ms" --res= ource_monitoring_interval=3D"1secs" --resources=3D"cpus:2;mem:1024;disk:102= 4;ports:[31000-32000]" --revocable_cpu_low_priority=3D"true" --sandbox_dire= ctory=3D"/mnt/mesos/sandbox" --strict=3D"true" --switch_user=3D"true" --ver= sion=3D"false" --work_dir=3D"/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8= L" > I0825 22:07:37.067343 27641 credentials.hpp:85] Loading credential for au= thentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/credenti= al' > I0825 22:07:37.067643 27641 slave.cpp:321] Slave using credential for: te= st-principal > I0825 22:07:37.068413 27641 slave.cpp:354] Slave resources: cpus(*):2; me= m(*):1024; disk(*):1024; ports(*):[31000-32000] > I0825 22:07:37.068580 27641 slave.cpp:384] Slave hostname: 09c6504e3a31 > I0825 22:07:37.068613 27641 slave.cpp:389] Slave checkpoint: true > I0825 22:07:37.069970 27636 state.cpp:54] Recovering state from '/tmp/Sla= veTest_HTTPSchedulerSlaveRestart_ukkA8L/meta' > I0825 22:07:37.070089 27636 state.cpp:690] Failed to find resources file = '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta/resources/resources.i= nfo' > I0825 22:07:37.075319 27628 fetcher.cpp:77] Clearing fetcher cache > I0825 22:07:37.075393 27628 slave.cpp:4157] Recovering framework 20150825= -220736-234885548-51219-27610-0000 > I0825 22:07:37.075475 27628 slave.cpp:4908] Recovering executor 'b89d1df8= -f2fb-44be-8f60-9352cf32a79d' of framework 20150825-220736-234885548-51219-= 27610-0000 > I0825 22:07:37.076370 27641 status_update_manager.cpp:202] Recovering sta= tus update manager > I0825 22:07:37.076409 27641 status_update_manager.cpp:210] Recovering exe= cutor 'b89d1df8-f2fb-44be-8f60-9352cf32a79d' of framework 20150825-220736-2= 34885548-51219-27610-0000 > I0825 22:07:37.076504 27641 status_update_manager.cpp:499] Creating Statu= sUpdate stream for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 2= 0150825-220736-234885548-51219-27610-0000 > I0825 22:07:37.077056 27641 status_update_manager.cpp:802] Replaying stat= us update stream for task b89d1df8-f2fb-44be-8f60-9352cf32a79d > I0825 22:07:37.077715 27628 slave.cpp:637] Successfully attached file '/t= mp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/slaves/20150825-220736-234885= 548-51219-27610-S0/frameworks/20150825-220736-234885548-51219-27610-0000/ex= ecutors/b89d1df8-f2fb-44be-8f60-9352cf32a79d/runs/1499299a-93dd-4982-9249-a= d0e19d1c06c' > I0825 22:07:37.078111 27634 containerizer.cpp:379] Recovering containeriz= er > I0825 22:07:37.078229 27634 containerizer.cpp:434] Recovering container '= 1499299a-93dd-4982-9249-ad0e19d1c06c' for executor 'b89d1df8-f2fb-44be-8f60= -9352cf32a79d' of framework 20150825-220736-234885548-51219-27610-0000 > I0825 22:07:37.079934 27640 slave.cpp:4010] Sending reconnect request to = executor b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-= 234885548-51219-27610-0000 at executor(1)@172.17.0.14:42774 > I0825 22:07:37.081012 2354 exec.cpp:253] Received reconnect request from= slave 20150825-220736-234885548-51219-27610-S0 > I0825 22:07:37.081893 27631 slave.cpp:2508] Re-registering executor b89d1= df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-5121= 9-27610-0000 > I0825 22:07:37.082904 2362 exec.cpp:230] Executor re-registered on slave= 20150825-220736-234885548-51219-27610-S0 > Re-registered executor on 09c6504e3a31 > I0825 22:07:37.084738 2362 exec.cpp:242] Executor::reregistered took 119= 419ns > I0825 22:07:37.816828 27634 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:37.816884 27634 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 129850ns > I0825 22:07:38.817526 27629 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:38.817607 27629 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 152923ns > I0825 22:07:39.081434 27637 slave.cpp:2645] Cleaning up un-reregistered e= xecutors > I0825 22:07:39.081596 27637 slave.cpp:4069] Finished recovery > I0825 22:07:39.082165 27637 slave.cpp:4226] Querying resource estimator f= or oversubscribable resources > I0825 22:07:39.082417 27637 status_update_manager.cpp:176] Pausing sendin= g status updates > I0825 22:07:39.082442 27643 slave.cpp:684] New master detected at master@= 172.17.0.14:51219 > I0825 22:07:39.082602 27643 slave.cpp:747] Authenticating with master mas= ter@172.17.0.14:51219 > I0825 22:07:39.082628 27643 slave.cpp:752] Using default CRAM-MD5 authent= icatee > I0825 22:07:39.082830 27643 slave.cpp:720] Detecting new master > I0825 22:07:39.082919 27638 authenticatee.cpp:115] Creating new client SA= SL connection > I0825 22:07:39.082973 27643 slave.cpp:4240] Received oversubscribable res= ources from the resource estimator > I0825 22:07:39.083277 27631 master.cpp:4694] Authenticating slave(287)@17= 2.17.0.14:51219 > I0825 22:07:39.083427 27635 authenticator.cpp:407] Starting authenticatio= n session for crammd5_authenticatee(667)@172.17.0.14:51219 > I0825 22:07:39.083731 27630 authenticator.cpp:92] Creating new server SAS= L connection > I0825 22:07:39.083982 27634 authenticatee.cpp:206] Received SASL authenti= cation mechanisms: CRAM-MD5 > I0825 22:07:39.084025 27634 authenticatee.cpp:232] Attempting to authenti= cate with mechanism 'CRAM-MD5' > I0825 22:07:39.084106 27634 authenticator.cpp:197] Received SASL authenti= cation start > I0825 22:07:39.084168 27634 authenticator.cpp:319] Authentication require= s more steps > I0825 22:07:39.084300 27639 authenticatee.cpp:252] Received SASL authenti= cation step > I0825 22:07:39.084527 27628 authenticator.cpp:225] Received SASL authenti= cation step > I0825 22:07:39.084625 27628 auxprop.cpp:102] Request to lookup properties= for user: 'test-principal' realm: '09c6504e3a31' server FQDN: '09c6504e3a3= 1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: false=20 > I0825 22:07:39.084650 27628 auxprop.cpp:174] Looking up auxiliary propert= y '*userPassword' > I0825 22:07:39.084709 27628 auxprop.cpp:174] Looking up auxiliary propert= y '*cmusaslsecretCRAM-MD5' > I0825 22:07:39.084738 27628 auxprop.cpp:102] Request to lookup properties= for user: 'test-principal' realm: '09c6504e3a31' server FQDN: '09c6504e3a3= 1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SAS= L_AUXPROP_AUTHZID: true=20 > I0825 22:07:39.084750 27628 auxprop.cpp:124] Skipping auxiliary property = '*userPassword' since SASL_AUXPROP_AUTHZID =3D=3D true > I0825 22:07:39.084763 27628 auxprop.cpp:124] Skipping auxiliary property = '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID =3D=3D true > I0825 22:07:39.084780 27628 authenticator.cpp:311] Authentication success > I0825 22:07:39.084905 27642 authenticatee.cpp:292] Authentication success > I0825 22:07:39.085000 27637 master.cpp:4724] Successfully authenticated p= rincipal 'test-principal' at slave(287)@172.17.0.14:51219 > I0825 22:07:39.085234 27642 slave.cpp:815] Successfully authenticated wit= h master master@172.17.0.14:51219 > I0825 22:07:39.085610 27642 slave.cpp:1209] Will retry registration in 6.= 014445ms if necessary > I0825 22:07:39.085907 27643 authenticator.cpp:425] Authentication session= cleanup for crammd5_authenticatee(667)@172.17.0.14:51219 > I0825 22:07:39.092914 27640 master.cpp:3773] Re-registering slave 2015082= 5-220736-234885548-51219-27610-S0 at slave(286)@172.17.0.14:51219 (09c6504e= 3a31) > I0825 22:07:39.093181 27630 slave.cpp:1209] Will retry registration in 20= .588077ms if necessary > I0825 22:07:39.093858 27635 slave.cpp:959] Re-registered with master mast= er@172.17.0.14:51219 > I0825 22:07:39.093879 27638 hierarchical.hpp:621] Slave 20150825-220736-2= 34885548-51219-27610-S0 reactivated > I0825 22:07:39.093855 27640 master.cpp:3936] Sending updated checkpointed= resources to slave 20150825-220736-234885548-51219-27610-S0 at slave(287)= @172.17.0.14:51219 (09c6504e3a31) > I0825 22:07:39.094110 27631 status_update_manager.cpp:183] Resuming sendi= ng status updates > I0825 22:07:39.094130 27635 slave.cpp:995] Forwarding total oversubscribe= d resources=20 > W0825 22:07:39.094172 27631 status_update_manager.cpp:190] Resending stat= us update TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for tas= k b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-2348855= 48-51219-27610-0000 > I0825 22:07:39.094211 27631 status_update_manager.cpp:376] Forwarding upd= ate TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d= 1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-512= 19-27610-0000 to the slave > I0825 22:07:39.094435 27640 master.cpp:3773] Re-registering slave 2015082= 5-220736-234885548-51219-27610-S0 at slave(287)@172.17.0.14:51219 (09c6504e= 3a31) > I0825 22:07:39.094602 27635 slave.cpp:2227] Updated checkpointed resource= s from to=20 > I0825 22:07:39.095346 27640 master.cpp:3936] Sending updated checkpointed= resources to slave 20150825-220736-234885548-51219-27610-S0 at slave(287)= @172.17.0.14:51219 (09c6504e3a31) > I0825 22:07:39.095775 27635 slave.cpp:2975] Forwarding the update TASK_RU= NNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-4= 4be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-00= 00 to master@172.17.0.14:51219 > I0825 22:07:39.095803 27640 master.cpp:3998] Received update of slave 201= 50825-220736-234885548-51219-27610-S0 at slave(287)@172.17.0.14:51219 (09c6= 504e3a31) with total oversubscribed resources=20 > I0825 22:07:39.096372 27635 slave.cpp:2131] Updating framework 20150825-2= 20736-234885548-51219-27610-0000 pid to @0.0.0.0:0 > I0825 22:07:39.096467 27635 slave.cpp:2147] Checkpointing framework pid '= @0.0.0.0:0' to '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta/slaves= /20150825-220736-234885548-51219-27610-S0/frameworks/20150825-220736-234885= 548-51219-27610-0000/framework.pid' > I0825 22:07:39.096544 27640 hierarchical.hpp:602] Slave 20150825-220736-2= 34885548-51219-27610-S0 (09c6504e3a31) updated with oversubscribed resource= s (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], al= located: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) > I0825 22:07:39.096652 27639 master.cpp:4069] Status update TASK_RUNNING (= UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-44be-8f6= 0-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-0000 from= slave 20150825-220736-234885548-51219-27610-S0 at slave(287)@172.17.0.14:5= 1219 (09c6504e3a31) > I0825 22:07:39.096709 27639 master.cpp:4108] Forwarding status update TAS= K_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2= fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-2761= 0-0000 > I0825 22:07:39.096978 27639 master.cpp:5576] Updating the latest state of= task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234= 885548-51219-27610-0000 to TASK_RUNNING > I0825 22:07:39.097105 27639 status_update_manager.cpp:183] Resuming sendi= ng status updates > W0825 22:07:39.097187 27635 slave.cpp:976] Already re-registered with mas= ter master@172.17.0.14:51219 > I0825 22:07:39.097229 27635 slave.cpp:995] Forwarding total oversubscribe= d resources=20 > W0825 22:07:39.097230 27639 status_update_manager.cpp:190] Resending stat= us update TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for tas= k b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-2348855= 48-51219-27610-0000 > I0825 22:07:39.097290 27639 status_update_manager.cpp:376] Forwarding upd= ate TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d= 1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-512= 19-27610-0000 to the slave > I0825 22:07:39.097373 27643 sched.cpp:910] Scheduler::statusUpdate took 7= 6470ns > I0825 22:07:39.097450 27635 slave.cpp:2131] Updating framework 20150825-2= 20736-234885548-51219-27610-0000 pid to scheduler-6c5ddcdb-9dd1-4b38-b051-5= f714d3c1c55@172.17.0.14:51219 > I0825 22:07:39.097473 27640 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:39.097497 27640 hierarchical.hpp:928] Performed allocation fo= r slave 20150825-220736-234885548-51219-27610-S0 in 818746ns > I0825 22:07:39.097525 27635 slave.cpp:2147] Checkpointing framework pid '= scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219' to '/tmp/= SlaveTest_HTTPSchedulerSlaveRestart_ukkA8L/meta/slaves/20150825-220736-2348= 85548-51219-27610-S0/frameworks/20150825-220736-234885548-51219-27610-0000/= framework.pid' > I0825 22:07:39.097991 27640 status_update_manager.cpp:183] Resuming sendi= ng status updates > W0825 22:07:39.098043 27640 status_update_manager.cpp:190] Resending stat= us update TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for tas= k b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-2348855= 48-51219-27610-0000 > I0825 22:07:39.098093 27640 status_update_manager.cpp:376] Forwarding upd= ate TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d= 1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-512= 19-27610-0000 to the slave > I0825 22:07:39.098242 27635 slave.cpp:2227] Updated checkpointed resource= s from to=20 > I0825 22:07:39.098433 27635 slave.cpp:3043] Sending message for framework= 20150825-220736-234885548-51219-27610-0000 to scheduler-6c5ddcdb-9dd1-4b38= -b051-5f714d3c1c55@172.17.0.14:51219 > I0825 22:07:39.098480 27636 master.cpp:3998] Received update of slave 201= 50825-220736-234885548-51219-27610-S0 at slave(287)@172.17.0.14:51219 (09c6= 504e3a31) with total oversubscribed resources=20 > I0825 22:07:39.098639 27635 slave.cpp:2975] Forwarding the update TASK_RU= NNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-4= 4be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-00= 00 to master@172.17.0.14:51219 > I0825 22:07:39.098755 27634 sched.cpp:1006] Scheduler::frameworkMessage t= ook 68683ns > I0825 22:07:39.098882 27636 master.cpp:3398] Processing ACKNOWLEDGE call = 98c4a799-ad82-497d-be1e-6dfb56a0894e for task b89d1df8-f2fb-44be-8f60-9352c= f32a79d of framework 20150825-220736-234885548-51219-27610-0000 (default) a= t scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219 on slave= 20150825-220736-234885548-51219-27610-S0 > I0825 22:07:39.098906 27635 slave.cpp:2975] Forwarding the update TASK_RU= NNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-4= 4be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-00= 00 to master@172.17.0.14:51219 > I0825 22:07:39.099019 27641 hierarchical.hpp:602] Slave 20150825-220736-2= 34885548-51219-27610-S0 (09c6504e3a31) updated with oversubscribed resource= s (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], al= located: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) > I0825 22:07:39.099192 27636 master.cpp:4069] Status update TASK_RUNNING (= UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-44be-8f6= 0-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-0000 from= slave 20150825-220736-234885548-51219-27610-S0 at slave(287)@172.17.0.14:5= 1219 (09c6504e3a31) > I0825 22:07:39.099244 27636 master.cpp:4108] Forwarding status update TAS= K_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2= fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-2761= 0-0000 > I0825 22:07:39.099369 27641 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:39.099395 27641 hierarchical.hpp:928] Performed allocation fo= r slave 20150825-220736-234885548-51219-27610-S0 in 332336ns > I0825 22:07:39.099403 27636 master.cpp:5576] Updating the latest state of= task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234= 885548-51219-27610-0000 to TASK_RUNNING > I0825 22:07:39.099426 27635 status_update_manager.cpp:394] Received statu= s update acknowledgement (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for t= ask b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-23488= 5548-51219-27610-0000 > I0825 22:07:39.099609 27641 sched.cpp:910] Scheduler::statusUpdate took 9= 0272ns > I0825 22:07:39.099617 27636 master.cpp:4069] Status update TASK_RUNNING (= UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-44be-8f6= 0-9352cf32a79d of framework 20150825-220736-234885548-51219-27610-0000 from= slave 20150825-220736-234885548-51219-27610-S0 at slave(287)@172.17.0.14:5= 1219 (09c6504e3a31) > I0825 22:07:39.099669 27636 master.cpp:4108] Forwarding status update TAS= K_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89d1df8-f2= fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51219-2761= 0-0000 > I0825 22:07:39.099607 27635 status_update_manager.cpp:826] Checkpointing = ACK for status update TASK_RUNNING (UUID: 98c4a799-ad82-497d-be1e-6dfb56a08= 94e) for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-22= 0736-234885548-51219-27610-0000 > I0825 22:07:39.099834 27636 master.cpp:5576] Updating the latest state of= task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234= 885548-51219-27610-0000 to TASK_RUNNING > I0825 22:07:39.099992 27643 sched.cpp:910] Scheduler::statusUpdate took 2= 9331ns > I0825 22:07:39.100038 27636 master.cpp:3398] Processing ACKNOWLEDGE call = 98c4a799-ad82-497d-be1e-6dfb56a0894e for task b89d1df8-f2fb-44be-8f60-9352c= f32a79d of framework 20150825-220736-234885548-51219-27610-0000 (default) a= t scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219 on slave= 20150825-220736-234885548-51219-27610-S0 > I0825 22:07:39.100381 27636 master.cpp:3398] Processing ACKNOWLEDGE call = 98c4a799-ad82-497d-be1e-6dfb56a0894e for task b89d1df8-f2fb-44be-8f60-9352c= f32a79d of framework 20150825-220736-234885548-51219-27610-0000 (default) a= t scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219 on slave= 20150825-220736-234885548-51219-27610-S0 > I0825 22:07:39.102119 27635 status_update_manager.cpp:394] Received statu= s update acknowledgement (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for t= ask b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-23488= 5548-51219-27610-0000 > I0825 22:07:39.102120 27637 slave.cpp:2298] Status update manager success= fully handled status update acknowledgement (UUID: 98c4a799-ad82-497d-be1e-= 6dfb56a0894e) for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20= 150825-220736-234885548-51219-27610-0000 > I0825 22:07:39.102375 27635 status_update_manager.cpp:394] Received statu= s update acknowledgement (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for t= ask b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-23488= 5548-51219-27610-0000 > E0825 22:07:39.102407 27633 slave.cpp:2291] Failed to handle status updat= e acknowledgement (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89= d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51= 219-27610-0000: Unexpected status update acknowledgment (UUID: 98c4a799-ad8= 2-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of = framework 20150825-220736-234885548-51219-27610-0000 > E0825 22:07:39.102546 27636 slave.cpp:2291] Failed to handle status updat= e acknowledgement (UUID: 98c4a799-ad82-497d-be1e-6dfb56a0894e) for task b89= d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234885548-51= 219-27610-0000: Unexpected status update acknowledgment (UUID: 98c4a799-ad8= 2-497d-be1e-6dfb56a0894e) for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of = framework 20150825-220736-234885548-51219-27610-0000 > I0825 22:07:39.819394 27637 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:39.819452 27637 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 536774ns > 2015-08-25 22:07:40,051:27610(0x2b3b2870c700):ZOO_ERROR@handle_socket_err= or_msg@1697: Socket [127.0.0.1:40031] zk retcode=3D-4, errno=3D111(Connecti= on refused): server refused to accept the client > I0825 22:07:40.820246 27633 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:40.820302 27633 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 511814ns > I0825 22:07:41.821671 27637 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:41.821719 27637 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 518909ns > I0825 22:07:42.822906 27628 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:42.822959 27628 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 659816ns > 2015-08-25 22:07:43,388:27610(0x2b3b2870c700):ZOO_ERROR@handle_socket_err= or_msg@1697: Socket [127.0.0.1:40031] zk retcode=3D-4, errno=3D111(Connecti= on refused): server refused to accept the client > I0825 22:07:43.824976 27632 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:43.825032 27632 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 727197ns > I0825 22:07:44.825883 27641 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:44.825932 27641 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 422745ns > I0825 22:07:45.828217 27634 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:45.828445 27634 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 1.288273ms > 2015-08-25 22:07:46,724:27610(0x2b3b2870c700):ZOO_ERROR@handle_socket_err= or_msg@1697: Socket [127.0.0.1:40031] zk retcode=3D-4, errno=3D111(Connecti= on refused): server refused to accept the client > I0825 22:07:46.829910 27632 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:46.829953 27632 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 483478ns > I0825 22:07:47.830860 27636 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:47.830922 27636 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 551674ns > I0825 22:07:48.832027 27628 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:48.832078 27628 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 417868ns > I0825 22:07:49.833906 27629 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:49.833962 27629 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 472647ns > 2015-08-25 22:07:50,060:27610(0x2b3b2870c700):ZOO_ERROR@handle_socket_err= or_msg@1697: Socket [127.0.0.1:40031] zk retcode=3D-4, errno=3D111(Connecti= on refused): server refused to accept the client > I0825 22:07:50.835659 27630 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:50.835718 27630 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 522864ns > I0825 22:07:51.837473 27638 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:51.837537 27638 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 575837ns > I0825 22:07:52.839296 27641 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:52.839350 27641 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 558642ns > 2015-08-25 22:07:53,397:27610(0x2b3b2870c700):ZOO_ERROR@handle_socket_err= or_msg@1697: Socket [127.0.0.1:40031] zk retcode=3D-4, errno=3D111(Connecti= on refused): server refused to accept the client > I0825 22:07:53.840854 27630 hierarchical.hpp:1010] No resources available= to allocate! > I0825 22:07:53.840904 27630 hierarchical.hpp:910] Performed allocation fo= r 1 slaves in 557112ns > I0825 22:07:54.083889 27631 slave.cpp:4226] Querying resource estimator f= or oversubscribable resources > I0825 22:07:54.084323 27629 slave.cpp:4240] Received oversubscribable res= ources from the resource estimator > ../../src/tests/slave_tests.cpp:2651: Failure > Failed to wait 15secs for executorToFrameworkMessage1 > I0825 22:07:54.098143 27629 master.cpp:1051] Framework 20150825-220736-23= 4885548-51219-27610-0000 (default) at scheduler-6c5ddcdb-9dd1-4b38-b051-5f7= 14d3c1c55@172.17.0.14:51219 disconnected > I0825 22:07:54.098212 27629 master.cpp:2370] Disconnecting framework 2015= 0825-220736-234885548-51219-27610-0000 (default) at scheduler-6c5ddcdb-9dd1= -4b38-b051-5f714d3c1c55@172.17.0.14:51219 > I0825 22:07:54.098254 27629 master.cpp:2394] Deactivating framework 20150= 825-220736-234885548-51219-27610-0000 (default) at scheduler-6c5ddcdb-9dd1-= 4b38-b051-5f714d3c1c55@172.17.0.14:51219 > I0825 22:07:54.098363 27629 master.cpp:1075] Giving framework 20150825-22= 0736-234885548-51219-27610-0000 (default) at scheduler-6c5ddcdb-9dd1-4b38-b= 051-5f714d3c1c55@172.17.0.14:51219 0ns to failover > I0825 22:07:54.098448 27631 hierarchical.hpp:474] Deactivated framework 2= 0150825-220736-234885548-51219-27610-0000 > I0825 22:07:54.098830 27641 master.cpp:4469] Framework failover timeout, = removing framework 20150825-220736-234885548-51219-27610-0000 (default) at = scheduler-6c5ddcdb-9dd1-4b38-b051-5f714d3c1c55@172.17.0.14:51219 > I0825 22:07:54.098867 27641 master.cpp:5112] Removing framework 20150825-= 220736-234885548-51219-27610-0000 (default) at scheduler-6c5ddcdb-9dd1-4b38= -b051-5f714d3c1c55@172.17.0.14:51219 > I0825 22:07:54.099156 27629 slave.cpp:1959] Asked to shut down framework = 20150825-220736-234885548-51219-27610-0000 by master@172.17.0.14:51219 > I0825 22:07:54.099211 27629 slave.cpp:1984] Shutting down framework 20150= 825-220736-234885548-51219-27610-0000 > I0825 22:07:54.099198 27641 master.cpp:5576] Updating the latest state of= task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framework 20150825-220736-234= 885548-51219-27610-0000 to TASK_KILLED > I0825 22:07:54.099328 27629 slave.cpp:3710] Shutting down executor 'b89d1= df8-f2fb-44be-8f60-9352cf32a79d' of framework 20150825-220736-234885548-512= 19-27610-0000 > I0825 22:07:54.099913 27641 master.cpp:5644] Removing task b89d1df8-f2fb-= 44be-8f60-9352cf32a79d with resources cpus(*):2; mem(*):1024; disk(*):1024;= ports(*):[31000-32000] of framework 20150825-220736-234885548-51219-27610-= 0000 on slave 20150825-220736-234885548-51219-27610-S0 at slave(287)@172.17= .0.14:51219 (09c6504e3a31) > I0825 22:07:54.099987 27632 hierarchical.hpp:816] Recovered cpus(*):2; me= m(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1= 024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 20150825-2= 20736-234885548-51219-27610-S0 from framework 20150825-220736-234885548-512= 19-27610-0000 > I0825 22:07:54.100440 27641 hierarchical.hpp:428] Removed framework 20150= 825-220736-234885548-51219-27610-0000 > I0825 22:07:54.100608 27643 master.cpp:860] Master terminating > I0825 22:07:54.100778 2360 exec.cpp:380] Executor asked to shutdown > II0825 22:07:54.100929 27641 hierarchical.hpp:573] Removed slave 20150825= -220736-234885548-51219-27610-S0 > 0825 22:07:54.100896 2364 exec.cpp:79] Scheduling shutdown of the execut= or > I0825 22:07:54.100958 2360 exec.cpp:395] Executor::shutdown took 75333ns > Shutting down > Sending SIGTERM to process tree at pid 2371 > I0825 22:07:54.101748 27640 slave.cpp:3143] master@172.17.0.14:51219 exit= ed > W0825 22:07:54.101866 27640 slave.cpp:3146] Master disconnected! Waiting = for a new master to be elected > I0825 22:07:54.106029 27632 containerizer.cpp:1079] Destroying container = '1499299a-93dd-4982-9249-ad0e19d1c06c' > Killing the following process trees: > [=20 > -+- 2371 sh -c sleep 1000=20 > \--- 2372 sleep 1000=20 > ] > I0825 22:07:54.211082 27639 containerizer.cpp:1266] Executor for containe= r '1499299a-93dd-4982-9249-ad0e19d1c06c' has exited > I0825 22:07:54.211087 27630 containerizer.cpp:1266] Executor for containe= r '1499299a-93dd-4982-9249-ad0e19d1c06c' has exited > I0825 22:07:54.211143 27639 containerizer.cpp:1079] Destroying container = '1499299a-93dd-4982-9249-ad0e19d1c06c' > I0825 22:07:54.212609 27637 slave.cpp:3399] Executor 'b89d1df8-f2fb-44be-= 8f60-9352cf32a79d' of framework 20150825-220736-234885548-51219-27610-0000 = terminated with signal Killed > I0825 22:07:54.212685 27637 slave.cpp:3503] Cleaning up executor 'b89d1df= 8-f2fb-44be-8f60-9352cf32a79d' of framework 20150825-220736-234885548-51219= -27610-0000 > I0825 22:07:54.213062 27631 gc.cpp:56] Scheduling '/tmp/SlaveTest_HTTPSch= edulerSlaveRestart_ukkA8L/slaves/20150825-220736-234885548-51219-27610-S0/f= rameworks/20150825-220736-234885548-51219-27610-0000/executors/b89d1df8-f2f= b-44be-8f60-9352cf32a79d/runs/1499299a-93dd-4982-9249-ad0e19d1c06c' for gc = 6.99999753474667days in the future > I0825 22:07:54.214745 27630 gc.cpp:56] Scheduling '/tmp/SlaveTest_HTTPSch= edulerSlaveRestart_ukkA8L/slaves/20150825-220736-234885548-51219-27610-S0/f= rameworks/20150825-220736-234885548-51219-27610-0000/executors/b89d1df8-f2f= b-44be-8f60-9352cf32a79d' for gc 6.99999753268444days in the future > I0825 22:07:54.214859 27630 gc.cpp:56] Scheduling '/tmp/SlaveTest_HTTPSch= edulerSlaveRestart_ukkA8L/meta/slaves/20150825-220736-234885548-51219-27610= -S0/frameworks/20150825-220736-234885548-51219-27610-0000/executors/b89d1df= 8-f2fb-44be-8f60-9352cf32a79d/runs/1499299a-93dd-4982-9249-ad0e19d1c06c' fo= r gc 6.99999751446815days in the future > I0825 22:07:54.214921 27637 slave.cpp:3592] Cleaning up framework 2015082= 5-220736-234885548-51219-27610-0000 > I0825 22:07:54.215047 27630 gc.cpp:56] Scheduling '/tmp/SlaveTest_HTTPSch= edulerSlaveRestart_ukkA8L/meta/slaves/20150825-220736-234885548-51219-27610= -S0/frameworks/20150825-220736-234885548-51219-27610-0000/executors/b89d1df= 8-f2fb-44be-8f60-9352cf32a79d' for gc 6.99999751310222days in the future > I0825 22:07:54.215140 27634 status_update_manager.cpp:284] Closing status= update streams for framework 20150825-220736-234885548-51219-27610-0000 > I0825 22:07:54.215338 27634 status_update_manager.cpp:530] Cleaning up st= atus update stream for task b89d1df8-f2fb-44be-8f60-9352cf32a79d of framewo= rk 20150825-220736-234885548-51219-27610-0000 > I0825 22:07:54.215358 27637 slave.cpp:564] Slave terminating > I0825 22:07:54.215347 27630 gc.cpp:56] Scheduling '/tmp/SlaveTest_HTTPSch= edulerSlaveRestart_ukkA8L/slaves/20150825-220736-234885548-51219-27610-S0/f= rameworks/20150825-220736-234885548-51219-27610-0000' for gc 6.999997510127= 41days in the future > I0825 22:07:54.215608 27630 gc.cpp:56] Scheduling '/tmp/SlaveTest_HTTPSch= edulerSlaveRestart_ukkA8L/meta/slaves/20150825-220736-234885548-51219-27610= -S0/frameworks/20150825-220736-234885548-51219-27610-0000' for gc 6.9999975= 0907259days in the future > ../../3rdparty/libprocess/include/process/gmock.hpp:365: Failure > Actual function call count doesn't match EXPECT_CALL(filter->mock, filter= (testing::A()))... > Expected args: message matcher (8-byte object <58-B2 02-68 3A-2B 00-0= 0>, 1, 1) > Expected: to be called once > Actual: never called - unsatisfied and active > ../../3rdparty/libprocess/include/process/gmock.hpp:365: Failure > Actual function call count doesn't match EXPECT_CALL(filter->mock, filter= (testing::A()))... > Expected args: message matcher (8-byte object <58-B2 02-68 3A-2B 00-0= 0>, 1, 1-byte object ) > Expected: to be called once > Actual: never called - unsatisfied and active > [ FAILED ] SlaveTest.HTTPSchedulerSlaveRestart (17413 ms) > {code} -- This message was sent by Atlassian JIRA (v6.3.4#6332)