Unicode Decode Error

[Stanpol]

Running replicator for one of my tables result in the following error:

Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/binlog_replicator.py", line 448, in run
    for row in event.rows:
               ^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 565, in rows
    self._fetch_rows()
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 560, in _fetch_rows
    self.__rows.append(self._fetch_one_row())
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 621, in _fetch_one_row
    row["values"] = self._read_column_data(self.columns_present_bitmap)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 148, in _read_column_data
    values[name] = self.__read_values_name(
                   ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 216, in __read_values_name
    else self.__read_string(1, column)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 335, in __read_string
    string = string.decode(errors=decode_errors)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xe4 in position 10: invalid continuation byte

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/bin/mysql_ch_replicator", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/main.py", line 150, in main
    run_binlog_replicator(args, config)
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/main.py", line 65, in run_binlog_replicator
    binlog_replicator.run()
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/binlog_replicator.py", line 486, in run
    logger.error(f'unhandled error {str(e)}', exc_info=True)
                                        ^
UnboundLocalError: cannot access local variable 'e' where it is not associated with a value

I'm trying to debug and see what exactly causes UnicodeDecodeError.

[Stanpol]

Deleting local binlog and restarting the application seems to magically fixing the problem. I'll still monitor this, but for now closing.

[bakwc]

Need to figure out what's going on, it could repeats. Probably some value in some column not processed correctly..

[Stanpol]

It does come back:

[binlogrepl 2024-11-27 13:33:31,354     INFO] last transaction id: ('mysql-bin.001348', 31583976), processed events: 10290
[dbrepl test 2024-11-27 13:33:38,135     INFO] replicating test_settings, replicated 3200000 records, primary key: [3202860]
[binlogrepl 2024-11-27 13:34:32,375     INFO] last transaction id: ('mysql-bin.001348', 32651239), processed events: 22750
[dbrepl test 2024-11-27 13:34:38,252     INFO] replicating test_settings, replicated 6300000 records, primary key: [6302902]
[dbrepl test 2024-11-27 13:34:39,195     INFO] touch binlog /app/writable/binlog/test
[binlogrepl 2024-11-27 13:35:32,769     INFO] last transaction id: ('mysql-bin.001348', 33880567), processed events: 38010
[dbrepl test 2024-11-27 13:35:39,040     INFO] replicating test_settings, replicated 9500000 records, primary key: [9504980]
[binlogrepl 2024-11-27 13:36:33,801     INFO] last transaction id: ('mysql-bin.001348', 34660670), processed events: 46803
[dbrepl test 2024-11-27 13:36:39,742     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:36:39,743     INFO] replicating test_settings, replicated 12500000 records, primary key: [12506992]
[binlogrepl 2024-11-27 13:37:34,762     INFO] last transaction id: ('mysql-bin.001348', 35540203), processed events: 57320
[dbrepl test 2024-11-27 13:37:39,748     INFO] replicating test_settings, replicated 15650000 records, primary key: [15657332]
[binlogrepl 2024-11-27 13:38:35,340     INFO] last transaction id: ('mysql-bin.001348', 36400253), processed events: 67019
[dbrepl test 2024-11-27 13:38:40,228     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:38:40,228     INFO] replicating test_settings, replicated 18850000 records, primary key: [18857333]
[binlogrepl 2024-11-27 13:39:35,767     INFO] last transaction id: ('mysql-bin.001348', 37168457), processed events: 75778
[dbrepl test 2024-11-27 13:39:40,585     INFO] replicating test_settings, replicated 21950000 records, primary key: [21957597]
[binlogrepl 2024-11-27 13:40:35,840     INFO] last transaction id: ('mysql-bin.001348', 38219707), processed events: 86670
[dbrepl test 2024-11-27 13:40:40,251     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:40:41,193     INFO] replicating test_settings, replicated 25200000 records, primary key: [25207916]
[binlogrepl 2024-11-27 13:41:36,711     INFO] last transaction id: ('mysql-bin.001348', 39609085), processed events: 103795
[dbrepl test 2024-11-27 13:41:41,709     INFO] replicating test_settings, replicated 28350000 records, primary key: [28357922]
[binlogrepl 2024-11-27 13:42:36,810     INFO] last transaction id: ('mysql-bin.001348', 40509768), processed events: 114012
[dbrepl test 2024-11-27 13:42:40,901     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:42:41,947     INFO] replicating test_settings, replicated 31500000 records, primary key: [31508082]
[binlogrepl 2024-11-27 13:43:37,489     INFO] last transaction id: ('mysql-bin.001348', 41376695), processed events: 124026
[dbrepl test 2024-11-27 13:43:42,319     INFO] replicating test_settings, replicated 34700000 records, primary key: [34708082]
[binlogrepl 2024-11-27 13:44:37,701     INFO] last transaction id: ('mysql-bin.001348', 42166431), processed events: 133468
[dbrepl test 2024-11-27 13:44:41,312     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:44:43,128     INFO] replicating test_settings, replicated 37950000 records, primary key: [37961652]
[binlogrepl 2024-11-27 13:45:37,751     INFO] last transaction id: ('mysql-bin.001348', 43528843), processed events: 151319
[dbrepl test 2024-11-27 13:45:44,190     INFO] replicating test_settings, replicated 41200000 records, primary key: [41212396]
[binlogrepl 2024-11-27 13:46:38,769     INFO] last transaction id: ('mysql-bin.001348', 44510894), processed events: 161978
[dbrepl test 2024-11-27 13:46:42,184     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:46:44,887     INFO] replicating test_settings, replicated 44300000 records, primary key: [44312400]
[binlogrepl 2024-11-27 13:47:39,733     INFO] last transaction id: ('mysql-bin.001348', 45797672), processed events: 175007
[dbrepl test 2024-11-27 13:47:45,695     INFO] replicating test_settings, replicated 47500000 records, primary key: [47514281]
[binlogrepl 2024-11-27 13:48:39,794     INFO] last transaction id: ('mysql-bin.001348', 46528451), processed events: 183281
[dbrepl test 2024-11-27 13:48:42,549     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:48:46,002     INFO] replicating test_settings, replicated 50750000 records, primary key: [50764301]
[binlogrepl 2024-11-27 13:49:40,400     INFO] last transaction id: ('mysql-bin.001348', 47402416), processed events: 193350
[dbrepl test 2024-11-27 13:49:46,004     INFO] replicating test_settings, replicated 53800000 records, primary key: [53815624]
[binlogrepl 2024-11-27 13:50:40,847     INFO] last transaction id: ('mysql-bin.001348', 48369257), processed events: 204329
[dbrepl test 2024-11-27 13:50:42,924     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:50:46,368     INFO] replicating test_settings, replicated 57050000 records, primary key: [57065626]
[binlogrepl 2024-11-27 13:51:41,511     INFO] last transaction id: ('mysql-bin.001348', 49332295), processed events: 215444
[dbrepl test 2024-11-27 13:51:46,619     INFO] replicating test_settings, replicated 60300000 records, primary key: [60315626]
[binlogrepl 2024-11-27 13:52:42,027     INFO] last transaction id: ('mysql-bin.001348', 50159061), processed events: 225412
[dbrepl test 2024-11-27 13:52:43,524     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:52:47,063     INFO] replicating test_settings, replicated 63550000 records, primary key: [63565656]
[binlogrepl 2024-11-27 13:53:42,082     INFO] last transaction id: ('mysql-bin.001348', 50972198), processed events: 235301
[dbrepl test 2024-11-27 13:53:47,509     INFO] replicating test_settings, replicated 66900000 records, primary key: [66915772]
[binlogrepl 2024-11-27 13:54:43,152     INFO] last transaction id: ('mysql-bin.001348', 51873876), processed events: 246382
[dbrepl test 2024-11-27 13:54:43,917     INFO] touch binlog /app/writable/binlog/test
[dbrepl test 2024-11-27 13:54:48,278     INFO] replicating test_settings, replicated 70300000 records, primary key: [70315773]
[binlogrepl 2024-11-27 13:55:43,704     INFO] last transaction id: ('mysql-bin.001348', 52753998), processed events: 256833
[dbrepl test 2024-11-27 13:55:48,974     INFO] replicating test_settings, replicated 73550000 records, primary key: [73565879]
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/binlog_replicator.py", line 448, in run
    for row in event.rows:
               ^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 565, in rows
    self._fetch_rows()
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 560, in _fetch_rows
    self.__rows.append(self._fetch_one_row())
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 621, in _fetch_one_row
    row["values"] = self._read_column_data(self.columns_present_bitmap)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 148, in _read_column_data
    values[name] = self.__read_values_name(
                   ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 216, in __read_values_name
    else self.__read_string(1, column)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/pymysqlreplication/row_event.py", line 335, in __read_string
    string = string.decode(errors=decode_errors)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xc9 in position 5: invalid continuation byte

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/bin/mysql_ch_replicator", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/main.py", line 150, in main
    run_binlog_replicator(args, config)
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/main.py", line 65, in run_binlog_replicator
    binlog_replicator.run()
  File "/usr/local/lib/python3.12/site-packages/mysql_ch_replicator/binlog_replicator.py", line 486, in run
    logger.error(f'unhandled error {str(e)}', exc_info=True)
                                        ^
UnboundLocalError: cannot access local variable 'e' where it is not associated with a value

I'm trying to reproduce this with more debug logging.

[bakwc]

Probably need to add some prints to: mysql_ch_replicator/pymysqlreplication/row_event.py
Something like this:

            encoding = self.charset_to_encoding(column.character_set_name)
            try:
                string = string.decode(encoding, decode_errors)
            except LookupError:
                # python does not support Mysql encoding type ex)swe7 it will not decoding then Show origin string
                string = origin_string
            except UnboundLocalError:
                print(' === ', self.table, column)
                raise

At least we will know what table and column is this.

Also you could try a following fix:

            encoding = self.charset_to_encoding(column.character_set_name)
            try:
                string = string.decode(encoding, decode_errors)
            except LookupError:
                # python does not support Mysql encoding type ex)swe7 it will not decoding then Show origin string
                string = origin_string
            except UnboundLocalError:
                string = origin_string

But need to double check that values in ClickHouse will be correct after this fix applied.

[Stanpol]

I found the source of the exception. There is a table:

CREATE TABLE `test` (
  `id` bigint NOT NULL AUTO_INCREMENT,
  `name` varchar(255) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=2478808 DEFAULT CHARSET=latin1

As you can see the default charset is latin1.
Then there is a row string = b'H\xe4llo' which fails to decode to utf8.

string = string.decode() fails with UnicodeDecodeError: 'utf-8' codec can't decode byte 0xe4 in position 1: invalid continuation byte
while string = string.decode('latin1') results in correctly decoded string: Hällo

So replicator could potentially:

• parse DEFAULT CHARSET and use it for decoding
• library like charset-normalizer can be utilised to guess a charset
• a setting decode_errors='ignore'/'replace' can be added to the yaml config

[bakwc]

parse DEFAULT CHARSET and use it for decoding

I like this one. Will look on weekend, or you could prepare a fix yourself if you want.
Thanks for sharing a simple test case!

[bakwc]

Fixed in 0.0.37

[Stanpol]

Thanks a lot, I'll check it tomorrow.
On the first glance, there might be problem with swe7, dec8, or hp8 charsets of MySQL that are not natively supported in Python. In my case it won't be a problem as I only work with latin1, but someone in the future will come with a bug that string.decode('swe7') not existing. Additionally, MySQL knows the charset koi8r, while Python knows it as koi8-r or koi8_r.
The full list of supported Python encodings is available here. The full list of MySQL encodings:

mysql> SHOW CHARACTER SET;
+----------+---------------------------------+---------------------+--------+
| Charset  | Description                     | Default collation   | Maxlen |
+----------+---------------------------------+---------------------+--------+
| armscii8 | ARMSCII-8 Armenian              | armscii8_general_ci |      1 |
| ascii    | US ASCII                        | ascii_general_ci    |      1 |
| big5     | Big5 Traditional Chinese        | big5_chinese_ci     |      2 |
| binary   | Binary pseudo charset           | binary              |      1 |
| cp1250   | Windows Central European        | cp1250_general_ci   |      1 |
| cp1251   | Windows Cyrillic                | cp1251_general_ci   |      1 |
| cp1256   | Windows Arabic                  | cp1256_general_ci   |      1 |
| cp1257   | Windows Baltic                  | cp1257_general_ci   |      1 |
| cp850    | DOS West European               | cp850_general_ci    |      1 |
| cp852    | DOS Central European            | cp852_general_ci    |      1 |
| cp866    | DOS Russian                     | cp866_general_ci    |      1 |
| cp932    | SJIS for Windows Japanese       | cp932_japanese_ci   |      2 |
| dec8     | DEC West European               | dec8_swedish_ci     |      1 |
| eucjpms  | UJIS for Windows Japanese       | eucjpms_japanese_ci |      3 |
| euckr    | EUC-KR Korean                   | euckr_korean_ci     |      2 |
| gb18030  | China National Standard GB18030 | gb18030_chinese_ci  |      4 |
| gb2312   | GB2312 Simplified Chinese       | gb2312_chinese_ci   |      2 |
| gbk      | GBK Simplified Chinese          | gbk_chinese_ci      |      2 |
| geostd8  | GEOSTD8 Georgian                | geostd8_general_ci  |      1 |
| greek    | ISO 8859-7 Greek                | greek_general_ci    |      1 |
| hebrew   | ISO 8859-8 Hebrew               | hebrew_general_ci   |      1 |
| hp8      | HP West European                | hp8_english_ci      |      1 |
| keybcs2  | DOS Kamenicky Czech-Slovak      | keybcs2_general_ci  |      1 |
| koi8r    | KOI8-R Relcom Russian           | koi8r_general_ci    |      1 |
| koi8u    | KOI8-U Ukrainian                | koi8u_general_ci    |      1 |
| latin1   | cp1252 West European            | latin1_swedish_ci   |      1 |
| latin2   | ISO 8859-2 Central European     | latin2_general_ci   |      1 |
| latin5   | ISO 8859-9 Turkish              | latin5_turkish_ci   |      1 |
| latin7   | ISO 8859-13 Baltic              | latin7_general_ci   |      1 |
| macce    | Mac Central European            | macce_general_ci    |      1 |
| macroman | Mac West European               | macroman_general_ci |      1 |
| sjis     | Shift-JIS Japanese              | sjis_japanese_ci    |      2 |
| swe7     | 7bit Swedish                    | swe7_swedish_ci     |      1 |
| tis620   | TIS620 Thai                     | tis620_thai_ci      |      1 |
| ucs2     | UCS-2 Unicode                   | ucs2_general_ci     |      2 |
| ujis     | EUC-JP Japanese                 | ujis_japanese_ci    |      3 |
| utf16    | UTF-16 Unicode                  | utf16_general_ci    |      4 |
| utf16le  | UTF-16LE Unicode                | utf16le_general_ci  |      4 |
| utf32    | UTF-32 Unicode                  | utf32_general_ci    |      4 |
| utf8mb3  | UTF-8 Unicode                   | utf8mb3_general_ci  |      3 |
| utf8mb4  | UTF-8 Unicode                   | utf8mb4_0900_ai_ci  |      4 |
+----------+---------------------------------+---------------------+--------+```

[bakwc]

Added better conversion table. For missing charsets - will add if someone request them.

[Stanpol]

No more unicode errors for me. Thank you for a quick fix, great job!