Problem starting analysis

[monwolf]

Hi everyone,

I've just followed the installation docs of the new version of deeptracy (on a fresh install of ubuntu server 18.04), I prepared a demo repo with this configuration (.deeptracy.yml):

projects:
    TestCi:
        type: deeptracy-mvn:3.5-jdk-8
        strategy: mvn_dependencytree
        unimportant: false
        config:
            path: src/main

But when I ran this call:

curl --data '{"repository": "http://stash/stash/scm/aeas/testci.git", "commit": "17e74a2a72cd15539f04d1ab888a4a98c13a1b65"}' -XPOST  http://localhost:8088/analysis/ -H "Content-Type: application/json"

I saw in the logs this error:

deeptracy-server_1    | 172.18.0.1 - - [20/Sep/2018 17:56:39] "POST /analysis/ HTTP/1.1" 200 46
deeptracy-worker_1    | [2018-09-20 17:56:39,022: INFO/MainProcess] Received task: deeptracy.tasks.request_extraction[78e1b7b4-81d6-4e96-b356-54c2450226e1]  
deeptracy-buildbot_1  | 2018-09-20 17:56:39+0000 [_GenericHTTPChannelProtocol,1,172.18.0.5] WARNING: change source is using deprecated self.master.addChange method; this method will disappear in Buildbot-1.0.0
deeptracy-buildbot_1  | 2018-09-20 17:56:39+0000 [-] added change with revision 17e74a2a72cd15539f04d1ab888a4a98c13a1b65 to database
deeptracy-buildbot_1  | 2018-09-20 17:56:39+0000 [-] injected change Change(revision='17e74a2a72cd15539f04d1ab888a4a98c13a1b65', who='deeptracy', branch=None, comments='', when=1537466199, category=None, project='http://stash/stash/scm/aeas/testci.git', repository='http://stash/stash/scm/aeas/testci.git', codebase='')
deeptracy-worker_1    | /usr/local/lib/python3.6/site-packages/celery/platforms.py:796: RuntimeWarning: You're running the worker with superuser privileges: this is
deeptracy-worker_1    | absolutely not recommended!
deeptracy-worker_1    | 
deeptracy-worker_1    | Please specify a different user using the --uid option.
deeptracy-worker_1    | 
deeptracy-worker_1    | User information: uid=0 euid=0 gid=0 egid=0
deeptracy-worker_1    | 
deeptracy-worker_1    |   uid=uid, euid=euid, gid=gid, egid=egid,
deeptracy-worker_1    | [2018-09-20 17:56:39,159: INFO/ForkPoolWorker-3] Task deeptracy.tasks.request_extraction[78e1b7b4-81d6-4e96-b356-54c2450226e1] succeeded in 0.1342389319997892s: None
deeptracy-buildbot_1  | 2018-09-20 17:56:40+0000 [-] added buildset 3 to database
deeptracy-buildbot_1  | 2018-09-20 17:56:40+0000 [-] starting build <Build launch number:None results:success> using worker <LatentWorkerForBuilder builder='launch' worker='docker-8' state=AVAILABLE>
deeptracy-buildbot_1  | 2018-09-20 17:56:40+0000 [-] <Build launch number:None results:success>.startBuild
deeptracy-buildbot_1  | 2018-09-20 17:56:40+0000 [-] acquireLocks(worker <WasherDockerLatentWorker 'docker-8'>, locks [])
deeptracy-buildbot_1  | 2018-09-20 17:56:40+0000 [-] substantiating worker <LatentWorkerForBuilder builder='launch' worker='docker-8' state=DETACHED>
deeptracy-buildbot_1  | 2018-09-20 17:56:40+0000 [-] Container created, Id: 241fad...
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [-] Container started
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [-] docker VM 241fad: b'2018-09-20T17:56:41+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] twistd 18.4.0 (/usr/local/bin/python 3.6.5) starting up.\n2018-09-20T17:56:41+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] reactor class: twisted.internet.epollreactor.EPollReactor.'
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [-] docker VM 241fad: b'2018-09-20T17:56:41+0000 [-] Starting Worker -- version: 1970.01.01'
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [-] docker VM 241fad: b'2018-09-20T17:56:41+0000 [-] recording hostname in twistd.hostname'
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [-] docker VM 241fad: b'2018-09-20T17:56:41+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x7f7c63e70b38>\n2018-09-20T17:56:41+0000 [-] Connecting to 172.17.0.1:9989'
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [Broker,4,172.18.0.1] worker 'docker-8' attaching from IPv4Address(type='TCP', host='172.18.0.1', port=42900)
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [-] docker VM 241fad: b'2018-09-20T17:56:41+0000 [HangCheckProtocol,client] message from master: attached'
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [Broker,4,172.18.0.1] Got workerinfo from 'docker-8'
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [-] bot attached
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [-] docker VM 241fad: b"2018-09-20T17:56:41+0000 [HangCheckProtocol,client] I have a leftover directory 'zope' that is not being used by the buildmaster: you can delete it now"
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [Broker,4,172.18.0.1] Worker docker-8 attached to launch
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [Broker,4,172.18.0.1] Worker docker-8 attached to analyze
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [Broker,4,172.18.0.1] Worker docker-8 attached to bootstrap
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [Broker,4,172.18.0.1] Worker docker-8 substantiated \o/
deeptracy-buildbot_1  | 2018-09-20 17:56:41+0000 [Broker,4,172.18.0.1] Firing docker-8 substantiation deferred with success
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] starting build <Build launch number:2 results:success>.. pinging the worker <LatentWorkerForBuilder builder='launch' worker='docker-8' state=BUILDING>
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] sending ping
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [Broker,4,172.18.0.1] ping finished: success
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] added buildset 4 to database
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] releaseLocks(Trigger(schedulerNames=['bootstrap'], set_properties={'virtual_builder_name': Property(project)})): []
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-]  step 'trigger' complete: success (None)
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-]  <Build launch number:2 results:success>: build finished
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] starting build <Build bootstrap number:None results:success> using worker <LatentWorkerForBuilder builder='bootstrap' worker='docker-0' state=AVAILABLE>
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] <Build bootstrap number:None results:success>.startBuild
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] releaseLocks(<WasherDockerLatentWorker 'docker-8'>): []
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] disconnecting old worker docker-8 now
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] waiting for worker to finish disconnecting
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [Broker,4,172.18.0.1] Worker.detached(docker-8)
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] Stopping container 241fad...
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [Broker,4,172.18.0.1] releaseLocks(<WasherDockerLatentWorker 'docker-8'>): []
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] acquireLocks(worker <WasherDockerLatentWorker 'docker-0'>, locks [])
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] substantiating worker <LatentWorkerForBuilder builder='bootstrap' worker='docker-0' state=DETACHED>
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] Container created, Id: 3d4c6e...
deeptracy-buildbot_1  | 2018-09-20 17:56:42+0000 [-] Container started
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] docker VM 3d4c6e: b'2018-09-20T17:56:43+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] twistd 18.4.0 (/usr/local/bin/python 3.6.5) starting up.'
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] docker VM 3d4c6e: b'2018-09-20T17:56:43+0000 [twisted.scripts._twistd_unix.UnixAppLogger#info] reactor class: twisted.internet.epollreactor.EPollReactor.\n2018-09-20T17:56:43+0000 [-] Starting Worker -- version: 1970.01.01\n2018-09-20T17:56:43+0000 [-] recording hostname in twistd.hostname'
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] docker VM 3d4c6e: b'2018-09-20T17:56:43+0000 [buildbot_worker.pb.BotFactory#info] Starting factory <buildbot_worker.pb.BotFactory object at 0x7feac505dba8>'
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] docker VM 3d4c6e: b'2018-09-20T17:56:43+0000 [-] Connecting to 172.17.0.1:9989'
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] worker 'docker-0' attaching from IPv4Address(type='TCP', host='172.18.0.1', port=42904)
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] docker VM 3d4c6e: b'2018-09-20T17:56:43+0000 [HangCheckProtocol,client] message from master: attached'
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] Got workerinfo from 'docker-0'
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] bot attached
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] docker VM 3d4c6e: b"2018-09-20T17:56:43+0000 [HangCheckProtocol,client] I have a leftover directory 'zope' that is not being used by the buildmaster: you can delete it now\n2018-09-20T17:56:43+0000 [HangCheckProtocol,client] I have a leftover directory 'sqlalchemy' that is not being used by the buildmaster: you can delete it now"
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] Worker docker-0 attached to launch
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] Worker docker-0 attached to analyze
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] Worker docker-0 attached to bootstrap
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] Worker docker-0 substantiated \o/
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] Firing docker-0 substantiation deferred with success
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] starting build <Build bootstrap number:2 results:success>.. pinging the worker <LatentWorkerForBuilder builder='bootstrap' worker='docker-0' state=BUILDING>
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] sending ping
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] ping finished: success
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] releaseLocks(SetProperty('repopath', '/work')): []
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-]  step 'SetProperty' complete: success (None)
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] <RemoteShellCommand '['git', '--version']'>: RemoteCommand.run [4]
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] command '['git', '--version']' in dir '/work'
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] <RemoteShellCommand '['git', '--version']'> rc=0
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] <RemoteCommand 'stat' at 139999432269776>: RemoteCommand.run [5]
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] <RemoteCommand 'stat' at 139999432269776> rc=2
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] <RemoteCommand 'listdir' at 139999559733936>: RemoteCommand.run [6]
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] <RemoteCommand 'listdir' at 139999559733936> rc=0
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] No git repo present, making full clone
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] <RemoteShellCommand '['git', 'clone', 'http://stash/stash/scm/aeas/testci.git', '.']'>: RemoteCommand.run [7]
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] command '['git', 'clone', 'http://stash/stash/scm/aeas/testci.git', '.']' in dir '/work'
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] <RemoteShellCommand '['git', 'clone', 'http://stash/stash/scm/aeas/testci.git', '.']'> rc=128
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] releaseLocks(Git(repourl=Property(repository), workdir=Property(repopath))): []
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-]  step 'git' complete: failure (['update (failure)'])
deeptracy-server_1    | 172.18.0.4 - - [20/Sep/2018 17:56:43] "PUT /analysis/94ead550-81a8-467d-b771-90093c469a4f/extraction/failed HTTP/1.1" 200 0
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] releaseLocks(BackendSignal(method='PUT', name='Dependency Extraction Failed Signal', url=Interpolate('http://deeptracy-server:8088/analysis/%(prop:analysis_id)s/extraction/failed'), doStepIf=<function has_property.<locals>._has_property at 0x7f5431c4a598>, alwaysRun=True)): []
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-]  step 'Dependency Extraction Failed Signal' complete: success (None)
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-]  <Build bootstrap number:2 results:failure>: build finished
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] releaseLocks(<WasherDockerLatentWorker 'docker-0'>): []
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] disconnecting old worker docker-0 now
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] waiting for worker to finish disconnecting
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] Worker.detached(docker-0)
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [Broker,5,172.18.0.1] releaseLocks(<WasherDockerLatentWorker 'docker-0'>): []
deeptracy-buildbot_1  | 2018-09-20 17:56:43+0000 [-] Stopping container 3d4c6e...
deeptracy-buildbot_1  | 2018-09-20 17:56:44+0000 [-] while insubstantiating
deeptracy-buildbot_1  |         Traceback (most recent call last):
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1475, in gotResult
deeptracy-buildbot_1  |             _inlineCallbacks(r, g, status)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
deeptracy-buildbot_1  |             result = result.throwExceptionIntoGenerator(g)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
deeptracy-buildbot_1  |             return g.throw(self.type, self.value, self.tb)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/latent.py", line 253, in insubstantiate
deeptracy-buildbot_1  |             log.err(e, "while insubstantiating")
deeptracy-buildbot_1  |         --- <exception caught here> ---
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/latent.py", line 248, in insubstantiate
deeptracy-buildbot_1  |             yield d
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/threadpool.py", line 250, in inContext
deeptracy-buildbot_1  |             result = inContext.theWork()
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/threadpool.py", line 266, in <lambda>
deeptracy-buildbot_1  |             inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/context.py", line 122, in callWithContext
deeptracy-buildbot_1  |             return self.currentContext().callWithContext(ctx, func, *args, **kw)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/context.py", line 85, in callWithContext
deeptracy-buildbot_1  |             return func(*args,**kw)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/docker.py", line 307, in _thd_stop_instance
deeptracy-buildbot_1  |             docker_client.stop(instance['Id'])
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/docker/utils/decorators.py", line 19, in wrapped
deeptracy-buildbot_1  |             return f(self, resource_id, *args, **kwargs)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/docker/api/container.py", line 1120, in stop
deeptracy-buildbot_1  |             self._raise_for_status(res)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/docker/api/client.py", line 231, in _raise_for_status
deeptracy-buildbot_1  |             raise create_api_error_from_http_exception(e)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/docker/errors.py", line 31, in create_api_error_from_http_exception
deeptracy-buildbot_1  |             raise cls(e, response=response, explanation=explanation)
deeptracy-buildbot_1  |         docker.errors.APIError: 500 Server Error: Internal Server Error ("cannot stop container: 241fad59d453476c28a17ea8bcd8834d289aadcfdb94073437cbc82c25e9da93: Cannot kill container 241fad59d453476c28a17ea8bcd8834d289aadcfdb94073437cbc82c25e9da93: unknown error after kill: docker-runc did not terminate sucessfully: container_linux.go:393: signaling init process caused "permission denied"
deeptracy-buildbot_1  |         : unknown")
deeptracy-buildbot_1  | 
deeptracy-buildbot_1  | 2018-09-20 17:56:44+0000 [Broker,6,172.18.0.1] worker 'docker-8' attaching from IPv4Address(type='TCP', host='172.18.0.1', port=42912)
deeptracy-buildbot_1  | 2018-09-20 17:56:44+0000 [Broker,6,172.18.0.1] Got workerinfo from 'docker-8'
deeptracy-buildbot_1  | 2018-09-20 17:56:44+0000 [Broker,6,172.18.0.1] Worker docker-8 received connection while not trying to substantiate.  Disconnecting.
deeptracy-buildbot_1  | 2018-09-20 17:56:44+0000 [Broker,6,172.18.0.1] waiting for worker to finish disconnecting
deeptracy-buildbot_1  | 2018-09-20 17:56:44+0000 [Broker,6,172.18.0.1] Peer will receive following PB traceback:
deeptracy-buildbot_1  | 2018-09-20 17:56:44+0000 [Broker,6,172.18.0.1] Unhandled Error
deeptracy-buildbot_1  |         Traceback (most recent call last):
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
deeptracy-buildbot_1  |             result = g.send(result)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/protocols/pb.py", line 147, in attached
deeptracy-buildbot_1  |             yield self.worker.attached(self)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1613, in unwindGenerator
deeptracy-buildbot_1  |             return _cancellableInlineCallbacks(gen)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1529, in _cancellableInlineCallbacks
deeptracy-buildbot_1  |             _inlineCallbacks(None, g, status)
deeptracy-buildbot_1  |         --- <exception caught here> ---
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/protocols/pb.py", line 147, in attached
deeptracy-buildbot_1  |             yield self.worker.attached(self)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
deeptracy-buildbot_1  |             result = g.send(result)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/latent.py", line 153, in attached
deeptracy-buildbot_1  |             raise RuntimeError(msg)
deeptracy-buildbot_1  |         builtins.RuntimeError: Worker docker-8 received connection while not trying to substantiate.  Disconnecting.
deeptracy-buildbot_1  | 
deeptracy-buildbot_1  | 2018-09-20 17:56:45+0000 [-] while insubstantiating
deeptracy-buildbot_1  |         Traceback (most recent call last):
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1475, in gotResult
deeptracy-buildbot_1  |             _inlineCallbacks(r, g, status)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
deeptracy-buildbot_1  |             result = result.throwExceptionIntoGenerator(g)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
deeptracy-buildbot_1  |             return g.throw(self.type, self.value, self.tb)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/latent.py", line 253, in insubstantiate
deeptracy-buildbot_1  |             log.err(e, "while insubstantiating")
deeptracy-buildbot_1  |         --- <exception caught here> ---
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/latent.py", line 248, in insubstantiate
deeptracy-buildbot_1  |             yield d
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/threadpool.py", line 250, in inContext
deeptracy-buildbot_1  |             result = inContext.theWork()
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/threadpool.py", line 266, in <lambda>
deeptracy-buildbot_1  |             inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/context.py", line 122, in callWithContext
deeptracy-buildbot_1  |             return self.currentContext().callWithContext(ctx, func, *args, **kw)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/python/context.py", line 85, in callWithContext
deeptracy-buildbot_1  |             return func(*args,**kw)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/docker.py", line 307, in _thd_stop_instance
deeptracy-buildbot_1  |             docker_client.stop(instance['Id'])
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/docker/utils/decorators.py", line 19, in wrapped
deeptracy-buildbot_1  |             return f(self, resource_id, *args, **kwargs)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/docker/api/container.py", line 1120, in stop
deeptracy-buildbot_1  |             self._raise_for_status(res)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/docker/api/client.py", line 231, in _raise_for_status
deeptracy-buildbot_1  |             raise create_api_error_from_http_exception(e)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/docker/errors.py", line 31, in create_api_error_from_http_exception
deeptracy-buildbot_1  |             raise cls(e, response=response, explanation=explanation)
deeptracy-buildbot_1  |         docker.errors.APIError: 500 Server Error: Internal Server Error ("cannot stop container: 3d4c6e3b402125c837cd8bc2be29d33a43643931dcd027d96c468e9f6cbd2666: Cannot kill container 3d4c6e3b402125c837cd8bc2be29d33a43643931dcd027d96c468e9f6cbd2666: unknown error after kill: docker-runc did not terminate sucessfully: container_linux.go:393: signaling init process caused "permission denied"
deeptracy-buildbot_1  |         : unknown")
deeptracy-buildbot_1  | 
deeptracy-buildbot_1  | 2018-09-20 17:56:46+0000 [Broker,7,172.18.0.1] worker 'docker-0' attaching from IPv4Address(type='TCP', host='172.18.0.1', port=42916)
deeptracy-buildbot_1  | 2018-09-20 17:56:46+0000 [Broker,7,172.18.0.1] Got workerinfo from 'docker-0'
deeptracy-buildbot_1  | 2018-09-20 17:56:46+0000 [Broker,7,172.18.0.1] Worker docker-0 received connection while not trying to substantiate.  Disconnecting.
deeptracy-buildbot_1  | 2018-09-20 17:56:46+0000 [Broker,7,172.18.0.1] waiting for worker to finish disconnecting
deeptracy-buildbot_1  | 2018-09-20 17:56:46+0000 [Broker,7,172.18.0.1] Peer will receive following PB traceback:
deeptracy-buildbot_1  | 2018-09-20 17:56:46+0000 [Broker,7,172.18.0.1] Unhandled Error
deeptracy-buildbot_1  |         Traceback (most recent call last):
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
deeptracy-buildbot_1  |             result = g.send(result)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/protocols/pb.py", line 147, in attached
deeptracy-buildbot_1  |             yield self.worker.attached(self)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1613, in unwindGenerator
deeptracy-buildbot_1  |             return _cancellableInlineCallbacks(gen)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1529, in _cancellableInlineCallbacks
deeptracy-buildbot_1  |             _inlineCallbacks(None, g, status)
deeptracy-buildbot_1  |         --- <exception caught here> ---
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/protocols/pb.py", line 147, in attached
deeptracy-buildbot_1  |             yield self.worker.attached(self)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
deeptracy-buildbot_1  |             result = g.send(result)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/worker/latent.py", line 153, in attached
deeptracy-buildbot_1  |             raise RuntimeError(msg)
deeptracy-buildbot_1  |         builtins.RuntimeError: Worker docker-0 received connection while not trying to substantiate.  Disconnecting.
deeptracy-buildbot_1  | 

If I do a git clone outside the docker I'm able to do a clone without problems (no credentials are required):

berni@ubuntu-ci:~$ git clone http://stash/stash/scm/aeas/testci.git
Cloning into 'testci'...
remote: Counting objects: 33, done.
remote: Compressing objects: 100% (22/22), done.
remote: Total 33 (delta 3), reused 0 (delta 0)
Unpacking objects: 100% (33/33), done.

Could you help me with this issue?

Thanks for your time

[nilp0inter]

It looks like deeptracy cannot stop containers in your computer:

deeptracy-buildbot_1  |         docker.errors.APIError: 500 Server Error: Internal Server Error ("cannot stop container: 3d4c6e3b402125c837cd8bc2be29d33a43643931dcd027d96c468e9f6cbd2666: Cannot kill container 3d4c6e3b402125c837cd8bc2be29d33a43643931dcd027d96c468e9f6cbd2666: unknown error after kill: docker-runc did not terminate sucessfully: container_linux.go:393: signaling init process caused "permission denied"

A quick search brought me to this answer: https://stackoverflow.com/questions/49104733/docker-on-ubuntu-16-04-error-when-killing-container

Maybe AppArmor is stopping us from stopping the container. Please try the solutions given in the StackOverflow answer and let me know if that help.

[nilp0inter]

Also, are you sure the hostname stash can be resolved inside your container?

[monwolf]

It looks like deeptracy cannot stop containers in your computer:

deeptracy-buildbot_1  |         docker.errors.APIError: 500 Server Error: Internal Server Error ("cannot stop container: 3d4c6e3b402125c837cd8bc2be29d33a43643931dcd027d96c468e9f6cbd2666: Cannot kill container 3d4c6e3b402125c837cd8bc2be29d33a43643931dcd027d96c468e9f6cbd2666: unknown error after kill: docker-runc did not terminate sucessfully: container_linux.go:393: signaling init process caused "permission denied"

A quick search brought me to this answer: https://stackoverflow.com/questions/49104733/docker-on-ubuntu-16-04-error-when-killing-container

Maybe AppArmor is stopping us from stopping the container. Please try the solutions given in the StackOverflow answer and let me know if that help.

After disable apparmor, kill the existing docker instances and then reload the deeptracy, the exception disappears.

But I stay with the other problem, I can't checkout the repo inside the docker. If I try to connect to stash from the docker I'm able to reach that (deeptracy_deeptracy-worker_1):

root@74d7c8f8869f:/tmp# git clone http://stash/stash/scm/aeas/testci.git
Cloning into 'testci'...
remote: Counting objects: 33, done.
remote: Compressing objects: 100% (22/22), done.
remote: Total 33 (delta 3), reused 0 (delta 0)
Unpacking objects: 100% (33/33), done.

root@74d7c8f8869f:/tmp/testci# git checkout 17e74a2a72cd15539f04d1ab888a4a98c13a1b65
Note: checking out '17e74a2a72cd15539f04d1ab888a4a98c13a1b65'.

You are in 'detached HEAD' state. You can look around, make experimental
changes and commit them, and you can discard any commits you make in this
state without impacting any branches by performing another checkout.

If you want to create a new branch to retain commits you create, you may
do so (now or later) by using -b with the checkout command again. Example:

  git checkout -b <new-branch-name>

HEAD is now at 17e74a2... test21

[nilp0inter]

Could you please access the buildbot access panel under: http://localhost:8010/, Access the build with the same name as your repository URL and take an screenshot of the steps, please.

Also, could you please send an analysis of the URL: https://github.com/nilp0inter/gitsectest with the commit a5a01ca69ac99c793ec5af1bbc190f518d8fc412 ?

[monwolf]

You were right.

fatal: unable to access 'http://stash/stash/scm/aeas/testci.git/': Could not resolve host: stash

So.. do you overwrite the DNS of the machine?

If I point to the IP of the stash server I works as spected (Now I have a problem with my project but I¡ll try to fix It to test again).

I would like to report a problem with buildbot. I'm accessing with the Ip of my VM, but when I navigate through buildboot gui I get redirected to "localhost". I attached the image that shows where it happens:

[nilp0inter]

I am not overwriting the DNS settings, but maybe Buildbot/Docker are.

To stop buildbot redirecting you to localhost there are a few environment variables you can change under the environment section of the deeptracy-buildbot definition in the docker-compose file.

I think the correct variable is BUILDBOT_WEB_URL. You can check the list of allowed variables and default values here:

deeptracy/deeptracy/buildbot/master.cfg

Lines 26 to 58 in e5e7e0e

	class Config(EnvironConfig):
	DOCKER_HOST = StringVar(default="unix://var/run/docker.sock")
	WORKER_IMAGE_AUTOPULL = BooleanVar(default=True)
	WORKER_INSTANCES = IntVar(default=16)
	# Comma separated list of allowed image shell-like patterns. By default '*'
	WORKER_IMAGE_WHITELIST = ImagePatternVar(default=lambda name: True)
	@MethodVar
	def WASHER_FORCE_GATEWAY(env):
	if (env.DOCKER_HOST.startswith('unix://')
	or "localhost" in env.DOCKER_HOST):
	return "1"
	else:
	return "0"
	BUILDBOT_MQ_URL = StringVar(default=None)
	BUILDBOT_MQ_REALM = StringVar(default="buildbot")
	BUILDBOT_MQ_DEBUG = BooleanVar(default=False)
	BUILDBOT_WORKER_PORT = IntVar(default=9989)
	BUILDBOT_WEB_URL = StringVar(default="http://localhost:8010/")
	BUILDBOT_WEB_PORT = IntVar(default=8010)
	BUILDBOT_WEB_HOST = StringVar(default="localhost")
	# This specifies what database buildbot uses to store its state. You can leave
	# this at its default for all but the largest installations.
	BUILDBOT_DB_URL = StringVar(default="sqlite://")
	DEEPTRACY_SERVER_CONFIG = PathVar(default=None)
	DEEPTRACY_WORKER_IMAGE = StringVar(default="bbvalabsci/gitsec-worker")
	DEEPTRACY_BACKEND_URL = StringVar()

[monwolf]

Thanks for this information, I corrected some problems the pom location and then I got the following error:

  File "/washer/twisted/spread/banana.py", line 335, in _encode
  File "/washer/twisted/spread/banana.py", line 335, in _encode
  File "/washer/twisted/spread/banana.py", line 335, in _encode
  File "/washer/twisted/spread/banana.py", line 335, in _encode
  File "/washer/twisted/spread/banana.py", line 335, in _encode 
  File "/washer/twisted/spread/banana.py", line 335, in _encode 
  File "/washer/twisted/spread/banana.py", line 364, in _encode 
twisted.spread.banana.BananaError: byte string is too long to send (836030)

That's how my project looks like:

│   .deeptracy.yml
│   .gitignore
│
└───src
    ├───main
    │   │   mvnw
    │   │   mvnw.cmd
    │   │   pom.xml
    │   │
    │   ├───.mvn
    │   │   └───wrapper
    │   │           maven-wrapper.jar
    │   │           maven-wrapper.properties
    │   │
    │   ├───java
    │   │   └───com
    │   │       └───org
    │   │           └───security
    │   │               └───testci
    │   │                       TestciApplication.java
    │   │
    │   └───resources
    │           application.properties
    │
    └───test
        └───java
            └───com
                └───org
                    └───security
                        └───testci
                                TestciApplicationTests.java

[nilp0inter]

That is very interesting, could you share the pom or at least the list of dependencies contained in it?

[monwolf]

Of course that's my pom.xml

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
	<modelVersion>4.0.0</modelVersion>
 
	<groupId>com.org.security</groupId>
	<artifactId>testci</artifactId>
	<version>0.0.1-SNAPSHOT</version>
	<packaging>jar</packaging>

	<name>testci</name>
	<description>Demo project for Spring Boot</description>

	<parent>
		<groupId>org.springframework.boot</groupId>
		<artifactId>spring-boot-starter-parent</artifactId>
		<version>2.0.3.RELEASE</version>
		<relativePath/> <!-- lookup parent from repository -->
	</parent>

	<properties>
		<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
		<project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
		<java.version>1.8</java.version>
	</properties>

	<dependencies>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-actuator</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-security</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-web</artifactId>
		</dependency>

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-devtools</artifactId>
			<scope>runtime</scope>
		</dependency>
		<dependency>
			<groupId>com.h2database</groupId>
			<artifactId>h2</artifactId>
			<scope>runtime</scope>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-test</artifactId>
			<scope>test</scope>
		</dependency>
		<dependency>
			<groupId>org.springframework.security</groupId>
			<artifactId>spring-security-test</artifactId>
			<scope>test</scope>
		</dependency>
	</dependencies>

	<build>
		<plugins>
			<plugin>
				<groupId>org.springframework.boot</groupId>
				<artifactId>spring-boot-maven-plugin</artifactId>
			</plugin>
		</plugins>
	</build>


</project>

[nilp0inter]

Hi @Berni69 ,

I've just uploaded a patch that should solve your problem. Please download the latest version and rebuild your containers with 'make' to test it out.

Cheers,
Roberto

[monwolf]

Hi @nilp0inter, now It seems that it passed from this point, but during the analysis I'm seeing this exception (in buildbot I can't see errors) in the container log:

deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [Broker,2,172.20.0.1] <RemoteShellCommand '['git', 'reset', '--hard', 'aa8165ce8a4c33a27fe6339d83efb20174469b08', '--']'> rc=0
deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [-] <RemoteShellCommand '['git', 'rev-parse', 'HEAD']'>: RemoteCommand.run [12]
deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [-] command '['git', 'rev-parse', 'HEAD']' in dir '/work'
deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [Broker,2,172.20.0.1] <RemoteShellCommand '['git', 'rev-parse', 'HEAD']'> rc=0
deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [-] Got Git revision aa8165ce8a4c33a27fe6339d83efb20174469b08
deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [-] Closing log, sending result of the command None 
deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [-] releaseLocks(Git(repourl=Property(repository), workdir=Property(repopath))): []
deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [-]  step 'git' complete: success (None)
deeptracy-buildbot_1  | 2018-09-24 08:27:11+0000 [-] <RemoteCommand 'washertask' at 139668006988600>: RemoteCommand.run [13]
deeptracy-buildbot_1  | 2018-09-24 08:27:56+0000 [_GenericHTTPChannelProtocol,1,192.168.222.1] while decoding JWT session
deeptracy-buildbot_1  |         Traceback (most recent call last):
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/twisted/web/server.py", line 481, in getSession
deeptracy-buildbot_1  |             session = self.site.getSession(sessionCookie)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/www/service.py", line 174, in getSession
deeptracy-buildbot_1  |             return BuildbotSession(self, uid)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/www/service.py", line 74, in __init__
deeptracy-buildbot_1  |             self._fromToken(token)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/www/service.py", line 88, in _fromToken
deeptracy-buildbot_1  |             log.err(e, "while decoding JWT session")
deeptracy-buildbot_1  |         --- <exception caught here> ---
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/buildbot/www/service.py", line 84, in _fromToken
deeptracy-buildbot_1  |             SESSION_SECRET_ALGORITHM])
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/jwt/api_jwt.py", line 93, in decode
deeptracy-buildbot_1  |             jwt, key=key, algorithms=algorithms, options=options, **kwargs
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/jwt/api_jws.py", line 157, in decode
deeptracy-buildbot_1  |             key, algorithms)
deeptracy-buildbot_1  |           File "/usr/local/lib/python3.6/site-packages/jwt/api_jws.py", line 224, in _verify_signature
deeptracy-buildbot_1  |             raise InvalidSignatureError('Signature verification failed')
deeptracy-buildbot_1  |         jwt.exceptions.InvalidSignatureError: Signature verification failed
deeptracy-buildbot_1  | 
deeptracy-buildbot_1  | 2018-09-24 08:28:08+0000 [-] Splitting long line: [INFO] Scanning for projects.. 4146 (not warning anymore for this log)
deeptracy-buildbot_1  | 2018-09-24 08:28:14+0000 [Broker,2,172.20.0.1] <RemoteCommand 'washertask' at 139668006988600> rc=0
deeptracy-buildbot_1  | 2018-09-24 08:28:15+0000 [-] releaseLocks(WasherTask(task_name=Property(task_name), task_args=Property(task_args))): []

I have another question, is there any way to set an ssh key to access private repositories?

[nilp0inter]

You can safely ignore the InvalidSignatureError; nevertheless I opened a ticket to try to fix it.

Regarding your other question, buildbot support ssh keys directly and through secret managers but at the moment deeptracy has no method of pass it to buildbot. http://docs.buildbot.net/current/manual/cfg-buildsteps.html?highlight=sshprivatekey#git

You can modify the Git steps on the master.cfg file to specify your custom SSH keys.

If you have any suggestions on what is the best way of implementing it please open another ticket to discuss it.

Thank you for your reports!