[MDEV-9749] InnoDB receives 'Bad file descriptor' error, possibly related to feedback plugin Created: 2016-03-16  Updated: 2016-06-20  Resolved: 2016-06-20

Status: Closed
Project: MariaDB Server
Component/s: Plugin - feedback
Affects Version/s: 10.0.22-galera
Fix Version/s: 5.5.51, 10.0.26, 10.1.15

Type: Bug Priority: Major
Reporter: Geoff Montee (Inactive) Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: feedback, galera

Issue Links:
Relates
relates to MDEV-10250 InnoDB: Error: File (unknown): 'close... Closed

 Description   

A user is seeing MariaDB Galera Cluster constantly abort due to 'Bad file descriptor' errors received by InnoDB. 100% of these failures look like the following:

  1. The node writes non-sensical feedback plugin error messages to the log every two minutes.
  2. The node writes some gcache.page files.
  3. The node writes another feedback plugin error message to the log that says the following: error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol
  4. Then InnoDB reports a 'Bad file descriptor' error.
  5. mysqld on the node then aborts.

This has happened on different nodes in the same cluster at different times.

This never happened when the user was running MariaDB Galera Cluster 10.0.21. It only started happening after the user upgraded to 10.0.22.

Here are some examples:

160225 23:14:08 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160225 23:16:11 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160225 23:18:14 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160225 23:20:17 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160225 23:22:12 [Note] WSREP: Created page /var/lib/mysql/data/gcache.page.000025 of size 157236726 bytes
 
160225 23:22:14 [Note] WSREP: Deleted page /var/lib/mysql/data/gcache.page.000025
 
160225 23:22:20 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol
 
2016-02-25 23:22:20 7f3ea0fb4700 InnoDB: Error: Write to file ./testdb/tab1.ibd failed at offset 180224.
 
InnoDB: 32768 bytes should have been written, only 0 were written.
 
InnoDB: Operating system error number 9.
 
InnoDB: Check that your OS and file system support files of this size.
 
InnoDB: Check also that the disk is not full or a disk quota exceeded.
 
InnoDB: Error number 9 means 'Bad file descriptor'.
 
InnoDB: Some operating system error numbers are described at
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
2016-02-25 23:22:20 7f3ea0fb4700  InnoDB: Operating system error number 9 in a file operation.
 
InnoDB: Error number 9 means 'Bad file descriptor'.
 
InnoDB: Some operating system error numbers are described at
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
160225 23:22:20 [ERROR] InnoDB: File ./testdb/tab1.ibd: 'os_file_write_func' returned OS error 109. Cannot continue operation
 
160225 23:22:20 mysqld_safe Number of processes running now: 0
 
160225 23:22:20 mysqld_safe WSREP: not restarting wsrep node automatically
 
160225 23:22:20 mysqld_safe mysqld from pid file /var/lib/mysql/org.local.pid ended


160302  2:30:40 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160302  2:32:43 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160302  2:34:46 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160302  2:36:49 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160302  2:38:00 [Note] WSREP: Created page /var/lib/mysql/data/gcache.page.000058 of size 157334503 bytes
 
160302  2:38:03 [Note] WSREP: Deleted page /var/lib/mysql/data/gcache.page.000058
 
160302  2:38:36 [Note] WSREP: Created page /var/lib/mysql/data/gcache.page.000059 of size 247299600 bytes
 
160302  2:38:39 [Note] WSREP: Deleted page /var/lib/mysql/data/gcache.page.000059
 
160302  2:38:52 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol
 
2016-03-02 02:38:52 7fcda2db7700 InnoDB: Error: Write to file ./testdb/tab2.ibd failed at offset 180224.
 
InnoDB: 32768 bytes should have been written, only 0 were written.
 
InnoDB: Operating system error number 9.
 
InnoDB: Check that your OS and file system support files of this size.
 
InnoDB: Check also that the disk is not full or a disk quota exceeded.
 
InnoDB: Error number 9 means 'Bad file descriptor'.
 
InnoDB: Some operating system error numbers are described at
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
2016-03-02 02:38:52 7fcda2db7700  InnoDB: Operating system error number 9 in a file operation.
 
InnoDB: Error number 9 means 'Bad file descriptor'.
 
InnoDB: Some operating system error numbers are described at
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
160302  2:38:52 [ERROR] InnoDB: File ./testdb/tab2.ibd: 'os_file_write_func' returned OS error 109. Cannot continue operation
 
160302 02:38:52 mysqld_safe Number of processes running now: 0
 
160302 02:38:52 mysqld_safe WSREP: not restarting wsrep node automatically
 
160302 02:38:52 mysqld_safe mysqld from pid file /var/lib/mysql/org.local.pid ended


160316  1:33:27 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160316  1:35:30 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160316  1:37:33 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160316  1:39:36 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160316  1:40:20 [Note] WSREP: Created page /var/lib/mysql/data/gcache.page.000034 of size 157462628 bytes
 
160316  1:40:23 [Note] WSREP: Deleted page /var/lib/mysql/data/gcache.page.000034
 
160316  1:41:07 [Note] WSREP: Created page /var/lib/mysql/data/gcache.page.000035 of size 249125066 bytes
 
160316  1:41:11 [Note] WSREP: Deleted page /var/lib/mysql/data/gcache.page.000035
 
160316  1:41:39 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol
 
2016-03-16 01:41:40 7f26babb4700 InnoDB: Error: Write to file ./testdb/tab3.ibd failed at offset 196608.
 
InnoDB: 32768 bytes should have been written, only 0 were written.
 
InnoDB: Operating system error number 9.
 
InnoDB: Check that your OS and file system support files of this size.
 
InnoDB: Check also that the disk is not full or a disk quota exceeded.
 
InnoDB: Error number 9 means 'Bad file descriptor'.
 
InnoDB: Some operating system error numbers are described at
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
2016-03-16 01:41:40 7f26babb4700  InnoDB: Operating system error number 9 in a file operation.
 
InnoDB: Error number 9 means 'Bad file descriptor'.
 
InnoDB: Some operating system error numbers are described at
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
160316  1:41:40 [ERROR] InnoDB: File ./testdb/tab3.ibd: 'os_file_write_func' returned OS error 109. Cannot continue operation
 
160316 01:41:40 mysqld_safe Number of processes running now: 0
 
160316 01:41:40 mysqld_safe WSREP: not restarting wsrep node automatically
 
160316 01:41:40 mysqld_safe mysqld from pid file /var/lib/mysql/org.local.pid ended


160225 23:14:08 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160225 23:16:11 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160225 23:18:14 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160225 23:20:17 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:00000000:lib(0):func(0):reason(0)
 
160225 23:22:12 [Note] WSREP: Created page /var/lib/mysql/data/gcache.page.000025 of size 157236726 bytes
 
160225 23:22:14 [Note] WSREP: Deleted page /var/lib/mysql/data/gcache.page.000025
 
160225 23:22:20 [ERROR] feedback plugin: ssl failed for url 'https://mariadb.org/feedback_plugin/post' error:140770FC:SSL routines:SSL23_GET_SERVER_HELLO:unknown protocol
 
2016-02-25 23:22:20 7f3ea0fb4700 InnoDB: Error: Write to file ./testdb/tab1.ibd failed at offset 180224.
 
InnoDB: 32768 bytes should have been written, only 0 were written.
 
InnoDB: Operating system error number 9.
 
InnoDB: Check that your OS and file system support files of this size.
 
InnoDB: Check also that the disk is not full or a disk quota exceeded.
 
InnoDB: Error number 9 means 'Bad file descriptor'.
 
InnoDB: Some operating system error numbers are described at
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
2016-02-25 23:22:20 7f3ea0fb4700  InnoDB: Operating system error number 9 in a file operation.
 
InnoDB: Error number 9 means 'Bad file descriptor'.
 
InnoDB: Some operating system error numbers are described at
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
 
160225 23:22:20 [ERROR] InnoDB: File ./testdb/tab1.ibd: 'os_file_write_func' returned OS error 109. Cannot continue operation
 
160225 23:22:20 mysqld_safe Number of processes running now: 0
 
160225 23:22:20 mysqld_safe WSREP: not restarting wsrep node automatically
 
160225 23:22:20 mysqld_safe mysqld from pid file /var/lib/mysql/org.local.pid ended



 Comments   
Comment by Elena Stepanova [ 2016-03-17 ]

Did the user try to disable FEEDBACK plugin to see if the problem goes away? If not, please suggest them to do so.

Comment by Geoff Montee (Inactive) [ 2016-03-17 ]

Thanks for the response. Yeah, the user has disabled the feedback plugin, and we are waiting to see if the problem happens again.

Comment by Elena Stepanova [ 2016-04-14 ]

GeoffMontee, were there any news on this?

Comment by Geoff Montee (Inactive) [ 2016-04-14 ]

The user has not mentioned seeing this problem since they disabled the feedback plugin, but I will ask them to make sure.

Comment by Elena Stepanova [ 2016-05-13 ]

GeoffMontee, any news on this?

Comment by Geoff Montee (Inactive) [ 2016-05-13 ]

I can confirm that this problem stopped happening when the users disabled the feedback plugin.

Comment by Elena Stepanova [ 2016-06-10 ]

Despite all the effort, so far I haven't been able to make the feedback plugin leak file descriptors. I'll keep this entry open, maybe somebody else comes up with new information so we can compare it and get ideas.

Comment by Elena Stepanova [ 2016-06-19 ]

More information has come with MDEV-10250.

Generated at Thu Feb 08 07:37:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.