mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Greg Mann (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (MESOS-4404) SlaveTest.HTTPSchedulerSlaveRestart is flaky
Date Fri, 15 Jan 2016 19:49:39 GMT

    [ https://issues.apache.org/jira/browse/MESOS-4404?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15102370#comment-15102370 ] 

Greg Mann commented on MESOS-4404:
----------------------------------

May be related to this patch: https://reviews.apache.org/r/41675/

> 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 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)

Mime
View raw message