[
https://issues.apache.org/jira/browse/MESOS-9079?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16631771#comment-16631771
]
Benno Evers commented on MESOS-9079:
------------------------------------
Observed the same for the `/1` variant: (Run 4504)
{noformat}
[ RUN ] bool/MasterTestPrePostReservationRefinement.LaunchGroup/1
I0927 16:41:07.341975 2560127808 cluster.cpp:173] Creating default 'local'
authorizer
I0927 16:41:07.343353 96841728 master.cpp:413] Master
d8823df0-8625-4d84-9980-2c64d226d6f8 (Jenkinss-Mac-mini.local) started on
10.0.49.4:56698
I0927 16:41:07.343381 96841728 master.cpp:416] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1000secs" --allocator="hierarchical"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authentication_v0_timeout="15secs"
--authenticators="crammd5" --authorizers="local"
--credentials="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/BKYcbZ/credentials"
--filter_gpu_resources="true" --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"
--max_unreachable_tasks_per_framework="1000" --memory_profiling="false"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--require_agent_domain="false" --role_sorter="drf" --root_submissions="true"
--version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/BKYcbZ/master"
--zk_session_timeout="10secs"
I0927 16:41:07.343574 96841728 master.cpp:465] Master only allowing
authenticated frameworks to register
I0927 16:41:07.343582 96841728 master.cpp:471] Master only allowing
authenticated agents to register
I0927 16:41:07.343588 96841728 master.cpp:477] Master only allowing
authenticated HTTP frameworks to register
I0927 16:41:07.343603 96841728 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/BKYcbZ/credentials'
I0927 16:41:07.343760 96841728 master.cpp:521] Using default 'crammd5'
authenticator
I0927 16:41:07.343873 96841728 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0927 16:41:07.343940 96841728 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0927 16:41:07.344009 96841728 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0927 16:41:07.344054 96841728 master.cpp:602] Authorization enabled
I0927 16:41:07.344269 95232000 whitelist_watcher.cpp:77] No whitelist given
I0927 16:41:07.344270 93085696 hierarchical.cpp:182] Initialized hierarchical
allocator process
I0927 16:41:07.345897 95232000 master.cpp:2083] Elected as the leading master!
I0927 16:41:07.345923 95232000 master.cpp:1638] Recovering from registrar
I0927 16:41:07.345969 93085696 registrar.cpp:339] Recovering registrar
I0927 16:41:07.346166 93085696 registrar.cpp:383] Successfully fetched the
registry (0B) in 175872ns
I0927 16:41:07.346269 93085696 registrar.cpp:487] Applied 1 operations in
23524ns; attempting to update the registry
I0927 16:41:07.346478 93085696 registrar.cpp:544] Successfully updated the
registry in 183040ns
I0927 16:41:07.346536 93085696 registrar.cpp:416] Successfully recovered
registrar
I0927 16:41:07.346678 93622272 master.cpp:1752] Recovered 0 agents from the
registry (155B); allowing 10mins for agents to reregister
I0927 16:41:07.346702 94695424 hierarchical.cpp:220] Skipping recovery of
hierarchical allocator: nothing to recover
W0927 16:41:07.349237 2560127808 process.cpp:2810] Attempted to spawn already
running process [email protected]:56698
I0927 16:41:07.349918 2560127808 containerizer.cpp:305] Using isolation {
environment_secret, filesystem/posix, posix/mem, posix/cpu }
I0927 16:41:07.350147 2560127808 provisioner.cpp:298] Using default backend
'copy'
I0927 16:41:07.351030 2560127808 cluster.cpp:485] Creating default 'local'
authorizer
I0927 16:41:07.352041 93622272 slave.cpp:267] Mesos agent started on
(905)@10.0.49.4:56698
I0927 16:41:07.352071 93622272 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/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="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1"
--gc_non_executor_container_sandboxes="false" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/jwt_secret_key"
--launcher="posix"
--launcher_dir="/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"
--logbufsecs="0" --logging_level="INFO"
--max_completed_executors_per_framework="150" --memory_profiling="false"
--network_cni_metrics="true" --oversubscribed_resources_interval="15secs"
--port="5051" --qos_correction_interval_min="0ns" --quiet="false"
--reconfiguration_policy="equal" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--runtime_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--version="false"
--work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP"
--zk_session_timeout="10secs"
I0927 16:41:07.352358 93622272 credentials.hpp:86] Loading credential for
authentication from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/credential'
I0927 16:41:07.352484 93622272 slave.cpp:300] Agent using credential for:
test-principal
I0927 16:41:07.352502 93622272 credentials.hpp:37] Loading credentials for
authentication from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/http_credentials'
I0927 16:41:07.352682 93622272 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I0927 16:41:07.352705 2560127808 scheduler.cpp:189] Version: 1.8.0
I0927 16:41:07.352741 93622272 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I0927 16:41:07.352836 93622272 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0927 16:41:07.352919 93622272 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I0927 16:41:07.353018 94158848 scheduler.cpp:355] Using default 'basic' HTTP
authenticatee
I0927 16:41:07.353144 93622272 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0927 16:41:07.353195 93622272 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0927 16:41:07.353287 95768576 scheduler.cpp:538] New master detected at
[email protected]:56698
I0927 16:41:07.353308 95768576 scheduler.cpp:547] Waiting for 0ns before
initiating a re-(connection) attempt with the master
I0927 16:41:07.353365 93622272 disk_profile_adaptor.cpp:80] Creating default
disk profile adaptor module
I0927 16:41:07.353750 93622272 slave.cpp:615] Agent resources:
[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0927 16:41:07.353925 93622272 slave.cpp:623] Agent attributes: [ ]
I0927 16:41:07.353940 93622272 slave.cpp:632] Agent hostname:
Jenkinss-Mac-mini.local
I0927 16:41:07.354004 94695424 task_status_update_manager.cpp:181] Pausing
sending task status updates
I0927 16:41:07.354363 96841728 scheduler.cpp:429] Connected with the master at
http://10.0.49.4:56698/master/api/v1/scheduler
I0927 16:41:07.354676 93085696 state.cpp:66] Recovering state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/meta'
I0927 16:41:07.354837 96841728 slave.cpp:6909] Finished recovering checkpointed
state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/meta',
beginning agent recovery
I0927 16:41:07.354928 93622272 task_status_update_manager.cpp:207] Recovering
task status update manager
I0927 16:41:07.355085 94695424 containerizer.cpp:727] Recovering Mesos
containers
I0927 16:41:07.355108 95232000 scheduler.cpp:248] Sending SUBSCRIBE call to
http://10.0.49.4:56698/master/api/v1/scheduler
I0927 16:41:07.355226 94695424 containerizer.cpp:1053] Recovering isolators
I0927 16:41:07.355531 94695424 containerizer.cpp:1092] Recovering provisioner
I0927 16:41:07.355823 96305152 provisioner.cpp:494] Provisioner recovery
complete
I0927 16:41:07.355931 95232000 process.cpp:3569] Handling HTTP event for
process 'master' with path: '/master/api/v1/scheduler'
I0927 16:41:07.356274 93622272 composing.cpp:339] Finished recovering all
containerizers
I0927 16:41:07.356331 93085696 slave.cpp:7138] Recovering executors
I0927 16:41:07.356386 93085696 slave.cpp:7291] Finished recovery
I0927 16:41:07.356607 94158848 http.cpp:1177] HTTP POST for
/master/api/v1/scheduler from 10.0.49.4:59571
I0927 16:41:07.356773 94158848 master.cpp:2502] Received subscription request
for HTTP framework 'default'
I0927 16:41:07.356812 94158848 master.cpp:2155] Authorizing framework principal
'test-principal' to receive offers for roles '{ default-role }'
I0927 16:41:07.357101 94158848 master.cpp:2637] Subscribing framework 'default'
with checkpointing disabled and capabilities [ MULTI_ROLE ]
I0927 16:41:07.357175 93085696 slave.cpp:1254] New master detected at
[email protected]:56698
I0927 16:41:07.357223 93085696 slave.cpp:1319] Detecting new master
I0927 16:41:07.357374 96841728 task_status_update_manager.cpp:181] Pausing
sending task status updates
I0927 16:41:07.357882 94158848 master.cpp:9883] Adding framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default) with roles { } suppressed
I0927 16:41:07.358126 96305152 hierarchical.cpp:306] Added framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.358263 96305152 hierarchical.cpp:1568] Performed allocation for
0 agents in 43106ns
I0927 16:41:07.358593 93622272 scheduler.cpp:845] Enqueuing event SUBSCRIBED
received from http://10.0.49.4:56698/master/api/v1/scheduler
I0927 16:41:07.358845 93622272 scheduler.cpp:845] Enqueuing event HEARTBEAT
received from http://10.0.49.4:56698/master/api/v1/scheduler
I0927 16:41:07.370728 94158848 slave.cpp:1346] Authenticating with master
[email protected]:56698
I0927 16:41:07.370784 94158848 slave.cpp:1355] Using default CRAM-MD5
authenticatee
I0927 16:41:07.370889 95232000 authenticatee.cpp:121] Creating new client SASL
connection
I0927 16:41:07.371057 95768576 master.cpp:9653] Authenticating
slave(905)@10.0.49.4:56698
I0927 16:41:07.371119 94695424 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1612)@10.0.49.4:56698
I0927 16:41:07.371201 93622272 authenticator.cpp:98] Creating new server SASL
connection
I0927 16:41:07.371317 96305152 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I0927 16:41:07.371338 96305152 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I0927 16:41:07.371431 93085696 authenticator.cpp:204] Received SASL
authentication start
I0927 16:41:07.371495 93085696 authenticator.cpp:326] Authentication requires
more steps
I0927 16:41:07.371543 96841728 authenticatee.cpp:259] Received SASL
authentication step
I0927 16:41:07.371616 94158848 authenticator.cpp:232] Received SASL
authentication step
I0927 16:41:07.371635 94158848 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0927 16:41:07.371646 94158848 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0927 16:41:07.371659 94158848 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0927 16:41:07.371668 94158848 auxprop.cpp:109] Request to lookup properties
for user: 'test-principal' realm: 'Jenkinss-Mac-mini.local' server FQDN:
'Jenkinss-Mac-mini.local' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0927 16:41:07.371675 94158848 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0927 16:41:07.371690 94158848 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0927 16:41:07.371708 94158848 authenticator.cpp:318] Authentication success
I0927 16:41:07.371755 95232000 authenticatee.cpp:299] Authentication success
I0927 16:41:07.371824 95768576 master.cpp:9685] Successfully authenticated
principal 'test-principal' at slave(905)@10.0.49.4:56698
I0927 16:41:07.371848 94695424 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1612)@10.0.49.4:56698
I0927 16:41:07.371999 93622272 slave.cpp:1446] Successfully authenticated with
master [email protected]:56698
I0927 16:41:07.372191 93622272 slave.cpp:1877] Will retry registration in
11.031086ms if necessary
I0927 16:41:07.372258 95232000 master.cpp:6605] Received register agent message
from slave(905)@10.0.49.4:56698 (Jenkinss-Mac-mini.local)
I0927 16:41:07.372398 95232000 master.cpp:3964] Authorizing agent providing
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal
'test-principal'
I0927 16:41:07.372685 93085696 master.cpp:6672] Authorized registration of
agent at slave(905)@10.0.49.4:56698 (Jenkinss-Mac-mini.local)
I0927 16:41:07.372740 93085696 master.cpp:6787] Registering agent at
slave(905)@10.0.49.4:56698 (Jenkinss-Mac-mini.local) with id
d8823df0-8625-4d84-9980-2c64d226d6f8-S0
I0927 16:41:07.373046 96841728 registrar.cpp:487] Applied 1 operations in
118367ns; attempting to update the registry
I0927 16:41:07.373260 94158848 registrar.cpp:544] Successfully updated the
registry in 185856ns
I0927 16:41:07.373317 94695424 master.cpp:6835] Admitted agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local)
I0927 16:41:07.373548 94695424 master.cpp:6880] Registered agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0927 16:41:07.373610 96305152 slave.cpp:1479] Registered with master
[email protected]:56698; given agent ID d8823df0-8625-4d84-9980-2c64d226d6f8-S0
I0927 16:41:07.373675 95768576 task_status_update_manager.cpp:188] Resuming
sending task status updates
I0927 16:41:07.373667 96841728 hierarchical.cpp:605] Added agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 (Jenkinss-Mac-mini.local) with cpus:2;
mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0927 16:41:07.373970 96305152 slave.cpp:1499] Checkpointing SlaveInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/meta/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/slave.info'
I0927 16:41:07.374048 96841728 hierarchical.cpp:1568] Performed allocation for
1 agents in 293803ns
I0927 16:41:07.374217 93622272 master.cpp:9468] Sending offers [
d8823df0-8625-4d84-9980-2c64d226d6f8-O0 ] to framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default)
I0927 16:41:07.374689 96305152 slave.cpp:1548] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"h5GQaxdiQaWanuwnTbfjKQ=="},"slave_id":{"value":"d8823df0-8625-4d84-9980-2c64d226d6f8-S0"},"update_oversubscribed_resources":false}
I0927 16:41:07.375167 96841728 scheduler.cpp:845] Enqueuing event OFFERS
received from http://10.0.49.4:56698/master/api/v1/scheduler
I0927 16:41:07.375241 94695424 master.cpp:7939] Ignoring update on agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local) as it reports no changes
I0927 16:41:07.376076 96305152 scheduler.cpp:248] Sending ACCEPT call to
http://10.0.49.4:56698/master/api/v1/scheduler
I0927 16:41:07.376763 95232000 process.cpp:3569] Handling HTTP event for
process 'master' with path: '/master/api/v1/scheduler'
I0927 16:41:07.377372 95232000 http.cpp:1177] HTTP POST for
/master/api/v1/scheduler from 10.0.49.4:59572
I0927 16:41:07.377741 95232000 master.cpp:11462] Removing offer
d8823df0-8625-4d84-9980-2c64d226d6f8-O0
I0927 16:41:07.377996 95232000 master.cpp:4467] Processing ACCEPT call for
offers: [ d8823df0-8625-4d84-9980-2c64d226d6f8-O0 ] on agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local) for framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default)
I0927 16:41:07.378087 95232000 master.cpp:3541] Authorizing framework principal
'test-principal' to launch task 15cbfc36-64d4-4ff8-87b8-4d18fae4462d
I0927 16:41:07.379261 95232000 master.cpp:12209] Adding task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d with resources cpus(allocated:
default-role):0.1; mem(allocated: default-role):32; disk(allocated:
default-role):32 on agent d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at
slave(905)@10.0.49.4:56698 (Jenkinss-Mac-mini.local)
I0927 16:41:07.379336 95232000 master.cpp:5663] Launching task group {
15cbfc36-64d4-4ff8-87b8-4d18fae4462d } of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default) with resources
cpus(allocated: default-role):0.1; mem(allocated: default-role):32;
disk(allocated: default-role):32 on agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local) on new executor
I0927 16:41:07.379701 96305152 hierarchical.cpp:1240] Recovered cpus(allocated:
default-role):1.8; mem(allocated: default-role):960; disk(allocated:
default-role):960; ports(allocated: default-role):[31000-32000] (total: cpus:2;
mem:1024; disk:1024; ports:[31000-32000], allocated: cpus(allocated:
default-role):0.2; mem(allocated: default-role):64; disk(allocated:
default-role):64) on agent d8823df0-8625-4d84-9980-2c64d226d6f8-S0 from
framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.379746 96305152 hierarchical.cpp:1286] Framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 filtered agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 for 5secs
I0927 16:41:07.379804 95768576 slave.cpp:2014] Got assigned task group
containing tasks [ 15cbfc36-64d4-4ff8-87b8-4d18fae4462d ] for framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.380352 95768576 slave.cpp:2388] Authorizing task group
containing tasks [ 15cbfc36-64d4-4ff8-87b8-4d18fae4462d ] for framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.380393 95768576 slave.cpp:8466] Authorizing framework principal
'test-principal' to launch task 15cbfc36-64d4-4ff8-87b8-4d18fae4462d
I0927 16:41:07.381274 95768576 slave.cpp:2831] Launching task group containing
tasks [ 15cbfc36-64d4-4ff8-87b8-4d18fae4462d ] for framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.381373 95768576 paths.cpp:752] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554'
for user 'jenkins'
I0927 16:41:07.382478 95768576 slave.cpp:8994] Launching executor 'default' of
framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000 with resources
[{"allocation_info":{"role":"default-role"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"default-role"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"},{"allocation_info":{"role":"default-role"},"name":"disk","scalar":{"value":32.0},"type":"SCALAR"}]
in work directory
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554'
I0927 16:41:07.383031 95768576 slave.cpp:3028] Queued task group containing
tasks [ 15cbfc36-64d4-4ff8-87b8-4d18fae4462d ] for executor 'default' of
framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.383127 95768576 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/latest'
I0927 16:41:07.383381 95768576 slave.cpp:3509] Launching container
17e70099-c1e5-4e09-b5fe-c12c8fede554 for executor 'default' of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.383615 95768576 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554'
to virtual path
'/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/latest'
I0927 16:41:07.383656 95768576 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554'
I0927 16:41:07.383854 93085696 containerizer.cpp:1280] Starting container
17e70099-c1e5-4e09-b5fe-c12c8fede554
I0927 16:41:07.384748 93085696 containerizer.cpp:1446] Checkpointed
ContainerConfig at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/containers/17e70099-c1e5-4e09-b5fe-c12c8fede554/config'
I0927 16:41:07.384768 93085696 containerizer.cpp:3118] Transitioning the state
of container 17e70099-c1e5-4e09-b5fe-c12c8fede554 from PROVISIONING to PREPARING
I0927 16:41:07.386382 93622272 containerizer.cpp:1939] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"arguments":["mesos-default-executor","--launcher_dir=/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src"],"shell":false,"value":"/Users/jenkins/workspace/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mac/mesos/build/src/mesos-default-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.4:56698"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiIxN2U3MDA5OS1jMWU1LTRlMDktYjVmZS1jMTJjOGZlZGU1NTQiLCJlaWQiOiJkZWZhdWx0IiwiZmlkIjoiZDg4MjNkZjAtODYyNS00ZDg0LTk5ODAtMmM2NGQyMjZkNmY4LTAwMDAifQ.3M9HecoqhP7VGDab7oV5G6Tgag_U_zJqdkS0vARdcT8"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"default"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"d8823df0-8625-4d84-9980-2c64d226d6f8-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"d8823df0-8625-4d84-9980-2c64d226d6f8-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(905)@10.0.49.4:56698"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554"}"
--pipe_read="48" --pipe_write="52"
--runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/containers/17e70099-c1e5-4e09-b5fe-c12c8fede554"'
I0927 16:41:07.388022 93622272 launcher.cpp:150] Forked child with pid '39702'
for container '17e70099-c1e5-4e09-b5fe-c12c8fede554'
I0927 16:41:07.388813 93622272 containerizer.cpp:3118] Transitioning the state
of container 17e70099-c1e5-4e09-b5fe-c12c8fede554 from PREPARING to ISOLATING
I0927 16:41:07.391413 93622272 containerizer.cpp:3118] Transitioning the state
of container 17e70099-c1e5-4e09-b5fe-c12c8fede554 from ISOLATING to FETCHING
I0927 16:41:07.391508 96841728 fetcher.cpp:369] Starting to fetch URIs for
container: 17e70099-c1e5-4e09-b5fe-c12c8fede554, directory:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554
I0927 16:41:07.392139 93085696 containerizer.cpp:3118] Transitioning the state
of container 17e70099-c1e5-4e09-b5fe-c12c8fede554 from FETCHING to RUNNING
[warn] kq_init: detected broken kqueue; not using.: Undefined error: 0
I0927 16:41:07.548449 64946176 executor.cpp:201] Version: 1.8.0
I0927 16:41:07.561666 96305152 process.cpp:3569] Handling HTTP event for
process 'slave(905)' with path: '/slave(905)/api/v1/executor'
I0927 16:41:07.562938 95232000 http.cpp:1177] HTTP POST for
/slave(905)/api/v1/executor from 10.0.49.4:59574
I0927 16:41:07.563058 95232000 slave.cpp:4607] Received Subscribe request for
HTTP executor 'default' of framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.564240 96841728 slave.cpp:3282] Sending queued task group
containing tasks [ 15cbfc36-64d4-4ff8-87b8-4d18fae4462d ] to executor 'default'
of framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (via HTTP)
I0927 16:41:07.565347 64946176 default_executor.cpp:204] Received SUBSCRIBED
event
I0927 16:41:07.566036 64946176 default_executor.cpp:208] Subscribed executor on
Jenkinss-Mac-mini.local
I0927 16:41:07.566217 64946176 default_executor.cpp:204] Received LAUNCH_GROUP
event
I0927 16:41:07.566648 62263296 default_executor.cpp:428] Setting
'MESOS_CONTAINER_IP' to: 10.0.49.4
I0927 16:41:07.573247 95768576 process.cpp:3569] Handling HTTP event for
process 'slave(905)' with path: '/slave(905)/api/v1/executor'
I0927 16:41:07.573549 95768576 process.cpp:3569] Handling HTTP event for
process 'slave(905)' with path: '/slave(905)/api/v1'
I0927 16:41:07.574481 93622272 http.cpp:1177] HTTP POST for
/slave(905)/api/v1/executor from 10.0.49.4:59575
I0927 16:41:07.574595 93622272 slave.cpp:5269] Handling status update
TASK_STARTING (Status UUID: 074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.574846 93622272 http.cpp:1177] HTTP POST for /slave(905)/api/v1
from 10.0.49.4:59576
I0927 16:41:07.575160 93085696 task_status_update_manager.cpp:328] Received
task status update TASK_STARTING (Status UUID:
074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.575192 93085696 task_status_update_manager.cpp:507] Creating
StatusUpdate stream for task 15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.575248 93622272 http.cpp:2408] Processing
LAUNCH_NESTED_CONTAINER call for container
'17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217'
I0927 16:41:07.575559 93085696 task_status_update_manager.cpp:383] Forwarding
task status update TASK_STARTING (Status UUID:
074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 to the agent
I0927 16:41:07.575635 96305152 slave.cpp:5761] Forwarding the update
TASK_STARTING (Status UUID: 074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 to [email protected]:56698
I0927 16:41:07.575836 96841728 master.cpp:8375] Status update TASK_STARTING
(Status UUID: 074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 from agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local)
I0927 16:41:07.575873 96841728 master.cpp:8432] Forwarding status update
TASK_STARTING (Status UUID: 074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.575915 96305152 slave.cpp:5654] Task status update manager
successfully handled status update TASK_STARTING (Status UUID:
074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.575991 94158848 containerizer.cpp:1242] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554/containers/9f8f22be-3520-4c72-bd6b-19677bdd2217'
for user 'jenkins'
I0927 16:41:07.576103 96841728 master.cpp:10932] Updating the state of task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (latest state: TASK_STARTING, status
update state: TASK_STARTING)
I0927 16:41:07.576599 94158848 containerizer.cpp:1280] Starting container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217
I0927 16:41:07.576792 64409600 default_executor.cpp:204] Received ACKNOWLEDGED
event
I0927 16:41:07.576874 95768576 scheduler.cpp:845] Enqueuing event UPDATE
received from http://10.0.49.4:56698/master/api/v1/scheduler
I0927 16:41:07.577581 94158848 containerizer.cpp:1446] Checkpointed
ContainerConfig at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/containers/17e70099-c1e5-4e09-b5fe-c12c8fede554/containers/9f8f22be-3520-4c72-bd6b-19677bdd2217/config'
I0927 16:41:07.577605 94158848 containerizer.cpp:3118] Transitioning the state
of container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 from
PROVISIONING to PREPARING
I0927 16:41:07.578650 96305152 containerizer.cpp:1939] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"shell":true,"value":"sleep
1000"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554/containers/9f8f22be-3520-4c72-bd6b-19677bdd2217"},{"name":"MESOS_CONTAINER_IP","type":"VALUE","value":"10.0.49.4"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554/containers/9f8f22be-3520-4c72-bd6b-19677bdd2217"}"
--pipe_read="54" --pipe_write="55"
--runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/containers/17e70099-c1e5-4e09-b5fe-c12c8fede554/containers/9f8f22be-3520-4c72-bd6b-19677bdd2217"'
I0927 16:41:07.580302 96305152 launcher.cpp:150] Forked child with pid '39730'
for container
'17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217'
I0927 16:41:07.581140 96305152 containerizer.cpp:3118] Transitioning the state
of container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 from
PREPARING to ISOLATING
I0927 16:41:07.583140 96305152 containerizer.cpp:3118] Transitioning the state
of container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 from
ISOLATING to FETCHING
I0927 16:41:07.583248 95232000 fetcher.cpp:369] Starting to fetch URIs for
container:
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217,
directory:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_RKEcpP/slaves/d8823df0-8625-4d84-9980-2c64d226d6f8-S0/frameworks/d8823df0-8625-4d84-9980-2c64d226d6f8-0000/executors/default/runs/17e70099-c1e5-4e09-b5fe-c12c8fede554/containers/9f8f22be-3520-4c72-bd6b-19677bdd2217
I0927 16:41:07.583832 96841728 containerizer.cpp:3118] Transitioning the state
of container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 from
FETCHING to RUNNING
I0927 16:41:07.592468 63873024 default_executor.cpp:663] Finished launching
tasks [ 15cbfc36-64d4-4ff8-87b8-4d18fae4462d ] in child containers [
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 ]
I0927 16:41:07.592530 63873024 default_executor.cpp:687] Waiting on child
containers of tasks [ 15cbfc36-64d4-4ff8-87b8-4d18fae4462d ]
I0927 16:41:07.593199 62263296 default_executor.cpp:748] Waiting for child
container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 of
task '15cbfc36-64d4-4ff8-87b8-4d18fae4462d'
I0927 16:41:07.593812 96305152 process.cpp:3569] Handling HTTP event for
process 'slave(905)' with path: '/slave(905)/api/v1/executor'
I0927 16:41:07.594540 96305152 process.cpp:3569] Handling HTTP event for
process 'slave(905)' with path: '/slave(905)/api/v1'
I0927 16:41:07.595577 94158848 http.cpp:1177] HTTP POST for
/slave(905)/api/v1/executor from 10.0.49.4:59575
I0927 16:41:07.595739 94158848 slave.cpp:5269] Handling status update
TASK_RUNNING (Status UUID: 5524e8e2-195e-4d4d-b0c0-3d1311a7f60e) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.596011 94158848 http.cpp:1177] HTTP POST for /slave(905)/api/v1
from 10.0.49.4:59577
I0927 16:41:07.596293 94158848 http.cpp:2643] Processing WAIT_NESTED_CONTAINER
call for container
'17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217'
I0927 16:41:07.596643 96841728 task_status_update_manager.cpp:328] Received
task status update TASK_RUNNING (Status UUID:
5524e8e2-195e-4d4d-b0c0-3d1311a7f60e) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.596808 96305152 slave.cpp:5654] Task status update manager
successfully handled status update TASK_RUNNING (Status UUID:
5524e8e2-195e-4d4d-b0c0-3d1311a7f60e) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:07.597615 64946176 default_executor.cpp:204] Received ACKNOWLEDGED
event
W0927 16:41:44.545560 95768576 task_status_update_manager.cpp:484] Resending
task status update TASK_STARTING (Status UUID:
074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:44.545631 95768576 task_status_update_manager.cpp:383] Forwarding
task status update TASK_STARTING (Status UUID:
074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 to the agent
I0927 16:41:44.546506 94695424 slave.cpp:5761] Forwarding the update
TASK_STARTING (Status UUID: 074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 to [email protected]:56698
../../src/tests/master_tests.cpp:9594: Failure
Failed to wait 15secs for runningUpdate
I0927 16:41:44.547423 95768576 master.cpp:8375] Status update TASK_STARTING
(Status UUID: 074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 from agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local)
I0927 16:41:44.547510 95768576 master.cpp:8432] Forwarding status update
TASK_STARTING (Status UUID: 074591e3-8664-4c74-85e3-74d3cdebb9f8) for task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:44.547833 95768576 master.cpp:10932] Updating the state of task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (latest state: TASK_RUNNING, status
update state: TASK_STARTING)
I0927 16:41:44.550495 95768576 master.cpp:1366] Framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default) disconnected
I0927 16:41:44.550542 95768576 master.cpp:3230] Deactivating framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default)
I0927 16:41:44.550663 95768576 master.cpp:3207] Disconnecting framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default)
I0927 16:41:44.550699 95768576 master.cpp:1381] Giving framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default) 0ns to failover
I0927 16:41:44.550835 96305152 hierarchical.cpp:420] Deactivated framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:44.550881 96841728 master.cpp:9261] Framework failover timeout,
removing framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default)
I0927 16:41:44.550915 96841728 master.cpp:10197] Removing framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (default)
I0927 16:41:44.551167 96841728 master.cpp:10932] Updating the state of task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d of framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
I0927 16:41:44.551229 93085696 slave.cpp:3896] Asked to shut down framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 by [email protected]:56698
I0927 16:41:44.551254 93085696 slave.cpp:3921] Shutting down framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:44.551275 93085696 slave.cpp:6640] Shutting down executor 'default'
of framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000 (via HTTP)
I0927 16:41:44.551846 96841728 master.cpp:11030] Removing task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d with resources cpus(allocated:
default-role):0.1; mem(allocated: default-role):32; disk(allocated:
default-role):32 of framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000 on
agent d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local)
I0927 16:41:44.552166 95232000 hierarchical.cpp:1240] Recovered cpus(allocated:
default-role):0.1; mem(allocated: default-role):32; disk(allocated:
default-role):32 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: cpus(allocated: default-role):0.1; mem(allocated: default-role):32;
disk(allocated: default-role):32) on agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 from framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:44.552203 96841728 master.cpp:11061] Removing executor 'default'
with resources
[{"allocation_info":{"role":"default-role"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"default-role"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"},{"allocation_info":{"role":"default-role"},"name":"disk","scalar":{"value":32.0},"type":"SCALAR"}]
of framework d8823df0-8625-4d84-9980-2c64d226d6f8-0000 on agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local)
I0927 16:41:44.552592 64946176 default_executor.cpp:204] Received SHUTDOWN event
I0927 16:41:44.552613 64946176 default_executor.cpp:1021] Shutting down
I0927 16:41:44.552625 64946176 default_executor.cpp:1126] Killing task
15cbfc36-64d4-4ff8-87b8-4d18fae4462d running in child container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 with
SIGTERM signal
I0927 16:41:44.552639 64946176 default_executor.cpp:1137] Scheduling escalation
to SIGKILL in 3secs from now
I0927 16:41:44.552953 94158848 hierarchical.cpp:1240] Recovered cpus(allocated:
default-role):0.1; mem(allocated: default-role):32; disk(allocated:
default-role):32 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: {}) on agent d8823df0-8625-4d84-9980-2c64d226d6f8-S0 from framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
I0927 16:41:44.553192 94158848 hierarchical.cpp:359] Removed framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000
../../src/tests/master_tests.cpp:9564: Failure
Actual function call count doesn't match EXPECT_CALL(*scheduler, update(_,
_))...
Expected: to be called twice
Actual: called once - unsatisfied and active
I0927 16:41:44.553771 2560127808 slave.cpp:909] Agent terminating
I0927 16:41:44.553803 2560127808 slave.cpp:3896] Asked to shut down framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 by @0.0.0.0:0
W0927 16:41:44.553823 2560127808 slave.cpp:3917] Ignoring shutdown framework
d8823df0-8625-4d84-9980-2c64d226d6f8-0000 because it is terminating
I0927 16:41:44.554621 93622272 master.cpp:1251] Agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local) disconnected
I0927 16:41:44.554653 93622272 master.cpp:3267] Disconnecting agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local)
I0927 16:41:44.554689 93622272 master.cpp:3286] Deactivating agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 at slave(905)@10.0.49.4:56698
(Jenkinss-Mac-mini.local)
I0927 16:41:44.554894 95768576 hierarchical.cpp:803] Agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0 deactivated
I0927 16:41:44.555285 95768576 containerizer.cpp:2455] Destroying container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 in
RUNNING state
I0927 16:41:44.555327 95768576 containerizer.cpp:3118] Transitioning the state
of container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 from
RUNNING to DESTROYING
I0927 16:41:44.555502 95768576 launcher.cpp:166] Asked to destroy container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217
E0927 16:41:44.555521 63873024 default_executor.cpp:1064] Unable to complete
the operation of killing child containers: Collect failed: The agent failed to
send signal Terminated: 15 (15) to the container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217:
I0927 16:41:44.555541 63873024 default_executor.cpp:1077] Terminating after
1secs
I0927 16:41:44.650964 96305152 containerizer.cpp:2957] Container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217 has
exited
I0927 16:41:44.651613 96305152 provisioner.cpp:597] Ignoring destroy request
for unknown container
17e70099-c1e5-4e09-b5fe-c12c8fede554.9f8f22be-3520-4c72-bd6b-19677bdd2217
I0927 16:41:44.651731 93085696 containerizer.cpp:2747] Checkpointing
termination state to nested container's runtime directory
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/bool_MasterTestPrePostReservationRefinement_LaunchGroup_1_KwdtlP/containers/17e70099-c1e5-4e09-b5fe-c12c8fede554/containers/9f8f22be-3520-4c72-bd6b-19677bdd2217/termination'
I0927 16:41:44.697268 93622272 containerizer.cpp:2455] Destroying container
17e70099-c1e5-4e09-b5fe-c12c8fede554 in RUNNING state
I0927 16:41:44.697310 93622272 containerizer.cpp:3118] Transitioning the state
of container 17e70099-c1e5-4e09-b5fe-c12c8fede554 from RUNNING to DESTROYING
I0927 16:41:44.697515 93622272 launcher.cpp:166] Asked to destroy container
17e70099-c1e5-4e09-b5fe-c12c8fede554
I0927 16:41:44.865507 93622272 containerizer.cpp:2957] Container
17e70099-c1e5-4e09-b5fe-c12c8fede554 has exited
I0927 16:41:44.867777 93085696 provisioner.cpp:597] Ignoring destroy request
for unknown container 17e70099-c1e5-4e09-b5fe-c12c8fede554
I0927 16:41:44.877279 2560127808 master.cpp:1093] Master terminating
I0927 16:41:44.877846 93085696 hierarchical.cpp:645] Removed agent
d8823df0-8625-4d84-9980-2c64d226d6f8-S0
[ FAILED ] bool/MasterTestPrePostReservationRefinement.LaunchGroup/1, where
GetParam() = false (37541 ms)
{noformat}
> Test MasterTestPrePostReservationRefinement.LaunchGroup/0 is flaky.
> -------------------------------------------------------------------
>
> Key: MESOS-9079
> URL: https://issues.apache.org/jira/browse/MESOS-9079
> Project: Mesos
> Issue Type: Bug
> Reporter: Meng Zhu
> Priority: Major
> Labels: flaky-test
> Attachments:
> MasterTestPrePostReservationRefinement_LaunchGroup_0_badrun.txt
>
>
> Flaky on CI mac-SSL.Mesos
> Error Message
> {noformat}
> ../../src/tests/master_tests.cpp:9270
> Failed to wait 15secs for runningUpdate
> {noformat}
> Log attached.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
