[MESOS-4614] SlaveRecoveryTest/0.CleanupHTTPExecutor is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: 0.27.0
Fix Version/s: 0.28.0
Component/s: agent, HTTP API, test
Labels:
- flaky-test
- mesosphere
Environment:

CentOS 7, gcc, libevent & SSL enabled

Epic Link:
Executor API v1
Sprint:
Mesosphere Sprint 28
Story Points:
3

Description

Just saw this failure on the ASF CI:

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

Attachments

Issue Links

is related to

MESOS-3273 EventCall Test Framework is flaky

Resolved

Activity

People

Assignee:: Anand Mazumdar

Reporter:: Greg Mann

Shepherd:: Vinod Kone

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 06/Feb/16 00:56

Updated:: 26/Apr/17 17:01

Resolved:: 08/Feb/16 23:35