[
https://issues.apache.org/jira/browse/MESOS-4404?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jian Qiu reassigned MESOS-4404:
-------------------------------
Assignee: Jian Qiu
> 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
> Assignee: Jian Qiu
> 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
> master@172.17.0.2: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
> master@172.17.0.2:49129
> I0115 18:42:25.441251 1782 sched.cpp:324] Authenticating with master
> master@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2:49129
> I0115 18:42:25.443459 1781 sched.cpp:413] Successfully authenticated with
> master master@172.17.0.2:49129
> I0115 18:42:25.443481 1781 sched.cpp:722] Sending SUBSCRIBE call to
> master@172.17.0.2: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
> master@172.17.0.2: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
> master@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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 master@172.17.0.2: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
> master@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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 scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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 master@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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
> master@172.17.0.2:49129
> I0115 18:42:25.691562 1789 slave.cpp:787] Authenticating with master
> master@172.17.0.2: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 master@172.17.0.2: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
> master@172.17.0.2: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 master@172.17.0.2: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
> master@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2:49129
> I0115 18:42:25.697890 1791 slave.cpp:2192] Checkpointing framework pid
> 'scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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 master@172.17.0.2: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 master@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2:49129 disconnected
> I0115 18:42:40.698753 1787 master.cpp:2574] Disconnecting framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2:49129
> I0115 18:42:40.698802 1787 master.cpp:2598] Deactivating framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2:49129
> I0115 18:42:40.699072 1787 master.cpp:1235] Giving framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2: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
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2:49129
> I0115 18:42:40.699455 1790 master.cpp:5933] Removing framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 (default) at
> scheduler-5d55118d-2bca-4afb-b6f9-8b60fa1a5274@172.17.0.2:49129
> I0115 18:42:40.699699 1786 slave.cpp:2007] Asked to shut down framework
> 544823be-76b5-47be-b326-2cd6d6a700b8-0000 by master@172.17.0.2: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] master@172.17.0.2: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)
