Benno Evers created MESOS-9263:
----------------------------------
Summary:
Mesos.SlaveRecoveryTest/0.KillQueuedTaskDuringExecutorRegistration
Key: MESOS-9263
URL: https://issues.apache.org/jira/browse/MESOS-9263
Project: Mesos
Issue Type: Bug
Reporter: Benno Evers
Observed in an internal CI run: (4488)
{noformat}
../../src/tests/agent_container_api_tests.cpp:596
Failed to wait 15secs for wait
{noformat}
Full log:
{noformat}
[ RUN ] SlaveRecoveryTest/0.KillQueuedTaskDuringExecutorRegistration
I0925 14:33:25.022527 2560127808 cluster.cpp:173] Creating default 'local'
authorizer
I0925 14:33:25.023804 92000256 master.cpp:413] Master
1abbba49-03a4-49da-a395-23ace0ac74cf (Jenkinss-Mac-mini.local) started on
10.0.49.4:63327
I0925 14:33:25.023830 92000256 master.cpp:416] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --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/AT29pT/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/AT29pT/master"
--zk_session_timeout="10secs"
I0925 14:33:25.023998 92000256 master.cpp:465] Master only allowing
authenticated frameworks to register
I0925 14:33:25.024010 92000256 master.cpp:471] Master only allowing
authenticated agents to register
I0925 14:33:25.024019 92000256 master.cpp:477] Master only allowing
authenticated HTTP frameworks to register
I0925 14:33:25.024029 92000256 credentials.hpp:37] Loading credentials for
authentication from
'/private/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/AT29pT/credentials'
I0925 14:33:25.024173 92000256 master.cpp:521] Using default 'crammd5'
authenticator
I0925 14:33:25.024246 92000256 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0925 14:33:25.024314 92000256 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0925 14:33:25.024374 92000256 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0925 14:33:25.024435 92000256 master.cpp:602] Authorization enabled
I0925 14:33:25.024689 89317376 whitelist_watcher.cpp:77] No whitelist given
I0925 14:33:25.024694 90927104 hierarchical.cpp:182] Initialized hierarchical
allocator process
I0925 14:33:25.026221 90390528 master.cpp:2083] Elected as the leading master!
I0925 14:33:25.026247 90390528 master.cpp:1638] Recovering from registrar
I0925 14:33:25.026294 90927104 registrar.cpp:339] Recovering registrar
I0925 14:33:25.026496 93073408 registrar.cpp:383] Successfully fetched the
registry (0B) in 182016ns
I0925 14:33:25.026584 93073408 registrar.cpp:487] Applied 1 operations in
26591ns; attempting to update the registry
I0925 14:33:25.026788 89853952 registrar.cpp:544] Successfully updated the
registry in 177920ns
I0925 14:33:25.026849 89853952 registrar.cpp:416] Successfully recovered
registrar
I0925 14:33:25.027001 92000256 master.cpp:1752] Recovered 0 agents from the
registry (155B); allowing 10mins for agents to reregister
I0925 14:33:25.027021 93073408 hierarchical.cpp:220] Skipping recovery of
hierarchical allocator: nothing to recover
I0925 14:33:25.029000 2560127808 containerizer.cpp:305] Using isolation {
environment_secret, filesystem/posix, posix/mem, posix/cpu }
I0925 14:33:25.029227 2560127808 provisioner.cpp:298] Using default backend
'copy'
W0925 14:33:25.031018 2560127808 process.cpp:2810] Attempted to spawn already
running process [email protected]:63327
I0925 14:33:25.031427 2560127808 cluster.cpp:485] Creating default 'local'
authorizer
I0925 14:33:25.032447 90390528 slave.cpp:267] Mesos agent started on
(512)@10.0.49.4:63327
I0925 14:33:25.032474 90390528 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/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/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/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/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/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/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/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/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/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/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--version="false"
--work_dir="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI"
--zk_session_timeout="10secs"
I0925 14:33:25.032770 90390528 credentials.hpp:86] Loading credential for
authentication from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/credential'
I0925 14:33:25.032932 90390528 slave.cpp:300] Agent using credential for:
test-principal
I0925 14:33:25.032949 90390528 credentials.hpp:37] Loading credentials for
authentication from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/http_credentials'
W0925 14:33:25.033085 2560127808 process.cpp:2810] Attempted to spawn already
running process [email protected]:63327
I0925 14:33:25.033126 90390528 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I0925 14:33:25.033187 90390528 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I0925 14:33:25.033269 90390528 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0925 14:33:25.033313 90390528 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I0925 14:33:25.033442 90390528 http.cpp:1037] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0925 14:33:25.033490 90390528 http.cpp:1058] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0925 14:33:25.033707 90390528 disk_profile_adaptor.cpp:80] Creating default
disk profile adaptor module
I0925 14:33:25.034266 90390528 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"}]
I0925 14:33:25.034448 90390528 slave.cpp:623] Agent attributes: [ ]
I0925 14:33:25.034459 90390528 slave.cpp:632] Agent hostname:
Jenkinss-Mac-mini.local
I0925 14:33:25.034544 92536832 task_status_update_manager.cpp:181] Pausing
sending task status updates
I0925 14:33:25.034822 2560127808 sched.cpp:232] Version: 1.8.0
I0925 14:33:25.035184 93073408 sched.cpp:336] New master detected at
[email protected]:63327
I0925 14:33:25.035249 93073408 sched.cpp:401] Authenticating with master
[email protected]:63327
I0925 14:33:25.035266 93073408 sched.cpp:408] Using default CRAM-MD5
authenticatee
I0925 14:33:25.035396 89853952 state.cpp:66] Recovering state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta'
I0925 14:33:25.035496 90927104 authenticatee.cpp:121] Creating new client SASL
connection
I0925 14:33:25.035569 92000256 slave.cpp:6909] Finished recovering checkpointed
state from
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta',
beginning agent recovery
I0925 14:33:25.035686 90390528 master.cpp:9653] Authenticating
[email protected]:63327
I0925 14:33:25.035693 89317376 task_status_update_manager.cpp:207] Recovering
task status update manager
I0925 14:33:25.035782 91463680 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1047)@10.0.49.4:63327
I0925 14:33:25.035899 92536832 authenticator.cpp:98] Creating new server SASL
connection
I0925 14:33:25.035950 92000256 containerizer.cpp:727] Recovering Mesos
containers
I0925 14:33:25.036003 93073408 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I0925 14:33:25.036026 93073408 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I0925 14:33:25.036078 91463680 authenticator.cpp:204] Received SASL
authentication start
I0925 14:33:25.036128 92000256 containerizer.cpp:1053] Recovering isolators
I0925 14:33:25.036144 91463680 authenticator.cpp:326] Authentication requires
more steps
I0925 14:33:25.036209 89853952 authenticatee.cpp:259] Received SASL
authentication step
I0925 14:33:25.036351 90390528 authenticator.cpp:232] Received SASL
authentication step
I0925 14:33:25.036375 90390528 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
I0925 14:33:25.036391 90390528 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0925 14:33:25.036413 90390528 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0925 14:33:25.036442 90390528 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
I0925 14:33:25.036454 90390528 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0925 14:33:25.036463 90390528 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0925 14:33:25.036494 90390528 authenticator.cpp:318] Authentication success
I0925 14:33:25.036566 90927104 containerizer.cpp:1092] Recovering provisioner
I0925 14:33:25.036636 92000256 authenticatee.cpp:299] Authentication success
I0925 14:33:25.036684 91463680 master.cpp:9685] Successfully authenticated
principal 'test-principal' at
[email protected]:63327
I0925 14:33:25.036698 89853952 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1047)@10.0.49.4:63327
I0925 14:33:25.036880 90390528 sched.cpp:513] Successfully authenticated with
master [email protected]:63327
I0925 14:33:25.036893 90390528 sched.cpp:817] Sending SUBSCRIBE call to
[email protected]:63327
I0925 14:33:25.036988 90390528 sched.cpp:850] Will retry registration in
1.984003826secs if necessary
I0925 14:33:25.036998 93073408 provisioner.cpp:494] Provisioner recovery
complete
I0925 14:33:25.037060 91463680 master.cpp:2854] Received SUBSCRIBE call for
framework 'default' at
[email protected]:63327
I0925 14:33:25.037089 91463680 master.cpp:2155] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I0925 14:33:25.037385 91463680 composing.cpp:339] Finished recovering all
containerizers
I0925 14:33:25.037444 92000256 slave.cpp:7138] Recovering executors
I0925 14:33:25.037473 89853952 master.cpp:2935] Subscribing framework default
with checkpointing enabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT ]
I0925 14:33:25.037503 92000256 slave.cpp:7291] Finished recovery
I0925 14:33:25.038233 92000256 slave.cpp:1254] New master detected at
[email protected]:63327
I0925 14:33:25.038257 91463680 task_status_update_manager.cpp:181] Pausing
sending task status updates
I0925 14:33:25.038285 92000256 slave.cpp:1319] Detecting new master
I0925 14:33:25.038478 89853952 master.cpp:9883] Adding framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327 with roles { }
suppressed
I0925 14:33:25.038744 90390528 sched.cpp:744] Framework registered with
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:25.038802 90390528 sched.cpp:758] Scheduler::registered took 35532ns
I0925 14:33:25.038835 89317376 hierarchical.cpp:306] Added framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:25.038923 89317376 hierarchical.cpp:1564] Performed allocation for
0 agents in 39141ns
I0925 14:33:25.047401 92536832 slave.cpp:1346] Authenticating with master
[email protected]:63327
I0925 14:33:25.047453 92536832 slave.cpp:1355] Using default CRAM-MD5
authenticatee
I0925 14:33:25.047554 91463680 authenticatee.cpp:121] Creating new client SASL
connection
I0925 14:33:25.047693 93073408 master.cpp:9653] Authenticating
slave(512)@10.0.49.4:63327
I0925 14:33:25.047760 89853952 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1048)@10.0.49.4:63327
I0925 14:33:25.047866 90390528 authenticator.cpp:98] Creating new server SASL
connection
I0925 14:33:25.047968 89317376 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
I0925 14:33:25.048000 89317376 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
I0925 14:33:25.048066 90927104 authenticator.cpp:204] Received SASL
authentication start
I0925 14:33:25.048136 90927104 authenticator.cpp:326] Authentication requires
more steps
I0925 14:33:25.048185 92000256 authenticatee.cpp:259] Received SASL
authentication step
I0925 14:33:25.048238 92536832 authenticator.cpp:232] Received SASL
authentication step
I0925 14:33:25.048256 92536832 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
I0925 14:33:25.048269 92536832 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0925 14:33:25.048310 92536832 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0925 14:33:25.048329 92536832 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
I0925 14:33:25.048343 92536832 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0925 14:33:25.048354 92536832 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0925 14:33:25.048370 92536832 authenticator.cpp:318] Authentication success
I0925 14:33:25.048436 91463680 authenticatee.cpp:299] Authentication success
I0925 14:33:25.048458 93073408 master.cpp:9685] Successfully authenticated
principal 'test-principal' at slave(512)@10.0.49.4:63327
I0925 14:33:25.048496 89853952 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1048)@10.0.49.4:63327
I0925 14:33:25.048645 90390528 slave.cpp:1446] Successfully authenticated with
master [email protected]:63327
I0925 14:33:25.048867 90390528 slave.cpp:1877] Will retry registration in
18.554281ms if necessary
I0925 14:33:25.048916 92536832 master.cpp:6605] Received register agent message
from slave(512)@10.0.49.4:63327 (Jenkinss-Mac-mini.local)
I0925 14:33:25.049011 92536832 master.cpp:3964] Authorizing agent providing
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal
'test-principal'
I0925 14:33:25.049345 91463680 master.cpp:6672] Authorized registration of
agent at slave(512)@10.0.49.4:63327 (Jenkinss-Mac-mini.local)
I0925 14:33:25.049407 91463680 master.cpp:6787] Registering agent at
slave(512)@10.0.49.4:63327 (Jenkinss-Mac-mini.local) with id
1abbba49-03a4-49da-a395-23ace0ac74cf-S0
I0925 14:33:25.049670 89853952 registrar.cpp:487] Applied 1 operations in
114590ns; attempting to update the registry
I0925 14:33:25.049906 90927104 registrar.cpp:544] Successfully updated the
registry in 194048ns
I0925 14:33:25.049983 92000256 master.cpp:6835] Admitted agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local)
I0925 14:33:25.050195 92000256 master.cpp:6880] Registered agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0925 14:33:25.050277 92536832 slave.cpp:1479] Registered with master
[email protected]:63327; given agent ID 1abbba49-03a4-49da-a395-23ace0ac74cf-S0
I0925 14:33:25.050302 89853952 hierarchical.cpp:601] Added agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 (Jenkinss-Mac-mini.local) with cpus:2;
mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0925 14:33:25.050392 89317376 task_status_update_manager.cpp:188] Resuming
sending task status updates
I0925 14:33:25.050632 92536832 slave.cpp:1499] Checkpointing SlaveInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/slave.info'
I0925 14:33:25.050714 89853952 hierarchical.cpp:1564] Performed allocation for
1 agents in 332294ns
I0925 14:33:25.050887 90390528 master.cpp:9468] Sending offers [
1abbba49-03a4-49da-a395-23ace0ac74cf-O0 ] to framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327
I0925 14:33:25.051203 90927104 sched.cpp:914] Scheduler::resourceOffers took
82338ns
I0925 14:33:25.051401 92536832 slave.cpp:1548] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"SJ+6S2LWRfSvPpFYKy1zIg=="},"slave_id":{"value":"1abbba49-03a4-49da-a395-23ace0ac74cf-S0"},"update_oversubscribed_resources":false}
I0925 14:33:25.051779 89853952 master.cpp:7939] Ignoring update on agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local) as it reports no changes
I0925 14:33:25.052278 93073408 master.cpp:11462] Removing offer
1abbba49-03a4-49da-a395-23ace0ac74cf-O0
I0925 14:33:25.052513 93073408 master.cpp:4467] Processing ACCEPT call for
offers: [ 1abbba49-03a4-49da-a395-23ace0ac74cf-O0 ] on agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local) for framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327
I0925 14:33:25.052587 93073408 master.cpp:3541] Authorizing framework principal
'test-principal' to launch task 4737334b-33a1-4b0a-898f-d29627c050a7
I0925 14:33:25.053434 90390528 master.cpp:12209] Adding task
4737334b-33a1-4b0a-898f-d29627c050a7 with resources cpus(allocated: *):2;
mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] on agent 1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at
slave(512)@10.0.49.4:63327 (Jenkinss-Mac-mini.local)
I0925 14:33:25.053589 90390528 master.cpp:5439] Launching task
4737334b-33a1-4b0a-898f-d29627c050a7 of framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
on agent 1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local) on new executor
I0925 14:33:25.054316 93073408 slave.cpp:2014] Got assigned task
'4737334b-33a1-4b0a-898f-d29627c050a7' for framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:25.054417 93073408 slave.cpp:8908] Checkpointing FrameworkInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/framework.info'
I0925 14:33:25.054996 93073408 slave.cpp:8919] Checkpointing framework pid
'[email protected]:63327' to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/framework.pid'
I0925 14:33:25.055688 93073408 slave.cpp:2388] Authorizing task
'4737334b-33a1-4b0a-898f-d29627c050a7' for framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:25.055727 93073408 slave.cpp:8466] Authorizing framework principal
'test-principal' to launch task 4737334b-33a1-4b0a-898f-d29627c050a7
I0925 14:33:25.056412 93073408 slave.cpp:2831] Launching task
'4737334b-33a1-4b0a-898f-d29627c050a7' for framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:25.056473 93073408 paths.cpp:752] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282'
for user 'jenkins'
I0925 14:33:25.058297 93073408 slave.cpp:9694] Checkpointing ExecutorInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/executor.info'
I0925 14:33:25.058969 93073408 paths.cpp:755] Creating sandbox
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282'
I0925 14:33:25.059506 93073408 slave.cpp:8994] Launching executor
'4737334b-33a1-4b0a-898f-d29627c050a7' of framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}]
in work directory
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282'
I0925 14:33:25.060123 93073408 slave.cpp:9725] Checkpointing TaskInfo to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282/tasks/4737334b-33a1-4b0a-898f-d29627c050a7/task.info'
I0925 14:33:25.061229 93073408 slave.cpp:3028] Queued task
'4737334b-33a1-4b0a-898f-d29627c050a7' for executor
'4737334b-33a1-4b0a-898f-d29627c050a7' of framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:25.061585 93073408 slave.cpp:3509] Launching container
f0644927-e0ca-44d3-a41d-41a8ef2d7282 for executor
'4737334b-33a1-4b0a-898f-d29627c050a7' of framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:25.061879 93073408 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/latest'
I0925 14:33:25.061920 93073408 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282'
to virtual path
'/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/latest'
I0925 14:33:25.061939 93073408 slave.cpp:988] Successfully attached
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282'
to virtual path
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282'
I0925 14:33:25.062165 92536832 containerizer.cpp:1280] Starting container
f0644927-e0ca-44d3-a41d-41a8ef2d7282
I0925 14:33:25.063184 92536832 containerizer.cpp:1446] Checkpointed
ContainerConfig at
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/containers/f0644927-e0ca-44d3-a41d-41a8ef2d7282/config'
I0925 14:33:25.063201 92536832 containerizer.cpp:3118] Transitioning the state
of container f0644927-e0ca-44d3-a41d-41a8ef2d7282 from PROVISIONING to PREPARING
I0925 14:33:25.065048 89853952 containerizer.cpp:1939] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"arguments":["mesos-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-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"10.0.49.4:63327"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiJmMDY0NDkyNy1lMGNhLTQ0ZDMtYTQxZC00MWE4ZWYyZDcyODIiLCJlaWQiOiI0NzM3MzM0Yi0zM2ExLTRiMGEtODk4Zi1kMjk2MjdjMDUwYTciLCJmaWQiOiIxYWJiYmE0OS0wM2E0LTQ5ZGEtYTM5NS0yM2FjZTBhYzc0Y2YtMDAwMCJ9.TGbzScbVX7XOjBnatXa54TXe3aN2M4PTWPxtzFWaNtI"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"4737334b-33a1-4b0a-898f-d29627c050a7"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"1abbba49-03a4-49da-a395-23ace0ac74cf-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_RECOVERY_TIMEOUT","type":"VALUE","value":"15mins"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"1abbba49-03a4-49da-a395-23ace0ac74cf-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(512)@10.0.49.4:63327"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282"}]},"task_environment":{},"user":"jenkins","working_directory":"/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282"}"
--pipe_read="19" --pipe_write="24"
--runtime_directory="/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_k9dVqd/containers/f0644927-e0ca-44d3-a41d-41a8ef2d7282"'
I0925 14:33:25.066889 89853952 launcher.cpp:150] Forked child with pid '98168'
for container 'f0644927-e0ca-44d3-a41d-41a8ef2d7282'
I0925 14:33:25.067217 89853952 containerizer.cpp:2044] Checkpointing
container's forked pid 98168 to
'/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/meta/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282/pids/forked.pid'
I0925 14:33:25.068645 89853952 containerizer.cpp:3118] Transitioning the state
of container f0644927-e0ca-44d3-a41d-41a8ef2d7282 from PREPARING to ISOLATING
I0925 14:33:25.070127 89853952 containerizer.cpp:3118] Transitioning the state
of container f0644927-e0ca-44d3-a41d-41a8ef2d7282 from ISOLATING to FETCHING
I0925 14:33:25.070209 92000256 fetcher.cpp:369] Starting to fetch URIs for
container: f0644927-e0ca-44d3-a41d-41a8ef2d7282, directory:
/var/folders/6w/rw03zh013y38ys6cyn8qppf80000gn/T/SlaveRecoveryTest_0_KillQueuedTaskDuringExecutorRegistration_OkyGZI/slaves/1abbba49-03a4-49da-a395-23ace0ac74cf-S0/frameworks/1abbba49-03a4-49da-a395-23ace0ac74cf-0000/executors/4737334b-33a1-4b0a-898f-d29627c050a7/runs/f0644927-e0ca-44d3-a41d-41a8ef2d7282
I0925 14:33:25.070868 91463680 containerizer.cpp:3118] Transitioning the state
of container f0644927-e0ca-44d3-a41d-41a8ef2d7282 from FETCHING to RUNNING
I0925 14:33:41.362643 89853952 hierarchical.cpp:1564] Performed allocation for
1 agents in 207361ns
../../src/tests/slave_recovery_tests.cpp:1371: Failure
Failed to wait 15secs for registerExecutor
I0925 14:33:41.364737 2560127808 slave.cpp:909] Agent terminating
I0925 14:33:41.365803 89853952 master.cpp:1366] Framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327 disconnected
I0925 14:33:41.365851 89853952 master.cpp:3230] Deactivating framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327
I0925 14:33:41.365913 89853952 master.cpp:3207] Disconnecting framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327
I0925 14:33:41.365944 89853952 master.cpp:1381] Giving framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327 0ns to failover
I0925 14:33:41.366225 89853952 master.cpp:1251] Agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local) disconnected
I0925 14:33:41.366255 89853952 master.cpp:3267] Disconnecting agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local)
I0925 14:33:41.366299 89853952 master.cpp:3286] Deactivating agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local)
I0925 14:33:41.367537 89853952 hierarchical.cpp:420] Deactivated framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:41.367584 89853952 hierarchical.cpp:795] Agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0 deactivated
I0925 14:33:41.368441 89853952 master.cpp:9261] Framework failover timeout,
removing framework 1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327
I0925 14:33:41.368507 89853952 master.cpp:10197] Removing framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (default) at
[email protected]:63327
I0925 14:33:41.368708 89853952 master.cpp:10932] Updating the state of task
4737334b-33a1-4b0a-898f-d29627c050a7 of framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
I0925 14:33:41.368824 90927104 containerizer.cpp:2455] Destroying container
f0644927-e0ca-44d3-a41d-41a8ef2d7282 in RUNNING state
I0925 14:33:41.368846 90927104 containerizer.cpp:3118] Transitioning the state
of container f0644927-e0ca-44d3-a41d-41a8ef2d7282 from RUNNING to DESTROYING
I0925 14:33:41.369050 90927104 launcher.cpp:166] Asked to destroy container
f0644927-e0ca-44d3-a41d-41a8ef2d7282
I0925 14:33:41.369097 89853952 master.cpp:11030] Removing task
4737334b-33a1-4b0a-898f-d29627c050a7 with resources cpus(allocated: *):2;
mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] of framework 1abbba49-03a4-49da-a395-23ace0ac74cf-0000 on
agent 1abbba49-03a4-49da-a395-23ace0ac74cf-S0 at slave(512)@10.0.49.4:63327
(Jenkinss-Mac-mini.local)
I0925 14:33:41.369916 89317376 hierarchical.cpp:1236] Recovered cpus(allocated:
*):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated:
*):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: {}) on agent 1abbba49-03a4-49da-a395-23ace0ac74cf-S0 from framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:41.370173 89317376 hierarchical.cpp:359] Removed framework
1abbba49-03a4-49da-a395-23ace0ac74cf-0000
I0925 14:33:41.572212 91463680 containerizer.cpp:2957] Container
f0644927-e0ca-44d3-a41d-41a8ef2d7282 has exited
I0925 14:33:41.573349 91463680 provisioner.cpp:597] Ignoring destroy request
for unknown container f0644927-e0ca-44d3-a41d-41a8ef2d7282
I0925 14:33:41.579113 2560127808 master.cpp:1093] Master terminating
I0925 14:33:41.579478 93073408 hierarchical.cpp:637] Removed agent
1abbba49-03a4-49da-a395-23ace0ac74cf-S0
../../3rdparty/libprocess/include/process/gmock.hpp:504: Failure
Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(to,
testing::A<const MessageEvent&>()))...
Expected args: message matcher (24-byte object <31-00 00-00 00-00 00-00
26-00 00-00 00-00 00-00 F0-42 63-BB B2-7F 00-00>, 1-byte object <31>)
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] SlaveRecoveryTest/0.KillQueuedTaskDuringExecutorRegistration,
where TypeParam = mesos::internal::slave::MesosContainerizer (16561 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
