[ https://issues.apache.org/jira/browse/MESOS-7905?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Kapil Arya reassigned MESOS-7905: --------------------------------- Assignee: (was: Kapil Arya) > GarbageCollectorIntegrationTest.ExitedFramework is flaky > -------------------------------------------------------- > > Key: MESOS-7905 > URL: https://issues.apache.org/jira/browse/MESOS-7905 > Project: Mesos > Issue Type: Bug > Affects Versions: 1.4.0 > Reporter: Vinod Kone > > Observed this on ASF CI. > {code} > [ RUN ] GarbageCollectorIntegrationTest.ExitedFramework > I0818 23:51:42.881799 5882 cluster.cpp:162] Creating default 'local' > authorizer > I0818 23:51:42.884285 5907 master.cpp:442] Master > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba (ef22537e2401) started on > 172.17.0.3:57495 > I0818 23:51:42.884332 5907 master.cpp:444] 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_frameworks="true" --authenticate_http_readonly="true" > --authenticate_http_readwrite="true" --authenticators="crammd5" > --authorizers="local" --credentials="/tmp/rYJzr3/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" --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" > --root_submissions="true" --user_sorter="drf" --version="false" > --webui_dir="/mesos/mesos-1.4.0/_inst/share/mesos/webui" > --work_dir="/tmp/rYJzr3/master" --zk_session_timeout="10secs" > I0818 23:51:42.884627 5907 master.cpp:494] Master only allowing > authenticated frameworks to register > I0818 23:51:42.884644 5907 master.cpp:508] Master only allowing > authenticated agents to register > I0818 23:51:42.884658 5907 master.cpp:521] Master only allowing > authenticated HTTP frameworks to register > I0818 23:51:42.884774 5907 credentials.hpp:37] Loading credentials for > authentication from '/tmp/rYJzr3/credentials' > I0818 23:51:42.885066 5907 master.cpp:566] Using default 'crammd5' > authenticator > I0818 23:51:42.885213 5907 http.cpp:1026] Creating default 'basic' HTTP > authenticator for realm 'mesos-master-readonly' > I0818 23:51:42.885382 5907 http.cpp:1026] Creating default 'basic' HTTP > authenticator for realm 'mesos-master-readwrite' > I0818 23:51:42.885512 5907 http.cpp:1026] Creating default 'basic' HTTP > authenticator for realm 'mesos-master-scheduler' > I0818 23:51:42.885640 5907 master.cpp:646] Authorization enabled > I0818 23:51:42.885818 5903 hierarchical.cpp:171] Initialized hierarchical > allocator process > I0818 23:51:42.886016 5905 whitelist_watcher.cpp:77] No whitelist given > I0818 23:51:42.889050 5908 master.cpp:2163] Elected as the leading master! > I0818 23:51:42.889081 5908 master.cpp:1702] Recovering from registrar > I0818 23:51:42.889387 5909 registrar.cpp:347] Recovering registrar > I0818 23:51:42.889838 5909 registrar.cpp:391] Successfully fetched the > registry (0B) in 409856ns > I0818 23:51:42.889966 5909 registrar.cpp:495] Applied 1 operations in > 38859ns; attempting to update the registry > I0818 23:51:42.890450 5909 registrar.cpp:552] Successfully updated the > registry in 425216ns > I0818 23:51:42.890552 5909 registrar.cpp:424] Successfully recovered > registrar > I0818 23:51:42.890890 5909 master.cpp:1801] Recovered 0 agents from the > registry (129B); allowing 10mins for agents to re-register > I0818 23:51:42.890969 5910 hierarchical.cpp:209] Skipping recovery of > hierarchical allocator: nothing to recover > I0818 23:51:42.895795 5882 process.cpp:3228] Attempting to spawn already > spawned process files@172.17.0.3:57495 > I0818 23:51:42.896057 5882 cluster.cpp:448] Creating default 'local' > authorizer > I0818 23:51:42.897809 5904 slave.cpp:250] Mesos agent started on > (85)@172.17.0.3:57495 > I0818 23:51:42.897848 5904 slave.cpp:251] Flags at startup: --acls="" > --appc_simple_discovery_uri_prefix="http://" > --appc_store_dir="/tmp/GarbageCollectorIntegrationTest_ExitedFramework_DayibR/store/appc" > --authenticate_http_executors="true" --authenticate_http_readonly="true" > --authenticate_http_readwrite="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/GarbageCollectorIntegrationTest_ExitedFramework_DayibR/credential" > --default_role="*" --disallow_sharing_agent_pid_namespace="false" > --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/GarbageCollectorIntegrationTest_ExitedFramework_DayibR/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_secret_key="/tmp/GarbageCollectorIntegrationTest_ExitedFramework_DayibR/executor_secret_key" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/GarbageCollectorIntegrationTest_ExitedFramework_DayibR/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --http_command_executor="false" > --http_credentials="/tmp/GarbageCollectorIntegrationTest_ExitedFramework_DayibR/http_credentials" > --http_heartbeat_interval="30secs" --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem" --launcher="posix" > --launcher_dir="/mesos/mesos-1.4.0/_build/src" --logbufsecs="0" > --logging_level="INFO" --max_completed_executors_per_framework="150" > --oversubscribed_resources_interval="15secs" --perf_duration="10secs" > --perf_interval="1mins" --port="5051" --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" > --runtime_dir="/tmp/GarbageCollectorIntegrationTest_ExitedFramework_DayibR" > --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/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs" > I0818 23:51:42.898264 5904 credentials.hpp:86] Loading credential for > authentication from > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_DayibR/credential' > I0818 23:51:42.898430 5904 slave.cpp:283] Agent using credential for: > test-principal > I0818 23:51:42.898454 5904 credentials.hpp:37] Loading credentials for > authentication from > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_DayibR/http_credentials' > I0818 23:51:42.898720 5904 http.cpp:1026] Creating default 'basic' HTTP > authenticator for realm 'mesos-agent-executor' > I0818 23:51:42.898852 5904 http.cpp:1047] Creating default 'jwt' HTTP > authenticator for realm 'mesos-agent-executor' > I0818 23:51:42.899080 5904 http.cpp:1026] Creating default 'basic' HTTP > authenticator for realm 'mesos-agent-readonly' > I0818 23:51:42.899186 5904 http.cpp:1047] Creating default 'jwt' HTTP > authenticator for realm 'mesos-agent-readonly' > I0818 23:51:42.899368 5904 http.cpp:1026] Creating default 'basic' HTTP > authenticator for realm 'mesos-agent-readwrite' > I0818 23:51:42.899469 5904 http.cpp:1047] Creating default 'jwt' HTTP > authenticator for realm 'mesos-agent-readwrite' > I0818 23:51:42.900774 5904 slave.cpp:565] 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"}] > I0818 23:51:42.900988 5904 slave.cpp:573] Agent attributes: [ ] > I0818 23:51:42.901008 5904 slave.cpp:582] Agent hostname: ef22537e2401 > I0818 23:51:42.901144 5915 status_update_manager.cpp:177] Pausing sending > status updates > I0818 23:51:42.902639 5912 state.cpp:64] Recovering state from > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/meta' > I0818 23:51:42.902976 5906 status_update_manager.cpp:203] Recovering status > update manager > I0818 23:51:42.903412 5902 slave.cpp:6210] Finished recovery > I0818 23:51:42.903928 5902 slave.cpp:6392] Querying resource estimator for > oversubscribable resources > I0818 23:51:42.904240 5915 status_update_manager.cpp:177] Pausing sending > status updates > I0818 23:51:42.904248 5900 slave.cpp:971] New master detected at > master@172.17.0.3:57495 > I0818 23:51:42.904345 5900 slave.cpp:1006] Detecting new master > I0818 23:51:42.904506 5900 slave.cpp:6406] Received oversubscribable > resources {} from the resource estimator > I0818 23:51:42.906594 5914 slave.cpp:1033] Authenticating with master > master@172.17.0.3:57495 > I0818 23:51:42.906664 5914 slave.cpp:1044] Using default CRAM-MD5 > authenticatee > I0818 23:51:42.906903 5904 authenticatee.cpp:121] Creating new client SASL > connection > I0818 23:51:42.907200 5911 master.cpp:7837] Authenticating > slave(85)@172.17.0.3:57495 > I0818 23:51:42.907385 5907 authenticator.cpp:414] Starting authentication > session for crammd5-authenticatee(188)@172.17.0.3:57495 > I0818 23:51:42.907665 5912 authenticator.cpp:98] Creating new server SASL > connection > I0818 23:51:42.907923 5913 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > I0818 23:51:42.908012 5913 authenticatee.cpp:239] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0818 23:51:42.908123 5903 authenticator.cpp:204] Received SASL > authentication start > I0818 23:51:42.908176 5903 authenticator.cpp:326] Authentication requires > more steps > I0818 23:51:42.908260 5903 authenticatee.cpp:259] Received SASL > authentication step > I0818 23:51:42.908351 5903 authenticator.cpp:232] Received SASL > authentication step > I0818 23:51:42.908380 5903 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: 'ef22537e2401' server FQDN: 'ef22537e2401' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0818 23:51:42.908394 5903 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I0818 23:51:42.908434 5903 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0818 23:51:42.908454 5903 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: 'ef22537e2401' server FQDN: 'ef22537e2401' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0818 23:51:42.908466 5903 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0818 23:51:42.908475 5903 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0818 23:51:42.908489 5903 authenticator.cpp:318] Authentication success > I0818 23:51:42.908646 5908 authenticatee.cpp:299] Authentication success > I0818 23:51:42.908715 5909 master.cpp:7867] Successfully authenticated > principal 'test-principal' at slave(85)@172.17.0.3:57495 > I0818 23:51:42.908787 5902 authenticator.cpp:432] Authentication session > cleanup for crammd5-authenticatee(188)@172.17.0.3:57495 > I0818 23:51:42.909061 5908 slave.cpp:1128] Successfully authenticated with > master master@172.17.0.3:57495 > I0818 23:51:42.909279 5908 slave.cpp:1572] Will retry registration in > 12.848578ms if necessary > I0818 23:51:42.909488 5914 master.cpp:5712] Received register agent message > from slave(85)@172.17.0.3:57495 (ef22537e2401) > I0818 23:51:42.909528 5914 master.cpp:3803] Authorizing agent with principal > 'test-principal' > I0818 23:51:42.909931 5911 master.cpp:5772] Authorized registration of agent > at slave(85)@172.17.0.3:57495 (ef22537e2401) > I0818 23:51:42.910024 5911 master.cpp:5865] Registering agent at > slave(85)@172.17.0.3:57495 (ef22537e2401) with id > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 > I0818 23:51:42.910446 5907 registrar.cpp:495] Applied 1 operations in > 77087ns; attempting to update the registry > I0818 23:51:42.911104 5907 registrar.cpp:552] Successfully updated the > registry in 580096ns > I0818 23:51:42.911363 5907 master.cpp:5912] Admitted agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) > I0818 23:51:42.911929 5915 slave.cpp:4887] Received ping from > slave-observer(78)@172.17.0.3:57495 > I0818 23:51:42.911926 5907 master.cpp:5943] Registered agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) with > [{"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"}] > I0818 23:51:42.912271 5915 slave.cpp:1174] Registered with master > master@172.17.0.3:57495; given agent ID > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 > I0818 23:51:42.912406 5902 hierarchical.cpp:593] Added agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 (ef22537e2401) with cpus:2; mem:1024; > disk:1024; ports:[31000-32000] (allocated: {}) > I0818 23:51:42.912451 5900 status_update_manager.cpp:184] Resuming sending > status updates > I0818 23:51:42.912685 5902 hierarchical.cpp:1925] No allocations performed > I0818 23:51:42.912727 5915 slave.cpp:1194] Checkpointing SlaveInfo to > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/meta/slaves/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0/slave.info' > I0818 23:51:42.912748 5902 hierarchical.cpp:1468] Performed allocation for 1 > agents in 186529ns > I0818 23:51:42.913038 5882 process.cpp:3228] Attempting to spawn already > spawned process version@172.17.0.3:57495 > I0818 23:51:42.913131 5915 slave.cpp:1232] Forwarding total oversubscribed > resources {} > I0818 23:51:42.913389 5905 master.cpp:6688] Received update of agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) with total oversubscribed resources {} > I0818 23:51:42.913751 5905 hierarchical.cpp:660] Agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 (ef22537e2401) updated with total > resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] > I0818 23:51:42.914408 5882 sched.cpp:232] Version: 1.4.0 > I0818 23:51:42.914973 5900 sched.cpp:336] New master detected at > master@172.17.0.3:57495 > I0818 23:51:42.915086 5900 sched.cpp:407] Authenticating with master > master@172.17.0.3:57495 > I0818 23:51:42.915112 5900 sched.cpp:414] Using default CRAM-MD5 > authenticatee > I0818 23:51:42.915390 5904 authenticatee.cpp:121] Creating new client SASL > connection > I0818 23:51:42.915645 5904 master.cpp:7837] Authenticating > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 > I0818 23:51:42.915757 5906 authenticator.cpp:414] Starting authentication > session for crammd5-authenticatee(189)@172.17.0.3:57495 > I0818 23:51:42.916033 5915 authenticator.cpp:98] Creating new server SASL > connection > I0818 23:51:42.916265 5912 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > I0818 23:51:42.916301 5912 authenticatee.cpp:239] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0818 23:51:42.916404 5912 authenticator.cpp:204] Received SASL > authentication start > I0818 23:51:42.916460 5912 authenticator.cpp:326] Authentication requires > more steps > I0818 23:51:42.916585 5905 authenticatee.cpp:259] Received SASL > authentication step > I0818 23:51:42.916739 5909 authenticator.cpp:232] Received SASL > authentication step > I0818 23:51:42.916781 5909 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: 'ef22537e2401' server FQDN: 'ef22537e2401' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0818 23:51:42.916805 5909 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I0818 23:51:42.916852 5909 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0818 23:51:42.916893 5909 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: 'ef22537e2401' server FQDN: 'ef22537e2401' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0818 23:51:42.916916 5909 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0818 23:51:42.916939 5909 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0818 23:51:42.916970 5909 authenticator.cpp:318] Authentication success > I0818 23:51:42.917076 5908 authenticatee.cpp:299] Authentication success > I0818 23:51:42.917136 5907 master.cpp:7867] Successfully authenticated > principal 'test-principal' at > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 > I0818 23:51:42.917186 5901 authenticator.cpp:432] Authentication session > cleanup for crammd5-authenticatee(189)@172.17.0.3:57495 > I0818 23:51:42.917417 5910 sched.cpp:513] Successfully authenticated with > master master@172.17.0.3:57495 > I0818 23:51:42.917449 5910 sched.cpp:836] Sending SUBSCRIBE call to > master@172.17.0.3:57495 > I0818 23:51:42.917596 5910 sched.cpp:869] Will retry registration in > 256.866833ms if necessary > I0818 23:51:42.917779 5902 master.cpp:2894] Received SUBSCRIBE call for > framework 'default' at > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 > I0818 23:51:42.917810 5902 master.cpp:2228] Authorizing framework principal > 'test-principal' to receive offers for roles '{ * }' > I0818 23:51:42.918273 5904 master.cpp:2974] Subscribing framework default > with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] > I0818 23:51:42.918817 5904 sched.cpp:759] Framework registered with > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.918862 5904 sched.cpp:773] Scheduler::registered took 27120ns > I0818 23:51:42.919013 5906 hierarchical.cpp:303] Added framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.920289 5906 hierarchical.cpp:2015] No inverse offers to send > out! > I0818 23:51:42.920361 5906 hierarchical.cpp:1468] Performed allocation for 1 > agents in 1.195621ms > I0818 23:51:42.920827 5905 master.cpp:7667] Sending 1 offers to framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 (default) at > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 > I0818 23:51:42.922165 5909 sched.cpp:933] Scheduler::resourceOffers took > 893885ns > I0818 23:51:42.923591 5908 master.cpp:9164] Removing offer > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-O0 > I0818 23:51:42.923743 5908 master.cpp:4153] Processing ACCEPT call for > offers: [ 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-O0 ] on agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) for framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > (default) at scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 > I0818 23:51:42.923858 5908 master.cpp:3530] Authorizing framework principal > 'test-principal' to launch task 0 > W0818 23:51:42.925671 5908 validation.cpp:1294] Executor 'default' for task > '0' uses less CPUs (None) than the minimum required (0.01). Please update > your executor, as this will be mandatory in future releases. > W0818 23:51:42.925716 5908 validation.cpp:1306] Executor 'default' for task > '0' uses less memory (None) than the minimum required (32MB). Please update > your executor, as this will be mandatory in future releases. > I0818 23:51:42.926206 5908 master.cpp:9724] Adding task 0 with resources > [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}] > on agent 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at > slave(85)@172.17.0.3:57495 (ef22537e2401) > I0818 23:51:42.926612 5908 master.cpp:4816] Launching task 0 of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 (default) at > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 with > resources > [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}] > on agent 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at > slave(85)@172.17.0.3:57495 (ef22537e2401) > I0818 23:51:42.927239 5902 slave.cpp:1701] Got assigned task '0' for > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.927909 5902 slave.cpp:1982] Authorizing task '0' for > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.927979 5902 slave.cpp:6709] Authorizing framework principal > 'test-principal' to launch task 0 > I0818 23:51:42.928616 5913 hierarchical.cpp:887] Updated allocation of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 on agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 from cpus(allocated: *):2; > mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: > *):[31000-32000] to cpus(allocated: *):2; mem(allocated: *):1024; > disk(allocated: *):1024; ports(allocated: *):[31000-32000] > I0818 23:51:42.928804 5906 slave.cpp:2169] Launching task '0' for framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.929502 5906 paths.cpp:578] Trying to chown > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/slaves/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0/frameworks/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000/executors/default/runs/10b7ad42-ede3-417a-9df1-5cc55d66676d' > to user 'mesos' > I0818 23:51:42.929594 5913 hierarchical.cpp:1152] Recovered ports(allocated: > *):[31000-32000]; disk(allocated: *):1024 (total: cpus:2; mem:1024; > disk:1024; ports:[31000-32000], allocated: cpus(allocated: *):2; > mem(allocated: *):1024) on agent 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 from > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.929667 5913 hierarchical.cpp:1189] Framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 filtered agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 for 5secs > I0818 23:51:42.929774 5906 slave.cpp:7165] Launching executor 'default' of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 with resources [] in work > directory > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/slaves/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0/frameworks/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000/executors/default/runs/10b7ad42-ede3-417a-9df1-5cc55d66676d' > I0818 23:51:42.930680 5906 slave.cpp:2398] Queued task '0' for executor > 'default' of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.930793 5906 slave.cpp:924] Successfully attached file > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/slaves/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0/frameworks/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000/executors/default/runs/10b7ad42-ede3-417a-9df1-5cc55d66676d' > I0818 23:51:42.930850 5906 slave.cpp:924] Successfully attached file > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/slaves/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0/frameworks/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000/executors/default/runs/10b7ad42-ede3-417a-9df1-5cc55d66676d' > I0818 23:51:42.931109 5906 slave.cpp:2856] Launching container > 10b7ad42-ede3-417a-9df1-5cc55d66676d for executor 'default' of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.934149 5900 process.cpp:3228] Attempting to spawn already > spawned process version@172.17.0.3:57495 > I0818 23:51:42.934360 5900 exec.cpp:162] Version: 1.4.0 > I0818 23:51:42.934665 5901 exec.cpp:212] Executor started at: > executor(13)@172.17.0.3:57495 with pid 5882 > I0818 23:51:42.934859 5901 slave.cpp:3881] Got registration for executor > 'default' of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 from > executor(13)@172.17.0.3:57495 > I0818 23:51:42.935279 5908 exec.cpp:237] Executor registered on agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 > I0818 23:51:42.935379 5908 exec.cpp:249] Executor::registered took 83778ns > I0818 23:51:42.935712 5901 slave.cpp:2603] Sending queued task '0' to > executor 'default' of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 at > executor(13)@172.17.0.3:57495 > I0818 23:51:42.936051 5905 exec.cpp:331] Executor asked to run task '0' > I0818 23:51:42.936159 5905 exec.cpp:340] Executor::launchTask took 89382ns > I0818 23:51:42.936336 5905 exec.cpp:571] Executor sending status update > TASK_RUNNING (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for task 0 of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.936666 5907 slave.cpp:4345] Handling status update > TASK_RUNNING (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for task 0 of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 from > executor(13)@172.17.0.3:57495 > I0818 23:51:42.937268 5910 status_update_manager.cpp:323] Received status > update TASK_RUNNING (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for task 0 > of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.937330 5910 status_update_manager.cpp:500] Creating > StatusUpdate stream for task 0 of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.937841 5910 status_update_manager.cpp:377] Forwarding update > TASK_RUNNING (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for task 0 of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 to the agent > I0818 23:51:42.938212 5915 slave.cpp:4797] Forwarding the update > TASK_RUNNING (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for task 0 of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 to master@172.17.0.3:57495 > I0818 23:51:42.938465 5915 slave.cpp:4691] Status update manager > successfully handled status update TASK_RUNNING (UUID: > b858571e-8f64-4af4-89a0-b196149d9340) for task 0 of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.938529 5915 slave.cpp:4707] Sending acknowledgement for > status update TASK_RUNNING (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for > task 0 of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 to > executor(13)@172.17.0.3:57495 > I0818 23:51:42.938661 5902 master.cpp:6846] Status update TASK_RUNNING > (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for task 0 of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 from agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) > I0818 23:51:42.938697 5908 exec.cpp:388] Executor received status update > acknowledgement b858571e-8f64-4af4-89a0-b196149d9340 for task 0 of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.938755 5902 master.cpp:6908] Forwarding status update > TASK_RUNNING (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for task 0 of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.938997 5902 master.cpp:8933] Updating the state of task 0 of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 (latest state: > TASK_RUNNING, status update state: TASK_RUNNING) > I0818 23:51:42.939317 5903 sched.cpp:1041] Scheduler::statusUpdate took > 129724ns > I0818 23:51:42.939702 5882 sched.cpp:2021] Asked to stop the driver > I0818 23:51:42.939810 5914 sched.cpp:1203] Stopping framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.939839 5909 master.cpp:5477] Processing ACKNOWLEDGE call > b858571e-8f64-4af4-89a0-b196149d9340 for task 0 of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 (default) at > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 on agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 > I0818 23:51:42.940078 5909 master.cpp:8348] Processing TEARDOWN call for > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 (default) at > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 > I0818 23:51:42.940134 5909 master.cpp:8360] Removing framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 (default) at > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 > I0818 23:51:42.940178 5909 master.cpp:3264] Deactivating framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 (default) at > scheduler-eb63a835-dba7-4484-9115-0491bd47d3c1@172.17.0.3:57495 > I0818 23:51:42.940284 5910 status_update_manager.cpp:395] Received status > update acknowledgement (UUID: b858571e-8f64-4af4-89a0-b196149d9340) for task > 0 of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.940336 5914 hierarchical.cpp:412] Deactivated framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.940423 5909 master.cpp:8933] Updating the state of task 0 of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 (latest state: > TASK_KILLED, status update state: TASK_KILLED) > I0818 23:51:42.940440 5908 slave.cpp:3159] Asked to shut down framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 by master@172.17.0.3:57495 > I0818 23:51:42.940481 5908 slave.cpp:3184] Shutting down framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.940532 5908 slave.cpp:5651] Shutting down executor 'default' > of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 at > executor(13)@172.17.0.3:57495 > I0818 23:51:42.940701 5904 exec.cpp:435] Executor asked to shutdown > I0818 23:51:42.940731 5908 slave.cpp:3609] Status update manager > successfully handled status update acknowledgement (UUID: > b858571e-8f64-4af4-89a0-b196149d9340) for task 0 of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.940995 5904 exec.cpp:450] Executor::shutdown took 34798ns > I0818 23:51:42.940861 5909 master.cpp:9027] Removing task 0 with resources > [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}] > of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 on agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) > I0818 23:51:42.941097 5902 hierarchical.cpp:1152] Recovered cpus(allocated: > *):2; mem(allocated: *):1024 (total: cpus:2; mem:1024; disk:1024; > ports:[31000-32000], allocated: {}) on agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 from framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.941233 5904 slave.cpp:4929] Got exited event for > executor(13)@172.17.0.3:57495 > I0818 23:51:42.941262 5909 master.cpp:9056] Removing executor 'default' with > resources [] of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 on agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) > I0818 23:51:42.941917 5907 hierarchical.cpp:355] Removed framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:42.942914 5905 hierarchical.cpp:1925] No allocations performed > I0818 23:51:42.942980 5905 hierarchical.cpp:1468] Performed allocation for 1 > agents in 190597ns > ../../src/tests/gc_tests.cpp:467: Failure > Failed to wait 15secs for schedule > I0818 23:51:57.951961 5914 slave.cpp:5329] Executor 'default' of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 exited with status 0 > I0818 23:51:57.952190 5914 slave.cpp:5429] Cleaning up executor 'default' of > framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 at > executor(13)@172.17.0.3:57495 > W0818 23:51:57.952453 5900 master.cpp:6963] Ignoring unknown exited executor > 'default' of framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 on agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) > I0818 23:51:57.952602 5915 gc.cpp:59] Scheduling > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/slaves/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0/frameworks/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000/executors/default/runs/10b7ad42-ede3-417a-9df1-5cc55d66676d' > for gc 1.00002324719238weeks in the future > I0818 23:51:57.952734 5914 slave.cpp:5525] Cleaning up framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:57.952812 5915 gc.cpp:59] Scheduling > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/slaves/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0/frameworks/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000/executors/default' > for gc 1.00002324719238weeks in the future > I0818 23:51:57.952880 5905 status_update_manager.cpp:285] Closing status > update streams for framework 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:57.952953 5905 status_update_manager.cpp:531] Cleaning up status > update stream for task 0 of framework > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000 > I0818 23:51:57.952993 5910 gc.cpp:59] Scheduling > '/tmp/GarbageCollectorIntegrationTest_ExitedFramework_NMAqjs/slaves/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0/frameworks/6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-0000' > for gc 1.00002324719238weeks in the future > I0818 23:51:57.953797 5908 slave.cpp:843] Agent terminating > I0818 23:51:57.954202 5904 master.cpp:1318] Agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) disconnected > I0818 23:51:57.954269 5904 master.cpp:3301] Disconnecting agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) > I0818 23:51:57.954423 5904 master.cpp:3320] Deactivating agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 at slave(85)@172.17.0.3:57495 > (ef22537e2401) > I0818 23:51:57.954895 5906 hierarchical.cpp:690] Agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 deactivated > I0818 23:51:57.959347 5882 master.cpp:1160] Master terminating > I0818 23:51:57.960389 5911 hierarchical.cpp:626] Removed agent > 6d3f4c59-27e2-4701-9f7f-7c1f301e7fba-S0 > [ FAILED ] GarbageCollectorIntegrationTest.ExitedFramework (15085 ms) > {code} -- This message was sent by Atlassian JIRA (v6.4.14#64029)