After build is triggered, state is shown as failed #3644

agjohnson · 2018-02-20T18:35:19Z

To reproduce, fire off a new build, make sure to catch the build list page while VCS operations are happening. Build will be in a failure state. This is a regression where we are setting the state of the build to failed without checking that the build has completed. This might be a byproduct of using multiple environments during the build process.

agjohnson · 2018-02-20T22:01:04Z

@davidfischer noted he also saw this in production, which means it might not even be related to the VCS changes

humitos · 2018-02-21T18:10:16Z

Mmm...

I'm not able to reproduce this in my local instance with master branch. I see the states: Triggered, Clonning and Installing without problem.

humitos · 2018-02-21T18:11:25Z

Same behaviour in .org production

stsewd · 2018-02-21T18:19:28Z

@humitos I also experiment this behavior on my local instance:

Build any project
Enter to the build (failure is shown)
Wait ~5 seconds, reload the page
Build is continued and successful

I haven't see this on production, yet.

agjohnson · 2018-02-22T17:48:51Z

@stsewd i get the same results as you once i click on the build, but the build list page is where i see a failure.

Another clue: I can reproduce on first build of the project, not afterwards though.

stsewd · 2018-02-23T02:37:23Z

@humitos I think the problem is with a project without tags.

If I ran this command on a project without tags, the exit code is 1 (here the build is marked as failure).

Then on another step the exit code is forced to be 0 (here is when the build goes back to the normality)

agjohnson · 2018-02-23T17:48:43Z

Another clue: if I build the same project, the second build doesn't initially show the build as failing in the build list, but if I quickly select the build, it's in a failed state by the end of the VCS commands:

This also causes the page to stop loading the build commands from the API, as we halt this process with JS when a build has failed. Reloading the page, I see I failed on the next command.

This is causing the build to be marked as FAILED when the repository has no branches. Closes #3644

humitos · 2018-03-06T21:41:57Z

I checked this again and I found something new:

I triggered a stable build
I kill my celery instance because it gets stucked
The build is in Triggered
I run celery again
I re-trigger the stable build
I get this error

Also, I have this crazy log in my debug.log

[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING --- Logging error ---
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING Traceback (most recent call last):
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/doc_builder/backends/sphinx.py", line 148, in append_conf
    self.version.get_conf_py_path()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/builds/models.py", line 228, in get_conf_py_path
    conf_py_path = self.project.conf_dir(self.slug)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/projects/models.py", line 557, in conf_dir
    conf_file = self.conf_file(version)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/projects/models.py", line 553, in conf_file
    ProjectConfigurationError.NOT_FOUND
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING readthedocs.projects.exceptions.ProjectConfigurationError: A configuration file was not found. Make sure you have a conf.py file in your repository.
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING During handling of the above exception, another exception occurred:
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING Traceback (most recent call last):
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/projects/tasks.py", line 399, in run_build
    outcomes = self.build_docs()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/projects/tasks.py", line 583, in build_docs
    outcomes['html'] = self.build_docs_html()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/projects/tasks.py", line 600, in build_docs_html
    html_builder.append_conf()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/doc_builder/backends/sphinx.py", line 151, in append_conf
    self._write_config(master_doc=master_doc)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/doc_builder/backends/sphinx.py", line 63, in _write_config
    safe_write(conf_file, conf_template)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/projects/utils.py", line 125, in safe_write
    fh.write(contents.encode('utf-8', 'ignore'))
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING TypeError: write() argument must be str, not SafeBytes
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING During handling of the above exception, another exception occurred:
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING Traceback (most recent call last):
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/lib/python3.6/logging/__init__.py", line 995, in emit
    stream.write(self.terminator)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING OSError: [Errno 5] Input/output error
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING Call stack:
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/rtd3/bin/celery", line 11, in <module>
    sys.exit(main())
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/__main__.py", line 14, in main
    _main()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bin/celery.py", line 326, in main
    cmd.execute_from_commandline(argv)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bin/celery.py", line 488, in execute_from_commandline
    super(CeleryCommand, self).execute_from_commandline(argv)))
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bin/base.py", line 281, in execute_from_commandline
    return self.handle_argv(self.prog_name, argv[1:])
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bin/celery.py", line 480, in handle_argv
    return self.execute(command, argv)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bin/celery.py", line 412, in execute
    ).run_from_argv(self.prog_name, argv[1:], command=argv[0])
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bin/worker.py", line 221, in run_from_argv
    return self(*args, **options)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bin/base.py", line 244, in __call__
    ret = self.run(*args, **kwargs)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bin/worker.py", line 256, in run
    worker.start()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/worker/worker.py", line 203, in start
    self.blueprint.start(self)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bootsteps.py", line 119, in start
    step.start(parent)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/bootsteps.py", line 370, in start
    return self.obj.start()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/concurrency/base.py", line 131, in start
    self.on_start()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/concurrency/prefork.py", line 112, in on_start
    **self.options)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/concurrency/asynpool.py", line 422, in __init__
    super(AsynPool, self).__init__(processes, *args, **kwargs)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/pool.py", line 1007, in __init__
    self._create_worker_process(i)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/concurrency/asynpool.py", line 439, in _create_worker_process
    return super(AsynPool, self)._create_worker_process(i)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/pool.py", line 1116, in _create_worker_process
    w.start()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/process.py", line 124, in start
    self._popen = self._Popen(self)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/context.py", line 333, in _Popen
    return Popen(process_obj)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/popen_fork.py", line 24, in __init__
    self._launch(process_obj)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/popen_fork.py", line 79, in _launch
    code = process_obj._bootstrap()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/process.py", line 327, in _bootstrap
    self.run()
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/process.py", line 114, in run
    self._target(*self._args, **self._kwargs)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/pool.py", line 289, in __call__
    sys.exit(self.workloop(pid=pid))
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/billiard/pool.py", line 358, in workloop
    result = (True, prepare_result(fun(*args, **kwargs)))
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/app/trace.py", line 537, in _fast_trace_task
    uuid, args, kwargs, request,
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/app/trace.py", line 374, in trace_task
    R = retval = fun(*args, **kwargs)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/.pyenv/versions/3.6.4/envs/rtd3/lib/python3.6/site-packages/celery/app/trace.py", line 629, in __protected_call__
    return self.run(*args, **kwargs)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/projects/tasks.py", line 297, in run
    self.run_build(record=record, docker=docker)
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/projects/tasks.py", line 414, in run_build
    log.warning('No build ID, not syncing files')
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING File "/home/humitos/rtfd/code/readthedocs.org/readthedocs/doc_builder/environments.py", line 720, in __exit__
    msg='Build finished'))
[06/Mar/2018 15:39:29] celery.redirected:235[20794]: WARNING Message: '(Build) [discoin:stable] Build finished'
Arguments: ()

humitos · 2018-03-06T22:04:02Z

I have more clues...

First, the issue happen when RTD doesn't find a conf.py and raises ProjectConfigurationError. That exception is being handled by our code by creating a conf.py based in a template, so we call render_to_string that returns a django.utils.safestring.SafeText the one that we pass to safe_write which encodes it to utf8 and call fh.write with a django.utils.safestring.SafeBytes which fails.

So, at that time, I think the Build is marked as FAILED but since it's an intermediate step that "it's OK to failed" (ProjectConfigurationError is not a error to abort) RTD continue building the docs.

I'm not 100% sure yet, but I wanted to write this down before I forget :)

humitos · 2018-03-06T22:17:35Z

I just noticed that even after closing Celery, there were some celery process around and that probably made things goes that crazy.

humitos · 2018-03-07T00:26:04Z

OK, I have two suppositions here:

go crazy with celery processes
this happen when running django and celery with Py3 and the project doesn't have a proper index.rst (or raise ProjectConfigurationError for some other reason that is not that terrible to abort the build).

I created a PR at #3745 that should fix number 2). I've been trying to replicate the error on that branch and I wasn't able to. I'd like you to take a look and try to test it.

I'm not sure if 1) worth to test it, since it's an edge case and we shouldn't be running multiple celery processes. I will give it a try, though.

agjohnson added the Bug A bug label Feb 20, 2018

agjohnson added this to the Build output page milestone Feb 20, 2018

agjohnson assigned humitos Feb 20, 2018

humitos added the Needed: replication Bug replication is required label Feb 21, 2018

humitos mentioned this issue Feb 22, 2018

Tip message on build page #3652

Closed

humitos added a commit that referenced this issue Feb 27, 2018

Always record the git branch command as success

8d26a7c

This is causing the build to be marked as FAILED when the repository has no branches. Closes #3644

humitos mentioned this issue Feb 27, 2018

Always record the git branch command as success #3693

Merged

humitos mentioned this issue Mar 6, 2018

Auto-generate conf.py compatible with Py2 and Py3 #3745

Merged

agjohnson closed this as completed in 1edd47a Mar 9, 2018

agjohnson reopened this Mar 9, 2018

humitos mentioned this issue Mar 22, 2018

Update instance and model when record_as_success #3831

Merged

agjohnson closed this as completed in #3831 Mar 22, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

After build is triggered, state is shown as failed #3644

After build is triggered, state is shown as failed #3644

agjohnson commented Feb 20, 2018

agjohnson commented Feb 20, 2018

humitos commented Feb 21, 2018

humitos commented Feb 21, 2018

stsewd commented Feb 21, 2018 •

edited

Loading

agjohnson commented Feb 22, 2018

stsewd commented Feb 23, 2018

agjohnson commented Feb 23, 2018

humitos commented Mar 6, 2018

humitos commented Mar 6, 2018

humitos commented Mar 6, 2018

humitos commented Mar 7, 2018

After build is triggered, state is shown as failed #3644

After build is triggered, state is shown as failed #3644

Comments

agjohnson commented Feb 20, 2018

agjohnson commented Feb 20, 2018

humitos commented Feb 21, 2018

humitos commented Feb 21, 2018

stsewd commented Feb 21, 2018 • edited Loading

agjohnson commented Feb 22, 2018

stsewd commented Feb 23, 2018

agjohnson commented Feb 23, 2018

humitos commented Mar 6, 2018

humitos commented Mar 6, 2018

humitos commented Mar 6, 2018

humitos commented Mar 7, 2018

stsewd commented Feb 21, 2018 •

edited

Loading