Fhem startet anscheinend ohne Grund neu, 96_SIP.pm beteiligt

[Gisbert]

Hallo zusammen,

in den letzten Tagen/Wochen kam es ein paar mal dazu, dass Fhem neu gestartet wurde. Dem Neustart geht folgender Eintrag in der log-Datei voraus:

Code Auswählen Erweitern

2021.04.20 20:00:11.556 1:  blockCallcenter[11422], can´t find my parent 10953 in process list !
Died at .//FHEM/96_SIP.pm line 387.
2021.04.20 20:01:35.094 1:  Including fhem.cfg
2021.04.20 20:01:35.822 3:  WEB: port 8083 opened


Was kann das sein?
Was kann ich zur Ursachenforschung beitragen?

Viele​ Grüße​ Gisbert​

[Jamo]

Hallo Gisbert,
das wurde hier schon mal diskutiert, liegt am systemd service der fhem automatisch wieder neu startet.

https://forum.fhem.de/index.php/topic,90042.0.html, siehe Antwort 31

[Gisbert]

Hallo Jamo,

vielen Dank für den Hinweis.
Dieser Thread ist 2 Jahre und 3 Monate alt. Was ich bisher gelernt habe, ist nicht alten Anleitungen blind zu folgen.

Hinzugekommen ist noch ein Freeze von sagenhaften 4 Minuten !!

Code Auswählen Erweitern


2021.04.20 20:31:42.897 1:  [Freezemon] myFreezemon: possible freeze starting at 20:27:33, delay is 249.848 possibly caused by: tmr-SIP_watch_listen(N/A) tmr-MQTT::Timer(MyBroker)

Ich bin etwas ratlos.

Viele​ Grüße​ Gisbert​

[Jamo]

Hallo Gisbert,
Dann aber hier nochmal, von 2019

https://forum.fhem.de/index.php/topic,95399.msg882288.html#msg882288

Wegen dem SIP_watch_listen(N/A) tmr-MQTT::Timer(MyBroker) kann ich Dir leider nicht helfen.

[Otto123]

FHEM startet durch systemd neu wenn es abstürzt.

Die Ursache ist mMn aber irgendwie hier -> Died at .//FHEM/96_SIP.pm
Ich würde die SIP Geschichte erstmal auf Eis legen.

Gruß Otto

[KölnSolar]

Hi Gisbert,
ich bin da bei Otto, da ja deutlich geschrieben steht

2021.04.20 20:00:11.556 1:  blockCallcenter[11422], can´t find my parent 10953 in process list !
Died at .//FHEM/96_SIP.pm line 387.

an oder mit SIP gestorben. Da ist es am Modulentwickler das abzustellen. Wird leider öfter in Perlpaketen genutzt(ich kenns vom DLNARenderer).
Grüße Markus

[Gisbert]

Hallo Wzut,
hallo plin,

könnt ihr euch das anschauen?

Code Auswählen Erweitern

2021.04.20 20:00:11.556 1:  blockCallcenter[11422], can´t find my parent 10953 in process list !
Died at .//FHEM/96_SIP.pm line 387.
2021.04.20 20:01:35.094 1:  Including fhem.cfg
2021.04.20 20:01:35.822 3:  WEB: port 8083 opened

Mit laufendem Fhem bekomme ich in Linux folgendes:

Code Auswählen Erweitern

pi@HPT610:~$ ps aux | grep [f]hem
fhem      1442 29.1  9.7 431300 339592 ?       S    20:01  20:39 /usr/bin/perl fhem
.pl fhem.cfg
fhem      1466  0.0  6.2 306616 217800 ?       S    20:01   0:00 Signal_tx
fhem      2037  0.0  9.1 409612 320428 ?       S    20:22   0:01 /usr/bin/perl fhem
.pl fhem.cfg
fhem     17456  0.2  1.8 3490340 65868 ?       Ssl  Jan16 288:57 java -Xms2m -class
path /opt/fhem/signal-cli/lib/signal-cli-0.7.2.jar:/opt/fhem/signal-cli/lib/signal-
service-java-2.15.3_unofficial_15.jar:/opt/fhem/signal-cli/lib/bcprov-jdk15on-1.68.
jar:/opt/fhem/signal-cli/lib/argparse4j-0.8.1.jar:/opt/fhem/signal-cli/lib/dbus-jav
a-3.2.4.jar:/opt/fhem/signal-cli/lib/slf4j-simple-1.7.30.jar:/opt/fhem/signal-cli/l
ib/libphonenumber-8.12.6.jar:/opt/fhem/signal-cli/lib/jackson-databind-2.9.9.2.jar:
/opt/fhem/signal-cli/lib/signal-metadata-java-0.1.2.jar:/opt/fhem/signal-cli/lib/ok
http-4.6.0.jar:/opt/fhem/signal-cli/lib/zkgroup-java-0.7.0.jar:/opt/fhem/signal-cli
/lib/signal-protocol-java-2.8.1.jar:/opt/fhem/signal-cli/lib/protobuf-javalite-3.10
.0.jar:/opt/fhem/signal-cli/lib/threetenbp-1.3.6.jar:/opt/fhem/signal-cli/lib/java-
utils-1.0.6.jar:/opt/fhem/signal-cli/lib/jnr-unixsocket-0.33.jar:/opt/fhem/signal-c
li/lib/slf4j-api-1.7.30.jar:/opt/fhem/signal-cli/lib/jackson-annotations-2.9.0.jar:
/opt/fhem/signal-cli/lib/jackson-core-2.9.9.jar:/opt/fhem/signal-cli/lib/okio-jvm-2
.6.0.jar:/opt/fhem/signal-cli/lib/kotlin-stdlib-1.3.71.jar:/opt/fhem/signal-cli/lib
/jnr-enxio-0.28.jar:/opt/fhem/signal-cli/lib/jnr-posix-3.0.58.jar:/opt/fhem/signal-
cli/lib/jnr-ffi-2.1.15.jar:/opt/fhem/signal-cli/lib/jnr-constants-0.9.15.jar:/opt/f
hem/signal-cli/lib/curve25519-java-0.5.0.jar:/opt/fhem/signal-cli/lib/kotlin-stdlib
-common-1.3.71.jar:/opt/fhem/signal-cli/lib/annotations-13.0.jar:/opt/fhem/signal-c
li/lib/jffi-1.2.23.jar:/opt/fhem/signal-cli/lib/jffi-1.2.23-native.jar:/opt/fhem/si
gnal-cli/lib/asm-commons-7.1.jar:/opt/fhem/signal-cli/lib/asm-util-7.1.jar:/opt/fhe
m/signal-cli/lib/asm-analysis-7.1.jar:/opt/fhem/signal-cli/lib/asm-tree-7.1.jar:/op
t/fhem/signal-cli/lib/asm-7.1.jar:/opt/fhem/signal-cli/lib/jnr-a64asm-1.0.0.jar:/op
t/fhem/signal-cli/lib/jnr-x86asm-1.0.2.jar org.asamk.signal.Main -u +492143103913 -
-config /opt/fhem/.local/share/signal-cli daemon --system
pi@HPT610:~$ pstree | grep [f]hem
pi@HPT610:~$

Viele​ Grüße​ Gisbert​

[Gisbert]

Hallo Wzut,
hallo plin,

hier noch ein list des Device

Code Auswählen Erweitern

Internals:
   CFGFN      ./FHEM/FritzboxUniFiAnwesenheit.cfg
   FUUID      5f1d89d5-f33f-e986-2326-c7928b4954d735f5
   LPID       2037
   NAME       blockCallcenter
   NOTIFYDEV  global
   NR         109
   NTFY_ORDER 50-blockCallcenter
   STATE      listen_echo
   TYPE       SIP
   VERSION    V1.92 / 21.03.2020
   READINGS:
     2021-04-12 09:00:13   caller          sip:021453914@fritz.box
     2021-04-12 09:00:13   caller_name     unknown
     2021-04-12 09:00:13   caller_nr       021453914
     2021-04-12 09:00:13   caller_state    ignoring
     2021-04-12 09:00:13   caller_time     0
     2021-04-20 22:07:33   expire          300
     2021-02-14 17:30:24   last_error      ListenRegister: Failed with error 110
     2021-04-20 22:07:33   listen_alive    2037
     2021-04-20 22:07:33   state           listen_echo
   helper:
     LISTEN_PID:
       abortArg   
       abortFn   
       arg        blockCallcenter
       bc_pid     68
       finishFn   SIP_ListenDone
       fn         SIP_ListenStart
       pid        2037
       timeout   
     bm:
       SIP_Notify:
         cnt        2
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        20.04. 20:41:09
         max        3.98159027099609e-05
         tot        6.89029693603516e-05
         mAr:
           HASH(0x55941dc83828)
           HASH(0x559418ae1e18)
       SIP_Set:
         cnt        13
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        20.04. 20:26:02
         max        6.79492950439453e-05
         tot        0.000646114349365234
         mAr:
           HASH(0x55941dc83828)
           blockCallcenter
           ?
Attributes:
   alias      block Callcenter
   comment    Die Rufumleitung als Parallelruf zu meiner Mobilnummer wurde gelöscht.
Stattdessen wurden bei allen Festnetznummern Rufumleitungen auf den SIP-Client blockCallcenter (**620) dauerhaft eingerichtet.
Im SIP-Client blockCallcenter werden nur die Rufnummern in der Liste sip_filter angenommen.
Diese Nummern sind Werbenummern, denen beim Anruf ihr eigenes Echo vorgespielt wird (sip_filter echo).
Damit werden die Rufnummern einerseits angenommen, sie laufen aber vollkommen ins Leere.
Die sip_ringtime wurde auf 0.5 Sekunden gesetzt, d.h. nach 0.5 Sekunden hebt der SIP-Client ab.
Mit dieser kurzen Klingeldauer klingelt keines der normalen Telefone, also gibt es keine Belästigung.
Siehe auch: https://wiki.fhem.de/wiki/SIP-Client#Nervende_Werbeanrufe
   devStateIcon .*:fts_shutter_1w_0
   group      FRITZBOX
   history_file ./log/blockCallcenter.sip
   history_size 0
   icon       it_telephone
   room       Network
   sip_dtmf_loop once
   sip_dtmf_send audio
   sip_dtmf_size 2
   sip_elbc   yes
   sip_filter <Nummern gelöscht>
   sip_from   sip:blockCallcenter@fritz.box
   sip_ip     192.168.xx.yy
   sip_listen echo
   sip_port   5070
   sip_registrar 192.168.aa.bb
   sip_ringtime 0.5
   sip_user   blockCallcenter

Viele​ Grüße​ Gisbert​

[yersinia]

Gibt der Systemd-log was sprechendes aus?

Code Auswählen Erweitern

journalctl -S "2021-04-20 19:59:30" -U "2021-04-20 20:03:00"
(Scrollen mit Pfeiltasten bzw Bild-hoch/-runter, verlassen mit q)

[Wzut]

Da ist es am Modulentwickler das abzustellen.

Leider nein, der Modulentwickler hat das mit voller Absicht eingebaut
Hintergrund : Hier stirbt nicht das das eigentliche FHEM Modul mittels die, sondern wir haben hier die Parent - Child Situation durch Blocking.pm vor uns.
Das Kind (Child) schaut halt gegelmäßig nach ob seine Eltern (Parent) noch leben. Ist dies nicht der Fall - z.b. weil der FHEM Haupt Prozess inzwischen beendet oder sogar neu gestartet wurde dann hat diese Waise leider ihre Daseinsberechtigung verloren und muß sterben.
D.h. was da im Log steht ist nicht der Grund eines Absturzes sondern lediglich die Spätfolgen.   

[KölnSolar]

Alles klar, ich kämpfe halt mit Standard-Perlpaketen, die gerne per die etc. aussteigen und das bringt dann den FHEM-Prozess zum Absturz.

Wenn in Deinem Fall nur der (unbedeutendere) child-Prozess "stirbt", ist das wohl in Ordnung(ähnlich hab ich das auch vor).

Bliebe dann nur noch offen, was FHEM zum Absturz brachte. Wenn ich Dich richtig verstehe, dann fand der Absturz ja vorher statt u. Gisbert müsste ein paar Log-Zeilen vor dem Absturz zur Analyse hier einstellen.
@Gisbert: oder hast Du einen Reboot-Mechanismus installiert und es war gar kein Absturz ? Der urlange freeze deutet ja fast darauf hin.  Dann wäre die Ursache im freeze-Log zu suchen.

Grüße Markus

[Gisbert]

Hallo zusammen,
super, dass ihr euch der Sache annehmt.

@yersinia,
hier ist der log, ich hab noch etwas eher abgefragt:

Code Auswählen Erweitern

pi@HPT610:~$ sudo journalctl -S "2021-04-20 19:45:00" -U "2021-04-20 20:03:00"
-- Logs begin at Wed 2021-04-07 12:39:01 CEST, end at Wed 2021-04-21 11:32:49 CEST. --
Apr 20 19:50:01 HPT610 CRON[1171]: pam_unix(cron:session): session opened for user root by (uid=0)
Apr 20 19:50:01 HPT610 CRON[1172]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Apr 20 19:50:02 HPT610 CRON[1171]: pam_unix(cron:session): session closed for user root
Apr 20 20:00:01 HPT610 CRON[1398]: pam_unix(cron:session): session opened for user root by (uid=0)
Apr 20 20:00:01 HPT610 CRON[1399]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Apr 20 20:00:01 HPT610 CRON[1398]: pam_unix(cron:session): session closed for user root
Apr 20 20:00:01 HPT610 kernel: perl[10953]: segfault at 24795 ip 00005603d602c03e sp 00007ffcf789ee00 error 6 in perl[5603d5fe1000+15e000]
Apr 20 20:00:01 HPT610 kernel: Code: 48 89 df e8 74 9d fb ff 48 8b 83 00 02 00 00 48 89 df 48 8b 40 08 48 8b 70 28 e8 ad a4 fe ff 48 8b 83 00 02 00 00 48 8b 40 08 <83> 45 08 01 48 89 68 28 80 7d 0c 0b 0f 84 29 6f 00 00 48 8b 83 00
Apr 20 20:00:01 HPT610 systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV
Apr 20 20:01:31 HPT610 systemd[1]: fhem.service: State 'stop-sigterm' timed out. Killing.
Apr 20 20:01:31 HPT610 systemd[1]: fhem.service: Killing process 10983 (Signal_tx) with signal SIGKILL.
Apr 20 20:01:32 HPT610 systemd[1]: fhem.service: Failed with result 'signal'.
Apr 20 20:01:32 HPT610 systemd[1]: fhem.service: Service RestartSec=100ms expired, scheduling restart.
Apr 20 20:01:32 HPT610 systemd[1]: fhem.service: Scheduled restart job, restart counter is at 24.
Apr 20 20:01:32 HPT610 systemd[1]: Stopped FHEM Home Automation.
Apr 20 20:01:32 HPT610 systemd[1]: Starting FHEM Home Automation...
Apr 20 20:01:35 HPT610 systemd[1]: Started FHEM Home Automation.

@Wzut,
vielen Dank für deine Erklärung. Falls dir doch noch etwas auffällt, dann bitte melde dich.

@Markus,
ich mache in Fhem ein automatisiertes, wöchentliches Update, gefolgt von einem ebenfalls automatisierten shudown restart, das aber Samstags läuft. Einen anderen Reboot-Mechanismus habe ich nicht, bzw. bin mir nicht darüber bewußt.

Der Fhem-logfile gibt nichts nennenswertes her:

Code Auswählen Erweitern

2021.04.20 19:32:34.414 3: [Freezemon] myFreezemon: possible freeze starting at 19:32:33, delay is 1.409 possibly caused by: tmr-CODE(0x5603dc1a9868)(GetUpdate)
2021.04.20 20:00:11.556 1: blockCallcenter[11422], can´t find my parent 10953 in process list !
Died at .//FHEM/96_SIP.pm line 387.
2021.04.20 20:01:35.094 1: Including fhem.cfg
2021.04.20 20:01:35.822 3: WEB: port 8083 opened

Die Freezemonlog-Datei ist sagenhafte 133 MB groß, kann das normal sein?
Im fraglichen Zeitraum sind kaum Einträge vorhanden.
Es gibt zwar ein Device heartbeat, das ist aber schon sehr lange disabled, weil es nicht richtig funktioniert.

Code Auswählen Erweitern

2021.04.20 19:32:34.373 5: monitoring (mymonitoring)
    entering monitoring_modify
        reading:   warning
        operation: add
        value:     VisualCrossingLeverkusen
        at:        2021-04-20 20:32:34
2021.04.20 19:32:34.405 5: End notify loop for VisualCrossingLeverkusen
2021.04.20 19:32:34.406 5: VisualCrossingLeverkusen: HandleSendQueue called from ReadCallback, qlen = 0
2021.04.20 19:32:34.406 5: VisualCrossingLeverkusen: HandleSendQueue found no usable entry in queue
2021.04.20 19:32:34.410 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2021.04.20 19:32:34.410 ---------------------
[Freezemon] myFreezemon: possible freeze starting at 19:32:33, delay is 1.409 possibly caused by: tmr-CODE(0x5603dc1a9868)(GetUpdate)
=========================================================
[Freezemon] myFreezemon: possible freeze starting at 20:02:17, delay is 2.625 possibly caused by: no bad guy found :-(
2021.04.20 20:01:51.139 5: Cmd: >attr myFreezemon fm_logKeep 3<
2021.04.20 20:01:51.140 5: Cmd: >attr myFreezemon group Performance<
2021.04.20 20:01:51.140 5: Cmd: >attr myFreezemon icon system_fhem<
2021.04.20 20:01:51.140 5: Cmd: >attr myFreezemon room Network<
2021.04.20 20:01:51.140 5: Cmd: >attr myFreezemon sortby 1<
2021.04.20 20:01:51.141 5: Cmd: >attr myFreezemon stateFormat Last freeze:<br/>_timestamp<
2021.04.20 20:01:51.141 5: Cmd: >attr myFreezemon userReadings _timestamp {substr(ReadingsTimestamp($name,'state',''),0,16)}<
2021.04.20 20:01:51.141 5: Cmd: >define heartbeat at +*00:01:00 {qx(systemd-notify WATCHDOG=1)}<
2021.04.20 20:01:51.143 5: Cmd: >setuuid heartbeat 5c99fcdd-f33f-e986-0e7c-7f943ce091350200<
2021.04.20 20:01:51.143 5: Cmd: >attr heartbeat disable 1<
2021.04.20 20:01:51.144 5: Cmd: >attr heartbeat group Performance<

Was aber besonders auffällt, ist das ein Wetter-Device (VisualCrossingLeverkusen) für gefühlte 99% dieser Datei verantwortlich sind, Auszug vom Anfang des gestrigen Tages:

Code Auswählen Erweitern

2021.04.20 00:02:31.165 4: VisualCrossingLeverkusen: BodyDecode is not decoding the response body (charset not found, bodyDecode defaults to none)
2021.04.20 00:02:31.180 4: VisualCrossingLeverkusen: extracted JSON values to internal
2021.04.20 00:02:31.181 5: VisualCrossingLeverkusen: GetCookies is looking for Cookies
2021.04.20 00:02:31.181 5: VisualCrossingLeverkusen: ExtractSid called, context reading, num unknown
2021.04.20 00:02:31.181 4: VisualCrossingLeverkusen: checking for redirects, code=200, ignore=0
2021.04.20 00:02:31.181 4: VisualCrossingLeverkusen: no redirects to handle
2021.04.20 00:02:31.181 5: VisualCrossingLeverkusen: Read callback sets LAST_REQUEST to update
2021.04.20 00:02:31.181 5: VisualCrossingLeverkusen: CheckAuth decided no authentication required
2021.04.20 00:02:31.184 5: VisualCrossingLeverkusen: FormatReading is encoding the reading value as utf-8 because no encoding was specified and the response body charset was unknown or decoded
2021.04.20 00:02:31.184 5: VisualCrossingLeverkusen: Read sets reading locations_51.02943__7.05584_values_41_wdir to value 341.8 of JSON locations_51.02943, 7.05584_values_41_wdir
2021.04.20 00:02:31.184 5: VisualCrossingLeverkusen: FormatReading is encoding the reading value as utf-8 because no encoding was specified and the response body charset was unknown or decoded
2021.04.20 00:02:31.184 5: VisualCrossingLeverkusen: Read sets reading locations_51.02943__7.05584_values_56_solarradiation to value 1 of JSON locations_51.02943, 7.05584_values_56_solarradiation
2021.04.20 00:02:31.184 5: VisualCrossingLeverkusen: FormatReading is encoding the reading value as utf-8 because no encoding was specified and the response body charset was unknown or decoded

Beitrag editiert, da der eingefügte Code nicht richtig dargestellt wurde.
Das Device habe ich vorsorglich gestoppt.

Viele Grüße Gisbert

[Otto123]

Ich würde denken hier findet das Sterben statt:

Code Auswählen Erweitern

Apr 20 20:00:01 HPT610 CRON[1398]: pam_unix(cron:session): session opened for user root by (uid=0)
Apr 20 20:00:01 HPT610 CRON[1399]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Apr 20 20:00:01 HPT610 CRON[1398]: pam_unix(cron:session): session closed for user root
Apr 20 20:00:01 HPT610 kernel: perl[10953]: segfault at 24795 ip 00005603d602c03e sp 00007ffcf789ee00 error 6 in perl[5603d5fe1000+15e000]
Apr 20 20:00:01 HPT610 kernel: Code: 48 89 df e8 74 9d fb ff 48 8b 83 00 02 00 00 48 89 df 48 8b 40 08 48 8b 70 28 e8 ad a4 fe ff 48 8b 83 00 02 00 00 48 8b 40 08 <83> 45 08 01 48 89 68 28 80 7d 0c 0b 0f 84 29 6f 00 00 48 8b 83 00
Apr 20 20:00:01 HPT610 systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV

Den hier würd ich  mal deaktivieren um weiter einzugrenzen:
pihole updatechecker local weil in unmittelbarer Folge stürzt der FHEM Prozess ab perl[10953] - wenn ich alles richtig interpretiere ... 

[Gisbert]

Ich würde denken hier findet das Sterben statt:

Code Auswählen Erweitern

Apr 20 20:00:01 HPT610 CRON[1398]: pam_unix(cron:session): session opened for user root by (uid=0)
Apr 20 20:00:01 HPT610 CRON[1399]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Apr 20 20:00:01 HPT610 CRON[1398]: pam_unix(cron:session): session closed for user root
Apr 20 20:00:01 HPT610 kernel: perl[10953]: segfault at 24795 ip 00005603d602c03e sp 00007ffcf789ee00 error 6 in perl[5603d5fe1000+15e000]
Apr 20 20:00:01 HPT610 kernel: Code: 48 89 df e8 74 9d fb ff 48 8b 83 00 02 00 00 48 89 df 48 8b 40 08 48 8b 70 28 e8 ad a4 fe ff 48 8b 83 00 02 00 00 48 8b 40 08 <83> 45 08 01 48 89 68 28 80 7d 0c 0b 0f 84 29 6f 00 00 48 8b 83 00
Apr 20 20:00:01 HPT610 systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV

Den hier würd ich  mal deaktivieren um weiter einzugrenzen:
pihole updatechecker local weil in unmittelbarer Folge stürzt der FHEM Prozess ab perl[10953] - wenn ich alles richtig interpretiere ... 

Hallo Otto,
der pihole Cronjob sieht folgendermaßen:

Code Auswählen Erweitern

# Pi-hole: A black hole for Internet advertisements
# (c) 2017 Pi-hole, LLC (https://pi-hole.net)
# Network-wide ad blocking via your own hardware.
#
# Updates ad sources every week
#
# This file is copyright under the latest version of the EUPL.
# Please see LICENSE file for your rights under this license.
#
#
#
# This file is under source-control of the Pi-hole installation and update
# scripts, any changes made to this file will be overwritten when the software
# is updated or re-installed. Please make any changes to the appropriate crontab
# or other cron file snippets.

# Pi-hole: Update the ad sources once a week on Sunday at a random time in the
#          early morning. Download any updates from the adlists
#          Squash output to log, then splat the log to stdout on error to allow for
#          standard crontab job error handling.
34 3   * * 7   root    PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updateGravity >/var/log/pihole_updateGravity.log || cat /var/log/pihole_updateGravity.log

# Pi-hole: Flush the log daily at 00:00
#          The flush script will use logrotate if available
#          parameter "once": logrotate only once (default is twice)
#          parameter "quiet": don't print messages
00 00   * * *   root    PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole flush once quiet

@reboot root /usr/sbin/logrotate /etc/pihole/logrotate

# Pi-hole: Grab local version and branch every 10 minutes
*/10 *  * * *   root    PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local

# Pi-hole: Grab remote version every 24 hours
28 12  * * *   root    PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker remote
@reboot root    PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker remote reboot

Der Systemd-log passt von der Uhrzeit exakt (bis auf eine Sekunde Abweichung) zur folgenden Passage im CronJob:

Code Auswählen Erweitern

# Pi-hole: Grab local version and branch every 10 minutes
*/10 *  * * *   root    PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local

Hast du eine Idee, was ich ändern sollte?

Viele​ Grüße​ Gisbert​

[Wernieman]

Einfach mal Auskommentieren ..

Weißt Du, wofür das Script ist? Mir ist es so nicht bekannt .. und läuft alle 10 Minuten??

Btw: Was für ein Betriebsystem?

Code Auswählen Erweitern

cat /etc/debian_version

[Gisbert]

Hallo Wernieman,

ich hab Debian 10.9.
In Github findet sich diese Zeile auch beim CronJob:
https://github.com/pi-hole/pi-hole/blob/master/advanced/Templates/pihole.cron
Was wären denn die Nebenwirkungen, wenn ich diese Zeile auskommentiere?

Viele​ Grüße​ Gisbert​

[Wernieman]

Du hast also zusätzlich pihole auf dem Pi?
Was hast Du noch auf dem Pi? Wäre eventuell sehr wichtig für uns ...

Da ich pihole auf einem x86 im Docker betriebe, kann ich Dir nicht sagen, was dieses Script denn macht. Aber testweise solltest Du es ohne Probleme 24h ausschalten können *) durch auskommentieren mit "#". Du kannst es ja derzeit wieder aktivieren, durch entfernen des "#"

*) Ich gebe Dir aber keine Garantie .....

[Gisbert]

Hallo Wernieman,

auf meinem HP T610 laufen:

• Fhem
• Pi-hole
• unbound
• UniFi Controller
• ein MQTT-Broker: mosquitto
• proftpd - keine Ahnung, für was ich das benötige
• ein frei verfügbarer Virenscanner für Linux: Sophos AV

Ich kann das auskommentieren; hoffentlich kann ich mich dann noch einloggen, falls es notwendig ist, und pi-hole in Kombination mit unbound mich nicht aussperrt. Ich beobachte lieber etwas weiter und sammele weitere Informationen.

Das merkwürdige ist, dass Pi-hole schon sehr lange läuft, kürzlich dazu gekommen ist unbound, mit entsprechenden Änderungen bei Pi-hole.

Durch diese Aktion bin ich auf sehr häufige Freezes des Wettermoduls VisualCrossing gestoßen, welches ich vorerst gestoppt habe - immerhin etwas positives.

Viele​ Grüße​ Gisbert​

[Wernieman]

Also wenn das Dich aussperrt ... ein CRON-Job der alle 10 Minuten läuft ... s.o. es ist umkehrbar ...

Du hast alles nativ installiert?

Code Auswählen Erweitern

Edit:
Warum unbound + pihole? pihole cached doch selber DNS Abfragen??

[yersinia]

Ich würde denken hier findet das Sterben statt:

Code Auswählen Erweitern

Apr 20 20:00:01 HPT610 CRON[1398]: pam_unix(cron:session): session opened for user root by (uid=0)
Apr 20 20:00:01 HPT610 CRON[1399]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Apr 20 20:00:01 HPT610 CRON[1398]: pam_unix(cron:session): session closed for user root
Apr 20 20:00:01 HPT610 kernel: perl[10953]: segfault at 24795 ip 00005603d602c03e sp 00007ffcf789ee00 error 6 in perl[5603d5fe1000+15e000]
Apr 20 20:00:01 HPT610 kernel: Code: 48 89 df e8 74 9d fb ff 48 8b 83 00 02 00 00 48 89 df 48 8b 40 08 48 8b 70 28 e8 ad a4 fe ff 48 8b 83 00 02 00 00 48 8b 40 08 <83> 45 08 01 48 89 68 28 80 7d 0c 0b 0f 84 29 6f 00 00 48 8b 83 00
Apr 20 20:00:01 HPT610 systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV

Den hier würd ich  mal deaktivieren um weiter einzugrenzen:
pihole updatechecker local weil in unmittelbarer Folge stürzt der FHEM Prozess ab perl[10953] - wenn ich alles richtig interpretiere ... 

Es gibt um 20:00:01 ein segfault, und ich vermute eher ein Device in FHEM welches genau um 20:00:00 ausgeführt wird und dann den Absturz führt.

Code Auswählen Erweitern

Apr 20 20:00:01 HPT610 kernel: perl[10953]: segfault at 24795 ip 00005603d602c03e sp 00007ffcf789ee00 error 6 in perl[5603d5fe1000+15e000]
Der pihole-cron ist in der Tat kurios, aber deswegen einen perl-prozess abstürzen zu lassen?
FHEM reagiert ja auch ganze 90 sekunden nicht auf das sigkill signal:

Code Auswählen Erweitern

Apr 20 20:00:01 HPT610 kernel: perl[10953]: segfault at 24795 ip 00005603d602c03e sp 00007ffcf789ee00 error 6 in perl[5603d5fe1000+15e000]
Apr 20 20:00:01 HPT610 kernel: Code: 48 89 df e8 74 9d fb ff 48 8b 83 00 02 00 00 48 89 df 48 8b 40 08 48 8b 70 28 e8 ad a4 fe ff 48 8b 83 00 02 00 00 48 8b 40 08 <83> 45 08 01 48 89 68 28 80 7d 0c 0b 0f 84 29 6f 00 00 48 8b 83 00
Apr 20 20:00:01 HPT610 systemd[1]: fhem.service: Main process exited, code=killed, status=11/SEGV
Apr 20 20:01:31 HPT610 systemd[1]: fhem.service: State 'stop-sigterm' timed out. Killing. <================ HIER
Apr 20 20:01:31 HPT610 systemd[1]: fhem.service: Killing process 10983 (Signal_tx) with signal SIGKILL.
Apr 20 20:01:32 HPT610 systemd[1]: fhem.service: Failed with result 'signal'.
Apr 20 20:01:32 HPT610 systemd[1]: fhem.service: Service RestartSec=100ms expired, scheduling restart.
Apr 20 20:01:32 HPT610 systemd[1]: fhem.service: Scheduled restart job, restart counter is at 24.

Ich habe ein ähnliches Verhalten mit einem (!) JsonMod-Device gehabt, seit dem ich dieses erst testhalber deaktiviert und dann gelöscht habe ist Ruhe.

In Github findet sich diese Zeile auch beim CronJob:
https://github.com/pi-hole/pi-hole/blob/master/advanced/Templates/pihole.cron
Was wären denn die Nebenwirkungen, wenn ich diese Zeile auskommentiere?

Ich wüsste nicht, warum pihole alle 10 minuten lokal auf Updates prüfen sollte. Das cron-file ist:

Code Auswählen Erweitern

/etc/cron.d/pihole

[frank]

Der Fhem-logfile gibt nichts nennenswertes her:

global verbose hochdrehen.

[Gisbert]

Hallo yersinia,

vielen Dank für deine Analyse.
Ich habe im CornJobs des Pi-holes die entsprechende Stelle auf einmal wöchentlich Ausführen gesetzt.
Da der Fhem-Absturz ja so sporadisch auftritt, muss ich beobachten, was geschieht.

Hallo frank,

ich hab derzeit verbose 3; verbose 5 holzt im Millisekundentakt Daten in den logfile, ich probiere dann mal, was bei verbose 4 rauskommt.
Ber verbose 4 wird auch fleissigst geloggt.
Da scheine ich ja wohl nur die Wahl zwischen Skylla und Charybdis zu haben.

Ich lasse es mal eine zeitlang bei verbose 4, es sei denn es kommt Widerspruch.

Viele Grüße Gisbert