You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Till Toenshoff (JIRA)" <ji...@apache.org> on 2017/10/02 14:07:00 UTC
[jira] [Commented] (MESOS-7742)
ContentType/AgentAPIStreamingTest.AttachInputToNestedContainerSession is
flaky
[ https://issues.apache.org/jira/browse/MESOS-7742?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16188081#comment-16188081 ]
Till Toenshoff commented on MESOS-7742:
---------------------------------------
Observed this as well on internal CI:
{noformat}
../../src/tests/api_tests.cpp:6951
Value of: (response).get().status
Actual: "500 Internal Server Error"
Expected: http::OK().status
Which is: "200 OK"
{noformat}
{noformat}
00:50:40 [ RUN ] ContentType/AgentAPIStreamingTest.AttachInputToNestedContainerSession/1
00:50:40 I0930 00:50:40.193588 7413 cluster.cpp:162] Creating default 'local' authorizer
00:50:40 I0930 00:50:40.194614 26521 master.cpp:445] Master 6d4d319b-ce27-402c-91d2-087edb6a4a11 (ip-172-16-10-96.ec2.internal) started on 172.16.10.96:38662
00:50:40 I0930 00:50:40.194630 26521 master.cpp:447] 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/wdBG06/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="/usr/local/share/mesos/webui" --work_dir="/tmp/wdBG06/master" --zk_session_timeout="10secs"
00:50:40 I0930 00:50:40.194720 26521 master.cpp:497] Master only allowing authenticated frameworks to register
00:50:40 I0930 00:50:40.194723 26521 master.cpp:511] Master only allowing authenticated agents to register
00:50:40 I0930 00:50:40.194725 26521 master.cpp:524] Master only allowing authenticated HTTP frameworks to register
00:50:40 I0930 00:50:40.194730 26521 credentials.hpp:37] Loading credentials for authentication from '/tmp/wdBG06/credentials'
00:50:40 I0930 00:50:40.194808 26521 master.cpp:569] Using default 'crammd5' authenticator
00:50:40 I0930 00:50:40.194844 26521 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
00:50:40 I0930 00:50:40.194876 26521 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
00:50:40 I0930 00:50:40.194905 26521 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
00:50:40 I0930 00:50:40.194932 26521 master.cpp:649] Authorization enabled
00:50:40 I0930 00:50:40.194973 26516 hierarchical.cpp:171] Initialized hierarchical allocator process
00:50:40 I0930 00:50:40.195008 26516 whitelist_watcher.cpp:77] No whitelist given
00:50:40 I0930 00:50:40.195634 26523 master.cpp:2216] Elected as the leading master!
00:50:40 I0930 00:50:40.195659 26523 master.cpp:1705] Recovering from registrar
00:50:40 I0930 00:50:40.195701 26523 registrar.cpp:347] Recovering registrar
00:50:40 I0930 00:50:40.195863 26521 registrar.cpp:391] Successfully fetched the registry (0B) in 144128ns
00:50:40 I0930 00:50:40.195896 26521 registrar.cpp:495] Applied 1 operations in 6568ns; attempting to update the registry
00:50:40 I0930 00:50:40.196048 26519 registrar.cpp:552] Successfully updated the registry in 119808ns
00:50:40 I0930 00:50:40.196079 26519 registrar.cpp:424] Successfully recovered registrar
00:50:40 I0930 00:50:40.196159 26520 master.cpp:1809] Recovered 0 agents from the registry (168B); allowing 10mins for agents to re-register
00:50:40 I0930 00:50:40.196218 26518 hierarchical.cpp:209] Skipping recovery of hierarchical allocator: nothing to recover
00:50:40 I0930 00:50:40.197204 7413 containerizer.cpp:292] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
00:50:40 I0930 00:50:40.202510 7413 linux_launcher.cpp:146] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
00:50:40 I0930 00:50:40.202874 7413 provisioner.cpp:255] Using default backend 'overlay'
00:50:40 W0930 00:50:40.204174 7413 process.cpp:3194] Attempted to spawn already running process files@172.16.10.96:38662
00:50:40 I0930 00:50:40.204308 7413 cluster.cpp:448] Creating default 'local' authorizer
00:50:40 I0930 00:50:40.204797 26523 slave.cpp:254] Mesos agent started on (819)@172.16.10.96:38662
00:50:40 W0930 00:50:40.204952 7413 process.cpp:3194] Attempted to spawn already running process version@172.16.10.96:38662
00:50:40 I0930 00:50:40.204813 26523 slave.cpp:255] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/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_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/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/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/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/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="linux" --launcher_dir="/home/centos/workspace/mesos/Mesos_CI-build/FLAG/Plain/label/mesos-ec2-centos-7/mesos/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/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf" --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_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb" --zk_session_timeout="10secs"
00:50:40 I0930 00:50:40.204982 26523 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/credential'
00:50:40 I0930 00:50:40.205235 26523 slave.cpp:287] Agent using credential for: test-principal
00:50:40 I0930 00:50:40.205251 26523 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/http_credentials'
00:50:40 I0930 00:50:40.205333 26523 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
00:50:40 I0930 00:50:40.205371 26523 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
00:50:40 I0930 00:50:40.206058 26523 slave.cpp:585] 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"}]
00:50:40 I0930 00:50:40.206146 26523 slave.cpp:593] Agent attributes: [ ]
00:50:40 I0930 00:50:40.206152 26523 slave.cpp:602] Agent hostname: ip-172-16-10-96.ec2.internal
00:50:40 I0930 00:50:40.206181 7413 sched.cpp:232] Version: 1.5.0
00:50:40 I0930 00:50:40.206272 26520 status_update_manager.cpp:177] Pausing sending status updates
00:50:40 I0930 00:50:40.206413 26516 state.cpp:64] Recovering state from '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/meta'
00:50:40 I0930 00:50:40.206516 26523 sched.cpp:336] New master detected at master@172.16.10.96:38662
00:50:40 I0930 00:50:40.206542 26523 sched.cpp:407] Authenticating with master master@172.16.10.96:38662
00:50:40 I0930 00:50:40.206553 26523 sched.cpp:414] Using default CRAM-MD5 authenticatee
00:50:40 I0930 00:50:40.206636 26523 authenticatee.cpp:121] Creating new client SASL connection
00:50:40 I0930 00:50:40.206815 26518 status_update_manager.cpp:203] Recovering status update manager
00:50:40 I0930 00:50:40.206869 26518 containerizer.cpp:648] Recovering containerizer
00:50:40 I0930 00:50:40.207083 26523 master.cpp:7915] Authenticating scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:40 I0930 00:50:40.207129 26523 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1523)@172.16.10.96:38662
00:50:40 I0930 00:50:40.207188 26523 authenticator.cpp:98] Creating new server SASL connection
00:50:40 I0930 00:50:40.207603 26523 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
00:50:40 I0930 00:50:40.207623 26523 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
00:50:40 I0930 00:50:40.207649 26523 authenticator.cpp:204] Received SASL authentication start
00:50:40 I0930 00:50:40.207682 26523 authenticator.cpp:326] Authentication requires more steps
00:50:40 I0930 00:50:40.207710 26523 authenticatee.cpp:259] Received SASL authentication step
00:50:40 I0930 00:50:40.207743 26523 authenticator.cpp:232] Received SASL authentication step
00:50:40 I0930 00:50:40.207757 26523 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-96.ec2.internal' server FQDN: 'ip-172-16-10-96.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
00:50:40 I0930 00:50:40.207765 26523 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
00:50:40 I0930 00:50:40.207774 26523 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
00:50:40 I0930 00:50:40.207783 26523 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-96.ec2.internal' server FQDN: 'ip-172-16-10-96.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
00:50:40 I0930 00:50:40.207789 26523 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
00:50:40 I0930 00:50:40.207794 26523 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
00:50:40 I0930 00:50:40.207806 26523 authenticator.cpp:318] Authentication success
00:50:40 I0930 00:50:40.207839 26523 authenticatee.cpp:299] Authentication success
00:50:40 I0930 00:50:40.207859 26523 master.cpp:7945] Successfully authenticated principal 'test-principal' at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:40 I0930 00:50:40.207883 26523 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1523)@172.16.10.96:38662
00:50:40 I0930 00:50:40.207972 26518 sched.cpp:513] Successfully authenticated with master master@172.16.10.96:38662
00:50:40 I0930 00:50:40.207983 26518 sched.cpp:836] Sending SUBSCRIBE call to master@172.16.10.96:38662
00:50:40 I0930 00:50:40.208019 26518 sched.cpp:869] Will retry registration in 1.680108139secs if necessary
00:50:40 I0930 00:50:40.208096 26518 master.cpp:2947] Received SUBSCRIBE call for framework 'default' at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:40 I0930 00:50:40.208118 26518 master.cpp:2281] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
00:50:40 I0930 00:50:40.208223 26518 master.cpp:3027] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
00:50:40 I0930 00:50:40.208391 26517 hierarchical.cpp:303] Added framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.208421 26519 sched.cpp:759] Framework registered with 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.208428 26517 hierarchical.cpp:1943] No allocations performed
00:50:40 I0930 00:50:40.208436 26517 hierarchical.cpp:2033] No inverse offers to send out!
00:50:40 I0930 00:50:40.208441 26519 sched.cpp:773] Scheduler::registered took 9347ns
00:50:40 I0930 00:50:40.208442 26517 hierarchical.cpp:1486] Performed allocation for 0 agents in 18451ns
00:50:40 I0930 00:50:40.208573 26516 provisioner.cpp:416] Provisioner recovery complete
00:50:40 I0930 00:50:40.208688 26516 slave.cpp:6313] Finished recovery
00:50:40 I0930 00:50:40.208909 26516 slave.cpp:6495] Querying resource estimator for oversubscribable resources
00:50:40 I0930 00:50:40.208961 26516 status_update_manager.cpp:177] Pausing sending status updates
00:50:40 I0930 00:50:40.208967 26519 slave.cpp:993] New master detected at master@172.16.10.96:38662
00:50:40 I0930 00:50:40.208997 26519 slave.cpp:1028] Detecting new master
00:50:40 I0930 00:50:40.209023 26519 slave.cpp:6509] Received oversubscribable resources {} from the resource estimator
00:50:40 I0930 00:50:40.216280 26516 slave.cpp:1055] Authenticating with master master@172.16.10.96:38662
00:50:40 I0930 00:50:40.216305 26516 slave.cpp:1066] Using default CRAM-MD5 authenticatee
00:50:40 I0930 00:50:40.216356 26516 authenticatee.cpp:121] Creating new client SASL connection
00:50:40 I0930 00:50:40.216756 26516 master.cpp:7915] Authenticating slave(819)@172.16.10.96:38662
00:50:40 I0930 00:50:40.216801 26516 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1524)@172.16.10.96:38662
00:50:40 I0930 00:50:40.216866 26516 authenticator.cpp:98] Creating new server SASL connection
00:50:40 I0930 00:50:40.217252 26516 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
00:50:40 I0930 00:50:40.217269 26516 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
00:50:40 I0930 00:50:40.217298 26516 authenticator.cpp:204] Received SASL authentication start
00:50:40 I0930 00:50:40.217324 26516 authenticator.cpp:326] Authentication requires more steps
00:50:40 I0930 00:50:40.217355 26516 authenticatee.cpp:259] Received SASL authentication step
00:50:40 I0930 00:50:40.217397 26516 authenticator.cpp:232] Received SASL authentication step
00:50:40 I0930 00:50:40.217414 26516 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-96.ec2.internal' server FQDN: 'ip-172-16-10-96.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
00:50:40 I0930 00:50:40.217427 26516 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
00:50:40 I0930 00:50:40.217437 26516 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
00:50:40 I0930 00:50:40.217444 26516 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-96.ec2.internal' server FQDN: 'ip-172-16-10-96.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
00:50:40 I0930 00:50:40.217452 26516 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
00:50:40 I0930 00:50:40.217456 26516 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
00:50:40 I0930 00:50:40.217468 26516 authenticator.cpp:318] Authentication success
00:50:40 I0930 00:50:40.217504 26516 authenticatee.cpp:299] Authentication success
00:50:40 I0930 00:50:40.217530 26516 master.cpp:7945] Successfully authenticated principal 'test-principal' at slave(819)@172.16.10.96:38662
00:50:40 I0930 00:50:40.217559 26516 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1524)@172.16.10.96:38662
00:50:40 I0930 00:50:40.217613 26516 slave.cpp:1150] Successfully authenticated with master master@172.16.10.96:38662
00:50:40 I0930 00:50:40.217680 26516 slave.cpp:1629] Will retry registration in 17.756664ms if necessary
00:50:40 I0930 00:50:40.217761 26516 master.cpp:5819] Received register agent message from slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:40 I0930 00:50:40.217798 26516 master.cpp:3856] Authorizing agent with principal 'test-principal'
00:50:40 I0930 00:50:40.217897 26516 master.cpp:5879] Authorized registration of agent at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:40 I0930 00:50:40.217936 26516 master.cpp:5972] Registering agent at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) with id 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0
00:50:40 I0930 00:50:40.218055 26516 registrar.cpp:495] Applied 1 operations in 29124ns; attempting to update the registry
00:50:40 I0930 00:50:40.218199 26516 registrar.cpp:552] Successfully updated the registry in 120064ns
00:50:40 I0930 00:50:40.218257 26516 master.cpp:6019] Admitted agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:40 I0930 00:50:40.218400 26520 slave.cpp:4969] Received ping from slave-observer(739)@172.16.10.96:38662
00:50:40 I0930 00:50:40.218441 26520 slave.cpp:1196] Registered with master master@172.16.10.96:38662; given agent ID 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0
00:50:40 I0930 00:50:40.218392 26516 master.cpp:6050] Registered agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) 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"}]
00:50:40 I0930 00:50:40.218538 26516 hierarchical.cpp:593] Added agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 (ip-172-16-10-96.ec2.internal) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
00:50:40 I0930 00:50:40.218684 26520 slave.cpp:1216] Checkpointing SlaveInfo to '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/meta/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/slave.info'
00:50:40 I0930 00:50:40.218747 26516 hierarchical.cpp:2033] No inverse offers to send out!
00:50:40 I0930 00:50:40.218763 26516 hierarchical.cpp:1486] Performed allocation for 1 agents in 179217ns
00:50:40 I0930 00:50:40.218793 26516 status_update_manager.cpp:184] Resuming sending status updates
00:50:40 I0930 00:50:40.218848 26520 slave.cpp:1265] Forwarding total oversubscribed resources {}
00:50:40 I0930 00:50:40.218911 26516 master.cpp:7745] Sending 1 offers to framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:40 I0930 00:50:40.218983 26516 master.cpp:6814] Received update of agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) with total oversubscribed resources {}
00:50:40 I0930 00:50:40.219099 26517 hierarchical.cpp:660] Agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 (ip-172-16-10-96.ec2.internal) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
00:50:40 I0930 00:50:40.219153 26516 sched.cpp:933] Scheduler::resourceOffers took 32305ns
00:50:40 I0930 00:50:40.219502 26523 master.cpp:9368] Removing offer 6d4d319b-ce27-402c-91d2-087edb6a4a11-O0
00:50:40 I0930 00:50:40.219549 26523 master.cpp:4214] Processing ACCEPT call for offers: [ 6d4d319b-ce27-402c-91d2-087edb6a4a11-O0 ] on agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) for framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:40 I0930 00:50:40.219584 26523 master.cpp:3583] Authorizing framework principal 'test-principal' to launch task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93
00:50:40 I0930 00:50:40.220018 26521 master.cpp:10114] Adding task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] on agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:40 I0930 00:50:40.220196 26521 master.cpp:4897] Launching task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] on agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:40 I0930 00:50:40.220515 26521 slave.cpp:1750] Got assigned task 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' for framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.220649 26517 hierarchical.cpp:887] Updated allocation of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 on agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-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]
00:50:40 I0930 00:50:40.220721 26521 slave.cpp:2018] Authorizing task 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' for framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.220746 26521 slave.cpp:6812] Authorizing framework principal 'test-principal' to launch task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93
00:50:40 I0930 00:50:40.220959 26518 slave.cpp:2186] Launching task 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' for framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.221333 26518 paths.cpp:594] Trying to chown '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767' to user 'root'
00:50:40 I0930 00:50:40.221451 26518 slave.cpp:7274] Launching executor 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}] in work directory '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767'
00:50:40 I0930 00:50:40.221639 26518 slave.cpp:2877] Launching container 300c41d5-1f13-4446-a4e7-e96059d9d767 for executor 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.221745 26518 slave.cpp:2414] Queued task 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' for executor 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.221860 26520 containerizer.cpp:1122] Starting container 300c41d5-1f13-4446-a4e7-e96059d9d767
00:50:40 I0930 00:50:40.221887 26518 slave.cpp:944] Successfully attached '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767' to virtual path '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/latest'
00:50:40 I0930 00:50:40.221904 26518 slave.cpp:944] Successfully attached '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767' to virtual path '/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/latest'
00:50:40 I0930 00:50:40.221915 26518 slave.cpp:944] Successfully attached '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767' to virtual path '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767'
00:50:40 I0930 00:50:40.222050 26520 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767 from PROVISIONING to PREPARING
00:50:40 I0930 00:50:40.223075 26521 containerizer.cpp:1720] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/home\/centos\/workspace\/mesos\/Mesos_CI-build\/FLAG\/Plain\/label\/mesos-ec2-centos-7\/mesos\/build\/src"],"shell":false,"value":"\/home\/centos\/workspace\/mesos\/Mesos_CI-build\/FLAG\/Plain\/label\/mesos-ec2-centos-7\/mesos\/build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.16.10.96:38662"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb\/slaves\/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0\/frameworks\/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000\/executors\/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93\/runs\/300c41d5-1f13-4446-a4e7-e96059d9d767"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"e25fe31f-7a7c-48f8-ad7c-09689b7a7d93"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"6d4d319b-ce27-402c-91d2-087edb6a4a11-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"6d4d319b-ce27-402c-91d2-087edb6a4a11-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(819)@172.16.10.96:38662"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb\/slaves\/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0\/frameworks\/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000\/executors\/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93\/runs\/300c41d5-1f13-4446-a4e7-e96059d9d767"}]},"task_environment":{},"user":"root","working_directory":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb\/slaves\/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0\/frameworks\/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000\/executors\/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93\/runs\/300c41d5-1f13-4446-a4e7-e96059d9d767"}" --pipe_read="19" --pipe_write="21" --runtime_directory="/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/containers/300c41d5-1f13-4446-a4e7-e96059d9d767" --unshare_namespace_mnt="false"'
00:50:40 I0930 00:50:40.223348 26519 linux_launcher.cpp:438] Launching container 300c41d5-1f13-4446-a4e7-e96059d9d767 and cloning with namespaces
00:50:40 I0930 00:50:40.227885 26521 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767 from PREPARING to ISOLATING
00:50:40 I0930 00:50:40.228426 26521 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767 from ISOLATING to FETCHING
00:50:40 I0930 00:50:40.228484 26521 fetcher.cpp:377] Starting to fetch URIs for container: 300c41d5-1f13-4446-a4e7-e96059d9d767, directory: /tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767
00:50:40 I0930 00:50:40.228716 26521 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767 from FETCHING to RUNNING
00:50:40 I0930 00:50:40.312839 26522 slave.cpp:3944] Got registration for executor 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 from executor(1)@172.16.10.96:43809
00:50:40 I0930 00:50:40.313544 26520 slave.cpp:2616] Sending queued task 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' to executor 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 at executor(1)@172.16.10.96:43809
00:50:40 I0930 00:50:40.321434 26518 slave.cpp:4398] Handling status update TASK_RUNNING (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 from executor(1)@172.16.10.96:43809
00:50:40 I0930 00:50:40.322016 26518 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.322057 26518 status_update_manager.cpp:500] Creating StatusUpdate stream for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.322343 26518 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 to the agent
00:50:40 I0930 00:50:40.322461 26518 slave.cpp:4879] Forwarding the update TASK_RUNNING (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 to master@172.16.10.96:38662
00:50:40 I0930 00:50:40.322535 26518 slave.cpp:4773] Status update manager successfully handled status update TASK_RUNNING (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.322551 26518 slave.cpp:4789] Sending acknowledgement for status update TASK_RUNNING (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 to executor(1)@172.16.10.96:43809
00:50:40 I0930 00:50:40.322646 26518 master.cpp:6972] Status update TASK_RUNNING (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 from agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:40 I0930 00:50:40.322667 26518 master.cpp:7034] Forwarding status update TASK_RUNNING (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.322715 26518 master.cpp:9136] Updating the state of task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
00:50:40 I0930 00:50:40.322815 26518 sched.cpp:1041] Scheduler::statusUpdate took 37577ns
00:50:40 I0930 00:50:40.322933 26518 master.cpp:5584] Processing ACKNOWLEDGE call 236e617e-92fa-4ba8-93d3-a3f873576551 for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662 on agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0
00:50:40 I0930 00:50:40.323016 26518 status_update_manager.cpp:395] Received status update acknowledgement (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.323101 26518 slave.cpp:3682] Status update manager successfully handled status update acknowledgement (UUID: 236e617e-92fa-4ba8-93d3-a3f873576551) for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:40 I0930 00:50:40.324592 26517 process.cpp:3929] Handling HTTP event for process 'slave(819)' with path: '/slave(819)/api/v1'
00:50:40 I0930 00:50:40.324864 26517 http.cpp:1185] HTTP POST for /slave(819)/api/v1 from 172.16.10.96:44942
00:50:40 I0930 00:50:40.325073 26517 http.cpp:532] Processing call LAUNCH_NESTED_CONTAINER_SESSION
00:50:40 I0930 00:50:40.325403 26517 containerizer.cpp:1093] Trying to chown '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767/containers/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d' to user 'root'
00:50:40 I0930 00:50:40.325503 26517 containerizer.cpp:1122] Starting container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:40 I0930 00:50:40.325817 26517 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d from PROVISIONING to PREPARING
00:50:40 I0930 00:50:40.326449 26517 switchboard.cpp:545] Launching 'mesos-io-switchboard' with flags '--heartbeat_interval="30secs" --help="false" --socket_address="/tmp/mesos-io-switchboard-d72f51ec-2d57-4d39-9db0-af48e64d279a" --stderr_from_fd="69" --stderr_to_fd="2" --stdin_to_fd="48" --stdout_from_fd="49" --stdout_to_fd="1" --tty="false" --wait_for_connection="true"' for container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:40 I0930 00:50:40.329478 26517 switchboard.cpp:575] Created I/O switchboard server (pid: 4749) listening on socket file '/tmp/mesos-io-switchboard-d72f51ec-2d57-4d39-9db0-af48e64d279a' for container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:40 I0930 00:50:40.330742 26517 containerizer.cpp:1720] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"shell":true,"value":"cat"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.16.10.96:38662"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb\/slaves\/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0\/frameworks\/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000\/executors\/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93\/runs\/300c41d5-1f13-4446-a4e7-e96059d9d767"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"e25fe31f-7a7c-48f8-ad7c-09689b7a7d93"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"6d4d319b-ce27-402c-91d2-087edb6a4a11-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"6d4d319b-ce27-402c-91d2-087edb6a4a11-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(819)@172.16.10.96:38662"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb\/slaves\/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0\/frameworks\/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000\/executors\/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93\/runs\/300c41d5-1f13-4446-a4e7-e96059d9d767"}]},"task_environment":{},"user":"root","working_directory":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb\/slaves\/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0\/frameworks\/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000\/executors\/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93\/runs\/300c41d5-1f13-4446-a4e7-e96059d9d767"}" --pipe_read="48" --pipe_write="49" --runtime_directory="/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/containers/300c41d5-1f13-4446-a4e7-e96059d9d767/containers/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d" --unshare_namespace_mnt="false"'
00:50:40 I0930 00:50:40.331483 26519 linux_launcher.cpp:438] Launching nested container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d and cloning with namespaces
00:50:40 I0930 00:50:40.345054 26517 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d from PREPARING to ISOLATING
00:50:40 I0930 00:50:40.345527 26517 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d from ISOLATING to FETCHING
00:50:40 I0930 00:50:40.345589 26517 fetcher.cpp:377] Starting to fetch URIs for container: 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d, directory: /tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767/containers/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:40 I0930 00:50:40.345861 26517 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d from FETCHING to RUNNING
00:50:41 I0930 00:50:40.504283 26516 process.cpp:3929] Handling HTTP event for process 'slave(819)' with path: '/slave(819)/api/v1'
00:50:41 I0930 00:50:40.504568 26516 http.cpp:1185] HTTP POST for /slave(819)/api/v1 from 172.16.10.96:44944
00:50:41 I0930 00:50:40.509361 26521 http.cpp:532] Processing call ATTACH_CONTAINER_INPUT
00:50:41 I0930 00:50:40.983932 26516 process.cpp:3986] Failed to process request for '/slave(819)/api/v1': Disconnected
00:50:41 I0930 00:50:40.984016 26516 process.cpp:1606] Returning '500 Internal Server Error' for '/slave(819)/api/v1' (Disconnected)
00:50:41 ../../src/tests/api_tests.cpp:6951: Failure
00:50:41 Value of: (response).get().status
00:50:41 Actual: "500 Internal Server Error"
00:50:41 Expected: http::OK().status
00:50:41 Which is: "200 OK"
00:50:41 I0930 00:50:40.987481 26518 switchboard.cpp:888] I/O switchboard server process for container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d has terminated (status=0)
00:50:41 I0930 00:50:40.987597 26518 containerizer.cpp:2651] Container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d has exited
00:50:41 I0930 00:50:40.987609 26518 containerizer.cpp:2205] Destroying container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d in RUNNING state
00:50:41 I0930 00:50:40.987617 26518 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d from RUNNING to DESTROYING
00:50:41 I0930 00:50:40.987680 26518 linux_launcher.cpp:514] Asked to destroy container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:41 I0930 00:50:40.988567 26518 linux_launcher.cpp:560] Using freezer to destroy cgroup mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:41 I0930 00:50:40.990252 26518 cgroups.cpp:3058] Freezing cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:41 I0930 00:50:40.992677 26518 cgroups.cpp:1413] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d after 2.402048ms
00:50:41 I0930 00:50:40.994889 26523 http.cpp:2885] Received EOF attach response for 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:41 W0930 00:50:40.995012 26523 http.cpp:2900] Launch nested container session connection for container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d closed
00:50:41 I0930 00:50:40.995134 26518 cgroups.cpp:3076] Thawing cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:41 I0930 00:50:40.997680 26517 cgroups.cpp:1442] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d after 2.516992ms
00:50:41 I0930 00:50:40.999186 26517 provisioner.cpp:490] Ignoring destroy request for unknown container 300c41d5-1f13-4446-a4e7-e96059d9d767.ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d
00:50:41 I0930 00:50:40.999230 26517 containerizer.cpp:2489] Checkpointing termination state to nested container's runtime directory '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_Z5jQsf/containers/300c41d5-1f13-4446-a4e7-e96059d9d767/containers/ee86af07-d8e4-47bb-a0bc-ab06f1e5f94d/termination'
00:50:41 I0930 00:50:41.089108 26516 master.cpp:1435] Framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662 disconnected
00:50:41 I0930 00:50:41.089134 26516 master.cpp:3317] Deactivating framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:41 I0930 00:50:41.089155 26516 master.cpp:3294] Disconnecting framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:41 I0930 00:50:41.089169 26516 master.cpp:1450] Giving framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662 0ns to failover
00:50:41 I0930 00:50:41.089256 26521 hierarchical.cpp:412] Deactivated framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:41 I0930 00:50:41.089416 26517 containerizer.cpp:2205] Destroying container 300c41d5-1f13-4446-a4e7-e96059d9d767 in RUNNING state
00:50:41 I0930 00:50:41.089433 26517 containerizer.cpp:2751] Transitioning the state of container 300c41d5-1f13-4446-a4e7-e96059d9d767 from RUNNING to DESTROYING
00:50:41 I0930 00:50:41.089551 26519 linux_launcher.cpp:514] Asked to destroy container 300c41d5-1f13-4446-a4e7-e96059d9d767
00:50:41 I0930 00:50:41.090142 26519 linux_launcher.cpp:560] Using freezer to destroy cgroup mesos/300c41d5-1f13-4446-a4e7-e96059d9d767
00:50:41 I0930 00:50:41.091104 26523 master.cpp:7577] Framework failover timeout, removing framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:41 I0930 00:50:41.091126 26523 master.cpp:8438] Removing framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (default) at scheduler-6c5d55b7-1ec2-4e3c-a283-8101db1d744f@172.16.10.96:38662
00:50:41 I0930 00:50:41.091178 26523 master.cpp:9136] Updating the state of task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
00:50:41 I0930 00:50:41.091327 26523 master.cpp:9230] Removing task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 on agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:41 I0930 00:50:41.091475 26519 slave.cpp:3214] Asked to shut down framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 by master@172.16.10.96:38662
00:50:41 I0930 00:50:41.091492 26519 slave.cpp:3239] Shutting down framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:41 I0930 00:50:41.091502 26519 slave.cpp:5746] Shutting down executor 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 at executor(1)@172.16.10.96:43809
00:50:41 I0930 00:50:41.091622 26519 cgroups.cpp:3058] Freezing cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos
00:50:41 I0930 00:50:41.091675 26519 cgroups.cpp:3058] Freezing cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767
00:50:41 I0930 00:50:41.091673 26523 hierarchical.cpp:1161] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 from framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:41 I0930 00:50:41.091751 26523 hierarchical.cpp:355] Removed framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:41 I0930 00:50:41.097478 26523 cgroups.cpp:1413] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767 after 5.785088ms
00:50:41 I0930 00:50:41.097930 26519 cgroups.cpp:1413] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos after 6.287872ms
00:50:41 I0930 00:50:41.100170 26523 cgroups.cpp:3076] Thawing cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767
00:50:41 I0930 00:50:41.100589 26519 cgroups.cpp:3076] Thawing cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos
00:50:41 I0930 00:50:41.104161 26519 cgroups.cpp:1442] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767/mesos after 3.547904ms
00:50:41 I0930 00:50:41.104324 26523 cgroups.cpp:1442] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/300c41d5-1f13-4446-a4e7-e96059d9d767 after 4.124928ms
00:50:41 I0930 00:50:41.104528 26520 slave.cpp:5011] Got exited event for executor(1)@172.16.10.96:43809
00:50:41 I0930 00:50:41.189157 26522 containerizer.cpp:2651] Container 300c41d5-1f13-4446-a4e7-e96059d9d767 has exited
00:50:41 I0930 00:50:41.190263 26521 provisioner.cpp:490] Ignoring destroy request for unknown container 300c41d5-1f13-4446-a4e7-e96059d9d767
00:50:41 I0930 00:50:41.190647 26517 slave.cpp:5411] Executor 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 terminated with signal Killed
00:50:41 I0930 00:50:41.190668 26517 slave.cpp:5515] Cleaning up executor 'e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000 at executor(1)@172.16.10.96:43809
00:50:41 I0930 00:50:41.190770 26521 gc.cpp:90] Scheduling '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93/runs/300c41d5-1f13-4446-a4e7-e96059d9d767' for gc 6.99999779246519days in the future
00:50:41 I0930 00:50:41.190820 26517 slave.cpp:5622] Cleaning up framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:41 I0930 00:50:41.190831 26520 gc.cpp:90] Scheduling '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000/executors/e25fe31f-7a7c-48f8-ad7c-09689b7a7d93' for gc 6.99999779158519days in the future
00:50:41 I0930 00:50:41.190860 26520 status_update_manager.cpp:285] Closing status update streams for framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:41 I0930 00:50:41.190870 26520 status_update_manager.cpp:531] Cleaning up status update stream for task e25fe31f-7a7c-48f8-ad7c-09689b7a7d93 of framework 6d4d319b-ce27-402c-91d2-087edb6a4a11-0000
00:50:41 I0930 00:50:41.190877 26517 gc.cpp:90] Scheduling '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_1_cn8Keb/slaves/6d4d319b-ce27-402c-91d2-087edb6a4a11-S0/frameworks/6d4d319b-ce27-402c-91d2-087edb6a4a11-0000' for gc 6.99999779099556days in the future
00:50:41 I0930 00:50:41.191022 7413 slave.cpp:869] Agent terminating
00:50:41 I0930 00:50:41.191403 26518 master.cpp:1321] Agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal) disconnected
00:50:41 I0930 00:50:41.191421 26518 master.cpp:3354] Disconnecting agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:41 I0930 00:50:41.191435 26518 master.cpp:3373] Deactivating agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 at slave(819)@172.16.10.96:38662 (ip-172-16-10-96.ec2.internal)
00:50:41 I0930 00:50:41.191529 26521 hierarchical.cpp:690] Agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0 deactivated
00:50:41 I0930 00:50:41.192953 7413 master.cpp:1163] Master terminating
00:50:41 I0930 00:50:41.193094 26518 hierarchical.cpp:626] Removed agent 6d4d319b-ce27-402c-91d2-087edb6a4a11-S0
00:50:41 [ FAILED ] ContentType/AgentAPIStreamingTest.AttachInputToNestedContainerSession/1, where GetParam() = application/json (1002 ms)
{noformat}
> ContentType/AgentAPIStreamingTest.AttachInputToNestedContainerSession is flaky
> ------------------------------------------------------------------------------
>
> Key: MESOS-7742
> URL: https://issues.apache.org/jira/browse/MESOS-7742
> Project: Mesos
> Issue Type: Bug
> Reporter: Vinod Kone
> Assignee: Gastón Kleiman
> Labels: flaky-test, mesosphere-oncall
>
> Observed this on ASF CI.
> [~gkleiman] mind triaging this?
> {code}
> [ RUN ] ContentType/AgentAPIStreamingTest.AttachInputToNestedContainerSession/0
> I0629 05:49:33.180673 25301 cluster.cpp:162] Creating default 'local' authorizer
> I0629 05:49:33.182234 25306 master.cpp:436] Master 90ea1640-bdf3-49ba-b78f-b2ba7ea30077 (296af9b598c3) started on 172.17.0.3:45726
> I0629 05:49:33.182289 25306 master.cpp:438] 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" --au
> thenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/a5h5J3/credentials" --framework_sorter="drf" --help="false" --hostn
> ame_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="10
> 00" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registr
> y_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/a5h5J3/master" --zk_session_timeout="10secs"
> I0629 05:49:33.182561 25306 master.cpp:488] Master only allowing authenticated frameworks to register
> I0629 05:49:33.182610 25306 master.cpp:502] Master only allowing authenticated agents to register
> I0629 05:49:33.182636 25306 master.cpp:515] Master only allowing authenticated HTTP frameworks to register
> I0629 05:49:33.182656 25306 credentials.hpp:37] Loading credentials for authentication from '/tmp/a5h5J3/credentials'
> I0629 05:49:33.182915 25306 master.cpp:560] Using default 'crammd5' authenticator
> I0629 05:49:33.183009 25306 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> I0629 05:49:33.183151 25306 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> I0629 05:49:33.183218 25306 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> I0629 05:49:33.183284 25306 master.cpp:640] Authorization enabled
> I0629 05:49:33.183462 25309 hierarchical.cpp:158] Initialized hierarchical allocator process
> I0629 05:49:33.183504 25309 whitelist_watcher.cpp:77] No whitelist given
> I0629 05:49:33.184311 25308 master.cpp:2161] Elected as the leading master!
> I0629 05:49:33.184341 25308 master.cpp:1700] Recovering from registrar
> I0629 05:49:33.184404 25308 registrar.cpp:345] Recovering registrar
> I0629 05:49:33.184622 25308 registrar.cpp:389] Successfully fetched the registry (0B) in 183040ns
> I0629 05:49:33.184687 25308 registrar.cpp:493] Applied 1 operations in 6441ns; attempting to update the registry
> I0629 05:49:33.184885 25304 registrar.cpp:550] Successfully updated the registry in 147200ns
> I0629 05:49:33.184993 25304 registrar.cpp:422] Successfully recovered registrar
> I0629 05:49:33.185148 25308 master.cpp:1799] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
> I0629 05:49:33.185161 25302 hierarchical.cpp:185] Skipping recovery of hierarchical allocator: nothing to recover
> I0629 05:49:33.186769 25301 containerizer.cpp:221] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
> W0629 05:49:33.187232 25301 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
> W0629 05:49:33.187363 25301 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
> I0629 05:49:33.187396 25301 provisioner.cpp:249] Using default backend 'copy'
> I0629 05:49:33.189133 25301 cluster.cpp:448] Creating default 'local' authorizer
> I0629 05:49:33.189707 25306 slave.cpp:231] Mesos agent started on (644)@172.17.0.3:45726
> I0629 05:49:33.189741 25306 slave.cpp:232] 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_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volu:
> me" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ/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/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ/http_credentials" --http_heartbeat_interval="30secs" --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" --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/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ" --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_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw"
> I0629 05:49:33.190001 25306 credentials.hpp:86] Loading credential for authentication from '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ/credential'
> I0629 05:49:33.190135 25306 slave.cpp:264] Agent using credential for: test-principal
> I0629 05:49:33.190228 25306 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ/http_credentials'
> I0629 05:49:33.190445 25306 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> I0629 05:49:33.190563 25306 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> I0629 05:49:33.191004 25301 sched.cpp:232] Version: 1.3.0
> I0629 05:49:33.191077 25306 slave.cpp:531] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0629 05:49:33.191150 25306 slave.cpp:539] Agent attributes: [ ]
> I0629 05:49:33.191172 25306 slave.cpp:544] Agent hostname: 296af9b598c3
> I0629 05:49:33.191313 25302 sched.cpp:336] New master detected at master@172.17.0.3:45726
> I0629 05:49:33.191349 25302 sched.cpp:407] Authenticating with master master@172.17.0.3:45726
> I0629 05:49:33.191433 25302 sched.cpp:414] Using default CRAM-MD5 authenticatee
> I0629 05:49:33.191622 25302 authenticatee.cpp:121] Creating new client SASL connection
> I0629 05:49:33.191917 25302 master.cpp:7475] Authenticating scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.192019 25302 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1229)@172.17.0.3:45726
> I0629 05:49:33.192194 25302 authenticator.cpp:98] Creating new server SASL connection
> I0629 05:49:33.192387 25302 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0629 05:49:33.192411 25302 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0629 05:49:33.192445 25302 authenticator.cpp:204] Received SASL authentication start
> I0629 05:49:33.192512 25302 authenticator.cpp:326] Authentication requires more steps
> I0629 05:49:33.192553 25302 authenticatee.cpp:259] Received SASL authentication step
> I0629 05:49:33.192591 25302 authenticator.cpp:232] Received SASL authentication step
> I0629 05:49:33.192699 25302 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '296af9b598c3' server FQDN: '296af9b598c3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0629 05:49:33.192715 25302 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0629 05:49:33.192823 25302 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0629 05:49:33.192849 25302 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '296af9b598c3' server FQDN: '296af9b598c3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0629 05:49:33.192932 25302 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0629 05:49:33.192996 25302 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0629 05:49:33.193013 25302 authenticator.cpp:318] Authentication success
> I0629 05:49:33.193075 25308 authenticatee.cpp:299] Authentication success
> I0629 05:49:33.193120 25307 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1229)@172.17.0.3:45726
> I0629 05:49:33.193137 25308 status_update_manager.cpp:177] Pausing sending status updates
> I0629 05:49:33.193213 25302 master.cpp:7505] Successfully authenticated principal 'test-principal' at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.193248 25308 sched.cpp:513] Successfully authenticated with master master@172.17.0.3:45726
> I0629 05:49:33.193265 25308 sched.cpp:836] Sending SUBSCRIBE call to master@172.17.0.3:45726
> I0629 05:49:33.193306 25308 sched.cpp:869] Will retry registration in 250.898986ms if necessary
> I0629 05:49:33.193398 25308 master.cpp:2813] Received SUBSCRIBE call for framework 'default' at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.193424 25308 master.cpp:2197] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
> I0629 05:49:33.193763 25305 state.cpp:62] Recovering state from '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/meta'
> I0629 05:49:33.193764 25306 master.cpp:2890] Subscribing framework default with checkpointing disabled and capabilities [ ]
> I0629 05:49:33.194470 25309 status_update_manager.cpp:203] Recovering status update manager
> I0629 05:49:33.194608 25306 sched.cpp:759] Framework registered with 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.194656 25306 sched.cpp:773] Scheduler::registered took 13886ns
> I0629 05:49:33.194751 25307 hierarchical.cpp:273] Added framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.194782 25308 containerizer.cpp:608] Recovering containerizer
> I0629 05:49:33.194805 25307 hierarchical.cpp:1850] No allocations performed
> I0629 05:49:33.194825 25307 hierarchical.cpp:1940] No inverse offers to send out!
> I0629 05:49:33.194835 25307 hierarchical.cpp:1434] Performed allocation for 0 agents in 37750ns
> I0629 05:49:33.195451 25302 provisioner.cpp:410] Provisioner recovery complete
> I0629 05:49:33.195629 25302 slave.cpp:6075] Finished recovery
> I0629 05:49:33.196087 25302 slave.cpp:6257] Querying resource estimator for oversubscribable resources
> I0629 05:49:33.196205 25307 slave.cpp:6271] Received oversubscribable resources {} from the resource estimator
> I0629 05:49:33.196358 25302 slave.cpp:924] New master detected at master@172.17.0.3:45726
> I0629 05:49:33.196447 25308 status_update_manager.cpp:177] Pausing sending status updates
> I0629 05:49:33.196465 25302 slave.cpp:959] Detecting new master
> I0629 05:49:33.200856 25302 slave.cpp:986] Authenticating with master master@172.17.0.3:45726
> I0629 05:49:33.200942 25302 slave.cpp:997] Using default CRAM-MD5 authenticatee
> I0629 05:49:33.201126 25309 authenticatee.cpp:121] Creating new client SASL connection
> I0629 05:49:33.201560 25309 master.cpp:7475] Authenticating slave(644)@172.17.0.3:45726
> I0629 05:49:33.201704 25309 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1230)@172.17.0.3:45726
> I0629 05:49:33.201792 25302 authenticator.cpp:98] Creating new server SASL connection
> I0629 05:49:33.202373 25302 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0629 05:49:33.202396 25302 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0629 05:49:33.202430 25302 authenticator.cpp:204] Received SASL authentication start
> I0629 05:49:33.202487 25302 authenticator.cpp:326] Authentication requires more steps
> I0629 05:49:33.202584 25302 authenticatee.cpp:259] Received SASL authentication step
> I0629 05:49:33.202633 25302 authenticator.cpp:232] Received SASL authentication step
> I0629 05:49:33.202648 25302 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '296af9b598c3' server FQDN: '296af9b598c3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0629 05:49:33.202656 25302 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0629 05:49:33.202678 25302 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0629 05:49:33.202693 25302 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '296af9b598c3' server FQDN: '296af9b598c3' SASL_AUXPROP_VERIF:
> Y_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0629 05:49:33.202698 25302 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0629 05:49:33.202702 25302 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0629 05:49:33.202713 25302 authenticator.cpp:318] Authentication success
> I0629 05:49:33.202810 25308 master.cpp:7505] Successfully authenticated principal 'test-principal' at slave(644)@172.17.0.3:45726
> I0629 05:49:33.202847 25307 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1230)@172.17.0.3:45726
> I0629 05:49:33.202766 25302 authenticatee.cpp:299] Authentication success
> I0629 05:49:33.202999 25302 slave.cpp:1081] Successfully authenticated with master master@172.17.0.3:45726
> I0629 05:49:33.203225 25302 slave.cpp:1509] Will retry registration in 6.854069ms if necessary
> I0629 05:49:33.203373 25309 master.cpp:5429] Received register agent message from slave(644)@172.17.0.3:45726 (296af9b598c3)
> I0629 05:49:33.203433 25309 master.cpp:3659] Authorizing agent with principal 'test-principal'
> I0629 05:49:33.203737 25306 master.cpp:5564] Registering agent at slave(644)@172.17.0.3:45726 (296af9b598c3) with id 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0
> I0629 05:49:33.204012 25308 registrar.cpp:493] Applied 1 operations in 28157ns; attempting to update the registry
> I0629 05:49:33.204355 25303 registrar.cpp:550] Successfully updated the registry in 277248ns
> I0629 05:49:33.204691 25303 master.cpp:5639] Registered agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0629 05:49:33.204764 25303 slave.cpp:4794] Received ping from slave-observer(589)@172.17.0.3:45726
> I0629 05:49:33.204795 25308 hierarchical.cpp:525] Added agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 (296af9b598c3) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
> I0629 05:49:33.204876 25303 slave.cpp:1127] Registered with master master@172.17.0.3:45726; given agent ID 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0
> I0629 05:49:33.204895 25303 fetcher.cpp:94] Clearing fetcher cache
> I0629 05:49:33.205031 25309 status_update_manager.cpp:184] Resuming sending status updates
> I0629 05:49:33.205252 25303 slave.cpp:1155] Checkpointing SlaveInfo to '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/meta/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/slave.info'
> I0629 05:49:33.205269 25308 hierarchical.cpp:1940] No inverse offers to send out!
> I0629 05:49:33.205291 25308 hierarchical.cpp:1434] Performed allocation for 1 agents in 251549ns
> I0629 05:49:33.205541 25309 master.cpp:7305] Sending 1 offers to framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.205585 25303 slave.cpp:1193] Forwarding total oversubscribed resources {}
> I0629 05:49:33.205760 25309 master.cpp:6324] Received update of agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3) with total oversubscribed resources {}
> I0629 05:49:33.205921 25308 sched.cpp:933] Scheduler::resourceOffers took 54996ns
> I0629 05:49:33.206763 25304 master.cpp:3875] Processing ACCEPT call for offers: [ 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-O0 ] on agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3) for framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.206811 25304 master.cpp:3426] Authorizing framework principal 'test-principal' to launch task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b
> I0629 05:49:33.207425 25304 master.cpp:9320] Adding task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b with resources cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] on agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3)
> I0629 05:49:33.207504 25304 master.cpp:4531] Launching task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726 with resources cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] on agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3)
> I0629 05:49:33.207877 25302 slave.cpp:1619] Got assigned task 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' for framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.208356 25304 hierarchical.cpp:850] Updated allocation of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 on agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077:
> -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]
> I0629 05:49:33.208642 25302 slave.cpp:1900] Authorizing task 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' for framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.208668 25302 slave.cpp:6694] Authorizing framework principal 'test-principal' to launch task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b
> I0629 05:49:33.208978 25302 slave.cpp:2087] Launching task 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' for framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.209475 25302 paths.cpp:573] Trying to chown '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000/executors/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b/runs/b36e964b-c357-4f62-a767-029668d71ff6' to user 'mesos'
> I0629 05:49:33.209678 25302 slave.cpp:7038] Launching executor 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 with resources cpus(*)(allocated: *):0.1; mem(*)(allocated: *):32 in work directory '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000/executors/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b/runs/b36e964b-c357-4f62-a767-029668d71ff6'
> I0629 05:49:33.210337 25302 slave.cpp:2316] Queued task 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' for executor 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.210480 25304 containerizer.cpp:1001] Starting container b36e964b-c357-4f62-a767-029668d71ff6 for executor 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.212021 25304 containerizer.cpp:1531] 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","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.3:45726"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw\/slaves\/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0\/frameworks\/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000\/executors\/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b\/runs\/b36e964b-c357-4f62-a767-029668d71ff6"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"ee05c102-e5cb-4cc2-9fb4-41fe1e06446b"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(644)@172.17.0.3:45726"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw\/slaves\/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0\/frameworks\/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000\/executors\/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b\/runs\/b36e964b-c357-4f62-a767-029668d71ff6"}]},"user":"mesos","working_directory":"\/tmp\/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw\/slaves\/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0\/frameworks\/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000\/executors\/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b\/runs\/b36e964b-c357-4f62-a767-029668d71ff6"}" --pipe_read="8" --pipe_write="9" --runtime_directory="/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ/containers/b36e964b-c357-4f62-a767-029668d71ff6" --unshare_namespace_mnt="false"'
> I0629 05:49:33.212301 25302 slave.cpp:877] Successfully attached file '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000/executors/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b/runs/b36e964b-c357-4f62-a767-029668d71ff6'
> I0629 05:49:33.214748 25304 launcher.cpp:140] Forked child with pid '28869' for container 'b36e964b-c357-4f62-a767-029668d71ff6'
> I0629 05:49:33.219424 25305 fetcher.cpp:353] Starting to fetch URIs for container: b36e964b-c357-4f62-a767-029668d71ff6, directory: /tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000/executors/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b/runs/b36e964b-c357-4f62-a767-029668d71ff6
> I0629 05:49:33.335734 25303 slave.cpp:3790] Got registration for executor 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 from executor(1)@172.17.0.3:40357
> I0629 05:49:33.337357 25306 slave.cpp:2529] Sending queued task 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' to executor 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 at executor(1)@172.17.0.3:40357
> I0629 05:49:33.344734 25305 slave.cpp:4264] Handling status update TASK_RUNNING (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 from executor(1)@172.17.0.3:40357
> I0629 05:49:33.346091 25306 status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9:
> fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.346123 25306 status_update_manager.cpp:500] Creating StatusUpdate stream for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.346360 25306 status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 to the agent
> I0629 05:49:33.346629 25306 slave.cpp:4704] Forwarding the update TASK_RUNNING (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 to master@172.17.0.3:45726
> I0629 05:49:33.346786 25306 slave.cpp:4598] Status update manager successfully handled status update TASK_RUNNING (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.346828 25306 slave.cpp:4614] Sending acknowledgement for status update TASK_RUNNING (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 to executor(1)@172.17.0.3:40357
> I0629 05:49:33.347121 25307 master.cpp:6469] Status update TASK_RUNNING (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 from agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3)
> I0629 05:49:33.347162 25307 master.cpp:6537] Forwarding status update TASK_RUNNING (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.347309 25307 master.cpp:8568] Updating the state of task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0629 05:49:33.347633 25304 sched.cpp:1041] Scheduler::statusUpdate took 82630ns
> I0629 05:49:33.347909 25309 master.cpp:5194] Processing ACKNOWLEDGE call 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07 for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726 on agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0
> I0629 05:49:33.348162 25307 status_update_manager.cpp:395] Received status update acknowledgement (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.348284 25307 slave.cpp:3510] Status update manager successfully handled status update acknowledgement (UUID: 3aa0c8c0-c78f-4c72-a638-ef2adf1eae07) for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.349153 25307 process.cpp:3731] Handling HTTP event for process 'slave(644)' with path: '/slave(644)/api/v1'
> I0629 05:49:33.349717 25305 http.cpp:1115] HTTP POST for /slave(644)/api/v1 from 172.17.0.3:38460
> I0629 05:49:33.350256 25305 http.cpp:527] Processing call LAUNCH_NESTED_CONTAINER_SESSION
> I0629 05:49:33.350522 25303 containerizer.cpp:1798] Starting nested container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b
> I0629 05:49:33.351016 25303 containerizer.cpp:1822] Trying to chown '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000/executors/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b/runs/b36e964b-c357-4f62-a767-029668d71ff6/containers/5bfa5b67-abd8-401d-a18e-7c800362d76b' to user 'mesos'
> I0629 05:49:33.352535 25309 switchboard.cpp:545] Launching 'mesos-io-switchboard' with flags '--heartbeat_interval="30secs" --help="false" --socket_address="/tmp/mesos-io-switchboard-8a787e7f-51e0-4f96-a310-73423d54dbd5" --stderr_from_fd="16" --stderr_to_fd="2" --stdin_to_fd="13" --stdout_from_fd="14" --stdout_to_fd="1" --tty="false" --wait_for_connection="true"' for container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b
> I0629 05:49:33.355439 25309 switchboard.cpp:575] Created I/O switchboard server (pid: 28881) listening on socket file '/tmp/mesos-io-switchboard-8a787e7f-51e0-4f96-a310-73423d54dbd5' for container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b
> I0629 05:49:33.356899 25309 containerizer.cpp:1531] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"shell":true,"value":"cat"},"environment":{},"user":"mesos"}" --pipe_read="13" --pipe_write="14" --runtime_directory="/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ/containers/b36e964b-c357-4f62-a767-029668d71ff6/containers/5bfa5b67-abd8-401d-a18e-7c800362d76b" --unshare_namespace_mnt="false"'
> I0629 05:49:33.358389 25309 launcher.cpp:140] Forked child with pid '28882' for container 'b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b'
> I0629 05:49:33.362704 25308 fetcher.cpp:353] Starting to fetch URIs for container: b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b, directory: /tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000/executors/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b/runs/b36e964b-c357-4f62-a767-029668d71ff6/containers/5bfa5b67-abd8-401d-a18e-7c800362d76b
> I0629 05:49:33.419852 25302 process.cpp:3731] Handling HTTP event for process 'slave(644)' with path: '/slave(644)/api/v1'
> I0629 05:49:33.420730 25302 http.cpp:1115] HTTP POST for /slave(644)/api/v1 from 172.17.0.3:38462
> I0629 05:49:33.421162 25308 http.cpp:527] Processing call ATTACH_CONTAINER_INPUT
> I0629 05:49:33.643208 25302 http.cpp:2808] Received EOF attach response for b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b
> I0629 05:49:33.643333 25302 containerizer.cpp:2109] Destroying container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b in RUNNING state
> W0629 05:49:33.643411 25306 http.cpp:2823] Launch nested container session connection for container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b closed
> I0629 05:49:33.643589 25302 launcher.cpp:156] Asked to destroy container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b
> I0629 05:49:33.656733 25305 process.cpp:3788] Failed to process request for '/slave(644)/api/v1': Disconnected
> I0629 05:49:33.656764 25306 process.cpp:1477] Returning '500 Internal Server Error' for '/slave(644)/api/v1' (Disconnected)
> /mesos/src/tests/api_tests.cpp:5487: Failure
> Value of: (response).get().status
> Actual: "500 Internal Server Error"
> Expected: http::OK().status
> Which is: "200 OK"
> I0629 05:49:33.683780 25306 master.cpp:1430] Framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726 disconnected
> I0629 05:49:33.683836 25306 master.cpp:3160] Deactivating framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.683857 25306 master.cpp:3137] Disconnecting framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.683899 25306 master.cpp:1445] Giving framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726 0ns to failover
> I0629 05:49:33.684054 25305 hierarchical.cpp:374] Deactivated framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.684756 25306 containerizer.cpp:2109] Destroying container b36e964b-c357-4f62-a767-029668d71ff6 in RUNNING state
> I0629 05:49:33.685206 25305 master.cpp:7146] Framework failover timeout, removing framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.685257 25305 master.cpp:8000] Removing framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (default) at scheduler-824cb0a6-7a56-4d6a-9e4d-4d302f0cfe06@172.17.0.3:45726
> I0629 05:49:33.685344 25305 master.cpp:8568] Updating the state of task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
> I0629 05:49:33.685416 25302 slave.cpp:3063] Asked to shut down framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 by master@172.17.0.3:45726
> I0629 05:49:33.685462 25302 slave.cpp:3088] Shutting down framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.685477 25302 slave.cpp:5531] Shutting down executor 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 at executor(1)@172.17.0.3:40357
> I0629 05:49:33.685734 25305 master.cpp:8662] Removing task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b with resources cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 on agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3)
> I0629 05:49:33.685771 25302 hierarchical.cpp:1114] Recovered cpus(*)(allocated: *):2; mem(*)(allocated: *):1024; disk(*)(allocated: *):1024; ports(*)(allocated: *):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 from framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.686462 25307 hierarchical.cpp:325] Removed framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.721328 25305 switchboard.cpp:888] I/O switchboard server process for container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b h:
> as terminated (status=0)
> I0629 05:49:33.721588 25302 containerizer.cpp:2515] Container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b has exited
> I0629 05:49:33.722765 25308 provisioner.cpp:484] Ignoring destroy request for unknown container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b
> I0629 05:49:33.722827 25308 containerizer.cpp:2388] Checkpointing termination state to nested container's runtime directory '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_AZGweZ/containers/b36e964b-c357-4f62-a767-029668d71ff6/containers/5bfa5b67-abd8-401d-a18e-7c800362d76b/termination'
> I0629 05:49:33.723461 25308 launcher.cpp:156] Asked to destroy container b36e964b-c357-4f62-a767-029668d71ff6
> I0629 05:49:33.731124 25308 slave.cpp:4836] Got exited event for executor(1)@172.17.0.3:40357
> I0629 05:49:33.822432 25305 containerizer.cpp:2515] Container b36e964b-c357-4f62-a767-029668d71ff6 has exited
> I0629 05:49:33.823519 25306 provisioner.cpp:484] Ignoring destroy request for unknown container b36e964b-c357-4f62-a767-029668d71ff6
> I0629 05:49:33.824609 25307 slave.cpp:5217] Executor 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 terminated with signal Killed
> I0629 05:49:33.824664 25307 slave.cpp:5317] Cleaning up executor 'ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000 at executor(1)@172.17.0.3:40357
> W0629 05:49:33.824992 25303 containerizer.cpp:2097] Attempted to destroy unknown container b36e964b-c357-4f62-a767-029668d71ff6.5bfa5b67-abd8-401d-a18e-7c800362d76b
> I0629 05:49:33.825323 25303 gc.cpp:55] Scheduling '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000/executors/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b/runs/b36e964b-c357-4f62-a767-029668d71ff6' for gc 6.99999044942222days in the future
> I0629 05:49:33.825505 25307 slave.cpp:5405] Cleaning up framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.825548 25305 gc.cpp:55] Scheduling '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000/executors/ee05c102-e5cb-4cc2-9fb4-41fe1e06446b' for gc 6.99999044592593days in the future
> I0629 05:49:33.825690 25305 status_update_manager.cpp:285] Closing status update streams for framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.825729 25305 status_update_manager.cpp:531] Cleaning up status update stream for task ee05c102-e5cb-4cc2-9fb4-41fe1e06446b of framework 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000
> I0629 05:49:33.825898 25307 slave.cpp:796] Agent terminating
> I0629 05:49:33.826009 25305 gc.cpp:55] Scheduling '/tmp/ContentType_AgentAPIStreamingTest_AttachInputToNestedContainerSession_0_2eciuw/slaves/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0/frameworks/90ea1640-bdf3-49ba-b78f-b2ba7ea30077-0000' for gc 6.99999044129778days in the future
> I0629 05:49:33.826244 25308 master.cpp:1313] Agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3) disconnected
> I0629 05:49:33.826398 25308 master.cpp:3197] Disconnecting agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3)
> I0629 05:49:33.826576 25308 master.cpp:3216] Deactivating agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 at slave(644)@172.17.0.3:45726 (296af9b598c3)
> I0629 05:49:33.826901 25302 hierarchical.cpp:653] Agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0 deactivated
> I0629 05:49:33.828503 25301 master.cpp:1155] Master terminating
> I0629 05:49:33.828763 25306 hierarchical.cpp:558] Removed agent 90ea1640-bdf3-49ba-b78f-b2ba7ea30077-S0
> [ FAILED ] ContentType/AgentAPIStreamingTest.AttachInputToNestedContainerSession/0, where GetParam() = application/x-protobuf (656 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)