Kudu: continuous webjobs logs are not persisted to application logs as per site settings

[ashelley]

Hello,

According to the documentation here:

https://github.com/projectkudu/kudu/wiki/Web-jobs#logging

"For continuous WebJobs - Console.Out and Console.Error are routed to the "application logs", they will show up as file, blob or table storage depends on your configuration of the application logs (similar to your Website)."

If I use the command

$ azure site log tail sitename
I am able to see the logs as they are currently running. However these logs are not written to D:\home\LogFiles\Application

The only logs I am able to retrieve for a continuous webjob is the first 100 lines per execution at

D:\homedata\jobs\continuous\jobname\job_log.txt

Because this file stops logging after 100 lines this is the only log I am able to retrieve for my continuous webjob:

[10/13/2015 19:49:08 > 13a748: WARN] Reached maximum allowed output lines for this run, to see all of the job's logs you can enable website application diagnostics
[10/13/2015 20:09:53 > 13a748: SYS INFO] WebJob is still running
[10/14/2015 07:33:10 > 13a748: SYS ERR ] Job failed due to exit code 1
right before 07:33:10 the application would have emitted a stack trace to the console so that I could see the reason for the crash. However because this log is truncated I am unable to tell why it crashed from this log.

The main problem I am having is that the logs for this webjob should be available in D:\home\LogFiles\Application as per the documentation. Note that I do have diagnostic logs turned on in my webapp and they are

Steps to reproduce:

• 1) Create a webapp and turn on diagnostic logs as per above image
• 2) Add a continuous webjob to D:\home\site\wwwroot\App_Data\jobs\continuous\testjob here is a test script I used:
  

  app.js:

var startDate = new Date();
var workerId = startDate.getTime();
var index = 0;
var pid = process.pid;

console.log('started workerid=', workerId, 'pid=', pid);

function run() {
    index++;
    console.log('log workerid =', workerId, 'pid=', pid, 'index=', index, 'start=', startDate.toISOString(), 'now=', (new Date()).toISOString());    
    setTimeout(function(){
        run();
    }, 60000);
}

run();

• 3) use the azure cli to see that the output of the continuous job can be streamed:

$ azure site log tail sitename
...
2015-10-15T20:14:32 PID[2868] Information log workerid = 1444940072697 pid= 3752 index= 1 start= 2015-10-15T20:14:32.697Z now= 2015-10-15T20:14:32.712Z
2015-10-15T20:15:32 PID[2868] Information log workerid = 1444940072697 pid= 3752 index= 2 start= 2015-10-15T20:14:32.697Z now= 2015-10-15T20:15:32.724Z
2015-10-15T20:16:32 PID[2868] Information log workerid = 1444940072697 pid= 3752 index= 3 start= 2015-10-15T20:14:32.697Z now= 2015-10-15T20:16:32.724Z
Note that the above output tells me that the logs are being output properly, however they are not being persisted in the application logs D:\home\LogFiles\Application

• 4) look in the application logs to try to find the logs by looking at the contents of D:\home\LogFiles\Application>

Expected results:

As per the documentation at https://github.com/projectkudu/kudu/wiki/Web-jobs#logging I would expect to see the non-truncated logs in the application logs.

Actual results:

Only truncated logs are available at D:\homedata\jobs\continuous\jobname\job_log.txt which prevents us from diagnosing long running continuous job crashes because the logs do not extend past 100 lines.

Other notes:

azure-cli seems to be able to tail off the log files from but I am unsure where these logs are available on the filesystem if at all.

I believe this is a bug however it could be that I just am unsure of the location of where these log files are stored.

Also note:

to test to see if this is just a problem with logging node.js specific jobs I created a bash script which also does not seem to log to the application logs. Here is the bash script I tested:

run.sh

START=`date +"%Y-%m-%dT%H:%M:%SZ"`
WORKER=`date +%s`
COUNT=0
while true
do
  COUNT=$((COUNT+1))  
  echo worker id=$WORKER index=$COUNT start=$START now=`date +"%Y-%m-%dT%H:%M:%SZ"`
  sleep 1m
done

Any help is appreciated as I am having a difficult time solving crashes that occur late at night because I am unable to log exceptions.

Originally I discussed this issue here:

https://github.com/projectkudu/kudu/issues/1744

also here:

https://github.com/projectkudu/kudu/issues/1733#issuecomment-146992336

Tagging @mathewc as per https://github.com/projectkudu/kudu/issues/1744#issuecomment-148558231

[makhdumi]

+1: Just wanted to say that we need this issue fixed badly as well. It's surprisingly difficult just to get the console output of our jobs.

There is logging to Blob/Table Storage, but they're comparatively hard/slow to read given that the blobs/rows are split by instance and time. I'd really gotten used to the nice format the job_logs are in.

[davidebbo]

What if we added an App Setting to set the max number of lines, with 0 meaning no max?

[ashelley]

@davidebbo sorry I missed this post here.. I would say that yes this would be an acceptable solution.

One could simply manually recycle a process to truncate the log manually. However I feel like if the settings.job file had similar settings to iis node:

https://github.com/tjanczuk/iisnode/blob/master/src/samples/configuration/iisnode.yml#L118-L126

where one could limit the amount of logging automatically that might be better. I think the complication in this would be that maybe the jobs don't support having multiple log files per pid.

[janfl]

Has this issue not been solved yet? I get the _"Reached maximum allowed output lines for this run, to see all of the job's logs you can enable website application diagnostics"_ in my webjobs as well and have not been able to solve it...

[snkscore]

This issue is really disappointing for us. Being able to look at the console to see what is going on currently with a continuous (long running) job was going to be a very nice feature for us, but because of this limit, after the 1st hour or so we hit the "Reached maximum allowed output lines for this run, to see all of the job's logs you can enable website application diagnostics". We don't want to store this type of data in a hard-to-access blob or table storage. Just being able to glance the console and see the last X number of lines was what we wanted and what we thought we were getting. Even stopping and restarting the continuous job doesn't refresh the log.

[Ander5]

This really needs to be fixed, working with web jobs is quite frustrating atm. It should at least be possible to clear the log, allowing for new messages to show up.

[davidebbo]

Actually, this works today, but when configuring logs to go to File System, they go to a different LogFiles folder: D:\home\LogFiles\SiteExtensions\Kudu. If you need to stream them, you can run (log in with your deployment credentials):

curl https://{app}.scm.azurewebsites.net/api/logstream/SiteExtensions/Kudu -u YourDeploymentUser

Or if using azure site log tail (which wraps the same API), pass -p SiteExtensions/Kudu to tell it to stream from that path.

[rholsman]

Would really like to see this issue fixed; this makes blob storage of logs a useless feature as I am hitting the
"WARN Reached maximum allowed output lines for this run, to see all of the job's logs you can enable website application diagnostics"

very quickly; this only working with file storage is a poor work around.

[davidebbo]

@rholsman you need to enable application logs per the message you're getting. Unless you're saying that you are seeing this message in the app logs that you send to blobs? That should not happen.

[bdelaney]

With application logs turned on for app service I still do not see how the output to blob storage helps very much in the diagnostics area. I would also vote for some kind of option (not default) that a dev can set in the Azure Webjob properties (Webjob-publish-settings) to allow a longer logging period. My Webjob quickly reaches 100 lines of output and then I'm stuck with the "Webjob is still running" which seems to repeat every 12 hours. Not clear to me if this state means that my Webjob code is unable to log errors to this convenient pane from then on.
More control points in the Kudu display of the Webjob logging would be so helpful. Like a way to clear the log so that detail lines can be logged again.

[davidebbo]

I still do not see how the output to blob storage helps very much in the diagnostics area

@bdelaney can you elaborate on this? Logging to blob lets you keep much longer history. We generally avoid any feature that involves writing to the app's file system in a continuous manner, as that can degrade performance.

[graemechristie]

Was there no resolution to this ? Is it possible to get some kind of option to auto-truncate the webjob logs for continuous web jobs. Seeing the first 100 lines of a log for a continuous webjob is of little use.

In our case we have full diagnostic logs in our log server - we don't need a long running history from the webjob logs. In the case where we are not seeing logs in the log server we need to webjob logs to see the current state of the job.

[makhdumi]

@graemechristie the recommended course of action seems to be to configure the WebApp log to Blob storage instead.

It seems from @davidebbo's comment that the reason for showing the first 100 lines rather than the latest 100 is done to avoid continuously writing to the filesystem, which affects overall performance? I think that makes sense. We had an issue a while back where the filesystem was being written to a lot by webjobs, and it very severely degraded the web app performance.

I ended up using Serilog with the Elasticsearch and Diagnostics.Trace sinks (with the Trace sink output going to Blob storage). I also use a rolling file sink for webjobs (which are sort of separate from the app now) - if the log file size goes over N MB, it's recreated.