Tomor's Notes: Cntlm daemon restart is slow (Fedora23)

Everything started with

$ sudo systemctl restart cntlm.service being very slow - it takes a minute or more.

So I started digging why.
I simply tried to stop it and then check how it looks during stopping.

Reproduced in Fedora23 and Fedora24

Running:

$ sudo systemctl start cntlm.service

$ sudo systemctl status cntlm.service -l
● cntlm.service - CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator
   Loaded: loaded (/usr/lib/systemd/system/cntlm.service; enabled; vendor preset: disabled)
   Active: active (running) since Tue 2016-10-25 12:34:33 CEST; 6min ago
  Process: 23537 ExecStart=/usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid (code=exited, status=0/SUCCESS)
 Main PID: 23540 (cntlm)
   Memory: 2.5M
      CPU: 257ms
  CGroup: /system.slice/cntlm.service
           └─23540 /usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid

Oct 25 12:39:23 mylaptop cntlm[23540]: 127.0.0.1 CONNECT ssl.gstatic.com:443
Oct 25 12:39:24 mylaptop cntlm[23540]: 127.0.0.1 CONNECT lh5.googleusercontent.com:443
Oct 25 12:39:24 mylaptop cntlm[23540]: 127.0.0.1 CONNECT csi.gstatic.com:443
Oct 25 12:39:24 mylaptop cntlm[23540]: 127.0.0.1 CONNECT plus.google.com:443
Oct 25 12:39:25 mylaptop cntlm[23540]: 127.0.0.1 CONNECT i18n-cloud.appspot.com:443
Oct 25 12:39:26 mylaptop cntlm[23540]: 127.0.0.1 CONNECT play.google.com:443
Oct 25 12:39:27 mylaptop cntlm[23540]: 127.0.0.1 CONNECT play.google.com:443
Oct 25 12:39:40 mylaptop cntlm[23540]: 127.0.0.1 CONNECT webpoolam30e10.infra.lync.com:443
Oct 25 12:40:35 mylaptop cntlm[23540]: 127.0.0.1 CONNECT accounts.google.com:443
Oct 25 12:40:36 mylaptop cntlm[23540]: 127.0.0.1 CONNECT beacons.gvt2.com:443

After recieving stop signal:

$ sudo systemctl stop cntlm.service

$ sudo systemctl status cntlm.service -l

● cntlm.service - CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator
   Loaded: loaded (/usr/lib/systemd/system/cntlm.service; enabled; vendor preset: disabled)
   Active: deactivating (stop-sigterm) since Tue 2016-10-25 12:41:10 CEST; 11s ago
  Process: 23537 ExecStart=/usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid (code=exited, status=0/SUCCESS)
 Main PID: 23540 (cntlm)
   Memory: 2.5M
      CPU: 260ms
   CGroup: /system.slice/cntlm.service
           └─23540 /usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid
Oct 25 12:39:24 mylaptop cntlm[23540]: 127.0.0.1 CONNECT csi.gstatic.com:443
Oct 25 12:39:24 mylaptop cntlm[23540]: 127.0.0.1 CONNECT plus.google.com:443
Oct 25 12:39:25 mylaptop cntlm[23540]: 127.0.0.1 CONNECT i18n-cloud.appspot.com:443
Oct 25 12:39:26 mylaptop cntlm[23540]: 127.0.0.1 CONNECT play.google.com:443
Oct 25 12:39:27 mylaptop cntlm[23540]: 127.0.0.1 CONNECT play.google.com:443
Oct 25 12:39:40 mylaptop cntlm[23540]: 127.0.0.1 CONNECT webpoolam30e10.infra.lync.com:443
Oct 25 12:40:35 mylaptop cntlm[23540]: 127.0.0.1 CONNECT accounts.google.com:443
Oct 25 12:40:36 mylaptop cntlm[23540]: 127.0.0.1 CONNECT beacons.gvt2.com:443
Oct 25 12:41:10 mylaptop systemd[1]: Stopping CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator...
Oct 25 12:41:10 mylaptop cntlm[23540]: Signal 15 received, issuing clean shutdown

After waiting a minute or more:

$ sudo systemctl status cntlm.service -l
● cntlm.service - CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator
   Loaded: loaded (/usr/lib/systemd/system/cntlm.service; enabled; vendor preset: disabled)
   Active: failed (Result: signal) since Tue 2016-10-25 12:42:40 CEST; 22s ago
  Process: 23537 ExecStart=/usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid (code=exited, status=0/SUCCESS)
 Main PID: 23540 (code=killed, signal=KILL)

Oct 25 12:41:10 mylaptop cntlm[23540]: Signal 15 received, issuing clean shutdown
Oct 25 12:41:26 mylaptop cntlm[23540]: 127.0.0.1 CONNECT likeabosh.hipchat.com:443
Oct 25 12:41:50 mylaptop cntlm[23540]: 127.0.0.1 CONNECT client-cf.dropbox.com:443
Oct 25 12:42:07 mylaptop cntlm[23540]: 127.0.0.1 CONNECT d.dropbox.com:443
Oct 25 12:42:17 v cntlm[23540]: 127.0.0.1 CONNECT mail.google.com:443
Oct 25 12:42:40 mylaptop systemd[1]: cntlm.service: State 'stop-sigterm' timed out. Killing.
Oct 25 12:42:40 mylaptop systemd[1]: cntlm.service: Main process exited, code=killed, status=9/KILL
Oct 25 12:42:40 mylaptop systemd[1]: Stopped CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator.
Oct 25 12:42:40 mylaptop systemd[1]: cntlm.service: Unit entered failed state.
Oct 25 12:42:40 mylaptop systemd[1]: cntlm.service: Failed with result 'signal'.

Wee see that it hangs somehow and then it's killed because of timeout.

Let's try to kill it instead of waiting for timeout

Kill it with SIGINT signal

$ sudo systemctl kill cntlm.service --signal=SIGINT --kill-who=all

$ sudo systemctl status cntlm.service -l
● cntlm.service - CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator
   Loaded: loaded (/usr/lib/systemd/system/cntlm.service; enabled; vendor preset: disabled)
   Active: active (running) since Tue 2016-10-25 12:55:58 CEST; 8s ago
  Process: 26197 ExecStart=/usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid (code=exited, status=0/SUCCESS)
 Main PID: 26206 (cntlm)
   Memory: 528.0K
      CPU: 9ms
   CGroup: /system.slice/cntlm.service
           └─26206 /usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid

Oct 25 12:55:58 mylaptop cntlm[26206]: Daemon ready
Oct 25 12:55:58 mylaptop systemd[1]: Started CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator.
Oct 25 12:55:58 mylaptop cntlm[26206]: Changing uid:gid to 991:985 - Success
Oct 25 12:55:58 mylaptop cntlm[26206]: Using proxy wp.xxxx.de:8080
Oct 25 12:55:59 mylaptop cntlm[26206]: 127.0.0.1 CONNECT webpoolam30e10.infra.lync.com:443
Oct 25 12:55:59 mylaptop cntlm[26206]: 127.0.0.1 CONNECT webpoolam30e10.infra.lync.com:443
Oct 25 12:56:02 mylaptop cntlm[26206]: 127.0.0.1 CONNECT tch750293.tch.quora.com:443
Oct 25 12:56:04 mylaptop cntlm[26206]: Signal 2 received, issuing clean shutdown

Wait 30 more seconds and then it looks like nothing happened:

sudo systemctl status cntlm.service -l
● cntlm.service - CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator
   Loaded: loaded (/usr/lib/systemd/system/cntlm.service; enabled; vendor preset: disabled)
   Active: active (running) since Tue 2016-10-25 12:55:58 CEST; 38s ago
  Process: 26197 ExecStart=/usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid (code=exited, status=0/SUCCESS)
 Main PID: 26206 (cntlm)
   Memory: 1.1M
      CPU: 21ms
   CGroup: /system.slice/cntlm.service
           └─26206 /usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid

Oct 25 12:56:14 mylaptop cntlm[26206]: 127.0.0.1 CONNECT 27.client-channel.google.com:443
Oct 25 12:56:20 mylaptop cntlm[26206]: 127.0.0.1 CONNECT outlook.office.com:443
Oct 25 12:56:21 mylaptop cntlm[26206]: 127.0.0.1 CONNECT 0.client-channel.google.com:443
Oct 25 12:56:21 mylaptop cntlm[26206]: 127.0.0.1 CONNECT outlook.office.com:443
Oct 25 12:56:21 mylaptop cntlm[26206]: 127.0.0.1 CONNECT cello.client-channel.google.com:443
Oct 25 12:56:29 mylaptop cntlm[26206]: 127.0.0.1 CONNECT www.blogger.com:443
Oct 25 12:56:30 mylaptop cntlm[26206]: 127.0.0.1 CONNECT outlook.office.com:443
Oct 25 12:56:30 mylaptop cntlm[26206]: 127.0.0.1 CONNECT outlook.office.com:443
Oct 25 12:56:33 mylaptop cntlm[26206]: 127.0.0.1 CONNECT webpoolam30e10.infra.lync.com:443

but then I executed the same kill command again and it stopped immediately:

$ sudo systemctl kill cntlm.service --signal=SIGINT --kill-who=all

$ sudo systemctl status cntlm.service -l                          
● cntlm.service - CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator
   Loaded: loaded (/usr/lib/systemd/system/cntlm.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Tue 2016-10-25 12:56:46 CEST; 2s ago
  Process: 26197 ExecStart=/usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid (code=exited, status=0/SUCCESS)
 Main PID: 26206 (code=exited, status=0/SUCCESS)

Oct 25 12:56:14 mylaptop cntlm[26206]: 127.0.0.1 CONNECT 27.client-channel.google.com:443
Oct 25 12:56:20 mylaptop cntlm[26206]: 127.0.0.1 CONNECT outlook.office.com:443
Oct 25 12:56:21 mylaptop cntlm[26206]: 127.0.0.1 CONNECT 0.client-channel.google.com:443
Oct 25 12:56:21 mylaptop cntlm[26206]: 127.0.0.1 CONNECT outlook.office.com:443
Oct 25 12:56:21 mylaptop cntlm[26206]: 127.0.0.1 CONNECT cello.client-channel.google.com:443
Oct 25 12:56:29 mylaptop cntlm[26206]: 127.0.0.1 CONNECT www.blogger.com:443
Oct 25 12:56:30 mylaptop cntlm[26206]: 127.0.0.1 CONNECT outlook.office.com:443
Oct 25 12:56:30 mylaptop cntlm[26206]: 127.0.0.1 CONNECT outlook.office.com:443
Oct 25 12:56:33 mylaptop cntlm[26206]: 127.0.0.1 CONNECT webpoolam30e10.infra.lync.com:443

...interesting, but not helpful.

Lets, use stronger signal - SIGKILL terminates immediately:

$ sudo systemctl kill cntlm.service --signal=SIGKILL

$ sudo systemctl status cntlm.service -l
● cntlm.service - CNTLM HTTP Accelerator For NTLM Secured Proxies Authenticator
   Loaded: loaded (/usr/lib/systemd/system/cntlm.service; enabled; vendor preset: disabled)
   Active: failed (Result: signal) since Tue 2016-10-25 12:59:10 CEST; 2s ago
  Process: 26512 ExecStart=/usr/sbin/cntlm -c /etc/cntlm.conf -U cntlm -P /run/cntlm/cntlmd.pid (code=exited, status=0/SUCCESS)
 Main PID: 26522 (code=killed, signal=KILL)

Oct 25 12:58:53 mylaptop cntlm[26522]: 127.0.0.1 CONNECT clients6.google.com:443
Oct 25 12:58:53 mylaptop cntlm[26522]: 127.0.0.1 CONNECT clients6.google.com:443
Oct 25 12:58:53 mylaptop cntlm[26522]: 127.0.0.1 CONNECT hangouts.google.com:443
Oct 25 12:58:53 mylaptop cntlm[26522]: 127.0.0.1 CONNECT clients6.google.com:443
Oct 25 12:58:53 mylaptop cntlm[26522]: 127.0.0.1 CONNECT clients6.google.com:443
Oct 25 12:59:07 mylaptop cntlm[26522]: 127.0.0.1 CONNECT tch750293.tch.quora.com:443
Oct 25 12:59:10 mylaptop systemd[1]: cntlm.service: Main process exited, code=killed, status=9/KILL
Oct 25 12:59:10 mylaptop systemd[1]: cntlm.service: Unit entered failed state.
Oct 25 12:59:10 mylaptop systemd[1]: cntlm.service: Failed with result 'signal'.

Right now I've changed my script for changing proxy settings to:

- change /etc/cntlm.con
- kill cnltm daemon with sigterm SIGKILL
- start cntlm daemon

But of course I would rather use "systemctl restart cntlm.service" instead of killing it.

Do you know how to restart it quickly without killing it that brutal way? Let me know.

Is it connected with settings of the daemon?

TODO - report to fedora?

Something what can help with more digging:

https://lists.fedoraproject.org/archives/list/scm-commits@lists.fedoraproject.org/thread/K2ODOIAPFFM2N7WY65P2YP2F5OMO4G4Z/

Tomor's Notes

Tuesday, 25 October 2016

Cntlm daemon restart is slow (Fedora23)