Difficult to make Hermes send an acknowledgement for received AppRec
message over smtp/pop3.
Hermes is successful in sending a xml-MSG, set up as a SOAP with
CPA,Action,Service and Roles, and a payload as signed, gzipped and
encrypted attachment. The receiver sends an ACK to the sender, and the
MSG from the sender is decrypted,uncompressed,verified and processed.
The receiver then sends an AppRec encrypted with senders cert as
answer for the processed senders MSG. Both messages enter the mailbox,
and upon hermes-start is taken into the mysql-database, but is not
sent to inbox. Therefore it cannot be fetched through GUI or by the
scripts in hermes2/samples/ebms-history or -envelope.
Sender is using Hermes2, receiver is not using Hermes2.
MSH is run async.
From the log it seems as enthough the CPA and partnership is
established and the cert is in its place in /home/hermes2/plugins/
hk.hku.cecid.ebms/security/, hermes cannot find the partnership and
the certificate in question displayed on the receivers ACK.
A similar test done as loopback to my own machine through the same
smtp with my own certs works in that Hermes is answering with positiv
ack.
I can not understand the mechanisms behind the error in the first
place. - Here is a log running on the problem. I have added comments
behind doubleslashes trying to explain what I for the most part think
is happening:
//START SENDING THE BKM MESSAGE
2011-12-20 12:57:33 [main ] <DEBUG> <cecid.ebms.spa> <Component
'System Logger' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:33 [main ] <DEBUG> <cecid.ebms.spa> <Component
'System Properties' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:33 [main ] <DEBUG> <cecid.ebms.spa> <Component
'System Messages' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:34 [main ] <DEBUG> <cecid.ebms.spa> <DAO
descriptor 'hk/hku/cecid/ebms/spa/conf/ebms.mysql.dao.xml' loaded
successfully>
2011-12-20 12:57:34 [main ] <DEBUG> <cecid.ebms.spa> <Component
'System DAO Factory' in module 'Ebms Plugin' initialized
successfully.>
2011-12-20 12:57:36 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Key Store Manager for Digital Signature' in module 'Ebms Plugin'
initialized successfully.>
2011-12-20 12:57:36 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Key Store Manager for Decryption (ebMS over SMTP)' in module 'Ebms
Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Outbox Collector' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Inbox Collector' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Mail Collector' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:57:36 [main ] <DEBUG> <cecid.ebms.spa> <Resuming
active monitor in module (Ebms Plugin). Current active threads: 0>
2011-12-20 12:57:36 [main ] <DEBUG> <cecid.ebms.spa> <Resuming
active monitor in module (Ebms Plugin). Current active threads: 0>
2011-12-20 12:57:36 [main ] <DEBUG> <cecid.ebms.spa> <Resuming
active monitor in module (Ebms Plugin). Current active threads: 0>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <Message
service handler started>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <Smtp
Server Setting: >
//NO SUPPORT FOR AUTH LOGIN ON THE SMTP SERVER; POP3 IS USED INSTEAD
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Host:
pop3.mimer.no>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Protocol: pop3>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Port: 25>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
From Mail Address:
sigb...@mimer.no>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Username:
sigb...@mimer.no>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Password: ********>
2011-12-20 12:57:36 [Thread-3 ] <INFO > <cecid.ebms.spa> <Mail
Collector started - Host:
pop3.mimer.no>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <Pop
Server Setting: >
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Host:
pop3.mimer.no>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Protocol: pop3>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Port: 110>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Folder: INBOX>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Username:
sigb...@mimer.no>
2011-12-20 12:57:36 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Password: ********>
2011-12-20 12:57:45 [-Processor25] <INFO > <cecid.ebms.spa> <Outbound
payload received - cpaId: 981789261_889640782_011, service:
BehandlerKrav, serviceType:string, action: OppgjorsMelding, convId:
be957f48-65b0-4d82-96de-3cce5dfa41ad, fromPartyId: 981789261,
fromPartyType: ENH, toPartyId: 889640782, toPartyType: ENH,
refToMessageId: null>
2011-12-20 12:57:45 [-Processor25] <INFO > <cecid.ebms.spa>
<Genereating message id:
20111220-1...@127.0.0.2>
2011-12-20 12:57:46 [-Processor25] <INFO > <cecid.ebms.spa> <Store
outgoing message:
20111220-1...@127.0.0.2>
2011-12-20 12:57:46 [-Processor25] <INFO > <cecid.ebms.spa> <Outbound
payload processed - cpaId: 981789261_889640782_011, service:
BehandlerKrav, action: OppgjorsMelding, convId:
be957f48-65b0-4d82-96de-3cce5dfa41ad, fromPartyId: 981789261,
fromPartyType: ENH, toPartyId: 889640782, toPartyType: ENH,
refToMessageId: null>
2011-12-20 12:57:47 [Thread-43 ] <INFO > <cecid.ebms.spa> <Sign the
message:
20111220-1...@127.0.0.2>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<setEnvelope, using algorithm: rsa-sha1>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<addDocument URI: cid:Payload-0, contentType: application/octet-
stream>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<start signing>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<got private key from keystore>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<created DocumentResolver>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<created Transform>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<added main document (envelope)>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<added 1 attachment documents>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<got the certificate chain from keystore>
2011-12-20 12:57:48 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<added the certificate chain to signature>
2011-12-20 12:57:51 [Thread-43 ] <DEBUG> <pkg.pki.ApacheXMLDSigner>
<message signed>
2011-12-20 12:57:51 [Thread-43 ] <INFO > <cecid.ebms.spa> <Send
message
20111220-1...@127.0.0.2 to
motta...@test-es.nav.no>
//STOP HERMES
2011-12-20 12:58:07 [main ] <DEBUG> <cecid.ebms.spa> <Message
service handler stopped>
2011-12-20 12:58:07 [main ] <DEBUG> <cecid.ebms.spa>
<Suspending active monitor in module (Ebms Plugin). Current active
threads: 0>
2011-12-20 12:58:07 [main ] <DEBUG> <cecid.ebms.spa>
<Suspending active monitor in module (Ebms Plugin). Current active
threads: 0>
2011-12-20 12:58:07 [main ] <DEBUG> <cecid.ebms.spa>
<Suspending active monitor in module (Ebms Plugin). Current active
threads: 0>
//START HERMES TO GET THE ACK AND APPREC
2011-12-20 12:58:51 [main ] <DEBUG> <cecid.ebms.spa> <Component
'System Logger' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:51 [main ] <DEBUG> <cecid.ebms.spa> <Component
'System Properties' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:51 [main ] <DEBUG> <cecid.ebms.spa> <Component
'System Messages' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:52 [main ] <DEBUG> <cecid.ebms.spa> <DAO
descriptor 'hk/hku/cecid/ebms/spa/conf/ebms.mysql.dao.xml' loaded
successfully>
2011-12-20 12:58:52 [main ] <DEBUG> <cecid.ebms.spa> <Component
'System DAO Factory' in module 'Ebms Plugin' initialized
successfully.>
2011-12-20 12:58:53 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Key Store Manager for Digital Signature' in module 'Ebms Plugin'
initialized successfully.>
2011-12-20 12:58:53 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Key Store Manager for Decryption (ebMS over SMTP)' in module 'Ebms
Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Outbox Collector' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Inbox Collector' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <DEBUG> <cecid.ebms.spa> <Component
'Mail Collector' in module 'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <INFO > <cecid.ebms.spa> <Module
'Ebms Plugin' initialized successfully.>
2011-12-20 12:58:53 [main ] <DEBUG> <cecid.ebms.spa> <Resuming
active monitor in module (Ebms Plugin). Current active threads: 0>
2011-12-20 12:58:53 [main ] <DEBUG> <cecid.ebms.spa> <Resuming
active monitor in module (Ebms Plugin). Current active threads: 0>
2011-12-20 12:58:53 [main ] <DEBUG> <cecid.ebms.spa> <Resuming
active monitor in module (Ebms Plugin). Current active threads: 0>
2011-12-20 12:58:53 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <Message
service handler started>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <Smtp
Server Setting: >
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Host:
pop3.mimer.no>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Protocol: pop3>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Port: 25>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
From Mail Address:
sigb...@mimer.no>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Username:
sigb...@mimer.no>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Smtp
Password: ********>
2011-12-20 12:58:54 [Thread-3 ] <INFO > <cecid.ebms.spa> <Mail
Collector started - Host:
pop3.mimer.no>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <Pop
Server Setting: >
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Host:
pop3.mimer.no>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Protocol: pop3>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Port: 110>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Folder: INBOX>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Username:
sigb...@mimer.no>
2011-12-20 12:58:54 [Thread-3 ] <DEBUG> <cecid.ebms.spa> <- Pop
Password: ********>
2011-12-20 12:58:55 [Thread-3 ] <INFO > <cecid.ebms.spa> <Found 2
message(s) in mail box>
2011-12-20 12:58:57 [Thread-1 ] <INFO > <cecid.ebms.spa> <Recover
outbox message sending thread 1/1>
2011-12-20 12:58:57 [Thread-4 ] <INFO > <cecid.ebms.spa> <1
message(s) has been marked re-sending.>
2011-12-20 12:59:00 [Thread-11 ] <INFO > <cecid.ebms.spa> <Sign the
message:
20111220-1...@127.0.0.2>
//HERMES RECEIVES THE ACKNOWLEDGMENT
2011-12-20 12:59:00 [Thread-12 ] <INFO > <cecid.ebms.spa> <Received
an ebxml message from mail box>
//CANNOT FIND PARTNERSHIP
2011-12-20 12:59:01 [Thread-12 ] <ERROR> <cecid.ebms.spa>
<Unauthorized message, no partnership is found>
//RESENDING BECAUSE ACK IS NOT RECOGNISED
2011-12-20 12:59:02 [Thread-4 ] <INFO > <cecid.ebms.spa> <1
message(s) has been marked re-sending.>
2011-12-20 12:59:02 [Thread-13 ] <INFO > <cecid.ebms.spa> <Sign the
message:
20111220-1...@127.0.0.2>
2011-12-20 12:59:02 [Thread-12 ] <INFO > <cecid.ebms.spa> <Store
outgoing message:
20111220-1...@127.0.0.2>
//HERMES RECEIVES THE APPREC
2011-12-20 12:59:03 [Thread-14 ] <INFO > <cecid.ebms.spa> <Received
an ebxml message from mail box>
2011-12-20 12:59:03 [Thread-14 ] <INFO > <cecid.ebms.spa> <Incoming
ebxml message received:
20111220-1...@ebxml.xenos.com>
2011-12-20 12:59:03 [Thread-14 ] <ERROR> <cecid.ebms.spa> <Please
upload the certificate>
2011-12-20 12:59:03 [Thread-14 ] <ERROR> <cecid.ebms.spa> <Error in
finding the certificate>
java.lang.RuntimeException: Please upload the certificate
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.findSenderCert(InboundMessageProcessor.java:
1513)
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.checkSignature(InboundMessageProcessor.java:
1564)
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processIncomingMessage(InboundMessageProcessor.java:
127)
at
hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processInboundMessage(MessageServiceHandler.java:
276)
at hk.hku.cecid.ebms.spa.task.MailTask.execute(MailTask.java:
119)
at
hk.hku.cecid.piazza.commons.module.ActiveThread.run(ActiveThread.java:
90)
at java.lang.Thread.run(Thread.java:679)
2011-12-20 12:59:03 [Thread-14 ] <ERROR> <cecid.ebms.spa> <Error in
verifying signature>
hk.hku.cecid.ebms.spa.handler.MessageServiceHandlerException: Error in
finding the certificate
by java.lang.RuntimeException: Please upload the certificate
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.findSenderCert(InboundMessageProcessor.java:
1518)
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.checkSignature(InboundMessageProcessor.java:
1564)
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.processIncomingMessage(InboundMessageProcessor.java:
127)
at
hk.hku.cecid.ebms.spa.handler.MessageServiceHandler.processInboundMessage(MessageServiceHandler.java:
276)
at hk.hku.cecid.ebms.spa.task.MailTask.execute(MailTask.java:
119)
at
hk.hku.cecid.piazza.commons.module.ActiveThread.run(ActiveThread.java:
90)
at java.lang.Thread.run(Thread.java:679)
Caused by: java.lang.RuntimeException: Please upload the certificate
at
hk.hku.cecid.ebms.spa.handler.InboundMessageProcessor.findSenderCert(InboundMessageProcessor.java:
1513)
... 6 more
2011-12-20 12:59:03 [Thread-14 ] <INFO > <cecid.ebms.spa> <Store the
incoming message:
20111220-1...@ebxml.xenos.com>
//HERMES SEEMINGLY SENDING AN ACKNOWLEDGEMENT RESP FOR THE APPREC
2011-12-20 12:59:03 [Thread-14 ] <INFO > <cecid.ebms.spa> <Sending
async reply message:
20111220-1...@127.0.0.2>
2011-12-20 12:59:04 [Thread-14 ] <INFO > <cecid.ebms.spa> <Store
outgoing message:
20111220-1...@127.0.0.2>
2011-12-20 12:59:04 [Thread-1 ] <ERROR> <cecid.ebms.spa>
<Partnership not found: (CPA ID: 981789261_889640782_011, Service:
BehandlerKrav , Action: Svarmelding)>
2011-12-20 12:59:04 [Thread-1 ] <ERROR> <cecid.ebms.spa> <Message
Validation Exception:
20111220-1...@127.0.0.2>
hk.hku.cecid.ebms.spa.task.MessageValidationException: Partnership
channel not found
at
hk.hku.cecid.ebms.spa.task.AgreementHandler.findPartnership(AgreementHandler.java:
191)
at
hk.hku.cecid.ebms.spa.task.AgreementHandler.<init>(AgreementHandler.java:
75)
at
hk.hku.cecid.ebms.spa.task.OutboxTask.<init>(OutboxTask.java:157)
at
hk.hku.cecid.ebms.spa.task.OutboxCollector.getTaskList(OutboxCollector.java:
68)
at
hk.hku.cecid.piazza.commons.module.ActiveTaskModule.execute(ActiveTaskModule.java:
137)
at
hk.hku.cecid.piazza.commons.module.ActiveModule.run(ActiveModule.java:
213)
at java.lang.Thread.run(Thread.java:679)