mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Vinod Kone (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (MESOS-7905) GarbageCollectorIntegrationTest.ExitedFramework is flaky
Date Thu, 12 Oct 2017 16:26:01 GMT

     [ https://issues.apache.org/jira/browse/MESOS-7905?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Vinod Kone updated MESOS-7905:
------------------------------
    Sprint: Mesosphere Sprint 62, Mesosphere Sprint 63, Mesosphere Sprint 64, Mesosphere Sprint
66  (was: Mesosphere Sprint 62, Mesosphere Sprint 63, Mesosphere Sprint 64)

> 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
>            Assignee: Kapil Arya
>
> 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)

Mime
View raw message