SE-2208 debugging page loads

[samuelallan72]

Add debug logging to help debug SE-2088.

[itsjeyd]

@swalladge I had a couple small suggestions but otherwise this looks good and should help with debugging the process of rendering contents of specific units in Studio.

Before deploying this, please rebase the changes on the feature branch of #14 (pooja/cherry-pick-pymongo-upgrade). Both stage and prod are currently running code from this branch (see this comment for additional details).

[samuelallan72]

@itsjeyd nits addressed and rebased on pooja/cherry-pick-pymongo-upgrade. :) Ok to deploy to stage, sanity check, then deploy to prod?

[samuelallan72]

Also a lot of unit tests are failing; not sure if they're related or not.

[itsjeyd]

@swalladge

nits addressed and rebased on pooja/cherry-pick-pymongo-upgrade. :)

Thanks!

Also a lot of unit tests are failing; not sure if they're related or not.

Most of them likely aren't -- the reason why we didn't merge #14 yet is because it didn't get a green build. So any failure that shows up here as well as on #14 is probably safe to ignore.

I noticed that the latest build for this PR includes some failures that seem related to the changes being applied here, for example:

======================================================================
ERROR: test_render_author_view (xmodule.tests.test_conditional.ConditionalModuleStudioTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/project/common/lib/xmodule/xmodule/tests/test_conditional.py", line 415, in test_render_author_view
    html = self.module_system.render(self.conditional, AUTHOR_VIEW, context).content
  File "/root/project/common/lib/xmodule/xmodule/x_module.py", line 1306, in render
    return super(MetricsMixin, self).render(block, view_name, context=context)
  File "/tmp/workspace/venv/local/lib/python2.7/site-packages/xblock/runtime.py", line 808, in render
    frag = view_fn(context)
  File "/root/project/common/lib/xmodule/xmodule/conditional_module.py", line 200, in author_view
    self.render_children(context, fragment, can_reorder=True, can_add=True)
  File "/root/project/common/lib/xmodule/xmodule/studio_editable.py", line 26, in render_children
    rendered_child = child.render(StudioEditableModule.get_preview_view_name(child), context)
  File "/tmp/workspace/venv/local/lib/python2.7/site-packages/xblock/core.py", line 202, in render
    return self.runtime.render(self, view, context)
  File "/root/project/common/lib/xmodule/xmodule/x_module.py", line 1901, in render
    return self.__getattr__('render')(block, view_name, context)
  File "/root/project/common/lib/xmodule/xmodule/x_module.py", line 1303, in render
    log.warning("SE2208 RENDER [block]: %s", block)
  File "/usr/lib/python2.7/logging/__init__.py", line 1179, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1286, in _log
    self.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1296, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1336, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 759, in handle
    self.emit(record)
  File "/tmp/workspace/venv/local/lib/python2.7/site-packages/nose/plugins/logcapture.py", line 82, in emit
    self.buffer.append(self.format(record))
  File "/usr/lib/python2.7/logging/__init__.py", line 734, in format
    return fmt.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 465, in format
    record.message = record.getMessage()
  File "/usr/lib/python2.7/logging/__init__.py", line 329, in getMessage
    msg = msg % self.args
  File "/root/project/common/lib/xmodule/xmodule/x_module.py", line 847, in __unicode__
    return u'<x_module(id={0})>'.format(self.id)
AttributeError: 'HtmlModuleWithMixins' object has no attribute 'id'

Things seem to be going south when reaching the following line?

  File "/root/project/common/lib/xmodule/xmodule/x_module.py", line 1303, in render
    log.warning("SE2208 RENDER [block]: %s", block)

Ok to deploy to stage, sanity check, then deploy to prod?

Not quite, test failures unique to this PR need checking first.

[samuelallan72]

@itsjeyd hmm that's not an issue with the log line, that's an issue with some module not having an id attribute that the __unicode__() method expects...

  File "/root/project/common/lib/xmodule/xmodule/x_module.py", line 847, in __unicode__
    return u'<x_module(id={0})>'.format(self.id)
AttributeError: 'HtmlModuleWithMixins' object has no attribute 'id'

I'll remove that log line.

[itsjeyd]

@swalladge Looks like the follow-up changes that you pushed made the cms_unit_tests pass again, and the failure keeping lib_unit_tests from turning green is the same as the one from #14. That's good news.

The output of lms_unit_tests for this PR is still different from what we got for #14 on the latest build although I couldn't find any obvious indication that the changes being introduced here are what's causing this difference.

We need to get this into production and start using it to diagnose the Studio issue soon, so perhaps just go ahead and deploy and sanity-check it on stage during the night IST. And then if there are no obvious issues you can go ahead and do the prod deployment right away, to have that happen during low-traffic hours as well.

To help prepare I'll start building an AMI for stage now.

[itsjeyd]

@swalladge The AMI for stage built successfully, see https://admin.edx-flatu.org:8080/job/build-ami/110/.

[itsjeyd]

Reasons for closing, for future reference.