search

OxalisCommunity / Oxalis-AS4

PEPPOL AS4 pMode plugin for Oxalis
32 stars 25 forks source link

"Error when looking up identifier" during inbound peppol testbed test #187

Closed cattuz closed 2 years ago

cattuz commented 2 years ago

Hello!

I'm stuck during the inbound part of the peppol test bed. When trying to send the file back (following the instructions at https://github.com/OxalisCommunity/Oxalis-AS4/blob/master/docs/peppol-test-bed/index.md) I'm getting an error saying "Message failed : Error when looking up identifier '0088:tbcntrl00002' in SML.".

The full command I'm running:

java --add-opens java.base/java.lang=ALL-UNNAMED -cp "standalone/*;as4/*" eu.sendregning.oxalis.Main -f inbound.xml

The full output:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
juni 09, 2022 2:27:37 EM com.google.inject.internal.ProxyFactory <init>
WARNING: Method [public java.lang.Object network.oxalis.persistence.platform.PlatformProvider.get()] is synthetic and is being intercepted by [network.oxalis.persistence.aop.RepositoryConnectionMethodInterceptor@7bebcd65]. This could indicate a bug.  The method may be intercepted twice, or may not be intercepted at all.
juni 09, 2022 2:27:37 EM com.google.inject.internal.ProxyFactory <init>
WARNING: Method [public java.lang.Object network.oxalis.persistence.platform.PlatformProvider.get()] is synthetic and is being intercepted by [network.oxalis.persistence.aop.RepositoryConnectionMethodInterceptor@263bbfeb]. This could indicate a bug.  The method may be intercepted twice, or may not be intercepted at all.

Message failed : Error when looking up identifier '0088:tbcntrl00002' in SML.

Total time spent: 0s
Attempted to send 0 files
Failed transmissions: 1

Current oxalis.conf:

oxalis.keystore: {
    path: peppol-test.p12
    password: ""

    key: {
        alias: "cert"
        password: ""
    }
}

lookup.locator.hostname="acc.edelivery.tech.ec.europa.eu"
lookup.locator.class = network.oxalis.vefa.peppol.lookup.locator.BusdoxLocator

I've tried a few versions of oxalis.conf, both with and without lookup.locator.hostname and lookup.locator.class. Something else I can try?

UPDATE with verbose logging:

2022-06-20 09:43:25,380 INFO [network.oxalis.commons.filesystem.detector.PropertyHomeDetector] Using Oxalis folder specified as Java System Property '-D OXALIS_HOME' with value 'C:\oxalis-as4'.
2022-06-20 09:43:25,395 INFO [network.oxalis.commons.filesystem.FileSystemModule] Home folder: C:\oxalis-as4
2022-06-20 09:43:25,398 INFO [network.oxalis.commons.filesystem.FileSystemModule] Configuration folder: C:\oxalis-as4   
2022-06-20 09:43:25,398 INFO [network.oxalis.commons.config.ConfigModule] Configuration file: C:\oxalis-as4\oxalis.conf 
2022-06-20 09:43:25,403 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => CONF:
2022-06-20 09:43:25,403 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => INBOUND: inbound
2022-06-20 09:43:25,403 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => PLUGIN: <null>
juni 20, 2022 9:43:26 FM com.google.inject.internal.ProxyFactory <init>
WARNING: Method [public java.lang.Object network.oxalis.persistence.platform.PlatformProvider.get()] is synthetic and is being intercepted by [network.oxalis.persistence.aop.RepositoryConnectionMethodInterceptor@5f7da3d3]. This could indicate a bug.  The method may be intercepted twice, or may not be intercepted at all.
juni 20, 2022 9:43:26 FM com.google.inject.internal.ProxyFactory <init>
WARNING: Method [public java.lang.Object network.oxalis.persistence.platform.PlatformProvider.get()] is synthetic and is being intercepted by [network.oxalis.persistence.aop.RepositoryConnectionMethodInterceptor@56afdf9a]. This could indicate a bug.  The method may be intercepted twice, or may not be intercepted at all.
2022-06-20 09:43:26,599 INFO [network.oxalis.commons.filesystem.detector.PropertyHomeDetector] Using Oxalis folder specified as Java System Property '-D OXALIS_HOME' with value 'C:\oxalis-as4'.
2022-06-20 09:43:26,600 INFO [network.oxalis.commons.filesystem.FileSystemModule] Home folder: C:\oxalis-as4 
2022-06-20 09:43:26,601 INFO [network.oxalis.commons.filesystem.FileSystemModule] Configuration folder: C:\oxalis-as4
2022-06-20 09:43:26,601 INFO [network.oxalis.commons.config.ConfigModule] Configuration file: C:\oxalis-as4\oxalis.conf
2022-06-20 09:43:26,603 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => POOL_TOTAL: 20
2022-06-20 09:43:26,603 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => POOL_MAX_ROUTE: 2
2022-06-20 09:43:26,603 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => POOL_VALIDATE_AFTER_INACTIVITY: 1000
2022-06-20 09:43:26,604 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => POOL_TIME_TO_LIVE: 30
2022-06-20 09:43:26,604 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => TIMEOUT_CONNECT: 0
2022-06-20 09:43:26,604 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => TIMEOUT_READ: 0
2022-06-20 09:43:26,604 INFO [network.oxalis.commons.settings.SettingsBuilder] HTTP => TIMEOUT_SOCKET: 0
2022-06-20 09:43:26,605 INFO [network.oxalis.commons.settings.SettingsBuilder] Error => TRACKER: quiet
2022-06-20 09:43:26,605 INFO [network.oxalis.commons.settings.SettingsBuilder] AS2 => NOTIFICATION: not.in.use@difi.no
2022-06-20 09:43:26,605 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => CONF:
2022-06-20 09:43:26,606 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => INBOUND: inbound
2022-06-20 09:43:26,606 INFO [network.oxalis.commons.settings.SettingsBuilder] File system => PLUGIN: <null>
2022-06-20 09:43:26,606 INFO [network.oxalis.commons.settings.SettingsBuilder] Identifiers => HOSTNAME:
2022-06-20 09:43:26,606 INFO [network.oxalis.commons.settings.SettingsBuilder] Identifiers => MSGID_GENERATOR: default
2022-06-20 09:43:26,607 INFO [network.oxalis.commons.settings.SettingsBuilder] Key store => PATH: peppol-test.p12
2022-06-20 09:43:26,607 INFO [network.oxalis.commons.settings.SettingsBuilder] Key store => PASSWORD: ************
2022-06-20 09:43:26,607 INFO [network.oxalis.commons.settings.SettingsBuilder] Key store => KEY_ALIAS: cert
2022-06-20 09:43:26,608 INFO [network.oxalis.commons.settings.SettingsBuilder] Key store => KEY_PASSWORD: ************
2022-06-20 09:43:26,608 INFO [network.oxalis.commons.settings.SettingsBuilder] Header => PARSER: sbdh
2022-06-20 09:43:26,608 INFO [network.oxalis.commons.settings.SettingsBuilder] Persister => PAYLOAD: default
2022-06-20 09:43:26,608 INFO [network.oxalis.commons.settings.SettingsBuilder] Persister => RECEIPT: default
2022-06-20 09:43:26,609 INFO [network.oxalis.commons.settings.SettingsBuilder] Persister => EXCEPTION: default
2022-06-20 09:43:26,609 INFO [network.oxalis.commons.settings.SettingsBuilder] Persister => HANDLER: default
2022-06-20 09:43:26,609 INFO [network.oxalis.commons.settings.SettingsBuilder] Tracing => REPORTER: noop
2022-06-20 09:43:26,609 INFO [network.oxalis.commons.settings.SettingsBuilder] Tracing => HTTP: <null>
2022-06-20 09:43:26,609 INFO [network.oxalis.commons.settings.SettingsBuilder] Tracing => TRACER: noop
2022-06-20 09:43:26,610 INFO [network.oxalis.commons.settings.SettingsBuilder] Executor => DEFAULT: 50
2022-06-20 09:43:26,610 INFO [network.oxalis.commons.settings.SettingsBuilder] Executor => STATISTICS: 50
2022-06-20 09:43:26,610 INFO [network.oxalis.commons.settings.SettingsBuilder] Tag => GENERATOR: noop
2022-06-20 09:43:26,611 INFO [network.oxalis.commons.settings.SettingsBuilder] Timestamp => SERVICE: system
2022-06-20 09:43:26,611 INFO [network.oxalis.commons.settings.SettingsBuilder] Evidence => SERVICE: rem
2022-06-20 09:43:26,612 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => DATASOURCE: dbcp
2022-06-20 09:43:26,612 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => DRIVER_CLASS: org.h2.Driver
2022-06-20 09:43:26,612 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => DRIVER_PATH: <null>
2022-06-20 09:43:26,612 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => JDBC_CONNECTION_URI: jdbc:h2:file:./data/oxalis
2022-06-20 09:43:26,613 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => JDBC_USERNAME: sa
2022-06-20 09:43:26,613 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => JDBC_PASSWORD:
2022-06-20 09:43:26,613 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => JNDI_RESOURCE: jdbc/oxalis
2022-06-20 09:43:26,613 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => DBCP_MAX_IDLE: 30
2022-06-20 09:43:26,613 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => DBCP_MAX_TOTAL: 100
2022-06-20 09:43:26,614 INFO [network.oxalis.commons.settings.SettingsBuilder] Persistence => DBCP_VALIDATION_QUERY: select 1
2022-06-20 09:43:26,614 INFO [network.oxalis.commons.settings.SettingsBuilder] Transformer => DETECTOR: noop
2022-06-20 09:43:26,614 INFO [network.oxalis.commons.settings.SettingsBuilder] Transformer => WRAPPER: xml
2022-06-20 09:43:26,614 INFO [network.oxalis.commons.settings.SettingsBuilder] Statistics => SERVICE: noop
2022-06-20 09:43:26,614 INFO [network.oxalis.commons.settings.SettingsBuilder] Transmission => VERIFIER: default
2022-06-20 09:43:26,615 INFO [network.oxalis.commons.settings.SettingsBuilder] AS4 => HOSTNAME:
2022-06-20 09:43:26,615 INFO [network.oxalis.commons.settings.SettingsBuilder] AS4 => MSGID_GENERATOR: default
2022-06-20 09:43:26,615 INFO [network.oxalis.commons.settings.SettingsBuilder] AS4 => TYPE: peppol
2022-06-20 09:43:26,615 INFO [network.oxalis.commons.settings.SettingsBuilder] Logging => CONFIG: logback.xml
2022-06-20 09:43:26,616 INFO [network.oxalis.commons.settings.SettingsBuilder] Logging => SERVICE: logback
2022-06-20 09:43:26,616 INFO [network.oxalis.persistence.datasource.DbcpDataSourceProvider] DataSource: jdbc:h2:file:./data/oxalis
2022-06-20 09:43:26,705 INFO [network.oxalis.commons.logging.LoggingHandler] Logging service: logback 
Configuring Logback with configuration: C:\oxalis-as4\logback.xml
2022-06-20 09:43:26,728 INFO [network.oxalis.commons.security.CertificateModule] Certificate subject: #REMOVED#
2022-06-20 09:43:26,729 INFO [network.oxalis.commons.security.CertificateModule] Certificate issuer: CN=PEPPOL ACCESS POINT TEST CA - G2, OU=FOR TEST ONLY, O=OpenPEPPOL AISBL, C=BE 
2022-06-20 09:43:27,619 INFO [network.oxalis.vefa.peppol.security.ModeDetector] Detected mode: TEST 
2022-06-20 09:43:27,624 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] Prioritized list of transport profiles: 
2022-06-20 09:43:27,625 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] => peppol-transport-as4-v2_0
2022-06-20 09:43:27,625 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] => busdox-transport-as2-ver1p0r1
2022-06-20 09:43:27,625 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] => busdox-transport-as2-ver2p0
2022-06-20 09:43:27,625 INFO [network.oxalis.outbound.transmission.MessageSenderFactory] => busdox-transport-as2-ver1p0

Message failed : Error when looking up identifier '0088:tbcntrl00002' in SML.

2022-06-20 09:43:27,867 ERROR [eu.sendregning.oxalis.Main] Execution failed: network.oxalis.api.lang.OxalisTransmissionException: No transmission is provided.
java.util.concurrent.ExecutionException: network.oxalis.api.lang.OxalisTransmissionException: No transmission is provided.
        at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
        at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
        at eu.sendregning.oxalis.Main.main(Main.java:225)
Caused by: network.oxalis.api.lang.OxalisTransmissionException: No transmission is provided.
        at network.oxalis.outbound.transmission.DefaultTransmitter.perform(DefaultTransmitter.java:116)
        at network.oxalis.outbound.transmission.DefaultTransmitter.transmit(DefaultTransmitter.java:93)
        at eu.sendregning.oxalis.TransmissionTask.performTransmission(TransmissionTask.java:166)
        at eu.sendregning.oxalis.TransmissionTask.call(TransmissionTask.java:94)
        at eu.sendregning.oxalis.TransmissionTask.call(TransmissionTask.java:48)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)
Total time spent: 0s
Attempted to send 0 files
Failed transmissions: 1
RichardVanMaaren commented 2 years ago

Should you not use the sender (-s) and receiver (-r) params as in the examples given ? As for as4 your need to add the protocol also : --protocol peppol-transport-as4-v2_0

Please refer to the section sending in : https://github.com/OxalisCommunity/oxalis/blob/master/doc/installation.md

Regards,

Richard

cattuz commented 2 years ago

I don't think adding sender and receiver has any other effect other than letting me override the sender and receiver that are already present in the payload.

java --add-opens java.base/java.lang=ALL-UNNAMED -cp "standalone/*;as4/*" eu.sendregning.oxalis.Main -f inbound.xml -s 0007:5563032498 -r 0088:tbcntrl00002 --protocol peppol-transport-as4-v2_0

Produces the same errror.

To be clear I'm following this guide: https://github.com/OxalisCommunity/Oxalis-AS4/blob/master/docs/peppol-test-bed/index.md in which the example omits sender receiver and protocol.

Looking at the debug output in my original post it seems to infer all the correct information - i.e. test env, correct procotol priority - so I'm kind of stumped. I will setup java dev env and run through the code manually to try and figure out what the error could be. I'm guessing the wrong SML is queried but I'm unsure which is the right one and how to configure that.

cattuz commented 2 years ago

Solved it! I had to run the command with Java version 1.8 to make it go through. My previous default version was Java 18.