You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@nifi.apache.org by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn> on 2019/07/02 04:05:51 UTC
CaptureChangeMysql initial binlog position not work
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the last posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by Koji Kawamura <ij...@gmail.com>.
Hi Lei,
Good question.
The issue comes from a bad combination of BEGIN and COMMIT.
If you start with 379, COMMIT (at 1900) is processed before the next BEGIN
(at 1996).
A COMMIT event reset 'inTransaction' flag.
The error occurs if the processor stops after BEGIN event, then restarts
with another BEGIN event.
If you start with 1931, I think you'll get the same error.
Thanks,
Koji
On Wed, Jul 10, 2019 at 11:22 AM wanglei2@geekplus.com.cn <
wanglei2@geekplus.com.cn> wrote:
>
> Hi Koji,
>
> Thanks very much. We finally got the reason.
>
> Actullay i don't really fully understand it.
> When the initial position is set to mysql-bin.000494/379, there's still
> some BEGIN event close to it. For example, the 1996 position. But there's
> no the stack trace error log.
> Perhaps the event before it（Rows_query, Table_map etc） cleared the 'inTransaction'
> variable you mentioned.
> But when the initial position is set to mysql-bin.000494/4, why the
> 'inTransaction' unable to be cleared? There's also 3 events
> (Format_desc, Previous_gtids, Gtid) before the BEGIN event.
>
>
>
>
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* Koji Kawamura <ij...@gmail.com>
> *Date:* 2019-07-10 08:39
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: Re: CaptureChangeMysql clear state not work
> Hi Lei,
>
> Thank you very much for sharing the stack trace and the event table.
> Now I understand what went wrong.
> Although binlog filename and position is cleared when the processor stops,
> there are other instance variables the processor holds.
> The exception is thrown because one of such instance variables,
> 'inTransaction' is not cleared when the processor stops.
>
> So, consuming from initial binlog works after NiFi restart. But restarting
> the processor doesn't, because 'inTransaction' remains true.
>
> I filed a JIRA to address this issue. Hopefully this will be addressed
> soon.
> NIFI-6428: CaptureChangeMySQL throws IOException with BIGIN event due to
> lingering 'inTransaction' instance variable
> https://issues.apache.org/jira/browse/NIFI-6428
>
> Thanks again for your patience and reporting the issue!
>
> Koji
>
> On Tue, Jul 9, 2019 at 8:54 PM wanglei2@geekplus.com.cn <
> wanglei2@geekplus.com.cn> wrote:
>
>> Hi Koji，
>>
>> Seems it is related with the Initial Binlog Position number i set.
>>
>> When I set to mysql-bin.000494/4, there will be quickly an error and
>> then the position is set to a value that is approximately the same with the
>> previous value
>> But when i set to mysql-bin.000494/379, it will work as expected.
>> But I don't know why.
>>
>> Flowing is the binlog position info and the error log when set to 4
>>
>>
>>
>> java.io.IOException: BEGIN event received while already processing a
>> transaction. This could indicate that your binlog position is invalid.
>> org.apache.nifi.processor.exception.ProcessException:
>> java.io.IOException: BEGIN event received while already processing a
>> transaction. This could indicate that your binlog position is invalid.
>> at
>> org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.onTrigger(CaptureChangeMySQL.java:593)
>> at
>> org.apache.nifi.controller.StandardProcessorNode.onTrigger(StandardProcessorNode.java:1162)
>> at
>> org.apache.nifi.controller.tasks.ConnectableTask.invoke(ConnectableTask.java:209)
>> at
>> org.apache.nifi.controller.scheduling.TimerDrivenSchedulingAgent$1.run(TimerDrivenSchedulingAgent.java:117)
>> at org.apache.nifi.engine.FlowEngine$2.run(FlowEngine.java:110)
>> at
>> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>> at
>> java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
>> at
>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
>> at
>> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
>> at
>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> at java.lang.Thread.run(Thread.java:745)
>> Caused by: java.io.IOException: BEGIN event received while already
>> processing a transaction. This could indicate that your binlog position is
>> invalid.
>> at
>> org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.outputEvents(CaptureChangeMySQL.java:793)
>> at
>> org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.onTrigger(CaptureChangeMySQL.java:571)
>> ... 11 common frames omitted
>> 2019-07-09 19:16:47,521 DEBUG [Timer-Driven Process Thread-1]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=4ab2b03c-7c51-3452-13ec-f7715baa1464] Returning
>> CLUSTER State: StandardStateMap[version=1472, values={cdc.sequence.id=339754,
>> binlog.filename=mysql-bin.000494, binlog.position=27915427}]
>>
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
>> *From:* Koji Kawamura <ij...@gmail.com>
>> *Date:* 2019-07-08 09:54
>> *To:* users <us...@nifi.apache.org>
>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>> Hi Lei,
>>
>> Thanks for providing the additional information.
>>
>> By looking at the code and tested a live MySQL and NiFi, I can see
>> CaptureChangeMySQL works as expected in my environment. The processor uses
>> the specified initial binlog position, and generates FlowFiles based on
>> what it receives. It doesn't require NiFi restart, just stopping the
>> processor, clearing its state, then restarting it works, and provide the
>> consistent results.
>>
>> Although it could be possible that in a special circumstance, that NiFi,
>> or the underlying binlog library NiFi uses, or MySQL server to return a
>> cached binlog position.. but I can't find that behavior or any
>> documentation.
>>
>> Please make sure that CaptureChangeMySQL 'Retrieve All Records' is set to
>> 'false' again. If it's not, the processor ignores specified initial binlog
>> position.
>>
>> # For further investigation:
>>
>> I'd suggest counting the number of FlowFiles as below, to rule-out the
>> possibility that having different results by restarting NiFi, or restarting
>> the processor.
>> 1. Stop CaptureChangeMySQL, clear its state, configure initial binlog
>> filename and position with ones confirmed available by SHOW BINARY LOGS sql.
>> 2. Clear the queued FlowFiles at the connection between
>> CaptureChangeMySQL and LogAttribute, by right-clicking the connection and
>> selecting 'Empty queue'. At this point, the queue should have 0 FlowFiles.
>> 3. Restart NiFi, and start CaptureChangeMySQL processor. After running it
>> for a while, stop the processor. Memorize the processor state, and the
>> number of generated FlowFiles (queued at the connection).
>> 4. Repeat step #1 and #2. But don't restart NiFi this time, instead,
>> restart the CaptureChangeMySQL processor. After running it for a while,
>> stop the processor. Memorize the processor state, and the number of
>> generated FlowFiles (queued at the connection).
>>
>> At the step #3 and #4, please log FlowFile contests by running
>> LogAttributes with 'Log Payload' as true. Then copy nifi-app.log to
>> different files to preserve them and check diffs later for further
>> investigation. If it didn't work as expected, these logs will be very
>> helpful for further debugging.
>>
>> My expectation is, having the approximately the same number of generated
>> FlowFiles at step #3 and #4, regardless how long did they take. If it
>> didn't work like that, we will be able to research what caused different
>> results.
>>
>> Thanks,
>> Koji
>>
>> On Fri, Jul 5, 2019 at 8:43 PM wanglei2@geekplus.com.cn <
>> wanglei2@geekplus.com.cn> wrote:
>>
>>>
>>> By grep and counting the lines contains ‘Standard FlowFile Attributes’
>>> in my nifi-app.log, #A and #B is quite different
>>> By observing the Queue number after stop the downstream processor in my
>>> nifi flow, #A and #B is also different.
>>>
>>>
>>>
>>> ------------------------------
>>> wanglei2@geekplus.com.cn
>>>
>>>
>>> *From:* wanglei2@geekplus.com.cn
>>> *Date:* 2019-07-05 19:14
>>> *To:* users <us...@nifi.apache.org>
>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>
>>> I used a business database of our company. There's a few tomcat
>>> applications that will select/update/insert/delete on the database.
>>> Sorry i am new to Nifi and have no idea how to count the number of
>>> FlowFiles. Let me google about it. Please let me know if there's any
>>> document available.
>>>
>>> Thanks,
>>> Lei
>>> ------------------------------
>>> wanglei2@geekplus.com.cn
>>>
>>>
>>> *From:* Koji Kawamura <ij...@gmail.com>
>>> *Date:* 2019-07-05 16:46
>>> *To:* users <us...@nifi.apache.org>
>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>> Hi Lei,
>>>
>>> I have few questions.
>>>
>>> How do you update MySQL server while testing CaptureChangeMySQL?
>>> Is there another program keep sending data to MySQL server?
>>>
>>> A. how many FlowFiles did the CaptureChangeMySQL generated after
>>> restarting NiFi?
>>> B. how many FlowFiles did the CaptureChangeMySQL generated after
>>> clearing the state and restart CaptureChangeMySQL?
>>>
>>> Are the number #A and #B the same? Or different?
>>>
>>> Thanks,
>>> Koji
>>>
>>>
>>> On Fri, Jul 5, 2019 at 3:54 PM wanglei2@geekplus.com.cn <
>>> wanglei2@geekplus.com.cn> wrote:
>>>
>>>>
>>>> Only 7 days' log retained.
>>>>
>>>>
>>>> First I restarted the nifi service by bin/nifi.sh resart. Clear the
>>>> state, set the initial position to mysql-bin.000493/4. Start it
>>>>
>>>> 2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306]
>>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>>>> at mysql-bin.000493/4 (sid:3721, cid:28459969)
>>>> Quickly logging a Standard FlowFile Attributes: show the
>>>> binlog.position: 816(a little bigger than 4) and then many many such
>>>> logging and the binlog position is becoming larger.
>>>> This is what i expected.
>>>>
>>>> After a few minutes, i stop the CaptureChangeMySQL processor. The
>>>> binlog position is 158441289, then i clear the state.
>>>> 2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>> CLUSTER State
>>>> 2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL
>>>> State
>>>> 2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL
>>>> State: StandardStateMap[version=422, values={}]
>>>>
>>>>
>>>>
>>>> Then i start the processor again:
>>>> 2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306]
>>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>>>> at mysql-bin.000493/4 (sid:3721, cid:28461051)
>>>> ..............
>>>> Quickly logging
>>>> 2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER
>>>> State to {binlog.filename=mysql-bin.000493, binlog.position=158443355,
>>>> cdc.sequence.id=137421}
>>>>
>>>> Standard FlowFile Attributes
>>>> Key: 'entryDate'
>>>> Value: 'Fri Jul 05 14:40:47 CST 2019'
>>>> Key: 'lineageStartDate'
>>>> Value: 'Fri Jul 05 14:40:47 CST 2019'
>>>> Key: 'fileSize'
>>>> Value: '1137'
>>>> FlowFile Attribute Map Content
>>>> Key: 'binlog.filename'
>>>> Value: 'mysql-bin.000493'
>>>> Key: 'binlog.position'
>>>> Value: '158439452'
>>>>
>>>>
>>>> The binlog.position is approximately the same with what i just have
>>>> cleared.
>>>>
>>>> Thanks,
>>>> Lei
>>>>
>>>>
>>>> ------------------------------
>>>> wanglei2@geekplus.com.cn
>>>>
>>>>
>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>> *Date:* 2019-07-05 14:11
>>>> *To:* users <us...@nifi.apache.org>
>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>> Hi Lei,
>>>>
>>>> Can you execute SHOW BINARY LOGS sql and share the result?
>>>> https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
>>>>
>>>> Thanks,
>>>> Koji
>>>>
>>>> On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <
>>>> wanglei2@geekplus.com.cn> wrote:
>>>>
>>>>>
>>>>> Hi Koji，
>>>>> Yes, it started with the specified initial position. And then
>>>>> updated the CLUSTER scope posion value, because it received such position
>>>>> information from MySQL server.
>>>>>
>>>>> What confused me is why the received position information from my
>>>>> MySQL Server is always approximately the same with the previous
>>>>> state position i have just cleared, but not a value that is little bigger
>>>>> than the specified initial position.
>>>>>
>>>>>
>>>>> Thanks,
>>>>> Lei
>>>>>
>>>>>
>>>>> ------------------------------
>>>>> wanglei2@geekplus.com.cn
>>>>>
>>>>>
>>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>>> *Date:* 2019-07-05 08:52
>>>>> *To:* users <us...@nifi.apache.org>
>>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>>> Hi Lei,
>>>>>
>>>>> If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope
>>>>> state to ${NIFI_HOME}/state/local.
>>>>> If your NiFi is clustered, NiFi stores CLUSTER scope state to
>>>>> Zookeeper.
>>>>>
>>>>> CaptureChangeMySQL updates CLUSTER scope state when it runs, so that
>>>>> it can start from where it stopped when it's restarted.
>>>>>
>>>>> CaptureChangeMySQL clears its variables in memory when it gets stopped.
>>>>> Then retrieve them from stored state.
>>>>> From the log you provided, the state was empty (because you cleared
>>>>> it) when it started running.
>>>>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>>>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to
>>>>> 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
>>>>>
>>>>> And after processing several events, the processor updated CLUSTER
>>>>> scope state.
>>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>>>>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>>
>>>>> To me, the processor looks working as expected.
>>>>> It started with the specified initial position. The reason it updated
>>>>> the CLUSTER scope like that is, because it received such position
>>>>> information from MySQL server.
>>>>> I'd recommend to look at MySQL server side to see what events
>>>>> available with the current binlog.
>>>>>
>>>>> Thanks,
>>>>> Koji
>>>>>
>>>>>
>>>>> On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <
>>>>> wanglei2@geekplus.com.cn> wrote:
>>>>>
>>>>>>
>>>>>>
>>>>>> Only when I restarted the nifi service, the processor consume from
>>>>>> the specialized intitial position.
>>>>>> Did the state info is always in memory ?
>>>>>>
>>>>>> ------------------------------
>>>>>> wanglei2@geekplus.com.cn
>>>>>>
>>>>>>
>>>>>> *From:* wanglei2@geekplus.com.cn
>>>>>> *Date:* 2019-07-04 16:23
>>>>>> *To:* users <us...@nifi.apache.org>
>>>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>>>>
>>>>>> Thanks Koji.
>>>>>>
>>>>>> I have tried many times, the log always show
>>>>>> Setting CLUSTER State to a value that is approximate the
>>>>>> previous state value, but not exactly the same.
>>>>>> But i have cleared the state!
>>>>>>
>>>>>>
>>>>>> Where the cluster state is stored?
>>>>>> I have configed zookeeper, But there's no node related to nifi in my
>>>>>> zookeeper
>>>>>>
>>>>>>
>>>>>>
>>>>>> Thanks,
>>>>>> Lei
>>>>>> ------------------------------
>>>>>> wanglei2@geekplus.com.cn
>>>>>>
>>>>>>
>>>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>>>> *Date:* 2019-07-04 09:37
>>>>>> *To:* users <us...@nifi.apache.org>
>>>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>>>> Hi Lei,
>>>>>>
>>>>>> The log seems that the processor started with an empty state then
>>>>>> received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its
>>>>>> state with the values derived from the latest event, QUERY.
>>>>>>
>>>>>> Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL
>>>>>> server may be helpful to understand what the binlog actually looks like.
>>>>>> https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
>>>>>>
>>>>>> Is your MySQL server clustered? If so, managing where to start
>>>>>> reading binlog by binlog position may not work in certain situations.
>>>>>> There is an existing JIRA to support GTID instead of binlog position.
>>>>>> Do you think it's related to your case?
>>>>>> https://issues.apache.org/jira/browse/NIFI-5583
>>>>>>
>>>>>> Thanks,
>>>>>> Koji
>>>>>>
>>>>>> On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <
>>>>>> wanglei2@geekplus.com.cn> wrote:
>>>>>>
>>>>>>>
>>>>>>> Hi Koji,
>>>>>>>
>>>>>>> Following is the log.
>>>>>>>
>>>>>>>
>>>>>>> 2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>>>> LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164,
>>>>>>> binlog.filename=mysql-bin.000488, binlog.position=28551660}]
>>>>>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>>>>> CLUSTER State
>>>>>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>>>>> LOCAL State
>>>>>>> 2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>>>>>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>>>>>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to
>>>>>>> 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
>>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>>> event type: ROTATE
>>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>>> event type: FORMAT_DESCRIPTION
>>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>>> event type: PREVIOUS_GTIDS
>>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>>> event type: GTID
>>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>>> event type: QUERY
>>>>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>>>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>>>>>>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>>>>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>>>>
>>>>>>>
>>>>>>> mysql-bin.000492/4 is the configed inition position, but it still
>>>>>>> set state to {binlog.filename=mysql-bin.000488,
>>>>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>>>>
>>>>>>> Why, any insight on this ?
>>>>>>>
>>>>>>>
>>>>>>> ------------------------------
>>>>>>> wanglei2@geekplus.com.cn
>>>>>>>
>>>>>>>
>>>>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>>>>> *Date:* 2019-07-03 16:14
>>>>>>> *To:* users <us...@nifi.apache.org>
>>>>>>> *Subject:* Re: CaptureChangeMysql clear state not work
>>>>>>> Hi Lei,
>>>>>>>
>>>>>>> Since 'State Update Interval' is set to '5 seconds', while the
>>>>>>> processor runs, it updates state per 5 seconds.
>>>>>>> It's possible that the processor started with the specified initial
>>>>>>> position, and consumed some binlog events then reached to the end of the
>>>>>>> binlog.
>>>>>>>
>>>>>>> After clearing the state and restart the processor, did you see some
>>>>>>> FlowFiles were generated? If so, it should be an expected behavior.
>>>>>>> Changing logging level for the processor to DEBUG may provide more
>>>>>>> insights.
>>>>>>> You can do so by adding the following entry at conf/logback.xml:
>>>>>>> <logger
>>>>>>> name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL"
>>>>>>> level="DEBUG"/>
>>>>>>>
>>>>>>> I confirmed how initial binlog position is used. The processor used
>>>>>>> the specified position if there's no stored state and 'Retrieve All
>>>>>>> Records' is false, then it stored state.
>>>>>>>
>>>>>>> Thanks,
>>>>>>> Koji
>>>>>>>
>>>>>>>
>>>>>>> On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <
>>>>>>> wanglei2@geekplus.com.cn> wrote:
>>>>>>>
>>>>>>>>
>>>>>>>> Stop -> view state -> clear state -> start again
>>>>>>>> I view the state again, the binlog.positon is still from the
>>>>>>>> previous posion, not from the initial position
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Lei
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> ------------------------------
>>>>>>>> wanglei2@geekplus.com.cn
>>>>>>>>
>>>>>>>>
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
Hi Koji,
Thanks very much. We finally got the reason.
Actullay i don't really fully understand it.
When the initial position is set to mysql-bin.000494/379, there's still some BEGIN event close to it. For example, the 1996 position. But there's no the stack trace error log.
Perhaps the event before it（Rows_query, Table_map etc） cleared the 'inTransaction' variable you mentioned.
But when the initial position is set to mysql-bin.000494/4, why the 'inTransaction' unable to be cleared? There's also 3 events (Format_desc, Previous_gtids, Gtid) before the BEGIN event.
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-10 08:39
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
Thank you very much for sharing the stack trace and the event table.
Now I understand what went wrong.
Although binlog filename and position is cleared when the processor stops, there are other instance variables the processor holds.
The exception is thrown because one of such instance variables, 'inTransaction' is not cleared when the processor stops.
So, consuming from initial binlog works after NiFi restart. But restarting the processor doesn't, because 'inTransaction' remains true.
I filed a JIRA to address this issue. Hopefully this will be addressed soon.
NIFI-6428: CaptureChangeMySQL throws IOException with BIGIN event due to lingering 'inTransaction' instance variable
https://issues.apache.org/jira/browse/NIFI-6428
Thanks again for your patience and reporting the issue!
Koji
On Tue, Jul 9, 2019 at 8:54 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji，
Seems it is related with the Initial Binlog Position number i set.
When I set to mysql-bin.000494/4, there will be quickly an error and then the position is set to a value that is approximately the same with the previous value
But when i set to mysql-bin.000494/379, it will work as expected.
But I don't know why.
Flowing is the binlog position info and the error log when set to 4
java.io.IOException: BEGIN event received while already processing a transaction. This could indicate that your binlog position is invalid.
org.apache.nifi.processor.exception.ProcessException: java.io.IOException: BEGIN event received while already processing a transaction. This could indicate that your binlog position is invalid.
at org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.onTrigger(CaptureChangeMySQL.java:593)
at org.apache.nifi.controller.StandardProcessorNode.onTrigger(StandardProcessorNode.java:1162)
at org.apache.nifi.controller.tasks.ConnectableTask.invoke(ConnectableTask.java:209)
at org.apache.nifi.controller.scheduling.TimerDrivenSchedulingAgent$1.run(TimerDrivenSchedulingAgent.java:117)
at org.apache.nifi.engine.FlowEngine$2.run(FlowEngine.java:110)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: BEGIN event received while already processing a transaction. This could indicate that your binlog position is invalid.
at org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.outputEvents(CaptureChangeMySQL.java:793)
at org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.onTrigger(CaptureChangeMySQL.java:571)
... 11 common frames omitted
2019-07-09 19:16:47,521 DEBUG [Timer-Driven Process Thread-1] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=4ab2b03c-7c51-3452-13ec-f7715baa1464] Returning CLUSTER State: StandardStateMap[version=1472, values={cdc.sequence.id=339754, binlog.filename=mysql-bin.000494, binlog.position=27915427}]
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-08 09:54
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
Thanks for providing the additional information.
By looking at the code and tested a live MySQL and NiFi, I can see CaptureChangeMySQL works as expected in my environment. The processor uses the specified initial binlog position, and generates FlowFiles based on what it receives. It doesn't require NiFi restart, just stopping the processor, clearing its state, then restarting it works, and provide the consistent results.
Although it could be possible that in a special circumstance, that NiFi, or the underlying binlog library NiFi uses, or MySQL server to return a cached binlog position.. but I can't find that behavior or any documentation.
Please make sure that CaptureChangeMySQL 'Retrieve All Records' is set to 'false' again. If it's not, the processor ignores specified initial binlog position.
# For further investigation:
I'd suggest counting the number of FlowFiles as below, to rule-out the possibility that having different results by restarting NiFi, or restarting the processor.
1. Stop CaptureChangeMySQL, clear its state, configure initial binlog filename and position with ones confirmed available by SHOW BINARY LOGS sql.
2. Clear the queued FlowFiles at the connection between CaptureChangeMySQL and LogAttribute, by right-clicking the connection and selecting 'Empty queue'. At this point, the queue should have 0 FlowFiles.
3. Restart NiFi, and start CaptureChangeMySQL processor. After running it for a while, stop the processor. Memorize the processor state, and the number of generated FlowFiles (queued at the connection).
4. Repeat step #1 and #2. But don't restart NiFi this time, instead, restart the CaptureChangeMySQL processor. After running it for a while, stop the processor. Memorize the processor state, and the number of generated FlowFiles (queued at the connection).
At the step #3 and #4, please log FlowFile contests by running LogAttributes with 'Log Payload' as true. Then copy nifi-app.log to different files to preserve them and check diffs later for further investigation. If it didn't work as expected, these logs will be very helpful for further debugging.
My expectation is, having the approximately the same number of generated FlowFiles at step #3 and #4, regardless how long did they take. If it didn't work like that, we will be able to research what caused different results.
Thanks,
Koji
On Fri, Jul 5, 2019 at 8:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
By grep and counting the lines contains ‘Standard FlowFile Attributes’ in my nifi-app.log, #A and #B is quite different
By observing the Queue number after stop the downstream processor in my nifi flow, #A and #B is also different.
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-05 19:14
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
I used a business database of our company. There's a few tomcat applications that will select/update/insert/delete on the database.
Sorry i am new to Nifi and have no idea how to count the number of FlowFiles. Let me google about it. Please let me know if there's any document available.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 16:46
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
I have few questions.
How do you update MySQL server while testing CaptureChangeMySQL?
Is there another program keep sending data to MySQL server?
A. how many FlowFiles did the CaptureChangeMySQL generated after restarting NiFi?
B. how many FlowFiles did the CaptureChangeMySQL generated after clearing the state and restart CaptureChangeMySQL?
Are the number #A and #B the same? Or different?
Thanks,
Koji
On Fri, Jul 5, 2019 at 3:54 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only 7 days' log retained.
First I restarted the nifi service by bin/nifi.sh resart. Clear the state, set the initial position to mysql-bin.000493/4. Start it
2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28459969)
Quickly logging a Standard FlowFile Attributes: show the binlog.position: 816(a little bigger than 4) and then many many such logging and the binlog position is becoming larger.
This is what i expected.
After a few minutes, i stop the CaptureChangeMySQL processor. The binlog position is 158441289, then i clear the state.
2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=422, values={}]
Then i start the processor again:
2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28461051)
..............
Quickly logging
2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000493, binlog.position=158443355, cdc.sequence.id=137421}
Standard FlowFile Attributes
Key: 'entryDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'lineageStartDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'fileSize'
Value: '1137'
FlowFile Attribute Map Content
Key: 'binlog.filename'
Value: 'mysql-bin.000493'
Key: 'binlog.position'
Value: '158439452'
The binlog.position is approximately the same with what i just have cleared.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 14:11
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
Can you execute SHOW BINARY LOGS sql and share the result?
https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
Thanks,
Koji
On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji，
Yes, it started with the specified initial position. And then updated the CLUSTER scope posion value, because it received such position information from MySQL server.
What confused me is why the received position information from my MySQL Server is always approximately the same with the previous state position i have just cleared, but not a value that is little bigger than the specified initial position.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 08:52
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope state to ${NIFI_HOME}/state/local.
If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it can start from where it stopped when it's restarted.
CaptureChangeMySQL clears its variables in memory when it gets stopped.
Then retrieve them from stored state.
From the log you provided, the state was empty (because you cleared it) when it started running.
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
And after processing several events, the processor updated CLUSTER scope state.
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
To me, the processor looks working as expected.
It started with the specified initial position. The reason it updated the CLUSTER scope like that is, because it received such position information from MySQL server.
I'd recommend to look at MySQL server side to see what events available with the current binlog.
Thanks,
Koji
On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only when I restarted the nifi service, the processor consume from the specialized intitial position.
Did the state info is always in memory ?
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-04 16:23
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Thanks Koji.
I have tried many times, the log always show
Setting CLUSTER State to a value that is approximate the previous state value, but not exactly the same.
But i have cleared the state!
Where the cluster state is stored?
I have configed zookeeper, But there's no node related to nifi in my zookeeper
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-04 09:37
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
The log seems that the processor started with an empty state then received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by Koji Kawamura <ij...@gmail.com>.
Hi Lei,
Thank you very much for sharing the stack trace and the event table.
Now I understand what went wrong.
Although binlog filename and position is cleared when the processor stops,
there are other instance variables the processor holds.
The exception is thrown because one of such instance variables,
'inTransaction' is not cleared when the processor stops.
So, consuming from initial binlog works after NiFi restart. But restarting
the processor doesn't, because 'inTransaction' remains true.
I filed a JIRA to address this issue. Hopefully this will be addressed soon.
NIFI-6428: CaptureChangeMySQL throws IOException with BIGIN event due to
lingering 'inTransaction' instance variable
https://issues.apache.org/jira/browse/NIFI-6428
Thanks again for your patience and reporting the issue!
Koji
On Tue, Jul 9, 2019 at 8:54 PM wanglei2@geekplus.com.cn <
wanglei2@geekplus.com.cn> wrote:
> Hi Koji，
>
> Seems it is related with the Initial Binlog Position number i set.
>
> When I set to mysql-bin.000494/4, there will be quickly an error and
> then the position is set to a value that is approximately the same with the
> previous value
> But when i set to mysql-bin.000494/379, it will work as expected.
> But I don't know why.
>
> Flowing is the binlog position info and the error log when set to 4
>
>
>
> java.io.IOException: BEGIN event received while already processing a
> transaction. This could indicate that your binlog position is invalid.
> org.apache.nifi.processor.exception.ProcessException: java.io.IOException:
> BEGIN event received while already processing a transaction. This could
> indicate that your binlog position is invalid.
> at
> org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.onTrigger(CaptureChangeMySQL.java:593)
> at
> org.apache.nifi.controller.StandardProcessorNode.onTrigger(StandardProcessorNode.java:1162)
> at
> org.apache.nifi.controller.tasks.ConnectableTask.invoke(ConnectableTask.java:209)
> at
> org.apache.nifi.controller.scheduling.TimerDrivenSchedulingAgent$1.run(TimerDrivenSchedulingAgent.java:117)
> at org.apache.nifi.engine.FlowEngine$2.run(FlowEngine.java:110)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: java.io.IOException: BEGIN event received while already
> processing a transaction. This could indicate that your binlog position is
> invalid.
> at
> org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.outputEvents(CaptureChangeMySQL.java:793)
> at
> org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.onTrigger(CaptureChangeMySQL.java:571)
> ... 11 common frames omitted
> 2019-07-09 19:16:47,521 DEBUG [Timer-Driven Process Thread-1]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=4ab2b03c-7c51-3452-13ec-f7715baa1464] Returning
> CLUSTER State: StandardStateMap[version=1472, values={cdc.sequence.id=339754,
> binlog.filename=mysql-bin.000494, binlog.position=27915427}]
>
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* Koji Kawamura <ij...@gmail.com>
> *Date:* 2019-07-08 09:54
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: Re: CaptureChangeMysql clear state not work
> Hi Lei,
>
> Thanks for providing the additional information.
>
> By looking at the code and tested a live MySQL and NiFi, I can see
> CaptureChangeMySQL works as expected in my environment. The processor uses
> the specified initial binlog position, and generates FlowFiles based on
> what it receives. It doesn't require NiFi restart, just stopping the
> processor, clearing its state, then restarting it works, and provide the
> consistent results.
>
> Although it could be possible that in a special circumstance, that NiFi,
> or the underlying binlog library NiFi uses, or MySQL server to return a
> cached binlog position.. but I can't find that behavior or any
> documentation.
>
> Please make sure that CaptureChangeMySQL 'Retrieve All Records' is set to
> 'false' again. If it's not, the processor ignores specified initial binlog
> position.
>
> # For further investigation:
>
> I'd suggest counting the number of FlowFiles as below, to rule-out the
> possibility that having different results by restarting NiFi, or restarting
> the processor.
> 1. Stop CaptureChangeMySQL, clear its state, configure initial binlog
> filename and position with ones confirmed available by SHOW BINARY LOGS sql.
> 2. Clear the queued FlowFiles at the connection between CaptureChangeMySQL
> and LogAttribute, by right-clicking the connection and selecting 'Empty
> queue'. At this point, the queue should have 0 FlowFiles.
> 3. Restart NiFi, and start CaptureChangeMySQL processor. After running it
> for a while, stop the processor. Memorize the processor state, and the
> number of generated FlowFiles (queued at the connection).
> 4. Repeat step #1 and #2. But don't restart NiFi this time, instead,
> restart the CaptureChangeMySQL processor. After running it for a while,
> stop the processor. Memorize the processor state, and the number of
> generated FlowFiles (queued at the connection).
>
> At the step #3 and #4, please log FlowFile contests by running
> LogAttributes with 'Log Payload' as true. Then copy nifi-app.log to
> different files to preserve them and check diffs later for further
> investigation. If it didn't work as expected, these logs will be very
> helpful for further debugging.
>
> My expectation is, having the approximately the same number of generated
> FlowFiles at step #3 and #4, regardless how long did they take. If it
> didn't work like that, we will be able to research what caused different
> results.
>
> Thanks,
> Koji
>
> On Fri, Jul 5, 2019 at 8:43 PM wanglei2@geekplus.com.cn <
> wanglei2@geekplus.com.cn> wrote:
>
>>
>> By grep and counting the lines contains ‘Standard FlowFile Attributes’
>> in my nifi-app.log, #A and #B is quite different
>> By observing the Queue number after stop the downstream processor in my
>> nifi flow, #A and #B is also different.
>>
>>
>>
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
>> *From:* wanglei2@geekplus.com.cn
>> *Date:* 2019-07-05 19:14
>> *To:* users <us...@nifi.apache.org>
>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>
>> I used a business database of our company. There's a few tomcat
>> applications that will select/update/insert/delete on the database.
>> Sorry i am new to Nifi and have no idea how to count the number of
>> FlowFiles. Let me google about it. Please let me know if there's any
>> document available.
>>
>> Thanks,
>> Lei
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
>> *From:* Koji Kawamura <ij...@gmail.com>
>> *Date:* 2019-07-05 16:46
>> *To:* users <us...@nifi.apache.org>
>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>> Hi Lei,
>>
>> I have few questions.
>>
>> How do you update MySQL server while testing CaptureChangeMySQL?
>> Is there another program keep sending data to MySQL server?
>>
>> A. how many FlowFiles did the CaptureChangeMySQL generated after
>> restarting NiFi?
>> B. how many FlowFiles did the CaptureChangeMySQL generated after clearing
>> the state and restart CaptureChangeMySQL?
>>
>> Are the number #A and #B the same? Or different?
>>
>> Thanks,
>> Koji
>>
>>
>> On Fri, Jul 5, 2019 at 3:54 PM wanglei2@geekplus.com.cn <
>> wanglei2@geekplus.com.cn> wrote:
>>
>>>
>>> Only 7 days' log retained.
>>>
>>>
>>> First I restarted the nifi service by bin/nifi.sh resart. Clear the
>>> state, set the initial position to mysql-bin.000493/4. Start it
>>>
>>> 2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306]
>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>>> at mysql-bin.000493/4 (sid:3721, cid:28459969)
>>> Quickly logging a Standard FlowFile Attributes: show the
>>> binlog.position: 816(a little bigger than 4) and then many many such
>>> logging and the binlog position is becoming larger.
>>> This is what i expected.
>>>
>>> After a few minutes, i stop the CaptureChangeMySQL processor. The
>>> binlog position is 158441289, then i clear the state.
>>> 2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>> CLUSTER State
>>> 2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL
>>> State
>>> 2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL
>>> State: StandardStateMap[version=422, values={}]
>>>
>>>
>>>
>>> Then i start the processor again:
>>> 2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306]
>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>>> at mysql-bin.000493/4 (sid:3721, cid:28461051)
>>> ..............
>>> Quickly logging
>>> 2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER
>>> State to {binlog.filename=mysql-bin.000493, binlog.position=158443355,
>>> cdc.sequence.id=137421}
>>>
>>> Standard FlowFile Attributes
>>> Key: 'entryDate'
>>> Value: 'Fri Jul 05 14:40:47 CST 2019'
>>> Key: 'lineageStartDate'
>>> Value: 'Fri Jul 05 14:40:47 CST 2019'
>>> Key: 'fileSize'
>>> Value: '1137'
>>> FlowFile Attribute Map Content
>>> Key: 'binlog.filename'
>>> Value: 'mysql-bin.000493'
>>> Key: 'binlog.position'
>>> Value: '158439452'
>>>
>>>
>>> The binlog.position is approximately the same with what i just have
>>> cleared.
>>>
>>> Thanks,
>>> Lei
>>>
>>>
>>> ------------------------------
>>> wanglei2@geekplus.com.cn
>>>
>>>
>>> *From:* Koji Kawamura <ij...@gmail.com>
>>> *Date:* 2019-07-05 14:11
>>> *To:* users <us...@nifi.apache.org>
>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>> Hi Lei,
>>>
>>> Can you execute SHOW BINARY LOGS sql and share the result?
>>> https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
>>>
>>> Thanks,
>>> Koji
>>>
>>> On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <
>>> wanglei2@geekplus.com.cn> wrote:
>>>
>>>>
>>>> Hi Koji，
>>>> Yes, it started with the specified initial position. And then
>>>> updated the CLUSTER scope posion value, because it received such position
>>>> information from MySQL server.
>>>>
>>>> What confused me is why the received position information from my
>>>> MySQL Server is always approximately the same with the previous state
>>>> position i have just cleared, but not a value that is little bigger than the
>>>> specified initial position.
>>>>
>>>>
>>>> Thanks,
>>>> Lei
>>>>
>>>>
>>>> ------------------------------
>>>> wanglei2@geekplus.com.cn
>>>>
>>>>
>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>> *Date:* 2019-07-05 08:52
>>>> *To:* users <us...@nifi.apache.org>
>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>> Hi Lei,
>>>>
>>>> If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope
>>>> state to ${NIFI_HOME}/state/local.
>>>> If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
>>>>
>>>> CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it
>>>> can start from where it stopped when it's restarted.
>>>>
>>>> CaptureChangeMySQL clears its variables in memory when it gets stopped.
>>>> Then retrieve them from stored state.
>>>> From the log you provided, the state was empty (because you cleared it)
>>>> when it started running.
>>>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>>>> at mysql-bin.000492/4 (sid:5, cid:28227568)
>>>>
>>>> And after processing several events, the processor updated CLUSTER
>>>> scope state.
>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>>>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>
>>>> To me, the processor looks working as expected.
>>>> It started with the specified initial position. The reason it updated
>>>> the CLUSTER scope like that is, because it received such position
>>>> information from MySQL server.
>>>> I'd recommend to look at MySQL server side to see what events available
>>>> with the current binlog.
>>>>
>>>> Thanks,
>>>> Koji
>>>>
>>>>
>>>> On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <
>>>> wanglei2@geekplus.com.cn> wrote:
>>>>
>>>>>
>>>>>
>>>>> Only when I restarted the nifi service, the processor consume from
>>>>> the specialized intitial position.
>>>>> Did the state info is always in memory ?
>>>>>
>>>>> ------------------------------
>>>>> wanglei2@geekplus.com.cn
>>>>>
>>>>>
>>>>> *From:* wanglei2@geekplus.com.cn
>>>>> *Date:* 2019-07-04 16:23
>>>>> *To:* users <us...@nifi.apache.org>
>>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>>>
>>>>> Thanks Koji.
>>>>>
>>>>> I have tried many times, the log always show
>>>>> Setting CLUSTER State to a value that is approximate the
>>>>> previous state value, but not exactly the same.
>>>>> But i have cleared the state!
>>>>>
>>>>>
>>>>> Where the cluster state is stored?
>>>>> I have configed zookeeper, But there's no node related to nifi in my
>>>>> zookeeper
>>>>>
>>>>>
>>>>>
>>>>> Thanks,
>>>>> Lei
>>>>> ------------------------------
>>>>> wanglei2@geekplus.com.cn
>>>>>
>>>>>
>>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>>> *Date:* 2019-07-04 09:37
>>>>> *To:* users <us...@nifi.apache.org>
>>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>>> Hi Lei,
>>>>>
>>>>> The log seems that the processor started with an empty state then
>>>>> received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its
>>>>> state with the values derived from the latest event, QUERY.
>>>>>
>>>>> Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL
>>>>> server may be helpful to understand what the binlog actually looks like.
>>>>> https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
>>>>>
>>>>> Is your MySQL server clustered? If so, managing where to start reading
>>>>> binlog by binlog position may not work in certain situations.
>>>>> There is an existing JIRA to support GTID instead of binlog position.
>>>>> Do you think it's related to your case?
>>>>> https://issues.apache.org/jira/browse/NIFI-5583
>>>>>
>>>>> Thanks,
>>>>> Koji
>>>>>
>>>>> On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <
>>>>> wanglei2@geekplus.com.cn> wrote:
>>>>>
>>>>>>
>>>>>> Hi Koji,
>>>>>>
>>>>>> Following is the log.
>>>>>>
>>>>>>
>>>>>> 2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>>> LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164,
>>>>>> binlog.filename=mysql-bin.000488, binlog.position=28551660}]
>>>>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>>>> CLUSTER State
>>>>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>>>> LOCAL State
>>>>>> 2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>>>>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>>>>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to
>>>>>> 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>> event type: ROTATE
>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>> event type: FORMAT_DESCRIPTION
>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>> event type: PREVIOUS_GTIDS
>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>> event type: GTID
>>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>>> event type: QUERY
>>>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>>>>>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>>>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>>>
>>>>>>
>>>>>> mysql-bin.000492/4 is the configed inition position, but it still
>>>>>> set state to {binlog.filename=mysql-bin.000488,
>>>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>>>
>>>>>> Why, any insight on this ?
>>>>>>
>>>>>>
>>>>>> ------------------------------
>>>>>> wanglei2@geekplus.com.cn
>>>>>>
>>>>>>
>>>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>>>> *Date:* 2019-07-03 16:14
>>>>>> *To:* users <us...@nifi.apache.org>
>>>>>> *Subject:* Re: CaptureChangeMysql clear state not work
>>>>>> Hi Lei,
>>>>>>
>>>>>> Since 'State Update Interval' is set to '5 seconds', while the
>>>>>> processor runs, it updates state per 5 seconds.
>>>>>> It's possible that the processor started with the specified initial
>>>>>> position, and consumed some binlog events then reached to the end of the
>>>>>> binlog.
>>>>>>
>>>>>> After clearing the state and restart the processor, did you see some
>>>>>> FlowFiles were generated? If so, it should be an expected behavior.
>>>>>> Changing logging level for the processor to DEBUG may provide more
>>>>>> insights.
>>>>>> You can do so by adding the following entry at conf/logback.xml:
>>>>>> <logger
>>>>>> name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL"
>>>>>> level="DEBUG"/>
>>>>>>
>>>>>> I confirmed how initial binlog position is used. The processor used
>>>>>> the specified position if there's no stored state and 'Retrieve All
>>>>>> Records' is false, then it stored state.
>>>>>>
>>>>>> Thanks,
>>>>>> Koji
>>>>>>
>>>>>>
>>>>>> On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <
>>>>>> wanglei2@geekplus.com.cn> wrote:
>>>>>>
>>>>>>>
>>>>>>> Stop -> view state -> clear state -> start again
>>>>>>> I view the state again, the binlog.positon is still from the
>>>>>>> previous posion, not from the initial position
>>>>>>>
>>>>>>> Thanks,
>>>>>>> Lei
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> ------------------------------
>>>>>>> wanglei2@geekplus.com.cn
>>>>>>>
>>>>>>>
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
Hi Koji，
Seems it is related with the Initial Binlog Position number i set.
When I set to mysql-bin.000494/4, there will be quickly an error and then the position is set to a value that is approximately the same with the previous value
But when i set to mysql-bin.000494/379, it will work as expected.
But I don't know why.
Flowing is the binlog position info and the error log when set to 4
java.io.IOException: BEGIN event received while already processing a transaction. This could indicate that your binlog position is invalid.
org.apache.nifi.processor.exception.ProcessException: java.io.IOException: BEGIN event received while already processing a transaction. This could indicate that your binlog position is invalid.
at org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.onTrigger(CaptureChangeMySQL.java:593)
at org.apache.nifi.controller.StandardProcessorNode.onTrigger(StandardProcessorNode.java:1162)
at org.apache.nifi.controller.tasks.ConnectableTask.invoke(ConnectableTask.java:209)
at org.apache.nifi.controller.scheduling.TimerDrivenSchedulingAgent$1.run(TimerDrivenSchedulingAgent.java:117)
at org.apache.nifi.engine.FlowEngine$2.run(FlowEngine.java:110)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: BEGIN event received while already processing a transaction. This could indicate that your binlog position is invalid.
at org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.outputEvents(CaptureChangeMySQL.java:793)
at org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL.onTrigger(CaptureChangeMySQL.java:571)
... 11 common frames omitted
2019-07-09 19:16:47,521 DEBUG [Timer-Driven Process Thread-1] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=4ab2b03c-7c51-3452-13ec-f7715baa1464] Returning CLUSTER State: StandardStateMap[version=1472, values={cdc.sequence.id=339754, binlog.filename=mysql-bin.000494, binlog.position=27915427}]
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-08 09:54
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
Thanks for providing the additional information.
By looking at the code and tested a live MySQL and NiFi, I can see CaptureChangeMySQL works as expected in my environment. The processor uses the specified initial binlog position, and generates FlowFiles based on what it receives. It doesn't require NiFi restart, just stopping the processor, clearing its state, then restarting it works, and provide the consistent results.
Although it could be possible that in a special circumstance, that NiFi, or the underlying binlog library NiFi uses, or MySQL server to return a cached binlog position.. but I can't find that behavior or any documentation.
Please make sure that CaptureChangeMySQL 'Retrieve All Records' is set to 'false' again. If it's not, the processor ignores specified initial binlog position.
# For further investigation:
I'd suggest counting the number of FlowFiles as below, to rule-out the possibility that having different results by restarting NiFi, or restarting the processor.
1. Stop CaptureChangeMySQL, clear its state, configure initial binlog filename and position with ones confirmed available by SHOW BINARY LOGS sql.
2. Clear the queued FlowFiles at the connection between CaptureChangeMySQL and LogAttribute, by right-clicking the connection and selecting 'Empty queue'. At this point, the queue should have 0 FlowFiles.
3. Restart NiFi, and start CaptureChangeMySQL processor. After running it for a while, stop the processor. Memorize the processor state, and the number of generated FlowFiles (queued at the connection).
4. Repeat step #1 and #2. But don't restart NiFi this time, instead, restart the CaptureChangeMySQL processor. After running it for a while, stop the processor. Memorize the processor state, and the number of generated FlowFiles (queued at the connection).
At the step #3 and #4, please log FlowFile contests by running LogAttributes with 'Log Payload' as true. Then copy nifi-app.log to different files to preserve them and check diffs later for further investigation. If it didn't work as expected, these logs will be very helpful for further debugging.
My expectation is, having the approximately the same number of generated FlowFiles at step #3 and #4, regardless how long did they take. If it didn't work like that, we will be able to research what caused different results.
Thanks,
Koji
On Fri, Jul 5, 2019 at 8:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
By grep and counting the lines contains ‘Standard FlowFile Attributes’ in my nifi-app.log, #A and #B is quite different
By observing the Queue number after stop the downstream processor in my nifi flow, #A and #B is also different.
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-05 19:14
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
I used a business database of our company. There's a few tomcat applications that will select/update/insert/delete on the database.
Sorry i am new to Nifi and have no idea how to count the number of FlowFiles. Let me google about it. Please let me know if there's any document available.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 16:46
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
I have few questions.
How do you update MySQL server while testing CaptureChangeMySQL?
Is there another program keep sending data to MySQL server?
A. how many FlowFiles did the CaptureChangeMySQL generated after restarting NiFi?
B. how many FlowFiles did the CaptureChangeMySQL generated after clearing the state and restart CaptureChangeMySQL?
Are the number #A and #B the same? Or different?
Thanks,
Koji
On Fri, Jul 5, 2019 at 3:54 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only 7 days' log retained.
First I restarted the nifi service by bin/nifi.sh resart. Clear the state, set the initial position to mysql-bin.000493/4. Start it
2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28459969)
Quickly logging a Standard FlowFile Attributes: show the binlog.position: 816(a little bigger than 4) and then many many such logging and the binlog position is becoming larger.
This is what i expected.
After a few minutes, i stop the CaptureChangeMySQL processor. The binlog position is 158441289, then i clear the state.
2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=422, values={}]
Then i start the processor again:
2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28461051)
..............
Quickly logging
2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000493, binlog.position=158443355, cdc.sequence.id=137421}
Standard FlowFile Attributes
Key: 'entryDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'lineageStartDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'fileSize'
Value: '1137'
FlowFile Attribute Map Content
Key: 'binlog.filename'
Value: 'mysql-bin.000493'
Key: 'binlog.position'
Value: '158439452'
The binlog.position is approximately the same with what i just have cleared.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 14:11
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
Can you execute SHOW BINARY LOGS sql and share the result?
https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
Thanks,
Koji
On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji，
Yes, it started with the specified initial position. And then updated the CLUSTER scope posion value, because it received such position information from MySQL server.
What confused me is why the received position information from my MySQL Server is always approximately the same with the previous state position i have just cleared, but not a value that is little bigger than the specified initial position.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 08:52
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope state to ${NIFI_HOME}/state/local.
If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it can start from where it stopped when it's restarted.
CaptureChangeMySQL clears its variables in memory when it gets stopped.
Then retrieve them from stored state.
From the log you provided, the state was empty (because you cleared it) when it started running.
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
And after processing several events, the processor updated CLUSTER scope state.
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
To me, the processor looks working as expected.
It started with the specified initial position. The reason it updated the CLUSTER scope like that is, because it received such position information from MySQL server.
I'd recommend to look at MySQL server side to see what events available with the current binlog.
Thanks,
Koji
On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only when I restarted the nifi service, the processor consume from the specialized intitial position.
Did the state info is always in memory ?
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-04 16:23
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Thanks Koji.
I have tried many times, the log always show
Setting CLUSTER State to a value that is approximate the previous state value, but not exactly the same.
But i have cleared the state!
Where the cluster state is stored?
I have configed zookeeper, But there's no node related to nifi in my zookeeper
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-04 09:37
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
The log seems that the processor started with an empty state then received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by Koji Kawamura <ij...@gmail.com>.
Hi Lei,
Thanks for providing the additional information.
By looking at the code and tested a live MySQL and NiFi, I can see
CaptureChangeMySQL works as expected in my environment. The processor uses
the specified initial binlog position, and generates FlowFiles based on
what it receives. It doesn't require NiFi restart, just stopping the
processor, clearing its state, then restarting it works, and provide the
consistent results.
Although it could be possible that in a special circumstance, that NiFi, or
the underlying binlog library NiFi uses, or MySQL server to return a cached
binlog position.. but I can't find that behavior or any documentation.
Please make sure that CaptureChangeMySQL 'Retrieve All Records' is set to
'false' again. If it's not, the processor ignores specified initial binlog
position.
# For further investigation:
I'd suggest counting the number of FlowFiles as below, to rule-out the
possibility that having different results by restarting NiFi, or restarting
the processor.
1. Stop CaptureChangeMySQL, clear its state, configure initial binlog
filename and position with ones confirmed available by SHOW BINARY LOGS sql.
2. Clear the queued FlowFiles at the connection between CaptureChangeMySQL
and LogAttribute, by right-clicking the connection and selecting 'Empty
queue'. At this point, the queue should have 0 FlowFiles.
3. Restart NiFi, and start CaptureChangeMySQL processor. After running it
for a while, stop the processor. Memorize the processor state, and the
number of generated FlowFiles (queued at the connection).
4. Repeat step #1 and #2. But don't restart NiFi this time, instead,
restart the CaptureChangeMySQL processor. After running it for a while,
stop the processor. Memorize the processor state, and the number of
generated FlowFiles (queued at the connection).
At the step #3 and #4, please log FlowFile contests by running
LogAttributes with 'Log Payload' as true. Then copy nifi-app.log to
different files to preserve them and check diffs later for further
investigation. If it didn't work as expected, these logs will be very
helpful for further debugging.
My expectation is, having the approximately the same number of generated
FlowFiles at step #3 and #4, regardless how long did they take. If it
didn't work like that, we will be able to research what caused different
results.
Thanks,
Koji
On Fri, Jul 5, 2019 at 8:43 PM wanglei2@geekplus.com.cn <
wanglei2@geekplus.com.cn> wrote:
>
> By grep and counting the lines contains ‘Standard FlowFile Attributes’
> in my nifi-app.log, #A and #B is quite different
> By observing the Queue number after stop the downstream processor in my
> nifi flow, #A and #B is also different.
>
>
>
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* wanglei2@geekplus.com.cn
> *Date:* 2019-07-05 19:14
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>
> I used a business database of our company. There's a few tomcat
> applications that will select/update/insert/delete on the database.
> Sorry i am new to Nifi and have no idea how to count the number of
> FlowFiles. Let me google about it. Please let me know if there's any
> document available.
>
> Thanks,
> Lei
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* Koji Kawamura <ij...@gmail.com>
> *Date:* 2019-07-05 16:46
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: Re: CaptureChangeMysql clear state not work
> Hi Lei,
>
> I have few questions.
>
> How do you update MySQL server while testing CaptureChangeMySQL?
> Is there another program keep sending data to MySQL server?
>
> A. how many FlowFiles did the CaptureChangeMySQL generated after
> restarting NiFi?
> B. how many FlowFiles did the CaptureChangeMySQL generated after clearing
> the state and restart CaptureChangeMySQL?
>
> Are the number #A and #B the same? Or different?
>
> Thanks,
> Koji
>
>
> On Fri, Jul 5, 2019 at 3:54 PM wanglei2@geekplus.com.cn <
> wanglei2@geekplus.com.cn> wrote:
>
>>
>> Only 7 days' log retained.
>>
>>
>> First I restarted the nifi service by bin/nifi.sh resart. Clear the
>> state, set the initial position to mysql-bin.000493/4. Start it
>>
>> 2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306]
>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>> at mysql-bin.000493/4 (sid:3721, cid:28459969)
>> Quickly logging a Standard FlowFile Attributes: show the
>> binlog.position: 816(a little bigger than 4) and then many many such
>> logging and the binlog position is becoming larger.
>> This is what i expected.
>>
>> After a few minutes, i stop the CaptureChangeMySQL processor. The binlog
>> position is 158441289, then i clear the state.
>> 2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>> CLUSTER State
>> 2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL
>> State
>> 2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL
>> State: StandardStateMap[version=422, values={}]
>>
>>
>>
>> Then i start the processor again:
>> 2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306]
>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>> at mysql-bin.000493/4 (sid:3721, cid:28461051)
>> ..............
>> Quickly logging
>> 2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER
>> State to {binlog.filename=mysql-bin.000493, binlog.position=158443355,
>> cdc.sequence.id=137421}
>>
>> Standard FlowFile Attributes
>> Key: 'entryDate'
>> Value: 'Fri Jul 05 14:40:47 CST 2019'
>> Key: 'lineageStartDate'
>> Value: 'Fri Jul 05 14:40:47 CST 2019'
>> Key: 'fileSize'
>> Value: '1137'
>> FlowFile Attribute Map Content
>> Key: 'binlog.filename'
>> Value: 'mysql-bin.000493'
>> Key: 'binlog.position'
>> Value: '158439452'
>>
>>
>> The binlog.position is approximately the same with what i just have
>> cleared.
>>
>> Thanks,
>> Lei
>>
>>
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
>> *From:* Koji Kawamura <ij...@gmail.com>
>> *Date:* 2019-07-05 14:11
>> *To:* users <us...@nifi.apache.org>
>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>> Hi Lei,
>>
>> Can you execute SHOW BINARY LOGS sql and share the result?
>> https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
>>
>> Thanks,
>> Koji
>>
>> On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <
>> wanglei2@geekplus.com.cn> wrote:
>>
>>>
>>> Hi Koji，
>>> Yes, it started with the specified initial position. And then
>>> updated the CLUSTER scope posion value, because it received such position
>>> information from MySQL server.
>>>
>>> What confused me is why the received position information from my
>>> MySQL Server is always approximately the same with the previous state
>>> position i have just cleared, but not a value that is little bigger than the
>>> specified initial position.
>>>
>>>
>>> Thanks,
>>> Lei
>>>
>>>
>>> ------------------------------
>>> wanglei2@geekplus.com.cn
>>>
>>>
>>> *From:* Koji Kawamura <ij...@gmail.com>
>>> *Date:* 2019-07-05 08:52
>>> *To:* users <us...@nifi.apache.org>
>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>> Hi Lei,
>>>
>>> If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope
>>> state to ${NIFI_HOME}/state/local.
>>> If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
>>>
>>> CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it
>>> can start from where it stopped when it's restarted.
>>>
>>> CaptureChangeMySQL clears its variables in memory when it gets stopped.
>>> Then retrieve them from stored state.
>>> From the log you provided, the state was empty (because you cleared it)
>>> when it started running.
>>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>>> at mysql-bin.000492/4 (sid:5, cid:28227568)
>>>
>>> And after processing several events, the processor updated CLUSTER scope
>>> state.
>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>
>>> To me, the processor looks working as expected.
>>> It started with the specified initial position. The reason it updated
>>> the CLUSTER scope like that is, because it received such position
>>> information from MySQL server.
>>> I'd recommend to look at MySQL server side to see what events available
>>> with the current binlog.
>>>
>>> Thanks,
>>> Koji
>>>
>>>
>>> On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <
>>> wanglei2@geekplus.com.cn> wrote:
>>>
>>>>
>>>>
>>>> Only when I restarted the nifi service, the processor consume from the
>>>> specialized intitial position.
>>>> Did the state info is always in memory ?
>>>>
>>>> ------------------------------
>>>> wanglei2@geekplus.com.cn
>>>>
>>>>
>>>> *From:* wanglei2@geekplus.com.cn
>>>> *Date:* 2019-07-04 16:23
>>>> *To:* users <us...@nifi.apache.org>
>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>>
>>>> Thanks Koji.
>>>>
>>>> I have tried many times, the log always show
>>>> Setting CLUSTER State to a value that is approximate the
>>>> previous state value, but not exactly the same.
>>>> But i have cleared the state!
>>>>
>>>>
>>>> Where the cluster state is stored?
>>>> I have configed zookeeper, But there's no node related to nifi in my
>>>> zookeeper
>>>>
>>>>
>>>>
>>>> Thanks,
>>>> Lei
>>>> ------------------------------
>>>> wanglei2@geekplus.com.cn
>>>>
>>>>
>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>> *Date:* 2019-07-04 09:37
>>>> *To:* users <us...@nifi.apache.org>
>>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>> Hi Lei,
>>>>
>>>> The log seems that the processor started with an empty state then
>>>> received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its
>>>> state with the values derived from the latest event, QUERY.
>>>>
>>>> Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL
>>>> server may be helpful to understand what the binlog actually looks like.
>>>> https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
>>>>
>>>> Is your MySQL server clustered? If so, managing where to start reading
>>>> binlog by binlog position may not work in certain situations.
>>>> There is an existing JIRA to support GTID instead of binlog position.
>>>> Do you think it's related to your case?
>>>> https://issues.apache.org/jira/browse/NIFI-5583
>>>>
>>>> Thanks,
>>>> Koji
>>>>
>>>> On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <
>>>> wanglei2@geekplus.com.cn> wrote:
>>>>
>>>>>
>>>>> Hi Koji,
>>>>>
>>>>> Following is the log.
>>>>>
>>>>>
>>>>> 2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>> LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164,
>>>>> binlog.filename=mysql-bin.000488, binlog.position=28551660}]
>>>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>>> CLUSTER State
>>>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>>> LOCAL State
>>>>> 2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>>>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>>>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to
>>>>> 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>> event type: ROTATE
>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>> event type: FORMAT_DESCRIPTION
>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>> event type: PREVIOUS_GTIDS
>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>> event type: GTID
>>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>>> event type: QUERY
>>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>>>>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>>
>>>>>
>>>>> mysql-bin.000492/4 is the configed inition position, but it still
>>>>> set state to {binlog.filename=mysql-bin.000488,
>>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>>
>>>>> Why, any insight on this ?
>>>>>
>>>>>
>>>>> ------------------------------
>>>>> wanglei2@geekplus.com.cn
>>>>>
>>>>>
>>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>>> *Date:* 2019-07-03 16:14
>>>>> *To:* users <us...@nifi.apache.org>
>>>>> *Subject:* Re: CaptureChangeMysql clear state not work
>>>>> Hi Lei,
>>>>>
>>>>> Since 'State Update Interval' is set to '5 seconds', while the
>>>>> processor runs, it updates state per 5 seconds.
>>>>> It's possible that the processor started with the specified initial
>>>>> position, and consumed some binlog events then reached to the end of the
>>>>> binlog.
>>>>>
>>>>> After clearing the state and restart the processor, did you see some
>>>>> FlowFiles were generated? If so, it should be an expected behavior.
>>>>> Changing logging level for the processor to DEBUG may provide more
>>>>> insights.
>>>>> You can do so by adding the following entry at conf/logback.xml:
>>>>> <logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL"
>>>>> level="DEBUG"/>
>>>>>
>>>>> I confirmed how initial binlog position is used. The processor used
>>>>> the specified position if there's no stored state and 'Retrieve All
>>>>> Records' is false, then it stored state.
>>>>>
>>>>> Thanks,
>>>>> Koji
>>>>>
>>>>>
>>>>> On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <
>>>>> wanglei2@geekplus.com.cn> wrote:
>>>>>
>>>>>>
>>>>>> Stop -> view state -> clear state -> start again
>>>>>> I view the state again, the binlog.positon is still from the
>>>>>> previous posion, not from the initial position
>>>>>>
>>>>>> Thanks,
>>>>>> Lei
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> ------------------------------
>>>>>> wanglei2@geekplus.com.cn
>>>>>>
>>>>>>
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
By grep and counting the lines contains ‘Standard FlowFile Attributes’ in my nifi-app.log, #A and #B is quite different
By observing the Queue number after stop the downstream processor in my nifi flow, #A and #B is also different.
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-05 19:14
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
I used a business database of our company. There's a few tomcat applications that will select/update/insert/delete on the database.
Sorry i am new to Nifi and have no idea how to count the number of FlowFiles. Let me google about it. Please let me know if there's any document available.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 16:46
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
I have few questions.
How do you update MySQL server while testing CaptureChangeMySQL?
Is there another program keep sending data to MySQL server?
A. how many FlowFiles did the CaptureChangeMySQL generated after restarting NiFi?
B. how many FlowFiles did the CaptureChangeMySQL generated after clearing the state and restart CaptureChangeMySQL?
Are the number #A and #B the same? Or different?
Thanks,
Koji
On Fri, Jul 5, 2019 at 3:54 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only 7 days' log retained.
First I restarted the nifi service by bin/nifi.sh resart. Clear the state, set the initial position to mysql-bin.000493/4. Start it
2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28459969)
Quickly logging a Standard FlowFile Attributes: show the binlog.position: 816(a little bigger than 4) and then many many such logging and the binlog position is becoming larger.
This is what i expected.
After a few minutes, i stop the CaptureChangeMySQL processor. The binlog position is 158441289, then i clear the state.
2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=422, values={}]
Then i start the processor again:
2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28461051)
..............
Quickly logging
2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000493, binlog.position=158443355, cdc.sequence.id=137421}
Standard FlowFile Attributes
Key: 'entryDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'lineageStartDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'fileSize'
Value: '1137'
FlowFile Attribute Map Content
Key: 'binlog.filename'
Value: 'mysql-bin.000493'
Key: 'binlog.position'
Value: '158439452'
The binlog.position is approximately the same with what i just have cleared.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 14:11
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
Can you execute SHOW BINARY LOGS sql and share the result?
https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
Thanks,
Koji
On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji，
Yes, it started with the specified initial position. And then updated the CLUSTER scope posion value, because it received such position information from MySQL server.
What confused me is why the received position information from my MySQL Server is always approximately the same with the previous state position i have just cleared, but not a value that is little bigger than the specified initial position.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 08:52
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope state to ${NIFI_HOME}/state/local.
If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it can start from where it stopped when it's restarted.
CaptureChangeMySQL clears its variables in memory when it gets stopped.
Then retrieve them from stored state.
From the log you provided, the state was empty (because you cleared it) when it started running.
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
And after processing several events, the processor updated CLUSTER scope state.
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
To me, the processor looks working as expected.
It started with the specified initial position. The reason it updated the CLUSTER scope like that is, because it received such position information from MySQL server.
I'd recommend to look at MySQL server side to see what events available with the current binlog.
Thanks,
Koji
On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only when I restarted the nifi service, the processor consume from the specialized intitial position.
Did the state info is always in memory ?
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-04 16:23
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Thanks Koji.
I have tried many times, the log always show
Setting CLUSTER State to a value that is approximate the previous state value, but not exactly the same.
But i have cleared the state!
Where the cluster state is stored?
I have configed zookeeper, But there's no node related to nifi in my zookeeper
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-04 09:37
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
The log seems that the processor started with an empty state then received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
I used a business database of our company. There's a few tomcat applications that will select/update/insert/delete on the database.
Sorry i am new to Nifi and have no idea how to count the number of FlowFiles. Let me google about it. Please let me know if there's any document available.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 16:46
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
I have few questions.
How do you update MySQL server while testing CaptureChangeMySQL?
Is there another program keep sending data to MySQL server?
A. how many FlowFiles did the CaptureChangeMySQL generated after restarting NiFi?
B. how many FlowFiles did the CaptureChangeMySQL generated after clearing the state and restart CaptureChangeMySQL?
Are the number #A and #B the same? Or different?
Thanks,
Koji
On Fri, Jul 5, 2019 at 3:54 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only 7 days' log retained.
First I restarted the nifi service by bin/nifi.sh resart. Clear the state, set the initial position to mysql-bin.000493/4. Start it
2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28459969)
Quickly logging a Standard FlowFile Attributes: show the binlog.position: 816(a little bigger than 4) and then many many such logging and the binlog position is becoming larger.
This is what i expected.
After a few minutes, i stop the CaptureChangeMySQL processor. The binlog position is 158441289, then i clear the state.
2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=422, values={}]
Then i start the processor again:
2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28461051)
..............
Quickly logging
2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000493, binlog.position=158443355, cdc.sequence.id=137421}
Standard FlowFile Attributes
Key: 'entryDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'lineageStartDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'fileSize'
Value: '1137'
FlowFile Attribute Map Content
Key: 'binlog.filename'
Value: 'mysql-bin.000493'
Key: 'binlog.position'
Value: '158439452'
The binlog.position is approximately the same with what i just have cleared.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 14:11
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
Can you execute SHOW BINARY LOGS sql and share the result?
https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
Thanks,
Koji
On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji，
Yes, it started with the specified initial position. And then updated the CLUSTER scope posion value, because it received such position information from MySQL server.
What confused me is why the received position information from my MySQL Server is always approximately the same with the previous state position i have just cleared, but not a value that is little bigger than the specified initial position.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 08:52
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope state to ${NIFI_HOME}/state/local.
If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it can start from where it stopped when it's restarted.
CaptureChangeMySQL clears its variables in memory when it gets stopped.
Then retrieve them from stored state.
From the log you provided, the state was empty (because you cleared it) when it started running.
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
And after processing several events, the processor updated CLUSTER scope state.
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
To me, the processor looks working as expected.
It started with the specified initial position. The reason it updated the CLUSTER scope like that is, because it received such position information from MySQL server.
I'd recommend to look at MySQL server side to see what events available with the current binlog.
Thanks,
Koji
On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only when I restarted the nifi service, the processor consume from the specialized intitial position.
Did the state info is always in memory ?
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-04 16:23
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Thanks Koji.
I have tried many times, the log always show
Setting CLUSTER State to a value that is approximate the previous state value, but not exactly the same.
But i have cleared the state!
Where the cluster state is stored?
I have configed zookeeper, But there's no node related to nifi in my zookeeper
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-04 09:37
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
The log seems that the processor started with an empty state then received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by Koji Kawamura <ij...@gmail.com>.
Hi Lei,
I have few questions.
How do you update MySQL server while testing CaptureChangeMySQL?
Is there another program keep sending data to MySQL server?
A. how many FlowFiles did the CaptureChangeMySQL generated after restarting
NiFi?
B. how many FlowFiles did the CaptureChangeMySQL generated after clearing
the state and restart CaptureChangeMySQL?
Are the number #A and #B the same? Or different?
Thanks,
Koji
On Fri, Jul 5, 2019 at 3:54 PM wanglei2@geekplus.com.cn <
wanglei2@geekplus.com.cn> wrote:
>
> Only 7 days' log retained.
>
>
> First I restarted the nifi service by bin/nifi.sh resart. Clear the
> state, set the initial position to mysql-bin.000493/4. Start it
>
> 2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306]
> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
> at mysql-bin.000493/4 (sid:3721, cid:28459969)
> Quickly logging a Standard FlowFile Attributes: show the binlog.position:
> 816(a little bigger than 4) and then many many such logging and the
> binlog position is becoming larger.
> This is what i expected.
>
> After a few minutes, i stop the CaptureChangeMySQL processor. The binlog
> position is 158441289, then i clear the state.
> 2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
> CLUSTER State
> 2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL
> State
> 2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL
> State: StandardStateMap[version=422, values={}]
>
>
>
> Then i start the processor again:
> 2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306]
> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
> at mysql-bin.000493/4 (sid:3721, cid:28461051)
> ..............
> Quickly logging
> 2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER
> State to {binlog.filename=mysql-bin.000493, binlog.position=158443355,
> cdc.sequence.id=137421}
>
> Standard FlowFile Attributes
> Key: 'entryDate'
> Value: 'Fri Jul 05 14:40:47 CST 2019'
> Key: 'lineageStartDate'
> Value: 'Fri Jul 05 14:40:47 CST 2019'
> Key: 'fileSize'
> Value: '1137'
> FlowFile Attribute Map Content
> Key: 'binlog.filename'
> Value: 'mysql-bin.000493'
> Key: 'binlog.position'
> Value: '158439452'
>
>
> The binlog.position is approximately the same with what i just have
> cleared.
>
> Thanks,
> Lei
>
>
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* Koji Kawamura <ij...@gmail.com>
> *Date:* 2019-07-05 14:11
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: Re: CaptureChangeMysql clear state not work
> Hi Lei,
>
> Can you execute SHOW BINARY LOGS sql and share the result?
> https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
>
> Thanks,
> Koji
>
> On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <
> wanglei2@geekplus.com.cn> wrote:
>
>>
>> Hi Koji，
>> Yes, it started with the specified initial position. And then
>> updated the CLUSTER scope posion value, because it received such position
>> information from MySQL server.
>>
>> What confused me is why the received position information from my
>> MySQL Server is always approximately the same with the previous state
>> position i have just cleared, but not a value that is little bigger than the
>> specified initial position.
>>
>>
>> Thanks,
>> Lei
>>
>>
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
>> *From:* Koji Kawamura <ij...@gmail.com>
>> *Date:* 2019-07-05 08:52
>> *To:* users <us...@nifi.apache.org>
>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>> Hi Lei,
>>
>> If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope
>> state to ${NIFI_HOME}/state/local.
>> If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
>>
>> CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it
>> can start from where it stopped when it's restarted.
>>
>> CaptureChangeMySQL clears its variables in memory when it gets stopped.
>> Then retrieve them from stored state.
>> From the log you provided, the state was empty (because you cleared it)
>> when it started running.
>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>> at mysql-bin.000492/4 (sid:5, cid:28227568)
>>
>> And after processing several events, the processor updated CLUSTER scope
>> state.
>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>> binlog.position=28530655, cdc.sequence.id=29158}
>>
>> To me, the processor looks working as expected.
>> It started with the specified initial position. The reason it updated the
>> CLUSTER scope like that is, because it received such position information
>> from MySQL server.
>> I'd recommend to look at MySQL server side to see what events available
>> with the current binlog.
>>
>> Thanks,
>> Koji
>>
>>
>> On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <
>> wanglei2@geekplus.com.cn> wrote:
>>
>>>
>>>
>>> Only when I restarted the nifi service, the processor consume from the
>>> specialized intitial position.
>>> Did the state info is always in memory ?
>>>
>>> ------------------------------
>>> wanglei2@geekplus.com.cn
>>>
>>>
>>> *From:* wanglei2@geekplus.com.cn
>>> *Date:* 2019-07-04 16:23
>>> *To:* users <us...@nifi.apache.org>
>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>>
>>> Thanks Koji.
>>>
>>> I have tried many times, the log always show
>>> Setting CLUSTER State to a value that is approximate the
>>> previous state value, but not exactly the same.
>>> But i have cleared the state!
>>>
>>>
>>> Where the cluster state is stored?
>>> I have configed zookeeper, But there's no node related to nifi in my
>>> zookeeper
>>>
>>>
>>>
>>> Thanks,
>>> Lei
>>> ------------------------------
>>> wanglei2@geekplus.com.cn
>>>
>>>
>>> *From:* Koji Kawamura <ij...@gmail.com>
>>> *Date:* 2019-07-04 09:37
>>> *To:* users <us...@nifi.apache.org>
>>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>> Hi Lei,
>>>
>>> The log seems that the processor started with an empty state then
>>> received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its
>>> state with the values derived from the latest event, QUERY.
>>>
>>> Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL
>>> server may be helpful to understand what the binlog actually looks like.
>>> https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
>>>
>>> Is your MySQL server clustered? If so, managing where to start reading
>>> binlog by binlog position may not work in certain situations.
>>> There is an existing JIRA to support GTID instead of binlog position.
>>> Do you think it's related to your case?
>>> https://issues.apache.org/jira/browse/NIFI-5583
>>>
>>> Thanks,
>>> Koji
>>>
>>> On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <
>>> wanglei2@geekplus.com.cn> wrote:
>>>
>>>>
>>>> Hi Koji,
>>>>
>>>> Following is the log.
>>>>
>>>>
>>>> 2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>> LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164,
>>>> binlog.filename=mysql-bin.000488, binlog.position=28551660}]
>>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>> CLUSTER State
>>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>>> LOCAL State
>>>> 2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>>>> at mysql-bin.000492/4 (sid:5, cid:28227568)
>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>> event type: ROTATE
>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>> event type: FORMAT_DESCRIPTION
>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>> event type: PREVIOUS_GTIDS
>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>> event type: GTID
>>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>>> event type: QUERY
>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>>>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>>
>>>>
>>>> mysql-bin.000492/4 is the configed inition position, but it still set
>>>> state to {binlog.filename=mysql-bin.000488, binlog.position=28530655,
>>>> cdc.sequence.id=29158}
>>>>
>>>> Why, any insight on this ?
>>>>
>>>>
>>>> ------------------------------
>>>> wanglei2@geekplus.com.cn
>>>>
>>>>
>>>> *From:* Koji Kawamura <ij...@gmail.com>
>>>> *Date:* 2019-07-03 16:14
>>>> *To:* users <us...@nifi.apache.org>
>>>> *Subject:* Re: CaptureChangeMysql clear state not work
>>>> Hi Lei,
>>>>
>>>> Since 'State Update Interval' is set to '5 seconds', while the
>>>> processor runs, it updates state per 5 seconds.
>>>> It's possible that the processor started with the specified initial
>>>> position, and consumed some binlog events then reached to the end of the
>>>> binlog.
>>>>
>>>> After clearing the state and restart the processor, did you see some
>>>> FlowFiles were generated? If so, it should be an expected behavior.
>>>> Changing logging level for the processor to DEBUG may provide more
>>>> insights.
>>>> You can do so by adding the following entry at conf/logback.xml:
>>>> <logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL"
>>>> level="DEBUG"/>
>>>>
>>>> I confirmed how initial binlog position is used. The processor used the
>>>> specified position if there's no stored state and 'Retrieve All Records' is
>>>> false, then it stored state.
>>>>
>>>> Thanks,
>>>> Koji
>>>>
>>>>
>>>> On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <
>>>> wanglei2@geekplus.com.cn> wrote:
>>>>
>>>>>
>>>>> Stop -> view state -> clear state -> start again
>>>>> I view the state again, the binlog.positon is still from the previous
>>>>> posion, not from the initial position
>>>>>
>>>>> Thanks,
>>>>> Lei
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> ------------------------------
>>>>> wanglei2@geekplus.com.cn
>>>>>
>>>>>
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
Only 7 days' log retained.
First I restarted the nifi service by bin/nifi.sh resart. Clear the state, set the initial position to mysql-bin.000493/4. Start it
2019-07-05 14:29:57,708 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28459969)
Quickly logging a Standard FlowFile Attributes: show the binlog.position: 816(a little bigger than 4) and then many many such logging and the binlog position is becoming larger.
This is what i expected.
After a few minutes, i stop the CaptureChangeMySQL processor. The binlog position is 158441289, then i clear the state.
2019-07-05 14:43:33,128 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-05 14:43:33,132 DEBUG [NiFi Web Server-24] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-05 14:43:42,210 DEBUG [NiFi Web Server-22] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=422, values={}]
Then i start the processor again:
2019-07-05 14:44:55,890 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000493/4 (sid:3721, cid:28461051)
..............
Quickly logging
2019-07-05 14:44:56,083 DEBUG [Timer-Driven Process Thread-5] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000493, binlog.position=158443355, cdc.sequence.id=137421}
Standard FlowFile Attributes
Key: 'entryDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'lineageStartDate'
Value: 'Fri Jul 05 14:40:47 CST 2019'
Key: 'fileSize'
Value: '1137'
FlowFile Attribute Map Content
Key: 'binlog.filename'
Value: 'mysql-bin.000493'
Key: 'binlog.position'
Value: '158439452'
The binlog.position is approximately the same with what i just have cleared.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 14:11
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
Can you execute SHOW BINARY LOGS sql and share the result?
https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
Thanks,
Koji
On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji，
Yes, it started with the specified initial position. And then updated the CLUSTER scope posion value, because it received such position information from MySQL server.
What confused me is why the received position information from my MySQL Server is always approximately the same with the previous state position i have just cleared, but not a value that is little bigger than the specified initial position.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 08:52
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope state to ${NIFI_HOME}/state/local.
If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it can start from where it stopped when it's restarted.
CaptureChangeMySQL clears its variables in memory when it gets stopped.
Then retrieve them from stored state.
From the log you provided, the state was empty (because you cleared it) when it started running.
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
And after processing several events, the processor updated CLUSTER scope state.
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
To me, the processor looks working as expected.
It started with the specified initial position. The reason it updated the CLUSTER scope like that is, because it received such position information from MySQL server.
I'd recommend to look at MySQL server side to see what events available with the current binlog.
Thanks,
Koji
On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only when I restarted the nifi service, the processor consume from the specialized intitial position.
Did the state info is always in memory ?
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-04 16:23
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Thanks Koji.
I have tried many times, the log always show
Setting CLUSTER State to a value that is approximate the previous state value, but not exactly the same.
But i have cleared the state!
Where the cluster state is stored?
I have configed zookeeper, But there's no node related to nifi in my zookeeper
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-04 09:37
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
The log seems that the processor started with an empty state then received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by Koji Kawamura <ij...@gmail.com>.
Hi Lei,
Can you execute SHOW BINARY LOGS sql and share the result?
https://dev.mysql.com/doc/refman/8.0/en/show-binary-logs.html
Thanks,
Koji
On Fri, Jul 5, 2019 at 12:55 PM wanglei2@geekplus.com.cn <
wanglei2@geekplus.com.cn> wrote:
>
> Hi Koji，
> Yes, it started with the specified initial position. And then updated
> the CLUSTER scope posion value, because it received such position
> information from MySQL server.
>
> What confused me is why the received position information from my MySQL
> Server is always approximately the same with the previous state
> position i have just cleared, but not a value that is little bigger than the
> specified initial position.
>
>
> Thanks,
> Lei
>
>
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* Koji Kawamura <ij...@gmail.com>
> *Date:* 2019-07-05 08:52
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: Re: CaptureChangeMysql clear state not work
> Hi Lei,
>
> If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope
> state to ${NIFI_HOME}/state/local.
> If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
>
> CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it
> can start from where it stopped when it's restarted.
>
> CaptureChangeMySQL clears its variables in memory when it gets stopped.
> Then retrieve them from stored state.
> From the log you provided, the state was empty (because you cleared it)
> when it started running.
> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
> at mysql-bin.000492/4 (sid:5, cid:28227568)
>
> And after processing several events, the processor updated CLUSTER scope
> state.
> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
> CLUSTER State to {binlog.filename=mysql-bin.000488,
> binlog.position=28530655, cdc.sequence.id=29158}
>
> To me, the processor looks working as expected.
> It started with the specified initial position. The reason it updated the
> CLUSTER scope like that is, because it received such position information
> from MySQL server.
> I'd recommend to look at MySQL server side to see what events available
> with the current binlog.
>
> Thanks,
> Koji
>
>
> On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <
> wanglei2@geekplus.com.cn> wrote:
>
>>
>>
>> Only when I restarted the nifi service, the processor consume from the
>> specialized intitial position.
>> Did the state info is always in memory ?
>>
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
>> *From:* wanglei2@geekplus.com.cn
>> *Date:* 2019-07-04 16:23
>> *To:* users <us...@nifi.apache.org>
>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>>
>> Thanks Koji.
>>
>> I have tried many times, the log always show
>> Setting CLUSTER State to a value that is approximate the previous
>> state value, but not exactly the same.
>> But i have cleared the state!
>>
>>
>> Where the cluster state is stored?
>> I have configed zookeeper, But there's no node related to nifi in my
>> zookeeper
>>
>>
>>
>> Thanks,
>> Lei
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
>> *From:* Koji Kawamura <ij...@gmail.com>
>> *Date:* 2019-07-04 09:37
>> *To:* users <us...@nifi.apache.org>
>> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>> Hi Lei,
>>
>> The log seems that the processor started with an empty state then
>> received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its
>> state with the values derived from the latest event, QUERY.
>>
>> Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL
>> server may be helpful to understand what the binlog actually looks like.
>> https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
>>
>> Is your MySQL server clustered? If so, managing where to start reading
>> binlog by binlog position may not work in certain situations.
>> There is an existing JIRA to support GTID instead of binlog position.
>> Do you think it's related to your case?
>> https://issues.apache.org/jira/browse/NIFI-5583
>>
>> Thanks,
>> Koji
>>
>> On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <
>> wanglei2@geekplus.com.cn> wrote:
>>
>>>
>>> Hi Koji,
>>>
>>> Following is the log.
>>>
>>>
>>> 2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>> LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164,
>>> binlog.filename=mysql-bin.000488, binlog.position=28551660}]
>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>> CLUSTER State
>>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>>> LOCAL State
>>> 2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>>> at mysql-bin.000492/4 (sid:5, cid:28227568)
>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>> event type: ROTATE
>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>> event type: FORMAT_DESCRIPTION
>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>> event type: PREVIOUS_GTIDS
>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>> event type: GTID
>>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>>> event type: QUERY
>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>>> CLUSTER State: StandardStateMap[version=8244, values={}]
>>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>>> o.a.n.c.m.processors.CaptureChangeMySQL
>>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>>> binlog.position=28530655, cdc.sequence.id=29158}
>>>
>>>
>>> mysql-bin.000492/4 is the configed inition position, but it still set
>>> state to {binlog.filename=mysql-bin.000488, binlog.position=28530655,
>>> cdc.sequence.id=29158}
>>>
>>> Why, any insight on this ?
>>>
>>>
>>> ------------------------------
>>> wanglei2@geekplus.com.cn
>>>
>>>
>>> *From:* Koji Kawamura <ij...@gmail.com>
>>> *Date:* 2019-07-03 16:14
>>> *To:* users <us...@nifi.apache.org>
>>> *Subject:* Re: CaptureChangeMysql clear state not work
>>> Hi Lei,
>>>
>>> Since 'State Update Interval' is set to '5 seconds', while the processor
>>> runs, it updates state per 5 seconds.
>>> It's possible that the processor started with the specified initial
>>> position, and consumed some binlog events then reached to the end of the
>>> binlog.
>>>
>>> After clearing the state and restart the processor, did you see some
>>> FlowFiles were generated? If so, it should be an expected behavior.
>>> Changing logging level for the processor to DEBUG may provide more
>>> insights.
>>> You can do so by adding the following entry at conf/logback.xml:
>>> <logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL"
>>> level="DEBUG"/>
>>>
>>> I confirmed how initial binlog position is used. The processor used the
>>> specified position if there's no stored state and 'Retrieve All Records' is
>>> false, then it stored state.
>>>
>>> Thanks,
>>> Koji
>>>
>>>
>>> On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <
>>> wanglei2@geekplus.com.cn> wrote:
>>>
>>>>
>>>> Stop -> view state -> clear state -> start again
>>>> I view the state again, the binlog.positon is still from the previous
>>>> posion, not from the initial position
>>>>
>>>> Thanks,
>>>> Lei
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> ------------------------------
>>>> wanglei2@geekplus.com.cn
>>>>
>>>>
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
Hi Koji，
Yes, it started with the specified initial position. And then updated the CLUSTER scope posion value, because it received such position information from MySQL server.
What confused me is why the received position information from my MySQL Server is always approximately the same with the previous state position i have just cleared, but not a value that is little bigger than the specified initial position.
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-05 08:52
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope state to ${NIFI_HOME}/state/local.
If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it can start from where it stopped when it's restarted.
CaptureChangeMySQL clears its variables in memory when it gets stopped.
Then retrieve them from stored state.
From the log you provided, the state was empty (because you cleared it) when it started running.
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
And after processing several events, the processor updated CLUSTER scope state.
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
To me, the processor looks working as expected.
It started with the specified initial position. The reason it updated the CLUSTER scope like that is, because it received such position information from MySQL server.
I'd recommend to look at MySQL server side to see what events available with the current binlog.
Thanks,
Koji
On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Only when I restarted the nifi service, the processor consume from the specialized intitial position.
Did the state info is always in memory ?
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-04 16:23
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Thanks Koji.
I have tried many times, the log always show
Setting CLUSTER State to a value that is approximate the previous state value, but not exactly the same.
But i have cleared the state!
Where the cluster state is stored?
I have configed zookeeper, But there's no node related to nifi in my zookeeper
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-04 09:37
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
The log seems that the processor started with an empty state then received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by Koji Kawamura <ij...@gmail.com>.
Hi Lei,
If your NiFi is standalone (not clustered), NiFi stores CLUSTER scope state
to ${NIFI_HOME}/state/local.
If your NiFi is clustered, NiFi stores CLUSTER scope state to Zookeeper.
CaptureChangeMySQL updates CLUSTER scope state when it runs, so that it can
start from where it stopped when it's restarted.
CaptureChangeMySQL clears its variables in memory when it gets stopped.
Then retrieve them from stored state.
From the log you provided, the state was empty (because you cleared it)
when it started running.
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at
mysql-bin.000492/4 (sid:5, cid:28227568)
And after processing several events, the processor updated CLUSTER scope
state.
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
o.a.n.c.m.processors.CaptureChangeMySQL
CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER
State to {binlog.filename=mysql-bin.000488, binlog.position=28530655,
cdc.sequence.id=29158}
To me, the processor looks working as expected.
It started with the specified initial position. The reason it updated the
CLUSTER scope like that is, because it received such position information
from MySQL server.
I'd recommend to look at MySQL server side to see what events available
with the current binlog.
Thanks,
Koji
On Thu, Jul 4, 2019 at 7:57 PM wanglei2@geekplus.com.cn <
wanglei2@geekplus.com.cn> wrote:
>
>
> Only when I restarted the nifi service, the processor consume from the
> specialized intitial position.
> Did the state info is always in memory ?
>
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* wanglei2@geekplus.com.cn
> *Date:* 2019-07-04 16:23
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: Re: CaptureChangeMysql clear state not work
>
> Thanks Koji.
>
> I have tried many times, the log always show
> Setting CLUSTER State to a value that is approximate the previous
> state value, but not exactly the same.
> But i have cleared the state!
>
>
> Where the cluster state is stored?
> I have configed zookeeper, But there's no node related to nifi in my
> zookeeper
>
>
>
> Thanks,
> Lei
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* Koji Kawamura <ij...@gmail.com>
> *Date:* 2019-07-04 09:37
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: Re: CaptureChangeMysql clear state not work
> Hi Lei,
>
> The log seems that the processor started with an empty state then received
> few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state
> with the values derived from the latest event, QUERY.
>
> Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server
> may be helpful to understand what the binlog actually looks like.
> https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
>
> Is your MySQL server clustered? If so, managing where to start reading
> binlog by binlog position may not work in certain situations.
> There is an existing JIRA to support GTID instead of binlog position.
> Do you think it's related to your case?
> https://issues.apache.org/jira/browse/NIFI-5583
>
> Thanks,
> Koji
>
> On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <
> wanglei2@geekplus.com.cn> wrote:
>
>>
>> Hi Koji,
>>
>> Following is the log.
>>
>>
>> 2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>> LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164,
>> binlog.filename=mysql-bin.000488, binlog.position=28551660}]
>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>> CLUSTER State
>> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
>> LOCAL State
>> 2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>> CLUSTER State: StandardStateMap[version=8244, values={}]
>> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
>> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
>> at mysql-bin.000492/4 (sid:5, cid:28227568)
>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>> event type: ROTATE
>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>> event type: FORMAT_DESCRIPTION
>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>> event type: PREVIOUS_GTIDS
>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>> event type: GTID
>> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
>> event type: QUERY
>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
>> CLUSTER State: StandardStateMap[version=8244, values={}]
>> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
>> o.a.n.c.m.processors.CaptureChangeMySQL
>> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
>> CLUSTER State to {binlog.filename=mysql-bin.000488,
>> binlog.position=28530655, cdc.sequence.id=29158}
>>
>>
>> mysql-bin.000492/4 is the configed inition position, but it still set
>> state to {binlog.filename=mysql-bin.000488, binlog.position=28530655,
>> cdc.sequence.id=29158}
>>
>> Why, any insight on this ?
>>
>>
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
>> *From:* Koji Kawamura <ij...@gmail.com>
>> *Date:* 2019-07-03 16:14
>> *To:* users <us...@nifi.apache.org>
>> *Subject:* Re: CaptureChangeMysql clear state not work
>> Hi Lei,
>>
>> Since 'State Update Interval' is set to '5 seconds', while the processor
>> runs, it updates state per 5 seconds.
>> It's possible that the processor started with the specified initial
>> position, and consumed some binlog events then reached to the end of the
>> binlog.
>>
>> After clearing the state and restart the processor, did you see some
>> FlowFiles were generated? If so, it should be an expected behavior.
>> Changing logging level for the processor to DEBUG may provide more
>> insights.
>> You can do so by adding the following entry at conf/logback.xml:
>> <logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL"
>> level="DEBUG"/>
>>
>> I confirmed how initial binlog position is used. The processor used the
>> specified position if there's no stored state and 'Retrieve All Records' is
>> false, then it stored state.
>>
>> Thanks,
>> Koji
>>
>>
>> On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <
>> wanglei2@geekplus.com.cn> wrote:
>>
>>>
>>> Stop -> view state -> clear state -> start again
>>> I view the state again, the binlog.positon is still from the previous
>>> posion, not from the initial position
>>>
>>> Thanks,
>>> Lei
>>>
>>>
>>>
>>>
>>>
>>>
>>> ------------------------------
>>> wanglei2@geekplus.com.cn
>>>
>>>
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
Only when I restarted the nifi service, the processor consume from the specialized intitial position.
Did the state info is always in memory ?
wanglei2@geekplus.com.cn
From: wanglei2@geekplus.com.cn
Date: 2019-07-04 16:23
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Thanks Koji.
I have tried many times, the log always show
Setting CLUSTER State to a value that is approximate the previous state value, but not exactly the same.
But i have cleared the state!
Where the cluster state is stored?
I have configed zookeeper, But there's no node related to nifi in my zookeeper
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-04 09:37
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
The log seems that the processor started with an empty state then received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
Thanks Koji.
I have tried many times, the log always show
Setting CLUSTER State to a value that is approximate the previous state value, but not exactly the same.
But i have cleared the state!
Where the cluster state is stored?
I have configed zookeeper, But there's no node related to nifi in my zookeeper
Thanks,
Lei
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-04 09:37
To: users
Subject: Re: Re: CaptureChangeMysql clear state not work
Hi Lei,
The log seems that the processor started with an empty state then received few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: Re: CaptureChangeMysql clear state not work
Posted by Koji Kawamura <ij...@gmail.com>.
Hi Lei,
The log seems that the processor started with an empty state then received
few events, ROTATE, FORMAT_DESCRIPTION ... QUERY. Then updated its state
with the values derived from the latest event, QUERY.
Execute 'show binary logs' SQL, or mysqlbinlog command at the MySQL server
may be helpful to understand what the binlog actually looks like.
https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
Is your MySQL server clustered? If so, managing where to start reading
binlog by binlog position may not work in certain situations.
There is an existing JIRA to support GTID instead of binlog position.
Do you think it's related to your case?
https://issues.apache.org/jira/browse/NIFI-5583
Thanks,
Koji
On Wed, Jul 3, 2019 at 8:00 PM wanglei2@geekplus.com.cn <
wanglei2@geekplus.com.cn> wrote:
>
> Hi Koji,
>
> Following is the log.
>
>
> 2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
> LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164,
> binlog.filename=mysql-bin.000488, binlog.position=28551660}]
> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
> CLUSTER State
> 2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing
> LOCAL State
> 2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
> CLUSTER State: StandardStateMap[version=8244, values={}]
> 2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306]
> c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306
> at mysql-bin.000492/4 (sid:5, cid:28227568)
> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
> event type: ROTATE
> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
> event type: FORMAT_DESCRIPTION
> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
> event type: PREVIOUS_GTIDS
> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
> event type: GTID
> 2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message
> event type: QUERY
> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning
> CLUSTER State: StandardStateMap[version=8244, values={}]
> 2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10]
> o.a.n.c.m.processors.CaptureChangeMySQL
> CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting
> CLUSTER State to {binlog.filename=mysql-bin.000488,
> binlog.position=28530655, cdc.sequence.id=29158}
>
>
> mysql-bin.000492/4 is the configed inition position, but it still set
> state to {binlog.filename=mysql-bin.000488, binlog.position=28530655,
> cdc.sequence.id=29158}
>
> Why, any insight on this ?
>
>
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
> *From:* Koji Kawamura <ij...@gmail.com>
> *Date:* 2019-07-03 16:14
> *To:* users <us...@nifi.apache.org>
> *Subject:* Re: CaptureChangeMysql clear state not work
> Hi Lei,
>
> Since 'State Update Interval' is set to '5 seconds', while the processor
> runs, it updates state per 5 seconds.
> It's possible that the processor started with the specified initial
> position, and consumed some binlog events then reached to the end of the
> binlog.
>
> After clearing the state and restart the processor, did you see some
> FlowFiles were generated? If so, it should be an expected behavior.
> Changing logging level for the processor to DEBUG may provide more
> insights.
> You can do so by adding the following entry at conf/logback.xml:
> <logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL"
> level="DEBUG"/>
>
> I confirmed how initial binlog position is used. The processor used the
> specified position if there's no stored state and 'Retrieve All Records' is
> false, then it stored state.
>
> Thanks,
> Koji
>
>
> On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <
> wanglei2@geekplus.com.cn> wrote:
>
>>
>> Stop -> view state -> clear state -> start again
>> I view the state again, the binlog.positon is still from the previous
>> posion, not from the initial position
>>
>> Thanks,
>> Lei
>>
>>
>>
>>
>>
>>
>> ------------------------------
>> wanglei2@geekplus.com.cn
>>
>>
Re: Re: CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
Hi Koji,
Following is the log.
2019-07-03 18:44:49,283 DEBUG [NiFi Web Server-117] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning LOCAL State: StandardStateMap[version=8242, values={cdc.sequence.id=29164, binlog.filename=mysql-bin.000488, binlog.position=28551660}]
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing CLUSTER State
2019-07-03 18:44:52,001 DEBUG [NiFi Web Server-21] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Clearing LOCAL State
2019-07-03 18:48:09,924 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,201 INFO [blc-172.31.43.138:3306] c.g.shyiko.mysql.binlog.BinaryLogClient Connected to 172.31.43.138:3306 at mysql-bin.000492/4 (sid:5, cid:28227568)
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: ROTATE
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: FORMAT_DESCRIPTION
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: PREVIOUS_GTIDS
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: GTID
2019-07-03 18:48:10,357 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Got message event type: QUERY
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Returning CLUSTER State: StandardStateMap[version=8244, values={}]
2019-07-03 18:48:10,358 DEBUG [Timer-Driven Process Thread-10] o.a.n.c.m.processors.CaptureChangeMySQL CaptureChangeMySQL[id=b12217e3-016b-1000-30f3-949e06fe2b84] Setting CLUSTER State to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
mysql-bin.000492/4 is the configed inition position, but it still set state to {binlog.filename=mysql-bin.000488, binlog.position=28530655, cdc.sequence.id=29158}
Why, any insight on this ?
wanglei2@geekplus.com.cn
From: Koji Kawamura
Date: 2019-07-03 16:14
To: users
Subject: Re: CaptureChangeMysql clear state not work
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial position, and consumed some binlog events then reached to the end of the binlog.
After clearing the state and restart the processor, did you see some FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL" level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the specified position if there's no stored state and 'Retrieve All Records' is false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <wa...@geekplus.com.cn> wrote:
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn
Re: CaptureChangeMysql clear state not work
Posted by Koji Kawamura <ij...@gmail.com>.
Hi Lei,
Since 'State Update Interval' is set to '5 seconds', while the processor
runs, it updates state per 5 seconds.
It's possible that the processor started with the specified initial
position, and consumed some binlog events then reached to the end of the
binlog.
After clearing the state and restart the processor, did you see some
FlowFiles were generated? If so, it should be an expected behavior.
Changing logging level for the processor to DEBUG may provide more insights.
You can do so by adding the following entry at conf/logback.xml:
<logger name="org.apache.nifi.cdc.mysql.processors.CaptureChangeMySQL"
level="DEBUG"/>
I confirmed how initial binlog position is used. The processor used the
specified position if there's no stored state and 'Retrieve All Records' is
false, then it stored state.
Thanks,
Koji
On Tue, Jul 2, 2019 at 2:43 PM wanglei2@geekplus.com.cn <
wanglei2@geekplus.com.cn> wrote:
>
> Stop -> view state -> clear state -> start again
> I view the state again, the binlog.positon is still from the previous
> posion, not from the initial position
>
> Thanks,
> Lei
>
>
>
>
>
>
> ------------------------------
> wanglei2@geekplus.com.cn
>
>
CaptureChangeMysql clear state not work
Posted by "wanglei2@geekplus.com.cn" <wa...@geekplus.com.cn>.
Stop -> view state -> clear state -> start again
I view the state again, the binlog.positon is still from the previous posion, not from the initial position
Thanks,
Lei
wanglei2@geekplus.com.cn