Hello
this thread should continue the discussion about by problem mentioned in the thread
Re-sending messages by mourovaz.
First some details on my test environment.
Tester 1:
- Apple iBook, 1.33 GHz PowerPC CPU, 1,5 GB RAM
- MacOS X 10.4.6
- Java Version 1.5.x released by Apple
- Java Heap size: Min: 128MB Max: 1536 MB
- IP: 192.168.0.37
Tester 2:
- Standard PC, Intel P4 1,8 GHz, 768 MB RAM
- Windows XP Pro, Service Pack 1
- Java Version 1.5.x
- IP: 192.168.0.13
- Java Heap size: Min: 128MB Max: 1024 MB
Both computers are connected to each other by a cross over 100MB/s LAN cable, that's the way they built a network and they talk to each other by using the fixed IP-addresses mentioned above.
The m-e-c as2 settings are:
m-e-c as2 installation on the iBook:
Tester1 (local station):
Name: Tester1
AS2 id: as2_tester1
eMail address: tester1@192.168.0.37
Certificate alias: tester1
MDN URL: http://192.168.0.37:8080/mec_as2/HttpReceiver
Tester2:
Name: Tester2
AS2 id: as2_tester2
Certificate alias: tester2
Receipt URL: http://192.168.0.13:8080/mec_as2/HttpReceiver
Payload subject: AS2 message
Payload content type: application/EDI-Consent
Request async MDM
m-e-c as2 installation on the Windows XP computer:
Tester2 (local station):
Name: Tester2
AS2 id: as2_tester2
eMail address: tester2@192.168.0.13
Certificate alias: tester2
MDN URL: http://192.168.0.13:8080/mec_as2/HttpReceiver
Tester1:
Name: Tester1
AS2 id: as2_tester1
Certificate alias: tester1
Receipt URL: http://192.168.0.37:8080/mec_as2/HttpReceiver
Payload subject: AS2 message
Payload content type: application/EDI-Consent
Request async MDM
I tried to test the behavior of m-e-c as2 working with big files. For testing I'm using a 50,9 MB PDF-file.
An annotation to the timestamps:
time_receiver = time_sender + 22 seconds!!!
This may explain some mismatches in the logs below.
This m-e-c as2 installation was sending the file
Tester 2:
[11:15:38 AM] Processing the file "test_pdf.pdf" for the receiver "Tester1".
[11:15:42 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Outgoing message signed using keystore alias "tester2".
[11:16:18 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Outgoing message encrypted using keystore alias "tester1".
[11:16:18 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Outgoing message packed.
[11:16:21 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Sending message to http://192.168.0.37:8080/mec_as2/HttpReceiver, async MDN requested.
[11:19:41 AM] org.apache.commons.httpclient.NoHttpResponseException: The server 192.168.0.37 failed to respond
[11:19:41 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: HTTP -1
[11:19:47 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Message payload stored to "C:\mec_as2b5\messages\Tester1\error\AS2Message17534.as2".
[11:19:47 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Raw outgoing message stored to "C:\mec_as2b5\messages\Tester1\error\raw\AS2Message17534.as2.raw".
[11:32:41 AM] mecAS2-1150104776610-91211@as2_tester1_as2_tester2: Incoming transmission is a MDN.
[11:32:41 AM] AS2ServerRemoteImpl: mecAS2-1150104776610-91211@as2_tester1_as2_tester2: The MDN references a AS2Message with the message id mecAS2-1150103738675-7306@as2_tester2_as2_tester1 that does not exist.
[11:35:41 AM] mecAS2-1150104962010-86423@as2_tester1_as2_tester2: Incoming transmission is a MDN.
[11:35:41 AM] mecAS2-1150104960815-92961@as2_tester1_as2_tester2: Incoming transmission is a MDN.
[11:35:41 AM] AS2ServerRemoteImpl: mecAS2-1150104962010-86423@as2_tester1_as2_tester2: The MDN references a AS2Message with the message id mecAS2-1150103738675-7306@as2_tester2_as2_tester1 that does not exist.
[11:35:41 AM] AS2ServerRemoteImpl: mecAS2-1150104960815-92961@as2_tester1_as2_tester2: The MDN references a AS2Message with the message id mecAS2-1150103738675-7306@as2_tester2_as2_tester1 that does not exist.
This m-e-c as2 installation was receiving the file
Tester 1:
[11:16:54 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Incoming transmission is a AS2 message.
[11:16:54 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: AS2 message is encrypted.
[11:17:32 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Incoming transmission is a AS2 message.
[11:17:32 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: AS2 message is encrypted.
[11:19:08 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Incoming transmission is a AS2 message.
[11:19:08 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: AS2 message is encrypted.
[11:20:14 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: MDN is signed.
[11:20:14 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Using certificate "tester2" to verify signature.
[11:20:21 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Incoming transmission is a AS2 message.
[11:20:22 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: AS2 message is encrypted.
[11:25:56 AM] Warning on the server site, request could not be executed!
[11:25:57 AM] Error message returned by the call:
[11:25:57 AM] Error occurred in server thread; nested exception is:
java.lang.OutOfMemoryError: Java heap space
[11:29:44 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: MDN is signed.
[11:29:44 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Using certificate "tester2" to verify signature.
[11:30:41 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: MDN is signed.
[11:30:41 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Using certificate "tester2" to verify signature.
[11:30:47 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Digital signature verified successful.
[11:30:58 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: MDN is signed.
[11:30:58 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Using certificate "tester2" to verify signature.
[11:32:24 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Digital signature verified successful.
[11:32:42 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: Digital signature verified successful.
[11:32:58 AM] mecAS2-1150104776610-91211@as2_tester1_as2_tester2: MDN created, state set to [processed].
[11:32:59 AM] mecAS2-1150104776610-91211@as2_tester1_as2_tester2: Sending async MDN to http://192.168.0.13:8080/mec_as2/HttpReceiver.
[11:33:02 AM] mecAS2-1150104776610-91211@as2_tester1_as2_tester2: Message sent successfully (HTTP 200).
[11:33:06 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: AS2 communication successful, payload has been moved to "$mecas2_HOME/messages/Tester1/inbox/mecAS2-1150103738675-7306@as2_tester2_as2_tester1".
[11:36:01 AM] mecAS2-1150104960815-92961@as2_tester1_as2_tester2: MDN created, state set to [processed].
[11:36:02 AM] mecAS2-1150104962010-86423@as2_tester1_as2_tester2: MDN created, state set to [processed].
[11:36:02 AM] mecAS2-1150104960815-92961@as2_tester1_as2_tester2: Sending async MDN to http://192.168.0.13:8080/mec_as2/HttpReceiver.
[11:36:02 AM] mecAS2-1150104962010-86423@as2_tester1_as2_tester2: Sending async MDN to http://192.168.0.13:8080/mec_as2/HttpReceiver.
[11:36:02 AM] mecAS2-1150104962010-86423@as2_tester1_as2_tester2: Message sent successfully (HTTP 200).
[11:36:02 AM] mecAS2-1150104960815-92961@as2_tester1_as2_tester2: Message sent successfully (HTTP 200).
[11:36:07 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: AS2 communication successful, payload has been moved to "$mecas2_HOME/messages/Tester1/inbox/mecAS2-1150103738675-7306@as2_tester2_as2_tester1".
[11:36:07 AM] mecAS2-1150103738675-7306@as2_tester2_as2_tester1: AS2 communication successful, payload has been moved to "$mecas2_HOME/messages/Tester1/inbox/mecAS2-1150103738675-7306@as2_tester2_as2_tester1".
Stack Trace from iBook console (Tester 1)
:INFO: Logging to STDERR via org.mortbay.log.StdErrLog
:INFO: jetty 6.0.0beta16
:INFO: Extract jar:file:$mecas2_HOME/jetty/webapps/mec_as2.war!/ to /tmp/Jetty__mec_as2/webapp
:INFO: Started SelectChannelConnector @ 0.0.0.0:8080
[Server@8cbb65]: [Thread[Thread-32,5,main]]: putPropertiesFromString(): [port=3335;database.0=file:AS2_DB;silent=true;trace=false;
hsqldb.cache_scale=15;hsqldb.cache_file_scale=8;
no_system_exit=true;shutdownarg=COMPACT;]
[Server@8cbb65]: [Thread[Thread-32,5,main]]: checkRunning(false) entered
[Server@8cbb65]: [Thread[Thread-32,5,main]]: checkRunning(false) exited
java.rmi.ServerError: Error occurred in server thread; nested exception is:
java.lang.OutOfMemoryError: Java heap space
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:322)
at sun.rmi.transport.Transport$1.run(Transport.java:153)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:149)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:460)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:701)
at java.lang.Thread.run(Thread.java:613)
at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:247)
at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:223)
at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:126)
at de.mendelson.comm.as2.server.AS2ServerRemoteImpl_Stub.execute(Unknown Source)
at de.mendelson.util.rmi.RMISenderAS2.sendRequest(Unknown Source)
at de.mendelson.comm.as2.client.rmi.GenericClient.sendRequest(Unknown Source)
at de.mendelson.comm.as2.client.rmi.GenericClient.send(Unknown Source)
at de.mendelson.comm.as2.servlet.HttpReceiver.informAS2ServerIncomingMessage(Unknown Source)
at de.mendelson.comm.as2.servlet.HttpReceiver.doPost(Unknown Source)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:423)
at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:355)
at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:219)
at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:542)
at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:145)
at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:126)
at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
at org.mortbay.jetty.Server.handle(Server.java:245)
at org.mortbay.jetty.HttpConnection.handlerRequest(HttpConnection.java:365)
at org.mortbay.jetty.HttpConnection.access$1500(HttpConnection.java:38)
at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:623)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:610)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:192)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:296)
at org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint.run(SelectChannelConnector.java:740)
at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:435)
Caused by: java.lang.OutOfMemoryError: Java heap space
Jun 12, 2006 11:25:56 AM de.mendelson.util.rmi.RMISenderAS2 sendRequest
INFO: Warning on the server site, request could not be executed!
Jun 12, 2006 11:25:56 AM de.mendelson.util.rmi.RMISenderAS2 sendRequest
INFO: Error message returned by the call:
Jun 12, 2006 11:25:56 AM de.mendelson.util.rmi.RMISenderAS2 sendRequest
INFO: Error occurred in server thread; nested exception is:
java.lang.OutOfMemoryError: Java heap space
So, if you can see, that the sender (Tester2) tries to send the file once and breaks after 3 minutes and 20 seconds with a NoHttpResponseException, but the receiver (Tester1) is still up and running.
The receiver (Tester1) got the same message 3 times an commits every message as it should. This three messages the receiver puts into his status list with status "green".
The sender (Tester2) did not get an entry in status list. There was no entry added to list.
This mismatch is dangerous it you are using m-e-c as2 in production environment. Think about an ORDERS, you try to send it, but you get the error and the receiver gets the same ORDERS 3 times and in the worst case he will process it 3 times.
Hope that the documentation is detailed enough. If you have any open questions post them.
Hello,
one thing I forgot.
It was possible to transfer this file with lower security settings (without encyption and signing), but for this cases it was not possible to open the message information/details. I abort this after waiting for 20 minutes.
There was no stack trace or other error message I recognized.
Tobias,
thanks for your detailled description of your problem. I will create such a szenario here to check where the problem happened (I suppose RMI serialization).
The second problem looks like the java swing problem to handle a big amount of data in text components (http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4203912 and relating). Sun reported that this has been fixed in java 1.5 but anyway I don't think that it is possible to open a 50MB text file in a swing text area. There is no swapping mechanism implemented at this point, the full amount of data will be loaded.
Anyway this should not happen it you set the heap on both sides to a much bigger amount for such a huge file test. Have you checked this with let's say 2GB?
Regards
Heller
Hello,
thanks for the answer and please keep me informed about your result results.
At the iBook it is possible to increase the heap size from now 1536 MB to 2048 MB or greater, but at the Windows computer I'm getting an error if I increase the heap size above 1024 MB. It doesn't matter if I alter the swap file settings to a fix value, which is much bigger than the heap size or set the options to "managed by Windows". If I start m-e-c as2 I'm getting an error about not possible to start Java VM.
The iBook-CPU is slower than the Intel P4, but after 20 minutes of waiting a 1,33 GHz CPU with 1,5 GB RAM should be able to handle 50 MB of text data. That sounds strange.
Is it possible to open the log somewhere outside the application?
Tobias,
we analyzed the code for out of memory problems at transmission of huge files and found some issues that should be responsible for the behavior you described. The main thing is that the servlet simply dropped the http connection instead of returning an error code if there occured an internal error in the RMI communication (like out of memory) between the receipt servlet and the m-e-c as2 server.
During this we are up to fix some smaller issues that have been mentioned before like log entries for errors during message creation, all this will go into the m-e-c as2 v1.0 build6 code.
Thanks again for your detailled description of the problem, it helped a lot.
Regards
Heller
Hello,
is it possible to get an appraisement about the release date of m-e-c AS2 v1.0 built6?
Tobias,
To be honest we have no idea about the release date so far. We plan to implement some more features the community suggests, then we will release the new version.
Regards
Heller