[ https://issues.apache.org/jira/browse/MESOS-4614?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Anand Mazumdar updated MESOS-4614: ---------------------------------- Shepherd: Vinod Kone Sprint: Mesosphere Sprint 28 Story Points: 3 Patch: https://reviews.apache.org/r/43285/ > SlaveRecoveryTest/0.CleanupHTTPExecutor is flaky > ------------------------------------------------ > > Key: MESOS-4614 > URL: https://issues.apache.org/jira/browse/MESOS-4614 > Project: Mesos > Issue Type: Bug > Components: HTTP API, slave, tests > Affects Versions: 0.27.0 > Environment: CentOS 7, gcc, libevent & SSL enabled > Reporter: Greg Mann > Assignee: Anand Mazumdar > Labels: flaky-test, mesosphere > > Just saw this failure on the ASF CI: > {code} > [ RUN ] SlaveRecoveryTest/0.CleanupHTTPExecutor > I0206 00:22:44.791671 2824 leveldb.cpp:174] Opened db in 2.539372ms > I0206 00:22:44.792459 2824 leveldb.cpp:181] Compacted db in 740473ns > I0206 00:22:44.792510 2824 leveldb.cpp:196] Created db iterator in 24164ns > I0206 00:22:44.792532 2824 leveldb.cpp:202] Seeked to beginning of db in > 1831ns > I0206 00:22:44.792548 2824 leveldb.cpp:271] Iterated through 0 keys in the > db in 342ns > I0206 00:22:44.792605 2824 replica.cpp:779] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0206 00:22:44.793256 2847 recover.cpp:447] Starting replica recovery > I0206 00:22:44.793480 2847 recover.cpp:473] Replica is in EMPTY status > I0206 00:22:44.794538 2847 replica.cpp:673] Replica in EMPTY status received > a broadcasted recover request from (9472)@172.17.0.2:43484 > I0206 00:22:44.795040 2848 recover.cpp:193] Received a recover response from > a replica in EMPTY status > I0206 00:22:44.795644 2848 recover.cpp:564] Updating replica status to > STARTING > I0206 00:22:44.796519 2850 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 752810ns > I0206 00:22:44.796545 2850 replica.cpp:320] Persisted replica status to > STARTING > I0206 00:22:44.796725 2848 recover.cpp:473] Replica is in STARTING status > I0206 00:22:44.797828 2857 replica.cpp:673] Replica in STARTING status > received a broadcasted recover request from (9473)@172.17.0.2:43484 > I0206 00:22:44.798355 2850 recover.cpp:193] Received a recover response from > a replica in STARTING status > I0206 00:22:44.799193 2850 recover.cpp:564] Updating replica status to VOTING > I0206 00:22:44.799583 2855 master.cpp:376] Master > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca (6632562f1ade) started on > 172.17.0.2:43484 > I0206 00:22:44.799609 2855 master.cpp:378] Flags at startup: --acls="" > --allocation_interval="1secs" --allocator="HierarchicalDRF" > --authenticate="true" --authenticate_http="true" --authenticate_slaves="true" > --authenticators="crammd5" --authorizers="local" > --credentials="/tmp/n2FxQV/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="100secs" --registry_strict="true" > --root_submissions="true" --slave_ping_timeout="15secs" > --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" > --webui_dir="/mesos/mesos-0.28.0/_inst/share/mesos/webui" > --work_dir="/tmp/n2FxQV/master" --zk_session_timeout="10secs" > I0206 00:22:44.799991 2855 master.cpp:423] Master only allowing > authenticated frameworks to register > I0206 00:22:44.800009 2855 master.cpp:428] Master only allowing > authenticated slaves to register > I0206 00:22:44.800020 2855 credentials.hpp:35] Loading credentials for > authentication from '/tmp/n2FxQV/credentials' > I0206 00:22:44.800245 2850 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 679345ns > I0206 00:22:44.800370 2850 replica.cpp:320] Persisted replica status to > VOTING > I0206 00:22:44.800397 2855 master.cpp:468] Using default 'crammd5' > authenticator > I0206 00:22:44.800693 2855 master.cpp:537] Using default 'basic' HTTP > authenticator > I0206 00:22:44.800815 2855 master.cpp:571] Authorization enabled > I0206 00:22:44.801216 2850 recover.cpp:578] Successfully joined the Paxos > group > I0206 00:22:44.801604 2850 recover.cpp:462] Recover process terminated > I0206 00:22:44.801759 2856 whitelist_watcher.cpp:77] No whitelist given > I0206 00:22:44.801725 2847 hierarchical.cpp:144] Initialized hierarchical > allocator process > I0206 00:22:44.803982 2855 master.cpp:1712] The newly elected leader is > master@172.17.0.2:43484 with id 0b206a40-a9c3-4d44-a5bd-8032d60a32ca > I0206 00:22:44.804026 2855 master.cpp:1725] Elected as the leading master! > I0206 00:22:44.804059 2855 master.cpp:1470] Recovering from registrar > I0206 00:22:44.804424 2855 registrar.cpp:307] Recovering registrar > I0206 00:22:44.805202 2855 log.cpp:659] Attempting to start the writer > I0206 00:22:44.806782 2856 replica.cpp:493] Replica received implicit > promise request from (9475)@172.17.0.2:43484 with proposal 1 > I0206 00:22:44.807368 2856 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 547939ns > I0206 00:22:44.807395 2856 replica.cpp:342] Persisted promised to 1 > I0206 00:22:44.808375 2856 coordinator.cpp:238] Coordinator attempting to > fill missing positions > I0206 00:22:44.809460 2848 replica.cpp:388] Replica received explicit > promise request from (9476)@172.17.0.2:43484 for position 0 with proposal 2 > I0206 00:22:44.809929 2848 leveldb.cpp:341] Persisting action (8 bytes) to > leveldb took 427561ns > I0206 00:22:44.809967 2848 replica.cpp:712] Persisted action at 0 > I0206 00:22:44.811035 2850 replica.cpp:537] Replica received write request > for position 0 from (9477)@172.17.0.2:43484 > I0206 00:22:44.811149 2850 leveldb.cpp:436] Reading position from leveldb > took 36452ns > I0206 00:22:44.811532 2850 leveldb.cpp:341] Persisting action (14 bytes) to > leveldb took 318924ns > I0206 00:22:44.811615 2850 replica.cpp:712] Persisted action at 0 > I0206 00:22:44.812532 2850 replica.cpp:691] Replica received learned notice > for position 0 from @0.0.0.0:0 > I0206 00:22:44.813117 2850 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 476530ns > I0206 00:22:44.813143 2850 replica.cpp:712] Persisted action at 0 > I0206 00:22:44.813166 2850 replica.cpp:697] Replica learned NOP action at > position 0 > I0206 00:22:44.813984 2848 log.cpp:675] Writer started with ending position 0 > I0206 00:22:44.815549 2848 leveldb.cpp:436] Reading position from leveldb > took 31800ns > I0206 00:22:44.817061 2848 registrar.cpp:340] Successfully fetched the > registry (0B) in 12.591104ms > I0206 00:22:44.817319 2848 registrar.cpp:439] Applied 1 operations in > 63480ns; attempting to update the 'registry' > I0206 00:22:44.818780 2845 log.cpp:683] Attempting to append 170 bytes to > the log > I0206 00:22:44.818981 2845 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 1 > I0206 00:22:44.819941 2845 replica.cpp:537] Replica received write request > for position 1 from (9478)@172.17.0.2:43484 > I0206 00:22:44.820582 2845 leveldb.cpp:341] Persisting action (189 bytes) to > leveldb took 600949ns > I0206 00:22:44.820608 2845 replica.cpp:712] Persisted action at 1 > I0206 00:22:44.821552 2845 replica.cpp:691] Replica received learned notice > for position 1 from @0.0.0.0:0 > I0206 00:22:44.821934 2845 leveldb.cpp:341] Persisting action (191 bytes) to > leveldb took 352813ns > I0206 00:22:44.821960 2845 replica.cpp:712] Persisted action at 1 > I0206 00:22:44.821979 2845 replica.cpp:697] Replica learned APPEND action at > position 1 > I0206 00:22:44.823447 2845 registrar.cpp:484] Successfully updated the > 'registry' in 5.987072ms > I0206 00:22:44.823580 2845 registrar.cpp:370] Successfully recovered > registrar > I0206 00:22:44.823833 2845 log.cpp:702] Attempting to truncate the log to 1 > I0206 00:22:44.824203 2845 master.cpp:1522] Recovered 0 slaves from the > Registry (131B) ; allowing 10mins for slaves to re-register > I0206 00:22:44.824291 2845 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 2 > I0206 00:22:44.824645 2845 hierarchical.cpp:171] Skipping recovery of > hierarchical allocator: nothing to recover > I0206 00:22:44.825222 2850 replica.cpp:537] Replica received write request > for position 2 from (9479)@172.17.0.2:43484 > I0206 00:22:44.825742 2850 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 481617ns > I0206 00:22:44.825772 2850 replica.cpp:712] Persisted action at 2 > I0206 00:22:44.826748 2852 replica.cpp:691] Replica received learned notice > for position 2 from @0.0.0.0:0 > I0206 00:22:44.827368 2852 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 588591ns > I0206 00:22:44.827432 2852 leveldb.cpp:399] Deleting ~1 keys from leveldb > took 33059ns > I0206 00:22:44.827450 2852 replica.cpp:712] Persisted action at 2 > I0206 00:22:44.827468 2852 replica.cpp:697] Replica learned TRUNCATE action > at position 2 > I0206 00:22:44.838011 2824 containerizer.cpp:149] Using isolation: > posix/cpu,posix/mem,filesystem/posix > W0206 00:22:44.838873 2824 backend.cpp:48] Failed to create 'bind' backend: > BindBackend requires root privileges > I0206 00:22:44.843785 2857 slave.cpp:193] Slave started on 172.17.0.2:43484 > I0206 00:22:44.843819 2857 slave.cpp:194] 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/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/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/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/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.28.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/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw" > I0206 00:22:44.844292 2857 credentials.hpp:83] Loading credential for > authentication from > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/credential' > I0206 00:22:44.844518 2857 slave.cpp:324] Slave using credential for: > test-principal > I0206 00:22:44.844696 2857 resources.cpp:564] Parsing resources as JSON > failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] > Trying semicolon-delimited string format instead > I0206 00:22:44.845243 2857 slave.cpp:464] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I0206 00:22:44.845326 2857 slave.cpp:472] Slave attributes: [ ] > I0206 00:22:44.845342 2857 slave.cpp:477] Slave hostname: 6632562f1ade > I0206 00:22:44.845953 2824 sched.cpp:222] Version: 0.28.0 > I0206 00:22:44.846853 2848 sched.cpp:326] New master detected at > master@172.17.0.2:43484 > I0206 00:22:44.846936 2848 sched.cpp:382] Authenticating with master > master@172.17.0.2:43484 > I0206 00:22:44.846958 2848 sched.cpp:389] Using default CRAM-MD5 > authenticatee > I0206 00:22:44.847692 2858 state.cpp:58] Recovering state from > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta' > I0206 00:22:44.848108 2850 status_update_manager.cpp:200] Recovering status > update manager > I0206 00:22:44.848325 2852 containerizer.cpp:397] Recovering containerizer > I0206 00:22:44.848603 2845 authenticatee.cpp:121] Creating new client SASL > connection > I0206 00:22:44.849719 2845 master.cpp:5523] Authenticating > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:44.850052 2852 authenticator.cpp:413] Starting authentication > session for crammd5_authenticatee(662)@172.17.0.2:43484 > I0206 00:22:44.850227 2854 provisioner.cpp:245] Provisioner recovery complete > I0206 00:22:44.850410 2852 authenticator.cpp:98] Creating new server SASL > connection > I0206 00:22:44.850692 2852 authenticatee.cpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I0206 00:22:44.850720 2852 authenticatee.cpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0206 00:22:44.850805 2852 authenticator.cpp:203] Received SASL > authentication start > I0206 00:22:44.850862 2852 authenticator.cpp:325] Authentication requires > more steps > I0206 00:22:44.850939 2852 authenticatee.cpp:258] Received SASL > authentication step > I0206 00:22:44.851027 2852 authenticator.cpp:231] Received SASL > authentication step > I0206 00:22:44.851052 2852 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: '6632562f1ade' server FQDN: '6632562f1ade' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0206 00:22:44.851063 2852 auxprop.cpp:179] Looking up auxiliary property > '*userPassword' > I0206 00:22:44.851102 2852 auxprop.cpp:179] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0206 00:22:44.851121 2852 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: '6632562f1ade' server FQDN: '6632562f1ade' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0206 00:22:44.851130 2852 auxprop.cpp:129] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0206 00:22:44.851136 2852 auxprop.cpp:129] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0206 00:22:44.851150 2852 authenticator.cpp:317] Authentication success > I0206 00:22:44.851219 2850 authenticatee.cpp:298] Authentication success > I0206 00:22:44.851310 2850 master.cpp:5553] Successfully authenticated > principal 'test-principal' at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:44.851485 2849 slave.cpp:4496] Finished recovery > I0206 00:22:44.852154 2843 sched.cpp:471] Successfully authenticated with > master master@172.17.0.2:43484 > I0206 00:22:44.852175 2843 sched.cpp:776] Sending SUBSCRIBE call to > master@172.17.0.2:43484 > I0206 00:22:44.852262 2843 sched.cpp:809] Will retry registration in > 939.183679ms if necessary > I0206 00:22:44.852375 2844 master.cpp:2280] Received SUBSCRIBE call for > framework 'default' at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:44.852448 2844 master.cpp:1751] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I0206 00:22:44.852699 2852 authenticator.cpp:431] Authentication session > cleanup for crammd5_authenticatee(662)@172.17.0.2:43484 > I0206 00:22:44.852782 2844 master.cpp:2351] Subscribing framework default > with checkpointing enabled and capabilities [ ] > I0206 00:22:44.853056 2849 slave.cpp:4668] Querying resource estimator for > oversubscribable resources > I0206 00:22:44.853421 2856 hierarchical.cpp:265] Added framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:44.853513 2856 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:44.853582 2844 sched.cpp:703] Framework registered with > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:44.853613 2852 slave.cpp:4682] Received oversubscribable > resources from the resource estimator > I0206 00:22:44.853663 2844 sched.cpp:717] Scheduler::registered took 53762ns > I0206 00:22:44.853899 2843 slave.cpp:796] New master detected at > master@172.17.0.2:43484 > I0206 00:22:44.853955 2854 status_update_manager.cpp:174] Pausing sending > status updates > I0206 00:22:44.853997 2856 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:44.853960 2843 slave.cpp:859] Authenticating with master > master@172.17.0.2:43484 > I0206 00:22:44.854035 2843 slave.cpp:864] Using default CRAM-MD5 > authenticatee > I0206 00:22:44.854030 2856 hierarchical.cpp:1096] Performed allocation for 0 > slaves in 581355ns > I0206 00:22:44.854182 2843 slave.cpp:832] Detecting new master > I0206 00:22:44.854277 2854 authenticatee.cpp:121] Creating new client SASL > connection > I0206 00:22:44.854517 2843 master.cpp:5523] Authenticating > slave@172.17.0.2:43484 > I0206 00:22:44.854603 2854 authenticator.cpp:413] Starting authentication > session for crammd5_authenticatee(663)@172.17.0.2:43484 > I0206 00:22:44.854836 2855 authenticator.cpp:98] Creating new server SASL > connection > I0206 00:22:44.855013 2852 authenticatee.cpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I0206 00:22:44.855044 2852 authenticatee.cpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0206 00:22:44.855139 2855 authenticator.cpp:203] Received SASL > authentication start > I0206 00:22:44.855186 2855 authenticator.cpp:325] Authentication requires > more steps > I0206 00:22:44.855263 2855 authenticatee.cpp:258] Received SASL > authentication step > I0206 00:22:44.855352 2855 authenticator.cpp:231] Received SASL > authentication step > I0206 00:22:44.855381 2855 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: '6632562f1ade' server FQDN: '6632562f1ade' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0206 00:22:44.855389 2855 auxprop.cpp:179] Looking up auxiliary property > '*userPassword' > I0206 00:22:44.855419 2855 auxprop.cpp:179] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0206 00:22:44.855438 2855 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: '6632562f1ade' server FQDN: '6632562f1ade' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0206 00:22:44.855448 2855 auxprop.cpp:129] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0206 00:22:44.855453 2855 auxprop.cpp:129] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0206 00:22:44.855464 2855 authenticator.cpp:317] Authentication success > I0206 00:22:44.855540 2851 authenticatee.cpp:298] Authentication success > I0206 00:22:44.855721 2851 authenticator.cpp:431] Authentication session > cleanup for crammd5_authenticatee(663)@172.17.0.2:43484 > I0206 00:22:44.855832 2852 slave.cpp:927] Successfully authenticated with > master master@172.17.0.2:43484 > I0206 00:22:44.855615 2855 master.cpp:5553] Successfully authenticated > principal 'test-principal' at slave@172.17.0.2:43484 > I0206 00:22:44.855973 2852 slave.cpp:1321] Will retry registration in > 9.327708ms if necessary > I0206 00:22:44.856145 2854 master.cpp:4237] Registering slave at > slave@172.17.0.2:43484 (6632562f1ade) with id > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 > I0206 00:22:44.856598 2851 registrar.cpp:439] Applied 1 operations in > 59112ns; attempting to update the 'registry' > I0206 00:22:44.857403 2851 log.cpp:683] Attempting to append 339 bytes to > the log > I0206 00:22:44.857525 2855 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 3 > I0206 00:22:44.858482 2844 replica.cpp:537] Replica received write request > for position 3 from (9493)@172.17.0.2:43484 > I0206 00:22:44.858755 2844 leveldb.cpp:341] Persisting action (358 bytes) to > leveldb took 228484ns > I0206 00:22:44.858855 2844 replica.cpp:712] Persisted action at 3 > I0206 00:22:44.859751 2852 replica.cpp:691] Replica received learned notice > for position 3 from @0.0.0.0:0 > I0206 00:22:44.860332 2852 leveldb.cpp:341] Persisting action (360 bytes) to > leveldb took 549638ns > I0206 00:22:44.860358 2852 replica.cpp:712] Persisted action at 3 > I0206 00:22:44.860411 2852 replica.cpp:697] Replica learned APPEND action at > position 3 > I0206 00:22:44.862709 2856 registrar.cpp:484] Successfully updated the > 'registry' in 6.020864ms > I0206 00:22:44.863106 2850 log.cpp:702] Attempting to truncate the log to 3 > I0206 00:22:44.863358 2850 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 4 > I0206 00:22:44.864321 2850 slave.cpp:3436] Received ping from > slave-observer(288)@172.17.0.2:43484 > I0206 00:22:44.864706 2849 hierarchical.cpp:473] Added slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 (6632562f1ade) with cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) > I0206 00:22:44.864716 2843 replica.cpp:537] Replica received write request > for position 4 from (9494)@172.17.0.2:43484 > I0206 00:22:44.865309 2843 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 410199ns > I0206 00:22:44.865337 2843 replica.cpp:712] Persisted action at 4 > I0206 00:22:44.866092 2849 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:44.866132 2848 replica.cpp:691] Replica received learned notice > for position 4 from @0.0.0.0:0 > I0206 00:22:44.866137 2849 hierarchical.cpp:1116] Performed allocation for > slave 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 in 1.30657ms > I0206 00:22:44.866497 2856 master.cpp:4305] Registered slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 at slave@172.17.0.2:43484 > (6632562f1ade) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I0206 00:22:44.866564 2843 slave.cpp:1321] Will retry registration in > 32.803438ms if necessary > I0206 00:22:44.866690 2843 slave.cpp:971] Registered with master > master@172.17.0.2:43484; given slave ID > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 > I0206 00:22:44.866716 2843 fetcher.cpp:81] Clearing fetcher cache > I0206 00:22:44.867066 2856 master.cpp:5352] Sending 1 offers to framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (default) at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:44.867105 2843 slave.cpp:994] Checkpointing SlaveInfo to > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/slave.info' > I0206 00:22:44.867347 2856 master.cpp:4207] Slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 at slave@172.17.0.2:43484 > (6632562f1ade) already registered, resending acknowledgement > I0206 00:22:44.867441 2856 status_update_manager.cpp:181] Resuming sending > status updates > I0206 00:22:44.867465 2843 slave.cpp:1030] Forwarding total oversubscribed > resources > W0206 00:22:44.867547 2843 slave.cpp:1016] Already registered with master > master@172.17.0.2:43484 > I0206 00:22:44.867574 2843 slave.cpp:1030] Forwarding total oversubscribed > resources > I0206 00:22:44.867710 2843 master.cpp:4646] Received update of slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 at slave@172.17.0.2:43484 > (6632562f1ade) with total oversubscribed resources > I0206 00:22:44.867951 2856 sched.cpp:873] Scheduler::resourceOffers took > 133371ns > I0206 00:22:44.867961 2843 master.cpp:4646] Received update of slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 at slave@172.17.0.2:43484 > (6632562f1ade) with total oversubscribed resources > I0206 00:22:44.868484 2856 hierarchical.cpp:531] Slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 (6632562f1ade) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000]) > I0206 00:22:44.868599 2848 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 2.418545ms > I0206 00:22:44.868700 2848 leveldb.cpp:399] Deleting ~2 keys from leveldb > took 54053ns > I0206 00:22:44.868751 2848 replica.cpp:712] Persisted action at 4 > I0206 00:22:44.868811 2848 replica.cpp:697] Replica learned TRUNCATE action > at position 4 > I0206 00:22:44.869241 2856 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:44.869287 2856 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:44.869321 2856 hierarchical.cpp:1116] Performed allocation for > slave 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 in 782848ns > I0206 00:22:44.869840 2856 hierarchical.cpp:531] Slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 (6632562f1ade) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000]) > I0206 00:22:44.869985 2856 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:44.870028 2856 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:44.870053 2856 hierarchical.cpp:1116] Performed allocation for > slave 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 in 160104ns > I0206 00:22:44.871824 2853 master.cpp:3138] Processing ACCEPT call for > offers: [ 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-O0 ] on slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 at slave@172.17.0.2:43484 > (6632562f1ade) for framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > (default) at scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:44.871868 2853 master.cpp:2825] Authorizing framework principal > 'test-principal' to launch task 1 as user 'mesos' > W0206 00:22:44.873613 2843 validation.cpp:404] Executor http for task 1 uses > less CPUs (None) than the minimum required (0.01). Please update your > executor, as this will be mandatory in future releases. > W0206 00:22:44.873667 2843 validation.cpp:416] Executor http for task 1 uses > less memory (None) than the minimum required (32MB). Please update your > executor, as this will be mandatory in future releases. > I0206 00:22:44.874035 2843 master.hpp:176] Adding task 1 with resources > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 (6632562f1ade) > I0206 00:22:44.874223 2843 master.cpp:3623] Launching task 1 of framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (default) at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 with > resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on > slave 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 at slave@172.17.0.2:43484 > (6632562f1ade) > I0206 00:22:44.874802 2843 slave.cpp:1361] Got assigned task 1 for framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:44.874966 2843 slave.cpp:5202] Checkpointing FrameworkInfo to > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/framework.info' > I0206 00:22:44.875440 2843 slave.cpp:5213] Checkpointing framework pid > 'scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484' to > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/framework.pid' > I0206 00:22:44.876106 2843 slave.cpp:1480] Launching task 1 for framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:44.876644 2843 paths.cpp:474] Trying to chown > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http/runs/fd4649a4-1c82-4eda-b663-b568b6110d17' > to user 'mesos' > I0206 00:22:44.884089 2843 slave.cpp:5654] Checkpointing ExecutorInfo to > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http/executor.info' > I0206 00:22:44.900928 2843 slave.cpp:5282] Launching executor http of > framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 with resources in work > directory > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http/runs/fd4649a4-1c82-4eda-b663-b568b6110d17' > I0206 00:22:44.901449 2853 containerizer.cpp:656] Starting container > 'fd4649a4-1c82-4eda-b663-b568b6110d17' for executor 'http' of framework > '0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000' > I0206 00:22:44.901561 2843 slave.cpp:5677] Checkpointing TaskInfo to > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http/runs/fd4649a4-1c82-4eda-b663-b568b6110d17/tasks/1/task.info' > I0206 00:22:44.902060 2843 slave.cpp:1698] Queuing task '1' for executor > 'http' of framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:44.902207 2843 slave.cpp:749] Successfully attached file > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http/runs/fd4649a4-1c82-4eda-b663-b568b6110d17' > I0206 00:22:44.907027 2850 launcher.cpp:132] Forked child with pid '8875' > for container 'fd4649a4-1c82-4eda-b663-b568b6110d17' > I0206 00:22:44.907229 2850 containerizer.cpp:1094] Checkpointing executor's > forked pid 8875 to > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http/runs/fd4649a4-1c82-4eda-b663-b568b6110d17/pids/forked.pid' > WARNING: Logging before InitGoogleLogging() is written to STDERR > I0206 00:22:45.080060 8875 process.cpp:991] libprocess is initialized on > 172.17.0.2:49724 for 16 cpus > I0206 00:22:45.082499 8875 logging.cpp:193] Logging to STDERR > I0206 00:22:45.082862 8875 executor.cpp:172] Version: 0.28.0 > I0206 00:22:45.087201 8903 executor.cpp:316] Connected with the agent > I0206 00:22:45.802878 2858 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:45.802969 2858 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:45.803014 2858 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 424120ns > 2016-02-06 > 00:22:45,982:2824(0x7fd8c5ffb700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:40712] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > W0206 00:22:46.588022 2854 group.cpp:503] Timed out waiting to connect to > ZooKeeper. Forcing ZooKeeper session (sessionId=0) expiration > I0206 00:22:46.588969 2854 group.cpp:519] ZooKeeper session expired > 2016-02-06 00:22:46,589:2824(0x7fd9fefd1700):ZOO_INFO@zookeeper_close@2522: > Freeing zookeeper resources for sessionId=0 > 2016-02-06 00:22:46,589:2824(0x7fda03fdb700):ZOO_INFO@log_env@712: Client > environment:zookeeper.version=zookeeper C client 3.4.5 > 2016-02-06 00:22:46,589:2824(0x7fda03fdb700):ZOO_INFO@log_env@716: Client > environment:host.name=6632562f1ade > 2016-02-06 00:22:46,589:2824(0x7fda03fdb700):ZOO_INFO@log_env@723: Client > environment:os.name=Linux > 2016-02-06 00:22:46,589:2824(0x7fda03fdb700):ZOO_INFO@log_env@724: Client > environment:os.arch=3.13.0-36-lowlatency > 2016-02-06 00:22:46,589:2824(0x7fda03fdb700):ZOO_INFO@log_env@725: Client > environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014 > 2016-02-06 00:22:46,589:2824(0x7fda03fdb700):ZOO_INFO@log_env@733: Client > environment:user.name=(null) > 2016-02-06 00:22:46,589:2824(0x7fda03fdb700):ZOO_INFO@log_env@741: Client > environment:user.home=/home/mesos > 2016-02-06 00:22:46,589:2824(0x7fda03fdb700):ZOO_INFO@log_env@753: Client > environment:user.dir=/tmp/n2FxQV > 2016-02-06 00:22:46,590:2824(0x7fda03fdb700):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:40712 sessionTimeout=10000 > watcher=0x7fda10e9e520 sessionId=0 sessionPasswd=<null> > context=0x7fd9d401bc10 flags=0 > 2016-02-06 > 00:22:46,590:2824(0x7fd8c67fc700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:40712] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I0206 00:22:46.804400 2844 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:46.804481 2844 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:46.804514 2844 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 347954ns > I0206 00:22:47.805842 2847 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:47.805934 2847 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:47.805980 2847 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 415449ns > I0206 00:22:48.807723 2851 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:48.807814 2851 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:48.807857 2851 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 442104ns > I0206 00:22:49.808733 2848 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:49.808816 2848 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:49.808856 2848 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 384959ns > 2016-02-06 > 00:22:49,926:2824(0x7fd8c67fc700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:40712] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I0206 00:22:50.810307 2847 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:50.810400 2847 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:50.810443 2847 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 389572ns > I0206 00:22:51.811586 2849 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:51.811681 2849 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:51.811722 2849 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 404450ns > I0206 00:22:52.812860 2851 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:52.812944 2851 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:52.812981 2851 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 359671ns > 2016-02-06 > 00:22:53,263:2824(0x7fd8c67fc700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:40712] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I0206 00:22:53.814512 2847 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:53.814599 2847 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:53.814651 2847 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 386669ns > I0206 00:22:54.815238 2852 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:54.815321 2852 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:54.815356 2852 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 376235ns > I0206 00:22:55.816453 2846 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:55.816550 2846 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:55.816596 2846 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 416350ns > W0206 00:22:56.592408 2849 group.cpp:503] Timed out waiting to connect to > ZooKeeper. Forcing ZooKeeper session (sessionId=0) expiration > I0206 00:22:56.593480 2849 group.cpp:519] ZooKeeper session expired > 2016-02-06 00:22:56,593:2824(0x7fda017d6700):ZOO_INFO@zookeeper_close@2522: > Freeing zookeeper resources for sessionId=0 > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@log_env@712: Client > environment:zookeeper.version=zookeeper C client 3.4.5 > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@log_env@716: Client > environment:host.name=6632562f1ade > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@log_env@723: Client > environment:os.name=Linux > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@log_env@724: Client > environment:os.arch=3.13.0-36-lowlatency > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@log_env@725: Client > environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014 > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@log_env@733: Client > environment:user.name=(null) > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@log_env@741: Client > environment:user.home=/home/mesos > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@log_env@753: Client > environment:user.dir=/tmp/n2FxQV > 2016-02-06 00:22:56,594:2824(0x7fda007d4700):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:40712 sessionTimeout=10000 > watcher=0x7fda10e9e520 sessionId=0 sessionPasswd=<null> > context=0x7fd9e401f350 flags=0 > 2016-02-06 > 00:22:56,595:2824(0x7fd8c5ffb700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:40712] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > I0206 00:22:56.817683 2848 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:56.817766 2848 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:56.817803 2848 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 374115ns > I0206 00:22:57.818447 2844 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:57.818526 2844 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:57.818562 2844 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 344545ns > I0206 00:22:58.819828 2851 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:58.819914 2851 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:58.819957 2851 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 376948ns > I0206 00:22:59.820874 2848 hierarchical.cpp:1403] No resources available to > allocate! > I0206 00:22:59.820957 2848 hierarchical.cpp:1498] No inverse offers to send > out! > I0206 00:22:59.820991 2848 hierarchical.cpp:1096] Performed allocation for 1 > slaves in 344192ns > I0206 00:22:59.854698 2845 slave.cpp:4668] Querying resource estimator for > oversubscribable resources > I0206 00:22:59.854991 2845 slave.cpp:4682] Received oversubscribable > resources from the resource estimator > I0206 00:22:59.864612 2857 slave.cpp:3436] Received ping from > slave-observer(288)@172.17.0.2:43484 > ../../src/tests/slave_recovery_tests.cpp:1105: Failure > Failed to wait 15secs for updateCall1 > I0206 00:22:59.876358 2852 master.cpp:1213] Framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (default) at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 disconnected > I0206 00:22:59.876410 2852 master.cpp:2576] Disconnecting framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (default) at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:59.876456 2852 master.cpp:2600] Deactivating framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (default) at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:59.876569 2852 master.cpp:1237] Giving framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (default) at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 0ns to > failover > I0206 00:22:59.876981 2844 hierarchical.cpp:375] Deactivated framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:59.877049 2844 master.cpp:5204] Framework failover timeout, > removing framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (default) at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:59.877075 2844 master.cpp:5935] Removing framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (default) at > scheduler-63899759-d7fc-42b2-8371-57484f352895@172.17.0.2:43484 > I0206 00:22:59.877276 2844 master.cpp:6447] Updating the state of task 1 of > framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 (latest state: > TASK_KILLED, status update state: TASK_KILLED) > I0206 00:22:59.878051 2844 master.cpp:6513] Removing task 1 with resources > cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 on slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 at slave@172.17.0.2:43484 > (6632562f1ade) > I0206 00:22:59.878433 2844 master.cpp:6542] Removing executor 'http' with > resources of framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 on slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 at slave@172.17.0.2:43484 > (6632562f1ade) > I0206 00:22:59.878667 2852 slave.cpp:2079] Asked to shut down framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 by master@172.17.0.2:43484 > I0206 00:22:59.878733 2852 slave.cpp:2104] Shutting down framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:59.878806 2852 slave.cpp:4129] Shutting down executor 'http' of > framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > W0206 00:22:59.878834 2852 slave.hpp:655] Unable to send event to executor > 'http' of framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000: unknown > connection type > I0206 00:22:59.879550 2844 master.cpp:1027] Master terminating > I0206 00:22:59.879703 2854 hierarchical.cpp:892] Recovered cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 from framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:59.879947 2854 hierarchical.cpp:326] Removed framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:59.880306 2854 hierarchical.cpp:505] Removed slave > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0 > I0206 00:22:59.880666 2852 slave.cpp:3482] master@172.17.0.2:43484 exited > W0206 00:22:59.880695 2852 slave.cpp:3485] Master disconnected! Waiting for > a new master to be elected > I0206 00:22:59.885498 2857 containerizer.cpp:1318] Destroying container > 'fd4649a4-1c82-4eda-b663-b568b6110d17' > I0206 00:22:59.904532 2858 containerizer.cpp:1534] Executor for container > 'fd4649a4-1c82-4eda-b663-b568b6110d17' has exited > I0206 00:22:59.907024 2858 provisioner.cpp:306] Ignoring destroy request for > unknown container fd4649a4-1c82-4eda-b663-b568b6110d17 > I0206 00:22:59.907428 2858 slave.cpp:3817] Executor 'http' of framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 terminated with signal Killed > I0206 00:22:59.907538 2858 slave.cpp:3921] Cleaning up executor 'http' of > framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:59.908213 2858 slave.cpp:4009] Cleaning up framework > 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:59.908555 2858 gc.cpp:54] Scheduling > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http/runs/fd4649a4-1c82-4eda-b663-b568b6110d17' > for gc 6.99998949252444days in the future > I0206 00:22:59.908720 2858 gc.cpp:54] Scheduling > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http' > for gc 6.99998949082074days in the future > I0206 00:22:59.908807 2858 gc.cpp:54] Scheduling > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http/runs/fd4649a4-1c82-4eda-b663-b568b6110d17' > for gc 6.99998948980444days in the future > I0206 00:22:59.908927 2858 gc.cpp:54] Scheduling > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000/executors/http' > for gc 6.99998948890074days in the future > I0206 00:22:59.909009 2858 gc.cpp:54] Scheduling > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000' > for gc 6.99998948710518days in the future > I0206 00:22:59.909121 2858 gc.cpp:54] Scheduling > '/tmp/SlaveRecoveryTest_0_CleanupHTTPExecutor_kAXwvw/meta/slaves/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-S0/frameworks/0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000' > for gc 6.99998948630815days in the future > I0206 00:22:59.909211 2858 status_update_manager.cpp:282] Closing status > update streams for framework 0b206a40-a9c3-4d44-a5bd-8032d60a32ca-0000 > I0206 00:22:59.910423 2853 slave.cpp:668] Slave terminating > ../../3rdparty/libprocess/include/process/gmock.hpp:425: Failure > Actual function call count doesn't match EXPECT_CALL(filter->mock, > filter(testing::A<const HttpEvent&>()))... > Expected args: union http matcher (72-byte object <D0-11 44-12 DA-7F > 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 > 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 01-00 > 00-00 00-00 00-00 00-00 00-00 00-00 00-00>, UPDATE, 1-byte object <1B>, > 16-byte object <1B-F4 34-01 00-00 00-00 00-00 00-00 DA-7F 00-00>) > Expected: to be called once > Actual: never called - unsatisfied and active > ../../3rdparty/libprocess/include/process/gmock.hpp:425: Failure > Actual function call count doesn't match EXPECT_CALL(filter->mock, > filter(testing::A<const HttpEvent&>()))... > Expected args: union http matcher (72-byte object <D0-11 44-12 DA-7F > 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 > 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 01-00 > 00-00 00-00 00-00 00-00 00-00 00-00 00-00>, UPDATE, 1-byte object <1B>, > 16-byte object <1B-F4 34-01 00-00 00-00 00-00 00-00 DA-7F 00-00>) > Expected: to be called once > Actual: never called - unsatisfied and active > [ FAILED ] SlaveRecoveryTest/0.CleanupHTTPExecutor, where TypeParam = > mesos::internal::slave::MesosContainerizer (15126 ms) > {code} -- This message was sent by Atlassian JIRA (v6.3.4#6332)