I have a NodeJS web app and I've added logging via bunyan. Works perfectly on my desktop. On Azure it works perfectly for 1-10 seconds and then nothing else is ever logged. The app continues to run and operates correctly otherwise. I can't figure out why this is happening. Logging to a plain local file, not a blob or Azure Storage.
Log type is rotating-file, set to rotate 1/day and keep 3 days. The web app has Always On and ARR Affinity set to On, and Application Logging (Filesystem) though I'm not sure that factors here. Instance Count is 1 and Autoscale is not enabled. Node version is 8.7.0. In Console:
> df -h .
D:\home\site\wwwroot\logs
Filesystem Size Used Avail Use% Mounted on
- 100G -892G 99G 113% /d/home/site
Frankly I don't know what that's trying to tell me. Somehow we've used 113% of something, which is impossible. We've used a negative amount, which is impossible. There is still 99G/100G available, so we really are only using 1%. So is it a 'disk full' problem? I don't know. I haven't seen such an error message anywhere.
Prior, the app was using console.log(). We added code to intercept console.X and write to a file first, then call the normal function. The same thing happened - it would work for a few seconds and then not log anything else. I had assumed it was because some component of Azure was also intercepting console calls in order to redirect them to XXX-stdout.txt, and both of us doing that somehow broke it. Now it seems the cause may have been something else.
Does anyone know why this is happening?
11/12 - Created from scratch an app to log a heartbeat once/second and it worked fine. Also worked once/minute. I'll have to add in pieces from the failing project until it breaks.
11/13 - I don't think there's anything special about the logger configuration.
'use strict'
const bunyan = require('bunyan');
const fs = require('fs');
const path = require('path');
const logname = 'tracker';
const folder = 'logs';
const filename = path.join(folder, logname + ".json");
if (!fs.existsSync(folder)) {
fs.mkdirSync(folder);
}
var log = bunyan.createLogger({
name: logname,
streams: [{
type: 'rotating-file',
path: filename,
level: process.env.LOG_LEVEL || "info",
period: '1d', // daily rotation
count: 3 // keep 3 back copies
}]
});
module.exports = { log };
Still working on reproducing it with something less than the entire project.
11/14 - I've satisfied myself that after the bunyan logging stops the app is still continuing to call it. The "calling log2" console.logs are visible in the Azure Log Stream, but beyond ~30 seconds nothing more gets added to the bunyan log. I never see the "ERROR" logged. This is still in the context of the project, I still can't reproduce it separately.
var log2 = bunyan.createLogger({
name: logname,
streams: [{
type: 'rotating-file',
path: filename,
level: process.env.LOG_LEVEL || "info",
period: '1d', // daily rotation
count: 3 // keep 3 back copies
}]
});
var log = {};
log.info = function() {
console.log("calling log2.info");
try {
log2.info(...arguments);
} catch(err) {
console.log("log.info ERROR " + err);
}
}
11/14 - Changed from 'rotating-file' to 'file', same behavior. Enabled xxx logging and it prints the "writing log rec" message but does not add to the file. Something happened to the file stream? Added code to catch close/finish/cork right where we catch 'error' from the stream, didn't catch any of those events.
11/15 - I can see from pids and log messages that Azure is restarting my app. I don't know why, nothing in logging-errors.txt, nothing dire on stderr. I also don't know why that second run isn't logging to the file, when the first one did. But if I can figure out why it's restarting and prevent that, then I won't care about the second problem. Azure is so opaque to me.
After much head-banging we've determined that what we're trying to do isn't compatible with an Azure web app. We'll need to stand up a VM. Closing this question.