Menu ▾ ▴

#200 TCPProxy fails to handle concurrent HTTPS requests

closed
Philip Aston
TCPProxy (41)
6
2015-02-25
2012-03-15
Anders Storsveen
No

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

Discussion

  • Anders Storsveen

    Anders Storsveen - 2012-03-15

    Found a way to get some ssl debug info:

    http://pastebin.com/mwi3fAXu

     

  • Anders Storsveen

    Anders Storsveen - 2012-03-15

    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....

     

  • Philip Aston

    Philip Aston - 2012-03-16

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

     

  • Philip Aston

    Philip Aston - 2012-03-17

    The good news is I can reproduce this.

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

     

  • Philip Aston

    Philip Aston - 2012-03-18

    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.

     

  • Anders Storsveen

    Anders Storsveen - 2012-03-19

    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]

     

  • Philip Aston

    Philip Aston - 2012-03-19

    Replacement xmlbeans jar - also required.

     
    grinder-xmlbeans-3.7.1.jar

  • Philip Aston

    Philip Aston - 2012-03-19

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

     

  • Anders Storsveen

    Anders Storsveen - 2012-03-19

    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'

     

  • Philip Aston

    Philip Aston - 2012-03-19

    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?

     

  • Anders Storsveen

    Anders Storsveen - 2012-03-21

    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

     

  • Anders Storsveen

    Anders Storsveen - 2012-03-23

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

     

  • Anders Storsveen

    Anders Storsveen - 2012-03-23

    Fix to urls being local instead of remote

     
    fix_url.patch

  • Anders Storsveen

    Anders Storsveen - 2012-03-23

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

     

  • Philip Aston

    Philip Aston - 2012-03-24

    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.

     

  • Philip Aston

    Philip Aston - 2012-03-24

    Replacement jar with patch applied. V2.

     
    grinder-http-3.7.1.jar

Log in to post a comment.