[MXS-1698]  error:140940F5:SSL routines:ssl3_read_bytes:unexpected record Created: 2018-03-04  Updated: 2020-08-25  Resolved: 2018-03-06

Status: Closed
Project: MariaDB MaxScale
Component/s: mariadbclient, Monitor
Affects Version/s: 2.2.2
Fix Version/s: 2.2.3

Type: Bug Priority: Major
Reporter: Vipul Assignee: markus makela
Resolution: Fixed Votes: 0
Labels: None
Environment:

vagrant and baremetal



 Description   

when I try to connect to mariadb 10.2 running with ssl on the maxscale serverip and port I get error " error:140940F5:SSL routines:ssl3_read_bytes:unexpected record"
when I connect to mysql server directly from maxscale machine the connection works

10.10.10.10 - maxscale 2.2 server
10.10.10.13/14/15 - mariadb Db servers

root@node1:~# mysql -h10.10.10.13 -umaxscale -pmaxscale -e "select @@server_id"
+-------------+
| @@server_id |
+-------------+
|    10101013 |
+-------------+
root@node1:~# mysql -h10.10.10.10 -umaxscale -pmaxscale -e "select @@server_id"
ERROR 2013 (HY000) at line 1: Lost connection to MySQL server during query

I have proper grants and self-sign certs

MariaDB [(none)]> show grants for maxscale@'10.%';
+---------------------------------------------------------------------------------------------------------------------------------+
| Grants for maxscale@10.%                                                                                                        |
+---------------------------------------------------------------------------------------------------------------------------------+
| GRANT ALL PRIVILEGES ON *.* TO 'maxscale'@'10.%' IDENTIFIED BY PASSWORD '*53E5D0C7885BD540911663B04133F20C94AD4306' REQUIRE SSL 
----
The log shows
---
2018-03-04 18:51:37   error  : (39) SSL operation failed, dcb 0x21213a0 in state DCB_STATE_POLLING fd 20 return code -1. More details may follow.
2018-03-04 18:51:37   error  : (39) error:140940F5:SSL routines:ssl3_read_bytes:unexpected record
2018-03-04 18:51:37   error  : [mariadbbackend] Unable to write to backend 'node4' due to authentication failure. Server in state RUNNING MASTER.
2018-03-04 18:51:37   error  : (39) SSL operation failed, dcb 0x2123420 in state DCB_STATE_POLLING fd 22 return code -1. More details may follow.
2018-03-04 18:51:37   error  : (39) error:140940F5:SSL routines:ssl3_read_bytes:unexpected record

The exact setup with ssl work fine with 2.1. I am using self-sign certs .



 Comments   
Comment by Vipul [ 2018-03-04 ]

Please let me know , if you need anything else from me.
I am trying to implement the autofailover feature of 2.2.2 in production after the testing is over

Comment by Vipul [ 2018-03-04 ]

I am using ubuntu 16.04

Comment by markus makela [ 2018-03-05 ]

Managed to reproduce the failure with 2.2.2.

Comment by markus makela [ 2018-03-05 ]

Bug was caused by a regression in TLS/SSL handling code. The TLS handshake was sent twice.

Comment by markus makela [ 2018-03-05 ]

We've build packages to verify that the fix indeed works. You can find the current development packages from here: http://max-tst-01.mariadb.com/ci-repository/2.2-markusjm-mar5/mariadb-maxscale/

If possible, try to test these packages to see if the SSL error is fixed. The packages were built from commit 4f6b9d2bc3514e96da13d64650a6491eb0144186.

Comment by Vipul [ 2018-03-05 ]

The issue has been fixed ... I can connect to the DB via maxscale.
I am seeing another issue now ... where maxscale just crashes and will not come up even after restart, when I bring up the old master after failover to new master.
The error I see is
2018-03-05 18:51:52 error : [mariadbmon] debug assert at /home/ubuntu/MaxScale/server/modules/monitor/mariadbmon/mariadbmon.cc:209 failed: found
2018-03-05 18:51:52 alert : Fatal: MaxScale 2.2.3 received fatal signal 6. Attempting backtrace.
2018-03-05 18:51:52 alert : Commit ID: 4f6b9d2bc3514e96da13d64650a6491eb0144186 System name: Linux Release string: Ubuntu 16.04.3 LTS
2018-03-05 18:51:52 alert : /usr/bin/maxscale() [0x405268]: ??:0
2018-03-05 18:51:52 alert : /lib/x86_64-linux-gnu/libpthread.so.0(+0x11390) [0x7f0c16c73390]: ??:?
2018-03-05 18:51:52 alert : /lib/x86_64-linux-gnu/libpthread.so.0(raise+0x29) [0x7f0c16c73269]: ??:?
2018-03-05 18:51:53 alert : /usr/lib/x86_64-linux-gnu/maxscale/libmariadbmon.so(_ZN4GtidC2EPKcl+0x243) [0x7f0c11fe4d87]: /home/ubuntu/MaxScale/server/modules/monitor/mariadbmon/mariadbmon.cc:211
2018-03-05 18:51:53 alert : /usr/lib/x86_64-linux-gnu/maxscale/libmariadbmon.so(+0x19ade) [0x7f0c11fe1ade]: /home/ubuntu/MaxScale/server/modules/monitor/mariadbmon/mariadbmon.cc:4011 (discriminator 4)
2018-03-05 18:51:53 alert : /usr/lib/x86_64-linux-gnu/maxscale/libmariadbmon.so(+0x1c10f) [0x7f0c11fe410f]: /home/ubuntu/MaxScale/server/modules/monitor/mariadbmon/mariadbmon.cc:4579
2018-03-05 18:51:53 alert : /usr/lib/x86_64-linux-gnu/maxscale/libmariadbmon.so(+0x1c4ad) [0x7f0c11fe44ad]: /home/ubuntu/MaxScale/server/modules/monitor/mariadbmon/mariadbmon.cc:4678 (discriminator 1)
2018-03-05 18:51:53 alert : /usr/lib/x86_64-linux-gnu/maxscale/libmariadbmon.so(+0x152cf) [0x7f0c11fdd2cf]: /home/ubuntu/MaxScale/server/modules/monitor/mariadbmon/mariadbmon.cc:2571
2018-03-05 18:51:53 alert : /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f0c16c696ba]: ??:?
2018-03-05 18:51:53 alert : /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f0c155ea3dd]: ??:0

MariaDB MaxScale /var/log/maxscale/maxscale.log Mon Mar 5 18:51:53 2018
----------------------------------------------------------------------------
2018-03-05 18:51:53 error : No data read from child process pipe.
2018-03-05 18:51:53 MariaDB MaxScale is shut down.
----------------------------------------------------

Comment by Vipul [ 2018-03-05 ]

I am not sure , if the above issue might be related with the fix you made. Can you please help ?

Comment by Vipul [ 2018-03-05 ]

When I shutdown the the DB server which was the original master ... after that I can start maxscale again
root@node2:~# service maxscale restart
root@node2:~# maxctrl list servers
┌────────┬─────────────┬──────┬─────────────┬─────────────────┬─────────────────────┐
│ Server │ Address │ Port │ Connections │ State │ GTID │
├────────┼─────────────┼──────┼─────────────┼─────────────────┼─────────────────────┤
│ node4 │ 10.10.10.13 │ 3306 │ 0 │ Down │ │
├────────┼─────────────┼──────┼─────────────┼─────────────────┼─────────────────────┤
│ node5 │ 10.10.10.14 │ 3306 │ 0 │ Master, Running │ 10101014-10101014-2 │
├────────┼─────────────┼──────┼─────────────┼─────────────────┼─────────────────────┤
│ node6 │ 10.10.10.15 │ 3306 │ 0 │ Slave, Running │ 10101014-10101014-2 │
└────────┴─────────────┴──────┴─────────────┴─────────────────┴─────────────────────┘

Comment by markus makela [ 2018-03-05 ]

This was a debug version of the packages which appears to have triggered a debug assertion. A look at the source code points out that it is dealing with the GTID tracking mechanism and it assumes that the slaves use the same GTID as the master. Can you show the output of the following query?

SHOW VARIABLES LIKE '%gtid%';

Meanwhile, I'll remove the assertion and start a fresh build.

Comment by Vipul [ 2018-03-05 ]

From node4 (Old master)

+------------------------+----------------------+
| Variable_name          | Value                |
+------------------------+----------------------+
| gtid_binlog_pos        | 10101013-10101013-20 |
| gtid_binlog_state      | 10101013-10101013-20 |
| gtid_current_pos       | 10101013-10101013-20 |
| gtid_domain_id         | 10101013             |
| gtid_ignore_duplicates | ON                   |
| gtid_seq_no            | 0                    |
| gtid_slave_pos         |                      |
| gtid_strict_mode       | ON                   |
| last_gtid              |                      |
| wsrep_gtid_domain_id   | 0                    |
| wsrep_gtid_mode        | OFF                  |
+------------------------+----------------------+

Node6 (Slave)


MariaDB [(none)]> SHOW VARIABLES LIKE '%gtid%';
+------------------------+------------------------------------------+
| Variable_name          | Value                                    |
+------------------------+------------------------------------------+
| gtid_binlog_pos        | 10101013-10101013-20,10101014-10101014-2 |
| gtid_binlog_state      | 10101013-10101013-20,10101014-10101014-2 |
| gtid_current_pos       | 10101013-10101013-20,10101014-10101014-2 |
| gtid_domain_id         | 10101015                                 |
| gtid_ignore_duplicates | ON                                       |
| gtid_seq_no            | 0                                        |
| gtid_slave_pos         | 10101013-10101013-20,10101014-10101014-2 |
| gtid_strict_mode       | ON                                       |
| last_gtid              |                                          |
| wsrep_gtid_domain_id   | 0                                        |
| wsrep_gtid_mode        | OFF                                      |
+------------------------+------------------------------------------+

Node5 (New Master / Earlier slave)

vagrant@node5:~$ sudo mysql -e "SHOW VARIABLES LIKE '%gtid%';"
+------------------------+------------------------------------------+
| Variable_name          | Value                                    |
+------------------------+------------------------------------------+
| gtid_binlog_pos        | 10101013-10101013-20,10101014-10101014-2 |
| gtid_binlog_state      | 10101013-10101013-20,10101014-10101014-2 |
| gtid_current_pos       | 10101013-10101013-20,10101014-10101014-2 |
| gtid_domain_id         | 10101014                                 |
| gtid_ignore_duplicates | ON                                       |
| gtid_seq_no            | 0                                        |
| gtid_slave_pos         | 10101013-10101013-20                     |
| gtid_strict_mode       | ON                                       |
| last_gtid              |                                          |
| wsrep_gtid_domain_id   | 0                                        |
| wsrep_gtid_mode        | OFF                                      |
+------------------------+------------------------------------------+

Comment by Vipul [ 2018-03-05 ]

I would expect mariadb to sync the new slave (old master) from new master or just show down but not crash maxscale

Comment by markus makela [ 2018-03-05 ]

The custom build you tried was a debug build so in a release build it would not have crashed. I have build new packages from commit cfa7a02a0818a0f001912169149ddb7fa640a391 which fixes the debug assertion: http://max-tst-01.mariadb.com/ci-repository/2.2-markusjm-mar5-2/mariadb-maxscale/

As these are development packages, debug assertions are enabled to help us catch bugs when testing MaxScale. For verification purposes, please try and see if these packages fix the problems.

Comment by Vipul [ 2018-03-05 ]

Thanks for taking care of this bug so soon. the new build does not crash maxscale.
Will this fix be part of 2.2.3 or 2.3 ?

Comment by markus makela [ 2018-03-06 ]

The fix will be a part of 2.2.3.

Generated at Thu Feb 08 04:08:44 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.