Timeout for request library

bartbutenaers commented 5 years ago

Hi,

I'm using this nice library successfully, except in combination with the popular request library.

Below you can find a simple test program:

var request = require('request');
var Mitm = require("mitm");

var options = { uri: 'https://api.ipify.org?format=json', timeout: 3000 };

request(options, function (error, response, body) {
    // ======================================================
    // This first test is successfull
    // ======================================================
    console.log('error1:', error); 
    console.log('statusCode1:', response && response.statusCode);
    console.log('body1:', body);
    console.log('****************************');

    // ======================================================
    // Let's enable tracing
    // ======================================================
    var mitm = Mitm();

    mitm.on("request", function(req, res) {
        console.log('mitm:', 'we arrived in our handler');
        console.log('****************************');
    })

    // ======================================================
    // This second test is gives me a timeout
    // ======================================================
    request(options, function (error, response, body) {
        console.log('error2:', error);
        console.log('statusCode2:', response && response.statusCode);
        console.log('body2:', body);
        console.log('****************************');
    });

    setTimeout(function () {
        console.log('mitm:', 'we waited 5 seconds for request to arrive');
    }, 5000);
});

Which results in the following:

error1: null statusCode1: 200 body1: {"ip":"84.195.139.33"}

mitm: we arrived in our handler

error2: { Error: ESOCKETTIMEDOUT at ClientRequest. (/home/pi/nr/node_modules/request/request.js:816:19) at Object.onceWrapper (events.js:313:30) at emitNone (events.js:106:13) at ClientRequest.emit (events.js:208:7) at TlsSocket.emitTimeout (_http_client.js:711:34) at Object.onceWrapper (events.js:313:30) at emitNone (events.js:106:13) at TlsSocket.emit (events.js:208:7) at TlsSocket.Socket._onTimeout (net.js:420:8) at ontimeout (timers.js:482:11) code: 'ESOCKETTIMEDOUT', connect: false } statusCode2: undefined body2: undefined

mitm: we waited 5 seconds for request to arrive

So the first request works fine.

Then I enable mitm

For the second request I arrive in my mitm handler, but the request library doesn't get a response anymore so it gives a timeout.

Am I perhaps using the mitm library incorrectly somehow? When I insert res.end() in my mitm handler, then there is no timeout but the request library gets of course an empty response.

P.S. I did my test on NodeJs version 8.10.0

Thanks for your time !!! Bart

moll commented 5 years ago

Hey!

What are you trying to do? Do you intend for the first request to go through to ipify.org or do you want to intercept that one? What about the second one? Trying to test how your code handles request timeouts or trying to just fake the remote API for your code?

bartbutenaers commented 5 years ago

Hello Andri,

I wanted to keep the example simple for you, but will explain below a bit more in detail what I want to achieve.

I developed some time ago a node for the Node-RED open source IOT framework. My block (A) listens to all http trafic (e.g. triggered by another httprequest block (B)), and if a request/response is intercepted an output messages is generated on my node's output (containing both the request AND the corresponding response):

I have been using the global-request-logger to accomplish this. However that library doesn't intercept the requests anymore on more recent NodeJs (10.xx), when those requests are generated by the "request" library. Therefore I wanted to use your module from now on...

So in the test program that I have provided, I just wanted to demonstrate that the first request works fine. But the second one doesn't work anymore, because I activated mitm: I arrive in the mitm handler but for some reason the request library doesn't get a response from the server (api.ipify.org) anymore, which results in a timeout error.

I had expected that it worked like this:

As soon as the (second) request is triggered, I would arrive in the mitm handler.

In that handler I could somehow wait for the response. Something like this (similar to the global-request-logger library):

node.mitm.on("request", function(request, response) {
  var responseData = [];

   response.on('data', function (data) {
       // append the data to responseData
   });

   response.on('end', function () {
      // 1. Join all response data
      // 2. Send an output message on my Node-RED node containing both request and response
   });

   response.on('error', function (error) {
      // Send an output message on my Node-RED node containing error information
   });
});

And I had hoped that the request-library wasn't aware that I had peeped at it's request, and kept running normal

Do you think something like this could be realized?

moll commented 5 years ago

It could certainly be achieved, but Mitm.js out of the box doesn't do any request proxying, which is something you seem to require. Once a request is "intercepted" by Mitm.js, it's handed off to your handler (the mitm.on("request", ... bit). To then get hold of any server's response, you'd need to redo the request, this time skipping Mitm.js (akin to the example https://github.com/moll/node-mitm#bypassing-interception).

Fortunately you're not the first to look for implementing recording. This was briefly talked about in https://github.com/moll/node-mitm/issues/51. Also, when I skim the dependents of Mitm.js, I see a few modules that portray to implement request forwarding — https://www.npmjs.com/browse/depended/mitm. Maybe they'll inspire your implementation. I've never needed recording myself, but I still presume it should be doable by just getting the hostname from the Host header, the request path from req.path firing a new request off, and then passing the response down via the response object Mitm.js gives your handler.

Let me know how it goes and if you need help.

bartbutenaers commented 5 years ago

Andri, really appreciate your assistance! Hmm. I hadn't seen discussion #51, which is indeed something similar.

Based on the links you have provided, and have updated my example program:

var request = require('request');
var Mitm = require("mitm");
var Http = require("http");

// ======================================================
// Let's enable tracing
// ======================================================
var mitm = Mitm();

mitm.on("connect", function(socket, opts) {
    if (opts.proxying) {
        socket.bypass();
        console.log('mitm:', 'socket bypassed');
        console.log('****************************'); 
    }
    else {
        console.log('mitm:', 'socket not bypassed');
        console.log('****************************'); 
    }
})

mitm.on("request", function(req, res) {
    var responseData = [];

    console.log('mitm:', 'request has arrived, so start waiting for the response');
    console.log('****************************');   

    // Forward the request, to execute the actual request
    var proxy_request = Http.request({host: req.host, path: req.path, proxying: true});

    proxy_request.addListener('response', function (proxy_response) {
        proxy_response.addListener('data', function(chunk) {
            res.write(chunk, 'binary');
        });

        proxy_response.addListener('end', function() {
            res.end();
        });

        res.writeHead(proxy_response.statusCode, proxy_response.headers);
    });

    req.addListener('data', function(chunk) {
        proxy_request.write(chunk, 'binary');
    });

    req.addListener('end', function() {
        proxy_request.end();
    });
})

// ======================================================
// Do the actual request
// ======================================================
var options = { uri: 'https://api.ipify.org?format=json', timeout: 3000 };
request(options, function (error, response, body) {
    console.log('error:', error);
    console.log('statusCode:', response && response.statusCode);
    console.log('body:', body);
    console.log('****************************');
});

I would have expected it to work like this:

A http request is executed
The mitm connection handler is called, which doesn't bypass the socket.
The mitm request handler is executed, where I proxy the request (based on another article) and activate the bypassing.
The mitm connection handler is called again (for the proxy_request), which will bypass the socket now.
By bypassing the socket, the proxy_request is actually send to the server (api.ipify.org) and the mitm request handler isn't called again.
As soon as the response of the proxy_request arrives, the (chunked) data will be written into the response of the first request. So eventually it seems like my original request got a response from the server (api.ipify.org).

But seems I made a huge mistake somewhere, because I'm arriving in my handlers much more as expected:

mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
(node:113) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 pipe listeners added. Use emitter.setMaxListeners() to increase limit
mitm: socket not bypassed
****************************
mitm: request has arrived, so start waiting for the response
****************************
mitm: socket bypassed
****************************
error: Error: Exceeded maxRedirects. Probably stuck in a redirect loop https://api.ipify.org/hg/html/index.html
    at Redirect.onResponse (/home/pi/nr/node_modules/request/lib/redirect.js:98:27)
    at Request.onRequestResponse (/home/pi/nr/node_modules/request/request.js:993:22)
    at emitOne (events.js:116:13)
    at ClientRequest.emit (events.js:211:7)
    at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:551:21)
    at HTTPParser.parserOnHeadersComplete (_http_common.js:115:23)
    at TlsSocket.socketOnData (_http_client.js:440:20)
    at emitOne (events.js:116:13)
    at TlsSocket.emit (events.js:211:7)
    at addChunk (_stream_readable.js:263:12)
statusCode: undefined
body: undefined
****************************

Do you have any clue what is going wrong?

moll commented 5 years ago

Hey,

I have a feeling that some of the req object properties you use are not Node's, but Express's. Mitm.js passes you the plain Http.IncomingMessage object from Node and does not extend it with Express' style helpers, of which req.host and req.path are.

Here's a full example that seems to work with Request v2.60 at least:

var Http = require("http")
var Https = require("https")
var Mitm = require("mitm")
var request = require("request")
var mitm = Mitm()

mitm.on("connect", function(socket, opts) {
    if (opts.proxying) socket.bypass()
})

mitm.on("request", function(req, res) {
    (req.connection.encrypted ? Https : Http).get({
        protocol: req.connection.encrypted ? "https:" : "http:",
        host: req.headers.host,
        path: req.url,
        proxying: true
    }, function(newRes) {
        res.writeHead(newRes.statusCode, newRes.headers)
        newRes.pipe(res)
    })
})

request({
    uri: "https://api.ipify.org?format=json",
    timeout: 3000
}, function(_err, _res, body) {
    console.log(body)
})

Note that there's no need for semicolons in JavaScript. :P If you want the above to work for other methods besides GET, swap Http.get out for Http.request, include the method property and pipe the intercepted request into it (req.pipe(newReq) should maybe do it).

bartbutenaers commented 5 years ago

That looks very neat!!!

Unfortunately it gives me an endless loop on NodeJs version v8.10.0 (Request version 2.88.0). When it bypasses the socket, it arrives again in the request handler:

Below you can see the call stack between both handlers, so perhaps that rings a bell ...

P.S. I ran your test program also on NodeJs version v10.15.3 (Request version 2.88.0) and there I have also an endless loop.

bartbutenaers commented 5 years ago

P.S. Yes I know that semicolons are not required in Javascript. But I'm more a Java fan, so I want to have a bit of Java in my Javascript code ;-)

moll commented 5 years ago

The same code above ends in an endless loop? I don't have Node v8 at hand, but would you mind trying it with Request v2.6 for a sec to see if it's something in Request? npm install request@2.6 should do it. In parallel, could you check that opts.proxying is really set for the request that the Request library makes? Maybe it started stripping options it doesn't know...

moll commented 5 years ago

Ah, nevermind, you're saying the plain old Http module get is the one causing the loop? Hmm. I did manage to get v8.15.1 on my system here to test and on that the test code from above also seems to work...

moll commented 5 years ago

Same with Node v10.15.3 — works.

bartbutenaers commented 5 years ago

I'm back ...
I have now installed Request version 2.60.0 but same effect (with exactly the same test program as you specified above!!!):

For the first connection, the socket isn't bypassed:
From then on the socket is bypassed every time I arrive in the connection handler:

But it keeps arriving continiously in my request handler ;-( I would have expected socket.bypassed to contain true (when arriving in the request handler), but that is not the case: Don't know if that is normal?

Above tests failed both on Raspbian (Raspberry Pi 3) and Ubuntu. So I installed nodeJs on Windows 10 and then it indeed works fine: I only arrive once in my request handler !!!!!!!!!!!!!!!!! Do you have perhaps anything else that I could test to troubleshoot this on Linux?

moll commented 5 years ago

How are you running the test program on Ubuntu? From the command line with node foo.js? And then later run the inspector through node --inspect foo.js? I run Linux here myself, too, albeit Arch Linux.

Is bypassed set in the connect handler after the bypass() call? Theoretically only the requests that were not bypassed should end in the request handler, and therefore bypassed shouldn't be set. Feel free to start adding console statements to Mitm's source code on your machine to make sense why bypass() is not properly bypassing. This is a good place to start: https://github.com/moll/node-mitm/blob/159e1c99618a77be085bcfea939f12eed08260d1/index.js#L95-L96

If you clone this repository or install Mitm.js via NPM and run its tests on your Ubuntu machine, do they pass? When you go Mitm's folder, you can install its test dependencies with npm install and run tests through make spec.

bartbutenaers commented 5 years ago

I run it with node foo.js. Or with node --inspect=0.0.0.0:5858 --debug-brk foo.js when I want to use my Chrome debugger.

Seems that the bypassed is nicely set to true on line 96:

Will debug a bit further tomorrow evening. My time is up for today...

bartbutenaers commented 5 years ago

Evening Andri,

Have been debugging quite a lot, with two debug sessions beside each other to compare my Linux and Windows sessions. Until the black line the entire call stack is the same, but then in Linux I'm ending up with the infinite loop (since client.bypassed becomes undefined again):

So the "orig" is different on both systems, and then it goes wrong.
But to be honest, no idea what that means ...

moll commented 5 years ago

Ah, if orig is pointing to Mitm.js's own tlsConnect again, then that would indeed cause an infinite loop. That can happen when Mitm is initialized twice — it's not guarding against this in any way. Are you sure the only contents of your test file at the moment is the example code from above? The line numbers on https://github.com/moll/node-mitm/issues/58#issuecomment-483834771 don't seem to match though, unless you've put some console.logs there. :)

IF we're suspecting that something is initializing Mitm twice, we need to check that. Start by confirming what Tls.connect points to before calling Mitm():

var Tls = require("tls")
console.log(Tls.connect.toString())

If that looks like something from Node.js internals, that's good. If after initializing it won't print its output, then that's good, too:

function () { [native code] }

To confirm whether Mitm is initialized twice, you could instrument its constructor (the Mitm function) and the Mitm.prototype.enable with some print statements and see. You'll also see Mitm.js assigning a bound version of tlsConnect to Node's Tls.connect in Mitm.prototype.enable. You can add a property to that bound function first and then when debugging see if that exists, thereby confirming the bound () thing you saw orig refer to on your Linux system is actually Mitm's bound tlsConnect function.

bartbutenaers commented 5 years ago

Hey Andri,

OMG... In the linux version I had copied some console statements from my original program, and seems indeed I had copied also a second var mitm = Mitm();. Don't know how I overlooked that...

Now it seems to be working fine. My apologies for wasting your precious time ;-( Think this your proposal is sufficient enough for replacing global-request-logger by mitm in my Node-RED developments.

Thanks again !!!!!! Bart

moll commented 5 years ago

Hehe, glad we figured it out at the end. :)

moll / node-mitm

Timeout for request library #58