See
<https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=autotools,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=centos%3A7,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4473/display/redirect?page=changes>
Changes:
[bmahler] Added a Future constructor for Try<Future<T>>.
------------------------------------------
[...truncated 7.16 MB...]
I1120 01:18:14.188364 6898 master.cpp:4228] Processing ACCEPT call for offers:
[ 9551275e-401b-45fe-b9e7-3b909dd81021-O0 ] on agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0 at slave(69)@172.17.0.4:44320
(9a9993d9e9bd) for framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
(default) at scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320
I1120 01:18:14.188524 6898 master.cpp:3597] Authorizing framework principal
'test-principal' to launch task 0
I1120 01:18:14.191622 6906 master.cpp:10770] Adding task 0 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1.0},"type":"SCALAR"}]
on agent 9551275e-401b-45fe-b9e7-3b909dd81021-S0 at slave(69)@172.17.0.4:44320
(9a9993d9e9bd)
I1120 01:18:14.192342 6906 master.cpp:4976] Launching task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 (default) at
scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1.0},"type":"SCALAR"}]
on agent 9551275e-401b-45fe-b9e7-3b909dd81021-S0 at slave(69)@172.17.0.4:44320
(9a9993d9e9bd)
I1120 01:18:14.193706 6902 slave.cpp:1803] Got assigned task '0' for framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.193897 6902 slave.cpp:7655] Checkpointing FrameworkInfo to
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/framework.info'
I1120 01:18:14.194121 6917 hierarchical.cpp:1132] Recovered cpus(allocated:
*):999; mem(allocated: *):999; disk(allocated: *):367489; ports(allocated:
*):[31000-32000] (total: cpus:1000; mem:1000; disk:367489; ports:[31000-32000],
allocated: cpus(allocated: *):1; mem(allocated: *):1) on agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0 from framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.194247 6917 hierarchical.cpp:1178] Framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 filtered agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0 for 5secs
I1120 01:18:14.194330 6902 slave.cpp:7666] Checkpointing framework pid
'scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320' to
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/framework.pid'
I1120 01:18:14.195266 6902 slave.cpp:2071] Authorizing task '0' for framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.195369 6902 slave.cpp:7262] Authorizing framework principal
'test-principal' to launch task 0
I1120 01:18:14.196403 6905 slave.cpp:2239] Launching task '0' for framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.197023 6905 paths.cpp:621] Trying to chown
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23'
to user 'mesos'
I1120 01:18:14.197520 6905 slave.cpp:8360] Checkpointing ExecutorInfo to
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/executor.info'
I1120 01:18:14.199012 6905 slave.cpp:7736] Launching executor '0' of framework
9551275e-401b-45fe-b9e7-3b909dd81021-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/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23'
I1120 01:18:14.200307 6905 slave.cpp:2930] Launching container
90392195-7a36-45fb-a93e-59616dd19c23 for executor '0' of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.200830 6903 containerizer.cpp:1149] Starting container
90392195-7a36-45fb-a93e-59616dd19c23
I1120 01:18:14.200949 6905 slave.cpp:8403] Checkpointing TaskInfo to
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23/tasks/0/task.info'
I1120 01:18:14.201665 6903 containerizer.cpp:2818] Transitioning the state of
container 90392195-7a36-45fb-a93e-59616dd19c23 from PROVISIONING to PREPARING
I1120 01:18:14.201969 6905 slave.cpp:2467] Queued task '0' for executor '0' of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.202219 6905 slave.cpp:958] Successfully attached
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23'
to virtual path
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/latest'
I1120 01:18:14.202344 6905 slave.cpp:958] Successfully attached
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23'
to virtual path
'/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/latest'
I1120 01:18:14.202446 6905 slave.cpp:958] Successfully attached
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23'
to virtual path
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23'
I1120 01:18:14.207136 6899 containerizer.cpp:1768] Launching
'mesos-containerizer' with flags '--help="false"
--launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.5.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.5.0\/_build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.4:44320"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"1"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/FetcherCacheTest_CachedCustomFilename_iqVy5C\/slaves\/9551275e-401b-45fe-b9e7-3b909dd81021-S0\/frameworks\/9551275e-401b-45fe-b9e7-3b909dd81021-0000\/executors\/0\/runs\/90392195-7a36-45fb-a93e-59616dd19c23"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"0"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"9551275e-401b-45fe-b9e7-3b909dd81021-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_RECOVERY_TIMEOUT","type":"VALUE","value":"15mins"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"9551275e-401b-45fe-b9e7-3b909dd81021-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(69)@172.17.0.4:44320"},{"name":"MESOS_SUBSCRIPTION_BACKOFF_MAX","type":"VALUE","value":"2secs"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/FetcherCacheTest_CachedCustomFilename_iqVy5C\/slaves\/9551275e-401b-45fe-b9e7-3b909dd81021-S0\/frameworks\/9551275e-401b-45fe-b9e7-3b909dd81021-0000\/executors\/0\/runs\/90392195-7a36-45fb-a93e-59616dd19c23"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/FetcherCacheTest_CachedCustomFilename_iqVy5C\/slaves\/9551275e-401b-45fe-b9e7-3b909dd81021-S0\/frameworks\/9551275e-401b-45fe-b9e7-3b909dd81021-0000\/executors\/0\/runs\/90392195-7a36-45fb-a93e-59616dd19c23"}"
--pipe_read="6" --pipe_write="7"
--runtime_directory="/tmp/FetcherCacheTest_CachedCustomFilename_zu1OHO/containers/90392195-7a36-45fb-a93e-59616dd19c23"
--unshare_namespace_mnt="false"'
I1120 01:18:14.210378 6899 launcher.cpp:140] Forked child with pid '10329' for
container '90392195-7a36-45fb-a93e-59616dd19c23'
I1120 01:18:14.211501 6899 containerizer.cpp:1860] Checkpointing container's
forked pid 10329 to
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23/pids/forked.pid'
I1120 01:18:14.212813 6899 containerizer.cpp:2818] Transitioning the state of
container 90392195-7a36-45fb-a93e-59616dd19c23 from PREPARING to ISOLATING
I1120 01:18:14.214440 6897 containerizer.cpp:2818] Transitioning the state of
container 90392195-7a36-45fb-a93e-59616dd19c23 from ISOLATING to FETCHING
I1120 01:18:14.214753 6905 fetcher.cpp:379] Starting to fetch URIs for
container: 90392195-7a36-45fb-a93e-59616dd19c23, directory:
/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23
I1120 01:18:14.214965 6905 fetcher.cpp:1002] Created cache entry
'mesos@/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
with file: c1-mesos-fetc_r-test-cmd
I1120 01:18:14.215361 6903 fetcher.cpp:322] Fetching size for URI:
/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/mesos-fetcher-test-assets/mesos-fetcher-test-cmd
I1120 01:18:14.215848 6905 fetcher.cpp:723] Claiming fetcher cache space for:
mesos@/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/mesos-fetcher-test-assets/mesos-fetcher-test-cmd
I1120 01:18:14.215874 6905 fetcher.cpp:1213] Claimed cache space: 30B, now
using: 30B
I1120 01:18:14.217190 6909 fetcher.cpp:876] Fetching URIs using command
'/mesos/mesos-1.5.0/_build/src/mesos-fetcher'
I1120 01:18:14.374312 6900 fetcher.cpp:1225] Released cache space: 0B, now
using: 30B
I1120 01:18:14.374788 6911 containerizer.cpp:2818] Transitioning the state of
container 90392195-7a36-45fb-a93e-59616dd19c23 from FETCHING to RUNNING
I1120 01:18:14.502418 10340 exec.cpp:162] Version: 1.5.0
I1120 01:18:14.518899 6914 slave.cpp:4063] Got registration for executor '0'
of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 from
executor(1)@172.17.0.4:44341
I1120 01:18:14.519949 6914 slave.cpp:4149] Checkpointing executor pid
'executor(1)@172.17.0.4:44341' to
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23/pids/libprocess.pid'
I1120 01:18:14.523679 6905 slave.cpp:2669] Sending queued task '0' to executor
'0' of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 at
executor(1)@172.17.0.4:44341
I1120 01:18:14.527382 10352 exec.cpp:237] Executor registered on agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0
I1120 01:18:14.532616 10356 executor.cpp:171] Received SUBSCRIBED event
I1120 01:18:14.534992 10356 executor.cpp:175] Subscribed executor on
9a9993d9e9bd
I1120 01:18:14.535373 10356 executor.cpp:171] Received LAUNCH event
I1120 01:18:14.538293 10356 executor.cpp:637] Starting task 0
I1120 01:18:14.542727 6896 slave.cpp:4517] Handling status update
TASK_STARTING (UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 from
executor(1)@172.17.0.4:44341
I1120 01:18:14.545210 6914 status_update_manager.cpp:323] Received status
update TASK_STARTING (UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.545315 6914 status_update_manager.cpp:500] Creating
StatusUpdate stream for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.546334 6914 status_update_manager.cpp:834] Checkpointing UPDATE
for status update TASK_STARTING (UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1)
for task 0 of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.546761 6914 status_update_manager.cpp:377] Forwarding update
TASK_STARTING (UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 to the agent
I1120 01:18:14.547264 6919 slave.cpp:4998] Forwarding the update TASK_STARTING
(UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 to master@172.17.0.4:44320
I1120 01:18:14.547616 6919 slave.cpp:4892] Status update manager successfully
handled status update TASK_STARTING (UUID:
9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.547698 6919 slave.cpp:4908] Sending acknowledgement for status
update TASK_STARTING (UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 to
executor(1)@172.17.0.4:44341
I1120 01:18:14.548003 6897 master.cpp:7247] Status update TASK_STARTING (UUID:
9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 from agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0 at slave(69)@172.17.0.4:44320
(9a9993d9e9bd)
I1120 01:18:14.548105 6897 master.cpp:7309] Forwarding status update
TASK_STARTING (UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.548414 6897 master.cpp:9502] Updating the state of task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 (latest state:
TASK_STARTING, status update state: TASK_STARTING)
I1120 01:18:14.548929 6903 sched.cpp:1029] Scheduler::statusUpdate took
216929ns
I1120 01:18:14.549396 6903 master.cpp:5791] Processing ACKNOWLEDGE call
9a078d0c-1767-405b-b801-e7e406ee1ae1 for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 (default) at
scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320 on agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0
I1120 01:18:14.550002 6916 status_update_manager.cpp:395] Received status
update acknowledgement (UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0
of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.550232 6916 status_update_manager.cpp:834] Checkpointing ACK
for status update TASK_STARTING (UUID: 9a078d0c-1767-405b-b801-e7e406ee1ae1)
for task 0 of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.550743 6899 slave.cpp:3801] Status update manager successfully
handled status update acknowledgement (UUID:
9a078d0c-1767-405b-b801-e7e406ee1ae1) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.568255 10356 executor.cpp:477] Running
'/mesos/mesos-1.5.0/_build/src/mesos-containerizer launch
<POSSIBLY-SENSITIVE-DATA>'
I1120 01:18:14.572101 10356 executor.cpp:650] Forked command at 10359
I1120 01:18:14.577348 6910 slave.cpp:4517] Handling status update TASK_RUNNING
(UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 from executor(1)@172.17.0.4:44341
I1120 01:18:14.580013 6898 status_update_manager.cpp:323] Received status
update TASK_RUNNING (UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.580114 6898 status_update_manager.cpp:834] Checkpointing UPDATE
for status update TASK_RUNNING (UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for
task 0 of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.580416 6898 status_update_manager.cpp:377] Forwarding update
TASK_RUNNING (UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 to the agent
I1120 01:18:14.580736 6906 slave.cpp:4998] Forwarding the update TASK_RUNNING
(UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 to master@172.17.0.4:44320
I1120 01:18:14.580950 6906 slave.cpp:4892] Status update manager successfully
handled status update TASK_RUNNING (UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86)
for task 0 of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.581008 6906 slave.cpp:4908] Sending acknowledgement for status
update TASK_RUNNING (UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 to
executor(1)@172.17.0.4:44341
I1120 01:18:14.581197 6914 master.cpp:7247] Status update TASK_RUNNING (UUID:
e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 from agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0 at slave(69)@172.17.0.4:44320
(9a9993d9e9bd)
I1120 01:18:14.581288 6914 master.cpp:7309] Forwarding status update
TASK_RUNNING (UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.581535 6914 master.cpp:9502] Updating the state of task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 (latest state:
TASK_RUNNING, status update state: TASK_RUNNING)
I1120 01:18:14.582027 6919 sched.cpp:1029] Scheduler::statusUpdate took
170415ns
I1120 01:18:14.582474 6897 master.cpp:5791] Processing ACKNOWLEDGE call
e44c0d91-2c8a-44c2-991d-b4b2d8400b86 for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 (default) at
scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320 on agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0
I1120 01:18:14.582993 6903 status_update_manager.cpp:395] Received status
update acknowledgement (UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0
of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.583214 6903 status_update_manager.cpp:834] Checkpointing ACK
for status update TASK_RUNNING (UUID: e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for
task 0 of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.583642 6901 slave.cpp:3801] Status update manager successfully
handled status update acknowledgement (UUID:
e44c0d91-2c8a-44c2-991d-b4b2d8400b86) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.801780 10346 executor.cpp:929] Command exited with status 0
(pid: 10359)
I1120 01:18:14.810324 6908 slave.cpp:4517] Handling status update
TASK_FINISHED (UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 from
executor(1)@172.17.0.4:44341
I1120 01:18:14.814836 6919 status_update_manager.cpp:323] Received status
update TASK_FINISHED (UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.814965 6919 status_update_manager.cpp:834] Checkpointing UPDATE
for status update TASK_FINISHED (UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed)
for task 0 of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.815373 6919 status_update_manager.cpp:377] Forwarding update
TASK_FINISHED (UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 to the agent
I1120 01:18:14.815763 6905 slave.cpp:4998] Forwarding the update TASK_FINISHED
(UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 to master@172.17.0.4:44320
I1120 01:18:14.816125 6905 slave.cpp:4892] Status update manager successfully
handled status update TASK_FINISHED (UUID:
c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.816231 6905 slave.cpp:4908] Sending acknowledgement for status
update TASK_FINISHED (UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 to
executor(1)@172.17.0.4:44341
I1120 01:18:14.816423 6908 master.cpp:7247] Status update TASK_FINISHED (UUID:
c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 from agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0 at slave(69)@172.17.0.4:44320
(9a9993d9e9bd)
I1120 01:18:14.816540 6908 master.cpp:7309] Forwarding status update
TASK_FINISHED (UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.816907 6908 master.cpp:9502] Updating the state of task 0 of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 (latest state:
TASK_FINISHED, status update state: TASK_FINISHED)
I1120 01:18:14.817276 6911 sched.cpp:1029] Scheduler::statusUpdate took
172830ns
I1120 01:18:14.817711 6917 master.cpp:5791] Processing ACKNOWLEDGE call
c1a160ab-fdce-4b92-bd1d-b15fa35df4ed for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 (default) at
scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320 on agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0
I1120 01:18:14.817822 6912 hierarchical.cpp:1132] Recovered cpus(allocated:
*):1; mem(allocated: *):1 (total: cpus:1000; mem:1000; disk:367489;
ports:[31000-32000], allocated: {}) on agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0 from framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.817796 6917 master.cpp:9596] Removing task 0 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1.0},"type":"SCALAR"}]
of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 on agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0 at slave(69)@172.17.0.4:44320
(9a9993d9e9bd)
I1120 01:18:14.818580 6913 status_update_manager.cpp:395] Received status
update acknowledgement (UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0
of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.818704 6913 status_update_manager.cpp:834] Checkpointing ACK
for status update TASK_FINISHED (UUID: c1a160ab-fdce-4b92-bd1d-b15fa35df4ed)
for task 0 of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.818827 6913 status_update_manager.cpp:531] Cleaning up status
update stream for task 0 of framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.819569 6913 slave.cpp:3801] Status update manager successfully
handled status update acknowledgement (UUID:
c1a160ab-fdce-4b92-bd1d-b15fa35df4ed) for task 0 of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.819651 6913 slave.cpp:8341] Completing task 0
I1120 01:18:14.822269 6904 process.cpp:3932] Handling HTTP event for process
'metrics' with path: '/metrics/snapshot'
I1120 01:18:14.823981 6916 http.cpp:851] Authorizing principal 'ANY' to GET
the endpoint '/metrics/snapshot'
I1120 01:18:14.848322 6895 sched.cpp:2009] Asked to stop the driver
I1120 01:18:14.848474 6909 sched.cpp:1191] Stopping framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.848773 6917 master.cpp:8792] Processing TEARDOWN call for
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 (default) at
scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320
I1120 01:18:14.848815 6917 master.cpp:8804] Removing framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 (default) at
scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320
I1120 01:18:14.848846 6917 master.cpp:3331] Deactivating framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 (default) at
scheduler-03447d5e-969d-4a58-ab59-42f1fe21a78f@172.17.0.4:44320
I1120 01:18:14.849084 6902 hierarchical.cpp:419] Deactivated framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.849172 6898 slave.cpp:3267] Asked to shut down framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 by master@172.17.0.4:44320
I1120 01:18:14.849218 6898 slave.cpp:3292] Shutting down framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.849264 6898 slave.cpp:5874] Shutting down executor '0' of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 at
executor(1)@172.17.0.4:44341
I1120 01:18:14.849413 6917 master.cpp:1151] Master terminating
I1120 01:18:14.849642 6918 hierarchical.cpp:358] Removed framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.850214 6917 slave.cpp:5130] Got exited event for
master@172.17.0.4:44320
W1120 01:18:14.850247 6917 slave.cpp:5135] Master disconnected! Waiting for a
new master to be elected
I1120 01:18:14.850296 6918 hierarchical.cpp:633] Removed agent
9551275e-401b-45fe-b9e7-3b909dd81021-S0
I1120 01:18:14.850417 10340 exec.cpp:435] Executor asked to shutdown
I1120 01:18:14.850833 10352 executor.cpp:171] Received SHUTDOWN event
I1120 01:18:14.850869 10352 executor.cpp:747] Shutting down
I1120 01:18:14.854946 6911 containerizer.cpp:2254] Destroying container
90392195-7a36-45fb-a93e-59616dd19c23 in RUNNING state
I1120 01:18:14.854998 6911 containerizer.cpp:2818] Transitioning the state of
container 90392195-7a36-45fb-a93e-59616dd19c23 from RUNNING to DESTROYING
I1120 01:18:14.855353 6911 launcher.cpp:156] Asked to destroy container
90392195-7a36-45fb-a93e-59616dd19c23
I1120 01:18:14.870409 6914 slave.cpp:5130] Got exited event for
executor(1)@172.17.0.4:44341
I1120 01:18:14.878864 6906 containerizer.cpp:2705] Container
90392195-7a36-45fb-a93e-59616dd19c23 has exited
I1120 01:18:14.881841 6897 provisioner.cpp:490] Ignoring destroy request for
unknown container 90392195-7a36-45fb-a93e-59616dd19c23
I1120 01:18:14.882962 6900 slave.cpp:5539] Executor '0' of framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000 terminated with signal Killed
I1120 01:18:14.883040 6900 slave.cpp:5643] Cleaning up executor '0' of
framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000 at
executor(1)@172.17.0.4:44341
I1120 01:18:14.883580 6901 gc.cpp:90] Scheduling
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23'
for gc 6.99998977530074days in the future
I1120 01:18:14.883891 6901 gc.cpp:90] Scheduling
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0'
for gc 6.9999897726163days in the future
I1120 01:18:14.884009 6900 slave.cpp:5750] Cleaning up framework
9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.884057 6901 gc.cpp:90] Scheduling
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0/runs/90392195-7a36-45fb-a93e-59616dd19c23'
for gc 6.99998977107556days in the future
I1120 01:18:14.884207 6901 gc.cpp:90] Scheduling
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000/executors/0'
for gc 6.99998976947852days in the future
I1120 01:18:14.884281 6909 status_update_manager.cpp:285] Closing status
update streams for framework 9551275e-401b-45fe-b9e7-3b909dd81021-0000
I1120 01:18:14.884347 6901 gc.cpp:90] Scheduling
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000'
for gc 6.99998976639111days in the future
I1120 01:18:14.884434 6900 slave.cpp:883] Agent terminating
I1120 01:18:14.884538 6901 gc.cpp:90] Scheduling
'/tmp/FetcherCacheTest_CachedCustomFilename_iqVy5C/meta/slaves/9551275e-401b-45fe-b9e7-3b909dd81021-S0/frameworks/9551275e-401b-45fe-b9e7-3b909dd81021-0000'
for gc 6.99998976531259days in the future
[ OK ] FetcherCacheTest.CachedCustomFilename (800 ms)
[ RUN ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory
I1120 01:18:14.917264 6895 cluster.cpp:162] Creating default 'local' authorizer
I1120 01:18:14.921609 6909 master.cpp:448] Master
ba5917a9-f240-403b-959b-a0a936fe1ac8 (9a9993d9e9bd) started on 172.17.0.4:44320
I1120 01:18:14.921655 6909 master.cpp:450] 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/j0iSpX/credentials"
--filter_gpu_resources="true" --framework_sorter="drf" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--http_framework_authenticators="basic" --initialize_driver_logging="true"
--log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
--max_agent_ping_timeouts="5" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000"
--max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/mesos/mesos-1.5.0/_inst/share/mesos/webui"
--work_dir="/tmp/j0iSpX/master" --zk_session_timeout="10secs"
I1120 01:18:14.922246 6909 master.cpp:499] Master only allowing authenticated
frameworks to register
I1120 01:18:14.922264 6909 master.cpp:505] Master only allowing authenticated
agents to register
I1120 01:18:14.922276 6909 master.cpp:511] Master only allowing authenticated
HTTP frameworks to register
I1120 01:18:14.922286 6909 credentials.hpp:37] Loading credentials for
authentication from '/tmp/j0iSpX/credentials'
I1120 01:18:14.922817 6909 master.cpp:555] Using default 'crammd5'
authenticator
I1120 01:18:14.923085 6909 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1120 01:18:14.923429 6909 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1120 01:18:14.923629 6909 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1120 01:18:14.923823 6909 master.cpp:634] Authorization enabled
I1120 01:18:14.924154 6914 whitelist_watcher.cpp:77] No whitelist given
I1120 01:18:14.924197 6902 hierarchical.cpp:173] Initialized hierarchical
allocator process
I1120 01:18:14.928532 6899 master.cpp:2213] Elected as the leading master!
I1120 01:18:14.928586 6899 master.cpp:1693] Recovering from registrar
I1120 01:18:14.928820 6916 registrar.cpp:347] Recovering registrar
I1120 01:18:14.929518 6916 registrar.cpp:391] Successfully fetched the
registry (0B) in 642048ns
I1120 01:18:14.929656 6916 registrar.cpp:495] Applied 1 operations in 33996ns;
attempting to update the registry
I1120 01:18:14.930618 6900 registrar.cpp:552] Successfully updated the
registry in 858112ns
I1120 01:18:14.930847 6900 registrar.cpp:424] Successfully recovered registrar
I1120 01:18:14.931675 6904 hierarchical.cpp:211] Skipping recovery of
hierarchical allocator: nothing to recover
I1120 01:18:14.931763 6919 master.cpp:1806] Recovered 0 agents from the
registry (129B); allowing 10mins for agents to re-register
W1120 01:18:14.932543 6895 process.cpp:3185] Attempted to spawn already
running process version@172.17.0.4:44320
I1120 01:18:14.933642 6895 containerizer.cpp:301] Using isolation {
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W1120 01:18:14.934351 6895 backend.cpp:76] Failed to create 'aufs' backend:
AufsBackend requires root privileges
W1120 01:18:14.934515 6895 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
I1120 01:18:14.934562 6895 provisioner.cpp:255] Using default backend 'copy'
W1120 01:18:14.939482 6895 process.cpp:3185] Attempted to spawn already
running process files@172.17.0.4:44320
I1120 01:18:14.939798 6895 cluster.cpp:448] Creating default 'local' authorizer
I1120 01:18:14.942322 6919 slave.cpp:262] Mesos agent started on
(70)@172.17.0.4:44320
I1120 01:18:14.942370 6919 slave.cpp:263] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_KOdovo/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/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_KOdovo/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/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_KOdovo/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/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_KOdovo/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/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_KOdovo/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --launcher="posix"
--launcher_dir="/mesos/mesos-1.5.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns"
--quiet="false" --recover="reconnect" --recovery_timeout="15mins"
--registration_backoff_factor="10ms" --resources="cpus:1000;mem:1000"
--revocable_cpu_low_priority="true"
--runtime_dir="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_KOdovo"
--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/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_oMGCXa"
--zk_session_timeout="10secs"
I1120 01:18:14.943146 6919 credentials.hpp:86] Loading credential for
authentication from
'/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_KOdovo/credential'
I1120 01:18:14.943480 6919 slave.cpp:295] Agent using credential for:
test-principal
I1120 01:18:14.943527 6919 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_KOdovo/http_credentials'
I1120 01:18:14.943857 6919 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1120 01:18:14.944090 6919 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1120 01:18:14.945916 6919 slave.cpp:593] Agent resources:
[{"name":"cpus","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I1120 01:18:14.946275 6919 slave.cpp:601] Agent attributes: [ ]
I1120 01:18:14.946300 6919 slave.cpp:610] Agent hostname: 9a9993d9e9bd
I1120 01:18:14.946605 6906 status_update_manager.cpp:177] Pausing sending
status updates
I1120 01:18:14.949177 6911 state.cpp:64] Recovering state from
'/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_oMGCXa/meta'
I1120 01:18:14.949677 6911 status_update_manager.cpp:203] Recovering status
update manager
I1120 01:18:14.949954 6905 containerizer.cpp:662] Recovering containerizer
I1120 01:18:14.951786 6899 provisioner.cpp:416] Provisioner recovery complete
I1120 01:18:14.952172 6899 slave.cpp:6441] Finished recovery
I1120 01:18:14.953021 6897 status_update_manager.cpp:177] Pausing sending
status updates
I1120 01:18:14.953079 6919 slave.cpp:1007] New master detected at
master@172.17.0.4:44320
I1120 01:18:14.953291 6919 slave.cpp:1042] Detecting new master
I1120 01:18:14.961755 6916 slave.cpp:1069] Authenticating with master
master@172.17.0.4:44320
I1120 01:18:14.961899 6916 slave.cpp:1078] Using default CRAM-MD5 authenticatee
I1120 01:18:14.962262 6901 authenticatee.cpp:121] Creating new client SASL
connection
I1120 01:18:14.962653 6911 master.cpp:8285] Authenticating
slave(70)@172.17.0.4:44320
I1120 01:18:14.962875 6918 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(159)@172.17.0.4:44320
I1120 01:18:14.963294 6898 authenticator.cpp:98] Creating new server SASL
connection
I1120 01:18:14.963721 6902 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1120 01:18:14.963779 6902 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1120 01:18:14.964048 6912 authenticator.cpp:204] Received SASL authentication
start
I1120 01:18:14.964176 6912 authenticator.cpp:326] Authentication requires more
steps
I1120 01:18:14.964328 6912 authenticatee.cpp:259] Received SASL authentication
step
I1120 01:18:14.964536 6909 authenticator.cpp:232] Received SASL authentication
step
I1120 01:18:14.964579 6909 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '9a9993d9e9bd' server FQDN: '9a9993d9e9bd'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1120 01:18:14.964596 6909 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1120 01:18:14.964638 6909 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1120 01:18:14.964663 6909 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '9a9993d9e9bd' server FQDN: '9a9993d9e9bd'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1120 01:18:14.964676 6909 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1120 01:18:14.964689 6909 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1120 01:18:14.964709 6909 authenticator.cpp:318] Authentication success
I1120 01:18:14.964835 6910 authenticatee.cpp:299] Authentication success
I1120 01:18:14.964870 6905 master.cpp:8315] Successfully authenticated
principal 'test-principal' at slave(70)@172.17.0.4:44320
I1120 01:18:14.964918 6908 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(159)@172.17.0.4:44320
I1120 01:18:14.965138 6910 slave.cpp:1161] Successfully authenticated with
master master@172.17.0.4:44320
I1120 01:18:14.965396 6910 slave.cpp:1682] Will retry registration in
8.879238ms if necessary
I1120 01:18:14.965687 6913 master.cpp:6032] Received register agent message
from slave(70)@172.17.0.4:44320 (9a9993d9e9bd)
I1120 01:18:14.965903 6913 master.cpp:3870] Authorizing agent with principal
'test-principal'
I1120 01:18:14.966382 6899 master.cpp:6092] Authorized registration of agent
at slave(70)@172.17.0.4:44320 (9a9993d9e9bd)
I1120 01:18:14.966508 6899 master.cpp:6185] Registering agent at
slave(70)@172.17.0.4:44320 (9a9993d9e9bd) with id
ba5917a9-f240-403b-959b-a0a936fe1ac8-S0
I1120 01:18:14.967104 6917 registrar.cpp:495] Applied 1 operations in 91207ns;
attempting to update the registry
I1120 01:18:14.967955 6917 registrar.cpp:552] Successfully updated the
registry in 762112ns
I1120 01:18:14.968269 6916 master.cpp:6232] Admitted agent
ba5917a9-f240-403b-959b-a0a936fe1ac8-S0 at slave(70)@172.17.0.4:44320
(9a9993d9e9bd)
I1120 01:18:14.969172 6916 master.cpp:6263] Registered agent
ba5917a9-f240-403b-959b-a0a936fe1ac8-S0 at slave(70)@172.17.0.4:44320
(9a9993d9e9bd) with
[{"name":"cpus","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":367489.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I1120 01:18:14.969540 6911 slave.cpp:1207] Registered with master
master@172.17.0.4:44320; given agent ID ba5917a9-f240-403b-959b-a0a936fe1ac8-S0
I1120 01:18:14.969636 6918 hierarchical.cpp:600] Added agent
ba5917a9-f240-403b-959b-a0a936fe1ac8-S0 (9a9993d9e9bd) with cpus:1000;
mem:1000; disk:367489; ports:[31000-32000] (allocated: {})
I1120 01:18:14.969719 6912 status_update_manager.cpp:184] Resuming sending
status updates
I1120 01:18:14.969983 6911 slave.cpp:1227] Checkpointing SlaveInfo to
'/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_oMGCXa/meta/slaves/ba5917a9-f240-403b-959b-a0a936fe1ac8-S0/slave.info'
I1120 01:18:14.970046 6918 hierarchical.cpp:1457] Performed allocation for 1
agents in 200351ns
I1120 01:18:14.970607 6911 slave.cpp:1295] Forwarding total oversubscribed
resources {}
I1120 01:18:14.970854 6904 master.cpp:7064] Received update of agent
ba5917a9-f240-403b-959b-a0a936fe1ac8-S0 at slave(70)@172.17.0.4:44320
(9a9993d9e9bd) with total oversubscribed resources {}
I1120 01:18:14.970947 6895 sched.cpp:232] Version: 1.5.0
I1120 01:18:14.971066 6904 master.cpp:7082] Ignoring update on agent
ba5917a9-f240-403b-959b-a0a936fe1ac8-S0 at slave(70)@172.17.0.4:44320
(9a9993d9e9bd) as it reports no changes
I1120 01:18:14.971552 6896 sched.cpp:336] New master detected at
master@172.17.0.4:44320
I1120 01:18:14.971662 6896 sched.cpp:396] Authenticating with master
master@172.17.0.4:44320
I1120 01:18:14.971684 6896 sched.cpp:403] Using default CRAM-MD5 authenticatee
I1120 01:18:14.971917 6899 authenticatee.cpp:121] Creating new client SASL
connection
I1120 01:18:14.972299 6903 master.cpp:8285] Authenticating
scheduler-15ed88be-3760-4e7d-893a-7ee988726663@172.17.0.4:44320
I1120 01:18:14.972548 6919 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(160)@172.17.0.4:44320
I1120 01:18:14.972928 6915 authenticator.cpp:98] Creating new server SASL
connection
I1120 01:18:14.973238 6917 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1120 01:18:14.973276 6917 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1120 01:18:14.973415 6917 authenticator.cpp:204] Received SASL authentication
start
I1120 01:18:14.973528 6917 authenticator.cpp:326] Authentication requires more
steps
I1120 01:18:14.973696 6916 authenticatee.cpp:259] Received SASL authentication
step
I1120 01:18:14.973877 6916 authenticator.cpp:232] Received SASL authentication
step
I1120 01:18:14.973918 6916 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '9a9993d9e9bd' server FQDN: '9a9993d9e9bd'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I1120 01:18:14.973937 6916 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1120 01:18:14.973992 6916 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1120 01:18:14.974033 6916 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: '9a9993d9e9bd' server FQDN: '9a9993d9e9bd'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I1120 01:18:14.974046 6916 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1120 01:18:14.974056 6916 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1120 01:18:14.974089 6916 authenticator.cpp:318] Authentication success
Build step 'Execute shell' marked build as failure
Not sending mail to unregistered user gregorywm...@gmail.com
Not sending mail to unregistered user xuj...@apple.com
