[ https://issues.apache.org/jira/browse/MESOS-4404?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15103209#comment-15103209 ]
Jian Qiu commented on MESOS-4404: --------------------------------- Sure, I will take a look at this. > 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)