Build logs endpoint?

[gnestor]

I have successfully built a repo using binderhub but my postBuild script didn't work so now I need to debug. Is there a way to access the original build logs to see what went wrong?

My binder URL is https://hub.beta.mybinder.org/user/gnestor-jupyter-renderers-82oqro3y and the repo branch is https://github.com/gnestor/jupyter-renderers/tree/vdom.

[yuvipanda]

Heya!

If you just go to https://beta.mybinder.org/v2/gh/gnestor/jupyter-renderers/vdom and click the 'build logs' button it should show you the build logs

[yuvipanda]

but it only shows it to you as it is being built - I guess you want to access it after it has been built?

[gnestor]

Yes, all I can see now is that it's already been built and that it's running the server...

[yuvipanda]

@gnestor I looked at the logs in the backend and it looks like your postBuild isn't being run at all. This is because it isn't marked executable - you need to chmod +x postBuild it. Can you try that?

[yuvipanda]

I don't know what the long term solution for this is though.

[gnestor]

Thank you for taking a look! That could've taken me a LONG time to debug. It would be nice if there were an endpoints for logs (e.g. https://beta.mybinder.org/v2/gh/gnestor/jupyter-renderers/logs), but I have no idea how that fits into the overall design of binderhub 🤷‍♂️

[yuvipanda]

:D The other thing to do is to run repo2docker locally - http://github.com/jupyter/repo2docker. It's the same thing that binder does, so you can test how that'll behave locally without having to wait for a rebuild each time.

I'm going to leave this open for us to figure out a longer term solution tho. Persisting logs is... sortof difficult, so we'll try to find a solution that doesn't involve that :D

[willingc]

Let's take a two pronged approach here:

• Short term: Add documentation to advise people that they can run repo2docker to test their buids
• Longer term: 1) investigate a solution to display post build to user during the build/postbuild process similar to travis; 2) investigate a test system which can display debug level messages to the user during build/post-build.

[gnestor]

@willingc Sounds like a good plan! However, I'm not having any luck using repo2docker in my repo root:

$ jupyter-repo2docker .
Using repo2docker-python3.5 builder
Traceback (most recent call last):
  File "/Users/grant/anaconda/lib/python3.5/site-packages/urllib3/connectionpool.py", line 601, in urlopen
    chunked=chunked)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/urllib3/connectionpool.py", line 357, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 934, in _send_output
    self.send(msg)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 877, in send
    self.connect()
  File "/Users/grant/anaconda/lib/python3.5/site-packages/docker/transport/unixconn.py", line 33, in connect
    sock.connect(self.unix_socket)
FileNotFoundError: [Errno 2] No such file or directory

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/grant/anaconda/lib/python3.5/site-packages/requests/adapters.py", line 440, in send
    timeout=timeout
  File "/Users/grant/anaconda/lib/python3.5/site-packages/urllib3/connectionpool.py", line 639, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/Users/grant/anaconda/lib/python3.5/site-packages/urllib3/util/retry.py", line 357, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/urllib3/packages/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/urllib3/connectionpool.py", line 601, in urlopen
    chunked=chunked)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/urllib3/connectionpool.py", line 357, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 934, in _send_output
    self.send(msg)
  File "/Users/grant/anaconda/lib/python3.5/http/client.py", line 877, in send
    self.connect()
  File "/Users/grant/anaconda/lib/python3.5/site-packages/docker/transport/unixconn.py", line 33, in connect
    sock.connect(self.unix_socket)
urllib3.exceptions.ProtocolError: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/grant/anaconda/lib/python3.5/site-packages/docker/api/client.py", line 166, in _retrieve_server_version
    return self.version(api_version=False)["ApiVersion"]
  File "/Users/grant/anaconda/lib/python3.5/site-packages/docker/api/daemon.py", line 177, in version
    return self._result(self._get(url), json=True)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/docker/utils/decorators.py", line 46, in inner
    return f(self, *args, **kwargs)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/docker/api/client.py", line 189, in _get
    return self.get(url, **self._set_request_timeout(kwargs))
  File "/Users/grant/anaconda/lib/python3.5/site-packages/requests/sessions.py", line 521, in get
    return self.request('GET', url, **kwargs)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/requests/sessions.py", line 508, in request
    resp = self.send(prep, **send_kwargs)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/requests/sessions.py", line 618, in send
    r = adapter.send(request, **kwargs)
  File "/Users/grant/anaconda/lib/python3.5/site-packages/requests/adapters.py", line 490, in send
    raise ConnectionError(err, request=request)
requests.exceptions.ConnectionError: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/grant/anaconda/bin/jupyter-repo2docker", line 11, in <module>
    sys.exit(main())
  File "/Users/grant/anaconda/lib/python3.5/site-packages/repo2docker/__main__.py", line 6, in main
    f.start()
  File "/Users/grant/anaconda/lib/python3.5/site-packages/repo2docker/app.py", line 325, in start
    for l in picked_buildpack.build(self.output_image_spec):
  File "/Users/grant/anaconda/lib/python3.5/site-packages/repo2docker/detectors.py", line 390, in build
    client = docker.APIClient(version='auto', **docker.utils.kwargs_from_env())
  File "/Users/grant/anaconda/lib/python3.5/site-packages/docker/api/client.py", line 147, in __init__
    self._version = self._retrieve_server_version()
  File "/Users/grant/anaconda/lib/python3.5/site-packages/docker/api/client.py", line 174, in _retrieve_server_version
    'Error while fetching server API version: {0}'.format(e)
docker.errors.DockerException: Error while fetching server API version: ('Connection aborted.', FileNotFoundError(2, 'No such file or directory'))

[choldgraf]

@gnestor do you have docker running when you run repo2docker?

and I got the executable thing to pas the initial build, but now it's failing at the very end. It detects postBuild and then tries to run it, but when it does it can't seem to find the file

[gnestor]

Doh!! 🤦‍♂️ Trying it again now...

Regarding the postBuild issue, try pulling jupyter-renderers/master now. I just merged the binder PR 👍

[mrustl]

I have a similar issue with my repo: https://mybinder.org/v2/gh/kwb-r/kwb.qmra/7f6a1c49ae9a8d0a953969c8ece762f2bbac72e3?urlpath=rstudio

[choldgraf]

Hmmm, this seems similar to another issue someone had on gitter recently where a requirements file wasn't being found. In that case the person was also using a direct git commit ref rather than a tag/branch. I wonder if these are related somehow...

[choldgraf]

@mrustl if you run the same command but using a branch (e.g. "master") what happens?

[mrustl]

@choldgraf I just created a branch for the postBuild problem, but it returns the same error:
https://mybinder.org/v2/gh/kwb-r/kwb.qmra/binder-postBuild?urlpath=rstudio

[ctb]

Continuing from my last comment,

I moved postBuild and install.R to the top directory (not sure this is required but that's how I always do it :).

then, I tried library('devtools') and that didn't work.

But install.packages('devtools') also didn't work when I tried it; see screenshot. The error text was:

Warning in install.packages :
  unable to access index for repository https://mran.microsoft.com/snapshot/2018-03-15/src/contrib:
  cannot open URL 'https://mran.microsoft.com/snapshot/2018-03-15/src/contrib/PACKAGES'
Installing package into ‘/home/jovyan/R/x86_64-pc-linux-gnu-library/3.4’
(as ‘lib’ is unspecified)
Warning in install.packages :
  unable to access index for repository https://mran.microsoft.com/snapshot/2018-03-15/src/contrib:
  cannot open URL 'https://mran.microsoft.com/snapshot/2018-03-15/src/contrib/PACKAGES'
Warning in install.packages :
  package ‘devtools’ is not available (for R version 3.4.2)

so maybe that's the (or at least a) problem?

My fork & branch is here

[betatim]

@ctb your last screenshot makes me think MRAN is down/unreachable? When I try and open https://mran.microsoft.com/snapshot/2018-03-15/src/contrib in a browser I get an error 500.

[ctb]

ahh.

[mrustl]

@ctb that's why I changed the snapshot day to 2018-02-01 to geht rid of the problem: https://github.com/KWB-R/kwb.qmra/blob/binder-postBuild-toplevel/runtime.txt

[eric-wieser]

This is particularly annoying because you have a very narrow window of time to read the build logs before you get redirected to the notebook.

[betatim]

If your build fails you shouldn't get redirected (but you still only have the view we provide which is not optimal). Do you know which repository you tried where something went wrong and you get redirected?

The best option at the moment for debugging builds is to install https://github.com/jupyter/repo2docker on a machine pip install -U https://github.com/jupyter/repo2docker/archive/master.zip (we run master on mybinder.org). That way you get much nicer (IMHO) access to the logs and get faster debug cycles because you don't have to make a change, commit, push to GitHub, restart the build. You can rebuild as soon as you've locally edited your repo.

[eric-wieser]

The build didn't fail, but it ended up with an unintended set of dependencies installed, and I wasn't able to inspect the install log to work out what had happened (in this case, I wanted to know whether it was pulling an old version of something from the pip cache).

Generally, the issue is when a notebook fails during execution, and I want to inspect the build log to work out what's different between my machine and the failing remote machine.

[meeseeksmachine]

This issue has been mentioned on Jupyter Community Forum. There might be relevant details there:

https://discourse.jupyter.org/t/how-to-reduce-mybinder-org-repository-startup-time/4956/30

[betolink]

I just ran into an issue with postBuild but strangely enough, repo2docker works locally.

See the log file for details:  /tmp/jupyterlab-debug-xe5__czw.log
The command '/bin/sh -c ./binder/postBuild' returned a non-zero code: 1

So where can I find this jupyterlab-debug-xe5.log file? It would be super useful if these binder build logs were available when something goes wrong.

[betatim]

I think there are at least two issue that are coming up in this discussion:

One is about making the text you see scrolling by in the console during the build available inside the launched container. The second is about making the "failed build" image available (for example to inspect the jupyterlab log file). For the first there were some ideas but the second sounds like it is super hard.

In your particular case @betolink my guess/hunch is that your jupyterlab build uses too much RAM. There is a thread on https://discourse.jupyter.org/ discussing this but I can't refind it right now :-( It is about turning off the build minimisation in jupyterlab as that consumes a lot of memory.

[manics]

These are the threads:

• https://discourse.jupyter.org/t/tip-binder-jupyterlab-extension/6022
• https://discourse.jupyter.org/t/jupyter-lab-build-hangs-and-then-fails-at-webpack-config-webpack-prod-minimize-config-js/6017/3

[choldgraf]

could one solution around the "make failed build logs available" problem be to store the last N lines of a build's log and write it to a public location if a build fails?

Either way, I think that we all agree this is something that would be nice in BinderHub, the question is who is able to scope out a solution and then implement it. Perhaps we should either update the top-level comment of this issue with that background, or open a new issue that has a clear "to-do" feel to it. Since the Binder team doesn't have cycles to implement major new features etc, maybe this would make the problem something that a person in the broader community could make progress on

[betatim]

#1156 (what symmetry :D) is an attempt at writing up a more actionable version of this issue.

[betolink]

In my case what @betatim and @manics suggested did the trick. The postBuild minimization step was causing the error. Thanks for the tip!