Runtime error

[emilhenriksson]

Hi,
We have come across a runtime errror with HBM any idea why this is happening?

Oct 15 14:16:29 sekalx583 hbm[1918]: time="2018-10-15T14:16:29+02:00" level=info action=image_inspect admin=false allowed=true authorization=true user=root
Oct 15 14:16:29 sekalx583 hbm[1918]: 2018/10/15 14:16:29 Recovered: runtime error: invalid memory address or nil pointer dereference
Oct 15 14:16:29 sekalx583 hbm[1918]: time="2018-10-15T14:16:29+02:00" level=warning msg="Recovered panic: runtime error: invalid memory address or nil pointer dereference"
Oct 15 14:16:29 sekalx583 hbm[1918]: time="2018-10-15T14:16:29+02:00" level=warning msg="goroutine 18 [running]:\nruntime/debug.Stack(0xc42086d100, 0xc42042e360, 0x2)\n\t/usr/local/go/src/runtime/debug/stack.go:24 +0x79\ngithub.com/kassisol/hbm/plugin.(*Api).Allow.func1(0xf74640, 0xc42086d100, 0xf70560, 0xc4205181b0, 0xc42065b950)\n\t/go/src/github.com/kassisol/hbm/plugin/api.go:56 +0x137\npanic(0xa314e0, 0xf5a0c0)\n\t/usr/local/go/src/runtime/panic.go:489 +0x2cf\ngithub.com/kassisol/hbm/plugin.(*Api).Allow(0xc42086d0e0, 0x0, 0x0, 0x0, 0x0, 0xc4202d0c90, 0x4, 0xc4207ec050, 0x4b, 0xc4203e6700, ...)\n\t/go/src/github.com/kassisol/hbm/plugin/api.go:112 +0x7e4\ngithub.com/kassisol/hbm/plugin.(*plugin).AuthZReq(0xc420386d20, 0x0, 0x0, 0x0, 0x0, 0xc4202d0c90, 0x4, 0xc4207ec050, 0x4b, 0xc4203e6700, ...)\n\t/go/src/github.com/kassisol/hbm/plugin/plugin.go:52 +0x238\ngithub.com/kassisol/hbm/vendor/github.com/docker/go-plugins-helpers/authorization.(*Handler).initMux.func1(0x0, 0x0, 0x0, 0x0, 0xc4202d0c90, 0x4, 0xc4207ec050, 0x4b, 0xc4203e6700, 0x656, ...)\n\t/go/src/github.com/kassisol/hbm/vendor/github.com/docker/go-plugins-helpers/authorization/api.go:118 +0xa0\ngithub.com/kassisol/hbm/vendor/github.com/docker/go-plugins-helpers/authorization.(*Handler).handle.func1(0xf6f9e0, 0xc4203900e0, 0xc420270200)\n\t/go/src/github.com/kassisol/hbm/vendor/github.com/docker/go-plugins-helpers/authorization/api.go:139 +0x14c\nnet/http.HandlerFunc.ServeHTTP(0xc42039ae00, 0xf6f9e0, 0xc4203900e0, 0xc420270200)\n\t/usr/local/go/src/net/http/server.go:1942 +0x44\nnet/http.(*ServeMux).ServeHTTP(0xc420386e10, 0xf6f9e0, 0xc4203900e0, 0xc420270200)\n\t/usr/local/go/src/net/http/server.go:2238 +0x130\nnet/http.serverHandler.ServeHTTP(0xc4200acc60, 0xf6f9e0, 0xc4203900e0, 0xc420270200)\n\t/usr/local/go/src/net/http/server.go:2568 +0x92\nnet/http.(*conn).serve(0xc4203c8000, 0xf702a0, 0xc4203cc040)\n\t/usr/local/go/src/net/http/server.go:1825 +0x612\ncreated by net/http.(*Server).Serve\n\t/usr/local/go/src/net/http/server.go:2668 +0x2ce\n"

[ghost]

which docker command did you run to get that error?

[emilhenriksson]

It's docker-compose so it's kind of hard to tell the exact docker command, but when I switch HBM off it looks like it's a container_create command that's next. I'll see if I can get more debug info from docker-compose...

[emilhenriksson]

Got some more information from docker-compose:
compose.cli.verbose_proxy.proxy_callable: docker create_container <- (command='worker', environment=['CONCOURSE_TSA_HOST=host:2222', 'CONCOURSE_GARDEN_DNS_SERVER=x.x.x.x', 'CONCOURSE_GARDEN_LOG_LEVEL=info', 'HOST_HOSTNAME=host1', 'HOST_DOMAINNAME=.xxx.se', 'CONCOURSE_NAME=host1_2018.October.15_14.21.03', 'SET_CONTAINER_TIMEZONE=true', 'CONTAINER_TIMEZONE=Europe/Stockholm', 'CONCOURSE_BAGGAGECLAIM_DRIVER=btrfs', 'CONCOURSE_GARDEN_MAX_CONTAINERS=512', 'CONCOURSE_GARDEN_NETWORK_POOL=10.254.0.0/21'], image='portus.se/concourse:3.14.1', ports=[('7777', 'tcp'), ('7788', 'tcp'), ('7799', 'tcp')], volumes={'/concourse-keys': {}}, name='sed_worker-host1_2018.October.15_14.21.03', detach=True, labels={'com.docker.compose.project': 'config', 'com.docker.compose.service': 'concourse-worker-host1', 'com.docker.compose.oneoff': 'False', 'com.docker.compose.container-number': '1', 'com.docker.compose.version': '1.22.0', 'com.docker.compose.config-hash': '899ee2f4ee6fda6990da6a422d03f2985a0ea354ac2514c8525733a8c504b801'}, host_config={'Privileged': True, 'NetworkMode': 'config_default', 'VolumesFrom': [], 'Binds': ['/proj/prov/env1/runarea/ci/concourse/production/keys/worker:/concourse-keys:rw'], 'PortBindings': {'7777/tcp': [{'HostIp': '', 'HostPort': '7777'}], '7788/tcp': [{'HostIp': '', 'HostPort': '7788'}], '7799/tcp': [{'HostIp': '', 'HostPort': '7799'}]}, 'Links': [], 'LogConfig': {'Type': '', 'Config': {}}}, networking_config={'EndpointsConfig': {'config_default': {'Aliases': ['concourse-worker-sekalx583'], 'IPAMConfig': {}}}})
compose.parallel.feed_queue: Pending: set()
urllib3.connectionpool._make_request: http://localhost:None "POST /v1.25/containers/create?name=sed_worker-sekalx583_2018.October.15_14.21.03 HTTP/1.1" 500 119
Creating sed_worker-sekalx583_2018.October.15_14.21.03 ... error
compose.parallel.feed_queue: Pending: set()

ERROR: for sed_worker-sekalx583_2018.October.15_14.21.03 Cannot create container for service concourse-worker-sekalx583: plugin hbm failed with error: AuthZPlugin.AuthZReq: an error occurred; contact your system administrator
compose.parallel.parallel_execute_iter: Failed: <Service: concourse-worker-sekalx583>
compose.parallel.feed_queue: Pending: set()

Don't know if you can find something from these logs...

[emilhenriksson]

Hi Julien,
Did some more digging and found that it looks like a regression with HBM 0.11.0, docker-compose doesn't work but if I revert to 0.10.0 the same docker-compose.yml works.

Does that help?

Regards Emil

[nenne70]

Hi
I experience the same issues. But for me it also fails also in 0.10.0, as long as I have config:authorization set to true.

But I managed to use a simple docker-compose file with 0.12.0, after adding network create, network disconnect and network connect. But initially I got it to crash there also.

[nenne70]

This a really strange bug. I just noticed I have it workin on a RHEL 7.4 host but not on RHEL 7.5 or 7.6.

So I removed the installed 0.11.0 version, installed 0.10.0. Ensured authorization was enabled. Removed the hbm database and applied all rules again. Tested. Successful.

Upgraded back to 0.11.0 version. Ensured authorization was enabled. Tested. Successful.

Is there any database difference between 0.10.0 and 0.11.0, when the database is initialized?

[emilhenriksson]

Interesting I haven't had time to look into it anymore but does it still work with 0.12.0 and a new initialization?