hblink.py - CRITICAL UPDATE


Cort N0MJS <n0mjs@...>
 

Folks,

Today I identified and corrected to critical problems with hblink.py in CLIENT mode, and have pushed to the master branch on GitHub. The HB_Bridge branch is also affected, but not updated by me at this time. Both issues are related.

Issue 1:

Somewhere along the line, I walked away from the code half baked and never finished implementing the missed keep-alive counter. So it was not working correctly. It has not been extensively tested, but I believe it’s at least “pretty good” now. You will see some logging updates that go along with this.

Issue 2:

when incoming packets are received, the “command” length is variable. Mostly, they can be disambiguated with 4 characters. When this is possible, I only parse 4 characters as to not waste time re-parsing. The “MSTNAK” – master negative acknowledgment to the client can be disambiguated with “MSTN”… so what did I do? Started looking for the radio ID (next piece of data) at offset 4… forgetting about the “AK”… I should have started parsing at offset 6.

@ elif _command == 'MSTN': # Actually MSTNAK -- a NACK from the master
- _radio_id = _data[4:8]
+ _radio_id = _data[6:10]

This caused hblink.py in client mode to NOT honor MSTNAK and not reset the connection. Between this and Issue 1, it’s possible for hblink.py to continue thinking it’s connected to an application virtually forever. What’s worse, if the master it is connected to continues to answer keep-alives even if it’s disconnected a client (there’s one that does this), it’s hard to even troubleshoot… which I’ve been doing for days.

Minor Changes:

A few minor changes so that per-packet logging does not occur at debug. The lines are still there and commented out. Uncomment locally if you need to debug that deeply.


Extra props go out to Corey Dean, N3FE for helping troubleshoot this one - Thanks Corey.

0x49 DE N0MJS



Cort Buffington
785-865-7206


David
 

I am loading it now on my stuff to see if it will fix the issue. 

Thank you


On Fri, Feb 2, 2018 at 2:39 PM, Cort N0MJS <n0mjs@...> wrote:
Folks,

Today I identified and corrected to critical problems with hblink.py in CLIENT mode, and have pushed to the master branch on GitHub. The HB_Bridge branch is also affected, but not updated by me at this time. Both issues are related.

Issue 1:

Somewhere along the line, I walked away from the code half baked and never finished implementing the missed keep-alive counter. So it was not working correctly. It has not been extensively tested, but I believe it’s at least “pretty good” now. You will see some logging updates that go along with this.

Issue 2:

when incoming packets are received, the “command” length is variable. Mostly, they can be disambiguated with 4 characters. When this is possible, I only parse 4 characters as to not waste time re-parsing. The “MSTNAK” – master negative acknowledgment to the client can be disambiguated with “MSTN”… so what did I do? Started looking for the radio ID (next piece of data) at offset 4… forgetting about the “AK”… I should have started parsing at offset 6.

@             elif _command == 'MSTN':    # Actually MSTNAK -- a NACK from the master
-                  _radio_id = _data[4:8]
+                 _radio_id = _data[6:10]

This caused hblink.py in client mode to NOT honor MSTNAK and not reset the connection. Between this and Issue 1, it’s possible for hblink.py to continue thinking it’s connected to an application virtually forever. What’s worse, if the master it is connected to continues to answer keep-alives even if it’s disconnected a client (there’s one that does this), it’s hard to even troubleshoot… which I’ve been doing for days.

Minor Changes:

A few minor changes so that per-packet logging does not occur at debug. The lines are still there and commented out. Uncomment locally if you need to debug that deeply.


Extra props go out to Corey Dean, N3FE for helping troubleshoot this one - Thanks Corey.

0x49 DE N0MJS



Cort Buffington
785-865-7206






Steve N4IRS
 

Remember the HB_Bridge branch has not been fix yet.

Steve

On 2/2/2018 3:57 PM, David wrote:
I am loading it now on my stuff to see if it will fix the issue. 

Thank you


On Fri, Feb 2, 2018 at 2:39 PM, Cort N0MJS <n0mjs@...> wrote:
Folks,

Today I identified and corrected to critical problems with hblink.py in CLIENT mode, and have pushed to the master branch on GitHub. The HB_Bridge branch is also affected, but not updated by me at this time. Both issues are related.

Issue 1:

Somewhere along the line, I walked away from the code half baked and never finished implementing the missed keep-alive counter. So it was not working correctly. It has not been extensively tested, but I believe it’s at least “pretty good” now. You will see some logging updates that go along with this.

Issue 2:

when incoming packets are received, the “command” length is variable. Mostly, they can be disambiguated with 4 characters. When this is possible, I only parse 4 characters as to not waste time re-parsing. The “MSTNAK” – master negative acknowledgment to the client can be disambiguated with “MSTN”… so what did I do? Started looking for the radio ID (next piece of data) at offset 4… forgetting about the “AK”… I should have started parsing at offset 6.

@             elif _command == 'MSTN':    # Actually MSTNAK -- a NACK from the master
-                  _radio_id = _data[4:8]
+                 _radio_id = _data[6:10]

This caused hblink.py in client mode to NOT honor MSTNAK and not reset the connection. Between this and Issue 1, it’s possible for hblink.py to continue thinking it’s connected to an application virtually forever. What’s worse, if the master it is connected to continues to answer keep-alives even if it’s disconnected a client (there’s one that does this), it’s hard to even troubleshoot… which I’ve been doing for days.

Minor Changes:

A few minor changes so that per-packet logging does not occur at debug. The lines are still there and commented out. Uncomment locally if you need to debug that deeply.


Extra props go out to Corey Dean, N3FE for helping troubleshoot this one - Thanks Corey.

0x49 DE N0MJS



Cort Buffington
785-865-7206







Mike Zingman - N4IRR
 

HB_Bridge has taken up Cort's changes as well as updated any other component that has changed to date.


David
 

I do not remember where I found HB_Bridge the first time but I can not find the updated version.

On Fri, Feb 2, 2018 at 3:51 PM, Mike Zingman - N4IRR <mike.zingman@...> wrote:
HB_Bridge has taken up Cort's changes as well as updated any other component that has changed to date.



JJ Cummings
 

It's a branch of HBLink, just like IPSC_Bridge is a branch of DMRLink.

JJC

On Mon, Feb 5, 2018 at 6:49 AM, David <david@...> wrote:
I do not remember where I found HB_Bridge the first time but I can not find the updated version.

On Fri, Feb 2, 2018 at 3:51 PM, Mike Zingman - N4IRR <mike.zingman@...> wrote:
HB_Bridge has taken up Cort's changes as well as updated any other component that has changed to date.




Steve N4IRS
 

On 2/5/2018 8:49 AM, David wrote:
I do not remember where I found HB_Bridge the first time but I can not find the updated version.

On Fri, Feb 2, 2018 at 3:51 PM, Mike Zingman - N4IRR <mike.zingman@...> wrote:
HB_Bridge has taken up Cort's changes as well as updated any other component that has changed to date.



Cort N0MJS <n0mjs@...>
 

or if you’re using Git/Github:

"git checkout HB_Bridge”

to switch to that code locally.

On Feb 5, 2018, at 8:15 AM, Steve N4IRS <szingman@...> wrote:

https://github.com/n0mjs710/HBlink/tree/HB_Bridge

On 2/5/2018 8:49 AM, David wrote:
I do not remember where I found HB_Bridge the first time but I can not find the updated version.

On Fri, Feb 2, 2018 at 3:51 PM, Mike Zingman - N4IRR <mike.zingman@...> wrote:
HB_Bridge has taken up Cort's changes as well as updated any other component that has changed to date.



--
Cort Buffington
H: +1-785-813-1501
M: +1-785-865-7206






David
 

Here is from the logs.  Looks like it restarts ok sometimes but not always

DEBUG 2018-02-06 18:50:40,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:50:40,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 19, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:50:45,244 (REPEATER-1) Client maintenance loop started
INFO 2018-02-06 18:50:45,245 (REPEATER-1) Sending login request to master 74.91.114.19:62031
DEBUG 2018-02-06 18:50:50,243 (REPEATER-1) Client maintenance loop started
INFO 2018-02-06 18:50:50,244 (REPEATER-1) Sending login request to master 74.91.114.19:62031
INFO 2018-02-06 18:50:50,267 (REPEATER-1) Repeater Login ACK Received with 32bit ID: 758215133
INFO 2018-02-06 18:50:50,291 (REPEATER-1) Repeater Authentication Accepted
INFO 2018-02-06 18:50:50,292 (REPEATER-1) Repeater Configuration Sent
INFO 2018-02-06 18:50:50,322 (REPEATER-1) Repeater Configuration Accepted
INFO 2018-02-06 18:50:50,322 (REPEATER-1) Connection to Master Completed
DEBUG 2018-02-06 18:50:55,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:50:55,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 0, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:50:55,267 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 1
DEBUG 2018-02-06 18:51:00,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:00,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 1, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:00,265 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 2
DEBUG 2018-02-06 18:51:05,244 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:05,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 2, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:05,265 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 3
DEBUG 2018-02-06 18:51:10,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:10,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 3, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:10,263 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 4
DEBUG 2018-02-06 18:51:15,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:15,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 4, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:15,264 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 5
DEBUG 2018-02-06 18:51:20,244 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:20,245 (REPEATER-1) RPTPING Sent to Master. Total Sent: 5, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:20,266 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 6
DEBUG 2018-02-06 18:51:25,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:25,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 6, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:25,266 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 7
DEBUG 2018-02-06 18:51:30,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:30,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 7, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:35,244 (REPEATER-1) Client maintenance loop started
INFO 2018-02-06 18:51:35,244 (REPEATER-1) Sending login request to master 74.91.114.19:62031
INFO 2018-02-06 18:51:35,266 (REPEATER-1) Repeater Login ACK Received with 32bit ID: 1635208484
INFO 2018-02-06 18:51:35,290 (REPEATER-1) Repeater Authentication Accepted
INFO 2018-02-06 18:51:35,291 (REPEATER-1) Repeater Configuration Sent
DEBUG 2018-02-06 18:51:40,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:45,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:50,243 (REPEATER-1) Client maintenance loop started


On Mon, Feb 5, 2018 at 8:47 AM, Cort N0MJS <n0mjs@...> wrote:
or if you’re using Git/Github:

"git checkout HB_Bridge”

to switch to that code locally.

On Feb 5, 2018, at 8:15 AM, Steve N4IRS <szingman@...> wrote:

https://github.com/n0mjs710/HBlink/tree/HB_Bridge

On 2/5/2018 8:49 AM, David wrote:
I do not remember where I found HB_Bridge the first time but I can not find the updated version.

On Fri, Feb 2, 2018 at 3:51 PM, Mike Zingman - N4IRR <mike.zingman@...> wrote:
HB_Bridge has taken up Cort's changes as well as updated any other component that has changed to date.



--
Cort Buffington
H: +1-785-813-1501
M: +1-785-865-7206







Cort N0MJS <n0mjs@...>
 

After the reconnect, I don’t see a:

"Connection to Master Completed”

Implying we never actually get connected. The reason why is of interest, though I also need to look into why hblink.py hangs there and does not reset itself again. My guess is that I’m never checking to see if it actually completed and if not, resting it again. Something that’ll need added to the client maintenance loop.

That’s exactly the kind of info I needed to chase it down!


On Feb 7, 2018, at 5:41 AM, David <david@...> wrote:

Here is from the logs.  Looks like it restarts ok sometimes but not always

DEBUG 2018-02-06 18:50:40,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:50:40,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 19, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:50:45,244 (REPEATER-1) Client maintenance loop started
INFO 2018-02-06 18:50:45,245 (REPEATER-1) Sending login request to master 74.91.114.19:62031
DEBUG 2018-02-06 18:50:50,243 (REPEATER-1) Client maintenance loop started
INFO 2018-02-06 18:50:50,244 (REPEATER-1) Sending login request to master 74.91.114.19:62031
INFO 2018-02-06 18:50:50,267 (REPEATER-1) Repeater Login ACK Received with 32bit ID: 758215133
INFO 2018-02-06 18:50:50,291 (REPEATER-1) Repeater Authentication Accepted
INFO 2018-02-06 18:50:50,292 (REPEATER-1) Repeater Configuration Sent
INFO 2018-02-06 18:50:50,322 (REPEATER-1) Repeater Configuration Accepted
INFO 2018-02-06 18:50:50,322 (REPEATER-1) Connection to Master Completed
DEBUG 2018-02-06 18:50:55,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:50:55,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 0, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:50:55,267 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 1
DEBUG 2018-02-06 18:51:00,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:00,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 1, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:00,265 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 2
DEBUG 2018-02-06 18:51:05,244 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:05,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 2, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:05,265 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 3
DEBUG 2018-02-06 18:51:10,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:10,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 3, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:10,263 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 4
DEBUG 2018-02-06 18:51:15,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:15,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 4, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:15,264 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 5
DEBUG 2018-02-06 18:51:20,244 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:20,245 (REPEATER-1) RPTPING Sent to Master. Total Sent: 5, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:20,266 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 6
DEBUG 2018-02-06 18:51:25,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:25,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 6, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:25,266 (REPEATER-1) MSTPONG Received. Pongs Since Connected: 7
DEBUG 2018-02-06 18:51:30,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:30,244 (REPEATER-1) RPTPING Sent to Master. Total Sent: 7, Total Missed: 0, Currently Outstanding: 0
DEBUG 2018-02-06 18:51:35,244 (REPEATER-1) Client maintenance loop started
INFO 2018-02-06 18:51:35,244 (REPEATER-1) Sending login request to master 74.91.114.19:62031
INFO 2018-02-06 18:51:35,266 (REPEATER-1) Repeater Login ACK Received with 32bit ID: 1635208484
INFO 2018-02-06 18:51:35,290 (REPEATER-1) Repeater Authentication Accepted
INFO 2018-02-06 18:51:35,291 (REPEATER-1) Repeater Configuration Sent
DEBUG 2018-02-06 18:51:40,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:45,243 (REPEATER-1) Client maintenance loop started
DEBUG 2018-02-06 18:51:50,243 (REPEATER-1) Client maintenance loop started


On Mon, Feb 5, 2018 at 8:47 AM, Cort N0MJS <n0mjs@...> wrote:
or if you’re using Git/Github:

"git checkout HB_Bridge”

to switch to that code locally.

On Feb 5, 2018, at 8:15 AM, Steve N4IRS <szingman@...> wrote:

https://github.com/n0mjs710/HBlink/tree/HB_Bridge

On 2/5/2018 8:49 AM, David wrote:
I do not remember where I found HB_Bridge the first time but I can not find the updated version.

On Fri, Feb 2, 2018 at 3:51 PM, Mike Zingman - N4IRR <mike.zingman@...> wrote:
HB_Bridge has taken up Cort's changes as well as updated any other component that has changed to date.



--
Cort Buffington
H: +1-785-813-1501
M: +1-785-865-7206










Cort Buffington
785-865-7206