Menu ▾ ▴

after upgrade to 3.4 from 2.11 error java.lang.NullPointerException

Open Discussion
robfantini2
2022-11-09
2023-03-10
1 2 3 > >> (Page 1 of 3)

  • robfantini2

    robfantini2 - 2022-11-09

    Hello
    /var/log/syslog is getting 100MB every few minutes of these lines:

    Nov 8 20:37:01 edi start-openas2.sh[182]: java.lang.NullPointerException Nov 8 20:37:01 edi start-openas2.sh[182]: Nov 08, 2022 8:37:00 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call Nov 8 20:37:01 edi start-openas2.sh[182]: SEVERE: null Nov 8 20:37:01 edi start-openas2.sh[182]: java.lang.NullPointerException Nov 8 20:37:01 edi start-openas2.sh[182]: Nov 08, 2022 8:37:00 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call Nov 8 20:37:01 edi start-openas2.sh[182]: SEVERE: null Nov 8 20:37:01 edi start-openas2.sh[182]: java.lang.NullPointerException Nov 8 20:37:01 edi start-openas2.sh[182]: Nov 08, 2022 8:37:00 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call Nov 8 20:37:01 edi start-openas2.sh[182]: SEVERE: null Nov 8 20:37:01 edi start-openas2.sh[182]: java.lang.NullPointerException Nov 8 20:37:01 edi start-openas2.sh[182]: Nov 08, 2022 8:37:00 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call Nov 8 20:37:01 edi start-openas2.sh[182]: SEVERE: null

    An idea what can be done to solve this issue?

    I search the forum and found this:
    https://sourceforge.net/p/openas2/discussion/265567/thread/ad254a4865/?limit=25#0921

    however did not see a sentdir line to change.

    besides the log error I was able to send a file and received a AsyncMDN

     

  • robfantini2

    robfantini2 - 2022-11-09

    I changed the config files to new format.

    the errors continue

    /var/log/syslog are getting close to 100MB larger every minute.

     

  • Christopher Broderick

    Christopher Broderick - 2022-11-09

    You need to start the application directly using the start_openas2.sh file from the command line.
    That will show you what the real errors are that are causing the daemon launch to fail.

     

  • robfantini2

    robfantini2 - 2022-11-09

    Hello,

    starting from cli, here is the output:

    ./start-openas2.sh

Running /usr/lib/jvm/java-8-oracle/bin/java -Xms32m -Xmx384m -Dorg.apache.commons.logging.Log=org.openas2.logging.Log -Dopenas2.config.file=/opt/OpenAS2/bin/../config/config.xml -cp .:/opt/OpenAS2/bin/../lib/activation-1.1.jar:/opt/OpenAS2/bin/../lib/angus-activation-1.0.0.jar:/opt/OpenAS2/bin/../lib/aopalliance-repackaged-3.0.3.jar:/opt/OpenAS2/bin/../lib/bcmail-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcpg-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcpkix-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcprov-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcutil-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/commons-cli-1.5.0.jar:/opt/OpenAS2/bin/../lib/commons-codec-1.11.jar:/opt/OpenAS2/bin/../lib/commons-io-2.11.0.jar:/opt/OpenAS2/bin/../lib/commons-lang3-3.12.0.jar:/opt/OpenAS2/bin/../lib/commons-logging-1.2.jar:/opt/OpenAS2/bin/../lib/dom4j-2.1.3.jar:/opt/OpenAS2/bin/../lib/grizzly-framework-4.0.0.jar:/opt/OpenAS2/bin/../lib/grizzly-http-4.0.0.jar:/opt/OpenAS2/bin/../lib/grizzly-http-server-4.0.0.jar:/opt/OpenAS2/bin/../lib/h2-2.1.214.jar:/opt/OpenAS2/bin/../lib/hk2-api-3.0.3.jar:/opt/OpenAS2/bin/../lib/hk2-locator-3.0.3.jar:/opt/OpenAS2/bin/../lib/hk2-utils-3.0.3.jar:/opt/OpenAS2/bin/../lib/httpclient-4.5.13.jar:/opt/OpenAS2/bin/../lib/httpcore-4.4.15.jar:/opt/OpenAS2/bin/../lib/jackson-annotations-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-core-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-databind-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-module-jakarta-xmlbind-annotations-2.13.3.jar:/opt/OpenAS2/bin/../lib/jakarta.activation-2.0.1.jar:/opt/OpenAS2/bin/../lib/jakarta.activation-api-2.1.0.jar:/opt/OpenAS2/bin/../lib/jakarta.annotation-api-2.1.1.jar:/opt/OpenAS2/bin/../lib/jakarta.inject-api-2.0.1.jar:/opt/OpenAS2/bin/../lib/jakarta.validation-api-3.0.2.jar:/opt/OpenAS2/bin/../lib/jakarta.ws.rs-api-3.1.0.jar:/opt/OpenAS2/bin/../lib/jakarta.xml.bind-api-4.0.0.jar:/opt/OpenAS2/bin/../lib/javassist-3.28.0-GA.jar:/opt/OpenAS2/bin/../lib/javax.activation-api-1.2.0.jar:/opt/OpenAS2/bin/../lib/javax.annotation-api-1.3.2.jar:/opt/OpenAS2/bin/../lib/javax.mail-1.6.2.jar:/opt/OpenAS2/bin/../lib/javax.ws.rs-api-2.1.1.jar:/opt/OpenAS2/bin/../lib/jaxb-api-2.4.0-b180830.0359.jar:/opt/OpenAS2/bin/../lib/jaxb-core-4.0.1.jar:/opt/OpenAS2/bin/../lib/jaxb-impl-4.0.1.jar:/opt/OpenAS2/bin/../lib/jersey-client-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-common-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-container-grizzly2-http-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-entity-filtering-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-hk2-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-media-json-jackson-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-server-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/openas2-server-3.4.0.jar:/opt/OpenAS2/bin/../lib/openas2-server.jar:/opt/OpenAS2/bin/../lib/osgi-resource-locator-1.0.3.jar:/opt/OpenAS2/bin/../lib/sentry-6.4.2.jar:/opt/OpenAS2/bin org.openas2.app.OpenAS2Server

2022-11-09 06:05:48.198 FINE OpenAS2Server: Retrieving config file...
2022-11-09 06:05:48.607 FINE OpenAS2Server: MANIFEST not accessed: Duplicate manifests detected: file:/opt/OpenAS2/lib/openas2-server-3.4.0.jar!/META-INF/MANIFEST.MF ::: file:/opt/OpenAS2/lib/openas2-server.jar!/META-INF/MANIFEST.MF
org.openas2.OpenAS2Exception: Duplicate manifests detected: file:/opt/OpenAS2/lib/openas2-server-3.4.0.jar!/META-INF/MANIFEST.MF ::: file:/opt/OpenAS2/lib/openas2-server.jar!/META-INF/MANIFEST.MF
        at org.openas2.app.OpenAS2Server.getManifestAttributes(OpenAS2Server.java:113)
        at org.openas2.XMLSession.getManifestAttributes(XMLSession.java:373)
        at org.openas2.XMLSession.<init>(XMLSession.java:70)
        at org.openas2.app.OpenAS2Server$Builder.run(OpenAS2Server.java:182)
        at org.openas2.app.OpenAS2Server.main(OpenAS2Server.java:72)


2022-11-09 06:05:48.612 FINE OpenAS2Server: Using MANIFEST file:/opt/OpenAS2/lib/openas2-server-3.4.0.jar!/META-INF/MANIFEST.MF
2022-11-09 06:05:48.684 FINE XMLSession: Loading configuration...
2022-11-09 06:05:48.684 FINE XMLSession: Loading properties...
2022-11-09 06:05:50.131 FINE XMLSession: Loading log manager(s)...
2022-11-09 06:05:50.161 FINE XMLSession: Loading command processor(s)...
2022-11-09 06:05:50.165 FINE XMLSession: Command processor is disabled ... ignoring: org.openas2.cmd.processor.SocketCommandProcessor
2022-11-09 06:05:50.166 FINE XMLSession: Loading processor nodes...
2022-11-09 06:05:50.178 FINE XMLSession: Loading partnerships...
2022-11-09 06:05:50.236 FINE OpenAS2Server: Shutdown hook registered.
2022-11-09 06:05:50.236 FINE OpenAS2Server: Starting OpenAS2 Server v3.4.0...
2022-11-09 06:05:50.581 FINE DefaultProcessor: DbTrackingModule started.
2022-11-09 06:05:50.590 FINE DefaultProcessor: AS2ReceiverModule started.
2022-11-09 06:05:50.591 FINE DefaultProcessor: AS2MDNReceiverModule started.
2022-11-09 06:05:50.592 FINE DefaultProcessor: DirectoryResenderModule started.
2022-11-09 06:05:50.592 FINE DefaultProcessor: 4 active module(s) started.
2022-11-09 06:05:50.606 FINE OpenAS2Server: OpenAS2 Server v3.4.0 started.

    the startup looks okay to me,

    the logs are quiet .

    and was able to send a test file and get a MDN .

    I'll test stopping the service and start it using systemd

     

  • Christopher Broderick

    Christopher Broderick - 2022-11-09

    Lookss like you have old and new jars mixed together.

    Look at tthis:

    2022-11-09 06:05:48.607 FINE OpenAS2Server: MANIFEST not accessed: Duplicate manifests detected: file:/opt/OpenAS2/lib/openas2-server-3.4.0.jar!/META-INF/MANIFEST.MF ::: file:/opt/OpenAS2/lib/openas2-server.jar!/META-INF/MANIFEST.MF
org.openas2.OpenAS2Exception: Duplicate manifests detected: file:/opt/OpenAS2/lib/openas2-server-3.4.0.jar!/META-INF/MANIFEST.MF ::: file:/opt/OpenAS2/lib/openas2-server.jar!/META-INF/MANIFEST.MF
        at org.openas2.app.OpenAS2Server.getManifestAttributes(OpenAS2Server.java:113)
        at org.openas2.XMLSession.getManifestAttributes(XMLSession.java:373)
        at org.openas2.XMLSession.<init>(XMLSession.java:70)
        at org.openas2.app.OpenAS2Server$Builder.run(OpenAS2Server.java:182)
        at org.openas2.app.OpenAS2Server.main(OpenAS2Server.java:72)
     

  • Christopher Broderick

    Christopher Broderick - 2022-11-09

    It may be the CLASSPATH setting for the java command (the "-cp" bit) including the old and new jars.

     

    • robfantini2

      robfantini2 - 2022-11-09

      I am unfamiliar with java.
      would these jars be located within openas2 directories ? Or part of java software ?

       

  • robfantini2

    robfantini2 - 2022-11-09

    start using systemd causes the issue. 

    # systemctl status openas2.service
● openas2.service - OpenAS2 Server
     Loaded: loaded (/etc/systemd/system/openas2.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2022-11-09 06:24:47 EST; 23s ago
    Process: 7813 ExecStart=/opt/OpenAS2/bin/start-openas2.sh (code=exited, status=0/SUCCESS)
   Main PID: 7826 (java)
      Tasks: 21 (limit: 309027)
     Memory: 214.6M
        CPU: 9.892s
     CGroup: /system.slice/openas2.service
             └─7826 /usr/lib/jvm/java-8-oracle/jre/bin/java -Xms32m -Xmx384m -Dorg.apache.commons.logging.Log=org.openas2.logging.Log -Dopenas2.config.file=/opt/OpenAS2/bin/../config/confi>

Nov 09 06:24:50 edi start-openas2.sh[7826]:         at java.lang.Thread.run(Thread.java:748)
Nov 09 06:24:50 edi start-openas2.sh[7826]: Nov 09, 2022 6:24:49 AM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 09 06:24:50 edi start-openas2.sh[7826]: SEVERE: null
Nov 09 06:24:50 edi start-openas2.sh[7826]: java.lang.NullPointerException
Nov 09 06:24:50 edi start-openas2.sh[7826]:         at org.openas2.cmd.processor.StreamCommandProcessor.readLine(StreamCommandProcessor.java:107)
Nov 09 06:24:50 edi start-openas2.sh[7826]:         at org.openas2.cmd.processor.StreamCommandProcessor.processCommand(StreamCommandProcessor.java:49)
Nov 09 06:24:50 edi start-openas2.sh[7826]:         at org.openas2.cmd.processor.BaseCommandProcessor$1.call(BaseCommandProcessor.java:95)
Nov 09 06:24:50 edi start-openas2.sh[7826]:         at org.openas2.cmd.processor.BaseCommandProcessor$1.call(BaseCommandProcessor.java:90)
Nov 09 06:24:50 edi start-openas2.sh[7826]:         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Nov 09 06:24:50 edi start-openas2.sh[7826]:         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

    We have used systemd for a couple years to start openas2 .

    I could try to use something besides systemd , however it may make sense to try to fix this issue for others .

    I'll continue to work on this .

     

  • Christopher Broderick

    Christopher Broderick - 2022-11-09

    It will not be solved using a different startup mechanism.
    Fix your classpath and you will probably fix your systemd issue.
    Starting from the command line is slightly different than launching using systemd in as much as the working directory will be different and the order of loading the jars will likely change so the use of old and new jars is not guaranteed to be in the same sequence meaning you will get random errors.

     

    • robfantini2

      robfantini2 - 2022-11-09

      forgive my lack of java knowledge...

      Is classpath configured in a openas2 file or operating system?

       

  • Christopher Broderick

    Christopher Broderick - 2022-11-09

    The start-openas2.sh file sets it.
    Search for "CLASSPATH" in that file.

    HOWEVER: In the log message for duplicate manifest files I see this:
    Duplicate manifests detected: file:/opt/OpenAS2/lib/openas2-server-3.4.0.jar!/META-INF/MANIFEST.MF ::: file:/opt/OpenAS2/lib/openas2-server.jar!/META-INF/MANIFEST.MF

    ie. Two different OpenAS2 server jar files in the same lib folder.

    Since they re in the same folder, I am guessing you left all the old jars there and added the new ones which is going to create completely random results because the clas loader is not guranteed to load files in the same order every time you start a Java program.

    I suggest you delete all files from the lib folder and copy all the files from the new package into the lib folder you are using for starting OpenAS2 (/opt/OpenAS2/lib)

     

  • robfantini2

    robfantini2 - 2022-11-09

    from start-openas2.sh:

    # Expand the classpath instead of using file globbing expansion in the java command as it seems to mess with Mailcap loading
CLASSPATH=$(echo "${binDir}/../lib/"*".jar" | tr ' ' ':')
# Include the bin dir so that commons-logging.properties is always found
CLASSPATH=${CLASSPATH}:${binDir}

    I do this every upgrade so the the script does not need to be modified:

    cd /opt/OpenAS2/lib
    cp openas2-server-3.4.0.jar openas2-server.jar

    that would cause two identical jar files at /opt/OpenAS2/lib

    I'll try moving openas2-server-3.4.0.jar aside.

    [ the rest of the jar files at /opt/OpenAs2/lib have the timestamp of Oct 3 13:37 ]

     

  • robfantini2

    robfantini2 - 2022-11-09

    after moving the extra jar file the startup error seems to be gone:

    root@edi:[/opt/OpenAS2/bin]:# ./start-openas2.sh

Running /usr/lib/jvm/java-8-oracle/bin/java -Xms32m -Xmx384m -Dorg.apache.commons.logging.Log=org.openas2.logging.Log -Dopenas2.config.file=/opt/OpenAS2/bin/../config/config.xml -cp .:/opt/OpenAS2/bin/../lib/activation-1.1.jar:/opt/OpenAS2/bin/../lib/angus-activation-1.0.0.jar:/opt/OpenAS2/bin/../lib/aopalliance-repackaged-3.0.3.jar:/opt/OpenAS2/bin/../lib/bcmail-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcpg-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcpkix-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcprov-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcutil-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/commons-cli-1.5.0.jar:/opt/OpenAS2/bin/../lib/commons-codec-1.11.jar:/opt/OpenAS2/bin/../lib/commons-io-2.11.0.jar:/opt/OpenAS2/bin/../lib/commons-lang3-3.12.0.jar:/opt/OpenAS2/bin/../lib/commons-logging-1.2.jar:/opt/OpenAS2/bin/../lib/dom4j-2.1.3.jar:/opt/OpenAS2/bin/../lib/grizzly-framework-4.0.0.jar:/opt/OpenAS2/bin/../lib/grizzly-http-4.0.0.jar:/opt/OpenAS2/bin/../lib/grizzly-http-server-4.0.0.jar:/opt/OpenAS2/bin/../lib/h2-2.1.214.jar:/opt/OpenAS2/bin/../lib/hk2-api-3.0.3.jar:/opt/OpenAS2/bin/../lib/hk2-locator-3.0.3.jar:/opt/OpenAS2/bin/../lib/hk2-utils-3.0.3.jar:/opt/OpenAS2/bin/../lib/httpclient-4.5.13.jar:/opt/OpenAS2/bin/../lib/httpcore-4.4.15.jar:/opt/OpenAS2/bin/../lib/jackson-annotations-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-core-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-databind-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-module-jakarta-xmlbind-annotations-2.13.3.jar:/opt/OpenAS2/bin/../lib/jakarta.activation-2.0.1.jar:/opt/OpenAS2/bin/../lib/jakarta.activation-api-2.1.0.jar:/opt/OpenAS2/bin/../lib/jakarta.annotation-api-2.1.1.jar:/opt/OpenAS2/bin/../lib/jakarta.inject-api-2.0.1.jar:/opt/OpenAS2/bin/../lib/jakarta.validation-api-3.0.2.jar:/opt/OpenAS2/bin/../lib/jakarta.ws.rs-api-3.1.0.jar:/opt/OpenAS2/bin/../lib/jakarta.xml.bind-api-4.0.0.jar:/opt/OpenAS2/bin/../lib/javassist-3.28.0-GA.jar:/opt/OpenAS2/bin/../lib/javax.activation-api-1.2.0.jar:/opt/OpenAS2/bin/../lib/javax.annotation-api-1.3.2.jar:/opt/OpenAS2/bin/../lib/javax.mail-1.6.2.jar:/opt/OpenAS2/bin/../lib/javax.ws.rs-api-2.1.1.jar:/opt/OpenAS2/bin/../lib/jaxb-api-2.4.0-b180830.0359.jar:/opt/OpenAS2/bin/../lib/jaxb-core-4.0.1.jar:/opt/OpenAS2/bin/../lib/jaxb-impl-4.0.1.jar:/opt/OpenAS2/bin/../lib/jersey-client-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-common-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-container-grizzly2-http-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-entity-filtering-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-hk2-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-media-json-jackson-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-server-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/openas2-server.jar:/opt/OpenAS2/bin/../lib/osgi-resource-locator-1.0.3.jar:/opt/OpenAS2/bin/../lib/sentry-6.4.2.jar:/opt/OpenAS2/bin org.openas2.app.OpenAS2Server

2022-11-09 07:16:19.309 FINE OpenAS2Server: Retrieving config file...
2022-11-09 07:16:19.589 FINE OpenAS2Server: Using MANIFEST file:/opt/OpenAS2/lib/openas2-server.jar!/META-INF/MANIFEST.MF
2022-11-09 07:16:19.629 FINE XMLSession: Loading configuration...
2022-11-09 07:16:19.629 FINE XMLSession: Loading properties...
2022-11-09 07:16:20.725 FINE XMLSession: Loading log manager(s)...
2022-11-09 07:16:20.744 FINE XMLSession: Loading command processor(s)...
2022-11-09 07:16:20.749 FINE XMLSession: Command processor is disabled ... ignoring: org.openas2.cmd.processor.SocketCommandProcessor
2022-11-09 07:16:20.750 FINE XMLSession: Loading processor nodes...
2022-11-09 07:16:20.766 FINE XMLSession: Loading partnerships...
2022-11-09 07:16:20.803 FINE OpenAS2Server: Shutdown hook registered.
2022-11-09 07:16:20.803 FINE OpenAS2Server: Starting OpenAS2 Server v3.4.0...
2022-11-09 07:16:20.989 FINE DefaultProcessor: DbTrackingModule started.
2022-11-09 07:16:20.996 FINE DefaultProcessor: AS2ReceiverModule started.
2022-11-09 07:16:20.997 FINE DefaultProcessor: AS2MDNReceiverModule started.
2022-11-09 07:16:20.997 FINE DefaultProcessor: DirectoryResenderModule started.
2022-11-09 07:16:20.997 FINE DefaultProcessor: 4 active module(s) started.
2022-11-09 07:16:20.998 FINE OpenAS2Server: OpenAS2 Server v3.4.0 started.

    logs are quiet
    classpath looks okay to me ...

    from what you see above let me know if that solved the classpath issue.

     

  • robfantini2

    robfantini2 - 2022-11-09

    after moving the extra jar file the startup error seems to be gone:

    root@edi:[/opt/OpenAS2/bin]:# ./start-openas2.sh

Running /usr/lib/jvm/java-8-oracle/bin/java -Xms32m -Xmx384m -Dorg.apache.commons.logging.Log=org.openas2.logging.Log -Dopenas2.config.file=/opt/OpenAS2/bin/../config/config.xml -cp .:/opt/OpenAS2/bin/../lib/activation-1.1.jar:/opt/OpenAS2/bin/../lib/angus-activation-1.0.0.jar:/opt/OpenAS2/bin/../lib/aopalliance-repackaged-3.0.3.jar:/opt/OpenAS2/bin/../lib/bcmail-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcpg-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcpkix-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcprov-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/bcutil-jdk18on-1.71.1.jar:/opt/OpenAS2/bin/../lib/commons-cli-1.5.0.jar:/opt/OpenAS2/bin/../lib/commons-codec-1.11.jar:/opt/OpenAS2/bin/../lib/commons-io-2.11.0.jar:/opt/OpenAS2/bin/../lib/commons-lang3-3.12.0.jar:/opt/OpenAS2/bin/../lib/commons-logging-1.2.jar:/opt/OpenAS2/bin/../lib/dom4j-2.1.3.jar:/opt/OpenAS2/bin/../lib/grizzly-framework-4.0.0.jar:/opt/OpenAS2/bin/../lib/grizzly-http-4.0.0.jar:/opt/OpenAS2/bin/../lib/grizzly-http-server-4.0.0.jar:/opt/OpenAS2/bin/../lib/h2-2.1.214.jar:/opt/OpenAS2/bin/../lib/hk2-api-3.0.3.jar:/opt/OpenAS2/bin/../lib/hk2-locator-3.0.3.jar:/opt/OpenAS2/bin/../lib/hk2-utils-3.0.3.jar:/opt/OpenAS2/bin/../lib/httpclient-4.5.13.jar:/opt/OpenAS2/bin/../lib/httpcore-4.4.15.jar:/opt/OpenAS2/bin/../lib/jackson-annotations-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-core-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-databind-2.13.4.jar:/opt/OpenAS2/bin/../lib/jackson-module-jakarta-xmlbind-annotations-2.13.3.jar:/opt/OpenAS2/bin/../lib/jakarta.activation-2.0.1.jar:/opt/OpenAS2/bin/../lib/jakarta.activation-api-2.1.0.jar:/opt/OpenAS2/bin/../lib/jakarta.annotation-api-2.1.1.jar:/opt/OpenAS2/bin/../lib/jakarta.inject-api-2.0.1.jar:/opt/OpenAS2/bin/../lib/jakarta.validation-api-3.0.2.jar:/opt/OpenAS2/bin/../lib/jakarta.ws.rs-api-3.1.0.jar:/opt/OpenAS2/bin/../lib/jakarta.xml.bind-api-4.0.0.jar:/opt/OpenAS2/bin/../lib/javassist-3.28.0-GA.jar:/opt/OpenAS2/bin/../lib/javax.activation-api-1.2.0.jar:/opt/OpenAS2/bin/../lib/javax.annotation-api-1.3.2.jar:/opt/OpenAS2/bin/../lib/javax.mail-1.6.2.jar:/opt/OpenAS2/bin/../lib/javax.ws.rs-api-2.1.1.jar:/opt/OpenAS2/bin/../lib/jaxb-api-2.4.0-b180830.0359.jar:/opt/OpenAS2/bin/../lib/jaxb-core-4.0.1.jar:/opt/OpenAS2/bin/../lib/jaxb-impl-4.0.1.jar:/opt/OpenAS2/bin/../lib/jersey-client-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-common-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-container-grizzly2-http-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-entity-filtering-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-hk2-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-media-json-jackson-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/jersey-server-3.1.0-M8.jar:/opt/OpenAS2/bin/../lib/openas2-server.jar:/opt/OpenAS2/bin/../lib/osgi-resource-locator-1.0.3.jar:/opt/OpenAS2/bin/../lib/sentry-6.4.2.jar:/opt/OpenAS2/bin org.openas2.app.OpenAS2Server

2022-11-09 07:16:19.309 FINE OpenAS2Server: Retrieving config file...
2022-11-09 07:16:19.589 FINE OpenAS2Server: Using MANIFEST file:/opt/OpenAS2/lib/openas2-server.jar!/META-INF/MANIFEST.MF
2022-11-09 07:16:19.629 FINE XMLSession: Loading configuration...
2022-11-09 07:16:19.629 FINE XMLSession: Loading properties...
2022-11-09 07:16:20.725 FINE XMLSession: Loading log manager(s)...
2022-11-09 07:16:20.744 FINE XMLSession: Loading command processor(s)...
2022-11-09 07:16:20.749 FINE XMLSession: Command processor is disabled ... ignoring: org.openas2.cmd.processor.SocketCommandProcessor
2022-11-09 07:16:20.750 FINE XMLSession: Loading processor nodes...
2022-11-09 07:16:20.766 FINE XMLSession: Loading partnerships...
2022-11-09 07:16:20.803 FINE OpenAS2Server: Shutdown hook registered.
2022-11-09 07:16:20.803 FINE OpenAS2Server: Starting OpenAS2 Server v3.4.0...
2022-11-09 07:16:20.989 FINE DefaultProcessor: DbTrackingModule started.
2022-11-09 07:16:20.996 FINE DefaultProcessor: AS2ReceiverModule started.
2022-11-09 07:16:20.997 FINE DefaultProcessor: AS2MDNReceiverModule started.
2022-11-09 07:16:20.997 FINE DefaultProcessor: DirectoryResenderModule started.
2022-11-09 07:16:20.997 FINE DefaultProcessor: 4 active module(s) started.
2022-11-09 07:16:20.998 FINE OpenAS2Server: OpenAS2 Server v3.4.0 started.

    logs are quiet
    classpath looks okay to me ...

    from what you see above let me know if that solved the classpath issue.

     

  • robfantini2

    robfantini2 - 2022-11-09

    assuming the claspath is fixed, I tested starting with systemd, and the logs are filling up at 100MB per minute.

    here is the systemd config :

    cat openas2.service
[Unit]
Description=OpenAS2 Server
After=network.target

[Service]
Type=forking
User=root
Group=root

Environment=OPENAS2_AS_DAEMON=true
Environment=OPENAS2_BASE=/opt/OpenAS2
Environment=OPENAS2_PID=/opt/OpenAS2/bin/OpenAS2.pid
PIDFile=/opt/OpenAS2/bin/OpenAS2.pid
WorkingDirectory=/opt/OpenAS2
ExecStart=/opt/OpenAS2/bin/start-openas2.sh

[Install]
WantedBy=multi-user.target

    that config has worked since 2017 .

    let me know if you spot something that could be tried to fix the systemd config.

    PS:

    I greatly appreciate your help.... will be back in a few hours.

     

  • robfantini2

    robfantini2 - 2022-11-09

    next tried using /opt/OpenAS2/bin/openas2.service which was slightly different .

    that did not solve the issue.

     

  • Christopher Broderick

    Christopher Broderick - 2022-11-09

    I am pretty certain you have mixed the 2.11 scripts and config with the 3.4.0 scripts and config.
    The start-openas2.sh for 3.4.0 appends the bin folder to the classpath but your log shows it prepended which means you are starting it with the old script.

    Can you upload an obfuscated version of your config.xml and partnerships.xml

     

  • Christopher Broderick

    Christopher Broderick - 2022-11-09

    Can you provide the output from this command (assuming the systemd service is called "openas2"):
    journalctl -u openas2.service
    Also, please check if the error in the syslog occurs at very set intervals as that may narrow join the problem.

     

  • robfantini2

    robfantini2 - 2022-11-09

    the output from journalctl is over 100MB. using less the entire output seems to be the following:

    -- Journal begins at Tue 2022-11-08 20:30:52 EST, ends at Wed 2022-11-09 14:15:31 EST. --
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null

    I'll upload the config files next.

    I did notice some %home% in config.xml . th database upgrade procedure failed until I change %home% s to fll pathname .

     
    config.xml
    partnerships.xml

  • robfantini2

    robfantini2 - 2022-11-09

    the output from journalctl is over 100MB. using less the entire output seems to be the following:

    -- Journal begins at Tue 2022-11-08 20:30:52 EST, ends at Wed 2022-11-09 14:15:31 EST. --
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null
Nov 08 20:30:52 edi start-openas2.sh[2093]: java.lang.NullPointerException
Nov 08 20:30:52 edi start-openas2.sh[2093]: Nov 08, 2022 8:30:51 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
Nov 08 20:30:52 edi start-openas2.sh[2093]: SEVERE: null

    I'll upload the config files next.

    I did notice some %home% in config.xml . th database upgrade procedure failed until I change %home% s to fll pathname .

     

  • robfantini2

    robfantini2 - 2022-11-09

    also regarding : 'Also, please check if the error in the syslog occurs at very set intervals as that may narrow join the problem.'

    syslog gets well over 900MB of the same lines posted every 5 minutes.

    these repeat:
    `
    Nov 9 14:22:46 edi start-openas2.sh[39524]: Nov 09, 2022 2:22:46 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
    Nov 9 14:22:46 edi start-openas2.sh[39524]: SEVERE: null
    Nov 9 14:22:46 edi start-openas2.sh[39524]: java.lang.NullPointerException
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at org.openas2.cmd.processor.StreamCommandProcessor.readLine(StreamCommandProcessor.java:107)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at org.openas2.cmd.processor.StreamCommandProcessor.processCommand(StreamCommandProcessor.java:4>
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at org.openas2.cmd.processor.BaseCommandProcessor$1.call(BaseCommandProcessor.java:95)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at org.openas2.cmd.processor.BaseCommandProcessor$1.call(BaseCommandProcessor.java:90)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThre>
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolE>
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.lang.Thread.run(Thread.java:748)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: Nov 09, 2022 2:22:46 PM org.openas2.cmd.processor.BaseCommandProcessor$1 call
    Nov 9 14:22:46 edi start-openas2.sh[39524]: SEVERE: null
    Nov 9 14:22:46 edi start-openas2.sh[39524]: java.lang.NullPointerException
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at org.openas2.cmd.processor.StreamCommandProcessor.readLine(StreamCommandProcessor.java:107)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at org.openas2.cmd.processor.StreamCommandProcessor.processCommand(StreamCommandProcessor.java:4>
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at org.openas2.cmd.processor.BaseCommandProcessor$1.call(BaseCommandProcessor.java:95)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at org.openas2.cmd.processor.BaseCommandProcessor$1.call(BaseCommandProcessor.java:90)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThre>
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolE>
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    Nov 9 14:22:46 edi start-openas2.sh[39524]: #011at java.lang.Thread.run(Thread.java:748)

    `

     

  • robfantini2

    robfantini2 - 2022-11-10

    I spent a couple of hours doing a fresh upgrade . this time I followed the appendix and tried this upgrade method :
    using the existing /opt/OpenAs2/ , rm existing lib directory and copying over new etc. also copied over the new config/DB/openas2.mv.db

    after that the logs are filling up as before.

    I wanted to try a fresh upgrade to make certain things like the lib directory were as they should be.

    In a few hours I will get back to this and start by checking my config.xml and partnerships.xml for something that may be causing the issue.

     

  • Christopher Broderick

    Christopher Broderick - 2022-11-10

    Looks like it might be the stream command processor.
    Set this to "false" in the config.xml:
    console.command.processor.enabled="true"

    ... and restart.

     

  • robfantini2

    robfantini2 - 2022-11-10

    to give you a better idea on log issue,
    I have logs set to rotate 5x hour.

    here are some of the sizes . and note root disk close to full:

    root@edi:[/var/log]:# ll -h syslog* daemon.log*|grep G
-rw-r----- 1 root adm  1.1G Nov 10 06:37 daemon.log
-rw-r----- 1 root adm  1.7G Nov 10 06:20 daemon.log.1
-rw-r----- 1 root adm  1.9G Nov 10 06:20 syslog.1
root@edi:[/var/log]:# df /
Filesystem     Type  Size  Used Avail Use% Mounted on
/dev/rbd1      ext4  9.8G  9.8G     0 100% /

    Probably there is something unusual with our configuration as others have not seen this issue.

    I am sure we will get this fixed.

     

  • robfantini2

    robfantini2 - 2022-11-10

    re: Set this to "false" in the config.xml:
    console.command.processor.enabled="true"

    that did not fix. syslog listing:

    root@edi:[/var/log]:# ls -lh syslog ;date
-rw-r----- 1 root adm 143M Nov 10 07:06 syslog
Thu Nov 10 07:06:57 EST 2022

root@edi:[/var/log]:# ls -lh syslog ;date
-rw-r----- 1 root adm 162M Nov 10 07:07 syslog
Thu Nov 10 07:07:00 EST 2022
root@edi:[/var/log]:# ls -lh syslog ;date

-rw-r----- 1 root adm 181M Nov 10 07:07 syslog
Thu Nov 10 07:07:04 EST 2022
root@edi:[/var/log]:# ls -lh syslog ;date

-rw-r----- 1 root adm 221M Nov 10 07:07 syslog
Thu Nov 10 07:07:10 EST 2022

root@edi:[/var/log]:# systemctl stop openas2.service

root@edi:[/var/log]:# ls -lh syslog ;date
-rw-r----- 1 root adm 268M Nov 10 07:07 syslog
Thu Nov 10 07:07:21 EST 2022

root@edi:[/var/log]:# ls -lh syslog ;date
-rw-r----- 1 root adm 268M Nov 10 07:07 syslog
Thu Nov 10 07:07:28 EST 2022

    Also - I am running edi in a lxc container . Perhaps a KVM would do better?

     

    Last edit: robfantini2 2022-11-10
1 2 3 > >> (Page 1 of 3)

Log in to post a comment.