Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ensure that we handle "on_row_event" before "on_save_position" #5

Closed
walro opened this issue Nov 18, 2015 · 6 comments · Fixed by #7
Closed

Ensure that we handle "on_row_event" before "on_save_position" #5

walro opened this issue Nov 18, 2015 · 6 comments · Fixed by #7
Assignees

Comments

@walro
Copy link
Contributor

walro commented Nov 18, 2015

I think we do now, but we need tests to confirm it and ensure that we don't break it in the future.

@walro walro changed the title Ensure that we handle on_row_event before on_save_event Ensure that we handle "on_row_event" before "on_save_event" Nov 18, 2015
@walro walro changed the title Ensure that we handle "on_row_event" before "on_save_event" Ensure that we handle "on_row_event" before "on_save_position" Nov 18, 2015
@walro
Copy link
Contributor Author

walro commented Nov 18, 2015

@walro
Copy link
Contributor Author

walro commented Nov 18, 2015

It's a LinkedList and I found this: http://stackoverflow.com/a/4767638 so I guess that we should add the on_row_event listener first.

@roback
Copy link
Member

roback commented Nov 18, 2015

  describe "#on_row_event, #on_save_position" do
    context "when a row is inserted" do
      let(:actual_event_order) do
        event_order = []
        subject.on_row_event { |_| event_order << :on_row_event }
        subject.on_save_position { |_, _| event_order << :on_save_position }

        subject.start_in_thread

        DatabaseHelper.insert(table_name, mysql_row)

        sleep 0.1 while event_order.count < 4
        event_order
      end
      let(:expected_event_order) { [ :on_row_event, :on_save_position ] }

      it "should receive the events in correct order" do
        expect(actual_event_order).to eq(expected_event_order)
      end
    end
  end
Failures:

  1) Ecco::Client#on_row_event, #on_save_position when a row is inserted should receive the events in correct order
     Failure/Error: expect(actual_event_order).to eq(expected_event_order)

       expected: [:on_row_event, :on_save_position]
            got: [:on_save_position, :on_save_position, :on_save_position, :on_row_event]

       (compared using ==)

       Diff:
       @@ -1,2 +1,2 @@
       -[:on_row_event, :on_save_position]
       +[:on_save_position, :on_save_position, :on_save_position, :on_row_event]

     # ./spec/integration/client_spec.rb:80:in `block in (root)'

@walro
Copy link
Contributor Author

walro commented Nov 18, 2015

From your test and from the LinkedList knowledge we now have attained I am certain we should register our row_event listener before our save_position listener. It would also be interesting to understand why we see four event (3 save followed by 1 row).

@roback roback self-assigned this Nov 19, 2015
@roback
Copy link
Member

roback commented Nov 19, 2015

Looks like mysql adds BEGIN (QueryEvent) and COMMIT (called XidEvent, explained here) around each insert. The first :save_position_event is triggered by the ROTATE event (I have no idea why the ROTATE is triggered though), end the second :save_position_event is caused by a BEGIN statement which is added before each query apparently.

I added a logger to sequel and added a event listener which just prints each event.

  #on_row_event, #on_save_position
    when a row is inserted
I, [2015-11-19T10:52:25.240000 #60842]  INFO -- : (0.001000s) DROP TABLE IF EXISTS `ecco_test_table`
I, [2015-11-19T10:52:25.245000 #60842]  INFO -- : (0.003000s) CREATE TABLE `ecco_test_table` (`id` integer PRIMARY KEY AUTO_INCREMENT, `column1` varchar(255))
RotateEventData{binlogFilename='mysql-bin.000150', binlogPosition=8107}
-------------
FormatDescriptionEventData{binlogVersion=4, serverVersion='5.5.46-0ubuntu0.14.04.2-log', headerLength=19}
-------------
QueryEventData{threadId=26379, executionTime=0, errorCode=0, database='ecco_test', sql='BEGIN'}
-------------
TableMapEventData{tableId=619, database='ecco_test', table='ecco_test_table', columnTypes=3, 15, columnMetadata=0, 255, columnNullability={1}}
-------------
I, [2015-11-19T10:52:25.257000 #60842]  INFO -- : (0.002000s) INSERT INTO `ecco_test_table` (`column1`) VALUES ('a value')
WriteRowsEventData{tableId=619, includedColumns={0, 1}, rows=[
    [1, a value]
]}
-------------
XidEventData{xid=57621}
-------------
[:on_save_position, :on_save_position, :on_row_event, :on_save_position]
I, [2015-11-19T10:52:25.262000 #60842]  INFO -- : (0.002000s) DROP TABLE `ecco_test_table`
      should receive the save event after the row event

@roback
Copy link
Member

roback commented Nov 19, 2015

Commented out the FLUSH BINARY LOGS query in DatabaseHelper but i'm still receiving the rotate event.

This could be a clue :)

https://github.com/shyiko/mysql-binlog-connector-java/blob/671c7e8cebeec61487dabb0c12f728b51916753a/src/main/java/com/github/shyiko/mysql/binlog/BinaryLogClient.java#L646

roback added a commit that referenced this issue Nov 19, 2015
Row events should be received before save events.

close #5
roback added a commit that referenced this issue Nov 19, 2015
The client always emits an initial save_position event when it starts.

Related to #5
@roback roback closed this as completed in #7 Nov 19, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants