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.)
This commit is contained in:
F. Eugene Aumson
2020-05-11 12:44:01 -04:00
parent b348084e2a
commit c77b620453
3 changed files with 40 additions and 26 deletions

View File

@@ -41,6 +41,7 @@ export {
ForwarderExtensionContractOpts,
GetExtensionContractTypeOpts,
LiquidityForTakerMakerAssetDataPair,
LogFunction,
MarketBuySwapQuote,
MarketOperation,
MarketSellSwapQuote,

View File

@@ -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;
};
}

View File

@@ -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<undefined | AxiosResponse<SignedOrder>> = 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<SignedOrder>(`${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;