[
https://issues.apache.org/jira/browse/MESOS-4404?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15103819#comment-15103819
]
Jian Qiu commented on MESOS-4404:
---------------------------------
After looking into the log, I think the problem is that the slave receives two
FrameworkUpdateMessage maybe because of re-registration timeout due to
advance(), the test wait for the first one and overwrite the framework pid,
however the pid is overwritten again when receiving the second
FrameworkUpdateMessage. And it causes the test failure.
{code}
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.697836 1791 slave.cpp:2176] Updating framework
544823be-76b5-47be-b326-2cd6d6a700b8-0000 pid to
[email protected]:49129
{code}
It should be resolved if putting Clock::resume() after the whole test. However,
I was unable to reproduce the bug on OSX, so will try centos to reproduce it.
> 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
> Labels: flaky-test, mesosphere
>
> 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)
