[MDEV-19651] CONNECT engine JDBC not adequately reporting error or exception in certain cases Created: 2019-05-30  Updated: 2019-07-17

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - Connect
Affects Version/s: 10.3.15
Fix Version/s: 10.3

Type: Bug Priority: Major
Reporter: Robert Dyas Assignee: Olivier Bertrand
Resolution: Unresolved Votes: 0
Labels: None
Environment:

centOS7

Attachments: Text File connect_error_1.txt     Text File connect_error_2.txt    

 Description   

When using CONNECT JDBC and an error occurs while obtaining schema info (i.e. with CATFUNC=TABLES) you generally get a good and very usable error message something like the following:

(conn=4121) Got error 174 'GetTables: XcoreXsalesforceX190X7062.fkd: [sf:INVALID_LOGIN] INVALID_LOGIN: Invalid username, password, security token; or user locked out. ' from CONNECT

In the above case it appears to be passing up the error message from exception thrown by the JDBC driver. However, if you then create a connect JDBC table successfully but later do something like a SELECT * FROM MyConnectTable that generates an error from the remote system, the error is generic as follows:

ERROR: (conn=4124) Got error 174 'Cannot get result size rc=-1' from CONNECT

It would be very, very helpful if the error text (exception.getLocalizedMessage() ) was included in the CONNECT error message at all times.... just like it is when CATFUNC=TABLES is used.

 Comments   
Comment by Olivier Bertrand [ 2019-06-04 ]

Could you provide an example of queries causing such error?

I tried to reproduce this by doing:

create table jt2 (
 
id int(8) not null,
 
message char(16))
 
engine=connect table_type=JDBC tabname=t1
 
connection='jdbc:postgresql:test?user=postgres&password=xxxxxx';
 
select * from jt2;

The error is that the name of the second column of the remote table is "msg". But when I executed the select statement, I did get an error message containing the exception message:

1296: Got error 174 'ExecuteQuery: org.postgresql.util.PSQLException:
 
ERREUR: la colonne "message" n'existe pas
 
Position: 12 from CONNECT

Comment by Robert Dyas [ 2019-06-04 ]

It does seem to depend on the driver. MS SQL Server seemed to behave correctly, but the following Salesforce driver does not.... you can download here:
https://www.cdata.com/drivers/salesforce/download/jdbc/

... and you can use this as the connection URL to our test environment:

jdbc:salesforce:User=support@appsynergy.com;Password=parasql12345;SecurityToken=0qBCttqd4Fp6365YfGnpkSPRH;Logfile=/var/log/mysql/sf.log;Verbosity=4;

That should connect successfully. Try doing a simple
SELECT * FROM Account

Then to break it, simply add something like the letter X to the end of the SecurityToken parameter.

Comment by Robert Dyas [ 2019-06-08 ]

Any luck in reproducing the problem?

Comment by Olivier Bertrand [ 2019-06-21 ]

Sorry, I am working on another thing and had no time for this.

Incidentally, as this seems to be dependant on only some drivers, shouldn't this be addressed to them instead of CONNECT?

Comment by Robert Dyas [ 2019-06-21 ]

Thanks for the update Olivier... I totally understand. No worries.

Yes, I can address it to them if I can pin it down. The same driver does pass the right info to connect, and connect does pass the info along in the error.... sometimes... but not in other cases. I just ran into it again with another driver... in this case (presumably) the JDBC driver is making API calls and part way through it fails (server down I think) and I get an error from connect like this:

HY000 Got error 174 'Cannot get result size rc=-3' from CONNECT

What made me think it might be how connect traps errors in different phases of processing is sometimes is says rc=-3, somtimes rc=-2, somtimes rc=-1 depending upon the situation. I guess I could write some Java code and try to pin it down one way or the other.

Comment by Robert Dyas [ 2019-06-24 ]

I get errors like this occassionally too... not sure why? Does this mean anything to you?

HY000 Got error 122 'Out of range valblock index value' from CONNECT

Comment by Olivier Bertrand [ 2019-06-24 ]

It does but I can't tell you why if you don't describe when it occured (on what SQL query and in what context)

Comment by Robert Dyas [ 2019-06-24 ]

There are scheduled events that run every 6 hours that copy maybe 10,000 to 20,000 rows on one table, and a few thousand rows on several other tables. I get an email with an error report when something fails. I seem to get this error maybe 1x or 2x per week, so maybe 1 or 2 times per 30 runs... not reproducible in any kind of predictable way.

Is it an internal CONNECT error message or caused by a problem with the JDBC connection?

Comment by Olivier Bertrand [ 2019-06-24 ]

It is an internal message telling that a function addressed a valblock array (an array of values) with an index bigger than the size of the array. There are many functions using valblk's and so far this never happened. It will be impossible to find why it occured without knowing exactly what the server was doing when it failed.

Comment by Robert Dyas [ 2019-06-24 ]

I doubt the following will help, but this is what the scheduled event is doing... note the FROM table in each of the select statements is a CONNECT JDBC table using a Shopify driver from CDATA. I could foresee where you are in a long "sending data" phase as the driver makes a bunch of API calls to collect the rows and the API calls fail part way through.... so wild maybe it is happening if an exception is thrown or something fails during the "sending data" phase (that term I am getting from Workbench when I do show processlist).

		CREATE OR REPLACE TABLE Orders_Local_NEW AS 
		
			SELECT Id, Name as FT_Number, CustomerId, FulfillmentStatus, FinancialStatus,  
				CancelReason, CancelledAt,  ProcessedAt, CreatedAt, UpdatedAt, Tags,
 
				SubtotalPrice, TotalPrice, TotalTax, TotalWeight, ProcessingMethod, DiscountCodes,
 
				ShippingAddressFirstName, ShippingAddressLastName, ShippingAddressAddress1, ShippingAddressAddress2, 
				ShippingAddressCity, ShippingAddressProvinceCode, ShippingAddressZip, ShippingAddressCountryCode, ShippingAddressPhone
 
				
			FROM Orders;
 
		ALTER TABLE Orders_Local_NEW ADD PRIMARY KEY (Id), ADD INDEX (FT_Number), ADD INDEX (CustomerId);
 
		
		
		CREATE OR REPLACE TABLE OrderItems_Local_NEW AS 
			SELECT * 
			FROM OrderItems;
 
		ALTER TABLE OrderItems_Local_NEW ADD PRIMARY KEY (ItemId), ADD INDEX (ItemVariantId), ADD INDEX (FulfillableQuantity), ADD INDEX (FulFillmentsService);
 
		
		
		CREATE OR REPLACE TABLE Products_Local_NEW AS
 
			SELECT Id, Handle, ProductType, Title 
			FROM Products;
 
		ALTER TABLE Products_Local_NEW ADD PRIMARY KEY (Id);
 
		
		
		CREATE OR REPLACE TABLE ProductVariants_Local_NEW AS 
			SELECT * 
			FROM ProductVariants;
 
		ALTER TABLE ProductVariants_Local_NEW ADD PRIMARY KEY (Id), ADD INDEX (ProductId);

Should I enable connect_xtrace and if so what value? 33? higher?
Thank you!

Comment by Olivier Bertrand [ 2019-06-24 ]

1023

Comment by Robert Dyas [ 2019-07-08 ]

I've attached two log files.... one with a valblock message as follows:

Jun 24 06:04:37 di-mariadb-test1 mysqld: rnd_next CONNECT: Out of range valblock index value

and one with errors relating to "cannot get result size"

Jul  8 12:05:19 di-mariadb-test1 mysqld: Exception 7: Cannot get result size rc=-1
 
Jul  8 12:05:19 di-mariadb-test1 mysqld: OpenTable: Cannot get result size rc=-1
 
Jul  8 12:05:19 di-mariadb-test1 mysqld: GEM(174): Cannot get result size rc=-1

I will try to attach the files in the next comment... it is giving errors on this one.

Comment by Robert Dyas [ 2019-07-08 ]

connect_error_1.txt connect_error_2.txt

Hi Olivier... Log files now attached.

Would be awesome if these intermittent errors could be found/fixed

Comment by Robert Dyas [ 2019-07-12 ]

Olivier.... any idea here now that you have the log file (connect_xtrace =1023) ?

Comment by Olivier Bertrand [ 2019-07-12 ]

No. The one with the valblock message has no trace, just that message out of nowhere. The other one indicates that executing the query meant to retrieve the size of the result failed but infortunately the message telling while it failed is lost. I'll try to change that but this will be only available in future releases.

Comment by Robert Dyas [ 2019-07-16 ]

Great. I'll re-run and capture new logs once the new release is available.
The "query meant to retrieve the size of the result failed but unfortunately the message telling while it failed is lost." happens slightly more often than the valblock error.

Comment by Robert Dyas [ 2019-07-17 ]

Olivier... a new set of log data below for the valblock error .... but this time it looks like there is more context as to why:

Jul 17 11:55:55 di-mariadb-test1 mysqld: server: ds1546043537772 Tabname: OrdersSubAlloc in 0x7f7e8bfff010 size=240 used=38648 free=67070216
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008708 used=38888 free=67069976
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=8 used=38888 free=67069976
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c0087f8 used=38896 free=67069968
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=8 used=38896 free=67069968
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008800 used=38904 free=67069960
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=8 used=38904 free=67069960
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008808 used=38912 free=67069952
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=392 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=392 used=38912 free=67069952
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008810 used=39304 free=67069560
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: 0x7f7ebc2c00b0 In info: flag=212 valid_info=0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: PlgDBSubAlloc: memp=0x7f7e8bfff010 size=16 used=39304 free=67069560
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008998 used=39320 free=67069544
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=56 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=56 used=39320 free=67069544
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c0089a8 used=39376 free=67069488
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: XTAB: making new TABLE Customers (null)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: ning tdbp=0x7f7e5c121718 mode=0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntCheckDB: dbuserp=0x7f7ec015a770
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: cat=0x7f7ec011bc20 oldhandler=(nil) newhandler=0x7f7ebc2b9630
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: name=Orders mode=10 cat=0x7f7ec011bc20
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: tabp=0x7f7eaffff038
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDB: name=Orders
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDesc: name=Orders am=<null>
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: MakeTableDesc: name=Orders schema=<null> am=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdb=0x7f7eaffff078 type=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdbp=0x7f7eb0003340 name=Orders amtype=102
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Returning tdbp=0x7f7eb0003340 mode=10
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntOpenTable: tdbp=0x7f7eb0003340 mode=10
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column Id
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column CustomerId
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column Name
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column TotalPrice
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column SubtotalPrice
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column TotalTax
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column TotalWeight
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column CancelReason
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ProcessingMethod
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column Tags
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column FulfillmentStatus
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column FinancialStatus
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column DiscountCodes
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressFirstName
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressLastName
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressAddress1
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressAddress2
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressPhone
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressCity
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressZip
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressCountryCode
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ShippingAddressProvinceCode
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ProcessedAt
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column CreatedAt
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column CancelledAt
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column UpdatedAt
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Opening table Orders in mode 10 tdbp=0x7f7eb0003340
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: About to open the table: tdbp=0x7f7eb0003340
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntCloseTable: tdbp=0x7f7eb0003340 mode=10 nox=1 abort=0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Table Orders closed
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: =====> Begin new query 568103
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntCheckDB: dbuserp=0x7f7ec015a770
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: cat=0x7f7ec011bc20 oldhandler=0x7f7ebc2b9630 newhandler=0x7f7ebc14f810
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: name=OrderItems mode=10 cat=0x7f7ec011bc20
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: tabp=0x7f7eaffff038
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDB: name=OrderItems
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDesc: name=OrderItems am=<null>
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: MakeTableDesc: name=OrderItems schema=<null> am=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdb=0x7f7eaffff080 type=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdbp=0x7f7eb00005f0 name=OrderItems amtype=102
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Returning tdbp=0x7f7eb00005f0 mode=10
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntOpenTable: tdbp=0x7f7eb00005f0 mode=10
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ItemId
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column OrderId
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column OrderUpdatedAt
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ProductId
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ItemVariantId
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ItemTitle
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column Name
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ItemQuantity
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ItemPrice
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column ItemGrams
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column SKU
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column VariantTitle
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column Properties
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column Vendor
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column FulFillmentsService
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column RequiresShipping
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column Taxable
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column GiftCard
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column FulfillableQuantity
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column TotalDiscount
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column FulfillmentStatus
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column AppliedDiscountTitle
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column AppliedDiscountDescription
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column AppliedDiscountValue
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column AppliedDiscountValueType
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Allocating column AppliedDiscountAmount
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Opening table OrderItems in mode 10 tdbp=0x7f7eb00005f0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: About to open the table: tdbp=0x7f7eb00005f0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Error 5 reading columns: Out of range valblock index value
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntCloseTable: tdbp=0x7f7eb00005f0 mode=10 nox=1 abort=0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Table OrderItems closed
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: name=OrderItems mode=0 cat=0x7f7ed001e260
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: tabp=0x7f7e8bfff028
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDB: name=OrderItems
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDesc: name=OrderItems am=<null>
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: MakeTableDesc: name=OrderItems schema=<null> am=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdb=0x7f7e8bfff070 type=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdbp=0x7f7e8c0016b0 name=OrderItems amtype=102
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Returning tdbp=0x7f7e8c0016b0 mode=0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: name=Products mode=0 cat=0x7f7ed001e260
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: tabp=0x7f7e8c001848
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDB: name=Products
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDesc: name=Products am=<null>
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: MakeTableDesc: name=Products schema=<null> am=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdb=0x7f7e8c001890 type=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdbp=0x7f7e8c003630 name=Products amtype=102
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Returning tdbp=0x7f7e8c003630 mode=0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: name=Orders mode=0 cat=0x7f7ed001e260
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: tabp=0x7f7e8c0037c8
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDB: name=Orders
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTableDesc: name=Orders am=<null>
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: MakeTableDesc: name=Orders schema=<null> am=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdb=0x7f7e8c003808 type=JDBC
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: tdbp=0x7f7e8c008810 name=Orders amtype=102
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Returning tdbp=0x7f7e8c008810 mode=0
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: name=Customers mode=0 cat=0x7f7ed001e260
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: CntGetTDB: tabp=0x7f7e8c0089a8
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: GetTabSubAlloc in 0x7f7e8bfff010 size=16 used=39376 free=67069488
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c0089e0 used=39392 free=67069472
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=272 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=272 used=39392 free=67069472
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c0089f0 used=39664 free=67069200
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=8 used=39664 free=67069200
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008b00 used=39672 free=67069192
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=8 used=39672 free=67069192
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008b08 used=39680 free=67069184
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=72 used=39680 free=67069184
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008b10 used=39752 free=67069112
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=39752 free=67069112
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008b58 used=39912 free=67068952
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=8 used=39912 free=67068952
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008bf8 used=39920 free=67068944
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=39920 free=67068944
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008c00 used=40080 free=67068784
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=16 used=40080 free=67068784
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008ca0 used=40096 free=67068768
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=40096 free=67068768
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008cb0 used=40256 free=67068608
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=16 used=40256 free=67068608
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008d50 used=40272 free=67068592
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=40272 free=67068592
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008d60 used=40432 free=67068432
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=16 used=40432 free=67068432
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008e00 used=40448 free=67068416
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=40448 free=67068416
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008e10 used=40608 free=67068256
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=16 used=40608 free=67068256
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008eb0 used=40624 free=67068240
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=40624 free=67068240
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008ec0 used=40784 free=67068080
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=8 used=40784 free=67068080
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008f60 used=40792 free=67068072
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=40792 free=67068072
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c008f68 used=40952 free=67067912
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=8 used=40952 free=67067912
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c009008 used=40960 free=67067904
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=40960 free=67067904
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c009010 used=41120 free=67067744
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=16 used=41120 free=67067744
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c0090b0 used=41136 free=67067728
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=41136 free=67067728
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c0090c0 used=41296 free=67067568
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=16 used=41296 free=67067568
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c009160 used=41312 free=67067552
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=41312 free=67067552
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c009170 used=41472 free=67067392
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=16 used=41472 free=67067392
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c009210 used=41488 free=67067376
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=41488 free=67067376
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c009220 used=41648 free=67067216
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=24 used=41648 free=67067216
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c0092c0 used=41672 free=67067192
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=160 used=41672 free=67067192
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c0092d8 used=41832 free=67067032
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: SubAlloc in 0x7f7e8bfff010 size=24 used=41832 free=67067032
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: Done memp=0x7f7e8c009378 used=41856 free=67067008
 
Jul 17 11:55:55 di-mariadb-test1 mysqld: New BLOCK: size=160 g=0x7f7ed00fea70 p=(nil)

Comment by Olivier Bertrand [ 2019-07-17 ]

ODBC/JDBC tables shouldn't be indexed. Indexing is done by the remote server. If the table is remotely modified, CONNECT doesn't know it and the local index is mismatching.

Comment by Robert Dyas [ 2019-07-17 ]

We have not indexed any connect columns. If an index is being added, it isn't by us.
Which table/column looks indexed to you?
Also, this is an intermittent error... 90% to 95% of the time it runs, but occasionally it fails.

Maybe a higher-level part of the MariaDB stack is adding a temporary index automatically?

Comment by Olivier Bertrand [ 2019-07-17 ]

The only way I see to spot the error is to execute this in debug mode. For this I must have the implied table definitions and access to the remote server. Can you provide this?

Comment by Robert Dyas [ 2019-07-17 ]

I'll have to try and get customer approval as the "server" is a live Shopify account ... it is a JDBC driver that accesses a REST API not a database directly. The main problem that I see is that the error is highly intermittent. I'm starting to wonder why that might be? Maybe if two threads try to access the same connect table at the same time there is an issue?

I can probably get customer approval if all you do is issue SELECT statements and I can private message or email you the connect URL that has the production password in it. If we try it with another account with less data we won't be able to reproduce the error I don't suspect.

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