More logic changes to error reporting, cleanup #3310

agjohnson · 2017-11-23T19:54:55Z

Alter project.task logic and include multiple points of error reporting during
build task
Build task returns true or false, not project data, which is unused anyways
New pattern for error messages
Localize error messages?
Make more specific error messages for repository error and project error
Remove unnecessary git/hg/bzr/svn exit codes and superfluous command data from
user errors
Add handling of git prompt for git 2.3+
Add errors for docker connection
Handle reporting on not able to connect to docker

agjohnson · 2017-11-23T19:57:16Z

Marked WIP, because:

Regression in reporting build finished in run_setup()
Not unittested yet
Need to play with exception translation pattern -- ultimately not worried about this yet, it will be an eventual improvement however.
Need to do more to catch an API exception with docker on memory issues and report this
Should actually write unittests around all of this

agjohnson · 2017-11-23T20:05:15Z

Also, I'm thinking that we need to move the vcs execution into a build environment, the error reporting with git stderr is sloppy, but there's no reason we can't just show this step to users. This will be a separate ticket.

humitos · 2017-11-23T21:07:15Z

readthedocs/doc_builder/environments.py

-        except DockerAPIError:
+        # Catch direct failures from Docker API, but also requests exceptions
+        # with the HTTP request
+        except (DockerAPIError, ConnectionError):
            log.error(LOG_TEMPLATE


isn't it better here to use log.exception ?

humitos · 2017-11-23T21:10:22Z

readthedocs/projects/exceptions.py


-    pass
+class ProjectConfigurationError(BuildEnvironmentError):


I think this class is missing the get_default_message method.

It should be inheriting this from BuildEnvironmentException

humitos · 2017-11-23T21:22:15Z

readthedocs/vcs_support/backends/git.py

@@ -58,10 +59,8 @@ def repo_exists(self):
    def fetch(self):
        code, _, err = self.run('git', 'fetch', '--tags', '--prune')


err could be _ now that's not used

humitos · 2017-11-23T21:22:34Z

readthedocs/vcs_support/backends/git.py

@@ -79,16 +78,7 @@ def clone(self):
        code, _, err = self.run('git', 'clone', '--recursive', '--quiet',


err could be _ now that's not used

humitos · 2017-11-23T21:29:24Z

readthedocs/vcs_support/backends/git.py

-                    sterr=err
-                )
-            )
+            raise RepositoryError


I think this is too much simpler that what we had, but what happen if there is another problem different than a private repository. I mean, the error message is very generic and we are not checking a specific error code:

For example:

[humitos@julia:tmp]$ GIT_TERMINAL_PROMPT=0 git clone https://github.com/readthedocs/readthedocs-corporate Clonando en 'readthedocs-corporate'... fatal: could not read Username for 'https://github.com': terminal prompts disabled [humitos@julia:tmp]$ echo $? 128

Ha, it doesn't seem to have a different error code:

[humitos@julia:tmp]$ LANG=C git clone [email protected]:rtfd/readthedocs Cloning into 'readthedocs'... ERROR: Repository not found. fatal: Could not read from remote repository. Please make sure you have the correct access rights and the repository exists. [humitos@julia:tmp]$ echo $? 128

Anyway, I think this is not really important if we don't have history/logs failing at these points because something different than a private repository.

I agree, but this would be out of scope for this work, and would be best served by surfacing the commands we execute to users. Currently, the checkout step is hidden because it uses it's own shell execution. This could be easily moved into a BuildCommand executed through the setup environment. This way, users can actually see the output in a meaningful way.

I like your proposal of moving it inside a BuildCommand and I agree it could be done in another PR.

humitos · 2017-11-23T21:46:04Z

readthedocs/projects/tasks.py

@@ -127,24 +126,40 @@ def run(self, pk, version_pk=None, build_pk=None, record=True,
            self.config = None

            setup_successful = self.run_setup(record=record)
-            if setup_successful:
-                self.run_build(record=record, docker=docker)
+            if not setup_successful:


I think there is something missing here. If the build fails because of the setup at this point: https://github.com/rtfd/readthedocs.org/pull/3310/files#diff-b9399e1d3499066c5564f98a620e8881R198

we are not raising any exception, so run_setup method just returns False and the task return False but nobody is updating the self.setup_env.build['error'] as we do when unhandled exception is catched at https://github.com/rtfd/readthedocs.org/pull/3310/files#diff-b9399e1d3499066c5564f98a620e8881R137 or https://github.com/rtfd/readthedocs.org/pull/3310/files#diff-b9399e1d3499066c5564f98a620e8881R154

Also, I think that's better to move this line https://github.com/rtfd/readthedocs.org/pull/3310/files#diff-b9399e1d3499066c5564f98a620e8881R207 inside this if, so we try to update the build state in not so many places

Links above have disconnected here, so hard to follow what's happening, but i think i understand this feedback.

So update of the build now always happens on build env __exit__, so we can just return false from the task.

In the case that another exception is raised outside the env, we still run update_build from the exception.

Is this logic ^^ documented somewhere?

Yup, on the environment class. I can expand more.

I'm using BuildEnvironmentError for now, but we should use ProjectConfigurationError once the PR got merged: #3310

ericholscher · 2017-11-29T19:42:50Z

Feel like this is a biggish change, which might conflict over time -- should try and get tests passing and work done, and then I'll review it.

* Alter project.task logic and include multiple points of error reporting during build task * Build task returns true or false, not project data, which is unused anyways * New pattern for error messages * Localize error messages? * Make more specific error messages for repository error and project error * Remove unnecessary git/hg/bzr/svn exit codes and superfluous command data from user errors * Add handling of git prompt for git 2.3+ * Add errors for docker connection * Handle reporting on not able to connect to docker * Add finalize argument to environments

agjohnson · 2017-11-29T22:30:16Z

Test failure was unrelated. Work is rebased to get CI fix

Our old tests weren't correctly testing the api calls at all. This expands our environment tests to actually test for build state updates.

agjohnson · 2017-11-30T17:42:32Z

Unittests around doc build environments have been made working, and more have been added.

a9c2a22 is lint clean up, review that separately.

ericholscher · 2017-11-30T17:48:55Z

How do I review it seperately?

humitos · 2017-11-30T18:27:39Z

You can select a range of commits to review from the top left dropdown: https://github.com/rtfd/readthedocs.org/pull/3310/files/0fd836669a2a3f87866634c534d3a32c7dff462b

(just the 2 commits to review with logic)

ericholscher · 2017-11-30T18:30:07Z

@humitos thanks!

ericholscher · 2017-11-30T18:31:44Z

readthedocs/doc_builder/environments.py

@@ -294,7 +297,7 @@ def __enter__(self):

    def __exit__(self, exc_type, exc_value, tb):
        ret = self.handle_exception(exc_type, exc_value, tb)
-        self.build['state'] = BUILD_STATE_FINISHED
+        self.update_build(BUILD_STATE_FINISHED)


Won't this post that status to the API? Seems like we don't want to publish here, but only below if finalize is False.

The finalize check is in update_build, so it should only post if finalize is True

Gah ok. Lost that in the review.

ericholscher · 2017-11-30T18:32:50Z

readthedocs/doc_builder/environments.py

+        except BuildEnvironmentError:
+            # There may have been a problem connecting to Docker altogether, or
+            # some other handled exception here.
+            self.__exit__(*sys.exc_info())


Will this not automatically call __exit__?

It won't, because this is raised in __enter__. Errors raised in __enter__ raise to the parent context, so we have to explicitly clean up here.

ericholscher · 2017-11-30T18:39:25Z

readthedocs/projects/exceptions.py


-    pass
+class ProjectConfigurationError(BuildEnvironmentError):


It seems we have a BuildEnvironmentException and a BuildEnvironmentError, what is the difference? Seems confusing..

Exception is the base class, Error is the specific class that kills a build and reports to a user, Warning also is absed on Exception and doesn't kill the build.

ericholscher · 2017-11-30T18:40:12Z

readthedocs/projects/exceptions.py

+    PRIVATE_REPO = _(
+        'There was a problem connecting to your repository, '
+        'ensure that your repository URL is correct.'
+    )


If it's a private repo, shouldn't we warn them here? Why are these messages the same?

We aren't thoroughly testing if this was a private repo or not, we'd have to grep the git output. @humitos raised a similar question and the best answer is to execute checkout in a build environment and report the commands, not parse them to determine what the error was.

Messages aren't the same, but usage could be clearer. I should probably rename these constants, as PRIVATE_REPO is raised if we support private repositories -- that is, we tell the user "check your url, because it wasn't the repository privacy that caused the problem. PUBLIC_REPO error is "check your url or your project privacy, because we don't support private repositories."

In fact, I'll update the copy here to be more explicit about repo privacy.

ericholscher · 2017-11-30T18:42:05Z

readthedocs/projects/tasks.py

@@ -127,24 +126,40 @@ def run(self, pk, version_pk=None, build_pk=None, record=True,
            self.config = None

            setup_successful = self.run_setup(record=record)
-            if setup_successful:
-                self.run_build(record=record, docker=docker)
+            if not setup_successful:


Is this logic ^^ documented somewhere?

ericholscher · 2017-11-30T18:43:04Z

readthedocs/projects/tasks.py

+                    'Please include the build id ({build_id}) in any bug reports.'.format(
+                        build_id=build_pk
+                    ))
+                self.build_env.update_build(BUILD_STATE_FINISHED)


Another place we're updating build finished..?

It seems this is what we want, no? This is the fallback that was added in case there are any exceptions outside of the build environment __enter__, normal context, or in __exit__, such as in run_build.

Ah, ok. I got lost when reviewing this for some reason, and didn't realize where everything was getting called from.

ericholscher · 2017-11-30T18:44:40Z

readthedocs/rtd_tests/tests/test_doc_building.py

+            'setup': u'',
+            'output': u'',
+            'state': u'finished',
+            'builder': u'foo'


All these listings of massive argument lists seem brittle (it will break whenever we add/change/remove/ an argument). Can we just check for the actual value we care about being called, presumably error?

Test are failing because of this, in fact:

'length': <ANY>

Besdies, it's complicated to find the differences when it fails. In case you want to leave as it is now, I'd suggest to use assertDictEqual

ericholscher · 2017-11-30T18:46:50Z

readthedocs/vcs_support/backends/git.py

-                "Failed to get code from '%s' (git fetch): %s\n\nStderr:\n\n%s\n\n" % (
-                    self.repo_url, code, err)
-            )
+            raise RepositoryError


Do we want to lose the specifics of these errors?

I think surfacing an error that is helpful provides more user guidance -- that is, showing a failed checkout command isn't clear to the user that the problem is their configuration. I think the ultimate fix here is to do both and show the command execution as a BuildCommand. I removed this for now, for consistency on errors and because displaying the stderr output like this looked sloppy. I think we can pretty quickly move towards combining execution environments though.

I think that having both in the future is better.

I like the idea of communicate the "common problem" to the user in a very simplified way, but also show the output (that could be used when debugging something and could help the user to understand it better -also if the problem is something different that we are reporting as simplified way)

humitos

I'd suggest to take a look at finalize new attribute since I think that doesn't work as you expect.

I'm not sure to understand how the test works, but since I think that attribute breaks the intermediate state of the building I would sugget to write a test to check that.

humitos · 2017-11-30T18:29:31Z

readthedocs/doc_builder/backends/sphinx.py

            trace = sys.exc_info()[2]
-            six.reraise(ProjectImportError('Conf file not found'), None, trace)
+            six.reraise(


Why do we need this six.reraise? It's not the same than just raise ProjectImportError(...)?

I'm not sure either, the docs aren't clear to me:
https://pythonhosted.org/six/#six.reraise

I'll leave it, assuming someone with more knowledge of py2/3 compat did this :)

humitos · 2017-11-30T18:34:32Z

readthedocs/doc_builder/environments.py

@@ -275,15 +276,17 @@ class BuildEnvironment(object):
    :param build: Build instance
    :param record: Record status of build object
    :param environment: shell environment variables
+    :param finalize: finalize the build by setting a finished state on exit


this sentence is True only if the update_build method is called with the BUILD_STATE_FINISHED status, otherwise that method will just update the build, but not finalize it

Ah true. I didn't like finalize either. I'll rename this commit to match the Django usage. Would this change make more sense?

maybe the commit should be in the update_build method to avoid the other problems that I mentioned

humitos · 2017-11-30T18:37:22Z

readthedocs/doc_builder/environments.py

+            try:
+                client.kill(self.container_id)
+            except DockerAPIError:
+                pass


what about logging something here (DEBUG level, maybe)?

humitos · 2017-11-30T18:38:44Z

readthedocs/doc_builder/environments.py

+                log.info('Removing container %s', self.container_id)
+                client.remove_container(self.container_id)
+            # Catch direct failures from Docker API, but also requests exceptions
+            # with the HTTP request. These should not


"These should not" ?

humitos · 2017-11-30T18:41:47Z

readthedocs/doc_builder/environments.py

+                    ),
+                )
+            self.container = None
+        except BuildEnvironmentError:


I'm not following this. I think it's not possible to BuildEnvironmentError be raised in the try: block here. What could be the case?

get_client raises a BuildEnvironmentError on failure here. I'll rethink refactoring this as well though, perhaps a more specific exception, or allowing the docker exception to bubble up makes more sense.

humitos · 2017-11-30T18:52:52Z

readthedocs/projects/tasks.py

-            if unhandled_failure:
-                self.build_env.build['error'] = unhandled_failure
-            self.build_env.update_build(BUILD_STATE_FINISHED)
+            self.setup_env.update_build(BUILD_STATE_FINISHED)


Since self.setup_env was instantiated with finalize=False this won't work.

Ah yes, good catch!

humitos · 2017-11-30T18:55:53Z

readthedocs/projects/tasks.py

@@ -297,19 +313,10 @@ def setup_vcs(self):
        self.setup_env.update_build(state=BUILD_STATE_CLONING)


Also a problem here. The build won't update with this status since it's finalize=False.

* Removes some redundant calls to update build objects * Updates some docs * Logic behind update_build is improved to update in more cases * Tests for incremental updates

agjohnson · 2017-12-01T00:20:18Z

Okay! There is even more logic now. I believe I've addressed all of the feedback and have dropped in a bunch more docs while this is fresh. One last pass would be a good idea

humitos · 2017-12-01T00:24:48Z

I'd like to take a look a it tomorrow El 30 nov. 2017 7:20 p. m., "Anthony" <[email protected]> escribió: Okay! There is even more logic now. I believe I've addressed all of the feedback and have dropped in a bunch more docs while this is fresh. One last pass would be a good idea — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#3310 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAO7sPgtnD0HvbdUwdy6V-2uf1OnhTI1ks5s70ZDgaJpZM4QpJDD> .

agjohnson · 2017-12-05T23:36:10Z

Pinging @humitos ☎️

humitos

I don't want to block this PR. I think we can continue from here in another PR later.

I left some comments that can be done in this PR and some, though. Like typos, messages in logs or docstrings.

humitos · 2017-12-01T00:01:11Z

readthedocs/doc_builder/environments.py


        # Attempt to stop unicode errors on build reporting
        for key, val in list(self.build.items()):
            if isinstance(val, six.binary_type):
                self.build[key] = val.decode('utf-8', 'ignore')

-        if self.finalize:
+        # We are selective about when we update the build object here
+        update_build = (


I think the use of any is clearer here, instead of ors

humitos · 2017-12-06T15:03:36Z

readthedocs/doc_builder/environments.py

+
+    We only update the build through the API in one of three cases:
+
+    * The build is not done and needs incremental builds


What is an incremental build?

humitos · 2017-12-06T15:06:38Z

readthedocs/doc_builder/environments.py


    :param project: Project that is being built
    :param version: Project version that is being built
    :param build: Build instance
    :param record: Record status of build object
    :param environment: shell environment variables
+    :param commit: update the build object via API if the build was successful


I think this is still confusing.

When commit=True (the default) and we are in the middle of the build, the build won't be updated. So, I think this should have a better name (if that is possible) like last_command, since I think it's more representative of what it measn.

Anyway, I don't see the best solution very clear.

probably the most explicit we can is update_on_success

humitos · 2017-12-06T15:12:12Z

readthedocs/doc_builder/environments.py

-        for the build)
+        This step is skipped if we aren't recording the build. To avoid
+        recording successful builds yet (for instance, running setup commands for
+        the build), set the ``commit`` argument on environment instantiation.


set the commit argument to False

humitos · 2017-12-06T15:18:40Z

readthedocs/doc_builder/environments.py

+            try:
+                api_v2.build(self.build['id']).put(self.build)
+            except HttpClientError as e:
+                log.error("Unable to post a new build: %s", e.content)


Unable to update the build: and maybe add the build id also to the log

humitos · 2017-12-06T15:20:20Z

readthedocs/doc_builder/environments.py

+                client.kill(self.container_id)
+            except DockerAPIError:
+                log.exception(
+                    'Unable to remove container: id=%s',


Unable to kill the container

humitos · 2017-12-06T15:21:39Z

readthedocs/doc_builder/environments.py

+                LOG_TEMPLATE.format(
+                    project=self.project.slug,
+                    version=self.version.slug,
+                    msg='Could not connection to Docker API',


Could not connect

humitos · 2017-12-06T15:23:47Z

readthedocs/doc_builder/environments.py

+                    msg=e,
+                ),
+            )
+            raise BuildEnvironmentError('There was a problem connecting to Docker')


Here, the problem is similar than https://github.com/rtfd/readthedocs.org/pull/3310/files#diff-ca52b098301dd315a834b3556ab9a7d5R638 but in this case we are communicating the Docker error to the user.

…bute Fixes the last of review feedback

agjohnson · 2017-12-07T16:13:33Z

@humitos Thanks for the thorough feedback! I'm just waiting on a final CI test here. If changes look good, lets merge!

agjohnson added the PR: work in progress Pull request is not ready for full review label Nov 23, 2017

humitos reviewed Nov 23, 2017

View reviewed changes

humitos added a commit that referenced this pull request Nov 27, 2017

Show proper error to user when conf.py is not found

e78be57

I'm using BuildEnvironmentError for now, but we should use ProjectConfigurationError once the PR got merged: #3310

humitos mentioned this pull request Nov 27, 2017

Show proper error to user when conf.py is not found #3326

Merged

agjohnson force-pushed the agj/more-build-error-reporting branch from ccc6fa6 to 95b94b1 Compare November 27, 2017 22:44

agjohnson force-pushed the agj/more-build-error-reporting branch from 95b94b1 to 47df9ee Compare November 29, 2017 22:28

agjohnson added 2 commits November 30, 2017 10:35

Fix up unittests

0fd8366

Our old tests weren't correctly testing the api calls at all. This expands our environment tests to actually test for build state updates.

Lint cleanup on test file

a9c2a22

agjohnson added PR: ready for review and removed PR: work in progress Pull request is not ready for full review labels Nov 30, 2017

agjohnson requested review from ericholscher and humitos November 30, 2017 17:43

ericholscher reviewed Nov 30, 2017

View reviewed changes

humitos reviewed Nov 30, 2017

View reviewed changes

agjohnson added 3 commits November 30, 2017 16:48

Feedback, more testing, logic changes

bacef7e

* Removes some redundant calls to update build objects * Updates some docs * Logic behind update_build is improved to update in more cases * Tests for incremental updates

Fix hostname in tests

4c3904e

More docs

d7513a6

humitos approved these changes Dec 6, 2017

View reviewed changes

Update some logging strings, alter docker error, change name of attri…

3bf4b9c

…bute Fixes the last of review feedback

agjohnson force-pushed the agj/more-build-error-reporting branch from 14899cc to 3bf4b9c Compare December 7, 2017 16:11

humitos approved these changes Dec 7, 2017

View reviewed changes

agjohnson added 2 commits December 7, 2017 10:51

Fix test arguments

f2e4096

Merge branch 'master' into agj/more-build-error-reporting

28f00a6

agjohnson merged commit ba20191 into master Dec 7, 2017

agjohnson deleted the agj/more-build-error-reporting branch December 7, 2017 18:19

humitos mentioned this pull request Dec 18, 2017

Fix up error messages that happen outside build environment #2512

Closed

		@@ -58,10 +59,8 @@ def repo_exists(self):
		def fetch(self):
		code, _, err = self.run('git', 'fetch', '--tags', '--prune')

		@@ -79,16 +78,7 @@ def clone(self):
		code, _, err = self.run('git', 'clone', '--recursive', '--quiet',

		@@ -297,19 +313,10 @@ def setup_vcs(self):
		self.setup_env.update_build(state=BUILD_STATE_CLONING)


		We only update the build through the API in one of three cases:

		* The build is not done and needs incremental builds

More logic changes to error reporting, cleanup #3310

More logic changes to error reporting, cleanup #3310

Conversation

agjohnson commented Nov 23, 2017

agjohnson commented Nov 23, 2017 • edited Loading

agjohnson commented Nov 23, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ericholscher commented Nov 29, 2017

agjohnson commented Nov 29, 2017 • edited Loading

agjohnson commented Nov 30, 2017

ericholscher commented Nov 30, 2017

humitos commented Nov 30, 2017

ericholscher commented Nov 30, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

humitos left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

agjohnson commented Dec 1, 2017

humitos commented Dec 1, 2017 via email

agjohnson commented Dec 5, 2017

humitos left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

agjohnson commented Dec 7, 2017

agjohnson commented Nov 23, 2017 •

edited

Loading

agjohnson commented Nov 29, 2017 •

edited

Loading