Dbus-org.freedesktop.timedate1.service message

Support
#1

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

#2

Maybe swingsd is not started:

#3

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.

1 Like
#4

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

Bob

#5

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?

#6

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

#7

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

#8 
[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.

#9

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
#10

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

#11

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.

#12

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

#13

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

#14

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:

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…:confused:

#15

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

1 Like
#16

I can confirm what you found out. Great work! :+1:
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?

#17

You forgot to escape the $ on $programname. :face_with_raised_eyebrow:

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

Cheers.

1 Like
#18

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

#19

@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

2 Likes
#20

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.

2 Likes