Could not find first log file name in binary log index file on AWS RDS

[vmishra]

I am connecting to RDS Mysql database using Maxwell 1.11 to Kafka 1.11.0.1 3 node cluster

While I'm able to bootstrap the records, But during a normal run I see following warnings in the console logs, They are generated nonstop.

13:15:05,321 WARN ProducerConfig - The configuration 'block.on.buffer.full' was supplied but isn't a known config. 13:15:05,323 INFO AppInfoParser - Kafka version : 0.11.0.1 13:15:05,323 INFO AppInfoParser - Kafka commitId : c2a0d5f9b1f45bf5 13:15:05,340 INFO Maxwell - Maxwell v?? is booting (MaxwellKafkaProducer), starting at Position[BinlogPosition[mysql-bin-changelog.035789:443217], lastHeartbeat=0] 13:15:05,454 INFO MysqlSavedSchema - Restoring schema id 1 (last modified at Position[BinlogPosition[mysql-bin-changelog.035789:422], lastHeartbeat=0]) 13:15:05,608 INFO BinlogConnectorReplicator - Setting initial binlog pos to: mysql-bin-changelog.035789:443217 13:15:05,697 INFO BinaryLogClient - Connected to devdb.cadcssodcqya.ap-south-1.rds.amazonaws.com:3306 at mysql-bin-changelog.035789/443217 (sid:6379, cid:1279388) 13:15:05,698 INFO BinlogConnectorLifecycleListener - Binlog connected. 13:15:05,737 WARN BinlogConnectorLifecycleListener - Communication failure. com.github.shyiko.mysql.binlog.network.ServerException: Could not find first log file name in binary log index file at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:882) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92] 13:15:05,741 INFO BinlogConnectorLifecycleListener - Binlog disconnected. 13:15:05,798 WARN BinlogConnectorReplicator - replicator stopped at position: mysql-bin-changelog.035789:443217 -- restarting 13:15:05,880 INFO BinaryLogClient - Connected to devdb.cadcssodcqya.ap-south-1.rds.amazonaws.com:3306 at mysql-bin-changelog.035789/443217 (sid:6379, cid:1279394) 13:15:05,880 INFO BinlogConnectorLifecycleListener - Binlog connected. 13:15:05,920 WARN BinlogConnectorLifecycleListener - Communication failure. com.github.shyiko.mysql.binlog.network.ServerException: Could not find first log file name in binary log index file at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:882) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92] 13:15:05,920 INFO BinlogConnectorLifecycleListener - Binlog disconnected. 13:15:05,981 WARN BinlogConnectorReplicator - replicator stopped at position: mysql-bin-changelog.035789:443217 -- restarting 13:15:06,060 INFO BinaryLogClient - Connected to devdb.cadcssodcqya.ap-south-1.rds.amazonaws.com:3306 at mysql-bin-changelog.035789/443217 (sid:6379, cid:1279395) 13:15:06,060 INFO BinlogConnectorLifecycleListener - Binlog connected. 13:15:06,100 WARN BinlogConnectorLifecycleListener - Communication failure. com.github.shyiko.mysql.binlog.network.ServerException: Could not find first log file name in binary log index file at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:882) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92] 13:15:06,100 INFO BinlogConnectorLifecycleListener - Binlog disconnected. 13:15:06,161 WARN BinlogConnectorReplicator - replicator stopped at position: mysql-bin-changelog.035789:443217 -- restarting 13:15:06,240 INFO BinaryLogClient - Connected to devdb.cadcssodcqya.ap-south-1.rds.amazonaws.com:3306 at mysql-bin-changelog.035789/443217 (sid:6379, cid:1279396) 13:15:06,240 INFO BinlogConnectorLifecycleListener - Binlog connected. 13:15:06,280 WARN BinlogConnectorLifecycleListener - Communication failure. com.github.shyiko.mysql.binlog.network.ServerException: Could not find first log file name in binary log index file at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:882) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793) [mysql-binlog-connector-java-0.13.0.jar:0.13.0] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_92] 13:15:06,280 INFO BinlogConnectorLifecycleListener - Binlog disconnected.

[osheroff]

this: "Could not find first log file name in binary log index file" generally means maxwell is pointing at a missing binlog. you can try dropping the maxwell database and restarting

[osheroff]

closing, feel free to re-open if new information is found

[cemo]

@vmishra is your RDS instance Multi-AZ? I have same problem and investigating deeply.

[osheroff]

@cemo was maxwell down for a period of time? "Could not find first log file name in binary log index" just means "the binlog isn't there", which can happen if mysql rotates the binlog away from underneath maxwell.

[cemo]

Yes, it was down for a period. I am almost sure it is related to this for my case. Cc @pasali

…

On 23 Feb 2018 Fri at 01:51 Ben Osheroff ***@***.***> wrote: @cemo <https://github.com/cemo> was maxwell down for a period of time? "Could not find first log file name in binary log index" just means "the binlog isn't there", which can happen if mysql rotates the binlog away from underneath maxwell. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#847 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AACsfF0Al2OpBv8MKncKYL006gGzf1hJks5tXe95gaJpZM4RfxQ5> .

[pasali]

@osheroff, @cemo and i are in the same team. It does not matter if maxwell is down or not because i think RDS rotates the binlog away cause every time i fix this problem, next day it occurs again. Actually we have another maxwell and rds instance which are working well. So this make think that rds instance is the one which causes the problem.

[osheroff]

@pasali hmmm. Is this a low-traffic server? Or is maxwell heavily filtered down to just a few inactive tables? I'm really not sure how this would happen with a running instance, please attach what logs you have...

[pasali]

there is 22 db schemes in the rds instance. do you think that maxwell does not catch up binglog changes ?

[m-denton]

@vmishra important to change the binlog retention time for RDS. We have ours set to 24hrs. Monitors and automation are in place for the event maxwell dies, hopefully we can recover within 24hrs and pick up where it stopped. If it goes over 24hrs, you will get the posted errors and pretty sure you have to drop the maxwell schema and start over.

CALL mysql.rds_set_configuration('binlog retention hours', 24);

[weiboyiyou]

Hi,all guys:
I find the reason,if your mysql rds has no dml(update/delete/insert),the position in the maxwell is not change,and the after 24h,the binlog files is remove to other place,and the position in the maxwell is still read the old binlog file.so error is that.can we think this is a bug?

[osheroff]

as I explaining in #884, even with no DML maxwell should receive a rotate-binlog event from the server, which should trigger a heartbeat, which should cause a position bump. Something in that chain may not be working properly, but it's hard to decipher from some of these problems if anyone actually has a consistent reproduction of the issue.

@pasali if this problem is still persistent on the one RDS cluster, maybe you could drop maxwell into debug-logging mode on that server?

[nitingarg1]

Hi All,

The same issue occurs for me, Maxwell was up and running from last 4 weeks, but there was no activity in the Database for 2 weeks and then we start seeing the below error.

com.github.shyiko.mysql.binlog.network.ServerException: Could not find first log file name in binary log index file
at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:882) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]
18:17:14,174 INFO BinlogConnectorLifecycleListener - Binlog disconnected.
18:17:14,235 WARN BinlogConnectorReplicator - replicator stopped at position: mysql-bin-changelog.009119:67353560 -- restarting
18:17:14,399 INFO BinaryLogClient - Connected to zuni-test-db-cluster.cluster-cav1zghpl4m8.us-east-1.rds.amazonaws.com:3306 at mysql-bin-changelog.009119/67353560 (sid:6379, cid:623538)
18:17:14,399 INFO BinlogConnectorLifecycleListener - Binlog connected.
18:17:14,438 WARN BinlogConnectorLifecycleListener - Communication failure.
com.github.shyiko.mysql.binlog.network.ServerException: Could not find first log file name in binary log index file
at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:882) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:559) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:793) [mysql-binlog-connector-java-0.16.1.jar:0.16.1]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]