Restarting ocserv doesn't clean up all workers

[Niels Peen]

> On 24 Sep 2014, at 16:44, Nikos Mavrogiannopoulos <n.mavrogiannopoulos at gmail.com> wrote:
> 
> Could you provide the log output of such cases? Unless killed with
> SIGKILL ocserv shouldn't have left children hanging.

I use the TERM signal to kill the main ocserv process (using the pid file).

Prior to restart:

root     15305  0.0  0.3  53432  6484 ?        Ss   05:24   0:02 /usr/local/sbin/ocserv -c /etc/ocserv/ocserv.conf
root     15306  0.0  0.1  48704  2144 ?        S    05:24   0:00 /usr/local/sbin/ocserv -c /etc/ocserv/ocserv.conf
nobody   27889  0.0  0.0  48748  1592 ?        S    21:40   0:03 /usr/local/sbin/ocserv -c /etc/ocserv/ocserv.conf

After restart:

[ ok ] Restarting ocserv: ocserv.
nobody   27889  0.0  0.0  48748  1592 ?        S    21:40   0:03 /usr/local/sbin/ocserv -c /etc/ocserv/ocserv.conf
root     29495  0.0  0.0  48696  1372 ?        Ss   23:25   0:00 /usr/local/sbin/ocserv -c /etc/ocserv/ocserv.conf
root     29497  0.0  0.0  48704  1404 ?        S    23:25   0:00 /usr/local/sbin/ocserv -c /etc/ocserv/ocserv.conf

27889 should’ve been killed but wasn’t. To kill it manually at this point I need to use SIGKILL - TERM won’t work.

The log doesn’t show the shutdown, only the (re)start:

Sep 24 23:25:07 stariba ocserv[29495]: main: initialized ocserv 0.8.4
Sep 24 23:25:07 stariba ocserv[29497]: sec-mod: sec-mod initialized (socket: ///var/run/ocserv-socket.29495)

If I search the log for 27889 I do see this one message:

Sep 24 21:40:49 stariba ocserv[15306]: sec-mod: received request from pid 27889 and uid 65534

Searching for 15306 shows me many repetitions like this one:

Sep 24 15:24:16 stariba ocserv[15306]: sec-mod: performing maintenance
Sep 24 15:24:16 stariba ocserv[15306]: sec-mod: active sessions 0, banned entries 0
Sep 24 15:24:51 stariba ocserv[15306]: sec-mod: received request from pid 22703 and uid 65534
Sep 24 15:24:51 stariba ocserv[15306]: sec-mod: cmd [size=40] sm: sign
Sep 24 15:24:59 stariba ocserv[15306]: sec-mod: received request from pid 22706 and uid 65534
Sep 24 15:24:59 stariba ocserv[15306]: sec-mod: cmd [size=55] sm: sign
Sep 24 15:25:24 stariba ocserv[15306]: sec-mod: received request from pid 22730 and uid 65534
Sep 24 15:25:24 stariba ocserv[15306]: sec-mod: cmd [size=55] sm: sign
Sep 24 15:25:25 stariba ocserv[15306]: sec-mod: received request from pid 22730 and uid 65534
Sep 24 15:25:25 stariba ocserv[15306]: sec-mod: cmd [size=34] sm: auth init
Sep 24 15:25:25 stariba ocserv[15306]: sec-mod: auth init for user ‘user' (group: '') from ‘X.X.X.X'
Sep 24 15:25:26 stariba ocserv[15306]: sec-mod: received request from pid 22730 and uid 65534
Sep 24 15:25:26 stariba ocserv[15306]: sec-mod: cmd [size=28] sm: auth cont
Sep 24 15:25:26 stariba ocserv[15306]: sec-mod: auth cont for user ‘user'
Sep 24 15:25:26 stariba ocserv[15306]: pam_radius_auth: DEBUG: getservbyname(radius, udp) returned -548460320.
Sep 24 15:25:26 stariba ocserv[15306]: sec-mod: auth deinit for user ‘user'
Sep 24 15:25:51 stariba ocserv[15306]: sec-mod: received request from pid 22738 and uid 65534
Sep 24 15:25:51 stariba ocserv[15306]: sec-mod: cmd [size=40] sm: sign
Sep 24 15:26:51 stariba ocserv[15306]: sec-mod: received request from pid 22746 and uid 65534
Sep 24 15:26:51 stariba ocserv[15306]: sec-mod: cmd [size=40] sm: sign
Sep 24 15:27:51 stariba ocserv[15306]: sec-mod: received request from pid 22771 and uid 65534
Sep 24 15:27:51 stariba ocserv[15306]: sec-mod: cmd [size=40] sm: sign
Sep 24 15:28:51 stariba ocserv[15306]: sec-mod: received request from pid 22787 and uid 65534
Sep 24 15:28:51 stariba ocserv[15306]: sec-mod: cmd [size=40] sm: sign

Regards,
Niels