JSON parse error aber nur wenn Aufruf über Traefik

eddy242 · 05 August 2022, 20:09:05

Hallo zusammen,

ich erhalte reproduzierbar die Fehlermeldung

fhemweb.js line 1215:
SyntaxError: JSON.parse: unexpected character at line 1 column 3 of the JSON data

beim Aufruf über den Reverse Proxy Traefik und mittels ducknds-DNS-Alias (fhem läuft im Docker). Beim Aufruf der Seite aus dem lokalen Netz mit fester lokaler URL ist alles prima.

Getestet mit sowohl im Edge als auch im Firefox. fhem update und Neustart ist gemacht (das Problem ist schon seit Wochen da). Stacktrace ist aktiviert und zeigt folgendes. Danke für Hinweise!

Code Auswählen


2022.08.05 20:00:36.088 1:     main::CallFn                        called by fhem.pl (782)
2022.08.05 20:00:36.088 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.05 20:00:36.088 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.05 20:00:36.088 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.05 20:00:36.088 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (685)
2022.08.05 20:00:36.088 1: stacktrace:
2022.08.05 20:00:36.088 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 685.
2022.08.05 20:00:36.088 1:     main::CallFn                        called by fhem.pl (782)
2022.08.05 20:00:36.088 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.05 20:00:36.088 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.05 20:00:36.088 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.05 20:00:36.088 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (684)
2022.08.05 20:00:36.088 1: stacktrace:
2022.08.05 20:00:36.088 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 684.
2022.08.05 20:00:31.499 1:     main::CallFn                        called by fhem.pl (782)
2022.08.05 20:00:31.499 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.05 20:00:31.498 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.05 20:00:31.498 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.05 20:00:31.498 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (685)
2022.08.05 20:00:31.498 1: stacktrace:
2022.08.05 20:00:31.498 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 685.
2022.08.05 20:00:31.498 1:     main::CallFn                        called by fhem.pl (782)
2022.08.05 20:00:31.498 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.05 20:00:31.498 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.05 20:00:31.498 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.05 20:00:31.498 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (684)
2022.08.05 20:00:31.498 1: stacktrace:
2022.08.05 20:00:31.498 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 684.
2022.08.05 20:00:00.438 1:     main::CallFn                        called by fhem.pl (782)
2022.08.05 20:00:00.438 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.05 20:00:00.438 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.05 20:00:00.438 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.05 20:00:00.438 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (685)
2022.08.05 20:00:00.438 1: stacktrace:
2022.08.05 20:00:00.438 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 685.
2022.08.05 20:00:00.438 1:     main::CallFn                        called by fhem.pl (782)
2022.08.05 20:00:00.438 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.05 20:00:00.438 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.05 20:00:00.438 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.05 20:00:00.438 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (684)
2022.08.05 20:00:00.438 1: stacktrace:
2022.08.05 20:00:00.438 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 684.
2022.08.05 20:00:00.187 3: DOIF_Calendarevents: Heiko.Homeoffice.active now off from calendar_heiko
2022.08.05 19:59:55.649 1:     main::CallFn                        called by fhem.pl (782)
2022.08.05 19:59:55.649 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.05 19:59:55.649 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.05 19:59:55.649 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.05 19:59:55.649 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (685)
2022.08.05 19:59:55.649 1: stacktrace:
2022.08.05 19:59:55.649 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 685.
2022.08.05 19:59:55.649 1:     main::CallFn                        called by fhem.pl (782)
2022.08.05 19:59:55.649 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.05 19:59:55.649 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.05 19:59:55.649 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.05 19:59:55.648 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (684)
2022.08.05 19:59:55.648 1: stacktrace:
2022.08.05 19:59:55.648 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 684.

Grüsse
eddy242

rudolfkoenig · 05 August 2022, 20:29:44

Was steht in der JavaScript-Console des Browsers?

eddy242 · 05 August 2022, 21:02:03

Das u.a. Sniplet wiederholt sich sinngemäß mit anderen Devices. Sieht nach DOIF uiTable Ursache aus? Soll ich die Frage im DOIF Board stellen?

Code Auswählen


20:56:20.865 Rcvd: #FHEMWEB:WEB<<doifUpdateCell('DOIF_Dashboard','doifId','DOIF_Dashboard_uiTable_c_9_2_0_0','<svg xmlns="http://www.w3.org/2000/svg" v...(9709) fhemweb.js:576:13
Uncaught SyntaxError: JSON.parse: unexpected character at line 1 column 1 of the JSON data
    FW_doUpdate https://xxxreplacedxxx.duckdns.org/fhem/pgm2/fhemweb.js:1215
    FW_longpoll https://xxxreplacedxxx.duckdns.org/fhem/pgm2/fhemweb.js:1342
    <anonymous> https://xxxreplacedxxx.duckdns.org/fhem/pgm2/fhemweb.js:100
fhemweb.js:1215:18

rudolfkoenig · 06 August 2022, 08:55:08

#1: ist das eine FHEMWEB Seite, oder was davon Abgeleitetes (FUIP, etc?).
#2: kannst Du bitte erst "attr WEB verbose 5" setzen, dann den Fehler reproduzieren, und zum Schluss aus dem FHEM-Log die Zeile mit "GET /fhem?..." hier zeigen, die vor der Fehlermeldung im Log auftaucht?
#3: diese Zeile kann man auch im Browser im Network Tab (ist neben der JavaScript Console zu finden) beobachten. Die Werte sollten (bis auf GET und HTTP/1) identisch sein, bitte pruefen
#4: steht das longpoll Attribut (evtl. wg. Voreinstellung) auf websocket? Das wird beim Aufruf der Seite in der JavaScript-Console am Anfang ausgegeben als "Inform-channel opened (websocket) with filter ". Diese Zeile interessiert mich auch.

eddy242 · 07 August 2022, 21:23:13

#1 rein FHEMWEB
#2 ich bin nicht sicher ob ich hier die richtigen Stellen aus dem Log rausgenommen habe:

Code Auswählen


2022.08.07 21:10:15.700 1: stacktrace:
2022.08.07 21:10:15.700 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (685)
2022.08.07 21:10:15.700 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.07 21:10:15.700 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.07 21:10:15.700 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.07 21:10:15.700 1:     main::CallFn                        called by fhem.pl (782)
2022.08.07 21:10:32.428 4: Connection closed for WEB_172.21.0.27_54020: EOF
2022.08.07 21:10:32.428 4: Connection accepted from WEB_172.21.0.27_54068
2022.08.07 21:10:32.431 5: GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2022-08-07.log HTTP/1.1
Host: xxxreplacedxxx.duckdns.org
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:103.0) Gecko/20100101 Firefox/103.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.5
Authorization: Basic bGFuZG86Z3JrbjczbnM=
Cookie: authelia_session=xxxreplacedxxx
Referer: https://xxxreplacedxxx.duckdns.org/fhem?room=ControlCenter
Remote-Email: xxxreplacedxxx
Remote-Groups: xxxreplacedxxx
Remote-Name: xxxreplacedxxx
Remote-User: xxxreplacedxxx
Sec-Fetch-Dest: document
Sec-Fetch-Mode: navigate
Sec-Fetch-Site: same-origin
Sec-Fetch-User: ?1
Te: trailers
Upgrade-Insecure-Requests: 1
X-Forwarded-For: 88.152.2.117
X-Forwarded-Host: xxxreplacedxxx.duckdns.org
X-Forwarded-Port: 443
X-Forwarded-Proto: https
X-Forwarded-Server: f7f9b8de17d4
X-Real-Ip: 88.152.2.117
2022.08.07 21:10:32.432 4: WEB_172.21.0.27_54068 GET /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2022-08-07.log; BUFLEN:0
2022.08.07 21:10:32.532 4: WEB: /fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2022-08-07.log / RL:158957 / text/html; charset=UTF-8 / Content-Encoding: gzip
 / Expires: Sun, 07 Aug 2022 19:25:32 GMT

2022.08.07 21:10:32.801 4: Connection accepted from WEB_127.0.0.1_46250
2022.08.07 21:10:32.802 5: GET /null/healthcheck HTTP/1.1
Host: localhost:8083
User-Agent: FHEM-Docker/1.0 Health Check
Accept: */*
2022.08.07 21:10:32.836 4: Connection closed for WEB_127.0.0.1_46250: EOF
2022.08.07 21:10:33.306 4: Connection accepted from WEB_172.21.0.27_54080
2022.08.07 21:10:33.306 5: GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status&filter=&since=1659899431.44582&fmt=JSON&fw_id=66576&timestamp=1659899433309 HTTP/1.1
Host: xxxreplacedxxx.duckdns.org
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:103.0) Gecko/20100101 Firefox/103.0
      
Accept: */*
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.5
Authorization: Basic bGFuZG86Z3JrbjczbnM=
Cookie: authelia_session=xxxreplacedxxx
Referer: https://xxxreplacedxxx.duckdns.org/fhem/FileLog_logWrapper?dev=Logfile&type=text&file=fhem-2022-08-07.log
Remote-Email: xxxreplacedxxx
Remote-Groups: xxxreplacedxxx
Remote-Name: xxxreplacedxxx
Remote-User: xxxreplacedxxx
Sec-Fetch-Dest: empty
Sec-Fetch-Mode: cors
Sec-Fetch-Site: same-origin
Te: trailers
X-Forwarded-For: 88.152.2.117
X-Forwarded-Host: xxxreplacedxxx.duckdns.org
X-Forwarded-Port: 443
X-Forwarded-Proto: https
X-Forwarded-Server: f7f9b8de17d4
X-Real-Ip: 88.152.2.117
2022.08.07 21:10:33.307 4: WEB_172.21.0.27_54080 GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status&filter=&since=1659899431.44582&fmt=JSON&fw_id=66576&timestamp=1659899433309; BUFLEN:0
2022.08.07 21:10:33.307 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 684.
2022.08.07 21:10:33.307 1: stacktrace:
2022.08.07 21:10:33.307 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (684)
2022.08.07 21:10:33.307 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.07 21:10:33.307 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.07 21:10:33.307 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.07 21:10:33.307 1:     main::CallFn                        called by fhem.pl (782)
2022.08.07 21:10:33.307 1: PERL WARNING: Use of uninitialized value $filter in string eq at ./FHEM/01_FHEMWEB.pm line 685.
2022.08.07 21:10:33.307 1: stacktrace:
2022.08.07 21:10:33.307 1:     main::__ANON__                      called by ./FHEM/01_FHEMWEB.pm (685)
2022.08.07 21:10:33.307 1:     main::FW_initInform                 called by ./FHEM/01_FHEMWEB.pm (956)
2022.08.07 21:10:33.307 1:     main::FW_answerCall                 called by ./FHEM/01_FHEMWEB.pm (609)
2022.08.07 21:10:33.307 1:     main::FW_Read                       called by fhem.pl (3955)
2022.08.07 21:10:33.307 1:     main::CallFn                        called by fhem.pl (782)
2022.08.07 21:10:54.009 4: Connection accepted from WEB_127.0.0.1_46314
2022.08.07 21:10:54.010 5: GET /null/healthcheck HTTP/1.1
Host: localhost:8083
User-Agent: FHEM-Docker/1.0 Health Check
Accept: */*
2022.08.07 21:10:54.045 4: Connection closed for WEB_127.0.0.1_46314: EOF
2022.08.07 21:11:15.120 4: Connection accepted from WEB_127.0.0.1_46370
2022.08.07 21:11:15.120 5: GET /null/healthcheck HTTP/1.1
Host: localhost:8083
User-Agent: FHEM-Docker/1.0 Health Check
Accept: */*
2022.08.07 21:11:15.157 4: Connection closed for WEB_127.0.0.1_46370: EOF
2022.08.07 21:11:36.355 4: Connection accepted from WEB_127.0.0.1_46598
2022.08.07 21:11:36.356 5: GET /null/healthcheck HTTP/1.1
Host: localhost:8083
User-Agent: FHEM-Docker/1.0 Health Check
Accept: */*
2022.08.07 21:11:36.439 4: Connection closed for WEB_127.0.0.1_46598: EOF

#3 im Network Tab (Firefox) sehe ich eine Tabelle mit Status (alles 200), Methoden (alles Get) etc. Einen direkten Vergleich mit den Werten aus #2 kann ich nicht erkennen bzw. erschließt sich mir nicht

#4 nein steht auf "1".

Code Auswählen

21:19:49.025 Inform-channel opened (HTTP) with filter room=ControlCenter

rudolfkoenig · 08 August 2022, 09:03:55

Erhellend ist die Zeile direkt vor WARNING:

Code Auswählen

GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status&filter=&since=1659899431.44582&fmt=JSON&fw_id=66576&timestamp=1659899433309;

Ich habe das bei mir nachgestellt, es sollte so ausschauen:

Code Auswählen

GET /fhem/FileLog_logWrapper?XHR=1&inform=type=status;filter=;since=1659940757.82205;fmt=JSON&fw_id=324&timestamp=1659940764377

Wichtiger Unterschied: der Trenner vor fmt=JSON wurde von ; bei mir in & bei Dir umgewandelt, damit wird dieser Parameter in FHEM in falsche Datenstrukturen reingepackt, nicht da wo das Modul ihn erwartet.

Mit dem Network-Tab kann man nachweisen, wie der Browser diese Daten versendet. Dafuer muss man mit bereits geoeffneten Network-Tab die Problemseite (irgendwas mit FileLog-Inhalt) erneut oeffnen. Da es lokal funktioniert, ueber Proxy aber nicht, ist sehr wahrscheinlich der Proxy die Ursache der URL-Manipulation, d.h man muesste ihn bitten das abzustellen.
Womoeglich ist eine alte Traefik Version oder ein Rewrite-Rule die Ursache, das ist aber wildes Raten ohne genaue Kenntnis.

Macht es einen Unterschied, wenn man "attr WEB longpoll websocket" setzt?

eddy242 · 08 August 2022, 10:50:38

Ich nehme an, das ist die Zeile aus dem Network Tab, die Dich interessiert:

Code Auswählen

GET
	wss://xxxreplacedxxx.duckdns.org/fhem?XHR=1&inform=type=status;filter=room=Raumklima;since=1659948293.50772;fmt=JSON&fw_id=84305&timestamp=1659948294852

Status
101
Switching Protocols
VersionHTTP/1.1
Transferred 169 B (0 B size)

Traefik ist aktuell über Autoupdater, verwendete Version von Ende Juli

Nach Umstellung auf websocket ändert sich nichts.

eddy242 · 08 August 2022, 11:12:43

Jetzt wo ich den Network Tab eh schon offen habe, neben den vielen Status 200 (ok) Rückmeldungen gibt es auch einige wenige 500. Wird dann aber gemäß Deiner Diagnose nicht im Zusammenhang stehen?

Code Auswählen


cmd
	{FW_makeImage('sani_heating_heatpump@grey','Aus',)}
XHR
	1
fwcsrf
	csrf_710631414142481
fw_id
	84305
Address
	88.152.76.154:443
Status
500
Internal Server Error
VersionHTTP/2
Transferred175 B (21 B size)
Referrer Policystrict-origin-when-cross-origin

rudolfkoenig · 08 August 2022, 11:23:14

ZitatIch nehme an, das ist die Zeile aus dem Network Tab, die Dich interessiert:

Richtig, d.h. Traefik manipuliert die URL nachweislich.
Ich koennte versuchen das zu umschiffen, aber erst nachdem ich weiss, was alles von Traefik geaendert wird.
Habe leider keine Doku dazu gefunden, und experimentieren will ich an dieser Stelle nicht.
Lieber waere es mir, wenn Traefik die URL unveraendert laesst.#

ZitatJetzt wo ich den Network Tab eh schon offen habe, neben den vielen Status 200 (ok) Rückmeldungen gibt es auch einige wenige 500. Wird dann aber gemäß Deiner Diagnose nicht im Zusammenhang stehen?

Dieses Problem ist nicht fuer das Dialog mit JSON verantwortlich.
500 wird von FHEMWEB selbst nicht zurueckgeliefert, aber der Proxy kann einen Verbindungsabbruch zu FHEM als 500 (Internal Server Error) zurueckliefern. Im FHEM-Log sollte so ein Verbindungsabbruch (z.Bsp. wg alten fw_csrf) aber sichtbar sein.

Nachtrag: Fuer das "JSON Dialog" ist eindeutig die URL-Manipulation zustaendig: da fmt=JSON fehlt (bzw. falsch zugeordnet wurde), wird das alte Format angenommen (Elemente durch << getrennt), was eindeutig nicht JSON ist. Das Frontend weiss davon nichts (hat ja JSON bestellt), versucht die Daten als JSON zu interpretieren, und das erzeugt das Dialog.

eddy242 · 08 August 2022, 15:31:33

In der Traefik Doku gibt es Hinweise, wie man die URL manipulieren kann https://doc.traefik.io/traefik/v2.1/middlewares/replacepathregex/#configuration-examples, aber es ist nichts zu finden, auch nicht auf stackoverflow etc, dass bereits im Default-Zustand Manipulationen vorgenommen werden. Eigentlich nutze ich Traefik schon mehr als 1 Jahr, eher 2 Jahre, und das war bis vor ein paar Wochen oder wenige Monate kein Problem. Vielleicht ist es ein Bug, den (hoffentlich) jemand findet und fixt. Vielleicht melde ich das mal auf Github.

Danke jedenfalls für die Diagnose.

cheanrod · 16 August 2022, 18:12:32

Da bei mir in einer ähnlichen Konfiguration dasselbe Problem auftritt, habe ich einmal ein Topic in der Traefik Community eröffnet:

https://community.traefik.io/t/unwanted-url-manipulation/15458?u=cheanrod

cheanrod · 17 August 2022, 06:47:34

Hier ist der bereits existierende GitHub Issue mit der Diskussion zu diesem Problem:

https://github.com/traefik/traefik/issues/9164

rudolfkoenig · 17 August 2022, 10:20:00

Danke fuer den Link, FHEM scheint in bester Gesellschaft zu sein.

Auch wenn ich die Begruendung fuer die Manipulation des URLs seitens traefik nicht nachvollziehen kann, muss Strichpunkt (

laut dem Link auf die HTML-Spec URL-Codiert werden. Aus diesem Grund habe ich fhemweb.js so angepasst, dass der inform Parameter URL-codiert wird, damit sollte das Problem auch ohne eine traefik Aenderung geloest sein.

SVG.pm musste auch geaendert werden wg. dem zoom Parameter.

cheanrod · 18 August 2022, 17:43:25

Ich kann bestätigen, dass mit der Änderung viele Dinge wieder mit dem aktuellen Traefik-Image funktionieren. Ich vermute aber, dass es noch weitere Stellen in Code gibt, die eine Änderung benötigen. Konkret funktioniert aktuell der Event Monitor und generell die Aktualisierung von Readings bei Events noch nicht über Traefik.

Ich bin auf das folgende GET gestoßen, das bei einem direkten Aufruf so aussieht:

Code Auswählen

GET /fhem?XHR=1&inform=type=raw;withLog=0;filter=.*&fw_id=772

Über Traefik aufgerufen wird daraus:

Code Auswählen

GET /fhem?XHR=1&inform=type=raw&withLog=0&filter=.*&fw_id=797

rudolfkoenig · 18 August 2022, 18:04:27

Event-Monitor (console.js) habe ich jetzt angepasst.
Wenn das Aktualisiern der Readings nicht funktoniert, was funktioniert denn ueberhaupt?