Log rotation

[peteruithoven]

Like @mpbomil noticed, currently our print3D logfiles keep growing on the limited RAM space of the WiFi-Box. One solution would be to implement some kind of log rotation. This means older logs are automatically removed.

It would be important to keep the first 100 / 200 lines, since this contains information about the 3D printer and how we've made the connection.

We can implement something ourselves, but we should probably use the regular logrotate utility, see: http://groenholdt.net/Computers/OpenWRT/openwrt-logrotate.html http://www.thegeekstuff.com/2010/07/logrotate-examples/ http://linux.die.net/man/8/logrotate http://manpages.ubuntu.com/manpages/saucy/en/man8/logrotate.8.html

[woutgg]

Enabling logrotate in Openwrt and using it i.c.w. cron looks like a suitable approach. The manual can be found here.

Parameters we should find good values for (including proposals):

• Invocation interval based on how fast logs fill up memory: 2 or 3 minutes
  (rule of thumb formula on bulk level: 1MB + (700kB + 14kB) * num_minutes - that is: inital filling of gcode buffer generates about 1MB of logging, then while printing this stabilizes to around 700kB for the print3d log and 14kB for the firmware log per minute).
• Maximum log file size: 1MB
  (probably not too large, so the interval is also less critical, there should at all times be enough room for an update image).
• How many rotated files to keep: 1 or 2
  (being plain text, the files compress quite well (~7%) so that is not a large concern).

Further aspects to consider:

• Rotation method: 'copytruncate' avoids print3d to be aware of rotation (but needs more room and might miss some lines); otherwise we could use SIGHUP to have print3d re-open its log file.
• Lua opens the file on each request so that is not an issue, but we should investigate what happens when logrotate runs during a request (use 'delaycompress' option?).

When rotation is in place, there are two further things to implement:

• Find a way to keep the first lines of both log files that contain printer and network initialization and the like (postrotate script or special script to copy them to a separate file?).
• Include rotated files in info/logfiles endpoint.

[peteruithoven]

With keeping the first lines you mean keeping the logs related to the initialization of the firmware / print3d?

[woutgg]

Indeed, I've updated the comment.

[peteruithoven]

(It's also relevant for the firmware (wifibox.log), because of the wifi related initialization.)

[woutgg]

Good point.

[peteruithoven]

With the early logrotation changes we did a big print on the Ultimaker2 and I did notice some momentary freezes, this might be caused by the copytruncate trick. These freezes are visible in the prints in the form of blobs:

[companje]

Are the blobs in the photo only occurring when logging extensively? Or is also a problem in normal use?

[peteruithoven]

We have not tested this yet without heavy logging.

[woutgg]

I would also suspect the compress option, this can quickly be disabled (it might be wise to also lower the rotate setting to 1 then). In either case, rotating earlier (e.g. at 500k) could reduce the freezing.

[woutgg]

I could not reproduce this. The printer did not stutter visibly or audibly while logrotate was running. Inspecting top during the rotation, I could see gzip running for a few seconds, taking about 80% of CPU, but it did not seem to have any impact on printing.

The stuttering might have had to do with a higher setting of Printer.MAX_LINES_PER_POST in the client.

Closing this for now.

[peteruithoven]

Even though we couldn't reproduce the blobs with a regular MAX_LINES_PER_POST there are still little things to fix for logrotation.

[woutgg]

The important aspects have all been implemented (see merge commit here).

We have decided not to implement log reopening on sighup/sigusr1 in print3d and firmware, assuming the copytruncate option will work well.

[jeroensomers]

I looked at the memory usage by doing "while true; do date; free; sleep 5; done" within the SSH of the WiFi-Box. The free memory goes down for about 3 minutes than log rotation comes in and the free memory goes up again. Most of the time the memory is between 2000 en 3000 (2 MB / 3MB) before it goes up again. This was while printing on the Ultimaker 2.

[peteruithoven]

On the test WiFi-Box I've lowered the logrotate size from 1000k to 500k. Hopefully this will give us a bit more playroom.

[woutgg]

The 3 minute interval however is a lower bound by the cron configuration so perhaps we should also lower that a bit.

[peteruithoven]

@woutgg What do you mean with lower bound?

[woutgg]

It will only run every 3 minutes, so regardless of actual log size, the logs will never be rotated sooner than the next time cron runs logrotate.

[peteruithoven]

Ah, I was convinced it was 3min. In that case, shouldn't we first lower just the interval? Because every rotate costs processing power. I've created a easier to use check that allows sorting:

while true; do echo "$(cat /proc/meminfo | grep MemFree | sed -E 's/^[^0-9]+//') $(date '+%H:%M:%S')";

[woutgg]

Yes, 3 minutes indeed. And I think we can safely lower it. Logrotate will only actually do something when the files are larger than the limit we set so it's rather cheap to run.