fix: #199, add tracing to EntityModelLoader and improve logging

src/main/java/io/neonbee/entity/EntityModelDefinition.java

@@ -66,13 +66,13 @@ public String toString() {
      * Extracts the prefix of the CSN Model Service to get the Namespace.
      *
      * @param csnModel the CSN Model
-     * @return the prefix of the Service or throws a RuntimeException if no service is available in the CDS model
+     * @return the prefix of the service in the CSN model, or null, in case no service was defined
      */
     public static String getNamespace(CdsModel csnModel) {
         return csnModel.services().findAny().map(CdsService::getQualifiedName).map(name -> {
             int lastIndexOf = name.lastIndexOf('.');
             return lastIndexOf == -1 ? "" : name.substring(0, lastIndexOf);
-        }).orElseThrow(() -> new RuntimeException("No service found in CDS model!"));
+        }).orElse(null);
     }
 
     /**

src/main/java/io/neonbee/entity/EntityModelLoader.java

@@ -24,6 +24,8 @@
 
 import javax.xml.stream.XMLStreamException;
 
+import org.apache.olingo.commons.api.edm.Edm;
+import org.apache.olingo.commons.api.edm.EdmEntityContainer;
 import org.apache.olingo.server.api.ServiceMetadata;
 import org.apache.olingo.server.api.etag.ServiceMetadataETagSupport;
 import org.apache.olingo.server.core.MetadataParser;
@@ -33,6 +35,7 @@
 import com.google.common.collect.Streams;
 import com.google.common.hash.HashFunction;
 import com.google.common.hash.Hashing;
+import com.sap.cds.reflect.CdsEntity;
 import com.sap.cds.reflect.CdsModel;
 
 import io.neonbee.NeonBee;
@@ -52,7 +55,7 @@ class EntityModelLoader {
     @VisibleForTesting
     static final String NEONBEE_MODELS = "NeonBee-Models";
 
-    private static final LoggingFacade LOGGER = LoggingFacade.create(EntityModelLoader.class);
+    private static final LoggingFacade LOGGER = LoggingFacade.create();
 
     private static final HashFunction HASH_FUNCTION = Hashing.murmur3_128();
 
@@ -91,11 +94,16 @@ public static Future<Map<String, EntityModel>> load(Vertx vertx) {
      * @return a map of all loaded models
      */
     public static Future<Map<String, EntityModel>> load(Vertx vertx, Collection<EntityModelDefinition> definitions) {
+        LOGGER.trace("Start loading entity model definitions");
         return new EntityModelLoader(vertx).loadModelsFromModelDirectoryAndClassPath().compose(loader -> {
             return CompositeFuture
                     .all(definitions.stream().map(loader::loadModelsFromDefinition).collect(Collectors.toList()))
                     .map(loader);
-        }).map(EntityModelLoader::getModels);
+        }).map(EntityModelLoader::getModels).onComplete(result -> {
+            if (LOGGER.isTraceEnabled()) {
+                LOGGER.trace("Loading entity model definitions {}", result.succeeded() ? "succeeded" : "failed");
+            }
+        });
     }
 
     /**
@@ -125,9 +133,18 @@ public Future<EntityModelLoader> loadModelsFromModelDirectoryAndClassPath() {
      * @return a future to the {@link EntityModelLoader} instance
      */
     public Future<EntityModelLoader> loadModelsFromDefinition(EntityModelDefinition definition) {
-        return allComposite(definition.getCSNModelDefinitions().entrySet().stream().map(entry -> {
-            return parseModel(entry.getKey(), entry.getValue(), definition.getAssociatedModelDefinitions());
-        }).collect(Collectors.toList())).map(this);
+        Map<String, byte[]> csnModelDefinitions = definition.getCSNModelDefinitions();
+        if (LOGGER.isTraceEnabled()) {
+            LOGGER.trace("Load models from definition {}", csnModelDefinitions.keySet());
+        }
+        return allComposite(csnModelDefinitions.entrySet().stream()
+                .map(entry -> parseModel(entry.getKey(), entry.getValue(), definition.getAssociatedModelDefinitions()))
+                .collect(Collectors.toList())).map(this).onComplete(result -> {
+                    if (LOGGER.isTraceEnabled()) {
+                        LOGGER.trace("Loading models from definition {} {}", csnModelDefinitions.keySet(),
+                                result.succeeded() ? "succeeded" : "failed");
+                    }
+                });
     }
 
     /**
@@ -138,6 +155,9 @@ public Future<EntityModelLoader> loadModelsFromDefinition(EntityModelDefinition
      */
     @VisibleForTesting
     Future<Void> scanDir(Path path) {
+        if (LOGGER.isTraceEnabled()) {
+            LOGGER.trace("Scanning directory {}", path);
+        }
         return FileSystemHelper.readDir(vertx, path).recover(throwable -> {
             // ignore if the models directory does not exist, or a file / folder was deleted after readDir
             return ((throwable instanceof FileSystemException) && throwable.getMessage().contains("Does not exist"))
@@ -148,16 +168,15 @@ Future<Void> scanDir(Path path) {
                         .map(file -> FileSystemHelper.isDirectory(vertx, file)
                                 .compose(isDir -> isDir ? scanDir(file) : loadModel(file)))
                         .collect(Collectors.toList())))
-                .compose(future -> succeededFuture());
+                .mapEmpty();
     }
 
     /**
      * Tries to read / load all model files from the class path.
      */
     @VisibleForTesting
     Future<Void> scanClassPath() {
-        LOGGER.info("Loading models from class path");
-
+        LOGGER.trace("Scanning class path");
         ClassPathScanner scanner = new ClassPathScanner();
         Future<List<String>> csnFiles = scanner.scanWithPredicate(vertx, name -> name.endsWith(CSN));
         Future<List<String>> modelFiles = scanner.scanManifestFiles(vertx, NEONBEE_MODELS);
@@ -178,6 +197,9 @@ Future<Void> loadModel(Path csnFile) {
             return succeededFuture();
         }
 
+        if (LOGGER.isTraceEnabled()) {
+            LOGGER.trace("Loading model {}", csnFile);
+        }
         return readCsnModel(csnFile).compose(cdsModel -> {
             return CompositeFuture.all(EntityModelDefinition.resolveEdmxPaths(csnFile, cdsModel).stream()
                     .map(this::loadEdmxModel).collect(Collectors.toList())).onSuccess(compositeFuture -> {
@@ -187,26 +209,50 @@ Future<Void> loadModel(Path csnFile) {
     }
 
     Future<Void> parseModel(String csnFile, byte[] csnPayload, Map<String, byte[]> associatedModels) {
-        return parseCsnModel(csnPayload)
-                .compose(cdsModel -> CompositeFuture
-                        .all(EntityModelDefinition.resolveEdmxPaths(Path.of(csnFile), cdsModel).stream()
-                                .map(Path::toString).map(path -> {
-                                    // we do not know if the path uses windows / unix path separators, try both!
-                                    return FileSystemHelper.getPathFromMap(associatedModels, path);
-                                }).map(this::parseEdmxModel).collect(Collectors.toList()))
-                        .onSuccess(compositeFuture -> {
-                            buildModelMap(cdsModel, compositeFuture.<ServiceMetadata>list());
-                        }))
-                .mapEmpty();
+        LOGGER.trace("Parse CSN model file {}", csnFile);
+        return parseCsnModel(csnPayload).onComplete(result -> {
+            if (LOGGER.isTraceEnabled()) {
+                LOGGER.trace("Parsing CSN model file {} {}", csnFile, result.succeeded() ? "succeeded" : "failed");
+            }
+        }).compose(cdsModel -> {
+            LOGGER.trace("Parse associated models of {}", csnFile);
+            return CompositeFuture.all(EntityModelDefinition.resolveEdmxPaths(Path.of(csnFile), cdsModel).stream()
+                    .map(Path::toString).map(path -> {
+                        // we do not know if the path uses windows / unix path separators, try both!
+                        return FileSystemHelper.getPathFromMap(associatedModels, path);
+                    }).map(this::parseEdmxModel).collect(Collectors.toList())).onComplete(result -> {
+                        if (LOGGER.isTraceEnabled()) {
+                            LOGGER.trace("Parsing associated models of {} {}", csnFile,
+                                    result.succeeded() ? "succeeded" : "failed");
+                        }
+                    }).onSuccess(compositeFuture -> {
+                        buildModelMap(cdsModel, compositeFuture.<ServiceMetadata>list());
+                    }).mapEmpty();
+        });
     }
 
     private void buildModelMap(CdsModel cdsModel, List<ServiceMetadata> edmxModels) {
-        Map<String, ServiceMetadata> edmxMap = edmxModels.stream().collect(Collectors.toMap(
-                serviceMetaData -> serviceMetaData.getEdm().getEntityContainer().getNamespace(), Function.identity()));
-        EntityModel entityModel = EntityModel.of(cdsModel, edmxMap);
         String namespace = EntityModelDefinition.getNamespace(cdsModel);
-        models.put(namespace, entityModel);
-        LOGGER.info("Entity model of model with schema namespace {} was added the entity model map.", namespace);
+
+        if (namespace == null) {
+            if (LOGGER.isWarnEnabled()) {
+                LOGGER.warn(
+                        "Could not determine namespace of CDS model. Model (with entities {}) will not added to the model map."
+                                + " Was any service defined in the CDS model?",
+                        cdsModel.entities().map(CdsEntity::getName).collect(Collectors.joining(", ")));
+            }
+            return;
+        } else {
+            LOGGER.trace("Building model map for namespace {}", namespace);
+        }
+
+        Map<String, ServiceMetadata> edmxMap = edmxModels.stream()
+                .collect(Collectors.toMap(EntityModelLoader::getSchemaNamespace, Function.identity()));
+        if (models.put(namespace, EntityModel.of(cdsModel, edmxMap)) != null) {
+            LOGGER.warn("Model with schema namespace {} replaced an existing model in the model map", namespace);
+        } else {
+            LOGGER.info("Model with schema namespace {} was added the model map", namespace);
+        }
     }
 
     /**
@@ -258,16 +304,14 @@ Future<ServiceMetadata> parseEdmxModel(byte[] payload) {
     private Future<ServiceMetadata> createServiceMetadataWithSchema(Buffer csdl) {
         return AsyncHelper.executeBlocking(vertx, () -> {
             // Get the service metadata first w/o the schema namespace, because we have to read it
-            ServiceMetadata serviceMetadata = createServiceMetadata(csdl);
-            String schemaNamespace = serviceMetadata.getEdm().getSchemas().get(0).getNamespace();
-            return createServiceMetadataWithSchema(csdl, schemaNamespace);
+            return createServiceMetadataWithSchema(csdl, getSchemaNamespace(createServiceMetadata(csdl)));
         });
     }
 
     /**
      * Transform the EDMX file which contains the XML representation of the OData Common Schema Definition Language
      * (CSDL) to a ServiceMetadata instance.
-     * <p>
+     *
      * ATTENTION: This method contains BLOCKING code and thus should only be called in a Vert.x worker thread!
      *
      * @param csdl            the String representation of the EDMX file's content
@@ -303,12 +347,23 @@ private ServiceMetadata createServiceMetadataWithSchema(Buffer csdl, String sche
      *
      * ATTENTION: This method contains BLOCKING code and thus should only be called in a Vert.x worker thread!
      */
-    private static ServiceMetadata createServiceMetadata(Buffer csdl) throws XMLStreamException {
+    @VisibleForTesting
+    static ServiceMetadata createServiceMetadata(Buffer csdl) throws XMLStreamException {
         InputStreamReader reader = new InputStreamReader(new BufferInputStream(csdl), UTF_8);
         SchemaBasedEdmProvider edmProvider = new MetadataParser().referenceResolver(null).buildEdmProvider(reader);
         return getBufferedOData().createServiceMetadata(edmProvider, Collections.emptyList());
     }
 
+    @VisibleForTesting
+    static String getSchemaNamespace(ServiceMetadata serviceMetadata) {
+        // a schema without an entity container is still an valid EDMX, an EDMX without any schema is not, thus try to
+        // determine the namespace of the schema containing the entity container first or fall back to use any schema
+        // associated with the EDMX
+        Edm edm = serviceMetadata.getEdm();
+        EdmEntityContainer entityCollection = edm.getEntityContainer();
+        return entityCollection != null ? entityCollection.getNamespace() : edm.getSchemas().get(0).getNamespace();
+    }
+
     @VisibleForTesting
     static class MetadataETagSupport implements ServiceMetadataETagSupport {
         private final String metadataETag;

src/main/java/io/neonbee/entity/EntityModelManager.java

@@ -18,6 +18,7 @@
 
 import io.neonbee.NeonBee;
 import io.neonbee.internal.SharedDataAccessor;
+import io.neonbee.logging.LoggingFacade;
 import io.vertx.core.Future;
 import io.vertx.core.Vertx;
 import io.vertx.core.eventbus.DeliveryOptions;
@@ -39,6 +40,8 @@ public class EntityModelManager {
 
     private static final DeliveryOptions LOCAL_DELIVERY = new DeliveryOptions().setLocalOnly(true);
 
+    private static final LoggingFacade LOGGER = LoggingFacade.create();
+
     /**
      * @deprecated remove with {@link #unregisterModels(Vertx, String)}
      */
@@ -357,11 +360,18 @@ public static Future<Map<String, EntityModel>> reloadModels(NeonBee neonBee) {
      * @return a {@link Future} to a map from schema namespace to EntityModel
      */
     public Future<Map<String, EntityModel>> reloadModels() {
+        LOGGER.info("Reload models");
         return EntityModelLoader.load(neonBee.getVertx(), externalModelDefinitions).onSuccess(models -> {
             bufferedModels = Collections.unmodifiableMap(models);
 
             // publish the event local only! models must be present locally on very instance in a cluster!
             neonBee.getVertx().eventBus().publish(EVENT_BUS_MODELS_LOADED_ADDRESS, null, LOCAL_DELIVERY);
+
+            if (LOGGER.isInfoEnabled()) {
+                LOGGER.info("Reloading models succeeded, size of new buffered models map {}", models.size());
+            }
+        }).onFailure(throwable -> {
+            LOGGER.error("Failed to reload models", throwable);
         }).map(Functions.forSupplier(() -> bufferedModels));
     }
 
@@ -411,7 +421,8 @@ public static Future<Map<String, EntityModel>> registerModels(NeonBee neonBee,
      * @return a {@link Future} to a map from schema namespace to EntityModel
      */
     public Future<Map<String, EntityModel>> registerModels(EntityModelDefinition modelDefinition) {
-        return externalModelDefinitions.add(modelDefinition) ? reloadModels() : getSharedModels();
+        return modelDefinition != null && !modelDefinition.getCSNModelDefinitions().isEmpty()
+                && externalModelDefinitions.add(modelDefinition) ? reloadModels() : getSharedModels();
     }
 
     /**

src/test/java/io/neonbee/NeonBeeMockHelper.java

@@ -31,6 +31,8 @@
 import io.vertx.core.file.FileSystem;
 import io.vertx.core.impl.ContextInternal;
 import io.vertx.core.impl.VertxInternal;
+import io.vertx.core.shareddata.Lock;
+import io.vertx.core.shareddata.SharedData;
 import io.vertx.micrometer.impl.VertxMetricsFactoryImpl;
 
 public final class NeonBeeMockHelper {
@@ -147,6 +149,17 @@ public static Vertx defaultVertxMock() {
         doAnswer(executeFutureAnswer).when(vertxMock).executeBlocking(any(), anyBoolean());
         doAnswer(executeFutureAnswer).when(vertxMock).executeBlocking(any());
 
+        // mock shared data
+        SharedData sharedDataMock = mock(SharedData.class);
+        when(vertxMock.sharedData()).thenReturn(sharedDataMock);
+
+        // mock local locks (and always grant them)
+        when(sharedDataMock.getLocalLock(any())).thenReturn(succeededFuture(mock(Lock.class)));
+        doAnswer(invocation -> {
+            invocation.<Handler<AsyncResult<Lock>>>getArgument(1).handle(succeededFuture(mock(Lock.class)));
+            return null;
+        }).when(sharedDataMock).getLocalLock(any(), any());
+
         return vertxMock;
     }
 

src/test/java/io/neonbee/entity/EntityModelDefinitionTest.java

@@ -11,7 +11,6 @@
 import java.util.Map;
 import java.util.stream.Stream;
 
-import org.junit.jupiter.api.Assertions;
 import org.junit.jupiter.api.DisplayName;
 import org.junit.jupiter.api.Test;
 
@@ -52,14 +51,18 @@ void getNamespace() {
         modelBuilder.addService(serviceBuilder);
         cdsModel = modelBuilder.build();
         assertThat(EntityModelDefinition.getNamespace(cdsModel)).isEqualTo("");
+
+        modelBuilder = CdsModelBuilder.create();
+        cdsModel = modelBuilder.build();
+        assertThat(EntityModelDefinition.getNamespace(cdsModel)).isNull();
     }
 
     @Test
-    @DisplayName("Checks if exception will be thrown if no service was found in CDS model")
+    @DisplayName("Checks if null is returned if no service was found in CDS model")
     void getNamespaceFails() {
         CdsModelBuilder modelBuilder = CdsModelBuilder.create();
         CdsModel cdsModel = modelBuilder.build();
-        Assertions.assertThrows(RuntimeException.class, () -> EntityModelDefinition.getNamespace(cdsModel));
+        assertThat(EntityModelDefinition.getNamespace(cdsModel)).isNull();
     }
 
     @Test

src/test/java/io/neonbee/entity/EntityModelLoaderTest.java

@@ -2,13 +2,17 @@
 
 import static com.google.common.truth.Truth.assertThat;
 import static io.neonbee.NeonBeeProfile.NO_WEB;
+import static io.neonbee.entity.EntityModelLoader.createServiceMetadata;
+import static io.neonbee.entity.EntityModelLoader.getSchemaNamespace;
 import static io.neonbee.test.helper.ResourceHelper.TEST_RESOURCES;
 
 import java.io.IOException;
 import java.nio.file.Path;
 import java.util.Map;
 import java.util.concurrent.TimeUnit;
 
+import javax.xml.stream.XMLStreamException;
+
 import org.junit.jupiter.api.DisplayName;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.TestInfo;
@@ -20,6 +24,7 @@
 import io.vertx.core.CompositeFuture;
 import io.vertx.core.Future;
 import io.vertx.core.Vertx;
+import io.vertx.core.buffer.Buffer;
 import io.vertx.junit5.Timeout;
 import io.vertx.junit5.VertxTestContext;
 
@@ -146,6 +151,15 @@ void dontFailModelLoadingOnNonExistingWorkingDir(Vertx vertx, VertxTestContext t
         }));
     }
 
+    @Test
+    @DisplayName("get schema namespace")
+    void testGetSchemaNamespace() throws XMLStreamException, IOException {
+        Buffer withEntityContainer = TEST_RESOURCES.getRelated("withEntityContainer.edmx");
+        Buffer withoutEntityContainer = TEST_RESOURCES.getRelated("withoutEntityContainer.edmx");
+        assertThat(getSchemaNamespace(createServiceMetadata(withEntityContainer))).isEqualTo("Test.Service");
+        assertThat(getSchemaNamespace(createServiceMetadata(withoutEntityContainer))).isEqualTo("Test.Service");
+    }
+
     private Map.Entry<String, byte[]> buildModelEntry(String modelName) throws IOException {
         return Map.entry("models/" + modelName, TEST_RESOURCES.getRelated(modelName).getBytes());
     }

src/test/java/io/neonbee/internal/deploy/DeployableModelsTest.java

@@ -32,6 +32,7 @@
 import io.neonbee.test.helper.ReflectionHelper;
 import io.vertx.core.Future;
 import io.vertx.core.Vertx;
+import io.vertx.core.json.JsonObject;
 
 class DeployableModelsTest {
     @Test
@@ -53,7 +54,8 @@ void testGetIdentifier() {
     @Test
     @DisplayName("test deploy and undeploy")
     void testDeployUndeploy() throws NoSuchFieldException, IllegalAccessException {
-        EntityModelDefinition definition = new EntityModelDefinition(Map.of(), Map.of());
+        EntityModelDefinition definition = new EntityModelDefinition(
+                Map.of("okay", new JsonObject().put("namespace", "test").toBuffer().getBytes()), Map.of());
         DeployableModels deployable = new DeployableModels(definition);
 
         Vertx vertxMock = defaultVertxMock();