FormatDescriptionEvent has zero log_pos

[bjoernhaeuser]

Hey,

I just updated to the latest commit and since then my tests are failing. It seems to be that the parsing of a FORMAT_DESCRIPTION_EVENT fails and the stream gets a zero log_pos. Subsequent requests will fail, because zero is not a allowed position in the file.

Here is the dump of the binlog:

mysqlbinlog --base64-output=auto --hexdump mysql-bin.000003 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#130525 21:42:04 server id 1  end_log_pos 107 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#        4 0c 14 a1 51   0f   01 00 00 00   67 00 00 00   6b 00 00 00   00 00
#       17 04 00 35 2e 35 2e 33 31  2d 6c 6f 67 00 00 00 00 |..5.5.31.log....|
#       27 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
#       37 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
#       47 00 00 00 00 0c 14 a1 51  13 38 0d 00 08 00 12 00 |.......Q.8......|
#       57 04 04 04 04 12 00 00 54  00 04 1a 08 00 00 00 08 |.......T........|
#       67 08 08 02 00  |....|
#   Start: binlog v 4, server v 5.5.31-log created 130525 21:42:04 at startup
ROLLBACK/*!*/;
BINLOG '
DBShUQ8BAAAAZwAAAGsAAAAAAAQANS41LjMxLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAMFKFREzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 107

This is the packet:

binlog_event.event.dump()
print vars(binlog_event)

generates

=== FormatDescriptionEvent ===
Date: 2013-05-25T22:27:33
Event size: 84
Read bytes: 0
()
{'server_id': 1, 'event_type': 15, 'timestamp': 1369513653, 'log_pos': 0, 'charset': 'utf8', 'packet': <pymysql.connections.MysqlPacket object at 0x2ca9b90>, 'read_bytes': 0, 'flags': 0, '_BinLogPacketWrapper__data_buffer': '', 'event': <pymysqlreplication.event.FormatDescriptionEvent object at 0x2ca9d50>, 'event_size': 103}

[bjoernhaeuser]

Wait, I am reading this wrong, sorry for the noise.

[bjoernhaeuser]

need to correct the last comment, log_pos seems to be zero!

[bjoernhaeuser]

It still works with commit 2c20101

[bjoernhaeuser]

What I believe is that making the file/pos settable from the outside changed the way the stream handled reconnects. Will try to come up with a test case for this.

[bjoernhaeuser]

@lxyu I added a test for this case. I think this is a not-yet handled corner case which come out of your patch. Do you have an idea what could be the source of this problem?

[lxyu]

Yah, gone through some tests and I agree with you.

It may be the log_pos logged an error state of position. When the file/pos always loads from "SHOW MASTER STATUS" or loads from the binlog start, the first event will never be FormatDescriptionEvent and so the pos will never be 0.

In this case, the logged position is not the "real" position, as some events like FormatDescriptionEvent never marks the end of a sql and it's pos should not be logged.

So may be we can come up with a list of useless events and we just directly bypass them?

[liorsion]

I'm just wondering, in those cases, won't it be safer to just force None when logpos is 0 (instead of listing all the known events that should not move the log, which is very error prone and might not be future safe?)

[lxyu]

If the log_pos forced to None, if the repl script crashed at that point, then it can't continue from the 'None' pos.

May be I'm wrong but I think events like FormatDescriptionEvent may be safely ignored and can be safe if it was read twice?

If so, it will be safe to fall back to the last valid pos.

[liorsion]

When I implemented that log pos resuming (in the way we decided to abandon) - when it was 0 I just marked it as None and didn't resume - I didn't have time to look at the current implementation but I guess the same thing can be done?

[lxyu]

so again let the user decide whether to save or not? yah it should works too.

while I still think a stream with pos randomly set to None is a little weird, if choose to do so, this behaviour should be documented.