Bug #24664 Rare problem in LCP, can lead to unability to restart
Submitted: 28 Nov 2006 17:23 Modified: 28 Dec 2006 13:58
Reporter: Anatoly Pidruchny (Candidate Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Cluster: Cluster (NDB) storage engine Severity:S3 (Non-critical)
Version:5.1.12 OS:Linux (Linux x86_64)
Assigned to: Jonas Oreland CPU Architecture:Any

[28 Nov 2006 17:23] Anatoly Pidruchny
Description:
A data node fails to restart on a fairly loaded Cluster when it can not restore from a REDO log. Looks like it happens when the REDO log is overwritten on the other node. But then I expect a good error message, not an internal program error.

Below is the error log:

========== ndb_3_error.log ==========
Current byte-offset of file-pointer is: 568                       

Time: Tuesday 28 November 2006 - 09:12:17
Status: Temporary error, restart node
Message: Internal program error (failed ndbrequire) (Internal error, programming error or missing error message, please report a bug)
Error: 2341
Error data: restore.cpp
Error object: RESTORE (Line: 1154) 0x0000000a
Program: ndbd
Pid: 21924
Trace: /sm/mysql/ndb_data/ndb_3_trace.log.6
Version: Version 5.1.12 (beta)
***EOM***
========== ndb_3_error.log ==========

How to repeat:
Put 2-data node Cluster under test load, bring down one of the data nodes, wait for two local checkpoints to finish, then try to bring the data node back up.
[28 Nov 2006 17:23] Anatoly Pidruchny
Changed category to Cluster.
[28 Nov 2006 17:24] Anatoly Pidruchny
Cluster configuration file

Attachment: config.ini (application/octet-stream, text), 861 bytes.

[28 Nov 2006 17:26] Anatoly Pidruchny
trace log

Attachment: ndb_3_trace.log.6.gz (application/x-gzip, text), 31.28 KiB.

[28 Nov 2006 17:33] Anatoly Pidruchny
Data node output log

Attachment: ndb_3_out.log (application/octet-stream, text), 32.70 KiB.

[28 Nov 2006 17:41] Anatoly Pidruchny
Some info about the aborted ndbd process from GDB

Attachment: gdb.out.log (application/octet-stream, text), 10.43 KiB.

[28 Nov 2006 18:57] Jonas Oreland
Hi,

Is it possible for you to when this happens
1) shutdown rest of cluster (might not be necessary, but to be "safe")
2) upload entire filesystem (including config.ini)
   (to ftp.mysql.com is probably a good idea)

/Jonas
[29 Nov 2006 14:35] Anatoly Pidruchny
Hi, Jonas,

I have uploaded the file bug-data-24664.tgz into ftp://ftp.mysql.com/pub/mysql/upload. This is the entire filesystem from the data node 2 after the crash. Please let me know if this file is OK. I am not sure if the full file has been uploaded. The config.ini file is already attached to this bug report.

/Anatoly
[1 Dec 2006 5:44] Anatoly Pidruchny
Hi, Jonas,

did you have a chance to take a look at this one?
I suspect that not the full data file bug-data-24664.tgz has been uploaded, but I can not check. The length of the file should be 211,244,711 bytes. Please let me know if the file was uploaded fully or partially. If partially then I will try to upload it again.

Thanks,

/Anatoly
[1 Dec 2006 7:37] Jonas Oreland
Hi

It looks like it's ok.
shell> ls -l bug-data-24664.tgz 
--w-rw----  1 ftpuploads myftp 211244711 Nov 29 15:27 bug-data-24664.tgz

shell> md5sum bug-data-24664.tgz
8bc7afb3701debb5a10586464a649c23  bug-data-24664.tgz
joreland@production:/supportftp/pub/mysql/upload> 

And I havent had time to look at it yet...

/Jonas
[4 Dec 2006 9:14] Jonas Oreland
Hi again,

Now actually started on this...
And I really wanted fs for both ndbd's 
Is this possible?

/Jonas
[4 Dec 2006 14:43] Anatoly Pidruchny
Hi, Jonas,

I have just re-produced the problem. I can send you the filesystems of the both data nodes 2 and 3. But it would take several days to upload them. The previous time when I uploaded the filesystem of node 2, it took about 18 hours. Can I remove some files from the filesystems before ziping?

1. I assume that you do not need the BACKUP directory.
2. ndb_2_signal.log is 1474225452 bytes and ndb_3_signal.log is 845740759 bytes. Do you need these files?
3. ndb_2_out.log is 264316175 bytes and ndb_3_out.log is 169104261 bytes. Do you need these files as they are? Can I cut history from these files and send you only some number of last lines?
4. On the filesystem of node 3 there is a core file core.17582, 103632896 bytes. Do you need this file? I think if you need it, then you also need the ndbd executable file that I am running, right?

/Anatoly
[4 Dec 2006 14:46] Jonas Oreland
Hi,

18h puhh...

Anyway I only need the config.ini + the content of FileSystemPath

shell> ls -l ../../ndb_2_fs/
drwxr-x--- 4 jonas users 96 Dec  4 15:15 D1/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 D10/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 D11/
drwxr-x--- 4 jonas users 96 Dec  4 15:15 D2/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 D8/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 D9/
drwxr-x--- 3 jonas users 72 Dec  4 15:15 LCP/

I.e. the actual filesystem...
Is that possible to upload ?

/Jonas
[4 Dec 2006 15:24] Anatoly Pidruchny
Jonas,

I am going to upload the following two files:

-rw-r--r--  1 apidruch games 340336991 Dec  4 10:19 bug_24664_ndb_2_fs.tgz
-rw-r--r--  1 apidruch games 342450453 Dec  4 10:20 bug_24664_ndb_3_fs.tgz

They are the filesystems of data nodes 2 and 3. The config.ini file is already attached to this bug report.

/Anatoly
[4 Dec 2006 20:53] Anatoly Pidruchny
Jonas,

can we use any other way to send the big files to you? Looks like the MySQL FTP service limits upload speed to less then 3K per second per FTP session. I tried to upload the files bug_24664_ndb_2_fs.tgz and bug_24664_ndb_3_fs.tgz. My FTP client estimated completion time to more then 31 hours. So, I canceled the uploads, then split the files into smaller 30M parts. I tried to upload the following files in parallel:
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.001
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.002
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.003
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.004
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.005
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.006
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.007
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.008
12/04/2006  11:45 AM        31,457,280 bug_24664_ndb_2_fs.tgz.009
12/04/2006  11:46 AM        31,457,280 bug_24664_ndb_2_fs.tgz.010
12/04/2006  11:46 AM        25,764,191 bug_24664_ndb_2_fs.tgz.011

Only the last part was uploaded successfully, all other files failed to upload after more then 90% was uploaded, because something happened and all FTP upload sessions failed. I think it is MySQL FTP server to blame. Now I can not re-start the upload of these files again, because probably parts of these files already exist on the server and FTP server does not allow to overwrite them.

I can send the files by email, I can upload them to some other FTP server (e.g., megaupload.com), I can send files using "Send File" command in a messenger, whatever works for you. I can also try to upload them again. But then please clean the files that were uploaded partially. These are the files bug_24664_ndb_2_fs.tgz.001 to bug_24664_ndb_2_fs.tgz.010, and also bug_24664_ndb_3_fs.tgz.003 and bug_24664_ndb_3_fs.tgz.005.

/Anatoly
[4 Dec 2006 21:52] Jonas Oreland
Hi,

any "ftp"-site that works for you works for me.

I never used megaupload.com, but if you think it will work, then let's try it...

/Jonas

ps. I removed the files from our ftp-site. ds.
[4 Dec 2006 23:49] Anatoly Pidruchny
Jonas,

by using a better FTP client I was able to upload both files to MySQL FTP server. Please delete any part files if still remaining. The MD5 checksums of the uploaded files are:

bug_24664_ndb_2_fs.tgz 5DF851324A5B67E9699BC3E7A15F6B58
bug_24664_ndb_3_fs.tgz B6AF999DB4C2F13E862FF95AA8261B79

/Anatoly
[5 Dec 2006 11:16] Jonas Oreland
Hi,

Thx for files.

FYI: making progress...it looks like I made a thinking error 
     and only enabled the lcp-snapshot for DD tables, which
     is very incorrect...or actually either way...
     will look more, expect to have patch quite soon...

BTW: Thx again for brilliant bug reports, and lots of help

/Jonas
[5 Dec 2006 11:46] Jonas Oreland
Now have "semi" reproducable testcase...
(using error inserts...)

Quite tricky to write test prg for this...

/Jonas
[5 Dec 2006 14:11] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/16456

ChangeSet@1.2343, 2006-12-05 15:10:56+01:00, jonas@perch.ndb.mysql.com +7 -0
  ndb - bug#24664
    1) run lcp snapshot for both MM and DD tables (so I dont have to change restore to use WRITE)
    2) fix >= and > bug in lcp skip/keep handling
    3) very cool test prog for this :-)
[5 Dec 2006 14:16] Jonas Oreland
Hi,

I now think I fixed it.

Could you test patch attached to bug report.
It's only the "dbtup/*"-part which is actual fix
rest is new debug code to be able to trigger bug...

Let me know how it goes

/Jonas

and again, thx for all help
[5 Dec 2006 17:49] Anatoly Pidruchny
Hi, Jonas.

I wanted to do a rolling upgrade of the two data nodes without bringing down the cluster. So I shut down node 2, then upgraded the software, then tried to start node 2 with "ndbd --initial --core". It crashed during startup on Phase 5. Here is the error log:

Current byte-offset of file-pointer is: 568                       

Time: Tuesday 5 December 2006 - 12:29:58
Status: Temporary error, restart node
Message: Internal program error (failed ndbrequire) (Internal error, programming error or missing error message, please report a bug)
Error: 2341
Error data: dbtup/DbtupScan.cpp
Error object: DBTUP (Line: 1064) 0x0000000e
Program: ndbd
Pid: 8621
Trace: /sm/mysql/ndb_data/ndb_2_trace.log.1
Version: Version 5.1.12 (beta)
***EOM***

It crashed on the ndbrequire that was added by your patch for this bug. I think I am missing some other patch. The thing is, the following change was rejected by the "patch -p1" command:

***************
*** 1052,1075 ****
    tablePtr.i = req->tableId;
    ptrCheckGuard(tablePtr, cnoOfTablerec, tablerec);
  
-   if(tablePtr.p->m_no_of_disk_attributes)
-   {
-     jam();
-     FragrecordPtr fragPtr;
-     Uint32 fragId = req->fragmentId;
-     fragPtr.i = RNIL;
-     getFragmentrec(fragPtr, fragId, tablePtr.p);
-     ndbrequire(fragPtr.i != RNIL);
-     Fragrecord& frag = *fragPtr.p;
-     
-     ndbrequire(frag.m_lcp_scan_op == RNIL && c_lcp_scan_op != RNIL);
-     frag.m_lcp_scan_op = c_lcp_scan_op;
-     ScanOpPtr scanPtr;
-     c_scanOpPool.getPtr(scanPtr, frag.m_lcp_scan_op);
-     ndbrequire(scanPtr.p->m_fragPtrI == RNIL);
-     scanPtr.p->m_fragPtrI = fragPtr.i;
-     
-     scanFirst(signal, scanPtr);
-     scanPtr.p->m_state = ScanOp::First;
-   }
  }
--- 1051,1071 ----
    tablePtr.i = req->tableId;
    ptrCheckGuard(tablePtr, cnoOfTablerec, tablerec);
  
+   jam();
+   FragrecordPtr fragPtr;
+   Uint32 fragId = req->fragmentId;
+   fragPtr.i = RNIL;
+   getFragmentrec(fragPtr, fragId, tablePtr.p);
+   ndbrequire(fragPtr.i != RNIL);
+   Fragrecord& frag = *fragPtr.p;
+   
+   ndbrequire(frag.m_lcp_scan_op == RNIL && c_lcp_scan_op != RNIL);
+   frag.m_lcp_scan_op = c_lcp_scan_op;
+   ScanOpPtr scanPtr;
+   c_scanOpPool.getPtr(scanPtr, frag.m_lcp_scan_op);
+   ndbrequire(scanPtr.p->m_fragPtrI == RNIL);
+   scanPtr.p->m_fragPtrI = fragPtr.i;
+   
+   scanFirst(signal, scanPtr);
+   scanPtr.p->m_state = ScanOp::First;
  }

So, I applied these changes manually. The reason this change was rejected is because in the original file version that I had this last ndbrequire was commented out, like this:

    //ndbrequire(scanPtr.p->m_fragPtrI == fragPtr.i); ?

The file storage/ndb/src/kernel/blocks/dbtup/DbtupScan.cpp that I had is the file that goes in MySQL version 5.1.12, you can see what I mean if you look at that version of the file.

What do you want me to do now? Should I apply some more patch(es)?

/Anatoly
[5 Dec 2006 18:16] Jonas Oreland
Hi,

Apply pathc to bug http://bugs.mysql.com/bug.php?id=24331 before
applying this patch...

/Jonas
[5 Dec 2006 18:43] Anatoly Pidruchny
Jonas,

I applied that patch for bug 24331 as well. I stopped node 2, upgraded the NDB software, then tried to start the node just with "ndbd --core". It crashed during startup phase 4. Here is the error log:
Current byte-offset of file-pointer is: 568                       

Time: Tuesday 5 December 2006 - 13:34:04
Status: Temporary error, restart node
Message: Internal program error (failed ndbrequire) (Internal error, programming error or missing error message, please report a bug)
Error: 2341
Error data: restore.cpp
Error object: RESTORE (Line: 1154) 0x0000000a
Program: ndbd
Pid: 8744
Trace: /sm/mysql/ndb_data/ndb_2_trace.log.1
Version: Version 5.1.12 (beta)
***EOM***

The other data node 3 is still running without these patches applied and I do not want to shut down the whole cluster. I can give you more information about this crash if you want. Now I am going to try to start the node 2 with "--initial --core".

/Anatoly.
[5 Dec 2006 18:55] Jonas Oreland
Hi,

The patch fixes writing of LCP...
So it's expected that you need to start node "--initial"

Sorry for not mentioning this...

/Jonas
[5 Dec 2006 20:32] Anatoly Pidruchny
Jonas,

I think I can confirm now that your patch fixes the problem! After the rolling restart of my data nodes with --initial, I tested several times the shutdown and restart of the data nodes without --initial, and there were no crashes. Thank you very much for the great job that you are doing!

/Anatoly
[5 Dec 2006 22:21] Jonas Oreland
pushed into 5.1-new-ndb
[11 Dec 2006 15:19] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/16777

ChangeSet@1.2352, 2006-12-11 16:18:34+01:00, jonas@perch.ndb.mysql.com +1 -0
  ndb - bug#24664
    Fix in bug fix, make sure LCP_SKIP is only used for inserts...
[20 Dec 2006 9:12] Jonas Oreland
Fixed bug
[28 Dec 2006 13:58] Jon Stephens
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Documented fix in 5.1.15 changelog.