FailedConsole Output

Skipping 5,812 KB.. Full Log
ners
18-05-21:08:00:15 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:00:15 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:00:18 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:00:19 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:00:20 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:00:20 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:00:20 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:00:20 INFO     [clipper_admin.py:456] {u'stream': u' ---> 24edddcc0fa3\n'}
18-05-21:08:00:20 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 24edddcc0fa3\n'}
18-05-21:08:00:20 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged m:v1\n'}
18-05-21:08:00:20 INFO     [clipper_admin.py:458] Pushing model Docker image to m:v1
18-05-21:08:00:20 INFO     [docker_container_manager.py:257] Found 0 replicas for m:v1. Adding 1
18-05-21:08:00:27 INFO     [clipper_admin.py:635] Successfully registered model m:v1
18-05-21:08:00:27 INFO     [clipper_admin.py:553] Done deploying model m:v1.
ok
test_set_num_replicas_for_deployed_model_succeeds (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:00:27 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:01:10 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:01:10 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:01:10 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:01:14 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:01:15 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:01:15 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:01:15 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:01:15 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:01:15 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:01:15 INFO     [clipper_admin.py:456] {u'stream': u' ---> 24edddcc0fa3\n'}
18-05-21:08:01:15 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 24edddcc0fa3\n'}
18-05-21:08:01:15 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged set-num-reps-model:v1\n'}
18-05-21:08:01:15 INFO     [clipper_admin.py:458] Pushing model Docker image to set-num-reps-model:v1
18-05-21:08:01:16 INFO     [docker_container_manager.py:257] Found 0 replicas for set-num-reps-model:v1. Adding 1
18-05-21:08:01:22 INFO     [clipper_admin.py:635] Successfully registered model set-num-reps-model:v1
18-05-21:08:01:22 INFO     [clipper_admin.py:553] Done deploying model set-num-reps-model:v1.
18-05-21:08:01:22 INFO     [docker_container_manager.py:257] Found 1 replicas for set-num-reps-model:v1. Adding 3
18-05-21:08:01:32 INFO     [docker_container_manager.py:278] Found 4 replicas for set-num-reps-model:v1. Removing 2
ok
test_remove_inactive_containers_succeeds (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:01:54 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:02:50 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:02:50 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:02:50 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:02:55 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:02:56 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:02:57 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:02:57 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:02:57 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:02:57 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:02:57 INFO     [clipper_admin.py:456] {u'stream': u' ---> 24edddcc0fa3\n'}
18-05-21:08:02:57 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 24edddcc0fa3\n'}
18-05-21:08:02:57 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged remove-inactive-test-model:1\n'}
18-05-21:08:02:57 INFO     [clipper_admin.py:458] Pushing model Docker image to remove-inactive-test-model:1
18-05-21:08:02:57 INFO     [docker_container_manager.py:257] Found 0 replicas for remove-inactive-test-model:1. Adding 2
18-05-21:08:03:05 INFO     [clipper_admin.py:635] Successfully registered model remove-inactive-test-model:1
18-05-21:08:03:05 INFO     [clipper_admin.py:553] Done deploying model remove-inactive-test-model:1.
18-05-21:08:03:05 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:03:05 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:03:05 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:03:05 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:03:05 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:03:05 INFO     [clipper_admin.py:456] {u'stream': u' ---> 24edddcc0fa3\n'}
18-05-21:08:03:05 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 24edddcc0fa3\n'}
18-05-21:08:03:05 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged remove-inactive-test-model:2\n'}
18-05-21:08:03:05 INFO     [clipper_admin.py:458] Pushing model Docker image to remove-inactive-test-model:2
18-05-21:08:03:06 INFO     [docker_container_manager.py:257] Found 0 replicas for remove-inactive-test-model:2. Adding 3
18-05-21:08:03:15 INFO     [clipper_admin.py:635] Successfully registered model remove-inactive-test-model:2
18-05-21:08:03:15 INFO     [clipper_admin.py:553] Done deploying model remove-inactive-test-model:2.
18-05-21:08:03:37 INFO     [clipper_admin.py:1238] Stopped all containers for these models and versions:
{   u'remove-inactive-test-model': [u'1']}
ok
test_stop_models (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:03:37 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:04:43 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:04:43 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:04:43 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:04:48 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:04:49 INFO     [docker_container_manager.py:257] Found 0 replicas for jimmypage:i. Adding 1
18-05-21:08:04:56 INFO     [clipper_admin.py:635] Successfully registered model jimmypage:i
18-05-21:08:04:56 INFO     [clipper_admin.py:553] Done deploying model jimmypage:i.
18-05-21:08:04:56 INFO     [docker_container_manager.py:257] Found 0 replicas for jimmypage:ii. Adding 1
18-05-21:08:05:03 INFO     [clipper_admin.py:635] Successfully registered model jimmypage:ii
18-05-21:08:05:03 INFO     [clipper_admin.py:553] Done deploying model jimmypage:ii.
18-05-21:08:05:03 INFO     [docker_container_manager.py:257] Found 0 replicas for jimmypage:iii. Adding 1
18-05-21:08:05:09 INFO     [clipper_admin.py:635] Successfully registered model jimmypage:iii
18-05-21:08:05:09 INFO     [clipper_admin.py:553] Done deploying model jimmypage:iii.
18-05-21:08:05:09 INFO     [docker_container_manager.py:257] Found 0 replicas for jimmypage:iv. Adding 1
18-05-21:08:05:16 INFO     [clipper_admin.py:635] Successfully registered model jimmypage:iv
18-05-21:08:05:16 INFO     [clipper_admin.py:553] Done deploying model jimmypage:iv.
18-05-21:08:05:16 INFO     [docker_container_manager.py:257] Found 0 replicas for robertplant:i. Adding 1
18-05-21:08:05:23 INFO     [clipper_admin.py:635] Successfully registered model robertplant:i
18-05-21:08:05:23 INFO     [clipper_admin.py:553] Done deploying model robertplant:i.
18-05-21:08:05:23 INFO     [docker_container_manager.py:257] Found 0 replicas for robertplant:ii. Adding 1
18-05-21:08:05:30 INFO     [clipper_admin.py:635] Successfully registered model robertplant:ii
18-05-21:08:05:30 INFO     [clipper_admin.py:553] Done deploying model robertplant:ii.
18-05-21:08:05:30 INFO     [docker_container_manager.py:257] Found 0 replicas for robertplant:iii. Adding 1
18-05-21:08:05:37 INFO     [clipper_admin.py:635] Successfully registered model robertplant:iii
18-05-21:08:05:37 INFO     [clipper_admin.py:553] Done deploying model robertplant:iii.
18-05-21:08:05:37 INFO     [docker_container_manager.py:257] Found 0 replicas for robertplant:iv. Adding 1
18-05-21:08:05:43 INFO     [clipper_admin.py:635] Successfully registered model robertplant:iv
18-05-21:08:05:43 INFO     [clipper_admin.py:553] Done deploying model robertplant:iv.
18-05-21:08:05:43 INFO     [docker_container_manager.py:257] Found 0 replicas for jpj:i. Adding 1
18-05-21:08:05:50 INFO     [clipper_admin.py:635] Successfully registered model jpj:i
18-05-21:08:05:50 INFO     [clipper_admin.py:553] Done deploying model jpj:i.
18-05-21:08:05:50 INFO     [docker_container_manager.py:257] Found 0 replicas for jpj:ii. Adding 1
18-05-21:08:05:57 INFO     [clipper_admin.py:635] Successfully registered model jpj:ii
18-05-21:08:05:57 INFO     [clipper_admin.py:553] Done deploying model jpj:ii.
18-05-21:08:05:57 INFO     [docker_container_manager.py:257] Found 0 replicas for jpj:iii. Adding 1
18-05-21:08:06:03 INFO     [clipper_admin.py:635] Successfully registered model jpj:iii
18-05-21:08:06:03 INFO     [clipper_admin.py:553] Done deploying model jpj:iii.
18-05-21:08:06:04 INFO     [docker_container_manager.py:257] Found 0 replicas for jpj:iv. Adding 1
18-05-21:08:06:11 INFO     [clipper_admin.py:635] Successfully registered model jpj:iv
18-05-21:08:06:11 INFO     [clipper_admin.py:553] Done deploying model jpj:iv.
18-05-21:08:06:11 INFO     [docker_container_manager.py:257] Found 0 replicas for johnbohnam:i. Adding 1
18-05-21:08:06:17 INFO     [clipper_admin.py:635] Successfully registered model johnbohnam:i
18-05-21:08:06:17 INFO     [clipper_admin.py:553] Done deploying model johnbohnam:i.
18-05-21:08:06:17 INFO     [docker_container_manager.py:257] Found 0 replicas for johnbohnam:ii. Adding 1
18-05-21:08:06:24 INFO     [clipper_admin.py:635] Successfully registered model johnbohnam:ii
18-05-21:08:06:24 INFO     [clipper_admin.py:553] Done deploying model johnbohnam:ii.
18-05-21:08:06:24 INFO     [docker_container_manager.py:257] Found 0 replicas for johnbohnam:iii. Adding 1
18-05-21:08:06:31 INFO     [clipper_admin.py:635] Successfully registered model johnbohnam:iii
18-05-21:08:06:31 INFO     [clipper_admin.py:553] Done deploying model johnbohnam:iii.
18-05-21:08:06:31 INFO     [docker_container_manager.py:257] Found 0 replicas for johnbohnam:iv. Adding 1
18-05-21:08:06:38 INFO     [clipper_admin.py:635] Successfully registered model johnbohnam:iv
18-05-21:08:06:38 INFO     [clipper_admin.py:553] Done deploying model johnbohnam:iv.
18-05-21:08:08:05 INFO     [clipper_admin.py:1176] Stopped all containers for these models and versions:
{   u'jimmypage': [u'iv', u'ii', u'iii', u'i'],
    u'robertplant': [u'iii', u'i', u'ii', u'iv']}
18-05-21:08:08:59 INFO     [clipper_admin.py:1202] Stopped all containers for these models and versions:
{   'johnbohnam': ['i', 'iv', 'iii'], 'jpj': ['ii', 'iv']}
18-05-21:08:09:30 INFO     [clipper_admin.py:1248] Stopped all Clipper model containers
ok
test_python_closure_deploys_successfully (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:09:30 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:10:02 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:10:03 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:10:03 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:10:06 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:10:07 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmp2E4ycC
18-05-21:08:10:07 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:10:07 INFO     [python.py:192] Python closure saved
18-05-21:08:10:07 INFO     [python.py:198] Using Python 2 base image
18-05-21:08:10:07 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmp2E4ycC
18-05-21:08:10:08 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/python-closure-container:develop\n'}
18-05-21:08:10:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:08:10:08 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmp2E4ycC /model/\n'}
18-05-21:08:10:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> f23d74b32379\n'}
18-05-21:08:10:08 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built f23d74b32379\n'}
18-05-21:08:10:08 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged m2:1\n'}
18-05-21:08:10:08 INFO     [clipper_admin.py:458] Pushing model Docker image to m2:1
18-05-21:08:10:09 INFO     [docker_container_manager.py:257] Found 0 replicas for m2:1. Adding 1
18-05-21:08:10:16 INFO     [clipper_admin.py:635] Successfully registered model m2:1
18-05-21:08:10:16 INFO     [clipper_admin.py:553] Done deploying model m2:1.
ok
test_register_py_endpoint (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:10:16 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:10:58 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:10:58 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:10:58 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:11:02 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:11:03 INFO     [clipper_admin.py:201] Application py-closure-test was successfully registered
18-05-21:08:11:03 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpGo_AP6
18-05-21:08:11:03 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:11:03 INFO     [python.py:192] Python closure saved
18-05-21:08:11:03 INFO     [python.py:198] Using Python 2 base image
18-05-21:08:11:03 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpGo_AP6
18-05-21:08:11:04 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/python-closure-container:develop\n'}
18-05-21:08:11:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:08:11:04 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpGo_AP6 /model/\n'}
18-05-21:08:11:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> 2ad71c97e189\n'}
18-05-21:08:11:04 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 2ad71c97e189\n'}
18-05-21:08:11:04 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged py-closure-test:1\n'}
18-05-21:08:11:04 INFO     [clipper_admin.py:458] Pushing model Docker image to py-closure-test:1
18-05-21:08:11:05 INFO     [docker_container_manager.py:257] Found 0 replicas for py-closure-test:1. Adding 1
18-05-21:08:11:11 INFO     [clipper_admin.py:635] Successfully registered model py-closure-test:1
18-05-21:08:11:11 INFO     [clipper_admin.py:553] Done deploying model py-closure-test:1.
18-05-21:08:11:11 INFO     [clipper_admin.py:263] Model py-closure-test is now linked to application py-closure-test
ok
test_test_predict_function (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:11:11 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:11:55 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:11:55 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:11:55 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:11:59 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:12:00 INFO     [clipper_admin.py:201] Application hello-world was successfully registered
18-05-21:08:12:00 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmp9yDG_U
18-05-21:08:12:00 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:12:00 INFO     [python.py:192] Python closure saved
18-05-21:08:12:00 INFO     [python.py:198] Using Python 2 base image
18-05-21:08:12:00 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmp9yDG_U
18-05-21:08:12:01 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/python-closure-container:develop\n'}
18-05-21:08:12:01 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:08:12:01 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmp9yDG_U /model/\n'}
18-05-21:08:12:01 INFO     [clipper_admin.py:456] {u'stream': u' ---> b616de668d04\n'}
18-05-21:08:12:01 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built b616de668d04\n'}
18-05-21:08:12:01 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged sum-model:1\n'}
18-05-21:08:12:01 INFO     [clipper_admin.py:458] Pushing model Docker image to sum-model:1
18-05-21:08:12:02 INFO     [docker_container_manager.py:257] Found 0 replicas for sum-model:1. Adding 1
18-05-21:08:12:08 INFO     [clipper_admin.py:635] Successfully registered model sum-model:1
18-05-21:08:12:08 INFO     [clipper_admin.py:553] Done deploying model sum-model:1.
18-05-21:08:12:08 INFO     [clipper_admin.py:263] Model sum-model is now linked to application hello-world
18-05-21:08:13:08 INFO     [clipper_admin_tests.py:437] test pred output {u'default': False, u'output': 6.6, u'query_id': 0}
ok
test_build_model_with_custom_packages (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:13:08 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:13:51 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:13:51 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:13:51 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:13:55 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:13:56 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/3 : FROM clipper/python-closure-container:develop\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/3 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u' ---> f1b31c2b76e1\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Step 3/3 : RUN apt-get -y install build-essential && pip install sympy==1.1.*\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u' ---> Running in 65847674c740\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Reading package lists...'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Building dependency tree...'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'\nReading state information...'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'build-essential is already the newest version (12.3).\n0 upgraded, 0 newly installed, 0 to remove and 5 not upgraded.\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Collecting sympy==1.1.*\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'  Downloading https://files.pythonhosted.org/packages/91/26/4e477dbd1f9260eb743d9f221af3044648a8fb2fcf3f2f23daee4dc831a4/sympy-1.1.1.tar.gz (4.6MB)\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Collecting mpmath>=0.19 (from sympy==1.1.*)\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'  Downloading https://files.pythonhosted.org/packages/7a/05/b3d1472885d8dc0606936ea5da0ccb1b4785682e78ab15e34ada24aea8d5/mpmath-1.0.0.tar.gz (511kB)\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Building wheels for collected packages: sympy, mpmath\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'  Running setup.py bdist_wheel for sympy: started\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u"  Running setup.py bdist_wheel for sympy: finished with status 'done'\n"}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'  Stored in directory: /root/.cache/pip/wheels/6d/47/7c/40a7cd9b9bd5bad329fcd21d8e50629700fcc6e5520a66a2de\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'  Running setup.py bdist_wheel for mpmath: started\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u"  Running setup.py bdist_wheel for mpmath: finished with status 'done'\n"}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'  Stored in directory: /root/.cache/pip/wheels/33/15/0f/9ca5f2ad88a5456803098daa189f382408a81556aa209e97ff\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built sympy mpmath\nInstalling collected packages: mpmath, sympy\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Successfully installed mpmath-1.0.0 sympy-1.1.1\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u"\x1b[91mYou are using pip version 9.0.3, however version 10.0.1 is available.\nYou should consider upgrading via the 'pip install --upgrade pip' command.\n\x1b[0m"}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u' ---> 190aab224224\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 190aab224224\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged buildmodeltest:py2\n'}
18-05-21:08:14:10 INFO     [clipper_admin.py:458] Pushing model Docker image to buildmodeltest:py2
18-05-21:08:14:11 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/3 : FROM clipper/python35-closure-container:develop\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u' ---> faab0356144a\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/3 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u' ---> bbb3b33c41c4\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Step 3/3 : RUN apt-get -y install build-essential && pip install sympy==1.1.*\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u' ---> Running in 10e1f9965813\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Reading package lists...'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Building dependency tree...'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'\nReading state information...'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'build-essential is already the newest version.\n0 upgraded, 0 newly installed, 0 to remove and 3 not upgraded.\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Collecting sympy==1.1.*\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'  Downloading https://files.pythonhosted.org/packages/91/26/4e477dbd1f9260eb743d9f221af3044648a8fb2fcf3f2f23daee4dc831a4/sympy-1.1.1.tar.gz (4.6MB)\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Collecting mpmath>=0.19 (from sympy==1.1.*)\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'  Downloading https://files.pythonhosted.org/packages/7a/05/b3d1472885d8dc0606936ea5da0ccb1b4785682e78ab15e34ada24aea8d5/mpmath-1.0.0.tar.gz (511kB)\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Building wheels for collected packages: sympy, mpmath\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'  Running setup.py bdist_wheel for sympy: started\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u"  Running setup.py bdist_wheel for sympy: finished with status 'done'\n"}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'  Stored in directory: /root/.cache/pip/wheels/6d/47/7c/40a7cd9b9bd5bad329fcd21d8e50629700fcc6e5520a66a2de\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'  Running setup.py bdist_wheel for mpmath: started\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u"  Running setup.py bdist_wheel for mpmath: finished with status 'done'\n"}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'  Stored in directory: /root/.cache/pip/wheels/33/15/0f/9ca5f2ad88a5456803098daa189f382408a81556aa209e97ff\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built sympy mpmath\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Installing collected packages: mpmath, sympy\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Successfully installed mpmath-1.0.0 sympy-1.1.1\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u"\x1b[91mYou are using pip version 9.0.3, however version 10.0.1 is available.\nYou should consider upgrading via the 'pip install --upgrade pip' command.\n\x1b[0m"}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u' ---> bc147dba7dd0\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built bc147dba7dd0\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged buildmodeltest:py35\n'}
18-05-21:08:14:28 INFO     [clipper_admin.py:458] Pushing model Docker image to buildmodeltest:py35
18-05-21:08:14:29 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/3 : FROM clipper/python35-closure-container:develop\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u' ---> faab0356144a\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/3 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u' ---> bbb3b33c41c4\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u'Step 3/3 : RUN apt-get -y install build-essential && pip install sympy==1.1.*\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u' ---> bc147dba7dd0\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built bc147dba7dd0\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged buildmodeltest:py36\n'}
18-05-21:08:14:29 INFO     [clipper_admin.py:458] Pushing model Docker image to buildmodeltest:py36
ok
test_delete_application_correct (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:14:36 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:15:08 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:15:08 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:15:08 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:15:12 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:15:13 INFO     [clipper_admin.py:201] Application testapp was successfully registered
18-05-21:08:15:13 INFO     [clipper_admin.py:220] Application testapp was successfully deleted
ok
test_query_specific_model_version (__main__.ClipperManagerTestCaseShort) ... 18-05-21:08:15:13 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:15:45 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:15:45 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:15:45 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:15:48 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:15:49 INFO     [clipper_admin.py:201] Application testapp was successfully registered
18-05-21:08:15:49 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpsWGf_i
18-05-21:08:15:49 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:15:49 INFO     [python.py:192] Python closure saved
18-05-21:08:15:49 INFO     [python.py:198] Using Python 2 base image
18-05-21:08:15:49 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpsWGf_i
18-05-21:08:15:50 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/python-closure-container:develop\n'}
18-05-21:08:15:50 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:08:15:50 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpsWGf_i /model/\n'}
18-05-21:08:15:50 INFO     [clipper_admin.py:456] {u'stream': u' ---> 604eb5cf7684\n'}
18-05-21:08:15:50 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 604eb5cf7684\n'}
18-05-21:08:15:50 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged testmodel:v1\n'}
18-05-21:08:15:50 INFO     [clipper_admin.py:458] Pushing model Docker image to testmodel:v1
18-05-21:08:15:51 INFO     [docker_container_manager.py:257] Found 0 replicas for testmodel:v1. Adding 1
18-05-21:08:15:57 INFO     [clipper_admin.py:635] Successfully registered model testmodel:v1
18-05-21:08:15:57 INFO     [clipper_admin.py:553] Done deploying model testmodel:v1.
18-05-21:08:15:57 INFO     [clipper_admin.py:263] Model testmodel is now linked to application testapp
18-05-21:08:16:27 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmp4BA361
18-05-21:08:16:27 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:16:27 INFO     [python.py:192] Python closure saved
18-05-21:08:16:27 INFO     [python.py:198] Using Python 2 base image
18-05-21:08:16:27 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmp4BA361
18-05-21:08:16:28 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/python-closure-container:develop\n'}
18-05-21:08:16:28 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:08:16:28 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmp4BA361 /model/\n'}
18-05-21:08:16:28 INFO     [clipper_admin.py:456] {u'stream': u' ---> 63098aebb92a\n'}
18-05-21:08:16:28 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 63098aebb92a\n'}
18-05-21:08:16:28 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged testmodel:v2\n'}
18-05-21:08:16:28 INFO     [clipper_admin.py:458] Pushing model Docker image to testmodel:v2
18-05-21:08:16:29 INFO     [docker_container_manager.py:257] Found 0 replicas for testmodel:v2. Adding 1
18-05-21:08:16:35 INFO     [clipper_admin.py:635] Successfully registered model testmodel:v2
18-05-21:08:16:35 INFO     [clipper_admin.py:553] Done deploying model testmodel:v2.
ok
18-05-21:08:17:36 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:18:29 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:18:29 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:45196
18-05-21:08:18:29 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:18:29 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:18:29 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:18:29 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:18:32 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:18:33 INFO     [clipper_admin.py:201] Application app3 was successfully registered
18-05-21:08:18:33 INFO     [clipper_admin.py:201] Application app4 was successfully registered
18-05-21:08:18:33 INFO     [clipper_admin.py:201] Application app5 was successfully registered
18-05-21:08:18:33 INFO     [clipper_admin.py:201] Application app6 was successfully registered
18-05-21:08:18:33 INFO     [clipper_admin.py:201] Application app7 was successfully registered
test_remove_inactive_container (__main__.ClipperManagerTestCaseLong) ... 18-05-21:08:18:33 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:18:33 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:18:33 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:18:33 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:18:33 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:18:33 INFO     [clipper_admin.py:456] {u'stream': u' ---> 24edddcc0fa3\n'}
18-05-21:08:18:33 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 24edddcc0fa3\n'}
18-05-21:08:18:33 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged m8:1\n'}
18-05-21:08:18:33 INFO     [clipper_admin.py:458] Pushing model Docker image to m8:1
18-05-21:08:18:34 INFO     [docker_container_manager.py:257] Found 0 replicas for m8:1. Adding 2
18-05-21:08:18:41 INFO     [clipper_admin.py:635] Successfully registered model m8:1
18-05-21:08:18:41 INFO     [clipper_admin.py:553] Done deploying model m8:1.
18-05-21:08:18:41 INFO     [clipper_admin.py:263] Model m8 is now linked to application app7
18-05-21:08:19:12 INFO     [docker_container_manager.py:278] Found 2 replicas for m8:1. Removing 1
18-05-21:08:21:02 INFO     [docker_container_manager.py:278] Found 1 replicas for m8:1. Removing 1
ok
test_unlinked_app_returns_default_predictions (__main__.ClipperManagerTestCaseLong) ... 18-05-21:08:22:53 INFO     [clipper_admin_tests.py:598] {u'default': True, u'output': u'DEFAULT', u'query_id': 6, u'default_explanation': u'No connected models found for query'}
ok
test_deployed_model_queried_successfully (__main__.ClipperManagerTestCaseLong) ... 18-05-21:08:22:53 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:22:53 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:22:53 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:22:53 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:22:53 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:22:53 INFO     [clipper_admin.py:456] {u'stream': u' ---> 24edddcc0fa3\n'}
18-05-21:08:22:53 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 24edddcc0fa3\n'}
18-05-21:08:22:53 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged m5:1\n'}
18-05-21:08:22:53 INFO     [clipper_admin.py:458] Pushing model Docker image to m5:1
18-05-21:08:22:53 INFO     [docker_container_manager.py:257] Found 0 replicas for m5:1. Adding 1
18-05-21:08:23:00 INFO     [clipper_admin.py:635] Successfully registered model m5:1
18-05-21:08:23:00 INFO     [clipper_admin.py:553] Done deploying model m5:1.
18-05-21:08:23:00 INFO     [clipper_admin.py:263] Model m5 is now linked to application app4
18-05-21:08:23:30 INFO     [clipper_admin_tests.py:619] {u'default': False, u'output': 1.0, u'query_id': 7}
ok
test_batch_queries_returned_successfully (__main__.ClipperManagerTestCaseLong) ... 18-05-21:08:23:30 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpKrzrGw
18-05-21:08:23:30 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:23:30 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:23:30 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpKrzrGw /model/\n'}
18-05-21:08:23:30 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:23:30 INFO     [clipper_admin.py:456] {u'stream': u' ---> 24edddcc0fa3\n'}
18-05-21:08:23:30 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 24edddcc0fa3\n'}
18-05-21:08:23:30 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged m6:1\n'}
18-05-21:08:23:30 INFO     [clipper_admin.py:458] Pushing model Docker image to m6:1
18-05-21:08:23:31 INFO     [docker_container_manager.py:257] Found 0 replicas for m6:1. Adding 1
18-05-21:08:23:38 INFO     [clipper_admin.py:635] Successfully registered model m6:1
18-05-21:08:23:38 INFO     [clipper_admin.py:553] Done deploying model m6:1.
18-05-21:08:23:38 INFO     [clipper_admin.py:263] Model m6 is now linked to application app5
18-05-21:08:24:08 INFO     [clipper_admin_tests.py:641] {u'batch_predictions': [{u'default': False, u'output': 1.0, u'query_id': 8}, {u'default': False, u'output': 1.0, u'query_id': 9}, {u'default': False, u'output': 1.0, u'query_id': 10}, {u'default': False, u'output': 1.0, u'query_id': 11}]}
ok
test_deployed_python_closure_queried_successfully (__main__.ClipperManagerTestCaseLong) ... 18-05-21:08:24:08 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpjtF945
18-05-21:08:24:08 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:24:08 INFO     [python.py:192] Python closure saved
18-05-21:08:24:08 INFO     [python.py:198] Using Python 2 base image
18-05-21:08:24:08 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpjtF945
18-05-21:08:24:08 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/python-closure-container:develop\n'}
18-05-21:08:24:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:08:24:08 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpjtF945 /model/\n'}
18-05-21:08:24:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> 73f7002bb9a5\n'}
18-05-21:08:24:08 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 73f7002bb9a5\n'}
18-05-21:08:24:08 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged m4:1\n'}
18-05-21:08:24:08 INFO     [clipper_admin.py:458] Pushing model Docker image to m4:1
18-05-21:08:24:09 INFO     [docker_container_manager.py:257] Found 0 replicas for m4:1. Adding 1
18-05-21:08:24:16 INFO     [clipper_admin.py:635] Successfully registered model m4:1
18-05-21:08:24:16 INFO     [clipper_admin.py:553] Done deploying model m4:1.
18-05-21:08:24:16 INFO     [clipper_admin.py:263] Model m4 is now linked to application app3
ok
test_fixed_batch_size_model_processes_specified_query_batch_size_when_saturated (__main__.ClipperManagerTestCaseLong) ... 18-05-21:08:25:16 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpYl96y7
18-05-21:08:25:16 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:25:16 INFO     [python.py:192] Python closure saved
18-05-21:08:25:16 INFO     [python.py:198] Using Python 2 base image
18-05-21:08:25:16 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpYl96y7
18-05-21:08:25:16 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/python-closure-container:develop\n'}
18-05-21:08:25:16 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:08:25:16 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpYl96y7 /model/\n'}
18-05-21:08:25:16 INFO     [clipper_admin.py:456] {u'stream': u' ---> 8e1082ab233f\n'}
18-05-21:08:25:16 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 8e1082ab233f\n'}
18-05-21:08:25:16 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged m7:1\n'}
18-05-21:08:25:16 INFO     [clipper_admin.py:458] Pushing model Docker image to m7:1
18-05-21:08:25:17 INFO     [docker_container_manager.py:257] Found 0 replicas for m7:1. Adding 1
18-05-21:08:25:24 INFO     [clipper_admin.py:635] Successfully registered model m7:1
18-05-21:08:25:24 INFO     [clipper_admin.py:553] Done deploying model m7:1.
18-05-21:08:25:24 INFO     [clipper_admin.py:263] Model m7 is now linked to application app6
ok
18-05-21:08:26:49 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:26:49 INFO     [test_utils.py:60] Socket error: [Errno 98] Address already in use
18-05-21:08:26:49 INFO     [test_utils.py:62] randomly generated port 35976 is bound. Trying again.
18-05-21:08:28:03 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:28:03 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:36472

----------------------------------------------------------------------
Ran 27 tests in 2074.433s

OK
{u'default': False, u'output': 3, u'query_id': 12}
18-05-21:08:28:04 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:28:04 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:28:04 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:28:04 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:28:07 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:28:18 INFO     [many_apps_many_models.py:114] Running integration test with 2 apps and 3 models
18-05-21:08:28:18 INFO     [clipper_admin.py:201] Application testapp0-app was successfully registered
18-05-21:08:28:19 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpbpcp9t
18-05-21:08:28:20 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:28:20 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:28:20 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpbpcp9t /model/\n'}
18-05-21:08:28:20 INFO     [clipper_admin.py:456] {u'stream': u' ---> 181476f34217\n'}
18-05-21:08:28:20 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 181476f34217\n'}
18-05-21:08:28:20 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged testapp0-model:0\n'}
18-05-21:08:28:20 INFO     [clipper_admin.py:458] Pushing model Docker image to testapp0-model:0
18-05-21:08:28:20 INFO     [docker_container_manager.py:257] Found 0 replicas for testapp0-model:0. Adding 1
18-05-21:08:28:27 INFO     [clipper_admin.py:635] Successfully registered model testapp0-model:0
18-05-21:08:28:27 INFO     [clipper_admin.py:553] Done deploying model testapp0-model:0.
18-05-21:08:28:37 INFO     [clipper_admin.py:263] Model testapp0-model is now linked to application testapp0-app
18-05-21:08:29:08 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpbpcp9t
18-05-21:08:29:08 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:29:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:29:08 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpbpcp9t /model/\n'}
18-05-21:08:29:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:29:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> 181476f34217\n'}
18-05-21:08:29:08 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 181476f34217\n'}
18-05-21:08:29:08 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged testapp0-model:1\n'}
18-05-21:08:29:08 INFO     [clipper_admin.py:458] Pushing model Docker image to testapp0-model:1
18-05-21:08:29:09 INFO     [docker_container_manager.py:257] Found 0 replicas for testapp0-model:1. Adding 1
18-05-21:08:29:16 INFO     [clipper_admin.py:635] Successfully registered model testapp0-model:1
18-05-21:08:29:16 INFO     [clipper_admin.py:553] Done deploying model testapp0-model:1.
18-05-21:08:29:57 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpbpcp9t
18-05-21:08:29:57 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:29:57 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:29:57 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpbpcp9t /model/\n'}
18-05-21:08:29:57 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:29:57 INFO     [clipper_admin.py:456] {u'stream': u' ---> 181476f34217\n'}
18-05-21:08:29:57 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 181476f34217\n'}
18-05-21:08:29:57 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged testapp0-model:2\n'}
18-05-21:08:29:57 INFO     [clipper_admin.py:458] Pushing model Docker image to testapp0-model:2
18-05-21:08:29:58 INFO     [docker_container_manager.py:257] Found 0 replicas for testapp0-model:2. Adding 1
18-05-21:08:30:05 INFO     [clipper_admin.py:635] Successfully registered model testapp0-model:2
18-05-21:08:30:05 INFO     [clipper_admin.py:553] Done deploying model testapp0-model:2.
18-05-21:08:30:46 INFO     [clipper_admin.py:201] Application testapp1-app was successfully registered
18-05-21:08:30:47 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpbpcp9t
18-05-21:08:30:47 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:30:47 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:30:47 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpbpcp9t /model/\n'}
18-05-21:08:30:47 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:30:47 INFO     [clipper_admin.py:456] {u'stream': u' ---> 181476f34217\n'}
18-05-21:08:30:47 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 181476f34217\n'}
18-05-21:08:30:47 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged testapp1-model:0\n'}
18-05-21:08:30:47 INFO     [clipper_admin.py:458] Pushing model Docker image to testapp1-model:0
18-05-21:08:30:48 INFO     [docker_container_manager.py:257] Found 0 replicas for testapp1-model:0. Adding 1
18-05-21:08:30:55 INFO     [clipper_admin.py:635] Successfully registered model testapp1-model:0
18-05-21:08:30:55 INFO     [clipper_admin.py:553] Done deploying model testapp1-model:0.
18-05-21:08:31:05 INFO     [clipper_admin.py:263] Model testapp1-model is now linked to application testapp1-app
18-05-21:08:31:36 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpbpcp9t
18-05-21:08:31:36 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:31:36 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:31:36 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpbpcp9t /model/\n'}
18-05-21:08:31:36 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:31:36 INFO     [clipper_admin.py:456] {u'stream': u' ---> 181476f34217\n'}
18-05-21:08:31:36 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 181476f34217\n'}
18-05-21:08:31:36 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged testapp1-model:1\n'}
18-05-21:08:31:36 INFO     [clipper_admin.py:458] Pushing model Docker image to testapp1-model:1
18-05-21:08:31:37 INFO     [docker_container_manager.py:257] Found 0 replicas for testapp1-model:1. Adding 1
18-05-21:08:31:43 INFO     [clipper_admin.py:635] Successfully registered model testapp1-model:1
18-05-21:08:31:43 INFO     [clipper_admin.py:553] Done deploying model testapp1-model:1.
18-05-21:08:32:25 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpbpcp9t
18-05-21:08:32:25 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:32:25 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:32:25 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpbpcp9t /model/\n'}
18-05-21:08:32:25 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:32:25 INFO     [clipper_admin.py:456] {u'stream': u' ---> 181476f34217\n'}
18-05-21:08:32:25 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 181476f34217\n'}
18-05-21:08:32:25 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged testapp1-model:2\n'}
18-05-21:08:32:25 INFO     [clipper_admin.py:458] Pushing model Docker image to testapp1-model:2
18-05-21:08:32:26 INFO     [docker_container_manager.py:257] Found 0 replicas for testapp1-model:2. Adding 1
18-05-21:08:32:32 INFO     [clipper_admin.py:635] Successfully registered model testapp1-model:2
18-05-21:08:32:32 INFO     [clipper_admin.py:553] Done deploying model testapp1-model:2.
18-05-21:08:33:14 INFO     [many_apps_many_models.py:121] ['/tmp/clipper/tmp2lW53O/image_sha256:181476f342:container_1ce3040ded.log', '/tmp/clipper/tmp2lW53O/image_sha256:181476f342:container_f911410493.log', '/tmp/clipper/tmp2lW53O/image_sha256:181476f342:container_ff1a4971db.log', '/tmp/clipper/tmp2lW53O/image_sha256:181476f342:container_9938d1302d.log', '/tmp/clipper/tmp2lW53O/image_sha256:181476f342:container_72a1a534a8.log', '/tmp/clipper/tmp2lW53O/image_sha256:181476f342:container_c0229fda1a.log', '/tmp/clipper/tmp2lW53O/image_sha256:c8ecf7c719:container_92b4fcf06f.log', '/tmp/clipper/tmp2lW53O/image_sha256:8add14e27e:container_b2d83faece.log', '/tmp/clipper/tmp2lW53O/image_sha256:f396902395:container_65885ceed4.log', '/tmp/clipper/tmp2lW53O/image_sha256:51c28ed0de:container_950fcc436a.log', '/tmp/clipper/tmp2lW53O/image_sha256:98bd7cfc43:container_d4c57a56ee.log']
18-05-21:08:33:14 INFO     [test_utils.py:141] 
APPLICATIONS:
[   {   u'default_output': u'default_pred',
        u'input_type': u'doubles',
        u'latency_slo_micros': 100000,
        u'linked_models': [u'testapp1-model'],
        u'name': u'testapp1-app'},
    {   u'default_output': u'default_pred',
        u'input_type': u'doubles',
        u'latency_slo_micros': 100000,
        u'linked_models': [u'testapp0-model'],
        u'name': u'testapp0-app'}]
18-05-21:08:33:14 INFO     [test_utils.py:143] 
MODELS:
[   {   u'container_name': u'testapp1-model:2',
        u'input_type': u'doubles',
        u'is_current_version': True,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp1-model',
        u'model_version': u'2'},
    {   u'container_name': u'testapp0-model:0',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp0-model',
        u'model_version': u'0'},
    {   u'container_name': u'testapp0-model:1',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp0-model',
        u'model_version': u'1'},
    {   u'container_name': u'testapp1-model:0',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp1-model',
        u'model_version': u'0'},
    {   u'container_name': u'testapp1-model:1',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp1-model',
        u'model_version': u'1'},
    {   u'container_name': u'testapp0-model:2',
        u'input_type': u'doubles',
        u'is_current_version': True,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp0-model',
        u'model_version': u'2'}]
18-05-21:08:33:14 INFO     [test_utils.py:145] 
CONTAINERS:
[   {   u'input_type': u'doubles',
        u'model_id': u'testapp1-model:2',
        u'model_name': u'testapp1-model',
        u'model_replica_id': 0,
        u'model_version': u'2'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp1-model:0',
        u'model_name': u'testapp1-model',
        u'model_replica_id': 0,
        u'model_version': u'0'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp1-model:1',
        u'model_name': u'testapp1-model',
        u'model_replica_id': 0,
        u'model_version': u'1'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp0-model:2',
        u'model_name': u'testapp0-model',
        u'model_replica_id': 0,
        u'model_version': u'2'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp0-model:0',
        u'model_name': u'testapp0-model',
        u'model_replica_id': 0,
        u'model_version': u'0'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp0-model:1',
        u'model_name': u'testapp0-model',
        u'model_replica_id': 0,
        u'model_version': u'1'}]
18-05-21:08:33:14 INFO     [many_apps_many_models.py:125] SUCCESS
18-05-21:08:33:14 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:34:49 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:34:49 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:41211
2018-05-21 08:34:51 WARN  Utils:66 - Your hostname, amp-jenkins-staging-worker-01 resolves to a loopback address: 127.0.1.1; using 192.168.10.31 instead (on interface eno1)
2018-05-21 08:34:51 WARN  Utils:66 - Set SPARK_LOCAL_IP if you need to bind to another address
2018-05-21 08:34:52 WARN  NativeCodeLoader:62 - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
Setting default log level to "WARN".
To adjust logging level use sc.setLogLevel(newLevel). For SparkR, use setLogLevel(newLevel).
18-05-21:08:34:54 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:34:54 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:34:54 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:34:54 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:34:58 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:35:00 INFO     [clipper_admin.py:201] Application pyspark-test was successfully registered

[Stage 0:>                                                          (0 + 1) / 1]
                                                                                
2018-05-21 08:35:03 WARN  BLAS:61 - Failed to load implementation from: com.github.fommil.netlib.NativeSystemBLAS
2018-05-21 08:35:03 WARN  BLAS:61 - Failed to load implementation from: com.github.fommil.netlib.NativeRefBLAS
18-05-21:08:35:04 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpsM2Zkr
18-05-21:08:35:04 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:35:08 INFO     [pyspark.py:233] Spark model saved
18-05-21:08:35:08 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpsM2Zkr
18-05-21:08:35:08 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pyspark-container:develop\n'}
18-05-21:08:35:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> f3bb6a6e313d\n'}
18-05-21:08:35:08 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpsM2Zkr /model/\n'}
18-05-21:08:35:08 INFO     [clipper_admin.py:456] {u'stream': u' ---> b97a43009846\n'}
18-05-21:08:35:08 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built b97a43009846\n'}
18-05-21:08:35:08 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged pyspark-model:1\n'}
18-05-21:08:35:08 INFO     [clipper_admin.py:458] Pushing model Docker image to pyspark-model:1
18-05-21:08:35:09 INFO     [docker_container_manager.py:257] Found 0 replicas for pyspark-model:1. Adding 1
18-05-21:08:35:25 INFO     [clipper_admin.py:635] Successfully registered model pyspark-model:1
18-05-21:08:35:25 INFO     [clipper_admin.py:553] Done deploying model pyspark-model:1.
18-05-21:08:35:30 INFO     [clipper_admin.py:263] Model pyspark-model is now linked to application pyspark-test
18-05-21:08:36:03 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpre_5ns
18-05-21:08:36:03 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:36:03 INFO     [pyspark.py:233] Spark model saved
18-05-21:08:36:03 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpre_5ns
18-05-21:08:36:04 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pyspark-container:develop\n'}
18-05-21:08:36:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> f3bb6a6e313d\n'}
18-05-21:08:36:04 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpre_5ns /model/\n'}
18-05-21:08:36:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> c83b8d8bc20a\n'}
18-05-21:08:36:04 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built c83b8d8bc20a\n'}
18-05-21:08:36:04 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged pyspark-model:2\n'}
18-05-21:08:36:04 INFO     [clipper_admin.py:458] Pushing model Docker image to pyspark-model:2
18-05-21:08:36:05 INFO     [docker_container_manager.py:257] Found 0 replicas for pyspark-model:2. Adding 1
18-05-21:08:36:20 INFO     [clipper_admin.py:635] Successfully registered model pyspark-model:2
18-05-21:08:36:20 INFO     [clipper_admin.py:553] Done deploying model pyspark-model:2.
18-05-21:08:36:52 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmptvofMb
18-05-21:08:36:52 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:36:53 INFO     [pyspark.py:233] Spark model saved
18-05-21:08:36:53 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmptvofMb
18-05-21:08:36:53 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pyspark-container:develop\n'}
18-05-21:08:36:53 INFO     [clipper_admin.py:456] {u'stream': u' ---> f3bb6a6e313d\n'}
18-05-21:08:36:53 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmptvofMb /model/\n'}
18-05-21:08:36:53 INFO     [clipper_admin.py:456] {u'stream': u' ---> 8badb5aa5e02\n'}
18-05-21:08:36:53 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 8badb5aa5e02\n'}
18-05-21:08:36:53 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged pyspark-model:3\n'}
18-05-21:08:36:53 INFO     [clipper_admin.py:458] Pushing model Docker image to pyspark-model:3
18-05-21:08:36:54 INFO     [docker_container_manager.py:257] Found 0 replicas for pyspark-model:3. Adding 1
18-05-21:08:37:07 INFO     [clipper_admin.py:635] Successfully registered model pyspark-model:3
18-05-21:08:37:07 INFO     [clipper_admin.py:553] Done deploying model pyspark-model:3.
18-05-21:08:37:37 INFO     [clipper_admin.py:201] Application easy-register-app-model was successfully registered
18-05-21:08:37:37 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpFdHl9G
18-05-21:08:37:37 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:37:37 INFO     [pyspark.py:233] Spark model saved
18-05-21:08:37:37 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpFdHl9G
18-05-21:08:37:38 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pyspark-container:develop\n'}
18-05-21:08:37:38 INFO     [clipper_admin.py:456] {u'stream': u' ---> f3bb6a6e313d\n'}
18-05-21:08:37:38 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpFdHl9G /model/\n'}
18-05-21:08:37:38 INFO     [clipper_admin.py:456] {u'stream': u' ---> 233356f3f516\n'}
18-05-21:08:37:38 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 233356f3f516\n'}
18-05-21:08:37:38 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged easy-register-app-model:1\n'}
18-05-21:08:37:38 INFO     [clipper_admin.py:458] Pushing model Docker image to easy-register-app-model:1
18-05-21:08:37:39 INFO     [docker_container_manager.py:257] Found 0 replicas for easy-register-app-model:1. Adding 1
18-05-21:08:37:51 INFO     [clipper_admin.py:635] Successfully registered model easy-register-app-model:1
18-05-21:08:37:51 INFO     [clipper_admin.py:553] Done deploying model easy-register-app-model:1.
18-05-21:08:37:51 INFO     [clipper_admin.py:263] Model easy-register-app-model is now linked to application easy-register-app-model
18-05-21:08:38:16 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmp9M9Gq2
18-05-21:08:38:16 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:38:17 INFO     [pyspark.py:233] Spark model saved
18-05-21:08:38:17 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmp9M9Gq2
18-05-21:08:38:17 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pyspark-container:develop\n'}
18-05-21:08:38:17 INFO     [clipper_admin.py:456] {u'stream': u' ---> f3bb6a6e313d\n'}
18-05-21:08:38:17 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmp9M9Gq2 /model/\n'}
18-05-21:08:38:17 INFO     [clipper_admin.py:456] {u'stream': u' ---> 66c1c63c655c\n'}
18-05-21:08:38:17 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 66c1c63c655c\n'}
18-05-21:08:38:17 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged pyspark-model:4\n'}
18-05-21:08:38:17 INFO     [clipper_admin.py:458] Pushing model Docker image to pyspark-model:4
18-05-21:08:38:18 INFO     [docker_container_manager.py:257] Found 0 replicas for pyspark-model:4. Adding 1
18-05-21:08:38:31 INFO     [clipper_admin.py:635] Successfully registered model pyspark-model:4
18-05-21:08:38:31 INFO     [clipper_admin.py:553] Done deploying model pyspark-model:4.
18-05-21:08:39:01 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:40:26 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:40:26 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:36231
2018-05-21 08:40:28 WARN  Utils:66 - Your hostname, amp-jenkins-staging-worker-01 resolves to a loopback address: 127.0.1.1; using 192.168.10.31 instead (on interface eno1)
2018-05-21 08:40:28 WARN  Utils:66 - Set SPARK_LOCAL_IP if you need to bind to another address
2018-05-21 08:40:28 WARN  NativeCodeLoader:62 - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
Setting default log level to "WARN".
To adjust logging level use sc.setLogLevel(newLevel). For SparkR, use setLogLevel(newLevel).

[Stage 0:>                                                        (0 + 48) / 48]
                                                                                
2018-05-21 08:40:36 WARN  BLAS:61 - Failed to load implementation from: com.github.fommil.netlib.NativeSystemBLAS
2018-05-21 08:40:36 WARN  BLAS:61 - Failed to load implementation from: com.github.fommil.netlib.NativeRefBLAS
18-05-21:08:40:39 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:40:39 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:40:39 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:40:39 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:40:43 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:40:44 INFO     [clipper_admin.py:201] Application pyspark-pipeline-test was successfully registered
18-05-21:08:40:45 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpHwEILR
18-05-21:08:40:45 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:40:46 INFO     [pyspark.py:233] Spark model saved
18-05-21:08:40:46 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpHwEILR
18-05-21:08:40:47 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pyspark-container:develop\n'}
18-05-21:08:40:47 INFO     [clipper_admin.py:456] {u'stream': u' ---> f3bb6a6e313d\n'}
18-05-21:08:40:47 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpHwEILR /model/\n'}
18-05-21:08:40:47 INFO     [clipper_admin.py:456] {u'stream': u' ---> 6f4d7741f480\n'}
18-05-21:08:40:47 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 6f4d7741f480\n'}
18-05-21:08:40:47 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged pyspark-pipeline:1\n'}
18-05-21:08:40:47 INFO     [clipper_admin.py:458] Pushing model Docker image to pyspark-pipeline:1
18-05-21:08:40:48 INFO     [docker_container_manager.py:257] Found 0 replicas for pyspark-pipeline:1. Adding 1
18-05-21:08:41:03 INFO     [clipper_admin.py:635] Successfully registered model pyspark-pipeline:1
18-05-21:08:41:03 INFO     [clipper_admin.py:553] Done deploying model pyspark-pipeline:1.
18-05-21:08:41:03 INFO     [clipper_admin.py:263] Model pyspark-pipeline is now linked to application pyspark-pipeline-test
18-05-21:08:41:39 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpex5ro2
18-05-21:08:41:39 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:41:40 INFO     [pyspark.py:233] Spark model saved
18-05-21:08:41:40 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpex5ro2
18-05-21:08:41:40 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pyspark-container:develop\n'}
18-05-21:08:41:40 INFO     [clipper_admin.py:456] {u'stream': u' ---> f3bb6a6e313d\n'}
18-05-21:08:41:40 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpex5ro2 /model/\n'}
18-05-21:08:41:40 INFO     [clipper_admin.py:456] {u'stream': u' ---> 435ecea1ab52\n'}
18-05-21:08:41:40 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 435ecea1ab52\n'}
18-05-21:08:41:40 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged pyspark-pipeline:2\n'}
18-05-21:08:41:40 INFO     [clipper_admin.py:458] Pushing model Docker image to pyspark-pipeline:2
18-05-21:08:41:41 INFO     [docker_container_manager.py:257] Found 0 replicas for pyspark-pipeline:2. Adding 1
18-05-21:08:41:54 INFO     [clipper_admin.py:635] Successfully registered model pyspark-pipeline:2
18-05-21:08:41:54 INFO     [clipper_admin.py:553] Done deploying model pyspark-pipeline:2.
18-05-21:08:42:30 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:43:23 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:43:23 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:45683
18-05-21:08:43:23 INFO     [deploy_pyspark_pipeline_models.py:176] ALL TESTS PASSED
(4, spark i j k) --> prob=[0.1596407738787475,0.8403592261212525], prediction=1.000000
(5, l m n) --> prob=[0.8378325685476744,0.16216743145232562], prediction=0.000000
(6, spark hadoop spark) --> prob=[0.06926633132976037,0.9307336686702395], prediction=1.000000
(7, apache hadoop) --> prob=[0.9821575333444218,0.01784246665557808], prediction=0.000000
['{"prob": "[0.1596407738787475,0.8403592261212525]", "prediction": 1.0}']
2018-05-21 08:43:25 WARN  Utils:66 - Your hostname, amp-jenkins-staging-worker-01 resolves to a loopback address: 127.0.1.1; using 192.168.10.31 instead (on interface eno1)
2018-05-21 08:43:25 WARN  Utils:66 - Set SPARK_LOCAL_IP if you need to bind to another address
2018-05-21 08:43:26 WARN  NativeCodeLoader:62 - Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
Setting default log level to "WARN".
To adjust logging level use sc.setLogLevel(newLevel). For SparkR, use setLogLevel(newLevel).
18-05-21:08:43:28 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:43:28 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:43:28 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:43:28 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:43:32 INFO     [clipper_admin.py:126] Clipper is running

[Stage 0:>                                                          (0 + 1) / 1]
                                                                                
18-05-21:08:43:36 INFO     [clipper_admin.py:201] Application pyspark-sparkml-test was successfully registered
2018-05-21 08:43:40 WARN  BLAS:61 - Failed to load implementation from: com.github.fommil.netlib.NativeSystemBLAS
2018-05-21 08:43:40 WARN  BLAS:61 - Failed to load implementation from: com.github.fommil.netlib.NativeRefBLAS
18-05-21:08:43:41 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpdZzx4N
18-05-21:08:43:41 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:43:43 INFO     [pyspark.py:233] Spark model saved
18-05-21:08:43:43 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpdZzx4N
18-05-21:08:43:43 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pyspark-container:develop\n'}
18-05-21:08:43:43 INFO     [clipper_admin.py:456] {u'stream': u' ---> f3bb6a6e313d\n'}
18-05-21:08:43:43 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpdZzx4N /model/\n'}
18-05-21:08:43:43 INFO     [clipper_admin.py:456] {u'stream': u' ---> 2d360879ce4b\n'}
18-05-21:08:43:43 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 2d360879ce4b\n'}
18-05-21:08:43:43 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged pyspark-sparkml-model:1\n'}
18-05-21:08:43:43 INFO     [clipper_admin.py:458] Pushing model Docker image to pyspark-sparkml-model:1
18-05-21:08:43:44 INFO     [docker_container_manager.py:257] Found 0 replicas for pyspark-sparkml-model:1. Adding 1
18-05-21:08:44:00 INFO     [clipper_admin.py:635] Successfully registered model pyspark-sparkml-model:1
18-05-21:08:44:00 INFO     [clipper_admin.py:553] Done deploying model pyspark-sparkml-model:1.
18-05-21:08:44:05 INFO     [clipper_admin.py:263] Model pyspark-sparkml-model is now linked to application pyspark-sparkml-test
18-05-21:08:44:49 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:45:32 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:45:32 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:43197
{u'default': True, u'output': u'default_pred', u'query_id': 1, u'default_explanation': u'Failed to retrieve a prediction response within the specified latency SLO'}
{u'default': True, u'output': u'default_pred', u'query_id': 2, u'default_explanation': u'Failed to retrieve a prediction response within the specified latency SLO'}
{u'default': False, u'output': 1.0, u'query_id': 3}
{u'default': False, u'output': 1.0, u'query_id': 4}
{u'default': False, u'output': 1.0, u'query_id': 5}
{u'default': False, u'output': 1.0, u'query_id': 6}
{u'default': False, u'output': 1.0, u'query_id': 7}
{u'default': False, u'output': 1.0, u'query_id': 8}
{u'default': False, u'output': 1.0, u'query_id': 9}
{u'default': False, u'output': 1.0, u'query_id': 10}
{u'default': False, u'output': 1.0, u'query_id': 11}
{u'default': False, u'output': 1.0, u'query_id': 12}
{u'default': False, u'output': 1.0, u'query_id': 13}
{u'default': False, u'output': 1.0, u'query_id': 14}
{u'default': False, u'output': 1.0, u'query_id': 15}
{u'default': False, u'output': 1.0, u'query_id': 16}
{u'default': False, u'output': 1.0, u'query_id': 17}
{u'default': False, u'output': 1.0, u'query_id': 18}
{u'default': False, u'output': 1.0, u'query_id': 19}
{u'default': False, u'output': 1.0, u'query_id': 20}
{u'default': False, u'output': 1.0, u'query_id': 21}
{u'default': False, u'output': 1.0, u'query_id': 22}
{u'default': False, u'output': 1.0, u'query_id': 23}
{u'default': False, u'output': 1.0, u'query_id': 24}
{u'default': False, u'output': 1.0, u'query_id': 25}
Error: 2/25 predictions were default
18-05-21:08:45:33 INFO     [test_utils.py:106] Creating KubernetesContainerManager
18-05-21:08:45:33 INFO     [kubernetes_container_manager.py:410] Stopping all running Clipper resources
18-05-21:08:45:33 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:45:53 INFO     [test_utils.py:116] Done cleaning up clipper
18-05-21:08:45:53 INFO     [test_utils.py:118] Starting Clipper
18-05-21:08:46:04 INFO     [kubernetes_container_manager.py:208] Found 3 nodes: ec2-18-144-21-32.us-west-1.compute.amazonaws.com, ec2-13-56-252-99.us-west-1.compute.amazonaws.com, ec2-18-144-38-86.us-west-1.compute.amazonaws.com
18-05-21:08:46:04 INFO     [kubernetes_container_manager.py:217] Setting Clipper mgmt port to 32156
18-05-21:08:46:04 INFO     [kubernetes_container_manager.py:225] Setting Clipper query port to 31674
18-05-21:08:46:04 INFO     [kubernetes_container_manager.py:235] Setting Clipper metric port to 31641
18-05-21:08:46:04 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:46:05 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:46:06 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:46:07 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:46:08 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:46:09 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:46:10 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:46:11 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:46:12 INFO     [kubernetes_container_manager.py:208] Found 3 nodes: ec2-18-144-21-32.us-west-1.compute.amazonaws.com, ec2-13-56-252-99.us-west-1.compute.amazonaws.com, ec2-18-144-38-86.us-west-1.compute.amazonaws.com
18-05-21:08:46:12 INFO     [kubernetes_container_manager.py:217] Setting Clipper mgmt port to 32156
18-05-21:08:46:12 INFO     [kubernetes_container_manager.py:225] Setting Clipper query port to 31674
18-05-21:08:46:12 INFO     [kubernetes_container_manager.py:235] Setting Clipper metric port to 31641
18-05-21:08:46:12 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at ec2-18-144-21-32.us-west-1.compute.amazonaws.com:31674
18-05-21:08:46:22 INFO     [kubernetes_integration_test.py:110] Running integration test with 3 apps and 3 models
18-05-21:08:46:22 INFO     [clipper_admin.py:201] Application testapp0-app was successfully registered
18-05-21:08:46:23 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:46:24 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:46:24 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:46:24 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:46:24 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:46:24 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:46:24 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:0\n'}
18-05-21:08:46:24 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:0
18-05-21:08:46:35 INFO     [clipper_admin.py:635] Successfully registered model testapp0-model:0
18-05-21:08:46:35 INFO     [clipper_admin.py:553] Done deploying model testapp0-model:0.
18-05-21:08:46:45 INFO     [clipper_admin.py:263] Model testapp0-model is now linked to application testapp0-app
18-05-21:08:47:16 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:47:16 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:47:16 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:47:16 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:47:16 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:47:16 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:47:16 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:47:16 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:1\n'}
18-05-21:08:47:16 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:1
18-05-21:08:47:23 INFO     [clipper_admin.py:635] Successfully registered model testapp0-model:1
18-05-21:08:47:23 INFO     [clipper_admin.py:553] Done deploying model testapp0-model:1.
18-05-21:08:48:04 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:48:04 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:48:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:48:04 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:48:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:48:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:48:04 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:48:04 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:2\n'}
18-05-21:08:48:04 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:2
18-05-21:08:48:14 INFO     [clipper_admin.py:635] Successfully registered model testapp0-model:2
18-05-21:08:48:14 INFO     [clipper_admin.py:553] Done deploying model testapp0-model:2.
18-05-21:08:48:55 INFO     [clipper_admin.py:201] Application testapp1-app was successfully registered
18-05-21:08:48:56 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:48:56 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:48:56 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:48:56 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:48:56 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:48:56 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:48:56 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:48:56 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:0\n'}
18-05-21:08:48:56 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:0
18-05-21:08:49:05 INFO     [clipper_admin.py:635] Successfully registered model testapp1-model:0
18-05-21:08:49:05 INFO     [clipper_admin.py:553] Done deploying model testapp1-model:0.
18-05-21:08:49:15 INFO     [clipper_admin.py:263] Model testapp1-model is now linked to application testapp1-app
18-05-21:08:49:46 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:49:46 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:49:46 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:49:46 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:49:46 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:49:46 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:49:46 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:49:46 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:1\n'}
18-05-21:08:49:46 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:1
18-05-21:08:49:56 INFO     [clipper_admin.py:635] Successfully registered model testapp1-model:1
18-05-21:08:49:56 INFO     [clipper_admin.py:553] Done deploying model testapp1-model:1.
18-05-21:08:50:37 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:50:37 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:50:37 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:50:37 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:50:37 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:50:37 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:50:37 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:50:37 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:2\n'}
18-05-21:08:50:37 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:2
18-05-21:08:50:44 INFO     [clipper_admin.py:635] Successfully registered model testapp1-model:2
18-05-21:08:50:44 INFO     [clipper_admin.py:553] Done deploying model testapp1-model:2.
18-05-21:08:51:25 INFO     [clipper_admin.py:201] Application testapp2-app was successfully registered
18-05-21:08:51:26 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:51:26 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:51:26 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:51:26 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:51:26 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:51:26 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:51:26 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:51:26 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:0\n'}
18-05-21:08:51:26 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:0
18-05-21:08:51:34 INFO     [clipper_admin.py:635] Successfully registered model testapp2-model:0
18-05-21:08:51:34 INFO     [clipper_admin.py:553] Done deploying model testapp2-model:0.
18-05-21:08:51:44 INFO     [clipper_admin.py:263] Model testapp2-model is now linked to application testapp2-app
18-05-21:08:52:16 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:52:16 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:52:16 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:52:16 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:52:16 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:52:16 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:52:16 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:52:16 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:1\n'}
18-05-21:08:52:16 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:1
18-05-21:08:52:22 INFO     [clipper_admin.py:635] Successfully registered model testapp2-model:1
18-05-21:08:52:22 INFO     [clipper_admin.py:553] Done deploying model testapp2-model:1.
18-05-21:08:53:04 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:53:04 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:53:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:53:04 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:53:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:53:04 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:53:04 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:53:04 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:2\n'}
18-05-21:08:53:04 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:2
18-05-21:08:53:13 INFO     [clipper_admin.py:635] Successfully registered model testapp2-model:2
18-05-21:08:53:13 INFO     [clipper_admin.py:553] Done deploying model testapp2-model:2.
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: metrics-7fcdf94575-642p8_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: metrics.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: mgmt-frontend-54cb6656f5-cjp4t_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: mgmt-frontend.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: query-frontend-0-5bc6cb976f-mjxwx_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: frontend-exporter.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: query-frontend-0-5bc6cb976f-mjxwx_1.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: query-frontend.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: redis-fd8df4f7d-nr5wr_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: redis.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp0-model-0-deployment-at-0-5847564b6-xx4bf_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp0-model-0-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp0-model-1-deployment-at-0-84545d85fd-vdjbg_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp0-model-1-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp0-model-2-deployment-at-0-77859499f4-hw8tp_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp0-model-2-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp1-model-0-deployment-at-0-7c46749b48-fjcdw_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp1-model-0-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp1-model-1-deployment-at-0-55cc5c5c64-qv6j6_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp1-model-1-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp1-model-2-deployment-at-0-576d45f9b4-tbfck_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp1-model-2-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp2-model-0-deployment-at-0-67b685cf54-2wlrb_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp2-model-0-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp2-model-1-deployment-at-0-bf5587b78-vpd6j_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp2-model-1-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:371] log file name: testapp2-model-2-deployment-at-0-f6b46f5c8-hbrrv_0.log
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp2-model-2-deployment-at-0.log
18-05-21:08:53:55 INFO     [kubernetes_integration_test.py:117] ['/tmp/clipper/tmp406phg/metrics-7fcdf94575-642p8_0.log', '/tmp/clipper/tmp406phg/mgmt-frontend-54cb6656f5-cjp4t_0.log', '/tmp/clipper/tmp406phg/query-frontend-0-5bc6cb976f-mjxwx_0.log', '/tmp/clipper/tmp406phg/query-frontend-0-5bc6cb976f-mjxwx_1.log', '/tmp/clipper/tmp406phg/redis-fd8df4f7d-nr5wr_0.log', '/tmp/clipper/tmp406phg/testapp0-model-0-deployment-at-0-5847564b6-xx4bf_0.log', '/tmp/clipper/tmp406phg/testapp0-model-1-deployment-at-0-84545d85fd-vdjbg_0.log', '/tmp/clipper/tmp406phg/testapp0-model-2-deployment-at-0-77859499f4-hw8tp_0.log', '/tmp/clipper/tmp406phg/testapp1-model-0-deployment-at-0-7c46749b48-fjcdw_0.log', '/tmp/clipper/tmp406phg/testapp1-model-1-deployment-at-0-55cc5c5c64-qv6j6_0.log', '/tmp/clipper/tmp406phg/testapp1-model-2-deployment-at-0-576d45f9b4-tbfck_0.log', '/tmp/clipper/tmp406phg/testapp2-model-0-deployment-at-0-67b685cf54-2wlrb_0.log', '/tmp/clipper/tmp406phg/testapp2-model-1-deployment-at-0-bf5587b78-vpd6j_0.log', '/tmp/clipper/tmp406phg/testapp2-model-2-deployment-at-0-f6b46f5c8-hbrrv_0.log']
18-05-21:08:53:55 INFO     [test_utils.py:141] 
APPLICATIONS:
[   {   u'default_output': u'default_pred',
        u'input_type': u'doubles',
        u'latency_slo_micros': 100000,
        u'linked_models': [u'testapp2-model'],
        u'name': u'testapp2-app'},
    {   u'default_output': u'default_pred',
        u'input_type': u'doubles',
        u'latency_slo_micros': 100000,
        u'linked_models': [u'testapp1-model'],
        u'name': u'testapp1-app'},
    {   u'default_output': u'default_pred',
        u'input_type': u'doubles',
        u'latency_slo_micros': 100000,
        u'linked_models': [u'testapp0-model'],
        u'name': u'testapp0-app'}]
18-05-21:08:53:55 INFO     [test_utils.py:143] 
MODELS:
[   {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:2',
        u'input_type': u'doubles',
        u'is_current_version': True,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp0-model',
        u'model_version': u'2'},
    {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:0',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp1-model',
        u'model_version': u'0'},
    {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:1',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp0-model',
        u'model_version': u'1'},
    {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:2',
        u'input_type': u'doubles',
        u'is_current_version': True,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp1-model',
        u'model_version': u'2'},
    {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:0',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp2-model',
        u'model_version': u'0'},
    {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:1',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp2-model',
        u'model_version': u'1'},
    {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:0',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp0-model',
        u'model_version': u'0'},
    {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp2-model:2',
        u'input_type': u'doubles',
        u'is_current_version': True,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp2-model',
        u'model_version': u'2'},
    {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp1-model:1',
        u'input_type': u'doubles',
        u'is_current_version': False,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp1-model',
        u'model_version': u'1'}]
18-05-21:08:53:55 INFO     [test_utils.py:145] 
CONTAINERS:
[   {   u'input_type': u'doubles',
        u'model_id': u'testapp1-model:0',
        u'model_name': u'testapp1-model',
        u'model_replica_id': 0,
        u'model_version': u'0'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp2-model:2',
        u'model_name': u'testapp2-model',
        u'model_replica_id': 0,
        u'model_version': u'2'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp0-model:1',
        u'model_name': u'testapp0-model',
        u'model_replica_id': 0,
        u'model_version': u'1'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp2-model:1',
        u'model_name': u'testapp2-model',
        u'model_replica_id': 0,
        u'model_version': u'1'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp2-model:0',
        u'model_name': u'testapp2-model',
        u'model_replica_id': 0,
        u'model_version': u'0'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp1-model:2',
        u'model_name': u'testapp1-model',
        u'model_replica_id': 0,
        u'model_version': u'2'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp0-model:0',
        u'model_name': u'testapp0-model',
        u'model_replica_id': 0,
        u'model_version': u'0'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp0-model:2',
        u'model_name': u'testapp0-model',
        u'model_replica_id': 0,
        u'model_version': u'2'},
    {   u'input_type': u'doubles',
        u'model_id': u'testapp1-model:1',
        u'model_name': u'testapp1-model',
        u'model_replica_id': 0,
        u'model_version': u'1'}]
18-05-21:08:53:55 INFO     [kubernetes_integration_test.py:121] SUCCESS
18-05-21:08:53:55 INFO     [kubernetes_container_manager.py:410] Stopping all running Clipper resources
18-05-21:08:53:58 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:53:58 INFO     [test_utils.py:106] Creating KubernetesContainerManager
18-05-21:08:53:58 INFO     [kubernetes_container_manager.py:410] Stopping all running Clipper resources
18-05-21:08:53:58 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:54:18 INFO     [test_utils.py:116] Done cleaning up clipper
18-05-21:08:54:18 INFO     [test_utils.py:118] Starting Clipper
18-05-21:08:54:29 INFO     [kubernetes_container_manager.py:208] Found 3 nodes: ec2-18-144-21-32.us-west-1.compute.amazonaws.com, ec2-13-56-252-99.us-west-1.compute.amazonaws.com, ec2-18-144-38-86.us-west-1.compute.amazonaws.com
18-05-21:08:54:29 INFO     [kubernetes_container_manager.py:217] Setting Clipper mgmt port to 31956
18-05-21:08:54:29 INFO     [kubernetes_container_manager.py:225] Setting Clipper query port to 31061
18-05-21:08:54:29 INFO     [kubernetes_container_manager.py:235] Setting Clipper metric port to 32445
18-05-21:08:54:29 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:54:30 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:54:31 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:54:32 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:54:33 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:54:34 INFO     [kubernetes_container_manager.py:208] Found 3 nodes: ec2-18-144-21-32.us-west-1.compute.amazonaws.com, ec2-13-56-252-99.us-west-1.compute.amazonaws.com, ec2-18-144-38-86.us-west-1.compute.amazonaws.com
18-05-21:08:54:34 INFO     [kubernetes_container_manager.py:217] Setting Clipper mgmt port to 31956
18-05-21:08:54:34 INFO     [kubernetes_container_manager.py:225] Setting Clipper query port to 31061
18-05-21:08:54:34 INFO     [kubernetes_container_manager.py:235] Setting Clipper metric port to 32445
18-05-21:08:54:34 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at 127.0.0.1:8080/api/v1/namespaces/default/services/query-frontend:1337/proxy
18-05-21:08:54:45 INFO     [kubernetes_integration_test.py:110] Running integration test with 1 apps and 1 models
18-05-21:08:54:45 INFO     [clipper_admin.py:201] Application testapp0-app was successfully registered
18-05-21:08:54:46 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpRzzxxV
18-05-21:08:54:46 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:54:46 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:54:46 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpRzzxxV /model/\n'}
18-05-21:08:54:46 INFO     [clipper_admin.py:456] {u'stream': u' ---> Using cache\n'}
18-05-21:08:54:46 INFO     [clipper_admin.py:456] {u'stream': u' ---> aaa800874c86\n'}
18-05-21:08:54:46 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built aaa800874c86\n'}
18-05-21:08:54:46 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:0\n'}
18-05-21:08:54:46 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:0
18-05-21:08:54:55 INFO     [clipper_admin.py:635] Successfully registered model testapp0-model:0
18-05-21:08:54:55 INFO     [clipper_admin.py:553] Done deploying model testapp0-model:0.
18-05-21:08:55:05 INFO     [clipper_admin.py:263] Model testapp0-model is now linked to application testapp0-app
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:371] log file name: metrics-7fcdf94575-c66tn_0.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:372] log alt file name: metrics.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:371] log file name: mgmt-frontend-54cb6656f5-nsv8m_0.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:372] log alt file name: mgmt-frontend.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:371] log file name: query-frontend-0-5bc6cb976f-x79lh_0.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:372] log alt file name: frontend-exporter.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:371] log file name: query-frontend-0-5bc6cb976f-x79lh_1.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:372] log alt file name: query-frontend.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:371] log file name: redis-fd8df4f7d-jlwpd_0.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:372] log alt file name: redis.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:371] log file name: testapp0-model-0-deployment-at-0-5847564b6-f5h5h_0.log
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp0-model-0-deployment-at-0.log
18-05-21:08:55:37 INFO     [kubernetes_integration_test.py:117] ['/tmp/clipper/tmp10vZfK/metrics-7fcdf94575-c66tn_0.log', '/tmp/clipper/tmp10vZfK/mgmt-frontend-54cb6656f5-nsv8m_0.log', '/tmp/clipper/tmp10vZfK/query-frontend-0-5bc6cb976f-x79lh_0.log', '/tmp/clipper/tmp10vZfK/query-frontend-0-5bc6cb976f-x79lh_1.log', '/tmp/clipper/tmp10vZfK/redis-fd8df4f7d-jlwpd_0.log', '/tmp/clipper/tmp10vZfK/testapp0-model-0-deployment-at-0-5847564b6-f5h5h_0.log']
18-05-21:08:55:37 INFO     [test_utils.py:141] 
APPLICATIONS:
[   {   u'default_output': u'default_pred',
        u'input_type': u'doubles',
        u'latency_slo_micros': 100000,
        u'linked_models': [u'testapp0-model'],
        u'name': u'testapp0-app'}]
18-05-21:08:55:37 INFO     [test_utils.py:143] 
MODELS:
[   {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:0',
        u'input_type': u'doubles',
        u'is_current_version': True,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp0-model',
        u'model_version': u'0'}]
18-05-21:08:55:37 INFO     [test_utils.py:145] 
CONTAINERS:
[   {   u'input_type': u'doubles',
        u'model_id': u'testapp0-model:0',
        u'model_name': u'testapp0-model',
        u'model_replica_id': 0,
        u'model_version': u'0'}]
18-05-21:08:55:37 INFO     [kubernetes_integration_test.py:121] SUCCESS
18-05-21:08:55:37 INFO     [kubernetes_container_manager.py:410] Stopping all running Clipper resources
18-05-21:08:55:38 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
ec2-18-144-21-32.us-west-1.compute.amazonaws.com:31674
{u'histograms': [{u'internal:rpc_request_queueing_delay': {u'p99': u'0', u'min': u'0', u'max': u'0', u'p95': u'0', u'std_dev': u'0', u'size': u'0', u'p50': u'0', u'unit': u'microseconds', u'mean': u'0'}}], u'meters': [{u'internal:aggregate_model_throughput': {u'rate': u'0', u'rate_1min': u'0', u'rate_15min': u'0', u'unit': u'events per second', u'rate_5min': u'0'}}], u'ratio_counters': [{u'internal:prediction_cache_hit_ratio': {u'ratio': u'nan'}}], u'counters': [{u'internal:prediction_cache_lookups': {u'count': u'0'}}, {u'internal:aggregate_num_predictions': {u'count': u'0'}}]}
127.0.0.1:8080/api/v1/namespaces/default/services/query-frontend:1337/proxy
{u'histograms': [{u'internal:rpc_request_queueing_delay': {u'p99': u'0', u'min': u'0', u'max': u'0', u'p95': u'0', u'std_dev': u'0', u'size': u'0', u'p50': u'0', u'unit': u'microseconds', u'mean': u'0'}}], u'meters': [{u'internal:aggregate_model_throughput': {u'rate': u'0', u'rate_1min': u'0', u'rate_15min': u'0', u'unit': u'events per second', u'rate_5min': u'0'}}], u'ratio_counters': [{u'internal:prediction_cache_hit_ratio': {u'ratio': u'nan'}}], u'counters': [{u'internal:prediction_cache_lookups': {u'count': u'0'}}, {u'internal:aggregate_num_predictions': {u'count': u'0'}}]}
18-05-21:08:55:39 INFO     [test_utils.py:106] Creating KubernetesContainerManager
18-05-21:08:55:39 INFO     [kubernetes_container_manager.py:410] Stopping all running Clipper resources
18-05-21:08:55:39 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:55:59 INFO     [test_utils.py:116] Done cleaning up clipper
18-05-21:08:55:59 INFO     [test_utils.py:118] Starting Clipper
18-05-21:08:56:10 INFO     [kubernetes_container_manager.py:208] Found 3 nodes: ec2-18-144-21-32.us-west-1.compute.amazonaws.com, ec2-13-56-252-99.us-west-1.compute.amazonaws.com, ec2-18-144-38-86.us-west-1.compute.amazonaws.com
18-05-21:08:56:10 INFO     [kubernetes_container_manager.py:217] Setting Clipper mgmt port to 31800
18-05-21:08:56:11 INFO     [kubernetes_container_manager.py:225] Setting Clipper query port to 31616
18-05-21:08:56:11 INFO     [kubernetes_container_manager.py:235] Setting Clipper metric port to 30268
18-05-21:08:56:11 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:56:12 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:08:56:13 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:56:14 INFO     [kubernetes_container_manager.py:208] Found 3 nodes: ec2-18-144-21-32.us-west-1.compute.amazonaws.com, ec2-13-56-252-99.us-west-1.compute.amazonaws.com, ec2-18-144-38-86.us-west-1.compute.amazonaws.com
18-05-21:08:56:14 INFO     [kubernetes_container_manager.py:217] Setting Clipper mgmt port to 31800
18-05-21:08:56:14 INFO     [kubernetes_container_manager.py:225] Setting Clipper query port to 31616
18-05-21:08:56:14 INFO     [kubernetes_container_manager.py:235] Setting Clipper metric port to 30268
18-05-21:08:56:14 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at ec2-18-144-21-32.us-west-1.compute.amazonaws.com:31616
18-05-21:08:56:24 INFO     [clipper_admin.py:201] Application testapp0-app was successfully registered
18-05-21:08:56:25 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmp6Ru0RG
18-05-21:08:56:25 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:08:56:25 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:08:56:25 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmp6Ru0RG /model/\n'}
18-05-21:08:56:25 INFO     [clipper_admin.py:456] {u'stream': u' ---> bbda088c3b7e\n'}
18-05-21:08:56:25 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built bbda088c3b7e\n'}
18-05-21:08:56:25 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:1526892985\n'}
18-05-21:08:56:25 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:1526892985
18-05-21:08:56:45 INFO     [clipper_admin.py:635] Successfully registered model testapp0-model:1526892985
18-05-21:08:56:45 INFO     [clipper_admin.py:553] Done deploying model testapp0-model:1526892985.
18-05-21:08:56:55 INFO     [clipper_admin.py:263] Model testapp0-model is now linked to application testapp0-app
18-05-21:08:57:25 ERROR    [kubernetes_multi_frontend.py:70] Error: 2/25 predictions were default
18-05-21:08:57:25 INFO     [kubernetes_multi_frontend.py:111] Begin Kubernetes Multiple Frontend Test
18-05-21:08:57:25 INFO     [kubernetes_multi_frontend.py:134] Ok: we have 2 query frontend depolyments
18-05-21:08:57:26 INFO     [kubernetes_multi_frontend.py:144] Ok: we have 2 query-frontend rpc services
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: metrics-7fcdf94575-hdb9q_0.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: metrics.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: mgmt-frontend-54cb6656f5-kb4mr_0.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: mgmt-frontend.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: query-frontend-0-5bc6cb976f-l2jjt_0.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: frontend-exporter.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: query-frontend-0-5bc6cb976f-l2jjt_1.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: query-frontend.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: query-frontend-1-5d66644fd8-5ctt2_0.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: frontend-exporter.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: query-frontend-1-5d66644fd8-5ctt2_1.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: query-frontend.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: redis-fd8df4f7d-z46kj_0.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: redis.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: testapp0-model-1526892985-deployment-at-0-6b9dd6cc74-pzkds_0.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp0-model-1526892985-deployment-at-0.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:371] log file name: testapp0-model-1526892985-deployment-at-1-7cf99f4bb8-4l68b_0.log
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:372] log alt file name: testapp0-model-1526892985-deployment-at-1.log
18-05-21:08:57:26 INFO     [kubernetes_multi_frontend.py:149] ['/tmp/clipper/tmpmlpfwR/metrics-7fcdf94575-hdb9q_0.log', '/tmp/clipper/tmpmlpfwR/mgmt-frontend-54cb6656f5-kb4mr_0.log', '/tmp/clipper/tmpmlpfwR/query-frontend-0-5bc6cb976f-l2jjt_0.log', '/tmp/clipper/tmpmlpfwR/query-frontend-0-5bc6cb976f-l2jjt_1.log', '/tmp/clipper/tmpmlpfwR/query-frontend-1-5d66644fd8-5ctt2_0.log', '/tmp/clipper/tmpmlpfwR/query-frontend-1-5d66644fd8-5ctt2_1.log', '/tmp/clipper/tmpmlpfwR/redis-fd8df4f7d-z46kj_0.log', '/tmp/clipper/tmpmlpfwR/testapp0-model-1526892985-deployment-at-0-6b9dd6cc74-pzkds_0.log', '/tmp/clipper/tmpmlpfwR/testapp0-model-1526892985-deployment-at-1-7cf99f4bb8-4l68b_0.log']
18-05-21:08:57:26 INFO     [test_utils.py:141] 
APPLICATIONS:
[   {   u'default_output': u'default_pred',
        u'input_type': u'doubles',
        u'latency_slo_micros': 100000,
        u'linked_models': [u'testapp0-model'],
        u'name': u'testapp0-app'}]
18-05-21:08:57:26 INFO     [test_utils.py:143] 
MODELS:
[   {   u'container_name': u'568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/testapp0-model:1526892985',
        u'input_type': u'doubles',
        u'is_current_version': True,
        u'labels': [u''],
        u'model_data_path': u'DEPRECATED',
        u'model_name': u'testapp0-model',
        u'model_version': u'1526892985'}]
18-05-21:08:57:26 INFO     [test_utils.py:145] 
CONTAINERS:
[   {   u'input_type': u'doubles',
        u'model_id': u'testapp0-model:1526892985',
        u'model_name': u'testapp0-model',
        u'model_replica_id': 0,
        u'model_version': u'1526892985'}]
18-05-21:08:57:26 INFO     [kubernetes_multi_frontend.py:154] SUCCESS
18-05-21:08:57:26 INFO     [kubernetes_container_manager.py:410] Stopping all running Clipper resources
18-05-21:08:57:28 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
ec2-18-144-21-32.us-west-1.compute.amazonaws.com:31616
{u'default': True, u'output': u'default_pred', u'query_id': 1, u'default_explanation': u'Failed to retrieve a prediction response within the specified latency SLO'}
{u'default': True, u'output': u'default_pred', u'query_id': 0, u'default_explanation': u'Failed to retrieve a prediction response within the specified latency SLO'}
{u'default': False, u'output': 1.0, u'query_id': 2}
{u'default': False, u'output': 1.0, u'query_id': 1}
{u'default': False, u'output': 1.0, u'query_id': 3}
{u'default': False, u'output': 1.0, u'query_id': 4}
{u'default': False, u'output': 1.0, u'query_id': 2}
{u'default': False, u'output': 1.0, u'query_id': 3}
{u'default': False, u'output': 1.0, u'query_id': 5}
{u'default': False, u'output': 1.0, u'query_id': 4}
{u'default': False, u'output': 1.0, u'query_id': 5}
{u'default': False, u'output': 1.0, u'query_id': 6}
{u'default': False, u'output': 1.0, u'query_id': 7}
{u'default': False, u'output': 1.0, u'query_id': 6}
{u'default': False, u'output': 1.0, u'query_id': 7}
{u'default': False, u'output': 1.0, u'query_id': 8}
{u'default': False, u'output': 1.0, u'query_id': 8}
{u'default': False, u'output': 1.0, u'query_id': 9}
{u'default': False, u'output': 1.0, u'query_id': 9}
{u'default': False, u'output': 1.0, u'query_id': 10}
{u'default': False, u'output': 1.0, u'query_id': 11}
{u'default': False, u'output': 1.0, u'query_id': 10}
{u'default': False, u'output': 1.0, u'query_id': 11}
{u'default': False, u'output': 1.0, u'query_id': 12}
{u'default': False, u'output': 1.0, u'query_id': 12}
18-05-21:08:57:29 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:08:57:29 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:08:57:29 INFO     [test_utils.py:82] Starting Clipper
18-05-21:08:57:29 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:08:57:33 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:08:57:34 INFO     [clipper_admin.py:201] Application tensorflow-test was successfully registered
2018-05-21 08:57:35.789077: I tensorflow/core/platform/cpu_feature_guard.cc:140] Your CPU supports instructions that this TensorFlow binary was not compiled to use: AVX2 FMA
WARNING:tensorflow:From ../integration-tests/deploy_tensorflow_models.py:129: softmax_cross_entropy_with_logits (from tensorflow.python.ops.nn_ops) is deprecated and will be removed in a future version.
Instructions for updating:

Future major versions of TensorFlow will allow gradients to flow
into the labels input on backprop by default.

See tf.nn.softmax_cross_entropy_with_logits_v2.

18-05-21:08:57:36 WARNING  [tf_logging.py:126] From ../integration-tests/deploy_tensorflow_models.py:129: softmax_cross_entropy_with_logits (from tensorflow.python.ops.nn_ops) is deprecated and will be removed in a future version.
Instructions for updating:

Future major versions of TensorFlow will allow gradients to flow
into the labels input on backprop by default.

See tf.nn.softmax_cross_entropy_with_logits_v2.

18-05-21:08:57:44 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmp9GRiCK
18-05-21:08:57:44 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:57:44 INFO     [tensorflow.py:191] TensorFlow model saved at: /tmp/clipper/tmp9GRiCK/tfmodel/model.ckpt 
18-05-21:08:57:44 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmp9GRiCK
18-05-21:08:57:44 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/tf-container:develop\n'}
18-05-21:08:57:44 INFO     [clipper_admin.py:456] {u'stream': u' ---> 5c8e353faa23\n'}
18-05-21:08:57:44 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmp9GRiCK /model/\n'}
18-05-21:08:57:44 INFO     [clipper_admin.py:456] {u'stream': u' ---> 7ce9f9405170\n'}
18-05-21:08:57:44 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 7ce9f9405170\n'}
18-05-21:08:57:44 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged tensorflow-model:1\n'}
18-05-21:08:57:44 INFO     [clipper_admin.py:458] Pushing model Docker image to tensorflow-model:1
18-05-21:08:57:45 INFO     [docker_container_manager.py:257] Found 0 replicas for tensorflow-model:1. Adding 1
18-05-21:08:57:52 INFO     [clipper_admin.py:635] Successfully registered model tensorflow-model:1
18-05-21:08:57:52 INFO     [clipper_admin.py:553] Done deploying model tensorflow-model:1.
18-05-21:08:57:57 INFO     [clipper_admin.py:263] Model tensorflow-model is now linked to application tensorflow-test
18-05-21:08:58:27 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpoLDiIQ
18-05-21:08:58:27 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:58:27 INFO     [tensorflow.py:259] TensorFlow model copied to: tfmodel 
18-05-21:08:58:27 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpoLDiIQ
18-05-21:08:58:28 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/tf-container:develop\n'}
18-05-21:08:58:28 INFO     [clipper_admin.py:456] {u'stream': u' ---> 5c8e353faa23\n'}
18-05-21:08:58:28 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpoLDiIQ /model/\n'}
18-05-21:08:58:28 INFO     [clipper_admin.py:456] {u'stream': u' ---> 7bfdea2f337a\n'}
18-05-21:08:58:28 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 7bfdea2f337a\n'}
18-05-21:08:58:28 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged tensorflow-model:2\n'}
18-05-21:08:58:28 INFO     [clipper_admin.py:458] Pushing model Docker image to tensorflow-model:2
18-05-21:08:58:28 INFO     [docker_container_manager.py:257] Found 0 replicas for tensorflow-model:2. Adding 1
18-05-21:08:58:35 INFO     [clipper_admin.py:635] Successfully registered model tensorflow-model:2
18-05-21:08:58:35 INFO     [clipper_admin.py:553] Done deploying model tensorflow-model:2.
INFO:tensorflow:No assets to save.
18-05-21:08:59:05 INFO     [tf_logging.py:116] No assets to save.
INFO:tensorflow:No assets to write.
18-05-21:08:59:05 INFO     [tf_logging.py:116] No assets to write.
INFO:tensorflow:SavedModel written to: data/export_dir/saved_model.pb
18-05-21:08:59:05 INFO     [tf_logging.py:116] SavedModel written to: data/export_dir/saved_model.pb
18-05-21:08:59:05 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpbOI73k
18-05-21:08:59:05 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:59:05 INFO     [tensorflow.py:259] TensorFlow model copied to: tfmodel 
18-05-21:08:59:05 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpbOI73k
18-05-21:08:59:06 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/tf-container:develop\n'}
18-05-21:08:59:06 INFO     [clipper_admin.py:456] {u'stream': u' ---> 5c8e353faa23\n'}
18-05-21:08:59:06 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpbOI73k /model/\n'}
18-05-21:08:59:06 INFO     [clipper_admin.py:456] {u'stream': u' ---> 87c9952b06ed\n'}
18-05-21:08:59:06 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 87c9952b06ed\n'}
18-05-21:08:59:06 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged tensorflow-model:3\n'}
18-05-21:08:59:06 INFO     [clipper_admin.py:458] Pushing model Docker image to tensorflow-model:3
18-05-21:08:59:07 INFO     [docker_container_manager.py:257] Found 0 replicas for tensorflow-model:3. Adding 1
18-05-21:08:59:13 INFO     [clipper_admin.py:635] Successfully registered model tensorflow-model:3
18-05-21:08:59:13 INFO     [clipper_admin.py:553] Done deploying model tensorflow-model:3.
18-05-21:08:59:44 INFO     [clipper_admin.py:201] Application easy-register-app-model was successfully registered
18-05-21:08:59:44 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmp_9sCo9
18-05-21:08:59:44 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:08:59:44 INFO     [tensorflow.py:259] TensorFlow model copied to: tfmodel 
18-05-21:08:59:44 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmp_9sCo9
18-05-21:08:59:44 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/tf-container:develop\n'}
18-05-21:08:59:44 INFO     [clipper_admin.py:456] {u'stream': u' ---> 5c8e353faa23\n'}
18-05-21:08:59:44 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmp_9sCo9 /model/\n'}
18-05-21:08:59:44 INFO     [clipper_admin.py:456] {u'stream': u' ---> ddf3d9a620e9\n'}
18-05-21:08:59:44 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built ddf3d9a620e9\n'}
18-05-21:08:59:44 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged easy-register-app-model:1\n'}
18-05-21:08:59:44 INFO     [clipper_admin.py:458] Pushing model Docker image to easy-register-app-model:1
18-05-21:08:59:45 INFO     [docker_container_manager.py:257] Found 0 replicas for easy-register-app-model:1. Adding 1
18-05-21:08:59:52 INFO     [clipper_admin.py:635] Successfully registered model easy-register-app-model:1
18-05-21:08:59:52 INFO     [clipper_admin.py:553] Done deploying model easy-register-app-model:1.
18-05-21:08:59:52 INFO     [clipper_admin.py:263] Model easy-register-app-model is now linked to application easy-register-app-model
18-05-21:09:00:17 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:09:01:31 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:01:31 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:35027
Cost , Accuracy
[6659.0625, 0.63461536]
Cost , Accuracy
[0.0, 1.0]
Cost , Accuracy
[0.0, 1.0]
Cost , Accuracy
[0.0, 1.0]
Cost , Accuracy
[0.0, 1.0]
localhost:36495
localhost:36495
localhost:36495
localhost:36495
18-05-21:09:01:32 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:09:01:32 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:01:32 INFO     [test_utils.py:82] Starting Clipper
18-05-21:09:01:32 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:09:01:36 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:09:01:37 INFO     [clipper_admin.py:201] Application mxnet-test was successfully registered
18-05-21:09:01:38 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpLjmclz
18-05-21:09:01:38 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:09:01:38 INFO     [module.py:180] Saved checkpoint to "/tmp/clipper/tmpLjmclz/mxnet_model-0000.params"
18-05-21:09:01:38 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpLjmclz
18-05-21:09:01:38 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/mxnet-container:develop\n'}
18-05-21:09:01:38 INFO     [clipper_admin.py:456] {u'stream': u' ---> a7eccc8ee0ba\n'}
18-05-21:09:01:38 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpLjmclz /model/\n'}
18-05-21:09:01:38 INFO     [clipper_admin.py:456] {u'stream': u' ---> 2bb0d73e1e9f\n'}
18-05-21:09:01:38 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 2bb0d73e1e9f\n'}
18-05-21:09:01:38 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged mxnet-model:1\n'}
18-05-21:09:01:38 INFO     [clipper_admin.py:458] Pushing model Docker image to mxnet-model:1
18-05-21:09:01:39 INFO     [docker_container_manager.py:257] Found 0 replicas for mxnet-model:1. Adding 1
18-05-21:09:01:46 INFO     [clipper_admin.py:635] Successfully registered model mxnet-model:1
18-05-21:09:01:46 INFO     [clipper_admin.py:553] Done deploying model mxnet-model:1.
18-05-21:09:01:46 INFO     [mxnet.py:255] MXNet model saved
18-05-21:09:01:51 INFO     [clipper_admin.py:263] Model mxnet-model is now linked to application mxnet-test
18-05-21:09:02:21 INFO     [clipper_admin.py:201] Application easy-register-app-model was successfully registered
18-05-21:09:02:21 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpo8oVAQ
18-05-21:09:02:21 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:09:02:21 INFO     [module.py:180] Saved checkpoint to "/tmp/clipper/tmpo8oVAQ/mxnet_model-0000.params"
18-05-21:09:02:21 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpo8oVAQ
18-05-21:09:02:22 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/mxnet-container:develop\n'}
18-05-21:09:02:22 INFO     [clipper_admin.py:456] {u'stream': u' ---> a7eccc8ee0ba\n'}
18-05-21:09:02:22 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpo8oVAQ /model/\n'}
18-05-21:09:02:22 INFO     [clipper_admin.py:456] {u'stream': u' ---> d25d357ebb2c\n'}
18-05-21:09:02:22 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built d25d357ebb2c\n'}
18-05-21:09:02:22 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged easy-register-app-model:1\n'}
18-05-21:09:02:22 INFO     [clipper_admin.py:458] Pushing model Docker image to easy-register-app-model:1
18-05-21:09:02:22 INFO     [docker_container_manager.py:257] Found 0 replicas for easy-register-app-model:1. Adding 1
18-05-21:09:02:29 INFO     [clipper_admin.py:635] Successfully registered model easy-register-app-model:1
18-05-21:09:02:29 INFO     [clipper_admin.py:553] Done deploying model easy-register-app-model:1.
18-05-21:09:02:29 INFO     [mxnet.py:255] MXNet model saved
18-05-21:09:02:29 INFO     [clipper_admin.py:263] Model easy-register-app-model is now linked to application easy-register-app-model
18-05-21:09:02:54 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:09:03:47 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:03:47 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:46282
18-05-21:09:03:48 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:09:03:48 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:03:48 INFO     [test_utils.py:82] Starting Clipper
18-05-21:09:03:48 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:09:03:52 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:09:03:53 INFO     [clipper_admin.py:201] Application pytorch-test was successfully registered
../integration-tests/deploy_pytorch_models.py:124: UserWarning: Implicit dimension choice for softmax has been deprecated. Change the call to include dim=X as an argument.
  return F.softmax(output)
18-05-21:09:03:55 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpDZazWl
18-05-21:09:03:55 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:09:03:55 INFO     [pytorch.py:206] Torch model saved
18-05-21:09:03:55 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpDZazWl
18-05-21:09:03:55 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pytorch-container:develop\n'}
18-05-21:09:03:55 INFO     [clipper_admin.py:456] {u'stream': u' ---> 521aed7dfb45\n'}
18-05-21:09:03:55 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpDZazWl /model/\n'}
18-05-21:09:03:55 INFO     [clipper_admin.py:456] {u'stream': u' ---> 9c40ef2feff9\n'}
18-05-21:09:03:55 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 9c40ef2feff9\n'}
18-05-21:09:03:55 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged pytorch-model:1\n'}
18-05-21:09:03:55 INFO     [clipper_admin.py:458] Pushing model Docker image to pytorch-model:1
18-05-21:09:03:56 INFO     [docker_container_manager.py:257] Found 0 replicas for pytorch-model:1. Adding 1
18-05-21:09:04:03 INFO     [clipper_admin.py:635] Successfully registered model pytorch-model:1
18-05-21:09:04:03 INFO     [clipper_admin.py:553] Done deploying model pytorch-model:1.
18-05-21:09:04:08 INFO     [clipper_admin.py:263] Model pytorch-model is now linked to application pytorch-test
18-05-21:09:04:38 INFO     [clipper_admin.py:201] Application easy-register-app-model was successfully registered
18-05-21:09:04:38 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpk0dKaJ
18-05-21:09:04:38 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:09:04:38 INFO     [pytorch.py:206] Torch model saved
18-05-21:09:04:38 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpk0dKaJ
18-05-21:09:04:38 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/pytorch-container:develop\n'}
18-05-21:09:04:38 INFO     [clipper_admin.py:456] {u'stream': u' ---> 521aed7dfb45\n'}
18-05-21:09:04:38 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpk0dKaJ /model/\n'}
18-05-21:09:04:38 INFO     [clipper_admin.py:456] {u'stream': u' ---> e1953c483a7b\n'}
18-05-21:09:04:38 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built e1953c483a7b\n'}
18-05-21:09:04:38 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged easy-register-app-model:1\n'}
18-05-21:09:04:38 INFO     [clipper_admin.py:458] Pushing model Docker image to easy-register-app-model:1
18-05-21:09:04:39 INFO     [docker_container_manager.py:257] Found 0 replicas for easy-register-app-model:1. Adding 1
18-05-21:09:04:46 INFO     [clipper_admin.py:635] Successfully registered model easy-register-app-model:1
18-05-21:09:04:46 INFO     [clipper_admin.py:553] Done deploying model easy-register-app-model:1.
18-05-21:09:04:46 INFO     [clipper_admin.py:263] Model easy-register-app-model is now linked to application easy-register-app-model
18-05-21:09:05:11 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:09:06:04 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:06:04 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:43898
* installing to library ‘/usr/local/lib/R/site-library’
* installing *source* package ‘Rclipper’ ...
** R
** inst
** preparing package for lazy loading
** help
No man pages found in package  ‘Rclipper’ 
*** installing help indices
** building package indices
** installing vignettes
** testing if installed package can be loaded
* DONE (Rclipper)
18-05-21:09:06:06 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:09:06:06 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:06:06 INFO     [test_utils.py:82] Starting Clipper
18-05-21:09:06:06 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:09:06:10 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:09:06:21 INFO     [deploy_query_test_model.py:92] Running R model deployment test
18-05-21:09:06:21 INFO     [clipper_admin.py:201] Application rtest-app was successfully registered
[1] "Serialized list of dependent libraries: stats: graphics: grDevices: utils: datasets: base"
[1] "Serialized model function!"
[1] "Done!"
18-05-21:09:06:22 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper//2018-05-21-09%M-22.365
18-05-21:09:06:23 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/r-container-base:develop\n'}
18-05-21:09:06:23 INFO     [clipper_admin.py:456] {u'stream': u' ---> 94d7dadc1589\n'}
18-05-21:09:06:23 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper//2018-05-21-09%M-22.365 /model/\n'}
18-05-21:09:06:23 INFO     [clipper_admin.py:456] {u'stream': u' ---> ec3905ded7e3\n'}
18-05-21:09:06:23 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built ec3905ded7e3\n'}
18-05-21:09:06:23 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged rtest-model:1\n'}
18-05-21:09:06:23 INFO     [clipper_admin.py:458] Pushing model Docker image to rtest-model:1
To deploy this model, execute the following command from a connected ClipperConnection object `conn`:
conn.deploy_model("rtest-model", "1", "doubles", "rtest-model:1", num_replicas=<num_container_replicas>)
18-05-21:09:06:24 INFO     [docker_container_manager.py:257] Found 0 replicas for rtest-model:1. Adding 1
18-05-21:09:06:31 INFO     [clipper_admin.py:635] Successfully registered model rtest-model:1
18-05-21:09:06:31 INFO     [clipper_admin.py:553] Done deploying model rtest-model:1.
18-05-21:09:06:31 INFO     [clipper_admin.py:263] Model rtest-model is now linked to application rtest-app
18-05-21:09:07:06 INFO     [deploy_query_test_model.py:60] ADDR: localhost:46639
18-05-21:09:07:06 INFO     [deploy_query_test_model.py:97] R model deployment completed SUCCESSFULLY!
18-05-21:09:07:06 INFO     [test_utils.py:66] Creating DockerContainerManager
18-05-21:09:07:48 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:07:48 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at localhost:42446
18-05-21:09:07:49 INFO     [clipper_metric_docker.py:87] Start Metric Test (0/1): Running 2 Replicas
18-05-21:09:07:49 INFO     [docker_container_manager.py:119] Starting managed Redis instance in Docker
18-05-21:09:07:53 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:09:07:53 INFO     [clipper_admin.py:201] Application simple-example was successfully registered
18-05-21:09:07:53 INFO     [deployer_utils.py:44] Saving function to /tmp/clipper/tmpTcehDX
18-05-21:09:07:53 INFO     [deployer_utils.py:54] Serialized and supplied predict function
18-05-21:09:07:53 INFO     [python.py:192] Python closure saved
18-05-21:09:07:53 INFO     [python.py:198] Using Python 2 base image
18-05-21:09:07:53 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpTcehDX
18-05-21:09:07:53 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/python-closure-container:develop\n'}
18-05-21:09:07:53 INFO     [clipper_admin.py:456] {u'stream': u' ---> 85cbd5aabc94\n'}
18-05-21:09:07:53 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpTcehDX /model/\n'}
18-05-21:09:07:53 INFO     [clipper_admin.py:456] {u'stream': u' ---> 12a9b8431a6f\n'}
18-05-21:09:07:53 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 12a9b8431a6f\n'}
18-05-21:09:07:53 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged simple-example:1\n'}
18-05-21:09:07:53 INFO     [clipper_admin.py:458] Pushing model Docker image to simple-example:1
18-05-21:09:07:54 INFO     [docker_container_manager.py:257] Found 0 replicas for simple-example:1. Adding 2
18-05-21:09:08:02 INFO     [clipper_admin.py:635] Successfully registered model simple-example:1
18-05-21:09:08:02 INFO     [clipper_admin.py:553] Done deploying model simple-example:1.
18-05-21:09:08:02 INFO     [clipper_admin.py:263] Model simple-example is now linked to application simple-example
18-05-21:09:08:04 INFO     [clipper_metric_docker.py:95] Making 100 predictions using two model container; Should takes 25 seconds.
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:101] Test 1: Checking status of 3 node exporter
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:55] Querying: http://localhost:9090/api/v1/targets
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:57] {u'status': u'success', u'data': {u'activeTargets': [{u'lastScrape': u'2018-05-21T09:08:23.561096425Z', u'discoveredLabels': {u'job': u'query', u'__metrics_path__': u'/metrics', u'__scheme__': u'http', u'__address__': u'query_frontend_exporter-38730:1390'}, u'labels': {u'instance': u'query_frontend_exporter-38730:1390', u'job': u'query'}, u'health': u'up', u'scrapeUrl': u'http://query_frontend_exporter-38730:1390/metrics', u'lastError': u''}, {u'lastScrape': u'2018-05-21T09:08:22.272297746Z', u'discoveredLabels': {u'job': u'simple-example_1-16749', u'__metrics_path__': u'/metrics', u'__scheme__': u'http', u'__address__': u'simple-example_1-16749:1390'}, u'labels': {u'instance': u'simple-example_1-16749:1390', u'job': u'simple-example_1-16749'}, u'health': u'up', u'scrapeUrl': u'http://simple-example_1-16749:1390/metrics', u'lastError': u''}, {u'lastScrape': u'2018-05-21T09:08:23.151994142Z', u'discoveredLabels': {u'job': u'simple-example_1-87115', u'__metrics_path__': u'/metrics', u'__scheme__': u'http', u'__address__': u'simple-example_1-87115:1390'}, u'labels': {u'instance': u'simple-example_1-87115:1390', u'job': u'simple-example_1-87115'}, u'health': u'up', u'scrapeUrl': u'http://simple-example_1-87115:1390/metrics', u'lastError': u''}]}}
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:103] Test 1 Passed
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:105] Test 2: Checking Model Container Metrics
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:42] Querying: http://localhost:9090/api/v1/series?match[]=clipper_mc_parse_time_ms_sum
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:44] {u'status': u'success', u'data': [{u'__name__': u'clipper_mc_parse_time_ms_sum', u'job': u'simple-example_1-16749', u'instance': u'simple-example_1-16749:1390'}, {u'__name__': u'clipper_mc_parse_time_ms_sum', u'job': u'simple-example_1-87115', u'instance': u'simple-example_1-87115:1390'}]}
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:42] Querying: http://localhost:9090/api/v1/series?match[]=clipper_mc_end_to_end_latency_ms_sum
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:44] {u'status': u'success', u'data': [{u'__name__': u'clipper_mc_end_to_end_latency_ms_sum', u'job': u'simple-example_1-16749', u'instance': u'simple-example_1-16749:1390'}, {u'__name__': u'clipper_mc_end_to_end_latency_ms_sum', u'job': u'simple-example_1-87115', u'instance': u'simple-example_1-87115:1390'}]}
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:42] Querying: http://localhost:9090/api/v1/series?match[]=clipper_mc_recv_time_ms_sum
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:44] {u'status': u'success', u'data': [{u'__name__': u'clipper_mc_recv_time_ms_sum', u'job': u'simple-example_1-16749', u'instance': u'simple-example_1-16749:1390'}, {u'__name__': u'clipper_mc_recv_time_ms_sum', u'job': u'simple-example_1-87115', u'instance': u'simple-example_1-87115:1390'}]}
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:42] Querying: http://localhost:9090/api/v1/series?match[]=clipper_mc_pred_total
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:44] {u'status': u'success', u'data': [{u'__name__': u'clipper_mc_pred_total', u'job': u'simple-example_1-16749', u'instance': u'simple-example_1-16749:1390'}, {u'__name__': u'clipper_mc_pred_total', u'job': u'simple-example_1-87115', u'instance': u'simple-example_1-87115:1390'}]}
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:42] Querying: http://localhost:9090/api/v1/series?match[]=clipper_mc_handle_time_ms_sum
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:44] {u'status': u'success', u'data': [{u'__name__': u'clipper_mc_handle_time_ms_sum', u'job': u'simple-example_1-16749', u'instance': u'simple-example_1-16749:1390'}, {u'__name__': u'clipper_mc_handle_time_ms_sum', u'job': u'simple-example_1-87115', u'instance': u'simple-example_1-87115:1390'}]}
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:116] Test 2 Passed
18-05-21:09:08:24 INFO     [clipper_metric_docker.py:118] Metric Test Done, Cleaning up...
18-05-21:09:09:17 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:09:18 INFO     [test_utils.py:106] Creating KubernetesContainerManager
18-05-21:09:09:18 INFO     [kubernetes_container_manager.py:410] Stopping all running Clipper resources
18-05-21:09:09:18 INFO     [clipper_admin.py:1258] Stopped all Clipper cluster and all model containers
18-05-21:09:09:38 INFO     [test_utils.py:116] Done cleaning up clipper
18-05-21:09:09:38 INFO     [test_utils.py:118] Starting Clipper
18-05-21:09:09:49 INFO     [kubernetes_container_manager.py:208] Found 3 nodes: ec2-18-144-21-32.us-west-1.compute.amazonaws.com, ec2-13-56-252-99.us-west-1.compute.amazonaws.com, ec2-18-144-38-86.us-west-1.compute.amazonaws.com
18-05-21:09:09:49 INFO     [kubernetes_container_manager.py:217] Setting Clipper mgmt port to 31777
18-05-21:09:09:49 INFO     [kubernetes_container_manager.py:225] Setting Clipper query port to 31138
18-05-21:09:09:49 INFO     [kubernetes_container_manager.py:235] Setting Clipper metric port to 31456
18-05-21:09:09:49 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:09:09:50 INFO     [clipper_admin.py:124] Clipper still initializing.
18-05-21:09:09:51 INFO     [clipper_admin.py:126] Clipper is running
18-05-21:09:09:52 INFO     [kubernetes_container_manager.py:208] Found 3 nodes: ec2-18-144-21-32.us-west-1.compute.amazonaws.com, ec2-13-56-252-99.us-west-1.compute.amazonaws.com, ec2-18-144-38-86.us-west-1.compute.amazonaws.com
18-05-21:09:09:52 INFO     [kubernetes_container_manager.py:217] Setting Clipper mgmt port to 31777
18-05-21:09:09:52 INFO     [kubernetes_container_manager.py:225] Setting Clipper query port to 31138
18-05-21:09:09:52 INFO     [kubernetes_container_manager.py:235] Setting Clipper metric port to 31456
18-05-21:09:09:52 INFO     [clipper_admin.py:138] Successfully connected to Clipper cluster at ec2-18-144-21-32.us-west-1.compute.amazonaws.com:31138
18-05-21:09:10:52 INFO     [clipper_metric_kube.py:144] ec2-18-144-21-32.us-west-1.compute.amazonaws.com:31138
18-05-21:09:10:52 INFO     [clipper_admin.py:201] Application kube-metric-app was successfully registered
18-05-21:09:10:54 INFO     [clipper_admin.py:452] Building model Docker image with model data from /tmp/clipper/tmpleapOz
18-05-21:09:10:54 INFO     [clipper_admin.py:456] {u'stream': u'Step 1/2 : FROM clipper/noop-container:develop\n'}
18-05-21:09:10:54 INFO     [clipper_admin.py:456] {u'stream': u' ---> 34db2de94c9e\n'}
18-05-21:09:10:54 INFO     [clipper_admin.py:456] {u'stream': u'Step 2/2 : COPY /tmp/clipper/tmpleapOz /model/\n'}
18-05-21:09:10:54 INFO     [clipper_admin.py:456] {u'stream': u' ---> 9ffdef4086eb\n'}
18-05-21:09:10:54 INFO     [clipper_admin.py:456] {u'stream': u'Successfully built 9ffdef4086eb\n'}
18-05-21:09:10:54 INFO     [clipper_admin.py:456] {u'stream': u'Successfully tagged 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/kube-metric-model:1\n'}
18-05-21:09:10:54 INFO     [clipper_admin.py:458] Pushing model Docker image to 568959175238.dkr.ecr.us-west-1.amazonaws.com/clipper/kube-metric-model:1
18-05-21:09:11:05 INFO     [clipper_admin.py:635] Successfully registered model kube-metric-model:1
18-05-21:09:11:05 INFO     [clipper_admin.py:553] Done deploying model kube-metric-model:1.
18-05-21:09:11:15 INFO     [clipper_admin.py:263] Model kube-metric-model is now linked to application kube-metric-app
18-05-21:09:11:46 INFO     [clipper_metric_kube.py:155] Test 1: Checking status of 3 node exporter
18-05-21:09:11:46 INFO     [clipper_metric_kube.py:127] Querying: http://ec2-18-144-21-32.us-west-1.compute.amazonaws.com:31456/api/v1/targets
18-05-21:09:11:46 INFO     [clipper_metric_kube.py:129] {u'status': u'success', u'data': {u'activeTargets': [{u'lastScrape': u'2018-05-21T09:11:45.110671111Z', u'discoveredLabels': {u'__meta_kubernetes_pod_annotation_kubernetes_io_limit_ranger': u'LimitRanger plugin set: cpu request for container query-frontend; cpu request for container frontend-exporter', u'__meta_kubernetes_pod_ready': u'true', u'__meta_kubernetes_pod_container_port_number': u'7000', u'__meta_kubernetes_pod_host_ip': u'172.20.59.225', u'__meta_kubernetes_pod_annotation_prometheus_io_scrape': u'true', u'__meta_kubernetes_pod_node_name': u'ip-172-20-59-225.us-west-1.compute.internal', u'__meta_kubernetes_pod_annotation_prometheus_io_port': u'1390', u'__meta_kubernetes_pod_uid': u'b6950d62-5cd6-11e8-ad4b-02f88d7d7972', u'__meta_kubernetes_pod_label_ai_clipper_name': u'query-frontend', u'job': u'Clipper Metrics', u'__scheme__': u'http', u'__meta_kubernetes_pod_label_ai_clipper_query_frontend_id': u'0', u'__meta_kubernetes_pod_label_ai_clipper_container_label': u'', u'__meta_kubernetes_pod_name': u'query-frontend-0-5bc6cb976f-kglg8', u'__meta_kubernetes_pod_container_port_name': u'', u'__meta_kubernetes_pod_label_pod_template_hash': u'1672765329', u'__meta_kubernetes_pod_container_port_protocol': u'TCP', u'__meta_kubernetes_pod_ip': u'100.96.2.244', u'__meta_kubernetes_namespace': u'default', u'__address__': u'100.96.2.244:7000', u'__meta_kubernetes_pod_container_name': u'query-frontend', u'__metrics_path__': u'/metrics'}, u'labels': {u'kubernetes_namespace': u'default', u'instance': u'100.96.2.244:1390', u'job': u'Clipper Metrics', u'kubernetes_pod_name': u'query-frontend-0-5bc6cb976f-kglg8'}, u'health': u'down', u'scrapeUrl': u'http://100.96.2.244:1390/metrics', u'lastError': u'Get http://100.96.2.244:1390/metrics: dial tcp 100.96.2.244:1390: getsockopt: connection refused'}, {u'lastScrape': u'2018-05-21T09:11:43.819398472Z', u'discoveredLabels': {u'__meta_kubernetes_pod_annotation_kubernetes_io_limit_ranger': u'LimitRanger plugin set: cpu request for container kube-metric-model-1-deployment-at-0', u'__meta_kubernetes_pod_annotation_test': u'readiness', u'__meta_kubernetes_pod_ready': u'false', u'__meta_kubernetes_pod_container_port_number': u'80', u'__meta_kubernetes_pod_host_ip': u'172.20.59.225', u'__meta_kubernetes_pod_annotation_prometheus_io_scrape': u'true', u'__meta_kubernetes_pod_node_name': u'ip-172-20-59-225.us-west-1.compute.internal', u'__meta_kubernetes_pod_annotation_prometheus_io_port': u'1390', u'__meta_kubernetes_pod_uid': u'def3b7f7-5cd6-11e8-ad4b-02f88d7d7972', u'job': u'Clipper Metrics', u'__scheme__': u'http', u'__meta_kubernetes_pod_label_ai_clipper_model_container_label': u'kube-metric-model_1', u'__meta_kubernetes_pod_label_ai_clipper_container_label': u'', u'__meta_kubernetes_pod_name': u'kube-metric-model-1-deployment-at-0-746d4f8cfd-qrcsj', u'__meta_kubernetes_pod_container_port_name': u'', u'__meta_kubernetes_pod_label_pod_template_hash': u'3028094798', u'__meta_kubernetes_pod_container_port_protocol': u'TCP', u'__meta_kubernetes_pod_ip': u'100.96.2.245', u'__meta_kubernetes_namespace': u'default', u'__address__': u'100.96.2.245:80', u'__meta_kubernetes_pod_container_name': u'kube-metric-model-1-deployment-at-0', u'__metrics_path__': u'/metrics'}, u'labels': {u'kubernetes_namespace': u'default', u'instance': u'100.96.2.245:1390', u'job': u'Clipper Metrics', u'model_container': u'kube-metric-model_1', u'kubernetes_pod_name': u'kube-metric-model-1-deployment-at-0-746d4f8cfd-qrcsj'}, u'health': u'up', u'scrapeUrl': u'http://100.96.2.245:1390/metrics', u'lastError': u''}, {u'lastScrape': u'2018-05-21T09:11:42.789489924Z', u'discoveredLabels': {u'__meta_kubernetes_pod_annotation_kubernetes_io_limit_ranger': u'LimitRanger plugin set: cpu request for container testapp0-model-0-deployment-at-0', u'__meta_kubernetes_pod_annotation_test': u'readiness', u'__meta_kubernetes_pod_ready': u'false', u'__meta_kubernetes_pod_container_port_number': u'80', u'__meta_kubernetes_pod_host_ip': u'172.20.51.85', u'__meta_kubernetes_pod_annotation_prometheus_io_scrape': u'true', u'__meta_kubernetes_pod_node_name': u'ip-172-20-51-85.us-west-1.compute.internal', u'__meta_kubernetes_pod_annotation_prometheus_io_port': u'1390', u'__meta_kubernetes_pod_uid': u'de7c9be4-5cd6-11e8-ad4b-02f88d7d7972', u'job': u'Clipper Metrics', u'__scheme__': u'http', u'__meta_kubernetes_pod_label_ai_clipper_model_container_label': u'testapp0-model_0', u'__meta_kubernetes_pod_label_ai_clipper_container_label': u'', u'__meta_kubernetes_pod_name': u'testapp0-model-0-deployment-at-0-5847564b6-v5c86', u'__meta_kubernetes_pod_container_port_name': u'', u'__meta_kubernetes_pod_label_pod_template_hash': u'140312062', u'__meta_kubernetes_pod_container_port_protocol': u'TCP', u'__meta_kubernetes_pod_ip': u'100.96.1.239', u'__meta_kubernetes_namespace': u'default', u'__address__': u'100.96.1.239:80', u'__meta_kubernetes_pod_container_name': u'testapp0-model-0-deployment-at-0', u'__metrics_path__': u'/metrics'}, u'labels': {u'kubernetes_namespace': u'default', u'instance': u'100.96.1.239:1390', u'job': u'Clipper Metrics', u'model_container': u'testapp0-model_0', u'kubernetes_pod_name': u'testapp0-model-0-deployment-at-0-5847564b6-v5c86'}, u'health': u'up', u'scrapeUrl': u'http://100.96.1.239:1390/metrics', u'lastError': u''}, {u'lastScrape': u'2018-05-21T09:11:46.074235238Z', u'discoveredLabels': {u'__meta_kubernetes_pod_annotation_kubernetes_io_limit_ranger': u'LimitRanger plugin set: cpu request for container kube-metric-model-1-deployment-at-0', u'__meta_kubernetes_pod_annotation_test': u'readiness', u'__meta_kubernetes_pod_ready': u'false', u'__meta_kubernetes_pod_container_port_number': u'80', u'__meta_kubernetes_pod_host_ip': u'172.20.51.85', u'__meta_kubernetes_pod_annotation_prometheus_io_scrape': u'true', u'__meta_kubernetes_pod_node_name': u'ip-172-20-51-85.us-west-1.compute.internal', u'__meta_kubernetes_pod_annotation_prometheus_io_port': u'1390', u'__meta_kubernetes_pod_uid': u'deef8425-5cd6-11e8-ad4b-02f88d7d7972', u'job': u'Clipper Metrics', u'__scheme__': u'http', u'__meta_kubernetes_pod_label_ai_clipper_model_container_label': u'kube-metric-model_1', u'__meta_kubernetes_pod_label_ai_clipper_container_label': u'', u'__meta_kubernetes_pod_name': u'kube-metric-model-1-deployment-at-0-746d4f8cfd-t4mfs', u'__meta_kubernetes_pod_container_port_name': u'', u'__meta_kubernetes_pod_label_pod_template_hash': u'3028094798', u'__meta_kubernetes_pod_container_port_protocol': u'TCP', u'__meta_kubernetes_pod_ip': u'100.96.1.240', u'__meta_kubernetes_namespace': u'default', u'__address__': u'100.96.1.240:80', u'__meta_kubernetes_pod_container_name': u'kube-metric-model-1-deployment-at-0', u'__metrics_path__': u'/metrics'}, u'labels': {u'kubernetes_namespace': u'default', u'instance': u'100.96.1.240:1390', u'job': u'Clipper Metrics', u'model_container': u'kube-metric-model_1', u'kubernetes_pod_name': u'kube-metric-model-1-deployment-at-0-746d4f8cfd-t4mfs'}, u'health': u'up', u'scrapeUrl': u'http://100.96.1.240:1390/metrics', u'lastError': u''}]}}
18-05-21:09:11:46 INFO     [clipper_metric_kube.py:167] Exception noted. Will retry again in 60 seconds.
18-05-21:09:11:46 INFO     [clipper_metric_kube.py:168] Wrong number of targets
18-05-21:09:12:46 INFO     [clipper_metric_kube.py:127] Querying: http://ec2-18-144-21-32.us-west-1.compute.amazonaws.com:31456/api/v1/targets
18-05-21:09:12:46 ERROR    [clipper_metric_kube.py:215] Exception: HTTPConnectionPool(host='ec2-18-144-21-32.us-west-1.compute.amazonaws.com', port=31456): Max retries exceeded with url: /api/v1/targets (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f89c01d3e90>: Failed to establish a new connection: [Errno 111] Connection refused',))
Traceback (most recent call last):
  File "../integration-tests/clipper_metric_kube.py", line 163, in <module>
    check_target_health(metric_api_addr)
  File "../integration-tests/clipper_metric_kube.py", line 128, in check_target_health
    res = requests.get(query).json()
  File "/usr/local/lib/python2.7/dist-packages/requests/api.py", line 72, in get
    return request('get', url, params=params, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/requests/api.py", line 58, in request
    return session.request(method=method, url=url, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 508, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 618, in send
    r = adapter.send(request, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/requests/adapters.py", line 508, in send
    raise ConnectionError(e, request=request)
ConnectionError: HTTPConnectionPool(host='ec2-18-144-21-32.us-west-1.compute.amazonaws.com', port=31456): Max retries exceeded with url: /api/v1/targets (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f89c01d3e90>: Failed to establish a new connection: [Errno 111] Connection refused',))
Exiting unit tests...
Cleanup exit code: 0
Build step 'Execute shell' marked build as failure
Sending e-mails to: dscrankshaw+clipper@gmail.com
Setting commit status on GitHub for https://github.com/ucbrise/clipper/commit/25f6031816e4b431d2a45dd7b3a00db015406447
Finished: FAILURE