Tests are not passed #7

nevill · 2015-01-07T03:16:38Z

When I try to run with npm test, it's failed

nevill@mba-nevill zongji(develop *) $ npm test

> zongji@0.2.0 test /Users/nevill/working/mysql-binlog/zongji
> nodeunit --reporter=minimal test

events:
/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/Parser.js:82
        throw err;
              ^
TypeError: Cannot read property 'rows' of undefined
    at /Users/nevill/working/mysql-binlog/zongji/test/events.js:73:29
    at Query._callback (/Users/nevill/working/mysql-binlog/zongji/test/helpers/querySequence.js:22:11)
    at Query.Sequence.end (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/sequences/Sequence.js:96:24)
    at Query._handleFinalResultPacket (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/sequences/Query.js:143:8)
    at Query.OkPacket (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/sequences/Query.js:77:10)
    at Protocol._parsePacket (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/Protocol.js:271:23)
    at Parser.write (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/Parser.js:77:12)
    at Protocol.write (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/Protocol.js:39:16)
    at Socket.<anonymous> (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/Connection.js:82:28)
    at Socket.emit (events.js:95:17)
npm ERR! Test failed.  See above for more details.
npm ERR! not ok code 0

I also try to run them one by one. For example,

nevill@mba-nevill zongji(develop *) $ node_modules/.bin/nodeunit test/types.js

types.js
✖ set

AssertionError: 2 === 0
    at Object.strictEqual (/Users/nevill/working/mysql-binlog/zongji/node_modules/nodeunit/lib/types.js:83:39)
    at module.exports (/Users/nevill/working/mysql-binlog/zongji/test/helpers/expectEvents.js:10:8)
    at /Users/nevill/working/mysql-binlog/zongji/test/types.js:73:7
    at Query._callback (/Users/nevill/working/mysql-binlog/zongji/test/helpers/querySequence.js:22:11)
    at Query.Sequence.end (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/sequences/Sequence.js:96:24)
    at Query._handleFinalResultPacket (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/sequences/Query.js:143:8)
    at Query.EofPacket (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/sequences/Query.js:127:8)
    at Protocol._parsePacket (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/Protocol.js:271:23)
    at Parser.write (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/Parser.js:77:12)
    at Protocol.write (/Users/nevill/working/mysql-binlog/zongji/node_modules/mysql/lib/protocol/Protocol.js:39:16)

@numtel Is there anything missing? Or MySQL version matters? (I'm testing against 5.6.13)

The text was updated successfully, but these errors were encountered:

numtel · 2015-01-07T09:07:50Z

Ok, I have updated to 5.6.19 and I see the same error. (If you saw my [now] deleted message, I was still running the old 5.5.40 version, I had to actually restart my machine not just the MySQL server to switch versions).

Please hold on, I'll see what's going on...

* Fixes error message posted in #7 * Reveals new error message for MySQL 5.6

numtel · 2015-01-08T08:29:18Z

I just committed a fix for the first error you have posted and now the test reveals the errors related to the different row format of MySQL 5.6. Now the error I receive is:

ben@x131e:~/mysql-binlog-tailer/zongji$ npm test

> zongji@0.2.0 test /home/ben/mysql-binlog-tailer/zongji
> nodeunit --reporter=minimal test

events: 
RangeError: Trying to access beyond buffer length
    at checkOffset (buffer.js:582:11)
    at Buffer.readUInt8 (buffer.js:588:5)
    at readRow (/home/ben/mysql-binlog-tailer/zongji/lib/rows_event.js:92:47)
    at WriteRows.RowsEvent._fetchOneRow (/home/ben/mysql-binlog-tailer/zongji/lib/rows_event.js:79:10)
    at WriteRows.RowsEvent (/home/ben/mysql-binlog-tailer/zongji/lib/rows_event.js:54:27)
    at new WriteRows (/home/ben/mysql-binlog-tailer/zongji/lib/rows_event.js:106:13)
    at BinlogHeader.parse (/home/ben/mysql-binlog-tailer/zongji/lib/packet/binlog_header.js:47:23)
    at Protocol._parsePacket (/home/ben/mysql-binlog-tailer/zongji/node_modules/mysql/lib/protocol/Protocol.js:253:12)
    at Parser.write (/home/ben/mysql-binlog-tailer/zongji/node_modules/mysql/lib/protocol/Parser.js:77:12)
    at process._tickCallback (node.js:442:13)

Something has changed in the log format and the parser is reading past the end of the buffer. Will continue debugging tomorrow...

numtel · 2015-01-08T08:31:56Z

Also, I did try using the log_bin_use_v1_row_events MySQL configuration option but same same error persists.

nevill · 2015-01-08T08:32:54Z

@numtel Great, keep going! 👍

numtel · 2015-01-08T23:25:46Z

Okay, the error about access beyond buffer length is directly related to the binlog_checksum.
Setting binlog_checksum=NONE makes many of the tests work.

I am working on a commit that makes it possible to have the checksum turned on (although it won't verify it being correct). ~~The checksum is appended to the end of the row event but its length is not always 32 bits. Seems to be dependent on the number of columns but I'm still figuring that out.~~

It appears that there is also a different version of some field types in 5.6. So expect another commit regarding that.

nevill · 2015-01-09T01:41:18Z

Oh, it recalls me that, I intended to detect checksum by calling show variables, but for some reasons, I didn't finish that 😈

* Fixes many tests, as discussed in #7

numtel · 2015-01-09T02:27:33Z

No worries, skipping past the checksum is not too complicated. There's a javascript implementation of the crc32 algorithm but I'm not going to implement that right now.

This commit makes almost all of the tests pass now!

ben@x131e:~/mysql-binlog-tailer/zongji$ npm test

> zongji@0.2.0 test /home/ben/mysql-binlog-tailer/zongji
> nodeunit --reporter=minimal test

events: ...
filtering: ..
types: ..........Type Test Error:  temporal [ [Error: Unsupported type: undefined],
  { [Error: Packets out of order. Got: 196 Expected: 115] code: 'PROTOCOL_PACKETS_OUT_OF_ORDER', fatal: true } ]
FFF
AssertionError: 1 === 2
    at Object.strictEqual (/home/ben/mysql-binlog-tailer/zongji/node_modules/nodeunit/lib/types.js:83:39)
    at module.exports (/home/ben/mysql-binlog-tailer/zongji/test/helpers/expectEvents.js:10:8)
    at /home/ben/mysql-binlog-tailer/zongji/test/types.js:72:7
    at null._onTimeout (/home/ben/mysql-binlog-tailer/zongji/test/helpers/querySequence.js:23:13)
    at Timer.listOnTimeout [as ontimeout] (timers.js:112:15)

AssertionError: 0 == 2
    at Object.equal (/home/ben/mysql-binlog-tailer/zongji/node_modules/nodeunit/lib/types.js:83:39)
    at /home/ben/mysql-binlog-tailer/zongji/test/types.js:81:12
    at null._onTimeout (/home/ben/mysql-binlog-tailer/zongji/test/helpers/querySequence.js:23:13)
    at Timer.listOnTimeout [as ontimeout] (timers.js:112:15)

AssertionError: 2 === 0
    at Object.strictEqual (/home/ben/mysql-binlog-tailer/zongji/node_modules/nodeunit/lib/types.js:83:39)
    at module.exports (/home/ben/mysql-binlog-tailer/zongji/test/helpers/expectEvents.js:10:8)
    at /home/ben/mysql-binlog-tailer/zongji/test/types.js:72:7
    at null._onTimeout (/home/ben/mysql-binlog-tailer/zongji/test/helpers/querySequence.js:23:13)
    at Timer.listOnTimeout [as ontimeout] (timers.js:112:15)

AssertionError: 2 === 0
    at Object.strictEqual (/home/ben/mysql-binlog-tailer/zongji/node_modules/nodeunit/lib/types.js:83:39)
    at module.exports (/home/ben/mysql-binlog-tailer/zongji/test/helpers/expectEvents.js:10:8)
    at /home/ben/mysql-binlog-tailer/zongji/test/types.js:72:7
    at null._onTimeout (/home/ben/mysql-binlog-tailer/zongji/test/helpers/querySequence.js:23:13)
    at Timer.listOnTimeout [as ontimeout] (timers.js:112:15)


FAILURES: 4/143 assertions failed (10719ms)
npm ERR! Test failed.  See above for more details.
npm ERR! not ok code 0

Looks like something going on in one of the time data types.

😎 Then onto testing other versions of MySQL I guess...

numtel · 2015-01-09T09:06:37Z

MySQL provides, in the internals manual, the Date and Time Data Type Representation.

For MySQL >= 5.6.4, TIME Data types are supposedly stored in the following format:

 1 bit sign    (1= non-negative, 0= negative)
 1 bit unused  (reserved for future extensions)
10 bits hour   (0-838)
 6 bits minute (0-59) 
 6 bits second (0-59) 
---------------------
24 bits = 3 bytes

The following is output from the test suite:

Value	MySQL 5.5.40 Bits	MySQL 5.6.19 Bits
`-838:59:59`	`100000000000101001011001`	`000001011001000101001011`
`838:59:59`	`011111111111010110100111`	`111110110110111010110100`
`01:07:08`	`000000000010100111010100`	`110010000001000110000000`
`01:27:28`	`000000000011000110111000`	`110111000001011010000000`
`-01:07:08`	`111111111101011000101100`	`001110001110111001111111`
`-01:27:28`	`111111111100111001001000`	`001001001110100101111111`

MySQL < 5.6.4 values are very easy to parse: (flip the bits and subtract 1 for negatives)

> parseInt('011111111111010110100111', 2)
< 8385959 // 838:59:59
> parseInt('000000000010100111010100', 2)
< 10708 // 01:07:08

It is strange though that this does not match the documentation linked above.

TIME: A three-byte integer packed as DD×24×3600 + HH×3600 + MM×60 + SS

What is appearing is: HH×10000 + MM×100 + SS

I am not able to see how the new data corresponds with the documentation. The 10 bit set for the number 838 seems completely missing from the value for 838:59:59: 111110110110111010110100 (neither normal, flipped-bits, or reversed for big-endian)?

> 838..toString(2)
< "1101000110"

That documentation page may not be applicable to the binary log though. It's hard to tell exactly.

@nevill This is where I am right now with the type differences. The DATETIME and TIMESTAMP type differences are similar. Hopefully when I get one figured out, the others will be very similar.

With this fix complete, all MySQL versions > 5.1.15 should be compatible according to the ROWS_EVENT documentation. Right now I've got MySQL 5.6.19 running locally and 5.5.40 in a Vagrant instance. I haven't used Docker yet but in order to test more versions, I'm thinking I'll look into seeing if it's possible to configure Docker instances to run the tests with each minor version of MySQL from 5.1 -> 5.6. (and maybe 5.7?)

numtel · 2015-01-09T11:06:43Z

Woo! 😺 Found the original functions in the MySQL source:
https://github.com/mysql/mysql-server/blob/5.6/sql/log_event.cc#L2132-2151

* Used instead of TIME in MySQL > 5.6.4 * Fractional second support * DATETIME2, TIMESTAMP2 still todo #7

numtel · 2015-01-10T09:16:52Z

Got the TIME2 data type decoded! 😤
(Ignore the extra commits above, it's all the same one. I had some extra logging to remove and had to test multiple fraction precision levels)

Commands to run the new time tests:

$ node_modules/.bin/nodeunit --reporter=minimal test/types.js -t time_fraction
$ node_modules/.bin/nodeunit --reporter=minimal test/types.js -t time_no_fraction

TIMESTAMP2 and DATETIME2 should be pretty simple now but it's late so they have to wait... 😴

* Used instead of TIME in MySQL > 5.6.4 * Fractional second support * DATETIME2, TIMESTAMP2 still todo #7

* Used instead of DATETIME in MySQL >= 5.6.4 * Fractional second support to milliseconds * TIMESTAMP2 still todo * Related issue: #7

* All tests now pass with MySQL server 5.6.19 and 5.5.40 * Wrap up #7

numtel · 2015-01-11T05:45:09Z

@nevill With that last commit, you should have no problem using npm test to run all tests.
😄

numtel · 2015-01-15T10:01:28Z

@nevill Travis CI support will be ready soon, I will make it run the tests using all of the latest patch releases:

5.1.73
5.5.41
5.6.22
5.7.5 m15 (Might as well try...)

I just got it working with 5.1.73:
https://travis-ci.org/numtel/zongji/builds/47096255

Time to sleep now but the other versions will be very much the same. And, I have to make the tests actually quit on success. Right now, the process keeps running because ZongJi does not close its connection after the last test.

nevill · 2015-01-15T13:53:03Z

@numtel Awesome, wish you good luck on travis. 👍

But, the tests are still not passed on my MySQL 5.6.13.

nevill@mba-nevill zongji(master *) $ npm test

> zongji@0.2.0 test /Users/nevill/working/mysql-binlog/zongji
> nodeunit --reporter=minimal test

events:
/Users/nevill/working/mysql-binlog/zongji/test/events.js:75
          test.equal(events[1].rows[0].col, 10);
                              ^
TypeError: Cannot read property 'rows' of undefined
    at /Users/nevill/working/mysql-binlog/zongji/test/events.js:75:31
    at null._onTimeout (/Users/nevill/working/mysql-binlog/zongji/test/helpers/querySequence.js:23:13)
    at Timer.listOnTimeout [as ontimeout] (timers.js:112:15)
npm ERR! Test failed.  See above for more details.

* Tested 5.6.13 in process, should work * querySequence timeout increased from 200ms=>800ms * nevill#7

* Tested 5.6.13 in process, should work * querySequence timeout increased from 200ms=>800ms * #7

numtel · 2015-01-16T04:54:17Z

Check out these test results: https://travis-ci.org/nevill/zongji/builds/47205912
There's a test results badge up on the readme 👍

The tests should probably now pass for you on your machine. I did run 5.6.13 on Travis successfully but for some reason Travis would not work with 4 MySQL servers running at the same time (see these results) so I have limited the test to 5.1.73, 5.5.41, and 5.6.22 (newest patch versions of each minor release).

The output you posted about the undefined variable is due to the test looking for the events in ZongJi too soon after running the query in MySQL. Before this commit, the interval was 200ms. In order to make the tests run smoothly on Travis CI, the new default is 800ms.

If you still experience the same error, you may specify this delay using an environment variable when running the tests. Like this:

$ QUERY_DELAY=1200 npm test

…eout * Max wait: 3000ms * Removed QUERY_DELAY environment variable configuration #7

numtel · 2015-01-17T05:36:27Z

@nevill With the commit I just posted, the delay has been replaced with simply waiting (up to 3000ms) for the events to appear. You should no longer see that error at all and the tests run about 3x faster than before.

nevill · 2015-02-01T10:27:34Z

Finally, I see why I cannot have tests passed. It relates to binlog_do_db = employees I have set. 😭

Since there is one gotcha on this option, I would remove it from my.cnf.

- see #7 (comment)

numtel self-assigned this Jan 7, 2015

This was referenced Jan 7, 2015

Binary log does not support MySQL 5.6 numtel/meteor-mysql#3

Closed

Does not support MySQL 5.6 numtel/mysql-live-select#1

Closed

numtel added a commit that referenced this issue Jan 8, 2015

Make querySequence callback asynchronous

14dee38

* Fixes error message posted in #7 * Reveals new error message for MySQL 5.6

numtel added a commit that referenced this issue Jan 9, 2015

Recognize checksum in row event

57ca7ab

* Fixes many tests, as discussed in #7

numtel added a commit that referenced this issue Jan 10, 2015

TIME2 data type added and tested

22b6d57

* Used instead of TIME in MySQL > 5.6.4 * Fractional second support * DATETIME2, TIMESTAMP2 still todo #7

numtel added a commit that referenced this issue Jan 10, 2015

TIME2 data type added and tested

08871f3

* Used instead of TIME in MySQL > 5.6.4 * Fractional second support * DATETIME2, TIMESTAMP2 still todo #7

numtel added a commit that referenced this issue Jan 10, 2015

TIME2 data type added and tested

bb94f6d

* Used instead of TIME in MySQL > 5.6.4 * Fractional second support * DATETIME2, TIMESTAMP2 still todo #7

numtel added a commit that referenced this issue Jan 10, 2015

TIME2 data type added and tested

f84f0fd

* Used instead of TIME in MySQL > 5.6.4 * Fractional second support * DATETIME2, TIMESTAMP2 still todo #7

numtel added a commit that referenced this issue Jan 11, 2015

TIME2 data type added and tested

93f498a

* Used instead of TIME in MySQL > 5.6.4 * Fractional second support * DATETIME2, TIMESTAMP2 still todo #7

numtel added a commit that referenced this issue Jan 11, 2015

DATETIME2 data type added and tested

538a093

* Used instead of DATETIME in MySQL >= 5.6.4 * Fractional second support to milliseconds * TIMESTAMP2 still todo * Related issue: #7

numtel added a commit that referenced this issue Jan 11, 2015

DATETIME2 data type added and tested

f39e91b

* Used instead of DATETIME in MySQL >= 5.6.4 * Fractional second support to milliseconds * TIMESTAMP2 still todo * Related issue: #7

numtel added a commit that referenced this issue Jan 11, 2015

TIMESTAMP2 data type added and tested

8f012db

* All tests now pass with MySQL server 5.6.19 and 5.5.40 * Wrap up #7

numtel added a commit to numtel/zongji that referenced this issue Jan 15, 2015

Travis CI with MySQL 5.1.73, 5.5.41, 5.6.22

06fb2b4

* Tested 5.6.13 in process, should work * querySequence timeout increased from 200ms=>800ms * nevill#7

numtel added a commit to numtel/zongji that referenced this issue Jan 16, 2015

Travis CI with MySQL 5.1.73, 5.5.41, 5.6.22

98d6036

* Tested 5.6.13 in process, should work * querySequence timeout increased from 200ms=>800ms * nevill#7

numtel added a commit that referenced this issue Jan 16, 2015

Travis CI with MySQL 5.1.73, 5.5.41, 5.6.22

38f3819

* Tested 5.6.13 in process, should work * querySequence timeout increased from 200ms=>800ms * #7

numtel added a commit that referenced this issue Jan 17, 2015

Fixed tests to wait for events instead of checking after a single tim…

c6248f5

…eout * Max wait: 3000ms * Removed QUERY_DELAY environment variable configuration #7

nevill mentioned this issue Jan 28, 2015

npm上的版本不可用 #8

Closed

nevill added a commit that referenced this issue Feb 1, 2015

Update README

be31d8c

- see #7 (comment)

nevill closed this as completed Feb 1, 2015

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Tests are not passed #7

Tests are not passed #7

nevill commented Jan 7, 2015

numtel commented Jan 7, 2015

numtel commented Jan 8, 2015

numtel commented Jan 8, 2015

nevill commented Jan 8, 2015

numtel commented Jan 8, 2015

nevill commented Jan 9, 2015

numtel commented Jan 9, 2015

numtel commented Jan 9, 2015

numtel commented Jan 9, 2015

numtel commented Jan 10, 2015

numtel commented Jan 11, 2015

numtel commented Jan 15, 2015

nevill commented Jan 15, 2015

numtel commented Jan 16, 2015

numtel commented Jan 17, 2015

nevill commented Feb 1, 2015

Tests are not passed #7

Tests are not passed #7

Comments

nevill commented Jan 7, 2015

numtel commented Jan 7, 2015

numtel commented Jan 8, 2015

numtel commented Jan 8, 2015

nevill commented Jan 8, 2015

numtel commented Jan 8, 2015

nevill commented Jan 9, 2015

numtel commented Jan 9, 2015

numtel commented Jan 9, 2015

numtel commented Jan 9, 2015

numtel commented Jan 10, 2015

numtel commented Jan 11, 2015

numtel commented Jan 15, 2015

nevill commented Jan 15, 2015

numtel commented Jan 16, 2015

numtel commented Jan 17, 2015

nevill commented Feb 1, 2015