staging.inyokaproject.org

Hallo zusammen,

ich habe ein sehr merkwürdiges Phänomen. Ich habe einen eigenen Mailserver mit Dovecot und Postfix eingerichtet. Der funktioniert soweit und es können darüber Mails verschickt und empfangen werden. Dann überwache ich über eine Systemd- Path- Unit ein bestimmtes Verzeichnis. Wird darin eine bestimmte Datei abgelegt startet eine Systemd- Service- Unit. Diese ruft ein Pythonscript auf, dass die Datei aus dem Verzeichnis in ein anderes verschiebt und den Inhalt der Datei per Mail an meine Mailadresse verschickt. Das Script funktioniert, wenn ich die Pfadüberwachung per Systemd stoppe es manuell aufrufe. Die Pfadüberwachung per Systemd funktioniert auch. Wenn eine Datei in das überwachte Verzeichnis verschoben wird, startet das Pythonscript, verschiebt die Datei in das andere Verzeichnis und will den Inhalt per Mail verschicken. Das Problem ist nur, dass mir jetzt irgendwer oder was Postfix stoppt. Damit ist dann natürlich kein Mailversand mehr möglich. Das Pythonscript kann ich ausschließen, da ein manueller Anstoß eine Mail erstellt und verschickt. Dann bleiben für mich noch die beiden Systemd Units übrig. Hier die Definitionen:

Die Path- Unit unter /etc/systemd/system/ueberwachungfromjudy.path:

1
2
3
4
5
6
7
8
9

[Unit]
Description=Ueberwachung_Verzeichnis_fromjudy

[Path]
PathExistsGlob=/srv/www/raspi/judy/fromjudy/Ergebnis*
Unit=sendmail.service

[Install]
WantedBy=multi-user.target

Die Service- Unit unter /etc/systemd/system/sendmail.service:

1
2
3
4
5

[Unit]
Description=Mailversand

[Service]
ExecStart=/usr/local/bin/mailversandjudy.py

Hat jemand von Euch eine Idee? Vielen Dank jedenfalls schonmal fürs Schauen und Mithelfen.

Jens

Wie versendet /usr/local/bin/mailversandjudy.py die Mail? Und woher schliesst du, dass Systemd Postfix abschiesst, kannst du dazu Logs zeigen?

Mir fällt niemand sonst ein, der Postfix stoppen soll. Wo finde ich passende Logs dazu? Dann hänge ich sie an.

Der Mailversand passiert über smtplib. Hier der Code- Auszug für die Anmeldung:

1
2
3

s = smtplib.SMTP('smtp.meinedomain.de', 587)
s.starttls()
s.login('Mailadresse', 'Password')

Wo finde ich passende Logs dazu?

sudo journalctl | grep -iE "postfix|judy"

Hier das Logfile:

Mai 23 22:32:47 meinserver systemd[1]: Starting Postfix Mail Transport Agent (instance -)...
Mai 23 22:32:47 meinserver postfix[19550]: Postfix is running with backwards-compatible default settings
Mai 23 22:32:47 meinserver postfix[19550]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Mai 23 22:32:47 meinserver postfix[19550]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
Mai 23 22:32:48 meinserver postfix/postfix-script[19647]: starting the Postfix mail system
Mai 23 22:32:48 meinserver postfix/master[19649]: daemon started -- version 3.3.0, configuration /etc/postfix
Mai 23 22:32:48 meinserver systemd[1]: Started Postfix Mail Transport Agent (instance -).
Mai 23 22:32:48 meinserver systemd[1]: Starting Postfix Mail Transport Agent...
Mai 23 22:32:48 meinserver systemd[1]: Started Postfix Mail Transport Agent.
Mai 23 22:33:41 meinserver systemd[1]: Stopped Postfix Mail Transport Agent.
Mai 23 22:33:41 meinserver systemd[1]: Stopping Postfix Mail Transport Agent (instance -)...
Mai 23 22:33:41 meinserver postfix[19665]: Postfix is running with backwards-compatible default settings
Mai 23 22:33:41 meinserver postfix[19665]: See http://www.postfix.org/COMPATIBILITY_README.html for details
Mai 23 22:33:41 meinserver postfix[19665]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
Mai 23 22:33:41 meinserver postfix/postfix-script[19671]: stopping the Postfix mail system
Mai 23 22:33:41 meinserver postfix/master[19649]: terminating on signal 15
Mai 23 22:33:41 meinserver systemd[1]: Stopped Postfix Mail Transport Agent (instance -).
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]: Traceback (most recent call last):
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/local/bin/mailversandjudy.py", line 41, in <module>
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     s = smtplib.SMTP('smtp.meinedomain.de', 587)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 251, in __init__
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     (code, msg) = self.connect(host, port)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 336, in connect
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     self.sock = self._get_socket(host, port, self.timeout)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 307, in _get_socket
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     self.source_address)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/socket.py", line 724, in create_connection
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     raise err
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/socket.py", line 713, in create_connection
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     sock.connect(sa)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]: ConnectionRefusedError: [Errno 111] Connection refused

Um 22:32:47 habe ich Postfix über "systemctl start postfix" manuell gestartet. Dann habe ich die Datei in das überwachte Verzeichnis verschoben. Daraufhin wurde Postfix wieder beendet und mailversandjudy.py gestartet.

Hier noch die Logs für die einzelnen Units:

Postfix:

-- Logs begin at Mon 2021-04-26 10:12:01 CEST, end at Sun 2021-05-23 22:35:21 CEST. --
Mai 23 22:32:48 meinserver systemd[1]: Starting Postfix Mail Transport Agent...
Mai 23 22:32:48 meinserver systemd[1]: Started Postfix Mail Transport Agent.
Mai 23 22:33:41 meinserver systemd[1]: Stopped Postfix Mail Transport Agent.

ueberwachungfromjudy.path:

-- Logs begin at Mon 2021-04-26 10:12:01 CEST, end at Sun 2021-05-23 22:34:30 CEST. --
-- No entries --

sendmail.service:

-- Logs begin at Mon 2021-04-26 10:12:01 CEST, end at Sun 2021-05-23 22:34:55 CEST. --
Mai 23 22:33:41 meinserver systemd[1]: Started Mailversand.
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]: Traceback (most recent call last):
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/local/bin/mailversandjudy.py", line 41, in <module>
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     s = smtplib.SMTP('smtp.meinedomain.de', 587)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 251, in __init__
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     (code, msg) = self.connect(host, port)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 336, in connect
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     self.sock = self._get_socket(host, port, self.timeout)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 307, in _get_socket
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     self.source_address)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/socket.py", line 724, in create_connection
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     raise err
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/socket.py", line 713, in create_connection
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     sock.connect(sa)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]: ConnectionRefusedError: [Errno 111] Connection refused
Mai 23 22:33:42 meinserver systemd[1]: sendmail.service: Main process exited, code=exited, status=1/FAILURE
Mai 23 22:33:42 meinserver systemd[1]: sendmail.service: Failed with result 'exit-code'.

Hier sieht man ganz gut, dass mit Started Mailversand um 22:33:41 Postfix beendet wurde.

Waren die Textinhalte der Units im Ausgangspost komplett oder nur Auszüge?

Nachtrag: Vielleicht solltest du auch mal den Inhalt von mailversandjudy.py zeigen.

JeDa schrieb:

Hier noch die Logs für die einzelnen Units:

Postfix:

Mai 23 22:33:41 meinserver systemd[1]: Started Mailversand.
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]: Traceback (most recent call last):
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/local/bin/mailversandjudy.py", line 41, in <module>
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     s = smtplib.SMTP('smtp.meinedomain.de', 587)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 251, in __init__
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     (code, msg) = self.connect(host, port)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 336, in connect
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     self.sock = self._get_socket(host, port, self.timeout)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/smtplib.py", line 307, in _get_socket
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     self.source_address)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/socket.py", line 724, in create_connection
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     raise err
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:   File "/usr/lib/python3.6/socket.py", line 713, in create_connection
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]:     sock.connect(sa)
Mai 23 22:33:42 meinserver mailversandjudy.py[19664]: ConnectionRefusedError: [Errno 111] Connection refused
Mai 23 22:33:42 meinserver systemd[1]: sendmail.service: Main process exited, code=exited, status=1/FAILURE
Mai 23 22:33:42 meinserver systemd[1]: sendmail.service: Failed with result 'exit-code'.

Die Fehlermeldung besagt, dass der Port am Gegenüber smtp.meinedomain.de nicht erreichbar war. Das kann viele Ursachen haben - z.B. könnte es sein, dass der SMTP-Dienst nicht läuft, der Port nicht nach außen hin ereichbar ist oder die Adresse bzw. Portnummer nicht stimmen...

Es koennte auch so ein Problem sein: https://superuser.com/questions/1022142/why-is-systemd-stopping-service-immediately-after-it-is-started/ oder https://stackoverflow.com/questions/34614710/why-is-systemd-stopping-service-immediately-after-it-is-started

@dingsbums Die Textinhalte der Units sind so komplett.

Hier ist der Code zu mailversandjudy.py:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73

!/usr/bin/python3

import os
import shutil
import smtplib
from email.mime.text import MIMEText
import datetime
import time

### Datum und Uhrzeit in Variable datuz schreiben ###
now = datetime.datetime.now()
datuz = now.strftime('%d:%m:%Y %H:%M')

### Datei aus fromjudy nach mailversand verschieben ###

# Variable vsftp für sftp- Verzeichnis festlegen
vsftp = '/srv/www/raspi/judy/fromjudy/'

# Liste dateiname mit Dateien aus vsftp erstellen
dateiname = [f for f in os.listdir(vsftp) if os.path.isfile(os.path.join(vsftp, f))]

# Variable vmail für Mailversand festlegen
vmail = '/home/perryu2/mailversand/'

# Variable sftpabsolut definieren
sftpabsolut = vsftp + dateiname[0]

# Variable mailabsolut definieren
mailabsolut = vmail + dateiname[0]

# Datei vom SFTP in Ordner mailversand verschieben
shutil.move(sftpabsolut, mailabsolut)

### Absender, Empfänger, cc und bcc festlegen ###
absender = 'Absenderadresse'
empfaenger = 'Empfängeradresse'

# SMTP connect festlegen (Google- Konto muss Zugriff durch weniger sichere Apps aktiviert sein)
## (ToDo) Austausch über Key prüfen, ob sinnvoll
s = smtplib.SMTP('smtp.meinedomain.de', 587)
s.starttls()
s.login('Maiadresse', 'Passwort')

# Mailtext aus mailabsolut holen
datei = open(mailabsolut, 'r')
mailtext = (datei.read())
datei.close()

# msg definieren
msg = MIMEText(mailtext)

msg['Subject'] = 'Wasserstandsmeldung von Judy vom ' + datuz

msg['From'] = absender

msg['To'] = empfaenger

# msg['Cc'] = cc

# Mailversand und Verbindung schließen
s.send_message(msg)
s.quit()

### Ausgelesene Datei in Ordner Gesendet verschieben ###

# Variable ziel für Zielverzeichnis gesendet nach Mailversand festlegen
ziel = vmail + 'gesendet/'

# Variable zielabsolut definieren
zielabsolut = ziel + dateiname[0]

# Datei verschieben in Ordner gesendet verschieben
shutil.move(mailabsolut, zielabsolut)

Wie gesagt, beim manuellen Ausführen funktioniert das. Darum vermute ich auch, dass Postfix nicht über das Pythonscript beendet wird.

@seahawk1986: Postfix ist zu diesem Zeitpunkt gestoppt. Darum geht der Mailversand nicht. Das Blöde ist, dass ich nicht weiß, wer Postfix anhält.

@sebix:

Ich habe meine Servie- Unit sendmail.service um Type und RamainAfterExit erweitert. Das Ergebnis ist dasselbe. Mit dem Start der Service- Unit wird Postfix automatisch beendet.

1
2
3
4
5
6
7

[Unit]
Description=Mailversand

[Service]
Type=oneshot
ExecStart=/usr/local/bin/mailversandjudy.py
RemainAfterExit=yes

Tausch doch mal den Inhalt des Python-Skripts gegen etwas Belangloses aus (irgendeine Textausgabe a la "hello world"). Wird Postfix dann immer noch beendet?

Ja, Postfix wird immer noch beendet. Hier die journalctl- Logs:

1

journalctl - u sendmail.service --since '2021-05-24 14:09:00'

-- Logs begin at Mon 2021-04-26 10:12:01 CEST, end at Mon 2021-05-24 14:13:34 CEST. --
Mai 24 14:10:33 meinserver systemd[1]: Starting Mailversand... 
Mai 24 14:10:33 meinserver mailversandjudy.py[27836]: Hallo
Mai 24 14:10:33 meinserver systemd[1]: Started Mailversand.

1

journalctl - u postfix --since '2021-05-24 14:09:00'

-- Logs begin at Mon 2021-04-26 10:12:01 CEST, end at Mon 2021-05-24 14:14:05 CEST. --
Mai 24 14:09:51 meinserver systemd[1]: Starting Postfix Mail Transport Agent...
Mai 24 14:09:51 meinserver systemd[1]: Started Postfix Mail Transport Agent.
Mai 24 14:10:33 meinserver systemd[1]: Stopped Postfix Mail Transport Agent.

Um 14:09:51 habe ich Postfix manuell gestartet. Dann habe ich die Datei ins überwachte Verzeichnis verschoben. Mit Starting Mailversand um 14:10:33 wird Postfix wieder beendet.

Eigenartig. Wie sieht denn die Postfix-Unit aus?

/lib/systemd/system/postfix.service:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13

[Unit]
Description=Postfix Mail Transport Agent
Conflicts=sendmail.service exim4.service
ConditionPathExists=/etc/postfix/main.cf

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/bin/true
ExecReload=/bin/true

[Install]
WantedBy=multi-user.target

Die habe ich weder vom Ort noch vom Inhalt angefasst. Warum da bei Conflicts=sendmail.service steht kann ich nicht sagen.