Skip to content

Commit 1afc54a

Browse files
d4vidid4vidi
authored
Expand retry() API and improve exec() retry-logging (wix#2434)
1 parent 5467f87 commit 1afc54a

File tree

4 files changed

+106
-70
lines changed

4 files changed

+106
-70
lines changed

‎detox/src/utils/exec.js

Lines changed: 23 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -7,21 +7,23 @@ const DetoxRuntimeError = require('../errors/DetoxRuntimeError');
77

88
let _operationCounter = 0;
99

10-
async function execWithRetriesAndLogs(bin, options, statusLogs, retries = 9, interval = 1000) {
10+
async function execWithRetriesAndLogs(bin, options, statusLogs = {}, retries = 9, interval = 1000) {
1111
const trackingId = _operationCounter++;
1212
const cmd = _composeCommand(bin, options);
1313
const execTimeout = _.get(options, 'timeout', 0);
1414
const log = execLogger.child({ fn: 'execWithRetriesAndLogs', cmd, trackingId });
1515
const verbosity = _.get(options, 'verbosity', 'normal');
16-
log.debug({ event: 'EXEC_CMD' }, `${cmd}`);
1716

1817
let result;
1918
try {
20-
await retry({retries, interval}, async (retryNumber) => {
21-
if (statusLogs && statusLogs.trying) {
22-
log.debug({ event: 'EXEC_TRY', retryNumber }, statusLogs.trying);
23-
}
19+
log.debug({ event: 'EXEC_CMD' }, `${cmd}`);
2420

21+
await retry({retries, interval}, async (retryNumber, lastError) => {
22+
if (statusLogs.trying) {
23+
_logTrying(log, statusLogs.trying, retryNumber, lastError);
24+
} else if (statusLogs.retrying) {
25+
_logRetrying(log, cmd, retryNumber, lastError);
26+
}
2527
result = await exec(cmd, { timeout: execTimeout });
2628
});
2729
} catch (err) {
@@ -45,7 +47,7 @@ async function execWithRetriesAndLogs(bin, options, statusLogs, retries = 9, int
4547

4648
_logExecOutput(log, result, verbosity === 'high' ? 'debug' : 'trace');
4749

48-
if (statusLogs && statusLogs.successful) {
50+
if (statusLogs.successful) {
4951
log.debug({ event: 'EXEC_SUCCESS' }, statusLogs.successful);
5052
}
5153

@@ -88,6 +90,20 @@ function _logExecOutput(log, process, level) {
8890
}
8991
}
9092

93+
function _logTrying(log, message, retryNumber, lastError) {
94+
if (lastError && lastError.stderr) {
95+
log.trace({ event: 'EXEC_TRY_FAIL' }, lastError.stderr);
96+
}
97+
log.debug({ event: 'EXEC_TRY', retryNumber }, message);
98+
}
99+
100+
function _logRetrying(log, message, retryNumber, lastError) {
101+
if (retryNumber > 1) {
102+
log.trace({ event: 'EXEC_TRY_FAIL' }, lastError.stderr);
103+
log.debug({ event: 'EXEC_RETRY', retryNumber }, `(Retry #${retryNumber - 1})`, message);
104+
}
105+
}
106+
91107
function _composeCommand(bin, options) {
92108
if (!options) {
93109
return bin;

‎detox/src/utils/exec.test.js

Lines changed: 61 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -1,15 +1,15 @@
1-
const _ = require('lodash');
2-
31
describe('exec', () => {
42
let logger;
53
let exec;
64
let cpp;
75

86
beforeEach(() => {
97
jest.mock('./logger');
10-
jest.mock('child-process-promise');
118
logger = require('./logger');
9+
10+
jest.mock('child-process-promise');
1211
cpp = require('child-process-promise');
12+
1313
exec = require('./exec');
1414
});
1515

@@ -20,9 +20,7 @@ describe('exec', () => {
2020
});
2121

2222
it(`exec command with no arguments successfully`, async () => {
23-
const successfulResult = returnSuccessfulNoValue();
24-
const resolvedPromise = Promise.resolve(successfulResult);
25-
cpp.exec.mockReturnValueOnce(resolvedPromise);
23+
mockCppSuccessful(cpp);
2624
await exec.execWithRetriesAndLogs('bin');
2725
expect(cpp.exec).toHaveBeenCalledWith(`bin`, { timeout: 0 });
2826
});
@@ -48,17 +46,39 @@ describe('exec', () => {
4846
expect(cpp.exec).toHaveBeenCalledWith(`export MY_PREFIX && bin --argument 123`, { timeout: 0 });
4947
});
5048

51-
it(`exec command with arguments and status logs successfully`, async () => {
52-
mockCppSuccessful(cpp);
49+
it(`exec command with arguments and try-based status logs successfully, with status logging`, async () => {
50+
cpp.exec
51+
.mockRejectedValueOnce(returnErrorWithValue('error result'))
52+
.mockResolvedValueOnce(returnSuccessfulWithValue('successful result'));
53+
54+
const options = {args: `--argument 123`};
55+
const statusLogs = {
56+
trying: 'trying status log',
57+
successful: 'successful status log',
58+
};
59+
await exec.execWithRetriesAndLogs('bin', options, statusLogs);
60+
61+
expect(cpp.exec).toHaveBeenCalledWith(`bin --argument 123`, { timeout: 0 });
62+
expect(logger.debug).toHaveBeenCalledWith({ event: 'EXEC_TRY', retryNumber: 1}, statusLogs.trying);
63+
expect(logger.debug).toHaveBeenCalledWith({ event: 'EXEC_TRY', retryNumber: 2}, statusLogs.trying);
64+
expect(logger.trace).toHaveBeenCalledWith({ event: 'EXEC_TRY_FAIL' }, 'error result');
65+
});
66+
67+
it(`exec command with arguments and retry-based status logs successfully, with status logging`, async () => {
68+
cpp.exec
69+
.mockRejectedValueOnce(returnErrorWithValue('error result'))
70+
.mockResolvedValueOnce(returnSuccessfulWithValue('successful result'));
5371

5472
const options = {args: `--argument 123`};
5573
const statusLogs = {
56-
trying: `trying status log`,
57-
successful: `successful status log`
74+
retrying: true,
5875
};
5976
await exec.execWithRetriesAndLogs('bin', options, statusLogs);
6077

6178
expect(cpp.exec).toHaveBeenCalledWith(`bin --argument 123`, { timeout: 0 });
79+
expect(logger.debug).toHaveBeenCalledWith({ event: 'EXEC_RETRY', retryNumber: 2}, '(Retry #1)', 'bin --argument 123');
80+
expect(logger.debug).not.toHaveBeenCalledWith({ event: 'EXEC_RETRY', retryNumber: 1}, expect.any(String), expect.any(String));
81+
expect(logger.trace).toHaveBeenCalledWith({ event: 'EXEC_TRY_FAIL' }, 'error result');
6282
});
6383

6484
it(`exec command should output success and err logs`, async () => {
@@ -75,7 +95,7 @@ describe('exec', () => {
7595
exitCode: 0
7696
}
7797
};
78-
cpp.exec.mockReturnValueOnce(Promise.resolve(cppResult));
98+
cpp.exec.mockResolvedValueOnce(cppResult);
7999

80100
await exec.execWithRetriesAndLogs('bin');
81101

@@ -103,9 +123,7 @@ describe('exec', () => {
103123
});
104124

105125
it(`exec command and fail with error code`, async () => {
106-
const errorResult = returnErrorWithValue('error result');
107-
const rejectedPromise = Promise.reject(errorResult);
108-
cpp.exec.mockReturnValueOnce(rejectedPromise);
126+
mockCppFailure(cpp);
109127

110128
try {
111129
await exec.execWithRetriesAndLogs('bin', null, '', 0, 1);
@@ -118,9 +136,7 @@ describe('exec', () => {
118136
});
119137

120138
it(`exec command and fail with error code, report only to debug log if verbosity is low`, async () => {
121-
const errorResult = returnErrorWithValue('error result');
122-
const rejectedPromise = Promise.reject(errorResult);
123-
cpp.exec.mockReturnValueOnce(rejectedPromise);
139+
mockCppFailure(cpp);
124140

125141
try {
126142
await exec.execWithRetriesAndLogs('bin', { verbosity: 'low' }, '', 0, 1);
@@ -133,9 +149,7 @@ describe('exec', () => {
133149
});
134150

135151
it(`exec command and fail with timeout`, async () => {
136-
const errorResult = returnErrorWithValue('error result');
137-
const rejectedPromise = Promise.reject(errorResult);
138-
cpp.exec.mockReturnValueOnce(rejectedPromise);
152+
mockCppFailure(cpp);
139153

140154
try {
141155
await exec.execWithRetriesAndLogs('bin', { timeout: 1 }, '', 0, 1);
@@ -148,13 +162,14 @@ describe('exec', () => {
148162

149163
it(`exec command with multiple failures`, async () => {
150164
const errorResult = returnErrorWithValue('error result');
151-
const rejectedPromise = Promise.reject(errorResult);
152-
cpp.exec.mockReturnValueOnce(rejectedPromise)
153-
.mockReturnValueOnce(rejectedPromise)
154-
.mockReturnValueOnce(rejectedPromise)
155-
.mockReturnValueOnce(rejectedPromise)
156-
.mockReturnValueOnce(rejectedPromise)
157-
.mockReturnValueOnce(rejectedPromise);
165+
cpp.exec
166+
.mockRejectedValueOnce(errorResult)
167+
.mockRejectedValueOnce(errorResult)
168+
.mockRejectedValueOnce(errorResult)
169+
.mockRejectedValueOnce(errorResult)
170+
.mockRejectedValueOnce(errorResult)
171+
.mockRejectedValueOnce(errorResult);
172+
158173
try {
159174
await exec.execWithRetriesAndLogs('bin', null, '', 5, 1);
160175
fail('expected execWithRetriesAndLogs() to throw');
@@ -167,16 +182,15 @@ describe('exec', () => {
167182

168183
it(`exec command with multiple failures and then a success`, async () => {
169184
const errorResult = returnErrorWithValue('error result');
170-
const rejectedPromise = Promise.reject(errorResult);
171185
const successfulResult = returnSuccessfulWithValue('successful result');
172-
const resolvedPromise = Promise.resolve(successfulResult);
173186

174-
cpp.exec.mockReturnValueOnce(rejectedPromise)
175-
.mockReturnValueOnce(rejectedPromise)
176-
.mockReturnValueOnce(rejectedPromise)
177-
.mockReturnValueOnce(rejectedPromise)
178-
.mockReturnValueOnce(rejectedPromise)
179-
.mockReturnValueOnce(resolvedPromise);
187+
cpp.exec
188+
.mockRejectedValueOnce(errorResult)
189+
.mockRejectedValueOnce(errorResult)
190+
.mockRejectedValueOnce(errorResult)
191+
.mockRejectedValueOnce(errorResult)
192+
.mockRejectedValueOnce(errorResult)
193+
.mockResolvedValueOnce(successfulResult);
180194

181195
await exec.execWithRetriesAndLogs('bin', null, '', 6, 1);
182196
expect(cpp.exec).toHaveBeenCalledWith(`bin`, { timeout: 0 });
@@ -298,42 +312,36 @@ function toStream(string) {
298312
return stream;
299313
}
300314

301-
function returnSuccessfulWithValue(value) {
302-
const result = {
315+
const returnSuccessfulWithValue = (value) => ({
303316
stdout: JSON.stringify(value),
304317
stderr: "err",
305318
childProcess: {
306319
exitCode: 0
307320
}
308-
};
309-
return result;
310-
}
321+
});
311322

312-
function returnErrorWithValue(value) {
313-
const result = {
323+
const returnErrorWithValue = (value) => ({
314324
stdout: "out",
315325
stderr: value,
316326
childProcess: {
317327
exitCode: 1
318328
}
319-
};
320-
return result;
321-
}
329+
});
322330

323-
function returnSuccessfulNoValue() {
324-
const result = {
331+
const returnSuccessfulNoValue = () => ({
325332
childProcess: {
326333
exitCode: 0
327334
}
328-
};
329-
return result;
330-
}
335+
});
331336

332337
function mockCppSuccessful(cpp) {
333338
const successfulResult = returnSuccessfulWithValue('successful result');
334-
const resolvedPromise = Promise.resolve(successfulResult);
335-
cpp.exec.mockReturnValueOnce(resolvedPromise);
336-
339+
cpp.exec.mockResolvedValueOnce(successfulResult);
337340
return successfulResult;
338341
}
339342

343+
function mockCppFailure(cpp) {
344+
const errorResult = returnErrorWithValue('error result');
345+
cpp.exec.mockRejectedValueOnce(errorResult);
346+
return errorResult;
347+
}

‎detox/src/utils/retry.js

Lines changed: 12 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,17 +1,19 @@
1+
const _ = require('lodash');
12
const sleep = require('./sleep');
23

34
const DEFAULT_RETRIES = 9;
45
const DEFAULT_INTERVAL = 500;
56
const DEFAULT_CONDITION_FN = () => true;
67
const DEFAULT_BACKOFF_MODE = 'linear';
78
const backoffModes = {
8-
'linear': () => ({ interval, totalRetries }) => totalRetries * interval,
9+
'linear': () => ({ interval, totalTries }) => totalTries * interval,
910
'none': () => ({ interval }) => interval,
1011
};
1112

12-
async function retry(options, func) {
13-
if (typeof options === 'function') {
14-
func = options;
13+
async function retry(optionsOrFunc, func) {
14+
let options = optionsOrFunc;
15+
if (typeof optionsOrFunc === 'function') {
16+
func = optionsOrFunc;
1517
options = {};
1618
}
1719

@@ -24,14 +26,16 @@ async function retry(options, func) {
2426

2527
const backoffFn = backoffModes[backoff]();
2628

27-
for (let totalRetries = 1; true; totalRetries++) {
29+
for (let totalTries = 1, lastError = null; true; totalTries++) {
2830
try {
29-
return await func(totalRetries);
31+
return await func(totalTries, lastError);
3032
} catch (e) {
31-
if (!conditionFn(e) || (totalRetries > retries)) {
33+
lastError = e;
34+
35+
if (!conditionFn(e) || (totalTries > retries)) {
3236
throw e;
3337
}
34-
await sleep(backoffFn({ interval, totalRetries }));
38+
await sleep(backoffFn({ interval, totalTries }));
3539
}
3640
}
3741
}

‎detox/src/utils/retry.test.js

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7,8 +7,8 @@ describe('retry', () => {
77
.mockReturnValueOnce(Promise.reject())
88
.mockReturnValueOnce(Promise.resolve());
99
const mockFailingTwiceUserFn = () => jest.fn()
10-
.mockReturnValueOnce(Promise.reject('once'))
11-
.mockReturnValueOnce(Promise.reject('twice'))
10+
.mockReturnValueOnce(Promise.reject(new Error('once')))
11+
.mockReturnValueOnce(Promise.reject(new Error('twice')))
1212
.mockReturnValueOnce(Promise.resolve());
1313

1414
beforeEach(() => {
@@ -36,6 +36,14 @@ describe('retry', () => {
3636
expect(mockFn).toHaveBeenCalledTimes(3);
3737
});
3838

39+
it('should provide error info in each failure', async () => {
40+
const mockFn = mockFailingTwiceUserFn();
41+
await retry({retries: 999, interval: 0}, mockFn);
42+
expect(mockFn).toHaveBeenCalledWith(1, null);
43+
expect(mockFn).toHaveBeenCalledWith(2, new Error('once'));
44+
expect(mockFn).toHaveBeenCalledWith(3, new Error('twice'));
45+
});
46+
3947
it('should adhere to retries parameter', async () => {
4048
const mockFn = mockFailingUserFn();
4149
try {

0 commit comments

Comments
 (0)