search

phax / as2-server

A standalone Java AS2 server - see as2-lib for the generic parts
Other
30 stars 8 forks source link

MDN send timing out #14

Closed mreinigjr closed 9 years ago

mreinigjr commented 9 years ago

Hi Philip,

New bug, might be isolated to a linux machine again. This time though, it is the MDN being sent that is timing out. I have 2 instances of as2-server running on 2 different machines. Here are the logs from the sender:

[2015-08-20T19:30:53,814] [AS2-SERVER] [INFO ] [Timer-5] processing /home/mreinigjr/as2-server/data/tomeas2/test.txt -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:214)
[2015-08-20T19:30:53,828] [AS2-SERVER] [DEBUG] [Timer-5] Setting message attribute: 'filepath' = '/home/mreinigjr/as2-server/data/tomeproas2/test.txt' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:53,828] [AS2-SERVER] [DEBUG] [Timer-5] Setting message attribute: 'filename' = 'test.txt' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:53,828] [AS2-SERVER] [DEBUG] [Timer-5] Setting message attribute: 'pendingfilename' = 'test.txt' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:53,829] [AS2-SERVER] [DEBUG] [Timer-5] AS2Message was created -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:227)
[2015-08-20T19:30:53,867] [AS2-SERVER] [DEBUG] [Timer-5] Setting message header: 'Content-Disposition' = 'Attachment; filename="test.txt"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:53,872] [AS2-SERVER] [DEBUG] [Timer-5] Setting message header: 'Content-Type' = 'application/EDI-X12' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:53,872] [AS2-SERVER] [DEBUG] [Timer-5] Setting message header: 'Content-Disposition' = 'Attachment; filename="test.txt"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:53,873] [AS2-SERVER] [DEBUG] [Timer-5] Updating partnership for AS2 message [no message ID set] -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.updateMessage(AbstractDirectoryPollingModule.java:391)
[2015-08-20T19:30:53,876] [AS2-SERVER] [DEBUG] [Timer-5] Updating partnership [Partnership@0x13da9fb4: name=metesting-meproas2; senderIDs=[StringMap@0x498e1bcf: attrs={name=metesting, as2_id=metesting, x509_alias=mycompanyAS2, email=metesting@testing.meinc.com}]; receiverIDs=[StringMap@0x40f0e815: attrs={name=meproas2, as2_id=meproas2, x509_alias=mycompanyAS2, email=mlrzpf@meinc.com}]; attributes=[StringMap@0x38d1b614: attrs={protocol=as2, content_transfer_encoding=binary, subject=TEST, as2_url=http://as2.meinc.com/incoming, as2_mdn_to=http://104.236.58.252:10080/HttpReceiver, as2_mdn_options=signed-receipt-protocol=optional, pkcs7-signature; signed-receipt-micalg=optional, sha1, encrypt=3des, sign=sha1}]] -- com.helger.as2lib.partner.AbstractPartnershipFactory.updatePartnership(AbstractPartnershipFactory.java:319)
[2015-08-20T19:30:53,877] [AS2-SERVER] [DEBUG] [Timer-5] Setting message header: 'Subject' = 'TEST' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:53,877] [AS2-SERVER] [DEBUG] [Timer-5] Finished updating partnership for AS2 message -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.updateMessage(AbstractDirectoryPollingModule.java:397)
[2015-08-20T19:30:53,884] [AS2-SERVER] [DEBUG] [Timer-5] Setting message header: 'Message-ID' = '<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:53,885] [AS2-SERVER] [DEBUG] [Timer-5] Updated message ID to <ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2> -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.updateMessage(AbstractDirectoryPollingModule.java:402)
[2015-08-20T19:30:53,888] [AS2-SERVER] [INFO ] [Timer-5] file assigned to message /home/mreinigjr/as2-server/data/tomeproas2/test.txt [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:232)
[2015-08-20T19:30:53,889] [AS2-SERVER] [DEBUG] [Timer-5] DefaultMessageProcessor.handle (send,[AS2Message@0x3e3f5bb5: data=javax.mail.internet.MimeBodyPart@527b5e2e; MDN=null; history=[DataHistory@0x376d2f04: Items=[[DataHistoryItem@0x70324a93: ContentType=application/EDI-X12; Attributes=null]]]],null) -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:128)
[2015-08-20T19:30:53,890] [AS2-SERVER] [DEBUG] [Timer-5]   handling with module [[AS2SenderModule@0x31fc71ab: attrs={classname=com.helger.as2lib.processor.sender.AS2SenderModule}]] -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:139)
[2015-08-20T19:30:53,890] [AS2-SERVER] [INFO ] [Timer-5] Submitting message [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:569)
[2015-08-20T19:30:54,209] [AS2-SERVER] [DEBUG] [Timer-5] Signed data with DIGEST_SHA1 to multipart/signed; protocol="application/pkcs7-signature"; micalg=sha-1; 
    boundary="----=_Part_1_174303576.1440113454198": [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.sender.AS2SenderModule.secure(AS2SenderModule.java:337)
[2015-08-20T19:30:54,313] [AS2-SERVER] [DEBUG] [Timer-5] Encrypted data with CRYPT_3DES to application/pkcs7-mime; name="smime.p7m"; smime-type=enveloped-data: [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.sender.AS2SenderModule.secure(AS2SenderModule.java:370)
[2015-08-20T19:30:54,322] [AS2-SERVER] [DEBUG] [Timer-5] DispositionOptions=[DispositionOptions@0x1d88b2e8: ProtocolImportance=optional; Protocol=pkcs7-signature; MICAlgImportance=optional; MICAlgs=[DIGEST_SHA1]] -- com.helger.as2lib.processor.sender.AS2SenderModule.calculateAndStoreMIC(AS2SenderModule.java:232)
[2015-08-20T19:30:54,465] [AS2-SERVER] [DEBUG] [Timer-5] Calculated MIC: 'e2KRThtpSX2p9T9AcwIQUXfIBn4=, sha1' -- com.helger.as2lib.processor.sender.AS2SenderModule.calculateAndStoreMIC(AS2SenderModule.java:243)
[2015-08-20T19:30:54,466] [AS2-SERVER] [DEBUG] [Timer-5] Setting message content type to 'application/pkcs7-mime; name="smime.p7m"; smime-type=enveloped-data' -- com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:586)
[2015-08-20T19:30:54,469] [AS2-SERVER] [DEBUG] [Timer-5] Setting message header: 'Content-Type' = 'application/pkcs7-mime; name="smime.p7m"; smime-type=enveloped-data' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:54,482] [AS2-SERVER] [DEBUG] [Timer-5] Setting message attribute: 'destination_ip' = 'as2.meinc.com' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,482] [AS2-SERVER] [DEBUG] [Timer-5] Setting message attribute: 'destination_port' = '-1' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,482] [AS2-SERVER] [INFO ] [Timer-5] Connecting to http://as2.meinc.com/incoming [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:608)
[2015-08-20T19:30:54,701] [AS2-SERVER] [INFO ] [Timer-5] transferred 2790 bytes in 0.158 seconds at 17.250 KBps [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:621)
[2015-08-20T19:30:58,807] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:58,808] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:58,808] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:58,809] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:03,807] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:03,808] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:03,808] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:03,819] [AS2-SERVER] [DEBUG] [Timer-6] File operation CREATE_DIR_RECURSIVE succeeded on 'data/resend' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:03,809] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:08,807] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:08,810] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:08,810] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:08,808] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:13,807] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:13,809] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:13,809] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:13,810] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:18,808] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:18,809] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:18,807] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:18,809] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:23,808] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:23,809] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:23,810] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:23,810] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:28,808] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:28,808] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:28,809] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:28,810] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:33,808] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:33,809] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:33,809] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:33,811] [AS2-SERVER] [DEBUG] [Timer-6] File operation CREATE_DIR_RECURSIVE succeeded on 'data/resend' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:33,809] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:38,807] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:38,808] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:38,809] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:38,809] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:43,808] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:43,809] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:43,809] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:43,809] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:48,807] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:48,808] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:48,809] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:48,810] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:53,807] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:53,809] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:53,809] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:53,809] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:54,760] [AS2-SERVER] [INFO ] [Timer-5] OpenAS2Exception terminated: java.net.SocketTimeoutException: Read timed out; sources: {message=[AS2Message@0x3e3f5bb5: data=javax.mail.internet.MimeBodyPart@527b5e2e; MDN=null; history=[DataHistory@0x376d2f04: Items=[[DataHistoryItem@0x70324a93: ContentType=application/EDI-X12; Attributes=null], [DataHistoryItem@0x149fc3d3: ContentType=multipart/signed; protocol="application/pkcs7-signature"; 
    micalg=sha-1; boundary="----=_Part_1_174303576.1440113454198"; Attributes=null], [DataHistoryItem@0x4492751c: ContentType=application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data; Attributes=null]]]]} -- com.helger.as2lib.exception.OpenAS2Exception.log(OpenAS2Exception.java:111)
java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method) ~[?:1.8.0_51]
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:1.8.0_51]
    at java.net.SocketInputStream.read(SocketInputStream.java:170) ~[?:1.8.0_51]
    at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:1.8.0_51]
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) ~[?:1.8.0_51]
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) ~[?:1.8.0_51]
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_51]
    at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:704) ~[?:1.8.0_51]
    at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:647) ~[?:1.8.0_51]
    at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1535) ~[?:1.8.0_51]
    at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1440) ~[?:1.8.0_51]
    at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480) ~[?:1.8.0_51]
    at com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:624) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:142) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:238) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.updateTracking(AbstractDirectoryPollingModule.java:201) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.poll(AbstractDirectoryPollingModule.java:104) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.receiver.AbstractPollingModule$PollTask.run(AbstractPollingModule.java:102) [as2-lib-2.1.0.jar:2.1.0]
    at java.util.TimerThread.mainLoop(Timer.java:555) [?:1.8.0_51]
    at java.util.TimerThread.run(Timer.java:505) [?:1.8.0_51]
[2015-08-20T19:31:54,777] [AS2-SERVER] [ERROR] [Timer-5] Message abandoned [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.sender.AS2SenderModule._resend(AS2SenderModule.java:559)
[2015-08-20T19:31:54,777] [AS2-SERVER] [DEBUG] [Timer-5] AS2Message was successfully handled my the MessageProcessor -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:241)
[2015-08-20T19:31:54,778] [AS2-SERVER] [DEBUG] [Timer-5] Trying to delete file /home/mreinigjr/as2-server/data/tomeproas2/test.txt -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:294)
[2015-08-20T19:31:54,780] [AS2-SERVER] [INFO ] [Timer-5] deleted /home/mreinigjr/as2-server/data/tomeproas2/test.txt [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:301)
[2015-08-20T19:31:54,780] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomeproas2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:54,781] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomeproas2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)

and here are the logs from the receiver:

[2015-08-20T19:30:54,714] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] AS2ConnectionThread: run -- com.helger.as2lib.processor.receiver.AbstractNetModule$ConnectionThread.run(AbstractNetModule.java:226)
[2015-08-20T19:30:54,720] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] Incoming connection 127.0.0.1:57605 -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.handle(AS2ReceiverHandler.java:486)
[2015-08-20T19:30:54,735] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'source_ip' = '/127.0.0.1' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,736] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'source_port' = '57605' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,738] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'destination_ip' = '/127.0.0.1' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,742] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'destination_port' = '10080' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,742] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'as2msg.received' = 'true' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,750] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'HTTP_REQUEST_TYPE' = 'POST' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,750] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'HTTP_REQUEST_URL' = '/HttpReciver' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,751] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'HTTP_REQUEST_VERSION' = 'HTTP/1.0' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:54,756] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] received 2790 bytes in 0.011 seconds at 247.708 KBps from 127.0.0.1:57605 [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.handle(AS2ReceiverHandler.java:513)
[2015-08-20T19:30:54,951] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Type' = 'application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:54,952] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Disposition' = 'null' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:54,958] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Updating partnership [Partnership@0x680c02b9: name=metesting-meproas2; senderIDs=[StringMap@0x0107ad73: attrs={name=metesting, as2_id=metesting, x509_alias=mycompanyAS2, email=metesting@testing.meinc.com}]; receiverIDs=[StringMap@0x6d2584ec: attrs={name=meproas2, as2_id=meproas2, x509_alias=mycompanyAS2, email=mlrzpf@meinc.com}]; attributes=[StringMap@0x7c6c95f8: attrs={}]] -- com.helger.as2lib.partner.AbstractPartnershipFactory.updatePartnership(AbstractPartnershipFactory.java:319)
[2015-08-20T19:30:54,963] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Decrypting [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.decrypt(AS2ReceiverHandler.java:135)
[2015-08-20T19:30:55,229] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Type' = 'multipart/signed; protocol="application/pkcs7-signature"; micalg=sha-1; 
    boundary="----=_Part_1_174303576.1440113454198"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,234] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Disposition' = 'null' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,237] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'as2msg.received.encrypted' = 'true' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:55,239] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Verifying signature [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.verify(AS2ReceiverHandler.java:164)
[2015-08-20T19:30:55,418] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Type' = 'application/EDI-X12' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,419] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Disposition' = 'Attachment; filename="test.txt"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,419] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'as2msg.received.signed' = 'true' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:55,420] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] DefaultMessageProcessor.handle (validate-before-store,[AS2Message@0x037cb315: data=javax.mail.internet.MimeBodyPart@9d0d45b; MDN=null; history=[DataHistory@0x5d4f5020: Items=[[DataHistoryItem@0x5fbbaf7f: ContentType=application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data; Attributes=null], [DataHistoryItem@0x39b95b86: ContentType=multipart/signed; protocol="application/pkcs7-signature"; 
    micalg=sha-1; boundary="----=_Part_1_174303576.1440113454198"; Attributes=null], [DataHistoryItem@0x364432e6: ContentType=application/EDI-X12; Attributes=null]]]],null) -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:128)
[2015-08-20T19:30:55,422] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] DefaultMessageProcessor.handle (store,[AS2Message@0x037cb315: data=javax.mail.internet.MimeBodyPart@9d0d45b; MDN=null; history=[DataHistory@0x5d4f5020: Items=[[DataHistoryItem@0x5fbbaf7f: ContentType=application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data; Attributes=null], [DataHistoryItem@0x39b95b86: ContentType=multipart/signed; protocol="application/pkcs7-signature"; 
    micalg=sha-1; boundary="----=_Part_1_174303576.1440113454198"; Attributes=null], [DataHistoryItem@0x364432e6: ContentType=application/EDI-X12; Attributes=null]]]],null) -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:128)
[2015-08-20T19:30:55,423] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule]   handling with module [[MessageFileModule@0x61a91912: attrs={classname=com.helger.as2lib.processor.storage.MessageFileModule, filename=data/inbox/$msg.sender.as2_id$-$msg.receiver.as2_id$-$msg.headers.message-id$, header=data/inbox/msgheaders/$date.yyyy$/$date.MM$/$msg.sender.as2_id$-$msg.receiver.as2_id$-$msg.headers.message-id$, protocol=as2, tempdir=data/temp}]] -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:139)
[2015-08-20T19:30:55,427] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation CREATE_DIR_RECURSIVE succeeded on 'data/inbox' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:55,431] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation CREATE_DIR_RECURSIVE succeeded on 'data/temp' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:55,433] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation RENAME_FILE succeeded on 'data/temp/metesting-meproas2-_ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2_' and 'data/inbox/metesting-meproas2-_ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2_' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:55,434] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] stored message to /home/mreinigjr/as2-server/data/inbox/metesting-meproas2-_ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2_ [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.storage.MessageFileModule.handle(MessageFileModule.java:85)
[2015-08-20T19:30:55,435] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation CREATE_DIR_RECURSIVE succeeded on 'data/inbox/msgheaders/2015/08' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:55,436] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation CREATE_DIR_RECURSIVE succeeded on 'data/temp' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:55,437] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation RENAME_FILE succeeded on 'data/temp/metesting-meproas2-_ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2_' and 'data/inbox/msgheaders/2015/08/metesting-meproas2-_ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2_' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:55,437] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] stored headers to /home/mreinigjr/as2-server/data/inbox/msgheaders/2015/08/metesting-meproas2-_ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2_ [<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>] -- com.helger.as2lib.processor.storage.MessageFileModule.handle(MessageFileModule.java:103)
[2015-08-20T19:30:55,438] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] DefaultMessageProcessor.handle (validate-after-store,[AS2Message@0x037cb315: data=javax.mail.internet.MimeBodyPart@9d0d45b; MDN=null; history=[DataHistory@0x5d4f5020: Items=[[DataHistoryItem@0x5fbbaf7f: ContentType=application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data; Attributes=null], [DataHistoryItem@0x39b95b86: ContentType=multipart/signed; protocol="application/pkcs7-signature"; 
    micalg=sha-1; boundary="----=_Part_1_174303576.1440113454198"; Attributes=null], [DataHistoryItem@0x364432e6: ContentType=application/EDI-X12; Attributes=null]]]],null) -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:128)
[2015-08-20T19:30:55,442] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-To' = 'metesting' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,442] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-From' = 'meproas2' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,443] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-Version' = '1.1' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,443] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Date' = 'Thu, 20 Aug 2015 19:30:55 -0400' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,444] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Server' = 'ph-OpenAS2 v1.0' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,444] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Mime-Version' = '1.0' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,444] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-From' = 'meproas2' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,444] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-To' = 'metesting' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,445] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'From' = 'mlrzpf@meinc.com' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,446] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Subject' = 'Your Requested MDN Response' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:55,447] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'REPORTING_UA' = 'ph-OpenAS2 v1.0@/127.0.0.1:10080' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:55,447] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'ORIGINAL_RECIPIENT' = 'rfc822; meproas2' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:55,448] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'FINAL_RECIPIENT' = 'rfc822; meproas2' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:55,448] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'ORIGINAL_MESSAGE_ID' = '<ph-OpenAS2-20082015193053-0400-2613@metesting_meproas2>' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:55,450] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'DISPOSITION' = 'automatic-action/MDN-sent-automatically; processed' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:55,612] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'MIC' = '+YUB2CsCLvvsfo4IztwAZn9tx38=, sha1' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T19:30:55,690] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Type' = 'multipart/signed; protocol="application/pkcs7-signature"; micalg=sha-1; 
    boundary="----=_Part_2_1793637442.1440113455690"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T19:30:58,769] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:58,771] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:58,771] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:58,771] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:30:58,772] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tometesting' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:03,770] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T19:31:03,772] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)

This might be related to the fix you implemented for https (https://github.com/phax/as2-lib/issues/2). To be honest though, I think this issue has been here the whole time. If you remember from #8, I was having issues sending messages between OpenAS2B and OpenAS2A and vice versa after the SecureRandom fix. I eventually attributed the problem to a network issue, but I never confirmed this.

Let me know if you need more info on this one.

Thanks, Michael

mreinigjr commented 9 years ago

UPDATE:

Confirmed same thing happens when sending messages between OpenAS2A and OpenAS2B. Logs for OpenAS2A -> OpenAS2B:

[2015-08-20T21:24:52,012] [AS2-SERVER] [INFO ] [Timer-3] processing /home/mreinigjr/as2-server/data/toOpenAS2B/test.txt -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:214)
[2015-08-20T21:24:52,012] [AS2-SERVER] [DEBUG] [Timer-3] Setting message attribute: 'filepath' = '/home/mreinigjr/as2-server/data/toOpenAS2B/test.txt' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,012] [AS2-SERVER] [DEBUG] [Timer-3] Setting message attribute: 'filename' = 'test.txt' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,013] [AS2-SERVER] [DEBUG] [Timer-3] Setting message attribute: 'pendingfilename' = 'test.txt' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,009] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,013] [AS2-SERVER] [DEBUG] [Timer-6] File operation CREATE_DIR_RECURSIVE succeeded on 'data/resend' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,013] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,014] [AS2-SERVER] [DEBUG] [Timer-3] AS2Message was created -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:227)
[2015-08-20T21:24:52,016] [AS2-SERVER] [DEBUG] [Timer-3] Setting message header: 'Content-Disposition' = 'Attachment; filename="test.txt"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,021] [AS2-SERVER] [DEBUG] [Timer-3] Setting message header: 'Content-Type' = 'application/EDI-X12' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,022] [AS2-SERVER] [DEBUG] [Timer-3] Setting message header: 'Content-Disposition' = 'Attachment; filename="test.txt"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,022] [AS2-SERVER] [DEBUG] [Timer-3] Updating partnership for AS2 message [no message ID set] -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.updateMessage(AbstractDirectoryPollingModule.java:391)
[2015-08-20T21:24:52,023] [AS2-SERVER] [DEBUG] [Timer-3] Updating partnership [Partnership@0x2d08187d: name=OpenAS2A-OpenAS2B; senderIDs=[StringMap@0x23cff3ac: attrs={name=OpenAS2A, as2_id=OpenAS2A, x509_alias=OpenAS2A, email=OpenAS2 A email}]; receiverIDs=[StringMap@0x27f0730d: attrs={name=OpenAS2B, as2_id=OpenAS2B, x509_alias=OpenAS2B, email=OpenAS2 B email}]; attributes=[StringMap@0x62f2f997: attrs={protocol=as2, subject=From OpenAS2A to OpenAS2B, as2_url=http://localhost:10080, as2_mdn_to=http://localhost:10080, as2_mdn_options=signed-receipt-protocol=optional, pkcs7-signature; signed-receipt-micalg=optional, sha1, encrypt=3des, sign=md5}]] -- com.helger.as2lib.partner.AbstractPartnershipFactory.updatePartnership(AbstractPartnershipFactory.java:319)
[2015-08-20T21:24:52,023] [AS2-SERVER] [DEBUG] [Timer-3] Setting message header: 'Subject' = 'From OpenAS2A to OpenAS2B' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,023] [AS2-SERVER] [DEBUG] [Timer-3] Finished updating partnership for AS2 message -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.updateMessage(AbstractDirectoryPollingModule.java:397)
[2015-08-20T21:24:52,024] [AS2-SERVER] [DEBUG] [Timer-3] Setting message header: 'Message-ID' = '<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,025] [AS2-SERVER] [DEBUG] [Timer-3] Updated message ID to <ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B> -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.updateMessage(AbstractDirectoryPollingModule.java:402)
[2015-08-20T21:24:52,025] [AS2-SERVER] [INFO ] [Timer-3] file assigned to message /home/mreinigjr/as2-server/data/toOpenAS2B/test.txt [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:232)
[2015-08-20T21:24:52,027] [AS2-SERVER] [DEBUG] [Timer-3] DefaultMessageProcessor.handle (send,[AS2Message@0x0fd4ce44: data=javax.mail.internet.MimeBodyPart@53da1e81; MDN=null; history=[DataHistory@0x771677ec: Items=[[DataHistoryItem@0x02dd06d8: ContentType=application/EDI-X12; Attributes=null]]]],null) -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:128)
[2015-08-20T21:24:52,027] [AS2-SERVER] [DEBUG] [Timer-3]   handling with module [[AS2SenderModule@0x31fc71ab: attrs={classname=com.helger.as2lib.processor.sender.AS2SenderModule}]] -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:139)
[2015-08-20T21:24:52,028] [AS2-SERVER] [INFO ] [Timer-3] Submitting message [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:569)
[2015-08-20T21:24:52,043] [AS2-SERVER] [DEBUG] [Timer-3] Signed data with DIGEST_MD5 to multipart/signed; protocol="application/pkcs7-signature"; micalg=md5; 
    boundary="----=_Part_10_679441364.1440120292043": [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.sender.AS2SenderModule.secure(AS2SenderModule.java:337)
[2015-08-20T21:24:52,046] [AS2-SERVER] [DEBUG] [Timer-3] Encrypted data with CRYPT_3DES to application/pkcs7-mime; name="smime.p7m"; smime-type=enveloped-data: [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.sender.AS2SenderModule.secure(AS2SenderModule.java:370)
[2015-08-20T21:24:52,047] [AS2-SERVER] [DEBUG] [Timer-3] DispositionOptions=[DispositionOptions@0x0693f8bc: ProtocolImportance=optional; Protocol=pkcs7-signature; MICAlgImportance=optional; MICAlgs=[DIGEST_SHA1]] -- com.helger.as2lib.processor.sender.AS2SenderModule.calculateAndStoreMIC(AS2SenderModule.java:232)
[2015-08-20T21:24:52,047] [AS2-SERVER] [DEBUG] [Timer-3] Calculated MIC: 'e2KRThtpSX2p9T9AcwIQUXfIBn4=, sha1' -- com.helger.as2lib.processor.sender.AS2SenderModule.calculateAndStoreMIC(AS2SenderModule.java:243)
[2015-08-20T21:24:52,048] [AS2-SERVER] [DEBUG] [Timer-3] Setting message content type to 'application/pkcs7-mime; name="smime.p7m"; smime-type=enveloped-data' -- com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:586)
[2015-08-20T21:24:52,048] [AS2-SERVER] [DEBUG] [Timer-3] Setting message header: 'Content-Type' = 'application/pkcs7-mime; name="smime.p7m"; smime-type=enveloped-data' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,056] [AS2-SERVER] [DEBUG] [Timer-3] Setting message attribute: 'destination_ip' = 'localhost' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,056] [AS2-SERVER] [DEBUG] [Timer-3] Setting message attribute: 'destination_port' = '10080' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,057] [AS2-SERVER] [INFO ] [Timer-3] Connecting to http://localhost:10080 [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:608)
[2015-08-20T21:24:52,061] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] AS2ConnectionThread: run -- com.helger.as2lib.processor.receiver.AbstractNetModule$ConnectionThread.run(AbstractNetModule.java:226)
[2015-08-20T21:24:52,061] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] Incoming connection 127.0.0.1:36261 -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.handle(AS2ReceiverHandler.java:486)
[2015-08-20T21:24:52,062] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'source_ip' = '/127.0.0.1' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,062] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'source_port' = '36261' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,065] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'destination_ip' = '/127.0.0.1' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,073] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'destination_port' = '10080' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,074] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'as2msg.received' = 'true' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,184] [AS2-SERVER] [INFO ] [Timer-3] transferred 2735 bytes in 0.121 seconds at 22.75 KBps [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:621)
[2015-08-20T21:24:52,186] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'HTTP_REQUEST_TYPE' = 'POST' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,186] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'HTTP_REQUEST_URL' = '/' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,187] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'HTTP_REQUEST_VERSION' = 'HTTP/1.1' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,188] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] received 2735 bytes in 0.113 seconds at 23.652 KBps from 127.0.0.1:36261 [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.handle(AS2ReceiverHandler.java:513)
[2015-08-20T21:24:52,188] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Type' = 'application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,188] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Disposition' = 'null' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,189] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Updating partnership [Partnership@0x2d08187d: name=OpenAS2A-OpenAS2B; senderIDs=[StringMap@0x23cff3ac: attrs={name=OpenAS2A, as2_id=OpenAS2A, x509_alias=OpenAS2A, email=OpenAS2 A email}]; receiverIDs=[StringMap@0x27f0730d: attrs={name=OpenAS2B, as2_id=OpenAS2B, x509_alias=OpenAS2B, email=OpenAS2 B email}]; attributes=[StringMap@0x62f2f997: attrs={protocol=as2, subject=From OpenAS2A to OpenAS2B, as2_url=http://localhost:10080, as2_mdn_to=http://localhost:10080, as2_mdn_options=signed-receipt-protocol=optional, pkcs7-signature; signed-receipt-micalg=optional, sha1, encrypt=3des, sign=md5}]] -- com.helger.as2lib.partner.AbstractPartnershipFactory.updatePartnership(AbstractPartnershipFactory.java:319)
[2015-08-20T21:24:52,189] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Decrypting [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.decrypt(AS2ReceiverHandler.java:135)
[2015-08-20T21:24:52,238] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Type' = 'multipart/signed; protocol="application/pkcs7-signature"; micalg=md5; 
    boundary="----=_Part_10_679441364.1440120292043"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,239] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Disposition' = 'null' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,239] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'as2msg.received.encrypted' = 'true' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,240] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Verifying signature [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.verify(AS2ReceiverHandler.java:164)
[2015-08-20T21:24:52,260] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Type' = 'application/EDI-X12' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,261] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Disposition' = 'Attachment; filename="test.txt"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,267] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'as2msg.received.signed' = 'true' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,274] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] DefaultMessageProcessor.handle (validate-before-store,[AS2Message@0x67bd641f: data=javax.mail.internet.MimeBodyPart@697a8698; MDN=null; history=[DataHistory@0x6d450f6f: Items=[[DataHistoryItem@0x28478ca3: ContentType=application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data; Attributes=null], [DataHistoryItem@0x24d68828: ContentType=multipart/signed; protocol="application/pkcs7-signature"; 
    micalg=md5; boundary="----=_Part_10_679441364.1440120292043"; Attributes=null], [DataHistoryItem@0x1925846c: ContentType=application/EDI-X12; Attributes=null]]]],null) -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:128)
[2015-08-20T21:24:52,277] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] DefaultMessageProcessor.handle (store,[AS2Message@0x67bd641f: data=javax.mail.internet.MimeBodyPart@697a8698; MDN=null; history=[DataHistory@0x6d450f6f: Items=[[DataHistoryItem@0x28478ca3: ContentType=application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data; Attributes=null], [DataHistoryItem@0x24d68828: ContentType=multipart/signed; protocol="application/pkcs7-signature"; 
    micalg=md5; boundary="----=_Part_10_679441364.1440120292043"; Attributes=null], [DataHistoryItem@0x1925846c: ContentType=application/EDI-X12; Attributes=null]]]],null) -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:128)
[2015-08-20T21:24:52,278] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule]   handling with module [[MessageFileModule@0x61a91912: attrs={classname=com.helger.as2lib.processor.storage.MessageFileModule, filename=data/inbox/$msg.sender.as2_id$-$msg.receiver.as2_id$-$msg.headers.message-id$, header=data/inbox/msgheaders/$date.yyyy$/$date.MM$/$msg.sender.as2_id$-$msg.receiver.as2_id$-$msg.headers.message-id$, protocol=as2, tempdir=data/temp}]] -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:139)
[2015-08-20T21:24:52,278] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation CREATE_DIR_RECURSIVE succeeded on 'data/inbox' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,279] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation CREATE_DIR_RECURSIVE succeeded on 'data/temp' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,281] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation RENAME_FILE succeeded on 'data/temp/OpenAS2A-OpenAS2B-_ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B_' and 'data/inbox/OpenAS2A-OpenAS2B-_ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B_' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,282] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] stored message to /home/mreinigjr/as2-server/data/inbox/OpenAS2A-OpenAS2B-_ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B_ [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.storage.MessageFileModule.handle(MessageFileModule.java:85)
[2015-08-20T21:24:52,282] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation CREATE_DIR_RECURSIVE succeeded on 'data/inbox/msgheaders/2015/08' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,283] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation CREATE_DIR_RECURSIVE succeeded on 'data/temp' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,284] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] File operation RENAME_FILE succeeded on 'data/temp/OpenAS2A-OpenAS2B-_ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B_' and 'data/inbox/msgheaders/2015/08/OpenAS2A-OpenAS2B-_ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B_' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:52,284] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] stored headers to /home/mreinigjr/as2-server/data/inbox/msgheaders/2015/08/OpenAS2A-OpenAS2B-_ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B_ [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.storage.MessageFileModule.handle(MessageFileModule.java:103)
[2015-08-20T21:24:52,289] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] DefaultMessageProcessor.handle (validate-after-store,[AS2Message@0x67bd641f: data=javax.mail.internet.MimeBodyPart@697a8698; MDN=null; history=[DataHistory@0x6d450f6f: Items=[[DataHistoryItem@0x28478ca3: ContentType=application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data; Attributes=null], [DataHistoryItem@0x24d68828: ContentType=multipart/signed; protocol="application/pkcs7-signature"; 
    micalg=md5; boundary="----=_Part_10_679441364.1440120292043"; Attributes=null], [DataHistoryItem@0x1925846c: ContentType=application/EDI-X12; Attributes=null]]]],null) -- com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:128)
[2015-08-20T21:24:52,290] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-To' = 'OpenAS2A' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,290] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-From' = 'OpenAS2B' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,290] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-Version' = '1.1' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,291] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Date' = 'Thu, 20 Aug 2015 21:24:52 -0400' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,291] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Server' = 'ph-OpenAS2 v1.0' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,291] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Mime-Version' = '1.0' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,291] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-From' = 'OpenAS2B' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,292] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'AS2-To' = 'OpenAS2A' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,292] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'From' = 'OpenAS2 B email' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,300] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Subject' = 'Your Requested MDN Response' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:52,300] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'REPORTING_UA' = 'ph-OpenAS2 v1.0@/127.0.0.1:10080' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,301] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'ORIGINAL_RECIPIENT' = 'rfc822; OpenAS2B' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,301] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'FINAL_RECIPIENT' = 'rfc822; OpenAS2B' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,301] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'ORIGINAL_MESSAGE_ID' = '<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,301] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'DISPOSITION' = 'automatic-action/MDN-sent-automatically; processed' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,302] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message attribute: 'MIC' = 'e2KRThtpSX2p9T9AcwIQUXfIBn4=, sha1' -- com.helger.as2lib.message.AbstractBaseMessage.setAttribute(AbstractBaseMessage.java:136)
[2015-08-20T21:24:52,311] [AS2-SERVER] [DEBUG] [AS2ConnectionThread-AS2ReceiverModule] Setting message header: 'Content-Type' = 'multipart/signed; protocol="application/pkcs7-signature"; micalg=sha-1; 
    boundary="----=_Part_14_1483683073.1440120292311"' -- com.helger.as2lib.message.AbstractBaseMessage.setHeader(AbstractBaseMessage.java:150)
[2015-08-20T21:24:57,007] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:57,013] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:57,009] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:24:57,008] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:02,007] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:02,008] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:02,009] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:02,009] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:07,007] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:07,008] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:07,008] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:07,008] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:12,007] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:12,008] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:12,009] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:12,009] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:17,007] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:17,009] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:17,009] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:17,008] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:22,007] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:22,008] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:22,009] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:22,011] [AS2-SERVER] [DEBUG] [Timer-6] File operation CREATE_DIR_RECURSIVE succeeded on 'data/resend' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:22,009] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:27,007] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:27,008] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:27,009] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:27,009] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:32,007] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:32,008] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:32,008] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:32,010] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:37,007] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:37,008] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:37,009] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:37,009] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:42,007] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:42,008] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:42,008] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:42,009] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:47,007] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:47,008] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:47,009] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:47,010] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:52,007] [AS2-SERVER] [DEBUG] [Timer-4] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toMendelsontestAS2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:52,008] [AS2-SERVER] [DEBUG] [Timer-1] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toAny' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:52,008] [AS2-SERVER] [DEBUG] [Timer-2] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2A' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:52,009] [AS2-SERVER] [DEBUG] [Timer-5] File operation CREATE_DIR_RECURSIVE succeeded on 'data/tomepartneras2' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:52,010] [AS2-SERVER] [DEBUG] [Timer-6] File operation CREATE_DIR_RECURSIVE succeeded on 'data/resend' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:52,240] [AS2-SERVER] [INFO ] [Timer-3] OpenAS2Exception terminated: java.net.SocketTimeoutException: Read timed out; sources: {message=[AS2Message@0x0fd4ce44: data=javax.mail.internet.MimeBodyPart@53da1e81; MDN=null; history=[DataHistory@0x771677ec: Items=[[DataHistoryItem@0x02dd06d8: ContentType=application/EDI-X12; Attributes=null], [DataHistoryItem@0x3f094d51: ContentType=multipart/signed; protocol="application/pkcs7-signature"; 
    micalg=md5; boundary="----=_Part_10_679441364.1440120292043"; Attributes=null], [DataHistoryItem@0x6cbb78b7: ContentType=application/pkcs7-mime; name=smime.p7m; 
    smime-type=enveloped-data; Attributes=null]]]]} -- com.helger.as2lib.exception.OpenAS2Exception.log(OpenAS2Exception.java:111)
java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method) ~[?:1.8.0_51]
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:1.8.0_51]
    at java.net.SocketInputStream.read(SocketInputStream.java:170) ~[?:1.8.0_51]
    at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:1.8.0_51]
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) ~[?:1.8.0_51]
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:286) ~[?:1.8.0_51]
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345) ~[?:1.8.0_51]
    at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:704) ~[?:1.8.0_51]
    at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:647) ~[?:1.8.0_51]
    at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1535) ~[?:1.8.0_51]
    at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1440) ~[?:1.8.0_51]
    at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480) ~[?:1.8.0_51]
    at com.helger.as2lib.processor.sender.AS2SenderModule.handle(AS2SenderModule.java:624) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.DefaultMessageProcessor.handle(DefaultMessageProcessor.java:142) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:238) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.updateTracking(AbstractDirectoryPollingModule.java:201) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.poll(AbstractDirectoryPollingModule.java:104) [as2-lib-2.1.0.jar:2.1.0]
    at com.helger.as2lib.processor.receiver.AbstractPollingModule$PollTask.run(AbstractPollingModule.java:102) [as2-lib-2.1.0.jar:2.1.0]
    at java.util.TimerThread.mainLoop(Timer.java:555) [?:1.8.0_51]
    at java.util.TimerThread.run(Timer.java:505) [?:1.8.0_51]
[2015-08-20T21:25:52,242] [AS2-SERVER] [ERROR] [Timer-3] Message abandoned [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.sender.AS2SenderModule._resend(AS2SenderModule.java:559)
[2015-08-20T21:25:52,242] [AS2-SERVER] [DEBUG] [Timer-3] AS2Message was successfully handled my the MessageProcessor -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:241)
[2015-08-20T21:25:52,243] [AS2-SERVER] [DEBUG] [Timer-3] Trying to delete file /home/mreinigjr/as2-server/data/toOpenAS2B/test.txt -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:294)
[2015-08-20T21:25:52,243] [AS2-SERVER] [INFO ] [Timer-3] deleted /home/mreinigjr/as2-server/data/toOpenAS2B/test.txt [<ph-OpenAS2-20082015212452-0400-0344@OpenAS2A_OpenAS2B>] -- com.helger.as2lib.processor.receiver.AbstractDirectoryPollingModule.processFile(AbstractDirectoryPollingModule.java:301)
[2015-08-20T21:25:52,243] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
[2015-08-20T21:25:52,244] [AS2-SERVER] [DEBUG] [Timer-3] File operation CREATE_DIR_RECURSIVE succeeded on 'data/toOpenAS2B' -- com.helger.commons.io.file.LoggingFileOperationCallback.onSuccess(LoggingFileOperationCallback.java:41)
phax commented 9 years ago

I discovered that there were some more places, where VerySecureRandom was used. See as2-lib issue https://github.com/phax/as2-lib/issues/2 - I will investigate this further.

phax commented 9 years ago

Sorry, no time today to dig into this. Maybe it would simplify things if we could communicate by email. Mine is ...

phax commented 9 years ago

Hi Michael!

The problem should be solved now. Update both projects to HEAD, and notice the changed build requirements for AS2-server (see README ans issue #13). Additionally you should now specify the parameter -DAS2.useSecureRandom=false on launch.

hth, Philip

mreinigjr commented 9 years ago

Hi Philip,

Great! I will be testing this shortly. Also, did you get my email? I just want to make sure I hit the correct address Friday.

Thanks, Michael

mreinigjr commented 9 years ago

Hi Philip,

Can you please clarify this? How should I use the -DAS2.useSecureRandom=false? I have tried building both as2-lib and as2-server with this option. I have tried running it as an option with java after specifying the config file. After a quick search, I don't really see where this even triggers anything. Can you please elaborate? Right now, everything is getting hung up like it was when we first discovered this issue.

UPDATE:

Correct usage:

java -cp "standalone/*" -DAS2.useSecureRandom=false com.helger.as2.app.MainOpenAS2Server standalone/config/config.xml

Thanks, Michael

phax commented 9 years ago

Hi Michael!

Yes, I got your email - thanks. Lets stay on GitHub I just thought it would be good to have a channel to exchange config files etc.

Concerning the usage: mea culpa - I had a copy paste error in the Linux section (missing config/)

Anyway, is the main problem - "hangig" - resolved with this fix???

Thanks, Philip

mreinigjr commented 9 years ago

Hi Philip,

Good Morning!

Great! Glad that worked out and I agree about GitHub.

No worries about the config/, I figured that one out no problem. The placement of -DAS2.useSecureRandom=false is what threw me off for a bit.

I then encountered another really interesting error. I wanted to investigate it further before reporting it, but I will go into it some here. Everything was working great all the way through the MDN sending, but I kept getting a MIC not match error on the returned MDN. I finally started messing around with the parameters.xml file and I got the error to go away if I specify the signing algorithm in both directions. Here is an example:

<partnership name="mycompanyAS2-mendelsontestAS2">
                <sender name="mycompanyAS2"/>
                <receiver name="mendelsontestAS2"/>
                <attribute name="protocol" value="as2"/>
                <attribute name="content_transfer_encoding" value="binary"/>
                <attribute name="subject" value="TEST"/>
                <attribute name="as2_url" value="http://testas2.mendelson-e-c.com:8080/as2/HttpReceiver"/>
                <attribute name="as2_mdn_to" value="http://128.76.98.99/incoming"/>
                <attribute name="as2_mdn_options" value="signed-receipt-protocol=optional, pkcs7-signature; signed-receipt-micalg=optional, sha1"/>
                <attribute name="encrypt" value="3des"/>
                <attribute name="sign" value="sha1"/>
        </partnership>

        <partnership name="mendelsontestAS2-mycompanyAS2">
                <sender name="mendelsontestAS2"/>
                <receiver name="mycompanyAS2"/>
                <attribute name="sign" value="sha1"/>
        </partnership>

Specifying the signing algorithm for mendelsontestAS2-mycompanyAS2 was what finally got everything to work between to separate as2-server instances I had set up. Do you happen to have any thoughts on when this kind of situation might occur again? I am thinking that the encryption algorithm needs to be specified as well in both directions. What are your thoughts.

I will be documenting this well. I am currently testing with a partner right now. I should have more details in the morning. They are using TrailBlazer ZMOD Exchange EDI-INT. So we will soon have compatibility verification for Mendelson and hopefully soon TrailBlazer. Both are commercial software. :)

Thanks, Michael

phax commented 9 years ago

Hi Michael!

Was it a synchronous or an asynchronous MDN? If it was asynchronous, your finding might make sense...

Sorry, but no more input on this one so far :(

// Philip

mreinigjr commented 9 years ago

Hi Philip,

No problem, I think the issue might be on their end. To help with this, what information is stored in the data/inbox/msgheaders folder? Is it raw message headers sent or received or is it parsed info by as2-lib?

By the way, it is synchronous. Here is the msgheaders data:

Headers:
Host: localhost:10080
Connection: close
Content-Length: 1616
AS2-To: mepartneras2
AS2-From: partneredi
AS2-Version: 1.1
Date: Tue, 25 Aug 2015  11:50:56 -0500
Message-ID: <7851781.2015-08-25.11.50.56@u7Pqup3njo54pU/YcIMOF1Yg3ks=>
Disposition-Notification-To: http://bpsedi.partner.com:4080
Disposition-notification-options: signed-receipt-protocol=optional, pkcs7-signature;
Content-Type: application/pkcs7-mime

Attributes:
source_ip: /127.0.0.1
source_port: 47570
destination_ip: /127.0.0.1
destination_port: 10080
as2msg.received: true
HTTP_REQUEST_TYPE: POST
HTTP_REQUEST_URL: /HttpReciver
HTTP_REQUEST_VERSION: HTTP/1.0

Here is the log info. Please note that I am not in debug mode for this server is currently being tested with my partner.

[2015-08-25T13:02:51,395] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] AS2ConnectionThread: run -- com.helger.as2lib.processor.receiver.AbstractNetModule$ConnectionThread.run(AbstractNetModule.java:226)
[2015-08-25T13:02:51,396] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] Incoming connection 127.0.0.1:47570 -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.handle(AS2ReceiverHandler.java:486)
[2015-08-25T13:02:51,397] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] received 1616 bytes in 0.0 seconds at 1.592 KBps from 127.0.0.1:47570 [<7851781.2015-08-25.11.50.56@u7Pqup3njo54pU/YcIMOF1Yg3ks=>] -- com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.handle(AS2ReceiverHandler.java:513)
[2015-08-25T13:02:51,401] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] stored message to /home/mreinigjr/as2-server/data/inbox/partneredi-mepartneras2-<7851781.2015-08-25.11.50.56@u7Pqup3njo54pU/YcIMOF1Yg3ks=_ [<7851781.2015-08-25.11.50.56@u7Pqup3njo54pU/YcIMOF1Yg3ks=>] -- com.helger.as2lib.processor.storage.MessageFileModule.handle(MessageFileModule.java:85)
[2015-08-25T13:02:51,409] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] stored headers to /home/mreinigjr/as2-server/data/inbox/msgheaders/2015/08/partneredi-mepartneras2-<7851781.2015-08-25.11.50.56@u7Pqup3njo54pU/YcIMOF1Yg3ks=_ [<7851781.2015-08-25.11.50.56@u7Pqup3njo54pU/YcIMOF1Yg3ks=>] -- com.helger.as2lib.processor.storage.MessageFileModule.handle(MessageFileModule.java:103)
[2015-08-25T13:02:51,411] [AS2-SERVER] [WARN ] [AS2ConnectionThread-AS2ReceiverModule] Failed to split disposition options parameter '' into attribute and values -- com.helger.as2lib.disposition.DispositionOptions.createFromString(DispositionOptions.java:392)
[2015-08-25T13:02:51,415] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] OpenAS2Exception terminated: java.lang.NullPointerException: The value of 'MICAlg' may not be null!; sources: {message=[AS2Message@0x5b3fd2bb: data=javax.mail.internet.MimeBodyPart@55f827ac; MDN=[[AS2MessageMDN@0x31ca9fbe: attributes=[StringMap@0x251b1b6c: attrs={REPORTING_UA=ph-OpenAS2 v1.0@/127.0.0.1:10080, ORIGINAL_RECIPIENT=rfc822; mepartneras2, FINAL_RECIPIENT=rfc822; mepartneras2, ORIGINAL_MESSAGE_ID=<7851781.2015-08-25.11.50.56@u7Pqup3njo54pU/YcIMOF1Yg3ks=>, DISPOSITION=automatic-action/MDN-sent-automatically; processed}]; headers=javax.mail.internet.InternetHeaders@49fef7e5; partnership=[Partnership@0x74ead2d8: name=mepartneras2-partneredi; senderIDs=[StringMap@0x11b88494: attrs={name=mepartneras2, as2_id=mepartneras2, x509_alias=mepartneras2, email=mlrzpf@meinc.com}]; receiverIDs=[StringMap@0x6c853db4: attrs={name=partneredi, as2_id=partneredi, x509_alias=partneredi, email=albreland@partner.com}]; attributes=[StringMap@0x52fabe1e: attrs={protocol=as2, content_transfer_encoding=binary, subject=AS2 Message, as2_url=http://bpsedi.partner.com:4080, as2_mdn_to=http://as2.meinc.com/incoming, as2_mdn_options=signed-receipt-protocol=optional, pkcs7-signature; signed-receipt-micalg=optional, sha1, encrypt=3des, sign=sha1}]]]; message=<7851781.2015-08-25.11.50.56@u7Pqup3njo54pU/YcIMOF1Yg3ks=>; data=null; text=The message sent to Recipient mepartneras2 on Tue, 25 Aug 2015  11:50:56 -0500 with Subject null has been received, the EDI Interchange was successfully decrypted and it's integrity was verified. In addition, the sender of the message, Sender partneredi at Location /127.0.0.1 was authenticated as the originator of the message. There is no guarantee however that the EDI Interchange was syntactically correct, or was received by the EDI application/translator.]; history=[DataHistory@0x51c7b9cb: Items=[[DataHistoryItem@0x14c52d97: ContentType=application/pkcs7-mime; Attributes=null]]]]} -- com.helger.as2lib.exception.OpenAS2Exception.log(OpenAS2Exception.java:111)
java.lang.NullPointerException: The value of 'MICAlg' may not be null!
    at com.helger.commons.ValueEnforcer.notNull(ValueEnforcer.java:86) ~[ph-commons-6.1.1.jar:6.1.1]
    at com.helger.as2lib.util.AS2Helper.createMDNData(AS2Helper.java:119) ~[as2-lib-2.1.1-SNAPSHOT.jar:2.1.1-SNAPSHOT]
    at com.helger.as2lib.util.AS2Helper.createMDN(AS2Helper.java:281) ~[as2-lib-2.1.1-SNAPSHOT.jar:2.1.1-SNAPSHOT]
    at com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.sendMDN(AS2ReceiverHandler.java:222) [as2-lib-2.1.1-SNAPSHOT.jar:2.1.1-SNAPSHOT]
    at com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.handleIncomingMessage(AS2ReceiverHandler.java:454) [as2-lib-2.1.1-SNAPSHOT.jar:2.1.1-SNAPSHOT]
    at com.helger.as2lib.processor.receiver.net.AS2ReceiverHandler.handle(AS2ReceiverHandler.java:519) [as2-lib-2.1.1-SNAPSHOT.jar:2.1.1-SNAPSHOT]
    at com.helger.as2lib.processor.receiver.AbstractNetModule$ConnectionThread.run(AbstractNetModule.java:228) [as2-lib-2.1.1-SNAPSHOT.jar:2.1.1-SNAPSHOT]
[2015-08-25T13:02:51,419] [AS2-SERVER] [INFO ] [AS2ConnectionThread-AS2ReceiverModule] AS2ConnectionThread: done running -- com.helger.as2lib.processor.receiver.AbstractNetModule$ConnectionThread.run(AbstractNetModule.java:240)

Thanks, Michael

phax commented 9 years ago

In this case the "Disposition-notification-options" is missing the MIC algorithm. Because the MDN should be signed (the "signed-recipeipt-protocol" section of the header) a MIC algorithm must be provided. But since "optional" is used (and no MIC alg is provided) I think it would make sense to simply not sign the MDN in this case.

Concerning the header information: they are parsed into the InternetHeaders class directly from the HTTP stream and therefore no headers should be missing!

phax commented 9 years ago

I pushed a change to as2-lib that should fix this issue. So if the signed-receipt is optional and no MIC algorithm is defined, the MDN will not be signed

mreinigjr commented 9 years ago

Hi Philip,

Awesome! Thanks Philip.

Michael