You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "haosdent (JIRA)" <ji...@apache.org> on 2016/07/19 05:11:20 UTC
[jira] [Commented] (MESOS-5860) MasterAPITest.GetTasks is flaky
[ https://issues.apache.org/jira/browse/MESOS-5860?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15383587#comment-15383587 ]
haosdent commented on MESOS-5860:
---------------------------------
We would generate two {{StatusUpdateAcknowledgementMessage}} which target is {{slave.get()->pid}}. So {{AWAIT_READY(acknowledgement);}} may satisfy when master send first {{StatusUpdateAcknowledgementMessage}}.
> MasterAPITest.GetTasks is flaky
> -------------------------------
>
> Key: MESOS-5860
> URL: https://issues.apache.org/jira/browse/MESOS-5860
> Project: Mesos
> Issue Type: Bug
> Reporter: haosdent
> Assignee: haosdent
>
> From https://builds.apache.org/job/Mesos/2517/BUILDTOOL=autotools,COMPILER=clang,CONFIGURATION=--verbose,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu:14.04,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)&&(!ubuntu-6)/consoleFull
> A failed run
> {code}
> [ RUN ] ContentType/MasterAPITest.GetTasks/0
> I0716 01:32:50.418465 26921 cluster.cpp:155] Creating default 'local' authorizer
> I0716 01:32:50.536353 26921 leveldb.cpp:174] Opened db in 117.63543ms
> I0716 01:32:50.570127 26921 leveldb.cpp:181] Compacted db in 33.607723ms
> I0716 01:32:50.570349 26921 leveldb.cpp:196] Created db iterator in 51989ns
> I0716 01:32:50.570523 26921 leveldb.cpp:202] Seeked to beginning of db in 28500ns
> I0716 01:32:50.570641 26921 leveldb.cpp:271] Iterated through 0 keys in the db in 13608ns
> I0716 01:32:50.570794 26921 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0716 01:32:50.571712 26949 recover.cpp:451] Starting replica recovery
> I0716 01:32:50.571979 26949 recover.cpp:477] Replica is in EMPTY status
> I0716 01:32:50.576714 26942 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (15981)@172.17.0.8:44669
> I0716 01:32:50.576823 26939 master.cpp:382] Master 2949f69e-5d82-48a7-80da-ba654dac4ed1 (f1ca07e700ef) started on 172.17.0.8:44669
> I0716 01:32:50.576858 26939 master.cpp:384] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ZWBVTM/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-1.1.0/_inst/share/mesos/webui" --work_dir="/tmp/ZWBVTM/master" --zk_session_timeout="10secs"
> I0716 01:32:50.577327 26939 master.cpp:434] Master only allowing authenticated frameworks to register
> I0716 01:32:50.577342 26939 master.cpp:448] Master only allowing authenticated agents to register
> I0716 01:32:50.577350 26939 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
> I0716 01:32:50.577360 26939 credentials.hpp:37] Loading credentials for authentication from '/tmp/ZWBVTM/credentials'
> I0716 01:32:50.577958 26944 recover.cpp:197] Received a recover response from a replica in EMPTY status
> I0716 01:32:50.578735 26944 recover.cpp:568] Updating replica status to STARTING
> I0716 01:32:50.578871 26939 master.cpp:506] Using default 'crammd5' authenticator
> I0716 01:32:50.579008 26939 master.cpp:578] Using default 'basic' HTTP authenticator
> I0716 01:32:50.579143 26939 master.cpp:658] Using default 'basic' HTTP framework authenticator
> I0716 01:32:50.579239 26939 master.cpp:705] Authorization enabled
> I0716 01:32:50.579459 26951 whitelist_watcher.cpp:77] No whitelist given
> I0716 01:32:50.580548 26946 hierarchical.cpp:151] Initialized hierarchical allocator process
> I0716 01:32:50.582908 26942 master.cpp:1973] The newly elected leader is master@172.17.0.8:44669 with id 2949f69e-5d82-48a7-80da-ba654dac4ed1
> I0716 01:32:50.582962 26942 master.cpp:1986] Elected as the leading master!
> I0716 01:32:50.582976 26942 master.cpp:1673] Recovering from registrar
> I0716 01:32:50.583252 26952 registrar.cpp:332] Recovering registrar
> I0716 01:32:50.609922 26944 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 30.925255ms
> I0716 01:32:50.610015 26944 replica.cpp:320] Persisted replica status to STARTING
> I0716 01:32:50.610350 26944 recover.cpp:477] Replica is in STARTING status
> I0716 01:32:50.613060 26951 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (15985)@172.17.0.8:44669
> I0716 01:32:50.615031 26944 recover.cpp:197] Received a recover response from a replica in STARTING status
> I0716 01:32:50.615545 26941 recover.cpp:568] Updating replica status to VOTING
> I0716 01:32:50.646492 26941 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 30.72503ms
> I0716 01:32:50.646581 26941 replica.cpp:320] Persisted replica status to VOTING
> I0716 01:32:50.646854 26941 recover.cpp:582] Successfully joined the Paxos group
> I0716 01:32:50.647066 26941 recover.cpp:466] Recover process terminated
> I0716 01:32:50.647867 26944 log.cpp:553] Attempting to start the writer
> I0716 01:32:50.651500 26945 replica.cpp:493] Replica received implicit promise request from (15986)@172.17.0.8:44669 with proposal 1
> I0716 01:32:50.671548 26945 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 20.039474ms
> I0716 01:32:50.671633 26945 replica.cpp:342] Persisted promised to 1
> I0716 01:32:50.673152 26943 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I0716 01:32:50.675154 26943 replica.cpp:388] Replica received explicit promise request from (15987)@172.17.0.8:44669 for position 0 with proposal 2
> I0716 01:32:50.696714 26943 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 21.465357ms
> I0716 01:32:50.696805 26943 replica.cpp:712] Persisted action at 0
> I0716 01:32:50.698724 26947 replica.cpp:537] Replica received write request for position 0 from (15988)@172.17.0.8:44669
> I0716 01:32:50.698840 26947 leveldb.cpp:436] Reading position from leveldb took 63125ns
> I0716 01:32:50.721994 26947 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 23.129832ms
> I0716 01:32:50.722702 26947 replica.cpp:712] Persisted action at 0
> I0716 01:32:50.724701 26947 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
> I0716 01:32:50.747094 26947 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 22.064167ms
> I0716 01:32:50.747727 26947 replica.cpp:712] Persisted action at 0
> I0716 01:32:50.748145 26947 replica.cpp:697] Replica learned NOP action at position 0
> I0716 01:32:50.749789 26950 log.cpp:569] Writer started with ending position 0
> I0716 01:32:50.751765 26950 leveldb.cpp:436] Reading position from leveldb took 74145ns
> I0716 01:32:50.753523 26943 registrar.cpp:365] Successfully fetched the registry (0B) in 170.22208ms
> I0716 01:32:50.754050 26943 registrar.cpp:464] Applied 1 operations in 49444ns; attempting to update the 'registry'
> I0716 01:32:50.755728 26950 log.cpp:577] Attempting to append 168 bytes to the log
> I0716 01:32:50.756314 26943 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I0716 01:32:50.758147 26943 replica.cpp:537] Replica received write request for position 1 from (15989)@172.17.0.8:44669
> I0716 01:32:50.785879 26943 leveldb.cpp:341] Persisting action (187 bytes) to leveldb took 27.261512ms
> I0716 01:32:50.785967 26943 replica.cpp:712] Persisted action at 1
> I0716 01:32:50.788110 26954 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
> I0716 01:32:50.805907 26954 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 17.773266ms
> I0716 01:32:50.806097 26954 replica.cpp:712] Persisted action at 1
> I0716 01:32:50.806252 26954 replica.cpp:697] Replica learned APPEND action at position 1
> I0716 01:32:50.807741 26945 registrar.cpp:509] Successfully updated the 'registry' in 53.299968ms
> I0716 01:32:50.808043 26954 log.cpp:596] Attempting to truncate the log to 1
> I0716 01:32:50.808254 26954 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I0716 01:32:50.808502 26945 registrar.cpp:395] Successfully recovered registrar
> I0716 01:32:50.809427 26945 master.cpp:1781] Recovered 0 agents from the Registry (129B) ; allowing 10mins for agents to re-register
> I0716 01:32:50.809613 26952 hierarchical.cpp:178] Skipping recovery of hierarchical allocator: nothing to recover
> I0716 01:32:50.809664 26951 replica.cpp:537] Replica received write request for position 2 from (15990)@172.17.0.8:44669
> I0716 01:32:50.830983 26951 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 20.868656ms
> I0716 01:32:50.831116 26951 replica.cpp:712] Persisted action at 2
> I0716 01:32:50.832618 26952 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
> I0716 01:32:50.856155 26952 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 23.506659ms
> I0716 01:32:50.856313 26952 leveldb.cpp:399] Deleting ~1 keys from leveldb took 84579ns
> I0716 01:32:50.856344 26952 replica.cpp:712] Persisted action at 2
> I0716 01:32:50.856379 26952 replica.cpp:697] Replica learned TRUNCATE action at position 2
> I0716 01:32:50.865809 26921 cluster.cpp:432] Creating default 'local' authorizer
> I0716 01:32:50.868458 26940 slave.cpp:205] Agent started on 443)@172.17.0.8:44669
> I0716 01:32:50.868494 26940 slave.cpp:206] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --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/ContentType_MasterAPITest_GetTasks_0_nF2pJL/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --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" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-1.1.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;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL"
> I0716 01:32:50.869688 26940 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/credential'
> I0716 01:32:50.870079 26940 slave.cpp:343] Agent using credential for: test-principal
> I0716 01:32:50.870344 26940 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/http_credentials'
> I0716 01:32:50.870832 26940 slave.cpp:395] Using default 'basic' HTTP authenticator
> I0716 01:32:50.871497 26940 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0716 01:32:50.872261 26940 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0716 01:32:50.873101 26940 slave.cpp:594] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 01:32:50.873483 26940 slave.cpp:602] Agent attributes: [ ]
> I0716 01:32:50.873859 26940 slave.cpp:607] Agent hostname: f1ca07e700ef
> I0716 01:32:50.875046 26921 sched.cpp:226] Version: 1.1.0
> I0716 01:32:50.876268 26952 state.cpp:57] Recovering state from '/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/meta'
> I0716 01:32:50.876366 26940 sched.cpp:330] New master detected at master@172.17.0.8:44669
> I0716 01:32:50.876677 26940 sched.cpp:396] Authenticating with master master@172.17.0.8:44669
> I0716 01:32:50.876759 26940 sched.cpp:403] Using default CRAM-MD5 authenticatee
> I0716 01:32:50.876907 26952 status_update_manager.cpp:200] Recovering status update manager
> I0716 01:32:50.877213 26952 authenticatee.cpp:121] Creating new client SASL connection
> I0716 01:32:50.877348 26940 slave.cpp:4856] Finished recovery
> I0716 01:32:50.877779 26952 master.cpp:6006] Authenticating scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:50.877959 26940 slave.cpp:5028] Querying resource estimator for oversubscribable resources
> I0716 01:32:50.878078 26952 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(916)@172.17.0.8:44669
> I0716 01:32:50.878319 26940 slave.cpp:969] New master detected at master@172.17.0.8:44669
> I0716 01:32:50.878448 26940 slave.cpp:1028] Authenticating with master master@172.17.0.8:44669
> I0716 01:32:50.878523 26939 status_update_manager.cpp:174] Pausing sending status updates
> I0716 01:32:50.878772 26939 authenticator.cpp:98] Creating new server SASL connection
> I0716 01:32:50.879057 26952 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0716 01:32:50.879104 26952 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 01:32:50.879220 26952 authenticator.cpp:204] Received SASL authentication start
> I0716 01:32:50.879286 26940 slave.cpp:1039] Using default CRAM-MD5 authenticatee
> I0716 01:32:50.879297 26952 authenticator.cpp:326] Authentication requires more steps
> I0716 01:32:50.879634 26951 authenticatee.cpp:259] Received SASL authentication step
> I0716 01:32:50.879743 26951 authenticator.cpp:232] Received SASL authentication step
> I0716 01:32:50.879848 26951 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f1ca07e700ef' server FQDN: 'f1ca07e700ef' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0716 01:32:50.879953 26951 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0716 01:32:50.880079 26951 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0716 01:32:50.880189 26951 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f1ca07e700ef' server FQDN: 'f1ca07e700ef' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0716 01:32:50.880283 26951 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0716 01:32:50.880374 26951 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0716 01:32:50.880496 26951 authenticator.cpp:318] Authentication success
> I0716 01:32:50.880745 26951 authenticatee.cpp:299] Authentication success
> I0716 01:32:50.880849 26951 master.cpp:6036] Successfully authenticated principal 'test-principal' at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:50.880964 26951 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(916)@172.17.0.8:44669
> I0716 01:32:50.881366 26951 sched.cpp:502] Successfully authenticated with master master@172.17.0.8:44669
> I0716 01:32:50.881392 26951 sched.cpp:820] Sending SUBSCRIBE call to master@172.17.0.8:44669
> I0716 01:32:50.881651 26951 sched.cpp:853] Will retry registration in 229.664721ms if necessary
> I0716 01:32:50.881934 26952 master.cpp:2550] Received SUBSCRIBE call for framework 'default' at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:50.882000 26952 master.cpp:2012] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0716 01:32:50.882587 26952 master.cpp:2626] Subscribing framework default with checkpointing disabled and capabilities [ ]
> I0716 01:32:50.883420 26952 hierarchical.cpp:271] Added framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:50.883642 26949 sched.cpp:743] Framework registered with 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:50.883785 26949 sched.cpp:757] Scheduler::registered took 33974ns
> I0716 01:32:50.883600 26952 hierarchical.cpp:1537] No allocations performed
> I0716 01:32:50.883970 26940 slave.cpp:1001] Detecting new master
> I0716 01:32:50.884094 26952 hierarchical.cpp:1632] No inverse offers to send out!
> I0716 01:32:50.884191 26940 slave.cpp:5042] Received oversubscribable resources from the resource estimator
> I0716 01:32:50.884492 26949 authenticatee.cpp:121] Creating new client SASL connection
> I0716 01:32:50.884531 26952 hierarchical.cpp:1172] Performed allocation for 0 agents in 1.098019ms
> I0716 01:32:50.884908 26946 master.cpp:6006] Authenticating slave(443)@172.17.0.8:44669
> I0716 01:32:50.885133 26946 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(917)@172.17.0.8:44669
> I0716 01:32:50.885511 26946 authenticator.cpp:98] Creating new server SASL connection
> I0716 01:32:50.885757 26949 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0716 01:32:50.885792 26949 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 01:32:50.885886 26949 authenticator.cpp:204] Received SASL authentication start
> I0716 01:32:50.885944 26949 authenticator.cpp:326] Authentication requires more steps
> I0716 01:32:50.886020 26949 authenticatee.cpp:259] Received SASL authentication step
> I0716 01:32:50.886106 26949 authenticator.cpp:232] Received SASL authentication step
> I0716 01:32:50.886137 26949 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f1ca07e700ef' server FQDN: 'f1ca07e700ef' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0716 01:32:50.886149 26949 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0716 01:32:50.886185 26949 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0716 01:32:50.886207 26949 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f1ca07e700ef' server FQDN: 'f1ca07e700ef' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0716 01:32:50.886220 26949 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0716 01:32:50.886231 26949 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0716 01:32:50.886248 26949 authenticator.cpp:318] Authentication success
> I0716 01:32:50.886387 26949 authenticatee.cpp:299] Authentication success
> I0716 01:32:50.886618 26949 master.cpp:6036] Successfully authenticated principal 'test-principal' at slave(443)@172.17.0.8:44669
> I0716 01:32:50.886695 26949 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(917)@172.17.0.8:44669
> I0716 01:32:50.886988 26949 slave.cpp:1123] Successfully authenticated with master master@172.17.0.8:44669
> I0716 01:32:50.887161 26949 slave.cpp:1529] Will retry registration in 8.740926ms if necessary
> I0716 01:32:50.887598 26949 master.cpp:4676] Registering agent at slave(443)@172.17.0.8:44669 (f1ca07e700ef) with id 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0
> I0716 01:32:50.888099 26949 registrar.cpp:464] Applied 1 operations in 82483ns; attempting to update the 'registry'
> I0716 01:32:50.889273 26947 log.cpp:577] Attempting to append 337 bytes to the log
> I0716 01:32:50.889516 26942 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I0716 01:32:50.890645 26942 replica.cpp:537] Replica received write request for position 3 from (15996)@172.17.0.8:44669
> I0716 01:32:50.896863 26944 slave.cpp:1529] Will retry registration in 16.748832ms if necessary
> I0716 01:32:50.897285 26944 master.cpp:4664] Ignoring register agent message from slave(443)@172.17.0.8:44669 (f1ca07e700ef) as admission is already in progress
> I0716 01:32:50.914973 26951 master.cpp:4664] Ignoring register agent message from slave(443)@172.17.0.8:44669 (f1ca07e700ef) as admission is already in progress
> I0716 01:32:50.914651 26939 slave.cpp:1529] Will retry registration in 4.693356ms if necessary
> I0716 01:32:50.920524 26942 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took 29.849165ms
> I0716 01:32:50.920678 26942 replica.cpp:712] Persisted action at 3
> I0716 01:32:50.920810 26945 slave.cpp:1529] Will retry registration in 140.669866ms if necessary
> I0716 01:32:50.921087 26942 master.cpp:4664] Ignoring register agent message from slave(443)@172.17.0.8:44669 (f1ca07e700ef) as admission is already in progress
> I0716 01:32:50.922183 26946 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
> I0716 01:32:50.962424 26946 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 39.939635ms
> I0716 01:32:50.962512 26946 replica.cpp:712] Persisted action at 3
> I0716 01:32:50.962548 26946 replica.cpp:697] Replica learned APPEND action at position 3
> I0716 01:32:50.965457 26945 log.cpp:596] Attempting to truncate the log to 3
> I0716 01:32:50.965677 26942 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I0716 01:32:50.965787 26946 registrar.cpp:509] Successfully updated the 'registry' in 77.241088ms
> I0716 01:32:50.966897 26939 replica.cpp:537] Replica received write request for position 4 from (15997)@172.17.0.8:44669
> I0716 01:32:50.966904 26945 slave.cpp:3760] Received ping from slave-observer(411)@172.17.0.8:44669
> I0716 01:32:50.966961 26946 master.cpp:4745] Registered agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 01:32:50.967288 26945 slave.cpp:1169] Registered with master master@172.17.0.8:44669; given agent ID 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0
> I0716 01:32:50.967479 26945 fetcher.cpp:86] Clearing fetcher cache
> I0716 01:32:50.967458 26954 hierarchical.cpp:478] Added agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 (f1ca07e700ef) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0716 01:32:50.967780 26946 status_update_manager.cpp:181] Resuming sending status updates
> I0716 01:32:50.968631 26954 hierarchical.cpp:1632] No inverse offers to send out!
> I0716 01:32:50.968713 26954 hierarchical.cpp:1195] Performed allocation for agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 in 1.009599ms
> I0716 01:32:50.969025 26941 master.cpp:5835] Sending 1 offers to framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:50.969563 26954 sched.cpp:917] Scheduler::resourceOffers took 135476ns
> I0716 01:32:50.971268 26945 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/meta/slaves/2949f69e-5d82-48a7-80da-ba654dac4ed1-S0/slave.info'
> I0716 01:32:50.971293 26940 master.cpp:3468] Processing ACCEPT call for offers: [ 2949f69e-5d82-48a7-80da-ba654dac4ed1-O0 ] on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef) for framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:50.971374 26940 master.cpp:3106] Authorizing framework principal 'test-principal' to launch task 1
> I0716 01:32:50.971781 26945 slave.cpp:1229] Forwarding total oversubscribed resources
> I0716 01:32:50.972097 26940 master.cpp:5128] Received update of agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef) with total oversubscribed resources
> I0716 01:32:50.972338 26940 hierarchical.cpp:542] Agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 (f1ca07e700ef) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I0716 01:32:50.972527 26940 hierarchical.cpp:1537] No allocations performed
> I0716 01:32:50.972671 26940 hierarchical.cpp:1632] No inverse offers to send out!
> I0716 01:32:50.972820 26940 hierarchical.cpp:1195] Performed allocation for agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 in 437908ns
> W0716 01:32:50.973783 26950 validation.cpp:650] Executor default 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.
> W0716 01:32:50.973839 26950 validation.cpp:662] Executor default for task 1 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
> I0716 01:32:50.974295 26950 master.cpp:7565] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 (f1ca07e700ef)
> I0716 01:32:50.974551 26950 master.cpp:3957] Launching task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:50.975044 26940 slave.cpp:1569] Got assigned task 1 for framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:50.975647 26940 slave.cpp:1688] Launching task 1 for framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:50.976299 26940 paths.cpp:528] Trying to chown '/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/slaves/2949f69e-5d82-48a7-80da-ba654dac4ed1-S0/frameworks/2949f69e-5d82-48a7-80da-ba654dac4ed1-0000/executors/default/runs/b9ec9438-ec55-4667-96ea-62e63e624cf8' to user 'mesos'
> I0716 01:32:50.991979 26940 slave.cpp:5748] Launching executor default of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 with resources in work directory '/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/slaves/2949f69e-5d82-48a7-80da-ba654dac4ed1-S0/frameworks/2949f69e-5d82-48a7-80da-ba654dac4ed1-0000/executors/default/runs/b9ec9438-ec55-4667-96ea-62e63e624cf8'
> I0716 01:32:50.995538 26940 exec.cpp:161] Version: 1.1.0
> I0716 01:32:50.996342 26940 slave.cpp:1914] Queuing task '1' for executor 'default' of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:50.996474 26952 exec.cpp:211] Executor started at: executor(147)@172.17.0.8:44669 with pid 26921
> I0716 01:32:50.996603 26940 slave.cpp:922] Successfully attached file '/tmp/ContentType_MasterAPITest_GetTasks_0_nF2pJL/slaves/2949f69e-5d82-48a7-80da-ba654dac4ed1-S0/frameworks/2949f69e-5d82-48a7-80da-ba654dac4ed1-0000/executors/default/runs/b9ec9438-ec55-4667-96ea-62e63e624cf8'
> I0716 01:32:50.996870 26940 slave.cpp:2902] Got registration for executor 'default' of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 from executor(147)@172.17.0.8:44669
> I0716 01:32:50.997639 26952 exec.cpp:236] Executor registered on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0
> I0716 01:32:50.997742 26952 exec.cpp:248] Executor::registered took 84319ns
> I0716 01:32:50.997860 26940 slave.cpp:2079] Sending queued task '1' to executor 'default' of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 at executor(147)@172.17.0.8:44669
> I0716 01:32:50.998267 26940 exec.cpp:323] Executor asked to run task '1'
> I0716 01:32:50.998633 26940 exec.cpp:332] Executor::launchTask took 244810ns
> I0716 01:32:50.998847 26940 exec.cpp:549] Executor sending status update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:50.999171 26940 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 from executor(147)@172.17.0.8:44669
> I0716 01:32:51.000075 26940 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.000264 26940 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.000880 26940 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 to the agent
> I0716 01:32:51.001377 26940 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 to master@172.17.0.8:44669
> I0716 01:32:51.001960 26945 master.cpp:5273] Status update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 from agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.002070 26945 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.002312 26945 master.cpp:6959] Updating the state of task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0716 01:32:51.002723 26941 sched.cpp:1025] Scheduler::statusUpdate took 156806ns
> I0716 01:32:51.003517 26941 master.cpp:4388] Processing ACKNOWLEDGE call 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887 for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669 on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0
> I0716 01:32:51.007225 26950 process.cpp:3354] Handling HTTP event for process 'master' with path: '/master/api/v1'
> I0716 01:32:51.008761 26950 http.cpp:381] HTTP POST for /master/api/v1 from 172.17.0.8:40837
> I0716 01:32:51.008914 26950 http.cpp:484] Processing call GET_TASKS
> I0716 01:32:51.013517 26939 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 46.510882ms
> I0716 01:32:51.013581 26939 replica.cpp:712] Persisted action at 4
> I0716 01:32:51.014714 26951 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
> I0716 01:32:51.016996 26949 exec.cpp:549] Executor sending status update TASK_FINISHED (UUID: f78d241c-6845-4b08-b16d-9156d226bc3d) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.017482 26940 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.017599 26940 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 to executor(147)@172.17.0.8:44669
> I0716 01:32:51.017900 26945 exec.cpp:372] Executor received status update acknowledgement 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887 for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.018393 26941 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.018950 26940 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: f78d241c-6845-4b08-b16d-9156d226bc3d) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 from executor(147)@172.17.0.8:44669
> I0716 01:32:51.019373 26940 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 97f0a1e3-0d3f-4a91-b9c7-04e7f3560887) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.019595 26940 slave.cpp:6088] Terminating task 1
> I0716 01:32:51.020350 26949 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: f78d241c-6845-4b08-b16d-9156d226bc3d) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.020614 26949 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: f78d241c-6845-4b08-b16d-9156d226bc3d) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 to the agent
> I0716 01:32:51.021210 26940 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: f78d241c-6845-4b08-b16d-9156d226bc3d) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 to master@172.17.0.8:44669
> I0716 01:32:51.021719 26953 master.cpp:5273] Status update TASK_FINISHED (UUID: f78d241c-6845-4b08-b16d-9156d226bc3d) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 from agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.021829 26953 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: f78d241c-6845-4b08-b16d-9156d226bc3d) for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.022313 26953 master.cpp:6959] Updating the state of task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0716 01:32:51.022878 26948 sched.cpp:1025] Scheduler::statusUpdate took 187419ns
> I0716 01:32:51.024267 26944 hierarchical.cpp:924] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 from framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.028446 26942 process.cpp:3354] Handling HTTP event for process 'master' with path: '/master/api/v1'
> I0716 01:32:51.029857 26942 http.cpp:381] HTTP POST for /master/api/v1 from 172.17.0.8:40838
> I0716 01:32:51.029990 26942 http.cpp:484] Processing call GET_TASKS
> ../../src/tests/api_tests.cpp:690: Failure
> Value of: v1Response.get().get_tasks().tasks().size()
> Actual: 1
> Expected: 0
> I0716 01:32:51.036751 26948 master.cpp:4388] Processing ACKNOWLEDGE call f78d241c-6845-4b08-b16d-9156d226bc3d for task 1 of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669 on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0
> I0716 01:32:51.038859 26948 master.cpp:7025] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.039563 26948 master.cpp:1410] Framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669 disconnected
> I0716 01:32:51.039683 26948 master.cpp:2851] Disconnecting framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:51.039808 26948 master.cpp:2875] Deactivating framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:51.040135 26941 hierarchical.cpp:382] Deactivated framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.040253 26948 master.cpp:1423] Giving framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669 0ns to failover
> I0716 01:32:51.040637 26940 slave.cpp:841] Agent terminating
> I0716 01:32:51.040760 26940 slave.cpp:2292] Asked to shut down framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 by @0.0.0.0:0
> I0716 01:32:51.040865 26940 slave.cpp:2317] Shutting down framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.040992 26940 slave.cpp:4481] Shutting down executor 'default' of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 at executor(147)@172.17.0.8:44669
> I0716 01:32:51.041618 26947 master.cpp:1371] Agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef) disconnected
> I0716 01:32:51.041784 26947 master.cpp:2910] Disconnecting agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.042137 26947 master.cpp:2929] Deactivating agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.044621 26947 master.cpp:1390] Removing framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669 from disconnected agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef) because the framework is not checkpointing
> I0716 01:32:51.044756 26945 hierarchical.cpp:571] Agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 deactivated
> I0716 01:32:51.044912 26947 master.cpp:6574] Removing framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669 from agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.045184 26947 master.cpp:7054] Removing executor 'default' with resources of framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 on agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0 at slave(443)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.045604 26947 master.cpp:5687] Framework failover timeout, removing framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:51.045850 26947 master.cpp:6422] Removing framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000 (default) at scheduler-103a824e-21cd-4dfb-9f8d-55b43d1b57dd@172.17.0.8:44669
> I0716 01:32:51.046778 26953 hierarchical.cpp:333] Removed framework 2949f69e-5d82-48a7-80da-ba654dac4ed1-0000
> I0716 01:32:51.054568 26921 master.cpp:1218] Master terminating
> I0716 01:32:51.054965 26945 hierarchical.cpp:510] Removed agent 2949f69e-5d82-48a7-80da-ba654dac4ed1-S0
> I0716 01:32:51.063762 26951 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 48.811786ms
> I0716 01:32:51.063956 26951 leveldb.cpp:399] Deleting ~2 keys from leveldb took 83527ns
> I0716 01:32:51.064023 26951 replica.cpp:712] Persisted action at 4
> I0716 01:32:51.064111 26951 replica.cpp:697] Replica learned TRUNCATE action at position 4
> [ FAILED ] ContentType/MasterAPITest.GetTasks/0, where GetParam() = application/x-protobuf (654 ms)
> {code}
> A success run
> {code}
> [ RUN ] ContentType/MasterAPITest.GetTasks/1
> I0716 01:32:51.098104 26921 cluster.cpp:155] Creating default 'local' authorizer
> I0716 01:32:51.264447 26921 leveldb.cpp:174] Opened db in 164.735275ms
> I0716 01:32:51.331194 26921 leveldb.cpp:181] Compacted db in 66.341913ms
> I0716 01:32:51.331606 26921 leveldb.cpp:196] Created db iterator in 70027ns
> I0716 01:32:51.331733 26921 leveldb.cpp:202] Seeked to beginning of db in 16516ns
> I0716 01:32:51.331825 26921 leveldb.cpp:271] Iterated through 0 keys in the db in 12801ns
> I0716 01:32:51.331959 26921 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0716 01:32:51.333200 26949 recover.cpp:451] Starting replica recovery
> I0716 01:32:51.333560 26949 recover.cpp:477] Replica is in EMPTY status
> I0716 01:32:51.335213 26949 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (16006)@172.17.0.8:44669
> I0716 01:32:51.335657 26949 recover.cpp:197] Received a recover response from a replica in EMPTY status
> I0716 01:32:51.336303 26949 recover.cpp:568] Updating replica status to STARTING
> I0716 01:32:51.343477 26952 master.cpp:382] Master 1f4b1971-a098-4ced-be7a-b26d4c06983c (f1ca07e700ef) started on 172.17.0.8:44669
> I0716 01:32:51.343580 26952 master.cpp:384] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/PD9O7I/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-1.1.0/_inst/share/mesos/webui" --work_dir="/tmp/PD9O7I/master" --zk_session_timeout="10secs"
> I0716 01:32:51.344064 26952 master.cpp:434] Master only allowing authenticated frameworks to register
> I0716 01:32:51.344149 26952 master.cpp:448] Master only allowing authenticated agents to register
> I0716 01:32:51.344214 26952 master.cpp:461] Master only allowing authenticated HTTP frameworks to register
> I0716 01:32:51.344279 26952 credentials.hpp:37] Loading credentials for authentication from '/tmp/PD9O7I/credentials'
> I0716 01:32:51.344698 26952 master.cpp:506] Using default 'crammd5' authenticator
> I0716 01:32:51.344935 26952 master.cpp:578] Using default 'basic' HTTP authenticator
> I0716 01:32:51.345160 26952 master.cpp:658] Using default 'basic' HTTP framework authenticator
> I0716 01:32:51.345499 26952 master.cpp:705] Authorization enabled
> I0716 01:32:51.346536 26943 hierarchical.cpp:151] Initialized hierarchical allocator process
> I0716 01:32:51.346608 26953 whitelist_watcher.cpp:77] No whitelist given
> I0716 01:32:51.351202 26952 master.cpp:1973] The newly elected leader is master@172.17.0.8:44669 with id 1f4b1971-a098-4ced-be7a-b26d4c06983c
> I0716 01:32:51.351379 26952 master.cpp:1986] Elected as the leading master!
> I0716 01:32:51.351469 26952 master.cpp:1673] Recovering from registrar
> I0716 01:32:51.351775 26952 registrar.cpp:332] Recovering registrar
> I0716 01:32:51.386600 26949 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 50.035837ms
> I0716 01:32:51.386680 26949 replica.cpp:320] Persisted replica status to STARTING
> I0716 01:32:51.386975 26949 recover.cpp:477] Replica is in STARTING status
> I0716 01:32:51.389536 26950 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (16010)@172.17.0.8:44669
> I0716 01:32:51.390117 26941 recover.cpp:197] Received a recover response from a replica in STARTING status
> I0716 01:32:51.390676 26941 recover.cpp:568] Updating replica status to VOTING
> I0716 01:32:51.431485 26941 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 40.608222ms
> I0716 01:32:51.431571 26941 replica.cpp:320] Persisted replica status to VOTING
> I0716 01:32:51.431807 26941 recover.cpp:582] Successfully joined the Paxos group
> I0716 01:32:51.432003 26941 recover.cpp:466] Recover process terminated
> I0716 01:32:51.432876 26947 log.cpp:553] Attempting to start the writer
> I0716 01:32:51.434335 26951 replica.cpp:493] Replica received implicit promise request from (16011)@172.17.0.8:44669 with proposal 1
> I0716 01:32:51.474196 26951 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 39.855836ms
> I0716 01:32:51.474290 26951 replica.cpp:342] Persisted promised to 1
> I0716 01:32:51.475812 26951 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I0716 01:32:51.477309 26945 replica.cpp:388] Replica received explicit promise request from (16012)@172.17.0.8:44669 for position 0 with proposal 2
> I0716 01:32:51.515359 26945 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 38.033709ms
> I0716 01:32:51.515458 26945 replica.cpp:712] Persisted action at 0
> I0716 01:32:51.517084 26944 replica.cpp:537] Replica received write request for position 0 from (16013)@172.17.0.8:44669
> I0716 01:32:51.517196 26944 leveldb.cpp:436] Reading position from leveldb took 56620ns
> I0716 01:32:51.558805 26944 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 41.493767ms
> I0716 01:32:51.558882 26944 replica.cpp:712] Persisted action at 0
> I0716 01:32:51.559965 26951 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
> I0716 01:32:51.584096 26951 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 23.543826ms
> I0716 01:32:51.584297 26951 replica.cpp:712] Persisted action at 0
> I0716 01:32:51.584491 26951 replica.cpp:697] Replica learned NOP action at position 0
> I0716 01:32:51.585485 26951 log.cpp:569] Writer started with ending position 0
> I0716 01:32:51.587004 26954 leveldb.cpp:436] Reading position from leveldb took 98945ns
> I0716 01:32:51.588127 26950 registrar.cpp:365] Successfully fetched the registry (0B) in 236.073984ms
> I0716 01:32:51.588337 26950 registrar.cpp:464] Applied 1 operations in 131037ns; attempting to update the 'registry'
> I0716 01:32:51.589709 26939 log.cpp:577] Attempting to append 168 bytes to the log
> I0716 01:32:51.589882 26948 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I0716 01:32:51.590795 26942 replica.cpp:537] Replica received write request for position 1 from (16014)@172.17.0.8:44669
> I0716 01:32:51.610009 26942 leveldb.cpp:341] Persisting action (187 bytes) to leveldb took 19.202954ms
> I0716 01:32:51.610101 26942 replica.cpp:712] Persisted action at 1
> I0716 01:32:51.611517 26942 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
> I0716 01:32:51.635295 26942 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 23.774987ms
> I0716 01:32:51.635390 26942 replica.cpp:712] Persisted action at 1
> I0716 01:32:51.635447 26942 replica.cpp:697] Replica learned APPEND action at position 1
> I0716 01:32:51.637537 26949 registrar.cpp:509] Successfully updated the 'registry' in 48.957952ms
> I0716 01:32:51.637552 26943 log.cpp:596] Attempting to truncate the log to 1
> I0716 01:32:51.638185 26949 registrar.cpp:395] Successfully recovered registrar
> I0716 01:32:51.638221 26943 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I0716 01:32:51.638700 26944 master.cpp:1781] Recovered 0 agents from the Registry (129B) ; allowing 10mins for agents to re-register
> I0716 01:32:51.638813 26949 hierarchical.cpp:178] Skipping recovery of hierarchical allocator: nothing to recover
> I0716 01:32:51.639576 26949 replica.cpp:537] Replica received write request for position 2 from (16015)@172.17.0.8:44669
> I0716 01:32:51.668931 26949 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 29.277183ms
> I0716 01:32:51.669129 26949 replica.cpp:712] Persisted action at 2
> I0716 01:32:51.670639 26946 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
> I0716 01:32:51.699235 26946 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 28.588884ms
> I0716 01:32:51.699571 26946 leveldb.cpp:399] Deleting ~1 keys from leveldb took 109168ns
> I0716 01:32:51.699676 26946 replica.cpp:712] Persisted action at 2
> I0716 01:32:51.699805 26946 replica.cpp:697] Replica learned TRUNCATE action at position 2
> I0716 01:32:51.711055 26921 cluster.cpp:432] Creating default 'local' authorizer
> I0716 01:32:51.721844 26945 slave.cpp:205] Agent started on 444)@172.17.0.8:44669
> I0716 01:32:51.721902 26945 slave.cpp:206] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --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/ContentType_MasterAPITest_GetTasks_1_B16J9J/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --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" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-1.1.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;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J"
> I0716 01:32:51.723016 26945 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/credential'
> I0716 01:32:51.723567 26945 slave.cpp:343] Agent using credential for: test-principal
> I0716 01:32:51.723621 26945 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/http_credentials'
> I0716 01:32:51.724102 26945 slave.cpp:395] Using default 'basic' HTTP authenticator
> I0716 01:32:51.724607 26945 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0716 01:32:51.725282 26945 resources.cpp:572] Parsing resources as JSON failed: cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0716 01:32:51.726402 26945 slave.cpp:594] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 01:32:51.726598 26945 slave.cpp:602] Agent attributes: [ ]
> I0716 01:32:51.726624 26945 slave.cpp:607] Agent hostname: f1ca07e700ef
> I0716 01:32:51.729462 26952 state.cpp:57] Recovering state from '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/meta'
> I0716 01:32:51.730470 26953 status_update_manager.cpp:200] Recovering status update manager
> I0716 01:32:51.730996 26942 slave.cpp:4856] Finished recovery
> I0716 01:32:51.733889 26921 sched.cpp:226] Version: 1.1.0
> I0716 01:32:51.734863 26948 sched.cpp:330] New master detected at master@172.17.0.8:44669
> I0716 01:32:51.735283 26948 sched.cpp:396] Authenticating with master master@172.17.0.8:44669
> I0716 01:32:51.735611 26948 sched.cpp:403] Using default CRAM-MD5 authenticatee
> I0716 01:32:51.736273 26948 authenticatee.cpp:121] Creating new client SASL connection
> I0716 01:32:51.737021 26948 master.cpp:6006] Authenticating scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669
> I0716 01:32:51.737483 26946 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(918)@172.17.0.8:44669
> I0716 01:32:51.738174 26948 authenticator.cpp:98] Creating new server SASL connection
> I0716 01:32:51.739084 26948 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0716 01:32:51.739521 26948 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 01:32:51.740059 26948 authenticator.cpp:204] Received SASL authentication start
> I0716 01:32:51.740506 26948 authenticator.cpp:326] Authentication requires more steps
> I0716 01:32:51.741026 26948 authenticatee.cpp:259] Received SASL authentication step
> I0716 01:32:51.741559 26948 authenticator.cpp:232] Received SASL authentication step
> I0716 01:32:51.742002 26948 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f1ca07e700ef' server FQDN: 'f1ca07e700ef' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0716 01:32:51.742313 26948 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0716 01:32:51.743170 26942 slave.cpp:5028] Querying resource estimator for oversubscribable resources
> I0716 01:32:51.743639 26948 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0716 01:32:51.744184 26948 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f1ca07e700ef' server FQDN: 'f1ca07e700ef' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0716 01:32:51.744524 26948 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0716 01:32:51.744845 26948 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0716 01:32:51.745173 26948 authenticator.cpp:318] Authentication success
> I0716 01:32:51.745687 26949 authenticatee.cpp:299] Authentication success
> I0716 01:32:51.746353 26939 sched.cpp:502] Successfully authenticated with master master@172.17.0.8:44669
> I0716 01:32:51.746675 26939 sched.cpp:820] Sending SUBSCRIBE call to master@172.17.0.8:44669
> I0716 01:32:51.747166 26939 sched.cpp:853] Will retry registration in 1.572936764secs if necessary
> I0716 01:32:51.747802 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.748358 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.748917 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.749441 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.749965 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.750463 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.751009 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.751515 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.752041 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.752570 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.753093 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.753612 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.754137 26939 master.cpp:2486] Queuing up SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 because authentication is still in progress
> I0716 01:32:51.754494 26939 master.cpp:6036] Successfully authenticated principal 'test-principal' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669
> I0716 01:32:51.754542 26947 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(918)@172.17.0.8:44669
> I0716 01:32:51.754624 26939 master.cpp:2550] Received SUBSCRIBE call for framework 'default' at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669
> I0716 01:32:51.754645 26939 master.cpp:2012] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0716 01:32:51.755347 26939 master.cpp:2626] Subscribing framework default with checkpointing disabled and capabilities [ ]
> I0716 01:32:51.755751 26942 slave.cpp:969] New master detected at master@172.17.0.8:44669
> I0716 01:32:51.755772 26940 status_update_manager.cpp:174] Pausing sending status updates
> I0716 01:32:51.756310 26942 slave.cpp:1028] Authenticating with master master@172.17.0.8:44669
> I0716 01:32:51.756665 26942 slave.cpp:1039] Using default CRAM-MD5 authenticatee
> I0716 01:32:51.756948 26948 authenticatee.cpp:121] Creating new client SASL connection
> I0716 01:32:51.756994 26942 slave.cpp:1001] Detecting new master
> I0716 01:32:51.757282 26942 slave.cpp:5042] Received oversubscribable resources from the resource estimator
> I0716 01:32:51.757871 26952 hierarchical.cpp:271] Added framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.758533 26952 hierarchical.cpp:1537] No allocations performed
> I0716 01:32:51.758572 26952 hierarchical.cpp:1632] No inverse offers to send out!
> I0716 01:32:51.758621 26943 sched.cpp:743] Framework registered with 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.758636 26952 hierarchical.cpp:1172] Performed allocation for 0 agents in 177317ns
> I0716 01:32:51.758898 26939 master.cpp:6006] Authenticating slave(444)@172.17.0.8:44669
> I0716 01:32:51.759042 26954 authenticator.cpp:414] Starting authentication session for crammd5_authenticatee(919)@172.17.0.8:44669
> I0716 01:32:51.758776 26943 sched.cpp:757] Scheduler::registered took 36064ns
> I0716 01:32:51.759495 26939 authenticator.cpp:98] Creating new server SASL connection
> I0716 01:32:51.759745 26954 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0716 01:32:51.759863 26954 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0716 01:32:51.760135 26939 authenticator.cpp:204] Received SASL authentication start
> I0716 01:32:51.760263 26939 authenticator.cpp:326] Authentication requires more steps
> I0716 01:32:51.760511 26939 authenticatee.cpp:259] Received SASL authentication step
> I0716 01:32:51.760748 26939 authenticator.cpp:232] Received SASL authentication step
> I0716 01:32:51.760790 26939 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f1ca07e700ef' server FQDN: 'f1ca07e700ef' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0716 01:32:51.760807 26939 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0716 01:32:51.760846 26939 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0716 01:32:51.760869 26939 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f1ca07e700ef' server FQDN: 'f1ca07e700ef' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0716 01:32:51.760882 26939 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0716 01:32:51.760892 26939 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0716 01:32:51.760910 26939 authenticator.cpp:318] Authentication success
> I0716 01:32:51.760990 26954 authenticatee.cpp:299] Authentication success
> I0716 01:32:51.761041 26948 master.cpp:6036] Successfully authenticated principal 'test-principal' at slave(444)@172.17.0.8:44669
> I0716 01:32:51.761131 26939 authenticator.cpp:432] Authentication session cleanup for crammd5_authenticatee(919)@172.17.0.8:44669
> I0716 01:32:51.761523 26948 slave.cpp:1123] Successfully authenticated with master master@172.17.0.8:44669
> I0716 01:32:51.761792 26948 slave.cpp:1529] Will retry registration in 2.587517ms if necessary
> I0716 01:32:51.762087 26941 master.cpp:4676] Registering agent at slave(444)@172.17.0.8:44669 (f1ca07e700ef) with id 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0
> I0716 01:32:51.762835 26939 registrar.cpp:464] Applied 1 operations in 105778ns; attempting to update the 'registry'
> I0716 01:32:51.763700 26949 log.cpp:577] Attempting to append 337 bytes to the log
> I0716 01:32:51.763993 26949 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I0716 01:32:51.766073 26949 replica.cpp:537] Replica received write request for position 3 from (16021)@172.17.0.8:44669
> I0716 01:32:51.766551 26952 slave.cpp:1529] Will retry registration in 37.839637ms if necessary
> I0716 01:32:51.766891 26952 master.cpp:4664] Ignoring register agent message from slave(444)@172.17.0.8:44669 (f1ca07e700ef) as admission is already in progress
> I0716 01:32:51.783509 26949 leveldb.cpp:341] Persisting action (356 bytes) to leveldb took 17.419693ms
> I0716 01:32:51.783599 26949 replica.cpp:712] Persisted action at 3
> I0716 01:32:51.785138 26943 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
> I0716 01:32:51.805289 26954 slave.cpp:1529] Will retry registration in 45.42709ms if necessary
> I0716 01:32:51.805660 26950 master.cpp:4664] Ignoring register agent message from slave(444)@172.17.0.8:44669 (f1ca07e700ef) as admission is already in progress
> I0716 01:32:51.826437 26943 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 41.233028ms
> I0716 01:32:51.826530 26943 replica.cpp:712] Persisted action at 3
> I0716 01:32:51.826565 26943 replica.cpp:697] Replica learned APPEND action at position 3
> I0716 01:32:51.830235 26943 registrar.cpp:509] Successfully updated the 'registry' in 67.3152ms
> I0716 01:32:51.830464 26947 log.cpp:596] Attempting to truncate the log to 3
> I0716 01:32:51.830680 26947 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I0716 01:32:51.832795 26947 replica.cpp:537] Replica received write request for position 4 from (16022)@172.17.0.8:44669
> I0716 01:32:51.833925 26943 master.cpp:4745] Registered agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0716 01:32:51.834278 26943 hierarchical.cpp:478] Added agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 (f1ca07e700ef) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0716 01:32:51.834508 26941 slave.cpp:1169] Registered with master master@172.17.0.8:44669; given agent ID 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0
> I0716 01:32:51.834538 26941 fetcher.cpp:86] Clearing fetcher cache
> I0716 01:32:51.834947 26941 slave.cpp:1192] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/meta/slaves/1f4b1971-a098-4ced-be7a-b26d4c06983c-S0/slave.info'
> I0716 01:32:51.835355 26941 slave.cpp:1229] Forwarding total oversubscribed resources
> I0716 01:32:51.836475 26941 slave.cpp:3760] Received ping from slave-observer(412)@172.17.0.8:44669
> I0716 01:32:51.836596 26941 status_update_manager.cpp:181] Resuming sending status updates
> I0716 01:32:51.836719 26941 master.cpp:5128] Received update of agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef) with total oversubscribed resources
> I0716 01:32:51.837754 26943 hierarchical.cpp:1632] No inverse offers to send out!
> I0716 01:32:51.837838 26943 hierarchical.cpp:1195] Performed allocation for agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 in 3.522957ms
> I0716 01:32:51.837980 26943 hierarchical.cpp:542] Agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 (f1ca07e700ef) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I0716 01:32:51.838125 26943 hierarchical.cpp:1537] No allocations performed
> I0716 01:32:51.838160 26943 hierarchical.cpp:1632] No inverse offers to send out!
> I0716 01:32:51.838204 26943 hierarchical.cpp:1195] Performed allocation for agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 in 176669ns
> I0716 01:32:51.838714 26943 master.cpp:5835] Sending 1 offers to framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (default) at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669
> I0716 01:32:51.839205 26943 sched.cpp:917] Scheduler::resourceOffers took 123086ns
> I0716 01:32:51.843250 26944 master.cpp:3468] Processing ACCEPT call for offers: [ 1f4b1971-a098-4ced-be7a-b26d4c06983c-O0 ] on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef) for framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (default) at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669
> I0716 01:32:51.843369 26944 master.cpp:3106] Authorizing framework principal 'test-principal' to launch task 1
> W0716 01:32:51.848954 26944 validation.cpp:650] Executor default 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.
> W0716 01:32:51.849031 26944 validation.cpp:662] Executor default for task 1 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
> I0716 01:32:51.851603 26944 master.cpp:7565] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 (f1ca07e700ef)
> I0716 01:32:51.851825 26944 master.cpp:3957] Launching task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (default) at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.852354 26944 slave.cpp:1569] Got assigned task 1 for framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.854076 26944 slave.cpp:1688] Launching task 1 for framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.868922 26944 paths.cpp:528] Trying to chown '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/slaves/1f4b1971-a098-4ced-be7a-b26d4c06983c-S0/frameworks/1f4b1971-a098-4ced-be7a-b26d4c06983c-0000/executors/default/runs/dfe27d79-8e51-4553-a3fd-80f28f0729ac' to user 'mesos'
> I0716 01:32:51.877212 26947 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 44.394669ms
> I0716 01:32:51.877305 26947 replica.cpp:712] Persisted action at 4
> I0716 01:32:51.879119 26947 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
> I0716 01:32:51.907600 26944 slave.cpp:5748] Launching executor default of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 with resources in work directory '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/slaves/1f4b1971-a098-4ced-be7a-b26d4c06983c-S0/frameworks/1f4b1971-a098-4ced-be7a-b26d4c06983c-0000/executors/default/runs/dfe27d79-8e51-4553-a3fd-80f28f0729ac'
> I0716 01:32:51.911151 26944 exec.cpp:161] Version: 1.1.0
> I0716 01:32:51.911532 26947 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 32.396128ms
> I0716 01:32:51.911641 26947 leveldb.cpp:399] Deleting ~2 keys from leveldb took 78972ns
> I0716 01:32:51.911666 26947 replica.cpp:712] Persisted action at 4
> I0716 01:32:51.911700 26947 replica.cpp:697] Replica learned TRUNCATE action at position 4
> I0716 01:32:51.911787 26949 exec.cpp:211] Executor started at: executor(148)@172.17.0.8:44669 with pid 26921
> I0716 01:32:51.912528 26944 slave.cpp:1914] Queuing task '1' for executor 'default' of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.912909 26944 slave.cpp:922] Successfully attached file '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/slaves/1f4b1971-a098-4ced-be7a-b26d4c06983c-S0/frameworks/1f4b1971-a098-4ced-be7a-b26d4c06983c-0000/executors/default/runs/dfe27d79-8e51-4553-a3fd-80f28f0729ac'
> I0716 01:32:51.913069 26944 slave.cpp:2902] Got registration for executor 'default' of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 from executor(148)@172.17.0.8:44669
> I0716 01:32:51.914299 26944 slave.cpp:2079] Sending queued task '1' to executor 'default' of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 at executor(148)@172.17.0.8:44669
> I0716 01:32:51.914625 26951 exec.cpp:236] Executor registered on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0
> I0716 01:32:51.914728 26951 exec.cpp:248] Executor::registered took 83014ns
> I0716 01:32:51.914926 26951 exec.cpp:323] Executor asked to run task '1'
> I0716 01:32:51.915531 26951 exec.cpp:332] Executor::launchTask took 593333ns
> I0716 01:32:51.915666 26951 exec.cpp:549] Executor sending status update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.916096 26951 slave.cpp:3285] Handling status update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 from executor(148)@172.17.0.8:44669
> I0716 01:32:51.917110 26951 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.917264 26951 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.918076 26951 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 to the agent
> I0716 01:32:51.918742 26951 slave.cpp:3678] Forwarding the update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 to master@172.17.0.8:44669
> I0716 01:32:51.919379 26940 master.cpp:5273] Status update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 from agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.919546 26940 master.cpp:5321] Forwarding status update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.919955 26940 master.cpp:6959] Updating the state of task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0716 01:32:51.920382 26953 sched.cpp:1025] Scheduler::statusUpdate took 157615ns
> I0716 01:32:51.920500 26951 slave.cpp:3572] Status update manager successfully handled status update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.921047 26951 slave.cpp:3588] Sending acknowledgement for status update TASK_RUNNING (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 to executor(148)@172.17.0.8:44669
> I0716 01:32:51.921084 26942 master.cpp:4388] Processing ACKNOWLEDGE call 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0 for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (default) at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0
> I0716 01:32:51.921303 26951 exec.cpp:372] Executor received status update acknowledgement 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0 for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.921558 26951 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.922010 26942 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 0c8c5ace-ba3e-46e4-ab46-0ef515474cb0) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.923655 26943 process.cpp:3354] Handling HTTP event for process 'master' with path: '/master/api/v1'
> I0716 01:32:51.924752 26953 http.cpp:381] HTTP POST for /master/api/v1 from 172.17.0.8:40839
> I0716 01:32:51.925014 26953 http.cpp:484] Processing call GET_TASKS
> I0716 01:32:51.931498 26954 exec.cpp:549] Executor sending status update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.931794 26954 slave.cpp:3285] Handling status update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 from executor(148)@172.17.0.8:44669
> I0716 01:32:51.932232 26954 slave.cpp:6088] Terminating task 1
> I0716 01:32:51.932971 26954 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.933166 26954 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 to the agent
> I0716 01:32:51.933600 26954 slave.cpp:3678] Forwarding the update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 to master@172.17.0.8:44669
> I0716 01:32:51.933760 26954 slave.cpp:3572] Status update manager successfully handled status update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.933806 26954 slave.cpp:3588] Sending acknowledgement for status update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 to executor(148)@172.17.0.8:44669
> I0716 01:32:51.934041 26954 master.cpp:5273] Status update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 from agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.934087 26954 master.cpp:5321] Forwarding status update TASK_FINISHED (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.934242 26954 master.cpp:6959] Updating the state of task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> I0716 01:32:51.934748 26954 exec.cpp:372] Executor received status update acknowledgement 486d5b5d-1684-4256-9f8f-22ae671f5cbe for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.935006 26954 sched.cpp:1025] Scheduler::statusUpdate took 96207ns
> I0716 01:32:51.935586 26941 master.cpp:4388] Processing ACKNOWLEDGE call 486d5b5d-1684-4256-9f8f-22ae671f5cbe for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (default) at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669 on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0
> I0716 01:32:51.935650 26941 master.cpp:7025] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.936885 26954 hierarchical.cpp:924] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 from framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.936180 26941 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.937144 26941 status_update_manager.cpp:528] Cleaning up status update stream for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.937614 26946 slave.cpp:2671] Status update manager successfully handled status update acknowledgement (UUID: 486d5b5d-1684-4256-9f8f-22ae671f5cbe) for task 1 of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.937662 26946 slave.cpp:6129] Completing task 1
> I0716 01:32:51.940557 26940 process.cpp:3354] Handling HTTP event for process 'master' with path: '/master/api/v1'
> I0716 01:32:51.941504 26939 http.cpp:381] HTTP POST for /master/api/v1 from 172.17.0.8:40840
> I0716 01:32:51.941634 26939 http.cpp:484] Processing call GET_TASKS
> I0716 01:32:51.948716 26921 sched.cpp:1987] Asked to stop the driver
> I0716 01:32:51.948840 26949 sched.cpp:1187] Stopping framework '1f4b1971-a098-4ced-be7a-b26d4c06983c-0000'
> I0716 01:32:51.949188 26949 master.cpp:6410] Processing TEARDOWN call for framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (default) at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669
> I0716 01:32:51.949229 26949 master.cpp:6422] Removing framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 (default) at scheduler-e402c32b-6841-4c1d-87a0-9cc0f74a3417@172.17.0.8:44669
> I0716 01:32:51.949489 26949 master.cpp:7054] Removing executor 'default' with resources of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.949704 26951 hierarchical.cpp:382] Deactivated framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.949873 26948 slave.cpp:2292] Asked to shut down framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 by master@172.17.0.8:44669
> I0716 01:32:51.950013 26948 slave.cpp:2317] Shutting down framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.950204 26948 slave.cpp:4481] Shutting down executor 'default' of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 at executor(148)@172.17.0.8:44669
> I0716 01:32:51.950700 26948 hierarchical.cpp:333] Removed framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.950405 26951 exec.cpp:413] Executor asked to shutdown
> I0716 01:32:51.950829 26951 exec.cpp:428] Executor::shutdown took 27614ns
> I0716 01:32:51.951040 26951 slave.cpp:3806] executor(148)@172.17.0.8:44669 exited
> I0716 01:32:51.951364 26951 slave.cpp:4163] Executor 'default' of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 exited with status 0
> I0716 01:32:51.951730 26951 slave.cpp:4267] Cleaning up executor 'default' of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 at executor(148)@172.17.0.8:44669
> W0716 01:32:51.951848 26940 master.cpp:5369] Ignoring unknown exited executor 'default' of framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000 on agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.953620 26953 gc.cpp:55] Scheduling '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/slaves/1f4b1971-a098-4ced-be7a-b26d4c06983c-S0/frameworks/1f4b1971-a098-4ced-be7a-b26d4c06983c-0000/executors/default/runs/dfe27d79-8e51-4553-a3fd-80f28f0729ac' for gc 6.99998897096days in the future
> I0716 01:32:51.953934 26951 slave.cpp:4355] Cleaning up framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.953948 26939 gc.cpp:55] Scheduling '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/slaves/1f4b1971-a098-4ced-be7a-b26d4c06983c-S0/frameworks/1f4b1971-a098-4ced-be7a-b26d4c06983c-0000/executors/default' for gc 6.99998895978963days in the future
> I0716 01:32:51.954439 26950 status_update_manager.cpp:282] Closing status update streams for framework 1f4b1971-a098-4ced-be7a-b26d4c06983c-0000
> I0716 01:32:51.954684 26951 slave.cpp:841] Agent terminating
> I0716 01:32:51.954877 26954 gc.cpp:55] Scheduling '/tmp/ContentType_MasterAPITest_GetTasks_1_B16J9J/slaves/1f4b1971-a098-4ced-be7a-b26d4c06983c-S0/frameworks/1f4b1971-a098-4ced-be7a-b26d4c06983c-0000' for gc 6.99998895301037days in the future
> I0716 01:32:51.955643 26951 master.cpp:1371] Agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef) disconnected
> I0716 01:32:51.956079 26951 master.cpp:2910] Disconnecting agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.956404 26951 master.cpp:2929] Deactivating agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 at slave(444)@172.17.0.8:44669 (f1ca07e700ef)
> I0716 01:32:51.956712 26946 hierarchical.cpp:571] Agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0 deactivated
> I0716 01:32:51.959475 26921 master.cpp:1218] Master terminating
> I0716 01:32:51.959877 26940 hierarchical.cpp:510] Removed agent 1f4b1971-a098-4ced-be7a-b26d4c06983c-S0
> [ OK ] ContentType/MasterAPITest.GetTasks/1 (882 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)