Greg Mann created MESOS-4404:
--------------------------------
Summary: SlaveTest.HTTPSchedulerSlaveRestart is flaky
Key: MESOS-4404
URL: https://issues.apache.org/jira/browse/MESOS-4404
Project: Mesos
Issue Type: Bug
Components: HTTP API, slave
Affects Versions: 0.26.0
Environment: From the Jenkins CI: gcc,--verbose --enable-libevent
--enable-ssl,centos:7,docker
Reporter: Greg Mann
Saw this failure on the Jenkins CI:
{code}
[ RUN ] SlaveTest.HTTPSchedulerSlaveRestart
I0115 18:42:25.393354 1762 leveldb.cpp:174] Opened db in 3.456169ms
I0115 18:42:25.394310 1762 leveldb.cpp:181] Compacted db in 922588ns
I0115 18:42:25.394361 1762 leveldb.cpp:196] Created db iterator in 18529ns
I0115 18:42:25.394378 1762 leveldb.cpp:202] Seeked to beginning of db in 1933ns
I0115 18:42:25.394390 1762 leveldb.cpp:271] Iterated through 0 keys in the db
in 280ns
I0115 18:42:25.394430 1762 replica.cpp:779] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0115 18:42:25.394963 1791 recover.cpp:447] Starting replica recovery
I0115 18:42:25.395396 1791 recover.cpp:473] Replica is in EMPTY status
I0115 18:42:25.396589 1795 replica.cpp:673] Replica in EMPTY status received a
broadcasted recover request from (11302)@172.17.0.2:49129
I0115 18:42:25.397101 1785 recover.cpp:193] Received a recover response from a
replica in EMPTY status
I0115 18:42:25.397721 1791 recover.cpp:564] Updating replica status to STARTING
I0115 18:42:25.398764 1789 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 684584ns
I0115 18:42:25.398807 1789 replica.cpp:320] Persisted replica status to
STARTING
I0115 18:42:25.398947 1795 master.cpp:374] Master
544823be-76b5-47be-b326-2cd6d6a700b8 (e648fe109cb1) started on 172.17.0.2:49129
I0115 18:42:25.399209 1788 recover.cpp:473] Replica is in STARTING status
I0115 18:42:25.398980 1795 master.cpp:376] Flags at startup: --acls=""
--allocation_interval="1secs" --allocator="HierarchicalDRF"
--authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/BOGaaq/credentials" --framework_sorter="drf" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000" --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"
--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/BOGaaq/master" --zk_session_timeout="10secs"
I0115 18:42:25.399435 1795 master.cpp:421] Master only allowing authenticated
frameworks to register
I0115 18:42:25.399451 1795 master.cpp:426] Master only allowing authenticated
slaves to register
I0115 18:42:25.399461 1795 credentials.hpp:35] Loading credentials for
authentication from '/tmp/BOGaaq/credentials'
I0115 18:42:25.399884 1795 master.cpp:466] Using default 'crammd5'
authenticator
I0115 18:42:25.400060 1795 master.cpp:535] Using default 'basic' HTTP
authenticator
I0115 18:42:25.400254 1795 master.cpp:569] Authorization enabled
I0115 18:42:25.400439 1785 hierarchical.cpp:147] Initialized hierarchical
allocator process
I0115 18:42:25.400470 1789 whitelist_watcher.cpp:77] No whitelist given
I0115 18:42:25.400656 1792 replica.cpp:673] Replica in STARTING status
received a broadcasted recover request from (11303)@172.17.0.2:49129
I0115 18:42:25.400943 1781 recover.cpp:193] Received a recover response from a
replica in STARTING status
I0115 18:42:25.401612 1791 recover.cpp:564] Updating replica status to VOTING
I0115 18:42:25.402313 1785 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 458849ns
I0115 18:42:25.402345 1785 replica.cpp:320] Persisted replica status to VOTING
I0115 18:42:25.402510 1788 recover.cpp:578] Successfully joined the Paxos group
I0115 18:42:25.402848 1788 recover.cpp:462] Recover process terminated
I0115 18:42:25.402997 1784 master.cpp:1710] The newly elected leader is
[email protected]:49129 with id 544823be-76b5-47be-b326-2cd6d6a700b8
I0115 18:42:25.403038 1784 master.cpp:1723] Elected as the leading master!
I0115 18:42:25.403059 1784 master.cpp:1468] Recovering from registrar
I0115 18:42:25.403267 1791 registrar.cpp:307] Recovering registrar
I0115 18:42:25.404359 1794 log.cpp:659] Attempting to start the writer
I0115 18:42:25.405777 1793 replica.cpp:493] Replica received implicit promise
request from (11305)@172.17.0.2:49129 with proposal 1
I0115 18:42:25.406337 1793 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 447531ns
I0115 18:42:25.406366 1793 replica.cpp:342] Persisted promised to 1
I0115 18:42:25.407235 1782 coordinator.cpp:238] Coordinator attempting to fill
missing positions
I0115 18:42:25.408753 1796 replica.cpp:388] Replica received explicit promise
request from (11306)@172.17.0.2:49129 for position 0 with proposal 2
I0115 18:42:25.409217 1796 leveldb.cpp:341] Persisting action (8 bytes) to
leveldb took 411390ns
I0115 18:42:25.409248 1796 replica.cpp:712] Persisted action at 0
I0115 18:42:25.410698 1787 replica.cpp:537] Replica received write request for
position 0 from (11307)@172.17.0.2:49129
I0115 18:42:25.410768 1787 leveldb.cpp:436] Reading position from leveldb took
30399ns
I0115 18:42:25.411203 1787 leveldb.cpp:341] Persisting action (14 bytes) to
leveldb took 390465ns
I0115 18:42:25.411233 1787 replica.cpp:712] Persisted action at 0
I0115 18:42:25.411984 1796 replica.cpp:691] Replica received learned notice
for position 0 from @0.0.0.0:0
I0115 18:42:25.412431 1796 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 401825ns
I0115 18:42:25.412464 1796 replica.cpp:712] Persisted action at 0
I0115 18:42:25.412494 1796 replica.cpp:697] Replica learned NOP action at
position 0
I0115 18:42:25.413146 1789 log.cpp:675] Writer started with ending position 0
I0115 18:42:25.414281 1781 leveldb.cpp:436] Reading position from leveldb took
34549ns
I0115 18:42:25.415433 1781 registrar.cpp:340] Successfully fetched the
registry (0B) in 12.112128ms
I0115 18:42:25.415557 1781 registrar.cpp:439] Applied 1 operations in 31219ns;
attempting to update the 'registry'
I0115 18:42:25.416365 1793 log.cpp:683] Attempting to append 170 bytes to the
log
I0115 18:42:25.416522 1796 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I0115 18:42:25.417402 1784 replica.cpp:537] Replica received write request for
position 1 from (11308)@172.17.0.2:49129
I0115 18:42:25.417948 1784 leveldb.cpp:341] Persisting action (189 bytes) to
leveldb took 495850ns
I0115 18:42:25.417979 1784 replica.cpp:712] Persisted action at 1
I0115 18:42:25.418685 1790 replica.cpp:691] Replica received learned notice
for position 1 from @0.0.0.0:0
I0115 18:42:25.419095 1790 leveldb.cpp:341] Persisting action (191 bytes) to
leveldb took 368951ns
I0115 18:42:25.419127 1790 replica.cpp:712] Persisted action at 1
I0115 18:42:25.419149 1790 replica.cpp:697] Replica learned APPEND action at
position 1
I0115 18:42:25.420243 1794 registrar.cpp:484] Successfully updated the
'registry' in 4.612096ms
I0115 18:42:25.420392 1794 registrar.cpp:370] Successfully recovered registrar
I0115 18:42:25.420490 1789 log.cpp:702] Attempting to truncate the log to 1
I0115 18:42:25.420765 1796 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I0115 18:42:25.421044 1791 hierarchical.cpp:165] Skipping recovery of
hierarchical allocator: nothing to recover
I0115 18:42:25.420999 1784 master.cpp:1520] Recovered 0 slaves from the
Registry (131B) ; allowing 10mins for slaves to re-register
I0115 18:42:25.421764 1793 replica.cpp:537] Replica received write request for
position 2 from (11309)@172.17.0.2:49129
I0115 18:42:25.422206 1793 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 399483ns
I0115 18:42:25.422238 1793 replica.cpp:712] Persisted action at 2
I0115 18:42:25.422935 1796 replica.cpp:691] Replica received learned notice
for position 2 from @0.0.0.0:0
I0115 18:42:25.423383 1796 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 354472ns
I0115 18:42:25.423449 1796 leveldb.cpp:399] Deleting ~1 keys from leveldb took
33881ns
I0115 18:42:25.423473 1796 replica.cpp:712] Persisted action at 2
I0115 18:42:25.423496 1796 replica.cpp:697] Replica learned TRUNCATE action at
position 2
I0115 18:42:25.432976 1762 containerizer.cpp:140] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W0115 18:42:25.433629 1762 backend.cpp:48] Failed to create 'bind' backend:
BindBackend requires root privileges
I0115 18:42:25.437697 1786 slave.cpp:191] Slave started on
366)@172.17.0.2:49129
I0115 18:42:25.437731 1786 slave.cpp:192] 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/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
--docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
--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/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/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/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj"
I0115 18:42:25.438261 1786 credentials.hpp:83] Loading credential for
authentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/credential'
I0115 18:42:25.438501 1786 slave.cpp:322] Slave using credential for:
test-principal
I0115 18:42:25.438727 1786 resources.cpp:482] Parsing resources as JSON
failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0115 18:42:25.439223 1786 slave.cpp:392] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0115 18:42:25.439311 1786 slave.cpp:400] Slave attributes: [ ]
I0115 18:42:25.439324 1786 slave.cpp:405] Slave hostname: e648fe109cb1
I0115 18:42:25.440315 1785 state.cpp:58] Recovering state from
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta'
I0115 18:42:25.440474 1762 sched.cpp:164] Version: 0.27.0
I0115 18:42:25.440711 1781 status_update_manager.cpp:200] Recovering status
update manager
I0115 18:42:25.441057 1795 containerizer.cpp:386] Recovering containerizer
I0115 18:42:25.441139 1782 sched.cpp:268] New master detected at
[email protected]:49129
I0115 18:42:25.441251 1782 sched.cpp:324] Authenticating with master
[email protected]:49129
I0115 18:42:25.441275 1782 sched.cpp:331] Using default CRAM-MD5 authenticatee
I0115 18:42:25.441511 1781 authenticatee.cpp:121] Creating new client SASL
connection
I0115 18:42:25.441839 1782 master.cpp:5521] Authenticating
[email protected]:49129
I0115 18:42:25.441931 1792 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(792)@172.17.0.2:49129
I0115 18:42:25.442155 1794 authenticator.cpp:98] Creating new server SASL
connection
I0115 18:42:25.442265 1793 provisioner.cpp:245] Provisioner recovery complete
I0115 18:42:25.442360 1795 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0115 18:42:25.442391 1795 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0115 18:42:25.442498 1788 authenticator.cpp:203] Received SASL authentication
start
I0115 18:42:25.442566 1788 authenticator.cpp:325] Authentication requires more
steps
I0115 18:42:25.442631 1783 slave.cpp:4424] Finished recovery
I0115 18:42:25.442664 1782 authenticatee.cpp:258] Received SASL authentication
step
I0115 18:42:25.442797 1782 authenticator.cpp:231] Received SASL authentication
step
I0115 18:42:25.442849 1782 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0115 18:42:25.442870 1782 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0115 18:42:25.442915 1782 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0115 18:42:25.442953 1782 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0115 18:42:25.442971 1782 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0115 18:42:25.442984 1782 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0115 18:42:25.443006 1782 authenticator.cpp:317] Authentication success
I0115 18:42:25.443120 1783 slave.cpp:4596] Querying resource estimator for
oversubscribable resources
I0115 18:42:25.443130 1784 authenticatee.cpp:298] Authentication success
I0115 18:42:25.443178 1796 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(792)@172.17.0.2:49129
I0115 18:42:25.443326 1785 master.cpp:5551] Successfully authenticated
principal 'test-principal' at
[email protected]:49129
I0115 18:42:25.443459 1781 sched.cpp:413] Successfully authenticated with
master [email protected]:49129
I0115 18:42:25.443481 1781 sched.cpp:722] Sending SUBSCRIBE call to
[email protected]:49129
I0115 18:42:25.443490 1789 status_update_manager.cpp:174] Pausing sending
status updates
I0115 18:42:25.443492 1784 slave.cpp:724] New master detected at
[email protected]:49129
I0115 18:42:25.443559 1781 sched.cpp:755] Will retry registration in
959.01868ms if necessary
I0115 18:42:25.443578 1784 slave.cpp:787] Authenticating with master
[email protected]:49129
I0115 18:42:25.443604 1784 slave.cpp:792] Using default CRAM-MD5 authenticatee
I0115 18:42:25.443645 1792 master.cpp:2278] Received SUBSCRIBE call for
framework 'default' at
[email protected]:49129
I0115 18:42:25.443694 1792 master.cpp:1749] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0115 18:42:25.443774 1784 slave.cpp:760] Detecting new master
I0115 18:42:25.443799 1786 authenticatee.cpp:121] Creating new client SASL
connection
I0115 18:42:25.443915 1790 master.cpp:2349] Subscribing framework default with
checkpointing enabled and capabilities [ ]
I0115 18:42:25.444027 1784 slave.cpp:4610] Received oversubscribable resources
from the resource estimator
I0115 18:42:25.444248 1793 hierarchical.cpp:259] Added framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.444324 1781 sched.cpp:649] Framework registered with
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.444350 1793 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:25.444353 1790 master.cpp:5521] Authenticating
slave(366)@172.17.0.2:49129
I0115 18:42:25.444376 1793 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:25.444393 1793 hierarchical.cpp:1075] Performed allocation for 0
slaves in 73885ns
I0115 18:42:25.444413 1781 sched.cpp:663] Scheduler::registered took 57859ns
I0115 18:42:25.444445 1792 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(793)@172.17.0.2:49129
I0115 18:42:25.444701 1793 authenticator.cpp:98] Creating new server SASL
connection
I0115 18:42:25.444942 1782 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0115 18:42:25.444968 1782 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0115 18:42:25.445047 1790 authenticator.cpp:203] Received SASL authentication
start
I0115 18:42:25.445101 1790 authenticator.cpp:325] Authentication requires more
steps
I0115 18:42:25.445176 1790 authenticatee.cpp:258] Received SASL authentication
step
I0115 18:42:25.445315 1793 authenticator.cpp:231] Received SASL authentication
step
I0115 18:42:25.445358 1793 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0115 18:42:25.445372 1793 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0115 18:42:25.445415 1793 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0115 18:42:25.445447 1793 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0115 18:42:25.445471 1793 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0115 18:42:25.445487 1793 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0115 18:42:25.445520 1793 authenticator.cpp:317] Authentication success
I0115 18:42:25.445637 1795 authenticatee.cpp:298] Authentication success
I0115 18:42:25.445724 1792 master.cpp:5551] Successfully authenticated
principal 'test-principal' at slave(366)@172.17.0.2:49129
I0115 18:42:25.445765 1785 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(793)@172.17.0.2:49129
I0115 18:42:25.446068 1787 slave.cpp:855] Successfully authenticated with
master [email protected]:49129
I0115 18:42:25.446259 1787 slave.cpp:1249] Will retry registration in
9.313561ms if necessary
I0115 18:42:25.446457 1785 master.cpp:4235] Registering slave at
slave(366)@172.17.0.2:49129 (e648fe109cb1) with id
544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:25.447036 1794 registrar.cpp:439] Applied 1 operations in 80668ns;
attempting to update the 'registry'
I0115 18:42:25.448024 1781 log.cpp:683] Attempting to append 339 bytes to the
log
I0115 18:42:25.448249 1794 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I0115 18:42:25.449117 1796 replica.cpp:537] Replica received write request for
position 3 from (11323)@172.17.0.2:49129
I0115 18:42:25.449368 1796 leveldb.cpp:341] Persisting action (358 bytes) to
leveldb took 201910ns
I0115 18:42:25.449406 1796 replica.cpp:712] Persisted action at 3
I0115 18:42:25.450243 1787 replica.cpp:691] Replica received learned notice
for position 3 from @0.0.0.0:0
I0115 18:42:25.450808 1787 leveldb.cpp:341] Persisting action (360 bytes) to
leveldb took 521012ns
I0115 18:42:25.450858 1787 replica.cpp:712] Persisted action at 3
I0115 18:42:25.450896 1787 replica.cpp:697] Replica learned APPEND action at
position 3
I0115 18:42:25.452599 1790 registrar.cpp:484] Successfully updated the
'registry' in 5.43488ms
I0115 18:42:25.452968 1786 log.cpp:702] Attempting to truncate the log to 3
I0115 18:42:25.453186 1796 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I0115 18:42:25.453496 1791 slave.cpp:3366] Received ping from
slave-observer(352)@172.17.0.2:49129
I0115 18:42:25.453496 1781 master.cpp:4303] Registered slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0115 18:42:25.453718 1791 slave.cpp:899] Registered with master
[email protected]:49129; given slave ID 544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:25.453744 1791 fetcher.cpp:81] Clearing fetcher cache
I0115 18:42:25.453927 1796 status_update_manager.cpp:181] Resuming sending
status updates
I0115 18:42:25.454176 1791 slave.cpp:922] Checkpointing SlaveInfo to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/slave.info'
I0115 18:42:25.454267 1787 hierarchical.cpp:461] Added slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0115 18:42:25.454401 1790 replica.cpp:537] Replica received write request for
position 4 from (11324)@172.17.0.2:49129
I0115 18:42:25.454630 1791 slave.cpp:958] Forwarding total oversubscribed
resources
I0115 18:42:25.454798 1791 master.cpp:4644] Received update of slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1) with total oversubscribed resources
I0115 18:42:25.454891 1790 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 440402ns
I0115 18:42:25.454924 1790 replica.cpp:712] Persisted action at 4
I0115 18:42:25.455684 1784 replica.cpp:691] Replica received learned notice
for position 4 from @0.0.0.0:0
I0115 18:42:25.456079 1784 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 353684ns
I0115 18:42:25.456157 1784 leveldb.cpp:399] Deleting ~2 keys from leveldb took
46041ns
I0115 18:42:25.456183 1784 replica.cpp:712] Persisted action at 4
I0115 18:42:25.456207 1784 replica.cpp:697] Replica learned TRUNCATE action at
position 4
I0115 18:42:25.457523 1787 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:25.457622 1787 hierarchical.cpp:1097] Performed allocation for
slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 in 3.296955ms
I0115 18:42:25.457895 1789 master.cpp:5350] Sending 1 offers to framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129
I0115 18:42:25.458412 1793 sched.cpp:819] Scheduler::resourceOffers took
137897ns
I0115 18:42:25.459161 1787 hierarchical.cpp:517] Slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0115 18:42:25.459393 1787 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:25.459455 1787 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:25.459499 1787 hierarchical.cpp:1097] Performed allocation for
slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 in 269541ns
I0115 18:42:25.460202 1793 master.cpp:3136] Processing ACCEPT call for offers:
[ 544823be-76b5-47be-b326-2cd6d6a700b8-O0 ] on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1) for framework 544823be-76b5-47be-b326-2cd6d6a700b8-0000
(default) at [email protected]:49129
I0115 18:42:25.460258 1793 master.cpp:2823] Authorizing framework principal
'test-principal' to launch task 81845273-41cb-4086-8d26-b58acd094ec7 as user
'mesos'
I0115 18:42:25.462309 1793 master.hpp:176] Adding task
81845273-41cb-4086-8d26-b58acd094ec7 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1)
I0115 18:42:25.462590 1793 master.cpp:3621] Launching task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.463987 1796 slave.cpp:1289] Got assigned task
81845273-41cb-4086-8d26-b58acd094ec7 for framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.464197 1796 slave.cpp:5130] Checkpointing FrameworkInfo to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/framework.info'
I0115 18:42:25.470656 1796 slave.cpp:5141] Checkpointing framework pid
'@0.0.0.0:0' to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/framework.pid'
I0115 18:42:25.471065 1796 resources.cpp:482] Parsing resources as JSON
failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0115 18:42:25.471667 1796 slave.cpp:1408] Launching task
81845273-41cb-4086-8d26-b58acd094ec7 for framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.471772 1796 resources.cpp:482] Parsing resources as JSON
failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0115 18:42:25.472612 1796 paths.cpp:434] Trying to chown
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
to user 'mesos'
I0115 18:42:25.482182 1796 slave.cpp:5579] Checkpointing ExecutorInfo to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/executor.info'
I0115 18:42:25.483156 1796 slave.cpp:5208] Launching executor
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
I0115 18:42:25.483779 1781 containerizer.cpp:634] Starting container
'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8' for executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
'544823be-76b5-47be-b326-2cd6d6a700b8-0000'
I0115 18:42:25.483911 1796 slave.cpp:5602] Checkpointing TaskInfo to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8/tasks/81845273-41cb-4086-8d26-b58acd094ec7/task.info'
I0115 18:42:25.484482 1796 slave.cpp:1626] Queuing task
'81845273-41cb-4086-8d26-b58acd094ec7' for executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.484664 1796 slave.cpp:677] Successfully attached file
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
I0115 18:42:25.490378 1795 launcher.cpp:132] Forked child with pid '9087' for
container 'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
I0115 18:42:25.490747 1795 containerizer.cpp:980] Checkpointing executor's
forked pid 9087 to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8/pids/forked.pid'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0115 18:42:25.631392 9087 process.cpp:994] libprocess is initialized on
172.17.0.2:51606 for 16 cpus
I0115 18:42:25.632158 9087 logging.cpp:172] Logging to STDERR
I0115 18:42:25.634042 9087 exec.cpp:134] Version: 0.27.0
I0115 18:42:25.642711 9116 exec.cpp:184] Executor started at:
executor(1)@172.17.0.2:51606 with pid 9087
I0115 18:42:25.645352 1788 slave.cpp:2573] Got registration for executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 from executor(1)@172.17.0.2:51606
I0115 18:42:25.646114 1788 slave.cpp:2659] Checkpointing executor pid
'executor(1)@172.17.0.2:51606' to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8/pids/libprocess.pid'
I0115 18:42:25.648432 9114 exec.cpp:208] Executor registered on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:25.648674 1790 slave.cpp:1791] Sending queued task
'81845273-41cb-4086-8d26-b58acd094ec7' to executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 at executor(1)@172.17.0.2:51606
I0115 18:42:25.650701 9114 exec.cpp:220] Executor::registered took 222804ns
Registered executor on e648fe109cb1
I0115 18:42:25.651016 9114 exec.cpp:295] Executor asked to run task
'81845273-41cb-4086-8d26-b58acd094ec7'
I0115 18:42:25.651127 9114 exec.cpp:304] Executor::launchTask took 86066ns
Starting task 81845273-41cb-4086-8d26-b58acd094ec7
Forked command at 9131
sh -c 'sleep 1000'
I0115 18:42:25.652997 9114 exec.cpp:517] Executor sending status update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.654008 1785 slave.cpp:2932] Handling status update TASK_RUNNING
(UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 from executor(1)@172.17.0.2:51606
I0115 18:42:25.654592 1788 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.654656 1788 status_update_manager.cpp:497] Creating
StatusUpdate stream for task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.655225 1788 status_update_manager.cpp:824] Checkpointing UPDATE
for status update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for
task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.657148 1788 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to the slave
I0115 18:42:25.657443 1794 slave.cpp:3284] Forwarding the update TASK_RUNNING
(UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to [email protected]:49129
I0115 18:42:25.657649 1794 slave.cpp:3178] Status update manager successfully
handled status update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9)
for task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.657691 1794 slave.cpp:3194] Sending acknowledgement for status
update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to executor(1)@172.17.0.2:51606
I0115 18:42:25.657877 1781 master.cpp:4789] Status update TASK_RUNNING (UUID:
53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 from slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.657943 1781 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.658174 1781 master.cpp:6445] Updating the state of task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I0115 18:42:25.658334 9124 exec.cpp:341] Executor received status update
acknowledgement 53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.658447 1790 sched.cpp:927] Scheduler::statusUpdate took 153056ns
I0115 18:42:25.658833 1792 master.cpp:3947] Processing ACKNOWLEDGE call
53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129 on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:25.658998 1796 slave.cpp:596] Slave terminating
I0115 18:42:25.659343 1782 master.cpp:1172] Slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1) disconnected
I0115 18:42:25.659446 1782 master.cpp:2633] Disconnecting slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.659584 1782 master.cpp:2652] Deactivating slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.659844 1795 hierarchical.cpp:546] Slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 deactivated
I0115 18:42:25.662204 1762 containerizer.cpp:140] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W0115 18:42:25.662964 1762 backend.cpp:48] Failed to create 'bind' backend:
BindBackend requires root privileges
I0115 18:42:25.667950 1793 slave.cpp:191] Slave started on
367)@172.17.0.2:49129
I0115 18:42:25.667984 1793 slave.cpp:192] 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/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
--docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
--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/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/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/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj"
I0115 18:42:25.668759 1793 credentials.hpp:83] Loading credential for
authentication from '/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/credential'
I0115 18:42:25.669105 1793 slave.cpp:322] Slave using credential for:
test-principal
I0115 18:42:25.669376 1793 resources.cpp:482] Parsing resources as JSON
failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0115 18:42:25.670003 1793 slave.cpp:392] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0115 18:42:25.670074 1793 slave.cpp:400] Slave attributes: [ ]
I0115 18:42:25.670085 1793 slave.cpp:405] Slave hostname: e648fe109cb1
I0115 18:42:25.671247 1795 state.cpp:58] Recovering state from
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta'
I0115 18:42:25.671295 1795 state.cpp:698] No checkpointed resources found at
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/resources/resources.info'
I0115 18:42:25.675850 1785 fetcher.cpp:81] Clearing fetcher cache
I0115 18:42:25.675925 1785 slave.cpp:4512] Recovering framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.676005 1785 slave.cpp:5317] Recovering executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.677289 1795 status_update_manager.cpp:200] Recovering status
update manager
I0115 18:42:25.677331 1795 status_update_manager.cpp:208] Recovering executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.677425 1795 status_update_manager.cpp:497] Creating
StatusUpdate stream for task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.677716 1785 slave.cpp:677] Successfully attached file
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
I0115 18:42:25.678043 1795 status_update_manager.cpp:800] Replaying status
update stream for task 81845273-41cb-4086-8d26-b58acd094ec7
I0115 18:42:25.679199 1781 containerizer.cpp:386] Recovering containerizer
I0115 18:42:25.679307 1781 containerizer.cpp:441] Recovering container
'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8' for executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.682132 1785 provisioner.cpp:245] Provisioner recovery complete
I0115 18:42:25.683300 1783 slave.cpp:4364] Sending reconnect request to
executor '81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 at executor(1)@172.17.0.2:51606
I0115 18:42:25.684046 9128 exec.cpp:254] Received reconnect request from slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:25.684902 1796 slave.cpp:2722] Re-registering executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.685632 9129 exec.cpp:231] Executor re-registered on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:25.687872 9129 exec.cpp:243] Executor::reregistered took 130269ns
Re-registered executor on e648fe109cb1
I0115 18:42:25.690438 1789 slave.cpp:2872] Cleaning up un-reregistered
executors
I0115 18:42:25.690439 1794 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:25.690556 1794 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:25.690580 1789 slave.cpp:4424] Finished recovery
I0115 18:42:25.690608 1794 hierarchical.cpp:1075] Performed allocation for 1
slaves in 247279ns
I0115 18:42:25.691195 1789 slave.cpp:4596] Querying resource estimator for
oversubscribable resources
I0115 18:42:25.691489 1791 status_update_manager.cpp:174] Pausing sending
status updates
I0115 18:42:25.691495 1789 slave.cpp:724] New master detected at
[email protected]:49129
I0115 18:42:25.691562 1789 slave.cpp:787] Authenticating with master
[email protected]:49129
I0115 18:42:25.691596 1789 slave.cpp:792] Using default CRAM-MD5 authenticatee
I0115 18:42:25.691777 1789 slave.cpp:760] Detecting new master
I0115 18:42:25.691809 1792 authenticatee.cpp:121] Creating new client SASL
connection
I0115 18:42:25.691990 1789 slave.cpp:4610] Received oversubscribable resources
from the resource estimator
I0115 18:42:25.692188 1781 master.cpp:5521] Authenticating
slave(367)@172.17.0.2:49129
I0115 18:42:25.692342 1792 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(794)@172.17.0.2:49129
I0115 18:42:25.692651 1793 authenticator.cpp:98] Creating new server SASL
connection
I0115 18:42:25.692940 1787 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0115 18:42:25.693004 1787 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0115 18:42:25.693135 1794 authenticator.cpp:203] Received SASL authentication
start
I0115 18:42:25.693204 1794 authenticator.cpp:325] Authentication requires more
steps
I0115 18:42:25.693315 1787 authenticatee.cpp:258] Received SASL authentication
step
I0115 18:42:25.693478 1783 authenticator.cpp:231] Received SASL authentication
step
I0115 18:42:25.693523 1783 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0115 18:42:25.693545 1783 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0115 18:42:25.693598 1783 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0115 18:42:25.693626 1783 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'e648fe109cb1' server FQDN: 'e648fe109cb1'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0115 18:42:25.693639 1783 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0115 18:42:25.693648 1783 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0115 18:42:25.693666 1783 authenticator.cpp:317] Authentication success
I0115 18:42:25.693774 1787 authenticatee.cpp:298] Authentication success
I0115 18:42:25.693836 1796 master.cpp:5551] Successfully authenticated
principal 'test-principal' at slave(367)@172.17.0.2:49129
I0115 18:42:25.693902 1790 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(794)@172.17.0.2:49129
I0115 18:42:25.694314 1784 slave.cpp:855] Successfully authenticated with
master [email protected]:49129
I0115 18:42:25.694669 1784 slave.cpp:1249] Will retry registration in 15390ns
if necessary
I0115 18:42:25.695060 1794 master.cpp:4395] Re-registering slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(366)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.695238 1791 slave.cpp:1249] Will retry registration in
22.225404ms if necessary
I0115 18:42:25.695515 1794 master.cpp:4582] Sending updated checkpointed
resources to slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at
slave(367)@172.17.0.2:49129 (e648fe109cb1)
I0115 18:42:25.695637 1791 slave.cpp:999] Re-registered with master
[email protected]:49129
I0115 18:42:25.695763 1788 hierarchical.cpp:534] Slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 reactivated
I0115 18:42:25.695778 1784 status_update_manager.cpp:181] Resuming sending
status updates
I0115 18:42:25.695786 1791 slave.cpp:1035] Forwarding total oversubscribed
resources
W0115 18:42:25.695839 1784 status_update_manager.cpp:188] Resending status
update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.695883 1784 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to the slave
I0115 18:42:25.696197 1794 master.cpp:4395] Re-registering slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.696455 1791 slave.cpp:2272] Updated checkpointed resources from
to
I0115 18:42:25.696579 1794 master.cpp:4582] Sending updated checkpointed
resources to slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 at
slave(367)@172.17.0.2:49129 (e648fe109cb1)
I0115 18:42:25.696653 1791 slave.cpp:3284] Forwarding the update TASK_RUNNING
(UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to [email protected]:49129
I0115 18:42:25.696790 1794 master.cpp:4644] Received update of slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
(e648fe109cb1) with total oversubscribed resources
I0115 18:42:25.696996 1791 slave.cpp:2176] Updating framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 pid to @0.0.0.0:0
I0115 18:42:25.697074 1791 slave.cpp:2192] Checkpointing framework pid
'@0.0.0.0:0' to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/framework.pid'
I0115 18:42:25.697226 1794 master.cpp:4789] Status update TASK_RUNNING (UUID:
53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 from slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.697279 1794 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.697571 1794 master.cpp:6445] Updating the state of task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
W0115 18:42:25.697615 1791 slave.cpp:1016] Already re-registered with master
[email protected]:49129
I0115 18:42:25.697641 1791 slave.cpp:1035] Forwarding total oversubscribed
resources
I0115 18:42:25.697654 1787 status_update_manager.cpp:181] Resuming sending
status updates
W0115 18:42:25.697703 1787 status_update_manager.cpp:188] Resending status
update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.697736 1788 sched.cpp:927] Scheduler::statusUpdate took 36082ns
I0115 18:42:25.697758 1787 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to the slave
I0115 18:42:25.697836 1791 slave.cpp:2176] Updating framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 pid to
[email protected]:49129
I0115 18:42:25.697890 1791 slave.cpp:2192] Checkpointing framework pid
'[email protected]:49129' to
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/framework.pid'
I0115 18:42:25.697940 1786 hierarchical.cpp:517] Slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0115 18:42:25.698093 1796 master.cpp:4644] Received update of slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
(e648fe109cb1) with total oversubscribed resources
I0115 18:42:25.698228 1786 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:25.698300 1786 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:25.698341 1786 hierarchical.cpp:1097] Performed allocation for
slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 in 339284ns
I0115 18:42:25.698362 1794 status_update_manager.cpp:181] Resuming sending
status updates
I0115 18:42:25.698397 1796 master.cpp:3947] Processing ACKNOWLEDGE call
53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129 on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0
W0115 18:42:25.698410 1794 status_update_manager.cpp:188] Resending status
update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.698447 1794 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to the slave
I0115 18:42:25.698626 1791 slave.cpp:2272] Updated checkpointed resources from
to
I0115 18:42:25.698807 1791 slave.cpp:3352] Sending message for framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to
[email protected]:49129
I0115 18:42:25.699002 1791 slave.cpp:3284] Forwarding the update TASK_RUNNING
(UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to [email protected]:49129
I0115 18:42:25.699121 1783 sched.cpp:1063] Scheduler::frameworkMessage took
89916ns
I0115 18:42:25.699154 1786 hierarchical.cpp:517] Slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 (e648fe109cb1) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0115 18:42:25.699357 1786 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:25.699419 1786 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:25.699421 1782 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.699398 1784 master.cpp:4789] Status update TASK_RUNNING (UUID:
53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 from slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.699455 1786 hierarchical.cpp:1097] Performed allocation for
slave 544823be-76b5-47be-b326-2cd6d6a700b8-S0 in 230854ns
I0115 18:42:25.699476 1784 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.699515 1791 slave.cpp:3284] Forwarding the update TASK_RUNNING
(UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 to [email protected]:49129
I0115 18:42:25.699589 1782 status_update_manager.cpp:824] Checkpointing ACK
for status update TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for
task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.699712 1784 master.cpp:6445] Updating the state of task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I0115 18:42:25.699880 1783 sched.cpp:927] Scheduler::statusUpdate took 24047ns
I0115 18:42:25.699972 1784 master.cpp:4789] Status update TASK_RUNNING (UUID:
53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 from slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:25.700028 1784 master.cpp:4837] Forwarding status update
TASK_RUNNING (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.700233 1784 master.cpp:6445] Updating the state of task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I0115 18:42:25.700458 1793 sched.cpp:927] Scheduler::statusUpdate took 16402ns
I0115 18:42:25.700492 1784 master.cpp:3947] Processing ACKNOWLEDGE call
53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129 on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:25.700654 1791 slave.cpp:2343] Status update manager successfully
handled status update acknowledgement (UUID:
53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.700763 1784 master.cpp:3947] Processing ACKNOWLEDGE call
53673a10-78b8-4628-9f10-9b55d5a7b6e9 for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129 on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:25.700933 1781 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
E0115 18:42:25.701177 1787 slave.cpp:2336] Failed to handle status update
acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000: Unexpected status update
acknowledgment (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:25.701195 1781 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
E0115 18:42:25.701463 1785 slave.cpp:2336] Failed to handle status update
acknowledgement (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000: Unexpected status update
acknowledgment (UUID: 53673a10-78b8-4628-9f10-9b55d5a7b6e9) for task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
2016-01-15
18:42:25,786:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
I0115 18:42:26.691529 1792 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:26.691583 1792 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:26.691611 1792 hierarchical.cpp:1075] Performed allocation for 1
slaves in 265866ns
I0115 18:42:27.692991 1781 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:27.693042 1781 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:27.693068 1781 hierarchical.cpp:1075] Performed allocation for 1
slaves in 221232ns
I0115 18:42:28.693617 1792 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:28.693681 1792 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:28.693709 1792 hierarchical.cpp:1075] Performed allocation for 1
slaves in 299122ns
2016-01-15
18:42:29,122:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
I0115 18:42:29.694614 1786 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:29.694679 1786 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:29.694710 1786 hierarchical.cpp:1075] Performed allocation for 1
slaves in 325965ns
I0115 18:42:30.695550 1796 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:30.695654 1796 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:30.695700 1796 hierarchical.cpp:1075] Performed allocation for 1
slaves in 501134ns
I0115 18:42:31.696338 1783 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:31.696422 1783 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:31.696457 1783 hierarchical.cpp:1075] Performed allocation for 1
slaves in 420467ns
2016-01-15
18:42:32,459:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
I0115 18:42:32.697325 1784 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:32.697397 1784 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:32.697429 1784 hierarchical.cpp:1075] Performed allocation for 1
slaves in 384033ns
I0115 18:42:33.698457 1788 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:33.698524 1788 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:33.698556 1788 hierarchical.cpp:1075] Performed allocation for 1
slaves in 338490ns
I0115 18:42:34.699501 1794 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:34.699554 1794 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:34.699581 1794 hierarchical.cpp:1075] Performed allocation for 1
slaves in 261802ns
I0115 18:42:35.700134 1785 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:35.700199 1785 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:35.700234 1785 hierarchical.cpp:1075] Performed allocation for 1
slaves in 306905ns
2016-01-15
18:42:35,795:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
I0115 18:42:36.700793 1796 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:36.700873 1796 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:36.700930 1796 hierarchical.cpp:1075] Performed allocation for 1
slaves in 282620ns
I0115 18:42:37.701592 1789 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:37.701655 1789 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:37.701690 1789 hierarchical.cpp:1075] Performed allocation for 1
slaves in 250604ns
I0115 18:42:38.702301 1792 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:38.702378 1792 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:38.702410 1792 hierarchical.cpp:1075] Performed allocation for 1
slaves in 374668ns
2016-01-15
18:42:39,132:1762(0x7f7353fff700):ZOO_ERROR@handle_socket_error_msg@1697:
Socket [127.0.0.1:32919] zk retcode=-4, errno=111(Connection refused): server
refused to accept the client
I0115 18:42:39.703342 1783 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:39.703418 1783 hierarchical.cpp:1419] No inverse offers to send
out!
I0115 18:42:39.703454 1783 hierarchical.cpp:1075] Performed allocation for 1
slaves in 342247ns
I0115 18:42:40.692309 1794 slave.cpp:4596] Querying resource estimator for
oversubscribable resources
I0115 18:42:40.692667 1794 slave.cpp:4610] Received oversubscribable resources
from the resource estimator
../../src/tests/slave_tests.cpp:2996: Failure
Failed to wait 15secs for executorToFrameworkMessage1
I0115 18:42:40.698703 1787 master.cpp:1211] Framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129 disconnected
I0115 18:42:40.698753 1787 master.cpp:2574] Disconnecting framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129
I0115 18:42:40.698802 1787 master.cpp:2598] Deactivating framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129
I0115 18:42:40.699072 1787 master.cpp:1235] Giving framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129 0ns to failover
I0115 18:42:40.699309 1789 hierarchical.cpp:365] Deactivated framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:40.699407 1790 master.cpp:5202] Framework failover timeout,
removing framework 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129
I0115 18:42:40.699455 1790 master.cpp:5933] Removing framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
[email protected]:49129
I0115 18:42:40.699699 1786 slave.cpp:2007] Asked to shut down framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 by [email protected]:49129
I0115 18:42:40.699720 1790 master.cpp:6445] Updating the state of task
81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
I0115 18:42:40.699760 1786 slave.cpp:2032] Shutting down framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:40.699887 1786 slave.cpp:4057] Shutting down executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 at executor(1)@172.17.0.2:51606
I0115 18:42:40.700575 1781 hierarchical.cpp:876] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 from framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:40.700724 1790 master.cpp:6511] Removing task
81845273-41cb-4086-8d26-b58acd094ec7 with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 on slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0 at slave(367)@172.17.0.2:49129
(e648fe109cb1)
I0115 18:42:40.701076 9121 exec.cpp:381] Executor asked to shutdown
I0115 18:42:40.701274 9123 exec.cpp:80] Scheduling shutdown of the executor
I0115 18:42:40.701431 9121 exec.cpp:396] Executor::shutdown took 164650ns
Shutting down
Sending SIGTERM to process tree at pid 9131
I0115 18:42:40.703037 1790 master.cpp:1025] Master terminating
I0115 18:42:40.703275 1788 hierarchical.cpp:320] Removed framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:40.703676 1787 slave.cpp:3412] [email protected]:49129 exited
W0115 18:42:40.703718 1787 slave.cpp:3415] Master disconnected! Waiting for a
new master to be elected
I0115 18:42:40.703891 1788 hierarchical.cpp:492] Removed slave
544823be-76b5-47be-b326-2cd6d6a700b8-S0
I0115 18:42:40.704502 1796 hierarchical.cpp:1325] No resources available to
allocate!
I0115 18:42:40.704558 1796 hierarchical.cpp:1075] Performed allocation for 0
slaves in 128159ns
Killing the following process trees:
[
--- 9131 sleep 1000
]
I0115 18:42:40.708323 1791 containerizer.cpp:1204] Destroying container
'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
I0115 18:42:40.717231 1794 slave.cpp:3412] executor(1)@172.17.0.2:51606 exited
I0115 18:42:40.776173 1788 containerizer.cpp:1420] Executor for container
'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8' has exited
I0115 18:42:40.776197 1783 containerizer.cpp:1420] Executor for container
'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8' has exited
I0115 18:42:40.776271 1788 containerizer.cpp:1204] Destroying container
'dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
I0115 18:42:40.777791 1785 provisioner.cpp:306] Ignoring destroy request for
unknown container dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8
I0115 18:42:40.778194 1790 slave.cpp:3745] Executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 terminated with signal Killed
I0115 18:42:40.778254 1790 slave.cpp:3849] Cleaning up executor
'81845273-41cb-4086-8d26-b58acd094ec7' of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 at executor(1)@172.17.0.2:51606
I0115 18:42:40.778851 1787 gc.cpp:54] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
for gc 6.99999098854222days in the future
I0115 18:42:40.779085 1787 gc.cpp:54] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7'
for gc 6.99999098597333days in the future
I0115 18:42:40.779307 1790 slave.cpp:3937] Cleaning up framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:40.779306 1787 gc.cpp:54] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7/runs/dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8'
for gc 6.99999098406222days in the future
I0115 18:42:40.779448 1794 status_update_manager.cpp:282] Closing status
update streams for framework 544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:40.779481 1787 gc.cpp:54] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000/executors/81845273-41cb-4086-8d26-b58acd094ec7'
for gc 6.99999098131852days in the future
I0115 18:42:40.779713 1794 status_update_manager.cpp:528] Cleaning up status
update stream for task 81845273-41cb-4086-8d26-b58acd094ec7 of framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000
I0115 18:42:40.779798 1787 gc.cpp:54] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000'
for gc 6.99999097825185days in the future
I0115 18:42:40.779907 1783 slave.cpp:596] Slave terminating
I0115 18:42:40.779973 1787 gc.cpp:54] Scheduling
'/tmp/SlaveTest_HTTPSchedulerSlaveRestart_RUYZPj/meta/slaves/544823be-76b5-47be-b326-2cd6d6a700b8-S0/frameworks/544823be-76b5-47be-b326-2cd6d6a700b8-0000'
for gc 6.99999097689778days in the future
I0115 18:42:40.781146 1791 provisioner.cpp:306] Ignoring destroy request for
unknown container dd1a7cdb-c2b4-4670-a63a-c2b125f4a6a8
../../3rdparty/libprocess/include/process/gmock.hpp:363: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock,
filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <58-EC 02-44 74-7F 00-00>, 1,
1)
Expected: to be called once
Actual: never called - unsatisfied and active
../../3rdparty/libprocess/include/process/gmock.hpp:363: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock,
filter(testing::A<const MessageEvent&>()))...
Expected args: message matcher (8-byte object <58-EC 02-44 74-7F 00-00>, 1,
1-byte object <D8>)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] SlaveTest.HTTPSchedulerSlaveRestart (15394 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
