Brewpi randomly changing temperature setting in profile mode

[colinhayes]

Well, the title basically explains it. It keeps changing from the profile of 10 C to 23 C and sometimes will go back if I reload the profile. It seems stable in beer constant mode. This is a v2.

Just updated yesterday, too.

Here’s some text from stderr.txt

Aug 16 2019 22:45:12 Controller debug message: INFO MESSAGE 12: Received new setting: mode = p
Aug 16 2019 22:45:12 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:46:14 Cannot process line from controller: 600,“beer2fridge_infilt”:1,“beer2fridge_dfilt”:4,“beer2fridge_pidMax”:6.00,“minCoolTime”:120,“minCoolIdleTime”:180$
Aug 16 2019 22:46:14 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:46:21 JSON decode error: Expecting ‘:’ delimiter: line 1 column 510 (char 509)
Aug 16 2019 22:46:21 Line received was: C:{“tempFormat”:“C”,“heater1_kp”:30.00,“heater1_ti”:1800,“heater1_td”:60,“heater1_infilt”:1,“heater1_dfilt”:4,“heater2_kp”:30.00,“he$
Aug 16 2019 22:46:29 Serial Error: device reports readiness to read but returned no data (device disconnected or multiple access on port?))
Aug 16 2019 22:46:29 Serial (re)connected for Photon [23001e001347353236343033] at port: ttyACM0
Aug 16 2019 22:47:15 Controller debug message: INFO MESSAGE 12: Received new setting: mode = p
Aug 16 2019 22:47:16 Cannot process line from controller: }
Aug 16 2019 22:48:11 Cannot process line from controller: ,“Log3Temp”:null,“State”:0}
Aug 16 2019 22:49:23 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 10.0
Aug 16 2019 22:49:23 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:49:51 JSON decode error: Expecting ‘:’ delimiter: line 1 column 140 (char 139)
Aug 16 2019 22:49:51 Line received was: T:{“BeerTemp”:10.31,“BeerSet”:23.00,“BeerAnn”:null,“FridgeTemp”:7.31,“FridgeSet”:29.00,“FridgeAnn”:null,“Log1Temp”:null,“Log2Temp”:n$
Aug 16 2019 22:50:17 JSON decode error: Expecting ‘:’ delimiter: line 1 column 201 (char 200)
Aug 16 2019 22:50:17 Line received was: d:[{“i”:0,“t”:1,“c”:1,“b”:1,“f”:9,“h”:2,“d”:0,“p”:0,“a”:“28AA468008000004”,“j”: -0.004},{“i”:1,“t”:1,“c”:1,“b”:0,“f”:5,“h”:2,“d”:0,”$
Aug 16 2019 22:50:17 Available devices received: [{“c”: 1, “b”: 0, “d”: 0, “f”: 0, “i”: -1, “h”: 1, “p”: 17, “t”: 0, “x”: 0}]
Aug 16 2019 22:50:35 Cannot process line from controller: ater1_ti":1800,“heater1_td”:60,“heater1_infilt”:1,“heater1_dfilt”:4,“heater2_kp”:30.00,“heater2_ti”:1800,“heater2_$
Aug 16 2019 22:50:35 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 10.0
Aug 16 2019 22:51:06 Cannot process line from controller: Log3Temp”:null,“State”:0}
Aug 16 2019 22:51:07 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:51:10 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 10.0
Aug 16 2019 22:51:26 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 10.0
Aug 16 2019 22:51:26 Serial Error: device reports readiness to read but returned no data (device disconnected or multiple access on port?))
Aug 16 2019 22:51:26 Serial (re)connected for Photon [23001e001347353236343033] at port: ttyACM0
Aug 16 2019 22:51:27 JSON decode error: Expecting ‘,’ delimiter or ‘}’: line 1 column 231 (char 230)
Aug 16 2019 22:51:27 Line received was: C:{“tempFormat”:“C”,“heater1_kp”:30.00,“heater1_ti”:1800,“heater1_td”:60,“heater1_infilt”:1,“heater1_dfilt”:4,“heater2_kp”:30.00,“he$
Aug 16 2019 22:53:20 Cannot process line from controller: :0}
Aug 16 2019 22:53:38 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:53:43 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:53:55 Serial Error: device reports readiness to read but returned no data (device disconnected or multiple access on port?))
Aug 16 2019 22:53:55 Serial (re)connected for Photon [23001e001347353236343033] at port: ttyACM0
Aug 16 2019 22:54:02 Cannot process line from controller: 4,“beer2fridge_kp”:5.00,“beer2fridge_ti”:10800,“beer2fridge_td”:600,“beer2fridge_infilt”:1,“beer2fridge_dfilt”:4,”$
Aug 16 2019 22:54:02 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 10.0
Aug 16 2019 22:54:03 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:54:21 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:54:03 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:54:21 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 16 2019 22:54:43 JSON decode error: Expecting ‘:’ delimiter: line 1 column 346 (char 345)
Aug 16 2019 22:54:43 Line received was: C:{“tempFormat”:“C”,“heater1_kp”:30.00,“heater1_ti”:1800,“heater1_td”:60,“heater1_infilt”:1,“heater1_dfilt”:4,“heater2_kp”:30.00,“he$
Aug 16 2019 22:55:11 Controller debug message: INFO MESSAGE 12: Received new setting: mode = b
Aug 16 2019 22:55:11 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 10.0
Aug 16 2019 22:59:44 JSON decode error: Expecting ‘:’ delimiter: line 1 column 157 (char 156)
Aug 16 2019 22:59:44 Line received was: T:{“BeerTemp”:10.31,“BeerSet”:10.00,“BeerAnn”:null,“FridgeTemp”:7.43,“FridgeSet”:7.76,“FridgeAnn”:null,“Log1Temp”:null,“Log2Temp”:nu$
Aug 16 2019 23:00:19 Serial Error: device reports readiness to read but returned no data (device disconnected or multiple access on port?))
Aug 16 2019 23:00:19 Serial (re)connected for Photon [23001e001347353236343033] at port: ttyACM0
Aug 16 2019 23:00:44 Cannot process line from controller: mp”:6.81,“FridgeSet”:8.20,“FridgeAnn”:null,“Log1Temp”:null,“Log2Temp”:null,“Log3Temp”:null,“State”:0}
Aug 16 2019 23:06:28 JSON decode error: Expecting ‘:’ delimiter: line 1 column 25 (char 24)
Aug 16 2019 23:06:28 Line received was: T:{“BeerTemp”:10.25,"BT:{“BeerTemp”:10.25,“BeerSet”:10.00,“BeerAnn”:null,“FridgeTemp”:7.12,“FridgeSet”:9.39,“FridgeAnn”:null,"Log1Te$
Aug 16 2019 23:08:36 Serial Error: device reports readiness to read but returned no data (device disconnected or multiple access on port?))
Aug 16 2019 23:08:36 Serial (re)connected for Photon [23001e001347353236343033] at port: ttyACM0

And here’s a screenshot of it.

[Elco]

It seems that you have a lot of communication errors.
I suspect a bad usb cable or underpowered pi.

With the BrewPi firmware, the profile is managed on the pi and updates are sent to the spark. A communication error could result in the wrong temperature setting being sent.

With our new beta BrewBlox platform, profiles run on the spark and don’t require communication with the pi to update.

[colinhayes]

I was thinking the same and ordered a couple nice short ones. I’ll swap them out later today when they arrive.

What’s the current draw on the spark and a pi? I’m powering both with a 3A supply, so I feel like that should be enough.

[Elco]

Yes 2A is recommended. Phone chargers are not recommended. But I don’t think that the power supply is the problem in your case.

[colinhayes]

Brand new cable, still doing it.

Aug 18 2019 18:24:41 Line received was: heater2_kp":30.00,“heater2_ti”:1800,“heater2_td”:60,“heater2_infilt”:1,“heater2_dfilt”:4,“cooler_kp”:20.00,“cooler_ti”:3600,“cooler_td”:300,“cooler_infilt”:1,“cooler_dfilt”:4,“beer2fridge_kp”:5.00,“beer2fridge_ti”:10800,“beer2fridge_td”:600,“beer2fridge_infilt”:1,“beer2fridge_dfilt”:4,“beer2fridge_pidMax”:6.00,“minCoolTime”:120,“minCoolIdleTime”:180,“heater1PwmPeriod”:4,“heater2PwmPeriod”:4,“coolerPwmPeriod”:1200,“deadTime”:1800}
Aug 18 2019 18:25:29 Cannot process line from controller: er_infilt":1,“cooler_dfilt”:4,“beer2fridge_kp”:5.00,“beer2fridge_ti”:10800,“beer2fridge_td”:600,“beer2fridge_infilt”:1,“beer2frinCoolIdleTime”:180,“heater1PwmPeriod”:4,“heater2PwmPeriod”:4,“coolerPwmPeriod”:1200,“deadTime”:1800}
Aug 18 2019 18:25:29 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 18 2019 18:25:54 Notification: Beer temperature set to 10.0 degrees in web interface
Aug 18 2019 18:25:55 Cannot process line from controller: “Beer temp set to 10.0 in web interface”,“FridgeTemp”:17.56,“FridgeSet”:29.00,“FridgeAnn”:null,“Log1Temp”:null,“Log2Temp”:null,“Set”:10.00,“fridgeSet”:null}

[colinhayes]

Here’s the output between then, me setting it to profile mode again, and it setting itself back to 23C.

Aug 18 2019 18:27:56 Cannot process line from controller: ":0}
Aug 18 2019 18:28:11 Setting profile ‘54%3A%20Tmave%20Specialni’ as active profile
Aug 18 2019 18:28:11 Notification: Profile mode enabled
Aug 18 2019 18:28:11 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 18 2019 18:28:12 JSON decode error: Expecting ‘:’ delimiter: line 1 column 10 (char 9)
Aug 18 2019 18:28:12 Line received was: C:{"temT:{“BeerTemp”:9.81,“BeerSet”:23.00,“BeerAnn”:“Beer temp set to 10.0 by temp_t profile”,“FridgeTemp”:17.18,“FridgeSet”:8.53,“FridgeAnn”:null,“Log1Temp”:null,“Log2Temp”:null,“Log3Temp”:null,“State”:0}
Aug 18 2019 18:28:12 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 10.0
Aug 18 2019 18:28:36 Serial Error: device reports readiness to read but returned no data (device disconnected or multiple access on port?))
Aug 18 2019 18:28:36 Serial (re)connected for Photon [23001e001347353236343033] at port: ttyACM0
Aug 18 2019 18:29:12 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 23.0
Aug 18 2019 18:29:13 Controller debug message: INFO MESSAGE 12: Received new setting: beerSet = 10.0
Aug 18 2019 18:29:15 JSON decode error: Expecting ‘:’ delimiter: line 1 column 417 (char 416)
Aug 18 2019 18:29:15 Line received was: C:{“tempFormat”:“C”,“heater1_kp”:30.00,“heater1_ti”:1800,“heater1_td”:60,“heater1_infilt”:1,“heater1_dfilt”:4,“heater2_kp”:30.00,“heater2_ti”:1800,“heater2_td”:60,“heater2_infilt”:1,“heater2_dfilt”:4,“cooler_kp”:20.00,“cooler_ti”:3600,“cooler_td”:300,“cooler_infilt”:1,“cooler_dfilt”:4,“beer2fridge_kp”:5.00,“beer2fridge_ti”:10800,“beer2fridge_td”:600,“beer2fridge_infilt”:1,“beer2fridge_dfilt”:4,"beer2fridge_pidMT:{“BeerTemp”:9.81,“BeerSet”:10.00,“BeerAnn”:null,“FridgeTemp”:16.93,“FridgeSet”:8.65,“FridgeAnn”:null,“Log1Temp”:null,“Log2Temp”:null,“Log3Temp”:null,“State”:0}

Oh and now it’s switching to 23 without even putting anything into the log.

[Elco]

Can you check whether you have multiple docker containers running or trying to start? Maybe 2 are interupting eachother.

docker ps -a

[colinhayes]

Looks like one to me:

pi@raspberrypi:~ $ docker ps -a
CONTAINER ID        IMAGE                 COMMAND                  CREATED             STATUS              
PORTS                      NAMES
fdd1a7b0b867        306653e4f18a          "/entrypoint.sh /wat…"   13 months ago       Up About an hour    
0.0.0.0:80-81->80-81/tcp   brewpi
8cd33d84074c        portainer/portainer   "/portainer -H unix:…"   14 months ago       Up About an hour    
0.0.0.0:9000->9000/tcp     portainer

I’m seeing more serial errors in the log, too. Could the pi or spark’s USB be failing?

I’m also getting JSON errors similar to this:

Aug 19 2019 09:23:21 JSON decode error: Expecting ':' delimiter: line 1 column 55 (char 54)
Aug 19 2019 09:23:21 Line received was: T:{"BeerTemp":9.75,"BeerSet":10.50,"BeerAnn":null,"FS:{"mode":"b","beerSet":10.50,"fridgeSet":null}

[colinhayes]

restarting the spark with a different cable while in beer constant mode, the output is this:

Aug 19 2019 13:42:03 Port setting changed to: auto
Aug 19 2019 13:42:03 Background thread for serial stopped
Aug 19 2019 13:42:03 Background thread for serial started
Aug 19 2019 13:43:20 Port setting changed to: auto
Aug 19 2019 13:43:20 Background thread for serial stopped
Aug 19 2019 13:43:21 Background thread for serial started
Aug 19 2019 14:00:21 Notification: Script started for beer '54: Tmave Specialni'
Aug 19 2019 14:00:21 Connecting to controller...
Aug 19 2019 14:00:21 Background thread for serial started
Aug 19 2019 14:00:21 Serial (re)connected for Photon [23001e001347353236343033] at port: ttyACM0
Aug 19 2019 14:00:25 Found BrewPi v0.5.10 build 0.5.10-0-gac67918, running on a Particle Photon with a V2 shield
Aug 19 2019 14:00:36 JSON decode error: Expecting ':' delimiter: line 1 column 80 (char 79)
Aug 19 2019 14:00:36 Line received was: T:{"BeerTemp":10.25,"BeerSet":10.50,"BeerAnn":null,"FridgeTemp":11.81,"FridgeSet"T:{"BeerTemp":10.25,"BeerSet":10.50,"BeerAnn":null,"FridgeTemp":11.81,"FridgeSet":11.46,"FridgeAnn":null,"Log1Temp":null,"Log2Temp":null,"Log3Temp":null,"State":0}
Aug 19 2019 14:02:22 JSON decode error: Expecting value: line 1 column 99 (char 98)
Aug 19 2019 14:02:22 Line received was: T:{"BeerTemp":10.25,"BeerSet":10.50,"BeerAnn":null,"FridgeTemp":11.93,"FridgeSet":10.83,"FridgeAnn":nS:{"mode":"b","beerSet":10.50,"fridgeSet":null}
Aug 19 2019 14:03:05 Cannot process line from controller: 2.06,"FridgeSet":11.09,"FridgeAnn":null,"Log1Temp":null,"Log2Temp":null,"Log3Temp":null,"State":0}
Aug 19 2019 14:03:36 Cannot process line from controller:

[Elco]

I don’t know why, but you are losing characters on USB.

Did you plug in anything else on the same pi or did you install something new?

A workaround would be to switch to WiFi for communication.

We’re also quite close to making BrewBlox the new stable and supported software, so you could consider upgrading to it. I am curious if it is also affected.

[colinhayes]

The pi is only connected to the spark, and has only ever been used with the spark. I only try to remember to SSH into it between brews and run updates, but sometimes it’s a few brews between this happening.

I’m going to switch to wifi communication and see how it does. After this brew I think I’m going to reinstall raspian and start from scratch on an install. And I’m definitely considering BrewBlox once it’s out of beta!

[colinhayes]

This seems to mostly be working. Log looks great, it’s sending over the set temp every few seconds (it’s ramping from 10 to 14.5 over the next five days).

But, every so often, it becomes this (screenshot following)

Before going back to the proper temp. These fluctuations don’t seem to be appearing in the graph.

[Elco]

It really looks like something else is also connecting the the spark.

Do you maybe have an old pre-docker version of brewpi on the system? Perhaps an old cron job bringing up a non-docker version of brewpi-script?

[colinhayes]

All that I can remember is that at one point the SD card became corrupted and I got a new one and started from scratch. I want to say I installed via docker then, but this was a few years ago so I’m not sure at all.

Is there a way to check?

[Elco]

Check your running processes using htop for BrewPi related things.

There should be no brewpi.py

[colinhayes]

Looks like there’s 4 and not 0.

[Elco]

Ok, check if you still have a cron job starting the old brewpi script.

Check if you have an entry in the brewpi user crontab:

sudo crontab -u brewpi

Or a file in cron.d that you have to remove:

rm /etc/cron.d/brewpi

After removing the old cron entries, restart and check whether you still have 4 scripts running with htop.

[colinhayes]

Nothing in the crontab, but there was a brewpi file in /etc/cron.d, which is gone now.

Restarted, have 2 scripts running showing in htop

I’m at almost an hour now with no set temp changes.

[Elco]

Thanks for the update. That explains all issues.

The old script was also changing the temperature and interrupting USB communication. We have a check to prevent multiple instances, but I think they could not see each other because one was inside a docker container and the other was not. I think this is resolved now.

[colinhayes]

Just weird that it decided to start doing this after however long they’ve coexisted.

Still going to wipe the pi after this brew is done.

Thanks for all the help, Elco!