AssertionError: Result length not requested length:

[rahilsh]

We are using pg_chameleon for replicating data from MySQL to PostgreSQL and pg_chameleon is using python-MySQL-replication internally. We are getting below error during replication. Is there any way to resolve it.

2018-09-13 15:12:49 MainProcess ERROR global_lib.py (558): Read process alive: False - Replay process alive: True                                                                                  [10/1912]
2018-09-13 15:12:49 MainProcess ERROR global_lib.py (559): Stack trace: Traceback (most recent call last):
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pg_chameleon/lib/global_lib.py", line 487, in read_replica
    self.mysql_source.read_replica()
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pg_chameleon/lib/mysql_lib.py", line 1336, in read_replica
    replica_data=self.__read_replica_stream(batch_data)
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pg_chameleon/lib/mysql_lib.py", line 1199, in __read_replica_stream
    for row in binlogevent.rows:
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pymysqlreplication/row_event.py", line 443, in rows
    self._fetch_rows()
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pymysqlreplication/row_event.py", line 438, in _fetch_rows
    self.__rows.append(self._fetch_one_row())
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pymysqlreplication/row_event.py", line 529, in _fetch_one_row
    row["after_values"] = self._read_column_data(self.columns_present_bitmap2)
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pymysqlreplication/row_event.py", line 138, in _read_column_data
    values[name] = self.__read_string(1, column)
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pymysqlreplication/row_event.py", line 232, in __read_string
    string = self.packet.read_length_coded_pascal_string(size)
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pymysqlreplication/packet.py", line 253, in read_length_coded_pascal_string
    return self.read(length)
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pymysqlreplication/packet.py", line 153, in read
    return self.packet.read(size)
  File "/home/rahilr/venv/lib64/python3.6/site-packages/pymysql/protocol.py", line 78, in read
    raise AssertionError(error)
AssertionError: Result length not requested length:
Expected=99.  Actual=51.  Position: 100.  Data Length: 151

[KiranPlastiq]

I am also getting this kind of error. had to wrap try/catch block to skip this

2020-08-17T11:33:24.704-07:00	Expected=13111. Actual=1051. Position: 496. Data Length: 1547
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00
	2020-08-17T11:33:24.704-07:00

[dongwook-chan]

Could you please specify the following:

1. the version of MySQL you're using
2. description about event that caused the error

[hgdangkhoi]

I run into this problem today, have anyone managed to come up with a solution?

[dongwook-chan]

@hgdangkhoi

1. Is error repeated when using 0.26 or later version of python-mysql-replication?
2. If so, please specify the version MySQL and the events that caused the error.

[hgdangkhoi]

@dongwook-chan
I am using python-mysql-replication 0.27, MySQL 8.0.23. I started pg_chameleon and it was working, until I kick off some scripts in the mysql DB and add some data then pg_chameleon is crashed with above error.

Is there a way to avoid this error by doing some try/catch and keep the replication running?

[hgdangkhoi]

Hi @dongwook-chan, any updates for me? Thanks

[dongwook-chan]

@hgdangkhoi
I'm sorry for the late reply.
It is most likely that DML events that were created by pg_chameleon in your specific eviroment have some additional fields that python-mysql-replication does not recognize and thus raised parsing error.
For me to debug this error, you need to provide scenario that reproduces the error.
(or at least the call stack as in OP)
And it would be beneficial to know which storage engine you use.

[kvitek]

So I have scenario.
I've reproduced this error using docker containers.

1. On host machine create folder "some_name" for docker files and extract content of this archive docker.zip
2. Create two subfolders "mysql_vol" and "postgres_vol"
3. Extract content of mysql_vol.zip to "mysql_vol" directory, and postgres_vol.zip to "postgres_vol"
4. Next you should edit example.yml to replace "/home/victor" with you "some_name" directory
5. Go to "some_name" directory and start compose by docker-compose -f example.yml up. It will take some time to download images and startup containers.
6. Connect to pg_cham container and issue commands:

chameleon create_replica_schema --debug
chameleon add_source --source mysql --debug
chameleon init_replica --source mysql --debug
chameleon start_replica --source mysql --debug

7. Connect to mysql container and run following: mysql -u root -p frontexp enter password root, than execute statement

INSERT INTO `sic_codes` VALUES (0,'Unknown SIC - 0000');

Than you'll see error something like this:

2022-03-07 16:23:11 read_replica DEBUG mysql_lib.py (1463): Batch data [(1, 'mysql-bin.000003', 157, 't_log_replica_mysql_2', '')]
2022-03-07 16:23:11 read_replica DEBUG mysql_lib.py (1011): collecting table type map
2022-03-07 16:23:11 read_replica DEBUG mysql_lib.py (1228): GTID DISABLED - log_file mysql-bin.000003, log_position 157. id_batch: 1
2022-03-07 16:23:11 read_replica DEBUG mysql_lib.py (1242): ROTATE EVENT - binlogfile mysql-bin.000003, position 157.
2022-03-07 16:23:11 MainProcess ERROR global_lib.py (571): Read process alive: False - Replay process alive: True
2022-03-07 16:23:11 MainProcess ERROR global_lib.py (572): Stack trace: Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pg_chameleon/lib/global_lib.py", line 500, in read_replica
    self.mysql_source.read_replica()
  File "/usr/local/lib/python3.10/site-packages/pg_chameleon/lib/mysql_lib.py", line 1464, in read_replica
    replica_data=self.__read_replica_stream(batch_data)
  File "/usr/local/lib/python3.10/site-packages/pg_chameleon/lib/mysql_lib.py", line 1230, in __read_replica_stream
    for binlogevent in my_stream:
  File "/usr/local/lib/python3.10/site-packages/pymysqlreplication/binlogstream.py", line 496, in fetchone
    binlog_event = BinLogPacketWrapper(pkt, self.table_map,
  File "/usr/local/lib/python3.10/site-packages/pymysqlreplication/packet.py", line 136, in __init__
    self.event = event_class(self, event_size_without_header, table_map,
  File "/usr/local/lib/python3.10/site-packages/pymysqlreplication/event.py", line 197, in __init__
    self._read_status_vars_value_for_key(status_vars_key)
  File "/usr/local/lib/python3.10/site-packages/pymysqlreplication/event.py", line 262, in _read_status_vars_value_for_key
    db = self.packet.read_string()
  File "/usr/local/lib/python3.10/site-packages/pymysqlreplication/packet.py", line 481, in read_string
    char = self.read(1)
  File "/usr/local/lib/python3.10/site-packages/pymysqlreplication/packet.py", line 157, in read
    return self.packet.read(size)
  File "/usr/local/lib/python3.10/site-packages/pymysql/protocol.py", line 74, in read
    raise AssertionError(error)
AssertionError: Result length not requested length:
Expected=1.  Actual=0.  Position: 82.  Data Length: 82

2022-03-07 16:23:11 MainProcess ERROR global_lib.py (578): Read daemon crashed. Terminating the replay daemon.
2022-03-07 16:23:11 MainProcess DEBUG pg_lib.py (660): Changing the autocommit flag to True
2022-03-07 16:23:11 MainProcess INFO global_lib.py (603): Replica process for source mysql ended

[dongwook-chan]

@kvitek

Thank you for the detailed instruction.
It was so well written that I could catch up so quickly.

I managed to follow the steps 1 to 5.
(I added build context '.' in example.yml at step 5. cuz I got an exception otherwise.)

...
  pg_cham:
    build:
      context: .
      dockerfile: pg_cham_build
...

However, I ran into exceptions below while executing the first command in step 6;

commands for step 6

[@host]$ sudo docker exec -it {continaer id} /bin/bash
pg_cham@{container id}$  chameleon create_replica_schema --debug

exceptions

pg_cham@ac9fda246651:/code$ chameleon create_replica_schema --debug
Traceback (most recent call last):
  File "/usr/local/bin/chameleon", line 5, in <module>
    exec(compile(open(__file__).read(), __file__, 'exec'))
  File "/usr/local/bin/chameleon.py", line 56, in <module>
    replica = replica_engine(args)
  File "/usr/local/lib/python3.10/site-packages/pg_chameleon/lib/global_lib.py", line 147, in __init__
    catalog_version = self.pg_engine.get_catalog_version()
  File "/usr/local/lib/python3.10/site-packages/pg_chameleon/lib/pg_lib.py", line 2133, in get_catalog_version
    self.connect_db()
  File "/usr/local/lib/python3.10/site-packages/pg_chameleon/lib/pg_lib.py", line 672, in connect_db
    self.pgsql_conn = psycopg2.connect(strconn)
  File "/usr/local/lib/python3.10/site-packages/psycopg2/__init__.py", line 122, in connect
    conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
psycopg2.OperationalError: connection to server at "db-psql" (172.18.1.4), port 5432 failed: FATAL:  password authentication failed for user "usr_replica"

Exception ignored in: <function pg_engine.__del__ at 0x7f3483737400>
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pg_chameleon/lib/pg_lib.py", line 649, in __del__
    self.disconnect_db()
  File "/usr/local/lib/python3.10/site-packages/pg_chameleon/lib/pg_lib.py", line 691, in disconnect_db
    if self.pgsql_cur:
AttributeError: 'pg_engine' object has no attribute 'pgsql_cur'

Unfortunately, since I'm not familiar with pg_cham, I have no idea what's causing this error.
Might the error ring a bell to you?

[kvitek]

It is because pg_cham container started up earlie than postgres container. I think you should rewrite definition of pg_cham:

pg_cham:
    depends_on:
      - db-mysql
      - db-psql
    build:
      dockerfile: pg_cham_build    
    restart: on-failure    
    command: ["sleep","infinity"]

So it will start after mysql and psql

[dongwook-chan]

@kvitek
Thanks again for your help. 😁
But it's 3 in the morning here in Korea.
I'll try to reproduce the issue after work and get back to you ASAP.
I think we got pretty close to the solution.

[dongwook-chan]

@kvitek
I'm here to share the progress so far.
I've successfully reproduced the error.
But as mysql-replication is run as Daemonizer in pg_chameleon, pdb doesn't work.
I'll write my own script to reproduce error and try to debug.
Please allow me some more time for me to figure this out.

[kvitek]

@dongwook-chan
I'm not in such a hurry. Do your work thoroughly. And thank you for response!

[dongwook-chan]

@kvitek
Found the cause of the exception.
My bad, it stems from code I committed. (released in mysql-replication 0.27)
But it might take a while to correct this.
So I suggest trying bypass:
Install mysql-replication<=0.26 before installing pg_chameleon.
I think this issue is the cause of the following commit:
the4thdoctor/pg_chameleon@38c7a90.
I'll leave a comment on the commit to alert the owner of the repo.
And I'll let you know if I come up with the solution for the exception.
I'll make sure to add your scenario to tests to prevent the same exception being raised in the future.
Thank you again for reporting this issue.