Daily Rotation sometimes happens twice #47
Comments
|
Hi @davesidwell , can you provide me the name of rotated files in order to understand how many midnight(s) those machines have each day? Thank you, |
|
Hi Daniele,
Here is an example (I am on EST so it is rotating at UCT+5)
…-rw-r--r-- 1 root root 630037 Jan 22 23:59 device.deadbeefcafe__EVAManager-3.0.1__2020-01-23__04.59.59__Thu_file-1.log.gz
-rw-r--r-- 1 root root 251 Jan 23 00:00 device.deadbeefcafe__EVAManager-3.0.1__2020-01-23__05.00.00__Thu_file-2.log.gz
Thanks,
Dave
_______________________________________________
Dave Sidwell | NEC Enterprise Communication Technologies | Senior Manager - SW Development
700 West Johnson Ave. Ste. 309 | Cheshire, CT 06410 | • (O) (203) 718-6263 | • (M) (203) 513-1677 | • [email protected]<mailto:[email protected]>
From: Daniele Ricci <[email protected]>
Sent: Thursday, January 23, 2020 11:58 AM
To: iccicci/rotating-file-stream <[email protected]>
Cc: Sidwell, David <[email protected]>; Mention <[email protected]>
Subject: Re: [iccicci/rotating-file-stream] Daily Rotation sometimes happens twice (#47)
Reminder: Please be cautious with external links and attachments.
Hi @davesidwell<https://github.com/davesidwell> ,
can you provide me the name of rotated files in order to understand how many midnight(s) those machines have each day?
Thank you,
iCC
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub<#47?email_source=notifications&email_token=ACNSFWM2YGEBDUSDN62RMFTQ7HD77A5CNFSM4KKHSC62YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJYBVRQ#issuecomment-577772230>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/ACNSFWKKLMSVUIMDPSVH56TQ7HD77ANCNFSM4KKHSC6Q>.
|
|
Hi @davesidwell , can I also see the piece of code initializing RotatingFileStream please? Thank you, |
|
Hi Daniele,
As requested:
// Instantiate a new RFS
rfsStream = rfs.createStream(logFileNameGenerator, {
interval: '1d', // rotate daily
path: logSettings.logFilePath,
size: logSettings.logFileMaxSize,
compress: logSettings.logFilesCompress ? 'gzip' : null, // compress rotated files
maxFiles: logSettings.logMaxFilesToKeep, // max number of rotated files to keep
maxSize: logSettings.logMaxSizeToKeep // max size of rotated files to keep
});
Where logSettings is set to:
{
"logFilePath": "/var/log/vict/",
"logFileMaxSize": "10M",
"logMaxFilesToKeep": 30,
"logMaxSizeToKeep": "100M",
"logFilesCompress": true
}
…_______________________________________________
Dave Sidwell | NEC Enterprise Communication Technologies | Senior Manager - SW Development
700 West Johnson Ave. Ste. 309 | Cheshire, CT 06410 | • (O) (203) 718-6263 | • (M) (203) 513-1677 | • [email protected]<mailto:[email protected]>
From: Daniele Ricci <[email protected]>
Sent: Friday, January 24, 2020 3:39 AM
To: iccicci/rotating-file-stream <[email protected]>
Cc: Sidwell, David <[email protected]>; Mention <[email protected]>
Subject: Re: [iccicci/rotating-file-stream] Daily Rotation sometimes happens twice (#47)
Reminder: Please be cautious with external links and attachments.
Hi @davesidwell<https://github.com/davesidwell> ,
can I also see the piece of code initializing RotatingFileStream please?
Thank you,
iCC
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub<#47?email_source=notifications&email_token=ACNSFWN26DYHQZTEKL3XYMDQ7KSLXA5CNFSM4KKHSC62YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ2DFIA#issuecomment-578040480>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/ACNSFWLHC3OXT5DHE3RB5B3Q7KSLXANCNFSM4KKHSC6Q>.
|
|
Hi Daniele,
I believe replacing the “interval” code with the following will correct this issue:
interval() {
if (!this.options.interval)
return;
this.intervalBounds(this.now());
const set = () => {
const time = this.next - this.now().getTime();
if (time > 0) {
this.timer = timers_1.setTimeout(set, time > this.maxTimeout ? this.maxTimeout : time);
this.timer.unref();
}
else
this.rotate(error => (this.error = error));
};
set();
}
In this code, if the target time has not yet been reached, the timeout will be restarted with whatever time remains.
At the same time, while doing some additional testing I uncovered a more serious error that occurs when the interval timer expires.
The rotating-file-stream code can crash if writes are queued up when the asynchronous interval timer causes the rotate to occur.
Within the “rewrite” function:
if (this.stream) {
return this.fsStat(this.filename, (error) => {
if (!error)
return rewrite();
if (error.code !== "ENOENT")
return destroy(error);
this.reclose(() => this.reopen(false, 0, () => rewrite()));
});
}
The “rotate” function calls “reclose” which then sets “this.stream” to null.
If this occurs after the call to “fsStat” above, but before the callback is executed, a crash occurs. An example of it occurring is as follows (this was generated by forcing a rotation to occur):
2020-01-24 18:35:34.195, info, CloudAdapter.js, UploadFile - queue length: 18
/opt/NEC/CloudAdapter/node_modules/rotating-file-stream/index.js:87
this.stream.write(chunk.chunk, chunk.encoding, (error) => {
^
TypeError: Cannot read property 'write' of null
at rewrite (/opt/NEC/CloudAdapter/node_modules/rotating-file-stream/index.js:87:25)
at fsStat (/opt/NEC/CloudAdapter/node_modules/rotating-file-stream/index.js:103:28)
at FSReqWrap.oncomplete (fs.js:154:5)
An example of this occurring at the actual rotation time (also shows rotation at 04:59:59) is also provided:
2020-01-23 04:59:59.881, debug, CloudAdapter.js, Adding /var/log/vict/device.deadbeefcafe__EVAManager-3.0.1__2020-01-23__04.59.59__Thu_file-1.log.gz to file upload queue
2020-01-23 04:59:59.882, info, CloudAdapter.js, UploadFile - queue length: 1
2020-01-23 04:59:59.883, debug, CloudAdapter.js, Adding /var/log/vict/device.deadbeefcafe__CloudAdapter-3.0.1__2020-01-23__04.59.59__Thu_file-1.log.gz to file upload queue
2020-01-23 05:00:00.169, info, MAFInterface.js, Upload file: device.deadbeefcafe__EVAManager-3.0.1__2020-01-23__04.59.59__Thu_file-1.log.gz
2020-01-23 05:00:00.170, debug, MAFInterface.js, Size: 630037 MD5: ea0ba8b70953e79b6cba0abb1fcda169
2020-01-23 05:00:00.171, debug, MAFInterface.js, <Buffer 1f 8b 08 00 00 00 00 00 00 03 ec bd 79 73 e2 4a d2 37 fa ff 7c 0a ee b9 11 d3 67 1e da 46 fb e2 98 9e 79 85 00 49 ec 12 3b 27 4e 74 68 43 12 68 01 6d ... >
2020-01-23 05:00:00.172, debug, MAFInterface.js, Complete
2020-01-23 05:00:00.172, debug, CloudAdapter.js, File uploaded: /var/log/vict/device.deadbeefcafe__EVAManager-3.0.1__2020-01-23__04.59.59__Thu_file-1.log.gz
2020-01-23 05:00:00.172, info, CloudAdapter.js, Sending 'avaLogFile' upload response for ''
2020-01-23 05:00:00.195, error, Default, Cannot read property 'write' of null
Regards,
Dave
…_______________________________________________
Dave Sidwell | NEC Enterprise Communication Technologies | Senior Manager - SW Development
700 West Johnson Ave. Ste. 309 | Cheshire, CT 06410 | • (O) (203) 718-6263 | • (M) (203) 513-1677 | • [email protected]<mailto:[email protected]>
From: Sidwell, David
Sent: Friday, January 24, 2020 11:23 AM
To: iccicci/rotating-file-stream <[email protected]>; iccicci/rotating-file-stream <[email protected]>
Cc: Mention <[email protected]>
Subject: RE: [iccicci/rotating-file-stream] Daily Rotation sometimes happens twice (#47)
Hi Daniele,
As requested:
// Instantiate a new RFS
rfsStream = rfs.createStream(logFileNameGenerator, {
interval: '1d', // rotate daily
path: logSettings.logFilePath,
size: logSettings.logFileMaxSize,
compress: logSettings.logFilesCompress ? 'gzip' : null, // compress rotated files
maxFiles: logSettings.logMaxFilesToKeep, // max number of rotated files to keep
maxSize: logSettings.logMaxSizeToKeep // max size of rotated files to keep
});
Where logSettings is set to:
{
"logFilePath": "/var/log/vict/",
"logFileMaxSize": "10M",
"logMaxFilesToKeep": 30,
"logMaxSizeToKeep": "100M",
"logFilesCompress": true
}
_______________________________________________
Dave Sidwell | NEC Enterprise Communication Technologies | Senior Manager - SW Development
700 West Johnson Ave. Ste. 309 | Cheshire, CT 06410 | • (O) (203) 718-6263 | • (M) (203) 513-1677 | • [email protected]<mailto:[email protected]>
From: Daniele Ricci <[email protected]<mailto:[email protected]>>
Sent: Friday, January 24, 2020 3:39 AM
To: iccicci/rotating-file-stream <[email protected]<mailto:[email protected]>>
Cc: Sidwell, David <[email protected]<mailto:[email protected]>>; Mention <[email protected]<mailto:[email protected]>>
Subject: Re: [iccicci/rotating-file-stream] Daily Rotation sometimes happens twice (#47)
Reminder: Please be cautious with external links and attachments.
Hi @davesidwell<https://github.com/davesidwell> ,
can I also see the piece of code initializing RotatingFileStream please?
Thank you,
iCC
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub<#47?email_source=notifications&email_token=ACNSFWN26DYHQZTEKL3XYMDQ7KSLXA5CNFSM4KKHSC62YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ2DFIA#issuecomment-578040480>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/ACNSFWLHC3OXT5DHE3RB5B3Q7KSLXANCNFSM4KKHSC6Q>.
|
|
Hi @davesidwell , about the first problem I applied the patch you proposed: hope this helps. I released v2.0.2, |
This was referenced Mar 13, 2021
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
On certain target machines, when set for a daily rotation, the file will rotate 1 second prior to 0:00 UTC, and then again at 0:00 UTC
This would seem to occur on target machines with internal clocks that run slightly fast.
The rotation time is set using setTimeout with a 24 hour timer.
If due to the internal clock, this triggers slightly early the rotation takes place and is completed prior to 0:00 UTC, and the scheduler then calls setTimeout again to trigger at 0:00 UTC.
The text was updated successfully, but these errors were encountered: