[MCP23017] Status changes are slow

[tobof]

The change of a status from ON to OFF and vice versa takes a lot of time.

Configuration:

mqtt:

  ### Broker
  host: 192.168.2.13 # address or hostname

######## MCP230xx Module ########
mcp230xx:

  device_section:

    bus id: 1
    address: 0x20
    chip: MCP23017
  
    single_pin:
      pin: 0
      invert: true
      direction: output

Log output:

2019-09-26 09:55:59,854 [DEBUG] [mqtt    ] [mqttany.mqtt.client     ] Received PUBLISH (d0, q0, r0, m0), 'i2cRelay/mcp230xx/device_section/0/set', ...  (2 bytes)
2019-09-26 09:55:59,870 [DEBUG] [mcp230xx] [mqttany.mcp230xx        ] Found 'single_pin' GP00 on 'device_section' for message topic 'i2cRelay/mcp230xx/device_section/0/set'
2019-09-26 09:55:59,871 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' locked GPIO03
2019-09-26 09:55:59,873 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' locked GPIO02
2019-09-26 09:56:04,871 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' locked I2C bus '1'
2019-09-26 09:56:04,876 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' released lock on GPIO02
2019-09-26 09:56:04,876 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' released lock on GPIO03
2019-09-26 09:56:04,877 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' released lock on I2C bus '1'
2019-09-26 09:56:04,878 [DEBUG] [mcp230xx] [mqttany.mcp230xx        ] Set state 'OFF' logic HIGH from GP00 on MCP23017 'device_section' at address 0x20 on I2C bus '1'
2019-09-26 09:56:04,878 [DEBUG] [mcp230xx] [mqttany.mcp230xx        ] Read state 'OFF' logic HIGH from GP00 on MCP23017 'device_section' at address 0x20 on I2C bus '1'
2019-09-26 09:56:04,883 [DEBUG] [mqtt    ] [mqttany.mqtt.client     ] Sending PUBLISH (d0, q0, r0, m7), 'b'i2cRelay/mcp230xx/device_section/0'', ... (3 bytes)
2019-09-26 09:56:13,917 [DEBUG] [mqtt    ] [mqttany.mqtt.client     ] Received PUBLISH (d0, q0, r0, m0), 'i2cRelay/mcp230xx/device_section/0/set', ...  (3 bytes)
2019-09-26 09:56:13,923 [DEBUG] [mcp230xx] [mqttany.mcp230xx        ] Found 'single_pin' GP00 on 'device_section' for message topic 'i2cRelay/mcp230xx/device_section/0/set'
2019-09-26 09:56:13,924 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' locked GPIO03
2019-09-26 09:56:13,926 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' locked GPIO02
2019-09-26 09:56:18,924 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' locked I2C bus '1'
2019-09-26 09:56:18,929 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' released lock on GPIO02
2019-09-26 09:56:18,930 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' released lock on GPIO03
2019-09-26 09:56:18,931 [DEBUG] [mcp230xx] [mqttany                 ] Module 'mcp230xx' released lock on I2C bus '1'
2019-09-26 09:56:18,931 [DEBUG] [mcp230xx] [mqttany.mcp230xx        ] Set state 'ON' logic LOW from GP00 on MCP23017 'device_section' at address 0x20 on I2C bus '1'
2019-09-26 09:56:18,932 [DEBUG] [mcp230xx] [mqttany.mcp230xx        ] Read state 'ON' logic LOW from GP00 on MCP23017 'device_section' at address 0x20 on I2C bus '1'
2019-09-26 09:56:18,954 [DEBUG] [mqtt    ] [mqttany.mqtt.client     ] Sending PUBLISH (d0, q0, r0, m8), 'b'i2cRelay/mcp230xx/device_section/0'', ... (2 bytes)

Looks like the acquirement of the locks takes 5 seconds?!

[CrazyIvan359]

Wow that's slow. It may be unnecessary to have the bus locks actually. When I decided to use the locks I was approaching it from a microcontroller perspective, but it seems the kernel provides file-like access to the bus.

Side note: your first payload is 2 bytes but the state is set to OFF, is that correct?

[CrazyIvan359]

Are you running v0.7.1? I made I tiny change to the function that acquired the bus lock so that I wouldn't have to repeat log messages.

If so replace common.py line 191 with

if lock:
    break
else:

[tobof]

To your side note:

The status reported back via MQTT seems to be inverted:

i2cRelay/mcp230xx/relayBoard1/0/set ON
i2cRelay/mcp230xx/relayBoard1/0 OFF
i2cRelay/mcp230xx/relayBoard1/0/set OFF
i2cRelay/mcp230xx/relayBoard1/0 ON
i2cRelay/mcp230xx/relayBoard1/0/set ON
i2cRelay/mcp230xx/relayBoard1/0 OFF

The output of the MCP23017 is okay.

A poll afterwards is okay:

i2cRelay/mcp230xx/relayBoard1/0/poll ON
i2cRelay/mcp230xx/relayBoard1/0 ON

[tobof]

Yes, I'm running 0.7.1!

2019-09-26 11:16:20,554 [INFO ] [mqttany ] [mqttany                 ] MQTTany 0.7.1 starting

[CrazyIvan359]

The status reported back via MQTT seems to be inverted

I thought I had fixed this, I will look into it.

[CrazyIvan359]

You must be running the dev version to have the lock delay bug. I need to identify dev versions better in the logs...

I'm going to push some commits that fix these issues, would you mind testing before I make it a release?

[tobof]

I am running dev, yes.

Both problems are fixed in dev now!

Thank you!

[CrazyIvan359]

Thank you for reporting and testing!

Let me know if you find anything else or have any suggestions. There's also a room over on Gitter I'd you have any questions.