Dbus-org.freedesktop.timedate1.service message

bobtskutter · 2018-05-16 19:53:39 UTC

NethServer Version: 7.4.1708
Module: dont know
Hello,
My messages log is showing hundreds of messages per day like this:

May 16 20:39:43 nethserver dbus[721]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' May 16 20:39:43 nethserver dbus-daemon: dbus[721]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' May 16 20:39:43 nethserver systemd: Starting Time & Date Service... May 16 20:39:43 nethserver dbus[721]: [system] Successfully activated service 'org.freedesktop.timedate1' May 16 20:39:43 nethserver dbus-daemon: dbus[721]: [system] Successfully activated service 'org.freedesktop.timedate1' May 16 20:39:43 nethserver systemd: Started Time & Date Service.

It seems to be appearing every 5mins, but there’s nothing obvious in the cron log.
It seems to be getting more frequent. When I first installed the machine in April it was about 1hr between events, now it’s 5mins.

Does anyone have any idea what’s happening?

edit:
it seems to be dbus causing the entries.

systemctl status dbus

dbus.service - D-Bus System Message Bus
   Loaded: loaded (/usr/lib/systemd/system/dbus.service; static; vendor preset: disabled)
   Active: active (running) since Wed 2018-05-16 20:04:53 BST; 1h 14min ago
 Main PID: 721 (dbus-daemon)
   CGroup: /system.slice/dbus.service
           └─721 /bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation

May 16 21:15:18 xxxxx.org.uk dbus-daemon[721]: dbus[721]: [system] Activating via systemd: se$
May 16 21:15:18 xxxxx.org.uk dbus[721]: [system] Activating via systemd: service name='org.fr$
May 16 21:15:18 xxxxx.org.uk dbus[721]: [system] Successfully activated service 'org.freedesk$
May 16 21:15:18 xxxxx.org.uk dbus-daemon[721]: dbus[721]: [system] Successfully activated ser$
May 16 21:15:30 xxxxx.org.uk dbus[721]: [system] Reloaded configuration
May 16 21:15:30 xxxxx.org.uk dbus-daemon[721]: dbus[721]: [system] Reloaded configuration
May 16 21:18:46 xxxxx.org.uk dbus[721]: [system] Reloaded configuration
May 16 21:18:46 xxxxx.org.uk dbus-daemon[721]: dbus[721]: [system] Reloaded configuration
May 16 21:18:55 xxxxx.org.uk dbus[721]: [system] Reloaded configuration
May 16 21:18:55 xxxxx.org.uk dbus-daemon[721]: dbus[721]: [system] Reloaded configuration

thanks
Bob

mrmarkuz · 2018-05-16 21:47:52 UTC

Maybe swingsd is not started:

EddieA · 2018-05-16 21:53:25 UTC

I’m seeing the same issue, but that isn’t the cause:

[root@Nethserver ~]# systemctl status dbus
● dbus.service - D-Bus System Message Bus
   Loaded: loaded (/usr/lib/systemd/system/dbus.service; static; vendor preset: disabled)
   Active: active (running) since Fri 2018-03-09 16:27:39 PST; 2 months 7 days ago
 Main PID: 1057 (dbus-daemon)
   CGroup: /system.slice/dbus.service
           └─1057 /bin/dbus-daemon --system --address=systemd: --nofork --nop...

May 16 14:40:16 Nethserver.BogoLinux.net dbus[1057]: [system] Successfully ac...
May 16 14:40:16 Nethserver.BogoLinux.net dbus-daemon[1057]: dbus[1057]: [syst...
May 16 14:45:16 Nethserver.BogoLinux.net dbus[1057]: [system] Activating via ...
May 16 14:45:16 Nethserver.BogoLinux.net dbus-daemon[1057]: dbus[1057]: [syst...
May 16 14:45:16 Nethserver.BogoLinux.net dbus-daemon[1057]: dbus[1057]: [syst...
May 16 14:45:16 Nethserver.BogoLinux.net dbus[1057]: [system] Successfully ac...
May 16 14:50:17 Nethserver.BogoLinux.net dbus-daemon[1057]: dbus[1057]: [syst...
May 16 14:50:17 Nethserver.BogoLinux.net dbus[1057]: [system] Activating via ...
May 16 14:50:17 Nethserver.BogoLinux.net dbus-daemon[1057]: dbus[1057]: [syst...
May 16 14:50:17 Nethserver.BogoLinux.net dbus[1057]: [system] Successfully ac...
Hint: Some lines were ellipsized, use -l to show in full.
[root@Nethserver ~]# systemctl status smwingsd
● smwingsd.service - Server Manager DB cache Daemon
   Loaded: loaded (/usr/lib/systemd/system/smwingsd.service; static; vendor preset: disabled)
   Active: active (running) since Tue 2018-05-01 18:13:33 PDT; 2 weeks 0 days ago
     Docs: https://github.com/NethServer/nethserver-httpd-admin
 Main PID: 2402 (smwingsd)
   CGroup: /system.slice/smwingsd.service
           └─2402 /usr/bin/perl /usr/libexec/nethserver/smwingsd

May 01 18:13:32 Nethserver.BogoLinux.net systemd[1]: Starting Server Manager ...
May 01 18:13:33 Nethserver.BogoLinux.net smwingsd[2402]: Process Backgrounded
May 01 18:13:33 Nethserver.BogoLinux.net smwingsd[2402]: 2018/05/01-18:13:33 ...
May 01 18:13:33 Nethserver.BogoLinux.net systemd[1]: Started Server Manager D...
May 01 18:13:33 Nethserver.BogoLinux.net smwingsd[2402]: Binding to UNIX sock...
May 01 18:13:33 Nethserver.BogoLinux.net smwingsd[2402]: Setting gid to "4 4"
May 01 18:13:33 Nethserver.BogoLinux.net smwingsd[2402]: Setting uid to "995"
Hint: Some lines were ellipsized, use -l to show in full.
[root@Nethserver ~]#

Cheers.

bobtskutter · 2018-05-17 17:03:29 UTC

swingsd is running on my system. So I don’t think that’s causing the problem on my system.

Bob

mrmarkuz · 2018-05-17 20:56:53 UTC

You are right, I thought it could be related but it’s a different message.

I checked the log files of my servers and couldn’t find an occurrence of every 5 mins.

You can trigger the message with signal-event nethserver-ntp-save or signal-event nethserver-ntp-update. So reboots/updates/config changes/service restarts may be responsible for the entries too. Did you change NTP settings?

bobtskutter · 2018-05-17 21:31:10 UTC

I spotted the “problem” yesterday. I’d not changed the ntp settings since I’d installed the system, so I don’t think that’s the cause either. I’ve changed the ntp settings since I spotted to the “problem” to test if that was the cause and things havn’t changed - which also suggests it’s not the ntp settings.

I’ve manually started the systemd-timedated.service and it runs for a few mins then is stopped again.

Something is automatically starting and stopping the systemd-timedated.service every 5mins.

Please note that dbus-org.freedesktop.timedate1.service seems to activate systemd-timedated.service

regards
Bob

mrmarkuz · 2018-05-17 22:09:34 UTC

Maybe it’s a time sync problem?

You may check your timeservers with

chronyc sourcestats

http://docs.nethserver.org/projects/nethserver-devel/en/v7/nethserver-ntp.html

EddieA · 2018-05-17 22:17:32 UTC

[root@Nethserver ~]# chronyc sourcestats
210 Number of sources = 4
Name/IP Address            NP  NR  Span  Frequency  Freq Skew  Offset  Std Dev
==============================================================================
clock.xmission.com          6   5  121m     -0.119      0.383   -939us   249us
ec2-52-6-160-3.compute-1>  10   7  120m     +0.088      0.245   +554us   269us
li210-194.members.linode>  11   7  172m     +0.029      0.200    +68us   501us
srcf-ntp.stanford.edu      16   9  276m     +0.021      0.086   +669us   393us
[root@Nethserver ~]#

Cheers.

mrmarkuz · 2018-05-17 22:21:36 UTC

Hmm, no relevant difference:

210 Number of sources = 4
Name/IP Address            NP  NR  Span  Frequency  Freq Skew  Offset  Std Dev
==============================================================================
tkswf.friesenecker.info    33  15  104m     -0.058      0.275    -34us   697us
manage.mediainvent.at      19   9   88m     +0.276      0.132  -1546us   275us
extern4.nemox.net          32  15  102m     -0.203      0.107  +2108us   250us
boxi.trexler.at             6   3   323     -7.904     39.679    -68ms  1262us

bobtskutter · 2018-05-18 20:00:09 UTC

The output on my system is the same as mrmarkuz and EddieA.

EddieA · 2018-05-18 20:13:59 UTC

After restoring some old logs from my backups, I’ve narrowed it down to these updates:

Apr 09 00:55:30 Installed: yum-cron-3.4.3-154.el7.centos.1.noarch
Apr 09 00:55:31 Installed: nethserver-yum-cron-1.0.0-1.ns7.sdl.noarch
Apr 09 00:55:38 Installed: puppet-agent-1.6.2-1.el7.x86_64
Apr 09 00:55:39 Installed: nethserver-subscription-3.0.1-1.ns7.noarch
Apr 09 00:55:41 Installed: nethserver-subscription-ui-3.0.1-1.ns7.noarch

Cheers.

bobtskutter · 2018-05-18 21:49:28 UTC

My system shows similar behaviour. Updates on the 15th of May and then the dbus messages start every 5mins. HOWEVER, there was a period on 13th May when the dbus messages appeared every 5mins, but it has become a regular occurrence since 15th of May.

The following updates were applied on 15th May:

May 15 20:40:16 Installed: yum-cron-3.4.3-158.el7.centos.noarch
May 15 20:40:28 Installed: puppet-agent-1.6.2-1.el7.x86_64
May 15 20:40:28 Installed: perl-Email-Valid-1.198-1.el7.noarch
May 15 20:40:29 Installed: nethserver-yum-cron-1.0.0-1.ns7.noarch
May 15 20:40:29 Installed: nethserver-subscription-3.0.2-1.ns7.noarch
May 15 20:40:29 Installed: nethserver-subscription-ui-3.0.2-1.ns7.noarch

May 15 20:40:28 Installed: puppet-agent-1.6.2-1.el7.x86_64

looks common to our problems

Bob

bobtskutter · 2018-05-19 07:24:01 UTC

Is puppet used on NethServer?
I don’t see any config files.

There is mention of puppet here:
http://docs.nethserver.org/projects/nethserver-devel/en/v7/rpm_rules.html

and a reference to

/etc/e-smith/db/configuration/defaults/puppet/type
/etc/e-smith/db/configuration/defaults/puppet/status

but that location and files don’t exist on my system.

according to:

the last commit was september 2013.

bob

bobtskutter · 2018-05-19 18:00:24 UTC

I think I’ve narrowed it down even further.
I think it’s the nethserver subscription daemon.
http://docs.nethserver.org/projects/nethserver-devel/en/v7/nethserver-subscription.html

NethServer Monitor Services (NMS)

NMS is a python daemon which monitor the status of all services registered inside the configuration db. Each service is checked every 300 seconds, if the status of a service changes, NMS writes a notification to Collectd socket.

then here:

github.com

NethServer/nethserver-subscription/blob/master/root/usr/sbin/nms

#!/usr/bin/python
#
# NethServer Monitor Services (NMS)
#
# This daemon monitors the status of all services registered
# inside the configuration database. 
#

import time, socket, subprocess, os, sys, getopt
import json


debug = 1
tick = 300
ignored_services = ('');

'''
_readline and _readlines methods borrowed from the _fileobject class 
in sockets.py, tweaked a little bit for use in the collectd context.
'''

This file has been truncated. show original

line 33 refers to

/usr/libexec/nethserver/read-service-status

running this script from the command prompt causes the freedesktop.timedate messages to appear in the log.

I’m not quite sure what to do next though…

bobtskutter · 2018-05-19 19:27:10 UTC

I’ve changed the timer in
/usr/sbin/nms
from 300 to 240, then restarted the machine.

The frequency of freedesktop.timedate messages changed from 5mins to 4mins (300sec to 240sec).

So it would appear that the nms service is causing the freedesktop.timedate messages.

bob

mrmarkuz · 2018-05-19 21:18:50 UTC

I can confirm what you found out. Great work!
The only solution I see for now is to suppress these messages in the logfile. I found similar issue with sogo here and in the docs and changed it to fit to our needs:

echo "if \$programname == \"dbus\" and (\$msg contains \"Activating via systemd: service name='org.freedesktop.timedate1'\" or \$msg contains \"Successfully activated service 'org.freedesktop.timedate1'\") then stop" > /etc/rsyslog.d/ignore-dbus-timedate.conf

systemctl restart rsyslog

@giacomo, do you see another way to get rid of these messages triggered by the subscription module?

EddieA · 2018-05-19 22:39:25 UTC

You forgot to escape the $ on $programname.

Also, that only suppresses 2 of the 6 lines produced. The others appear to come from programs: dbus-daemon or systemd.

Cheers.

mrmarkuz · 2018-05-19 22:51:20 UTC

Thanks, corrected.

Are all lines produced by the subscription module? You may add more files or lines like:

if $programname == "dbus-daemon" and ($msg contains "..." or $msg contains "...") then stop

bobtskutter · 2018-05-20 17:46:11 UTC

@mrmarkuz @EddieA

These are the config entries I used in the end:

if $programname == "systemd" and ($msg contains "Starting Time & Date Service..." or $msg contains "Started Time & Date Service.") then stop
if ($msg contains "Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'") then stop
if ($msg contains "Successfully activated service 'org.freedesktop.timedate1'") then stop

regards
bob

giacomo · 2018-05-21 07:59:19 UTC

IIRC the database initialization access chronyd via DBUS which generates these lines.

Adding the suggested configuration to rsyslog will surely work, but we can’t apply such fix.
In fact rsyslog can’t be restarted without human supervision because sometime, after the restart, journalctl stops sending messages to it.
I don’t know why, I couldn’t reproduce the problem but I know it exists.

I will try to find a way to avoid such log directly from db code, but probably there is no solution.