Gaps in logged data in the web chart, but not in the CSV

Troubleshooting
1

I’ve been running 0.4.1 during a week+ of conditioning a pale ale. Partly this is so I can monitor the new firmware without worrying about a fermentation going weird on me. I suspect I’ve found a bug, possibly limited just to plotting code but possibly more fundamental.

Please refer to the two screenshots. Screenshot #1 is direct from the BrewPi web page, screenshot #2 is an Excel chart of the same data available via BrewPi’s “Previous Beers” CSV download. The attached file is the CSV as downloaded from my BrewPi. I had to remove rows from the top and bottom of the file in order to meet the max upload size criteria enforced by Disqus, but both periods of weird plotting, described below, are contained in the CSV.

You can see two places in the BrewPi chart where logging appears to have stopped for ~12 hours. The first occurrence began at Dec 15, 23:53:09. The second occurrence began at Dec 19, 23:59:53. The similarity in the time of occurrence of these two gaps seems more than coincidental, perhaps a cron job is to blame. When hovering the mouse over the web chart there is a complete loss of telemetry; no data points anywhere from the start of the gap to its end. This screencast shows what I mean by a lack of data points.

While the gaps are weird on their own, here’s the kicker: the CSV file has no gaps during those times! There was some anomalous activity before and during those times, but not a lack of telemetry. Before the first gap the cooling periods averaged 3 minutes, and resumed that average afterwards. But just before gap #1 there were several non-standard cooling cycles: 9.5-min, 17-min, 6.5-min, 5-min, and 4-min, before the cooling cycles settled back to 3 mins. The (false) gap shown on the web chart started around the end of the 17-min cooling cycle.

Prior to gap #2 I lengthened the algorithm’s minimum ON and OFF times for the cooler, and the cooling cycles averaged 5 mins for about 8 hours. But a longer-than-normal cooling cycle again happened just before gap #2, and again the cooling cycles went back to normal during the time the web plot falsely shows a gap in telemetry.

Both gaps were preceded by unexpected rises in fridge temp, which explains the longer-than-normal cooling cycles but the reason for the rise in fridge temp escapes me! I wasn’t opening the door of my freezer, that’s for sure.

I also draw attention the line #16459 of the CSV file, which occurs after the two gap periods. That line has 62 consecutive [NUL] characters (ASCII Hex “00”), and then the line ends with a normal data point. But not 30 seconds after the prior point; instead it’s about 2 minutes later.

Pasted image992×534 46 KB

Pasted image1897×1173 157 KB

Testing new 0.4.x logging.csv (993.8 KB)

2

The script creates a new json file each day. Can you check what is in the json file for december 16?

3

What directory do I find the JSON data in?

It will be a couple of hours because I’m at the office and the Pi is at home (and presumably I need console access to fetch the files)

4

Files are in /var/www/data/-Beer name-

Easiest is to use FileZilla to connect to the IP address of your pi, port 22.

5

There are two JSON files for December 16. One is attached here. The other, titled Testing new 0.4.x logging-2015-12-16.json is zero bytes and would not upload.

Testing new 0.4.x logging-2015-12-16-2.json.txt (152.5 KB)

There are also 3 JSON files for December 20th, the first one being empty again.

p.s. had to change the file extension of the uploaded file so that Disqus would accept it

6

Ok, thanks for the input. So the data does not exist on the server.

Do you have any error messages in the log files (mainly stderr)?

You can also download it from /home/brewpi/logs

7

I am going to assume “No space left on device” is the gremlin at work here, and that I need to clear out some old beers:

Dec 14 2015 00:00:00 Notification: New day, creating new JSON file.
Dec 15 2015 00:00:00 Notification: New day, creating new JSON file.
Dec 16 2015 00:00:00 Notification: New day, creating new JSON file.
Traceback (most recent call last):
File “/home/brewpi/brewpi.py”, line 770, in
shutil.copyfile(localJsonFileName, wwwJsonFileName)
File “/usr/lib/python2.7/shutil.py”, line 84, in copyfile
copyfileobj(fsrc, fdst)
File “/usr/lib/python2.7/shutil.py”, line 52, in copyfileobj
fdst.write(buf)
IOError: [Errno 28] No space left on device
Dec 16 2015 12:50:22 Opening serial port
Dec 16 2015 12:50:22 Notification: Script started for beer 'Testing new 0.4.x logging’
Dec 16 2015 12:50:32 Checking software version on controller…
Dec 16 2015 12:50:32 Found BrewPi v0.4.1 build 0.4.1-0-g69ee566, running on a Particle Core with a V1 shield on port /dev/ttyACM0

Traceback (most recent call last):
File “/home/brewpi/brewpi.py”, line 431, in
startBeer(config[‘beerName’])
File “/home/brewpi/brewpi.py”, line 282, in startBeer
setFiles()
File “/home/brewpi/brewpi.py”, line 268, in setFiles
brewpiJson.newEmptyFile(localJsonFileName)
File “/home/brewpi/brewpiJson.py”, line 111, in newEmptyFile
jsonFile.close()
IOError: [Errno 28] No space left on device
Dec 16 2015 12:51:08 Opening serial port
Dec 16 2015 12:51:08 Notification: Script started for beer 'Testing new 0.4.x logging’
Dec 16 2015 12:51:18 Checking software version on controller…
Dec 16 2015 12:51:18 Found BrewPi v0.4.1 build 0.4.1-0-g69ee566, running on a Particle Core with a V1 shield on port /dev/ttyACM0

Dec 17 2015 00:00:00 Notification: New day, creating new JSON file.
Traceback (most recent call last):
File “/home/brewpi/brewpi.py”, line 187, in
allProcesses.update()
File “/home/brewpi/BrewPiProcess.py”, line 124, in update
matching = [p for p in psutil.process_iter() if any(‘python’ in p.name() and 'brewpi.py’in s for s in p.cmdline())]
File “/usr/local/lib/python2.7/dist-packages/psutil/init.py”, line 592, in cmdline
return self._proc.cmdline()
File “/usr/local/lib/python2.7/dist-packages/psutil/_pslinux.py”, line 768, in wrapper
raise NoSuchProcess(self.pid, self._name)
psutil.NoSuchProcess: psutil.NoSuchProcess process no longer exists (pid=1175)
Dec 17 2015 01:25:06 Another instance of BrewPi is already running, which will conflict with this instance. This instance will exit
Traceback (most recent call last):
File “/home/brewpi/brewpi.py”, line 187, in
allProcesses.update()
File “/home/brewpi/BrewPiProcess.py”, line 124, in update
matching = [p for p in psutil.process_iter() if any(‘python’ in p.name() and 'brewpi.py’in s for s in p.cmdline())]
File “/home/brewpi/BrewPiProcess.py”, line 124, in
matching = [p for p in psutil.process_iter() if any(‘python’ in p.name() and 'brewpi.py’in s for s in p.cmdline())]
File “/usr/local/lib/python2.7/dist-packages/psutil/init.py”, line 532, in name
name = self._proc.name()
File “/usr/local/lib/python2.7/dist-packages/psutil/_pslinux.py”, line 768, in wrapper
raise NoSuchProcess(self.pid, self._name)
psutil.NoSuchProcess: psutil.NoSuchProcess process no longer exists (pid=3501)
Dec 17 2015 05:05:07 Another instance of BrewPi is already running, which will conflict with this instance. This instance will exit
Dec 18 2015 00:00:00 Notification: New day, creating new JSON file.
Dec 19 2015 00:00:00 Notification: New day, creating new JSON file.
Traceback (most recent call last):
File “/home/brewpi/brewpi.py”, line 187, in
allProcesses.update()
File “/home/brewpi/BrewPiProcess.py”, line 124, in update
matching = [p for p in psutil.process_iter() if any(‘python’ in p.name() and 'brewpi.py’in s for s in p.cmdline())]
File “/home/brewpi/BrewPiProcess.py”, line 124, in
matching = [p for p in psutil.process_iter() if any(‘python’ in p.name() and 'brewpi.py’in s for s in p.cmdline())]
File “/usr/local/lib/python2.7/dist-packages/psutil/init.py”, line 532, in name
name = self._proc.name()
File “/usr/local/lib/python2.7/dist-packages/psutil/_pslinux.py”, line 768, in wrapper
raise NoSuchProcess(self.pid, self._name)
psutil.NoSuchProcess: psutil.NoSuchProcess process no longer exists (pid=31135, name=‘sh’)
Dec 19 2015 00:45:06 Another instance of BrewPi is already running, which will conflict with this instance. This instance will exit
Dec 19 2015 15:55:12 controller debug message: INFO MESSAGE 12: Received new setting: minCoolTime = 300
Dec 20 2015 00:00:00 Notification: New day, creating new JSON file.
Traceback (most recent call last):
File “/home/brewpi/brewpi.py”, line 770, in
shutil.copyfile(localJsonFileName, wwwJsonFileName)
File “/usr/lib/python2.7/shutil.py”, line 84, in copyfile
copyfileobj(fsrc, fdst)
File “/usr/lib/python2.7/shutil.py”, line 52, in copyfileobj
fdst.write(buf)
IOError: [Errno 28] No space left on device
Dec 20 2015 11:57:12 Opening serial port
Dec 20 2015 11:57:12 Notification: Script started for beer 'Testing new 0.4.x logging’
Dec 20 2015 11:57:22 Checking software version on controller…
Dec 20 2015 11:57:22 Found BrewPi v0.4.1 build 0.4.1-0-g69ee566, running on a Particle Core with a V1 shield on port /dev/ttyACM0

Traceback (most recent call last):
File “/home/brewpi/brewpi.py”, line 431, in
startBeer(config[‘beerName’])
File “/home/brewpi/brewpi.py”, line 282, in startBeer
setFiles()
File “/home/brewpi/brewpi.py”, line 268, in setFiles
brewpiJson.newEmptyFile(localJsonFileName)
File “/home/brewpi/brewpiJson.py”, line 111, in newEmptyFile
jsonFile.close()
IOError: [Errno 28] No space left on device
Dec 20 2015 11:58:09 Opening serial port
Dec 20 2015 11:58:09 Notification: Script started for beer 'Testing new 0.4.x logging’
Dec 20 2015 11:58:19 Checking software version on controller…
Dec 20 2015 11:58:19 Found BrewPi v0.4.1 build 0.4.1-0-g69ee566, running on a Particle Core with a V1 shield on port /dev/ttyACM0

Dec 20 2015 20:43:16 Opening serial port
Dec 20 2015 20:43:16 Notification: Script started for beer 'Testing new 0.4.x logging’
Dec 20 2015 20:43:26 Checking software version on controller…
Dec 20 2015 20:43:26 Found BrewPi v0.4.1 build 0.4.1-0-g69ee566, running on a Particle Core with a V1 shield on port /dev/ttyACM0

Dec 21 2015 00:00:00 Notification: New day, creating new JSON file.

8

I just deleted pretty much every prior beer of mine, under both /var/www and /home/brewpi. But unless there is some Linux garbage collection not yet done my SD card is still at 96% usage. I guess I might need a bigger card in the near future.

9

How big is your card?
Maybe the log files are pretty big too in /home/brewpi/logs

10

My current SD card is 8 GB, of which it looks like about 5.4GB are in use, at least according to the following output of “df -v”.

Filesystem 1K-blocks Used Available Use% Mounted on
/dev/root 5871092 5285672 264140 96% /
devtmpfs 218244 0 218244 0% /dev
tmpfs 44504 248 44256 1% /run
tmpfs 5120 0 5120 0% /run/lock
tmpfs 89000 0 89000 0% /run/shm
/dev/mmcblk0p5 60479 19865 40615 33% /boot

According to “du -h” the whole of /home/brewpi occupies 68 MB, and the stderr.txt file in /home/brewpi/logs is 62 MB of that. But by my calcs 62MB is less than 1% of 8GB, so that shouldn’t be the problem.

11

It seems like filesystem issues are a sypmtom here rather than a root cause.

The mystery to me is: why did my fridge / beer temps drift unexpectedly up just prior to the (apparent) 12-hour gaps in logging? A beer which had been locked-in at 35F, needing only a 3-minute cooling cycle every 30 mins to keep within 0.07F of that mark, suddenly warmed up to more than 36F in 1 hour even in the presence of more cooling, then took about 7 hours and several cooling cycles to come back down to 35F. All the while the ambient room temp was at one of its lowest of the day. Seems to me like the sensors went a little haywire, or something like that.

12

I am very puzzled too.
Maybe if you find the cause of your disk space running out, you can find the cause of the temperature issue.
If you really ran out of disk space, all kinds of weird things can happen. However, the temperature control on the core should not be affected.

8 GB should be plenty. I have 3.3G in use on my pi.

13

Another oddity is that data logging never stopped during the false gap. I can download the data via CSV, it’s just that the web-based plot doesn’t leverage this data. I take it from this evidence that the web charting is done via the JSON files rather than the CSV, and there are conditions under which the CSV has data not represented in JSON.

I’ve had zero “no space on device” messages in the log since the 2nd time, which probably means removing old beer logs helped with disk utilization. Even though my card should not be close to capacity, I decided that /dev/root filesystem being at 97% is a bad thing.

To that end, below is the output of a more advanced use of “du” before and after running “sudo apt-get clean”. The /dev/root filesystem went from 97% to 74% utilization, and notice that /var went from the #2 user to not even in the top 10 any longer. If I see weird plotting again soon then disk space is probably not the root cause!

pi@RaspberryBrewPi1 / $ sudo du -k / | sort -n -r | head
5299853 /
1705020 /usr
1453044 /var
1426700 /lib
1405076 /lib/modules
1194040 /var/cache
1187672 /var/cache/apt
1152268 /var/cache/apt/archives
860052 /usr/lib
686648 /usr/share

pi@RaspberryBrewPi1 / $ sudo apt-get clean
pi@RaspberryBrewPi1 / $ sudo du -k / | sort -n -r | head
4112245 /
1705020 /usr
1426700 /lib
1405076 /lib/modules
860052 /usr/lib
686648 /usr/share
582748 /opt
466096 /opt/Wolfram
466092 /opt/Wolfram/WolframEngine
466088 /opt/Wolfram/WolframEngine/10.0

14

I think the gaps in the json can be fully explained by no disk space. Probably it was able to append a bit of data to the csv file, it probably reserved some space for that. But there was not enough room to create a new json file for the new day.

Uninstalling wolfram-engine will save some space too:

sudo apt-get purge wolfram-engine

Crazy that is installed by default.

15

The gaps in logging are no longer an issue ever since I cleaned up space on the SD card. However I am still getting occasional odd behavior. My BrewPi spends the majority of its day idling for 40 minutes and cooling for 5 minutes, keeping beer temp locked at 35F. But once in a while beer temp rises even in the presence of increased cooling.

Included here is some text taken from stderr.txt, plus a screenshot zoomed-in to roughly the time where the log reported a second instance of BrewPi (13:35 on Dec 28). Notice that the unexpected rise in beer temp reaches its maximum at roughly this same time, followed by the resumption of regular cooling / idle cycles.

Dec 28 2015 00:00:00 Notification: New day, creating new JSON file.
Traceback (most recent call last):
File "/home/brewpi/brewpi.py", line 187, in 
allProcesses.update()
File "/home/brewpi/BrewPiProcess.py", line 124, in update
matching = [p for p in psutil.process_iter() if any('python' in p.name() and 'brewpi.py'in s for s in p.cmdline())]
File "/usr/local/lib/python2.7/dist-packages/psutil/__init__.py", line 592, in cmdline
return self._proc.cmdline()
File "/usr/local/lib/python2.7/dist-packages/psutil/_pslinux.py", line 768, in wrapper
raise NoSuchProcess(self.pid, self._name)
psutil.NoSuchProcess: psutil.NoSuchProcess process no longer exists (pid=32310)
Dec 28 2015 13:35:07 Another instance of BrewPi is already running, which will conflict with this instance. This instance will exit
Dec 29 2015 00:00:00 Notification: New day, creating new JSON file.

Pasted image995×539 48.8 KB

16

I wonder why the room temperature rises when the cooler is active. It does make sense (moving heat from inside to outside of the fridge), but the strange thing is that this does not happen between 12:00 and 13:00.

Does your fridge have a de-icing mechanism? That would explain the rise in temperature. It also seems that during that hour, the compressor is not active, even though the SSR is active.

17

The room temp goes up when the cooler (large upright freezer) is active simply because the room temp sensor is right next to the freezer. The BrewPi is stuck with Velcro to the side of the freezer, and the temp sensor is plugged into the OneWire connector. The sensor itself is probably not more than 2 inches from the Pi, therefore not more than 2 inches from the side of the freezer, Since the freezer outer sidewalls warm up during cooling activity, the room temp reading goes up. If I had more separation between the freezer and the sensor then this effect would be dampened.

As for whether the freezer has a de-icing mechanism, it does have a defrost coil on the back. At least, according to this PDF for Frigidaire model # FFUH21F2NWA (pages 6 and 7). I am not sure how the freezer decides to engage the defrost cycle instead of the normal cooling cycle. I have the freezer turned up to max (lowest temp) and simply plugged into a mechanical relay (PowerSwitch Tail II).

18

Adaptive Defrost Control
“An adaptive defrost control or ADC system attempts to save energy by fine-tuning the timing of defrost cycles. An electronic processor monitors how long it takes to defrost the evaporator coil during each defrost cycle and adjusts the time between cycles to optimize efficiency. Frigidaire ADC systems run defrost cycles of about 30 minutes, with between six and 72 hours of compressor run time between cycles.”

I think the defrost cycle is a very plausible explanation for your 30 minute heat up and that the sensors are reading the correct value. You can see yourself that brewpi is powering the fridge but that it is not cooling.

I think we can chalk up the JSON data missing to the disk space running out.

So I think you do not have any problems caused by BrewPi and no issues that you need to worry about.

19

I don’t want to spoil the fun, but if you’re on an existing thread and have a new question, it’s best to start a new thread, so we don’t end up with one thread mixing two subjects. This will make it much easier for someone with the same problem to later review what’s already written without having to dive into other unrelated stuff. cheers :+1: