Tweaked error reporting and logging when loading VASL extensions.

vasl_templates/webapp/file_server/vasl_mod.py

@@ -18,6 +18,8 @@ from vasl_templates.webapp.file_server.utils import get_vo_gpids, get_effective_
 SUPPORTED_VASL_MOD_VERSIONS = [ "6.4.0", "6.4.1", "6.4.2", "6.4.3" ]
 SUPPORTED_VASL_MOD_VERSIONS_DISPLAY = "6.4.0-6.4.3"
 
+warnings = [] # nb: for the test suite
+
 # ---------------------------------------------------------------------
 
 # NOTE: The lock only controls access to the _vasl_mod variable, not the VaslMod object it points to.
@@ -52,7 +54,7 @@ def set_vasl_mod( vmod_fname, msg_store ):
         global _vasl_mod
         if vmod_fname:
             extns_dir = app.config.get( "VASL_EXTENSIONS_DIR" )
-            extns = _load_vasl_extns( extns_dir, msg_store )
+            extns = _load_vasl_extns( extns_dir )
             _vasl_mod = VaslMod( vmod_fname, DATA_DIR, extns )
             if _vasl_mod.vasl_version not in SUPPORTED_VASL_MOD_VERSIONS:
                 msg_store.warning(
@@ -63,12 +65,17 @@ def set_vasl_mod( vmod_fname, msg_store ):
         else:
             _vasl_mod = None
 
-def _load_vasl_extns( extn_dir, msg_store ): #pylint: disable=too-many-locals
+def _load_vasl_extns( extn_dir ): #pylint: disable=too-many-locals,too-many-statements
     """Locate VASL extensions and their corresponding vehicle/ordnance info files."""
 
     if not extn_dir:
         return []
 
+    def log_warning( fmt, *args, **kwargs ): #pylint: disable=missing-docstring
+        msg = fmt.format( *args, **kwargs )
+        warnings.append( msg )
+        _logger.warning( msg )
+
     # load our extension info files
     all_extn_info = {}
     if "_VASL_EXTN_INFO_DIR_" in app.config:
@@ -96,48 +103,44 @@ def _load_vasl_extns( extn_dir, msg_store ): #pylint: disable=too-many-locals
         extn_fname = os.path.join( extn_dir, extn_fname )
 
         # try to load the extension
-        _logger.debug( "Loading VASL extension: %s", extn_fname )
+        _logger.debug( "Checking VASL extension: %s", extn_fname )
         try:
             zip_file = zipfile.ZipFile( extn_fname, "r" )
         except zipfile.BadZipFile:
-            msg_store.warning( "Can't load VASL extension (not a ZIP file): {}", extn_fname, logger=_logger )
+            log_warning( "Can't check VASL extension (not a ZIP file): {}", extn_fname )
             continue
         try:
             build_info = zip_file.read( "buildFile" )
         except KeyError:
-            msg_store.warning( "Missing buildFile: {}", extn_fname, logger=_logger )
+            log_warning( "Missing buildFile: {}", extn_fname )
             continue
         doc = xml.etree.ElementTree.fromstring( build_info )
         node = doc.findall( "." )[0]
         if node.tag != "VASSAL.build.module.ModuleExtension":
-            msg_store.warning( "Unexpected root node ({}) for VASL extension: {}",
-                node.tag, extn_fname, logger=_logger
-            )
+            log_warning( "Unexpected root node ({}) for VASL extension: {}", node.tag, extn_fname )
             continue
 
         # get the extension's ID and version string
         extn_id = node.attrib.get( "extensionId" )
         if not extn_id:
-            msg_store.warning( "Can't find ID for VASL extension: {}", extn_fname, logger=_logger )
+            log_warning( "Can't find ID for VASL extension: {}", extn_fname )
             continue
         extn_version = node.attrib.get( "version" )
         if not extn_version:
-            msg_store.warning( "Can't find version for VASL extension: {}", extn_fname, logger=_logger )
+            log_warning( "Can't find version for VASL extension: {}", extn_fname )
             continue
         _logger.debug( "- id=%s ; version=%s", extn_id, extn_version )
 
         # check if we have a corresponding info file
         extn_info = all_extn_info.get( ( extn_id, extn_version ) )
         if not extn_info:
-            msg_store.warning( "Not loading VASL extension \"{}\".<p>No extension info file for {}/{}.".format(
+            log_warning( "Not accepting {}: no extension info for {}/{}.",
                 os.path.split(extn_fname)[1], extn_id, extn_version
-            ) )
-            _logger.warning( "Not loading VASL extension (no info file for %s/%s): %s",
-                extn_id, extn_version, extn_fname
             )
             continue
 
         # yup - add the extension to the list
+        _logger.info( "Accepting VASL extension: %s (%s/%s)", os.path.split(extn_fname)[1], extn_id, extn_version )
         extns.append( ( extn_fname, extn_info ) )
 
     return extns

vasl_templates/webapp/tests/remote.py

@@ -24,6 +24,7 @@ from vasl_templates.webapp import snippets as webapp_snippets
 from vasl_templates.webapp import vo_notes as webapp_vo_notes
 from vasl_templates.webapp.file_server import utils as webapp_file_server_utils
 from vasl_templates.webapp.file_server.vasl_mod import set_vasl_mod
+from vasl_templates.webapp.file_server import vasl_mod as vasl_mod_module
 
 _logger = logging.getLogger( "control_tests" )
 
@@ -173,6 +174,7 @@ class ControlTests:
         # install the new VASL module
         from vasl_templates.webapp.main import startup_msg_store
         startup_msg_store.reset()
+        vasl_mod_module.warnings = []
         set_vasl_mod( vmod, startup_msg_store )
 
         return self
@@ -271,3 +273,8 @@ class ControlTests:
         assert last_snippet_image
         _logger.info( "Returning the last snippet image: #bytes=%d", len(last_snippet_image) )
         return base64.b64encode( last_snippet_image ).decode( "utf-8" )
+
+    def _get_vasl_mod_warnings( self ): #pylint: disable=no-self-use
+        """Get the vasl_mod startup warnings."""
+        _logger.info( "Returning the vasl_mod startup warnings: %s", vasl_mod_module.warnings )
+        return vasl_mod_module.warnings

vasl_templates/webapp/tests/test_vasl_extensions.py

@@ -2,9 +2,6 @@
 
 import os
 import zipfile
-import urllib
-import json
-import re
 import typing
 
 import pytest
@@ -12,7 +9,7 @@ from selenium.webdriver.common.action_chains import ActionChains
 from selenium.webdriver.common.keys import Keys
 
 from vasl_templates.webapp.utils import TempFile
-from vasl_templates.webapp.tests.utils import init_webapp, set_player, find_child, find_children, wait_for
+from vasl_templates.webapp.tests.utils import init_webapp, set_player, find_child, find_children
 from vasl_templates.webapp.tests.test_vehicles_ordnance import add_vo
 
 # ---------------------------------------------------------------------
@@ -31,7 +28,7 @@ def test_load_vasl_extensions( webapp, webdriver ):
         # reload the webapp
         control_tests.set_vasl_mod( vmod="random", extns_dtype="test" )
         webdriver.refresh()
-        _check_startup_messages( webapp, expected )
+        _check_warning_msgs( control_tests, expected )
 
     # try loading an extension that has no buildFile
     do_test( "foo", "<foo />", "Missing buildFile:" )
@@ -46,14 +43,14 @@ def test_load_vasl_extensions( webapp, webdriver ):
 
     # try loading an extension with an unknown ID
     do_test( "buildFile", '<VASSAL.build.module.ModuleExtension version="v0.1" extensionId="unknown" />',
-        re.compile( r'Not loading VASL extension "test\.zip".+No extension info file for unknown/v0\.1' )
+        "Not accepting test.zip: no extension info for unknown/v0.1"
     )
 
     # try loading something that's not a ZIP file
     control_tests.set_test_vasl_extn( fname="test.zip", bin_data=b"This is not a ZIP file." ) \
                  .set_vasl_mod( vmod="random", extns_dtype="test" )
     webdriver.refresh()
-    _check_startup_messages( webapp, "Can't load VASL extension (not a ZIP file):" )
+    _check_warning_msgs( control_tests, "Can't check VASL extension (not a ZIP file):" )
 
 # ---------------------------------------------------------------------
 
@@ -71,14 +68,14 @@ def test_vasl_extension_info( webapp, webdriver ):
         control_tests.set_vasl_extn_info_dir( dtype=dtype ) \
                      .set_vasl_mod( vmod="random", extns_dtype="test" )
         webdriver.refresh()
-        _check_startup_messages( webapp, expected )
+        _check_warning_msgs( control_tests, expected )
 
     # try loading the VASL extension, with no matching extension info
     do_test( "mismatched-id",
-        re.compile( r'Not loading VASL extension.+No extension info file for test/v0\.1' )
+        "Not accepting test.zip: no extension info for test/v0.1"
     )
     do_test( "mismatched-version",
-        re.compile( r'Not loading VASL extension.+No extension info file for test/v0\.1' )
+        "Not accepting test.zip: no extension info for test/v0.1"
     )
 
     # try loading the VASL extension, with matching extension info
@@ -173,21 +170,14 @@ def _set_test_vasl_extn( control_tests, build_info, build_info_fname="buildFile"
             zip_data = fp.read()
     control_tests.set_test_vasl_extn( fname="test.zip", bin_data=zip_data )
 
-def _check_startup_messages( webapp, expected ):
-    """Check that the startup messages are what we expect."""
-
-    # wait for the startup messages to become available
-    wait_for( 2, lambda: find_child("#_startup-msgs-ready_") is not None )
-
-    # check the startup messages
-    url = webapp.url_for( "get_startup_msgs" )
-    startup_msgs = json.load( urllib.request.urlopen( url ) )
+def _check_warning_msgs( control_tests, expected ):
+    """Check that the startup warning messages are what we expect."""
+    warnings = control_tests.get_vasl_mod_warnings()
     if expected:
-        assert list(startup_msgs.keys()) == [ "warning" ]
-        assert len(startup_msgs["warning"]) == 1
+        assert len(warnings) == 1
         if isinstance( expected, typing.re.Pattern ):
-            assert expected.search( startup_msgs["warning"][0] )
+            assert expected.search( warnings[0] )
         else:
-            assert startup_msgs["warning"][0].startswith( expected )
+            assert warnings[0].startswith( expected )
     else:
-        assert not startup_msgs
+        assert not warnings