[
https://issues.apache.org/jira/browse/MESOS-6948?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15832393#comment-15832393
]
Anand Mazumdar commented on MESOS-6948:
---------------------------------------
This showed up with an identical stack trace on ASF CI.
{code}
[ RUN ] ContentType/AgentAPITest.LaunchNestedContainerSession/1
I0120 20:51:26.939275 26158 cluster.cpp:160] Creating default 'local' authorizer
I0120 20:51:26.940529 26164 master.cpp:383] Master
2b435d8e-3792-458e-96ff-0ecff4b4aa54 (9a52de5d9dcd) started on 172.17.0.3:38943
I0120 20:51:26.940562 26164 master.cpp:385] 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/rLq2TT/credentials"
--framework_sorter="drf" --help="false" --hostname_lookup="true"
--http_authenticators="basic" --http_framework_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--quiet="false" --recovery_agent_removal_limit="100%" --registry="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="/usr/local/share/mesos/webui" --work_dir="/tmp/rLq2TT/master"
--zk_session_timeout="10secs"
I0120 20:51:26.940747 26164 master.cpp:435] Master only allowing authenticated
frameworks to register
I0120 20:51:26.940754 26164 master.cpp:449] Master only allowing authenticated
agents to register
I0120 20:51:26.940757 26164 master.cpp:462] Master only allowing authenticated
HTTP frameworks to register
I0120 20:51:26.940762 26164 credentials.hpp:37] Loading credentials for
authentication from '/tmp/rLq2TT/credentials'
I0120 20:51:26.940891 26164 master.cpp:507] Using default 'crammd5'
authenticator
I0120 20:51:26.940939 26164 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0120 20:51:26.940978 26164 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0120 20:51:26.941035 26164 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0120 20:51:26.941082 26164 master.cpp:587] Authorization enabled
I0120 20:51:26.941186 26167 hierarchical.cpp:151] Initialized hierarchical
allocator process
I0120 20:51:26.941215 26172 whitelist_watcher.cpp:77] No whitelist given
I0120 20:51:26.941815 26164 master.cpp:2119] Elected as the leading master!
I0120 20:51:26.941829 26164 master.cpp:1641] Recovering from registrar
I0120 20:51:26.941910 26170 registrar.cpp:329] Recovering registrar
I0120 20:51:26.942194 26173 registrar.cpp:362] Successfully fetched the
registry (0B) in 175872ns
I0120 20:51:26.942227 26173 registrar.cpp:461] Applied 1 operations in 5497ns;
attempting to update the registry
I0120 20:51:26.942468 26172 registrar.cpp:506] Successfully updated the
registry in 222976ns
I0120 20:51:26.942519 26172 registrar.cpp:392] Successfully recovered registrar
I0120 20:51:26.942750 26164 hierarchical.cpp:178] Skipping recovery of
hierarchical allocator: nothing to recover
I0120 20:51:26.942751 26165 master.cpp:1757] Recovered 0 agents from the
registry (129B); allowing 10mins for agents to re-register
I0120 20:51:26.943758 26158 containerizer.cpp:220] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
W0120 20:51:26.944063 26158 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges, but is running as user mesos
W0120 20:51:26.944141 26158 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
I0120 20:51:26.945397 26158 cluster.cpp:446] Creating default 'local' authorizer
I0120 20:51:26.945864 26163 slave.cpp:209] Mesos agent started on
(579)@172.17.0.3:38943
I0120 20:51:26.945879 26163 slave.cpp:210] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --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/ContentType_AgentAPITest_LaunchNestedContainerSession_1_tIgxW4/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="<a
href='https://registry-1.docker.io'>https://registry-1.docker.io</a>"
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_tIgxW4/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--http_command_executor="false"
--http_credentials="/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_tIgxW4/http_credentials"
--http_heartbeat_interval="30secs" --image_provisioner_backend="copy"
--initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
--launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
--recover="reconnect" --recovery_timeout="15mins"
--registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true"
--runtime_dir="/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_tIgxW4"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu"
I0120 20:51:26.946244 26163 credentials.hpp:86] Loading credential for
authentication from
'/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_tIgxW4/credential'
I0120 20:51:26.946334 26163 slave.cpp:352] Agent using credential for:
test-principal
I0120 20:51:26.946365 26158 sched.cpp:232] Version: 1.2.0
I0120 20:51:26.946367 26163 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_tIgxW4/http_credentials'
I0120 20:51:26.946568 26163 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0120 20:51:26.946611 26163 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0120 20:51:26.946804 26168 sched.cpp:336] New master detected at
[email protected]:38943
I0120 20:51:26.946853 26168 sched.cpp:407] Authenticating with master
[email protected]:38943
I0120 20:51:26.946868 26168 sched.cpp:414] Using default CRAM-MD5 authenticatee
I0120 20:51:26.946948 26170 authenticatee.cpp:121] Creating new client SASL
connection
I0120 20:51:26.947038 26163 slave.cpp:539] Agent resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0120 20:51:26.947078 26163 slave.cpp:547] Agent attributes: [ ]
I0120 20:51:26.947083 26163 slave.cpp:552] Agent hostname: 9a52de5d9dcd
I0120 20:51:26.947129 26170 master.cpp:6842] Authenticating
[email protected]:38943
I0120 20:51:26.947187 26171 status_update_manager.cpp:177] Pausing sending
status updates
I0120 20:51:26.947300 26166 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1119)@172.17.0.3:38943
I0120 20:51:26.947371 26168 authenticator.cpp:98] Creating new server SASL
connection
I0120 20:51:26.947409 26170 state.cpp:60] Recovering state from
'/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu/meta'
I0120 20:51:26.947633 26173 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0120 20:51:26.947662 26173 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0120 20:51:26.947671 26168 status_update_manager.cpp:203] Recovering status
update manager
I0120 20:51:26.947749 26167 authenticator.cpp:204] Received SASL authentication
start
I0120 20:51:26.947787 26171 containerizer.cpp:599] Recovering containerizer
I0120 20:51:26.947809 26167 authenticator.cpp:326] Authentication requires more
steps
I0120 20:51:26.947860 26167 authenticatee.cpp:259] Received SASL authentication
step
I0120 20:51:26.947950 26174 authenticator.cpp:232] Received SASL authentication
step
I0120 20:51:26.948001 26174 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '9a52de5d9dcd' server FQDN: '9a52de5d9dcd'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0120 20:51:26.948014 26174 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0120 20:51:26.948031 26174 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0120 20:51:26.948072 26174 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '9a52de5d9dcd' server FQDN: '9a52de5d9dcd'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0120 20:51:26.948087 26174 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0120 20:51:26.948092 26174 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0120 20:51:26.948106 26174 authenticator.cpp:318] Authentication success
I0120 20:51:26.948158 26167 authenticatee.cpp:299] Authentication success
I0120 20:51:26.948194 26164 master.cpp:6872] Successfully authenticated
principal 'test-principal' at
[email protected]:38943
I0120 20:51:26.948288 26161 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1119)@172.17.0.3:38943
I0120 20:51:26.948405 26164 sched.cpp:513] Successfully authenticated with
master [email protected]:38943
I0120 20:51:26.948421 26164 sched.cpp:836] Sending SUBSCRIBE call to
[email protected]:38943
I0120 20:51:26.948474 26164 sched.cpp:869] Will retry registration in
683.987022ms if necessary
I0120 20:51:26.948523 26161 master.cpp:2707] Received SUBSCRIBE call for
framework 'default' at
[email protected]:38943
I0120 20:51:26.948544 26161 master.cpp:2155] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0120 20:51:26.948689 26172 master.cpp:2783] Subscribing framework default with
checkpointing disabled and capabilities [ ]
I0120 20:51:26.948720 26167 provisioner.cpp:251] Provisioner recovery complete
I0120 20:51:26.948846 26172 sched.cpp:759] Framework registered with
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:26.948894 26172 sched.cpp:773] Scheduler::registered took 27801ns
I0120 20:51:26.949010 26169 slave.cpp:5422] Finished recovery
I0120 20:51:26.949050 26163 hierarchical.cpp:271] Added framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:26.949074 26163 hierarchical.cpp:1677] No allocations performed
I0120 20:51:26.949084 26163 hierarchical.cpp:1772] No inverse offers to send
out!
I0120 20:51:26.949098 26163 hierarchical.cpp:1279] Performed allocation for 0
agents in 33483ns
I0120 20:51:26.949394 26169 slave.cpp:5596] Querying resource estimator for
oversubscribable resources
I0120 20:51:26.949549 26168 slave.cpp:929] New master detected at
[email protected]:38943
I0120 20:51:26.949561 26171 status_update_manager.cpp:177] Pausing sending
status updates
I0120 20:51:26.949607 26168 slave.cpp:964] Detecting new master
I0120 20:51:26.949692 26168 slave.cpp:5610] Received oversubscribable resources
{} from the resource estimator
I0120 20:51:26.953790 26163 slave.cpp:991] Authenticating with master
[email protected]:38943
I0120 20:51:26.953835 26163 slave.cpp:1002] Using default CRAM-MD5 authenticatee
I0120 20:51:26.953943 26167 authenticatee.cpp:121] Creating new client SASL
connection
I0120 20:51:26.954089 26163 master.cpp:6842] Authenticating
slave(579)@172.17.0.3:38943
I0120 20:51:26.954202 26160 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1120)@172.17.0.3:38943
I0120 20:51:26.954330 26167 authenticator.cpp:98] Creating new server SASL
connection
I0120 20:51:26.954530 26170 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0120 20:51:26.954546 26170 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0120 20:51:26.954576 26170 authenticator.cpp:204] Received SASL authentication
start
I0120 20:51:26.954615 26170 authenticator.cpp:326] Authentication requires more
steps
I0120 20:51:26.954668 26164 authenticatee.cpp:259] Received SASL authentication
step
I0120 20:51:26.954777 26165 authenticator.cpp:232] Received SASL authentication
step
I0120 20:51:26.954812 26165 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '9a52de5d9dcd' server FQDN: '9a52de5d9dcd'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0120 20:51:26.954830 26165 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0120 20:51:26.954854 26165 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0120 20:51:26.954865 26165 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '9a52de5d9dcd' server FQDN: '9a52de5d9dcd'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0120 20:51:26.954874 26165 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0120 20:51:26.954883 26165 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0120 20:51:26.954893 26165 authenticator.cpp:318] Authentication success
I0120 20:51:26.954946 26170 authenticatee.cpp:299] Authentication success
I0120 20:51:26.954972 26161 master.cpp:6872] Successfully authenticated
principal 'test-principal' at slave(579)@172.17.0.3:38943
I0120 20:51:26.954990 26169 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1120)@172.17.0.3:38943
I0120 20:51:26.955232 26172 slave.cpp:1086] Successfully authenticated with
master [email protected]:38943
I0120 20:51:26.955298 26172 slave.cpp:1508] Will retry registration in
14.969835ms if necessary
I0120 20:51:26.955387 26168 master.cpp:5232] Registering agent at
slave(579)@172.17.0.3:38943 (9a52de5d9dcd) with id
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0
I0120 20:51:26.955548 26165 registrar.cpp:461] Applied 1 operations in 19695ns;
attempting to update the registry
I0120 20:51:26.955932 26169 registrar.cpp:506] Successfully updated the
registry in 356096ns
I0120 20:51:26.956336 26159 slave.cpp:4286] Received ping from
slave-observer(524)@172.17.0.3:38943
I0120 20:51:26.956328 26166 master.cpp:5303] Registered agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 at slave(579)@172.17.0.3:38943
(9a52de5d9dcd) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0120 20:51:26.956439 26159 slave.cpp:1132] Registered with master
[email protected]:38943; given agent ID 2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0
I0120 20:51:26.956434 26164 hierarchical.cpp:478] Added agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 (9a52de5d9dcd) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I0120 20:51:26.956465 26159 fetcher.cpp:90] Clearing fetcher cache
I0120 20:51:26.956569 26161 status_update_manager.cpp:184] Resuming sending
status updates
I0120 20:51:26.956748 26164 hierarchical.cpp:1772] No inverse offers to send
out!
I0120 20:51:26.956774 26164 hierarchical.cpp:1302] Performed allocation for
agent 2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 in 299624ns
I0120 20:51:26.956792 26159 slave.cpp:1160] Checkpointing SlaveInfo to
'/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu/meta/slaves/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0/slave.info'
I0120 20:51:26.956919 26165 master.cpp:6671] Sending 1 offers to framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 (default) at
[email protected]:38943
I0120 20:51:26.957151 26159 slave.cpp:1198] Forwarding total oversubscribed
resources {}
I0120 20:51:26.957171 26170 sched.cpp:933] Scheduler::resourceOffers took
57116ns
I0120 20:51:26.957227 26159 master.cpp:5710] Received update of agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 at slave(579)@172.17.0.3:38943
(9a52de5d9dcd) with total oversubscribed resources {}
I0120 20:51:26.957355 26161 hierarchical.cpp:548] Agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 (9a52de5d9dcd) updated with
oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0120 20:51:26.957440 26161 hierarchical.cpp:1677] No allocations performed
I0120 20:51:26.957458 26161 hierarchical.cpp:1772] No inverse offers to send
out!
I0120 20:51:26.957480 26161 hierarchical.cpp:1302] Performed allocation for
agent 2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 in 61947ns
I0120 20:51:26.957870 26174 master.cpp:3661] Processing ACCEPT call for offers:
[ 2b435d8e-3792-458e-96ff-0ecff4b4aa54-O0 ] on agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 at slave(579)@172.17.0.3:38943
(9a52de5d9dcd) for framework 2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
(default) at [email protected]:38943
I0120 20:51:26.957916 26174 master.cpp:3249] Authorizing framework principal
'test-principal' to launch task 7e4c1b3d-2297-4d19-8cba-f55ae009201d
I0120 20:51:26.958585 26170 master.cpp:8584] Adding task
7e4c1b3d-2297-4d19-8cba-f55ae009201d with resources cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000] on agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 at slave(579)@172.17.0.3:38943
(9a52de5d9dcd)
I0120 20:51:26.958679 26170 master.cpp:4311] Launching task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 (default) at
[email protected]:38943 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 at slave(579)@172.17.0.3:38943
(9a52de5d9dcd)
I0120 20:51:26.959043 26162 slave.cpp:1576] Got assigned task
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' for framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:26.959344 26162 slave.cpp:1736] Launching task
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' for framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:26.959897 26162 paths.cpp:547] Trying to chown
'/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu/slaves/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0/frameworks/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000/executors/7e4c1b3d-2297-4d19-8cba-f55ae009201d/runs/51822148-9c1d-40e6-b255-d788c3dca267'
to user 'mesos'
I0120 20:51:26.960147 26162 slave.cpp:6331] Launching executor
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu/slaves/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0/frameworks/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000/executors/7e4c1b3d-2297-4d19-8cba-f55ae009201d/runs/51822148-9c1d-40e6-b255-d788c3dca267'
I0120 20:51:26.960433 26173 containerizer.cpp:992] Starting container
51822148-9c1d-40e6-b255-d788c3dca267 for executor
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:26.960469 26162 slave.cpp:2058] Queued task
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' for executor
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:26.960530 26162 slave.cpp:882] Successfully attached file
'/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu/slaves/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0/frameworks/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000/executors/7e4c1b3d-2297-4d19-8cba-f55ae009201d/runs/51822148-9c1d-40e6-b255-d788c3dca267'
I0120 20:51:26.962117 26167 containerizer.cpp:1541] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/build\/src"],"shell":false,"value":"\/mesos\/build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","value":"172.17.0.3:38943"},{"name":"MESOS_CHECKPOINT","value":"0"},{"name":"MESOS_DIRECTORY","value":"\/tmp\/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu\/slaves\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0\/frameworks\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000\/executors\/7e4c1b3d-2297-4d19-8cba-f55ae009201d\/runs\/51822148-9c1d-40e6-b255-d788c3dca267"},{"name":"MESOS_EXECUTOR_ID","value":"7e4c1b3d-2297-4d19-8cba-f55ae009201d"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","value":"2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","value":"0"},{"name":"MESOS_SLAVE_ID","value":"2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0"},{"name":"MESOS_SLAVE_PID","value":"slave(579)@172.17.0.3:38943"},{"name":"MESOS_SANDBOX","value":"\/tmp\/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu\/slaves\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0\/frameworks\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000\/executors\/7e4c1b3d-2297-4d19-8cba-f55ae009201d\/runs\/51822148-9c1d-40e6-b255-d788c3dca267"}]},"err":{"path":"\/tmp\/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu\/slaves\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0\/frameworks\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000\/executors\/7e4c1b3d-2297-4d19-8cba-f55ae009201d\/runs\/51822148-9c1d-40e6-b255-d788c3dca267\/stderr","type":"PATH"},"out":{"path":"\/tmp\/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu\/slaves\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0\/frameworks\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000\/executors\/7e4c1b3d-2297-4d19-8cba-f55ae009201d\/runs\/51822148-9c1d-40e6-b255-d788c3dca267\/stdout","type":"PATH"},"user":"mesos","working_directory":"\/tmp\/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu\/slaves\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0\/frameworks\/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000\/executors\/7e4c1b3d-2297-4d19-8cba-f55ae009201d\/runs\/51822148-9c1d-40e6-b255-d788c3dca267"}"
--pipe_read="9" --pipe_write="10"
--runtime_directory="/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_tIgxW4/containers/51822148-9c1d-40e6-b255-d788c3dca267"
--unshare_namespace_mnt="false"'
I0120 20:51:26.964438 26167 launcher.cpp:135] Forked child with pid '30032' for
container '51822148-9c1d-40e6-b255-d788c3dca267'
I0120 20:51:26.966521 26170 fetcher.cpp:349] Starting to fetch URIs for
container: 51822148-9c1d-40e6-b255-d788c3dca267, directory:
/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu/slaves/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0/frameworks/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000/executors/7e4c1b3d-2297-4d19-8cba-f55ae009201d/runs/51822148-9c1d-40e6-b255-d788c3dca267
I0120 20:51:27.064268 26172 slave.cpp:3325] Got registration for executor
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 from executor(1)@172.17.0.3:45428
I0120 20:51:27.065098 26159 slave.cpp:2271] Sending queued task
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' to executor
'7e4c1b3d-2297-4d19-8cba-f55ae009201d' of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 at executor(1)@172.17.0.3:45428
I0120 20:51:27.071434 26173 slave.cpp:3756] Handling status update TASK_RUNNING
(UUID: fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 from executor(1)@172.17.0.3:45428
I0120 20:51:27.071974 26167 status_update_manager.cpp:323] Received status
update TASK_RUNNING (UUID: fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:27.072001 26167 status_update_manager.cpp:500] Creating
StatusUpdate stream for task 7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:27.072142 26167 status_update_manager.cpp:377] Forwarding update
TASK_RUNNING (UUID: fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 to the agent
I0120 20:51:27.072268 26160 slave.cpp:4196] Forwarding the update TASK_RUNNING
(UUID: fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 to [email protected]:38943
I0120 20:51:27.072345 26160 slave.cpp:4090] Status update manager successfully
handled status update TASK_RUNNING (UUID: fc8ced65-824c-40e5-971c-c5bb8333c49a)
for task 7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:27.072368 26160 slave.cpp:4106] Sending acknowledgement for status
update TASK_RUNNING (UUID: fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 to executor(1)@172.17.0.3:45428
I0120 20:51:27.072432 26168 master.cpp:5855] Status update TASK_RUNNING (UUID:
fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 from agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0 at slave(579)@172.17.0.3:38943
(9a52de5d9dcd)
I0120 20:51:27.072468 26168 master.cpp:5917] Forwarding status update
TASK_RUNNING (UUID: fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:27.072549 26168 master.cpp:7956] Updating the state of task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I0120 20:51:27.072660 26169 sched.cpp:1041] Scheduler::statusUpdate took 57036ns
I0120 20:51:27.072844 26168 master.cpp:4948] Processing ACKNOWLEDGE call
fc8ced65-824c-40e5-971c-c5bb8333c49a for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000 (default) at
[email protected]:38943 on agent
2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0
I0120 20:51:27.073006 26169 status_update_manager.cpp:395] Received status
update acknowledgement (UUID: fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:27.073171 26160 slave.cpp:3045] Status update manager successfully
handled status update acknowledgement (UUID:
fc8ced65-824c-40e5-971c-c5bb8333c49a) for task
7e4c1b3d-2297-4d19-8cba-f55ae009201d of framework
2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000
I0120 20:51:27.073739 26161 process.cpp:3697] Handling HTTP event for process
'slave(579)' with path: '/slave(579)/api/v1'
I0120 20:51:27.074090 26172 http.cpp:303] HTTP POST for /slave(579)/api/v1 from
172.17.0.3:60484
I0120 20:51:27.074259 26172 http.cpp:464] Processing call
LAUNCH_NESTED_CONTAINER_SESSION
I0120 20:51:27.074430 26172 containerizer.cpp:1808] Starting nested container
51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e
I0120 20:51:27.074621 26172 containerizer.cpp:1832] Trying to chown
'/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu/slaves/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0/frameworks/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000/executors/7e4c1b3d-2297-4d19-8cba-f55ae009201d/runs/51822148-9c1d-40e6-b255-d788c3dca267/containers/e7902473-84f1-4c46-a2fb-dc3b91133c0e'
to user 'mesos'
I0120 20:51:27.075654 26166 switchboard.cpp:571] Launching
'mesos-io-switchboard' with flags '--heartbeat_interval="30secs" --help="false"
--socket_address="/tmp/mesos-io-switchboard-646d928f-4493-4aa3-a337-7b12fa3c5ecf"
--stderr_from_fd="17" --stderr_to_fd="2" --stdin_to_fd="14"
--stdout_from_fd="15" --stdout_to_fd="1" --tty="false"
--wait_for_connection="true"' for container
51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e
I0120 20:51:27.077797 26166 switchboard.cpp:601] Created I/O switchboard server
(pid: 30052) listening on socket file
'/tmp/mesos-io-switchboard-646d928f-4493-4aa3-a337-7b12fa3c5ecf' for container
51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e
I0120 20:51:27.078768 26160 containerizer.cpp:1541] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"shell":true,"value":"printf output &&
printf error
1>&2"},"environment":{},"err":{"fd":18,"type":"FD"},"in":{"fd":13,"type":"FD"},"out":{"fd":16,"type":"FD"},"user":"mesos"}"
--pipe_read="14" --pipe_write="15"
--runtime_directory="/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_tIgxW4/containers/51822148-9c1d-40e6-b255-d788c3dca267/containers/e7902473-84f1-4c46-a2fb-dc3b91133c0e"
--unshare_namespace_mnt="false"'
I0120 20:51:27.080716 26160 launcher.cpp:135] Forked child with pid '30053' for
container
'51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e'
I0120 20:51:27.082023 26169 fetcher.cpp:349] Starting to fetch URIs for
container:
51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e,
directory:
/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_1_fDrhqu/slaves/2b435d8e-3792-458e-96ff-0ecff4b4aa54-S0/frameworks/2b435d8e-3792-458e-96ff-0ecff4b4aa54-0000/executors/7e4c1b3d-2297-4d19-8cba-f55ae009201d/runs/51822148-9c1d-40e6-b255-d788c3dca267/containers/e7902473-84f1-4c46-a2fb-dc3b91133c0e
I0120 20:51:27.128425 26170 containerizer.cpp:2482] Container
51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e has
exited
I0120 20:51:27.128443 26170 containerizer.cpp:2119] Destroying container
51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e in
RUNNING state
I0120 20:51:27.128509 26170 launcher.cpp:151] Asked to destroy container
51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e
I0120 20:51:27.134526 26163 process.cpp:3754] Failed to process request for
'/slave(579)/api/v1': Container has or is being destroyed
I0120 20:51:27.134551 26169 process.cpp:1456] Returning '500 Internal Server
Error' for '/slave(579)/api/v1' (Container has or is being destroyed)
W0120 20:51:27.134552 26174 http.cpp:2673] Failed to attach to nested container
51822148-9c1d-40e6-b255-d788c3dca267.e7902473-84f1-4c46-a2fb-dc3b91133c0e:
Container has or is being destroyed
/mesos/src/tests/api_tests.cpp:4098: Failure
Value of: (response).get().status
Actual: "500 Internal Server Error"
Expected: http::OK().status
Which is: "200 OK"
/mesos/src/tests/api_tests.cpp:4099: Failure
Value of: response->headers.at("Content-Type")
Actual: "text/plain; charset=utf-8"
Expected: stringify(contentType)
Which is: "application/json"
{code}
https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)&&(!ubuntu-eu2)/3170/changes
> AgentAPITest.LaunchNestedContainerSession is flaky
> --------------------------------------------------
>
> Key: MESOS-6948
> URL: https://issues.apache.org/jira/browse/MESOS-6948
> Project: Mesos
> Issue Type: Bug
> Components: tests
> Environment: CentOS 7 VM, libevent and SSL enabled
> Reporter: Greg Mann
> Assignee: Kevin Klues
> Priority: Critical
> Labels: debugging, tests
> Attachments: AgentAPITest.LaunchNestedContainerSession.txt
>
>
> This was observed in a CentOS 7 VM, with libevent and SSL enabled:
> {code}
> I0118 22:17:23.528846 2887 http.cpp:464] Processing call
> LAUNCH_NESTED_CONTAINER_SESSION
> I0118 22:17:23.530452 2887 containerizer.cpp:1807] Starting nested container
> 492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e
> I0118 22:17:23.532265 2887 containerizer.cpp:1831] Trying to chown
> '/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_0_ykIax9/slaves/707fd1a2-1a93-4e9f-a9b2-5453a207b4c5-S0/frameworks/707fd1a2-1a93-4e9f-a9b2-5453a207b4c5-0000/executors/14a26e2a-58b7-4166-909c-c90787d84fcb/runs/492a5d0a-0060-416c-ad80-dd0441f558dc/containers/62c170bb-7298-4209-b797-80d7ca73353e'
> to user 'vagrant'
> I0118 22:17:23.535213 2887 switchboard.cpp:570] Launching
> 'mesos-io-switchboard' with flags '--heartbeat_interval="30secs"
> --help="false"
> --socket_address="/tmp/mesos-io-switchboard-5a08fbd5-0d70-411e-8389-ac115a5f6430"
> --stderr_from_fd="15" --stderr_to_fd="2" --stdin_to_fd="12"
> --stdout_from_fd="13" --stdout_to_fd="1" --tty="false"
> --wait_for_connection="true"' for container
> 492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e
> I0118 22:17:23.537210 2887 switchboard.cpp:600] Created I/O switchboard
> server (pid: 3335) listening on socket file
> '/tmp/mesos-io-switchboard-5a08fbd5-0d70-411e-8389-ac115a5f6430' for
> container
> 492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e
> I0118 22:17:23.543665 2887 containerizer.cpp:1540] Launching
> 'mesos-containerizer' with flags '--help="false"
> --launch_info="{"command":{"shell":true,"value":"printf output && printf
> error
> 1>&2"},"environment":{},"err":{"fd":16,"type":"FD"},"in":{"fd":11,"type":"FD"},"out":{"fd":14,"type":"FD"},"user":"vagrant"}"
> --pipe_read="12" --pipe_write="13"
> --runtime_directory="/tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_0_QVZGrY/containers/492a5d0a-0060-416c-ad80-dd0441f558dc/containers/62c170bb-7298-4209-b797-80d7ca73353e"
> --unshare_namespace_mnt="false"'
> I0118 22:17:23.556032 2887 launcher.cpp:133] Forked child with pid '3337'
> for container
> '492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e'
> I0118 22:17:23.563900 2887 fetcher.cpp:349] Starting to fetch URIs for
> container:
> 492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e,
> directory:
> /tmp/ContentType_AgentAPITest_LaunchNestedContainerSession_0_ykIax9/slaves/707fd1a2-1a93-4e9f-a9b2-5453a207b4c5-S0/frameworks/707fd1a2-1a93-4e9f-a9b2-5453a207b4c5-0000/executors/14a26e2a-58b7-4166-909c-c90787d84fcb/runs/492a5d0a-0060-416c-ad80-dd0441f558dc/containers/62c170bb-7298-4209-b797-80d7ca73353e
> I0118 22:17:23.962441 2887 containerizer.cpp:2481] Container
> 492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e has
> exited
> I0118 22:17:23.962484 2887 containerizer.cpp:2118] Destroying container
> 492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e in
> RUNNING state
> I0118 22:17:23.962715 2887 launcher.cpp:149] Asked to destroy container
> 492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e
> I0118 22:17:23.977562 2887 process.cpp:3733] Failed to process request for
> '/slave(69)/api/v1': Container has or is being destroyed
> W0118 22:17:23.978216 2887 http.cpp:2734] Failed to attach to nested
> container
> 492a5d0a-0060-416c-ad80-dd0441f558dc.62c170bb-7298-4209-b797-80d7ca73353e:
> Container has or is being destroyed
> I0118 22:17:23.978330 2887 process.cpp:1435] Returning '500 Internal Server
> Error' for '/slave(69)/api/v1' (Container has or is being destroyed)
> ../../src/tests/api_tests.cpp:3960: Failure
> Value of: (response).get().status
> Actual: "500 Internal Server Error"
> Expected: http::OK().status
> Which is: "200 OK"
> {code}
> Find attached the full log from a failed run.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
