Nachdem ich heute ein Update von FHEM gemacht habe, startet FHEM nicht mehr, bzw. startet in einer Endlosschleife immer wieder neu.
Die letzten Log-Einträge sind:
2017.10.02 16:11:48.282 1: BlockingInformParent (BlockingStart): Can't connect to localhost:37201: IO::Socket::INET: connect: Connection refused
2017.10.02 16:11:48.284 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:37201: IO::Socket::INET: connect: Connection refused
2017.10.02 16:11:48.309 1: BlockingInformParent (BlockingStart): Can't connect to localhost:37201: IO::Socket::INET: connect: Connection refused
2017.10.02 16:11:48.311 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:37201: IO::Socket::INET: connect: Connection refused
Die Portnummer ist variabel, d.h. sie ändert sich bei jedem Startversuch. Ich habe aber an irgendwelchen PRESENCE-Einträgen schon ewig nichts geändert. Da ich configDB nutze, kann ich die Einträge auch nicht so ganz einfach auskommentieren. :-\
Wie kann ich dem Fehler auf den Grund gehen? Womit will sich PRESENCE denn verbinden?
ZitatWomit will sich PRESENCE denn verbinden?
Mit dem "Haupt-FHEM".
Versuch bitte eine telnet Instanz anzulegen (ohne Passwort, und gerne ohne "global"), und pruefen, ob es damit besser funktioniert.
Ohne definierte telnet-Instanz wird eine dynamisch angelegt, damit das geforkte Prozess (aka BlockingCall, verwendet von PRESENCE) die berechneten Daten an die Haupt-Instanz zurueckgeben kann.
Hm, PRESENCE selbst war gar nicht vom Update betroffen:
pi@raspberrypi:/opt/fhem $ ls restoreDir/2017-10-02/FHEM/
00_OWX.pm 14_SD_WS.pm 75_msgConfig.pm
00_SIGNALduino.pm 31_LightScene.pm 90_SIGNALduino_un.pm
00_SONOS.pm 32_LedController.pm 93_DbLog.pm
10_FS10.pm 36_EleroDrive.pm 98_ArduCounter.pm
10_MQTT_BRIDGE.pm 41_OREGON.pm 98_cmdalias.pm
14_BresserTemeo.pm 49_SSCam.pm 98_Dooya.pm
14_FLAMINGO.pm 70_Pushover.pm 98_monitoring.pm
14_Hideki.pm 71_YAMAHA_AVR.pm controls_fhem.txt
14_SD_AS.pm 72_FB_CALLLIST.pm controls_ledcontroller.txt
14_SD_RSL.pm 72_FRITZBOX.pm controls_signalduino.txt
14_SD_UT.pm 73_AMADCommBridge.pm firmware
14_SD_WS07.pm 73_GardenaSmartBridge.pm lib
14_SD_WS09.pm 74_AMADDevice.pm msgSchema.pm
14_SD_WS_Maverick.pm 74_XiaomiFlowerSens.pm
Warum taucht dann aber PRESENCE_ProcessLocalScan als letzter Log-Eintrag auf?
Edit: Da war Rudi schneller. ;)
Eine Telnet-Instanz gibt es auf Port 7072, also wie im Standard. Trotzdem wird eine zusätzliche telnet-Instanz angelegt:
2017.10.02 15:50:24.771 3: telnetPort: port 7072 opened
2017.10.02 15:50:59.661 3: telnetForBlockingFn_1506952259: port 35529 opened
Das hat bis vor dem Update auch funktioniert, danach nicht mehr.
BlockingCall verwendet keine telnet Instanzen, die ein Passwort benoetigen.
Ich spiele jetzt erst einmal das Backup von letzter Nacht ein, dann seh ich mir mal die telnet-Instanz an.
So, Backup eingespielt und FHEM läuft wieder. :)
Hier die Ausgabe von version mit den Versionen aus dem Backup:
File Rev Last Change
fhem.pl 15112 2017-09-21 07:22:33Z rudolfkoenig
57_ABFALL.pm 11020 2017-09-13 00:40:21Z uniqueck
96_allowed.pm 14888 2017-08-13 12:07:12Z rudolfkoenig
90_at.pm 14995 2017-09-03 14:23:14Z rudolfkoenig
98_autocreate.pm 15038 2017-09-10 10:00:18Z rudolfkoenig
57_Calendar.pm 14832 2017-08-01 18:36:03Z neubert
57_CALVIEW.pm 15061 2017-09-13 20:05:11Z chris1284
98_cmdalias.pm 14835 2017-08-02 07:37:54Z rudolfkoenig
00_CUL.pm 15027 2017-09-08 09:11:43Z rudolfkoenig
14_CUL_MAX.pm 12440 2016-10-26 20:24:45Z mgehre
37_dash_dhcp.pm 12926 2017-01-01 13:07:33Z justme1968
98_dewpoint.pm 6757 2014-10-12 18:58:57Z joachim09876
98_DOIF.pm 14790 2017-07-26 10:27:41Z Damian
98_DOIFtools.pm 14806 2017-07-28 06:21:38Z Ellert
98_dummy.pm 12700 2016-12-02 16:49:42Z rudolfkoenig
64_ESA2000.pm 7243 2014-12-17 13:04:32Z stromer-12
91_eventTypes.pm 14888 2017-08-13 12:07:12Z rudolfkoenig
01_FHEMWEB.pm 15111 2017-09-21 07:08:41Z rudolfkoenig
92_FileLog.pm 14888 2017-08-13 12:07:12Z rudolfkoenig
No Id found for 98_FireTV.pm
98_FReplacer.pm 13876 2017-04-02 09:08:03Z StefanStrobel
98_GEOFANCY.pm 14110 2017-04-26 06:54:58Z loredo
98_GoogleAuth.pm 13155 2017-01-20 16:01:24Z betateilchen
95_holiday.pm 15042 2017-09-10 13:59:16Z rudolfkoenig
98_HTTPMOD.pm 15035 2017-09-09 12:02:21Z StefanStrobel
02_HTTPSRV.pm 13976 2017-04-12 13:35:44Z neubert
30_HUEBridge.pm 15123 2017-09-23 17:20:38Z justme1968
31_HUEDevice.pm 14256 2017-05-12 13:35:40Z justme1968
10_IT.pm 14852 2017-08-06 08:48:24Z bjoernh
36_JeeLink.pm 14707 2017-07-13 18:08:33Z justme1968
36_LaCrosse.pm 13301 2017-02-01 18:21:32Z HCS
30_LIGHTIFY.pm 13672 2017-03-11 23:20:19Z justme1968
98_logProxy.pm 13399 2017-02-12 13:00:43Z justme1968
10_MAX.pm 12107 2016-09-01 18:25:08Z mgehre
98_MaxScanner.pm 11044 2016-03-11 19:18:03Z john99sr
30_MilightBridge.pm 11710 2016-06-24 09:07:17Z mattwire
31_MilightDevice.pm 11177 2016-04-03 11:40:34Z markus-m
75_msgConfig.pm 14012 2017-04-17 13:09:41Z loredo
99_myUtils.pm 4711 2017-03-08 09:18:44Z mahowi
74_Nmap.pm 14107 2017-04-26 03:51:05Z igami
91_notify.pm 14888 2017-08-13 12:07:12Z rudolfkoenig
34_NUT.pm 9023 2015-08-05 09:00:12Z narsskrarc
No Id found for 99_perfmon.pm
10_pilight_ctrl.pm 14997 2017-09-03 17:27:39Z Risiko
73_PRESENCE.pm 15140 2017-09-26 09:20:09Z markusbloch
70_Pushbullet.pm 9730 2015-10-30 15:06:41Z fhainz
70_Pushover.pm 14012 2017-04-17 13:09:41Z loredo
33_readingsGroup.pm 15100 2017-09-19 21:21:27Z justme1968
No Id found for 98_ReadingsSupervision.pm
95_remotecontrol.pm 10724 2016-02-04 18:17:33Z ulimaass
10_RESIDENTS.pm 14136 2017-04-29 16:31:46Z loredo
No Id found for 19_Revolt.pm
43_RFXX10REC.pm 5599 2014-04-22 15:26:46Z wherzig
20_ROOMMATE.pm 14136 2017-04-29 16:31:46Z loredo
98_SB_PLAYER.pm 88 2017-09-17 21:07:00Z CD/MM/Matthew/Heppel
97_SB_SERVER.pm 43 2017-08-20 18:19:00Z CD
00_SIGNALduino.pm 10488 2017-09-08 19:00:00Z v3.3.1-dev
No Id found for 98_SmarterCoffee.pm
54_SOW323.pm 6 2017-05-03 17:30:00Z FHEM_RIIR
No Id found for 70_SpeedPortHybridReadings.pm
32_speedtest.pm 12056 2016-08-22 19:30:31Z justme1968
37_Spotify.pm 14987 2017-09-02 13:14:37Z neumann
98_statistics.pm 12218 2016-09-27 19:25:42Z grompo
98_structure.pm 15129 2017-09-24 08:58:57Z rudolfkoenig
70_STV.pm 12857 2016-12-21 11:59:33Z Zwiebel
99_SUNRISE_EL.pm 14888 2017-08-13 12:07:12Z rudolfkoenig
98_SVG.pm 14888 2017-08-13 12:07:12Z rudolfkoenig
42_SYSMON.pm 14823 2017-07-31 16:53:41Z hexenmeister
50_TelegramBot.pm 15131 2017-09-24 19:37:07Z viegener
98_telnet.pm 15006 2017-09-05 09:37:33Z rudolfkoenig
98_THRESHOLD.pm 14179 2017-05-03 20:10:16Z Damian
99_Utils.pm 13259 2017-01-28 17:39:39Z rudolfkoenig
77_UWZ.pm 14680 2017-07-09 15:15:13Z CoolTux
98_version.pm 15140 2017-09-26 09:20:09Z markusbloch
91_watchdog.pm 14888 2017-08-13 12:07:12Z rudolfkoenig
98_weblink.pm 14888 2017-08-13 12:07:12Z rudolfkoenig
98_weekprofile.pm 14084 2017-04-23 11:57:48Z Risiko
59_Wunderground.pm 14401 2017-05-28 13:44:29Z loredo
# $Id: 98_wunderlist.pm 3700 Version 0.7.1 2017-01-14 10:43:10Z marvin1978 $
# $Id: 59_WUup.pm 11 2017-08-216 20:43:35Z mahowi $
No Id found for 71_XiaomiSmartHome.pm
No Id found for 71_XiaomiSmartHome_Device.pm
32_yowsup.pm 12219 2016-09-29 10:03:25Z justme1968
10_ZWave.pm 15064 2017-09-14 18:34:05Z rudolfkoenig
00_ZWDongle.pm 15055 2017-09-12 15:41:02Z rudolfkoenig
ABFALL_getEvents.pm 11021 2017-09-13 00:32:22Z uniqueck
ABFALL_setUpdate.pm 11021 2017-09-13 00:32:22Z uniqueck
Blocking.pm 15128 2017-09-24 08:16:16Z rudolfkoenig
Color.pm 11159 2016-03-30 16:08:06Z justme1968
configDB.pm 15096 2017-09-19 12:55:19Z betateilchen
DevIo.pm 14933 2017-08-20 14:21:58Z rudolfkoenig
HttpUtils.pm 15041 2017-09-10 13:52:34Z rudolfkoenig
No Id found for MaxCommon.pm
msgSchema.pm 14012 2017-04-17 13:09:41Z loredo
RESIDENTStk.pm 14160 2017-05-01 19:43:40Z loredo
RTypes.pm 10476 2016-01-12 21:03:33Z borisneubert
SetExtensions.pm 12935 2017-01-02 19:51:46Z rudolfkoenig
SubProcess.pm 14334 2017-05-20 23:11:06Z neubert
TcpServerUtils.pm 14862 2017-08-07 15:16:03Z rudolfkoenig
TimeSeries.pm 10907 2016-02-21 17:38:02Z borisneubert
UConv.pm 14398 2017-05-28 09:40:42Z loredo
Unit.pm 14136 2017-04-29 16:31:46Z loredo
ZWLib.pm 12651 2016-11-25 15:12:14Z rudolfkoenig
fhemweb.js 14906 2017-08-15 20:06:05Z rudolfkoenig
fhemweb_colorpicker.js 13580 2017-03-02 13:03:29Z justme1968
fhemweb_fbcalllist.js 13629 2017-03-06 20:50:43Z markusbloch
fhemweb_readingsGroup.js 13580 2017-03-02 13:03:29Z justme1968
fhemweb_readingsHistory.js 13580 2017-03-02 13:03:29Z justme1968
fhemweb_sortable.js 13629 2017-03-06 20:50:43Z markusbloch
fhemweb_uzsu.js 13580 2017-03-02 13:03:29Z justme1968
Es wird eine telnet-Instanz dynamisch angelegt, aber ohne Probleme:
2017.10.02 18:12:09.204 3: telnetPort: port 7072 opened
2017.10.02 18:12:41.069 3: telnetForBlockingFn_1506960761: port 46091 opened
list telnetPort:
Internals:
CFGFN
CONNECTS 1
DEF 7072 global
FD 4
NAME telnetPort
NR 2
NTFY_ORDER 50-telnetPort
PORT 7072
STATE Initialized
TYPE telnet
Attributes:
telnetPort hat ein gesetztes Paßwort, daher kann BlockingCall die Instanz also nicht verwenden:
Internals:
CFGFN
NAME allowed_telnetPort
NR 3
STATE validFor:telnetPort
TYPE allowed
validFor telnetPort
READINGS:
2017-10-02 18:12:09 state validFor:telnetPort
Attributes:
globalpassword SHA256:xxxxx
validFor telnetPort
Wie kann ich jetzt herausfinden, was da beim Update schiefgelaufen ist?
Um es rauszufinden brauche ich ein paar Infos mit der FHEM-Version, wo das Problem auftritt:
- Ausgabe von "list TYPE=telnet"
- Alle telnetForBlockingFn.*opened Zeilen aus dem Log, und alle unterschiedlichen BlockingInformParent.*Connection refused Zeilen (komplett mit Zeitstempel).
- Wurde nach dem FHEM-Start ein rereadcfg ausgefuehrt (evtl. durch Edit Files / fhem.cfg in FHEMWEB)? Das wuerde das Problem erklaeren. Erkennbar im FHEM-Log an "Including fhem.cfg"
FHEM Version ist auf dem Stand vom 28.09., die einzelnen Versionen habe ich im letzten Post angegeben. Der Fehler trat nach dem Update auf den Stand vom 02.10. auf.
list TYPE=telnet:
telnetForBlockingFn_1507005413
telnetPort
pi@raspberrypi:/opt/fhem/log $ grep --binary-files=text telnetForBlockingFn.*opened fhem-2017-10.log
2017.10.01 01:08:52.506 3: telnetForBlockingFn_1506812932: port 41517 opened
2017.10.01 13:57:39.664 3: telnetForBlockingFn_1506859059: port 42577 opened
2017.10.01 13:58:40.209 3: telnetForBlockingFn_1506859120: port 36895 opened
2017.10.01 14:35:08.521 3: telnetForBlockingFn_1506861308: port 37259 opened
2017.10.01 18:51:05.590 3: telnetForBlockingFn_1506876665: port 39461 opened
2017.10.02 18:12:41.069 3: telnetForBlockingFn_1506960761: port 46091 opened
2017.10.03 00:21:46.654 3: telnetForBlockingFn_1506982906: port 35479 opened
2017.10.03 05:49:33.087 3: telnetForBlockingFn_1507002573: port 41321 opened
2017.10.03 06:36:53.632 3: telnetForBlockingFn_1507005413: port 34275 opened
pi@raspberrypi:/opt/fhem/log $ grep --binary-files=text BlockingInformParent.*Connection fhem-2017-10.log
2017.10.03 00:21:12.650 1: BlockingInformParent (BlockingStart): Can't connect to localhost:46091: IO::Socket::INET: connect: Connection refused
2017.10.03 00:21:12.652 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:46091: IO::Socket::INET: connect: Connection refused
2017.10.03 05:48:59.507 1: BlockingInformParent (BlockingStart): Can't connect to localhost:35479: IO::Socket::INET: connect: Connection refused
2017.10.03 05:48:59.508 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:35479: IO::Socket::INET: connect: Connection refused
2017.10.03 06:36:19.316 1: BlockingInformParent (BlockingStart): Can't connect to localhost:41321: IO::Socket::INET: connect: Connection refused
2017.10.03 06:36:19.317 1: BlockingInformParent (PRESENCE_ProcessLocalScan): Can't connect to localhost:41321: IO::Socket::INET: connect: Connection refused
Ich habe FHEM nach dem Update lediglich mittels shutdown 1 neu gestartet. Ich habe weder die Konfiguration editiert noch händisch rereadcfg ausgeführt.
Kannst du bitte fuer den fraglichen Zeitraum auch noch die "Including" Zeilen aus dem Log hier anhaengen?
Wenn nicht jeweils kurz vor der "opened" Meldung so ein "Including" zu sehen ist, dann bin ich ratlos: irgendwer loescht die telnet-Instanzen, mir ist aber dafuer kein Mechanismus bekannt. Ich wuerde vermutlich in FHEM/TcpServerUtils.pm/TcpServer_Close() ein stacktrace() einbauen, um zu wissen, wer das ausloest.
Hm, es gibt keine Zeilen mit "Including" o.ä. im Log.
Ich wage jetzt nochmal ein Update und sehe mal, was passiert.
So, Update gemacht und alles funktioniert noch. Sehr merkwürdig das Ganze. ::) Was immer es auch war, es scheint jetzt behoben zu sein.