You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@commons.apache.org by "Rustam Abdullaev (JIRA)" <ji...@apache.org> on 2017/11/09 11:36:00 UTC
[jira] [Updated] (DAEMON-377) Race in PID file handing in jsvc
resulting in Tomcat running without a pidfile
[ https://issues.apache.org/jira/browse/DAEMON-377?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Rustam Abdullaev updated DAEMON-377:
------------------------------------
Description:
This issue is reproducible in FreeBSD under moderate load during a restart of Tomcat 8 running via jsvc.
The old jsvc controller process exits _after_ the new process is started, deleting the new pid file with it. As a result, the jsvc starter process fails with a timeout since it is waiting on the pid file to be created, which never happens. The Tomcat process itself is *started without a pid file*.
Example: (35659/35660 is the old jsvc process, 56362/56363 is the new jsvc process):
{noformat}
2017-11-08 09:36:59 35660 jsvc debug: Daemon destroyed successfully
2017-11-08 09:36:59 35660 jsvc debug: Calling System.exit(0)
2017-11-08 09:36:59 56362 jsvc debug: Switching umask back to 022 from 077
(((/var/run/tomcat8.pid is written by 56362 here)))
2017-11-08 09:36:59 56363 jsvc debug: Using specific JVM in /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so
2017-11-08 09:36:59 56363 jsvc debug: Attemtping to load library /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so
(((/var/run/tomcat8.pid is deleted by 35659 here)))
2017-11-08 09:36:59 35659 jsvc debug: Service shut down
2017-11-08 09:36:59 56363 jsvc debug: JVM library /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so loaded
2017-11-08 09:36:59 56363 jsvc debug: JVM library entry point found (0x019DE640)
{noformat}
Restart script eventually times out:
{noformat}
>/usr/local/etc/rc.d/tomcat8 restart
Stopping tomcat8.
Waiting for PIDS: 35660.
Starting tomcat8.
/usr/local/etc/rc.d/tomcat8: WARNING: failed to start tomcat8
{noformat}
No PID file:
{noformat}
>ls -l /var/run/tomcat8.pid
ls: /var/run/tomcat8.pid: No such file or directory
{noformat}
Yet Tomcat is running:
{noformat}
>ps ax|grep java|grep -v grep
56362 - Is 0:00.00 /usr/local/bin/jsvc -java-home /usr/local/openjdk8 -server -user www -pidfile /var/run/tomcat8.pid -wait 300 -outfile /u
56363 - I 0:57.25 /usr/local/bin/jsvc -java-home /usr/local/openjdk8 -server -user www -pidfile /var/run/tomcat8.pid -wait 300 -outfile /u
{noformat}
The issue is that the pidfile contains the PID of the _child_, but is being deleted by the _parent_ process (the controller), in the {{run_controller}} function which looks like:
{code}
static int run_controller(arg_data *args, home_data *data, uid_t uid,
gid_t gid)
. . .
waitpid(pid, &status, 0);
unlink(args->pidf);
{code}
If the controller process is paged out (which happens often because it is dormant while inside {{waitpid}}), then considerable amount of time can pass between the time the child terminates and the call to {{unlink(args->pidf)}}.
The issue can be reproduced reliably by adding {{sleep(1);}} before {{unlink(args->pidf)}}.
was:
This issue is reproducible in FreeBSD under moderate load during a restart of Tomcat 8 running via jsvc.
The old jsvc controller process exits _after_ the new process is started, deleting the new pid file with it. As a result, the jsvc starter process fails with a timeout since it is waiting on the pid file to be created, which never happens. The Tomcat process itself is *started without a pid file*.
Example: (35659/35660 is the old jsvc process, 56362/56363 is the new jsvc process):
{noformat}
2017-11-08 09:36:59 35660 jsvc debug: Daemon destroyed successfully
2017-11-08 09:36:59 35660 jsvc debug: Calling System.exit(0)
2017-11-08 09:36:59 56362 jsvc debug: Switching umask back to 022 from 077
(((/var/run/tomcat8.pid is written by 56362 here)))
2017-11-08 09:36:59 56363 jsvc debug: Using specific JVM in /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so
2017-11-08 09:36:59 56363 jsvc debug: Attemtping to load library /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so
(((/var/run/tomcat8.pid is deleted by 35659 here)))
2017-11-08 09:36:59 35659 jsvc debug: Service shut down
2017-11-08 09:36:59 56363 jsvc debug: JVM library /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so loaded
2017-11-08 09:36:59 56363 jsvc debug: JVM library entry point found (0x019DE640)
{noformat}
Restart script eventually times out:
{noformat}
>/usr/local/etc/rc.d/tomcat8 restart
Stopping tomcat8.
Waiting for PIDS: 35660.
Starting tomcat8.
/usr/local/etc/rc.d/tomcat8: WARNING: failed to start tomcat8
{noformat}
No PID file:
{noformat}
>ls -l /var/run/tomcat8.pid
ls: /var/run/tomcat8.pid: No such file or directory
{noformat}
Yet Tomcat is running:
{noformat}
>ps ax|grep java|grep -v grep
56362 - Is 0:00.00 /usr/local/bin/jsvc -java-home /usr/local/openjdk8 -server -user www -pidfile /var/run/tomcat8.pid -wait 300 -outfile /u
56363 - I 0:57.25 /usr/local/bin/jsvc -java-home /usr/local/openjdk8 -server -user www -pidfile /var/run/tomcat8.pid -wait 300 -outfile /u
{noformat}
> Race in PID file handing in jsvc resulting in Tomcat running without a pidfile
> ------------------------------------------------------------------------------
>
> Key: DAEMON-377
> URL: https://issues.apache.org/jira/browse/DAEMON-377
> Project: Commons Daemon
> Issue Type: Bug
> Reporter: Rustam Abdullaev
>
> This issue is reproducible in FreeBSD under moderate load during a restart of Tomcat 8 running via jsvc.
> The old jsvc controller process exits _after_ the new process is started, deleting the new pid file with it. As a result, the jsvc starter process fails with a timeout since it is waiting on the pid file to be created, which never happens. The Tomcat process itself is *started without a pid file*.
> Example: (35659/35660 is the old jsvc process, 56362/56363 is the new jsvc process):
> {noformat}
> 2017-11-08 09:36:59 35660 jsvc debug: Daemon destroyed successfully
> 2017-11-08 09:36:59 35660 jsvc debug: Calling System.exit(0)
> 2017-11-08 09:36:59 56362 jsvc debug: Switching umask back to 022 from 077
> (((/var/run/tomcat8.pid is written by 56362 here)))
> 2017-11-08 09:36:59 56363 jsvc debug: Using specific JVM in /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so
> 2017-11-08 09:36:59 56363 jsvc debug: Attemtping to load library /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so
> (((/var/run/tomcat8.pid is deleted by 35659 here)))
> 2017-11-08 09:36:59 35659 jsvc debug: Service shut down
> 2017-11-08 09:36:59 56363 jsvc debug: JVM library /usr/local/openjdk8/jre/lib/amd64/server/libjvm.so loaded
> 2017-11-08 09:36:59 56363 jsvc debug: JVM library entry point found (0x019DE640)
> {noformat}
> Restart script eventually times out:
> {noformat}
> >/usr/local/etc/rc.d/tomcat8 restart
> Stopping tomcat8.
> Waiting for PIDS: 35660.
> Starting tomcat8.
> /usr/local/etc/rc.d/tomcat8: WARNING: failed to start tomcat8
> {noformat}
> No PID file:
> {noformat}
> >ls -l /var/run/tomcat8.pid
> ls: /var/run/tomcat8.pid: No such file or directory
> {noformat}
> Yet Tomcat is running:
> {noformat}
> >ps ax|grep java|grep -v grep
> 56362 - Is 0:00.00 /usr/local/bin/jsvc -java-home /usr/local/openjdk8 -server -user www -pidfile /var/run/tomcat8.pid -wait 300 -outfile /u
> 56363 - I 0:57.25 /usr/local/bin/jsvc -java-home /usr/local/openjdk8 -server -user www -pidfile /var/run/tomcat8.pid -wait 300 -outfile /u
> {noformat}
> The issue is that the pidfile contains the PID of the _child_, but is being deleted by the _parent_ process (the controller), in the {{run_controller}} function which looks like:
> {code}
> static int run_controller(arg_data *args, home_data *data, uid_t uid,
> gid_t gid)
> . . .
> waitpid(pid, &status, 0);
> unlink(args->pidf);
> {code}
> If the controller process is paged out (which happens often because it is dormant while inside {{waitpid}}), then considerable amount of time can pass between the time the child terminates and the call to {{unlink(args->pidf)}}.
> The issue can be reproduced reliably by adding {{sleep(1);}} before {{unlink(args->pidf)}}.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)