cancel
Showing results forΒ 
Search instead forΒ 
Did you mean:Β 

Strange problem with Mysql agent

achebib
Level 4
Partner

Hi, I am facing a strange problem using mysql veritas agent.

My environment is the following one:

Infoscale 7 enterprise in redhat 6.5

VRTS agent for mysql: 7.0.0.0

ACClib : 6.2.0.0

After lot of debuggin process I have been able to check that when the online command runs launches the following command:

017/04/29 18:32:42 VCS DBG_5 MySQL:pis_mysql_res:online:Sys:RunWithEnvCmdWithOutputWithTimeOut:Now going to run complete command line [/bin/su mysql -c 'cd /usr ;/usr/bin/mysqld_safe --defaults-file=/etc/my_safe.cnf --datadir=/opt/mysql/pisdata --user=mysql ']

After some time the mysql resource remains trying to online but then fails.

The logs from mysql are the following ones:

2017-04-29T15:40:53.907388Z mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
2017-04-29T15:49:21.010321Z mysqld_safe Logging to '/var/log/mysqld.log'.
2017-04-29T15:49:21.057562Z mysqld_safe Starting mysqld daemon with databases from /opt/mysql/pisdata
mysqld: Can't change dir to '/opt/mysql/pisdata/' (Errcode: 13 - Permission denied)
2017-04-29T15:49:21.087284Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2017-04-29T15:49:21.087500Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
2017-04-29T15:49:21.262986Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-04-29T15:49:21.263827Z 0 [Warning] Can't create test file /opt/mysql/pisdata/msql01.lower-test
2017-04-29T15:49:21.263891Z 0 [Note] /usr/bin/mysqld (mysqld 5.7.17-enterprise-commercial-advanced) starting as process 24238 ...
2017-04-29T15:49:21.268310Z 0 [Warning] Can't create test file /opt/mysql/pisdata/msql01.lower-test
2017-04-29T15:49:21.268377Z 0 [Warning] Can't create test file /opt/mysql/pisdata/msql01.lower-test
2017-04-29T15:49:21.268532Z 0 [ERROR] failed to set datadir to /opt/mysql/pisdata/
2017-04-29T15:49:21.268571Z 0 [ERROR] Aborting

2017-04-29T15:49:21.268590Z 0 [Note] Binlog end
2017-04-29T15:49:21.268645Z 0 [Note] /usr/bin/mysqld: Shutdown complete

2017-04-29T15:49:21.278570Z mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

 

But the question is that if you manually run the command:

/bin/su mysql -c 'cd /usr ;/usr/bin/mysqld_safe --defaults-file=/etc/my_safe.cnf --datadir=/opt/mysql/pisdata --user=mysql '

Then the agent after some seconds is able to monitor the process and it becomes online and you can also offline...

You can also see the mysql process:

[root@msql01 pisdata]# ps -ef | grep mysql
root 11144 8805 0 17:18 pts/1 00:00:00 tail -f /var/log/mysqld.log
root 25302 22379 0 19:03 pts/3 00:00:00 /bin/su mysql -c cd /usr ;/usr/bin/mysqld_safe --defaults-file=/etc/my_safe.cnf --datadir=/opt/mysql/pisdata --user=mysql
mysql 25303 25302 0 19:03 ? 00:00:00 bash -c cd /usr ;/usr/bin/mysqld_safe --defaults-file=/etc/my_safe.cnf --datadir=/opt/mysql/pisdata --user=mysql
mysql 25304 25303 0 19:03 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --defaults-file=/etc/my_safe.cnf --datadir=/opt/mysql/pisdata --user=mysql
mysql 25524 25304 0 19:03 ? 00:00:00 /usr/bin/mysqld --defaults-file=/etc/my_safe.cnf --basedir=/usr --datadir=/opt/mysql/pisdata --plugin-dir=/usr/lib64/mysql/plugin --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
root 25908 22379 0 19:04 pts/3 00:00:00 grep mysql
[root@msql01 pisdata]#

Logs from mysql are the followin ones:

2017-04-29T16:03:44.092067Z mysqld_safe Logging to '/var/log/mysqld.log'.
2017-04-29T16:03:44.116049Z mysqld_safe Starting mysqld daemon with databases from /opt/mysql/pisdata
2017-04-29T16:03:44.129356Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2017-04-29T16:03:44.129450Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
2017-04-29T16:03:44.285109Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-04-29T16:03:44.286379Z 0 [Note] /usr/bin/mysqld (mysqld 5.7.17-enterprise-commercial-advanced) starting as process 25524 ...
2017-04-29T16:03:44.291727Z 0 [Note] InnoDB: PUNCH HOLE support available
2017-04-29T16:03:44.291769Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-04-29T16:03:44.291792Z 0 [Note] InnoDB: Uses event mutexes
2017-04-29T16:03:44.291834Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2017-04-29T16:03:44.291862Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-04-29T16:03:44.291885Z 0 [Note] InnoDB: Using Linux native AIO
2017-04-29T16:03:44.292210Z 0 [Note] InnoDB: Number of pools: 1
2017-04-29T16:03:44.292370Z 0 [Note] InnoDB: Using CPU crc32 instructions
2017-04-29T16:03:44.295888Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2017-04-29T16:03:44.306079Z 0 [Note] InnoDB: Completed initialization of buffer pool
2017-04-29T16:03:44.308436Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-04-29T16:03:44.333154Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2017-04-29T16:03:44.336576Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2535333
2017-04-29T16:03:44.336641Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 2535342
2017-04-29T16:03:44.337029Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 2535342
2017-04-29T16:03:44.337075Z 0 [Note] InnoDB: Database was not shutdown normally!
2017-04-29T16:03:44.337099Z 0 [Note] InnoDB: Starting crash recovery.
2017-04-29T16:03:44.452353Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-04-29T16:03:44.452432Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-04-29T16:03:44.452647Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-04-29T16:03:44.489842Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-04-29T16:03:44.491471Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2017-04-29T16:03:44.491532Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2017-04-29T16:03:44.493663Z 0 [Note] InnoDB: Waiting for purge to start
2017-04-29T16:03:44.544003Z 0 [Note] InnoDB: 5.7.17 started; log sequence number 2535342
2017-04-29T16:03:44.544409Z 0 [Note] InnoDB: Loading buffer pool(s) from /opt/mysql/pisdata/ib_buffer_pool
2017-04-29T16:03:44.544943Z 0 [Note] Plugin 'FEDERATED' is disabled.
2017-04-29T16:03:44.548719Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170429 19:03:44
2017-04-29T16:03:44.565873Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2017-04-29T16:03:44.565935Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2017-04-29T16:03:44.567544Z 0 [Warning] CA certificate ca.pem is self signed.
2017-04-29T16:03:44.567707Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2017-04-29T16:03:44.568616Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2017-04-29T16:03:44.585056Z 0 [Note] IPv6 is available.
2017-04-29T16:03:44.585109Z 0 [Note] - '::' resolves to '::';
2017-04-29T16:03:44.585157Z 0 [Note] Server socket created on IP: '::'.
2017-04-29T16:03:44.632961Z 0 [Note] Event Scheduler: Loaded 0 events
2017-04-29T16:03:44.633191Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check.
2017-04-29T16:03:44.633241Z 0 [Note] Beginning of list of non-natively partitioned tables
2017-04-29T16:03:44.666668Z 0 [Note] End of list of non-natively partitioned tables
2017-04-29T16:03:44.666889Z 0 [Note] /usr/bin/mysqld: ready for connections.
Version: '5.7.17-enterprise-commercial-advanced' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Enterprise Server - Advanced Edition (Commercial)

3 REPLIES 3

Mouse
Moderator
Moderator
Partner    VIP    Accredited Certified

This looks like the root cause: mysqld: Can't change dir to '/opt/mysql/pisdata/' (Errcode: 13 - Permission denied)

I'd guess something is not correct with permissions.

achebib
Level 4
Partner
Yes, I saw that issue, but why with command is not complaining about that? The path is correctly owned by mysql user [root@msql01 mysql]# ls -altr total 12 drwxr-xr-x. 30 root root 4096 Feb 12 15:29 .. drwxr-xr-x. 3 root root 4096 Feb 12 15:29 . drwxr-xr-x. 2 mysql mysql 4096 Apr 29 17:16 pisdata [root@msql01 mysql]# pwd /opt/mysql If it is due to an user problem in the Mysql configuration part for Mysql resource there is one attribute called MySQLUSer and it is mysql. I don't know why it is not showing in the configuration... MySQL pis_mysql_res ( MySQLAdminPasswd = GQKsMSlKKsOSoUImI BaseDir = "/usr" DataDir = "/opt/mysql/pisdata" HostName @msql01 = msql01 HostName @msql02 = msql02 )

Attached is the log file, if you see the complete command is when it says the following:

Now going to run complete command line [/bin/su mysql -c 'cd /usr ;/usr/bin/mysqld_safe --datadir=/opt/mysql/pisdata --user=mysql ']

 

If I run this command manually, database starts and resource becomes online after some time due to monitor scritp, but if I online with gui interface it does not work...

[root@msql01 ~]# /bin/su mysql -c 'cd /usr ;/usr/bin/mysqld_safe --datadir=/opt/mysql/pisdata --user=mysql ' &
[1] 30726
[root@msql01 ~]# 2017-05-09T09:32:05.442027Z mysqld_safe Logging to '/var/log/mysqld.log'.
2017-05-09T09:32:05.447169Z mysqld_safe Logging to '/var/log/mysqld.log'.
2017-05-09T09:32:05.490017Z mysqld_safe Starting mysqld daemon with databases from /opt/mysql/pisdata

 

[root@msql01 ~]# ps -fea | grep mysql
root 30726 28146 0 12:32 pts/0 00:00:00 /bin/su mysql -c cd /usr ;/usr/bin/mysqld_safe --datadir=/opt/mysql/pisdata --user=mysql
mysql 30727 30726 0 12:32 ? 00:00:00 bash -c cd /usr ;/usr/bin/mysqld_safe --datadir=/opt/mysql/pisdata --user=mysql
mysql 30728 30727 0 12:32 ? 00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir=/opt/mysql/pisdata --user=mysql
mysql 30898 30728 1 12:32 ? 00:00:00 /usr/bin/mysqld --basedir=/usr --datadir=/opt/mysql/pisdata --plugin-dir=/usr/lib64/mysql/plugin --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
root 30935 28146 0 12:32 pts/0 00:00:00 grep mysql
[root@msql01 ~]#