Andal.LND/edx-platform
4
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

Add missing import logs. (#27066)

Browse Source
This commit is contained in:
Awais Jibran
2021-03-22 15:28:13 +05:00
committed by GitHub
parent 41c1d237eb
commit 5f773d326d
5 changed files with 164 additions and 74 deletions
Download Patch File Download Diff File Expand all files Collapse all files

148
cms/djangoapps/contentstore/tasks.py
View File

@@ -2,7 +2,6 @@
This file contains celery tasks for contentstore views
"""
import base64
import json
import os
@@ -22,7 +21,13 @@ from django.core.files import File
from django.test import RequestFactory
from django.utils.text import get_valid_filename
from django.utils.translation import ugettext as _
from edx_django_utils.monitoring import set_code_owner_attribute, set_code_owner_attribute_from_module
from edx_django_utils.monitoring import (
set_code_owner_attribute,
set_code_owner_attribute_from_module,
set_custom_attribute,
set_custom_attributes_for_course_key,
)
from common.djangoapps.util.monitoring import monitor_import_failure
from opaque_keys.edx.keys import CourseKey
from opaque_keys.edx.locator import LibraryLocator
from organizations.api import add_organization_course, ensure_organization
@@ -391,19 +396,70 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan
"""
Import a course or library from a provided OLX .tar.gz archive.
"""
set_code_owner_attribute_from_module(__name__)
current_step = 'Unpacking'
courselike_key = CourseKey.from_string(course_key_string)
try:
user = User.objects.get(pk=user_id)
except User.DoesNotExist:
with translation_language(language):
LOGGER.error(f'Course import {courselike_key}: Unknown User ID: {user_id}')
self.status.fail(_('Unknown User ID: {0}').format(user_id))
set_code_owner_attribute_from_module(__name__)
set_custom_attributes_for_course_key(courselike_key)
log_prefix = f'Course import {courselike_key}'
self.status.set_state(current_step)
data_root = path(settings.GITHUB_REPO_ROOT)
subdir = base64.urlsafe_b64encode(repr(courselike_key).encode('utf-8')).decode('utf-8')
course_dir = data_root / subdir
def validate_user():
"""Validate if the user exists otherwise log error. """
try:
return User.objects.get(pk=user_id)
except User.DoesNotExist as exc:
with translation_language(language):
self.status.fail(_('Unknown User ID: {0}').format(user_id))
LOGGER.error(f'{log_prefix}: Unknown User: {user_id}')
monitor_import_failure(courselike_key, current_step, exception=exc)
return
def user_has_access(user):
"""Return True if user has studio write access to the given course."""
has_access = has_course_author_access(user, courselike_key)
if not has_access:
message = f'User permission denied: {user.username}'
with translation_language(language):
self.status.fail(_('Permission denied'))
LOGGER.error(f'{log_prefix}: {message}')
monitor_import_failure(courselike_key, current_step, message=message)
return has_access
def file_is_supported():
"""Check if it is a supported file."""
file_is_valid = archive_name.endswith('.tar.gz')
if not file_is_valid:
message = f'Unsupported file {archive_name}'
with translation_language(language):
self.status.fail(_('We only support uploading a .tar.gz file.'))
LOGGER.error(f'{log_prefix}: {message}')
monitor_import_failure(courselike_key, current_step, message=message)
return file_is_valid
def file_exists_in_storage():
archive_path_exists = course_import_export_storage.exists(archive_path)
if not archive_path_exists:
message = f'Uploaded file {archive_path} not found'
with translation_language(language):
self.status.fail(_('Tar file not found'))
LOGGER.error(f'{log_prefix}: {message}')
monitor_import_failure(courselike_key, current_step, message=message)
return archive_path_exists
user = validate_user()
if not user:
return
if not has_course_author_access(user, courselike_key):
with translation_language(language):
LOGGER.error(f'Course import {courselike_key}: Permission denied User ID: {user_id}')
self.status.fail(_('Permission denied'))
if not user_has_access(user):
return
if not file_is_supported():
return
is_library = isinstance(courselike_key, LibraryLocator)
@@ -419,30 +475,19 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan
# Locate the uploaded OLX archive (and download it from S3 if necessary)
# Do everything in a try-except block to make sure everything is properly cleaned up.
data_root = path(settings.GITHUB_REPO_ROOT)
subdir = base64.urlsafe_b64encode(repr(courselike_key).encode('utf-8')).decode('utf-8')
course_dir = data_root / subdir
try:
self.status.set_state('Unpacking')
LOGGER.info(f'Course import {courselike_key}: unpacking step started')
if not archive_name.endswith('.tar.gz'):
with translation_language(language):
LOGGER.error(f'Course import {courselike_key}: Only .tar.gz file is supported')
self.status.fail(_('We only support uploading a .tar.gz file.'))
return
LOGGER.info(f'{log_prefix}: unpacking step started')
temp_filepath = course_dir / get_valid_filename(archive_name)
if not course_dir.isdir():
os.mkdir(course_dir)
LOGGER.info(f'Course import: {courselike_key}: importing course to {temp_filepath}')
LOGGER.info(f'{log_prefix}: importing course to {temp_filepath}')
# Copy the OLX archive from where it was uploaded to (S3, Swift, file system, etc.)
if not course_import_export_storage.exists(archive_path):
LOGGER.error(f'Course import {courselike_key}: Uploaded file {archive_path} not found')
with translation_language(language):
self.status.fail(_('Tar file not found'))
if not file_exists_in_storage():
return
with course_import_export_storage.open(archive_path, 'rb') as source:
with open(temp_filepath, 'wb') as destination:
def read_chunk():
@@ -450,9 +495,11 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan
Read and return a sequence of bytes from the source file.
"""
return source.read(FILE_READ_CHUNK)
for chunk in iter(read_chunk, b''):
destination.write(chunk)
LOGGER.info(f'Course import {courselike_key}: Download from storage complete')
LOGGER.info(f'{log_prefix}: Download from storage complete')
# Delete from source location
course_import_export_storage.delete(archive_path)
@@ -465,17 +512,16 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan
from .views.entrance_exam import remove_entrance_exam_milestone_reference
# TODO: Is this really ok? Seems dangerous for a live course
remove_entrance_exam_milestone_reference(fake_request, courselike_key)
LOGGER.info(
f'Course import {courselike_key}: entrance exam milestone content reference has been removed'
)
LOGGER.info(f'{log_prefix}: entrance exam milestone content reference has been removed')
# Send errors to client with stage at which error occurred.
except Exception as exception: # pylint: disable=broad-except
if course_dir.isdir():
shutil.rmtree(course_dir)
LOGGER.info(f'Course import {courselike_key}: Temp data cleared')
LOGGER.info(f'{log_prefix}: Temp data cleared')
LOGGER.exception(f'Course import {courselike_key}: Unknown error while unpacking', exc_info=True)
self.status.fail(str(exception))
LOGGER.exception(f'{log_prefix}: Unknown error while unpacking', exc_info=True)
monitor_import_failure(courselike_key, current_step, exception=exception)
return
# try-finally block for proper clean up after receiving file.
@@ -484,16 +530,18 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan
try:
safetar_extractall(tar_file, (course_dir + '/'))
except SuspiciousOperation as exc:
LOGGER.error(f'Course import {courselike_key}: Unsafe tar file')
with translation_language(language):
self.status.fail(_('Unsafe tar file. Aborting import.'))
LOGGER.error(f'{log_prefix}: Unsafe tar file')
monitor_import_failure(courselike_key, current_step, exception=exc)
return
finally:
tar_file.close()
LOGGER.info(f'Course import {courselike_key}: Uploaded file extracted. Verification step started')
self.status.set_state('Verifying')
current_step = 'Verifying'
self.status.set_state(current_step)
self.status.increment_completed_steps()
LOGGER.info(f'{log_prefix}: Uploaded file extracted. Verification step started')
# find the 'course.xml' file
def get_all_files(directory):
@@ -518,16 +566,19 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan
dirpath = get_dir_for_filename(course_dir, root_name)
if not dirpath:
message = f'Could not find the {root_name} file in the package.'
with translation_language(language):
LOGGER.error(f'Course import {courselike_key}: Could not find the {root_name} file in the package.')
self.status.fail(_('Could not find the {0} file in the package.').format(root_name))
return
LOGGER.error(f'{log_prefix}: {message}')
monitor_import_failure(courselike_key, current_step, message=message)
return
dirpath = os.path.relpath(dirpath, data_root)
LOGGER.info(f'Course import {courselike_key}: Extracted file verified. Updating course started')
self.status.set_state('Updating')
current_step = 'Updating'
self.status.set_state(current_step)
self.status.increment_completed_steps()
LOGGER.info(f'{log_prefix}: Extracted file verified. Updating course started')
courselike_items = import_func(
modulestore(), user.id,
@@ -541,14 +592,17 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan
new_location = courselike_items[0].location
LOGGER.debug('new course at %s', new_location)
LOGGER.info(f'Course import {courselike_key}: Course import successful')
except Exception as exception: # pylint: disable=broad-except
LOGGER.exception(f'Course import {courselike_key}: Unknown error while updating course')
self.status.fail(str(exception))
LOGGER.info(f'{log_prefix}: Course import successful')
set_custom_attribute('course_import_completed', True)
except Exception as exception: # pylint: disable=broad-except
msg = str(exception)
LOGGER.exception(f'{log_prefix}: Unknown error while updating course {msg}')
self.status.fail(msg)
monitor_import_failure(courselike_key, current_step, exception=exception)
finally:
if course_dir.isdir():
shutil.rmtree(course_dir)
LOGGER.info(f'Course import {courselike_key}: Temp data cleared')
LOGGER.info(f'{log_prefix}: Temp data cleared')
if self.status.state == 'Updating' and is_course:
# Reload the course so we have the latest state
@@ -564,7 +618,7 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan
CourseMetadata.update_from_dict(metadata, course, user)
from .views.entrance_exam import add_entrance_exam_milestone
add_entrance_exam_milestone(course.id, entrance_exam_chapter)
LOGGER.info('Course %s Entrance exam imported', course.id)
LOGGER.info(f'Course import {course.id}: Entrance exam imported')
@shared_task

32
cms/djangoapps/contentstore/views/import_export.py
View File

@@ -22,6 +22,7 @@ from django.http import Http404, HttpResponse, HttpResponseNotFound, StreamingHt
from django.utils.translation import ugettext as _
from django.views.decorators.csrf import ensure_csrf_cookie
from django.views.decorators.http import require_GET, require_http_methods
from edx_django_utils.monitoring import set_custom_attribute, set_custom_attributes_for_course_key
from opaque_keys.edx.keys import CourseKey
from opaque_keys.edx.locator import LibraryLocator
from path import Path as path
@@ -33,6 +34,7 @@ from user_tasks.models import UserTaskArtifact, UserTaskStatus
from common.djangoapps.edxmako.shortcuts import render_to_response
from common.djangoapps.student.auth import has_course_author_access
from common.djangoapps.util.json_request import JsonResponse
from common.djangoapps.util.monitoring import monitor_import_failure
from common.djangoapps.util.views import ensure_valid_course_key
from xmodule.modulestore.django import modulestore
@@ -121,11 +123,11 @@ def _write_chunk(request, courselike_key):
subdir = base64.urlsafe_b64encode(repr(courselike_key).encode('utf-8')).decode('utf-8')
course_dir = data_root / subdir
filename = request.FILES['course-data'].name
set_custom_attributes_for_course_key(courselike_key)
current_step = 'Uploading'
def error_response(message, status):
"""
Returns Json error response
"""
"""Returns Json error response"""
return JsonResponse({'ErrMsg': message, 'Stage': -1}, status=status)
courselike_string = str(courselike_key) + filename
@@ -135,8 +137,10 @@ def _write_chunk(request, courselike_key):
_save_request_status(request, courselike_string, 0)
if not filename.endswith('.tar.gz'):
error_message = _('We only support uploading a .tar.gz file.')
_save_request_status(request, courselike_string, -1)
return error_response(_('We only support uploading a .tar.gz file.'), 415)
monitor_import_failure(courselike_key, current_step, message=error_message)
return error_response(error_message, 415)
temp_filepath = course_dir / filename
if not course_dir.isdir():
@@ -154,25 +158,30 @@ def _write_chunk(request, courselike_key):
content_range = {'start': 0, 'stop': 1, 'end': 2}
# stream out the uploaded files in chunks to disk
if int(content_range['start']) == 0:
is_initial_import_request = int(content_range['start']) == 0
if is_initial_import_request:
mode = "wb+"
set_custom_attribute('course_import_init', True)
else:
mode = "ab+"
# Appending to fail would fail if the file doesn't exist.
if not temp_filepath.exists():
error_message = _('Some chunks missed during file upload. Please try again')
_save_request_status(request, courselike_string, -1)
log.error(f'Course Import: {courselike_key} Chunks missed during upload.')
return error_response(_('Some chunks missed during file upload. Please try again'), 409)
log.error(f'Course Import {courselike_key}: {error_message}')
monitor_import_failure(courselike_key, current_step, message=error_message)
return error_response(error_message, status=409)
size = os.path.getsize(temp_filepath)
# Check to make sure we haven't missed a chunk
# This shouldn't happen, even if different instances are handling
# the same session, but it's always better to catch errors earlier.
if size < int(content_range['start']):
error_message = _('File upload corrupted. Please try again')
_save_request_status(request, courselike_string, -1)
log.error(
f'Course import {courselike_key}: A chunk has been missed'
)
return error_response(_('File upload corrupted. Please try again'), 409)
log.error(f'Course import {courselike_key}: A chunk has been missed')
monitor_import_failure(courselike_key, current_step, message=error_message)
return error_response(error_message, status=409)
# The last request sometimes comes twice. This happens because
# nginx sends a 499 error code when the response takes too long.
@@ -212,6 +221,7 @@ def _write_chunk(request, courselike_key):
shutil.rmtree(course_dir)
log.info("Course import %s: Temp data cleared", courselike_key)
monitor_import_failure(courselike_key, current_step, exception=exception)
log.exception(f'Course import {courselike_key}: error importing course.')
return error_response(str(exception), 400)

26
common/djangoapps/util/monitoring.py Normal file
View File

@@ -0,0 +1,26 @@
"""Helper methods for monitoring of events."""
from edx_django_utils.monitoring import set_custom_attribute, set_custom_attributes_for_course_key
def monitor_import_failure(course_key, import_step, message=None, exception=None):
"""
Helper method to add custom parameters to for import failures.
Arguments:
course_key: CourseKey object
import_step (str): current step in course import
message (str): any particular message to add
exception: Exception object
"""
exception_module = getattr(exception, '__module__', '')
separator = '.' if exception_module else ''
module_and_class = f'{exception_module}{separator}{exception.__class__.__name__}'
exc_message = str(exception)
set_custom_attribute('course_import_failure', import_step)
set_custom_attributes_for_course_key(course_key)
if message:
set_custom_attribute('course_import_failure_message', message)
if exception is not None:
set_custom_attribute('course_import_failure_error_class', module_and_class)
set_custom_attribute('course_import_failure_error_message', exc_message)

4
common/lib/xmodule/xmodule/modulestore/xml.py
View File

@@ -14,7 +14,6 @@ from contextlib import contextmanager
from importlib import import_module
from django.utils.encoding import python_2_unicode_compatible
from edx_django_utils.monitoring import set_custom_attribute
from fs.osfs import OSFS
from lazy import lazy
from lxml import etree
@@ -25,6 +24,7 @@ from xblock.field_data import DictFieldData
from xblock.fields import ScopeIds
from xblock.runtime import DictKeyValueStore
from common.djangoapps.util.monitoring import monitor_import_failure
from xmodule.error_module import ErrorBlock
from xmodule.errortracker import exc_info_to_str, make_error_tracker
from xmodule.mako_module import MakoDescriptorSystem
@@ -378,10 +378,10 @@ class XMLModuleStore(ModuleStoreReadBase):
course_descriptor = self.load_course(course_dir, course_ids, errorlog.tracker, target_course_id)
except Exception as exc: # pylint: disable=broad-except
msg = f'Course import {target_course_id}: ERROR: Failed to load courselike "{course_dir}": {str(exc)}'
set_custom_attribute('course_import_failure', f"Courselike load failure: {msg}")
log.exception(msg)
errorlog.tracker(msg)
self.errored_courses[course_dir] = errorlog
monitor_import_failure(target_course_id, 'Updating', exception=exc)
if course_descriptor is None:
pass

28
common/lib/xmodule/xmodule/modulestore/xml_importer.py
View File

@@ -31,7 +31,6 @@ import re
from abc import abstractmethod
import xblock
from edx_django_utils.monitoring import set_custom_attribute
from lxml import etree
from opaque_keys.edx.keys import UsageKey
from opaque_keys.edx.locator import LibraryLocator
@@ -40,6 +39,7 @@ from xblock.core import XBlockMixin
from xblock.fields import Reference, ReferenceList, ReferenceValueDict, Scope
from xblock.runtime import DictKeyValueStore, KvsFieldData
from common.djangoapps.util.monitoring import monitor_import_failure
from xmodule.assetstore import AssetMetadata
from xmodule.contentstore.content import StaticContent
from xmodule.errortracker import make_error_tracker
@@ -173,9 +173,9 @@ class StaticContentImporter: # lint-amnesty, pylint: disable=missing-class-docs
try:
self.static_content_store.save(content)
except Exception as err: # lint-amnesty, pylint: disable=broad-except
msg = f"Course import {self.target_id}: Error importing {file_subpath}, error={err}"
log.exception(msg)
set_custom_attribute('course_import_failure', f"Static Content Save Failure: {msg}")
msg = f'Error importing {file_subpath}, error={err}'
log.exception(f'Course import {self.target_id}: {msg}')
monitor_import_failure(self.target_id, 'Updating', exception=err)
return file_subpath, asset_key
@@ -355,13 +355,14 @@ class ImportManager:
asset_md = AssetMetadata(asset_key)
asset_md.from_xml(asset)
all_assets.append(asset_md)
except OSError:
logging.error(
f'Course import {self.target_id}: No {assets_filename} file is present with asset metadata.'
)
except OSError as os_exc:
msg = f'No {assets_filename} file is present with asset metadata.'
logging.error(f'Course import {course_id}: {msg}')
monitor_import_failure(course_id, 'Updating', msg, os_exc)
return
except Exception: # pylint: disable=W0703
logging.exception(f'Course import {self.target_id}: Error while parsing asset xml.')
except Exception as exc: # pylint: disable=W0703
monitor_import_failure(course_id, 'Updating', exception=exc)
logging.exception(f'Course import {course_id}: Error while parsing asset xml.')
if self.raise_on_failure: # lint-amnesty, pylint: disable=no-else-raise
raise
else:
@@ -478,7 +479,7 @@ class ImportManager:
)
except Exception:
log.exception(
f'Course import {self.target_id}: failed to import module location {child.location}'
f'Course import {dest_id}: failed to import module location {child.location}'
)
raise
@@ -501,9 +502,8 @@ class ImportManager:
runtime=courselike.runtime,
)
except Exception:
msg = f'Course import {self.target_id}: failed to import module location {leftover}'
msg = f'Course import {dest_id}: failed to import module location {leftover}'
log.error(msg)
set_custom_attribute('course_import_failure', f"Module Load failure: {msg}")
raise
def run_imports(self):
@@ -1008,7 +1008,7 @@ def _import_course_draft(
try:
_import_module(draft.module)
except Exception: # pylint: disable=broad-except
logging.exception('while importing draft descriptor %s', draft.module)
logging.exception(f'Course import {source_course_id}: while importing draft descriptor {draft.module}')
def allowed_metadata_by_category(category):