[Akonadi] [Bug 334420] New: Different behavior when starting mysqld via command line and crash/do not start after doing same via akonadi

Tue May 6 15:58:19 BST 2014

https://bugs.kde.org/show_bug.cgi?id=334420

            Bug ID: 334420
           Summary: Different behavior when starting mysqld via command
                    line and crash/do not start after doing same via
                    akonadi
    Classification: Unclassified
           Product: Akonadi
           Version: 4.13
          Platform: openSUSE RPMs
                OS: Linux
            Status: UNCONFIRMED
          Severity: critical
          Priority: NOR
         Component: server
          Assignee: kdepim-bugs at kde.org
          Reporter: peter.fodrek at stuba.sk

When staring mysqld 
via
 /usr/sbin/mysqld --defaults-file=/home/peto/.local/share/akonadi/mysql.conf
--datadir=/home/peto/.local/share/akonadi/db_data/
--socket=/tmp/akonadi-petoMOJ/mysql.socket 

is mysqld straed as single process and
I reached mysql.err as of

140506 14:34:49 InnoDB: The InnoDB memory heap is disabled
140506 14:34:49 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140506 14:34:49 InnoDB: Compressed tables use zlib 1.2.8
140506 14:34:49 InnoDB: Using Linux native AIO
140506 14:34:49 InnoDB: Initializing buffer pool, size = 128.0M
140506 14:34:49 InnoDB: Completed initialization of buffer pool
140506 14:34:49 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 815629381135
140506 14:34:49  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 815629381247
140506 14:34:49  InnoDB: Starting an apply batch of log records to the
database...
InnoDB: Progress in percents: 44 45 46 47 48 49 50 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 
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 634, file name ./mysql-bin.000331
140506 14:34:50  InnoDB: Waiting for the background threads to start
140506 14:34:51 Percona XtraDB (http://www.percona.com) 5.5.33-MariaDB-31.1
started; log sequence number 815629381247
140506 14:34:51 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.33-MariaDB-log'  socket: '/tmp/akonadi-petoMOJ/mysql.socket' 
port: 0  openSUSE package
140506 14:39:13 [Note] /usr/sbin/mysqld: Normal shutdown

140506 14:39:13  InnoDB: Starting shutdown...
140506 14:39:14  InnoDB: Shutdown completed; log sequence number 815629381247
140506 14:39:14 [Note] /usr/sbin/mysqld: Shutdown complete

or

140506 14:34:49 InnoDB: The InnoDB memory heap is disabled
140506 14:34:49 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140506 14:34:49 InnoDB: Compresse
devtmpfs        1.9G  8.0K  1.9G   1% /dev
tmpfs           2.0G   88K  2.0G   1% /dev/shm
tmpfs           2.0G  3.7M  2.0G   1% /run                                      
tmpfs           2.0G     0  2.0G   0% /sys/fs/cgroup                           

                                                                             d
tables use zlib 1.2.8
140506 14:34:49 InnoDB: Using Linux native AIO
140506 14:34:49 InnoDB: Initializing buffer pool, size = 128.0M
140506 14:34:49 InnoDB: Completed initialization of buffer pool
140506 14:34:49 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 815629381135
140506 14:34:49  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 815629381247
140506 14:34:49  InnoDB: Starting an apply batch of log records to the
database...
InnoDB: Progress in percents: 44 45 46 47 48 49 50 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 
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 634, file name ./mysql-bin.000331
140506 14:34:50  InnoDB: Waiting for the background threads to start
140506 14:34:51 Percona XtraDB (http://www.percona.com) 5.5.33-MariaDB-31.1
started; log sequence number 815629381247
140506 14:34:51 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.33-MariaDB-log'  socket: '/tmp/akonadi-petoMOJ/mysql.socket' 
port: 0  openSUSE package
140506 14:39:13 [Note] /usr/sbin/mysqld: Normal shutdown

140506 14:39:13  InnoDB: Starting shutdown...
140506 14:39:14  InnoDB: Shutdown completed; log sequence number 815629381247
140506 14:39:14 [Note] /usr/sbin/mysqld: Shutdown complete

140506 14:40:27 InnoDB: The InnoDB memory heap is disabled
140506 14:40:27 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140506 14:40:27 InnoDB: Compressed tables use zlib 1.2.8
140506 14:40:27 InnoDB: Using Linux native AIO
140506 14:40:27 InnoDB: Initializing buffer pool, size = 128.0M
140506 14:40:27 InnoDB: Completed initialization of buffer pool
140506 14:40:27 InnoDB: highest supported file format is Barracuda.
140506 14:40:27  InnoDB: Waiting for the background threads to start
140506 14:40:28 Percona XtraDB (http://www.percona.com) 5.5.33-MariaDB-31.1
started; log sequence number 815629381247
140506 14:40:28 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.33-MariaDB-log'  socket: '/tmp/akonadi-petoMOJ/mysql.socket' 
port: 0  openSUSE package
140506 14:40:35 [Note] /usr/sbin/mysqld: Normal shutdown

140506 14:40:35  InnoDB: Starting shutdown...
140506 14:40:36  InnoDB: Shutdown completed; log sequence number 815629381247
140506 14:40:36 [Note] /usr/sbin/mysqld: Shutdown complete

But when started akonadi i got four mysqld processes and mysql.err as of

140506 14:43:46 InnoDB: The InnoDB memory heap is disabled
140506 14:43:46 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140506 14:43:46 InnoDB: Compressed tables use zlib 1.2.8
140506 14:43:46 InnoDB: Using Linux native AIO
140506 14:43:46  InnoDB: Warning: io_setup() failed with EAGAIN. Will make 5
attempts before giving up.
InnoDB: Warning: io_setup() attempt 1 failed.
InnoDB: Warning: io_setup() attempt 2 failed.
InnoDB: Warning: io_setup() attempt 3 failed.
InnoDB: Warning: io_setup() attempt 4 failed.
InnoDB: Warning: io_setup() attempt 5 failed.
140506 14:43:48  InnoDB: Error: io_setup() failed with EAGAIN after 5 attempts.
InnoDB: You can disable Linux Native AIO by setting innodb_use_native_aio = 0
in my.cnf
  InnoDB: Warning: Linux Native AIO disabled because
os_aio_linux_create_io_ctx() failed. To get rid of this warning you can try
increasing system fs.aio-max-nr to 1048576 or larger or setting
innodb_use_native_aio = 0 in my.cnf
140506 14:43:48 InnoDB: Initializing buffer pool, size = 128.0M
140506 14:43:48 InnoDB: Completed initialization of buffer pool
InnoDB: Unable to lock ./ibdata1, error: 11
InnoDB: Check that you do not already have another mysqld process
InnoDB: using the same InnoDB data or log files.
140506 14:43:48  InnoDB: Retrying to lock the first data file
InnoDB: Unable to lock ./ibdata1, error: 11
.................................
InnoDB: using the same InnoDB data or log files.
140506 14:45:28  InnoDB: Unable to open the first data file
InnoDB: Error in opening ./ibdata1
140506 14:45:28  InnoDB: Operating system error number 11 in a file operation.
InnoDB: Error number 11 means 'Resource temporarily unavailable'.
InnoDB: Some operating system error numbers are described at
InnoDB:
http://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
140506 14:45:28 InnoDB: Could not open or create data files.
140506 14:45:28 InnoDB: If you tried to add new data files, and it failed here,
140506 14:45:28 InnoDB: you should now edit innodb_data_file_path in my.cnf
back
140506 14:45:28 InnoDB: to what it was, and remove the new ibdata files InnoDB
created
140506 14:45:28 InnoDB: in this failed attempt. InnoDB only wrote those files
full of
140506 14:45:28 InnoDB: zeros, but did not yet use them in any way. But be
careful: do not
140506 14:45:28 InnoDB: remove old data files which contain your precious data!
140506 14:45:28 [ERROR] Plugin 'InnoDB' init function returned error.
140506 14:45:28 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE
failed.
140506 14:45:28 [ERROR] mysqld: Can't lock aria control file
'/home/peto/.local/share/akonadi/db_data/aria_log_control' for exclusive use,
error: 11. Will retry for 30 seconds
140506 14:45:59 [ERROR] mysqld: Got error 'Could not get an exclusive lock;
file is probably in use by another process' when trying to use aria control
file '/home/peto/.local/share/akonadi/db_data/aria_log_control'
140506 14:45:59 [ERROR] Plugin 'Aria' init function returned error.
140506 14:45:59 [ERROR] Plugin 'Aria' registration as a STORAGE ENGINE failed.
140506 14:45:59 [ERROR] Unknown/unsupported storage engine: InnoDB
140506 14:45:59 [ERROR] Aborting

140506 14:45:59 [Note] /usr/sbin/mysqld: Shutdown complete

It seems to be coincidence between mysqld/mariadb instances

And i see unstandard output of
>pwd
/home/peto/.local/share/akonadi/db_data

and
> ls -lah
258M May  6 16:06 ibdata1
113G May  6 16:06 mysql.full

for personal email database as well
and 
>df -h

/dev/sda6        39G   26G   12G  69% /
/dev/sda9       494M  310M  149M  68% /boot
/dev/sda7        18G   17G  1.3G  93% /usr/src
/dev/sda10      136G  128G  1.2G 100% /home
/dev/sda8       3.9G  2.4G  1.6G  61% /var
/dev/sda1        29G  5.5G   24G  20% /tmp

-- 
You are receiving this mail because:
You are the assignee for the bug.