Excessive apache logging

djh · 19 December 2018 18:24

On my emonBase I just noticed that logging had stopped some time ago and discovered it was because /var/log was full. After a little more investigation it appears the problem is down to apache logging and especially /var/log/apache2/access.log

This seems to log at least one message a second. e.g.:

192.168.1.83 - - [19/Dec/2018:18:22:44 +0000] "GET /emoncms/config/getemonhublog HTTP/1.1" 200 1025 "http://emonpi/emoncms/config/view" "Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0"
192.168.1.83 - - [19/Dec/2018:18:22:45 +0000] "GET /emoncms/config/getemonhublog HTTP/1.1" 200 1069 "http://emonpi/emoncms/config/view" "Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0"
192.168.1.83 - - [19/Dec/2018:18:22:45 +0000] "GET /emoncms/feed/list.json HTTP/1.1" 200 973 "http://emonpi/emoncms/feed/list" "Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0"
192.168.1.83 - - [19/Dec/2018:18:22:46 +0000] "GET /emoncms/config/getemonhublog HTTP/1.1" 200 1073 "http://emonpi/emoncms/config/view" "Mozilla/5.0 (X11; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0"

Is there some approved way to turn down this logging?
And/or is there some approved way to tell the system to delete old logs before the filesystem fills up?

djh · 19 December 2018 21:47

I’ve been looking at the emonhub logging as well, since my attention was drawn to it. It is logging many DEBUG messages per second, of every MQTT item published and every radio packet received

2018-12-19 18:30:23,998 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 11 235 127 93 127 249 208 203 127 250 67 201 255 195 121 254 63 253 212 79 243 (-97)
2018-12-19 18:30:25,032 DEBUG    emoncmsorg Buffer size: 6
2018-12-19 18:30:25,544 DEBUG    RFM2Pi     291220 NEW FRAME : OK 7 204 1 0 0 0 0 0 0 145 97 78 0 184 11 184 11 184 11 184 11 184 11 181 50 6 0 (-68)
2018-12-19 18:30:25,548 DEBUG    RFM2Pi     291220 Timestamp : 1545244225.54
2018-12-19 18:30:25,549 DEBUG    RFM2Pi     291220 From Node : 7
2018-12-19 18:30:25,550 DEBUG    RFM2Pi     291220    Values : [460, 0, 0, 0, 249.77, 7.800000000000001, 300, 300, 300, 300, 300, 406197]
2018-12-19 18:30:25,550 DEBUG    RFM2Pi     291220      RSSI : -68
2018-12-19 18:30:25,551 DEBUG    RFM2Pi     291220 Sent to channel(start)' : ToEmonCMS
2018-12-19 18:30:25,552 DEBUG    RFM2Pi     291220 Sent to channel(end)' : ToEmonCMS
2018-12-19 18:30:25,638 DEBUG    MQTT       Publishing: emon/emontx4/power1 460
2018-12-19 18:30:25,640 DEBUG    MQTT       Publishing: emon/emontx4/power2 0
2018-12-19 18:30:25,642 DEBUG    MQTT       Publishing: emon/emontx4/power3 0
2018-12-19 18:30:25,644 DEBUG    MQTT       Publishing: emon/emontx4/power4 0
2018-12-19 18:30:25,646 DEBUG    MQTT       Publishing: emon/emontx4/vrms 249.77
2018-12-19 18:30:25,647 DEBUG    MQTT       Publishing: emon/emontx4/temp1 7.8
2018-12-19 18:30:25,649 DEBUG    MQTT       Publishing: emon/emontx4/temp2 300
2018-12-19 18:30:25,651 DEBUG    MQTT       Publishing: emon/emontx4/temp3 300
2018-12-19 18:30:25,653 DEBUG    MQTT       Publishing: emon/emontx4/temp4 300
2018-12-19 18:30:25,655 DEBUG    MQTT       Publishing: emon/emontx4/temp5 300
2018-12-19 18:30:25,657 DEBUG    MQTT       Publishing: emon/emontx4/temp6 300
2018-12-19 18:30:25,659 DEBUG    MQTT       Publishing: emon/emontx4/pulse 406197
2018-12-19 18:30:25,660 DEBUG    MQTT       Publishing: emon/emontx4/rssi -68
2018-12-19 18:30:25,662 INFO     MQTT       Publishing: emonhub/rx/7/values 460,0,0,0,249.77,7.8,300,300,300,300,300,406197,-68
2018-12-19 18:30:26,262 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 3 18 121 195 47 253 146 247 243 243 250 251 246 110 125 239 109 246 255 239 31 (-94)
2018-12-19 18:30:27,908 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 11 125 158 255 178 47 127 251 252 183 241 232 190 249 239 247 247 191 181 71 51 (-95)
2018-12-19 18:30:28,447 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 25 195 246 115 219 188 255 202 255 246 191 191 189 239 159 91 229 223 251 237 245 (-95)
2018-12-19 18:30:31,269 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 31 207 254 235 94 119 123 254 247 255 223 110 253 237 251 255 250 191 29 243 201 (-93)
2018-12-19 18:30:32,182 DEBUG    RFM2Pi     291221 NEW FRAME : OK 8 2 0 32 1 198 0 0 0 247 98 184 11 184 11 184 11 184 11 184 11 184 11 241 170 0 0 (-28)
2018-12-19 18:30:32,186 DEBUG    RFM2Pi     291221 Timestamp : 1545244232.18
2018-12-19 18:30:32,187 DEBUG    RFM2Pi     291221 From Node : 8
2018-12-19 18:30:32,188 DEBUG    RFM2Pi     291221    Values : [2, 288, 198, 0, 253.35, 300, 300, 300, 300, 300, 300, 43761]
2018-12-19 18:30:32,189 DEBUG    RFM2Pi     291221      RSSI : -28
2018-12-19 18:30:32,189 DEBUG    RFM2Pi     291221 Sent to channel(start)' : ToEmonCMS
2018-12-19 18:30:32,190 DEBUG    RFM2Pi     291221 Sent to channel(end)' : ToEmonCMS
2018-12-19 18:30:32,302 DEBUG    MQTT       Publishing: emon/emontx3/power1 2
2018-12-19 18:30:32,304 DEBUG    MQTT       Publishing: emon/emontx3/power2 288
2018-12-19 18:30:32,306 DEBUG    MQTT       Publishing: emon/emontx3/power3 198
2018-12-19 18:30:32,308 DEBUG    MQTT       Publishing: emon/emontx3/power4 0
2018-12-19 18:30:32,310 DEBUG    MQTT       Publishing: emon/emontx3/vrms 253.35
2018-12-19 18:30:32,312 DEBUG    MQTT       Publishing: emon/emontx3/temp1 300
2018-12-19 18:30:32,315 DEBUG    MQTT       Publishing: emon/emontx3/temp2 300
2018-12-19 18:30:32,317 DEBUG    MQTT       Publishing: emon/emontx3/temp3 300
2018-12-19 18:30:32,319 DEBUG    MQTT       Publishing: emon/emontx3/temp4 300
2018-12-19 18:30:32,320 DEBUG    MQTT       Publishing: emon/emontx3/temp5 300
2018-12-19 18:30:32,322 DEBUG    MQTT       Publishing: emon/emontx3/temp6 300
2018-12-19 18:30:32,324 DEBUG    MQTT       Publishing: emon/emontx3/pulse 43761
2018-12-19 18:30:32,326 DEBUG    MQTT       Publishing: emon/emontx3/rssi -28
2018-12-19 18:30:32,328 INFO     MQTT       Publishing: emonhub/rx/8/values 2,288,198,0,253.35,300,300,300,300,300,300,43761,-28

That seems a bit excessive - especially the MQTT logging since I’m not using it at all at the moment. I might do later though. I suppose it’s not a problem if there’s a cure for the filesystem filling up?

borpin · 19 December 2018 22:08

You can change the log level of EmonCMS in settings.php.

djh · 19 December 2018 22:11

Right, but these are the emonhub log and the apache logs.

borpin · 19 December 2018 22:18

To change the log level of emonhub, set the level in the conf file. For Apache I suspect you need to Google it. I think logrotate is still used so you may need to tweak a setting although I’m not sure why you should be seeing high levels of logging.

However, I cannot help on the Apache at all as I am running my instance on Lighttpd.

djh · 20 December 2018 00:26

Thanks, Brian. I’ve turned down the emonHub log level.

My main concern is that on an out-of-the-box system, apache logging filled the filesystem, which is BAD and nothing has warned me, which is even WORSE. So there’s something seriously wrong with the default configuration as far as I can tell. I’m surprised that nobody else has apparently encountered this problem???

I shouldn’t have to be poking about in logrotate or apache settings just to get a standard system to work!

borpin · 20 December 2018 09:05

It could well be an issue with the new build, not that many folk are using it and it was a significant revise from the old (Jessie) SD card.

I also suspect you are, because of what you have been doing, making far more requests to the Apache server than you (or any one else) would under normal circumstances so the issue has never appeared before.

Add a GitHub issue and, if you solve it, suggest the change.

BTW, do you have a tab open with the admin screen updating the logs continually? That certainly would not be a normal use case.

djh · 21 December 2018 16:06

The log filled because I had three pages open:

feed/list - GET every 5 seconds
input/view - GET every 10 seconds
config/view - GET every second

Plus whatever other requests I actually made. Obviously I no longer have the actual log, since I had to delete it to get things running again. I don’t think any of those things is unexpected or unreasonable.

Log format is set to combined LF, thus approx doubling the space over common format LF

logrotate is set to keep logs for two weeks. (and BTW uses the old /etc/init.d style of command instead of sudo service apache2 reload)

So what I would suggest is:

recode config/view in particular to use web sockets instead of ajax that causes stupidly large numbers of log entries
switch apache to common log format - knowing the referring URL and browser is not likely to be helpful in debugging
cut down the number of logs kept and add a size directive so that the logs can’t overflow the space available
Add an alert field in the blue header at the top of every page, where messages such as ‘log space is full’ could be posted
Check for conditions like running out of log space and raise an alert

borpin · 21 December 2018 20:59

Look forward to the Pull Requests …

I use monit to do these sort of tasks.

djh · 21 December 2018 21:22

If anybody had responded to my original bug request, I’d have some faith in the system as used here. But they didn’t so I don’t and I won’t be using it until I 'm shown I can trust it.

PS what’s monit?

Bill.Thomson · 21 December 2018 23:25

Remember, Google is your friend.

djh · 22 December 2018 01:37

Yes, but sites that show me : “Javascript on, please!” as the only thing on screen when I go to their home page don’t encourage me to look any further. Clearly they don’t want to be my friend.

Bill.Thomson · 22 December 2018 01:42

Odd. I turned off JS, went looking for Monit, and the third result in the list returned by Google was
the Monit manual. Monit Manual
It displayed sans any issues caused by the lack of JS.

On top of that, Wikipedia worked with no issues.
Ref: Monit - Wikipedia
That was the result of a “monit wikipedia” search

Why no Javascript?

Security?

Hmm. I’ve been surfing the web since '95, and despite Steve Gibson’s (grc.com) recommendation to turn
JS off, I’ve never done so. I do keep my anti-virus/anti-malware apps up to date, and I’ve never had a
problem.

If that’s not enough, you can always use a VM to run an instance of your OS in.

If memory serves, Gibson himself (on his weekly podcast Security Now) recommended an app called
Sandboxie for just that purpose.