Database hang or may fail to OPEN in 12c IBM AIX - ORA-742

Oracle 12c introduces a new default feature of using multiple LGWRs which may lead to DEADLOCK / Database Hang or ORA-742 "Log read detects lost write" or ORA-600 [kcrfrgv_nextlwn_scn] during instance OPEN or ORA-600 [krr_process_read_error_2] during Recovery on IBM AIX.

DEADLOCK or ORA-742 "Log read detects lost write" or ORA-600 [kcrfrgv_nextlwn_scn] during instance OPEN or ORA-600 [krr_process_read_error_2] during Recovery.

PMON may terminate the instance while extensive block recovery is being performed.

Please disable the new feature of multiple LGWR slave processes by proactively setting _use_single_log_writer=true.  This is a temporary recommendation for IBM AIX installations until a formal fix is identified for this problem.

Setting _use_single_log_writer = true is a safe workaround; it is the behavior before 12c where multiple LGWR slave groups were not available. 

ALTER SYSTEM SET "_use_single_log_writer"=TRUE SID='*' SCOPE=SPFILE;
-- Restart the database or all instances of the RAC database

Note that while _use_single_log_writer=true is not set, then error ORA-600 [kcrfrgv_nextlwn_scn] might be produced avoiding the database to OPEN.  Once the problem is introduced, _use_single_log_writer=true may or may not fix it. _use_single_log_writer = true prevents inconsistencies in the redo log to be introduced which causes that error. 

If the parameter does not help, because the problem was already introduced when _use_single_log_writer=true had not been proactively set, then Point in Time Recovery (PITR) or Flashback Database are the options to recover from this situation.  

Oracle FailSafe Security Setup Tool Must be Run With Administrative Privileges

If a user is not logged into an account with administrative privileges and they start the Oracle Services for MSCS Security Setup utility (FsSvrSec.bat) from the Windows Start menu, the utility executes and reports that it ran sucessfully, even though it did not actually succeed in changing the account or password for the OracleMSCSServices service. The Windows Application event log shows the following events (note that error 5 is ERROR_ACCESS_DENIED, "Access is denied"):

Failed to open Service Control Manager with error: 5
Unable to set the user account for OracleMSCSServices service.
Unable to open cluster on local node.
Failed to open cluster with error 0

Failed to register Oracle Services for MSCS server with error: 10007.
Failed to create NT registry key AppID\{239D150B-FA41-11D1-BF40-00805FE9145B} with error: 5
Unable to set RunAs for OracleMSCSServices DCOM component.

To successfully run the tool, it is necessary to login to an account that has administrative privileges, or the FsSvrSec.bat file must be started from an MS-DOS command prompt that has been started with the Run as administrator option selected.

https://docs.oracle.com/cd/E16161_01/doc.342/e14976/toc.htm#BAJIIIAI

MySQL innodb hotbackup (mysqlbackup) with table filtering

C:\Program Files\MySQL\MySQL Enterprise Backup 3.12>mysqlbackup.exe -u root -p --include-tables="^sakila.(actor|address)$" --with-timestamp --backup-dir=c:\mysql\backup backup

MySQL Enterprise Backup version 3.12.0 Windows-6.0-x86 [10.03.2015 ]
Copyright (c) 2003, 2015, Oracle and/or its affiliates. All Rights Reserved.

 mysqlbackup: INFO: Starting with following command line ...
 mysqlbackup.exe -u root -p --include-tables=^sakila.(actor|address)
        --with-timestamp --backup-dir=c:\mysql\backup backup

 mysqlbackup: INFO:
Enter password: ********
 mysqlbackup: INFO: MySQL server version is '5.6.25-enterprise-commercial-advanced-log'.
 mysqlbackup: INFO: Got some server configuration information from running server.

IMPORTANT: Please check that mysqlbackup run completes successfully.
           At the end of a successful 'backup' run mysqlbackup
           prints "mysqlbackup completed OK!".

150706 22:39:31 mysqlbackup: INFO: MEB logfile created at c:\mysql\backup\2015-07-06_22-39-31\meta\MEB_2015-07-06.22-39-31_backup.log

--------------------------------------------------------------------
                       Server Repository Options:
--------------------------------------------------------------------
  datadir = C:\ProgramData\MySQL\MySQL Server 5.6\Data\
  innodb_data_home_dir =
  innodb_data_file_path = ibdata1:12M:autoextend
  innodb_log_group_home_dir = C:\ProgramData\MySQL\MySQL Server 5.6\Data\
  innodb_log_files_in_group = 2
  innodb_log_file_size = 50331648
  innodb_page_size = 16384
  innodb_checksum_algorithm = crc32
  innodb_undo_directory = C:\ProgramData\MySQL\MySQL Server 5.6\Data\
  innodb_undo_tablespaces = 0
  innodb_undo_logs = 128

--------------------------------------------------------------------
                       Backup Config Options:
--------------------------------------------------------------------
  datadir = c:\mysql\backup\2015-07-06_22-39-31\datadir
  innodb_data_home_dir = c:\mysql\backup\2015-07-06_22-39-31\datadir
  innodb_data_file_path = ibdata1:12M:autoextend
  innodb_log_group_home_dir = c:\mysql\backup\2015-07-06_22-39-31\datadir
  innodb_log_files_in_group = 2
  innodb_log_file_size = 50331648
  innodb_page_size = 16384
  innodb_checksum_algorithm = crc32
  innodb_undo_directory = c:\mysql\backup\2015-07-06_22-39-31\datadir
  innodb_undo_tablespaces = 0
  innodb_undo_logs = 128

 mysqlbackup: INFO: Unique generated backup id for this is 14361935712403634

 mysqlbackup: INFO: Creating 14 buffers each of size 16777216.
150706 22:39:33 mysqlbackup: INFO: Full Backup operation starts with following threads
                1 read-threads    6 process-threads    1 write-threads
150706 22:39:33 mysqlbackup: INFO: System tablespace file format is Antelope.
150706 22:39:33 mysqlbackup: INFO: Starting to copy all innodb files...
150706 22:39:33 mysqlbackup: INFO: Found checkpoint at lsn 8424992.
150706 22:39:33 mysqlbackup: INFO: Copying C:\ProgramData\MySQL\MySQL Server 5.6\Data\ibdata1 (Antelope file format).
150706 22:39:33 mysqlbackup: INFO: Starting log scan from lsn 8424960.
150706 22:39:33 mysqlbackup: INFO: Copying log...
150706 22:39:33 mysqlbackup: INFO: Log copied, lsn 8424992.
150706 22:39:33 mysqlbackup: INFO: Copying C:\ProgramData\MySQL\MySQL Server 5.6\Data\sakila\actor.ibd (Antelope file format).
150706 22:39:33 mysqlbackup: INFO: Copying C:\ProgramData\MySQL\MySQL Server 5.6\Data\sakila\address.ibd (Antelope file format).
150706 22:39:33 mysqlbackup: INFO: Completing the copy of innodb files.
150706 22:39:33 mysqlbackup: INFO: Starting to copy Binlog files...
150706 22:39:33 mysqlbackup: INFO: Copying C:\ProgramData\MySQL\MySQL Server 5.6\Data\VMMDB01-bin.000001.
150706 22:39:33 mysqlbackup: INFO: Copying C:\ProgramData\MySQL\MySQL Server 5.6\Data\VMMDB01-bin.000003.
150706 22:39:33 mysqlbackup: INFO: Preparing to lock tables: Connected to mysqld server.
150706 22:39:33 mysqlbackup: INFO: Starting to lock all the tables...
150706 22:39:33 mysqlbackup: INFO: All tables are locked and flushed to disk
150706 22:39:33 mysqlbackup: INFO: Copying C:\ProgramData\MySQL\MySQL Server 5.6\Data\VMMDB01-bin.000004.
150706 22:39:34 mysqlbackup: INFO: Completed the copy of binlog files...
150706 22:39:34 mysqlbackup: INFO: Opening backup source directory 'C:\ProgramData\MySQL\MySQL Server 5.6\Data\'
150706 22:39:34 mysqlbackup: INFO: Starting to backup all non-innodb files in
        subdirectories of 'C:\ProgramData\MySQL\MySQL Server 5.6\Data\'
150706 22:39:34 mysqlbackup: INFO: Copying the database directory 'sakila'
150706 22:39:34 mysqlbackup: INFO: Completing the copy of all non-innodb files.
150706 22:39:35 mysqlbackup: INFO: A copied database page was modified at 8424992.
          (This is the highest lsn found on page)
          Scanned log up to lsn 8424992.
          Was able to parse the log up to lsn 8424992.
          Maximum page number for a log record 0
150706 22:39:35 mysqlbackup: INFO: All tables unlocked
150706 22:39:35 mysqlbackup: INFO: All MySQL tables were locked for 1.783 seconds.
150706 22:39:35 mysqlbackup: INFO: Reading all global variables from the server.
150706 22:39:35 mysqlbackup: INFO: Completed reading of all global variables from the server.
150706 22:39:35 mysqlbackup: INFO: Creating server config files server-my.cnf and server-all.cnf in c:\mysql\backup\2015-07-06_22-39-31
150706 22:39:35 mysqlbackup: INFO: Full Backup operation completed successfully.
150706 22:39:35 mysqlbackup: INFO: Backup created in directory 'c:\mysql\backup\2015-07-06_22-39-31'
150706 22:39:35 mysqlbackup: INFO: MySQL binlog position: filename VMMDB01-bin.000004, position 120

-------------------------------------------------------------
   Parameters Summary
-------------------------------------------------------------
   Start LSN                  : 8424960
   End LSN                    : 8424992
-------------------------------------------------------------

mysqlbackup completed OK!

## Before restoration, shutdown the MySQL instance.

C:\Program Files\MySQL\MySQL Enterprise Backup 3.12>mysqlbackup.exe --defaults-file="C:\MySQL\Backup\2015-07-06_22-40-55\server-my.cnf" --backup-dir=c:\mysql\backup\2015-07-06_22-40-55 copy-back-and-apply-log

MySQL Enterprise Backup version 3.12.0 Windows-6.0-x86 [10.03.2015 ]

Copyright (c) 2003, 2015, Oracle and/or its affiliates. All Rights Reserved.

 mysqlbackup: INFO: Starting with following command line ...

 mysqlbackup.exe

        --defaults-file=C:\MySQL\Backup\2015-07-06_22-40-55\server-my.cnf

        --backup-dir=c:\mysql\backup\2015-07-06_22-40-55

        copy-back-and-apply-log

 mysqlbackup: INFO:

IMPORTANT: Please check that mysqlbackup run completes successfully.

           At the end of a successful 'copy-back-and-apply-log' run mysqlbackup

           prints "mysqlbackup completed OK!".

150706 22:48:47 mysqlbackup: INFO: MEB logfile created at c:\mysql\backup\2015-07-06_22-40-55\meta\MEB_2015-07-06.22-48-47_copy_back_dir_to_datadir.log

--------------------------------------------------------------------

                       Server Repository Options:

--------------------------------------------------------------------

  datadir = C:\ProgramData\MySQL\MySQL Server 5.6\Data\

  innodb_data_home_dir = C:\ProgramData\MySQL\MySQL Server 5.6\Data\

  innodb_data_file_path = ibdata1:12M:autoextend

  innodb_log_group_home_dir = C:\ProgramData\MySQL\MySQL Server 5.6\Data\.\

  innodb_log_files_in_group = 2

  innodb_log_file_size = 50331648

  innodb_page_size = 16384

  innodb_checksum_algorithm = crc32

  innodb_undo_directory = C:\ProgramData\MySQL\MySQL Server 5.6\Data\

  innodb_undo_tablespaces = 0

  innodb_undo_logs = 128

--------------------------------------------------------------------

                       Backup Config Options:

--------------------------------------------------------------------

  datadir = c:\mysql\backup\2015-07-06_22-40-55\datadir

  innodb_data_home_dir = c:\mysql\backup\2015-07-06_22-40-55\datadir

  innodb_data_file_path = ibdata1:12M:autoextend

  innodb_log_group_home_dir = c:\mysql\backup\2015-07-06_22-40-55\datadir

  innodb_log_files_in_group = 2

  innodb_log_file_size = 50331648

  innodb_page_size = 16384

  innodb_checksum_algorithm = crc32

 mysqlbackup: INFO: Creating 14 buffers each of size 16777216.

150706 22:48:47 mysqlbackup: INFO: Copy-back-and-apply-log operation starts with following threads

                1 read-threads    1 write-threads

150706 22:48:47 mysqlbackup: INFO: Copying c:\mysql\backup\2015-07-06_22-40-55\datadir\ibdata1.

150706 22:48:47 mysqlbackup: INFO: Copying c:\mysql\backup\2015-07-06_22-40-55\datadir\sakila\actor.ibd.

150706 22:48:47 mysqlbackup: INFO: Copying c:\mysql\backup\2015-07-06_22-40-55\datadir\sakila\address.ibd.

150706 22:48:47 mysqlbackup: INFO: Starting to copy Binlog files...

150706 22:48:47 mysqlbackup: INFO: Copying c:\mysql\backup\2015-07-06_22-40-55\datadir\VMMDB01-bin.000001.

150706 22:48:47 mysqlbackup: INFO: Copying c:\mysql\backup\2015-07-06_22-40-55\datadir\VMMDB01-bin.000003.

150706 22:48:47 mysqlbackup: INFO: Copying c:\mysql\backup\2015-07-06_22-40-55\datadir\VMMDB01-bin.000004.

150706 22:48:48 mysqlbackup: INFO: Completed the copy of binlog files...

150706 22:48:48 mysqlbackup: INFO: Copying the database directory 'sakila'

150706 22:48:48 mysqlbackup: INFO: Completing the copy of all non-innodb files.

150706 22:48:48 mysqlbackup: INFO: Creating server config files server-my.cnf and server-all.cnf in C:\ProgramData\MySQL\MySQL Server 5.6\Data\

150706 22:48:48 mysqlbackup: INFO: Copy-back operation completed successfully.

 mysqlbackup: INFO: Creating 14 buffers each of size 65536.

150706 22:48:48 mysqlbackup: INFO: Apply-log operation starts with following threads

                1 read-threads    1 process-threads

 mysqlbackup: INFO: Using up to 100 MB of memory.

150706 22:48:48 mysqlbackup: INFO: ibbackup_logfile's creation parameters:

          start lsn 8424960, end lsn 8424992,

          start checkpoint 8424992.

 mysqlbackup: INFO: Backup was originally taken with the --include regexp option

InnoDB: Doing recovery: scanned up to log sequence number 8424992

 mysqlbackup: INFO: InnoDB: Starting an apply batch of log records to the database...

InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 5

0 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99

 mysqlbackup: INFO: InnoDB: Setting log file size to 50331648

 mysqlbackup: INFO: InnoDB: Setting log file size to 50331648

150706 22:48:50 mysqlbackup: INFO: We were able to parse ibbackup_logfile up to

          lsn 8424992.

 mysqlbackup: INFO: Last MySQL binlog file position 0 120, file name VMMDB01-bin.000004:120

150706 22:48:50 mysqlbackup: INFO: The first data file is 'C:\ProgramData\MySQL\MySQL Server 5.6\Data\ibdata1'

          and the new created log files are at 'C:/ProgramData/MySQL/MySQL Server 5.6/Data/./'

150706 22:48:50 mysqlbackup: INFO: Apply-log operation completed successfully.

150706 22:48:50 mysqlbackup: INFO: Full Backup has been restored successfully.

mysqlbackup completed OK!

Caused by error 2341: 'Internal program error (failed ndbrequire)(Internal error...

Symptom: (mysql-5.6.24 with ndb-7.4.6)


[mysql@localhost ndb_data]$ tail -10 ndb_11_out.log
2015-07-02 15:08:42 [ndbd] INFO     -- Grant nodes to start phase: 5, nodes: 0000000000001800
2015-07-02 15:08:42 [ndbd] INFO     -- NDB start phase 4 completed
2015-07-02 15:08:42 [ndbd] INFO     -- As master we will wait for other nodes to reach the state waitpoint52 as well
2015-07-02 15:08:42 [ndbd] INFO     -- Node 12 have reached completion of NDB start phase 4
2015-07-02 15:08:42 [ndbd] INFO     -- Start NDB start phase 5 (only to DBDIH)
2015-07-02 15:08:47 [ndbd] INFO     -- /export/home/pb2/build/sb_0-14878975-1427908966.28/mysql-cluster-com-7.4.6/storage/ndb/src/kernel/blocks/backup/Backup.cpp
2015-07-02 15:08:47 [ndbd] INFO     -- BACKUP (Line: 3846) 0x00000002
2015-07-02 15:08:47 [ndbd] INFO     -- Error handler shutting down system
2015-07-02 15:08:47 [ndbd] INFO     -- Error handler shutdown completed - exiting
2015-07-02 15:08:47 [ndbd] ALERT    -- Node 11: Forced node shutdown completed. Occured during startphase 5. Caused by error 2341: 'Internal program error (failed ndbrequire)(Internal error, programming error or missing error message, please report a bug). Temporary error, restart node'.



[mysql@localhost ndb_data]$ more ndb_11_error.log
Current byte-offset of file-pointer is: 1067

Time: Thursday 2 July 2015 - 15:08:47
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: Backup.cpp
Error object: BACKUP (Line: 3846) 0x00000002
Program: ndbd
Pid: 25840
Version: mysql-5.6.24 ndb-7.4.6
Trace: /var/local/mysql/server5-ndb/ndb_data/ndb_11_trace.log.2 [t1..t1]
***EOM***

Root Cause:

And I found it was caused by some files inside "datadir" not owned by "mysql" any more, it was changed to "root".
After change permission back to "mysql", this problem resolved. 

[mysql@localhost server2-ndb]$ find . -exec ls -l {} \; |grep root
-rw-r--r--. 1 root  root   1244 Jul  1 15:11 T52F0.Data
-rw-r--r--. 1 root  root   1244 Jul  1 15:11 T52F1.Data
-rw-r--r--. 1 root root 1244 Jul  1 15:11 ./ndb_data/ndb_11_fs/LCP/1/T52F1.Data
-rw-r--r--. 1 root root 1244 Jul  1 15:11 ./ndb_data/ndb_11_fs/LCP/1/T52F0.Data

http://bugs.mysql.com/bug.php?id=70217