[ grinder-Bugs-3505060 ] TCPProxy fails to handle concurrent HTTPS requests

SourceForge.net <[email protected]> Tue, 18 Sep 2012 14:54:54 -0700
Newsgroups gmane.comp.java.grinder.devel
Message-ID <[email protected]> 
Bugs item #3505060, was opened at 2012-03-15 02:12
Message generated for change (Settings changed) made by philipa
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=118598&aid=3505060&group_id=18598

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: TCPProxy
Group: None
>Status: Closed
Resolution: Fixed
Priority: 6
Private: No
Submitted By: Anders Storsveen (bushwakko)
Assigned to: Philip Aston (philipa)
Summary: TCPProxy fails to handle concurrent HTTPS requests

Initial Comment:
I've been trying to record via https for a while now, but I've been having some troubles. I've managed to add the grinder certificate to java's keystore and I've managed to get my browser to accept the certificates that are involved in my transactions (Firefox silently fails with all certificates that are needed on indirect transactions like a picture linked on a page etc). I'm having huge troubles with other browsers than firefox 9 though (firefox 11 fails, and chrome and safari doesn't work either).

With firefox 9, it seems to work, but it randomly fails to load a certain number of the elements on the page. For instance, it seems to have trouble loading about half of the elements. They seem to either go through at 31seconds or around 60 seconds, or they eventually fail. This can be elements from the same source, so it doesn't seem to be server specific at all.

Example: http://imgur.com/Hpq1b

This is the output I get from the proxy:


macwakko:grinder-3.7.1: wakko$ java -cp lib/grinder.jar net.grinder.TCPProxy -http -debug
PicoContainer: No component for key: interface net.grinder.plugin.http.tcpproxyfilter.HTTPFilterEventListener
PicoContainer: No component for key: interface net.grinder.plugin.http.tcpproxyfilter.ConnectionHandlerFactory
PicoContainer: No component for key: interface net.grinder.plugin.http.tcpproxyfilter.HTTPRecording
PicoContainer: No component for key: interface org.slf4j.Logger
PicoContainer: No component for key: interface net.grinder.plugin.http.tcpproxyfilter.RegularExpressions
PicoContainer: No component for key: interface net.grinder.util.http.URIParser
PicoContainer: No component for key: interface net.grinder.util.AttributeStringParser
PicoContainer: No component for key: interface net.grinder.util.StringEscaper
PicoContainer: No component for key: interface net.grinder.tools.tcpproxy.CommentSource
PicoContainer: No component for key: interface net.grinder.plugin.http.tcpproxyfilter.HTTPRecordingResultProcessor
PicoContainer: No component for key: interface org.slf4j.Logger
PicoContainer: No component for key: interface net.grinder.plugin.http.tcpproxyfilter.RegularExpressions
PicoContainer: No component for key: interface net.grinder.util.http.URIParser
PicoContainer: No component for key: class net.grinder.plugin.http.tcpproxyfilter.ProcessHTTPRecordingWithXSLT$BuiltInStyleSheet
PicoContainer: No component for key: class net.grinder.plugin.http.tcpproxyfilter.ProcessHTTPRecordingWithXSLT$StyleSheetFile
PicoContainer: No component for key: interface org.slf4j.Logger
PicoContainer: instantiating net.grinder.plugin.http.tcpproxyfilter.ProcessHTTPRecordingWithXSLT(java.io.PrintWriter, org.slf4j.Logger)
PicoContainer: instantiated net.grinder.plugin.http.tcpproxyfilter.ProcessHTTPRecordingWithXSLT(java.io.PrintWriter, org.slf4j.Logger) [3 ms], component net.grinder.plugin.http.tcpproxyfilter.ProcessHTTPRecordingWithXSLT, injected [java.io.PrintWriter, ch.qos.logback.classic.Logger]
PicoContainer: instantiating net.grinder.plugin.http.tcpproxyfilter.RegularExpressionsImplementation()
PicoContainer: instantiated net.grinder.plugin.http.tcpproxyfilter.RegularExpressionsImplementation() [2 ms], component net.grinder.plugin.http.tcpproxyfilter.RegularExpressionsImplementation, injected []
PicoContainer: instantiating net.grinder.util.http.URIParserImplementation()
PicoContainer: instantiated net.grinder.util.http.URIParserImplementation() [0 ms], component net.grinder.util.http.URIParserImplementation, injected []
PicoContainer: instantiating net.grinder.plugin.http.tcpproxyfilter.HTTPRecordingImplementation(net.grinder.plugin.http.tcpproxyfilter.HTTPRecordingResultProcessor, org.slf4j.Logger, net.grinder.plugin.http.tcpproxyfilter.RegularExpressions, net.grinder.util.http.URIParser)
PicoContainer: instantiated net.grinder.plugin.http.tcpproxyfilter.HTTPRecordingImplementation(net.grinder.plugin.http.tcpproxyfilter.HTTPRecordingResultProcessor, org.slf4j.Logger, net.grinder.plugin.http.tcpproxyfilter.RegularExpressions, net.grinder.util.http.URIParser) [155 ms], component net.grinder.plugin.http.tcpproxyfilter.HTTPRecordingImplementation, injected [net.grinder.plugin.http.tcpproxyfilter.ProcessHTTPRecordingWithXSLT, ch.qos.logback.classic.Logger, net.grinder.plugin.http.tcpproxyfilter.RegularExpressionsImplementation, net.grinder.util.http.URIParserImplementation]
PicoContainer: instantiating net.grinder.util.AttributeStringParserImplementation()
PicoContainer: instantiated net.grinder.util.AttributeStringParserImplementation() [0 ms], component net.grinder.util.AttributeStringParserImplementation, injected []
PicoContainer: instantiating net.grinder.util.SimpleStringEscaper()
PicoContainer: instantiated net.grinder.util.SimpleStringEscaper() [0 ms], component net.grinder.util.SimpleStringEscaper, injected []
PicoContainer: instantiating net.grinder.plugin.http.tcpproxyfilter.ConnectionHandlerFactoryImplementation(net.grinder.plugin.http.tcpproxyfilter.HTTPRecording, org.slf4j.Logger, net.grinder.plugin.http.tcpproxyfilter.RegularExpressions, net.grinder.util.http.URIParser, net.grinder.util.AttributeStringParser, net.grinder.util.StringEscaper, net.grinder.tools.tcpproxy.CommentSource)
PicoContainer: instantiated net.grinder.plugin.http.tcpproxyfilter.ConnectionHandlerFactoryImplementation(net.grinder.plugin.http.tcpproxyfilter.HTTPRecording, org.slf4j.Logger, net.grinder.plugin.http.tcpproxyfilter.RegularExpressions, net.grinder.util.http.URIParser, net.grinder.util.AttributeStringParser, net.grinder.util.StringEscaper, net.grinder.tools.tcpproxy.CommentSource) [0 ms], component net.grinder.plugin.http.tcpproxyfilter.ConnectionHandlerFactoryImplementation, injected [net.grinder.plugin.http.tcpproxyfilter.HTTPRecordingImplementation, ch.qos.logback.classic.Logger, net.grinder.plugin.http.tcpproxyfilter.RegularExpressionsImplementation, net.grinder.util.http.URIParserImplementation, net.grinder.util.AttributeStringParserImplementation, net.grinder.util.SimpleStringEscaper
 , net.grinder.tools.tcpproxy.CommentSourceImplementation]
PicoContainer: instantiating net.grinder.plugin.http.tcpproxyfilter.ConnectionCache(net.grinder.plugin.http.tcpproxyfilter.ConnectionHandlerFactory)
PicoContainer: instantiated net.grinder.plugin.http.tcpproxyfilter.ConnectionCache(net.grinder.plugin.http.tcpproxyfilter.ConnectionHandlerFactory) [0 ms], component net.grinder.plugin.http.tcpproxyfilter.ConnectionCache, injected [net.grinder.plugin.http.tcpproxyfilter.ConnectionHandlerFactoryImplementation]
PicoContainer: instantiating net.grinder.plugin.http.tcpproxyfilter.HTTPRequestFilter(net.grinder.plugin.http.tcpproxyfilter.HTTPFilterEventListener)
PicoContainer: instantiated net.grinder.plugin.http.tcpproxyfilter.HTTPRequestFilter(net.grinder.plugin.http.tcpproxyfilter.HTTPFilterEventListener) [0 ms], component net.grinder.plugin.http.tcpproxyfilter.HTTPRequestFilter, injected [net.grinder.plugin.http.tcpproxyfilter.ConnectionCache]
PicoContainer: No component for key: interface net.grinder.plugin.http.tcpproxyfilter.HTTPFilterEventListener
PicoContainer: instantiating net.grinder.plugin.http.tcpproxyfilter.HTTPResponseFilter(net.grinder.plugin.http.tcpproxyfilter.HTTPFilterEventListener)
PicoContainer: instantiated net.grinder.plugin.http.tcpproxyfilter.HTTPResponseFilter(net.grinder.plugin.http.tcpproxyfilter.HTTPFilterEventListener) [0 ms], component net.grinder.plugin.http.tcpproxyfilter.HTTPResponseFilter, injected [net.grinder.plugin.http.tcpproxyfilter.ConnectionCache]
2012-03-15 10:08:38,374 INFO  tcpproxy: Initialising as an HTTP/HTTPS proxy with the parameters:
   Request filters:    HTTPRequestFilter
   Response filters:   HTTPResponseFilter
   Local address:      localhost:8001
2012-03-15 10:08:38,577 INFO  tcpproxy: Engine initialised, listening on port 8001
2012-03-15 10:08:43,064 ERROR tcpproxy: Received fatal alert: unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75) ~[na:1.6]
        at net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:431) ~[grinder-http-3.7.1.jar:na]
        at net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58) [grinder-core-3.7.1.jar:na]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
2012-03-15 10:08:43,079 ERROR tcpproxy: Received fatal alert: unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75) ~[na:1.6]
        at net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:431) ~[grinder-http-3.7.1.jar:na]
        at net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58) [grinder-core-3.7.1.jar:na]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
2012-03-15 10:08:43,097 ERROR tcpproxy: Received fatal alert: unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75) ~[na:1.6]
        at net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:431) ~[grinder-http-3.7.1.jar:na]
        at net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58) [grinder-core-3.7.1.jar:na]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
2012-03-15 10:09:14,055 ERROR tcpproxy: Received fatal alert: unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75) ~[na:1.6]
        at net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:431) ~[grinder-http-3.7.1.jar:na]
        at net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58) [grinder-core-3.7.1.jar:na]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
2012-03-15 10:10:18,050 ERROR tcpproxy: Received fatal alert: unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75) ~[na:1.6]
        at net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:431) ~[grinder-http-3.7.1.jar:na]
        at net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58) [grinder-core-3.7.1.jar:na]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
2012-03-15 10:10:18,260 ERROR tcpproxy: Received fatal alert: unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75) ~[na:1.6]
        at net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:431) ~[grinder-http-3.7.1.jar:na]
        at net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58) [grinder-core-3.7.1.jar:na]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
2012-03-15 10:10:18,399 ERROR tcpproxy: Received fatal alert: unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75) ~[na:1.6]
        at net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:431) ~[grinder-http-3.7.1.jar:na]
        at net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58) [grinder-core-3.7.1.jar:na]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
2012-03-15 10:10:18,534 ERROR tcpproxy: java.lang.IllegalStateException: Internal error
javax.net.ssl.SSLException: java.lang.IllegalStateException: Internal error
        at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1731) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1692) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.handleException(SSLSocketImpl.java:1675) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.handleException(SSLSocketImpl.java:1601) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:86) ~[na:1.6]
        at net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:431) ~[grinder-http-3.7.1.jar:na]
        at net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58) [grinder-core-3.7.1.jar:na]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
Caused by: java.lang.IllegalStateException: Internal error
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.initHandshaker(SSLSocketImpl.java:1107) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:916) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785) ~[na:1.6]
        at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75) ~[na:1.6]
        ... 3 common frames omitted


----------------------------------------------------------------------

Comment By: Philip Aston (philipa)
Date: 2012-03-24 11:56

Message:
Thanks Anders - that looks good (heaven knows how long it would have taken
me to spot).

I've applied the patch. I'll refresh the attached jar file, can you give it
a go just so I know we're good to close this.

----------------------------------------------------------------------

Comment By: Anders Storsveen (bushwakko)
Date: 2012-03-23 04:27

Message:
I added a patch that I think fixes the problem with the recorded urls being
local socket instead of remote.

----------------------------------------------------------------------

Comment By: Anders Storsveen (bushwakko)
Date: 2012-03-23 02:20

Message:
It seems to me that the proxy returns the local socket connection instead
of the remote one when using https.

----------------------------------------------------------------------

Comment By: Anders Storsveen (bushwakko)
Date: 2012-03-21 08:46

Message:
Here is the output from the Echo filter:


2012-03-21 16:43:41,408 INFO  tcpproxy: Initialising as an HTTP/HTTPS proxy
with the parameters:
   Request filters:    EchoFilter
   Response filters:   EchoFilter
   Local address:      localhost:8001
2012-03-21 16:43:42,680 INFO  tcpproxy: Engine initialised, listening on
port 8001
2012-03-21 16:43:45,280 DEBUG tcpproxy: prepareNewConnection for
localhost:54011 -> staging.comoyo.no:443
2012-03-21 16:43:45,287 DEBUG tcpproxy: Creating connection threads for
localhost:54011 -> staging.comoyo.no:443
2012-03-21 16:43:45,574 DEBUG tcpproxy: Flushed response to
localhost:54011
2012-03-21 16:43:45,967 DEBUG tcpproxy: prepareNewConnection for
localhost:54014 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:45,968 DEBUG tcpproxy: Creating connection threads for
localhost:54014 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:45,970 DEBUG tcpproxy: prepareNewConnection for
localhost:54015 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,107 DEBUG tcpproxy: Flushed response to
localhost:54014
2012-03-21 16:43:46,108 DEBUG tcpproxy: Creating connection threads for
localhost:54015 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,134 DEBUG tcpproxy: Flushed response to
localhost:54015
2012-03-21 16:43:46,450 DEBUG tcpproxy: prepareNewConnection for
localhost:54020 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,450 DEBUG tcpproxy: Creating connection threads for
localhost:54020 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,454 DEBUG tcpproxy: prepareNewConnection for
localhost:54021 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,477 DEBUG tcpproxy: Flushed response to
localhost:54020
2012-03-21 16:43:46,480 DEBUG tcpproxy: Creating connection threads for
localhost:54021 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,496 DEBUG tcpproxy: prepareNewConnection for
localhost:54022 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,520 DEBUG tcpproxy: Flushed response to
localhost:54021
2012-03-21 16:43:46,523 DEBUG tcpproxy: Creating connection threads for
localhost:54022 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,527 DEBUG tcpproxy: prepareNewConnection for
localhost:54024 -> ssl.google-analytics.com:443
2012-03-21 16:43:46,551 DEBUG tcpproxy: Flushed response to
localhost:54022
2012-03-21 16:43:46,552 DEBUG tcpproxy: Creating connection threads for
localhost:54024 -> ssl.google-analytics.com:443
2012-03-21 16:43:46,555 DEBUG tcpproxy: prepareNewConnection for
localhost:54026 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,648 DEBUG tcpproxy: Flushed response to
localhost:54024
2012-03-21 16:43:46,651 DEBUG tcpproxy: Creating connection threads for
localhost:54026 -> d2zl3c8ue8jcvu.cloudfront.net:443
2012-03-21 16:43:46,654 DEBUG tcpproxy: prepareNewConnection for
localhost:54027 -> comoyo.no:443
2012-03-21 16:43:46,676 DEBUG tcpproxy: Flushed response to
localhost:54026
2012-03-21 16:43:46,677 DEBUG tcpproxy: Creating connection threads for
localhost:54027 -> comoyo.no:443
2012-03-21 16:43:46,723 DEBUG tcpproxy: prepareNewConnection for
localhost:54030 -> staging.comoyo.no:443
2012-03-21 16:43:46,752 DEBUG tcpproxy: Flushed response to
localhost:54027
2012-03-21 16:43:46,756 DEBUG tcpproxy: Creating connection threads for
localhost:54030 -> staging.comoyo.no:443
2012-03-21 16:43:46,758 DEBUG tcpproxy: prepareNewConnection for
localhost:54031 -> staging.comoyo.no:443
2012-03-21 16:43:46,814 DEBUG tcpproxy: Flushed response to
localhost:54030
2012-03-21 16:43:46,815 DEBUG tcpproxy: Creating connection threads for
localhost:54031 -> staging.comoyo.no:443
2012-03-21 16:43:46,817 DEBUG tcpproxy: prepareNewConnection for
localhost:54032 -> staging.comoyo.no:443
2012-03-21 16:43:46,864 DEBUG tcpproxy: Flushed response to
localhost:54031
2012-03-21 16:43:46,864 DEBUG tcpproxy: Creating connection threads for
localhost:54032 -> staging.comoyo.no:443
2012-03-21 16:43:46,911 DEBUG tcpproxy: Flushed response to
localhost:54032


The output was huge so here is some of it:

--- staging.comoyo.no:443->localhost:54011 opened --
--- localhost:54011->staging.comoyo.no:443 opened --
------ staging.comoyo.no:443->localhost:54011 ------
GET /fotball HTTP/1.1
Host: staging.comoyo.no
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:9.0.1)
Gecko/20100101 Firefox/9.0.1
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: nb,en-us;q=0.7,en;q=0.3
Accept-Encoding: gzip, deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Connection: keep-alive
Cookie: __utma=246154075.333186731.1330940429.1332157175.1332344230.13;
__utmz=246154075.1330940429.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
__utma=90712792.1747208111.1330940429.1332157175.1332344230.13;
__utmz=90712792.1330940429.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
stagingSimpleSAMLSessionID=0408589a811cd6993d8fb95089308631;
__utmb=246154075.3.10.1332344230; __utmc=246154075;
__utmb=90712792.3.10.1332344230; __utmc=90712792


------ localhost:54011->staging.comoyo.no:443 ------
HTTP/1.1 200 OK
Accept-Ranges: bytes
Age: 0
cache-control: max-age=60, public
Content-Encoding: gzip
Content-Type: text/html
Date: Wed, 21 Mar 2012 15:43:45 GMT
P3P: CP="IDC DSP COR ADM DEVi TAIi PSA PSD IVAi IVDi CONi HIS OUR IND CNT"
Server: Apache/2.2.14 (Ubuntu)
Vary: Accept-Encoding
Via: 1.1 varnish
X-Powered-By: PHP/5.3.2-1ubuntu4.14
X-Varnish: 1524471986
Content-Length: 2017
Connection: keep-alive

[1F8B0800000000000003BD]X[EB]r[DB]6[16FE]-?[05CC]dV[D


----------------------------------------------------------------------

Comment By: Philip Aston (philipa)
Date: 2012-03-19 11:53

Message:
Not sure what's going on with your URLs. 

Perhaps you could do a recorrding with the echo filters (drop -http), and
check the HTTP requests?

----------------------------------------------------------------------

Comment By: Anders Storsveen (bushwakko)
Date: 2012-03-19 04:40

Message:
Tested with 1.3.8-SNAPSHOT from git, and it seems to work! Thank you!

All the urls except one, are wrong though, dunno why this is:

url0 = 'https://localhost:64831'
url1 = 'https://localhost:64835'
url2 = 'https://localhost:64836'
url3 = 'https://localhost:64837'
url4 = 'https://localhost:64838'
url5 = 'https://localhost:64839'
url6 = 'https://localhost:64840'
url7 = 'https://localhost:64853'
url8 = 'https://localhost:64855'
url9 = 'https://localhost:64856'
url10 = 'https://localhost:64858'
url11 = 'https://localhost:64859'
url12 = 'https://localhost:64860'
url13 = 'https://localhost:64861'
url14 = 'https://localhost:64870'
url15 = 'https://localhost:64877'
url16 = 'https://localhost:64880'
url17 = 'https://localhost:64881'
url18 = 'https://localhost:64882'
url19 = 'https://localhost:64886'
url20 = 'https://localhost:64887'
url21 = 'https://localhost:64888'
url22 = 'https://localhost:64889'
url23 = 'http://frontend.xstream.dk:80'
url24 = 'https://localhost:64903'
url25 = 'https://localhost:64904'

----------------------------------------------------------------------

Comment By: Philip Aston (philipa)
Date: 2012-03-19 04:40

Message:
Ah, sorry. Yes, you also need an updated xmlbeans jar (attached).

----------------------------------------------------------------------

Comment By: Anders Storsveen (bushwakko)
Date: 2012-03-19 04:21

Message:
Seems like this fix has some dependencies on some other changes as well:

macwakko:grinder-3.7.1: wakko$ java -cp lib/grinder.jar
net.grinder.TCPProxy -console -http
2012-03-19 12:20:10,467 ERROR tcpproxy: Could not initialise
java.lang.NoSuchMethodError:
net.grinder.plugin.http.xml.HTTPRecordingType$Metadata.setTestNumberOffset(I)V
	at
net.grinder.plugin.http.tcpproxyfilter.HTTPRecordingImplementation.<init>(HTTPRecordingImplementation.java:121)
~[grinder-http-3.7.1.jar:na]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
~[na:1.6.0_29]
	at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
~[na:1.6.0_29]
	at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
~[na:1.6.0_29]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
~[na:1.6.0_29]



----------------------------------------------------------------------

Comment By: Philip Aston (philipa)
Date: 2012-03-18 04:29

Message:
I believe I've fixed this:
http://grinder.git.sourceforge.net/git/gitweb.cgi?p=grinder/grinder;a=commitdiff;h=019e6d42bb7fe340ec5673915f8c2029b187f9e2

I'll attach a new grinder-http-3.7.1.jar to this bug. You can drop this
over the existing one. It will also include the pending TCPProxy fixes for
3471476, 3484390, 3475516.

Please give this a go and let me know how you get on.

Note, the attached jar will produce additional debug statements to stderr
during the recording. These will be disabled by default when the fix is
released in the next version of The Grinder.

----------------------------------------------------------------------

Comment By: Philip Aston (philipa)
Date: 2012-03-17 08:16

Message:
The good news is I can reproduce this.

It will take me a while to figure out what's going on however.

----------------------------------------------------------------------

Comment By: Philip Aston (philipa)
Date: 2012-03-16 11:56

Message:
The localhost connections are not unusual. There are several TCPProxyEngine
instances. The Grinder terminates the SSL connection from the browser with
one of them.

----------------------------------------------------------------------

Comment By: Anders Storsveen (bushwakko)
Date: 2012-03-15 07:13

Message:
I added the following debug output to AbstractTCPProxyEngine:

    /**
     * Main event loop.
     */
    @Override
    public void interruptibleRun() {

      m_outputStreamFilterTee.connectionOpened();

      final byte[] buffer = new byte[BUFFER_SIZE];

           
System.out.println(m_outputStreamFilterTee.m_connectionDetails.getConnectionIdentity()
+ " and "
                +
m_outputStreamFilterTee.getConnectionDetails().hashCode());



and got:




2012-03-15 15:04:14,461 INFO  tcpproxy: Engine initialised, listening on
port 8001
localhost:51498|snippets.mozilla.com:443|true and 727668954
localhost:51498|snippets.mozilla.com:443|true and 727668954
2012-03-15 15:04:18,292 ERROR tcpproxy: Received fatal alert:
access_denied
javax.net.ssl.SSLHandshakeException: Received fatal alert: access_denied
	at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:174)
~[na:1.6]
	at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
~[na:1.6]
	at
net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:436)
~[grinder-http-3.8-SNAPSHOT.jar:na]
	at
net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58)
[grinder-core-3.8-SNAPSHOT.jar:na]
	at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
localhost:51501|staging.comoyo.no:443|true and -836403326
localhost:51501|staging.comoyo.no:443|true and -836403326
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51509|true and 680119289
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51509|true and 680119289
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51509|true and 680119289
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51509|true and 680119289
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51518|true and 1538993819
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51518|true and 1538993819
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51518|true and 1538993819
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51518|true and 1538993819
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51518|true and 1538993819
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51518|true and 1538993819
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51523|true and -2011615551
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51523|true and -2011615551
2012-03-15 15:04:22,366 ERROR tcpproxy: Received fatal alert:
unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message
	at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190)
~[na:1.6]
	at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:136)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:1806)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:986)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:785)
~[na:1.6]
	at
com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
~[na:1.6]
	at
net.grinder.tools.tcpproxy.AbstractTCPProxyEngine$FilteredStreamThread.interruptibleRun(AbstractTCPProxyEngine.java:436)
~[grinder-http-3.8-SNAPSHOT.jar:na]
	at
net.grinder.util.thread.InterruptibleRunnableAdapter.run(InterruptibleRunnableAdapter.java:58)
[grinder-core-3.8-SNAPSHOT.jar:na]
	at java.lang.Thread.run(Thread.java:680) [na:1.6.0_29]
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51523|true and -2011615551
d2zl3c8ue8jcvu.cloudfront.net:443|localhost:51523|true and -2011615551
2012-03-15 15:04:22,387 ERROR tcpproxy: Received fatal alert:
unexpected_message
javax.net.ssl.SSLException: Received fatal alert: unexpected_message


and strangely i found this in the http recording:


url0 = 'https://localhost:51501'


This seems a little strange, since there is nothing in the webpage that
points to localhost, so it looks like wires are getting crossed somewhere
in the code....

----------------------------------------------------------------------

Comment By: Anders Storsveen (bushwakko)
Date: 2012-03-15 04:50

Message:
Found a way to get some ssl debug info:

http://pastebin.com/mwi3fAXu

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=118598&aid=3505060&group_id=18598

------------------------------------------------------------------------------
Live Security Virtual Conference
Exclusive live event will cover all the ways today's security and 
threat landscape has changed and how IT managers can respond. Discussions 
will include endpoint security, mobile security and the latest in malware 
threats. http://www.accelacomm.com/jaw/sfrnl04242012/114/50122263/