strange influence cups - nut-server

    • OMV 3.x

    This site uses cookies. By continuing to browse this site, you are agreeing to our Cookie Policy.

    • strange influence cups - nut-server

      Hallo all,

      I noticed a strange problem: each day at 7:35 I get a message "PID nut-server changed", which means nut-server is restarted, right?.
      I think this is caused by anacron, which does a restart of CUPS (I am not sure if this is by design or if this is already some kind of error?), and after this, the PID of nut-server changes and gives a notification message.
      This happens since I activated the CUPS printing plugin and I have no idea about the relation between this two plugins. I can reproduce this by switching off the printing plugin, this also causes a "PID nut-server changed" message.

      Any idea what is going wrong?

      Thanks and greetings

      Franz
    • I assume it is because of logrotate which restarts the daemon, but i did not have checked that.
      Absolutely no support through PM!

      I must not fear.
      Fear is the mind-killer.
      Fear is the little-death that brings total obliteration.
      I will face my fear.
      I will permit it to pass over me and through me.
      And when it has gone past I will turn the inner eye to see its path.
      Where the fear has gone there will be nothing.
      Only I will remain.

      Litany against fear by Bene Gesserit
    • Check the syslog for a related message
      Absolutely no support through PM!

      I must not fear.
      Fear is the mind-killer.
      Fear is the little-death that brings total obliteration.
      I will face my fear.
      I will permit it to pass over me and through me.
      And when it has gone past I will turn the inner eye to see its path.
      Where the fear has gone there will be nothing.
      Only I will remain.

      Litany against fear by Bene Gesserit
    • I have checked the syslog, unfortunately there is no hint about "logrotate", see syslog file below (the gap in the middle is where one syslog stops and the next one begins, which is at about 7:35 when I get the nut-ser PID change message).
      I try to understand: logrotate switch to a new logfile (lets say rename /var/log/cups/error_log to error_log.1), create a new error_log and in its postrotate action it restart cups, right?
      But I have not found some logrotate configuration about "nut" and the "nut" log file seems not to be rotated at all (at least not for longer than a half year), so who is restarting the nut-server and why is this since I installed the cups plugin?

      Source Code

      1. Jul 17 07:00:01 homeserver CRON[7883]: (root) CMD (/usr/sbin/omv-mkgraph >/dev/null 2>&1)
      2. Jul 17 07:00:01 homeserver rrdcached[1164]: Received FLUSHALL
      3. Jul 17 07:09:01 homeserver CRON[8082]: (root) CMD ( [ -x /usr/lib/php5/sessionclean ] && /usr/lib/php5/sessionclean)
      4. Jul 17 07:15:01 homeserver CRON[8182]: (root) CMD (/usr/sbin/omv-mkgraph >/dev/null 2>&1)
      5. Jul 17 07:15:02 homeserver rrdcached[1164]: Received FLUSHALL
      6. Jul 17 07:17:01 homeserver CRON[8321]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
      7. Jul 17 07:24:01 homeserver clamd[1100]: SelfCheck: Database status OK.
      8. Jul 17 07:30:02 homeserver CRON[8437]: (root) CMD (test -x /etc/init.d/anacron && /usr/sbin/invoke-rc.d anacron start >/dev/null)
      9. Jul 17 07:30:02 homeserver CRON[8438]: (root) CMD (/usr/sbin/omv-mkgraph >/dev/null 2>&1)
      10. Jul 17 07:30:02 homeserver rrdcached[1164]: Received FLUSHALL
      11. Jul 17 07:30:02 homeserver systemd[1]: Starting Run anacron jobs...
      12. Jul 17 07:30:02 homeserver systemd[1]: Started Run anacron jobs.
      13. Jul 17 07:30:02 homeserver anacron[8469]: Anacron 2.3 started on 2017-07-17
      14. Jul 17 07:30:02 homeserver anacron[8469]: Will run job `cron.daily' in 5 min.
      15. Jul 17 07:30:02 homeserver anacron[8469]: Jobs will be executed sequentially
      16. Jul 17 07:35:02 homeserver anacron[8469]: Job `cron.daily' started
      17. Jul 17 07:35:02 homeserver anacron[8624]: Updated timestamp for job `cron.daily' to 2017-07-17
      18. Jul 17 07:35:15 homeserver clamd[1100]: SIGHUP caught: re-opening log file.
      19. Jul 17 07:35:15 homeserver freshclam[1063]: Received signal: re-opening log file
      20. Jul 17 07:35:15 homeserver freshclam[1063]: ClamAV update process started at Mon Jul 17 07:35:15 2017
      21. Jul 17 07:35:15 homeserver freshclam[1063]: main.cld is up to date (version: 58, sigs: 4566249, f-level: 60, builder: sigmgr)
      22. Jul 17 07:35:15 homeserver freshclam[1063]: daily.cld is up to date (version: 23570, sigs: 1740460, f-level: 63, builder: neo)
      23. Jul 17 07:35:15 homeserver freshclam[1063]: bytecode.cld is up to date (version: 306, sigs: 65, f-level: 63, builder: raynman)
      24. Jul 17 07:35:15 homeserver systemd[1]: Stopping CUPS Printing Service...
      25. Jul 17 07:35:15 homeserver systemd[1]: Starting CUPS Printing Service...
      26. Jul 17 07:35:15 homeserver systemd[1]: Started CUPS Printing Service.
      27. Jul 17 07:35:15 homeserver rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="1156" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
      28. Jul 17 07:35:16 homeserver rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="1156" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
      29. Jul 17 07:35:16 homeserver systemd[1]: Reloading LSB: start Samba SMB/CIFS daemon (smbd).
      30. Jul 17 07:35:16 homeserver smbd[8899]: Reloading /etc/samba/smb.conf: smbd.
      31. Jul 17 07:35:16 homeserver systemd[1]: Reloaded LSB: start Samba SMB/CIFS daemon (smbd).
      32. Jul 17 07:35:26 homeserver monit[1133]: 'nut-server' process PID changed from 14209 to 2853
      33. Jul 17 07:35:26 homeserver postfix/smtpd[8949]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
      34. Jul 17 07:35:26 homeserver postfix/smtpd[8949]: connect from localhost[127.0.0.1]
      35. Jul 17 07:35:26 homeserver postfix/smtpd[8949]: 59575159374: client=localhost[127.0.0.1]
      36. Jul 17 07:35:26 homeserver postfix/cleanup[8952]: 59575159374: message-id=<1500269726.962170960@homeserver.local>
      37. Jul 17 07:35:26 homeserver postfix/qmgr[3020]: 59575159374: from=<fr.mittermeier@t-online.de>, size=736, nrcpt=2 (queue active)
      38. Jul 17 07:35:26 homeserver postfix/smtpd[8949]: disconnect from localhost[127.0.0.1]
      39. Jul 17 07:35:26 homeserver postfix/pipe[8954]: 59575159374: to=<openmediavault-notification@localhost.localdomain>, relay=omvnotificationfilter, delay=0.42, delays=0.06/0.02/0/0.33,$
      40. Jul 17 07:35:27 homeserver postfix/smtp[8953]: 59575159374: replace: header Subject: monit alert -- PID changed nut-server: Subject: [homeserver.local] monit alert -- PID changed $
      41. Jul 17 07:35:27 homeserver postfix/smtp[8953]: 59575159374: to=<fr.mittermeier@t-online.de>, relay=sfwdallmx.t-online.de[194.25.134.110]:587, delay=0.73, delays=0.06/0.04/0.48/0.14,$
      42. Jul 17 07:35:27 homeserver postfix/qmgr[3020]: 59575159374: removed
      43. Jul 17 07:35:56 homeserver monit[1133]: 'nut-server' process PID has not changed since last cycle
      44. Jul 17 07:39:01 homeserver rsyslogd0: action 'action 31' resumed (module 'builtin:ompipe') [try http://www.rsyslog.com/e/0 ]
      45. Jul 17 07:39:01 homeserver rsyslogd-2359: action 'action 31' resumed (module 'builtin:ompipe') [try http://www.rsyslog.com/e/2359 ]
      46. Jul 17 07:39:01 homeserver CRON[9003]: (root) CMD ( [ -x /usr/lib/php5/sessionclean ] && /usr/lib/php5/sessionclean)
      47. Jul 17 07:45:01 homeserver CRON[9104]: (root) CMD (/usr/sbin/omv-mkgraph >/dev/null 2>&1)
      48. Jul 17 07:45:01 homeserver rrdcached[1164]: Received FLUSHALL
      49. Jul 17 07:46:49 homeserver rrdcached[1164]: flushing old values
      Display All

      BTW: the cups/error_log shows me some error (could this cause any problem?):

      Source Code

      1. E [17/Jul/2017:23:18:11 +0200] Unknown directive BrowseOrder on line 13 of /etc/cups/cupsd.conf.
      2. E [17/Jul/2017:23:18:11 +0200] Unknown directive BrowseAllow on line 14 of /etc/cups/cupsd.conf.
      3. E [17/Jul/2017:23:18:11 +0200] Unknown directive BrowseRemoteProtocols on line 15 of /etc/cups/cupsd.conf.
      4. E [17/Jul/2017:23:18:11 +0200] Unknown directive BrowseAddress on line 16 of /etc/cups/cupsd.conf.
      5. E [17/Jul/2017:23:18:11 +0200] Unknown browse protocol "CUPS" ignored.
      Thank you for your help!
    • I did some more testing ... checked /etc/logrotate.d/cups-daemon, here the postrotate actions says: "invoke-rc.d --quiet cups restart > /dev/null", when I do this manually by entering the command "invoke-rc.d cups restart" in the shell, I get the same result, the nut-server is restarted, so it seems to be the case that cups restarting causes also a restart of nut-server and I get the PID changed messsage. Why this is the case? Where is the relation between this two services? And how can I solve this?

      Thank your for your help!
    • I have seen a similar behavior in "Anacron job 'cron.daily''' mail. It seems that the urbackup-server.service is also influenced by logrotate:

      Source Code

      1. /etc/cron.daily/logrotate:
      2. Failed to kill unit urbackup-server.service: Unit urbackup-server.service is not loaded.
      3. error: error running non-shared postrotate script for /var/log/urbackup.log of '"/var/log/urbackup.log" '
      4. run-parts: /etc/cron.daily/logrotate exited with return code 1

      In this special case the urbackup-server plugin is installed but the service is not running. Therefore I understand the message, that the service is not loaded:

      Is it a regular behavior when cron.daily is executed logrotate wants to kill some services?
      OMV 3.0.90 (Gray style)
      ASRock Rack C2550D4I - 16GB ECC - 6x WD RED 3TB (ZFS 2x3 Striped RaidZ1)- Fractal Design Node 304