search

eclipse-basyx / basyx-java-examples

java-examples
MIT License
17 stars 20 forks source link

POST AASX Upload [NEED HELP] #145

Closed STUBA-rupr closed 1 year ago

STUBA-rupr commented 1 year ago

Hello, I am really despaired with upload aasx. I did fetch and pull of my source codes, so it should be up-to-date. I am using HelloWorldServer.java I just modified the main:

public static void main(String[] args) throws IOException {

        File currentDirFile = new File(".");
        String helper = currentDirFile.getAbsolutePath();

        startMqttBroker();
        startAASRegistry();
        startAASServer();

        // Create Manager - This manager is used to interact with an AAS server
        ConnectedAssetAdministrationShellManager manager = new ConnectedAssetAdministrationShellManager(new AASRegistryProxy(REGISTRYPATH));

        // Create AAS and push it to server
        /* 
         * rupr 08-JUL-23 - do not create an AAS programmatically 
        Asset asset = new Asset("ovenAsset", new CustomId("eclipse.basyx.asset.oven"), AssetKind.INSTANCE);
        AssetAdministrationShell shell = new AssetAdministrationShell("oven", OVENAASID, asset);

        // The manager uploads the AAS and registers it in the Registry server
        manager.createAAS(shell, AASSERVERPATH);

        // Create submodel
        Submodel documentationSubmodel = new Submodel("documentationSm", DOCUSMID);

        // - Create property
        Property maxTemp = new Property(MAXTEMPID, 1000);

        // Add the property to the Submodel
        documentationSubmodel.addSubmodelElement(maxTemp);

        // - Push the Submodel to the AAS server
        manager.createSubmodel(shell.getIdentification(), documentationSubmodel);*/
    }

The upload is enabled: image

I use PostMan to upload the aasx: image

I try to get AASs, but with no result: image

What I am doing wrong?

Originally posted by @STUBA-rupr in https://github.com/eclipse-basyx/basyx-java-examples/issues/63#issuecomment-1717779101

FrankSchnicke commented 1 year ago

Thank you very much for moving this to a separate issue. Which version of BaSyx are you using?

STUBA-rupr commented 1 year ago

Sure, I am using repositories with these commits: basyx-java-components 1a2112a0e276e9a12e2e4ffc5253f748dcc0a52b basyx-java-examples 1c7c0c52c16be996e8310f71194919450eb09bf5 basyx-java-sdk 81d001323a0ef45fd48bb51324b8340f8696f1f7

I tried also the project basyx.components.AASServer main org.eclipse.basyx.components.aas.executable.AASServerExecutable with the same result

FrankSchnicke commented 1 year ago

Can you provide the output of the console? It may be that you need to add a logger to the pom.xml of the HelloWorld project:

    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>1.4.11</version>
    </dependency>

Additionally, can you check if the problem persists if you update the BaSyx dependencies of the HelloWorld project to 1.4.0?

STUBA-rupr commented 1 year ago

Hello I updated dependencies to 1.4.0 and added logger. I have these logs (actually there is nothing about upload request, in fact there is same result if the file exists or not)

15:01:23,084 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.11
15:01:23,093 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - No custom configurators were discovered as a service.
15:01:23,094 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
15:01:23,097 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
15:01:23,148 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
15:01:23,151 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
15:01:23,192 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 55 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
15:01:23,192 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
15:01:23,194 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
15:01:23,197 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
15:01:23,219 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/adm2pribis/eclipse-workspace/basyx/basyx-java-components/basyx.components/basyx.components.docker/basyx.components.registry/target/classes/logback.xml]
15:01:23,222 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@14555e0a - Resource [logback.xml] occurs multiple times on the classpath.
15:01:23,223 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@14555e0a - Resource [logback.xml] occurs at [file:/C:/Users/adm2pribis/eclipse-workspace/basyx/basyx-java-components/basyx.components/basyx.components.docker/basyx.components.registry/target/classes/logback.xml]
15:01:23,223 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@14555e0a - Resource [logback.xml] occurs at [file:/C:/Users/adm2pribis/eclipse-workspace/basyx/basyx-java-components/basyx.components/basyx.components.docker/basyx.components.AASServer/target/classes/logback.xml]
15:01:23,579 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT]
15:01:23,580 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
15:01:23,617 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
15:01:23,735 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to INFO
15:01:23,744 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT]
15:01:23,746 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@4bb33f74 - End of configuration.
15:01:23,747 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@759d26fb - Registering current configuration as safe fallback point
15:01:23,747 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 553 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY

15:01:23.775 [main] INFO  i.m.b.c.ResourceLoaderConfig - Loading configuration. ResourceLoader = classpath resource, configName = null.
15:01:23.781 [main] INFO  i.m.b.c.ClasspathResourceLoader - Loading resource. RelativePath = config/moquette.conf.
15:01:23.784 [main] INFO  i.m.b.c.ResourceLoaderConfig - Parsing configuration properties. ResourceLoader = classpath resource, configName = null.
15:01:23.794 [main] INFO  i.m.b.Server - Configuring message interceptors...
15:01:23.798 [main] INFO  i.m.i.BrokerInterceptor - Initializing broker interceptor. InterceptorIds=[]
15:01:23.809 [main] INFO  i.m.b.Server - Using default SSL context creator
15:01:23.813 [main] INFO  i.m.b.Server - An io.moquette.broker.security.AcceptAllAuthenticator authenticator instance will be used
15:01:23.815 [main] INFO  i.m.b.Server - Authorizator policy io.moquette.broker.security.PermitAllAuthorizatorPolicy instance will be used
15:01:23.824 [main] INFO  i.m.b.s.CTrieSubscriptionDirectory - Initializing CTrie
15:01:23.833 [main] INFO  i.m.b.s.CTrieSubscriptionDirectory - Initializing subscriptions store...
15:01:24.020 [main] INFO  i.m.b.NewNettyAcceptor - Netty is using NIO
15:01:25.280 [main] INFO  i.m.b.NewNettyAcceptor - Server bound to host=0.0.0.0, port=1884, protocol=TCP MQTT
15:01:25.316 [main] INFO  i.m.b.NewNettyAcceptor - Server bound to host=0.0.0.0, port=8080, protocol=Websocket MQTT
15:01:25.320 [main] INFO  i.m.b.Server - Moquette integration has been started successfully in 1532 ms
15:01:25.387 [main] INFO  o.e.b.c.r.RegistryComponent - Creating InMemoryRegistry
sep 27, 2023 3:01:25 PM org.apache.catalina.core.StandardContext setPath
WARNING: A context path must either be an empty string or start with a '/' and do not end with a '/'. The path [registry] does not meet these criteria and has been changed to [/registry]
sep 27, 2023 3:01:26 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-nio-4000"]
sep 27, 2023 3:01:26 PM org.apache.catalina.core.StandardService startInternal
INFO: Starting service [Tomcat]
sep 27, 2023 3:01:26 PM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet engine: [Apache Tomcat/9.0.73]
sep 27, 2023 3:01:27 PM org.apache.catalina.util.SessionIdGeneratorBase createSecureRandom
WARNING: Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [217] milliseconds.
sep 27, 2023 3:01:27 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-nio-4000"]
15:01:27.209 [main] INFO  o.e.b.c.r.RegistryComponent - Registry server started
15:01:27.221 [main] INFO  o.e.b.c.c.BaSyxConfiguration - Loading properties from resource 'aas.properties'
15:01:27.224 [main] INFO  o.e.b.c.c.BaSyxConfiguration - Loading from inputStream: java.io.BufferedInputStream@2a79d4b1
15:01:27.224 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.aasxUpload: 'Enabled'
15:01:27.224 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.backend: 'InMemory'
15:01:27.225 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.authorization: 'Disabled'
15:01:27.225 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.events: 'MQTTV2_SIMPLE_ENCODING'
15:01:27.225 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.source: ''
15:01:27.256 [main] INFO  o.e.b.c.a.AASServerComponent - Create the server...
15:01:27.264 [main] INFO  o.e.b.c.c.BaSyxConfiguration - Loading properties from resource 'mqtt.properties'
15:01:27.267 [main] INFO  o.e.b.c.c.BaSyxConfiguration - Loading from inputStream: java.io.BufferedInputStream@5286c33a
15:01:27.268 [main] INFO  o.e.b.c.c.BaSyxConfiguration - server: 'tcp://localhost:1884'
15:01:27.268 [main] INFO  o.e.b.c.c.BaSyxConfiguration - clientId: 'aasServerClientId'
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.eclipse.paho.client.mqttv3.internal.FileLock (file:/C:/Users/adm2pribis/.m2/repository/org/eclipse/paho/org.eclipse.paho.client.mqttv3/1.2.5/org.eclipse.paho.client.mqttv3-1.2.5.jar) to method sun.nio.ch.FileLockImpl.release()
WARNING: Please consider reporting this to the maintainers of org.eclipse.paho.client.mqttv3.internal.FileLock
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
15:01:28.046 [nioEventLoopGroup-3-1] INFO  i.m.b.m.MQTTMessageLogger - C->B CONNECT <null>
15:01:28.121 [main] INFO  o.e.b.e.a.a.m.MqttV2AASAggregatorObserver - Create new MQTT AAS Aggregator Observer for endpoint tcp://localhost:1884
15:01:28.228 [main] INFO  o.e.b.c.a.AASServerComponent - Start the server
sep 27, 2023 3:01:28 PM org.apache.catalina.core.StandardContext setPath
WARNING: A context path must either be an empty string or start with a '/' and do not end with a '/'. The path [aasServer] does not meet these criteria and has been changed to [/aasServer]
15:01:28.231 [main] INFO  o.e.b.v.p.h.s.BaSyxHTTPServer - DefaultServlet cannot be cast to BasysHTTPServlet java.lang.ClassCastException: class org.apache.catalina.servlets.DefaultServlet cannot be cast to class org.eclipse.basyx.vab.protocol.http.server.BasysHTTPServlet (org.apache.catalina.servlets.DefaultServlet and org.eclipse.basyx.vab.protocol.http.server.BasysHTTPServlet are in unnamed module of loader 'app')
sep 27, 2023 3:01:28 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-nio-4001"]
sep 27, 2023 3:01:28 PM org.apache.catalina.core.StandardService startInternal
INFO: Starting service [Tomcat]
sep 27, 2023 3:01:28 PM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet engine: [Apache Tomcat/9.0.73]
sep 27, 2023 3:01:28 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-nio-4001"]
15:01:29.608 [http-nio-4001-exec-1] INFO  o.e.b.e.s.a.m.MqttV2SubmodelAggregatorObserver - Create new MQTT Submodel Aggregator Observer for endpoint tcp://localhost:1884
15:01:29.645 [nioEventLoopGroup-3-1] INFO  i.m.b.m.MQTTMessageLogger - C<-B PUBACK <aasServerClientId> packetID <1>
15:01:29.712 [main] INFO  o.e.b.a.r.p.AASRegistryProxy - AAS with Id eclipse.basyx.aas.oven created
15:01:29.995 [nioEventLoopGroup-3-1] INFO  i.m.b.m.MQTTMessageLogger - C<-B PUBACK <aasServerClientId> packetID <2>
FrankSchnicke commented 1 year ago

This is indeed very strange. Can you change the log level to "trace" by adding the following file as logback.xml in your src/main/resource folder and post the result?

<?xml version="1.0" encoding="UTF-8"?>

<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">

    <!-- Example for a filter, which removes all entries not containing "[TEST]" in the message. -->

    <!--<filter class="ch.qos.logback.core.filter.EvaluatorFilter">      
      <evaluator>
        <expression>return message.contains("[TEST]");</expression>
      </evaluator>
      <OnMismatch>DENY</OnMismatch>
      <OnMatch>NEUTRAL</OnMatch>
    </filter>-->

    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{5} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="TRACE">          
    <appender-ref ref="STDOUT" />
  </root>  

</configuration>
STUBA-rupr commented 1 year ago

There is no record about UPLOAD action:

15:07:20,470 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.11
15:07:20,487 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - No custom configurators were discovered as a service.
15:07:20,487 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
15:07:20,494 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
15:07:20,577 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
15:07:20,581 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
15:07:20,644 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 89 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
15:07:20,644 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
15:07:20,647 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
15:07:20,651 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
15:07:20,680 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/adm2pribis/eclipse-workspace/basyx/basyx-java-examples/basyx.hello_world/target/classes/logback.xml]
15:07:20,684 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@14555e0a - Resource [logback.xml] occurs multiple times on the classpath.
15:07:20,685 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@14555e0a - Resource [logback.xml] occurs at [file:/C:/Users/adm2pribis/eclipse-workspace/basyx/basyx-java-components/basyx.components/basyx.components.docker/basyx.components.registry/target/classes/logback.xml]
15:07:20,685 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@14555e0a - Resource [logback.xml] occurs at [file:/C:/Users/adm2pribis/eclipse-workspace/basyx/basyx-java-examples/basyx.hello_world/target/classes/logback.xml]
15:07:20,685 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@14555e0a - Resource [logback.xml] occurs at [file:/C:/Users/adm2pribis/eclipse-workspace/basyx/basyx-java-components/basyx.components/basyx.components.docker/basyx.components.AASServer/target/classes/logback.xml]
15:07:21,036 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT]
15:07:21,036 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
15:07:21,063 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
15:07:21,153 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to DEBUG
15:07:21,160 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT]
15:07:21,161 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@4bb33f74 - End of configuration.
15:07:21,162 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@759d26fb - Registering current configuration as safe fallback point
15:07:21,162 |-INFO in ch.qos.logback.classic.util.ContextInitializer@7a419da4 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 515 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY

15:07:21.186 [main] INFO  i.m.b.c.ResourceLoaderConfig - Loading configuration. ResourceLoader = classpath resource, configName = null.
15:07:21.194 [main] INFO  i.m.b.c.ClasspathResourceLoader - Loading resource. RelativePath = config/moquette.conf.
15:07:21.197 [main] INFO  i.m.b.c.ResourceLoaderConfig - Parsing configuration properties. ResourceLoader = classpath resource, configName = null.
15:07:21.201 [main] DEBUG i.m.b.Server - Starting Moquette integration using IConfig instance
15:07:21.202 [main] DEBUG i.m.b.Server - Starting moquette integration using IConfig instance and intercept handlers
15:07:21.207 [main] DEBUG i.m.b.Server - Configuring Using persistent store file, path: null
15:07:21.207 [main] INFO  i.m.b.Server - Configuring message interceptors...
15:07:21.211 [main] INFO  i.m.i.BrokerInterceptor - Initializing broker interceptor. InterceptorIds=[]
15:07:21.222 [main] DEBUG i.m.b.Server - Initialized MQTT protocol processor
15:07:21.223 [main] INFO  i.m.b.Server - Using default SSL context creator
15:07:21.226 [main] DEBUG i.m.b.Server - Configuring MQTT authenticator
15:07:21.228 [main] INFO  i.m.b.Server - An io.moquette.broker.security.AcceptAllAuthenticator authenticator instance will be used
15:07:21.228 [main] DEBUG i.m.b.Server - Configuring MQTT authorizator policy
15:07:21.230 [main] INFO  i.m.b.Server - Authorizator policy io.moquette.broker.security.PermitAllAuthorizatorPolicy instance will be used
15:07:21.241 [main] INFO  i.m.b.s.CTrieSubscriptionDirectory - Initializing CTrie
15:07:21.251 [main] INFO  i.m.b.s.CTrieSubscriptionDirectory - Initializing subscriptions store...
15:07:21.363 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
15:07:21.369 [main] DEBUG i.n.u.i.PlatformDependent - Platform: Windows
15:07:21.376 [main] DEBUG i.n.u.i.PlatformDependent0 - -Dio.netty.noUnsafe: false
15:07:21.376 [main] DEBUG i.n.u.i.PlatformDependent0 - Java version: 11
15:07:21.382 [main] DEBUG i.n.u.i.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
15:07:21.386 [main] DEBUG i.n.u.i.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
15:07:21.388 [main] DEBUG i.n.u.i.PlatformDependent0 - java.nio.Buffer.address: available
15:07:21.390 [main] DEBUG i.n.u.i.PlatformDependent0 - direct buffer constructor: unavailable
java.lang.UnsupportedOperationException: Reflective setAccessible(true) disabled
    at io.netty.util.internal.ReflectionUtil.trySetAccessible(ReflectionUtil.java:31)
    at io.netty.util.internal.PlatformDependent0$4.run(PlatformDependent0.java:238)
    at java.base/java.security.AccessController.doPrivileged(Native Method)
    at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:232)
    at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:294)
    at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:93)
    at io.netty.util.ConstantPool.<init>(ConstantPool.java:32)
    at io.netty.util.AttributeKey$1.<init>(AttributeKey.java:27)
    at io.netty.util.AttributeKey.<clinit>(AttributeKey.java:27)
    at io.moquette.broker.NewNettyMQTTHandler.<clinit>(NewNettyMQTTHandler.java:37)
    at io.moquette.broker.Server.startServer(Server.java:186)
    at io.moquette.broker.Server.startServer(Server.java:133)
    at io.moquette.broker.Server.startServer(Server.java:120)
    at org.eclipse.basyx.hello_world.HelloWorldServer.startMqttBroker(HelloWorldServer.java:142)
    at org.eclipse.basyx.hello_world.HelloWorldServer.main(HelloWorldServer.java:74)
15:07:21.401 [main] DEBUG i.n.u.i.PlatformDependent0 - java.nio.Bits.unaligned: available, true
15:07:21.404 [main] DEBUG i.n.u.i.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable
java.lang.IllegalAccessException: class io.netty.util.internal.PlatformDependent0$6 cannot access class jdk.internal.misc.Unsafe (in module java.base) because module java.base does not export jdk.internal.misc to unnamed module @18271936
    at java.base/jdk.internal.reflect.Reflection.newIllegalAccessException(Reflection.java:361)
    at java.base/java.lang.reflect.AccessibleObject.checkAccess(AccessibleObject.java:591)
    at java.base/java.lang.reflect.Method.invoke(Method.java:558)
    at io.netty.util.internal.PlatformDependent0$6.run(PlatformDependent0.java:352)
    at java.base/java.security.AccessController.doPrivileged(Native Method)
    at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:343)
    at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:294)
    at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:93)
    at io.netty.util.ConstantPool.<init>(ConstantPool.java:32)
    at io.netty.util.AttributeKey$1.<init>(AttributeKey.java:27)
    at io.netty.util.AttributeKey.<clinit>(AttributeKey.java:27)
    at io.moquette.broker.NewNettyMQTTHandler.<clinit>(NewNettyMQTTHandler.java:37)
    at io.moquette.broker.Server.startServer(Server.java:186)
    at io.moquette.broker.Server.startServer(Server.java:133)
    at io.moquette.broker.Server.startServer(Server.java:120)
    at org.eclipse.basyx.hello_world.HelloWorldServer.startMqttBroker(HelloWorldServer.java:142)
    at org.eclipse.basyx.hello_world.HelloWorldServer.main(HelloWorldServer.java:74)
15:07:21.405 [main] DEBUG i.n.u.i.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): unavailable
15:07:21.405 [main] DEBUG i.n.u.i.PlatformDependent - sun.misc.Unsafe: available
15:07:21.441 [main] DEBUG i.n.u.i.PlatformDependent - maxDirectMemory: 4294967296 bytes (maybe)
15:07:21.442 [main] DEBUG i.n.u.i.PlatformDependent - -Dio.netty.tmpdir: C:\Users\ADM2PR~1\AppData\Local\Temp\5 (java.io.tmpdir)
15:07:21.443 [main] DEBUG i.n.u.i.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
15:07:21.447 [main] DEBUG i.n.u.i.PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes
15:07:21.447 [main] DEBUG i.n.u.i.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
15:07:21.451 [main] DEBUG i.n.u.i.CleanerJava9 - java.nio.ByteBuffer.cleaner(): available
15:07:21.452 [main] DEBUG i.n.u.i.PlatformDependent - -Dio.netty.noPreferDirect: false
15:07:21.471 [main] DEBUG i.m.b.NewNettyAcceptor - Initializing Netty acceptor
15:07:21.471 [main] INFO  i.m.b.NewNettyAcceptor - Netty is using NIO
15:07:21.491 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
15:07:21.545 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
15:07:21.546 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
15:07:21.571 [main] DEBUG i.n.c.n.NioEventLoop - -Dio.netty.noKeySetOptimization: false
15:07:21.572 [main] DEBUG i.n.c.n.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
15:07:21.609 [main] DEBUG i.n.u.i.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
15:07:22.106 [main] DEBUG i.m.b.NewNettyAcceptor - Configuring TCP MQTT transport
15:07:22.110 [main] DEBUG i.m.b.NewNettyAcceptor - Initializing integration. Protocol=TCP MQTT
15:07:22.141 [main] DEBUG i.m.b.NewNettyAcceptor - Binding integration. host=0.0.0.0, port=1884
15:07:22.198 [main] DEBUG i.n.c.DefaultChannelId - -Dio.netty.processId: 7544 (auto-detected)
15:07:22.204 [main] DEBUG i.n.u.NetUtil - -Djava.net.preferIPv4Stack: false
15:07:22.204 [main] DEBUG i.n.u.NetUtil - -Djava.net.preferIPv6Addresses: false
15:07:22.454 [main] DEBUG i.n.u.NetUtilInitializations - Loopback interface: lo (Software Loopback Interface 1, 127.0.0.1)
15:07:22.455 [main] DEBUG i.n.u.NetUtil - Failed to get SOMAXCONN from sysctl and file \proc\sys\net\core\somaxconn. Default: 200
15:07:22.702 [main] DEBUG i.n.c.DefaultChannelId - -Dio.netty.machineId: 00:0c:29:ff:fe:93:66:de (auto-detected)
15:07:22.724 [main] DEBUG i.n.u.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
15:07:22.724 [main] DEBUG i.n.u.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
15:07:22.779 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 16
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 16
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
15:07:22.780 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
15:07:22.781 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
15:07:22.781 [main] DEBUG i.n.b.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
15:07:22.817 [main] DEBUG i.n.b.ByteBufUtil - -Dio.netty.allocator.type: pooled
15:07:22.818 [main] DEBUG i.n.b.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
15:07:22.818 [main] DEBUG i.n.b.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
15:07:22.846 [main] INFO  i.m.b.NewNettyAcceptor - Server bound to host=0.0.0.0, port=1884, protocol=TCP MQTT
15:07:22.881 [main] DEBUG i.m.b.NewNettyAcceptor - Configuring Websocket MQTT transport
15:07:22.881 [main] DEBUG i.m.b.NewNettyAcceptor - Initializing integration. Protocol=Websocket MQTT
15:07:22.881 [main] DEBUG i.m.b.NewNettyAcceptor - Binding integration. host=0.0.0.0, port=8080
15:07:22.882 [main] INFO  i.m.b.NewNettyAcceptor - Server bound to host=0.0.0.0, port=8080, protocol=Websocket MQTT
15:07:22.882 [nioEventLoopGroup-2-1] DEBUG i.m.b.NewNettyAcceptor - bound TCP MQTT port: 1884
15:07:22.887 [main] INFO  i.m.b.Server - Moquette integration has been started successfully in 1685 ms
15:07:22.887 [nioEventLoopGroup-2-2] DEBUG i.m.b.NewNettyAcceptor - bound Websocket MQTT port: 8080
15:07:22.949 [main] INFO  o.e.b.c.r.RegistryComponent - Creating InMemoryRegistry
sep 28, 2023 3:07:23 PM org.apache.catalina.core.StandardContext setPath
WARNING: A context path must either be an empty string or start with a '/' and do not end with a '/'. The path [registry] does not meet these criteria and has been changed to [/registry]
sep 28, 2023 3:07:23 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-nio-4000"]
sep 28, 2023 3:07:24 PM org.apache.catalina.core.StandardService startInternal
INFO: Starting service [Tomcat]
sep 28, 2023 3:07:24 PM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet engine: [Apache Tomcat/9.0.73]
sep 28, 2023 3:07:24 PM org.apache.catalina.util.SessionIdGeneratorBase createSecureRandom
WARNING: Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [267] milliseconds.
sep 28, 2023 3:07:24 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-nio-4000"]
15:07:24.777 [main] INFO  o.e.b.c.r.RegistryComponent - Registry server started
15:07:24.790 [main] INFO  o.e.b.c.c.BaSyxConfiguration - Loading properties from resource 'aas.properties'
15:07:24.793 [main] INFO  o.e.b.c.c.BaSyxConfiguration - Loading from inputStream: java.io.BufferedInputStream@74a6a609
15:07:24.794 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.aasxUpload: 'Enabled'
15:07:24.794 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.backend: 'InMemory'
15:07:24.794 [main] DEBUG o.e.b.c.c.BaSyxConfiguration - aas.id: 'aas-server'
15:07:24.794 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.authorization: 'Disabled'
15:07:24.794 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.events: 'MQTTV2_SIMPLE_ENCODING'
15:07:24.794 [main] INFO  o.e.b.c.c.BaSyxConfiguration - aas.source: ''
15:07:24.844 [main] INFO  o.e.b.c.a.AASServerComponent - Create the server...
15:07:24.851 [main] INFO  o.e.b.c.c.BaSyxConfiguration - Loading properties from resource 'mqtt.properties'
15:07:24.854 [main] INFO  o.e.b.c.c.BaSyxConfiguration - Loading from inputStream: java.io.BufferedInputStream@4e70a728
15:07:24.855 [main] INFO  o.e.b.c.c.BaSyxConfiguration - server: 'tcp://localhost:1884'
15:07:24.855 [main] INFO  o.e.b.c.c.BaSyxConfiguration - clientId: 'aasServerClientId'
15:07:24.855 [main] DEBUG o.e.b.c.c.BaSyxConfiguration - whitelist.element.patientTemplate.active: 'true'
15:07:24.856 [main] DEBUG o.e.b.c.c.BaSyxConfiguration - whitelist.patientTemplate: 'true'
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.eclipse.paho.client.mqttv3.internal.FileLock (file:/C:/Users/adm2pribis/.m2/repository/org/eclipse/paho/org.eclipse.paho.client.mqttv3/1.2.5/org.eclipse.paho.client.mqttv3-1.2.5.jar) to method sun.nio.ch.FileLockImpl.release()
WARNING: Please consider reporting this to the maintainers of org.eclipse.paho.client.mqttv3.internal.FileLock
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
15:07:25.218 [nioEventLoopGroup-3-1] DEBUG i.m.b.AutoFlushHandler - Initializing autoflush handler on channel [id: 0x6c02318a, L:/127.0.0.1:1884 - R:/127.0.0.1:54627] Cid: null
15:07:25.493 [nioEventLoopGroup-3-1] DEBUG i.n.u.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
15:07:25.493 [nioEventLoopGroup-3-1] DEBUG i.n.u.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
15:07:25.493 [nioEventLoopGroup-3-1] DEBUG i.n.u.Recycler - -Dio.netty.recycler.linkCapacity: 16
15:07:25.493 [nioEventLoopGroup-3-1] DEBUG i.n.u.Recycler - -Dio.netty.recycler.ratio: 8
15:07:25.493 [nioEventLoopGroup-3-1] DEBUG i.n.u.Recycler - -Dio.netty.recycler.delayedQueue.ratio: 8
15:07:25.516 [nioEventLoopGroup-3-1] DEBUG i.n.b.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
15:07:25.516 [nioEventLoopGroup-3-1] DEBUG i.n.b.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
15:07:25.520 [nioEventLoopGroup-3-1] DEBUG i.n.u.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@2e4ece5
15:07:25.587 [nioEventLoopGroup-3-1] INFO  i.m.b.m.MQTTMessageLogger - C->B CONNECT <null>
15:07:25.588 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - Received MQTT message, type: CONNECT
15:07:25.621 [nioEventLoopGroup-3-1] DEBUG i.m.b.m.MQTTMessageLogger - C<-B CONNACK <null>
15:07:25.629 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - Connection has been configured CId=aasServerClientId, keepAlive=60, removeTemporaryQoS2=true, idleTime=90
15:07:25.633 [nioEventLoopGroup-3-1] DEBUG i.m.b.InflightResender - Initializing autoflush handler on channel [id: 0x6c02318a, L:/127.0.0.1:1884 - R:/127.0.0.1:54627]
15:07:25.636 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - readCompleted client CId: aasServerClientId
15:07:25.703 [main] INFO  o.e.b.e.a.a.m.MqttV2AASAggregatorObserver - Create new MQTT AAS Aggregator Observer for endpoint tcp://localhost:1884
15:07:25.856 [main] INFO  o.e.b.c.a.AASServerComponent - Start the server
sep 28, 2023 3:07:25 PM org.apache.catalina.core.StandardContext setPath
WARNING: A context path must either be an empty string or start with a '/' and do not end with a '/'. The path [aasServer] does not meet these criteria and has been changed to [/aasServer]
15:07:25.861 [main] INFO  o.e.b.v.p.h.s.BaSyxHTTPServer - DefaultServlet cannot be cast to BasysHTTPServlet java.lang.ClassCastException: class org.apache.catalina.servlets.DefaultServlet cannot be cast to class org.eclipse.basyx.vab.protocol.http.server.BasysHTTPServlet (org.apache.catalina.servlets.DefaultServlet and org.eclipse.basyx.vab.protocol.http.server.BasysHTTPServlet are in unnamed module of loader 'app')
sep 28, 2023 3:07:25 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-nio-4001"]
sep 28, 2023 3:07:25 PM org.apache.catalina.core.StandardService startInternal
INFO: Starting service [Tomcat]
sep 28, 2023 3:07:25 PM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet engine: [Apache Tomcat/9.0.73]
sep 28, 2023 3:07:25 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-nio-4001"]
15:07:27.192 [http-nio-4001-exec-1] INFO  o.e.b.e.s.a.m.MqttV2SubmodelAggregatorObserver - Create new MQTT Submodel Aggregator Observer for endpoint tcp://localhost:1884
15:07:27.209 [http-nio-4001-exec-1] DEBUG o.e.b.e.s.m.MqttEventService - Send MQTT message to aas-repository/aas-server/shells/created: {"modelType":{"name":"AssetAdministrationShell"},"idShort":"oven","identification":{"idType":"Custom","id":"eclipse.basyx.aas.oven"},"dataSpecification":[],"embeddedDataSpecifications":[],"submodels":[],"asset":{"modelType":{"name":"Asset"},"dataSpecification":[],"embeddedDataSpecifications":[],"idShort":"ovenAsset","identification":{"idType":"Custom","id":"eclipse.basyx.asset.oven"},"kind":"Instance"},"views":[],"conceptDictionary":[]}
15:07:27.233 [nioEventLoopGroup-3-1] DEBUG i.m.b.m.MQTTMessageLogger - C->B PUBLISH <aasServerClientId> to topics <aas-repository/aas-server/shells/created>
15:07:27.234 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - Received MQTT message, type: PUBLISH
15:07:27.239 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - OUT PUBACK
15:07:27.240 [nioEventLoopGroup-3-1] INFO  i.m.b.m.MQTTMessageLogger - C<-B PUBACK <aasServerClientId> packetID <1>
15:07:27.244 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - readCompleted client CId: aasServerClientId
15:07:27.291 [main] INFO  o.e.b.a.r.p.AASRegistryProxy - AAS with Id eclipse.basyx.aas.oven created
15:07:27.408 [http-nio-4000-exec-1] DEBUG o.e.b.a.r.m.AASRegistry - Registered eclipse.basyx.aas.oven
15:07:27.610 [http-nio-4001-exec-4] DEBUG o.e.b.e.s.m.MqttEventService - Send MQTT message to aas-repository/aas-server/shells/eclipse.basyx.aas.oven/submodels/created: {"idShort":"documentationSm","identification":{"idType":"Custom","id":"eclipse.basyx.submodel.documentation"},"dataSpecification":[],"embeddedDataSpecifications":[],"modelType":{"name":"Submodel"},"kind":"Instance","submodelElements":{},"parent":{"keys":[{"type":"AssetAdministrationShell","local":true,"value":"eclipse.basyx.aas.oven","idType":"Custom"}]}}
15:07:27.615 [nioEventLoopGroup-3-1] DEBUG i.m.b.m.MQTTMessageLogger - C->B PUBLISH <aasServerClientId> to topics <aas-repository/aas-server/shells/eclipse.basyx.aas.oven/submodels/created>
15:07:27.616 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - Received MQTT message, type: PUBLISH
15:07:27.616 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - OUT PUBACK
15:07:27.616 [nioEventLoopGroup-3-1] INFO  i.m.b.m.MQTTMessageLogger - C<-B PUBACK <aasServerClientId> packetID <2>
15:07:27.617 [nioEventLoopGroup-3-1] DEBUG i.m.b.MQTTConnection - readCompleted client CId: aasServerClientId
15:07:28.269 [http-nio-4000-exec-4] DEBUG o.e.b.a.r.m.AASRegistry - Registered submodel documentationSm for AAS eclipse.basyx.aas.oven

But I investigated the code and I found the place where it "jump out" as: image fileStreams is empty. This is my request I sent: image

My suspect is that I made somewhere a fool mistake

FrankSchnicke commented 1 year ago

Is this maybe a bug in Postman? Can you verify that the postman request is looking as expected, i.e., having the AASX attached?

STUBA-rupr commented 1 year ago

Nice catch! It sends it as a GET. image

Once I use command line curl it works. So many hours wasted.