python3 -u test.py
RUN ./ol new -p=test-dir
b'Init OL dir at /root/open-lambda/test-dir\nCreate lambda base at /root/open-lambda/test-dir/lambda (may take several minutes)\nWorking Directory: /root/open-lambda/test-dir\n\nWorker Defaults: \n{\n\t"registry": "/root/open-lambda/test-dir/registry",\n\t"registry_cache_ms": 5000,\n\t"sandbox": "sock",\n\t"cluster_name": "/root/open-lambda/test-dir",\n\t"pip_mirror": "",\n\t"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",\n\t"handler_cache_mb": 239,\n\t"import_cache_mb": 239,\n\t"server_mode": "lambda",\n\t"worker_dir": "/root/open-lambda/test-dir/worker",\n\t"SOCK_base_path": "/root/open-lambda/test-dir/lambda",\n\t"worker_port": "5000",\n\t"Skip_pull_existing": false,\n\t"sandbox_config": {},\n\t"docker_runtime": "",\n\t"sock_cgroups": {\n\t\t"max_procs": 10,\n\t\t"max_mem_mb": 50\n\t}\n}\n\nYou may modify the defaults here: /root/open-lambda/test-dir/config.json\n\nYou may now start a server using the "ol worker" command\n'
PUSH conf: {'registry': '/root/open-lambda/test-registry'}
========================================
ping_test
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=7286, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 7286\n'
{
"test": "ping_test",
"params": {},
"pass": true,
"seconds": 2.421900510787964,
"total_seconds": 2.670208215713501,
"stats": {
"pings_per_sec": 412.9026567385574
},
"ol-stats": {
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 1,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 1,
"Create()/fresh-proc:ms.avg": 1371,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 3,
"Create()/make-root-fs:ms.cnt": 1,
"Create():ms.avg": 1375,
"Create():ms.cnt": 1,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 1,
"Destroy()/kill-procs:ms.avg": 1,
"Destroy()/kill-procs:ms.cnt": 1,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 1,
"Destroy():ms.avg": 1,
"Destroy():ms.cnt": 1
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 239,
"pip_mirror": "",
"registry": "/root/open-lambda/test-registry",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"server_mode": "lambda",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 5000,
"handler_cache_mb": 239,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [],
"worker_tail": [
"2019/07/04 21:43:04 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 21:43:04 remove worker.pid",
"2019/07/04 21:43:04 exiting",
""
]
}
PUSH conf: {'import_cache_mb': 0, 'handler_cache_mb': 100}
========================================
smoke_tests
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=7312, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 7312\n'
{
"test": "smoke_tests",
"params": {},
"pass": false,
"seconds": null,
"total_seconds": 459.61167883872986,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 11,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 11,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 11,
"Create()/fresh-proc:ms.avg": 205,
"Create()/fresh-proc:ms.cnt": 11,
"Create()/make-root-fs:ms.avg": 1,
"Create()/make-root-fs:ms.cnt": 11,
"Create():ms.avg": 207,
"Create():ms.cnt": 11,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 11,
"Destroy()/kill-procs:ms.avg": 2,
"Destroy()/kill-procs:ms.cnt": 11,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 11,
"Destroy():ms.avg": 2,
"Destroy():ms.cnt": 12,
"Pause():ms.avg": 3,
"Pause():ms.cnt": 4,
"evict:ms.avg": 5,
"evict:ms.cnt": 1,
"pip-install:ms.avg": 65367,
"pip-install:ms.cnt": 7
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 0,
"pip_mirror": "",
"server_mode": "lambda",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"registry": "/root/open-lambda/test-registry",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 5000,
"handler_cache_mb": 100,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [
[
"Traceback (most recent call last):",
" File \"test.py\", line 76, in wrapper",
" rv = fn(**kwargs)",
" File \"test.py\", line 193, in smoke_tests",
" raise Exception(\"STATUS %d: %s\" % (r.status_code, r.text))",
"Exception: STATUS 500: 500: Internal Server Error500: Internal Server Error",
""
]
],
"worker_tail": [
"using existing OL directory at /root/open-lambda/test-dir",
"2019/07/04 21:43:04 save PID 7312 to file /root/open-lambda/test-dir/worker/worker.pid",
"2019/07/04 21:43:04 Start Lambda Server",
"2019/07/04 21:43:04 Create SandboxPool",
"2019/07/04 21:43:04 create /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 create /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 create /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 create /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 create /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 create /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 create /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 create /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 create /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 Create ModulePuller",
"2019/07/04 21:43:04 Create HandlerPuller",
"2019/07/04 21:43:04 Setups Handlers",
"2019/07/04 21:43:04 Execute handler by POSTing to localhost:5000/run/",
"2019/07/04 21:43:04 Get status by sending request to localhost:5000/status",
"2019/07/04 21:43:04 start creating/serving CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 Receive request to /pid",
"2019/07/04 21:43:04 Receive request to /run/echo",
"2019/07/04 21:43:04 debug: LambdaFunc.Task() runs on goroutine 15 [FUNC echo]",
"2019/07/04 21:43:04 increase instances to 1 [FUNC echo]",
"2019/07/04 21:43:04 .Create(, true, /root/open-lambda/test-dir/worker/lambda_code/1-echo, /root/open-lambda/test-dir/worker/scratch/func-echo-1001, &{[] []})...",
"2019/07/04 21:43:04 ...returns &{0xc000174a20 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:04 Channel() [SB 1]",
"2019/07/04 21:43:04 Pause() [SB 1]",
"2019/07/04 21:43:04 Receive request to /run/install",
"2019/07/04 21:43:04 debug: LambdaFunc.Task() runs on goroutine 28 [FUNC install]",
"2019/07/04 21:43:04 run pip install parso from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/parso on host",
"2019/07/04 21:43:04 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/parso, )...",
"2019/07/04 21:43:04 ...returns &{0xc0001a8060 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:04 Channel() [SB 2]",
"2019/07/04 21:43:04 Evict Sandbox 1",
"2019/07/04 21:43:04 Destroy() [SB 1]",
"2019/07/04 21:43:04 kill all procs in CG [SOCK 1]",
"2019/07/04 21:43:04 waiting for 1 procs in cg-1 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:04 unmount and remove dirs [SOCK 1]",
"Collecting parso",
" Downloading https://files.pythonhosted.org/packages/68/59/482f5a00fe3da7f0aaeedf61c2a25c445b68c9124437195f6e8b2beddbc0/parso-0.5.0-py2.py3-none-any.whl (94kB)",
"Installing collected packages: parso",
"Successfully installed parso-0.5.0",
"2019/07/04 21:43:05 Destroy() [SB 2]",
"2019/07/04 21:43:05 kill all procs in CG [SOCK 2]",
"2019/07/04 21:43:05 waiting for 1 procs in cg-2 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:05 unmount and remove dirs [SOCK 2]",
"2019/07/04 21:43:05 run pip install jedi from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/jedi on host",
"2019/07/04 21:43:05 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/jedi, )...",
"2019/07/04 21:43:05 ...returns &{0xc0001a8f60 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:05 Channel() [SB 3]",
"Collecting jedi",
" Downloading https://files.pythonhosted.org/packages/68/42/6309f3871b2f8361764ac5b2fe6719f9c6e6561d9307d8cecda319cf5843/jedi-0.14.0-py2.py3-none-any.whl (1.0MB)",
"Installing collected packages: jedi",
"Successfully installed jedi-0.14.0",
"2019/07/04 21:43:06 Destroy() [SB 3]",
"2019/07/04 21:43:06 kill all procs in CG [SOCK 3]",
"2019/07/04 21:43:06 waiting for 1 procs in cg-3 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:06 unmount and remove dirs [SOCK 3]",
"2019/07/04 21:43:06 run pip install idna from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/idna on host",
"2019/07/04 21:43:06 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/idna, )...",
"2019/07/04 21:43:07 ...returns &{0xc0001a9b60 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:07 Channel() [SB 4]",
"Collecting idna",
" Downloading https://files.pythonhosted.org/packages/14/2c/cd551d81dbe15200be1cf41cd03869a46fe7226e7450af7a6545bfc474c9/idna-2.8-py2.py3-none-any.whl (58kB)",
"Installing collected packages: idna",
"Successfully installed idna-2.8",
"2019/07/04 21:43:07 Destroy() [SB 4]",
"2019/07/04 21:43:07 kill all procs in CG [SOCK 4]",
"2019/07/04 21:43:07 waiting for 1 procs in cg-4 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:07 unmount and remove dirs [SOCK 4]",
"2019/07/04 21:43:07 run pip install chardet from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/chardet on host",
"2019/07/04 21:43:07 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/chardet, )...",
"2019/07/04 21:43:07 ...returns &{0xc0001cc780 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:07 Channel() [SB 5]",
"Collecting chardet",
" Using cached https://files.pythonhosted.org/packages/bc/a9/01ffebfb562e4274b6487b4bb1ddec7ca55ec7510b22e4c51f14098443b8/chardet-3.0.4-py2.py3-none-any.whl",
"Installing collected packages: chardet",
"Successfully installed chardet-3.0.4",
"2019/07/04 21:43:08 Destroy() [SB 5]",
"2019/07/04 21:43:08 kill all procs in CG [SOCK 5]",
"2019/07/04 21:43:08 waiting for 1 procs in cg-5 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:08 unmount and remove dirs [SOCK 5]",
"2019/07/04 21:43:08 run pip install certifi from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/certifi on host",
"2019/07/04 21:43:08 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/certifi, )...",
"2019/07/04 21:43:08 ...returns &{0xc0001cd380 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:08 Channel() [SB 6]",
"Collecting certifi",
" Using cached https://files.pythonhosted.org/packages/69/1b/b853c7a9d4f6a6d00749e94eb6f3a041e342a885b87340b79c1ef73e3a78/certifi-2019.6.16-py2.py3-none-any.whl",
"Installing collected packages: certifi",
"Successfully installed certifi-2019.6.16",
"2019/07/04 21:43:09 Destroy() [SB 6]",
"2019/07/04 21:43:09 kill all procs in CG [SOCK 6]",
"2019/07/04 21:43:09 waiting for 1 procs in cg-6 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:09 unmount and remove dirs [SOCK 6]",
"2019/07/04 21:43:09 run pip install requests from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/requests on host",
"2019/07/04 21:43:09 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/requests, )...",
"2019/07/04 21:43:09 ...returns &{0xc0001cdf80 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:09 Channel() [SB 7]",
"Collecting requests",
" Using cached https://files.pythonhosted.org/packages/51/bd/23c926cd341ea6b7dd0b2a00aba99ae0f828be89d72b2190f27c11d4b7fb/requests-2.22.0-py2.py3-none-any.whl",
"Installing collected packages: requests",
"Successfully installed requests-2.22.0",
"2019/07/04 21:43:09 Destroy() [SB 7]",
"2019/07/04 21:43:09 kill all procs in CG [SOCK 7]",
"2019/07/04 21:43:09 waiting for 1 procs in cg-7 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:43:09 unmount and remove dirs [SOCK 7]",
"2019/07/04 21:43:09 increase instances to 1 [FUNC install]",
"2019/07/04 21:43:09 .Create(, true, /root/open-lambda/test-dir/worker/lambda_code/2-install, /root/open-lambda/test-dir/worker/scratch/func-install-1002, &{[parso jedi idna chardet certifi requests] [parso jedi idna chardet certifi requests urllib3]})...",
"2019/07/04 21:43:09 ...returns &{0xc0001f0c00 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:09 Channel() [SB 8]",
"2019/07/04 21:43:10 Pause() [SB 8]",
"2019/07/04 21:43:10 Receive request to /stats",
"2019/07/04 21:43:10 Receive request to /run/install2",
"2019/07/04 21:43:10 debug: LambdaFunc.Task() runs on goroutine 59 [FUNC install2]",
"2019/07/04 21:43:10 skip installing parso, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing jedi, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing idna, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing chardet, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing certifi, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing requests, already installed during this run of OL",
"2019/07/04 21:43:10 increase instances to 1 [FUNC install2]",
"2019/07/04 21:43:10 .Create(, true, /root/open-lambda/test-dir/worker/lambda_code/3-install2, /root/open-lambda/test-dir/worker/scratch/func-install2-1003, &{[parso jedi idna chardet certifi requests] [parso jedi idna chardet certifi requests urllib3]})...",
"2019/07/04 21:43:10 ...returns &{0xc000220240 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:10 Channel() [SB 9]",
"2019/07/04 21:43:10 Pause() [SB 9]",
"2019/07/04 21:43:10 Receive request to /stats",
"2019/07/04 21:43:10 Receive request to /run/install3",
"2019/07/04 21:43:10 debug: LambdaFunc.Task() runs on goroutine 71 [FUNC install3]",
"2019/07/04 21:43:10 skip installing parso, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing jedi, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing idna, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing chardet, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing certifi, already installed during this run of OL",
"2019/07/04 21:43:10 skip installing requests, already installed during this run of OL",
"2019/07/04 21:43:10 run pip install simplejson from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/simplejson on host",
"2019/07/04 21:43:10 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/simplejson, )...",
"2019/07/04 21:43:10 ...returns &{0xc0002217a0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:43:10 Channel() [SB 10]",
"Collecting simplejson",
" Downloading https://files.pythonhosted.org/packages/e3/24/c35fb1c1c315fc0fffe61ea00d3f88e85469004713dab488dee4f35b0aff/simplejson-3.16.0.tar.gz (81kB)",
"Building wheels for collected packages: simplejson",
" WARNING: Building wheel for simplejson failed: [Errno 30] Read-only file system: '/root/.cache/pip/wheels/5d'",
"Failed to build simplejson",
"Installing collected packages: simplejson",
" Running setup.py install for simplejson: started",
"Killed",
"2019/07/04 21:50:42 Destroy() [SB 10]",
"2019/07/04 21:50:42 kill all procs in CG [SOCK 10]",
"2019/07/04 21:50:42 waiting for 3 procs in cg-10 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:42 unmount and remove dirs [SOCK 10]",
"2019/07/04 21:50:42 increase instances to 1 [FUNC install3]",
"2019/07/04 21:50:42 .Create(, true, /root/open-lambda/test-dir/worker/lambda_code/4-install3, /root/open-lambda/test-dir/worker/scratch/func-install3-1004, &{[parso jedi idna chardet certifi requests simplejson] [parso jedi idna chardet certifi requests simplejson urllib3]})...",
"2019/07/04 21:50:43 ...returns &{0xc00024c540 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:43 Channel() [SB 11]",
"ERROR:tornado.application:Uncaught exception POST /run/install3 (0.0.0.0)",
"HTTPServerRequest(protocol='http', host='localhost:5000', method='POST', uri='/run/install3', version='HTTP/1.1', remote_ip='0.0.0.0', headers={'Host': 'localhost:5000', 'User-Agent': 'python-requests/2.9.1', 'Content-Length': '2', 'Accept': '*/*', 'Accept-Encoding': 'gzip, deflate', 'X-Forwarded-For': '127.0.0.1'})",
"Traceback (most recent call last):",
" File \"/usr/local/lib/python3.6/dist-packages/tornado/web.py\", line 1510, in _execute",
" result = method(*self.path_args, **self.path_kwargs)",
" File \"sock2.py\", line 33, in post",
" import lambda_func",
" File \"/handler/lambda_func.py\", line 3, in ",
" import simplejson",
"ModuleNotFoundError: No module named 'simplejson'",
"2019/07/04 21:50:43 Pause() [SB 11]",
"2019/07/04 21:50:43 received kill signal, cleaning up",
"Kill function: echo2019/07/04 21:50:43 Destroy() [SB 1]",
"Kill function: install2019/07/04 21:50:43 Destroy() [SB 8]",
"2019/07/04 21:50:43 kill all procs in CG [SOCK 8]",
"2019/07/04 21:50:43 unmount and remove dirs [SOCK 8]",
"Kill function: install22019/07/04 21:50:43 Destroy() [SB 9]",
"2019/07/04 21:50:43 kill all procs in CG [SOCK 9]",
"2019/07/04 21:50:43 unmount and remove dirs [SOCK 9]",
"Kill function: install32019/07/04 21:50:43 Destroy() [SB 11]",
"2019/07/04 21:50:43 kill all procs in CG [SOCK 11]",
"2019/07/04 21:50:43 unmount and remove dirs [SOCK 11]",
"2019/07/04 21:50:43 SOCKPool.Cleanup: make sure all memory is free",
"2019/07/04 21:50:43 SOCKPool.Cleanup: memory pool emptied",
"2019/07/04 21:50:43 received shutdown request [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 empty queues and release CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 21:50:43 remove worker.pid",
"2019/07/04 21:50:43 exiting",
""
]
}
POP conf: {'import_cache_mb': 0, 'handler_cache_mb': 100}
PUSH conf: {'import_cache_mb': 0, 'handler_cache_mb': 250}
========================================
smoke_tests
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=7442, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 7442\n'
{
"test": "smoke_tests",
"params": {},
"pass": false,
"seconds": null,
"total_seconds": 386.12637424468994,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 11,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 11,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 11,
"Create()/fresh-proc:ms.avg": 139,
"Create()/fresh-proc:ms.cnt": 11,
"Create()/make-root-fs:ms.avg": 1,
"Create()/make-root-fs:ms.cnt": 11,
"Create():ms.avg": 141,
"Create():ms.cnt": 11,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 11,
"Destroy()/kill-procs:ms.avg": 2,
"Destroy()/kill-procs:ms.cnt": 11,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 11,
"Destroy():ms.avg": 2,
"Destroy():ms.cnt": 11,
"Pause():ms.avg": 4,
"Pause():ms.cnt": 4,
"pip-install:ms.avg": 54968,
"pip-install:ms.cnt": 7
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/root/open-lambda/test-registry",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 250,
"worker_port": "5000",
"import_cache_mb": 0,
"server_mode": "lambda",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [
[
"Traceback (most recent call last):",
" File \"test.py\", line 76, in wrapper",
" rv = fn(**kwargs)",
" File \"test.py\", line 193, in smoke_tests",
" raise Exception(\"STATUS %d: %s\" % (r.status_code, r.text))",
"Exception: STATUS 500: 500: Internal Server Error500: Internal Server Error",
""
]
],
"worker_tail": [
"using existing OL directory at /root/open-lambda/test-dir",
"2019/07/04 21:50:43 save PID 7442 to file /root/open-lambda/test-dir/worker/worker.pid",
"2019/07/04 21:50:43 Start Lambda Server",
"2019/07/04 21:50:43 Create SandboxPool",
"2019/07/04 21:50:43 create /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 create /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 create /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 create /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 create /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 create /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 create /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 create /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 create /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 Create ModulePuller",
"2019/07/04 21:50:43 Create HandlerPuller",
"2019/07/04 21:50:43 Setups Handlers",
"2019/07/04 21:50:43 Execute handler by POSTing to localhost:5000/run/",
"2019/07/04 21:50:43 Get status by sending request to localhost:5000/status",
"2019/07/04 21:50:43 start creating/serving CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:43 Receive request to /pid",
"2019/07/04 21:50:43 Receive request to /run/echo",
"2019/07/04 21:50:43 debug: LambdaFunc.Task() runs on goroutine 15 [FUNC echo]",
"2019/07/04 21:50:43 increase instances to 1 [FUNC echo]",
"2019/07/04 21:50:43 .Create(, true, /root/open-lambda/test-dir/worker/lambda_code/1-echo, /root/open-lambda/test-dir/worker/scratch/func-echo-1001, &{[] []})...",
"2019/07/04 21:50:44 ...returns &{0xc000198c60 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:44 Channel() [SB 1]",
"2019/07/04 21:50:44 Pause() [SB 1]",
"2019/07/04 21:50:44 Receive request to /run/install",
"2019/07/04 21:50:44 debug: LambdaFunc.Task() runs on goroutine 28 [FUNC install]",
"2019/07/04 21:50:44 run pip install parso from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/parso on host",
"2019/07/04 21:50:44 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/parso, )...",
"2019/07/04 21:50:44 ...returns &{0xc0001d4240 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:44 Channel() [SB 2]",
"Collecting parso",
" Downloading https://files.pythonhosted.org/packages/68/59/482f5a00fe3da7f0aaeedf61c2a25c445b68c9124437195f6e8b2beddbc0/parso-0.5.0-py2.py3-none-any.whl (94kB)",
"Installing collected packages: parso",
"Successfully installed parso-0.5.0",
"2019/07/04 21:50:44 Destroy() [SB 2]",
"2019/07/04 21:50:44 kill all procs in CG [SOCK 2]",
"2019/07/04 21:50:44 waiting for 1 procs in cg-2 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:44 unmount and remove dirs [SOCK 2]",
"2019/07/04 21:50:44 run pip install jedi from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/jedi on host",
"2019/07/04 21:50:44 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/jedi, )...",
"2019/07/04 21:50:44 ...returns &{0xc0001d4ea0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:44 Channel() [SB 3]",
"Collecting jedi",
" Downloading https://files.pythonhosted.org/packages/68/42/6309f3871b2f8361764ac5b2fe6719f9c6e6561d9307d8cecda319cf5843/jedi-0.14.0-py2.py3-none-any.whl (1.0MB)",
"Installing collected packages: jedi",
"Successfully installed jedi-0.14.0",
"2019/07/04 21:50:46 Destroy() [SB 3]",
"2019/07/04 21:50:46 kill all procs in CG [SOCK 3]",
"2019/07/04 21:50:46 waiting for 1 procs in cg-3 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:46 unmount and remove dirs [SOCK 3]",
"2019/07/04 21:50:46 run pip install idna from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/idna on host",
"2019/07/04 21:50:46 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/idna, )...",
"2019/07/04 21:50:46 ...returns &{0xc0001d5aa0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:46 Channel() [SB 4]",
"Collecting idna",
" Downloading https://files.pythonhosted.org/packages/14/2c/cd551d81dbe15200be1cf41cd03869a46fe7226e7450af7a6545bfc474c9/idna-2.8-py2.py3-none-any.whl (58kB)",
"Installing collected packages: idna",
"Killed",
"2019/07/04 21:50:46 Destroy() [SB 4]",
"2019/07/04 21:50:46 kill all procs in CG [SOCK 4]",
"2019/07/04 21:50:46 waiting for 1 procs in cg-4 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:46 unmount and remove dirs [SOCK 4]",
"2019/07/04 21:50:46 run pip install chardet from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/chardet on host",
"2019/07/04 21:50:46 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/chardet, )...",
"2019/07/04 21:50:47 ...returns &{0xc0001f6720 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:47 Channel() [SB 5]",
"Collecting chardet",
" Using cached https://files.pythonhosted.org/packages/bc/a9/01ffebfb562e4274b6487b4bb1ddec7ca55ec7510b22e4c51f14098443b8/chardet-3.0.4-py2.py3-none-any.whl",
"Installing collected packages: chardet",
"Successfully installed chardet-3.0.4",
"2019/07/04 21:50:47 Destroy() [SB 5]",
"2019/07/04 21:50:47 kill all procs in CG [SOCK 5]",
"2019/07/04 21:50:47 waiting for 1 procs in cg-5 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:47 unmount and remove dirs [SOCK 5]",
"2019/07/04 21:50:47 run pip install certifi from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/certifi on host",
"2019/07/04 21:50:47 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/certifi, )...",
"2019/07/04 21:50:47 ...returns &{0xc0001f7320 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:47 Channel() [SB 6]",
"Collecting certifi",
" Using cached https://files.pythonhosted.org/packages/69/1b/b853c7a9d4f6a6d00749e94eb6f3a041e342a885b87340b79c1ef73e3a78/certifi-2019.6.16-py2.py3-none-any.whl",
"Installing collected packages: certifi",
"Successfully installed certifi-2019.6.16",
"2019/07/04 21:50:48 Destroy() [SB 6]",
"2019/07/04 21:50:48 kill all procs in CG [SOCK 6]",
"2019/07/04 21:50:48 waiting for 1 procs in cg-6 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:48 unmount and remove dirs [SOCK 6]",
"2019/07/04 21:50:48 run pip install requests from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/requests on host",
"2019/07/04 21:50:48 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/requests, )...",
"2019/07/04 21:50:48 ...returns &{0xc0001f7f20 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:48 Channel() [SB 7]",
"Collecting requests",
" Using cached https://files.pythonhosted.org/packages/51/bd/23c926cd341ea6b7dd0b2a00aba99ae0f828be89d72b2190f27c11d4b7fb/requests-2.22.0-py2.py3-none-any.whl",
"Installing collected packages: requests",
"Successfully installed requests-2.22.0",
"2019/07/04 21:50:49 Destroy() [SB 7]",
"2019/07/04 21:50:49 kill all procs in CG [SOCK 7]",
"2019/07/04 21:50:49 waiting for 1 procs in cg-7 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:50:49 unmount and remove dirs [SOCK 7]",
"2019/07/04 21:50:49 increase instances to 1 [FUNC install]",
"2019/07/04 21:50:49 .Create(, true, /root/open-lambda/test-dir/worker/lambda_code/2-install, /root/open-lambda/test-dir/worker/scratch/func-install-1002, &{[parso jedi idna chardet certifi requests] [parso jedi idna chardet certifi requests urllib3]})...",
"2019/07/04 21:50:49 ...returns &{0xc000218ba0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:49 Channel() [SB 8]",
"2019/07/04 21:50:49 Pause() [SB 8]",
"2019/07/04 21:50:49 Receive request to /stats",
"2019/07/04 21:50:49 Receive request to /run/install2",
"2019/07/04 21:50:49 debug: LambdaFunc.Task() runs on goroutine 58 [FUNC install2]",
"2019/07/04 21:50:49 skip installing parso, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing jedi, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing idna, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing chardet, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing certifi, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing requests, already installed during this run of OL",
"2019/07/04 21:50:49 increase instances to 1 [FUNC install2]",
"2019/07/04 21:50:49 .Create(, true, /root/open-lambda/test-dir/worker/lambda_code/3-install2, /root/open-lambda/test-dir/worker/scratch/func-install2-1003, &{[parso jedi idna chardet certifi requests] [parso jedi idna chardet certifi requests urllib3]})...",
"2019/07/04 21:50:49 ...returns &{0xc00024a240 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:49 Channel() [SB 9]",
"2019/07/04 21:50:49 Pause() [SB 9]",
"2019/07/04 21:50:49 Receive request to /stats",
"2019/07/04 21:50:49 Receive request to /run/install3",
"2019/07/04 21:50:49 debug: LambdaFunc.Task() runs on goroutine 70 [FUNC install3]",
"2019/07/04 21:50:49 skip installing parso, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing jedi, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing idna, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing chardet, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing certifi, already installed during this run of OL",
"2019/07/04 21:50:49 skip installing requests, already installed during this run of OL",
"2019/07/04 21:50:49 run pip install simplejson from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/simplejson on host",
"2019/07/04 21:50:49 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/simplejson, )...",
"2019/07/04 21:50:49 ...returns &{0xc00024b740 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:50:49 Channel() [SB 10]",
"Collecting simplejson",
" Downloading https://files.pythonhosted.org/packages/e3/24/c35fb1c1c315fc0fffe61ea00d3f88e85469004713dab488dee4f35b0aff/simplejson-3.16.0.tar.gz (81kB)",
"Building wheels for collected packages: simplejson",
" WARNING: Building wheel for simplejson failed: [Errno 30] Read-only file system: '/root/.cache/pip/wheels/5d'",
"Failed to build simplejson",
"Installing collected packages: simplejson",
" Running setup.py install for simplejson: started",
"Killed",
"2019/07/04 21:57:09 Destroy() [SB 10]",
"2019/07/04 21:57:09 kill all procs in CG [SOCK 10]",
"2019/07/04 21:57:09 waiting for 3 procs in cg-10 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 unmount and remove dirs [SOCK 10]",
"2019/07/04 21:57:09 increase instances to 1 [FUNC install3]",
"2019/07/04 21:57:09 .Create(, true, /root/open-lambda/test-dir/worker/lambda_code/4-install3, /root/open-lambda/test-dir/worker/scratch/func-install3-1004, &{[parso jedi idna chardet certifi requests simplejson] [parso jedi idna chardet certifi requests simplejson urllib3]})...",
"2019/07/04 21:57:09 ...returns &{0xc0002744e0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:09 Channel() [SB 11]",
"ERROR:tornado.application:Uncaught exception POST /run/install3 (0.0.0.0)",
"HTTPServerRequest(protocol='http', host='localhost:5000', method='POST', uri='/run/install3', version='HTTP/1.1', remote_ip='0.0.0.0', headers={'Host': 'localhost:5000', 'User-Agent': 'python-requests/2.9.1', 'Content-Length': '2', 'Accept': '*/*', 'Accept-Encoding': 'gzip, deflate', 'X-Forwarded-For': '127.0.0.1'})",
"Traceback (most recent call last):",
" File \"/usr/local/lib/python3.6/dist-packages/tornado/web.py\", line 1510, in _execute",
" result = method(*self.path_args, **self.path_kwargs)",
" File \"sock2.py\", line 33, in post",
" import lambda_func",
" File \"/handler/lambda_func.py\", line 3, in ",
" import simplejson",
"ModuleNotFoundError: No module named 'simplejson'",
"2019/07/04 21:57:09 Pause() [SB 11]",
"2019/07/04 21:57:09 received kill signal, cleaning up",
"Kill function: install2019/07/04 21:57:09 Destroy() [SB 8]",
"2019/07/04 21:57:09 kill all procs in CG [SOCK 8]",
"2019/07/04 21:57:09 unmount and remove dirs [SOCK 8]",
"Kill function: install22019/07/04 21:57:09 Destroy() [SB 9]",
"2019/07/04 21:57:09 kill all procs in CG [SOCK 9]",
"2019/07/04 21:57:09 unmount and remove dirs [SOCK 9]",
"Kill function: install32019/07/04 21:57:09 Destroy() [SB 11]",
"2019/07/04 21:57:09 kill all procs in CG [SOCK 11]",
"2019/07/04 21:57:09 unmount and remove dirs [SOCK 11]",
"Kill function: echo2019/07/04 21:57:09 Destroy() [SB 1]",
"2019/07/04 21:57:09 kill all procs in CG [SOCK 1]",
"2019/07/04 21:57:09 waiting for 1 procs in cg-1 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 unmount and remove dirs [SOCK 1]",
"2019/07/04 21:57:09 SOCKPool.Cleanup: make sure all memory is free",
"2019/07/04 21:57:09 SOCKPool.Cleanup: memory pool emptied",
"2019/07/04 21:57:09 received shutdown request [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 empty queues and release CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 21:57:09 remove worker.pid",
"2019/07/04 21:57:09 exiting",
""
]
}
POP conf: {'import_cache_mb': 0, 'handler_cache_mb': 250}
PUSH conf: {'import_cache_mb': 250, 'handler_cache_mb': 100}
========================================
smoke_tests
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=7580, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 7580\n'
{
"test": "smoke_tests",
"params": {},
"pass": false,
"seconds": null,
"total_seconds": 362.9417140483856,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 11,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 12,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 12,
"Create()/fork-proc:ms.avg": 5,
"Create()/fork-proc:ms.cnt": 4,
"Create()/fresh-proc:ms.avg": 143,
"Create()/fresh-proc:ms.cnt": 8,
"Create()/make-root-fs:ms.avg": 1,
"Create()/make-root-fs:ms.cnt": 12,
"Create():ms.avg": 99,
"Create():ms.cnt": 12,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 12,
"Destroy()/kill-procs:ms.avg": 2,
"Destroy()/kill-procs:ms.cnt": 12,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 12,
"Destroy():ms.avg": 2,
"Destroy():ms.cnt": 13,
"Pause():ms.avg": 4,
"Pause():ms.cnt": 4,
"evict:ms.avg": 6,
"evict:ms.cnt": 1,
"fork():ms.avg": 5,
"fork():ms.cnt": 4,
"forkRequest:ms.avg": 3,
"forkRequest:ms.cnt": 4,
"move-to-cg-after-fork:ms.avg": 0,
"move-to-cg-after-fork:ms.cnt": 4,
"pip-install:ms.avg": 51739,
"pip-install:ms.cnt": 7
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 250,
"pip_mirror": "",
"server_mode": "lambda",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"registry": "/root/open-lambda/test-registry",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 5000,
"handler_cache_mb": 100,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [
[
"Traceback (most recent call last):",
" File \"test.py\", line 76, in wrapper",
" rv = fn(**kwargs)",
" File \"test.py\", line 193, in smoke_tests",
" raise Exception(\"STATUS %d: %s\" % (r.status_code, r.text))",
"Exception: STATUS 500: 500: Internal Server Error500: Internal Server Error",
""
]
],
"worker_tail": [
"using existing OL directory at /root/open-lambda/test-dir",
"2019/07/04 21:57:09 save PID 7580 to file /root/open-lambda/test-dir/worker/worker.pid",
"2019/07/04 21:57:09 Start Lambda Server",
"2019/07/04 21:57:09 Create SandboxPool",
"2019/07/04 21:57:09 create /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 start creating/serving CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:09 Create ModulePuller",
"2019/07/04 21:57:09 Create HandlerPuller",
"2019/07/04 21:57:09 Create ImportCache",
"2019/07/04 21:57:09 create /sys/fs/cgroup/blkio/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/cpu/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/devices/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/freezer/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/hugetlb/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/memory/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/perf_event/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/systemd/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 create /sys/fs/cgroup/pids/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 Setups Handlers",
"2019/07/04 21:57:09 Execute handler by POSTing to localhost:5000/run/",
"2019/07/04 21:57:09 Get status by sending request to localhost:5000/status",
"2019/07/04 21:57:09 start creating/serving CGs [CGROUP POOL worker-sock-cache]",
"2019/07/04 21:57:09 .Create(, false, , /root/open-lambda/test-dir/worker/scratch/import-cache-1001, )...",
"2019/07/04 21:57:10 Receive request to /pid",
"2019/07/04 21:57:10 Receive request to /run/echo",
"2019/07/04 21:57:10 debug: LambdaFunc.Task() runs on goroutine 22 [FUNC echo]",
"2019/07/04 21:57:10 increase instances to 1 [FUNC echo]",
"2019/07/04 21:57:10 ...returns &{0xc00017f440 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:10 .Create(&{0xc00017f440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/1-echo, /root/open-lambda/test-dir/worker/scratch/func-echo-1002, &{[] []})...",
"2019/07/04 21:57:10 fork(&{0xc000082690 2 /root/open-lambda/test-dir/worker/sock-handlers/2 /root/open-lambda/test-dir/worker/lambda_code/1-echo /root/open-lambda/test-dir/worker/scratch/func-echo-1002 0xc00000f0c0}) [SB 1]",
"2019/07/04 21:57:10 ...returns &{0xc0001ba5a0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:10 Channel() [SB 2]",
"2019/07/04 21:57:10 Pause() [SB 2]",
"2019/07/04 21:57:10 Receive request to /run/install",
"2019/07/04 21:57:10 debug: LambdaFunc.Task() runs on goroutine 33 [FUNC install]",
"2019/07/04 21:57:10 run pip install parso from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/parso on host",
"2019/07/04 21:57:10 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/parso, )...",
"2019/07/04 21:57:10 ...returns &{0xc0001bbb60 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:10 Channel() [SB 3]",
"2019/07/04 21:57:10 Evict Sandbox 2",
"2019/07/04 21:57:10 Destroy() [SB 2]",
"2019/07/04 21:57:10 kill all procs in CG [SOCK 2]",
"2019/07/04 21:57:10 waiting for 1 procs in cg-1 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:10 unmount and remove dirs [SOCK 2]",
"Collecting parso",
" Downloading https://files.pythonhosted.org/packages/68/59/482f5a00fe3da7f0aaeedf61c2a25c445b68c9124437195f6e8b2beddbc0/parso-0.5.0-py2.py3-none-any.whl (94kB)",
"Installing collected packages: parso",
"Successfully installed parso-0.5.0",
"2019/07/04 21:57:11 Destroy() [SB 3]",
"2019/07/04 21:57:11 kill all procs in CG [SOCK 3]",
"2019/07/04 21:57:11 waiting for 1 procs in cg-2 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:11 unmount and remove dirs [SOCK 3]",
"2019/07/04 21:57:11 run pip install jedi from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/jedi on host",
"2019/07/04 21:57:11 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/jedi, )...",
"2019/07/04 21:57:11 ...returns &{0xc0001f6ba0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:11 Channel() [SB 4]",
"Collecting jedi",
" Downloading https://files.pythonhosted.org/packages/68/42/6309f3871b2f8361764ac5b2fe6719f9c6e6561d9307d8cecda319cf5843/jedi-0.14.0-py2.py3-none-any.whl (1.0MB)",
"Installing collected packages: jedi",
"Successfully installed jedi-0.14.0",
"2019/07/04 21:57:12 Destroy() [SB 4]",
"2019/07/04 21:57:12 kill all procs in CG [SOCK 4]",
"2019/07/04 21:57:12 waiting for 1 procs in cg-3 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:12 unmount and remove dirs [SOCK 4]",
"2019/07/04 21:57:12 run pip install idna from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/idna on host",
"2019/07/04 21:57:12 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/idna, )...",
"2019/07/04 21:57:12 ...returns &{0xc0001f77a0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:12 Channel() [SB 5]",
"Collecting idna",
" Downloading https://files.pythonhosted.org/packages/14/2c/cd551d81dbe15200be1cf41cd03869a46fe7226e7450af7a6545bfc474c9/idna-2.8-py2.py3-none-any.whl (58kB)",
"Installing collected packages: idna",
"Successfully installed idna-2.8",
"2019/07/04 21:57:13 Destroy() [SB 5]",
"2019/07/04 21:57:13 kill all procs in CG [SOCK 5]",
"2019/07/04 21:57:13 waiting for 1 procs in cg-4 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:13 unmount and remove dirs [SOCK 5]",
"2019/07/04 21:57:13 run pip install chardet from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/chardet on host",
"2019/07/04 21:57:13 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/chardet, )...",
"2019/07/04 21:57:13 ...returns &{0xc0002223c0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:13 Channel() [SB 6]",
"Collecting chardet",
" Using cached https://files.pythonhosted.org/packages/bc/a9/01ffebfb562e4274b6487b4bb1ddec7ca55ec7510b22e4c51f14098443b8/chardet-3.0.4-py2.py3-none-any.whl",
"Installing collected packages: chardet",
"Successfully installed chardet-3.0.4",
"2019/07/04 21:57:14 Destroy() [SB 6]",
"2019/07/04 21:57:14 kill all procs in CG [SOCK 6]",
"2019/07/04 21:57:14 waiting for 1 procs in cg-5 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:14 unmount and remove dirs [SOCK 6]",
"2019/07/04 21:57:14 run pip install certifi from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/certifi on host",
"2019/07/04 21:57:14 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/certifi, )...",
"2019/07/04 21:57:14 ...returns &{0xc000222fc0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:14 Channel() [SB 7]",
"Collecting certifi",
" Using cached https://files.pythonhosted.org/packages/69/1b/b853c7a9d4f6a6d00749e94eb6f3a041e342a885b87340b79c1ef73e3a78/certifi-2019.6.16-py2.py3-none-any.whl",
"Installing collected packages: certifi",
"Successfully installed certifi-2019.6.16",
"2019/07/04 21:57:15 Destroy() [SB 7]",
"2019/07/04 21:57:15 kill all procs in CG [SOCK 7]",
"2019/07/04 21:57:15 waiting for 1 procs in cg-6 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:15 unmount and remove dirs [SOCK 7]",
"2019/07/04 21:57:15 run pip install requests from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/requests on host",
"2019/07/04 21:57:15 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/requests, )...",
"2019/07/04 21:57:15 ...returns &{0xc000223bc0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:15 Channel() [SB 8]",
"Collecting requests",
" Using cached https://files.pythonhosted.org/packages/51/bd/23c926cd341ea6b7dd0b2a00aba99ae0f828be89d72b2190f27c11d4b7fb/requests-2.22.0-py2.py3-none-any.whl",
"Installing collected packages: requests",
"Successfully installed requests-2.22.0",
"2019/07/04 21:57:15 Destroy() [SB 8]",
"2019/07/04 21:57:15 kill all procs in CG [SOCK 8]",
"2019/07/04 21:57:15 waiting for 1 procs in cg-7 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 21:57:15 unmount and remove dirs [SOCK 8]",
"2019/07/04 21:57:15 increase instances to 1 [FUNC install]",
"2019/07/04 21:57:15 .Create(&{0xc00017f440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/2-install, /root/open-lambda/test-dir/worker/scratch/func-install-1003, &{[parso jedi idna chardet certifi requests] [parso jedi idna chardet certifi requests urllib3]})...",
"2019/07/04 21:57:15 fork(&{0xc000082690 9 /root/open-lambda/test-dir/worker/sock-handlers/9 /root/open-lambda/test-dir/worker/lambda_code/2-install /root/open-lambda/test-dir/worker/scratch/func-install-1003 0xc00000f280}) [SB 1]",
"2019/07/04 21:57:15 ...returns &{0xc000236840 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:15 Channel() [SB 9]",
"2019/07/04 21:57:16 Pause() [SB 9]",
"2019/07/04 21:57:16 Receive request to /stats",
"2019/07/04 21:57:16 Receive request to /run/install2",
"2019/07/04 21:57:16 debug: LambdaFunc.Task() runs on goroutine 64 [FUNC install2]",
"2019/07/04 21:57:16 skip installing parso, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing jedi, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing idna, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing chardet, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing certifi, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing requests, already installed during this run of OL",
"2019/07/04 21:57:16 increase instances to 1 [FUNC install2]",
"2019/07/04 21:57:16 .Create(&{0xc00017f440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/3-install2, /root/open-lambda/test-dir/worker/scratch/func-install2-1004, &{[parso jedi idna chardet certifi requests] [parso jedi idna chardet certifi requests urllib3]})...",
"2019/07/04 21:57:16 fork(&{0xc000082690 10 /root/open-lambda/test-dir/worker/sock-handlers/10 /root/open-lambda/test-dir/worker/lambda_code/3-install2 /root/open-lambda/test-dir/worker/scratch/func-install2-1004 0xc00000f2a0}) [SB 1]",
"2019/07/04 21:57:16 ...returns &{0xc000237da0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:16 Channel() [SB 10]",
"2019/07/04 21:57:16 Pause() [SB 10]",
"2019/07/04 21:57:16 Receive request to /stats",
"2019/07/04 21:57:16 Receive request to /run/install3",
"2019/07/04 21:57:16 debug: LambdaFunc.Task() runs on goroutine 76 [FUNC install3]",
"2019/07/04 21:57:16 skip installing parso, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing jedi, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing idna, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing chardet, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing certifi, already installed during this run of OL",
"2019/07/04 21:57:16 skip installing requests, already installed during this run of OL",
"2019/07/04 21:57:16 run pip install simplejson from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/simplejson on host",
"2019/07/04 21:57:16 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/simplejson, )...",
"2019/07/04 21:57:16 ...returns &{0xc000267380 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 21:57:16 Channel() [SB 11]",
"Collecting simplejson",
" Downloading https://files.pythonhosted.org/packages/e3/24/c35fb1c1c315fc0fffe61ea00d3f88e85469004713dab488dee4f35b0aff/simplejson-3.16.0.tar.gz (81kB)",
"Building wheels for collected packages: simplejson",
" WARNING: Building wheel for simplejson failed: [Errno 30] Read-only file system: '/root/.cache/pip/wheels/5d'",
"Failed to build simplejson",
"Installing collected packages: simplejson",
" Running setup.py install for simplejson: started",
"Killed",
"2019/07/04 22:03:12 Destroy() [SB 11]",
"2019/07/04 22:03:12 kill all procs in CG [SOCK 11]",
"2019/07/04 22:03:12 waiting for 3 procs in cg-10 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 unmount and remove dirs [SOCK 11]",
"2019/07/04 22:03:12 increase instances to 1 [FUNC install3]",
"2019/07/04 22:03:12 .Create(&{0xc00017f440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/4-install3, /root/open-lambda/test-dir/worker/scratch/func-install3-1005, &{[parso jedi idna chardet certifi requests simplejson] [parso jedi idna chardet certifi requests simplejson urllib3]})...",
"2019/07/04 22:03:12 fork(&{0xc000082690 12 /root/open-lambda/test-dir/worker/sock-handlers/12 /root/open-lambda/test-dir/worker/lambda_code/4-install3 /root/open-lambda/test-dir/worker/scratch/func-install3-1005 0xc00000f2e0}) [SB 1]",
"2019/07/04 22:03:12 ...returns &{0xc0002a2120 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:12 Channel() [SB 12]",
"ERROR:tornado.application:Uncaught exception POST /run/install3 (0.0.0.0)",
"HTTPServerRequest(protocol='http', host='localhost:5000', method='POST', uri='/run/install3', version='HTTP/1.1', remote_ip='0.0.0.0', headers={'Host': 'localhost:5000', 'User-Agent': 'python-requests/2.9.1', 'Content-Length': '2', 'Accept': '*/*', 'Accept-Encoding': 'gzip, deflate', 'X-Forwarded-For': '127.0.0.1'})",
"Traceback (most recent call last):",
" File \"/usr/local/lib/python3.6/dist-packages/tornado/web.py\", line 1510, in _execute",
" result = method(*self.path_args, **self.path_kwargs)",
" File \"sock2.py\", line 33, in post",
" import lambda_func",
" File \"/handler/lambda_func.py\", line 3, in ",
" import simplejson",
"ModuleNotFoundError: No module named 'simplejson'",
"2019/07/04 22:03:12 Pause() [SB 12]",
"2019/07/04 22:03:12 received kill signal, cleaning up",
"2019/07/04 22:03:12 Destroy() [SB 1]",
"2019/07/04 22:03:12 kill all procs in CG [SOCK 1]",
"2019/07/04 22:03:12 unmount and remove dirs [SOCK 1]",
"2019/07/04 22:03:12 SOCKPool.Cleanup: make sure all memory is free",
"2019/07/04 22:03:12 SOCKPool.Cleanup: memory pool emptied",
"2019/07/04 22:03:12 received shutdown request [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 empty queues and release CGs [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/blkio/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/cpu/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/devices/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/freezer/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/hugetlb/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/memory/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/perf_event/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/systemd/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/pids/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"Kill function: echo2019/07/04 22:03:12 Destroy() [SB 2]",
"Kill function: install2019/07/04 22:03:12 Destroy() [SB 9]",
"2019/07/04 22:03:12 kill all procs in CG [SOCK 9]",
"2019/07/04 22:03:12 unmount and remove dirs [SOCK 9]",
"Kill function: install22019/07/04 22:03:12 Destroy() [SB 10]",
"2019/07/04 22:03:12 kill all procs in CG [SOCK 10]",
"2019/07/04 22:03:12 unmount and remove dirs [SOCK 10]",
"Kill function: install32019/07/04 22:03:12 Destroy() [SB 12]",
"2019/07/04 22:03:12 kill all procs in CG [SOCK 12]",
"2019/07/04 22:03:12 unmount and remove dirs [SOCK 12]",
"2019/07/04 22:03:12 SOCKPool.Cleanup: make sure all memory is free",
"2019/07/04 22:03:12 SOCKPool.Cleanup: memory pool emptied",
"2019/07/04 22:03:12 received shutdown request [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 empty queues and release CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:03:12 remove worker.pid",
"2019/07/04 22:03:12 exiting",
""
]
}
POP conf: {'import_cache_mb': 250, 'handler_cache_mb': 100}
PUSH conf: {'import_cache_mb': 250, 'handler_cache_mb': 250}
========================================
smoke_tests
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=7718, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 7718\n'
{
"test": "smoke_tests",
"params": {},
"pass": false,
"seconds": null,
"total_seconds": 381.1776170730591,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 11,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 12,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 12,
"Create()/fork-proc:ms.avg": 5,
"Create()/fork-proc:ms.cnt": 4,
"Create()/fresh-proc:ms.avg": 142,
"Create()/fresh-proc:ms.cnt": 8,
"Create()/make-root-fs:ms.avg": 1,
"Create()/make-root-fs:ms.cnt": 12,
"Create():ms.avg": 98,
"Create():ms.cnt": 12,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 12,
"Destroy()/kill-procs:ms.avg": 2,
"Destroy()/kill-procs:ms.cnt": 12,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 12,
"Destroy():ms.avg": 2,
"Destroy():ms.cnt": 12,
"Pause():ms.avg": 4,
"Pause():ms.cnt": 4,
"fork():ms.avg": 5,
"fork():ms.cnt": 4,
"forkRequest:ms.avg": 4,
"forkRequest:ms.cnt": 4,
"move-to-cg-after-fork:ms.avg": 0,
"move-to-cg-after-fork:ms.cnt": 4,
"pip-install:ms.avg": 54344,
"pip-install:ms.cnt": 7
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/root/open-lambda/test-registry",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 250,
"worker_port": "5000",
"import_cache_mb": 250,
"server_mode": "lambda",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [
[
"Traceback (most recent call last):",
" File \"test.py\", line 76, in wrapper",
" rv = fn(**kwargs)",
" File \"test.py\", line 193, in smoke_tests",
" raise Exception(\"STATUS %d: %s\" % (r.status_code, r.text))",
"Exception: STATUS 500: 500: Internal Server Error500: Internal Server Error",
""
]
],
"worker_tail": [
"using existing OL directory at /root/open-lambda/test-dir",
"2019/07/04 22:03:12 save PID 7718 to file /root/open-lambda/test-dir/worker/worker.pid",
"2019/07/04 22:03:12 Start Lambda Server",
"2019/07/04 22:03:12 Create SandboxPool",
"2019/07/04 22:03:12 create /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 Create ModulePuller",
"2019/07/04 22:03:12 Create HandlerPuller",
"2019/07/04 22:03:12 Create ImportCache",
"2019/07/04 22:03:12 create /sys/fs/cgroup/blkio/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/cpu/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/devices/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/freezer/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/hugetlb/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/memory/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/perf_event/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/systemd/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 create /sys/fs/cgroup/pids/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 Setups Handlers",
"2019/07/04 22:03:12 Execute handler by POSTing to localhost:5000/run/",
"2019/07/04 22:03:12 Get status by sending request to localhost:5000/status",
"2019/07/04 22:03:12 start creating/serving CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:12 start creating/serving CGs [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:03:12 .Create(, false, , /root/open-lambda/test-dir/worker/scratch/import-cache-1001, )...",
"2019/07/04 22:03:12 Receive request to /pid",
"2019/07/04 22:03:13 Receive request to /run/echo",
"2019/07/04 22:03:13 debug: LambdaFunc.Task() runs on goroutine 22 [FUNC echo]",
"2019/07/04 22:03:13 increase instances to 1 [FUNC echo]",
"2019/07/04 22:03:13 ...returns &{0xc0001a9500 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:13 .Create(&{0xc0001a9500 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/1-echo, /root/open-lambda/test-dir/worker/scratch/func-echo-1002, &{[] []})...",
"2019/07/04 22:03:13 fork(&{0xc000082690 2 /root/open-lambda/test-dir/worker/sock-handlers/2 /root/open-lambda/test-dir/worker/lambda_code/1-echo /root/open-lambda/test-dir/worker/scratch/func-echo-1002 0xc00000f260}) [SB 1]",
"2019/07/04 22:03:13 ...returns &{0xc0001d0660 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:13 Channel() [SB 2]",
"2019/07/04 22:03:13 Pause() [SB 2]",
"2019/07/04 22:03:13 Receive request to /run/install",
"2019/07/04 22:03:13 debug: LambdaFunc.Task() runs on goroutine 33 [FUNC install]",
"2019/07/04 22:03:13 run pip install parso from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/parso on host",
"2019/07/04 22:03:13 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/parso, )...",
"2019/07/04 22:03:13 ...returns &{0xc0001d1c20 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:13 Channel() [SB 3]",
"Collecting parso",
" Downloading https://files.pythonhosted.org/packages/68/59/482f5a00fe3da7f0aaeedf61c2a25c445b68c9124437195f6e8b2beddbc0/parso-0.5.0-py2.py3-none-any.whl (94kB)",
"Installing collected packages: parso",
"Successfully installed parso-0.5.0",
"2019/07/04 22:03:13 Destroy() [SB 3]",
"2019/07/04 22:03:13 kill all procs in CG [SOCK 3]",
"2019/07/04 22:03:13 waiting for 1 procs in cg-2 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:13 unmount and remove dirs [SOCK 3]",
"2019/07/04 22:03:13 run pip install jedi from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/jedi on host",
"2019/07/04 22:03:13 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/jedi, )...",
"2019/07/04 22:03:13 ...returns &{0xc0002028a0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:13 Channel() [SB 4]",
"Collecting jedi",
" Downloading https://files.pythonhosted.org/packages/68/42/6309f3871b2f8361764ac5b2fe6719f9c6e6561d9307d8cecda319cf5843/jedi-0.14.0-py2.py3-none-any.whl (1.0MB)",
"Installing collected packages: jedi",
"Successfully installed jedi-0.14.0",
"2019/07/04 22:03:15 Destroy() [SB 4]",
"2019/07/04 22:03:15 kill all procs in CG [SOCK 4]",
"2019/07/04 22:03:15 waiting for 1 procs in cg-3 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:15 unmount and remove dirs [SOCK 4]",
"2019/07/04 22:03:15 run pip install idna from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/idna on host",
"2019/07/04 22:03:15 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/idna, )...",
"2019/07/04 22:03:15 ...returns &{0xc0002034a0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:15 Channel() [SB 5]",
"Collecting idna",
" Downloading https://files.pythonhosted.org/packages/14/2c/cd551d81dbe15200be1cf41cd03869a46fe7226e7450af7a6545bfc474c9/idna-2.8-py2.py3-none-any.whl (58kB)",
"Installing collected packages: idna",
"Successfully installed idna-2.8",
"2019/07/04 22:03:15 Destroy() [SB 5]",
"2019/07/04 22:03:15 kill all procs in CG [SOCK 5]",
"2019/07/04 22:03:15 waiting for 1 procs in cg-4 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:15 unmount and remove dirs [SOCK 5]",
"2019/07/04 22:03:15 run pip install chardet from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/chardet on host",
"2019/07/04 22:03:15 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/chardet, )...",
"2019/07/04 22:03:16 ...returns &{0xc00022a0c0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:16 Channel() [SB 6]",
"Collecting chardet",
" Using cached https://files.pythonhosted.org/packages/bc/a9/01ffebfb562e4274b6487b4bb1ddec7ca55ec7510b22e4c51f14098443b8/chardet-3.0.4-py2.py3-none-any.whl",
"Installing collected packages: chardet",
"Successfully installed chardet-3.0.4",
"2019/07/04 22:03:16 Destroy() [SB 6]",
"2019/07/04 22:03:16 kill all procs in CG [SOCK 6]",
"2019/07/04 22:03:16 waiting for 1 procs in cg-5 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:16 unmount and remove dirs [SOCK 6]",
"2019/07/04 22:03:16 run pip install certifi from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/certifi on host",
"2019/07/04 22:03:16 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/certifi, )...",
"2019/07/04 22:03:16 ...returns &{0xc00022acc0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:16 Channel() [SB 7]",
"Collecting certifi",
" Using cached https://files.pythonhosted.org/packages/69/1b/b853c7a9d4f6a6d00749e94eb6f3a041e342a885b87340b79c1ef73e3a78/certifi-2019.6.16-py2.py3-none-any.whl",
"Installing collected packages: certifi",
"Successfully installed certifi-2019.6.16",
"2019/07/04 22:03:17 Destroy() [SB 7]",
"2019/07/04 22:03:17 kill all procs in CG [SOCK 7]",
"2019/07/04 22:03:17 waiting for 1 procs in cg-6 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:17 unmount and remove dirs [SOCK 7]",
"2019/07/04 22:03:17 run pip install requests from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/requests on host",
"2019/07/04 22:03:17 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/requests, )...",
"2019/07/04 22:03:17 ...returns &{0xc00022b8c0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:17 Channel() [SB 8]",
"Collecting requests",
" Using cached https://files.pythonhosted.org/packages/51/bd/23c926cd341ea6b7dd0b2a00aba99ae0f828be89d72b2190f27c11d4b7fb/requests-2.22.0-py2.py3-none-any.whl",
"Installing collected packages: requests",
"Successfully installed requests-2.22.0",
"2019/07/04 22:03:17 Destroy() [SB 8]",
"2019/07/04 22:03:17 kill all procs in CG [SOCK 8]",
"2019/07/04 22:03:17 waiting for 1 procs in cg-7 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:03:17 unmount and remove dirs [SOCK 8]",
"2019/07/04 22:03:17 increase instances to 1 [FUNC install]",
"2019/07/04 22:03:17 .Create(&{0xc0001a9500 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/2-install, /root/open-lambda/test-dir/worker/scratch/func-install-1003, &{[parso jedi idna chardet certifi requests] [parso jedi idna chardet certifi requests urllib3]})...",
"2019/07/04 22:03:17 fork(&{0xc000082690 9 /root/open-lambda/test-dir/worker/sock-handlers/9 /root/open-lambda/test-dir/worker/lambda_code/2-install /root/open-lambda/test-dir/worker/scratch/func-install-1003 0xc00000f340}) [SB 1]",
"2019/07/04 22:03:17 ...returns &{0xc000240540 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:17 Channel() [SB 9]",
"2019/07/04 22:03:18 Pause() [SB 9]",
"2019/07/04 22:03:18 Receive request to /stats",
"2019/07/04 22:03:18 Receive request to /run/install2",
"2019/07/04 22:03:18 debug: LambdaFunc.Task() runs on goroutine 63 [FUNC install2]",
"2019/07/04 22:03:18 skip installing parso, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing jedi, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing idna, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing chardet, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing certifi, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing requests, already installed during this run of OL",
"2019/07/04 22:03:18 increase instances to 1 [FUNC install2]",
"2019/07/04 22:03:18 .Create(&{0xc0001a9500 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/3-install2, /root/open-lambda/test-dir/worker/scratch/func-install2-1004, &{[parso jedi idna chardet certifi requests] [parso jedi idna chardet certifi requests urllib3]})...",
"2019/07/04 22:03:18 fork(&{0xc000082690 10 /root/open-lambda/test-dir/worker/sock-handlers/10 /root/open-lambda/test-dir/worker/lambda_code/3-install2 /root/open-lambda/test-dir/worker/scratch/func-install2-1004 0xc00000f360}) [SB 1]",
"2019/07/04 22:03:18 ...returns &{0xc000241b00 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:18 Channel() [SB 10]",
"2019/07/04 22:03:18 Pause() [SB 10]",
"2019/07/04 22:03:18 Receive request to /stats",
"2019/07/04 22:03:18 Receive request to /run/install3",
"2019/07/04 22:03:18 debug: LambdaFunc.Task() runs on goroutine 75 [FUNC install3]",
"2019/07/04 22:03:18 skip installing parso, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing jedi, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing idna, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing chardet, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing certifi, already installed during this run of OL",
"2019/07/04 22:03:18 skip installing requests, already installed during this run of OL",
"2019/07/04 22:03:18 run pip install simplejson from a new Sandbox to /root/open-lambda/test-dir/lambda/packages/simplejson on host",
"2019/07/04 22:03:18 .Create(, true, /root/open-lambda/test-dir/worker/admin-lambdas/pip-install, /root/open-lambda/test-dir/lambda/packages/simplejson, )...",
"2019/07/04 22:03:18 ...returns &{0xc000277080 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:03:18 Channel() [SB 11]",
"Collecting simplejson",
" Downloading https://files.pythonhosted.org/packages/e3/24/c35fb1c1c315fc0fffe61ea00d3f88e85469004713dab488dee4f35b0aff/simplejson-3.16.0.tar.gz (81kB)",
"Building wheels for collected packages: simplejson",
" WARNING: Building wheel for simplejson failed: [Errno 30] Read-only file system: '/root/.cache/pip/wheels/5d'",
"Failed to build simplejson",
"Installing collected packages: simplejson",
" Running setup.py install for simplejson: started",
"Killed",
"2019/07/04 22:09:33 Destroy() [SB 11]",
"2019/07/04 22:09:33 kill all procs in CG [SOCK 11]",
"2019/07/04 22:09:33 waiting for 3 procs in cg-10 to die [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 unmount and remove dirs [SOCK 11]",
"2019/07/04 22:09:33 increase instances to 1 [FUNC install3]",
"2019/07/04 22:09:33 .Create(&{0xc0001a9500 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/4-install3, /root/open-lambda/test-dir/worker/scratch/func-install3-1005, &{[parso jedi idna chardet certifi requests simplejson] [parso jedi idna chardet certifi requests simplejson urllib3]})...",
"2019/07/04 22:09:33 fork(&{0xc000082690 12 /root/open-lambda/test-dir/worker/sock-handlers/12 /root/open-lambda/test-dir/worker/lambda_code/4-install3 /root/open-lambda/test-dir/worker/scratch/func-install3-1005 0xc00000f3a0}) [SB 1]",
"2019/07/04 22:09:33 ...returns &{0xc000277e00 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:09:33 Channel() [SB 12]",
"ERROR:tornado.application:Uncaught exception POST /run/install3 (0.0.0.0)",
"HTTPServerRequest(protocol='http', host='localhost:5000', method='POST', uri='/run/install3', version='HTTP/1.1', remote_ip='0.0.0.0', headers={'Host': 'localhost:5000', 'User-Agent': 'python-requests/2.9.1', 'Content-Length': '2', 'Accept': '*/*', 'Accept-Encoding': 'gzip, deflate', 'X-Forwarded-For': '127.0.0.1'})",
"Traceback (most recent call last):",
" File \"/usr/local/lib/python3.6/dist-packages/tornado/web.py\", line 1510, in _execute",
" result = method(*self.path_args, **self.path_kwargs)",
" File \"sock2.py\", line 33, in post",
" import lambda_func",
" File \"/handler/lambda_func.py\", line 3, in ",
" import simplejson",
"ModuleNotFoundError: No module named 'simplejson'",
"2019/07/04 22:09:33 Pause() [SB 12]",
"2019/07/04 22:09:33 received kill signal, cleaning up",
"2019/07/04 22:09:33 Destroy() [SB 1]",
"2019/07/04 22:09:33 kill all procs in CG [SOCK 1]",
"2019/07/04 22:09:33 unmount and remove dirs [SOCK 1]",
"2019/07/04 22:09:33 SOCKPool.Cleanup: make sure all memory is free",
"2019/07/04 22:09:33 SOCKPool.Cleanup: memory pool emptied",
"2019/07/04 22:09:33 received shutdown request [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 empty queues and release CGs [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/blkio/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/cpu/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/devices/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/freezer/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/hugetlb/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/memory/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/perf_event/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/systemd/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/pids/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"Kill function: echo2019/07/04 22:09:33 Destroy() [SB 2]",
"2019/07/04 22:09:33 kill all procs in CG [SOCK 2]",
"2019/07/04 22:09:33 unmount and remove dirs [SOCK 2]",
"Kill function: install2019/07/04 22:09:33 Destroy() [SB 9]",
"2019/07/04 22:09:33 kill all procs in CG [SOCK 9]",
"2019/07/04 22:09:33 unmount and remove dirs [SOCK 9]",
"Kill function: install22019/07/04 22:09:33 Destroy() [SB 10]",
"2019/07/04 22:09:33 kill all procs in CG [SOCK 10]",
"2019/07/04 22:09:33 unmount and remove dirs [SOCK 10]",
"Kill function: install32019/07/04 22:09:33 Destroy() [SB 12]",
"2019/07/04 22:09:33 kill all procs in CG [SOCK 12]",
"2019/07/04 22:09:33 unmount and remove dirs [SOCK 12]",
"2019/07/04 22:09:33 SOCKPool.Cleanup: make sure all memory is free",
"2019/07/04 22:09:33 SOCKPool.Cleanup: memory pool emptied",
"2019/07/04 22:09:33 received shutdown request [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 empty queues and release CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:09:33 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:09:33 remove worker.pid",
"2019/07/04 22:09:33 exiting",
""
]
}
POP conf: {'import_cache_mb': 250, 'handler_cache_mb': 250}
PUSH conf: {'sandbox': 'docker', 'import_cache_mb': 0, 'handler_cache_mb': 100}
========================================
smoke_tests
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=7869, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 7869\n'
{
"test": "smoke_tests",
"params": {},
"pass": true,
"seconds": 21.11687445640564,
"total_seconds": 22.444127082824707,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 22,
"Create():ms.avg": 829,
"Create():ms.cnt": 11,
"Destroy():ms.avg": 284,
"Destroy():ms.cnt": 22,
"Pause():ms.avg": 28,
"Pause():ms.cnt": 8,
"pip-install:ms.avg": 2203,
"pip-install:ms.cnt": 7
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 0,
"pip_mirror": "",
"server_mode": "lambda",
"sandbox": "docker",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"registry": "/root/open-lambda/test-registry",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 5000,
"handler_cache_mb": 100,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [],
"worker_tail": [
"Kill function: install22019/07/04 22:09:55 Destroy() [SB 8]",
"2019/07/04 22:09:55 Destroy() [SB 8]",
"Kill function: install32019/07/04 22:09:56 Destroy() [SB 10]",
"2019/07/04 22:09:56 Destroy() [SB 10]",
"Kill function: echo2019/07/04 22:09:56 Destroy() [SB 0]",
"2019/07/04 22:09:56 Destroy() [SB 0]",
"2019/07/04 22:09:56 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:09:56 remove worker.pid",
"2019/07/04 22:09:56 exiting",
""
]
}
POP conf: {'sandbox': 'docker', 'import_cache_mb': 0, 'handler_cache_mb': 100}
PUSH conf: {'sandbox': 'docker', 'import_cache_mb': 0, 'handler_cache_mb': 250}
========================================
smoke_tests
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=10565, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 10565\n'
{
"test": "smoke_tests",
"params": {},
"pass": true,
"seconds": 14.223451137542725,
"total_seconds": 15.149529457092285,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 22,
"Create():ms.avg": 589,
"Create():ms.cnt": 11,
"Destroy():ms.avg": 183,
"Destroy():ms.cnt": 22,
"Pause():ms.avg": 29,
"Pause():ms.cnt": 8,
"pip-install:ms.avg": 1645,
"pip-install:ms.cnt": 7
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/root/open-lambda/test-registry",
"sandbox": "docker",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 250,
"worker_port": "5000",
"import_cache_mb": 0,
"server_mode": "lambda",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [],
"worker_tail": [
"Kill function: install2019/07/04 22:10:11 Destroy() [SB 7]",
"2019/07/04 22:10:11 Destroy() [SB 7]",
"Kill function: install22019/07/04 22:10:11 Destroy() [SB 8]",
"2019/07/04 22:10:11 Destroy() [SB 8]",
"Kill function: install32019/07/04 22:10:11 Destroy() [SB 10]",
"2019/07/04 22:10:11 Destroy() [SB 10]",
"2019/07/04 22:10:11 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:10:11 remove worker.pid",
"2019/07/04 22:10:11 exiting",
""
]
}
POP conf: {'sandbox': 'docker', 'import_cache_mb': 0, 'handler_cache_mb': 250}
========================================
fork_bomb
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=13261, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 13261\n'
{
"test": "fork_bomb",
"params": {},
"pass": true,
"seconds": 0.07770156860351562,
"total_seconds": 0.30737948417663574,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 1,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 2,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 2,
"Create()/fork-proc:ms.avg": 3,
"Create()/fork-proc:ms.cnt": 1,
"Create()/fresh-proc:ms.avg": 144,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 2,
"Create()/make-root-fs:ms.cnt": 2,
"Create():ms.avg": 75,
"Create():ms.cnt": 2,
"Destroy()/detach-root:ms.avg": 1,
"Destroy()/detach-root:ms.cnt": 2,
"Destroy()/kill-procs:ms.avg": 0,
"Destroy()/kill-procs:ms.cnt": 2,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 2,
"Destroy():ms.avg": 2,
"Destroy():ms.cnt": 2,
"Pause():ms.avg": 4,
"Pause():ms.cnt": 1,
"fork():ms.avg": 3,
"fork():ms.cnt": 1,
"forkRequest:ms.avg": 3,
"forkRequest:ms.cnt": 1,
"move-to-cg-after-fork:ms.avg": 0,
"move-to-cg-after-fork:ms.cnt": 1
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 239,
"pip_mirror": "",
"server_mode": "lambda",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"registry": "/root/open-lambda/test-registry",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 5000,
"handler_cache_mb": 239,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [],
"worker_tail": [
"2019/07/04 22:10:11 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:11 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:11 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:11 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:11 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:11 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:11 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:10:11 remove worker.pid",
"2019/07/04 22:10:11 exiting",
""
]
}
========================================
max_mem_alloc
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=13304, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 13304\n'
{
"test": "max_mem_alloc",
"params": {},
"pass": true,
"seconds": 0.8374347686767578,
"total_seconds": 1.071457862854004,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 1,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 2,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 2,
"Create()/fork-proc:ms.avg": 7,
"Create()/fork-proc:ms.cnt": 1,
"Create()/fresh-proc:ms.avg": 142,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 4,
"Create()/make-root-fs:ms.cnt": 2,
"Create():ms.avg": 79,
"Create():ms.cnt": 2,
"Destroy()/detach-root:ms.avg": 1,
"Destroy()/detach-root:ms.cnt": 2,
"Destroy()/kill-procs:ms.avg": 0,
"Destroy()/kill-procs:ms.cnt": 2,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 2,
"Destroy():ms.avg": 2,
"Destroy():ms.cnt": 2,
"Pause():ms.avg": 4,
"Pause():ms.cnt": 1,
"fork():ms.avg": 7,
"fork():ms.cnt": 1,
"forkRequest:ms.avg": 6,
"forkRequest:ms.cnt": 1,
"move-to-cg-after-fork:ms.avg": 1,
"move-to-cg-after-fork:ms.cnt": 1
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 239,
"pip_mirror": "",
"server_mode": "lambda",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"registry": "/root/open-lambda/test-registry",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 5000,
"handler_cache_mb": 239,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [],
"worker_tail": [
"2019/07/04 22:10:12 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:12 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:12 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:12 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:12 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:12 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:12 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:10:12 remove worker.pid",
"2019/07/04 22:10:12 exiting",
""
]
}
PUSH conf: {'import_cache_mb': 0, 'sock_cgroups': {'max_mem_mb': 250}, 'handler_cache_mb': 500}
========================================
numpy_test
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=13387, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 13387\n'
{
"test": "numpy_test",
"params": {},
"pass": true,
"seconds": 10.563190460205078,
"total_seconds": 10.81367564201355,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 5,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 5,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 5,
"Create()/fresh-proc:ms.avg": 153,
"Create()/fresh-proc:ms.cnt": 5,
"Create()/make-root-fs:ms.avg": 2,
"Create()/make-root-fs:ms.cnt": 5,
"Create():ms.avg": 156,
"Create():ms.cnt": 5,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 5,
"Destroy()/kill-procs:ms.avg": 2,
"Destroy()/kill-procs:ms.cnt": 5,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 5,
"Destroy():ms.avg": 3,
"Destroy():ms.cnt": 6,
"Pause():ms.avg": 3,
"Pause():ms.cnt": 3,
"evict:ms.avg": 8,
"evict:ms.cnt": 1,
"pip-install:ms.avg": 4842,
"pip-install:ms.cnt": 2
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 0,
"pip_mirror": "",
"server_mode": "lambda",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 250
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"registry": "/root/open-lambda/test-registry",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 5000,
"handler_cache_mb": 500,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [],
"worker_tail": [
"2019/07/04 22:10:23 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:23 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:23 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:23 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:23 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:23 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:23 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:10:23 remove worker.pid",
"2019/07/04 22:10:23 exiting",
""
]
}
POP conf: {'import_cache_mb': 0, 'sock_cgroups': {'max_mem_mb': 250}, 'handler_cache_mb': 500}
POP conf: {'registry': '/root/open-lambda/test-registry'}
PUSH conf: {'server_mode': 'sock'}
========================================
sock_churn {'seconds': 15, 'fork': True, 'baseline': 0, 'procs': 1}
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=13448, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 13448\n'
{
"test": "sock_churn",
"params": {
"seconds": 15,
"fork": true,
"baseline": 0,
"procs": 1
},
"pass": true,
"seconds": 15.187789916992188,
"total_seconds": 15.416234016418457,
"stats": {
"sandboxes_per_sec": 48.666666666666664
},
"ol-stats": {
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 731,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 731,
"Create()/fork-proc:ms.avg": 6,
"Create()/fork-proc:ms.cnt": 730,
"Create()/fresh-proc:ms.avg": 134,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 2,
"Create()/make-root-fs:ms.cnt": 731,
"Create():ms.avg": 9,
"Create():ms.cnt": 731,
"Destroy()/detach-root:ms.avg": 1,
"Destroy()/detach-root:ms.cnt": 731,
"Destroy()/kill-procs:ms.avg": 1,
"Destroy()/kill-procs:ms.cnt": 731,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 731,
"Destroy():ms.avg": 1,
"Destroy():ms.cnt": 1461,
"fork():ms.avg": 6,
"fork():ms.cnt": 730,
"forkRequest:ms.avg": 5,
"forkRequest:ms.cnt": 730,
"move-to-cg-after-fork:ms.avg": 0,
"move-to-cg-after-fork:ms.cnt": 730
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/root/open-lambda/test-dir/registry",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 239,
"worker_port": "5000",
"import_cache_mb": 239,
"server_mode": "sock",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [],
"worker_tail": [
"2019/07/04 22:10:39 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:39 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:39 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:39 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:39 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:39 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:39 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:10:39 remove worker.pid",
"2019/07/04 22:10:39 exiting",
""
]
}
========================================
sock_churn {'seconds': 15, 'fork': True, 'baseline': 0, 'procs': 15}
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=16399, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 16399\n'
{
"test": "sock_churn",
"params": {
"seconds": 15,
"fork": true,
"baseline": 0,
"procs": 15
},
"pass": true,
"seconds": 15.402562379837036,
"total_seconds": 15.63777470588684,
"stats": {
"sandboxes_per_sec": 48.6
},
"ol-stats": {
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 730,
"Create()/acquire-mem:ms.avg": 93,
"Create()/acquire-mem:ms.cnt": 730,
"Create()/fork-proc:ms.avg": 40,
"Create()/fork-proc:ms.cnt": 729,
"Create()/fresh-proc:ms.avg": 132,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 2,
"Create()/make-root-fs:ms.cnt": 730,
"Create():ms.avg": 138,
"Create():ms.cnt": 730,
"Destroy()/detach-root:ms.avg": 2,
"Destroy()/detach-root:ms.cnt": 730,
"Destroy()/kill-procs:ms.avg": 6,
"Destroy()/kill-procs:ms.cnt": 730,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 730,
"Destroy():ms.avg": 5,
"Destroy():ms.cnt": 1459,
"fork():ms.avg": 40,
"fork():ms.cnt": 729,
"forkRequest:ms.avg": 10,
"forkRequest:ms.cnt": 729,
"move-to-cg-after-fork:ms.avg": 3,
"move-to-cg-after-fork:ms.cnt": 729
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/root/open-lambda/test-dir/registry",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 239,
"worker_port": "5000",
"import_cache_mb": 239,
"server_mode": "sock",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [],
"worker_tail": [
"2019/07/04 22:10:54 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:54 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:54 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:54 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:54 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:54 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:10:54 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:10:54 remove worker.pid",
"2019/07/04 22:10:54 exiting",
""
]
}
POP conf: {'server_mode': 'sock'}
PUSH conf: {'sandbox': 'sock', 'registry': '/tmp/tmpuy_2dlg1', 'registry_cache_ms': 3000}
========================================
update_code
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=19366, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 19366\n'
{
"test": "update_code",
"params": {},
"pass": true,
"seconds": 6.02485990524292,
"total_seconds": 6.265734672546387,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 3,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 4,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 4,
"Create()/fork-proc:ms.avg": 8,
"Create()/fork-proc:ms.cnt": 3,
"Create()/fresh-proc:ms.avg": 142,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 3,
"Create()/make-root-fs:ms.cnt": 4,
"Create():ms.avg": 45,
"Create():ms.cnt": 4,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 4,
"Destroy()/kill-procs:ms.avg": 0,
"Destroy()/kill-procs:ms.cnt": 4,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 4,
"Destroy():ms.avg": 1,
"Destroy():ms.cnt": 4,
"Pause():ms.avg": 0,
"Pause():ms.cnt": 1705,
"Unpause():ms.avg": 0,
"Unpause():ms.cnt": 1702,
"fork():ms.avg": 8,
"fork():ms.cnt": 3,
"forkRequest:ms.avg": 6,
"forkRequest:ms.cnt": 3,
"move-to-cg-after-fork:ms.avg": 1,
"move-to-cg-after-fork:ms.cnt": 3
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 239,
"pip_mirror": "",
"server_mode": "lambda",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"registry": "/tmp/tmpuy_2dlg1",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 3000,
"handler_cache_mb": 239,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [],
"worker_tail": [
"2019/07/04 22:11:01 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:01 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:01 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:01 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:01 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:01 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:01 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:11:01 remove worker.pid",
"2019/07/04 22:11:01 exiting",
""
]
}
POP conf: {'sandbox': 'sock', 'registry': '/tmp/tmpuy_2dlg1', 'registry_cache_ms': 3000}
PUSH conf: {'sandbox': 'sock', 'import_cache_mb': 250, 'handler_cache_mb': 250, 'registry': '/root/open-lambda/test-registry'}
========================================
stress_one_lambda {'seconds': 15, 'procs': 1}
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=19409, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 19409\n'
{
"test": "stress_one_lambda",
"params": {
"seconds": 15,
"procs": 1
},
"pass": true,
"seconds": 15.046573162078857,
"total_seconds": 15.277432918548584,
"stats": {
"reqs_per_sec": 290.8
},
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 3,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 4,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 4,
"Create()/fork-proc:ms.avg": 9,
"Create()/fork-proc:ms.cnt": 3,
"Create()/fresh-proc:ms.avg": 147,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 3,
"Create()/make-root-fs:ms.cnt": 4,
"Create():ms.avg": 47,
"Create():ms.cnt": 4,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 4,
"Destroy()/kill-procs:ms.avg": 0,
"Destroy()/kill-procs:ms.cnt": 4,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 4,
"Destroy():ms.avg": 1,
"Destroy():ms.cnt": 4,
"Pause():ms.avg": 0,
"Pause():ms.cnt": 4362,
"Unpause():ms.avg": 0,
"Unpause():ms.cnt": 4359,
"fork():ms.avg": 9,
"fork():ms.cnt": 3,
"forkRequest:ms.avg": 7,
"forkRequest:ms.cnt": 3,
"move-to-cg-after-fork:ms.avg": 1,
"move-to-cg-after-fork:ms.cnt": 3
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/root/open-lambda/test-registry",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 250,
"worker_port": "5000",
"import_cache_mb": 250,
"server_mode": "lambda",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [],
"worker_tail": [
"2019/07/04 22:11:16 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:16 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:16 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:16 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:16 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:16 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:16 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:11:16 remove worker.pid",
"2019/07/04 22:11:16 exiting",
""
]
}
========================================
stress_one_lambda {'seconds': 15, 'procs': 2}
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=19456, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 19456\n'
{
"test": "stress_one_lambda",
"params": {
"seconds": 15,
"procs": 2
},
"pass": true,
"seconds": 15.044992446899414,
"total_seconds": 15.28028130531311,
"stats": {
"reqs_per_sec": 290.53333333333336
},
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 3,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 4,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 4,
"Create()/fork-proc:ms.avg": 7,
"Create()/fork-proc:ms.cnt": 3,
"Create()/fresh-proc:ms.avg": 154,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 2,
"Create()/make-root-fs:ms.cnt": 4,
"Create():ms.avg": 47,
"Create():ms.cnt": 4,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 4,
"Destroy()/kill-procs:ms.avg": 0,
"Destroy()/kill-procs:ms.cnt": 4,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 4,
"Destroy():ms.avg": 1,
"Destroy():ms.cnt": 4,
"Pause():ms.avg": 0,
"Pause():ms.cnt": 3966,
"Unpause():ms.avg": 0,
"Unpause():ms.cnt": 3963,
"fork():ms.avg": 7,
"fork():ms.cnt": 3,
"forkRequest:ms.avg": 6,
"forkRequest:ms.cnt": 3,
"move-to-cg-after-fork:ms.avg": 0,
"move-to-cg-after-fork:ms.cnt": 3
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/root/open-lambda/test-registry",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 250,
"worker_port": "5000",
"import_cache_mb": 250,
"server_mode": "lambda",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [],
"worker_tail": [
"2019/07/04 22:11:31 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:31 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:31 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:31 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:31 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:31 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:31 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:11:31 remove worker.pid",
"2019/07/04 22:11:31 exiting",
""
]
}
PUSH conf: {'import_cache_mb': 100, 'handler_cache_mb': 500}
========================================
stress_one_lambda {'seconds': 15, 'procs': 8}
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=19504, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 19504\n'
{
"test": "stress_one_lambda",
"params": {
"seconds": 15,
"procs": 8
},
"pass": true,
"seconds": 15.073072671890259,
"total_seconds": 15.302305459976196,
"stats": {
"reqs_per_sec": 266.93333333333334
},
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 3,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 4,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 4,
"Create()/fork-proc:ms.avg": 8,
"Create()/fork-proc:ms.cnt": 3,
"Create()/fresh-proc:ms.avg": 191,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 3,
"Create()/make-root-fs:ms.cnt": 4,
"Create():ms.avg": 58,
"Create():ms.cnt": 4,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 4,
"Destroy()/kill-procs:ms.avg": 0,
"Destroy()/kill-procs:ms.cnt": 4,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 4,
"Destroy():ms.avg": 2,
"Destroy():ms.cnt": 4,
"Pause():ms.avg": 0,
"Pause():ms.cnt": 3080,
"Unpause():ms.avg": 0,
"Unpause():ms.cnt": 3077,
"fork():ms.avg": 8,
"fork():ms.cnt": 3,
"forkRequest:ms.avg": 7,
"forkRequest:ms.cnt": 3,
"move-to-cg-after-fork:ms.avg": 1,
"move-to-cg-after-fork:ms.cnt": 3
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/root/open-lambda/test-registry",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 500,
"worker_port": "5000",
"import_cache_mb": 100,
"server_mode": "lambda",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [],
"worker_tail": [
"2019/07/04 22:11:46 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:46 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:46 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:46 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:46 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:46 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:46 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:11:46 remove worker.pid",
"2019/07/04 22:11:46 exiting",
""
]
}
POP conf: {'import_cache_mb': 100, 'handler_cache_mb': 500}
POP conf: {'sandbox': 'sock', 'import_cache_mb': 250, 'handler_cache_mb': 250, 'registry': '/root/open-lambda/test-registry'}
PUSH conf: {'sandbox': 'sock', 'import_cache_mb': 250, 'handler_cache_mb': 250}
PUSH conf: {'registry': '/tmp/tmpl8fh6cbo'}
========================================
call_each_once_exec {'alloc_mb': 1, 'lambda_count': 100}
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=19559, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 19559\n'
{
"test": "call_each_once_exec",
"params": {
"alloc_mb": 1,
"lambda_count": 100
},
"pass": false,
"seconds": null,
"total_seconds": 0.7567539215087891,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 21,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 22,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 22,
"Create()/fork-proc:ms.avg": 8,
"Create()/fork-proc:ms.cnt": 21,
"Create()/fresh-proc:ms.avg": 141,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 0,
"Create()/make-root-fs:ms.cnt": 22,
"Create():ms.avg": 15,
"Create():ms.cnt": 22,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 22,
"Destroy()/kill-procs:ms.avg": 1,
"Destroy()/kill-procs:ms.cnt": 22,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 22,
"Destroy():ms.avg": 1,
"Destroy():ms.cnt": 22,
"Pause():ms.avg": 4,
"Pause():ms.cnt": 21,
"fork():ms.avg": 8,
"fork():ms.cnt": 21,
"forkRequest:ms.avg": 5,
"forkRequest:ms.cnt": 21,
"move-to-cg-after-fork:ms.avg": 1,
"move-to-cg-after-fork:ms.cnt": 21
},
"conf": {
"Skip_pull_existing": false,
"import_cache_mb": 250,
"pip_mirror": "",
"server_mode": "lambda",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"worker_port": "5000",
"worker_dir": "/root/open-lambda/test-dir/worker",
"registry": "/tmp/tmpl8fh6cbo",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"registry_cache_ms": 5000,
"handler_cache_mb": 250,
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"sandbox_config": {}
},
"errors": [
[
"Traceback (most recent call last):",
" File \"test.py\", line 76, in wrapper",
" rv = fn(**kwargs)",
" File \"test.py\", line 258, in call_each_once_exec",
" r.raise_for_status()",
" File \"/usr/lib/python3/dist-packages/requests/models.py\", line 840, in raise_for_status",
" raise HTTPError(http_error_msg, response=self)",
"requests.exceptions.HTTPError: 502 Server Error: Bad Gateway for url: http://localhost:5000/run/L20",
""
]
],
"worker_tail": [
"using existing OL directory at /root/open-lambda/test-dir",
"2019/07/04 22:11:47 save PID 19559 to file /root/open-lambda/test-dir/worker/worker.pid",
"2019/07/04 22:11:47 Start Lambda Server",
"2019/07/04 22:11:47 Create SandboxPool",
"2019/07/04 22:11:47 create /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 Create ModulePuller",
"2019/07/04 22:11:47 Create HandlerPuller",
"2019/07/04 22:11:47 Create ImportCache",
"2019/07/04 22:11:47 create /sys/fs/cgroup/blkio/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/cpu/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/devices/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/freezer/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/hugetlb/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/memory/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/perf_event/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/systemd/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/pids/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 Setups Handlers",
"2019/07/04 22:11:47 Execute handler by POSTing to localhost:5000/run/",
"2019/07/04 22:11:47 Get status by sending request to localhost:5000/status",
"2019/07/04 22:11:47 start creating/serving CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 start creating/serving CGs [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 .Create(, false, , /root/open-lambda/test-dir/worker/scratch/import-cache-1001, )...",
"2019/07/04 22:11:47 Receive request to /pid",
"2019/07/04 22:11:47 Receive request to /run/L0",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 22 [FUNC L0]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L0]",
"2019/07/04 22:11:47 ...returns &{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/1-L0, /root/open-lambda/test-dir/worker/scratch/func-L0-1002, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 2 /root/open-lambda/test-dir/worker/sock-handlers/2 /root/open-lambda/test-dir/worker/lambda_code/1-L0 /root/open-lambda/test-dir/worker/scratch/func-L0-1002 0xc00000f260}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0001c45a0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 2]",
"2019/07/04 22:11:47 Pause() [SB 2]",
"2019/07/04 22:11:47 Receive request to /run/L1",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 33 [FUNC L1]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L1]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/2-L1, /root/open-lambda/test-dir/worker/scratch/func-L1-1003, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 3 /root/open-lambda/test-dir/worker/sock-handlers/3 /root/open-lambda/test-dir/worker/lambda_code/2-L1 /root/open-lambda/test-dir/worker/scratch/func-L1-1003 0xc00000f280}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0001c5aa0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 3]",
"2019/07/04 22:11:47 Pause() [SB 3]",
"2019/07/04 22:11:47 Receive request to /run/L2",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 43 [FUNC L2]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L2]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/3-L2, /root/open-lambda/test-dir/worker/scratch/func-L2-1004, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 4 /root/open-lambda/test-dir/worker/sock-handlers/4 /root/open-lambda/test-dir/worker/lambda_code/3-L2 /root/open-lambda/test-dir/worker/scratch/func-L2-1004 0xc00000f2a0}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0001faf60 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 4]",
"2019/07/04 22:11:47 Pause() [SB 4]",
"2019/07/04 22:11:47 Receive request to /run/L3",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 53 [FUNC L3]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L3]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/4-L3, /root/open-lambda/test-dir/worker/scratch/func-L3-1005, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 5 /root/open-lambda/test-dir/worker/sock-handlers/5 /root/open-lambda/test-dir/worker/lambda_code/4-L3 /root/open-lambda/test-dir/worker/scratch/func-L3-1005 0xc00000f2c0}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc000230420 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 5]",
"2019/07/04 22:11:47 Pause() [SB 5]",
"2019/07/04 22:11:47 Receive request to /run/L4",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 63 [FUNC L4]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L4]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/5-L4, /root/open-lambda/test-dir/worker/scratch/func-L4-1006, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 6 /root/open-lambda/test-dir/worker/sock-handlers/6 /root/open-lambda/test-dir/worker/lambda_code/5-L4 /root/open-lambda/test-dir/worker/scratch/func-L4-1006 0xc00000f2e0}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc000231860 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 6]",
"2019/07/04 22:11:47 Pause() [SB 6]",
"2019/07/04 22:11:47 Receive request to /run/L5",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 73 [FUNC L5]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L5]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/6-L5, /root/open-lambda/test-dir/worker/scratch/func-L5-1007, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 7 /root/open-lambda/test-dir/worker/sock-handlers/7 /root/open-lambda/test-dir/worker/lambda_code/6-L5 /root/open-lambda/test-dir/worker/scratch/func-L5-1007 0xc00000f300}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc00025acc0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 7]",
"2019/07/04 22:11:47 Pause() [SB 7]",
"2019/07/04 22:11:47 Receive request to /run/L6",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 83 [FUNC L6]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L6]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/7-L6, /root/open-lambda/test-dir/worker/scratch/func-L6-1008, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 8 /root/open-lambda/test-dir/worker/sock-handlers/8 /root/open-lambda/test-dir/worker/lambda_code/7-L6 /root/open-lambda/test-dir/worker/scratch/func-L6-1008 0xc00000f320}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc000292180 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 8]",
"2019/07/04 22:11:47 Pause() [SB 8]",
"2019/07/04 22:11:47 Receive request to /run/L7",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 93 [FUNC L7]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L7]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/8-L7, /root/open-lambda/test-dir/worker/scratch/func-L7-1009, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 9 /root/open-lambda/test-dir/worker/sock-handlers/9 /root/open-lambda/test-dir/worker/lambda_code/8-L7 /root/open-lambda/test-dir/worker/scratch/func-L7-1009 0xc00000f340}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0002935c0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 9]",
"2019/07/04 22:11:47 Pause() [SB 9]",
"2019/07/04 22:11:47 Receive request to /run/L8",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 103 [FUNC L8]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L8]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/9-L8, /root/open-lambda/test-dir/worker/scratch/func-L8-1010, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 10 /root/open-lambda/test-dir/worker/sock-handlers/10 /root/open-lambda/test-dir/worker/lambda_code/9-L8 /root/open-lambda/test-dir/worker/scratch/func-L8-1010 0xc00000f360}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0002c2a80 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 10]",
"2019/07/04 22:11:47 Pause() [SB 10]",
"2019/07/04 22:11:47 Receive request to /run/L9",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 113 [FUNC L9]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L9]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/10-L9, /root/open-lambda/test-dir/worker/scratch/func-L9-1011, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 11 /root/open-lambda/test-dir/worker/sock-handlers/11 /root/open-lambda/test-dir/worker/lambda_code/10-L9 /root/open-lambda/test-dir/worker/scratch/func-L9-1011 0xc00000f380}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0002c3f20 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 11]",
"2019/07/04 22:11:47 Pause() [SB 11]",
"2019/07/04 22:11:47 Receive request to /run/L10",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 123 [FUNC L10]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L10]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/11-L10, /root/open-lambda/test-dir/worker/scratch/func-L10-1012, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 12 /root/open-lambda/test-dir/worker/sock-handlers/12 /root/open-lambda/test-dir/worker/lambda_code/11-L10 /root/open-lambda/test-dir/worker/scratch/func-L10-1012 0xc00000f3a0}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0002fd3e0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 12]",
"2019/07/04 22:11:47 Pause() [SB 12]",
"2019/07/04 22:11:47 Receive request to /run/L11",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 133 [FUNC L11]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L11]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/12-L11, /root/open-lambda/test-dir/worker/scratch/func-L11-1013, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 13 /root/open-lambda/test-dir/worker/sock-handlers/13 /root/open-lambda/test-dir/worker/lambda_code/12-L11 /root/open-lambda/test-dir/worker/scratch/func-L11-1013 0xc00000f3c0}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0003268a0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 13]",
"2019/07/04 22:11:47 Pause() [SB 13]",
"2019/07/04 22:11:47 Receive request to /run/L12",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 143 [FUNC L12]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L12]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/13-L12, /root/open-lambda/test-dir/worker/scratch/func-L12-1014, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 14 /root/open-lambda/test-dir/worker/sock-handlers/14 /root/open-lambda/test-dir/worker/lambda_code/13-L12 /root/open-lambda/test-dir/worker/scratch/func-L12-1014 0xc00000f3e0}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc000327d40 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 14]",
"2019/07/04 22:11:47 Pause() [SB 14]",
"2019/07/04 22:11:47 Receive request to /run/L13",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 153 [FUNC L13]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L13]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/14-L13, /root/open-lambda/test-dir/worker/scratch/func-L13-1015, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 15 /root/open-lambda/test-dir/worker/sock-handlers/15 /root/open-lambda/test-dir/worker/lambda_code/14-L13 /root/open-lambda/test-dir/worker/scratch/func-L13-1015 0xc00000f400}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc000355200 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 15]",
"2019/07/04 22:11:47 Pause() [SB 15]",
"2019/07/04 22:11:47 Receive request to /run/L14",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 163 [FUNC L14]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L14]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/15-L14, /root/open-lambda/test-dir/worker/scratch/func-L14-1016, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 16 /root/open-lambda/test-dir/worker/sock-handlers/16 /root/open-lambda/test-dir/worker/lambda_code/15-L14 /root/open-lambda/test-dir/worker/scratch/func-L14-1016 0xc00000f420}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0003926c0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 16]",
"2019/07/04 22:11:47 Pause() [SB 16]",
"2019/07/04 22:11:47 Receive request to /run/L15",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 173 [FUNC L15]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L15]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/16-L15, /root/open-lambda/test-dir/worker/scratch/func-L15-1017, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 17 /root/open-lambda/test-dir/worker/sock-handlers/17 /root/open-lambda/test-dir/worker/lambda_code/16-L15 /root/open-lambda/test-dir/worker/scratch/func-L15-1017 0xc00000f440}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc000393b60 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 17]",
"2019/07/04 22:11:47 Pause() [SB 17]",
"2019/07/04 22:11:47 Receive request to /run/L16",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 183 [FUNC L16]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L16]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/17-L16, /root/open-lambda/test-dir/worker/scratch/func-L16-1018, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 18 /root/open-lambda/test-dir/worker/sock-handlers/18 /root/open-lambda/test-dir/worker/lambda_code/17-L16 /root/open-lambda/test-dir/worker/scratch/func-L16-1018 0xc00000f460}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0003bf020 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 18]",
"2019/07/04 22:11:47 Pause() [SB 18]",
"2019/07/04 22:11:47 Receive request to /run/L17",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 193 [FUNC L17]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L17]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/18-L17, /root/open-lambda/test-dir/worker/scratch/func-L17-1019, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 19 /root/open-lambda/test-dir/worker/sock-handlers/19 /root/open-lambda/test-dir/worker/lambda_code/18-L17 /root/open-lambda/test-dir/worker/scratch/func-L17-1019 0xc00000fb80}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0003ea480 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 19]",
"2019/07/04 22:11:47 Pause() [SB 19]",
"2019/07/04 22:11:47 Receive request to /run/L18",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 203 [FUNC L18]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L18]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/19-L18, /root/open-lambda/test-dir/worker/scratch/func-L18-1020, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 20 /root/open-lambda/test-dir/worker/sock-handlers/20 /root/open-lambda/test-dir/worker/lambda_code/19-L18 /root/open-lambda/test-dir/worker/scratch/func-L18-1020 0xc0001ea240}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0003eb920 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 20]",
"2019/07/04 22:11:47 Pause() [SB 20]",
"2019/07/04 22:11:47 Receive request to /run/L19",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 213 [FUNC L19]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L19]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/20-L19, /root/open-lambda/test-dir/worker/scratch/func-L19-1021, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 21 /root/open-lambda/test-dir/worker/sock-handlers/21 /root/open-lambda/test-dir/worker/lambda_code/20-L19 /root/open-lambda/test-dir/worker/scratch/func-L19-1021 0xc0001ea8c0}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc00041ad80 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 21]",
"2019/07/04 22:11:47 Pause() [SB 21]",
"2019/07/04 22:11:47 Receive request to /run/L20",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 223 [FUNC L20]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L20]",
"2019/07/04 22:11:47 .Create(&{0xc00019d440 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/21-L20, /root/open-lambda/test-dir/worker/scratch/func-L20-1022, &{[] []})...",
"2019/07/04 22:11:47 fork(&{0xc000082690 22 /root/open-lambda/test-dir/worker/sock-handlers/22 /root/open-lambda/test-dir/worker/lambda_code/21-L20 /root/open-lambda/test-dir/worker/scratch/func-L20-1022 0xc0001eaf40}) [SB 1]",
"2019/07/04 22:11:47 ...returns &{0xc0004522a0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:47 Channel() [SB 22]",
"2019/07/04 22:11:47 http: proxy error: read unix @->/host/ol.sock: read: connection reset by peer",
"2019/07/04 22:11:47 Pause() [SB 22]",
"2019/07/04 22:11:47 received kill signal, cleaning up",
"2019/07/04 22:11:47 Destroy() [SB 1]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 1]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 1]",
"2019/07/04 22:11:47 SOCKPool.Cleanup: make sure all memory is free",
"2019/07/04 22:11:47 SOCKPool.Cleanup: memory pool emptied",
"2019/07/04 22:11:47 received shutdown request [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 empty queues and release CGs [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/blkio/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/cpu/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/devices/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/freezer/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/hugetlb/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/memory/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/perf_event/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/systemd/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/pids/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"Kill function: L152019/07/04 22:11:47 Destroy() [SB 17]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 17]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 17]",
"Kill function: L162019/07/04 22:11:47 Destroy() [SB 18]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 18]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 18]",
"Kill function: L92019/07/04 22:11:47 Destroy() [SB 11]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 11]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 11]",
"Kill function: L102019/07/04 22:11:47 Destroy() [SB 12]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 12]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 12]",
"Kill function: L72019/07/04 22:11:47 Destroy() [SB 9]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 9]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 9]",
"Kill function: L182019/07/04 22:11:47 Destroy() [SB 20]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 20]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 20]",
"Kill function: L192019/07/04 22:11:47 Destroy() [SB 21]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 21]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 21]",
"Kill function: L202019/07/04 22:11:47 Destroy() [SB 22]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 22]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 22]",
"Kill function: L42019/07/04 22:11:47 Destroy() [SB 6]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 6]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 6]",
"Kill function: L52019/07/04 22:11:47 Destroy() [SB 7]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 7]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 7]",
"Kill function: L22019/07/04 22:11:47 Destroy() [SB 4]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 4]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 4]",
"Kill function: L172019/07/04 22:11:47 Destroy() [SB 19]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 19]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 19]",
"Kill function: L32019/07/04 22:11:47 Destroy() [SB 5]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 5]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 5]",
"Kill function: L62019/07/04 22:11:47 Destroy() [SB 8]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 8]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 8]",
"Kill function: L82019/07/04 22:11:47 Destroy() [SB 10]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 10]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 10]",
"Kill function: L112019/07/04 22:11:47 Destroy() [SB 13]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 13]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 13]",
"Kill function: L122019/07/04 22:11:47 Destroy() [SB 14]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 14]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 14]",
"Kill function: L132019/07/04 22:11:47 Destroy() [SB 15]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 15]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 15]",
"Kill function: L02019/07/04 22:11:47 Destroy() [SB 2]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 2]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 2]",
"Kill function: L12019/07/04 22:11:47 Destroy() [SB 3]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 3]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 3]",
"Kill function: L142019/07/04 22:11:47 Destroy() [SB 16]",
"2019/07/04 22:11:47 kill all procs in CG [SOCK 16]",
"2019/07/04 22:11:47 unmount and remove dirs [SOCK 16]",
"2019/07/04 22:11:47 SOCKPool.Cleanup: make sure all memory is free",
"2019/07/04 22:11:47 SOCKPool.Cleanup: memory pool emptied",
"2019/07/04 22:11:47 received shutdown request [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 empty queues and release CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 remove /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 save stats to /root/open-lambda/test-dir/worker/stats.json",
"2019/07/04 22:11:47 remove worker.pid",
"2019/07/04 22:11:47 exiting",
""
]
}
POP conf: {'registry': '/tmp/tmpl8fh6cbo'}
PUSH conf: {'registry': '/tmp/tmp9l9mvihl'}
========================================
call_each_once_exec {'alloc_mb': 10, 'lambda_count': 1000}
========================================
RUN ./ol worker -p=test-dir --detach
b'using existing OL directory at /root/open-lambda/test-dir\nStarting worker: pid=19693, port=5000, log=/root/open-lambda/test-dir/worker.out\nready\n'
RUN ./ol kill -p=test-dir
b'Kill worker process with PID 19693\n'
{
"test": "call_each_once_exec",
"params": {
"alloc_mb": 10,
"lambda_count": 1000
},
"pass": false,
"seconds": null,
"total_seconds": 1.2547612190246582,
"stats": null,
"ol-stats": {
"Channel():ms.avg": 0,
"Channel():ms.cnt": 27,
"Create()/acquire-cgroup:ms.avg": 0,
"Create()/acquire-cgroup:ms.cnt": 28,
"Create()/acquire-mem:ms.avg": 0,
"Create()/acquire-mem:ms.cnt": 28,
"Create()/fork-proc:ms.avg": 7,
"Create()/fork-proc:ms.cnt": 27,
"Create()/fresh-proc:ms.avg": 161,
"Create()/fresh-proc:ms.cnt": 1,
"Create()/make-root-fs:ms.avg": 2,
"Create()/make-root-fs:ms.cnt": 28,
"Create():ms.avg": 15,
"Create():ms.cnt": 28,
"Destroy()/detach-root:ms.avg": 0,
"Destroy()/detach-root:ms.cnt": 28,
"Destroy()/kill-procs:ms.avg": 2,
"Destroy()/kill-procs:ms.cnt": 28,
"Destroy()/remove-root:ms.avg": 0,
"Destroy()/remove-root:ms.cnt": 28,
"Destroy():ms.avg": 2,
"Destroy():ms.cnt": 32,
"Pause():ms.avg": 10,
"Pause():ms.cnt": 27,
"evict:ms.avg": 3,
"evict:ms.cnt": 4,
"fork():ms.avg": 7,
"fork():ms.cnt": 27,
"forkRequest:ms.avg": 6,
"forkRequest:ms.cnt": 27,
"move-to-cg-after-fork:ms.avg": 0,
"move-to-cg-after-fork:ms.cnt": 27
},
"conf": {
"Skip_pull_existing": false,
"worker_dir": "/root/open-lambda/test-dir/worker",
"pip_mirror": "",
"registry": "/tmp/tmp9l9mvihl",
"sandbox": "sock",
"sock_cgroups": {
"max_procs": 10,
"max_mem_mb": 50
},
"handler_cache_mb": 250,
"worker_port": "5000",
"import_cache_mb": 250,
"server_mode": "lambda",
"SOCK_base_path": "/root/open-lambda/test-dir/lambda",
"sandbox_config": {},
"Pkgs_dir": "/root/open-lambda/test-dir/lambda/packages",
"docker_runtime": "",
"cluster_name": "/root/open-lambda/test-dir",
"registry_cache_ms": 5000
},
"errors": [
[
"Traceback (most recent call last):",
" File \"test.py\", line 76, in wrapper",
" rv = fn(**kwargs)",
" File \"test.py\", line 258, in call_each_once_exec",
" r.raise_for_status()",
" File \"/usr/lib/python3/dist-packages/requests/models.py\", line 840, in raise_for_status",
" raise HTTPError(http_error_msg, response=self)",
"requests.exceptions.HTTPError: 502 Server Error: Bad Gateway for url: http://localhost:5000/run/L26",
""
]
],
"worker_tail": [
"using existing OL directory at /root/open-lambda/test-dir",
"2019/07/04 22:11:47 save PID 19693 to file /root/open-lambda/test-dir/worker/worker.pid",
"2019/07/04 22:11:47 Start Lambda Server",
"2019/07/04 22:11:47 Create SandboxPool",
"2019/07/04 22:11:47 create /sys/fs/cgroup/blkio/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/cpu/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/devices/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/freezer/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/hugetlb/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/memory/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/perf_event/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/systemd/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/pids/worker-sock-handlers [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 Create ModulePuller",
"2019/07/04 22:11:47 Create HandlerPuller",
"2019/07/04 22:11:47 Create ImportCache",
"2019/07/04 22:11:47 create /sys/fs/cgroup/blkio/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/cpu/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/devices/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/freezer/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/hugetlb/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/memory/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/perf_event/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/systemd/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 create /sys/fs/cgroup/pids/worker-sock-cache [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 Setups Handlers",
"2019/07/04 22:11:47 Execute handler by POSTing to localhost:5000/run/",
"2019/07/04 22:11:47 Get status by sending request to localhost:5000/status",
"2019/07/04 22:11:47 start creating/serving CGs [CGROUP POOL worker-sock-handlers]",
"2019/07/04 22:11:47 start creating/serving CGs [CGROUP POOL worker-sock-cache]",
"2019/07/04 22:11:47 .Create(, false, , /root/open-lambda/test-dir/worker/scratch/import-cache-1001, )...",
"2019/07/04 22:11:47 Receive request to /pid",
"2019/07/04 22:11:47 Receive request to /run/L0",
"2019/07/04 22:11:47 debug: LambdaFunc.Task() runs on goroutine 22 [FUNC L0]",
"2019/07/04 22:11:47 increase instances to 1 [FUNC L0]",
"2019/07/04 22:11:48 ...returns &{0xc0002821e0 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:48 .Create(&{0xc0002821e0 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/1-L0, /root/open-lambda/test-dir/worker/scratch/func-L0-1002, &{[] []})...",
"2019/07/04 22:11:48 fork(&{0xc000082690 2 /root/open-lambda/test-dir/worker/sock-handlers/2 /root/open-lambda/test-dir/worker/lambda_code/1-L0 /root/open-lambda/test-dir/worker/scratch/func-L0-1002 0xc00000f240}) [SB 1]",
"2019/07/04 22:11:48 ...returns &{0xc000283320 {0 0} false [0x8193c0 0x81a800]}, ",
"2019/07/04 22:11:48 Channel() [SB 2]",
"2019/07/04 22:11:48 Pause() [SB 2]",
"2019/07/04 22:11:48 Receive request to /run/L1",
"2019/07/04 22:11:48 debug: LambdaFunc.Task() runs on goroutine 33 [FUNC L1]",
"2019/07/04 22:11:48 increase instances to 1 [FUNC L1]",
"2019/07/04 22:11:48 .Create(&{0xc0002821e0 {0 0} false [0x8193c0 0x81a800]}, true, /root/open-lambda/test-dir/worker/lambda_code/2-L1, /root/open-lambda/test-dir/worker/scratch/func-L1-1003, &{[] []})...",
"2019/07/04 22:11:48 fork(&{0xc000082690 3 /root/open-lambda/test-dir/worker/sock-handlers/3 /root/open-lambda/test-dir/worker/lambda_code/2-L1 /root/open-lambda/test-dir/worker/scratch/func-L1-1003