[ https://issues.apache.org/jira/browse/MESOS-4002?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15025269#comment-15025269 ]
Anand Mazumdar commented on MESOS-4002: --------------------------------------- Partial Fix: https://reviews.apache.org/r/40667/ Still does not answer why the test kept looping for 300 minutes. There might be some future that was never ready and we invoked a .get() blocking forever or a deadlock somewhere else. Would keep digging for the root cause and for future failures on the ASF CI leading to more clues. > ReservationEndpointsTest.UnreserveAvailableAndOfferedResources is flaky > ----------------------------------------------------------------------- > > Key: MESOS-4002 > URL: https://issues.apache.org/jira/browse/MESOS-4002 > Project: Mesos > Issue Type: Bug > Reporter: Anand Mazumdar > Assignee: Anand Mazumdar > Labels: flaky-test, mesosphere, reservations > > Showed up on ASF CI: ( test kept looping on and on and ultimately failing the > build after 300 minutes ) > https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu%3A14.04,label_exp=docker%7C%7CHadoop/1269/changes > {code} > [ RUN ] ReservationEndpointsTest.UnreserveAvailableAndOfferedResources > I1124 01:07:20.050729 30260 leveldb.cpp:174] Opened db in 107.434842ms > I1124 01:07:20.099630 30260 leveldb.cpp:181] Compacted db in 48.82312ms > I1124 01:07:20.099722 30260 leveldb.cpp:196] Created db iterator in 29905ns > I1124 01:07:20.099738 30260 leveldb.cpp:202] Seeked to beginning of db in > 3145ns > I1124 01:07:20.099750 30260 leveldb.cpp:271] Iterated through 0 keys in the > db in 279ns > I1124 01:07:20.099804 30260 replica.cpp:778] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I1124 01:07:20.100637 30292 recover.cpp:447] Starting replica recovery > I1124 01:07:20.100934 30292 recover.cpp:473] Replica is in EMPTY status > I1124 01:07:20.103240 30288 replica.cpp:674] Replica in EMPTY status received > a broadcasted recover request from (6305)@172.17.18.107:37993 > I1124 01:07:20.103672 30292 recover.cpp:193] Received a recover response from > a replica in EMPTY status > I1124 01:07:20.104142 30292 recover.cpp:564] Updating replica status to > STARTING > I1124 01:07:20.114534 30284 master.cpp:365] Master > ad27bc60-16d1-4239-9a65-235a991f9600 (9f2f81738d5e) started on > 172.17.18.107:37993 > I1124 01:07:20.114558 30284 master.cpp:367] Flags at startup: --acls="" > --allocation_interval="1000secs" --allocator="HierarchicalDRF" > --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" > --authorizers="local" --credentials="/tmp/I60I5f/credentials" > --framework_sorter="drf" --help="false" --hostname_lookup="true" > --initialize_driver_logging="true" --log_auto_initialize="true" > --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" > --quiet="false" --recovery_slave_removal_limit="100%" > --registry="replicated_log" --registry_fetch_timeout="1mins" > --registry_store_timeout="25secs" --registry_strict="true" --roles="role" > --root_submissions="true" --slave_ping_timeout="15secs" > --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" > --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" > --work_dir="/tmp/I60I5f/master" --zk_session_timeout="10secs" > I1124 01:07:20.114809 30284 master.cpp:412] Master only allowing > authenticated frameworks to register > I1124 01:07:20.114820 30284 master.cpp:417] Master only allowing > authenticated slaves to register > I1124 01:07:20.114825 30284 credentials.hpp:35] Loading credentials for > authentication from '/tmp/I60I5f/credentials' > I1124 01:07:20.115067 30284 master.cpp:456] Using default 'crammd5' > authenticator > I1124 01:07:20.115320 30284 master.cpp:493] Authorization enabled > I1124 01:07:20.115792 30285 hierarchical.cpp:162] Initialized hierarchical > allocator process > I1124 01:07:20.115855 30285 whitelist_watcher.cpp:77] No whitelist given > I1124 01:07:20.118755 30285 master.cpp:1625] The newly elected leader is > master@172.17.18.107:37993 with id ad27bc60-16d1-4239-9a65-235a991f9600 > I1124 01:07:20.118788 30285 master.cpp:1638] Elected as the leading master! > I1124 01:07:20.118809 30285 master.cpp:1383] Recovering from registrar > I1124 01:07:20.119078 30285 registrar.cpp:307] Recovering registrar > I1124 01:07:20.143256 30292 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 38.787419ms > I1124 01:07:20.143347 30292 replica.cpp:321] Persisted replica status to > STARTING > I1124 01:07:20.143717 30292 recover.cpp:473] Replica is in STARTING status > I1124 01:07:20.145454 30286 replica.cpp:674] Replica in STARTING status > received a broadcasted recover request from (6307)@172.17.18.107:37993 > I1124 01:07:20.145979 30292 recover.cpp:193] Received a recover response from > a replica in STARTING status > I1124 01:07:20.146654 30292 recover.cpp:564] Updating replica status to VOTING > I1124 01:07:20.182672 30286 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 35.422256ms > I1124 01:07:20.182747 30286 replica.cpp:321] Persisted replica status to > VOTING > I1124 01:07:20.182929 30286 recover.cpp:578] Successfully joined the Paxos > group > I1124 01:07:20.183115 30286 recover.cpp:462] Recover process terminated > I1124 01:07:20.183831 30286 log.cpp:659] Attempting to start the writer > I1124 01:07:20.185907 30285 replica.cpp:494] Replica received implicit > promise request from (6308)@172.17.18.107:37993 with proposal 1 > I1124 01:07:20.225256 30285 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 39.291288ms > I1124 01:07:20.225344 30285 replica.cpp:343] Persisted promised to 1 > I1124 01:07:20.226850 30286 coordinator.cpp:238] Coordinator attempting to > fill missing positions > I1124 01:07:20.228394 30293 replica.cpp:389] Replica received explicit > promise request from (6309)@172.17.18.107:37993 for position 0 with proposal 2 > I1124 01:07:20.266371 30293 leveldb.cpp:341] Persisting action (8 bytes) to > leveldb took 37.874181ms > I1124 01:07:20.266456 30293 replica.cpp:713] Persisted action at 0 > I1124 01:07:20.267927 30293 replica.cpp:538] Replica received write request > for position 0 from (6310)@172.17.18.107:37993 > I1124 01:07:20.268002 30293 leveldb.cpp:436] Reading position from leveldb > took 37139ns > I1124 01:07:20.308117 30293 leveldb.cpp:341] Persisting action (14 bytes) to > leveldb took 39.961976ms > I1124 01:07:20.308205 30293 replica.cpp:713] Persisted action at 0 > I1124 01:07:20.309033 30290 replica.cpp:692] Replica received learned notice > for position 0 from @0.0.0.0:0 > I1124 01:07:20.343257 30290 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 34.175337ms > I1124 01:07:20.343343 30290 replica.cpp:713] Persisted action at 0 > I1124 01:07:20.343377 30290 replica.cpp:698] Replica learned NOP action at > position 0 > I1124 01:07:20.344446 30282 log.cpp:675] Writer started with ending position 0 > I1124 01:07:20.346143 30291 leveldb.cpp:436] Reading position from leveldb > took 56896ns > I1124 01:07:20.347618 30291 registrar.cpp:340] Successfully fetched the > registry (0B) in 228.495104ms > I1124 01:07:20.347862 30291 registrar.cpp:439] Applied 1 operations in > 41164ns; attempting to update the 'registry' > I1124 01:07:20.348794 30279 log.cpp:683] Attempting to append 178 bytes to > the log > I1124 01:07:20.349081 30279 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 1 > I1124 01:07:20.350244 30294 replica.cpp:538] Replica received write request > for position 1 from (6311)@172.17.18.107:37993 > I1124 01:07:20.385246 30294 leveldb.cpp:341] Persisting action (197 bytes) to > leveldb took 34.872508ms > I1124 01:07:20.385323 30294 replica.cpp:713] Persisted action at 1 > I1124 01:07:20.386814 30294 replica.cpp:692] Replica received learned notice > for position 1 from @0.0.0.0:0 > I1124 01:07:20.425163 30294 leveldb.cpp:341] Persisting action (199 bytes) to > leveldb took 38.282493ms > I1124 01:07:20.425262 30294 replica.cpp:713] Persisted action at 1 > I1124 01:07:20.425298 30294 replica.cpp:698] Replica learned APPEND action at > position 1 > I1124 01:07:20.427994 30287 registrar.cpp:484] Successfully updated the > 'registry' in 79.949056ms > I1124 01:07:20.428141 30283 log.cpp:702] Attempting to truncate the log to 1 > I1124 01:07:20.428738 30287 registrar.cpp:370] Successfully recovered > registrar > I1124 01:07:20.429306 30290 master.cpp:1435] Recovered 0 slaves from the > Registry (139B) ; allowing 10mins for slaves to re-register > I1124 01:07:20.429592 30290 hierarchical.cpp:174] Allocator recovery is not > supported yet > I1124 01:07:20.430083 30294 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 2 > I1124 01:07:20.431411 30294 replica.cpp:538] Replica received write request > for position 2 from (6312)@172.17.18.107:37993 > I1124 01:07:20.467258 30294 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 35.661978ms > I1124 01:07:20.467342 30294 replica.cpp:713] Persisted action at 2 > I1124 01:07:20.468842 30290 replica.cpp:692] Replica received learned notice > for position 2 from @0.0.0.0:0 > I1124 01:07:20.502264 30290 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 33.367074ms > I1124 01:07:20.502426 30290 leveldb.cpp:399] Deleting ~1 keys from leveldb > took 80765ns > I1124 01:07:20.502452 30290 replica.cpp:713] Persisted action at 2 > I1124 01:07:20.502488 30290 replica.cpp:698] Replica learned TRUNCATE action > at position 2 > I1124 01:07:20.510509 30260 containerizer.cpp:141] Using isolation: > posix/cpu,posix/mem,filesystem/posix > W1124 01:07:20.511119 30260 backend.cpp:48] Failed to create 'bind' backend: > BindBackend requires root privileges > I1124 01:07:20.516801 30288 slave.cpp:189] Slave started on > 219)@172.17.18.107:37993 > I1124 01:07:20.516839 30288 slave.cpp:190] Flags at startup: > --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" > --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" > --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" > --cgroups_root="mesos" --container_disk_watch_interval="15secs" > --containerizers="mesos" > --credential="/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_CSzecr/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" > --docker_kill_orphans="true" > --docker_local_archives_dir="/tmp/mesos/images/docker" > --docker_puller="local" --docker_puller_timeout="60" > --docker_registry="registry-1.docker.io" --docker_registry_port="443" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_CSzecr/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --image_provisioner_backend="copy" > --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" > --launcher_dir="/mesos/mesos-0.26.0/_build/src" --logbufsecs="0" > --logging_level="INFO" --oversubscribed_resources_interval="15secs" > --perf_duration="10secs" --perf_interval="1mins" > --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" > --recovery_timeout="15mins" --registration_backoff_factor="10ms" > --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" > --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" > --strict="true" --switch_user="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_CSzecr" > I1124 01:07:20.517670 30288 credentials.hpp:83] Loading credential for > authentication from > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_CSzecr/credential' > I1124 01:07:20.517982 30288 slave.cpp:320] Slave using credential for: > test-principal > I1124 01:07:20.518334 30288 resources.cpp:472] Parsing resources as JSON > failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] > Trying semicolon-delimited string format instead > I1124 01:07:20.518815 30260 resources.cpp:472] Parsing resources as JSON > failed: cpus:1;mem:128 > Trying semicolon-delimited string format instead > I1124 01:07:20.518975 30288 slave.cpp:390] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I1124 01:07:20.519104 30288 slave.cpp:398] Slave attributes: [ ] > I1124 01:07:20.519124 30288 slave.cpp:403] Slave hostname: 9f2f81738d5e > I1124 01:07:20.519136 30288 slave.cpp:408] Slave checkpoint: true > I1124 01:07:20.519407 30260 resources.cpp:472] Parsing resources as JSON > failed: mem:384 > Trying semicolon-delimited string format instead > I1124 01:07:20.522702 30288 state.cpp:52] Recovering state from > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_CSzecr/meta' > I1124 01:07:20.523265 30288 status_update_manager.cpp:200] Recovering status > update manager > I1124 01:07:20.523531 30288 containerizer.cpp:383] Recovering containerizer > I1124 01:07:20.524998 30288 slave.cpp:4258] Finished recovery > I1124 01:07:20.525802 30288 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1124 01:07:20.526753 30288 slave.cpp:727] New master detected at > master@172.17.18.107:37993 > I1124 01:07:20.527292 30288 slave.cpp:790] Authenticating with master > master@172.17.18.107:37993 > I1124 01:07:20.528240 30288 slave.cpp:795] Using default CRAM-MD5 > authenticatee > I1124 01:07:20.527003 30286 status_update_manager.cpp:174] Pausing sending > status updates > I1124 01:07:20.528955 30285 authenticatee.cpp:121] Creating new client SASL > connection > I1124 01:07:20.529469 30285 master.cpp:5169] Authenticating > slave(219)@172.17.18.107:37993 > I1124 01:07:20.529729 30283 authenticator.cpp:413] Starting authentication > session for crammd5_authenticatee(515)@172.17.18.107:37993 > I1124 01:07:20.530287 30283 authenticator.cpp:98] Creating new server SASL > connection > I1124 01:07:20.530764 30285 authenticatee.cpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I1124 01:07:20.530903 30285 authenticatee.cpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1124 01:07:20.531096 30285 authenticator.cpp:203] Received SASL > authentication start > I1124 01:07:20.531241 30285 authenticator.cpp:325] Authentication requires > more steps > I1124 01:07:20.531388 30285 authenticatee.cpp:258] Received SASL > authentication step > I1124 01:07:20.531616 30285 authenticator.cpp:231] Received SASL > authentication step > I1124 01:07:20.531668 30285 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: '9f2f81738d5e' server FQDN: '9f2f81738d5e' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1124 01:07:20.531690 30285 auxprop.cpp:179] Looking up auxiliary property > '*userPassword' > I1124 01:07:20.531774 30285 auxprop.cpp:179] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1124 01:07:20.531834 30285 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: '9f2f81738d5e' server FQDN: '9f2f81738d5e' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1124 01:07:20.531855 30285 auxprop.cpp:129] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1124 01:07:20.531867 30285 auxprop.cpp:129] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1124 01:07:20.531903 30285 authenticator.cpp:317] Authentication success > I1124 01:07:20.532016 30283 authenticatee.cpp:298] Authentication success > I1124 01:07:20.532331 30281 master.cpp:5199] Successfully authenticated > principal 'test-principal' at slave(219)@172.17.18.107:37993 > I1124 01:07:20.532652 30291 authenticator.cpp:431] Authentication session > cleanup for crammd5_authenticatee(515)@172.17.18.107:37993 > I1124 01:07:20.533113 30288 slave.cpp:763] Detecting new master > I1124 01:07:20.533628 30288 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1124 01:07:20.546396 30288 slave.cpp:858] Successfully authenticated with > master master@172.17.18.107:37993 > I1124 01:07:20.547111 30287 master.cpp:3878] Registering slave at > slave(219)@172.17.18.107:37993 (9f2f81738d5e) with id > ad27bc60-16d1-4239-9a65-235a991f9600-S0 > I1124 01:07:20.547886 30287 registrar.cpp:439] Applied 1 operations in > 91121ns; attempting to update the 'registry' > I1124 01:07:20.550647 30287 log.cpp:683] Attempting to append 347 bytes to > the log > I1124 01:07:20.550935 30279 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 3 > I1124 01:07:20.551534 30288 slave.cpp:1252] Will retry registration in > 3.399312ms if necessary > I1124 01:07:20.551868 30291 replica.cpp:538] Replica received write request > for position 3 from (6324)@172.17.18.107:37993 > I1124 01:07:20.557605 30281 slave.cpp:1252] Will retry registration in > 16.296866ms if necessary > I1124 01:07:20.557891 30293 master.cpp:3866] Ignoring register slave message > from slave(219)@172.17.18.107:37993 (9f2f81738d5e) as admission is already in > progress > I1124 01:07:20.574681 30279 slave.cpp:1252] Will retry registration in > 73.52632ms if necessary > I1124 01:07:20.575078 30293 master.cpp:3866] Ignoring register slave message > from slave(219)@172.17.18.107:37993 (9f2f81738d5e) as admission is already in > progress > I1124 01:07:20.586236 30291 leveldb.cpp:341] Persisting action (366 bytes) to > leveldb took 34.301173ms > I1124 01:07:20.586287 30291 replica.cpp:713] Persisted action at 3 > I1124 01:07:20.587509 30289 replica.cpp:692] Replica received learned notice > for position 3 from @0.0.0.0:0 > I1124 01:07:20.611263 30289 leveldb.cpp:341] Persisting action (368 bytes) to > leveldb took 23.677211ms > I1124 01:07:20.611352 30289 replica.cpp:713] Persisted action at 3 > I1124 01:07:20.611387 30289 replica.cpp:698] Replica learned APPEND action at > position 3 > I1124 01:07:20.613580 30279 registrar.cpp:484] Successfully updated the > 'registry' in 65.490944ms > I1124 01:07:20.613802 30288 log.cpp:702] Attempting to truncate the log to 3 > I1124 01:07:20.613993 30288 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 4 > I1124 01:07:20.615281 30289 replica.cpp:538] Replica received write request > for position 4 from (6325)@172.17.18.107:37993 > I1124 01:07:20.615883 30279 master.cpp:3946] Registered slave > ad27bc60-16d1-4239-9a65-235a991f9600-S0 at slave(219)@172.17.18.107:37993 > (9f2f81738d5e) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I1124 01:07:20.616261 30282 slave.cpp:902] Registered with master > master@172.17.18.107:37993; given slave ID > ad27bc60-16d1-4239-9a65-235a991f9600-S0 > I1124 01:07:20.616883 30282 fetcher.cpp:79] Clearing fetcher cache > I1124 01:07:20.617261 30280 status_update_manager.cpp:181] Resuming sending > status updates > I1124 01:07:20.617766 30282 slave.cpp:925] Checkpointing SlaveInfo to > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_CSzecr/meta/slaves/ad27bc60-16d1-4239-9a65-235a991f9600-S0/slave.info' > I1124 01:07:20.616550 30284 hierarchical.cpp:380] Added slave > ad27bc60-16d1-4239-9a65-235a991f9600-S0 (9f2f81738d5e) with cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) > I1124 01:07:20.618670 30282 slave.cpp:961] Forwarding total oversubscribed > resources > I1124 01:07:20.618932 30282 slave.cpp:3197] Received ping from > slave-observer(216)@172.17.18.107:37993 > I1124 01:07:20.619288 30285 master.cpp:4288] Received update of slave > ad27bc60-16d1-4239-9a65-235a991f9600-S0 at slave(219)@172.17.18.107:37993 > (9f2f81738d5e) with total oversubscribed resources > I1124 01:07:20.619446 30284 hierarchical.cpp:1066] No resources available to > allocate! > I1124 01:07:20.619526 30284 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 01:07:20.619568 30284 hierarchical.cpp:977] Performed allocation for > slave ad27bc60-16d1-4239-9a65-235a991f9600-S0 in 1.108641ms > I1124 01:07:20.620057 30284 hierarchical.cpp:436] Slave > ad27bc60-16d1-4239-9a65-235a991f9600-S0 (9f2f81738d5e) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: ) > I1124 01:07:20.620393 30284 hierarchical.cpp:1066] No resources available to > allocate! > I1124 01:07:20.620462 30284 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 01:07:20.620507 30284 hierarchical.cpp:977] Performed allocation for > slave ad27bc60-16d1-4239-9a65-235a991f9600-S0 in 395959ns > I1124 01:07:20.624356 30285 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/reserve' > I1124 01:07:20.624418 30285 http.cpp:336] HTTP POST for /master/reserve from > 172.17.18.107:48995 > I1124 01:07:20.626936 30285 master.cpp:6224] Sending checkpointed resources > cpus(role, test-principal):1; mem(role, test-principal):512 to slave > ad27bc60-16d1-4239-9a65-235a991f9600-S0 at slave(219)@172.17.18.107:37993 > (9f2f81738d5e) > I1124 01:07:20.631428 30260 sched.cpp:164] Version: 0.26.0 > I1124 01:07:20.632068 30287 sched.cpp:262] New master detected at > master@172.17.18.107:37993 > I1124 01:07:20.632230 30287 sched.cpp:318] Authenticating with master > master@172.17.18.107:37993 > I1124 01:07:20.632307 30287 sched.cpp:325] Using default CRAM-MD5 > authenticatee > I1124 01:07:20.632693 30287 authenticatee.cpp:121] Creating new client SASL > connection > I1124 01:07:20.633275 30287 master.cpp:5169] Authenticating > scheduler-2c19aed9-7470-4927-949b-fb23f1775ab4@172.17.18.107:37993 > I1124 01:07:20.633519 30287 authenticator.cpp:413] Starting authentication > session for crammd5_authenticatee(516)@172.17.18.107:37993 > I1124 01:07:20.633965 30287 authenticator.cpp:98] Creating new server SASL > connection > I1124 01:07:20.634316 30287 authenticatee.cpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I1124 01:07:20.634456 30287 authenticatee.cpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1124 01:07:20.634605 30287 authenticator.cpp:203] Received SASL > authentication start > I1124 01:07:20.634771 30287 authenticator.cpp:325] Authentication requires > more steps > I1124 01:07:20.634914 30287 authenticatee.cpp:258] Received SASL > authentication step > I1124 01:07:20.635126 30287 authenticator.cpp:231] Received SASL > authentication step > I1124 01:07:20.635270 30287 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: '9f2f81738d5e' server FQDN: '9f2f81738d5e' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1124 01:07:20.635347 30287 auxprop.cpp:179] Looking up auxiliary property > '*userPassword' > I1124 01:07:20.636262 30287 auxprop.cpp:179] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1124 01:07:20.636349 30287 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: '9f2f81738d5e' server FQDN: '9f2f81738d5e' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1124 01:07:20.636415 30287 auxprop.cpp:129] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1124 01:07:20.636466 30287 auxprop.cpp:129] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1124 01:07:20.636541 30287 authenticator.cpp:317] Authentication success > I1124 01:07:20.636754 30287 authenticatee.cpp:298] Authentication success > I1124 01:07:20.636831 30286 master.cpp:5199] Successfully authenticated > principal 'test-principal' at > scheduler-2c19aed9-7470-4927-949b-fb23f1775ab4@172.17.18.107:37993 > I1124 01:07:20.636884 30281 authenticator.cpp:431] Authentication session > cleanup for crammd5_authenticatee(516)@172.17.18.107:37993 > I1124 01:07:20.637516 30286 sched.cpp:407] Successfully authenticated with > master master@172.17.18.107:37993 > I1124 01:07:20.637622 30286 sched.cpp:714] Sending SUBSCRIBE call to > master@172.17.18.107:37993 > I1124 01:07:20.637763 30286 sched.cpp:747] Will retry registration in > 1.659715229secs if necessary > I1124 01:07:20.637928 30280 master.cpp:2195] Received SUBSCRIBE call for > framework 'default' at > scheduler-2c19aed9-7470-4927-949b-fb23f1775ab4@172.17.18.107:37993 > I1124 01:07:20.638162 30280 master.cpp:1664] Authorizing framework principal > 'test-principal' to receive offers for role 'role' > I1124 01:07:20.638510 30280 master.cpp:2266] Subscribing framework default > with checkpointing disabled and capabilities [ ] > I1124 01:07:20.639348 30283 sched.cpp:641] Framework registered with > ad27bc60-16d1-4239-9a65-235a991f9600-0000 > I1124 01:07:20.639452 30283 sched.cpp:655] Scheduler::registered took 18594ns > I1124 01:07:20.639559 30280 hierarchical.cpp:220] Added framework > ad27bc60-16d1-4239-9a65-235a991f9600-0000 > I1124 01:07:20.640575 30280 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 01:07:20.641254 30280 hierarchical.cpp:961] Performed allocation for 1 > slaves in 1.618341ms > I1124 01:07:20.641125 30283 master.cpp:4998] Sending 1 offers to framework > ad27bc60-16d1-4239-9a65-235a991f9600-0000 (default) at > scheduler-2c19aed9-7470-4927-949b-fb23f1775ab4@172.17.18.107:37993 > GMOCK WARNING: > Uninteresting mock function call - returning directly. > Function call: resourceOffers(0x7fffe27c3830, @0x2ae03c9ce9d0 { 144-byte > object <D0-1C B2-33 E0-2A 00-00 00-00 00-00 00-00 00-00 70-CF 00-48 E0-2A > 00-00 10-D0 00-48 E0-2A 00-00 B0-D0 00-48 E0-2A 00-00 50-D1 00-48 E0-2A 00-00 > A0-D1 00-48 E0-2A 00-00 40-00 01-48 E0-2A 00-00 ... 00-00 00-00 00-00 00-00 > 00-00 00-00 00-00 00-00 00-00 00-00 35-61 39-39 00-00 00-00 00-00 00-00 00-00 > 00-00 00-00 00-00 00-00 00-00 63-36 30-2D 00-00 00-00 00-00 00-00 00-00 00-00 > 1F-00 00-00> }) > Stack trace: > I1124 01:07:20.642010 30283 sched.cpp:811] Scheduler::resourceOffers took > 257483ns > I1124 01:07:20.642578 30283 master.cpp:3395] Processing REVIVE call for > framework ad27bc60-16d1-4239-9a65-235a991f9600-0000 (default) at > scheduler-2c19aed9-7470-4927-949b-fb23f1775ab4@172.17.18.107:37993 > I1124 01:07:20.642757 30283 hierarchical.cpp:886] Removed offer filters for > framework ad27bc60-16d1-4239-9a65-235a991f9600-0000 > I1124 01:07:20.644323 30283 hierarchical.cpp:1066] No resources available to > allocate! > I1124 01:07:20.644377 30283 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 01:07:20.644404 30283 hierarchical.cpp:961] Performed allocation for 1 > slaves in 1.616762ms > I1124 01:07:20.644626 30291 slave.cpp:2275] Updated checkpointed resources > from to cpus(role, test-principal):1; mem(role, test-principal):512 > I1124 01:07:20.652545 30289 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 37.216951ms > I1124 01:07:20.652601 30289 replica.cpp:713] Persisted action at 4 > I1124 01:07:20.667095 30279 replica.cpp:692] Replica received learned notice > for position 4 from @0.0.0.0:0 > I1124 01:07:20.695262 30279 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 28.08901ms > I1124 01:07:20.695446 30279 leveldb.cpp:399] Deleting ~2 keys from leveldb > took 96033ns > I1124 01:07:20.695482 30279 replica.cpp:713] Persisted action at 4 > I1124 01:07:20.695523 30279 replica.cpp:698] Replica learned TRUNCATE action > at position 4 > 2015-11-24 > 01:07:21,415:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:24,751:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:28,087:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:31,424:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:34,760:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I1124 01:07:35.534328 30283 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1124 01:07:35.534613 30283 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1124 01:07:35.616957 30293 slave.cpp:3197] Received ping from > slave-observer(216)@172.17.18.107:37993 > 2015-11-24 > 01:07:38,096:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:41,433:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:44,769:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:48,105:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I1124 01:07:50.535526 30284 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1124 01:07:50.535809 30284 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1124 01:07:50.618424 30284 slave.cpp:3197] Received ping from > slave-observer(216)@172.17.18.107:37993 > 2015-11-24 > 01:07:51,441:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:54,778:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:07:58,114:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:01,450:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:04,785:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I1124 01:08:05.536947 30293 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1124 01:08:05.537225 30293 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1124 01:08:05.619575 30293 slave.cpp:3197] Received ping from > slave-observer(216)@172.17.18.107:37993 > 2015-11-24 > 01:08:08,119:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:11,456:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:14,790:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:18,127:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I1124 01:08:20.520412 30280 slave.cpp:4067] Current disk usage 6.86%. Max > allowed age: 5.820034363201435days > I1124 01:08:20.539533 30289 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1124 01:08:20.539852 30289 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1124 01:08:20.620409 30284 slave.cpp:3197] Received ping from > slave-observer(216)@172.17.18.107:37993 > 2015-11-24 > 01:08:21,463:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:24,799:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:28,135:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:31,471:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:34,807:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I1124 01:08:35.540747 30288 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1124 01:08:35.541132 30288 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1124 01:08:35.621484 30287 slave.cpp:3197] Received ping from > slave-observer(216)@172.17.18.107:37993 > 2015-11-24 > 01:08:38,143:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:41,479:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:44,815:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:48,152:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I1124 01:08:50.543668 30280 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1124 01:08:50.544008 30280 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1124 01:08:50.622236 30287 slave.cpp:3197] Received ping from > slave-observer(216)@172.17.18.107:37993 > 2015-11-24 > 01:08:51,488:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:54,824:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > 01:08:58,160:30260(0x2ae0d6471700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:46930] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-11-24 > .... (more lines of similar logs) > {code} > Logs from a good run: > {code} > [ RUN ] ReservationEndpointsTest.UnreserveAvailableAndOfferedResources > I1124 14:31:32.379406 30274 leveldb.cpp:174] Opened db in 3.209566ms > I1124 14:31:32.380513 30274 leveldb.cpp:181] Compacted db in 1.056579ms > I1124 14:31:32.380601 30274 leveldb.cpp:196] Created db iterator in 26511ns > I1124 14:31:32.380617 30274 leveldb.cpp:202] Seeked to beginning of db in > 1855ns > I1124 14:31:32.380625 30274 leveldb.cpp:271] Iterated through 0 keys in the > db in 390ns > I1124 14:31:32.380677 30274 replica.cpp:778] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I1124 14:31:32.381772 30304 recover.cpp:447] Starting replica recovery > I1124 14:31:32.382041 30304 recover.cpp:473] Replica is in EMPTY status > I1124 14:31:32.383296 30303 replica.cpp:674] Replica in EMPTY status received > a broadcasted recover request from (6249)@172.17.6.149:52680 > I1124 14:31:32.383708 30298 recover.cpp:193] Received a recover response from > a replica in EMPTY status > I1124 14:31:32.384263 30305 recover.cpp:564] Updating replica status to > STARTING > I1124 14:31:32.384837 30303 master.cpp:365] Master > 540f518e-1ba4-4f89-8b15-7b99ef53c093 (c264cb162c79) started on > 172.17.6.149:52680 > I1124 14:31:32.384984 30304 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 591432ns > I1124 14:31:32.385017 30304 replica.cpp:321] Persisted replica status to > STARTING > I1124 14:31:32.384865 30303 master.cpp:367] Flags at startup: --acls="" > --allocation_interval="1000secs" --allocator="HierarchicalDRF" > --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" > --authorizers="local" --credentials="/tmp/L5EFJU/credentials" > --framework_sorter="drf" --help="false" --hostname_lookup="true" > --initialize_driver_logging="true" --log_auto_initialize="true" > --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" > --quiet="false" --recovery_slave_removal_limit="100%" > --registry="replicated_log" --registry_fetch_timeout="1mins" > --registry_store_timeout="25secs" --registry_strict="true" --roles="role" > --root_submissions="true" --slave_ping_timeout="15secs" > --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" > --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui" > --work_dir="/tmp/L5EFJU/master" --zk_session_timeout="10secs" > I1124 14:31:32.385262 30303 master.cpp:412] Master only allowing > authenticated frameworks to register > I1124 14:31:32.385279 30303 master.cpp:417] Master only allowing > authenticated slaves to register > I1124 14:31:32.385288 30303 credentials.hpp:35] Loading credentials for > authentication from '/tmp/L5EFJU/credentials' > I1124 14:31:32.385319 30297 recover.cpp:473] Replica is in STARTING status > I1124 14:31:32.385628 30303 master.cpp:456] Using default 'crammd5' > authenticator > I1124 14:31:32.385783 30303 master.cpp:493] Authorization enabled > I1124 14:31:32.386221 30299 whitelist_watcher.cpp:77] No whitelist given > I1124 14:31:32.386329 30302 hierarchical.cpp:162] Initialized hierarchical > allocator process > I1124 14:31:32.386343 30299 replica.cpp:674] Replica in STARTING status > received a broadcasted recover request from (6250)@172.17.6.149:52680 > I1124 14:31:32.386756 30308 recover.cpp:193] Received a recover response from > a replica in STARTING status > I1124 14:31:32.387285 30305 recover.cpp:564] Updating replica status to VOTING > I1124 14:31:32.388052 30293 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 444555ns > I1124 14:31:32.388090 30293 replica.cpp:321] Persisted replica status to > VOTING > I1124 14:31:32.388299 30300 recover.cpp:578] Successfully joined the Paxos > group > I1124 14:31:32.388371 30308 master.cpp:1625] The newly elected leader is > master@172.17.6.149:52680 with id 540f518e-1ba4-4f89-8b15-7b99ef53c093 > I1124 14:31:32.388417 30308 master.cpp:1638] Elected as the leading master! > I1124 14:31:32.388442 30308 master.cpp:1383] Recovering from registrar > I1124 14:31:32.388593 30305 registrar.cpp:307] Recovering registrar > I1124 14:31:32.388627 30300 recover.cpp:462] Recover process terminated > I1124 14:31:32.389482 30294 log.cpp:659] Attempting to start the writer > I1124 14:31:32.390638 30294 replica.cpp:494] Replica received implicit > promise request from (6251)@172.17.6.149:52680 with proposal 1 > I1124 14:31:32.391034 30294 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 365035ns > I1124 14:31:32.391055 30294 replica.cpp:343] Persisted promised to 1 > I1124 14:31:32.391635 30297 coordinator.cpp:238] Coordinator attempting to > fill missing positions > I1124 14:31:32.392724 30305 replica.cpp:389] Replica received explicit > promise request from (6252)@172.17.6.149:52680 for position 0 with proposal 2 > I1124 14:31:32.393254 30305 leveldb.cpp:341] Persisting action (8 bytes) to > leveldb took 490425ns > I1124 14:31:32.393277 30305 replica.cpp:713] Persisted action at 0 > I1124 14:31:32.394223 30305 replica.cpp:538] Replica received write request > for position 0 from (6253)@172.17.6.149:52680 > I1124 14:31:32.394282 30305 leveldb.cpp:436] Reading position from leveldb > took 29241ns > I1124 14:31:32.394809 30305 leveldb.cpp:341] Persisting action (14 bytes) to > leveldb took 477617ns > I1124 14:31:32.394830 30305 replica.cpp:713] Persisted action at 0 > I1124 14:31:32.395393 30307 replica.cpp:692] Replica received learned notice > for position 0 from @0.0.0.0:0 > I1124 14:31:32.395923 30307 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 499295ns > I1124 14:31:32.395946 30307 replica.cpp:713] Persisted action at 0 > I1124 14:31:32.395979 30307 replica.cpp:698] Replica learned NOP action at > position 0 > I1124 14:31:32.396602 30304 log.cpp:675] Writer started with ending position 0 > I1124 14:31:32.397611 30298 leveldb.cpp:436] Reading position from leveldb > took 29312ns > I1124 14:31:32.398551 30297 registrar.cpp:340] Successfully fetched the > registry (0B) in 9.914112ms > I1124 14:31:32.398671 30297 registrar.cpp:439] Applied 1 operations in > 29912ns; attempting to update the 'registry' > I1124 14:31:32.399397 30296 log.cpp:683] Attempting to append 176 bytes to > the log > I1124 14:31:32.399523 30302 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 1 > I1124 14:31:32.400318 30304 replica.cpp:538] Replica received write request > for position 1 from (6254)@172.17.6.149:52680 > I1124 14:31:32.400794 30304 leveldb.cpp:341] Persisting action (195 bytes) to > leveldb took 416219ns > I1124 14:31:32.400825 30304 replica.cpp:713] Persisted action at 1 > I1124 14:31:32.401752 30307 replica.cpp:692] Replica received learned notice > for position 1 from @0.0.0.0:0 > I1124 14:31:32.402163 30307 leveldb.cpp:341] Persisting action (197 bytes) to > leveldb took 367685ns > I1124 14:31:32.402194 30307 replica.cpp:713] Persisted action at 1 > I1124 14:31:32.402217 30307 replica.cpp:698] Replica learned APPEND action at > position 1 > I1124 14:31:32.403475 30301 registrar.cpp:484] Successfully updated the > 'registry' in 4.722944ms > I1124 14:31:32.403673 30301 registrar.cpp:370] Successfully recovered > registrar > I1124 14:31:32.403895 30297 log.cpp:702] Attempting to truncate the log to 1 > I1124 14:31:32.404165 30293 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 2 > I1124 14:31:32.404492 30307 master.cpp:1435] Recovered 0 slaves from the > Registry (137B) ; allowing 10mins for slaves to re-register > I1124 14:31:32.404580 30306 hierarchical.cpp:174] Allocator recovery is not > supported yet > I1124 14:31:32.405313 30307 replica.cpp:538] Replica received write request > for position 2 from (6255)@172.17.6.149:52680 > I1124 14:31:32.405725 30307 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 369717ns > I1124 14:31:32.405756 30307 replica.cpp:713] Persisted action at 2 > I1124 14:31:32.406597 30303 replica.cpp:692] Replica received learned notice > for position 2 from @0.0.0.0:0 > I1124 14:31:32.407234 30303 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 590194ns > I1124 14:31:32.407291 30303 leveldb.cpp:399] Deleting ~1 keys from leveldb > took 31709ns > I1124 14:31:32.407313 30303 replica.cpp:713] Persisted action at 2 > I1124 14:31:32.407346 30303 replica.cpp:698] Replica learned TRUNCATE action > at position 2 > I1124 14:31:32.417404 30274 containerizer.cpp:141] Using isolation: > posix/cpu,posix/mem,filesystem/posix > W1124 14:31:32.417768 30274 backend.cpp:48] Failed to create 'bind' backend: > BindBackend requires root privileges > I1124 14:31:32.420657 30300 slave.cpp:189] Slave started on > 219)@172.17.6.149:52680 > I1124 14:31:32.420680 30300 slave.cpp:190] Flags at startup: > --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" > --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" > --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" > --cgroups_root="mesos" --container_disk_watch_interval="15secs" > --containerizers="mesos" > --credential="/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" > --docker_kill_orphans="true" > --docker_local_archives_dir="/tmp/mesos/images/docker" > --docker_puller="local" --docker_puller_timeout="60" > --docker_registry="registry-1.docker.io" --docker_registry_port="443" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --image_provisioner_backend="copy" > --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" > --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0" > --logging_level="INFO" --oversubscribed_resources_interval="15secs" > --perf_duration="10secs" --perf_interval="1mins" > --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" > --recovery_timeout="15mins" --registration_backoff_factor="10ms" > --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" > --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" > --strict="true" --switch_user="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa" > I1124 14:31:32.421241 30300 credentials.hpp:83] Loading credential for > authentication from > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/credential' > I1124 14:31:32.421465 30300 slave.cpp:320] Slave using credential for: > test-principal > I1124 14:31:32.421685 30300 resources.cpp:472] Parsing resources as JSON > failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] > Trying semicolon-delimited string format instead > I1124 14:31:32.422097 30300 slave.cpp:390] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I1124 14:31:32.422158 30300 slave.cpp:398] Slave attributes: [ ] > I1124 14:31:32.422168 30300 slave.cpp:403] Slave hostname: c264cb162c79 > I1124 14:31:32.422163 30274 resources.cpp:472] Parsing resources as JSON > failed: cpus:1;mem:128 > Trying semicolon-delimited string format instead > I1124 14:31:32.422174 30300 slave.cpp:408] Slave checkpoint: true > I1124 14:31:32.422358 30274 resources.cpp:472] Parsing resources as JSON > failed: mem:384 > Trying semicolon-delimited string format instead > I1124 14:31:32.423035 30299 state.cpp:52] Recovering state from > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/meta' > I1124 14:31:32.423334 30294 status_update_manager.cpp:200] Recovering status > update manager > I1124 14:31:32.423507 30300 containerizer.cpp:383] Recovering containerizer > I1124 14:31:32.424350 30296 slave.cpp:4258] Finished recovery > I1124 14:31:32.424875 30296 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1124 14:31:32.425091 30297 status_update_manager.cpp:174] Pausing sending > status updates > I1124 14:31:32.425112 30296 slave.cpp:727] New master detected at > master@172.17.6.149:52680 > I1124 14:31:32.425194 30296 slave.cpp:790] Authenticating with master > master@172.17.6.149:52680 > I1124 14:31:32.425214 30296 slave.cpp:795] Using default CRAM-MD5 > authenticatee > I1124 14:31:32.425395 30296 slave.cpp:763] Detecting new master > I1124 14:31:32.425431 30305 authenticatee.cpp:121] Creating new client SASL > connection > I1124 14:31:32.425519 30296 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1124 14:31:32.425684 30301 master.cpp:5169] Authenticating > slave(219)@172.17.6.149:52680 > I1124 14:31:32.425815 30293 authenticator.cpp:413] Starting authentication > session for crammd5_authenticatee(513)@172.17.6.149:52680 > I1124 14:31:32.426038 30296 authenticator.cpp:98] Creating new server SASL > connection > I1124 14:31:32.426308 30305 authenticatee.cpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I1124 14:31:32.426344 30305 authenticatee.cpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1124 14:31:32.426435 30305 authenticator.cpp:203] Received SASL > authentication start > I1124 14:31:32.426487 30305 authenticator.cpp:325] Authentication requires > more steps > I1124 14:31:32.426573 30305 authenticatee.cpp:258] Received SASL > authentication step > I1124 14:31:32.426687 30302 authenticator.cpp:231] Received SASL > authentication step > I1124 14:31:32.426719 30302 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: 'c264cb162c79' server FQDN: 'c264cb162c79' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1124 14:31:32.426733 30302 auxprop.cpp:179] Looking up auxiliary property > '*userPassword' > I1124 14:31:32.426770 30302 auxprop.cpp:179] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1124 14:31:32.426789 30302 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: 'c264cb162c79' server FQDN: 'c264cb162c79' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1124 14:31:32.426797 30302 auxprop.cpp:129] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1124 14:31:32.426803 30302 auxprop.cpp:129] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1124 14:31:32.426815 30302 authenticator.cpp:317] Authentication success > I1124 14:31:32.426888 30299 authenticatee.cpp:298] Authentication success > I1124 14:31:32.426975 30307 master.cpp:5199] Successfully authenticated > principal 'test-principal' at slave(219)@172.17.6.149:52680 > I1124 14:31:32.427198 30308 authenticator.cpp:431] Authentication session > cleanup for crammd5_authenticatee(513)@172.17.6.149:52680 > I1124 14:31:32.427345 30299 slave.cpp:858] Successfully authenticated with > master master@172.17.6.149:52680 > I1124 14:31:32.427480 30299 slave.cpp:1252] Will retry registration in > 14.843642ms if necessary > I1124 14:31:32.427793 30298 master.cpp:3878] Registering slave at > slave(219)@172.17.6.149:52680 (c264cb162c79) with id > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 > I1124 14:31:32.428304 30301 registrar.cpp:439] Applied 1 operations in > 66689ns; attempting to update the 'registry' > I1124 14:31:32.429102 30296 log.cpp:683] Attempting to append 345 bytes to > the log > I1124 14:31:32.429255 30301 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 3 > I1124 14:31:32.429944 30305 replica.cpp:538] Replica received write request > for position 3 from (6267)@172.17.6.149:52680 > I1124 14:31:32.430567 30305 leveldb.cpp:341] Persisting action (364 bytes) to > leveldb took 565035ns > I1124 14:31:32.430591 30305 replica.cpp:713] Persisted action at 3 > I1124 14:31:32.431191 30301 replica.cpp:692] Replica received learned notice > for position 3 from @0.0.0.0:0 > I1124 14:31:32.431586 30301 leveldb.cpp:341] Persisting action (366 bytes) to > leveldb took 363559ns > I1124 14:31:32.431609 30301 replica.cpp:713] Persisted action at 3 > I1124 14:31:32.431627 30301 replica.cpp:698] Replica learned APPEND action at > position 3 > 2015-11-24 > 14:31:32,432:30274(0x2b7afc200700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:34475] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I1124 14:31:32.433154 30296 registrar.cpp:484] Successfully updated the > 'registry' in 4.772864ms > I1124 14:31:32.433446 30300 log.cpp:702] Attempting to truncate the log to 3 > I1124 14:31:32.433552 30294 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 4 > I1124 14:31:32.434074 30295 slave.cpp:3197] Received ping from > slave-observer(219)@172.17.6.149:52680 > I1124 14:31:32.434813 30302 hierarchical.cpp:380] Added slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 (c264cb162c79) with cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) > I1124 14:31:32.435241 30302 hierarchical.cpp:1066] No resources available to > allocate! > I1124 14:31:32.435408 30302 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 14:31:32.435560 30302 hierarchical.cpp:977] Performed allocation for > slave 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 in 687663ns > I1124 14:31:32.435897 30304 replica.cpp:538] Replica received write request > for position 4 from (6268)@172.17.6.149:52680 > I1124 14:31:32.435978 30306 master.cpp:3946] Registered slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at slave(219)@172.17.6.149:52680 > (c264cb162c79) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I1124 14:31:32.436049 30294 slave.cpp:902] Registered with master > master@172.17.6.149:52680; given slave ID > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 > I1124 14:31:32.436082 30294 fetcher.cpp:79] Clearing fetcher cache > I1124 14:31:32.436264 30300 status_update_manager.cpp:181] Resuming sending > status updates > I1124 14:31:32.436611 30294 slave.cpp:925] Checkpointing SlaveInfo to > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/meta/slaves/540f518e-1ba4-4f89-8b15-7b99ef53c093-S0/slave.info' > I1124 14:31:32.437463 30294 slave.cpp:961] Forwarding total oversubscribed > resources > I1124 14:31:32.437489 30304 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 1.540024ms > I1124 14:31:32.437528 30304 replica.cpp:713] Persisted action at 4 > I1124 14:31:32.437707 30293 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/reserve' > I1124 14:31:32.437942 30293 http.cpp:336] HTTP POST for /master/reserve from > 172.17.6.149:46929 > I1124 14:31:32.438607 30294 replica.cpp:692] Replica received learned notice > for position 4 from @0.0.0.0:0 > I1124 14:31:32.439095 30294 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 443410ns > I1124 14:31:32.439173 30294 leveldb.cpp:399] Deleting ~2 keys from leveldb > took 47749ns > I1124 14:31:32.439280 30294 replica.cpp:713] Persisted action at 4 > I1124 14:31:32.439323 30294 replica.cpp:698] Replica learned TRUNCATE action > at position 4 > I1124 14:31:32.439617 30293 master.cpp:4288] Received update of slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at slave(219)@172.17.6.149:52680 > (c264cb162c79) with total oversubscribed resources > I1124 14:31:32.440897 30294 master.cpp:6224] Sending checkpointed resources > cpus(role, test-principal):1; mem(role, test-principal):512 to slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at slave(219)@172.17.6.149:52680 > (c264cb162c79) > I1124 14:31:32.441396 30298 hierarchical.cpp:436] Slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 (c264cb162c79) updated with > oversubscribed resources (total: cpus(*):1; mem(*):512; disk(*):1024; > ports(*):[31000-32000]; cpus(role, test-principal):1; mem(role, > test-principal):512, allocated: ) > I1124 14:31:32.441532 30294 slave.cpp:2275] Updated checkpointed resources > from to cpus(role, test-principal):1; mem(role, test-principal):512 > I1124 14:31:32.441783 30298 hierarchical.cpp:1066] No resources available to > allocate! > I1124 14:31:32.441862 30298 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 14:31:32.441889 30298 hierarchical.cpp:977] Performed allocation for > slave 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 in 427498ns > I1124 14:31:32.443641 30274 sched.cpp:164] Version: 0.27.0 > I1124 14:31:32.444103 30303 sched.cpp:1261] Ignoring revive offers message as > master is disconnected > I1124 14:31:32.444250 30304 sched.cpp:262] New master detected at > master@172.17.6.149:52680 > I1124 14:31:32.444331 30304 sched.cpp:318] Authenticating with master > master@172.17.6.149:52680 > I1124 14:31:32.444356 30304 sched.cpp:325] Using default CRAM-MD5 > authenticatee > I1124 14:31:32.444573 30298 authenticatee.cpp:121] Creating new client SASL > connection > I1124 14:31:32.444828 30297 master.cpp:5169] Authenticating > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.444926 30307 authenticator.cpp:413] Starting authentication > session for crammd5_authenticatee(514)@172.17.6.149:52680 > I1124 14:31:32.445137 30302 authenticator.cpp:98] Creating new server SASL > connection > I1124 14:31:32.445329 30304 authenticatee.cpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I1124 14:31:32.445359 30304 authenticatee.cpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1124 14:31:32.445464 30294 authenticator.cpp:203] Received SASL > authentication start > I1124 14:31:32.445531 30294 authenticator.cpp:325] Authentication requires > more steps > I1124 14:31:32.445641 30304 authenticatee.cpp:258] Received SASL > authentication step > I1124 14:31:32.445760 30294 authenticator.cpp:231] Received SASL > authentication step > I1124 14:31:32.445794 30294 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: 'c264cb162c79' server FQDN: 'c264cb162c79' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1124 14:31:32.445811 30294 auxprop.cpp:179] Looking up auxiliary property > '*userPassword' > I1124 14:31:32.445849 30294 auxprop.cpp:179] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1124 14:31:32.445875 30294 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: 'c264cb162c79' server FQDN: 'c264cb162c79' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1124 14:31:32.445885 30294 auxprop.cpp:129] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1124 14:31:32.445890 30294 auxprop.cpp:129] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1124 14:31:32.445904 30294 authenticator.cpp:317] Authentication success > I1124 14:31:32.446023 30303 authenticatee.cpp:298] Authentication success > I1124 14:31:32.446034 30308 master.cpp:5199] Successfully authenticated > principal 'test-principal' at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.446112 30302 authenticator.cpp:431] Authentication session > cleanup for crammd5_authenticatee(514)@172.17.6.149:52680 > I1124 14:31:32.446387 30299 sched.cpp:407] Successfully authenticated with > master master@172.17.6.149:52680 > I1124 14:31:32.446409 30299 sched.cpp:714] Sending SUBSCRIBE call to > master@172.17.6.149:52680 > I1124 14:31:32.446502 30299 sched.cpp:747] Will retry registration in > 22.168105ms if necessary > I1124 14:31:32.446610 30308 master.cpp:2195] Received SUBSCRIBE call for > framework 'default' at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.446663 30308 master.cpp:1664] Authorizing framework principal > 'test-principal' to receive offers for role 'role' > I1124 14:31:32.446889 30293 master.cpp:2266] Subscribing framework default > with checkpointing disabled and capabilities [ ] > I1124 14:31:32.447237 30297 hierarchical.cpp:220] Added framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.447360 30304 sched.cpp:641] Framework registered with > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.447406 30304 sched.cpp:655] Scheduler::registered took 20613ns > I1124 14:31:32.448019 30297 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 14:31:32.448055 30297 hierarchical.cpp:961] Performed allocation for 1 > slaves in 792842ns > I1124 14:31:32.448572 30294 master.cpp:4998] Sending 1 offers to framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.449141 30293 sched.cpp:811] Scheduler::resourceOffers took > 122685ns > I1124 14:31:32.451211 30305 master.cpp:2934] Processing ACCEPT call for > offers: [ 540f518e-1ba4-4f89-8b15-7b99ef53c093-O0 ] on slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at slave(219)@172.17.6.149:52680 > (c264cb162c79) for framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > (default) at scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.451257 30305 master.cpp:2730] Authorizing framework principal > 'test-principal' to launch task 981ca865-a5f9-42c6-8090-eaf909f78186 as user > 'mesos' > I1124 14:31:32.452697 30296 master.hpp:176] Adding task > 981ca865-a5f9-42c6-8090-eaf909f78186 with resources cpus(role, > test-principal):1; mem(role, test-principal):128 on slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 (c264cb162c79) > I1124 14:31:32.452819 30296 master.cpp:3264] Launching task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 with > resources cpus(role, test-principal):1; mem(role, test-principal):128 on > slave 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at > slave(219)@172.17.6.149:52680 (c264cb162c79) > I1124 14:31:32.453191 30305 slave.cpp:1292] Got assigned task > 981ca865-a5f9-42c6-8090-eaf909f78186 for framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.453485 30305 resources.cpp:472] Parsing resources as JSON > failed: cpus:0.1;mem:32 > Trying semicolon-delimited string format instead > I1124 14:31:32.453652 30303 hierarchical.cpp:793] Recovered cpus(*):1; > mem(*):512; disk(*):1024; ports(*):[31000-32000]; mem(role, > test-principal):384 (total: cpus(*):1; mem(*):512; disk(*):1024; > ports(*):[31000-32000]; cpus(role, test-principal):1; mem(role, > test-principal):512, allocated: cpus(role, test-principal):1; mem(role, > test-principal):128) on slave 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 from > framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.453729 30303 hierarchical.cpp:830] Framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 filtered slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 for 5secs > I1124 14:31:32.454195 30305 slave.cpp:1411] Launching task > 981ca865-a5f9-42c6-8090-eaf909f78186 for framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.454306 30305 resources.cpp:472] Parsing resources as JSON > failed: cpus:0.1;mem:32 > Trying semicolon-delimited string format instead > I1124 14:31:32.455086 30305 paths.cpp:434] Trying to chown > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/slaves/540f518e-1ba4-4f89-8b15-7b99ef53c093-S0/frameworks/540f518e-1ba4-4f89-8b15-7b99ef53c093-0000/executors/981ca865-a5f9-42c6-8090-eaf909f78186/runs/8544eb55-baa8-495a-98e7-565ec58da673' > to user 'mesos' > I1124 14:31:32.462555 30305 slave.cpp:5043] Launching executor > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 with resources cpus(*):0.1; > mem(*):32 in work directory > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/slaves/540f518e-1ba4-4f89-8b15-7b99ef53c093-S0/frameworks/540f518e-1ba4-4f89-8b15-7b99ef53c093-0000/executors/981ca865-a5f9-42c6-8090-eaf909f78186/runs/8544eb55-baa8-495a-98e7-565ec58da673' > I1124 14:31:32.463389 30296 containerizer.cpp:617] Starting container > '8544eb55-baa8-495a-98e7-565ec58da673' for executor > '981ca865-a5f9-42c6-8090-eaf909f78186' of framework > '540f518e-1ba4-4f89-8b15-7b99ef53c093-0000' > I1124 14:31:32.463459 30305 slave.cpp:1629] Queuing task > '981ca865-a5f9-42c6-8090-eaf909f78186' for executor > '981ca865-a5f9-42c6-8090-eaf909f78186' of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.463846 30305 slave.cpp:680] Successfully attached file > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/slaves/540f518e-1ba4-4f89-8b15-7b99ef53c093-S0/frameworks/540f518e-1ba4-4f89-8b15-7b99ef53c093-0000/executors/981ca865-a5f9-42c6-8090-eaf909f78186/runs/8544eb55-baa8-495a-98e7-565ec58da673' > I1124 14:31:32.468849 30301 launcher.cpp:132] Forked child with pid '3901' > for container '8544eb55-baa8-495a-98e7-565ec58da673' > WARNING: Logging before InitGoogleLogging() is written to STDERR > I1124 14:31:32.614969 3915 process.cpp:936] libprocess is initialized on > 172.17.6.149:55307 for 16 cpus > I1124 14:31:32.615892 3915 logging.cpp:175] Logging to STDERR > I1124 14:31:32.617889 3915 exec.cpp:134] Version: 0.27.0 > I1124 14:31:32.627719 3936 exec.cpp:184] Executor started at: > executor(1)@172.17.6.149:55307 with pid 3915 > I1124 14:31:32.630262 30298 slave.cpp:2406] Got registration for executor > '981ca865-a5f9-42c6-8090-eaf909f78186' of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 from executor(1)@172.17.6.149:55307 > I1124 14:31:32.632133 30293 slave.cpp:1794] Sending queued task > '981ca865-a5f9-42c6-8090-eaf909f78186' to executor > '981ca865-a5f9-42c6-8090-eaf909f78186' of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 at executor(1)@172.17.6.149:55307 > I1124 14:31:32.632527 3933 exec.cpp:208] Executor registered on slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 > Registered executor on c264cb162c79 > I1124 14:31:32.634414 3933 exec.cpp:220] Executor::registered took 256013ns > I1124 14:31:32.634769 3933 exec.cpp:295] Executor asked to run task > '981ca865-a5f9-42c6-8090-eaf909f78186' > I1124 14:31:32.634874 3933 exec.cpp:304] Executor::launchTask took 75212ns > Starting task 981ca865-a5f9-42c6-8090-eaf909f78186 > Forked command at 3946 > sh -c 'sleep 1000' > I1124 14:31:32.638731 3939 exec.cpp:517] Executor sending status update > TASK_RUNNING (UUID: 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.639981 30298 slave.cpp:2763] Handling status update > TASK_RUNNING (UUID: 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 from executor(1)@172.17.6.149:55307 > I1124 14:31:32.640444 30296 status_update_manager.cpp:320] Received status > update TASK_RUNNING (UUID: 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.640498 30296 status_update_manager.cpp:497] Creating > StatusUpdate stream for task 981ca865-a5f9-42c6-8090-eaf909f78186 of > framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.640938 30296 status_update_manager.cpp:374] Forwarding update > TASK_RUNNING (UUID: 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 to the slave > I1124 14:31:32.641361 30301 slave.cpp:3115] Forwarding the update > TASK_RUNNING (UUID: 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 to master@172.17.6.149:52680 > I1124 14:31:32.641582 30301 slave.cpp:3009] Status update manager > successfully handled status update TASK_RUNNING (UUID: > 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.641636 30301 slave.cpp:3025] Sending acknowledgement for > status update TASK_RUNNING (UUID: 574d2d42-c323-4733-9982-f4398c654776) for > task 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 to executor(1)@172.17.6.149:55307 > I1124 14:31:32.641923 30306 master.cpp:4433] Status update TASK_RUNNING > (UUID: 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 from slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at slave(219)@172.17.6.149:52680 > (c264cb162c79) > I1124 14:31:32.642014 30306 master.cpp:4481] Forwarding status update > TASK_RUNNING (UUID: 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.642205 30306 master.cpp:6085] Updating the state of task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (latest state: TASK_RUNNING, status > update state: TASK_RUNNING) > I1124 14:31:32.642366 30298 sched.cpp:919] Scheduler::statusUpdate took > 38074ns > I1124 14:31:32.642711 30307 master.cpp:3590] Processing ACKNOWLEDGE call > 574d2d42-c323-4733-9982-f4398c654776 for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 on slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 > I1124 14:31:32.642789 3932 exec.cpp:341] Executor received status update > acknowledgement 574d2d42-c323-4733-9982-f4398c654776 for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.643095 30307 status_update_manager.cpp:392] Received status > update acknowledgement (UUID: 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.643564 30304 slave.cpp:2346] Status update manager > successfully handled status update acknowledgement (UUID: > 574d2d42-c323-4733-9982-f4398c654776) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.644278 30308 master.cpp:3395] Processing REVIVE call for > framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.644439 30308 hierarchical.cpp:886] Removed offer filters for > framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.645293 30308 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 14:31:32.645335 30308 hierarchical.cpp:961] Performed allocation for 1 > slaves in 872704ns > I1124 14:31:32.645678 30306 master.cpp:4998] Sending 1 offers to framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.646204 30297 sched.cpp:811] Scheduler::resourceOffers took > 109082ns > I1124 14:31:32.646776 30299 master.cpp:3498] Telling slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at slave(219)@172.17.6.149:52680 > (c264cb162c79) to kill task 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.646927 30294 slave.cpp:1822] Asked to kill task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.647976 3937 exec.cpp:315] Executor asked to kill task > '981ca865-a5f9-42c6-8090-eaf909f78186' > I1124 14:31:32.648072 3937 exec.cpp:324] Executor::killTask took 61578ns > Shutting down > Sending SIGTERM to process tree at pid 3946 > Killing the following process trees: > [ > -+- 3946 sh -c sleep 1000 > \--- 3947 sleep 1000 > ] > Command terminated with signal Terminated (pid: 3946) > I1124 14:31:32.738593 3939 exec.cpp:517] Executor sending status update > TASK_KILLED (UUID: 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.739966 30306 slave.cpp:2763] Handling status update > TASK_KILLED (UUID: 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 from executor(1)@172.17.6.149:55307 > I1124 14:31:32.740249 30306 slave.cpp:5342] Terminating task > 981ca865-a5f9-42c6-8090-eaf909f78186 > I1124 14:31:32.741641 30299 status_update_manager.cpp:320] Received status > update TASK_KILLED (UUID: 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.741881 30299 status_update_manager.cpp:374] Forwarding update > TASK_KILLED (UUID: 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 to the slave > I1124 14:31:32.742216 30297 slave.cpp:3115] Forwarding the update TASK_KILLED > (UUID: 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 to master@172.17.6.149:52680 > I1124 14:31:32.742477 30297 slave.cpp:3009] Status update manager > successfully handled status update TASK_KILLED (UUID: > 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.742528 30297 slave.cpp:3025] Sending acknowledgement for > status update TASK_KILLED (UUID: 26f9ee98-2124-44d0-93f0-4537c828a375) for > task 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 to executor(1)@172.17.6.149:55307 > I1124 14:31:32.742624 30299 master.cpp:4433] Status update TASK_KILLED (UUID: > 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 from slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at slave(219)@172.17.6.149:52680 > (c264cb162c79) > I1124 14:31:32.742676 30299 master.cpp:4481] Forwarding status update > TASK_KILLED (UUID: 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.742945 30299 master.cpp:6085] Updating the state of task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (latest state: TASK_KILLED, status > update state: TASK_KILLED) > I1124 14:31:32.743191 30297 sched.cpp:919] Scheduler::statusUpdate took > 26231ns > I1124 14:31:32.743536 30297 hierarchical.cpp:793] Recovered cpus(role, > test-principal):1; mem(role, test-principal):128 (total: cpus(*):1; > mem(*):512; disk(*):1024; ports(*):[31000-32000]; cpus(role, > test-principal):1; mem(role, test-principal):512, allocated: mem(role, > test-principal):384; cpus(*):1; mem(*):512; disk(*):1024; > ports(*):[31000-32000]) on slave 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 from > framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.743746 30299 master.cpp:3590] Processing ACKNOWLEDGE call > 26f9ee98-2124-44d0-93f0-4537c828a375 for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 on slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 > I1124 14:31:32.743865 30299 master.cpp:6151] Removing task > 981ca865-a5f9-42c6-8090-eaf909f78186 with resources cpus(role, > test-principal):1; mem(role, test-principal):128 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 on slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at slave(219)@172.17.6.149:52680 > (c264cb162c79) > I1124 14:31:32.744144 3932 exec.cpp:341] Executor received status update > acknowledgement 26f9ee98-2124-44d0-93f0-4537c828a375 for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.744676 30299 status_update_manager.cpp:392] Received status > update acknowledgement (UUID: 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.745034 30299 status_update_manager.cpp:528] Cleaning up status > update stream for task 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.745612 30299 slave.cpp:2346] Status update manager > successfully handled status update acknowledgement (UUID: > 26f9ee98-2124-44d0-93f0-4537c828a375) for task > 981ca865-a5f9-42c6-8090-eaf909f78186 of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.745776 30299 slave.cpp:5383] Completing task > 981ca865-a5f9-42c6-8090-eaf909f78186 > I1124 14:31:32.746186 30295 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/unreserve' > I1124 14:31:32.746253 30295 http.cpp:336] HTTP POST for /master/unreserve > from 172.17.6.149:46936 > I1124 14:31:32.747879 30307 hierarchical.cpp:793] Recovered cpus(*):1; > mem(*):512; disk(*):1024; ports(*):[31000-32000]; mem(role, > test-principal):384 (total: cpus(*):1; mem(*):512; disk(*):1024; > ports(*):[31000-32000]; cpus(role, test-principal):1; mem(role, > test-principal):512, allocated: ) on slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 from framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.748006 30307 hierarchical.cpp:830] Framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 filtered slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 for 5secs > I1124 14:31:32.748070 30299 sched.cpp:837] Rescinded offer > 540f518e-1ba4-4f89-8b15-7b99ef53c093-O1 > I1124 14:31:32.748138 30299 sched.cpp:848] Scheduler::offerRescinded took > 21855ns > I1124 14:31:32.749619 30305 master.cpp:6224] Sending checkpointed resources > to slave 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 at > slave(219)@172.17.6.149:52680 (c264cb162c79) > I1124 14:31:32.750159 30305 slave.cpp:2275] Updated checkpointed resources > from cpus(role, test-principal):1; mem(role, test-principal):512 to > I1124 14:31:32.754276 30296 master.cpp:3395] Processing REVIVE call for > framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.754508 30305 hierarchical.cpp:886] Removed offer filters for > framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.755517 30305 hierarchical.cpp:1159] No inverse offers to send > out! > I1124 14:31:32.755565 30305 hierarchical.cpp:961] Performed allocation for 1 > slaves in 1.0104ms > I1124 14:31:32.755949 30298 master.cpp:4998] Sending 1 offers to framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.756631 30298 sched.cpp:811] Scheduler::resourceOffers took > 128650ns > I1124 14:31:32.757311 30274 sched.cpp:1803] Asked to stop the driver > I1124 14:31:32.757488 30303 sched.cpp:1041] Stopping framework > '540f518e-1ba4-4f89-8b15-7b99ef53c093-0000' > I1124 14:31:32.757752 30295 master.cpp:5566] Processing TEARDOWN call for > framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.757786 30295 master.cpp:5578] Removing framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 (default) at > scheduler-0ff32e9c-a0bb-4f1c-a2e6-580485a123be@172.17.6.149:52680 > I1124 14:31:32.758023 30294 hierarchical.cpp:303] Deactivated framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.758117 30296 slave.cpp:2010] Asked to shut down framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 by master@172.17.6.149:52680 > I1124 14:31:32.758167 30296 slave.cpp:2035] Shutting down framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.758249 30296 slave.cpp:3891] Shutting down executor > '981ca865-a5f9-42c6-8090-eaf909f78186' of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 at executor(1)@172.17.6.149:55307 > I1124 14:31:32.758635 30302 hierarchical.cpp:793] Recovered cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 from framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.758935 30302 hierarchical.cpp:260] Removed framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.759083 30304 master.cpp:926] Master terminating > I1124 14:31:32.759553 30303 hierarchical.cpp:410] Removed slave > 540f518e-1ba4-4f89-8b15-7b99ef53c093-S0 > I1124 14:31:32.759668 3938 exec.cpp:381] Executor asked to shutdown > I1124 14:31:32.759775 3938 exec.cpp:396] Executor::shutdown took 14378ns > I1124 14:31:32.759929 3938 exec.cpp:80] Scheduling shutdown of the executor > I1124 14:31:32.760166 30304 slave.cpp:3243] master@172.17.6.149:52680 exited > W1124 14:31:32.760193 30304 slave.cpp:3246] Master disconnected! Waiting for > a new master to be elected > I1124 14:31:32.764683 30297 containerizer.cpp:1073] Destroying container > '8544eb55-baa8-495a-98e7-565ec58da673' > I1124 14:31:32.774528 30299 containerizer.cpp:1256] Executor for container > '8544eb55-baa8-495a-98e7-565ec58da673' has exited > I1124 14:31:32.776396 30296 slave.cpp:3581] Executor > '981ca865-a5f9-42c6-8090-eaf909f78186' of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 terminated with signal Killed > I1124 14:31:32.776568 30296 slave.cpp:3685] Cleaning up executor > '981ca865-a5f9-42c6-8090-eaf909f78186' of framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 at executor(1)@172.17.6.149:55307 > I1124 14:31:32.776974 30298 gc.cpp:54] Scheduling > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/slaves/540f518e-1ba4-4f89-8b15-7b99ef53c093-S0/frameworks/540f518e-1ba4-4f89-8b15-7b99ef53c093-0000/executors/981ca865-a5f9-42c6-8090-eaf909f78186/runs/8544eb55-baa8-495a-98e7-565ec58da673' > for gc 6.99999100884444days in the future > I1124 14:31:32.777122 30296 slave.cpp:3773] Cleaning up framework > 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.777163 30298 gc.cpp:54] Scheduling > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/slaves/540f518e-1ba4-4f89-8b15-7b99ef53c093-S0/frameworks/540f518e-1ba4-4f89-8b15-7b99ef53c093-0000/executors/981ca865-a5f9-42c6-8090-eaf909f78186' > for gc 6.99999100695704days in the future > I1124 14:31:32.777220 30301 status_update_manager.cpp:282] Closing status > update streams for framework 540f518e-1ba4-4f89-8b15-7b99ef53c093-0000 > I1124 14:31:32.777307 30296 slave.cpp:599] Slave terminating > I1124 14:31:32.777298 30298 gc.cpp:54] Scheduling > '/tmp/ReservationEndpointsTest_UnreserveAvailableAndOfferedResources_N4vdsa/slaves/540f518e-1ba4-4f89-8b15-7b99ef53c093-S0/frameworks/540f518e-1ba4-4f89-8b15-7b99ef53c093-0000' > for gc 6.99999100426074days in the future > [ OK ] ReservationEndpointsTest.UnreserveAvailableAndOfferedResources > (409 ms) > {code} -- This message was sent by Atlassian JIRA (v6.3.4#6332)