1 | const sinon = require('sinon');
|
2 | const nock = require('nock');
|
3 | const assert = require('assert');
|
4 | const moment = require('moment');
|
5 | const zlib = require('zlib');
|
6 | const logzioLogger = require('../lib/logzio-nodejs.js');
|
7 | const hrtimemock = require('hrtimemock');
|
8 | const axiosInstance = require('../lib/axiosInstance.js');
|
9 | axiosInstance.defaults.adapter = require('axios/lib/adapters/http');
|
10 |
|
11 |
|
12 | const dummyHost = 'logz.io';
|
13 | const nockHttpAddress = `http://${dummyHost}:8070`;
|
14 |
|
15 | const createLogger = function createLogger(options) {
|
16 | const myOptions = options;
|
17 | myOptions.token = 'testToken';
|
18 | myOptions.type = 'test-node';
|
19 | myOptions.debug = true;
|
20 | myOptions.host = dummyHost;
|
21 | myOptions.sendIntervalMs = options.sendIntervalMs || 1000;
|
22 | return logzioLogger.createLogger(myOptions);
|
23 | };
|
24 |
|
25 | const sendLogs = (logger, count = 1, message = 'hello there from test') => {
|
26 | Array(count).fill().forEach((item, i) => {
|
27 | logger.log({
|
28 | message: `${message} #${i}`,
|
29 | id: i,
|
30 | });
|
31 | });
|
32 | };
|
33 | describe('logger', () => {
|
34 | describe('logs a single line', () => {
|
35 | beforeAll((done) => {
|
36 | sinon
|
37 | .stub(axiosInstance, 'post')
|
38 | .resolves({
|
39 | statusCode: 200,
|
40 | });
|
41 | done();
|
42 | });
|
43 |
|
44 | afterAll((done) => {
|
45 | axiosInstance.post.restore();
|
46 | done();
|
47 | });
|
48 |
|
49 | it('sends log as a string', (done) => {
|
50 | const logger = createLogger({
|
51 | bufferSize: 1,
|
52 | callback: done,
|
53 | });
|
54 | sinon.spy(logger, '_createBulk');
|
55 |
|
56 | const logMsg = 'hello there from test';
|
57 | logger.log(logMsg);
|
58 | assert.equal(logger._createBulk.getCall(0).args[0][0].message, logMsg);
|
59 | logger._createBulk.restore();
|
60 | logger.close();
|
61 | });
|
62 |
|
63 | it('sends log without user-agent header', (done) => {
|
64 | const logger = createLogger({
|
65 | bufferSize: 1,
|
66 | callback: onDone,
|
67 | setUserAgent:false
|
68 | });
|
69 | sinon.spy(logger, '_tryToSend');
|
70 |
|
71 | const logMsg = 'hello there from test';
|
72 | logger.log(logMsg);
|
73 |
|
74 | function onDone() {
|
75 | assert.equal(axiosInstance.defaults.headers.common['user-agent'], undefined);
|
76 | logger._tryToSend.restore();
|
77 | logger.close();
|
78 | done();
|
79 | }
|
80 | });
|
81 |
|
82 | it('should send a log with an object as additional param', (done) => {
|
83 | const logger = createLogger({
|
84 | bufferSize: 1,
|
85 | callback: done,
|
86 | });
|
87 | sinon.spy(logger, '_createBulk');
|
88 | const obj = { key1: "val1", key2: "val2"};
|
89 | const strMsg = 'message: ';
|
90 | const expectedLog = strMsg + JSON.stringify(obj);
|
91 | logger.log(strMsg, obj);
|
92 |
|
93 | assert.equal(logger._createBulk.getCall(0).args[0][0].message, expectedLog);
|
94 | logger._createBulk.restore();
|
95 | logger.close();
|
96 | });
|
97 |
|
98 | it('sends log as a string with extra fields', (done) => {
|
99 | const logger = createLogger({
|
100 | bufferSize: 1,
|
101 | callback: done,
|
102 | extraFields: {
|
103 | extraField1: 'val1',
|
104 | extraField2: 'val2',
|
105 | },
|
106 | });
|
107 | sinon.spy(logger, '_createBulk');
|
108 |
|
109 | const logMsg = 'hello there from test';
|
110 | logger.log(logMsg);
|
111 | assert.equal(logger._createBulk.getCall(0).args[0][0].extraField1, 'val1');
|
112 | assert.equal(logger._createBulk.getCall(0).args[0][0].extraField2, 'val2');
|
113 |
|
114 | logger._createBulk.restore();
|
115 | logger.close();
|
116 | });
|
117 |
|
118 | it('sends log as an object', (done) => {
|
119 | const logger = createLogger({
|
120 | bufferSize: 1,
|
121 | callback: done,
|
122 | });
|
123 | sinon.spy(logger, '_createBulk');
|
124 |
|
125 | const logMsg = {
|
126 | message: 'hello there from test',
|
127 | };
|
128 | logger.log(logMsg);
|
129 | assert.equal(logger._createBulk.getCall(0).args[0][0].message, logMsg.message);
|
130 |
|
131 | logger._createBulk.restore();
|
132 | logger.close();
|
133 | });
|
134 |
|
135 | it('sends log as an object with extra fields', (done) => {
|
136 | const logger = createLogger({
|
137 | bufferSize: 1,
|
138 | callback: done,
|
139 | extraFields: {
|
140 | extraField1: 'val1',
|
141 | extraField2: 'val2',
|
142 | },
|
143 | });
|
144 | sinon.spy(logger, '_createBulk');
|
145 |
|
146 | const logMsg = {
|
147 | message: 'hello there from test',
|
148 | };
|
149 | logger.log(logMsg);
|
150 | assert.equal(logger._createBulk.getCall(0).args[0][0].extraField1, 'val1');
|
151 | assert.equal(logger._createBulk.getCall(0).args[0][0].extraField2, 'val2');
|
152 |
|
153 | logger._createBulk.restore();
|
154 | logger.close();
|
155 | });
|
156 |
|
157 | it('sends compressed log as an object with extra fields', (done) => {
|
158 | const extraField1 = 'val1';
|
159 | const extraField2 = 'val2';
|
160 | const logger = createLogger({
|
161 | bufferSize: 1,
|
162 | callback: onDone,
|
163 | extraFields: {
|
164 | extraField1,
|
165 | extraField2,
|
166 | },
|
167 | compress: true,
|
168 | });
|
169 |
|
170 | sinon.spy(logger, '_tryToSend');
|
171 | const logMsg = {
|
172 | message: 'hello there from test',
|
173 | };
|
174 |
|
175 | logger.log(logMsg);
|
176 |
|
177 | function onDone() {
|
178 | assert.equal(axiosInstance.defaults.headers.post['content-encoding'], 'gzip');
|
179 | const unzipBody = JSON.parse(zlib.gunzipSync(logger._tryToSend.getCall(0).args[0]));
|
180 | assert.equal(unzipBody.message, logMsg.message);
|
181 | assert.equal(unzipBody.extraField1, extraField1);
|
182 | assert.equal(unzipBody.extraField2, extraField2);
|
183 | logger._tryToSend.restore();
|
184 | logger.close();
|
185 | done();
|
186 | }
|
187 | });
|
188 |
|
189 | it('sends log as an object with type', (done) => {
|
190 | const logger = createLogger({
|
191 | bufferSize: 1,
|
192 | callback: done,
|
193 | });
|
194 | sinon.spy(logger, '_createBulk');
|
195 |
|
196 | const logMsg = {
|
197 | message: 'hello there from test',
|
198 | type: 'myTestType',
|
199 | };
|
200 |
|
201 | logger.log(logMsg);
|
202 | assert.equal(logger._createBulk.getCall(0).args[0][0].message, logMsg.message);
|
203 | assert.equal(logger._createBulk.getCall(0).args[0][0].type, logMsg.type);
|
204 |
|
205 | logger._createBulk.restore();
|
206 | logger.close();
|
207 | });
|
208 |
|
209 | it('should not include nano timestamp by default', (done) => {
|
210 | let logger = createLogger({
|
211 | bufferSize: 1,
|
212 | callback: done
|
213 | });
|
214 | sinon.spy(logger, '_createBulk');
|
215 |
|
216 | logger.log({
|
217 | message: 'hello there from test',
|
218 | });
|
219 | assert.equal(logger._createBulk.getCall(0).args[0][0].hasOwnProperty('@timestamp_nano_secs'), false);
|
220 |
|
221 | logger._createBulk.restore();
|
222 | logger.close();
|
223 | });
|
224 |
|
225 | it('should add a valid nano-sec timestamp to the log', (done) => {
|
226 | var mockTime = 0.123456;
|
227 | var expectedLogTime = '000123456';
|
228 |
|
229 | logger = createLogger({
|
230 | bufferSize: 1,
|
231 | callback: done,
|
232 | addTimestampWithNanoSecs: true,
|
233 | });
|
234 | sinon.spy(logger, '_createBulk');
|
235 | hrtimemock(mockTime);
|
236 | process.hrtime();
|
237 | logger.log({
|
238 | message: 'hello there from test'
|
239 | })
|
240 | const mockLogCall = logger._createBulk.getCall(0).args[0][0];
|
241 | assert.equal(mockLogCall['@timestamp_nano'].endsWith(expectedLogTime), true);
|
242 |
|
243 | logger._createBulk.restore();
|
244 | logger.close();
|
245 | });
|
246 |
|
247 | it('writes a log message without @timestamp', (done) => {
|
248 | const logger = createLogger({
|
249 |
|
250 | bufferSize: 2,
|
251 | callback: done,
|
252 | });
|
253 |
|
254 | const fakeTime = moment('2011-09-01').valueOf();
|
255 |
|
256 |
|
257 | const clock = sinon.useFakeTimers(fakeTime);
|
258 | logger.log({
|
259 | message: 'hello there from test',
|
260 | });
|
261 | clock.restore();
|
262 |
|
263 | assert.equal(fakeTime, moment(logger.messages[logger.messages.length - 1]['@timestamp'].valueOf()));
|
264 | logger.close();
|
265 | });
|
266 |
|
267 | it('writes a log message with a custom @timestamp', (done) => {
|
268 | const logger = createLogger({
|
269 |
|
270 | bufferSize: 2,
|
271 | callback: done,
|
272 | });
|
273 |
|
274 | const fakeTime = moment('2011-09-01');
|
275 |
|
276 | logger.log({
|
277 | message: 'hello there from test',
|
278 | '@timestamp': fakeTime.format(),
|
279 | });
|
280 |
|
281 | assert.equal(fakeTime.format(), logger.messages[logger.messages.length - 1]['@timestamp']);
|
282 | logger.close();
|
283 | });
|
284 | });
|
285 |
|
286 | describe('logs multiple lines', () => {
|
287 | beforeAll((done) => {
|
288 | sinon
|
289 | .stub(axiosInstance, 'post')
|
290 | .resolves({
|
291 | statusCode: 200,
|
292 | });
|
293 | done();
|
294 | });
|
295 |
|
296 | afterAll((done) => {
|
297 | axiosInstance.post.restore();
|
298 | done();
|
299 | });
|
300 |
|
301 | it('Send multiple lines', (done) => {
|
302 | const logger = createLogger({
|
303 | bufferSize: 3,
|
304 | callback: done,
|
305 | });
|
306 |
|
307 | sendLogs(logger, 3);
|
308 |
|
309 | logger.close();
|
310 | });
|
311 |
|
312 | it('Send multiple bulks', (done) => {
|
313 | let timesCalled = 0;
|
314 | const bufferSize = 3;
|
315 | const logCount = 6;
|
316 | const expectedTimes = logCount / bufferSize;
|
317 |
|
318 | function assertCalled() {
|
319 | timesCalled += 1;
|
320 |
|
321 | if (expectedTimes === timesCalled) {
|
322 | done();
|
323 | } else if (timesCalled > expectedTimes) {
|
324 | throw new Error('called more than expected');
|
325 | }
|
326 | }
|
327 |
|
328 | const logger = createLogger({
|
329 | bufferSize,
|
330 | callback: assertCalled,
|
331 | });
|
332 |
|
333 | sendLogs(logger, logCount);
|
334 |
|
335 | logger.close();
|
336 | });
|
337 | });
|
338 |
|
339 | describe('#log-closing', () => {
|
340 | beforeAll((done) => {
|
341 | sinon
|
342 | .stub(axiosInstance, 'post')
|
343 | .resolves({
|
344 | statusCode: 200,
|
345 | });
|
346 | done();
|
347 | });
|
348 |
|
349 | afterAll((done) => {
|
350 | axiosInstance.post.restore();
|
351 | done();
|
352 | });
|
353 |
|
354 | it('Don\'t allow logs after closing', (done) => {
|
355 | const logger = createLogger({
|
356 | bufferSize: 1,
|
357 | });
|
358 | logger.close();
|
359 | try {
|
360 | logger.log({
|
361 | messge: 'hello there from test',
|
362 | });
|
363 | done('Expected an error when logging into a closed log!');
|
364 | } catch (ex) {
|
365 | done();
|
366 | }
|
367 | });
|
368 | });
|
369 |
|
370 | describe('timers', () => {
|
371 | beforeAll((done) => {
|
372 | sinon
|
373 | .stub(axiosInstance, 'post')
|
374 | .resolves({
|
375 | statusCode: 200,
|
376 | });
|
377 | done();
|
378 | });
|
379 |
|
380 | afterAll((done) => {
|
381 | axiosInstance.post.restore();
|
382 | done();
|
383 | });
|
384 |
|
385 | it('timer send test', (done) => {
|
386 | const bufferSize = 100;
|
387 | let timesCalled = 0;
|
388 | const expectedTimes = 2;
|
389 |
|
390 | function assertCalled() {
|
391 | timesCalled += 1;
|
392 | if (expectedTimes === timesCalled) done();
|
393 | }
|
394 |
|
395 | const logger = createLogger({
|
396 | bufferSize,
|
397 | callback: assertCalled,
|
398 | sendIntervalMs: 10,
|
399 | });
|
400 |
|
401 |
|
402 | sendLogs(logger, 3);
|
403 |
|
404 |
|
405 | setTimeout(() => {
|
406 | sendLogs(logger, bufferSize);
|
407 | logger.close();
|
408 | }, 30);
|
409 | }, 5000);
|
410 | });
|
411 |
|
412 | describe('recovers after server fails one time', () => {
|
413 | let errorAndThenSuccessScope;
|
414 | let extraRequestScope;
|
415 | const socketDelay = 20;
|
416 |
|
417 | beforeAll((done) => {
|
418 | nock.cleanAll();
|
419 | errorAndThenSuccessScope = nock(nockHttpAddress)
|
420 | .post('/')
|
421 | .socketDelay(socketDelay)
|
422 | .query(true)
|
423 | .once()
|
424 | .reply(200, '')
|
425 |
|
426 |
|
427 | .post('/')
|
428 | .socketDelay(0)
|
429 | .query(true)
|
430 | .once()
|
431 | .reply(200, '');
|
432 |
|
433 | extraRequestScope = nock(nockHttpAddress)
|
434 | .filteringPath(() => '/')
|
435 | .post('/')
|
436 | .once()
|
437 | .reply(200, '');
|
438 |
|
439 | done();
|
440 | });
|
441 |
|
442 | afterAll((done) => {
|
443 | nock.restore();
|
444 | nock.cleanAll();
|
445 | done();
|
446 | });
|
447 |
|
448 | it('Msgs are only sent once', (done) => {
|
449 |
|
450 |
|
451 | const logger = createLogger({
|
452 | bufferSize: 1,
|
453 | sendIntervalMs: 50000,
|
454 | timeout: socketDelay / 2,
|
455 | sleepUntilNextRetry: socketDelay * 2,
|
456 | });
|
457 |
|
458 | sendLogs(logger);
|
459 | logger.close();
|
460 |
|
461 | setTimeout(() => {
|
462 | if (!errorAndThenSuccessScope.isDone()) {
|
463 | done(new Error(`pending mocks: ${errorAndThenSuccessScope.pendingMocks()}`));
|
464 | } else if (extraRequestScope.isDone()) {
|
465 | done(new Error('We don\'t expect another request'));
|
466 | } else {
|
467 | done();
|
468 | }
|
469 | }, socketDelay * 5);
|
470 | }, 10000);
|
471 | });
|
472 |
|
473 | describe('bad request', () => {
|
474 | afterEach((done) => {
|
475 | axiosInstance.post.restore();
|
476 | done();
|
477 | });
|
478 |
|
479 | it('bad request with code', (done) => {
|
480 | sinon
|
481 | .stub(axiosInstance, 'post')
|
482 | .rejects({
|
483 | statusCode: 400,
|
484 | cause: { code: 'BAD_REQUEST' },
|
485 | messge: 'bad',
|
486 | });
|
487 |
|
488 | const logger = createLogger({
|
489 | bufferSize: 3,
|
490 | callback(err) {
|
491 | if (err) {
|
492 | done();
|
493 | return;
|
494 | }
|
495 |
|
496 | done(new Error('Expected an error'));
|
497 | },
|
498 | });
|
499 |
|
500 | sendLogs(logger, 3);
|
501 |
|
502 | logger.close();
|
503 | });
|
504 |
|
505 | it('bad request with no cause nor code', (done) => {
|
506 | sinon
|
507 | .stub(axiosInstance, 'post')
|
508 | .rejects({
|
509 | statusCode: 400,
|
510 | message: 'bad',
|
511 | });
|
512 |
|
513 | const logger = createLogger({
|
514 | bufferSize: 3,
|
515 | callback(err) {
|
516 | if (err) {
|
517 | done();
|
518 | return;
|
519 | }
|
520 |
|
521 | done(new Error('Expected an error'));
|
522 | },
|
523 | });
|
524 |
|
525 | sendLogs(logger, 3);
|
526 |
|
527 | logger.close();
|
528 | });
|
529 | });
|
530 |
|
531 | describe('Logger callback', () => {
|
532 | it('should execute external logger', (done) => {
|
533 | const internalLogger = {
|
534 | log: () => {
|
535 | done();
|
536 | },
|
537 | };
|
538 |
|
539 | const logger = createLogger({
|
540 | bufferSize: 1,
|
541 | internalLogger,
|
542 | });
|
543 |
|
544 | sendLogs(logger);
|
545 | logger.close();
|
546 | });
|
547 | });
|
548 | });
|