nifi-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Anand Dev <anandt8...@gmail.com>
Subject Re: CaptureChangeMySQL - throwing Binlog connector communications failure
Date Fri, 16 Nov 2018 15:50:12 GMT
Yes, it fails with same message.

And I noticed that it happened in the sequence, ROTATE event followed by
FORMAT_DESCRIPTION event followed by above ERROR
When I reset with same binlog position, it again follows same order and
fails. I then have to reset with latest binlog pos but that costs data loss.

I have also seen instances when it has successfully processed these events
but not sure why it fails sometimes and everytime it fails after
FORMAT_DESCRIPTION.

Error is same:
 INFO [Process Cluster Protocol Request-3]
o.a.n.c.p.impl.SocketProtocolListener Finished processing request
b731e751-c486-4820-bffd-2eb543240457 (type=HEARTBEAT, length=2781 bytes)
from xxxxxxxxxx:5001 in 1 millis
 INFO [blc-172.16.2.223:5101] c.g.shyiko.mysql.binlog.BinaryLogClient
Connected to xxxxxxxx:5324 at  (sid:65535, cid:239876)
 INFO [Timer-Driven Process Thread-2]
o.a.n.c.m.processors.CaptureChangeMySQL
CaptureChangeMySQL[id=879f5c10-0166-1000-0000-00005772bb34] Got message
event type: ROTATE
 INFO [Timer-Driven Process Thread-2]
o.a.n.c.m.processors.CaptureChangeMySQL
CaptureChangeMySQL[id=879f5c10-0166-1000-0000-00005772bb34] Got message
event type: FORMAT_DESCRIPTION
 ERROR [Timer-Driven Process Thread-7]
o.a.n.c.m.processors.CaptureChangeMySQL
CaptureChangeMySQL[id=879f5c10-0166-1000-0000-00005772bb34] Binlog
connector communications failure: could not find next log; the first event
'bin_5101.000013' at 2343174, the last event read from
'/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at 2343260, the last byte
read from '/u01/mysql/var/log/binlogs/bin_5101.000013' at 2343260.:
com.github.shyiko.mysql.binlog.network.ServerException: could not find next
log; the first event 'bin_5101.000013' at 2343174, the last event read from
'/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at 2343260, the last byte
read from '/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at 2343260.
com.github.shyiko.mysql.binlog.network.ServerException: could not find next
log; the first event 'bin_5101.000013' at 2343174, the last event read from
'/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at 2343260, the last byte
read from '/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at 2343260.
        at
com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:882)
        at
com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559)
        at
com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793)
        at java.lang.Thread.run(Thread.java:745)


I face this scenario in every 2-3 days. And surprisingly, the binlog file
never changed still received ROTATE events, do you know any reason why
MySQL sends ROTATE and FOR_DES events even when there is no change in
binlog file?

P.S. using NiFi 1.4

On Thu, Nov 15, 2018 at 11:02 AM Koji Kawamura <ijokarumawak@gmail.com>
wrote:

> > Sometimes it fails (I ensure that the state is cleared), and then I have
> to restart it with latest binlog position.
>
> Does it fail with the same error message?
> com.github.shyiko.mysql.binlog.network.ServerException: could not find
> next log; the first event 'bin_8101.000001' at 142923964, the last
> event read from '/u01/mysql/8101/var/log/binlogs/bin_8101.000001' at
> 142924061, the last byte read from
> '/u01/mysql/8101/var/log/binlogs/bin_8101.000001' at 142924061.
>
> Excuse me if I'm not understanding it correctly, but you mean when you
> clear the processor state and manually put "Initial Binlog Filename"
> and "Initial Binlog Position" the processor fails to start with the
> above error message? If so, where did you get the initial binlog
> filename and position?
>
> On Wed, Nov 14, 2018 at 8:50 PM Anand Dev <anandt8dev@gmail.com> wrote:
> >
> > When I restart the Processor from the binlog pos where it stopped, not
> everytime it starts successfully.
> >
> > Sometimes it fails (I ensure that the state is cleared), and then I have
> to restart it with latest binlog position.
> >
> > Is there any thing apart from state to be taken care while restarting
> the processor from any binlog position?
> >
> >
> > On Tue, Nov 13, 2018 at 7:27 AM Koji Kawamura <ijokarumawak@gmail.com>
> wrote:
> >>
> >> Hi Anand,
> >>
> >> I'm not sure what caused the error, but I believe the error is MySQL
> error 1236.
> >> The error can happen with different reasons, you may find this article
> >> informative.
> >>
> https://www.percona.com/blog/2014/10/08/mysql-replication-got-fatal-error-1236-causes-and-cures/
> >>
> >> Also, there is a JIRA that may be related to the issue.
> >> "Make Change Data Capture (CDC) processor for MySQL refer to GTID"
> >> https://issues.apache.org/jira/browse/NIFI-5739
> >>
> >> Did your MySQL server cluster undergo master change recently?
> >>
> >> If the error keeps happening and you can't get events from the binlog
> >> any more, I'd stop the CaptureChangeMySQL processor and clear its
> >> state, then restart capturing to recover from that situation. If your
> >> use-case allows that..
> >> This will do the same thing with the one described in the preceding
> >> percona article.
> >> > The solution would be to move the slave thread to the next available
> binary log and initialize slave thread with the first available position on
> binary log as below:
> >>
> >> Thanks,
> >> Koji
> >> On Mon, Nov 12, 2018 at 10:28 PM Anand Chandrashekhar Tirthgirikar
> >> <anand.tirthgirikar@e2open.com> wrote:
> >> >
> >> > Thanks Koji for the resolution of previous issue.
> >> >
> >> >
> >> >
> >> > But I see below error again and again once in a day. There is nothing
> else in the logs apart from below error.
> >> >
> >> >
> >> >
> >> > Can you please tell what could be the problem here? Is it from server
> side or from processor or any network issue? We are not able to reproduce
> it.
> >> >
> >> >
> >> >
> >> >
> >> >
> >> > 2018-11-12 11:46:31,952 ERROR [Timer-Driven Process Thread-9]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=df913697-f589-121f-b681-da192917092a] Binlog
> connector communications failure: could not find next log; the first event
> 'bin_8101.000001' at 142923964, the last event read from
> '/u01/mysql/8101/var/log/binlogs/bin_8101.000001' at 142924061, the last
> byte read from '/u01/mysql/8101/var/log/binlogs/bin_8101.000001' at
> 142924061.: com.github.shyiko.mysql.binlog.network.ServerException: could
> not find next log; the first event 'bin_8101.000001' at 142923964, the last
> event read from '/u01/mysql/8101/var/log/binlogs/bin_8101.000001' at
> 142924061, the last byte read from
> '/u01/mysql/8101/var/log/binlogs/bin_8101.000001' at 142924061.
> >> >
> >> > com.github.shyiko.mysql.binlog.network.ServerException: could not
> find next log; the first event 'bin_8101.000001' at 142923964, the last
> event read from '/u01/mysql/8101/var/log/binlogs/bin_8101.000001' at
> 142924061, the last byte read from
> '/u01/mysql/8101/var/log/binlogs/bin_8101.000001' at 142924061.
> >> >
> >> >         at
> com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:882)
> >> >
> >> >         at
> com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559)
> >> >
> >> >         at
> com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793)
> >> >
> >> >         at java.lang.Thread.run(Thread.java:745)
> >> >
> >> >
> >> >
> >> >
> >> >
> >> > From: Koji Kawamura <ijokarumawak@gmail.com>
> >> > Sent: 23 October 2018 12:02
> >> > To: users@nifi.apache.org
> >> > Subject: Re: CaptureChangeMySQL - throwing Binlog connector
> communications failure
> >> >
> >> >
> >> >
> >> > Hello,
> >> >
> >> > Thanks for reporting the issue and the detailed analysis.
> >> > I was able to reproduce by setting short wait_timeout as 30 sec.
> >> >
> >> > I'm not aware of any work-around to make keep alive CaptureChangeMySQL
> >> > at the moment.
> >> > But you can write a script to stop/start CaptureChangeMySQL processor
> >> > using NiFi API to refresh underlying JDBC connection.
> >> > NipyAPI can be useful to write such scripts.
> >> > https://github.com/Chaffelson/nipyapi
> >> >
> >> > I submit a JIRA for this issue.
> >> > https://issues.apache.org/jira/browse/NIFI-5739
> >> >
> >> > Thanks,
> >> > Koji
> >> >
> >> >
> >> > On Wed, Oct 10, 2018 at 9:42 PM Anand Dev <anandt8dev@gmail.com>
> wrote:
> >> > >
> >> > > In logs, below error is reported
> >> > >
> >> > > 2018-10-10 00:16:19,766 ERROR [Timer-Driven Process Thread-1]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=3c3f6e89-8401-3a67-a49d-3af14abf13dc] Error in
> getting DDL Table info create table .... :
> com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No
> operations allowed after connection closed.
> >> > >
> >> > > Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:
> The last packet successfully received from the server was 58,006,344
> milliseconds ago. The last packet sent successfully to the server was
> 58,006,345 milliseconds ago. is longer than the server configured value of
> 'wait_timeout'. You should consider either expiring and/or testing
> connection validity before use in your application, increasing the server
> configured values for client timeouts, or using the Connector/J connection
> property 'autoReconnect=true' to avoid this problem.
> >> > >
> >> > > It happened because the connection got stale / dead after 8 hours.
> >> > >
> >> > > How to keep alive CaptureChangeMySQL processor connection with DB
?
> >> > > One way would be increasing 'wait_timeout' to high value but the
> error can still occur post that time.
> >> > > How to keep alive connection forever unless processor is stopped?
> >> > >
> >> > > On Wed, Oct 10, 2018 at 4:41 PM Anand Dev <anandt8dev@gmail.com>
> wrote:
> >> > >>
> >> > >> When I start the CaptureChangeMySQL processor, it worked fine
till
> the point when DDL event occured for Creating a table.
> >> > >>
> >> > >> Processor captured the CREATE table event successfully.
> >> > >> Next, when record was inserted in the newly created table, it
> threw below error and stopped capturing further events.
> >> > >>
> >> > >> ERROR
> >> > >> ===============
> >> > >> Binlog connector communications failure: could not find next log;
> the first event 'bin_5101.000013' at 921485, the last event read from
> '/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at 921565, the last byte
> read from '/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at 921565
> >> > >>
> >> > >> com.github.shyiko.mysql.binlog.network.ServerException: could
not
> find next log; the first event 'bin_5101.000013' at 921485, the last event
> read from '/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at 921565, the
> last byte read from '/u01/mysql/5101/var/log/binlogs/bin_5101.000013' at
> 921565
> >> > >> ================
> >> > >>
> >> > >> Can someone suggest what's going wrong here?
>

Mime
View raw message