From c77b620453d09d19ef2c77a7ac793f0d757d7b89 Mon Sep 17 00:00:00 2001 From: "F. Eugene Aumson" Date: Mon, 11 May 2020 12:44:01 -0400 Subject: [PATCH 1/6] asset-swapper: Improve RFQ-T logging for 0x API * Change QuoteRequestor logger parameters to conform to pino logging library, duplicating (one of) their LogFunction prototype interfaces for our purposes here. With this, every log emission now includes BOTH a human-readable message AND a JSON object. Also, this pattern has been applied to both the error logger and the info logger. * Do better handling of Axios errors when logging them. Before we were (a) logging errors in a separate log entry than the message that explains it, and (b) dumping the whole error object to the log entry, which was resulting in an object so massive that pino/Kibana was splitting it into 3 separate entries. Now, we (a) follow the pattern described in the previous bullet, which puts the error object and the human readable message into the same log entry, and (b) we check to see if an error object is Axios-specific, and if so then we use the AxiosError.toJSON() method to strip out the irrelevant properties. * Log a uniform maker response metric, with maker endpoint URL, status code, and latency, for both successful cases and erroneous ones. (Before, we were only doing this for successful cases.) --- packages/asset-swapper/src/index.ts | 1 + packages/asset-swapper/src/types.ts | 7 ++- .../src/utils/quote_requestor.ts | 58 +++++++++++-------- 3 files changed, 40 insertions(+), 26 deletions(-) diff --git a/packages/asset-swapper/src/index.ts b/packages/asset-swapper/src/index.ts index f6c4477c1d..187f8df134 100644 --- a/packages/asset-swapper/src/index.ts +++ b/packages/asset-swapper/src/index.ts @@ -41,6 +41,7 @@ export { ForwarderExtensionContractOpts, GetExtensionContractTypeOpts, LiquidityForTakerMakerAssetDataPair, + LogFunction, MarketBuySwapQuote, MarketOperation, MarketSellSwapQuote, diff --git a/packages/asset-swapper/src/types.ts b/packages/asset-swapper/src/types.ts index db3f993eec..f08de9d704 100644 --- a/packages/asset-swapper/src/types.ts +++ b/packages/asset-swapper/src/types.ts @@ -3,6 +3,7 @@ import { SignedOrder } from '@0x/types'; import { BigNumber } from '@0x/utils'; import { GetMarketOrdersOpts } from './utils/market_operation_utils/types'; +import { LogFunction } from './utils/quote_requestor'; /** * expiryBufferMs: The number of seconds to add when calculating whether an order is expired or not. Defaults to 300s (5m). @@ -216,6 +217,8 @@ export interface RfqtMakerAssetOfferings { [endpoint: string]: Array<[string, string]>; } +export { LogFunction } from './utils/quote_requestor'; + /** * chainId: The ethereum chain id. Defaults to 1 (mainnet). * orderRefreshIntervalMs: The interval in ms that getBuyQuoteAsync should trigger an refresh of orders and order states. Defaults to 10000ms (10s). @@ -234,8 +237,8 @@ export interface SwapQuoterOpts extends OrderPrunerOpts { takerApiKeyWhitelist: string[]; makerAssetOfferings: RfqtMakerAssetOfferings; skipBuyRequests?: boolean; - warningLogger?: (s: string) => void; - infoLogger?: (s: string) => void; + warningLogger?: LogFunction; + infoLogger?: LogFunction; }; } diff --git a/packages/asset-swapper/src/utils/quote_requestor.ts b/packages/asset-swapper/src/utils/quote_requestor.ts index 6eedca4a0a..413d18b22f 100644 --- a/packages/asset-swapper/src/utils/quote_requestor.ts +++ b/packages/asset-swapper/src/utils/quote_requestor.ts @@ -80,13 +80,25 @@ function hasExpectedAssetData( return hasExpectedMakerAssetData && hasExpectedTakerAssetData; } +function convertIfAxiosError(error: any): Error { + if (error.hasOwnProperty('isAxiosError') && error.isAxiosError && error.hasOwnProperty('toJSON')) { + return error.toJSON(); + } else { + return error; + } +} + +export type LogFunction = (obj: object, msg?: string, ...args: any[]) => void; + export class QuoteRequestor { private readonly _schemaValidator: SchemaValidator = new SchemaValidator(); constructor( private readonly _rfqtAssetOfferings: RfqtMakerAssetOfferings, - private readonly _warningLogger: (a: any) => void = a => logUtils.warn(a), - private readonly _infoLogger: (a: any) => void = () => undefined, + private readonly _warningLogger: LogFunction = (obj, msg) => + logUtils.warn(`${msg ? `${msg}: ` : ''}${JSON.stringify(obj)}`), + private readonly _infoLogger: LogFunction = (obj, msg) => + logUtils.log(`${msg ? `${msg}: ` : ''}${JSON.stringify(obj)}`), private readonly _expiryBufferMs: number = constants.DEFAULT_SWAP_QUOTER_OPTS.expiryBufferMs, ) {} @@ -105,8 +117,9 @@ export class QuoteRequestor { const responsesIfDefined: Array> = await Promise.all( Object.keys(this._rfqtAssetOfferings).map(async url => { if (this._makerSupportsPair(url, makerAssetData, takerAssetData)) { + let logEntry; + const timeBeforeAwait = Date.now(); try { - const timeBeforeAwait = Date.now(); const response = await Axios.get(`${url}/quote`, { headers: { '0x-api-key': _opts.apiKey }, params: { @@ -115,22 +128,25 @@ export class QuoteRequestor { }, timeout: _opts.makerEndpointMaxResponseTimeMs, }); - this._infoLogger({ - rfqtFirmQuoteMakerResponseTime: { - makerEndpoint: url, - responseTimeMs: Date.now() - timeBeforeAwait, - }, - }); + logEntry = { + statusCode: response.status, + latency: Date.now() - timeBeforeAwait, + }; return response; } catch (err) { + logEntry = { + statusCode: err.code, + latency: Date.now() - timeBeforeAwait, + }; this._warningLogger( + convertIfAxiosError(err), `Failed to get RFQ-T firm quote from market maker endpoint ${url} for API key ${ _opts.apiKey } for taker address ${_opts.takerAddress}`, ); - this._warningLogger(err); return undefined; } + this._infoLogger({ rfqtFirmQuoteMakerResponse: { ...logEntry, makerEndpoint: url } }); } return undefined; }), @@ -145,7 +161,7 @@ export class QuoteRequestor { const validatedOrdersWithStringInts = ordersWithStringInts.filter(order => { const hasValidSchema = this._schemaValidator.isValid(order, schemas.signedOrderSchema); if (!hasValidSchema) { - this._warningLogger(`Invalid RFQ-t order received, filtering out: ${JSON.stringify(order)}`); + this._warningLogger(order, 'Invalid RFQ-t order received, filtering out'); return false; } @@ -157,12 +173,12 @@ export class QuoteRequestor { order.takerAssetData.toLowerCase(), ) ) { - this._warningLogger(`Unexpected asset data in RFQ-T order, filtering out: ${JSON.stringify(order)}`); + this._warningLogger(order, 'Unexpected asset data in RFQ-T order, filtering out'); return false; } if (order.takerAddress.toLowerCase() !== _opts.takerAddress.toLowerCase()) { - this._warningLogger(`Unexpected takerAddress in RFQ-T order, filtering out: ${JSON.stringify(order)}`); + this._warningLogger(order, 'Unexpected takerAddress in RFQ-T order, filtering out'); return false; } @@ -183,7 +199,7 @@ export class QuoteRequestor { const orders = validatedOrders.filter(order => { if (orderCalculationUtils.willOrderExpire(order, this._expiryBufferMs / constants.ONE_SECOND_MS)) { - this._warningLogger(`Expiry too soon in RFQ-T order, filtering out: ${JSON.stringify(order)}`); + this._warningLogger(order, 'Expiry too soon in RFQ-T order, filtering out'); return false; } return true; @@ -226,11 +242,11 @@ export class QuoteRequestor { return response; } catch (err) { this._warningLogger( + convertIfAxiosError(err), `Failed to get RFQ-T indicative quote from market maker endpoint ${url} for API key ${ options.apiKey } for taker address ${options.takerAddress}`, ); - this._warningLogger(err); return undefined; } } @@ -246,17 +262,13 @@ export class QuoteRequestor { const validResponsesWithStringInts = responsesWithStringInts.filter(response => { if (!this._isValidRfqtIndicativeQuoteResponse(response)) { - this._warningLogger( - `Invalid RFQ-T indicative quote received, filtering out: ${JSON.stringify(response)}`, - ); + this._warningLogger(response, 'Invalid RFQ-T indicative quote received, filtering out'); return false; } if ( !hasExpectedAssetData(makerAssetData, takerAssetData, response.makerAssetData, response.takerAssetData) ) { - this._warningLogger( - `Unexpected asset data in RFQ-T indicative quote, filtering out: ${JSON.stringify(response)}`, - ); + this._warningLogger(response, 'Unexpected asset data in RFQ-T indicative quote, filtering out'); return false; } return true; @@ -273,9 +285,7 @@ export class QuoteRequestor { const responses = validResponses.filter(response => { if (this._isExpirationTooSoon(response.expirationTimeSeconds)) { - this._warningLogger( - `Expiry too soon in RFQ-T indicative quote, filtering out: ${JSON.stringify(response)}`, - ); + this._warningLogger(response, 'Expiry too soon in RFQ-T indicative quote, filtering out'); return false; } return true; From 9a7d9abe3c4e45ce80637c649926bb4ac8a3d98a Mon Sep 17 00:00:00 2001 From: "F. Eugene Aumson" Date: Mon, 11 May 2020 13:52:42 -0400 Subject: [PATCH 2/6] asset-swapper: consolidate RFQ-T usage of Axios --- .../src/utils/quote_requestor.ts | 165 +++++++++--------- 1 file changed, 81 insertions(+), 84 deletions(-) diff --git a/packages/asset-swapper/src/utils/quote_requestor.ts b/packages/asset-swapper/src/utils/quote_requestor.ts index 413d18b22f..41c29adb1d 100644 --- a/packages/asset-swapper/src/utils/quote_requestor.ts +++ b/packages/asset-swapper/src/utils/quote_requestor.ts @@ -112,52 +112,15 @@ export class QuoteRequestor { const _opts: RfqtRequestOpts = { ...constants.DEFAULT_RFQT_REQUEST_OPTS, ...options }; assertTakerAddressOrThrow(_opts.takerAddress); - // create an array of promises for quote responses, using "undefined" - // as a placeholder for failed requests. - const responsesIfDefined: Array> = await Promise.all( - Object.keys(this._rfqtAssetOfferings).map(async url => { - if (this._makerSupportsPair(url, makerAssetData, takerAssetData)) { - let logEntry; - const timeBeforeAwait = Date.now(); - try { - const response = await Axios.get(`${url}/quote`, { - headers: { '0x-api-key': _opts.apiKey }, - params: { - takerAddress: _opts.takerAddress, - ...inferQueryParams(marketOperation, makerAssetData, takerAssetData, assetFillAmount), - }, - timeout: _opts.makerEndpointMaxResponseTimeMs, - }); - logEntry = { - statusCode: response.status, - latency: Date.now() - timeBeforeAwait, - }; - return response; - } catch (err) { - logEntry = { - statusCode: err.code, - latency: Date.now() - timeBeforeAwait, - }; - this._warningLogger( - convertIfAxiosError(err), - `Failed to get RFQ-T firm quote from market maker endpoint ${url} for API key ${ - _opts.apiKey - } for taker address ${_opts.takerAddress}`, - ); - return undefined; - } - this._infoLogger({ rfqtFirmQuoteMakerResponse: { ...logEntry, makerEndpoint: url } }); - } - return undefined; - }), + const ordersWithStringInts = await this._getQuotesAsync( // not yet BigNumber + makerAssetData, + takerAssetData, + assetFillAmount, + marketOperation, + _opts, + 'firm', ); - const responses = responsesIfDefined.filter( - (respIfDefd): respIfDefd is AxiosResponse => respIfDefd !== undefined, - ); - - const ordersWithStringInts = responses.map(response => response.data); // not yet BigNumber - const validatedOrdersWithStringInts = ordersWithStringInts.filter(order => { const hasValidSchema = this._schemaValidator.isValid(order, schemas.signedOrderSchema); if (!hasValidSchema) { @@ -218,48 +181,15 @@ export class QuoteRequestor { const _opts: RfqtRequestOpts = { ...constants.DEFAULT_RFQT_REQUEST_OPTS, ...options }; assertTakerAddressOrThrow(_opts.takerAddress); - const axiosResponsesIfDefined: Array< - undefined | AxiosResponse - > = await Promise.all( - Object.keys(this._rfqtAssetOfferings).map(async url => { - if (this._makerSupportsPair(url, makerAssetData, takerAssetData)) { - try { - const timeBeforeAwait = Date.now(); - const response = await Axios.get(`${url}/price`, { - headers: { '0x-api-key': options.apiKey }, - params: { - takerAddress: options.takerAddress, - ...inferQueryParams(marketOperation, makerAssetData, takerAssetData, assetFillAmount), - }, - timeout: options.makerEndpointMaxResponseTimeMs, - }); - this._infoLogger({ - rfqtIndicativeQuoteMakerResponseTime: { - makerEndpoint: url, - responseTimeMs: Date.now() - timeBeforeAwait, - }, - }); - return response; - } catch (err) { - this._warningLogger( - convertIfAxiosError(err), - `Failed to get RFQ-T indicative quote from market maker endpoint ${url} for API key ${ - options.apiKey - } for taker address ${options.takerAddress}`, - ); - return undefined; - } - } - return undefined; - }), + const responsesWithStringInts = await this._getQuotesAsync( // not yet BigNumber + makerAssetData, + takerAssetData, + assetFillAmount, + marketOperation, + _opts, + 'indicative', ); - const axiosResponses = axiosResponsesIfDefined.filter( - (respIfDefd): respIfDefd is AxiosResponse => respIfDefd !== undefined, - ); - - const responsesWithStringInts = axiosResponses.map(response => response.data); // not yet BigNumber - const validResponsesWithStringInts = responsesWithStringInts.filter(response => { if (!this._isValidRfqtIndicativeQuoteResponse(response)) { this._warningLogger(response, 'Invalid RFQ-T indicative quote received, filtering out'); @@ -341,4 +271,71 @@ export class QuoteRequestor { const currentTimeMs = new BigNumber(Date.now()); return expirationTimeMs.isLessThan(currentTimeMs.plus(this._expiryBufferMs)); } + + private async _getQuotesAsync( + makerAssetData: string, + takerAssetData: string, + assetFillAmount: BigNumber, + marketOperation: MarketOperation, + options: RfqtRequestOpts, + quoteType: 'firm' | 'indicative', + ): Promise { + // create an array of promises for quote responses, using "undefined" + // as a placeholder for failed requests. + const responsesIfDefined: Array> = await Promise.all( + Object.keys(this._rfqtAssetOfferings).map(async url => { + if (this._makerSupportsPair(url, makerAssetData, takerAssetData)) { + let logEntry; + const timeBeforeAwait = Date.now(); + try { + const quotePath = (() => { + switch (quoteType) { + case 'firm': + return 'quote'; + break; + case 'indicative': + return 'price'; + break; + default: + throw new Error(`Unexpected quote type ${quoteType}`); + } + })(); + const response = await Axios.get(`${url}/${quotePath}`, { + headers: { '0x-api-key': options.apiKey }, + params: { + takerAddress: options.takerAddress, + ...inferQueryParams(marketOperation, makerAssetData, takerAssetData, assetFillAmount), + }, + timeout: options.makerEndpointMaxResponseTimeMs, + }); + logEntry = { + statusCode: response.status, + latency: Date.now() - timeBeforeAwait, + }; + return response; + } catch (err) { + logEntry = { + statusCode: err.code, + latency: Date.now() - timeBeforeAwait, + }; + this._warningLogger( + convertIfAxiosError(err), + `Failed to get RFQ-T ${quoteType} quote from market maker endpoint ${url} for API key ${ + options.apiKey + } for taker address ${options.takerAddress}`, + ); + return undefined; + } + this._infoLogger({ rfqtMakerResponse: { ...logEntry, makerEndpoint: url, quoteType } }); + } + return undefined; + }), + ); + + const responses = responsesIfDefined.filter( + (respIfDefd): respIfDefd is AxiosResponse => respIfDefd !== undefined, + ); + + return responses.map(response => response.data); + } } From b95cec9c3243ac8843c04b2f483fbb04f3c62b1b Mon Sep 17 00:00:00 2001 From: "F. Eugene Aumson" Date: Mon, 11 May 2020 17:39:30 -0400 Subject: [PATCH 3/6] asset-swapper: fix bug: RFQ-T info log was broken --- .../src/utils/quote_requestor.ts | 28 ++++++++++++------- 1 file changed, 18 insertions(+), 10 deletions(-) diff --git a/packages/asset-swapper/src/utils/quote_requestor.ts b/packages/asset-swapper/src/utils/quote_requestor.ts index 41c29adb1d..7e47d0b6a6 100644 --- a/packages/asset-swapper/src/utils/quote_requestor.ts +++ b/packages/asset-swapper/src/utils/quote_requestor.ts @@ -285,7 +285,10 @@ export class QuoteRequestor { const responsesIfDefined: Array> = await Promise.all( Object.keys(this._rfqtAssetOfferings).map(async url => { if (this._makerSupportsPair(url, makerAssetData, takerAssetData)) { - let logEntry; + const partialLogEntry = { + makerEndpoint: url, + quoteType, + }; const timeBeforeAwait = Date.now(); try { const quotePath = (() => { @@ -308,16 +311,22 @@ export class QuoteRequestor { }, timeout: options.makerEndpointMaxResponseTimeMs, }); - logEntry = { - statusCode: response.status, - latency: Date.now() - timeBeforeAwait, - }; + this._infoLogger({ + rfqtMakerResponse: { + ...partialLogEntry, + statusCode: response.status, + latency: Date.now() - timeBeforeAwait, + }, + }); return response; } catch (err) { - logEntry = { - statusCode: err.code, - latency: Date.now() - timeBeforeAwait, - }; + this._infoLogger({ + rfqtMakerResponse: { + ...partialLogEntry, + statusCode: err.code, + latency: Date.now() - timeBeforeAwait, + }, + }); this._warningLogger( convertIfAxiosError(err), `Failed to get RFQ-T ${quoteType} quote from market maker endpoint ${url} for API key ${ @@ -326,7 +335,6 @@ export class QuoteRequestor { ); return undefined; } - this._infoLogger({ rfqtMakerResponse: { ...logEntry, makerEndpoint: url, quoteType } }); } return undefined; }), From a43c7e36f85521c1b246e2a867bf97e28e3f3c6f Mon Sep 17 00:00:00 2001 From: "F. Eugene Aumson" Date: Mon, 11 May 2020 17:40:19 -0400 Subject: [PATCH 4/6] asset-swapper/RFQT: log maker response metadata --- packages/asset-swapper/src/utils/quote_requestor.ts | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/packages/asset-swapper/src/utils/quote_requestor.ts b/packages/asset-swapper/src/utils/quote_requestor.ts index 7e47d0b6a6..5016b57aa3 100644 --- a/packages/asset-swapper/src/utils/quote_requestor.ts +++ b/packages/asset-swapper/src/utils/quote_requestor.ts @@ -287,6 +287,10 @@ export class QuoteRequestor { if (this._makerSupportsPair(url, makerAssetData, takerAssetData)) { const partialLogEntry = { makerEndpoint: url, + makerAssetData, + takerAssetData, + assetFillAmount, + marketOperation, quoteType, }; const timeBeforeAwait = Date.now(); From c929782e0d087f2051e673d20c672478807b8dcd Mon Sep 17 00:00:00 2001 From: "F. Eugene Aumson" Date: Mon, 11 May 2020 18:01:06 -0400 Subject: [PATCH 5/6] asset-swapper/RFQT: Log params sent to maker * Include in RFQ-T info log entry the query parameters that were sent to the maker. * Re-organize log entry * Rename top-level field from rfqtMakerResponse to rfqtMakerInteraction. * Create separate `request` and `response` sub-objects. * Rename field `latency` to `latencyMs`. --- .../src/utils/quote_requestor.ts | 32 +++++++++---------- 1 file changed, 15 insertions(+), 17 deletions(-) diff --git a/packages/asset-swapper/src/utils/quote_requestor.ts b/packages/asset-swapper/src/utils/quote_requestor.ts index 5016b57aa3..630f5838a5 100644 --- a/packages/asset-swapper/src/utils/quote_requestor.ts +++ b/packages/asset-swapper/src/utils/quote_requestor.ts @@ -285,14 +285,11 @@ export class QuoteRequestor { const responsesIfDefined: Array> = await Promise.all( Object.keys(this._rfqtAssetOfferings).map(async url => { if (this._makerSupportsPair(url, makerAssetData, takerAssetData)) { - const partialLogEntry = { - makerEndpoint: url, - makerAssetData, - takerAssetData, - assetFillAmount, - marketOperation, - quoteType, + const requestParams = { + takerAddress: options.takerAddress, + ...inferQueryParams(marketOperation, makerAssetData, takerAssetData, assetFillAmount), }; + const partialLogEntry = { url, quoteType, requestParams }; const timeBeforeAwait = Date.now(); try { const quotePath = (() => { @@ -309,26 +306,27 @@ export class QuoteRequestor { })(); const response = await Axios.get(`${url}/${quotePath}`, { headers: { '0x-api-key': options.apiKey }, - params: { - takerAddress: options.takerAddress, - ...inferQueryParams(marketOperation, makerAssetData, takerAssetData, assetFillAmount), - }, + params: requestParams, timeout: options.makerEndpointMaxResponseTimeMs, }); this._infoLogger({ - rfqtMakerResponse: { + rfqtMakerInteraction: { ...partialLogEntry, - statusCode: response.status, - latency: Date.now() - timeBeforeAwait, + response: { + statusCode: response.status, + latencyMs: Date.now() - timeBeforeAwait, + }, }, }); return response; } catch (err) { this._infoLogger({ - rfqtMakerResponse: { + rfqtMakerInteraction: { ...partialLogEntry, - statusCode: err.code, - latency: Date.now() - timeBeforeAwait, + response: { + statusCode: err.code, + latencyMs: Date.now() - timeBeforeAwait, + }, }, }); this._warningLogger( From dede076835fbc48dd1a5ab7f65446f2e0d105b75 Mon Sep 17 00:00:00 2001 From: "F. Eugene Aumson" Date: Mon, 11 May 2020 18:34:32 -0400 Subject: [PATCH 6/6] asset-s/QuoteRequestor: clarify axios error type Addresses review comment https://github.com/0xProject/0x-monorepo/pull/2581#discussion_r423337773 --- packages/asset-swapper/src/utils/quote_requestor.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/asset-swapper/src/utils/quote_requestor.ts b/packages/asset-swapper/src/utils/quote_requestor.ts index 630f5838a5..d1ccbc588d 100644 --- a/packages/asset-swapper/src/utils/quote_requestor.ts +++ b/packages/asset-swapper/src/utils/quote_requestor.ts @@ -80,7 +80,7 @@ function hasExpectedAssetData( return hasExpectedMakerAssetData && hasExpectedTakerAssetData; } -function convertIfAxiosError(error: any): Error { +function convertIfAxiosError(error: any): Error | object /* axios' .d.ts has AxiosError.toJSON() returning object */ { if (error.hasOwnProperty('isAxiosError') && error.isAxiosError && error.hasOwnProperty('toJSON')) { return error.toJSON(); } else {