java.io.EOFException at ByteArrayInputStream.java:180 about mysql-binlog-connector-java HOT 12 CLOSED

Hi @swordance,

This may happen for a number of reasons. First, make sure each BinaryLogClient (in case you are using multiple instances reading binary log stream from the same MySQL server) have different serverId set. Also, depending on your configuration and how long there were no changes, wait_timeout may or may not be the cause. Network "flickering" could be another issue. That's just of the top of my head.

In any case, even though you could write custom LifecycleListener to reconnect on EOF automatically it seems it's better off to be built in. I'll make the change soon.

Thanks a lot for reporting it.

from mysql-binlog-connector-java.

hi,
For the possible reasons you mentioned:

1. multiple BinaryLogClient: the exception happened when I used only one binaryLogClient and no other replication happened on a server.
2. I tried use BinaryLogClient without timeout setting, but it still happened.
3. I encountered the exception on two machines inside same intranet, and connection between them are quite stable and fast, so it seems network flickering should not happen.. however, the exception happened a lot between them..

from mysql-binlog-connector-java.

Commit above brings transparent reconnection on EOF/Socket exception.

One thing that I thought I would ask, could you please register LifecycleListener and log exceptions (along with the timestamp) when they occur? I'm curious whether failures are sporadic or not.

Thank you.

from mysql-binlog-connector-java.

hi,

I collected logs as you mentioned, and filtered other stuff, leaving the times when the exception happened. I would provide full traces if you needed.

Here it is...it is what happened when replicating with mysql server v5.1.28.

event deserialization failed at: 2014/05/14 06:17:55
event deserialization failed at: 2014/05/14 06:18:15
event deserialization failed at: 2014/05/14 06:18:36
event deserialization failed at: 2014/05/14 06:18:56
event deserialization failed at: 2014/05/14 06:19:16
event deserialization failed at: 2014/05/14 06:19:36
event deserialization failed at: 2014/05/14 06:19:56
event deserialization failed at: 2014/05/14 06:20:17
event deserialization failed at: 2014/05/14 06:20:37
event deserialization failed at: 2014/05/14 06:20:57
event deserialization failed at: 2014/05/14 06:21:17
event deserialization failed at: 2014/05/14 06:21:37
event deserialization failed at: 2014/05/14 06:21:57
event deserialization failed at: 2014/05/14 06:22:18
event deserialization failed at: 2014/05/14 06:22:38
event deserialization failed at: 2014/05/14 06:22:58
event deserialization failed at: 2014/05/14 06:23:18
event deserialization failed at: 2014/05/14 06:23:28
event deserialization failed at: 2014/05/14 06:23:48
event deserialization failed at: 2014/05/14 06:24:04
event deserialization failed at: 2014/05/14 06:24:14
event deserialization failed at: 2014/05/14 06:24:34
event deserialization failed at: 2014/05/14 06:24:54
event deserialization failed at: 2014/05/14 06:25:14
event deserialization failed at: 2014/05/14 06:25:35
event deserialization failed at: 2014/05/14 06:25:55
event deserialization failed at: 2014/05/14 06:26:15
event deserialization failed at: 2014/05/14 06:26:35
event deserialization failed at: 2014/05/14 06:26:56
event deserialization failed at: 2014/05/14 06:27:16
event deserialization failed at: 2014/05/14 06:27:36
event deserialization failed at: 2014/05/14 06:27:56
event deserialization failed at: 2014/05/14 06:28:17
event deserialization failed at: 2014/05/14 06:28:37
event deserialization failed at: 2014/05/14 06:28:58
event deserialization failed at: 2014/05/14 06:29:18
event deserialization failed at: 2014/05/14 06:29:38
event deserialization failed at: 2014/05/14 06:29:58
event deserialization failed at: 2014/05/14 06:30:18
event deserialization failed at: 2014/05/14 06:30:28
event deserialization failed at: 2014/05/14 06:30:48
event deserialization failed at: 2014/05/14 06:31:05
event deserialization failed at: 2014/05/14 06:31:15
event deserialization failed at: 2014/05/14 06:31:35
event deserialization failed at: 2014/05/14 06:31:55
event deserialization failed at: 2014/05/14 06:32:16
event deserialization failed at: 2014/05/14 06:32:36
event deserialization failed at: 2014/05/14 06:32:56
event deserialization failed at: 2014/05/14 06:33:16
event deserialization failed at: 2014/05/14 06:33:36
event deserialization failed at: 2014/05/14 06:33:56
event deserialization failed at: 2014/05/14 06:34:17

This is typical what happened. I logged the content in stream being checked:

client connect at: 2014/05/14 06:34:06
may 14, 2014 6:34:06 INFO com.github.shyiko.mysql.binlog.BinaryLogClient listenForEventPackets
INFO: inputstream peek not -1
may 14, 2014 6:34:06 INFO com.github.shyiko.mysql.binlog.BinaryLogClient listenForEventPackets
INFO: inputstream read is 0
may 14, 2014 6:34:06 INFO com.github.shyiko.mysql.binlog.BinaryLogClient listenForEventPackets
INFO: inputstream peek not -1
may 14, 2014 6:34:06 INFO com.github.shyiko.mysql.binlog.BinaryLogClient listenForEventPackets
INFO: inputstream read is 0
may 14, 2014 6:34:17 INFO com.github.shyiko.mysql.binlog.BinaryLogClient listenForEventPackets
INFO: inputstream peek not -1
may 14, 2014 6:34:17 INFO com.github.shyiko.mysql.binlog.BinaryLogClient listenForEventPackets
INFO: inputstream read is 254
java.io.EOFException
at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:180)
at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.readInteger(ByteArrayInputStream.java:46)
at com.github.shyiko.mysql.binlog.event.deserialization.EventHeaderV4Deserializer.deserialize(EventHeaderV4Deserializer.java:35)
at com.github.shyiko.mysql.binlog.event.deserialization.EventHeaderV4Deserializer.deserialize(EventHeaderV4Deserializer.java:27)
at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:98)
at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:468)
at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:298)
at com.alipay.xflush.prometheus.connector.ConnectorMain.main(ConnectorMain.java:34)
event deserialization failed at: 2014/05/14 06:34:17
client disconnect at: 2014/05/14 06:34:17

from mysql-binlog-connector-java.

Another thing:

for mysql server v5.6.x, the exception was rare. Actually I only saw it once.

from mysql-binlog-connector-java.

Interesting... EOFException is being thrown every ~20 seconds :) I'll try to reproduce it at my end (though I don't have high hopes, to be honest).

If it's not too much to ask, could you please add 'show variables \G' output and check MySQL logs for possible explanation.

Also, make sure there is no mysqlbinlog run every 20 seconds (via cron or whatever) as it uses same server-id by default (65535). You can try changing serverId of BinaryLogClient to make sure it's not the reason.

Thank you.

from mysql-binlog-connector-java.

Hi,

I found no cronjob of replication running on the machine, also chaning server-id cannot solve the problem..I think the 20 seconds interval is part of caused by the retry interval I set in my code, but my setting is 10 seconds, so still not sure where does the extra 10 seconds comes from..
I didn't find anything in error logs indicating what happened...
Here is the output of 'show variables \G', I hide some path info because they might be sensitive information..

mysql> show variables\G
*************************** 1. row ***************************
Variable_name: auto_increment_increment
Value: 1
*************************** 2. row ***************************
Variable_name: auto_increment_offset
Value: 1
*************************** 3. row ***************************
Variable_name: autocommit
Value: ON
*************************** 4. row ***************************
Variable_name: automatic_sp_privileges
Value: ON
*************************** 5. row ***************************
Variable_name: back_log
Value: 50
*************************** 6. row ***************************
Variable_name: basedir
Value: xxx
*************************** 7. row ***************************
Variable_name: big_tables
Value: OFF
*************************** 8. row ***************************
Variable_name: binlog_cache_size
Value: 32768
*************************** 9. row ***************************
Variable_name: binlog_format
Value: MIXED
*************************** 10. row ***************************
Variable_name: bulk_insert_buffer_size
Value: 8388608
*************************** 11. row ***************************
Variable_name: character_set_client
Value: gbk
*************************** 12. row ***************************
Variable_name: character_set_connection
Value: gbk
*************************** 13. row ***************************
Variable_name: character_set_database
Value: gbk
*************************** 14. row ***************************
Variable_name: character_set_filesystem
Value: binary
*************************** 15. row ***************************
Variable_name: character_set_results
Value: gbk
*************************** 16. row ***************************
Variable_name: character_set_server
Value: gbk
*************************** 17. row ***************************
Variable_name: character_set_system
Value: utf8
*************************** 18. row ***************************
Variable_name: character_sets_dir
Value: xxx
*************************** 19. row ***************************
Variable_name: collation_connection
Value: gbk_chinese_ci
*************************** 20. row ***************************
Variable_name: collation_database
Value: gbk_chinese_ci
*************************** 21. row ***************************
Variable_name: collation_server
Value: gbk_chinese_ci
*************************** 22. row ***************************
Variable_name: completion_type
Value: 0
*************************** 23. row ***************************
Variable_name: concurrent_insert
Value: 1
*************************** 24. row ***************************
Variable_name: connect_timeout
Value: 10
*************************** 25. row ***************************
Variable_name: datadir
Value: xxx
*************************** 26. row ***************************
Variable_name: date_format
Value: %Y-%m-%d
*************************** 27. row ***************************
Variable_name: datetime_format
Value: %Y-%m-%d %H:%i:%s
*************************** 28. row ***************************
Variable_name: default_week_format
Value: 0
*************************** 29. row ***************************
Variable_name: delay_key_write
Value: ON
*************************** 30. row ***************************
Variable_name: delayed_insert_limit
Value: 100
*************************** 31. row ***************************
Variable_name: delayed_insert_timeout
Value: 300
*************************** 32. row ***************************
Variable_name: delayed_queue_size
Value: 1000
*************************** 33. row ***************************
Variable_name: div_precision_increment
Value: 4
*************************** 34. row ***************************
Variable_name: engine_condition_pushdown
Value: ON
*************************** 35. row ***************************
Variable_name: error_count
Value: 0
*************************** 36. row ***************************
Variable_name: event_scheduler
Value: OFF
*************************** 37. row ***************************
Variable_name: expire_logs_days
Value: 0
*************************** 38. row ***************************
Variable_name: flush
Value: OFF
*************************** 39. row ***************************
Variable_name: flush_time
Value: 0
*************************** 40. row ***************************
Variable_name: foreign_key_checks
Value: ON
*** 41. row ***************************
Variable_name: ft_boolean_syntax
Value: + -><()~:""&|
** 42. row ***************************
Variable_name: ft_max_word_len
Value: 84
*************************** 43. row ***************************
Variable_name: ft_min_word_len
Value: 4
*************************** 44. row ***************************
Variable_name: ft_query_expansion_limit
Value: 20
*************************** 45. row ***************************
Variable_name: ft_stopword_file
Value: (built-in)
*************************** 46. row ***************************
Variable_name: general_log
Value: OFF
*************************** 48. row ***************************
Variable_name: group_concat_max_len
Value: 1024
*************************** 49. row ***************************
Variable_name: have_community_features
Value: YES
*************************** 50. row ***************************
Variable_name: have_compress
Value: YES
*************************** 51. row ***************************
Variable_name: have_crypt
Value: YES
*************************** 52. row ***************************
Variable_name: have_csv
Value: YES
*************************** 53. row ***************************
Variable_name: have_dynamic_loading
Value: YES
*************************** 54. row ***************************
Variable_name: have_geometry
Value: YES
*************************** 55. row ***************************
Variable_name: have_innodb
Value: YES
*************************** 56. row ***************************
Variable_name: have_ndbcluster
Value: NO
*************************** 57. row ***************************
Variable_name: have_openssl
Value: NO
*************************** 58. row ***************************
Variable_name: have_partitioning
Value: NO
*************************** 59. row ***************************
Variable_name: have_query_cache
Value: YES
*************************** 60. row ***************************
Variable_name: have_rtree_keys
Value: YES
*************************** 61. row ***************************
Variable_name: have_ssl
Value: NO
*************************** 62. row ***************************
Variable_name: have_symlink
Value: YES
*************************** 63. row ***************************
Variable_name: hostname
Value: xxx
*************************** 64. row ***************************
Variable_name: identity
Value: 3
*************************** 65. row ***************************
Variable_name: init_connect
Value:
*************************** 66. row ***************************
Variable_name: init_file
Value:
*************************** 67. row ***************************
Variable_name: init_slave
Value:
*************************** 68. row ***************************
Variable_name: innodb_adaptive_hash_index
Value: ON
*************************** 69. row ***************************
Variable_name: innodb_additional_mem_pool_size
Value: 1048576
*************************** 70. row ***************************
Variable_name: innodb_autoextend_increment
Value: 8
*************************** 71. row ***************************
Variable_name: innodb_autoinc_lock_mode
Value: 1
*************************** 72. row ***************************
Variable_name: innodb_buffer_pool_size
Value: 8388608
*************************** 73. row ***************************
Variable_name: innodb_checksums
Value: ON
*************************** 74. row ***************************
Variable_name: innodb_commit_concurrency
Value: 0
*************************** 75. row ***************************
Variable_name: innodb_concurrency_tickets
Value: 500
*************************** 76. row ***************************
Variable_name: innodb_data_file_path
Value: ibdata1:10M:autoextend
*************************** 77. row ***************************
Variable_name: innodb_data_home_dir
Value:
*************************** 78. row ***************************
Variable_name: innodb_doublewrite
Value: ON
*************************** 79. row ***************************
Variable_name: innodb_fast_shutdown
Value: 1
*************************** 80. row ***************************
Variable_name: innodb_file_io_threads
Value: 4
*************************** 81. row ***************************
Variable_name: innodb_file_per_table
Value: OFF
*************************** 82. row ***************************
Variable_name: innodb_flush_log_at_trx_commit
Value: 1
*************************** 83. row ***************************
Variable_name: innodb_flush_method
Value:
*************************** 84. row ***************************
Variable_name: innodb_force_recovery
Value: 0
*************************** 85. row ***************************
Variable_name: innodb_lock_wait_timeout
Value: 50
*************************** 86. row ***************************
Variable_name: innodb_locks_unsafe_for_binlog
Value: OFF
*************************** 87. row ***************************
Variable_name: innodb_log_buffer_size
Value: 1048576
*************************** 88. row ***************************
Variable_name: innodb_log_file_size
Value: 5242880
*************************** 89. row ***************************
Variable_name: innodb_log_files_in_group
Value: 2
*************************** 90. row ***************************
Variable_name: innodb_log_group_home_dir
Value: ./
*************************** 91. row ***************************
Variable_name: innodb_max_dirty_pages_pct
Value: 90
*************************** 92. row ***************************
Variable_name: innodb_max_purge_lag
Value: 0
*************************** 93. row ***************************
Variable_name: innodb_mirrored_log_groups
Value: 1
*************************** 94. row ***************************
Variable_name: innodb_open_files
Value: 300
*************************** 95. row ***************************
Variable_name: innodb_rollback_on_timeout
Value: OFF
*************************** 96. row ***************************
Variable_name: innodb_support_xa
Value: ON
*************************** 97. row ***************************
Variable_name: innodb_sync_spin_loops
Value: 20
*************************** 98. row ***************************
Variable_name: innodb_table_locks
Value: ON
*************************** 99. row ***************************
Variable_name: innodb_thread_concurrency
Value: 8
*************************** 100. row ***************************
Variable_name: innodb_thread_sleep_delay
Value: 10000
*************************** 101. row ***************************
Variable_name: insert_id
Value: 0
*************************** 102. row ***************************
Variable_name: interactive_timeout
Value: 28800
*************************** 103. row ***************************
Variable_name: join_buffer_size
Value: 131072
*************************** 104. row ***************************
Variable_name: keep_files_on_create
Value: OFF
*************************** 105. row ***************************
Variable_name: key_buffer_size
Value: 16777216
*************************** 106. row ***************************
Variable_name: key_cache_age_threshold
Value: 300
*************************** 107. row ***************************
Variable_name: key_cache_block_size
Value: 1024
*************************** 108. row ***************************
Variable_name: key_cache_division_limit
Value: 100
*************************** 109. row ***************************
Variable_name: language
Value: xxx/english/
*************************** 110. row ***************************
Variable_name: large_files_support
Value: ON
*************************** 111. row ***************************
Variable_name: large_page_size
Value: 0
*************************** 112. row ***************************
Variable_name: large_pages
Value: OFF
*************************** 113. row ***************************
Variable_name: last_insert_id
Value: 3
*************************** 114. row ***************************
Variable_name: lc_time_names
Value: en_US
*************************** 115. row ***************************
Variable_name: license
Value: GPL
*************************** 116. row ***************************
Variable_name: local_infile
Value: ON
*************************** 117. row ***************************
Variable_name: locked_in_memory
Value: OFF
*************************** 118. row ***************************
Variable_name: log
Value: OFF
*************************** 119. row ***************************
Variable_name: log_bin
Value: ON
*************************** 120. row ***************************
Variable_name: log_bin_trust_function_creators
Value: OFF
*************************** 121. row ***************************
Variable_name: log_bin_trust_routine_creators
Value: OFF
*************************** 123. row ***************************
Variable_name: log_output
Value: FILE
*************************** 124. row ***************************
Variable_name: log_queries_not_using_indexes
Value: OFF
*************************** 125. row ***************************
Variable_name: log_slave_updates
Value: OFF
*************************** 126. row ***************************
Variable_name: log_slow_queries
Value: OFF
*************************** 127. row ***************************
Variable_name: log_warnings
Value: 1
*************************** 128. row ***************************
Variable_name: long_query_time
Value: 10.000000
*************************** 129. row ***************************
Variable_name: low_priority_updates
Value: OFF
*************************** 130. row ***************************
Variable_name: lower_case_file_system
Value: OFF
*************************** 131. row ***************************
Variable_name: lower_case_table_names
Value: 0
*************************** 132. row ***************************
Variable_name: max_allowed_packet
Value: 1048576
*************************** 133. row ***************************
Variable_name: max_binlog_cache_size
Value: 4294967295
*************************** 134. row ***************************
Variable_name: max_binlog_size
Value: 1073741824
*************************** 135. row ***************************
Variable_name: max_connect_errors
Value: 10
*************************** 136. row ***************************
Variable_name: max_connections
Value: 151
*************************** 137. row ***************************
Variable_name: max_delayed_threads
Value: 20
*************************** 138. row ***************************
Variable_name: max_error_count
Value: 64
*************************** 139. row ***************************
Variable_name: max_heap_table_size
Value: 16777216
*************************** 140. row ***************************
Variable_name: max_insert_delayed_threads
Value: 20
*************************** 141. row ***************************
Variable_name: max_join_size
Value: 4294967295
*************************** 142. row ***************************
Variable_name: max_length_for_sort_data
Value: 1024
*************************** 143. row ***************************
Variable_name: max_prepared_stmt_count
Value: 16382
*************************** 144. row ***************************
Variable_name: max_relay_log_size
Value: 0
*************************** 145. row ***************************
Variable_name: max_seeks_for_key
Value: 4294967295
*************************** 146. row ***************************
Variable_name: max_sort_length
Value: 1024
*************************** 147. row ***************************
Variable_name: max_sp_recursion_depth
Value: 0
*************************** 148. row

from mysql-binlog-connector-java.

Hi,
I tried the code in your comment, and now I got this exception:

java.net.SocketException: socket closed
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at com.github.shyiko.mysql.binlog.io.BufferedSocketInputStream.read(BufferedSocketInputStream.java:51)
at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.readWithinBlockBoundaries(ByteArrayInputStream.java:192)
at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.peek(ByteArrayInputStream.java:166)
at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:456)
at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:300)
at com.alipay.xflush.prometheus.connector.ConnectorMain.main(ConnectorMain.java:35)

from mysql-binlog-connector-java.

Hi again,

I haven't found 5.1.28 build online so I went with 5.1.30 (with the following variables). The code I used was:

public class RemoteTest {
    public static void main(String[] args) throws Exception {
        BinaryLogClient client = new BinaryLogClient("remote.mysql.host", 33062, 
"msandbox", "msandbox");
        client.setServerId(0x007);
        client.setKeepAliveInterval(TimeUnit.SECONDS.toMillis(3));
        client.registerEventListener(new TraceEventListener());
        client.registerLifecycleListener(new TraceLifecycleListener());
        client.connect(3000);
        synchronized (RemoteTest.class) {
            RemoteTest.class.wait();
        }
    }
}

• for TraceEventListener and TraceLifecycleListener look here and here respectively.

The only time I got EOFException was when I started another instance of RemoteTest. Each instance was constantly loosing (and gaining back automatically) connection because of the "same serverId" problem I mentioned before. I've tried multiple usage patterns but unfortunately was unable to reproduce your issue using single (nor multiple but with different serverIds) RemoteTest(s).

from mysql-binlog-connector-java.

In case you are willing to install Vagrant - here is vagrant box I used for testing. You might want to verify your client against it (if all falls short).

from mysql-binlog-connector-java.

hi,

I cleaned up all the environment and tried again, now the exception has gone. It has already run several days, and no error occured. So it seems somewhere I didn't know tried to do replication with same sever id. I added a method to assign different id for different slaves to avoid duplicate server-id. I'm very sorry for the mis-leading before.. and Thanks for your help! mysql-binlog-connector-java is an excellent project with every function I need and very good performance, as long as a very intelligent author 👍 I feed so lucky of finding the project :)

from mysql-binlog-connector-java.

That's very kind of you 😊

I hope it will serve you well. Good luck!

from mysql-binlog-connector-java.