Extra data is being transmitted with SC16IS752 connected to I2C

[ApiumJacob]

Describe the bug

Extra data is being transmitted with SC16IS752 connected to I2C bus on Raspberry Pi running Jessie, Stretch, Buster or Bullseye. However, I have a version of Raspian that can best be described as a Frankenstein Monster version that I believe is the result of a failed distribution upgrade. In this Frankenstein version the problem described above and below does not exits.

Per the recommendation of Phil Elwell, I have captured runs of trying to transmit 256 bytes of data [0x00-0xFF] using a Saleae Logic Analyzer. I have done this both the working Frankenstein version of Raspian and an "out of the box" Buster (this run may actually come for an upgraded Jessie, but an out of the box version does the same thing).

Both files represents the same 256 bytes of data being transmitted yet the Buster-Bad file logged over 20K of I2C communications. The Frankenstein-Good version of the OS had in the neighborhood of 512 bytes of I2C data (which is what would be expected due to the heavy protocol overhead of I2C). Both of these files come from the same hardware setup and differ primarily by the OS that is running on them.

Buster-Bad I2C.csv
Frankenstein-Good no inter byte delay I2C.csv

While I have been trying to unravel this mystery I've been posting about it here: https://forums.raspberrypi.com/viewtopic.php?t=328190 but the summary in this issue is probably more concise that the thread. At least once while posting I fooled myself and posted what I now believe to be incorrect information.

I am invested heavily in finding and getting a solution rolled into Raspian so that we do not have to tip toe around the issue in the future nor be stuck using this Frankenstein image.

Steps to reproduce the behaviour

1. Fresh install of jessie, stretch, buster, bullseye on a Raspberry Pi 3B with SC16IS752 installed connected to I2C1 (BCM2, BCM3, pins 3 &5) with the interrupt connected to (BCM24, pin 18). I'm currently using a custom board with two of these chips, but the waveshare board should be equivalent to my setup (I have seen the problem with both a single or double chip configuration).

• https://www.waveshare.com/serial-expansion-hat.htm

2. add ssh file to /boot to allow ssh'ing into the device
3. Update /boot/config.txt to the following:

# For more options and information see
# http://rpf.io/configtxt
# Some settings may impact device functionality. See link above for details

# uncomment if you get no picture on HDMI for a default "safe" mode
#hdmi_safe=1

# uncomment this if your display has a black border of unused pixels visible
# and your display can output without overscan
#disable_overscan=1

# uncomment the following to adjust overscan. Use positive numbers if console
# goes off screen, and negative if there is too much border
#overscan_left=16
#overscan_right=16
#overscan_top=16
#overscan_bottom=16

# uncomment to force a console size. By default it will be display's size minus
# overscan.
#framebuffer_width=1280
#framebuffer_height=720

# uncomment if hdmi display is not detected and composite is being output
#hdmi_force_hotplug=1

# uncomment to force a specific HDMI mode (this will force VGA)
#hdmi_group=1
#hdmi_mode=1

# uncomment to force a HDMI mode rather than DVI. This can make audio work in
# DMT (computer monitor) modes
#hdmi_drive=2

# uncomment to increase signal to HDMI, if you have interference, blanking, or
# no display
#config_hdmi_boost=4

# uncomment for composite PAL
#sdtv_mode=2

#uncomment to overclock the arm. 700 MHz is the default.
#arm_freq=800

# Uncomment some or all of these to enable the optional hardware interfaces
dtparam=i2c_arm=on
#dtparam=i2s=on
#dtparam=spi=on

# Uncomment this to enable infrared communication.
#dtoverlay=gpio-ir,gpio_pin=17
#dtoverlay=gpio-ir-tx,gpio_pin=18

# Additional overlays and parameters are documented /boot/overlays/README

# Enable audio (loads snd_bcm2835)
dtparam=audio=on

[pi4]
# Enable DRM VC4 V3D driver on top of the dispmanx display stack
dtoverlay=vc4-fkms-v3d
max_framebuffers=2

[all]
#dtoverlay=vc4-fkms-v3d
dtoverlay=disable-bt
enable_uart=1
dtoverlay=sc16is752-i2c,int_pin=24,addr=0x48
dtoverlay=sc16is752-i2c,int_pin=23,addr=0x49
dtparam=i2c_arm_baudrate=400000
#dtoverlay=i2c-rtc,pcf8523
#dtoverlay=i2c-rtc,ds3231

4. boot the pi
5. ssh into p
6. Clone this simple project to transmit 256 bytes of data [0x00-0xFF]
   git clone https://github.com/ApiumJacob/rxtx
7. edit tx.c to set the port_name to /dev/ttySC0 if only one SC16IS752 is connected or /dev/ttySC2 if two SC16IS752's are connected.
   char port_name[] = "/dev/ttySC0";
8. Build rx program

cd rxtx
make

9. run tx
   ./tx

Monitor the I2C bus or the incoming data with the rx program to see the excess data being transmitted.

Device (s)

Raspberry Pi 3 Mod. B

System

From the bad pi:

pi@SwarmBridge-09999:~ $ cat /etc/rpi-issue
Raspberry Pi reference 2020-02-13
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 5f884374b6ac6e155330c58caa1fb7249b8badf1, stage2

pi@SwarmBridge-09999:~ $ vcgencmd version
Dec  1 2021 15:07:06 
Copyright (c) 2012 Broadcom
version 71bd3109023a0c8575585ba87cbb374d2eeb038f (clean) (release) (start)

pi@SwarmBridge-09999:~ $ uname -a
Linux SwarmBridge-09999 5.10.63-v7+ #1496 SMP Wed Dec 1 15:58:11 GMT 2021 armv7l GNU/Linux

From the good pi:

pi@SwarmBridge-09999:~ $ cat /etc/rpi-issue
Raspberry Pi reference 2020-02-13
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 5f884374b6ac6e155330c58caa1fb7249b8badf1, stage2

pi@SwarmBridge-09999:~ $ vcgencmd version
Feb 12 2020 12:38:08 
Copyright (c) 2012 Broadcom
version 53a54c770c493957d99bf49762dfabc4eee00e45 (clean) (release) (start)

pi@SwarmBridge-09999:~ $ uname -a
Linux SwarmBridge-09999 4.19.97-v7+ #1294 SMP Thu Jan 30 13:15:58 GMT 2020 armv7l GNU/Linux

Logs

From the bad pi:
dmesg-bad.txt
From the good pi:
dmesg-good.txt

Additional context

No response

[pelwell]

Sending data as individual bytes has a huge protocol overhead - ignoring starts and stops etc. I see 23 bytes being transferred for every single byte being sent to the UART, i.e. 22 overhead + 1 payload. Larger transfers are sent in groups of 30 bytes, with each group preceded by between 10 and about 30 bytes (it depends on the timing, since the driver is polling a FIFO status flag in the UART).

There is no evidence here of anything untoward, just the efficiency of sending data in bulk.

[ApiumJacob]

My apologies, when I ran the data yesterday I was so confident (and an bit lazy) that there was an error that I didn't look at the output, if there is a long enough delay between inter byte data there are no errors. The last time I tested 2ms produced lots of errors so I just assumed they were there. Mea culpa.

Here is a run with with verify bad data and its easier to digest (as the data is sent in larger groups) so there is not 20k work of data. But in the past I have received 30k worth of data when only sending 256 bytes. In these runs the inter byte delay has been removed (because I know it very reliably produces errors):

output from tx program:

$ ./tx 

Total written 0x0000:[00][01][02][03][04][05][06][07][08][09][0a][0b][0c][0d][0e][0f]
Total written 0x0010:[10][11][12][13][14][15][16][17][18][19][1a][1b][1c][1d][1e][1f]
Total written 0x0020:[20][21][22][23][24][25][26][27][28][29][2a][2b][2c][2d][2e][2f]
Total written 0x0030:[30][31][32][33][34][35][36][37][38][39][3a][3b][3c][3d][3e][3f]
Total written 0x0040:[40][41][42][43][44][45][46][47][48][49][4a][4b][4c][4d][4e][4f]
Total written 0x0050:[50][51][52][53][54][55][56][57][58][59][5a][5b][5c][5d][5e][5f]
Total written 0x0060:[60][61][62][63][64][65][66][67][68][69][6a][6b][6c][6d][6e][6f]
Total written 0x0070:[70][71][72][73][74][75][76][77][78][79][7a][7b][7c][7d][7e][7f]
Total written 0x0080:[80][81][82][83][84][85][86][87][88][89][8a][8b][8c][8d][8e][8f]
Total written 0x0090:[90][91][92][93][94][95][96][97][98][99][9a][9b][9c][9d][9e][9f]
Total written 0x00a0:[a0][a1][a2][a3][a4][a5][a6][a7][a8][a9][aa][ab][ac][ad][ae][af]
Total written 0x00b0:[b0][b1][b2][b3][b4][b5][b6][b7][b8][b9][ba][bb][bc][bd][be][bf]
Total written 0x00c0:[c0][c1][c2][c3][c4][c5][c6][c7][c8][c9][ca][cb][cc][cd][ce][cf]
Total written 0x00d0:[d0][d1][d2][d3][d4][d5][d6][d7][d8][d9][da][db][dc][dd][de][df]
Total written 0x00e0:[e0][e1][e2][e3][e4][e5][e6][e7][e8][e9][ea][eb][ec][ed][ee][ef]
Total written 0x00f0:[f0][f1][f2][f3][f4][f5][f6][f7][f8][f9][fa][fb][fc][fd][fe][ff]

Total bytes transmitted: 256.

output from rx program:

Total read 0x0000: 00  01  02  03  04  05  06 {31}{32}{33}{34}{35}{36}{37}{38}{39}
Total read 0x0010:{3a}{3b}{3c}{3d}{3e}{3f}{40}{41}{42}{43}{44}{45}{46}{47}{48}{49}
Total read 0x0020:{4a}{4b}{4c}{4d}{4e}{4f}{50}{51} 28  29  2a  2b  2c  2d  2e  2f 
Total read 0x0030: 30  31  32  33  34  35  36  37  38  39  3a  3b  3c  3d  3e  3f 
Total read 0x0040: 40  41  42  43  44  45  46  47  48  49  4a  4b  4c  4d  4e  4f 
Total read 0x0050: 50  51  52  53  54  55  56  57  58  59  5a  5b  5c  5d  5e  5f 
Total read 0x0060: 60  61  62  63  64  65  66  67  68  69  6a  6b  6c  6d  6e  6f 
Total read 0x0070: 70  71  72  73  74  75  76  77  78  79  7a  7b  7c  7d  7e  7f 
Total read 0x0080: 80  81  82  83  84  85  86  87  88  89  8a  8b  8c  8d  8e  8f 
Total read 0x0090: 90  91  92  93  94  95  96  97  98  99  9a  9b  9c  9d  9e  9f 
Total read 0x00a0: a0  a1  a2  a3  a4  a5  a6  a7  a8  a9  aa  ab  ac  ad  ae  af 
Total read 0x00b0: b0  b1  b2  b3  b4  b5  b6  b7  b8  b9  ba  bb  bc  bd  be  bf 
Total read 0x00c0: c0  c1  c2  c3  c4  c5  c6  c7  c8  c9  ca  cb  cc  cd  ce  cf 
Total read 0x00d0: d0  d1  d2  d3  d4  d5  d6  d7  d8  d9  da  db  dc  dd  de  df 
Total read 0x00e0: e0  e1  e2  e3  e4  e5  e6  e7  e8  e9  ea  eb  ec  ed  ee  ef 
Total read 0x00f0: f0  f1  f2  f3  f4  f5  f6  f7  f8  f9  fa  fb  fc  fd  fe  ff 

Total bytes received: 256.
flushing receive buffer...

Total bytes flushed: 0.

Bytes 0x07 - 0x27 are received incorrectly (errors wrapped in {handle bars}).

Trace:

Start of bad data at byte 0x07:

The I2C data from the protocol analyzer which shows the incorrect data in the same places:
Buster-Bad I2C - 2022-02-11.csv

Here are some additional runs. The received data always seems to be offset from the expected value but the offset is not always the same.

Total bytes flushed: 0.

Total read 0x0000: 00  01  02  03 {44}{45}{46}{47}{48}{49}{4a}{4b}{4c}{4d}{4e}{4f}
Total read 0x0010:{50}{51}{52}{53}{54}{55}{56}{57}{58}{59}{5a}{5b}{5c}{5d}{5e}{5f}
Total read 0x0020:{60}{61}{62}{63}{64}{65} 26  27  28  29  2a  2b  2c  2d  2e  2f 
Total read 0x0030: 30  31  32  33  34  35  36  37  38  39  3a  3b  3c  3d  3e  3f 
Total read 0x0040: 40  41  42  43  44  45  46  47  48  49  4a  4b  4c  4d  4e  4f 
Total read 0x0050: 50  51  52  53  54  55  56  57  58  59  5a  5b  5c  5d  5e  5f 
Total read 0x0060: 60  61  62  63  64  65  66  67  68  69  6a  6b  6c  6d  6e  6f 
Total read 0x0070: 70  71  72  73  74  75  76  77  78  79  7a  7b  7c  7d  7e  7f 
Total read 0x0080: 80  81  82  83  84  85  86  87  88  89  8a  8b  8c  8d  8e  8f 
Total read 0x0090: 90  91  92  93  94  95  96  97  98  99  9a  9b  9c  9d  9e  9f 
Total read 0x00a0: a0  a1  a2  a3  a4  a5  a6  a7  a8  a9  aa  ab  ac  ad  ae  af 
Total read 0x00b0: b0  b1  b2  b3  b4  b5  b6  b7  b8  b9  ba  bb  bc  bd  be  bf 
Total read 0x00c0: c0  c1  c2  c3  c4  c5  c6  c7  c8  c9  ca  cb  cc  cd  ce  cf 
Total read 0x00d0: d0  d1  d2  d3  d4  d5  d6  d7  d8  d9  da  db  dc  dd  de  df 
Total read 0x00e0: e0  e1  e2  e3  e4  e5  e6  e7  e8  e9  ea  eb  ec  ed  ee  ef 
Total read 0x00f0: f0  f1  f2  f3  f4  f5  f6  f7  f8  f9  fa  fb  fc  fd  fe  ff 

Total bytes received: 256.
flushing receive buffer...

Total bytes flushed: 0.

Total read 0x0000: 00  01  02  03  04  05 {2f}{30}{31}{32}{33}{34}{35}{36}{37}{38}
Total read 0x0010:{39}{3a}{3b}{3c}{3d}{3e}{3f}{40}{41}{42}{43}{44}{45}{46}{47}{48}
Total read 0x0020:{49}{4a}{4b}{4c} 24  25  26  27  28  29  2a  2b  2c  2d  2e  2f 
Total read 0x0030: 30  31  32  33  34  35  36  37  38  39  3a  3b  3c  3d  3e  3f 
Total read 0x0040: 40  41  42  43  44  45  46  47  48  49  4a  4b  4c  4d  4e  4f 
Total read 0x0050: 50  51  52  53  54  55  56  57  58  59  5a  5b  5c  5d  5e  5f 
Total read 0x0060: 60  61  62  63  64  65  66  67  68  69  6a  6b  6c  6d  6e  6f 
Total read 0x0070: 70  71  72  73  74  75  76  77  78  79  7a  7b  7c  7d  7e  7f 
Total read 0x0080: 80  81  82  83  84  85  86  87  88  89  8a  8b  8c  8d  8e  8f 
Total read 0x0090: 90  91  92  93  94  95  96  97  98  99  9a  9b  9c  9d  9e  9f 
Total read 0x00a0: a0  a1  a2  a3  a4  a5  a6  a7  a8  a9  aa  ab  ac  ad  ae  af 
Total read 0x00b0: b0  b1  b2  b3  b4  b5  b6  b7  b8  b9  ba  bb  bc  bd  be  bf 
Total read 0x00c0: c0  c1  c2  c3  c4  c5  c6  c7  c8  c9  ca  cb  cc  cd  ce  cf 
Total read 0x00d0: d0  d1  d2  d3  d4  d5  d6  d7  d8  d9  da  db  dc  dd  de  df 
Total read 0x00e0: e0  e1  e2  e3  e4  e5  e6  e7  e8  e9  ea  eb  ec  ed  ee  ef 
Total read 0x00f0: f0  f1  f2  f3  f4  f5  f6  f7  f8  f9  fa  fb  fc  fd  fe  ff 

Total bytes received: 256.
flushing receive buffer...

Total bytes flushed: 0.

Total read 0x0000: 00  01  02  03  04  05 {25}{26}{27}{28}{29}{2a}{2b}{2c}{2d}{2e}
Total read 0x0010:{2f}{30}{31}{32}{33}{34}{35}{36}{37}{38}{39}{3a} 1c  1d  1e  1f 
Total read 0x0020: 20  21  22  23  24  25  26  27  28  29  2a  2b  2c  2d  2e  2f 
Total read 0x0030: 30  31  32  33  34  35  36  37  38  39  3a  3b  3c  3d  3e  3f 
Total read 0x0040: 40  41  42  43  44  45  46  47  48  49  4a  4b  4c  4d  4e  4f 
Total read 0x0050: 50  51  52  53  54  55  56  57  58  59  5a  5b  5c  5d  5e  5f 
Total read 0x0060: 60  61  62  63  64  65  66  67  68  69  6a  6b  6c  6d  6e  6f 
Total read 0x0070: 70  71  72  73  74  75  76  77  78  79  7a  7b  7c  7d  7e  7f 
Total read 0x0080: 80  81  82  83  84  85  86  87  88  89  8a  8b  8c  8d  8e  8f 
Total read 0x0090: 90  91  92  93  94  95  96  97  98  99  9a  9b  9c  9d  9e  9f 
Total read 0x00a0: a0  a1  a2  a3  a4  a5  a6  a7  a8  a9  aa  ab  ac  ad  ae  af 
Total read 0x00b0: b0  b1  b2  b3  b4  b5  b6  b7  b8  b9  ba  bb  bc  bd  be  bf 
Total read 0x00c0: c0  c1  c2  c3  c4  c5  c6  c7  c8  c9  ca  cb  cc  cd  ce  cf 
Total read 0x00d0: d0  d1  d2  d3  d4  d5  d6  d7  d8  d9  da  db  dc  dd  de  df 
Total read 0x00e0: e0  e1  e2  e3  e4  e5  e6  e7  e8  e9  ea  eb  ec  ed  ee  ef 
Total read 0x00f0: f0  f1  f2  f3  f4  f5  f6  f7  f8  f9  fa  fb  fc  fd  fe  ff 

Total bytes received: 256.
flushing receive buffer...

Total bytes flushed: 0.

Now for the fun stuff. Here I have set the inter byte delay to 100us and then transmit 256 bytes:

$ ./tx 

Total written 0x0000:[00][01][02][03][04][05][06][07][08][09][0a][0b][0c][0d][0e][0f]
Total written 0x0010:[10][11][12][13][14][15][16][17][18][19][1a][1b][1c][1d][1e][1f]
Total written 0x0020:[20][21][22][23][24][25][26][27][28][29][2a][2b][2c][2d][2e][2f]
Total written 0x0030:[30][31][32][33][34][35][36][37][38][39][3a][3b][3c][3d][3e][3f]
Total written 0x0040:[40][41][42][43][44][45][46][47][48][49][4a][4b][4c][4d][4e][4f]
Total written 0x0050:[50][51][52][53][54][55][56][57][58][59][5a][5b][5c][5d][5e][5f]
Total written 0x0060:[60][61][62][63][64][65][66][67][68][69][6a][6b][6c][6d][6e][6f]
Total written 0x0070:[70][71][72][73][74][75][76][77][78][79][7a][7b][7c][7d][7e][7f]
Total written 0x0080:[80][81][82][83][84][85][86][87][88][89][8a][8b][8c][8d][8e][8f]
Total written 0x0090:[90][91][92][93][94][95][96][97][98][99][9a][9b][9c][9d][9e][9f]
Total written 0x00a0:[a0][a1][a2][a3][a4][a5][a6][a7][a8][a9][aa][ab][ac][ad][ae][af]
Total written 0x00b0:[b0][b1][b2][b3][b4][b5][b6][b7][b8][b9][ba][bb][bc][bd][be][bf]
Total written 0x00c0:[c0][c1][c2][c3][c4][c5][c6][c7][c8][c9][ca][cb][cc][cd][ce][cf]
Total written 0x00d0:[d0][d1][d2][d3][d4][d5][d6][d7][d8][d9][da][db][dc][dd][de][df]
Total written 0x00e0:[e0][e1][e2][e3][e4][e5][e6][e7][e8][e9][ea][eb][ec][ed][ee][ef]
Total written 0x00f0:[f0][f1][f2][f3][f4][f5][f6][f7][f8][f9][fa][fb][fc][fd][fe][ff]

Total bytes transmitted: 256.

The reveive program (running on an Ubuntu laptop) report that 4352 byts have been received:

Total read 0x0000: 00 {02} 02  03  04  05  06 {0c} 08  09  0a  0b  0c {10}{11}{12}
Total read 0x0010: 10  11  12  13  14  15 {1a} 17  18  19  1a {20} 1c  1d  1e  1f 
Total read 0x0020: 20  21  22  23  24  25  26  27  28  29  2a {2f} 2c  2d  2e  2f 
Total read 0x0030:{34}{35} 32  33  34  35  36  37  38 {3c} 3a  3b  3c {41}{42} 3f 
Total read 0x0040: 40  41  42  43  44  45 {4a} 47  48  49  4a {4f}{50} 4d  4e  4f 
Total read 0x0050: 50  51  52  53 {59} 55  56  57  58  59 {5d}{5e} 5c  5d  5e  5f 
Total read 0x0060: 60  61 {66} 63  64  65  66 {6b}{6c} 69  6a  6b  6c  6d  6e  6f 
Total read 0x0070:{74} 71  72  73  74 {79}{7a} 77  78  79  7a  7b  7c  7d {82} 7f 
Total read 0x0080: 80  81  82 {87}{88} 85  86  87  88  89  8a  8b {90} 8d  8e  8f 
Total read 0x0090: 90 {96}{97}{98}{99}{96}{97}{98}{99}{95} 9a  9b  9c  9d  9e  9f 
Total read 0x00a0: a0  a1  a2  a3  a4  a5  a6  a7  a8  a9  aa  ab  ac  ad  ae  af 
Total read 0x00b0: b0  b1  b2  b3  b4  b5  b6  b7  b8  b9  ba  bb  bc  bd  be  bf 
Total read 0x00c0: c0  c1  c2  c3  c4  c5  c6  c7  c8  c9  ca  cb  cc  cd  ce  cf 
Total read 0x00d0: d0  d1  d2  d3  d4  d5  d6  d7  d8  d9  da  db  dc  dd  de  df 
Total read 0x00e0: e0  e1  e2  e3  e4  e5  e6  e7  e8  e9  ea  eb  ec  ed  ee  ef 
Total read 0x00f0: f0  f1  f2  f3  f4  f5  f6  f7  f8  f9  fa  fb  fc  fd  fe  ff 
Total read 0x0100:{00}{01}{02}{03}{04}{05}{06}{07}{08}{09}{0a}{0b}{0c}{0d}{0e}{0f}
Total read 0x0110:{10}{11}{12}{13}{14}{15}{16}{17}{18}{19}{1a}{1b}{1c}{1d}{1e}{1f}
Total read 0x0120:{20}{21}{22}{23}{24}{25}{26}{27}{28}{29}{2a}{2b}{2c}{2d}{2e}{2f}
Total read 0x0130:{30}{31}{32}{33}{34}{35}{36}{37}{38}{39}{3a}{3b}{3c}{3d}{3e}{3f}
Total read 0x0140:{40}{41}{42}{43}{44}{45}{46}{47}{48}{49}{4a}{4b}{4c}{4d}{4e}{4f}
Total read 0x0150:{50}{51}{52}{53}{54}{55}{56}{57}{58}{59}{5a}{5b}{5c}{5d}{5e}{5f}
Total read 0x0160:{60}{61}{62}{63}{64}{65}{66}{67}{68}{69}{6a}{6b}{6c}{6d}{6e}{6f}
Total read 0x0170:{70}{71}{72}{73}{74}{75}{76}{77}{78}{79}{7a}{7b}{7c}{7d}{7e}{7f}
Total read 0x0180:{80}{81}{82}{83}{84}{85}{86}{87}{88}{89}{8a}{8b}{8c}{8d}{8e}{8f}
Total read 0x0190:{90}{91}{92}{93}{94}{95}{96}{97}{98}{99}{9a}{9b}{9c}{9d}{9e}{9f}
Total read 0x01a0:{a0}{a1}{a2}{a3}{a4}{a5}{a6}{a7}{a8}{a9}{aa}{ab}{ac}{ad}{ae}{af}
Total read 0x01b0:{b0}{b1}{b2}{b3}{b4}{b5}{b6}{b7}{b8}{b9}{ba}{bb}{bc}{bd}{be}{bf}
Total read 0x01c0:{c0}{c1}{c2}{c3}{c4}{c5}{c6}{c7}{c8}{c9}{ca}{cb}{cc}{cd}{ce}{cf}
Total read 0x01d0:{d0}{d1}{d2}{d3}{d4}{d5}{d6}{d7}{d8}{d9}{da}{db}{dc}{dd}{de}{df}
Total read 0x01e0:{e0}{e1}{e2}{e3}{e4}{e5}{e6}{e7}{e8}{e9}{ea}{eb}{ec}{ed}{ee}{ef}
Total read 0x01f0:{f0}{f1}{f2}{f3}{f4}{f5}{f6}{f7}{f8}{f9}{fa}{fb}{fc}{fd}{fe}{ff}
Total read 0x0200:{00}{01}{02}{03}{04}{05}

Total bytes received: 518.
flushing receive buffer...

Total bytes flushed: 3834.

Here is the point where the first bad byte is detected with two additional good bytes:

Additionally, here is the entire sal file and exported csv of the I2C analyzer output zipped up:

Buster-Bad-I2C-2022-02-11-4352 bytes.zip

[pelwell]

Those traces are illuminating because they clearly show incorrect data being sent. I hope to have some working test equipment soon.

[pelwell]

The problem is easily reproducible with the Waveshare Serial "HAT" (it isn't a true HAT without an EEPROM) that has just arrived.

[ApiumJacob]

Hopefully, its as easy to fix, let me know if there is anything I can do to support the effort.

What if your "HAT" has an EEPROM but it's blank? Does it get promoted from "HAT" to HAT or do you actually have to program it first? ;-)

[pelwell]

The sc16is7xx driver does virtually no interlocking, as some added tracing shows:

[   32.871999] sc16is7xx: to_send: 1 [ 00 ]
[   32.872826] sc16is7xx:   sent: [ 00 ]
[   32.874994] sc16is7xx: to_send: 40 [ 01 ]
[   32.876074] sc16is7xx: to_send: 40 [ 41 ]
[   32.906103] sc16is7xx:   sent: [ 41 ]
[   32.906119] sc16is7xx:   sent: [ 41 ]
[   32.907209] sc16is7xx: to_send: 40 [ 81 ]
[   32.925468] sc16is7xx: to_send: 3f [ c1 ]
[   32.925483] sc16is7xx:   sent: [ c1 ]
[   32.939162] sc16is7xx:   sent: [ c1 ]

The to_send lines show how many bytes (in hex) to send, and the first one in the block. The sent line shows the content of the send buffer after the send has occurred, but here also serves to show the timing - in particular the overlapping of pairs of to_send and sent lines, meaning that two blocks of bytes are using the same buffer at the same time.

Which means we're on stage 6 of the debugging process:

[pelwell]

Adding the usual spinlocks breaks horribly because the driver uses the regmap abstraction to support both I2C and SPI modes. regmap does its own interlocking against multiple accesses using mutexes, which expect to be able to put the calling thread to sleep - something that isn't allowed while a spinlock is held because it disables interrupts - "scheduling while atomic" is the kernel error message.

It is possible to disable regmap's internal interlocking by adding the following line before the calls to devm_regmap_init_*:

	regcfg.disable_locking = true;

Surprisingly this prevents data corruption, but causes a different set of warning messages:

[   70.303626] sc16is7xx 1-0048: ttySC0: Unexpected interrupt: 0
[   70.305502] sc16is7xx 1-0048: ttySC1: Unexpected interrupt: 20
...
[  220.780727] sc16is7xx 1-0048: chip reports 193 free bytes in TX fifo, but it only has 64

As such, I don't think it is a suitable workaround, let alone a fix.

[pelwell]

The problem reentrancy is between the IRQ thread and work queue used for transmission. Claiming an existing mutex (.efr_lock) inside sc16is7xx_tx_proc eliminates any corruption in my test.

Note that this doesn't solve the problem of dropped data when sent to the sc16is752, but that looks like overrun at the receive FIFO because it isn't drained fast enough - something that the use of RTS/CTS flow control would solve.

[pelwell]

See de9c455 (before rebasing) for a patch containing the fix.

[pelwell]

The dropped data mentioned above is cured with the dtparam=i2c_arm_baudrate=400000, which I had omitted, although it's not impossible that a scheduling catastrophe could still result in lost data without flow control.

[popcornmix]

Latest rpi-update kernel contains @pelwell's potential fix.

[ApiumJacob]

I couldn't find any documentation on how to install these pre-built kernels on to an existing SD card. I looked at https://www.raspberrypi.com/documentation/computers/linux_kernel.html#install-directly-onto-the-sd-card but these don't seem quite right for this operation.

So here is what I tried:

I mounted my SD card on my Ubuntu computer, blew away the .../boot/overlays directory and replaced it with the files from this commit. I then overwrote all the file in .../boot/

The following for files remained untouched.

commandline.txt
config.txt
issue.txt
.config.txt.swp

I removed then SD card then inserted into my pi and I was pleasantly surprised that it booted.

$ uname -a
Linux SwarmBridge-09999 5.15.23-v7+ #1525 SMP Wed Feb 16 14:34:22 GMT 2022 armv7l GNU/Linux

Looks like the correct kernel is there. However none of the SC16IS752 serial ports are showing up:

$ ls /dev/ttyS*
/dev/ttyS0

dmesg output: dmesg.5.15.23-v7+.txt

[pelwell]

rpi-update is a tool for installing kernels, firmware and Device Tree files. To install the latest, permanently-beta-build, just run sudo rpi-update.

[pelwell]

As part of an attempt to upstream the patch I had to locate the point where the bug was introduced, and it looks like it was in May 2020 - all the way back in Linux 5.8.

[paulenuta]

I will run an update and re-test with the configuration from #4711.

[ApiumJacob]

As part of an attempt to upstream the patch I had to locate the point where the bug was introduced, and it looks like it was in May 2020 - all the way back in Linux 5.8.

Okay, the Frankenstein image we have works is kernel version 4.19.97-v7+, but all these versions and they all exhibit the problem as well.

2017-07-05-raspbian-jessie.zip
2019-04-08-raspbian-stretch.zip
2019-06-20-raspbian-buster.zip
2021-10-30-raspios-bullseye-armhf-lite.zip
2021-12-02-raspios-buster-armhf-lite.zip

[ApiumJacob]

rpi-update is a tool for installing kernels, firmware and Device Tree files. To install the latest, permanently-beta-build, just run sudo rpi-update.

rpi-update worked great. After running I got back /dev/ttySC* ports. I ran data the tx program with 2ms, 1ms, 100us and 0us delays and saw no obvious loss or insertion of data. I'll run more extensive testing over the next week with multiple ports operating at the same time.

[ApiumJacob]

When I reboot, I notice this output: it just looks like some Hayes AT commands, which I think is normal upon booting a *nix system. But I'm not sure what the 0x00, 0xfc, 0x00, 0xfc at the start is all about. or the two CANCEL's are all about but they seem very modemy.

Total read 0x0000: 00 {fc}{00}{fc}{61}{74}{0d}{60}{0d}{18}{18}{0d}{60} 0d {61}{74}
Total read 0x0010:{6f}{67}{2d}{6f}{66}{66}{0d}

at\r
`\r
[CANCEL][CANCEL]\r
`\r
atog-off\r

[paulenuta]

I will run an update and re-test with the configuration from #4711.

After sudo rpi_update I got uname -a: Linux raspberrypi 5.15.23-v7+ #1525 SMP Wed Feb 16 14:34:22 GMT 2022 armv7l GNU/Linux.

Running the test linux-serial-test/linux-serial-test -s -e -p /dev/ttySC0 -b 9600 -A -T -o 120 -i 125 give me no error

/dev/ttySC0: count for this session: rx=115683, tx=115683, rx err=0
/dev/ttySC0: TIOCGICOUNT: ret=0, rx=20401, tx=219630, frame = 0, overrun = 0, parity = 0, brk = 0, buf_overrun = 0

Full log on #4711.

Thank you @pelwell !