telebit.js/lib/remote.js

584 lines
20 KiB
JavaScript
Raw Permalink Normal View History

2016-09-30 01:10:40 +00:00
(function () {
'use strict';
var PromiseA;
try {
PromiseA = require('bluebird');
} catch(e) {
PromiseA = global.Promise;
}
2016-09-30 01:10:40 +00:00
var WebSocket = require('ws');
var sni = require('sni');
2018-05-31 06:19:53 +00:00
var Packer = require('proxy-packer');
2018-06-06 09:24:14 +00:00
var os = require('os');
2018-09-04 04:56:52 +00:00
var EventEmitter = require('events').EventEmitter;
2016-09-30 01:10:40 +00:00
function timeoutPromise(duration) {
return new PromiseA(function (resolve) {
setTimeout(resolve, duration);
});
}
2018-09-04 04:56:52 +00:00
function TelebitRemote(state) {
// jshint latedef:false
2018-09-04 04:56:52 +00:00
if (!(this instanceof TelebitRemote)) {
return new TelebitRemote(state);
}
EventEmitter.call(this);
var me = this;
2018-09-05 07:18:12 +00:00
var priv = {};
2018-09-04 04:56:52 +00:00
2018-09-05 07:18:12 +00:00
//var defaultHttpTimeout = (2 * 60);
//var activityTimeout = state.activityTimeout || (defaultHttpTimeout - 5) * 1000;
var activityTimeout = 6 * 1000;
2018-05-31 06:19:53 +00:00
var pongTimeout = state.pongTimeout || 10*1000;
// Allow the tunnel client to be created with no token. This will prevent the connection from
// being established initialy and allows the caller to use `.append` for the first token so
// they can get a promise that will provide feedback about invalid tokens.
2018-09-05 07:18:12 +00:00
priv.tokens = [];
2018-06-06 07:01:56 +00:00
var auth;
if(!state.sortingHat) {
state.sortingHat = "./sorting-hat.js";
}
2018-05-31 06:19:53 +00:00
if (state.token) {
2018-06-29 20:51:56 +00:00
if ('undefined' === state.token) {
throw new Error("passed string 'undefined' as token");
}
2018-09-05 07:18:12 +00:00
priv.tokens.push(state.token);
}
2016-09-30 19:04:27 +00:00
var wstunneler;
2017-04-08 00:49:52 +00:00
var authenticated = false;
2018-06-06 07:01:56 +00:00
var authsent = false;
var initialConnect = true;
2018-09-05 07:18:12 +00:00
priv.localclients = {};
var pausedClients = [];
var clientHandlers = {
2018-05-31 06:19:53 +00:00
add: function (conn, cid, tun) {
2018-09-05 07:18:12 +00:00
priv.localclients[cid] = conn;
2018-09-14 05:42:04 +00:00
console.info("[connect] new client '" + tun.name + ":" + tun.serviceport + "' for '" + cid + "'"
2018-05-31 06:19:53 +00:00
+ "(" + clientHandlers.count() + " clients)");
conn.tunnelCid = cid;
if (tun.data) {
conn.tunnelRead = tun.data.byteLength;
} else {
conn.tunnelRead = 0;
}
conn.tunnelWritten = 0;
conn.on('data', function onLocalData(chunk) {
//var chunk = conn.read();
if (conn.tunnelClosing) {
console.warn("[onLocalData] received data for '"+cid+"' over socket after connection was ended");
return;
}
// This value is bytes written to the tunnel (ie read from the local connection)
conn.tunnelWritten += chunk.byteLength;
// If we have a lot of buffered data waiting to be sent over the websocket we want to slow
// down the data we are getting to send over. We also want to pause all active connections
// if any connections are paused to make things more fair so one connection doesn't get
// stuff waiting for all other connections to finish because it tried writing near the border.
2018-09-05 07:18:12 +00:00
var bufSize = sendMessage(Packer.packHeader(tun, chunk));
// Sending 2 messages instead of copying the buffer
2018-09-05 07:18:12 +00:00
var bufSize2 = sendMessage(chunk);
if (pausedClients.length || (bufSize + bufSize2) > 1024*1024) {
// console.log('[onLocalData] paused connection', cid, 'to allow websocket to catch up');
conn.pause();
pausedClients.push(conn);
}
});
var sentEnd = false;
conn.on('end', function onLocalEnd() {
2018-09-14 05:42:04 +00:00
//console.info("[onLocalEnd] connection '" + cid + "' ended, will probably close soon");
conn.tunnelClosing = true;
if (!sentEnd) {
2018-09-05 07:18:12 +00:00
sendMessage(Packer.packHeader(tun, null, 'end'));
sentEnd = true;
}
});
conn.on('error', function onLocalError(err) {
console.info("[onLocalError] connection '" + cid + "' errored:", err);
if (!sentEnd) {
var packBody = true;
2018-09-05 07:18:12 +00:00
sendMessage(Packer.packHeader(tun, {message: err.message, code: err.code}, 'error', packBody));
sentEnd = true;
}
});
conn.on('close', function onLocalClose(hadErr) {
2018-09-05 07:18:12 +00:00
delete priv.localclients[cid];
console.log('[onLocalClose] closed "' + cid + '" read:'+conn.tunnelRead+', wrote:'+conn.tunnelWritten+' (' + clientHandlers.count() + ' clients)');
if (!sentEnd) {
2018-09-05 07:18:12 +00:00
sendMessage(Packer.packHeader(tun, null, hadErr && 'error' || 'end'));
sentEnd = true;
}
});
}
, write: function (cid, opts) {
2018-09-05 07:18:12 +00:00
var conn = priv.localclients[cid];
if (!conn) {
return false;
}
//console.log("[=>] received data from '" + cid + "' =>", opts.data.byteLength);
if (conn.tunnelClosing) {
console.warn("[onmessage] received data for '"+cid+"' over socket after connection was ended");
return true;
}
conn.write(opts.data);
// It might seem weird to increase the "read" value in a function named `write`, but this
// is bytes read from the tunnel and written to the local connection.
conn.tunnelRead += opts.data.byteLength;
if (!conn.remotePaused && conn.bufferSize > 1024*1024) {
var packBody = true;
2018-09-05 07:18:12 +00:00
sendMessage(Packer.packHeader(opts, conn.tunnelRead, 'pause', packBody));
conn.remotePaused = true;
conn.once('drain', function () {
var packBody = true;
2018-09-05 07:18:12 +00:00
sendMessage(Packer.packHeader(opts, conn.tunnelRead, 'resume', packBody));
conn.remotePaused = false;
});
}
return true;
}
, closeSingle: function (cid) {
2018-09-05 07:18:12 +00:00
if (!priv.localclients[cid]) {
return;
}
2018-09-14 05:42:04 +00:00
//console.log('[closeSingle]', cid);
PromiseA.resolve().then(function () {
2018-09-05 07:18:12 +00:00
var conn = priv.localclients[cid];
conn.tunnelClosing = true;
conn.end();
// If no data is buffered for writing then we don't need to wait for it to drain.
if (!conn.bufferSize) {
return timeoutPromise(500);
}
// Otherwise we want the connection to be able to finish, but we also want to impose
// a time limit for it to drain, since it shouldn't have more than 1MB buffered.
return new PromiseA(function (resolve) {
var timeoutId = setTimeout(resolve, 60*1000);
conn.once('drain', function () {
clearTimeout(timeoutId);
setTimeout(resolve, 500);
});
});
}).then(function () {
2018-09-05 07:18:12 +00:00
if (priv.localclients[cid]) {
console.warn('[closeSingle]', cid, 'connection still present after calling `end`');
2018-09-05 07:18:12 +00:00
priv.localclients[cid].destroy();
return timeoutPromise(500);
}
}).then(function () {
2018-09-05 07:18:12 +00:00
if (priv.localclients[cid]) {
console.error('[closeSingle]', cid, 'connection still present after calling `destroy`');
2018-09-05 07:18:12 +00:00
delete priv.localclients[cid];
}
}).catch(function (err) {
console.error('[closeSingle] failed to close connection', cid, err.toString());
2018-09-05 07:18:12 +00:00
delete priv.localclients[cid];
});
}
, closeAll: function () {
console.log('[closeAll]');
2018-09-05 07:18:12 +00:00
Object.keys(priv.localclients).forEach(function (cid) {
clientHandlers.closeSingle(cid);
});
}
, count: function () {
2018-09-05 07:18:12 +00:00
return Object.keys(priv.localclients).length;
}
};
var pendingCommands = {};
2018-09-05 07:18:12 +00:00
function sendMessage(msg) {
// There is a chance that this occurred after the websocket was told to close
// and before it finished, in which case we don't need to log the error.
if (wstunneler.readyState !== wstunneler.CLOSING) {
wstunneler.send(msg, {binary: true});
return wstunneler.bufferedAmount;
}
}
function sendCommand(name) {
var id = Math.ceil(1e9 * Math.random());
var cmd = [id, name].concat(Array.prototype.slice.call(arguments, 1));
2018-06-06 07:01:56 +00:00
if (state.debug) { console.log('[DEBUG] command sending', cmd); }
var packBody = true;
2018-09-05 07:18:12 +00:00
sendMessage(Packer.packHeader(null, cmd, 'control', packBody));
setTimeout(function () {
if (pendingCommands[id]) {
2018-06-07 06:45:42 +00:00
console.warn('command', name, id, 'timed out');
pendingCommands[id]({
message: 'response not received in time'
, code: 'E_TIMEOUT'
});
}
}, pongTimeout);
return new PromiseA(function (resolve, reject) {
pendingCommands[id] = function (err, result) {
delete pendingCommands[id];
if (err) {
reject(err);
} else {
resolve(result);
}
};
});
}
function noHandler(cmd) {
console.warn("[telebit] state.handlers['" + cmd[1] + "'] not set");
console.warn(cmd[2]);
2018-06-01 09:13:04 +00:00
}
var connCallback;
2018-08-08 07:11:29 +00:00
function hyperPeek(tun) {
var m;
var str;
if (tun.data) {
if ('http' === tun.service) {
str = tun.data.toString();
m = str.match(/(?:^|[\r\n])Host: ([^\r\n]+)[\r\n]*/im);
tun._name = tun._hostname = (m && m[1].toLowerCase() || '').split(':')[0];
}
else if ('https' === tun.service || 'tls' === tun.service) {
tun._name = tun._servername = sni(tun.data);
} else {
tun._name = '';
}
}
}
var packerHandlers = {
oncontrol: function (opts) {
var cmd, err;
try {
cmd = JSON.parse(opts.data.toString());
} catch (err) {}
if (!Array.isArray(cmd) || typeof cmd[0] !== 'number') {
console.warn('received bad command "' + opts.data.toString() + '"');
return;
}
if (cmd[0] < 0) {
var cb = pendingCommands[-cmd[0]];
if (!cb) {
console.warn('received response for unknown request:', cmd);
} else {
cb.apply(null, cmd.slice(1));
}
return;
}
if (cmd[0] === 0) {
console.warn('received dis-associated error from server', cmd[1]);
if (connCallback) {
connCallback(cmd[1]);
}
return;
}
if (cmd[1] === 'hello') {
2018-06-06 07:01:56 +00:00
if (state.debug) { console.log('[DEBUG] hello received'); }
2018-09-05 07:18:12 +00:00
if (auth) {
authsent = true;
sendCommand('auth', auth).catch(function (err) { console.error('1', err); });
}
priv.tokens.forEach(function (jwtoken) {
if (state.debug) { console.log('[DEBUG] send token'); }
authsent = true;
sendCommand('add_token', jwtoken)
.catch(function (err) {
console.error('failed re-adding token', jwtoken, 'after reconnect', err);
// Not sure if we should do something like remove the token here. It worked
// once or it shouldn't have stayed in the list, so it's less certain why
// it would have failed here.
});
});
if (connCallback) {
connCallback();
}
// TODO: handle the versions and commands provided by 'hello' - isn't super important
// yet since there is only one version and set of commands.
err = null;
2018-06-06 07:01:56 +00:00
} else if (cmd[1] === 'grant') {
authenticated = true;
if (state.handlers[cmd[1]]) {
state.handlers[cmd[1]](cmd[2]);
} else {
noHandler(cmd);
}
return;
} else if (cmd[1] === 'access_token') {
authenticated = true;
if (state.handlers[cmd[1]]) {
state.handlers[cmd[1]](cmd[2]);
} else {
noHandler(cmd);
}
2018-06-01 09:13:04 +00:00
return;
2018-06-06 07:01:56 +00:00
} else {
err = { message: 'unknown command "'+cmd[1]+'"', code: 'E_UNKNOWN_COMMAND' };
2018-06-01 09:13:04 +00:00
}
var packBody = true;
2018-09-05 07:18:12 +00:00
sendMessage(Packer.packHeader(null, [-cmd[0], err], 'control', packBody));
}
2018-08-08 07:11:29 +00:00
, onconnection: function (tun) {
2018-05-31 06:19:53 +00:00
var cid = tun._id = Packer.addrToId(tun);
2017-06-05 17:20:58 +00:00
2018-08-08 07:11:29 +00:00
// this data should have been gathered already as part of the proxy protocol
// but if it's available again here we can double check
hyperPeek(tun);
2016-10-11 23:43:24 +00:00
2018-08-08 07:11:29 +00:00
// TODO use readable streams instead
2018-09-04 04:56:52 +00:00
wstunneler._socket.pause();
2018-05-31 06:19:53 +00:00
require(state.sortingHat).assign(state, tun, function (err, conn) {
if (err) {
err.message = err.message.replace(/:tun_id/, tun._id);
packerHandlers._onConnectError(cid, tun, err);
return;
}
2018-05-31 06:19:53 +00:00
clientHandlers.add(conn, cid, tun);
2018-05-31 10:10:47 +00:00
if (tun.data) { conn.write(tun.data); }
2018-09-04 04:56:52 +00:00
wstunneler._socket.resume();
2018-05-31 06:19:53 +00:00
});
}
2016-10-11 23:43:24 +00:00
2018-08-08 07:11:29 +00:00
, onmessage: function (tun) {
var cid = tun._id = Packer.addrToId(tun);
var handled;
hyperPeek(tun);
handled = clientHandlers.write(cid, tun);
// quasi backwards compat
if (!handled) { console.log("[debug] did not get 'connection' event"); packerHandlers.onconnection(tun); }
2018-08-08 07:11:29 +00:00
}
, onpause: function (opts) {
var cid = Packer.addrToId(opts);
2018-09-05 07:18:12 +00:00
if (priv.localclients[cid]) {
console.log("[TunnelPause] pausing '"+cid+"', remote received", opts.data.toString(), 'of', priv.localclients[cid].tunnelWritten, 'sent');
priv.localclients[cid].manualPause = true;
priv.localclients[cid].pause();
} else {
console.log('[TunnelPause] remote tried pausing finished connection', cid);
// Often we have enough latency that we've finished sending before we're told to pause, so
// don't worry about sending back errors, since we won't be sending data over anyway.
// var packBody = true;
2018-09-05 07:18:12 +00:00
// sendMessage(Packer.packHeader(opts, {message: 'no matching connection', code: 'E_NO_CONN'}, 'error', packBody));
}
}
, onresume: function (opts) {
var cid = Packer.addrToId(opts);
2018-09-05 07:18:12 +00:00
if (priv.localclients[cid]) {
console.log("[TunnelResume] resuming '"+cid+"', remote received", opts.data.toString(), 'of', priv.localclients[cid].tunnelWritten, 'sent');
priv.localclients[cid].manualPause = false;
priv.localclients[cid].resume();
} else {
console.log('[TunnelResume] remote tried resuming finished connection', cid);
// var packBody = true;
2018-09-05 07:18:12 +00:00
// sendMessage(Packer.packHeader(opts, {message: 'no matching connection', code: 'E_NO_CONN'}, 'error', packBody));
}
2016-09-30 19:04:27 +00:00
}
2016-09-30 19:04:27 +00:00
, onend: function (opts) {
2016-10-06 05:55:48 +00:00
var cid = Packer.addrToId(opts);
2016-09-30 19:04:27 +00:00
//console.log("[end] '" + cid + "'");
clientHandlers.closeSingle(cid);
2016-09-30 19:04:27 +00:00
}
, onerror: function (opts) {
2016-10-06 05:55:48 +00:00
var cid = Packer.addrToId(opts);
2016-09-30 19:04:27 +00:00
//console.log("[error] '" + cid + "'", opts.code || '', opts.message);
clientHandlers.closeSingle(cid);
2016-09-30 19:04:27 +00:00
}
, _onConnectError: function (cid, opts, err) {
console.info("[_onConnectError] opening '" + cid + "' failed because " + err.message);
2018-09-05 07:18:12 +00:00
sendMessage(Packer.packHeader(opts, null, 'error'));
2016-09-30 19:04:27 +00:00
}
};
2018-09-05 07:18:12 +00:00
priv.timeoutId = null;
priv.lastActivity = Date.now();
priv.refreshTimeout = function refreshTimeout() {
priv.lastActivity = Date.now();
};
priv.checkTimeout = function checkTimeout() {
if (!wstunneler) {
console.warn('checkTimeout called when websocket already closed');
return;
}
2018-09-05 07:18:12 +00:00
// Determine how long the connection has been "silent", ie no activity.
var silent = Date.now() - priv.lastActivity;
2018-09-05 07:18:12 +00:00
// If we have had activity within the last activityTimeout then all we need to do is
// call this function again at the soonest time when the connection could be timed out.
if (silent < activityTimeout) {
priv.timeoutId = setTimeout(priv.checkTimeout, activityTimeout-silent);
}
2018-09-05 07:18:12 +00:00
// Otherwise we check to see if the pong has also timed out, and if not we send a ping
// and call this function again when the pong will have timed out.
else if (silent < activityTimeout + pongTimeout) {
2018-09-14 05:42:04 +00:00
//console.log('DEBUG: pinging tunnel server');
2018-09-05 07:18:12 +00:00
try {
wstunneler.ping();
} catch (err) {
console.warn('failed to ping tunnel server', err);
}
2018-09-05 07:18:12 +00:00
priv.timeoutId = setTimeout(priv.checkTimeout, pongTimeout);
}
2018-09-05 07:18:12 +00:00
// Last case means the ping we sent before didn't get a response soon enough, so we
// need to close the websocket connection.
else {
console.info('[info] closing due to connection timeout');
2018-09-05 07:18:12 +00:00
wstunneler.close(1000, 'connection timeout');
}
};
2018-09-05 07:18:12 +00:00
me.destroy = function destroy() {
console.info('[info] destroy()');
2018-09-05 07:18:12 +00:00
try {
//wstunneler.close(1000, 're-connect');
wstunneler._socket.destroy();
} catch(e) {
// ignore
}
};
me.connect = function connect() {
if (!priv.tokens.length && state.config.email) {
auth = TelebitRemote._tokenFromState(state);
}
priv.timeoutId = null;
var machine = Packer.create(packerHandlers);
2018-09-16 06:16:43 +00:00
console.info("[telebit:lib/remote.js] [connect] '" + (state.wss || state.relay) + "'");
2018-09-05 07:18:12 +00:00
var tunnelUrl = (state.wss || state.relay).replace(/\/$/, '') + '/'; // + auth;
wstunneler = new WebSocket(tunnelUrl, { rejectUnauthorized: !state.insecure });
// XXXXXX
wstunneler.on('open', function () {
2018-09-16 06:16:43 +00:00
console.info("[telebit:lib/remote.js] [open] connected to '" + (state.wss || state.relay) + "'");
2018-09-05 07:18:12 +00:00
me.emit('connect');
priv.refreshTimeout();
priv.timeoutId = setTimeout(priv.checkTimeout, activityTimeout);
wstunneler._socket.on('drain', function () {
// the websocket library has it's own buffer apart from node's socket buffer, but that one
// is much more difficult to watch, so we watch for the lower level buffer to drain and
// then check to see if the upper level buffer is still too full to write to. Note that
// the websocket library buffer has something to do with compression, so I'm not requiring
// that to be 0 before we start up again.
if (wstunneler.bufferedAmount > 128*1024) {
return;
}
pausedClients.forEach(function (conn) {
if (!conn.manualPause) {
// console.log('resuming connection', conn.tunnelCid, 'now the websocket has caught up');
conn.resume();
}
});
pausedClients.length = 0;
});
initialConnect = false;
2018-09-05 07:18:12 +00:00
});
wstunneler.on('close', function () {
console.info("[info] [closing] received close signal from relay");
2018-09-05 07:18:12 +00:00
clearTimeout(priv.timeoutId);
clientHandlers.closeAll();
var error = new Error('websocket connection closed before response');
error.code = 'E_CONN_CLOSED';
Object.keys(pendingCommands).forEach(function (id) {
pendingCommands[id](error);
});
if (connCallback) {
connCallback(error);
}
me.emit('close');
2018-09-05 07:18:12 +00:00
});
wstunneler.on('error', function (err) {
me.emit('error', err);
2018-09-04 04:56:52 +00:00
});
// Our library will automatically handle sending the pong respose to ping requests.
2018-09-05 07:18:12 +00:00
wstunneler.on('ping', priv.refreshTimeout);
wstunneler.on('pong', function () {
2018-09-14 05:42:04 +00:00
//console.log('DEBUG received pong');
2018-09-05 07:18:12 +00:00
priv.refreshTimeout();
});
2017-04-08 00:49:52 +00:00
wstunneler.on('message', function (data, flags) {
2018-09-05 07:18:12 +00:00
priv.refreshTimeout();
2017-04-08 00:49:52 +00:00
if (data.error || '{' === data[0]) {
console.log(data);
return;
}
machine.fns.addChunk(data, flags);
});
2018-09-04 04:56:52 +00:00
};
me.end = function() {
2018-09-05 07:18:12 +00:00
priv.tokens.length = 0;
if (priv.timeoutId) {
clearTimeout(priv.timeoutId);
priv.timeoutId = null;
}
console.info('[info] closing due to tr.end()');
2018-09-05 07:18:12 +00:00
wstunneler.close(1000, 're-connect');
wstunneler.on('close', function () {
me.emit('end');
2018-09-04 04:56:52 +00:00
});
2017-04-14 22:27:25 +00:00
};
2016-09-30 19:04:27 +00:00
}
2018-09-05 07:18:12 +00:00
2018-09-04 04:56:52 +00:00
TelebitRemote.prototype = EventEmitter.prototype;
2018-09-05 07:18:12 +00:00
TelebitRemote._tokenFromState = function (state) {
return {
subject: state.config.email
, subject_scheme: 'mailto'
// TODO create domains list earlier
, scope: Object.keys(state.config.servernames || {}).join(',')
, otp: state.otp
, hostname: os.hostname()
// Used for User-Agent
, os_type: os.type()
, os_platform: os.platform()
, os_release: os.release()
, os_arch: os.arch()
};
};
2018-09-04 04:56:52 +00:00
TelebitRemote.create = function (opts) {
return new TelebitRemote(opts);
};
TelebitRemote.createConnection = function (opts, cb) {
var tunnel = TelebitRemote.create(opts);
tunnel.connect(opts);
tunnel.once('connect', cb);
return tunnel;
};
TelebitRemote.connect = TelebitRemote.createConnection;
module.exports.TelebitRemote = TelebitRemote;
2016-09-30 01:10:40 +00:00
}());