search

kizniche / Mycodo

An environmental monitoring and regulation system
http://kylegabriel.com/projects/
GNU General Public License v3.0
2.99k stars 499 forks source link

upgrade to 8.8.0, then 8.8.1, PCF8574 module fails to install and breaks installation #840

Closed ticomyco closed 4 years ago

ticomyco commented 4 years ago

**I saw your comment about releasing 8.8.0 for the multichannel outputs, and I upgraded my test system from 8.7.2 to 8.8.0, and then as soon as it finished I noticed that you'd released 8.8.1 so I upgraded again.

-- Same system as before -- RPi 4 with latest raspbian and the Krida relay board using the PCF8574 chip connected.

Last lines of mycodo.log are:

2020-09-09 09:52:19,943 - ERROR - mycodo.utils.outputs - Error: Cannot add output modules because it does not have a unique name: PCF8574
2020-09-09 09:52:19,953 - INFO - mycodo.outputs.on_off_shell_8b5fa089 - Initialized in 57.4 ms
2020-09-09 09:52:19,954 - INFO - mycodo.controllers.controller_output - Activated in 557.8 ms
2020-09-09 09:52:19,954 - ERROR - mycodo.controllers.controller_output - loop() Error
Traceback (most recent call last):
  File "/var/mycodo-root/mycodo/controllers/base_controller.py", line 84, in run
    self.loop()
  File "/var/mycodo-root/mycodo/controllers/controller_output.py", line 104, in loop
    self.output[output_id].output_on_until[each_channel] < datetime.datetime.now() and
KeyError: 0
2020-09-09 09:52:20,005 - ERROR - mycodo.controllers.controller_output - loop() Error
Traceback (most recent call last):
  File "/var/mycodo-root/mycodo/controllers/base_controller.py", line 84, in run
    self.loop()

(which then repeat a few thousand times)

and I've attached the mycodoupgrade.log file as well. It looks like there's a naming conflict with the PCF8574 module but I'm not sure what to do about it (such as trying to delete any configured outputs for example) because the webserver gives a 500 error with the following output when I try to load the login page, any dashboard, etc:

Error (Full Traceback):

Traceback (most recent call last):
  File "/home/pi/Mycodo/env/lib/python3.7/site-packages/flask/app.py", line 2447, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/pi/Mycodo/env/lib/python3.7/site-packages/flask/app.py", line 1952, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/home/pi/Mycodo/env/lib/python3.7/site-packages/flask_restx/api.py", line 639, in error_router
    return original_handler(e)
  File "/home/pi/Mycodo/env/lib/python3.7/site-packages/flask/app.py", line 1821, in handle_user_exception
    reraise(exc_type, exc_value, tb)
  File "/home/pi/Mycodo/env/lib/python3.7/site-packages/flask/_compat.py", line 39, in reraise
    raise value
  File "/home/pi/Mycodo/env/lib/python3.7/site-packages/flask/app.py", line 1950, in full_dispatch_request
    rv = self.dispatch_request()
  File "/home/pi/Mycodo/env/lib/python3.7/site-packages/flask/app.py", line 1936, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/home/pi/Mycodo/env/lib/python3.7/site-packages/flask_login/utils.py", line 272, in decorated_view
    return func(*args, **kwargs)
  File "/home/pi/Mycodo/mycodo/mycodo_flask/routes_page.py", line 716, in page_dashboard
    output, OutputChannel, dict_outputs, dict_units, dict_measurements)
  File "/home/pi/Mycodo/mycodo/mycodo_flask/utils/utils_general.py", line 764, in choices_outputs_channels_measurements
    choices, each_output, output_channels, dict_outputs, dict_units, dict_measurements)
  File "/home/pi/Mycodo/mycodo/mycodo_flask/utils/utils_general.py", line 1011, in form_output_channel_measurement_choices
    measurement_channels = dict_outputs[each_output.output_type]['channels_dict'][each_channel.channel]['measurements']
KeyError: 'channels_dict'

mycodoupgrade.log**

kizniche commented 4 years ago

Just for grins, (with all channels set to off in Mycodo and also off on the relay board), I changed the "on state" for only the first channel to be LOW instead of HIGH. I saved the settings and immediately the first channel on the krida board was enabled with all others disabled, and in the Mycodo interface that channel immediately turned green and indicated and active state.

You could also have just changed the Start State to On, because setup_output() (where the outputs are set to the startup state) didn't have the issue, it was in output_switch(). setup_output() successfully generated a list of 8 boolean values and passed it to port():

2020-09-09 15:09:28,581 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [True, False, False, False, False, False, False, False]

It was setup_output() that was generating a list of one boolean value (the value of the channel being switched), and causing the AssertionError to be raised:

2020-09-09 15:10:23,167 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [True]
ticomyco commented 4 years ago

Awesome -- and thanks for the detailed explanation -- I was digging through it and had realized my comment couldn't be accurate as to the cause, but hadn't yet managed to put in enough logger statements to point me in the direction for why dict_states wasn't being populated inside of output_switch() when I saw your comment. Upgrading now ...

ticomyco commented 4 years ago

So, initially I left the previously configured output as-is after the upgrade (ie, first channel is set to active LOW but all others are the default of HIGH), and I no longer get the error messages or incomplete lists sent to the relay board, however despite enabling/disabling the first channel, it remains enabled on the relay board. The other channels can be successfully enabled/disabled, and their physical state matches their state in Mycodo:

2020-09-09 16:25:34,909 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(on, 0, sec, 0.0, 0.0, True) 2020-09-09 16:25:34,910 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH0 (test5) is already on. 2020-09-09 16:25:39,827 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(off, 0, None, 0.0, 0.0, True) 2020-09-09 16:25:39,828 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [True, False, False, False, False, False, False, False] 2020-09-09 16:25:39,829 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH0 (test5) OFF at 2020-09-09 16:25:39. Output returned: success

2020-09-09 16:25:56,898 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(on, 0, sec, 0.0, 0.0, True) 2020-09-09 16:25:56,899 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH0 (test5) is already on.

2020-09-09 16:26:16,854 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(on, 2, sec, 0.0, 0.0, True) 2020-09-09 16:26:16,855 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [True, False, True, False, False, False, False, False] 2020-09-09 16:26:16,855 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH2 (test5) ON at 2020-09-09 16:26:16.854862. Output returned: success 2020-09-09 16:26:27,695 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(off, 2, None, 0.0, 0.0, True) 2020-09-09 16:26:27,695 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [True, False, False, False, False, False, False, False] 2020-09-09 16:26:27,696 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH2 (test5) OFF at 2020-09-09 16:26:27. Output returned: success 2020-09-09 16:26:39,582 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(off, 0, None, 0.0, 0.0, True) 2020-09-09 16:26:39,583 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [True, False, False, False, False, False, False, False] 2020-09-09 16:26:39,584 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH0 (test5) OFF at 2020-09-09 16:26:39. Output returned: success

After modifying the output for the first channel to be active HIGH like the other ones, as expected it performs correctly like the other ones do

2020-09-09 16:30:03,673 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - I2C: Address: 0x26, Bus: 19 2020-09-09 16:30:03,673 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [False, False, False, False, False, False, False, False] 2020-09-09 16:30:03,674 - INFO - mycodo.outputs.pcf8574_720cdb9f - Initialized in 52.4 ms

2020-09-09 16:30:13,603 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(on, 0, sec, 0.0, 0.0, True) 2020-09-09 16:30:13,604 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [True, False, False, False, False, False, False, False] 2020-09-09 16:30:13,604 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH0 (test5) ON at 2020-09-09 16:30:13.604005. Output returned: success 2020-09-09 16:30:17,910 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(off, 0, None, 0.0, 0.0, True) 2020-09-09 16:30:17,910 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [False, False, False, False, False, False, False, False] 2020-09-09 16:30:17,911 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH0 (test5) OFF at 2020-09-09 16:30:17. Output returned: success 2020-09-09 16:30:21,087 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - output_on_off(on, 2, sec, 0.0, 0.0, True) 2020-09-09 16:30:21,087 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - List sent to device: [False, False, True, False, False, False, False, False] 2020-09-09 16:30:21,088 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH2 (test5) ON at 2020-09-09 16:30:21.087753. Output returned: success

kizniche commented 4 years ago

This log line is the clue:

2020-09-09 16:25:56,899 - DEBUG - mycodo.outputs.pcf8574_720cdb9f - Output 720cdb9f-b3e4-426f-af11-a59a308f98fd CH0 (test5) is already on.

This is indicating the is_on() is returning that the channel is already on when it's requested to be turned on. If you look at the commit I just made, you can see we were merely returning the HIGH/LOW state of the channel, and not the ON/OFF state, which are different. We can get a True = On and False = Off by testing channel_state == on_state. This should be the last bug in the system.

kizniche commented 4 years ago

Let me know if that works, when you test it.

ticomyco commented 4 years ago

Hi -- I just got a chance to test this -- I upgraded to master, set the upper 4 channels to be active LOW and left the lower 4 channels to be active HIGH as default. Testing turning random channels on or off works as expected, with the channels that were set active LOW acting opposite of what their state in Mycodo.

I'd call it done! Thank you again for the explanation.

Regarding the state-tracking code for outputs, if I were to copy your pcf8574 as a template for making a python version for the mcp230xx scripts (which can have their state read from the chip directly), would you think it's a better idea to keep the state in the Mycodo DB as you've done for the PCF, then write to the chip for an output change (and possibly read from it afterwards as an extra check to verify?),

or would you think it better to just read the state from the MCP, calculate the new byte needed when an output change is requested, and write the new byte back?

kizniche commented 4 years ago

Great. For the chips that can have their pin states read, I would first do a test to time how long it takes to read a pin, then how long it takes to read all pins. If the time isn't large, I would build the module to query the pin state from the chip in the is_on() function. This is the safest way to actually know if the pin is high or low, rather than assuming or only querying intermittently.

kizniche commented 4 years ago

Fixed in latest release