diff --git a/cms/djangoapps/contentstore/api/views/course_import.py b/cms/djangoapps/contentstore/api/views/course_import.py index 13106b1d36..2cc5518b47 100644 --- a/cms/djangoapps/contentstore/api/views/course_import.py +++ b/cms/djangoapps/contentstore/api/views/course_import.py @@ -150,7 +150,7 @@ class CourseImportView(CourseImportExportViewMixin, GenericAPIView): 'task_id': async_result.task_id }) except Exception as e: - log.exception(str(e)) + log.exception(f'Course import {course_key: Unknown error in import}') raise self.api_error( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, developer_message=str(e), diff --git a/cms/djangoapps/contentstore/tasks.py b/cms/djangoapps/contentstore/tasks.py index 51a15273bc..853f2eca8d 100644 --- a/cms/djangoapps/contentstore/tasks.py +++ b/cms/djangoapps/contentstore/tasks.py @@ -397,10 +397,12 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan 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)) 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')) return @@ -422,9 +424,10 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan 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 @@ -432,11 +435,11 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan if not course_dir.isdir(): os.mkdir(course_dir) - LOGGER.debug(f'importing course to {temp_filepath}') + LOGGER.info(f'Course import: {courselike_key}: 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.info('Course import %s: Uploaded file %s not found', courselike_key, 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')) return @@ -449,7 +452,7 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan return source.read(FILE_READ_CHUNK) for chunk in iter(read_chunk, b''): destination.write(chunk) - LOGGER.info('Course import %s: Download from storage complete', courselike_key) + LOGGER.info(f'Course import {courselike_key}: Download from storage complete') # Delete from source location course_import_export_storage.delete(archive_path) @@ -463,16 +466,15 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan # TODO: Is this really ok? Seems dangerous for a live course remove_entrance_exam_milestone_reference(fake_request, courselike_key) LOGGER.info( - 'entrance exam milestone content reference for course %s has been removed', - courselike_module.id + f'Course import {courselike_key}: 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('Course import %s: Temp data cleared', courselike_key) + LOGGER.info(f'Course import {courselike_key}: Temp data cleared') - LOGGER.exception('Error importing course %s', courselike_key, exc_info=True) + LOGGER.exception(f'Course import {courselike_key}: Unknown error while unpacking', exc_info=True) self.status.fail(str(exception)) return @@ -482,14 +484,14 @@ 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.info('Course import %s: Unsafe tar file - %s', courselike_key, exc.args[0]) + LOGGER.error(f'Course import {courselike_key}: Unsafe tar file') with translation_language(language): self.status.fail(_('Unsafe tar file. Aborting import.')) return finally: tar_file.close() - LOGGER.info('Course import %s: Uploaded file extracted', courselike_key) + LOGGER.info(f'Course import {courselike_key}: Uploaded file extracted. Verification step started') self.status.set_state('Verifying') self.status.increment_completed_steps() @@ -517,13 +519,13 @@ 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: 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 dirpath = os.path.relpath(dirpath, data_root) - LOGGER.debug('found %s at %s', root_name, dirpath) - LOGGER.info('Course import %s: Extracted file verified', courselike_key) + LOGGER.info(f'Course import {courselike_key}: Extracted file verified. Updating course started') self.status.set_state('Updating') self.status.increment_completed_steps() @@ -532,20 +534,21 @@ def import_olx(self, user_id, course_key_string, archive_path, archive_name, lan settings.GITHUB_REPO_ROOT, [dirpath], load_error_modules=False, static_content_store=contentstore(), - target_id=courselike_key + target_id=courselike_key, + verbose=True ) new_location = courselike_items[0].location LOGGER.debug('new course at %s', new_location) - LOGGER.info('Course import %s: Course import successful', courselike_key) + LOGGER.info(f'Course import {courselike_key}: Course import successful') except Exception as exception: # pylint: disable=broad-except - LOGGER.exception('error importing course', exc_info=True) + LOGGER.exception(f'Course import {courselike_key}: Unknown error while updating course') self.status.fail(str(exception)) finally: if course_dir.isdir(): shutil.rmtree(course_dir) - LOGGER.info('Course import %s: Temp data cleared', courselike_key) + LOGGER.info(f'Course import {courselike_key}: Temp data cleared') if self.status.state == 'Updating' and is_course: # Reload the course so we have the latest state diff --git a/cms/djangoapps/contentstore/views/import_export.py b/cms/djangoapps/contentstore/views/import_export.py index 8e5bb99d43..29b0f84642 100644 --- a/cms/djangoapps/contentstore/views/import_export.py +++ b/cms/djangoapps/contentstore/views/import_export.py @@ -142,7 +142,7 @@ def _write_chunk(request, courselike_key): if not course_dir.isdir(): os.mkdir(course_dir) - logging.debug(f'importing course to {temp_filepath}') + logging.info(f'Course import {courselike_key}: importing course to {temp_filepath}') # Get upload chunks byte ranges try: @@ -150,6 +150,7 @@ def _write_chunk(request, courselike_key): content_range = matches.groupdict() except KeyError: # Single chunk # no Content-Range header, so make one that will work + logging.info(f'Course import {courselike_key}: single chunk found') content_range = {'start': 0, 'stop': 1, 'end': 2} # stream out the uploaded files in chunks to disk @@ -163,10 +164,8 @@ def _write_chunk(request, courselike_key): # the same session, but it's always better to catch errors earlier. if size < int(content_range['start']): _save_request_status(request, courselike_string, -1) - log.warning( - "Reported range %s does not match size downloaded so far %s", - content_range['start'], - size + log.error( + f'Course import {courselike_key}: A chunk has been missed' ) return JsonResponse( { @@ -199,7 +198,7 @@ def _write_chunk(request, courselike_key): }] }) - log.info("Course import %s: Upload complete", courselike_key) + log.info(f'Course import {courselike_key}: Upload complete') with open(temp_filepath, 'rb') as local_file: django_file = File(local_file) storage_path = course_import_export_storage.save('olx_import/' + filename, django_file) @@ -213,9 +212,7 @@ def _write_chunk(request, courselike_key): shutil.rmtree(course_dir) log.info("Course import %s: Temp data cleared", courselike_key) - log.exception( - "error importing course" - ) + log.exception(f'Course import {courselike_key}: error importing course.') return JsonResponse( { 'ErrMsg': str(exception), diff --git a/common/lib/xmodule/xmodule/modulestore/xml_importer.py b/common/lib/xmodule/xmodule/modulestore/xml_importer.py index a331779bd1..57b31dcc36 100644 --- a/common/lib/xmodule/xmodule/modulestore/xml_importer.py +++ b/common/lib/xmodule/xmodule/modulestore/xml_importer.py @@ -173,7 +173,7 @@ 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"Error importing {file_subpath}, error={err}" + 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}") @@ -274,7 +274,9 @@ class ImportManager: Import all static items into the content store. """ if self.static_content_store is None: - log.warning("Static content store is None. Skipping static content import...") + log.error( + f'Course import {self.target_id}: Static content store is None. Skipping static content import.' + ) return static_content_importer = StaticContentImporter( @@ -284,14 +286,16 @@ class ImportManager: ) if self.do_import_static: if self.verbose: - log.debug("Importing static content and python library") + log.info(f'Course import {self.target_id}: Importing static content and python library') # first pass to find everything in the static content directory static_content_importer.import_static_content_directory( content_subdir=self.static_content_subdir, verbose=self.verbose ) elif self.do_import_python_lib and self.python_lib_filename: if self.verbose: - log.debug("Skipping static content import, still importing python library") + log.info( + f'Course import {self.target_id}: Skipping static content import, still importing python library' + ) python_lib_dir_path = data_path / self.static_content_subdir python_lib_full_path = python_lib_dir_path / self.python_lib_filename if os.path.isfile(python_lib_full_path): @@ -300,7 +304,7 @@ class ImportManager: ) else: if self.verbose: - log.debug("Skipping import of static content and python library") + log.info(f'Course import {self.target_id}: Skipping import of static content and python library') # No matter what do_import_static is, import "static_import" directory. # This is needed because the "about" pages (eg "overview") are @@ -314,7 +318,7 @@ class ImportManager: simport = 'static_import' if os.path.exists(data_path / simport): if self.verbose: - log.debug("Importing %s directory", simport) + log.info(f'Course import {self.target_id}: Importing {simport} directory') static_content_importer.import_static_content_directory( content_subdir=simport, verbose=self.verbose ) @@ -352,10 +356,12 @@ class ImportManager: asset_md.from_xml(asset) all_assets.append(asset_md) except OSError: - logging.info('No %s file is present with asset metadata.', assets_filename) + logging.error( + f'Course import {self.target_id}: No {assets_filename} file is present with asset metadata.' + ) return except Exception: # pylint: disable=W0703 - logging.exception('Error while parsing asset xml.') + logging.exception(f'Course import {self.target_id}: Error while parsing asset xml.') if self.raise_on_failure: # lint-amnesty, pylint: disable=no-else-raise raise else: @@ -471,7 +477,9 @@ class ImportManager: runtime=courselike.runtime, ) except Exception: - log.error('failed to import module location %s', child.location) + log.exception( + f'Course import {self.target_id}: failed to import module location {child.location}' + ) raise depth_first(child) @@ -493,7 +501,7 @@ class ImportManager: runtime=courselike.runtime, ) except Exception: - msg = f'failed to import module location {leftover}' + msg = f'Course import {self.target_id}: failed to import module location {leftover}' log.error(msg) set_custom_attribute('course_import_failure', f"Module Load failure: {msg}") raise