Repeating tasks

M

mystic

Member
Jan 8, 2023
8
1
8
Tasks that should work once every night start to work around 22:00 at night and continue until around 01:00 at night by repeating every 2-3 minutes, so many report mails are generated and delivered. The problem has been going on since 9 January. How can I fix this?

1737466050473.png
 
This seems odd - please share the journal from the timeframe - anonymize what you have to:
`journalctl --since '2025-01-21'` should give you the journal since yesterday 00:00
 
please use journalctl on the command-line.

do you still get mails around the clock informing your about pending updates? - then you can share the journal of 1-2 days ago as well
 
Unfortunately, there is only last days log available.
I receive status report emails, but I was not receiving any emails about pending updates before.

1737542307942.png
 
Last edited:
what's the output of journalctl without any parameters? - please post the results as text in a code-block instead of a screenshot
 
Without any parameters journalctl outputs as follows


Jan 22 13:17:40 mx systemd[1]: Reloading pmgpolicy.service - Proxmox Mail Gateway Policy Daemon...
Jan 22 13:17:40 mx systemd-journald[465]: Time jumped backwards, rotating.
Jan 22 13:17:40 mx pmgpolicy[894951]: Received a SIG HUP
Jan 22 13:17:40 mx systemd[1]: Reloaded pmgpolicy.service - Proxmox Mail Gateway Policy Daemon.
Jan 22 13:17:40 mx pmgpolicy[894951]: 2025/01/22-13:17:40 Server closing!
Jan 22 13:17:40 mx pmgpolicy[894951]: 2025/01/22-13:17:40 Re-exec server during HUP
Jan 22 13:17:40 mx pmg-hourly[1256683]: start syncing ldap profile 'zimbra' (eposta.omu.edu.tr)
Jan 22 13:17:41 mx postfix/smtpd[1256089]: warning: hostname sn.dheera.in.net does not resolve to address 51.222.110.89: Name or service not known
Jan 22 13:17:41 mx postfix/smtpd[1256089]: connect from unknown[51.222.110.89]
Jan 22 13:17:41 mx postfix/smtpd[1256156]: connect from unknown[10.10.35.17]
Jan 22 13:17:41 mx postfix/smtpd[1256156]: 77D772815ED: client=unknown[10.10.35.17]
Jan 22 13:17:41 mx postfix/cleanup[1256012]: 77D772815ED: message-id=<>
Jan 22 13:17:41 mx postfix/qmgr[1075]: 77D772815ED: from=<ebysotomasyon@omu.edu.tr>, size=864, nrcpt=1 (queue active)
Jan 22 13:17:41 mx pmg-smtp-filter[1256533]: 2025/01/22-13:17:41 CONNECT TCP Peer: "[127.0.0.1]:52754" Local: "[127.0.0.1]:10023"
Jan 22 13:17:41 mx postfix/smtpd[1256156]: disconnect from unknown[10.10.35.17] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jan 22 13:17:41 mx pmg-smtp-filter[1256533]: 2815EE6790C5C583DA8: new mail message-id=
Jan 22 13:17:41 mx postfix/smtpd[1255732]: connect from localhost.localdomain[127.0.0.1]
Jan 22 13:17:41 mx postfix/smtpd[1255732]: 951142815EF: client=localhost.localdomain[127.0.0.1], orig_client=unknown[10.10.35.17]
Jan 22 13:17:41 mx postfix/cleanup[1256305]: 951142815EF: message-id=<20250122101741.951142815EF@mx.omu.edu.tr>
Jan 22 13:17:41 mx postfix/qmgr[1075]: 951142815EF: from=<ebysotomasyon@omu.edu.tr>, size=1119, nrcpt=1 (queue active)
Jan 22 13:17:41 mx postfix/smtpd[1255732]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
Jan 22 13:17:41 mx pmg-smtp-filter[1256533]: 2815EE6790C5C583DA8: accept mail to <sahaniraz.korkmaz@omu.edu.tr> (951142815EF) (rule: default-accept)
Jan 22 13:17:41 mx pmg-smtp-filter[1256533]: 2815EE6790C5C583DA8: processing time: 0.118 seconds (0, 0.053, 0)
Jan 22 13:17:41 mx postfix/lmtp[1254127]: 77D772815ED: to=<sahaniraz.korkmaz@omu.edu.tr>, relay=127.0.0.1[127.0.0.1]:10023, delay=0.17, delays=0.01/0/0.04/0.12, dsn=2.5.0, status=sent (250 2.5.0 O>Jan 22 13:17:41 mx postfix/qmgr[1075]: 77D772815ED: removed
Jan 22 13:17:41 mx postfix/smtp[1256464]: 951142815EF: to=<sahaniraz.korkmaz@omu.edu.tr>, relay=eposta.omu.edu.tr[193.140.28.32]:25, delay=0.21, delays=0.05/0/0.01/0.16, dsn=2.0.0, status=sent (25>Jan 22 13:17:41 mx postfix/qmgr[1075]: 951142815EF: removed
Jan 22 13:17:42 mx pmgpolicy[894951]: WARNING: Pid_file created by this same process. Doing nothing.
Jan 22 13:17:42 mx pmgpolicy[894951]: WARNING: Pid_file created by this same process. Doing nothing.
Jan 22 13:17:42 mx pmgpolicy[894951]: 2025/01/22-13:17:42 main (type Net::Server::PreForkSimple) starting! pid(894951)
Jan 22 13:17:42 mx pmgpolicy[894951]: Binding open file descriptors
Jan 22 13:17:42 mx pmgpolicy[894951]: Binding to TCP port 10022 on host 127.0.0.1 with IPv4
Jan 22 13:17:42 mx pmgpolicy[894951]: Reassociating file descriptor 8 with TCP on [127.0.0.1]:10022, using IPv4
Jan 22 13:17:42 mx pmgpolicy[894951]: Group Not Defined. Defaulting to EGID '0'
Jan 22 13:17:42 mx pmgpolicy[894951]: User Not Defined. Defaulting to EUID '0'
Jan 22 13:17:42 mx pmgpolicy[894951]: Setting up serialization via flock
Jan 22 13:17:42 mx pmgpolicy[894951]: Policy daemon (re)started
Jan 22 13:17:42 mx pmgpolicy[894951]: Beginning prefork (5 processes)
Jan 22 13:17:42 mx pmgpolicy[894951]: Starting "5" children
Jan 22 13:17:45 mx postfix/smtpd[1256156]: connect from unknown[10.10.35.14]
Jan 22 13:17:45 mx postfix/smtpd[1256156]: 22FC02815ED: client=unknown[10.10.35.14]
Jan 22 13:17:45 mx postfix/cleanup[1256305]: 22FC02815ED: message-id=<>
Jan 22 13:17:45 mx postfix/qmgr[1075]: 22FC02815ED: from=<ebysotomasyon@omu.edu.tr>, size=826, nrcpt=1 (queue active)
Jan 22 13:17:45 mx pmg-smtp-filter[1256318]: 2025/01/22-13:17:45 CONNECT TCP Peer: "[127.0.0.1]:35690" Local: "[127.0.0.1]:10023"
Jan 22 13:17:45 mx postfix/smtpd[1256156]: disconnect from unknown[10.10.35.14] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jan 22 13:17:45 mx postfix/postscreen[1255797]: CONNECT from [156.224.63.247]:53320 to [10.10.1.3]:25
Jan 22 13:17:45 mx postfix/postscreen[1255797]: PASS OLD [156.224.63.247]:53320
Jan 22 13:17:45 mx postfix/smtpd[1256567]: connect from unknown[156.224.63.247]
.....
 
This is the only output? - It's quite strange that your journal only covers less than a minute...
 
I downloaded all output in a text file and then zipped it, but the resulting zip file has size 2.5MB and the site says "The uploaded file is too large for server to process."
I am using head and tail commands for you to see the timespan when I issue the command.
Thank you for your reply.


root@mx:~# head journalctloutput.txt
Jan 23 10:33:40 mx pmgmirror[894975]: starting cluster synchronization
Jan 23 10:33:40 mx systemd-journald[465]: Time jumped backwards, rotating.
Jan 23 10:33:40 mx pmgmirror[894975]: cluster synchronization finished (0 errors, 0.01 seconds (files 0.00, database 0.01, config 0.00))
Jan 23 10:33:41 mx postfix/smtpd[1374060]: connect from unknown[10.10.35.4]
Jan 23 10:33:41 mx postfix/smtpd[1374060]: A530A280526: client=unknown[10.10.35.4]
Jan 23 10:33:41 mx postfix/cleanup[1373708]: A530A280526: message-id=<>
Jan 23 10:33:41 mx postfix/qmgr[1075]: A530A280526: from=<ebysotomasyon@omu.edu.tr>, size=855, nrcpt=1 (queue active)
Jan 23 10:33:41 mx pmg-smtp-filter[1373959]: 2025/01/23-10:33:41 CONNECT TCP Peer: "[127.0.0.1]:53278" Local: "[127.0.0.1]:10023"
Jan 23 10:33:41 mx postfix/smtpd[1374060]: disconnect from unknown[10.10.35.4] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jan 23 10:33:41 mx pmg-smtp-filter[1373959]: 2827336791F0D5B11F6: new mail message-id=
root@mx:~#
root@mx:~# tail journalctloutput.txt
Jan 23 12:58:09 mx postfix/smtpd[1396799]: disconnect from unknown[180.111.177.28] commands=0/0
Jan 23 12:58:09 mx pmg-smtp-filter[1396916]: 282B91679212B19C6CA: new mail message-id=<46dc27e7284fc29c6cbeda04ab9560b9@sendsafe1.com>
Jan 23 12:58:10 mx pmg-smtp-filter[1396813]: 28084D679212AD14374: SA score=0/5 time=5.574 bayes=0.00 autolearn=no autolearn_force=no hits=AWL(-0.151),BAYES_00(-1.9),DKIM_SIGNED(0.1),DKIM_VALID(-0.1),DKIM_VALID_AU(-0.1),DKIM_VALID_EF(-0.1),DMARC_PASS(-0.1),HTML_FONT_LOW_CONTRAST(0.001),HTML_IMAGE_RATIO_06(0.001),HTML_MESSAGE(0.001),LONG_HEX_URI(1),MIME_HTML_ONLY(0.1),SPF_HELO_NONE(0.001),SPF_PASS(-0.001),URIBL_DBL_BLOCKED(0.001)
Jan 23 12:58:10 mx pmg-smtp-filter[1396813]: 28084D679212AD14374: block mail to <aysenur@omu.edu.tr> (rule: Blacklist)
Jan 23 12:58:10 mx pmg-smtp-filter[1396813]: 28084D679212AD14374: processing time: 5.666 seconds (5.574, 0.069, 0)
Jan 23 12:58:10 mx postfix/lmtp[1396062]: 9F5D9282B9B: to=<aysenur@omu.edu.tr>, relay=127.0.0.1[127.0.0.1]:10024, delay=6.1, delays=0.35/0/0.09/5.7, dsn=2.7.0, status=sent (250 2.7.0 BLOCKED (28084D679212AD14374))
Jan 23 12:58:10 mx postfix/qmgr[1075]: 9F5D9282B9B: removed
Jan 23 12:58:12 mx postfix/postscreen[1389988]: CONNECT from [54.39.196.49]:44832 to [10.10.1.3]:25
Jan 23 12:58:12 mx postfix/postscreen[1389988]: PASS OLD [54.39.196.49]:44832
Jan 23 12:58:12 mx postfix/smtpd[1396804]: connect from mt8.oap-scientificjournals.org[54.39.196.49]
root@mx:~#
 
While looking closely at the logs, I noticed a line that said:
'Jan 24 01:53:41 MX postfix/qmgr[1075]: warning: backward time jump recovered — back to normality'
Then I realised that there are so many lines like that.
For example:
Jan 24 01:53:41 mx postfix/qmgr[1075]: warning: backward time jump recovered -- back to normality
Jan 23 22:54:41 mx postfix/qmgr[1075]: warning: backward time jump detected -- slewing clock
Jan 24 02:00:41 mx postfix/qmgr[1075]: warning: backward time jump recovered -- back to normality
Jan 23 23:01:41 mx postfix/qmgr[1075]: warning: backward time jump detected -- slewing clock.

I then changed the NTP client on the host running pmg and the problem was solved.
We recently had to reinstall the vmware host and the ntp client was not configured. This caused the problem in pmg.

Thanks for your help focusing me on the journalctl output.
 
  • Like
Reactions: Stoiko Ivanov
You must log in or register to reply here.
Top Bottom