change debug logging?

[flammagenitus]

Hello, This is probably documented somewhere but I didn't see it. How do I decrease the volume of debugging output from solarthing? My old raspberry pi doesn't have much free space and I'd like to minimize writing to the SD card anyway. There is a lot of output being written to /var/log/daemon and /var/log/syslog as well as /opt/solarthing/rover/logs/log_debug.log that I don't really need. Thanks.

[retrodaredevil]

Yeah I definitely need to document more on how to change the amount of logging. Currently if you want to change the logging, you can put a file named exactly log4j2.xml in /opt/solarthing/program/rover/ and it will use that to debug.

Now, to make it have less output, you can edit the contents of a template log configuration file such as: https://github.com/wildmountainfarms/solarthing/blob/master/config_templates/log/instant_log4j2.xml

First, you can remote line 65, which is <AppenderRef ref="logAll" level="DEBUG"/>. That will get rid of debug logging going into logs/log_debug.log. Then, you can change line 62, which is <AppenderRef ref="Console" level="DEBUG"/> to <AppenderRef ref="Console" level="INFO"/>. That will get rid of debug logging going into stdout, which I believe eventually ends up in /var/log/daemon through systemctl somehow.

Once you do that, the only logs that will be stored are errors and important summary logs. The "summary" logs are even less frequent than errors as summary logs are only used when something happens that isn't likely to be repeated (program just started, program is crashing, etc).

I'll try to create some more templates and put them in config_templates/logs so you don't have to do this manually. I'll probably make that commit in the next few days.

[flammagenitus]

Good deal; that sounds great- I'll just watch github and wait for your next commit.

[retrodaredevil]

I created this config file that you can use: https://github.com/wildmountainfarms/solarthing/blob/master/config_templates/log/no-debug_log4j2.xml

And I found the documentation I wrote a file ago for using log4j2.xml files: https://github.com/wildmountainfarms/solarthing/blob/master/other/docs/log4j.md

Please let me know how that works out for you. And if you need a different config, let me know.

[flammagenitus]

Thanks! I copied your no-debug_log4j2.xml file as log4j2.xml into program/rover and it seems to be working. systemctl status showed that the program found that xml file and didn't report any errors. Initially I copied it into program/rover/config and it had no effect (as expected). I've been following (tail -F) solarthing's log_debug.log for several minutes and it hasn't been adding any new debug logging since it was restarted. However /var/log/syslog continues to grow with regular influxdb POST and response lines every few seconds. /var/log/daemon contains the same information as syslog. Your no-debug_log4j2.xml file that I copied already has the <AppenderRef ref="Console" level="INFO"/> line in it. The influxdb records that are being logged are "INFO" so maybe I need to use a different level than INFO for Console.

[retrodaredevil]

I didn't think about that. Yeah, I'll fix that in my next commit. You could change it from INFO to WARN, but then you'd lose out on some useful SolarThing messages that might be important. Really I just need to decide what stuff gets logged to console like I already do with the log files.

[flammagenitus]

What about NOTICE?

[retrodaredevil]

Log4j2 doesn't have a NOTICE log level: source. But generally, the really important stuff that SolarThing logs has the "SUMMARY" marker added to it.

I believe I have fixed the issue in no-debug_log4j2.xml. Now the stuff that is printed to the console should be exactly the same as the info logs.

If you still find that it's logging too much (maybe you have a long period where your database is down so it prints a bunch of errors), you can remove line 53 and 54 (The AppenderRef for "Console" and "logInfo" respectively), which will only log summary.

Let me know how this works out for you.

[flammagenitus]

It looks like that's working as expected so far- nothing logged anywhere other than the startup information. I'll check it again in the morning and let you know what I find.

[flammagenitus]

That fixed it- thanks again.

This might be useful for others too: solarthing would die when my rpi was unstable due to lack of storage space so I added "Restart=on-failure" and "RestartSec=10s" to its service file to restart it automatically.

[retrodaredevil]

That might be useful for some users, but normally SolarThing should never crash, so I find it useful when it crashes so I can fix it, rather than have it keep restarting without you getting a chance to see the error.

Sometime in the future I would like to try to make it easier for users to stop so much debug logging. I didn't realize that systemd services automatically got their outputs written to a few files in /var/log. I just have to find a good balance between full debug logging and no debug logging at all. If someone ever ends up with a really weird error, I know the debug logs would help me find the problem.

I might end up stopping the standard output from being logged in the systemd service, then possibly disable debug logging to files. This would allow users to see debug when running the program with ./run.sh, but wouldn't actually write the debug to files.

I had two pis become corrupt in 2019, so this is definitely something I want to fully fix. I haven't had any pis become corrupt in 2020, so I thought I had fixed it, but there's still a lot of logging going on with systemd that isn't needed.

[flammagenitus]

I just ordered a new SD card for this particular Pi so hopefully that will keep it running more stably. Less logging will definitely help too. I also noticed an "under-voltage" warning in dmesg so maybe that is what makes it periodically unresponsive. Maybe the USB cable or the AC/DC inverter is bad. I've got a 12 V to 5 V converter coming in the mail so I can power it and an Arduino MKR1010 directly from my solar power system.

[retrodaredevil]

Usually you'll want to make sure your power supply can give the Pi 5V and 3A, similar to some fast charging USB adapters.

A new SD card will probably allow it to run more stable than a better power supply. Sometimes I'll run a Raspberry Pi with a power supply that doesn't give enough current, and it's usually fine.

I couple days ago I made a change to the systemd service, so very, very little (almost nothing) will be logged to /var/log. So if you reinstall the systemd service, that'd be good. But since you turned off debug logging anyway, it doesn't matter too much.

[flammagenitus]

Fortunately that Pi isn't powering anything. I'll have to check but I think the power supply is good for 3A. My solar power system is almost purely experimental at this point since it only has a single 100W panel. According to Grafana it's produced about $0.25 worth of energy since I started it up. I just ordered a 2nd panel with the goal of being able to power the Pi + an Arduino MKR1010 weather recorder (~0.01W) + about 20W worth of outdoor Ubiquiti networking equipment. I tried connecting the networking gear yesterday but the battery was being depleted pretty quickly. It's been so cloudy here in western Iowa that my 100W panel is producing less than 40 Wh of energy per day.

I pulled your latest updates to stay current and just manually added the StandardOutput=null line to my installed service file.

[flammagenitus]

I got the Pi wired into solar power today. It turns out that my AC inverter was only rated for 0.7A! I must have grabbed the wrong one. I can't believe it worked as well as it did.

[retrodaredevil]

An AC inverter rated for 0.7A is perfectly fine, since 120 * 0.7 = 84W, so that should have been plenty to power your Pi, assuming you had a decent AC power supply.

[flammagenitus]

Actually that inverter is only good for 0.7A out at 5VDC so 3.5W out. I've watched power consumption by various raspberrys before and they usually stayed between 3 and 5W so I think that power supply was my main problem, not the SD card. Should be fixed now!

[CapnJackOff]

The inverter has a power loss associated with it and likely a lot of distortion if it's not a pure sine type. Not a huge deal, I know, but I run mine from a 12V battery attached to a voltage regulator output with 5V on pins 2 and 6. I wish the pi could take 12V like a lot of other other microcontroller boards.

[CapnJackOff]

According to Grafana it's produced about $0.25 worth of energy since I started it up.

WINNING! :dancing_men:

[flammagenitus]

Right now everything I want to run off solar power can be powered by either 24VDC or 5VDC so there is no need to run my 1 kW inverter just for them. This inverter will supposedly produce a pure sine wave but I haven't actually checked with an oscilloscope.

I'm using fairly efficient voltage regulators to go from 12VDC- probably similar to yours- but it's still not ideal.

I had been powering the rpi and Arduino from individual mains AC power supplies and I must have swapped them at some point which is why the rpi was being underpowered. I've got a USB 'y' splitter cable ordered that will let me run both the rpi and the Arduino directly from the 12V->5V regulator. Previously I used a 2Ah battery on the Arduino MKR1010 with a 1W PV panel which worked fairly well. I've got a 2nd 12V/100W PV panel ordered so now I need to figure out if my Renogy Rover charger controller can take 24V input but still manage a single battery and load at 12V. If not I guess I'll need to either wire the panels in parallel for 12V output, or add a 2nd battery in series for 24V and buy a new 24V to 5V voltage regulator.

As of this morning I'm up to almost $0.32 worth of energy produced. $$$

[retrodaredevil]

I've got a 2nd 12V/100W PV panel ordered so now I need to figure out if my Renogy Rover charger controller can take 24V input but still manage a single battery and load at 12V

Since the Rover is MPPT, you can wire panels in series and get any voltage up to 100V, just make sure the amps don't go over what the Rover is rated for.

You could also add another battery in series to get a 24V battery bank, but the load would then be 24V, not 12V.

[flammagenitus]

OK, thanks. I was definitely planning on wiring the panels in series to limit the current flowing through my wiring and the Rover. However, I think the 2nd battery will need to be in parallel because I need to increase storage capacity. On these cloudy days my single 100Ah battery is dipping down to 75% SOC or lower, even with a continuous load of only a few watts.

[retrodaredevil]

If you wire the batteries in series, the amp hours won't go up, but the watt hours will, so your storage capacity will increase the same number of watt hours no matter if you wire the batteries in series or parallel.

Also, the SOC is a terrible way to judge how your battery is doing since it doesn't take into account the current going in and out of the battery, it just uses the battery voltage.

[retrodaredevil]

I'm gonna go ahead and close this issue since the original problem is solved. I'm going to keep debug logging default for new users as it doesn't actually write to disk for every log, so SD cards will be fine.

Feel free to keep replying to this closed issue. I can always answer questions unrelated to SolarThing.

[flammagenitus]

If you wire the batteries in series, the amp hours won't go up, but the watt hours will, so your storage capacity will increase the same number of watt hours no matter if you wire the batteries in series or parallel.

My mistake. So the increase in storage capacity is the same whether the voltage goes up (series) or the current goes up (parallel)- makes sense.

Also, the SOC is a terrible way to judge how your battery is doing since it doesn't take into account the current going in and out of the battery, it just uses the battery voltage.

Good point. It did seem a little fishy how quickly SOC changes along with the input voltage. If you can assume that your battery is at 100% SOC at t0, couldn't you simply calculate the current SOC (%) as something like: (nominal capacity in Ah - (Ii - Io in A)(t1 - t0 in hr)) / (nominal capacity in Ah) 100, where t0 = initial time, t1 = ending time, Ii = charging current, and Io = load current? That seems like something that could be periodically (daily, maybe, if it's always fully recharged) calculated with a Grafana query. No need for voltage or temperature adjustments .

[retrodaredevil]

If you can assume that your battery is at 100% SOC at t0, couldn't you simply calculate the current SOC (%) as something like

Yeah that's a good idea, and I think that's something that most BMS systems do that actually have decent state of charge calculations. Normally, you'd know you're at 100% every time you complete a boost charge, so that's when you'd reset t0.

I think this would be difficult to do in something like an InfludDB query because you need to use a lot of past data. This might be something I eventually try in SolarThing GraphQL, but I really don't think it'd be all that accurate, especially for a system like the one I'm monitoring with FX inverters, which I'm sure have inefficiencies and probably aren't accurate enough to use for an integral over a long period of time. Plus the system I'm monitoring only does full boost/absorb charges every few days, so it'd have to be pretty accurate over even a short period for it to be anywhere near useful over a long period of time.

Something I've been thinking of doing is having a semi-accurate SOC calculation, which uses the battery voltage and maybe data from somewhere between the last hour and the last 5 minutes. (Similar to how a person would look at data from the last 5 minutes to determine how charged their battery is)

[flammagenitus]

Cool. So in theory it's possible at least. I'll have to think about how that could be done with a time series database, which unfortunately I don't know much about. Sometime maybe I'll try it with dummy data and SQL and then try to convert to InfluxQL. In the meantime, let me know if you get that going at some point!