I just compared the traces between OEM-SW (logs via portmon) and the debug-log of chirp:

OEM-SW sends:
605 0.00183710 UV3BAND_E_CPS.e IRP_MJ_WRITE Serial4 SUCCESS Length 1: 06

613 0.00227850 UV3BAND_E_CPS.e IRP_MJ_WRITE Serial4 SUCCESS Length 1: 53

617 0.00195919 UV3BAND_E_CPS.e IRP_MJ_WRITE Serial4 SUCCESS Length 1: 00

623 0.00099817 UV3BAND_E_CPS.e IRP_MJ_WRITE Serial4 SUCCESS Length 1: 00

629 0.00198657 UV3BAND_E_CPS.e IRP_MJ_WRITE Serial4 SUCCESS Length 1: 40

Radio sends:
1050 0.00000838 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 06

1052 0.00001090 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 58

1054 0.00000810 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 00

1056 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 00

1058 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 40

1060 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 25

1062 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1064 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1066 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1068 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1070 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1072 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1074 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1076 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1078 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1080 0.00001117 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1082 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1084 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1086 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1088 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1090 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1092 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 00

1094 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 50

1096 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 89

1098 0.00000810 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 43

1100 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 00

1102 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 50

1104 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 89

1106 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 43

1108 0.00000810 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 00

1110 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 00

1112 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 56

1114 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 06

1116 0.00000754 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 50

1118 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 00

1120 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 01

1122 0.00000810 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: 48

1124 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1126 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1128 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1130 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1132 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1134 0.00000950 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1136 0.00000810 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1138 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1140 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1142 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1144 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1146 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1148 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1150 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1152 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1154 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1156 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1158 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1160 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1162 0.00000810 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1164 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1166 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1168 0.00000810 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1170 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1172 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1174 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1176 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1178 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1180 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1182 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1184 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

1186 0.00000782 UV3BAND_E_CPS.e IRP_MJ_READ Serial4 SUCCESS Length 1: FF

Chirp sends:
[2016-09-08 08:05:49,346] chirp.drivers.btech - DEBUG: ==> (5) bytes:

000: 06 53 00 00 40 00 00 00 .S..@...

Chirp receives:
[2016-09-08 08:05:49,450] chirp.drivers.btech - DEBUG: <== (69) bytes:

000: 06 05 58 00 00 40 25 ff ..X..@%.
008: ff ff ff ff ff ff ff ff ........
016: ff ff ff ff ff ff 00 50 .......P
024: 89 43 00 50 89 43 00 00 .C.P.C..
032: 56 06 50 00 01 48 ff ff V.P..H..
040: ff ff ff ff ff ff ff ff ........
048: ff ff ff ff ff ff ff ff ........
056: ff ff ff ff ff ff ff ff ........
064: ff ff ff ff ff 00 00 00 ........

=> in case of chirp, the second byte (0x05) byte is wrong (without that byte, chirp would be able to decode the message).
I am unable to tell whether:

• the debug.log is wrong
• the radio indeed sends different headers to chirp than it does with the oem-SW
• whether there is a low-level error in the linux-serial-driver or the python-library for serial communication, that inserts that addidional byte. But in that case, also different radios might behave strange?

Does anyone know a serial-port-monitoring tool for linux?
I will try to install chirp (daily) on windows, and create a portmon-log. This however might take a while...

BTW FYI:

I have found that the bad \x05 byte sent by the radio make it non responsive to further commands from the PC. I have crafted a dev version of the driver that detect's the bad \x05 and restart the process for a few times recursively but in the tests with some other users it don't worked as expected: it keeps failing.

Even cleaning the buffer before asking for the data in this particular moment is of no help, the bad placed \x05 is generated by the MCU, it's not generated before hand.

One thing that puzzle me is that this bug/feature is almost exclusive of Linux OS, I have managed to catch a log in this site for portmon (windows) with a radio giving the \x05 and the CPS software restarted the comm process... that's why my hypothesis of it being a flag for kind of: "no go, busy here, restart it over".

73 Pavel CO7WT.

Hi Pavel,

of course I'm willing and interested to support you with tests.
Maybe I can even give you access to my serial port using a tool like http://lpccomp.bc.ca/remserial/ - let me know what you think about that.

Maybe the whole thing is related to timing? In the one case, where I send the commands manually (which is a very indeterministic timing behaviour ;-) ) i did not receive the x05.

BTW: My radio keeps somehow responsive: at least it reacts on a consecutive 55 20 15 09 25 01 4D 02 and reboots ...

73 de Michael, OE4AMW

until now, i was not sucessful in finding the "05" with the OEM-software.
However, I found a way to avoid it in linux, by adding delay of 0.01sec after each byte in "_send":

def _send(radio, data):
"""Send data to the radio device"""

try:
    for byte in data:
        radio.pipe.write(byte)
        sleep(0.01)

this of course slows down the whole process, however, without that line, in > than 90% of the cases the download fails, with that line, it worked every time (until now).
So, my assumption is: chirp on linux is too fast for the serial port of the radio ...

The new, uploaded Windows version now worksl like a charm on my KT-8900R. Thank you so very much!

Kristian Thomassen wrote:

The new, uploaded Windows version now works like a charm on my KT-8900R. Thank you so very much!

You are welcomed, 73

Thanks for this fix - I'll give it a try this evening (UTC-6) if I can find time, and report back.

73
Jim VE5EIS

Hi,

I've just tried btech_2.py on my Linux 14.04 LTS connected to a Baofeng UV-5001. Downloading and uploading to the radio using the official Baofeng cable worked like a charm (which was not the case before this update). Thanks for the awesome work guys!

Hi,

glad to hear that. Can you uplad a debug.log of the procedure? I'd like to understand how your radio behaves (and why the upload also works - I thought my changes will only affect download ...).

Hi to all, thanks for the fix and bug hunt (import sleep... GGRRR)

I'm on a hurry now from a WiFi in a public square, last night I spend a few hour reviewing logs and I have a theory of why this slow down works (and that will be the confirmation of Linux being too fast on the serial :0, at least for this code.)

I'm downloading everything to review it in the night and comment with calm tomorrow, I would like to hear about a Waccom mini 8900 user under linux...

73 Pavel CO7WT.

Hi,

I´m quite curious about your analysis / theory of the root-cause.
Which solution do you prefer? Statically slowing down for all linux-users? Or trying without delay first, and retrying delayed in case of errors (btech_2.py)?

Furthermore, you mentioned that x05-problem also happens (rarely) also on windows. It would be fine to have also reports from affected windows-users.

73 Michael OE4AMW

I only had time for a quick check this morning. I tried two radios. BTECH UV-2501+220 and WACCOM Mini-8900Plus

Both radios failed the first download attempt when downloading with the default CHIRP driver. After loading the test driver module, both downloaded successfully. Switch back to default, download failed. Load special driver again, success. The btech_2.py definitely made a difference.

Jim KC9HI

Jim Unroe wrote:

I only had time for a quick check this morning. I tried two radios. BTECH UV-2501+220 and WACCOM Mini-8900Plus

Both radios failed the first download attempt when downloading with the default CHIRP driver. After loading the test driver module, both downloaded successfully. Switch back to default, download failed. Load special driver again, success. The btech_2.py definitely made a difference.

Jim KC9HI

Hi Jim, good to know.

So far we have confirmed it's working on the following models:

• Waccom Mini 8900 Plus
• BTECH UV-5001
• BTECH UV-2501+220
• QYT KT8900
• QYT KT9000R

That's pretty much 90% of the affected models, so it's time for a patch. My thanks and acknowledge to Michael Wagner in the name of the Chirp team & users for finding and fixing this bug.

73 Pavel CO7WT.

I just purchased a BTECH UV-2501+220, and with the help of this patch, am able to upload/download to it from my Fedora Linux 24 box - thanks!

I have one issue that may or may not be related. While most of the channel data appears to be uploaded properly, each channel displays the frequency of Channel 0. I've verified each channel is configured properly, with that one exception.

Any ideas?

Thanks.

73 - Orv - W6BI

Michael Wagner wrote:

(...) I´m quite curious about your analysis / theory of the root-cause. (...)
(...)
73 Michael OE4AMW

I was in debt with the explanation for my theory about this, please note that this is a speculation from my side; Aka: I'm maybe wrong here.

The question here is why this bug affects only Linux based systems and why the delay in the writes solved the issue.

It's a know fact that Linux kernel based operating systems have a more precise and have more granular control over time sensitive applications/operations, for example: Python in Linux can control delays in the order of 1 msec, but python in any Desktop version os MS Windows can only go as low as 5 msecs in modern versions.

Yes, it's a fact backed up with data: google the terms "python timing issues linux vs windows" and you will find a lot of data about it. The numbers I state there (1 vs 5 msecs) are taken from those public data & tests on the internet.

I found an issue in the serial portmon logs latter in the investigations of why this patch worked: on the write operations every write take between 3 to 5 msecs to process it, but at 9600 baud the write operation must take no longer of 1 msec for each individual byte write. I think in that time that was a result of the MS Window time granularity control, but now it appears not.

Maybe some of the MCUs (Micro Controller Units, aka brains of the radio) for the affected models are prepared/instructed/slow to handle serial RX operations (writes from the PC) in intervals of about 5 msecs each byte and no more than that. (This is not rare, some other radios do this for CAT commands, see the source in the hamlib project for more details)

The early versions of this drivers used to have another download/upload strategy that don't have this problem (I think it was top speed at that time) but Dan and others revealed that we are just slowing down the read/writes and getting 100% of the CPU (which match the latter findings, being slow and getting time to the MCU to answer back), so we switched to the actual strategy that's more fast and less resource intensive... and get hit by this problem.

So, my conclusions are that some of the MCU in this radios need a pace of about 5 msecs between writes to be safe or it will trough a misplaced 0x05 char in the stream to sign for a error, and that spoils the download/upload process in Linux with Chirp, the OEM software is prepared for this and just restart the process with a bigger delay as logs shows.

Windows with a worst time granularity rarely get hits by this bug and when it's the OEM software knows what to do, Linux OS in the other hand (No OEM Software for Linux so we are talking about Chirp here) is so fast that it get hit more often, and we have a bug here. Then just slowing the writes in Linux OSs solved it.

About the preferred strategy, I think your way is the best as it get two checkpoints for the signs of a "too fast" operation and get slowed just once flagged, that way both Linux and Windows OS get safe in case of a trouble.

With the actual proliferation of variants and clones for this family it's not rare to find one of them failing on windows soon, so this is the way to go.

73 Pavel CO7WT

Orv Beach wrote:

I just purchased a BTECH UV-2501+220, and with the help of this patch, am able to upload/download to it from my Fedora Linux 24 box - thanks!

I have one issue that may or may not be related. While most of the channel data appears to be uploaded properly, each channel displays the frequency of Channel 0. I've verified each channel is configured properly, with that one exception.

Any ideas?

Thanks.

73 - Orv - W6BI

Hi Orv,

I´m afraid that this issue is not related ... I suggest waiting for this patch to be included in the daily build, and (if it still persist) opening a new issue for it.

Br,
Michael

After discussion with Dan Smith ( http://intrepid.danplanet.com/pipermail/chirp_devel/2016-September/004264.html ) I added a new patch, that pretty much looks like in post #9 (with shorter delay ...)
http://intrepid.danplanet.com/pipermail/chirp_devel/2016-September/004265.html

73,
OE4AMW

Retested with chirp-daily 20160926~xenial~1 - from my point of view, ticket can be closed.