Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Button press doesn't turn on/off #1031

Open
SirJMD opened this issue Jul 5, 2018 · 27 comments
Open

Button press doesn't turn on/off #1031

SirJMD opened this issue Jul 5, 2018 · 27 comments

Comments

@SirJMD
Copy link

SirJMD commented Jul 5, 2018

I've paired my remote with my Sonoff RF bridge (R2 v1.0). From the debug log I can see every single button press is being received - not a single one is lost. However, only very few of the button presses changes the state of the switch #0 (I've assigned both on and off to this switch).

Am I missing something or is there a bug?

@mcspr
Copy link
Collaborator

mcspr commented Jul 6, 2018

Hello. Can you share that debug log?

@SirJMD
Copy link
Author

SirJMD commented Jul 6, 2018

@mcspr Sure!

1st button press

[058346] [RFBRIDGE] Action 0xA4
[058349] [RFBRIDGE] Sending ACK
[058353] [RFBRIDGE] Received message '2788014A03CA11555F'
[058354] [RFBRIDGE] Trying to match code 11555F
[058364] [RFBRIDGE] Matched  message '2788014A03CA11555F'
[058367] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2788014A03CA11555F (PID 1)
[058368] [RFBRIDGE] Forward message '2788014A03CA11555F'
[060003] [MAIN] System OK

2nd button press

[074416] [RFBRIDGE] Action 0xA4
[074419] [RFBRIDGE] Sending ACK
[074423] [RFBRIDGE] Received message '27C4012C03E8114551'
[074424] [RFBRIDGE] Trying to match code 114551
[074425] [RFBRIDGE] Match ON code for relay 0
[074427] [RFBRIDGE] Matched  message '2774013603D4114551'
[074429] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2774013603D4114551 (PID 1)
[074431] [RFBRIDGE] Forward message '2774013603D4114551'
[074432] [RELAY] #0 scheduled ON in 0 ms
[074445] [RELAY] #0 set to ON
[074449] [MQTT] Sending Sonoff-RF-Bridge/relay/0 => 1 (PID 1)
[075451] [RELAY] Saving mask: 1

First time I pressed the button it received it just fine, but didn't turn on the switch. Second time it did, and it sent out the correct MQTT message.

@SirJMD
Copy link
Author

SirJMD commented Jul 6, 2018

This time it took 11 button presses to get the switch to turn on, but this time it didn't send out a MQTT message.

[246838] [RFBRIDGE] Action 0xA4
[246841] [RFBRIDGE] Sending ACK
[246845] [RFBRIDGE] Received message '2788014A03CA11455F'
[246846] [RFBRIDGE] Trying to match code 11455F
[246854] [RFBRIDGE] Matched  message '2788014A03CA11455F'
[246856] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2788014A03CA11455F (PID 1)
[246857] [RFBRIDGE] Forward message '2788014A03CA11455F'
[250948] [RFBRIDGE] Action 0xA4
[250951] [RFBRIDGE] Sending ACK
[250955] [RFBRIDGE] Received message '2788014A03CA11555F'
[250957] [RFBRIDGE] Trying to match code 11555F
[250965] [RFBRIDGE] Matched  message '2788014A03CA11555F'
[250968] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2788014A03CA11555F (PID 1)
[250971] [RFBRIDGE] Forward message '2788014A03CA11555F'
[255345] [RFBRIDGE] Action 0xA4
[255348] [RFBRIDGE] Sending ACK
[255352] [RFBRIDGE] Received message '2788014A03CA11555F'
[255353] [RFBRIDGE] Trying to match code 11555F
[255361] [RFBRIDGE] Matched  message '2788014A03CA11555F'
[255363] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2788014A03CA11555F (PID 1)
[255364] [RFBRIDGE] Forward message '2788014A03CA11555F'
[258127] [RFBRIDGE] Action 0xA4
[258130] [RFBRIDGE] Sending ACK
[258134] [RFBRIDGE] Received message '2788014A03CA11455F'
[258135] [RFBRIDGE] Trying to match code 11455F
[258142] [RFBRIDGE] Matched  message '2788014A03CA11455F'
[258145] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2788014A03CA11455F (PID 1)
[258147] [RFBRIDGE] Forward message '2788014A03CA11455F'
[260077] [RFBRIDGE] Action 0xA4
[260080] [RFBRIDGE] Sending ACK
[260083] [RFBRIDGE] Received message '2774014A03CA11555F'
[260086] [RFBRIDGE] Trying to match code 11555F
[260095] [RFBRIDGE] Matched  message '2774014A03CA11555F'
[260099] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2774014A03CA11555F (PID 1)
[260100] [RFBRIDGE] Forward message '2774014A03CA11555F'
[264232] [RFBRIDGE] Action 0xA4
[264235] [RFBRIDGE] Sending ACK
[264239] [RFBRIDGE] Received message '277E014A03CA114557'
[264242] [RFBRIDGE] Trying to match code 114557
[264250] [RFBRIDGE] Matched  message '277E014A03CA114557'
[264253] [MQTT] Sending Sonoff-RF-Bridge/rfin => 277E014A03CA114557 (PID 1)
[264255] [RFBRIDGE] Forward message '277E014A03CA114557'
[266052] [RFBRIDGE] Action 0xA4
[266055] [RFBRIDGE] Sending ACK
[266059] [RFBRIDGE] Received message '27A6014A03CA11555F'
[266061] [RFBRIDGE] Trying to match code 11555F
[266069] [RFBRIDGE] Matched  message '27A6014A03CA11555F'
[266071] [MQTT] Sending Sonoff-RF-Bridge/rfin => 27A6014A03CA11555F (PID 1)
[266073] [RFBRIDGE] Forward message '27A6014A03CA11555F'
[267335] [RFBRIDGE] Action 0xA4
[267338] [RFBRIDGE] Sending ACK
[267342] [RFBRIDGE] Received message '2788014A03CA11555F'
[267343] [RFBRIDGE] Trying to match code 11555F
[267350] [RFBRIDGE] Matched  message '2788014A03CA11555F'
[267352] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2788014A03CA11555F (PID 1)
[267355] [RFBRIDGE] Forward message '2788014A03CA11555F'
[268546] [RFBRIDGE] Action 0xA4
[268549] [RFBRIDGE] Sending ACK
[268553] [RFBRIDGE] Received message '277E014A03CA11555F'
[268554] [RFBRIDGE] Trying to match code 11555F
[268561] [RFBRIDGE] Matched  message '277E014A03CA11555F'
[268563] [MQTT] Sending Sonoff-RF-Bridge/rfin => 277E014A03CA11555F (PID 1)
[268565] [RFBRIDGE] Forward message '277E014A03CA11555F'
[269777] [RFBRIDGE] Action 0xA4
[269780] [RFBRIDGE] Sending ACK
[269784] [RFBRIDGE] Received message '279C014A03CA11555F'
[269785] [RFBRIDGE] Trying to match code 11555F
[269792] [RFBRIDGE] Matched  message '279C014A03CA11555F'
[269794] [MQTT] Sending Sonoff-RF-Bridge/rfin => 279C014A03CA11555F (PID 1)
[269796] [RFBRIDGE] Forward message '279C014A03CA11555F'
[270519] [RFBRIDGE] Action 0xA4
[270522] [RFBRIDGE] Sending ACK
[270525] [RFBRIDGE] Received message '27BA012C03E8114551'
[270527] [RFBRIDGE] Trying to match code 114551
[270528] [RFBRIDGE] Match ON code for relay 0
[270531] [RFBRIDGE] Matched  message '2774013603D4114551'
[270534] [MQTT] Sending Sonoff-RF-Bridge/rfin => 2774013603D4114551 (PID 1)
[270535] [RFBRIDGE] Forward message '2774013603D4114551'
[270549] [RELAY] #0 set to ON
[271556] [RELAY] Saving mask: 1

@mcspr
Copy link
Collaborator

mcspr commented Jul 6, 2018

Check the match code / match ON entries. Codes are different most of the time, that's why it does not switch the relay: 114557, 11555F, 114551, 11455F

Just guessing, but I had similar issue with rfbridge when it was placed near wifi router. Codes produced by it were scrambled most of the time and moving it to a different spot helped with that.

@SirJMD
Copy link
Author

SirJMD commented Jul 6, 2018

Maybe it's a faulty remote then. I'm testing about 5 meters from my AP, so it should be ok - also considering how far apart those wireless frequencies are.

Looking at the received codes, many of them are consistently wrong. Many are "2788014A03CA11555F". Interference wouldn't be consistent like that.

But it doesn't explain the issue where it turns on the switch, but doesn't publish MQTT.

@mcspr
Copy link
Collaborator

mcspr commented Jul 6, 2018

Well, 114551 is the rf code it knows (27C4 012C 03E8 114551). It does not match other ones => does not switch the relay => no mqtt relay/0 status change. It still sends codes to rfin topic judging by the log.
Replacing ON/OFF with 2774014A03CA11555F will improve matching (... with 90% success rate :) )

@SirJMD
Copy link
Author

SirJMD commented Jul 6, 2018

At the end of debug you can see it setting relay #0 to ON, but it doesn't publish to MQTT (other than the rfin).

Testing the remote it seems to often output random codes. New remotes are still in the mail..

@xoseperez
Copy link
Owner

Several things:

  • The debug messages are not very clear, the "Matched message ..." message is not always true, I'm fixing this
  • If the 3 last bytes of the code are different there is no match and no relay triggering
  • If the relay is already in ON status and you turn it on there will be no message either, same for OFF

@SirJMD
Copy link
Author

SirJMD commented Jul 10, 2018

@xoseperez Sounds great.
In the case where it didn't publish MQTT, the relay was off (that is always my starting state for any testing).

@xoseperez
Copy link
Owner

@SirJMD Can you flash the latest version in dev branch and copy here the debug log while doing the same tests as before?

@SirJMD
Copy link
Author

SirJMD commented Jul 10, 2018

Sure thing @xoseperez, I'll get right on it.

@SirJMD
Copy link
Author

SirJMD commented Jul 11, 2018

1.13.1:

[599161] [WEBSOCKET] Requested action: relay
[599164] [RELAY] #0 scheduled OFF in 0 ms
[599167] [RELAY] #0 set to OFF
[599170] [RFBRIDGE] Enqueuing MESSAGE '2774014A03CA114554' 4 time(s)
[600028] [RFBRIDGE] Action 0xA0
[600180] [RELAY] Saving mask: 0
[601026] [RFBRIDGE] Action 0xA0
[601526] [RFBRIDGE] Action 0xA0
[602641] [RFBRIDGE] Action 0xA4
[602644] [RFBRIDGE] Sending ACK
[602648] [RFBRIDGE] Received message '276A014A03CA11555F'
[602649] [RFBRIDGE] Trying to match code 11555F
[602651] [RFBRIDGE] Match ON code for relay 0
[602655] [RFBRIDGE] Matched  message '2788014A03CA11555F'
[602657] [RELAY] #0 scheduled ON in 0 ms
[602672] [RELAY] #0 set to ON
[603679] [RELAY] Saving mask: 1

First i manually set relay 0 in off-state via the web GUI. I then press the button on the remote and the RF bridge receives the correct code and turns on relay 0 - but doesn't publish MQTT.

@mcspr
Copy link
Collaborator

mcspr commented Jul 11, 2018

1.13.1 from releases:

[743011] [RFBRIDGE] Action 0xA4
[743012] [RFBRIDGE] Sending ACK
[743016] [RFBRIDGE] Received message '28AA0172043861B024'
[743017] [RFBRIDGE] Trying to match code 61B024
[743019] [RFBRIDGE] Match ON code for relay 0
[743020] [RFBRIDGE] Match OFF code for relay 0
[743021] [RFBRIDGE] Matched  message '28BE0172042E61B024'
[743023] [RELAY] #0 scheduled ON in 0 ms
[743025] [MQTT] Sending test/ESPURNA-9EFF46/rfin => 28BE0172042E61B024 (PID 1)
[743037] [RELAY] #0 set to ON
[743041] [MQTT] Sending test/ESPURNA-9EFF46/relay/0 => 1 (PID 1)
[744043] [RELAY] Saving mask: 1
[744200] [RFBRIDGE] Action 0xA4
[744203] [RFBRIDGE] Sending ACK
[744206] [RFBRIDGE] Received message '28BE0172042461B024'
[744208] [RFBRIDGE] Trying to match code 61B024
[744210] [RFBRIDGE] Match ON code for relay 0
[744212] [RFBRIDGE] Match OFF code for relay 0
[744213] [RFBRIDGE] Matched  message '28BE0172042E61B024'
[744215] [RELAY] #0 scheduled OFF in 0 ms
[744217] [MQTT] Sending test/ESPURNA-9EFF46/rfin => 28BE0172042E61B024 (PID 1)
[744229] [RELAY] #0 set to OFF
[744233] [MQTT] Sending test/ESPURNA-9EFF46/relay/0 => 0 (PID 1)
[745235] [RELAY] Saving mask: 0

Edit: some dropped logs...

Settings of relays <-> rf (via send command)

get rfbOFF0 rfbON0
[155197] > rfbOFF0 => "28BE0172042E61B024"
[155200] > rfbON0 => "28BE0172042E61B024"
[155202] +OK

I am not seeing OFF match in your logs.

@SirJMD
Copy link
Author

SirJMD commented Jul 11, 2018

Observing the MQTT telegrams with MQTTlens, I actually do get a "1" for relay 0, even though the debugger doesn't say it published anything.

I just tested with a "door open" sensor and it works 100% of the time, out of 20 tries. The debugger shows no MQTT publishes, but I get them anyway.

@xoseperez
Copy link
Owner

The second log (1.13.1 from releases) looks perfectly normal. You are using the same code for ON and OFF , the firmware detects that (it matches both) and toggles the device sending only one RF packet. Both RFIN and relay status MQTT messages are sent.

The first one is normal expect for the missing MQTT message. Is it the same device but a different remote?

@SirJMD
Copy link
Author

SirJMD commented Jul 12, 2018

@xoseperez Yes, same exact device. I've tried the same remote as well as a door sensor - both work fine, but no MQTT message in the debug log. I do however receive a MQTT message, so it does get published.

@xoseperez
Copy link
Owner

Well, the codes are different so the remote or the button you are pressing is a different one. Still, no reason why it would send the MQTT message but not print it to the debug log...

@SirJMD
Copy link
Author

SirJMD commented Jul 12, 2018

Same remote, different button :) Via MQTTlens I can see every single MQTT message, with 100% success rate, so it does indeed publish it as it should.

Are you able to replicate the bug?

@xoseperez
Copy link
Owner

No. It works fine for me. The "relay/#" MQTT message is printed in the debug log and sent to the broker if the relays status changes.

@SirJMD
Copy link
Author

SirJMD commented Jul 12, 2018

Just got a new remote in the mail today. 100% accuracy on button presses. Same code every time, so it's just my old remote that's nearing its end of life.

The only issue new is the web gui being mostly inaccessible from computer (Win7), but always working from my phone (OnePlus 5T).

@SirJMD
Copy link
Author

SirJMD commented Jul 14, 2018

Testing a bit more and I've encountered a new weird thing..

[625443] [RFBRIDGE] Sending ACK
[625447] [RFBRIDGE] Received message '34EE0186048855550C'
[625448] [RFBRIDGE] Trying to match code 55550C
[625450] [RFBRIDGE] Match ON code for relay 0
[625452] [RFBRIDGE] Match OFF code for relay 0
[625453] [RFBRIDGE] Matched  message '34E40190048855550C'
[625454] [RELAY] #0 scheduled ON in 0 ms
[625456] [MQTT] Sending Sonoff-RF-Bridge/rfin => 34E40190048855550C (PID 1)
[625469] [RELAY] #0 set to ON
[626476] [RELAY] #0 scheduled OFF in 0 ms
[626478] [RELAY] Saving mask: 3
[626577] [RELAY] #0 set to OFF
[626580] [RFBRIDGE] Enqueuing MESSAGE '34E40190048855550C' 1 time(s)
[627507] [RFBRIDGE] Action 0xA0
[627585] [RELAY] Saving mask: 2

The message it received and the message it published to rfin, are different. It also turned on and the right after turned off again.

Why does it only try to match a partial of the received message?

My RF setting is:

Switch ON   34EE0186049255550C
Switch OFF   34E40190048855550C

@xoseperez
Copy link
Owner

The actual code is the 3 last bytes (55550C). The previous bytes are times (sync, high, low), they are required but not critical. ESPurna tries to match the latest 3 bytes to the codes it has stored and uses the stored code instead of the received one (hence the difference between the codes in the "received" and "matched" lines.

On the other hand, ESPurna expects the exact same code (9 bytes) for toggle buttons (same button for ON and OFF). Since your codes are not the same ESPurna gets puzzled and triggers both actions. Change either of the two codes to match the other one and your issue will be gone.

@SirJMD
Copy link
Author

SirJMD commented Jul 20, 2018

Finally had a few minutes to test a bit more. With only a code in the ON for switch #1, I still get the ON relay #1 and the right after it turns it off again. Now it says (new remote):

[804647] [RFBRIDGE] Sending ACK
[804651] [RFBRIDGE] Received message '2904014A03FC7A31A2'
[804652] [RFBRIDGE] Trying to match code 7A31A2
[804654] [RFBRIDGE] Match ON code for relay 0
[804656] [RFBRIDGE] Matched  message '28FA014A03FC7A31A2'
[804657] [RELAY] #0 scheduled ON in 0 ms
[804659] [MQTT] Sending Sonoff-RF-Bridge/rfin => 28FA014A03FC7A31A2 (PID 1)
[804671] [RELAY] #0 set to ON
[804675] [MQTT] Sending Sonoff-RF-Bridge/relay/0 => 1 (PID 1)
[804677] [RELAY] Scheduling relay #0 back in 1000ms (pulse)
[805680] [RELAY] #0 scheduled OFF in 0 ms
[805683] [RELAY] Saving mask: 1
[805782] [RELAY] #0 set to OFF
[805785] [MQTT] Sending Sonoff-RF-Bridge/relay/0 => 0 (PID 1)
[806788] [RELAY] Saving mask: 0

Where did that Scheduling relay #0 back in 1000ms (pulse) suddenly come from? Is that due to not having an off code set? (feel free to tell me to read the documentation if it's that obvious :D )

@mcspr
Copy link
Collaborator

mcspr commented Jul 20, 2018

@SirJMD Rogue switch pulse settings? Check the Switches or these settings:

get relayTime0 relayPulse0
[715257] > relayTime0 => "1" // 1 second
[715259] > relayPulse0 => "1" // internal RELAY_PULSE_OFF, turns off ON relay after relayTime0
[715259] +OK

@SirJMD
Copy link
Author

SirJMD commented Jul 20, 2018

[572932] > relayTime0 => "1"
[572935] > relayPulse0 => "1"
[572936] +OK

So somehow it has set relayPulse0 to 1? I used set relayPulse0 0 and tested the remote again:

[144799] [RFBRIDGE] Action 0xA4
[144803] [RFBRIDGE] Sending ACK
[144807] [RFBRIDGE] Received message '28FA015403FC7A31A2'
[144808] [RFBRIDGE] Trying to match code 7A31A2
[144810] [RFBRIDGE] Match ON code for relay 0
[144811] [RFBRIDGE] Matched  message '28FA014A03FC7A31A2'
[144813] [RELAY] #0 scheduled ON in 0 ms
[145832] [RELAY] #0 scheduled OFF in 0 ms
[145835] [RELAY] Saving mask: 1
[145934] [RELAY] #0 set to OFF
[146939] [RELAY] Saving mask: 0

I guess that wasn't the way to combat the issue?

EDIT: In the switch settings I found that "Pulse mode" was set to "Normally OFF", somehow. After changing that back to "Don't pulse", it's back to working as before. Would be nice with a toggle option actually..

@xoseperez
Copy link
Owner

Sorry, I cannot reproduce the problem. Just don't see why it turns off immediately...

@xoseperez xoseperez added the bug label Jul 23, 2018
@SirJMD
Copy link
Author

SirJMD commented Jul 25, 2018

It's back to behaving normally again.. Nothing has been touched in between it not working and now. Nothing. I'll continue to do some testing.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants