Bug 1276248 - [Tier]: restarting volume reports "insert/update failure" in cold brick logs
[Tier]: restarting volume reports "insert/update failure" in cold brick logs
Status: CLOSED ERRATA
Product: Red Hat Gluster Storage
Classification: Red Hat
Component: tier (Show other bugs)
3.1
x86_64 Linux
high Severity high
: ---
: RHGS 3.1.2
Assigned To: Joseph Elwin Fernandes
Rahul Hinduja
: ZStream
Depends On:
Blocks: 1260783 1260923 1277352 1279059
  Show dependency treegraph
 
Reported: 2015-10-29 04:55 EDT by Rahul Hinduja
Modified: 2016-09-17 11:38 EDT (History)
6 users (show)

See Also:
Fixed In Version: glusterfs-3.7.5-7
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1277352 (view as bug list)
Environment:
Last Closed: 2016-03-01 00:48:18 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2016:0193 normal SHIPPED_LIVE Red Hat Gluster Storage 3.1 update 2 2016-03-01 05:20:36 EST

  None (edit)
Description Rahul Hinduja 2015-10-29 04:55:53 EDT
Description of problem:
=======================

On longevity setup consists of hot tier {6x2} and cold tier {2x (4 + 2)}. Stopping volume and starting back continuous logs below error in bricks:

[2015-10-29 08:29:01.694498] E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB
[2015-10-29 08:29:01.694545] E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert
[2015-10-29 08:29:01.694562] E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed
The message "E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB" repeated 4513 times between [2015-10-29 08:29:01.694498] and [2015-10-29 08:31:01.636651]
The message "E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert" repeated 4513 times between [2015-10-29 08:29:01.694545] and [2015-10-29 08:31:01.636654]
The message "E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed" repeated 4513 times between [2015-10-29 08:29:01.694562] and [2015-10-29 08:31:01.636655]
[2015-10-29 08:31:01.699494] E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB
[2015-10-29 08:31:01.699522] E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert
[2015-10-29 08:31:01.699534] E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed
The message "E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB" repeated 4377 times between [2015-10-29 08:31:01.699494] and [2015-10-29 08:33:01.636690]
The message "E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert" repeated 4377 times between [2015-10-29 08:31:01.699522] and [2015-10-29 08:33:01.636692]
The message "E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed" repeated 4377 times between [2015-10-29 08:31:01.699534] and [2015-10-29 08:33:01.636694]
[2015-10-29 08:33:01.750465] E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB
[2015-10-29 08:33:01.750501] E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert
[2015-10-29 08:33:01.750510] E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed
The message "E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB" repeated 3848 times between [2015-10-29 08:33:01.750465] and [2015-10-29 08:35:01.688212]
The message "E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert" repeated 3848 times between [2015-10-29 08:33:01.750501] and [2015-10-29 08:35:01.688213]
The message "E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed" repeated 3848 times between [2015-10-29 08:33:01.750510] and [2015-10-29 08:35:01.688214]
[2015-10-29 08:35:01.845733] E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB
[2015-10-29 08:35:01.845775] E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert
[2015-10-29 08:35:01.845789] E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed
The message "E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB" repeated 3954 times between [2015-10-29 08:35:01.845733] and [2015-10-29 08:37:01.532783]
The message "E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert" repeated 3954 times between [2015-10-29 08:35:01.845775] and [2015-10-29 08:37:01.532786]
The message "E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed" repeated 3954 times between [2015-10-29 08:35:01.845789] and [2015-10-29 08:37:01.532788]
[2015-10-29 08:37:01.940133] E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB
[2015-10-29 08:37:01.940187] E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert
[2015-10-29 08:37:01.940203] E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed
The message "E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB" repeated 3347 times between [2015-10-29 08:37:01.940133] and [2015-10-29 08:39:01.422669]
The message "E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert" repeated 3347 times between [2015-10-29 08:37:01.940187] and [2015-10-29 08:39:01.422672]
The message "E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed" repeated 3347 times between [2015-10-29 08:37:01.940203] and [2015-10-29 08:39:01.422674]
[2015-10-29 08:39:01.798003] E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB
[2015-10-29 08:39:01.798047] E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert
[2015-10-29 08:39:01.798062] E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed
The message "E [MSGID: 101027] [gfdb_sqlite3_helper.c:800:gf_sql_insert_wind] 0-sqlite3: Failed inserting link in DB" repeated 2903 times between [2015-10-29 08:39:01.798003] and [2015-10-29 08:41:01.750550]
The message "E [MSGID: 101027] [gfdb_sqlite3.c:542:gf_sqlite3_insert] 0-sqlite3: Failed wind insert" repeated 2903 times between [2015-10-29 08:39:01.798047] and [2015-10-29 08:41:01.750552]
The message "E [MSGID: 101130] [gfdb_data_store.c:387:insert_record] 0-gfdbdatastore: Insert/Update operation failed" repeated 2903 times between [2015-10-29 08:39:01.798062] and [2015-10-29 08:41:01.750553


[root@dhcp37-165 glusterfs]# grep "800:gf_sql_insert_wind" bricks/rhs-brick1-tiervolume_ct-disp1.log | wc -l 
2515
[root@dhcp37-165 glusterfs]# 


Version-Release number of selected component (if applicable):
=============================================================

glusterfs-3.7.5-0.3.el7rhgs.x86_64


Steps carried:
==============
1. 12 node cluster
2. Hot tier {6x2} , Cold tier {2x(4=2)}
3. Mounted the volume on 7.2,7.1 and 6.7 clients
4. Huge set of data is created on volume {148GB}
5. Stopped the volume {No data creation or IO was in progress at this time}
6. Started the volume
Comment 3 Joseph Elwin Fernandes 2015-11-03 01:19:56 EST
This is caused due to the lookup heal. Well CTR doesnt read from the DB, so to make sure that file records are created it does a heal during a lookup. It remembers the decision in the inode context cache and retrys periodically. When the volume is restarted it looses all the inode cache from the previous time and CTR lookup heals tries the heal again, but this time it finds that the records are already there from sql and logs this error, and remembers this until the volume is restarted or inode is flushed out of inode cache of the brick.

Solution: the log levels should be reduced to trace for this case and customers need not see this.
Comment 4 Vivek Agarwal 2015-11-03 01:22:15 EST
What is the default? Default should be, we do not see the logs. If more information is needed, then we setup the loglevel to see the additional logs.
Comment 5 Joseph Elwin Fernandes 2015-11-03 01:33:23 EST
Well any insert/update failure to the Db should be ERROR. But for this special case we should use TRACE.
Comment 6 Joseph Elwin Fernandes 2015-11-03 02:14:04 EST
Upstream patch posted : http://review.gluster.org/#/c/12491
Comment 8 Dan Lambright 2015-11-07 12:03:34 EST
Per RCA, the log message is not an error. The merged patch makes the behavior visible at the trace level.
Comment 9 nchilaka 2015-11-21 01:27:47 EST
this has not been put up in 3.7.5-6 as it has been moved to modified from on_qa by dev
Comment 10 Rahul Hinduja 2015-12-29 04:19:27 EST
Verified with build: glusterfs-3.7.5-13.el7rhgs.x86_64

No errors related to insert/update is observed on brick logs. Moving the bug to verified state. 

[root@dhcp37-165 glusterfs]# grep -ri "insert" *
[root@dhcp37-165 glusterfs]# 
[root@dhcp37-165 bricks]# grep -ri "insert" *
[root@dhcp37-165 bricks]#
Comment 12 errata-xmlrpc 2016-03-01 00:48:18 EST
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2016-0193.html

Note You need to log in before you can comment on or make changes to this bug.