[MDEV-5287] pidfile has been removed after call mysqld -V Created: 2013-11-13  Updated: 2014-08-16  Resolved: 2014-08-16

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 5.5.33a
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: massimo disaro Assignee: Elena Stepanova
Resolution: Fixed Votes: 0
Labels: None
Environment:

version is 5.5.27


Attachments: File my.cnf.copy    

 Description   

we got maria install in many servers so we try to reproduce in test environment and it works :

uname -a
Linux siucidmdbsb2 2.6.32-279.14.1.el6.x86_64 #1 SMP Mon Oct 15 13:44:51 EDT 2012 x86_64 x86_64 x86_64 GNU/Linux
[mysql@siucidmdbsb2 INT db]$ ls -la
total 170080
drwxr-x--- 6 mysql mysql      4096 Nov 13 14:44 .
drwxr-xr-x 4 root  root       4096 Dec 18  2012 ..
-rw-rw---- 1 mysql mysql     16384 Nov  7 10:48 aria_log.00000001
-rw-rw---- 1 mysql mysql        52 Nov  7 10:48 aria_log_control
-rw-rw---- 1 mysql mysql 163577856 Nov 13 14:41 ibdata1
-rw-rw---- 1 mysql mysql   5242880 Nov 13 14:41 ib_logfile0
-rw-rw---- 1 mysql mysql   5242880 Nov 12 13:48 ib_logfile1
-rw-rw---- 1 mysql mysql     16384 Aug 12 16:15 ib_lru_dump
drwx------ 2 mysql mysql     12288 Oct  2 17:03 jbilling
-rw-rw---- 1 mysql mysql       109 Nov 13 14:41 master.info
drwx------ 2 mysql mysql      4096 Mar 13  2013 mysql
drwx------ 2 mysql mysql     20480 Nov 12 10:39 nevisidm
drwx------ 2 mysql mysql      4096 Mar 13  2013 performance_schema
-rw-rw-r-- 1 mysql mysql         5 Nov 13 14:44 siucidmdbsb2.pid
[mysql@siucidmdbsb2 INT db]$ mysqld -V
mysqld  Ver 5.5.27-MariaDB-log for Linux on x86_64 (MariaDB Server)
[mysql@siucidmdbsb2 INT db]$ ls -la
total 170076
drwxr-x--- 6 mysql mysql      4096 Nov 13 14:44 .
drwxr-xr-x 4 root  root       4096 Dec 18  2012 ..
-rw-rw---- 1 mysql mysql     16384 Nov  7 10:48 aria_log.00000001
-rw-rw---- 1 mysql mysql        52 Nov  7 10:48 aria_log_control
-rw-rw---- 1 mysql mysql 163577856 Nov 13 14:41 ibdata1
-rw-rw---- 1 mysql mysql   5242880 Nov 13 14:41 ib_logfile0
-rw-rw---- 1 mysql mysql   5242880 Nov 12 13:48 ib_logfile1
-rw-rw---- 1 mysql mysql     16384 Aug 12 16:15 ib_lru_dump
drwx------ 2 mysql mysql     12288 Oct  2 17:03 jbilling
-rw-rw---- 1 mysql mysql       109 Nov 13 14:41 master.info
drwx------ 2 mysql mysql      4096 Mar 13  2013 mysql
drwx------ 2 mysql mysql     20480 Nov 12 10:39 nevisidm
drwx------ 2 mysql mysql      4096 Mar 13  2013 performance_schema

So as u can see pidfile has been removed also with mysqld --help same results.
we use DTRACE and we see this:

unlink("/data/mariadb/db/siucidmdbsb2.pid") = 0
write(1, "mysqld  Ver 5.5.27-MariaDB-log f"..., 68) = 68

installation is by RPM by puppet



 Comments   
Comment by massimo disaro [ 2013-11-13 ]

this is info has been ask to update from IRC

$ which mysqld
/usr/sbin/mysqld

$ ls -al /usr/sbin/mysqld
-rwxr-xr-x 1 root root 13845453 Sep 6 2012 /usr/sbin/mysqld

$ file /usr/sbin/mysqld
/usr/sbin/mysqld: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), dynamically linked (uses shared libs), for GNU/Linux 2.6.18, not stripped

Comment by Elena Stepanova [ 2013-11-15 ]

Hi,

I couldn't reproduce the problem so far, neither does dtrace show unlink for me in this situation (it does when the server is shutdown).
There are some strange things though in your paste.
For one, on some reason your master.info file is considerably older than the pid file. This is weird, as if some other process created the pid file afterwards.
Besides, there is master.info but no relay log info. Also, there is ib_lru_dump file there (although old), where did it come from?

Could you please do the following:

  • restart mysql server;
  • wait a minute
  • run sudo ps -ef | grep mysqld (or whatever shows all mysqld processes on your system);
  • run ls -la /data/mariadb/db/
  • wait a minute
  • run mysqld -V
  • wait a minute
  • again run ls -la /data/mariadb/db/
  • again run sudo ps -ef | grep mysqld

paste all output, also attach the error log file from at least the last server start and up to the end (remember, you just restarted the server, so the startup should be just a few minutes ago), and also all your cnf files.

Thanks!

Comment by massimo disaro [ 2013-11-18 ]

Hi Elena,

i am going to do what u ask me very soon, in the meanwhile :

> For one, on some reason your master.info file is considerably older than the pid file.
because we reproduce and reproduce again the bug, as soon as we saw that the pid has been delete at the first time we recreated and see that happend again. We just want to avoid sent a bug report and wasting your time, that s why master.info is older than pid file

> Besides, there is master.info but no relay log info.
Well we want to use maria as fast as possible so log file (binary and relay) are in another follder. pretty simple, nobody ask me to report the list of file there.

>Also, there is ib_lru_dump file there (although old), where did it come from?
we did a warm up manual server long time ago. I dont see the point that is there and why should be an issue, But yes, is there because once we create and use it.

I will provide the rest u ask ASAP.

Comment by massimo disaro [ 2013-11-19 ]

Could you please DO the following:

  • restart mysql SERVER;
    DONE
  • WAIT a MINUTE
    done
  • run sudo ps -ef | grep mysqld (OR whatever shows ALL mysqld processes ON your system);

[tgddimaa@siucidmdbsb2 INT ~]$ ps aux | grep mysql
root 2327 0.0 0.0 106228 1416 pts/0 S 14:25 0:00 /bin/sh /usr/bin/mysqld_safe --datadir=/data/mariadb/db --pid-file=/data/mariadb/db/siucidmdbsb2.pid
mysql 3020 0.3 1.6 1574648 137000 pts/0 Sl 14:25 0:00 /usr/sbin/mysqld --basedir=/usr --datadir=/data/mariadb/db --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/data/log/mariadb/mariadb-error.log --pid-file=/data/mariadb/db/siucidmdbsb2.pid --socket=/var/lib/mysql/mysql.sock

  • run ls -la /data/mariadb/db/

[mysql@siucidmdbsb2 INT db]$ ls -la
total 170084
drwxr-X--- 6 mysql mysql 4096 Nov 19 14:26 .
drwxr-xr-X 4 root root 4096 DEC 18 2012 ..
rw-rw--- 1 mysql mysql 16384 Nov 19 14:25 aria_log.00000001
rw-rw--- 1 mysql mysql 52 Nov 19 14:25 aria_log_control
rw-rw--- 1 mysql mysql 163577856 Nov 19 14:28 ibdata1
rw-rw--- 1 mysql mysql 5242880 Nov 19 14:28 ib_logfile0
rw-rw--- 1 mysql mysql 5242880 Nov 19 14:28 ib_logfile1
rw-rw--- 1 mysql mysql 16384 Aug 12 16:15 ib_lru_dump
drwx------ 2 mysql mysql 12288 OCT 2 17:03 jbilling
rw-rw--- 1 mysql mysql 109 Nov 19 14:28 master.info
drwx------ 2 mysql mysql 4096 Mar 13 2013 mysql
drwx------ 2 mysql mysql 20480 Nov 18 15:50 nevisidm
drwx------ 2 mysql mysql 4096 Mar 13 2013 performance_schema
rw-rw--- 1 mysql mysql 5 Nov 19 14:26 siucidmdbsb2.pid

PLUS
[mysql@siucidmdbsb2 INT mariadb]$ ls -la
total 253216
drwxr-X--- 2 mysql mysql 4096 Nov 19 14:26 .
drwxr-xr-X 4 root root 4096 DEC 18 2012 ..
rw-rr- 1 root root 838 Aug 12 16:16 check_status_mail.log
rw-rr- 1 root root 8161052 Nov 19 14:28 check_status.sh.log
rw-rr- 1 root root 68 Aug 12 16:19 in_mail.txt
rw-rw--- 1 mysql mysql 2400909 Nov 19 14:26 mariadb-error.log
rw-rw--- 1 mysql mysql 104858042 Nov 11 11:22 mysql-bin.000022
rw-rw--- 1 mysql mysql 104857938 Nov 11 15:59 mysql-bin.000023
rw-rw--- 1 mysql mysql 25129789 Nov 13 15:06 mysql-bin.000024
rw-rw--- 1 mysql mysql 2477630 Nov 14 14:50 mysql-bin.000025
rw-rw--- 1 mysql mysql 11324150 Nov 19 14:25 mysql-bin.000026
rw-rw--- 1 mysql mysql 2027 Nov 19 14:28 mysql-bin.000027
rw-rw--- 1 mysql mysql 210 Nov 19 14:26 mysql-bin.log.index
rw-rw--- 1 mysql mysql 294 Nov 19 14:26 mysql-relay-bin.000154
rw-rw--- 1 mysql mysql 2350 Nov 19 14:28 mysql-relay-bin.000155
rw-rw--- 1 mysql mysql 82 Nov 19 14:26 mysql-relay-bin.index
rw-rw--- 1 mysql mysql 78 Nov 19 14:28 relay-log.info

  • WAIT a MINUTE
    DONE
  • run mysqld -V

[mysql@siucidmdbsb2 INT mariadb]$ mysqld -V
mysqld Ver 5.5.27-MariaDB-LOG FOR Linux ON x86_64 (MariaDB SERVER)

  • WAIT a MINUTE
    DONE
  • again run ls -la /DATA/mariadb/db/

[mysql@siucidmdbsb2 INT mariadb]$ ls -la /DATA/mariadb/db/
total 170080
drwxr-X--- 6 mysql mysql 4096 Nov 19 14:29 .
drwxr-xr-X 4 root root 4096 DEC 18 2012 ..
rw-rw--- 1 mysql mysql 16384 Nov 19 14:25 aria_log.00000001
rw-rw--- 1 mysql mysql 52 Nov 19 14:25 aria_log_control
rw-rw--- 1 mysql mysql 163577856 Nov 19 14:29 ibdata1
rw-rw--- 1 mysql mysql 5242880 Nov 19 14:29 ib_logfile0
rw-rw--- 1 mysql mysql 5242880 Nov 19 14:29 ib_logfile1
rw-rw--- 1 mysql mysql 16384 Aug 12 16:15 ib_lru_dump
drwx------ 2 mysql mysql 12288 OCT 2 17:03 jbilling
rw-rw--- 1 mysql mysql 109 Nov 19 14:29 master.info
drwx------ 2 mysql mysql 4096 Mar 13 2013 mysql
drwx------ 2 mysql mysql 20480 Nov 18 15:50 nevisidm
drwx------ 2 mysql mysql 4096 Mar 13 2013 performance_schema

PLUS
[mysql@siucidmdbsb2 INT mariadb]$ ls -la /DATA/LOG/mariadb/
total 253216
drwxr-X--- 2 mysql mysql 4096 Nov 19 14:26 .
drwxr-xr-X 4 root root 4096 DEC 18 2012 ..
rw-rr- 1 root root 838 Aug 12 16:16 check_status_mail.log
rw-rr- 1 root root 8161160 Nov 19 14:30 check_status.sh.log
rw-rr- 1 root root 68 Aug 12 16:19 in_mail.txt
rw-rw--- 1 mysql mysql 2400909 Nov 19 14:26 mariadb-error.log
rw-rw--- 1 mysql mysql 104858042 Nov 11 11:22 mysql-bin.000022
rw-rw--- 1 mysql mysql 104857938 Nov 11 15:59 mysql-bin.000023
rw-rw--- 1 mysql mysql 25129789 Nov 13 15:06 mysql-bin.000024
rw-rw--- 1 mysql mysql 2477630 Nov 14 14:50 mysql-bin.000025
rw-rw--- 1 mysql mysql 11324150 Nov 19 14:25 mysql-bin.000026
rw-rw--- 1 mysql mysql 2621 Nov 19 14:29 mysql-bin.000027
rw-rw--- 1 mysql mysql 210 Nov 19 14:26 mysql-bin.log.index
rw-rw--- 1 mysql mysql 294 Nov 19 14:26 mysql-relay-bin.000154
rw-rw--- 1 mysql mysql 2957 Nov 19 14:29 mysql-relay-bin.000155
rw-rw--- 1 mysql mysql 82 Nov 19 14:26 mysql-relay-bin.index
rw-rw--- 1 mysql mysql 78 Nov 19 14:29 relay-log.info

  • again run sudo ps -ef | grep mysqld

ps -ef | grep mysql
root 2327 1 0 14:25 pts/0 00:00:00 /BIN/sh /usr/BIN/mysqld_safe --datadir=/DATA/mariadb/db --pid-FILE=/DATA/mariadb/db/siucidmdbsb2.pid
mysql 3020 2327 0 14:25 pts/0 00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/DATA/mariadb/db --plugin-dir=/usr/lib64/mysql/PLUGIN --user=mysql --log-error=/DATA/LOG/mariadb/mariadb-error.log --pid-FILE=/DATA/mariadb/db/siucidmdbsb2.pid --socket=/var/lib/mysql/mysql.sock

THE PID FILE IS NOT THERE ANYMORE. i did as u request

Comment by massimo disaro [ 2013-11-19 ]

here the output of the error logs:

131119 14:25:57 [Note] /usr/sbin/mysqld: Normal shutdown

131119 14:25:57 [Note] Event Scheduler: Purging the queue. 0 events
131119 14:25:57 [Note] Error reading relay log event: slave SQL thread was killed
131119 14:25:57 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
131119 14:25:57 [Note] Slave I/O thread killed while reading event
131119 14:25:57 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.000056', position 45643675
131119 14:25:57 InnoDB: Starting shutdown...
131119 14:25:58 InnoDB: Shutdown completed; log sequence number 2544614477
131119 14:25:58 [Note] /usr/sbin/mysqld: Shutdown complete

131119 14:25:58 mysqld_safe mysqld from pid file /data/mariadb/db/siucidmdbsb2.pid ended
131119 14:25:58 mysqld_safe Starting mysqld daemon with databases from /data/mariadb/db
131119 14:25:58 InnoDB: The InnoDB memory heap is disabled
131119 14:25:58 InnoDB: Mutexes and rw_locks use GCC atomic builtins
131119 14:25:58 InnoDB: Compressed tables use zlib 1.2.3
131119 14:25:58 InnoDB: Using Linux native AIO
131119 14:25:58 InnoDB: Initializing buffer pool, size = 512.0M
131119 14:25:58 InnoDB: Completed initialization of buffer pool
131119 14:25:58 InnoDB: highest supported file format is Barracuda.
131119 14:26:01 InnoDB: Waiting for the background threads to start
131119 14:26:02 Percona XtraDB (http://www.percona.com) 1.1.8-28.1 started; log sequence number 2544614477
131119 14:26:02 [Note] Plugin 'FEEDBACK' is disabled.
131119 14:26:03 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000056' at position 45643675, relay log '/data/log/mariadb/mysql-relay-bin.000153' position: 11463904
131119 14:26:03 [Note] Event Scheduler: Loaded 0 events
131119 14:26:03 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.27-MariaDB-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MariaDB Server
131119 14:26:03 [Note] Slave I/O thread: connected to master 'repl@siucidmdbmb2.ucid.local:3306',replication started in log 'mysql-bin.000056' at position 45643675

Comment by Elena Stepanova [ 2013-11-19 ]

Thanks, I will look into it further.

Regarding your previous comment, please don't take the questions for an offense, I am not trying to imply that you have done anything wrong. It's just that the problem you encountered is bizarre, so any smallest oddity is suspicious and can potentially point at the root reason, thus I'm covering everything unusual I notice in the output you provide.

Comment by massimo disaro [ 2013-11-19 ]

Elena don't worry, i was also really doubt that i was the first to face this, and i did not want to open a official jira cause often we face bugs that already exist. The Mariadb IRC channel suggest me to open. BTW , u said is it bizarre and it is, but somebody at IRC told me to try to do the same with " mysqld --help " and the pid disapper also with this command, so it looks to me that something must be behind . Let me know if u need something else.

Comment by Elena Stepanova [ 2013-11-19 ]

>> somebody at IRC told me to try to do the same with " mysqld --help " and the pid disapper also with this command

I think you mean this part of the discussion:

2013-11-13 14:29:18 knielsen I suppose, normally the new process would get a conflict on the socket or port, and thus would fail and not overwrite pid file
2013-11-13 14:29:51 knielsen So when it doesn't do any socket opening or stuff like that, it should not delete pid file or touch any other files...
2013-11-13 14:30:10 knielsen same for mysqld --help ...
2013-11-13 14:30:38 mathnode Does anyone know if tokutek ever intend to add contraints support to tokudb?
2013-11-13 14:32:04 mathnode constraints*
2013-11-13 14:33:29 TGDDIMAA but that s really bad
2013-11-13 14:35:13 grknight i am running a 5.5.33a version from an init script and "# mysqld -V" doesn't remove the pid file
2013-11-13 14:35:18 elenst_ TGDDIMAA: knielsen: actually no, i can't reproduce it
2013-11-13 14:35:24 elenst_ not right away at least
2013-11-13 14:35:55 elenst_ okay i don't have 5.5.27 handy, but i have 5.5.25 and 5.5.28, let me try those
2013-11-13 14:36:00 TGDDIMAA well it happend also with the mysqld --help too!!
2013-11-13 14:36:03 knielsen TGDDIMAA: Maybe you can file a bug, explaining the steps you take to get this incorrect behaviour?
2013-11-13 14:37:03 TGDDIMAA 1- login to linux redhat 6.3 with mysql user : this is the uanme for your information: Linux siucidmdbsb2 2.6.32-279.14.1.el6.x86_64 #1 SMP Mon Oct 15 13:44:51 EDT 2012 x86_64 x86_64 x86_64 GNU/Linux
2013-11-13 14:37:37 TGDDIMAA 2- execute: /.../mysqld -V or /../../mysqld --help
2013-11-13 14:37:55 TGDDIMAA 3- output is fine, but pidfile has been remove

So actually no, knielsen wasn't saying that pid disappeared for him, his words "same for mysqld -help" were about that it should NOT, either for '-V' or for '-help':

Link to the log: http://marialog.archivist.info/2013-11-13.txt

That said, still obviously there must be something behind it, we just need to find out what it is.

Comment by massimo disaro [ 2013-11-19 ]

make sense... so probably i misunderstood, just then so surprise he point it out imminently " --help " option too .

Comment by massimo disaro [ 2013-11-19 ]

checking the installation has been done by RPM from http://archive.mariadb.org/mariadb-5.5.27/rhel6-amd64/rpms/ <http://archive.mariadb.org/mariadb-5.5.27/rhel6-amd64/rpms/>

just check the MD5 now
$ md5sum MariaDB-5.5.27-centos6-x86_64-server.rpm
e4f374278836a7bad4b4b6fb76f5ea59 MariaDB-5.5.27-centos6-x86_64-server.rpm

it looks good

Comment by Elena Stepanova [ 2013-11-19 ]

Could you please also attach your cnf files, as previously mentioned?
Thanks.

Comment by massimo disaro [ 2013-11-19 ]

see Attachment of a copy of my.cnf

Comment by Elena Stepanova [ 2013-11-29 ]

Hi,

I've been looking at the information you provided, and there is one file that I would like to know where it comes from:

rw-rr- 1 root root 8161052 Nov 19 14:28 check_status.sh.log

Can you find the script that creates it and attach it? I don't see it on my CentOS installation, so it must be something custom.

Comment by massimo disaro [ 2013-12-02 ]

hi,
rw-rr- 1 root root 838 Aug 12 16:16 check_status_mail.log
rw-rr- 1 root root 8161160 Nov 19 14:30 check_status.sh.log
rw-rr- 1 root root 68 Aug 12 16:19 in_mail.txt

are logs/files related a customs check about replication. Because of legacy Nagios is going to be able to 'inform' one team, this is going to inform another team .

Comment by Elena Stepanova [ 2013-12-02 ]

Do you have access to the script code? Can you make sure it has nothing to do with pid files?

Comment by massimo disaro [ 2013-12-06 ]

i just check double , these checks are even disable (there are no script running for any reason in background) in owr environment, the log is up to date because the log just store a string like u see bellow. So nothing is related with mysql and mysqld, just a wrong place to out a log.

      • MySQl Check is disabled
      • MySQl Check is disabled
      • MySQl Check is disabled
      • MySQl Check is disabled
      • MySQl Check is disabled
Comment by massimo disaro [ 2014-01-16 ]

we have this problem again in another cluster, Monday 19/01/2014 we are going to upgrade to maria5534 as we did before, if u need something else we still some days

Comment by Elena Stepanova [ 2014-01-16 ]

Hi,
Does it mean you haven't had the problem for a while and just got it now again?

Comment by massimo disaro [ 2014-01-16 ]

no, actually means we resolve the problem to upgrade the version and on 5534 we did not see this bug.

For a new project has been set a new 'cluster' , and because of puppet config we end up to install 5527. Where the problem is happening permanent and we reproduce.

Comment by Elena Stepanova [ 2014-01-31 ]

Please let us know whether upgrade to 5.5.34 resolved the problem on the new cluster as well.

Comment by massimo disaro [ 2014-01-31 ]

yes the problem with 55.34 is not there anymore.

Comment by Elena Stepanova [ 2014-08-16 ]

While we don't know what exactly fixed the problem in 5.5.34, since we could never reproduce it locally, I'm closing it as fixed for now. If somebody ever encounters it again, the bug can be re-opened.

Generated at Thu Feb 08 07:03:07 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.