diff --git a/js/background.js b/js/background.js index f28b2df2b..7e87ac953 100644 --- a/js/background.js +++ b/js/background.js @@ -124,9 +124,6 @@ 'loki/session_icon_128.png', ]); - // Set server-client time difference - window.LokiPublicChatAPI.setClockParams(); - // We add this to window here because the default Node context is erased at the end // of preload.js processing window.setImmediate = window.nodeSetImmediate; @@ -289,7 +286,10 @@ // Update zoom window.updateZoomFactor(); - if (window.lokiFeatureFlags.useOnionRequests) { + if ( + window.lokiFeatureFlags.useOnionRequests || + window.lokiFeatureFlags.useFileOnionRequests + ) { // Initialize paths for onion requests window.lokiSnodeAPI.buildNewOnionPaths(); } diff --git a/js/expire.js b/js/expire.js index 0d4750c3b..ba200c41e 100644 --- a/js/expire.js +++ b/js/expire.js @@ -52,6 +52,8 @@ } // no message logged means serverRequest never returned... }; + + // don't wait for this to finish checkForUpgrades(); window.extension = window.extension || {}; @@ -91,4 +93,45 @@ // yes we know cb(expiredVersion); }; + + const getServerTime = async () => { + let timestamp = NaN; + + try { + const res = await window.tokenlessFileServerAdnAPI.serverRequest( + 'loki/v1/time' + ); + if (res.statusCode === 200) { + timestamp = res.response; + } + } catch (e) { + return timestamp; + } + + return Number(timestamp); + }; + + const getTimeDifferential = async () => { + // Get time differential between server and client in seconds + const serverTime = await getServerTime(); + const clientTime = Math.ceil(Date.now() / 1000); + + if (Number.isNaN(serverTime)) { + log.error('expire:::getTimeDifferential - serverTime is not valid'); + return 0; + } + return serverTime - clientTime; + }; + + // require for PoW to work + const setClockParams = async () => { + // Set server-client time difference + const maxTimeDifferential = 30 + 15; // + 15 for onion requests + const timeDifferential = await getTimeDifferential(); + log.info('expire:::setClockParams - Clock difference', timeDifferential); + + window.clientClockSynced = Math.abs(timeDifferential) < maxTimeDifferential; + return window.clientClockSynced; + }; + setClockParams(); })(); diff --git a/js/modules/loki_app_dot_net_api.js b/js/modules/loki_app_dot_net_api.js index f87c0dcc9..2ba549388 100644 --- a/js/modules/loki_app_dot_net_api.js +++ b/js/modules/loki_app_dot_net_api.js @@ -65,15 +65,15 @@ const sendViaOnion = async (srvPubKey, url, fetchOptions, options = {}) => { } const payloadObj = { - method: fetchOptions.method, - body: fetchOptions.body, + method: fetchOptions.method || 'GET', + body: fetchOptions.body || '', // safety issue with file server, just safer to have this headers: fetchOptions.headers || {}, // no initial / endpoint: url.pathname.replace(/^\//, ''), }; if (url.search) { - payloadObj.endpoint += `?${url.search}`; + payloadObj.endpoint += url.search; } // from https://github.com/sindresorhus/is-stream/blob/master/index.js @@ -128,6 +128,10 @@ const sendViaOnion = async (srvPubKey, url, fetchOptions, options = {}) => { return {}; } + if (result === lokiRpcUtils.BAD_PATH) { + return {}; + } + // handle error/retries if (!result.status) { log.error( @@ -141,20 +145,49 @@ const sendViaOnion = async (srvPubKey, url, fetchOptions, options = {}) => { }); } + if (options.noJson) { + return { + result, + txtResponse: result.body, + response: { + data: result.body, + headers: result.headers, + }, + }; + } + // get the return variables we need let response = {}; let txtResponse = ''; - let body = ''; - try { - body = JSON.parse(result.body); - } catch (e) { - log.error( - `loki_app_dot_net:::sendViaOnion #${options.requestNumber} - Cant decode JSON body`, - result.body + + let { body } = result; + if (typeof body === 'string') { + // adn does uses this path + // log.info(`loki_app_dot_net:::sendViaOnion - got text response ${url.toString()}`); + txtResponse = result.body; + try { + body = JSON.parse(result.body); + } catch (e) { + log.error( + `loki_app_dot_net:::sendViaOnion #${options.requestNumber} - Cant decode JSON body`, + typeof result.body, + result.body + ); + } + } else { + // why is + // https://chat-dev.lokinet.org/loki/v1/channel/1/deletes?count=200&since_id= + // difference in response than all the other calls.... + log.info( + `loki_app_dot_net:::sendViaOnion #${ + options.requestNumber + } - got object response ${url.toString()}` ); } // result.status has the http response code - txtResponse = JSON.stringify(body); + if (!txtResponse) { + txtResponse = JSON.stringify(body); + } response = body; response.headers = result.headers; @@ -216,8 +249,7 @@ const sendToProxy = async (srvPubKey, endpoint, fetchOptions, options = {}) => { // make temporary key for this request/response // async maybe preferable to avoid cpu spikes - // tho I think sync might be more apt in certain cases here... - // like sending + // but I think sync might be more apt in cases like sending... const ephemeralKey = await libloki.crypto.generateEphemeralKeyPair(); // mix server pub key with our priv key @@ -377,10 +409,14 @@ const serverRequest = async (endpoint, options = {}) => { FILESERVER_HOSTS.includes(host) ) { mode = 'sendViaOnion'; - // url.search automatically includes the ? part - // const search = url.search || ''; - // strip first slash - // const endpointWithQS = `${url.pathname}${search}`.replace(/^\//, ''); + ({ response, txtResponse, result } = await sendViaOnion( + srvPubKey, + url, + fetchOptions, + options + )); + } else if (window.lokiFeatureFlags.useFileOnionRequests && srvPubKey) { + mode = 'sendViaOnionOG'; ({ response, txtResponse, result } = await sendViaOnion( srvPubKey, url, @@ -410,9 +446,11 @@ const serverRequest = async (endpoint, options = {}) => { result = await nodeFetch(url, fetchOptions); // always make sure this check is enabled process.env.NODE_TLS_REJECT_UNAUTHORIZED = '1'; + txtResponse = await result.text(); // cloudflare timeouts (504s) will be html... response = options.textResponse ? txtResponse : JSON.parse(txtResponse); + // result.status will always be 200 // emulate the correct http code if available if (response && response.meta && response.meta.code) { @@ -570,55 +608,39 @@ class LokiAppDotNetServerAPI { // Hard coded let pubKeyAB; - if (urlPubkeyMap) { + if (urlPubkeyMap && urlPubkeyMap[this.baseServerUrl]) { pubKeyAB = window.Signal.Crypto.base64ToArrayBuffer( urlPubkeyMap[this.baseServerUrl] ); } - // else will fail validation later - - // if in proxy mode, don't allow "file-dev."... - // it only supports "file."... host. - if ( - window.lokiFeatureFlags.useSnodeProxy && - !window.lokiFeatureFlags.useOnionRequests - ) { - pubKeyAB = window.Signal.Crypto.base64ToArrayBuffer( - LOKIFOUNDATION_FILESERVER_PUBKEY - ); - } // do we have their pubkey locally? // FIXME: this._server won't be set yet... // can't really do this for the file server because we'll need the key // before we can communicate with lsrpc - /* - // get remote pubKey - this._server.serverRequest('loki/v1/public_key').then(keyRes => { - // we don't need to delay to protect identity because the token request - // should only be done over lokinet-lite - this.delayToken = true; - if (keyRes.err || !keyRes.response || !keyRes.response.data) { - if (keyRes.err) { - log.error(`Error ${keyRes.err}`); - } - } else { - // store it - this.pubKey = dcodeIO.ByteBuffer.wrap( - keyRes.response.data, - 'base64' - ).toArrayBuffer(); - // write it to a file + if (window.lokiFeatureFlags.useFileOnionRequests) { + if ( + window.lokiPublicChatAPI && + window.lokiPublicChatAPI.openGroupPubKeys && + window.lokiPublicChatAPI.openGroupPubKeys[this.baseServerUrl] + ) { + pubKeyAB = + window.lokiPublicChatAPI.openGroupPubKeys[this.baseServerUrl]; } - }); - */ + } else if (window.lokiFeatureFlags.useSnodeProxy) { + // if in proxy mode, replace with "file."... + // it only supports this host... + pubKeyAB = window.Signal.Crypto.base64ToArrayBuffer( + LOKIFOUNDATION_FILESERVER_PUBKEY + ); + } + // else will fail validation later // now that key is loaded, lets verify if (pubKeyAB && pubKeyAB.byteLength && pubKeyAB.byteLength !== 33) { log.error('FILESERVER PUBKEY is invalid, length:', pubKeyAB.byteLength); process.exit(1); } - this.pubKey = pubKeyAB; this.pubKeyHex = StringView.arrayBufferToHex(pubKeyAB); @@ -1095,7 +1117,11 @@ class LokiAppDotNetServerAPI { if (res.err || !res.response || !res.response.data) { if (res.err) { - log.error(`getUsers Error ${res.err}`); + log.error( + `loki_app_dot_net:::getUsers - Error: ${res.err} for ${pubKeys.join( + ',' + )}` + ); } return []; } @@ -2315,6 +2341,9 @@ class LokiPublicChannelAPI { } } +LokiAppDotNetServerAPI.serverRequest = serverRequest; +LokiAppDotNetServerAPI.sendViaOnion = sendViaOnion; + // These files are expected to be in commonjs so we can't use es6 syntax :( // If we move these to TS then we should be able to use es6 module.exports = LokiAppDotNetServerAPI; diff --git a/js/modules/loki_public_chat_api.js b/js/modules/loki_public_chat_api.js index 61b96a1ae..e37c01f3c 100644 --- a/js/modules/loki_public_chat_api.js +++ b/js/modules/loki_public_chat_api.js @@ -1,14 +1,87 @@ -/* global log, window, process, URL */ +/* global log, window, process, URL, dcodeIO */ const EventEmitter = require('events'); -const nodeFetch = require('node-fetch'); const LokiAppDotNetAPI = require('./loki_app_dot_net_api'); +const nodeFetch = require('node-fetch'); + +const validOpenGroupServer = async serverUrl => { + // test to make sure it's online (and maybe has a valid SSL cert) + try { + const url = new URL(serverUrl); + + if (window.lokiFeatureFlags.useFileOnionRequests) { + // check for LSRPC + + // this is safe (as long as node's in your trust model) + // because + const result = await window.tokenlessFileServerAdnAPI.serverRequest( + `loki/v1/getOpenGroupKey/${url.hostname}` + ); + if (result.response.meta.code === 200) { + // supports it + const obj = JSON.parse(result.response.data); + const pubKey = dcodeIO.ByteBuffer.wrap( + obj.data, + 'base64' + ).toArrayBuffer(); + // verify it works... + // get around the FILESERVER_HOSTS filter by not using serverRequest + const res = await LokiAppDotNetAPI.sendViaOnion( + pubKey, + url, + { method: 'GET' }, + { noJson: true } + ); + if (res.result.status === 200) { + log.info( + `loki_public_chat::validOpenGroupServer - onion routing enabled on ${url.toString()}` + ); + // save pubkey for use... + window.lokiPublicChatAPI.openGroupPubKeys[serverUrl] = pubKey; + return true; + } + // otherwise fall back + } else if (result.response.meta.code !== 404) { + // unknown error code + log.warn( + 'loki_public_chat::validOpenGroupServer - unknown error code', + result.response.meta + ); + } + } + // doesn't support it, fallback + log.info( + `loki_public_chat::validOpenGroupServer - directly contacting ${url.toString()}` + ); + + // allow .loki (may only need an agent but not sure + // until we have a .loki to test with) + process.env.NODE_TLS_REJECT_UNAUTHORIZED = url.host.match(/\.loki$/i) + ? '0' + : '1'; + await nodeFetch(serverUrl); + process.env.NODE_TLS_REJECT_UNAUTHORIZED = '1'; + // const txt = await res.text(); + } catch (e) { + process.env.NODE_TLS_REJECT_UNAUTHORIZED = '1'; + log.warn( + `loki_public_chat::validOpenGroupServer - failing to create ${serverUrl}`, + e.code, + e.message + ); + // bail out if not valid enough + return false; + } + return true; +}; + class LokiPublicChatFactoryAPI extends EventEmitter { constructor(ourKey) { super(); this.ourKey = ourKey; this.servers = []; this.allMembers = []; + this.openGroupPubKeys = {}; // Multidevice states this.primaryUserProfileName = {}; } @@ -24,37 +97,20 @@ class LokiPublicChatFactoryAPI extends EventEmitter { await Promise.all(this.servers.map(server => server.close())); } - static async validServer(serverUrl) { - // test to make sure it's online (and maybe has a valid SSL cert) - try { - const url = new URL(serverUrl); - // allow .loki (may only need an agent but not sure - // until we have a .loki to test with) - process.env.NODE_TLS_REJECT_UNAUTHORIZED = url.host.match(/\.loki$/i) - ? '0' - : '1'; - // FIXME: use proxy when we have open groups that work with proxy - await nodeFetch(serverUrl); - process.env.NODE_TLS_REJECT_UNAUTHORIZED = '1'; - // const txt = await res.text(); - } catch (e) { - process.env.NODE_TLS_REJECT_UNAUTHORIZED = '1'; - log.warn(`failing to created ${serverUrl}`, e.code, e.message); - // bail out if not valid enough - return false; - } - return true; - } - // server getter/factory async findOrCreateServer(serverUrl) { let thisServer = this.servers.find( server => server.baseServerUrl === serverUrl ); if (!thisServer) { - log.info(`LokiAppDotNetAPI creating ${serverUrl}`); - - if (!(await this.constructor.validServer(serverUrl))) { + log.info(`loki_public_chat::findOrCreateServer - creating ${serverUrl}`); + + const serverIsValid = await validOpenGroupServer(serverUrl); + if (!serverIsValid) { + // FIXME: add toast? + log.error( + `loki_public_chat::findOrCreateServer - error: ${serverUrl} is not valid` + ); return null; } @@ -65,15 +121,27 @@ class LokiPublicChatFactoryAPI extends EventEmitter { thisServer = new StubAppDotNetAPI(this.ourKey, serverUrl); } else { thisServer = new LokiAppDotNetAPI(this.ourKey, serverUrl); + if (this.openGroupPubKeys[serverUrl]) { + thisServer.getPubKeyForUrl(); + if (!thisServer.pubKeyHex) { + log.warn( + `loki_public_chat::findOrCreateServer - failed to set public key` + ); + } + } } const gotToken = await thisServer.getOrRefreshServerToken(); if (!gotToken) { - log.warn(`Invalid server ${serverUrl}`); + log.warn( + `loki_public_chat::findOrCreateServer - Invalid server ${serverUrl}` + ); return null; } if (window.isDev) { - log.info(`set token ${thisServer.token} for ${serverUrl}`); + log.info( + `loki_public_chat::findOrCreateServer - set token ${thisServer.token} for ${serverUrl}` + ); } this.servers.push(thisServer); @@ -81,42 +149,6 @@ class LokiPublicChatFactoryAPI extends EventEmitter { return thisServer; } - static async getServerTime() { - const url = `${window.getDefaultFileServer()}/loki/v1/time`; - let timestamp = NaN; - - try { - const res = await nodeFetch(url); - if (res.ok) { - timestamp = await res.text(); - } - } catch (e) { - return timestamp; - } - - return Number(timestamp); - } - - static async getTimeDifferential() { - // Get time differential between server and client in seconds - const serverTime = await this.getServerTime(); - const clientTime = Math.ceil(Date.now() / 1000); - - if (Number.isNaN(serverTime)) { - return 0; - } - return serverTime - clientTime; - } - - static async setClockParams() { - // Set server-client time difference - const maxTimeDifferential = 30; - const timeDifferential = await this.getTimeDifferential(); - - window.clientClockSynced = Math.abs(timeDifferential) < maxTimeDifferential; - return window.clientClockSynced; - } - // channel getter/factory async findOrCreateChannel(serverUrl, channelId, conversationId) { const server = await this.findOrCreateServer(serverUrl); diff --git a/js/modules/loki_rpc.js b/js/modules/loki_rpc.js index faf59adcd..62c4b4e49 100644 --- a/js/modules/loki_rpc.js +++ b/js/modules/loki_rpc.js @@ -656,7 +656,7 @@ const lokiFetch = async (url, options = {}, targetNode = null) => { const result = await response.json(); log.warn( `lokirpc:::lokiFetch ${type} - wrong swarm, now looking at snodes`, - result.snode + result.snodes ); const newSwarm = result.snodes ? result.snodes : []; throw new textsecure.WrongSwarmError(newSwarm); @@ -845,5 +845,6 @@ const lokiRpc = ( module.exports = { lokiRpc, + BAD_PATH, sendOnionRequestLsrpcDest, }; diff --git a/js/modules/loki_rss_api.js b/js/modules/loki_rss_api.js index 566a2afc1..fb6763c97 100644 --- a/js/modules/loki_rss_api.js +++ b/js/modules/loki_rss_api.js @@ -63,7 +63,7 @@ class LokiRssAPI extends EventEmitter { log.warn('LokiRssAPI unsupported rss feed', this.feedUrl); return; } - const result = await window.lokiFileServerAPI._server.serverRequest( + const result = await window.tokenlessFileServerAdnAPI.serverRequest( map[this.feedUrl] ); if (!result) { @@ -77,6 +77,7 @@ class LokiRssAPI extends EventEmitter { if (!result.response.data) { log.error( 'LokiRssAPI rss proxy error, no data, response', + typeof result.response, result.response ); return; diff --git a/js/modules/loki_snode_api.js b/js/modules/loki_snode_api.js index e015fc923..390825f4f 100644 --- a/js/modules/loki_snode_api.js +++ b/js/modules/loki_snode_api.js @@ -27,11 +27,8 @@ async function tryGetSnodeListFromLokidSeednode( seedNodes = window.seedNodeList ) { if (!seedNodes.length) { - log.error( - `loki_snodes:::tryGetSnodeListFromLokidSeednode - no seedNodes given`, - seedNodes, - 'window', - window.seedNodeList + log.info( + 'loki_snode_api::tryGetSnodeListFromLokidSeednode - seedNodes are empty' ); return []; } @@ -48,13 +45,10 @@ async function tryGetSnodeListFromLokidSeednode( }, }; // FIXME: use sample - const seedNode = seedNodes.splice( - Math.floor(Math.random() * seedNodes.length), - 1 - )[0]; + const seedNode = seedNodes[Math.floor(Math.random() * seedNodes.length)]; if (!seedNode) { - log.error( - `loki_snodes:::tryGetSnodeListFromLokidSeednode - seedNode selection failure - seedNodes`, + log.warn( + 'loki_snode_api::tryGetSnodeListFromLokidSeednode - Could not select random snodes from', seedNodes ); return []; @@ -72,7 +66,7 @@ async function tryGetSnodeListFromLokidSeednode( ); if (!response) { log.error( - `loki_snodes:::tryGetSnodeListFromLokidSeednode - invalid response from seed ${urlObj.toString()}:`, + `loki_snode_api:::tryGetSnodeListFromLokidSeednode - invalid response from seed ${urlObj.toString()}:`, response ); return []; @@ -81,7 +75,7 @@ async function tryGetSnodeListFromLokidSeednode( // should we try to JSON.parse this? if (typeof response === 'string') { log.error( - `loki_snodes:::tryGetSnodeListFromLokidSeednode - invalid string response from seed ${urlObj.toString()}:`, + `loki_snode_api:::tryGetSnodeListFromLokidSeednode - invalid string response from seed ${urlObj.toString()}:`, response ); return []; @@ -89,7 +83,7 @@ async function tryGetSnodeListFromLokidSeednode( if (!response.result) { log.error( - `loki_snodes:::tryGetSnodeListFromLokidSeednode - invalid result from seed ${urlObj.toString()}:`, + `loki_snode_api:::tryGetSnodeListFromLokidSeednode - invalid result from seed ${urlObj.toString()}:`, response ); return []; @@ -103,10 +97,17 @@ async function tryGetSnodeListFromLokidSeednode( snodes = await getSnodesFromSeedUrl(tryUrl); // throw before clearing the lock, so the retries can kick in if (snodes.length === 0) { + log.warn( + `loki_snode_api::tryGetSnodeListFromLokidSeednode - ${seedNode.url} did not return any snodes, falling back to IP`, + seedNode.ip_url + ); // fall back on ip_url const tryIpUrl = new URL(seedNode.ip_url); snodes = await getSnodesFromSeedUrl(tryIpUrl); if (snodes.length === 0) { + log.warn( + `loki_snode_api::tryGetSnodeListFromLokidSeednode - ${seedNode.ip_url} did not return any snodes` + ); // does this error message need to be exactly this? throw new window.textsecure.SeedNodeError( 'Failed to contact seed node' @@ -115,15 +116,17 @@ async function tryGetSnodeListFromLokidSeednode( } if (snodes.length) { log.info( - `loki_snodes:::tryGetSnodeListFromLokidSeednode - got ${snodes.length} service nodes from seed` + `loki_snode_api::tryGetSnodeListFromLokidSeednode - ${seedNode.url} returned ${snodes.length} snodes` ); } return snodes; } catch (e) { log.warn( - 'loki_snodes:::tryGetSnodeListFromLokidSeednode - error', + 'LokiSnodeAPI::tryGetSnodeListFromLokidSeednode - error', e.code, - e.message + e.message, + 'on', + seedNode ); if (snodes.length === 0) { throw new window.textsecure.SeedNodeError('Failed to contact seed node'); @@ -137,11 +140,8 @@ async function getSnodeListFromLokidSeednode( retries = 0 ) { if (!seedNodes.length) { - log.error( - `loki_snodes:::getSnodeListFromLokidSeednode - no seedNodes given`, - seedNodes, - 'window', - window.seedNodeList + log.info( + 'loki_snode_api::getSnodeListFromLokidSeednode - seedNodes are empty' ); return []; } @@ -150,7 +150,7 @@ async function getSnodeListFromLokidSeednode( snodes = await tryGetSnodeListFromLokidSeednode(seedNodes); } catch (e) { log.warn( - 'loki_snodes:::getSnodeListFromLokidSeednode - error', + 'loki_snode_api::getSnodeListFromLokidSeednode - error', e.code, e.message ); @@ -158,13 +158,15 @@ async function getSnodeListFromLokidSeednode( if (retries < SEED_NODE_RETRIES) { setTimeout(() => { log.info( - 'loki_snodes:::refreshRandomPoolPromise - Retrying initialising random snode pool, try #', - retries + 'loki_snode_api::getSnodeListFromLokidSeednode - Retrying initialising random snode pool, try #', + retries, + 'seed nodes total', + seedNodes.length ); getSnodeListFromLokidSeednode(seedNodes, retries + 1); }, retries * retries * 5000); } else { - log.error('loki_snodes:::getSnodeListFromLokidSeednode - failing'); + log.error('loki_snode_api::getSnodeListFromLokidSeednode - failing'); throw new window.textsecure.SeedNodeError('Failed to contact seed node'); } } @@ -240,6 +242,8 @@ class LokiSnodeAPI { let response; try { + // Log this line for testing + // curl -k -X POST -H 'Content-Type: application/json' -d '"+fetchOptions.body.replace(/"/g, "\\'")+"'", url response = await nodeFetch(url, fetchOptions); } catch (e) { if (e.type === 'request-timeout') { @@ -329,21 +333,32 @@ class LokiSnodeAPI { async getOnionPath(toExclude = null) { const _ = window.Lodash; - const goodPaths = this.onionPaths.filter(x => !x.bad); + let goodPaths = this.onionPaths.filter(x => !x.bad); - if (goodPaths.length < MIN_GUARD_COUNT) { + let attemptNumber = 0; + while (goodPaths.length < MIN_GUARD_COUNT) { log.error( - `Must have at least 2 good onion paths, actual: ${goodPaths.length}` + `Must have at least 2 good onion paths, actual: ${goodPaths.length}, attempt #${attemptNumber} fetching more...` ); + // eslint-disable-next-line no-await-in-loop await this.buildNewOnionPaths(); // should we add a delay? buildNewOnionPaths should act as one + // reload goodPaths now - return this.getOnionPath(toExclude); + attemptNumber += 1; + goodPaths = this.onionPaths.filter(x => !x.bad); } const paths = _.shuffle(goodPaths); if (!toExclude) { + if (!paths[0]) { + log.error('LokiSnodeAPI::getOnionPath - no path in', paths); + return []; + } + if (!paths[0].path) { + log.error('LokiSnodeAPI::getOnionPath - no path in', paths[0]); + } return paths[0].path; } @@ -359,7 +374,7 @@ class LokiSnodeAPI { // await this.buildNewOnionPaths(); // and restart call? log.error( - `loki_snode_api::getOnionPath - no paths without`, + `LokiSnodeAPI::getOnionPath - no paths without`, toExclude.pubkey_ed25519, 'path count', paths.length, @@ -371,11 +386,21 @@ class LokiSnodeAPI { throw new Error('No onion paths available after filtering'); } + if (!otherPaths[0].path) { + log.error( + 'LokiSnodeAPI::getOnionPath - otherPaths no path in', + otherPaths[0] + ); + } + return otherPaths[0].path; } - async markPathAsBad(path) { + markPathAsBad(path) { this.onionPaths.forEach(p => { + if (!p.path) { + log.error('LokiSnodeAPI::markPathAsBad - no path in', p); + } if (p.path === path) { // eslint-disable-next-line no-param-reassign p.bad = true; @@ -383,14 +408,14 @@ class LokiSnodeAPI { }); } - // Does this get called multiple times on startup?? + // FIXME: need a lock because it is being called multiple times in parallel async buildNewOnionPaths() { // Note: this function may be called concurrently, so // might consider blocking the other calls const _ = window.Lodash; - log.info('building new onion paths'); + log.info('LokiSnodeAPI::buildNewOnionPaths - building new onion paths'); const allNodes = await this.getRandomSnodePool(); @@ -399,7 +424,9 @@ class LokiSnodeAPI { const nodes = await window.libloki.storage.getGuardNodes(); if (nodes.length === 0) { - log.warn('no guard nodes in DB. Will be selecting new guards nodes...'); + log.warn( + 'LokiSnodeAPI::buildNewOnionPaths - no guard nodes in DB. Will be selecting new guards nodes...' + ); } else { // We only store the nodes' keys, need to find full entries: const edKeys = nodes.map(x => x.ed25519PubKey); @@ -409,7 +436,7 @@ class LokiSnodeAPI { if (this.guardNodes.length < edKeys.length) { log.warn( - `could not find some guard nodes: ${this.guardNodes.length}/${edKeys.length} left` + `LokiSnodeAPI::buildNewOnionPaths - could not find some guard nodes: ${this.guardNodes.length}/${edKeys.length} left` ); } } @@ -425,7 +452,11 @@ class LokiSnodeAPI { let otherNodes = _.difference(allNodes, this.guardNodes); if (otherNodes.length < 2) { - log.error('Too few nodes to build an onion path!'); + log.warn( + 'LokiSnodeAPI::buildNewOnionPaths - Too few nodes to build an onion path! Refreshing pool and retrying' + ); + await this.refreshRandomPool(); + await this.buildNewOnionPaths(); return; } @@ -494,7 +525,7 @@ class LokiSnodeAPI { await this.refreshRandomPool(); } catch (e) { log.error( - `loki_snode:::getRandomProxySnodeAddress - error ${e.code} ${e.message}` + `LokiSnodeAPI::getRandomProxySnodeAddress - error ${e.code} ${e.message}` ); throw e; } @@ -506,7 +537,7 @@ class LokiSnodeAPI { if (!goodPool.length) { // FIXME: retry log.warn( - `loki_snode:::getRandomProxySnodeAddress - no good versions yet` + `LokiSnodeAPI::getRandomProxySnodeAddress - no good versions yet` ); return false; } @@ -538,7 +569,7 @@ class LokiSnodeAPI { } else { // maybe already marked bad... log.debug( - `loki_snode:::_getVersion - can't find ${node.ip}:${node.port} in randomSnodePool` + `LokiSnodeAPI::_getVersion - can't find ${node.ip}:${node.port} in randomSnodePool` ); } } @@ -553,13 +584,13 @@ class LokiSnodeAPI { const randomNodesLeft = this.getRandomPoolLength(); // clean up these error messages to be a little neater log.warn( - `loki_snode:::_getVersion - ${node.ip}:${node.port} is offline, removing, leaving ${randomNodesLeft} in the randomPool` + `LokiSnodeAPI::_getVersion - ${node.ip}:${node.port} is offline, removing, leaving ${randomNodesLeft} in the randomPool` ); // if not ECONNREFUSED, it's mostly ECONNRESETs // ENOTFOUND could mean no internet or hiccup } else if (retries < SNODE_VERSION_RETRIES) { log.warn( - 'loki_snode:::_getVersion - Error', + 'LokiSnodeAPI::_getVersion - Error', e.code, e.message, `on ${node.ip}:${node.port} retrying in 1s` @@ -570,7 +601,7 @@ class LokiSnodeAPI { this.markRandomNodeUnreachable(node); const randomNodesLeft = this.getRandomPoolLength(); log.warn( - `loki_snode:::_getVersion - failing to get version for ${node.ip}:${node.port}, removing, leaving ${randomNodesLeft} in the randomPool` + `LokiSnodeAPI::_getVersion - failing to get version for ${node.ip}:${node.port}, removing, leaving ${randomNodesLeft} in the randomPool` ); } // maybe throw? @@ -596,19 +627,19 @@ class LokiSnodeAPI { // give stats const diff = Date.now() - verionStart; log.debug( - `loki_snode:::_getAllVerionsForRandomSnodePool - ${count}/${total} pool version status update, has taken ${diff.toLocaleString()}ms` + `LokiSnodeAPI:::_getAllVerionsForRandomSnodePool - ${count}/${total} pool version status update, has taken ${diff.toLocaleString()}ms` ); Object.keys(this.versionPools).forEach(version => { const nodes = this.versionPools[version].length; log.debug( - `loki_snode:::_getAllVerionsForRandomSnodePool - version ${version} has ${nodes.toLocaleString()} snodes` + `LokiSnodeAPI:::_getAllVerionsForRandomSnodePool - version ${version} has ${nodes.toLocaleString()} snodes` ); }); } */ } catch (e) { log.error( - `loki_snode:::_getAllVerionsForRandomSnodePool - error`, + `LokiSnodeAPI::_getAllVerionsForRandomSnodePool - error`, e.code, e.message ); @@ -628,7 +659,7 @@ class LokiSnodeAPI { return curVal; }, []); log.debug( - `loki_snode:::_getAllVerionsForRandomSnodePool - ${versions.length} versions retrieved from network!:`, + `LokiSnodeAPI::_getAllVerionsForRandomSnodePool - ${versions.length} versions retrieved from network!:`, versions.join(',') ); } @@ -637,7 +668,7 @@ class LokiSnodeAPI { if (!seedNodes.length) { if (!window.seedNodeList || !window.seedNodeList.length) { log.error( - `loki_snodes:::refreshRandomPool - seedNodeList has not been loaded yet` + `LokiSnodeAPI:::refreshRandomPool - seedNodeList has not been loaded yet` ); return []; } @@ -664,17 +695,17 @@ class LokiSnodeAPI { pubkey_ed25519: snode.pubkey_ed25519, })); log.info( - 'loki_snodes:::refreshRandomPool - Refreshed random snode pool with', + 'LokiSnodeAPI::refreshRandomPool - Refreshed random snode pool with', this.randomSnodePool.length, 'snodes' ); // start polling versions but no need to await it this._getAllVerionsForRandomSnodePool(); } catch (e) { - log.warn('loki_snodes:::refreshRandomPool - error', e.code, e.message); + log.warn('LokiSnodeAPI::refreshRandomPool - error', e.code, e.message); /* log.error( - 'loki_snodes:::refreshRandomPoolPromise - Giving up trying to contact seed node' + 'LokiSnodeAPI:::refreshRandomPoolPromise - Giving up trying to contact seed node' ); */ if (snodes.length === 0) { @@ -693,7 +724,7 @@ class LokiSnodeAPI { const swarmNodes = [...conversation.get('swarmNodes')]; if (typeof unreachableNode === 'string') { log.warn( - 'loki_snodes:::unreachableNode - String passed as unreachableNode to unreachableNode' + 'LokiSnodeAPI::unreachableNode - String passed as unreachableNode to unreachableNode' ); return swarmNodes; } @@ -710,13 +741,13 @@ class LokiSnodeAPI { }); if (!found) { log.warn( - `loki_snodes:::unreachableNode - snode ${unreachableNode.ip}:${unreachableNode.port} has already been marked as bad` + `LokiSnodeAPI::unreachableNode - snode ${unreachableNode.ip}:${unreachableNode.port} has already been marked as bad` ); } try { await conversation.updateSwarmNodes(filteredNodes); } catch (e) { - log.error(`loki_snodes:::unreachableNode - error ${e.code} ${e.message}`); + log.error(`LokiSnodeAPI::unreachableNode - error ${e.code} ${e.message}`); throw e; } return filteredNodes; @@ -754,7 +785,7 @@ class LokiSnodeAPI { node.address ); log.debug( - `loki_snode:::getSwarmNodesForPubKey - ${j} ${node.ip}:${node.port}` + `LokiSnodeAPI::getSwarmNodesForPubKey - ${j} ${node.ip}:${node.port}` ); swarmNodes[j] = { ...node, @@ -781,7 +812,7 @@ class LokiSnodeAPI { return filteredNodes; } catch (e) { log.error( - `loki_snodes:::updateSwarmNodes - error ${e.code} ${e.message}` + `LokiSnodeAPI::updateSwarmNodes - error ${e.code} ${e.message}` ); throw new window.textsecure.ReplayableError({ message: 'Could not get conversation', @@ -794,6 +825,10 @@ class LokiSnodeAPI { async refreshSwarmNodesForPubKey(pubKey) { // FIXME: handle rejections const newNodes = await this._getFreshSwarmNodes(pubKey); + log.debug( + 'LokiSnodeAPI::refreshSwarmNodesForPubKey - newNodes', + newNodes.length + ); const filteredNodes = this.updateSwarmNodes(pubKey, newNodes); return filteredNodes; } @@ -805,7 +840,7 @@ class LokiSnodeAPI { newSwarmNodes = await this._getSwarmNodes(pubKey); } catch (e) { log.error( - 'loki_snodes:::_getFreshSwarmNodes - error', + 'LokiSnodeAPI::_getFreshSwarmNodes - error', e.code, e.message ); @@ -960,7 +995,7 @@ class LokiSnodeAPI { // get snodes for pubkey from random snode async _getSnodesForPubkey(pubKey) { - let snode = {}; + let snode = { ip: '', port: 0 }; try { snode = await this.getRandomSnodeAddress(); const result = await lokiRpc( @@ -976,7 +1011,7 @@ class LokiSnodeAPI { ); if (!result) { log.warn( - `loki_snode:::_getSnodesForPubkey - lokiRpc on ${snode.ip}:${snode.port} returned falsish value`, + `LokiSnodeAPI::_getSnodesForPubkey - lokiRpc on ${snode.ip}:${snode.port} returned falsish value`, result ); return []; @@ -984,7 +1019,7 @@ class LokiSnodeAPI { if (!result.snodes) { // we hit this when snode gives 500s log.warn( - `loki_snode:::_getSnodesForPubkey - lokiRpc on ${snode.ip}:${snode.port} returned falsish value for snodes`, + `LokiSnodeAPI::_getSnodesForPubkey - lokiRpc on ${snode.ip}:${snode.port} returned falsish value for snodes`, result ); return []; @@ -995,7 +1030,7 @@ class LokiSnodeAPI { this.markRandomNodeUnreachable(snode); const randomPoolRemainingCount = this.getRandomPoolLength(); log.error( - 'loki_snodes:::_getSnodesForPubkey - error', + 'LokiSnodeAPI::_getSnodesForPubkey - error', e.code, e.message, `for ${snode.ip}:${snode.port}. ${randomPoolRemainingCount} snodes remaining in randomPool` @@ -1010,9 +1045,14 @@ class LokiSnodeAPI { const questions = [...Array(RANDOM_SNODES_TO_USE_FOR_PUBKEY_SWARM).keys()]; // FIXME: handle rejections await Promise.all( - questions.map(async () => { + questions.map(async qNum => { // allow exceptions to pass through upwards const resList = await this._getSnodesForPubkey(pubKey); + log.info( + `LokiSnodeAPI::_getSwarmNodes - question ${qNum} got`, + resList.length, + 'snodes' + ); resList.map(item => { const hasItem = snodes.some(n => compareSnodes(n, item)); if (!hasItem) { @@ -1022,7 +1062,7 @@ class LokiSnodeAPI { }); }) ); - // should we only activate entries that are in all results? + // should we only activate entries that are in all results? yes return snodes; } }