[MDEV-10273] mariadb server crashes after CONNECT engine operation Created: 2016-06-22  Updated: 2016-12-30  Resolved: 2016-12-30

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - Connect
Affects Version/s: 10.1.10, 10.1.14
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Robert Dyas Assignee: Olivier Bertrand
Resolution: Not a Bug Votes: 0
Labels: connect-engine
Environment:

CentOS7 image on Google Compute Engine


 Description   

MariaDB server crashes at times, apparently with root cause somewhere in the CONNECT engine. Log info below:

 
 
Jun 22 09:13:24 si-mariadb-3 mysqld: 160622  9:13:24 [ERROR] mysqld got signal 7 ;
 
Jun 22 09:13:24 si-mariadb-3 mysqld: This could be because you hit a bug. It is also possible that this binary
 
Jun 22 09:13:24 si-mariadb-3 mysqld: or one of the libraries it was linked against is corrupt, improperly built,
 
Jun 22 09:13:24 si-mariadb-3 mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Jun 22 09:13:24 si-mariadb-3 mysqld: To report this bug, see http://kb.askmonty.org/en/reporting-bugs
 
Jun 22 09:13:24 si-mariadb-3 mysqld: We will try our best to scrape up some info that will hopefully help
 
Jun 22 09:13:24 si-mariadb-3 mysqld: diagnose the problem, but since we have already crashed,
 
Jun 22 09:13:24 si-mariadb-3 mysqld: something is definitely wrong and this may fail.
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Server version: 10.1.10-MariaDB-log
 
Jun 22 09:13:24 si-mariadb-3 mysqld: key_buffer_size=134217728
 
Jun 22 09:13:24 si-mariadb-3 mysqld: read_buffer_size=131072
 
Jun 22 09:13:24 si-mariadb-3 mysqld: max_used_connections=2
 
Jun 22 09:13:24 si-mariadb-3 mysqld: max_threads=153
 
Jun 22 09:13:24 si-mariadb-3 mysqld: thread_count=2
 
Jun 22 09:13:24 si-mariadb-3 mysqld: It is possible that mysqld could use up to
 
Jun 22 09:13:24 si-mariadb-3 mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467105 K  bytes of memory
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Hope that's ok; if not, decrease some variables in the equation.
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Thread pointer: 0x0x7fcda8f5b008
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Attempting backtrace. You can use the following information to find out
 
Jun 22 09:13:24 si-mariadb-3 mysqld: where mysqld died. If you see no messages after this, something went
 
Jun 22 09:13:24 si-mariadb-3 mysqld: terribly wrong...
 
Jun 22 09:13:24 si-mariadb-3 mysqld: stack_bottom = 0x7fce39146d30 thread_stack 0x48000
 
Jun 22 09:13:24 si-mariadb-3 mysqld: mysys/stacktrace.c:247(my_print_stacktrace)[0x7fce39d4736e]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/signal_handler.cc:160(handle_fatal_signal)[0x7fce398756ad]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libpthread.so.0(+0xf100)[0x7fce38e97100]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libodbc.so.2(+0xc3cc)[0x7fce2ae3b3cc]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libodbc.so.2(+0xc7b9)[0x7fce2ae3b7b9]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libodbc.so.2(+0xec28)[0x7fce2ae3dc28]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libodbc.so.2(SQLDriverConnect+0x88b)[0x7fce2ae4273b]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /usr/lib64/mysql/plugin/ha_connect.so(_ZN7ODBConn13DriverConnectEj+0x5c)[0x7fce339ac57c]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /usr/lib64/mysql/plugin/ha_connect.so(_ZN7ODBConn4OpenEPcP10odbc_parmsj+0x58)[0x7fce339ac648]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /usr/lib64/mysql/plugin/ha_connect.so(_ZN7TDBODBC6OpenDBEP7_global+0x66)[0x7fce339a7b86]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /usr/lib64/mysql/plugin/ha_connect.so(_Z12CntOpenTableP7_globalP3TDB4MODEPcS4_bP10ha_connect+0x3bd)[0x7fce33920fed]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /usr/lib64/mysql/plugin/ha_connect.so(_ZN10ha_connect9OpenTableEP7_globalb+0x1ac)[0x7fce33914a4c]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /usr/lib64/mysql/plugin/ha_connect.so(_ZN10ha_connect8rnd_initEb+0x1d6)[0x7fce33915196]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/handler.h:2768(handler::ha_rnd_init(bool))[0x7fce3987b067]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/records.cc:281(init_read_record(READ_RECORD*, THD*, TABLE*, SQL_SELECT*, int, bool, bool))[0x7fce3997ca36]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_select.cc:19179(join_init_read_record(st_join_table*))[0x7fce3972f150]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_join_cache.cc:2255(JOIN_CACHE::join_matching_records(bool))[0x7fce397ed8e6]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_join_cache.cc:2093(JOIN_CACHE::join_records(bool))[0x7fce397ed3f4]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_select.cc:18064(sub_select_cache(JOIN*, st_join_table*, bool))[0x7fce3972f7ea]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_select.cc:17939(do_select)[0x7fce3973cdee]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_select.cc:2773(JOIN::exec_inner())[0x7fce3974ca26]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_select.cc:2519(JOIN::exec())[0x7fce3974ed54]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_select.cc:3453(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x7fce3974b3f2]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_select.cc:384(handle_select(THD*, LEX*, select_result*, unsigned long))[0x7fce3974bed5]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_parse.cc:5903(execute_sqlcom_select)[0x7fce396ee9b1]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_parse.cc:2961(mysql_execute_command(THD*))[0x7fce396fac31]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_prepare.cc:4019(Prepared_statement::execute(String*, bool))[0x7fce397113f6]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_prepare.cc:3650(Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*))[0x7fce39711563]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_prepare.cc:2730(mysqld_stmt_execute(THD*, char*, unsigned int))[0x7fce39711a5e]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_parse.cc:1431(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x7fce39700627]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_parse.cc:1111(do_command(THD*))[0x7fce397020a9]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_connect.cc:1349(do_handle_one_connection(THD*))[0x7fce397c4dda]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: sql/sql_connect.cc:1263(handle_one_connection)[0x7fce397c4fb0]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libpthread.so.0(+0x7dc5)[0x7fce38e8fdc5]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libc.so.6(clone+0x6d)[0x7fce372b321d]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Trying to get some variables.
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Some pointers may be invalid and cause the dump to abort.
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Query (0x7fcdadbf8468): SELECT `SiteVisits`.`SiteVisit_ID`, `SiteVisits`.`VisitType`, `SiteVisits`.`VisitStatus`, `SiteVisits`.`Account_ID`, `SiteVisits`.`Location_ID`, `rmt_Account`.`Name`, `rmt_Account`.`IsDeleted`, `SiteVisits`.`EndTime`, `SiteVisits`.`LeadEngineer_ID`, `SiteVisits`.`OtherEngineers_ID`, `SiteVisits`.`Contact_ID`, `SiteVisits`.`Owner_ID`, `SiteVisits`.`ServiceDeskEngineer_ID`, `SiteVisits`.`CustomerContactName`, `SiteVisits`.`CustomerContactMobile`, `rmt_Account`.`Id`, `SiteVisits`.`VisitDate`, `SiteVisits`.`StartTime`, `rmt_Account`.`BillingStreet`, `rmt_Account`.`BillingCity`, `rmt_Account`.`BillingCountry`, `rmt_Account`.`Phone`, `rmt_Account`.`OwnerId`, `rmt_Account`.`Principle_Contact__c`, `rmt_Account`.`Principle_Contact_Title__c`, `SiteVisitEngineers`.`SiteVisitEngineer_ID`, `SiteVisitEngineers`.`Mobile`, `SiteVisitEngineers`.`Email`, `SiteVisitEngineers`.`Active` FROM `SiteVisits` LEFT JOIN `rmt_Account` ON ( `rmt_Account`.`Id` = `SiteVisits`.`Account_ID` ) LEFT JOIN `SiteVisitEngineers` ON ( `SiteVisitEngineers`.`SiteVisitEngineer_ID` = `SiteVisits`.`LeadEngineer_ID` )  WHERE  (  ( `SiteVisitEngineers`.`Email` = 'hutzeflutz@gmail.com' AND `SiteVisits`.`VisitStatus` = 'Open' )  AND  ( TRUE )  )  ORDER BY `SiteVisits`.`VisitDate` ASC LIMIT 0,50
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Connection ID (thread ID): 1292
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Status: NOT_KILLED
 
Jun 22 09:13:24 si-mariadb-3 mysqld: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
 
Jun 22 09:13:24 si-mariadb-3 mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
Jun 22 09:13:24 si-mariadb-3 mysqld: information that should help you find out what is causing the crash.



 Comments   
Comment by Elena Stepanova [ 2016-06-22 ]

Is it reproducible if you run the query quoted in the error log?

 SELECT `SiteVisits`.`SiteVisit_ID`, `SiteVisits`.`VisitType`, `SiteVisits`.`VisitStatus`, `SiteVisits`.`Account_ID`, `SiteVisits`.`Location_ID`, `rmt_Account`.`Name`, `rmt_Account`.`IsDeleted`, `SiteVisits`.`EndTime`, `SiteVisits`.`LeadEngineer_ID`, `SiteVisits`.`OtherEngineers_ID`, `SiteVisits`.`Contact_ID`, `SiteVisits`.`Owner_ID`, `SiteVisits`.`ServiceDeskEngineer_ID`, `SiteVisits`.`CustomerContactName`, `SiteVisits`.`CustomerContactMobile`, `rmt_Account`.`Id`, `SiteVisits`.`VisitDate`, `SiteVisits`.`StartTime`, `rmt_Account`.`BillingStreet`, `rmt_Account`.`BillingCity`, `rmt_Account`.`BillingCountry`, `rmt_Account`.`Phone`, `rmt_Account`.`OwnerId`, `rmt_Account`.`Principle_Contact__c`, `rmt_Account`.`Principle_Contact_Title__c`, `SiteVisitEngineers`.`SiteVisitEngineer_ID`, `SiteVisitEngineers`.`Mobile`, `SiteVisitEngineers`.`Email`, `SiteVisitEngineers`.`Active` FROM `SiteVisits` LEFT JOIN `rmt_Account` ON ( `rmt_Account`.`Id` = `SiteVisits`.`Account_ID` ) LEFT JOIN `SiteVisitEngineers` ON ( `SiteVisitEngineers`.`SiteVisitEngineer_ID` = `SiteVisits`.`LeadEngineer_ID` )  WHERE  (  ( `SiteVisitEngineers`.`Email` = 'hutzeflutz@gmail.com' AND `SiteVisits`.`VisitStatus` = 'Open' )  AND  ( TRUE )  )  ORDER BY `SiteVisits`.`VisitDate` ASC LIMIT 0,50

If it's reproducible, please provide the output of 

SHOW CREATE TABLE `SiteVisits`;
 
SHOW CREATE TABLE `rmt_Account`;
 
SHOW TABLE STATUS LIKE 'SiteVisits';
 
SHOW TABLE STATUS LIKE 'rmt_Account';

and the same for underlying tables, if there are any.

Comment by Robert Dyas [ 2016-06-22 ]

Unfortunately it is not reproducible. This query works fine before the crash, and after a reboot.

Here is the info you asked for just in case it helps:

 
 
SHOW CREATE TABLE `SiteVisits`;
 
'SiteVisits', 'CREATE TABLE \"SiteVisits\" (\n  \"SiteVisit_ID\" bigint(20) NOT NULL COMMENT \'AUTOKEY\',\n  \"VisitType\" varchar(40) DEFAULT NULL,\n  \"VisitStatus\" varchar(15) DEFAULT NULL,\n  \"Account_ID\" varchar(18) DEFAULT NULL,\n  \"Location_ID\" varchar(50) DEFAULT NULL,\n  \"VisitDate\" date DEFAULT NULL,\n  \"StartTime\" time DEFAULT NULL,\n  \"EndTime\" time DEFAULT NULL,\n  \"LeadEngineer_ID\" varchar(50) DEFAULT NULL,\n  \"OtherEngineers_ID\" varchar(50) DEFAULT NULL,\n  \"Contact_ID\" varchar(18) DEFAULT NULL,\n  \"Owner_ID\" varchar(18) DEFAULT NULL,\n  \"ServiceDeskEngineer_ID\" varchar(50) DEFAULT NULL,\n  \"CustomerContactName\" varchar(50) DEFAULT NULL,\n  \"CustomerContactMobile\" varchar(15) DEFAULT NULL,\n  PRIMARY KEY (\"SiteVisit_ID\"),\n  KEY \"VisitType\" (\"VisitType\"),\n  KEY \"Account_ID\" (\"Account_ID\"),\n  KEY \"Location_ID\" (\"Location_ID\"),\n  KEY \"ServiceDeskEngineer_ID\" (\"ServiceDeskEngineer_ID\"),\n  KEY \"LeadEngineer_ID\" (\"LeadEngineer_ID\"),\n  KEY \"OtherEngineers_ID\" (\"OtherEngineers_ID\"),\n  KEY \"VisitStatus\" (\"VisitStatus\"),\n  CONSTRAINT \"SiteVisits_ibfk_11\" FOREIGN KEY (\"ServiceDeskEngineer_ID\") REFERENCES \"ServiceDeskEngineers\" (\"ServiceDeskEngineer_ID\") ON UPDATE CASCADE,\n  CONSTRAINT \"SiteVisits_ibfk_12\" FOREIGN KEY (\"LeadEngineer_ID\") REFERENCES \"SiteVisitEngineers\" (\"SiteVisitEngineer_ID\") ON UPDATE CASCADE,\n  CONSTRAINT \"SiteVisits_ibfk_13\" FOREIGN KEY (\"OtherEngineers_ID\") REFERENCES \"SiteVisitEngineers\" (\"SiteVisitEngineer_ID\") ON UPDATE CASCADE,\n  CONSTRAINT \"SiteVisits_ibfk_14\" FOREIGN KEY (\"VisitStatus\") REFERENCES \"Statuses\" (\"Status_ID\") ON UPDATE CASCADE,\n  CONSTRAINT \"SiteVisits_ibfk_4\" FOREIGN KEY (\"VisitType\") REFERENCES \"VisitTypes\" (\"VisitType_ID\") ON UPDATE CASCADE,\n  CONSTRAINT \"SiteVisits_ibfk_9\" FOREIGN KEY (\"Location_ID\") REFERENCES \"Locations\" (\"Location_ID\") ON UPDATE CASCADE\n) ENGINE=InnoDB DEFAULT CHARSET=utf8'
 
 
 
SHOW CREATE TABLE `rmt_Account`;
 
'rmt_Account', 'CREATE TABLE \"rmt_Account\" (\n  \"Id\" varchar(18) NOT NULL,\n  \"IsDeleted\" tinyint(1) NOT NULL,\n  \"Name\" varchar(255) NOT NULL,\n  \"BillingStreet\" varchar(255) DEFAULT NULL,\n  \"BillingCity\" varchar(40) DEFAULT NULL,\n  \"BillingCountry\" varchar(80) DEFAULT NULL,\n  \"Phone\" varchar(40) DEFAULT NULL,\n  \"OwnerId\" varchar(18) NOT NULL,\n  \"Principle_Contact__c\" varchar(18) DEFAULT NULL,\n  \"Principle_Contact_Title__c\" varchar(1300) DEFAULT NULL\n) ENGINE=CONNECT DEFAULT CHARSET=utf8 COMMENT=\'Remote Table: SALESFORCE:null/null/Account as user: tony.tenwolde@roamworks.com\' CONNECTION=\'driver=SimbaSalesforce64;MetadataLevel=FULL;SecurityToken=dxzQqoTnqUUNFStzzjinU2CK;URL=login.salesforce.com;database_name=db11404;pwd=20Sal3s16F0rc3;uid=tony.tenwolde@roamworks.com;\' \"TABLE_TYPE\"=ODBC \"TABNAME\"=\'Account\' \"OPTION_LIST\"=\'Memory=3\''
 
 
 
SHOW TABLE STATUS LIKE 'SiteVisits';
 
'SiteVisits', 'InnoDB', '10', 'Compact', '45', '364', '16384', '0', '114688', '0', NULL, '2016-05-06 09:34:01', NULL, NULL, 'utf8_general_ci', NULL, '', ''
 
 
 
SHOW TABLE STATUS LIKE 'rmt_Account';
 
'rmt_Account', 'CONNECT', '10', 'Dynamic', '10', '0', '0', '0', '0', '0', NULL, NULL, NULL, NULL, 'utf8_general_ci', NULL, '\"TABLE_TYPE\"=ODBC \"TABNAME\"=\'Account\' \"OPTION_LIST\"=\'Memory=3\'', 'Remote Table: SALESFORCE:null/null/Account as user: tony.tenwolde@roamworks.com'

Comment by Olivier Bertrand [ 2016-06-23 ]

Since this is not always reproducible and that I don't have the data source it will be very difficult for me to work on this case.

In addition, looking in the error log, it seems that the crash does not directly occur in CONNECT code but in the unixODBC code after the function SQLDriverConnect is called.

What could be done is to see whether there is a difference when the data source is connected via SQLConnect instead of SQLDriverConnect.

There are two ways to establish a connection to a data source:

  1. Using SQLDriverConnect and a Connection String
  2. Using SQLConnect and a Data Source Name (DSN)

The first way uses a Connection String whose components describe what is needed to establish the connection. It is the most complete way to do it and by default CONNECT uses it.

The second way is a simplified way in which ODBC is just given the name of a DSN that must have been defined to ODBC or UnixOdbc and that contains the necessary information to establish the connection. Only the user name and password can be specified out of the DSN specification.

This is done by specifying in the option list the Boolean option “UseDSN” as yes or 1. In addition, string options “user” and “password” can be optionally specified in the option list.

When doing so, the connection string just contains the name of the predefined Data Source. For instance:

CREATE TABLE tlite ENGINE=CONNECT TABLE_TYPE=ODBC tabname='lite'
 
CONNECTION='SQLite3 Datasource' 
OPTION_LIST='UseDSN=Yes,User=me,Password=mypass';

Note: the connection data source name (limited to 32 characters) should not be preceded by “DSN=”.

Comment by Robert Dyas [ 2016-06-23 ]

No option to use DSN. What is interesting is that the setup was stable for weeks and now has crashed 3 times in 24 hours.

Each crash comes after a different SQL statement, so it does not appear to be the statement causing the issue. You can issue the same statement after reboot and it runs fine.

And each of these three times it ALWAYS crashes with the exact same stack trace, specifically:

Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libodbc.so.2(+0xc3cc)[0x7fce2ae3b3cc]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libodbc.so.2(+0xc7b9)[0x7fce2ae3b7b9]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libodbc.so.2(+0xec28)[0x7fce2ae3dc28]
 
Jun 22 09:13:24 si-mariadb-3 mysqld: /lib64/libodbc.so.2(SQLDriverConnect+0x88b)[0x7fce2ae4273b]

Also, the unixODBC package has not been changed since January, so no difference there.

Could this be the result of a corrupt database? Maybe try dump/delete/restore the database and see if problem is the same? Any suggest to get stability back would be appreciated.

NOTE: I upgraded to 10.1.14 yesterday and have had two crashes since.

Comment by Vicențiu Ciorbaru [ 2016-11-30 ]

Hi rdyas!

Can you find out which underlying architecture Google Compute Engine has? I suspect it's intel x86 chips but the problem might be related to: https://jira.mariadb.org/browse/MDEV-11366

Comment by Robert Dyas [ 2016-12-30 ]

Yes, x86.
I am 99% sure this issue was due to a bug in a 3rd party odbc driver that didn't like a free message that it received at a delayed time from the odbc manager, which crashed connect. You may be able to close this ticket given this.

Comment by Olivier Bertrand [ 2016-12-30 ]

See last Robert Dyas comment.

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