LMS is not updating correctly

[schko]

Bug description
I added a subsection, and changed names of subsections on the Studio, but these aren't updating on the LMS.

How to reproduce

1. Add a new subsection, add grading option to it (optional),
2. Check LMS, this does not show on the course page (even after cache clear),
3. However, if you press Next on a visible subsection, you can track children all the way through subsections.
4. Certificates are not updated.

Environment
Ubuntu, installed using instructions found here: https://blog.lawrencemcdaniel.com/tutor-1-click-installer-open-edx-installation-guide/#8
tutor, version 3.6.0

Additional context

[schko]

Actually saw a quick fix to "tutor local stop" "tutor local start" that fixes the names and visibility of subsections, but was wondering if there was a reason why certification is still not showing up despite students meeting requirements?

[regisb]

Hi @schko! Please don't try to address two different problems in the same Github issue. I urge you to discuss the issues you face in the official forums prior to posting them here: https://discuss.overhang.io
In particular, your issue looks similar to https://discuss.overhang.io/t/content-issue-with-open-edx/262 Restarting the entire Open edX platform is not a proper fix, but it's a good lead to help us resolve the root issue.

[regisb]

I finally found some time to investigate this. I manage to reproduce the bug in tutor, but not in the devstack (ironwood.master release). Thus, this appears to be a bug with Tutor itself.

[regisb]

The closest lead I've got is an issue with the CMS worker, which appears to be responsible for clearing the memcached key that contains the course structure. For the demo course, this cache key is:

default:1:v2.root.key.block-v1%3AedX%2BDemoX%2BDemo_Course%2Btype%40course%2Bblock%40course

When I clear this cache key manually, the course structure is properly updated in the LMS.

Here is the prelude of the logs from the cms-worker:

$ tutor local logs cms-worker | head -200
docker-compose -f /home/data/regis/.local/share/tutor.local/env/local/docker-compose.yml --project-name tutor_local logs cms-worker
Attaching to tutor_local_cms-worker_1
WARNING:py.warnings:/openedx/edx-platform/lms/djangoapps/courseware/__init__.py:5: DeprecationWarning: Importing 'lms.djangoapps.courseware' as 'courseware' is no longer supported
  warnings.warn("Importing 'lms.djangoapps.courseware' as 'courseware' is no longer supported", DeprecationWarning)

2020-04-03 18:39:40,649 WARNING 1 [enterprise.utils] utils.py:50 - Could not import Registry from third_party_auth.provider
2020-04-03 18:39:40,650 WARNING 1 [enterprise.utils] utils.py:51 - cannot import name EnterpriseCustomerUser
2020-04-03 18:39:51,566 WARNING 1 [py.warnings] platforms.py:812 - /openedx/venv/local/lib/python2.7/site-packages/celery/platforms.py:812: RuntimeWarning: You are running the worker with superuser privileges, which is
absolutely not recommended!

Please specify a different user using the -u option.

User information: uid=0 euid=0 gid=0 egid=0

  uid=uid, euid=euid, gid=gid, egid=egid,

[2020-04-03 18:39:51,648: WARNING/MainProcess] /openedx/venv/local/lib/python2.7/site-packages/celery/apps/worker.py:161: CDeprecationWarning: 
Starting from version 3.2 Celery will refuse to accept pickle by default.

The pickle serializer is a security concern as it may give attackers
the ability to execute any command.  It's important to secure
your broker from unauthorized access when using pickle, so we think
that enabling pickle should require a deliberate action and not be
the default choice.

If you depend on pickle then you should set a setting to disable this
warning and to be sure that everything will continue working
when you upgrade to Celery 3.2::

    CELERY_ACCEPT_CONTENT = ['pickle', 'json', 'msgpack', 'yaml']

You must only enable the serializers that you will actually use.


  warnings.warn(CDeprecationWarning(W_PICKLE_DEPRECATED))

 
 -------------- celery@edx.cms.core.default.%80693ea1c349 v3.1.25 (Cipater)
---- **** ----- 
--- * ***  * -- Linux-4.15.0-91-generic-x86_64-with-Ubuntu-16.04-xenial
-- * - **** --- 
- ** ---------- [config]
- ** ---------- .> app:         proj:0x7f5963529850
- ** ---------- .> transport:   amqp://guest:**@rabbitmq:5672//
- ** ---------- .> results:     
- *** --- * --- .> concurrency: 4 (prefork)
-- ******* ---- 
--- ***** ----- [queues]
 -------------- .> edx.cms.core.default exchange=edx.cms.core(direct) key=edx.cms.core.default
                .> edx.cms.core.high exchange=edx.cms.core(direct) key=edx.cms.core.high

[tasks]
  . celery_utils.tasks.mark_resolved
  . cms.djangoapps.contentstore.tasks.CourseExportTask
  . cms.djangoapps.contentstore.tasks.CourseImportTask
  . cms.djangoapps.contentstore.tasks.async_migrate_transcript
  . cms.djangoapps.contentstore.tasks.async_migrate_transcript_subtask
  . cms.djangoapps.contentstore.tasks.export_olx
  . cms.djangoapps.contentstore.tasks.import_olx
  . cms.djangoapps.contentstore.tasks.push_course_update_task
  . cms.djangoapps.contentstore.tasks.rerun_course
  . cms.djangoapps.contentstore.tasks.task_scrape_youtube_thumbnail
  . cms.djangoapps.contentstore.tasks.task_scrape_youtube_thumbnail_callback
  . cms.djangoapps.contentstore.tasks.task_status_callback
  . cms.djangoapps.contentstore.tasks.update_library_index
  . cms.djangoapps.contentstore.tasks.update_search_index
  . cms_user_tasks.tasks.send_task_complete_email
  . contentstore.tasks.CourseExportTask
  . contentstore.tasks.CourseImportTask
  . contentstore.tasks.async_migrate_transcript
  . contentstore.tasks.async_migrate_transcript_subtask
  . contentstore.tasks.export_olx
  . contentstore.tasks.import_olx
  . contentstore.tasks.push_course_update_task
  . contentstore.tasks.rerun_course
  . contentstore.tasks.task_scrape_youtube_thumbnail
  . contentstore.tasks.task_scrape_youtube_thumbnail_callback
  . contentstore.tasks.task_status_callback
  . contentstore.tasks.update_library_index
  . contentstore.tasks.update_search_index
  . edx_sga.tasks.zip_student_submissions
  . entitlements.tasks.expire_old_entitlements
  . integrated_channels.integrated_channel.tasks.transmit_content_metadata
  . integrated_channels.integrated_channel.tasks.transmit_learner_data
  . integrated_channels.integrated_channel.tasks.unlink_inactive_learners
  . lms.djangoapps.discussion.tasks.send_ace_message
  . lms.djangoapps.discussion.tasks.update_discussions_map
  . lms.djangoapps.email_marketing.tasks.get_email_cookies_via_sailthru
  . lms.djangoapps.email_marketing.tasks.update_course_enrollment
  . lms.djangoapps.email_marketing.tasks.update_user
  . lms.djangoapps.email_marketing.tasks.update_user_email
  . lms.djangoapps.grades.tasks.compute_all_grades_for_course
  . lms.djangoapps.grades.tasks.compute_grades_for_course
  . lms.djangoapps.grades.tasks.compute_grades_for_course_v2
  . lms.djangoapps.grades.tasks.recalculate_course_and_subsection_grades_for_user
  . lms.djangoapps.grades.tasks.recalculate_subsection_grade_v3
  . openedx.core.djangoapps.content.block_structure.tasks.get_course_in_cache
  . openedx.core.djangoapps.content.block_structure.tasks.get_course_in_cache_v2
  . openedx.core.djangoapps.content.block_structure.tasks.update_course_in_cache
  . openedx.core.djangoapps.content.block_structure.tasks.update_course_in_cache_v2
  . openedx.core.djangoapps.coursegraph.tasks.dump_course_to_neo4j
  . openedx.core.djangoapps.credit.tasks.update_credit_course_requirements
  . openedx.core.djangoapps.schedules.tasks.ScheduleCourseUpdate
  . openedx.core.djangoapps.schedules.tasks.ScheduleMessageBaseTask
  . openedx.core.djangoapps.schedules.tasks.ScheduleRecurringNudge
  . openedx.core.djangoapps.schedules.tasks.ScheduleUpgradeReminder
  . openedx.core.djangoapps.schedules.tasks._course_update_schedule_send
  . openedx.core.djangoapps.schedules.tasks._recurring_nudge_schedule_send
  . openedx.core.djangoapps.schedules.tasks._upgrade_reminder_schedule_send
[2020-04-03 18:39:54,305: INFO/MainProcess] Connected to amqp://guest:**@rabbitmq:5672//
[2020-04-03 18:39:54,432: INFO/MainProcess] mingle: searching for neighbors
[2020-04-03 18:39:55,970: INFO/MainProcess] mingle: all alone
[2020-04-03 18:39:56,221: WARNING/MainProcess] celery@edx.cms.core.default.%80693ea1c349 ready.

Updating the course structure in the CMS generates the following logs in the cms-worker container:

...
[2020-04-03 18:58:45,203: INFO/Worker-4] POST http://elasticsearch:9200/_bulk [status:200 request:0.012s]
[2020-04-03 18:58:45,488: INFO/MainProcess] Received task: contentstore.tasks.update_search_index[258d7fc4-3407-4833-b75f-cdf99301b5fd]
[2020-04-03 18:58:45,498: INFO/Worker-3] HEAD http://elasticsearch:9200/courseware_index [status:200 request:0.003s]
[2020-04-03 18:58:45,608: INFO/MainProcess] Received task: openedx.core.djangoapps.content.block_structure.tasks.update_course_in_cache_v2[bd158ef0-31e4-45a0-b04e-294f775c2132] eta:[2020-04-03 14:59:15.572366-04:00]
[2020-04-03 18:58:45,635: INFO/Worker-3] HEAD http://elasticsearch:9200/courseware_index [status:200 request:0.008s]
[2020-04-03 18:58:45,687: INFO/MainProcess] Received task: lms.djangoapps.discussion.tasks.update_discussions_map[8e6a0e27-c23a-42b1-9884-8625cd83fe82] eta:[2020-04-03 14:59:15.632027-04:00]
[2020-04-03 18:58:45,720: INFO/Worker-3] POST http://elasticsearch:9200/_bulk [status:200 request:0.010s]
[2020-04-03 18:58:45,731: ERROR/MainProcess] Received unregistered task of type u'openedx.core.djangoapps.bookmarks.tasks.update_xblock_cache'.
The message has been ignored and discarded.

Did you remember to import the module containing this task?
Or maybe you are using relative imports?
Please see http://bit.ly/gLye1c for more information.

The full contents of the message body was:
{u'utc': True, u'chord': None, u'args': [u'course-v1:edX+DemoX+Demo_Course'], u'retries': 0, u'expires': None, u'task': u'openedx.core.djangoapps.bookmarks.tasks.update_xblock_cache', u'callbacks': None, u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'id': u'afbc2e6d-d805-4e09-a525-687215f19753'} (329b)
Traceback (most recent call last):
  File "/openedx/venv/local/lib/python2.7/site-packages/celery/worker/consumer.py", line 465, in on_task_received
    strategies[type_](message, body,
KeyError: u'openedx.core.djangoapps.bookmarks.tasks.update_xblock_cache'

There's also a bunch of the following errors:

[2020-04-03 18:50:41,970: ERROR/Worker-2] BlockStructure: update_course_in_cache_v2 encountered unknown error in course course-v1:edX+DemoX+Demo_Course, task_id 69e3ef5c-b322-4368-b45d-35d59fc617b3. Retry #5
Traceback (most recent call last):
  File "/openedx/edx-platform/openedx/core/djangoapps/content/block_structure/tasks.py", line 101, in _call_and_retry_if_needed
    api_method(course_key)
  File "/openedx/edx-platform/openedx/core/djangoapps/content/block_structure/api.py", line 29, in update_course_in_cache
    return get_block_structure_manager(course_key).update_collected_if_needed()
  File "/openedx/edx-platform/openedx/core/djangoapps/content/block_structure/manager.py", line 115, in update_collected_if_needed
    self._update_collected()
  File "/openedx/edx-platform/openedx/core/djangoapps/content/block_structure/manager.py", line 127, in _update_collected
    BlockStructureTransformers.collect(block_structure)
  File "/openedx/edx-platform/openedx/core/djangoapps/content/block_structure/transformers.py", line 80, in collect
    transformer.collect(block_structure)
  File "/openedx/edx-platform/lms/djangoapps/course_api/blocks/transformers/blocks_api.py", line 51, in collect
    StudentViewTransformer.collect(block_structure)
  File "/openedx/edx-platform/lms/djangoapps/course_api/blocks/transformers/student_view.py", line 63, in collect
    student_view_data = block.student_view_data()
  File "/openedx/edx-platform/common/lib/xmodule/xmodule/video_module/video_module.py", line 1147, in student_view_data
    for lang in available_translations
  File "/openedx/edx-platform/common/lib/xmodule/xmodule/video_module/video_module.py", line 1147, in <dictcomp>
    for lang in available_translations
  File "/openedx/edx-platform/common/lib/xmodule/xmodule/x_module.py", line 1499, in handler_url
    return descriptor_global_handler_url(block, handler_name, suffix, query, thirdparty)
  File "/openedx/edx-platform/cms/lib/xblock/runtime.py", line 14, in handler_url
    raise NotImplementedError("edX Studio doesn't support third-party xblock handler urls")
NotImplementedError: edX Studio doesn't support third-party xblock handler urls

I don't have time to investigate this further right now, but I acknowledge that this is a serious issue. The next step will be to compare the logs with those coming from the cms worker in the devstack. At this point, the best lead is probably the following error message: "Received unregistered task of type u'openedx.core.djangoapps.bookmarks.tasks.update_xblock_cache'." This might be due to a misconfigured CELERY_IMPORTS setting, but I don't understand why this setting would differ from the devstack in Tutor.

[cacciaresi]

Hi @regis, this pull request seems to fix first issue.:

`KeyError: u'openedx.core.djangoapps.bookmarks.tasks.update_xblock_cache'

This PR was not merged to ironwood.master, also there is another PR here with more info about it and it seems to validate that is a proper fix.

Maybe a quick test to add these changes to tutor settings for CMS can be useful to verify if the issue is solved.

The second issue:

NotImplementedError: edX Studio doesn't support third-party xblock handler urls

seems to be related with this issue: https://openedx.atlassian.net/browse/EDUCATOR-2679 I took a look but didn't fully understand what is going there, I've tried setting the waffle flag but still see the error. Trying to find info about it I found: #8 ;)

[regisb]

Good digging @cacciaresi! I didn't think to search for those errors. This was a really helpful clue. I must have spent at least an entire working day trying to understand this, so this was the hardest issue I resolved in a long time.

I wrote a long commit message to explain the underlying issue, so I'm not going to reproduce it here. Just take a look at: 48ca6eb

tl;dr: this should now work in production, and in development you should follow the instructions from the troubleshooting docs: https://docs.tutor.overhang.io/troubleshooting.html#when-i-make-changes-to-a-course-in-the-cms-they-are-not-taken-into-account-by-the-lms

@cacciaresi The reason why the waffle flag did not solve your issue is that you need to create a Waffle switch (yes, I know). It also took me a while to figure this out...

The following upstream PR helped me debug this issue: https://github.com/edx/edx-platform/pull/12689
I wish I could see this related Atlassian issue but unfortunately it's unavailable: https://openedx.atlassian.net/browse/TNL-4630

I will now create a new Tutor release to publish this solution.

@nasthagiri @efischer19 as the original authors of this feature, could you please confirm that in order to have an up-to-date course structure cache in the LMS, users need either to run the CMS with asynchronous celery workers, or define a waffle switch?

[cacciaresi]

Awesome! Thanks for the updates.

[kit-johnson]

This thread references "development" mode, as does the fix. How do I know if I'm using tutor in development mode or production mode?