Syncronisation via WebDAV hängt sich auf

Dieses Problem begleitet micht seit Jahren und auch in der neuesten Version 3.7.2:

synconisiert wird via WebDAV von einem iMac (High Sierra) auf ein Netzwerklaufwerk, dass unter Debian 4.9.258-1 gehostet wird. Das System ist wiederum als eine VM unter VMware 6.7.0 ESXi-Server angelegt.

Es sind keinerlei Abbrüche in den Logs festzustellen.
Allerdings wird diese VM jeden zweiten Tag mit einem Snapshot inkl. RAM gesichert. Das bedeutet, dass die VM kurzfristig dazu angehalten wird.

Meine Vermutung ist nun, dass bei einem Versuch der Syncronisation durch DT und gleichzeitiger Erstellung eines Snapshots ein Timout wg. Netzwerkunterbrechung erfolgt und die Sync-Task von DT sich dabei aufhängt. Sofern eine Programmschleife zum re-connect darin programmiert sein sollte, scheint sie (zumindest bei mir) nicht richtig zu funktionieren. Vielleicht liege ich aber mit meiner Vermutung auch vollkommen falsch ?

Aber es nervt …

Die Sync-Engine von DEVONthink versucht es nach ein paar Minuten automatisch von selbst erneut.

(Übersetzt mit https://deepl.com)

Verstehe ich das richtig:

  • Du betreibst ein Debian 4.9 in einer VM. Wenn das so ist: Diese Version ist vor 11 Jahren erschienen und wird nicht mehr gepflegt. Ist es wirklich sinnvoll, das nicht zu aktualisieren? Die ESXi ist doch auch aktuell.
  • Diese VM hat eine virtuelle Platte
  • auf derselben VM läuft ein Apache, der WebDAV bereitstellt und die Platte darüber bereitstellt
  • Und nun sicherst du diese VM alle zwei Tage irgendwo hin

Weder auf dem VM-Host noch in der VM noch in DT? Und hat es denn überhaupt Änderungen gegeben, die hätten synchronisiert werden müssen?

Wenn man keine Synchronisation hat aber gerne eine hätte, dann ist das doch eigentlich eher fatal als “es nervt”? Oder funktioniert es irgendwann dann doch?

Gegenfrage: Muss das so komplex sein? Könntest Du nicht einfach dein System so aufsetzen, dass Du ohne die VM auskommst? Und wenn das nicht geht: Wäre es nicht deutlich einfacher, nur die virtuelle Platte regelmäßig zu sichern (USB oder so)? Anders gesagt: Ich mache hier WebDAV-Sync mit einer Synology NAS, und das läuft anstandslos.

@BLUEFROG
Tja , offensichtlich gibt es auch nach ein paar Minuten noch Probleme.
Frage stellt sich: wie häufig wird es denn überhaupt “versucht” und was genau sind die Abbruchbedingungen in dieser(n) Schleife(n) ?

@chrillek:
sorry: Debian Version = 9.13

Keinerlei Log-Einträge weder bei VMware, geschweige denn bei DT.
Wenn die Sync-Task von DT aufgerufen wurde, wird automatisch das dortige Datum aktualisiert - egal, ob etwas zu syncronisieren ist oder nicht.

Man kann es durchaus als “fatal” nennen.

Es gibt hier keine wirkliche Alternative zu VMware, da diverse verschiedene BS eingesetzt werden.
Nur die (vrituelle) Platte zu sichern dauert länger, als die gesamte VM. Ausnahme, wenn nur inkrementelle Backups erstellt werden. Das hat in der Vergangenheit aber zu erheblichen (zeitlichen Problemen) beim Restore geführt, weshalb das hier bewußt vermieden wird.

Frage stellt sich also: wann genau “stirbt” eigentlich die Sync-Task ?
Kann ich leider nicht konkret beantworten.

Es gibt bisher auch nur wenige Hinweise:

  • wird der iMac mehrere Tage nicht benutzt, hängt sich der Sync-Mechanismus garantiert auf
  • der Rechner kann in den Standy-Modus gehen → keine Probleme nach dem aufwachen
  • Energiesparmodus auf dem Rechner komplett ausgeschaltet → keine Änderung (mal ja, mal nicht) - über mehrere Wochen jetzt getestet)
  • wird DT neu gestartet, wird sofort syncronisiert und das Sync-Datum im GUI aktualisiert → das
    sich zuvor immer “drehende Zahnrad” täuscht also nur eine Tätigkeit vor. Tatsächlich ist die Task schon “tod”

Merkwürdig ist : DT wird in diesen Fällen über das GUI “DEVONthink beenden” immer erst nach 2x anklicken tatsächlich beendet, sonst immer (!) nach nur 1x. Scheint fast so, als ob ein “kill” zu einer hängenden “subtask” ausgeführt wird, die den eigentlichen dadurch Hauptprozess stoppt.

Er sollte es mehrmals hintereinander versuchen, etwa fünf Minuten warten und es dann erneut versuchen.
Ich kann nicht über die spezifischen “Abbruchbedingungen” sprechen, da es sich lediglich um eine -1001-Zeitüberschreitung handeln könnte.

Gibt es irgendeine Möglichkeit zu einem aussagefähigem Log zu kommen ?

Der Webdav-Server auf deiner VM? Der sollte doch zumindest Verbindungsversuche protokollieren. Oder gleich die physische Maschine. Wireshark?
Edit: Wireshark hilft allerdings nur, wenn Du WebDAV über HTTP machst. Bei HTTPS wirst Du vermutlich wenig herausbekommen.

im Apache “error.log” sind überhaupt keine Einträge in Verbindung mit DT am 25.06.2021 (Tag der letzten Syncronisation, siehe Screenshot) vorhanden.

Im “access.log”:


192.168.1.xxx - DTaccessUser [25/Jun/2021:11:24:49 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/ HTTP/1.1” 207 581 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [25/Jun/2021:11:24:49 +0200] “GET /webdav/DTsync_archive.dtCloud/inbox/master.plist HTTP/1.1” 200 592 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [25/Jun/2021:11:24:49 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/inbox/ HTTP/1.1” 207 4110 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - - [25/Jun/2021:11:26:29 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/ HTTP/1.1” 401 4157 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [25/Jun/2021:11:26:29 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/ HTTP/1.1” 207 581 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [25/Jun/2021:11:26:29 +0200] “GET /webdav/DTsync_archive.dtCloud/4fb8988da1abed249cc2a98ef52807e4ed2f5aa0b07837918b78dbfdfbb218e2/master.plist HTTP/1.1” 200 591 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [25/Jun/2021:11:26:29 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/4fb8988da1abed249cc2a98ef52807e4ed2f5aa0b07837918b78dbfdfbb218e2/ HTTP/1.1” 207 6273 “-” “DEVONcloudy 1.16.9”

Alle Einträge zuvor haben den gleichen Inhalt

Im “syslog” der VM sind zu keinem Zeitpunkt Einträge zum Apache bzw. DT zu finden.

Lt . “access.log” fand der letzte Zugriff von DT via WebDAV um 11.26:29 statt. Gemäß Screenshot 11:24:29.
Das sind 2 Minuten Differenz. Alle Maschinen werden aber über die gleichen Zeitserver syncronisiert, da ansonsten schon der Domain-Server Probleme bereiten würde.
Daher ist diese Abweichung für mich nicht nachvollziehbar.

Ein Zugriff auf die im Protokoll vermerkte “master.list” war heute via smb problemlos möglich (und scheint einen ordnungsgemäßen Inhalt zu haben).
Das Verzeichnis “4fb8988…” hat unter dem Unterverzeichnis “receipts” eine weitere Dir mit gleichem Erstellungsdatum inkl. gleichnamigen Datei darin (.item), auf welche auch problemlos zugegriffen werden kann.

Wie weiter ?

Ein Zugriff ist nicht zwingend ein Sync-Versuch. Laut dem Screenshot (s. drehendes Rad am rechten Rand) lief aber gerade noch ein Versuch.

Zumindest gibt es offenbar einmal 401, also unauthorized access, be PROPFIND /webdav…/inbox. Das sollte vielleicht nicht passieren?

Und dann mehrmals 207, was “multiple results code” bedeutet, und nicht, dass jeder einzelne Result Code 200 sein muss.

Wie gesagt, zur Not mal Wireshark auf dem WebDAV-Port/Interface laufen lassen und schauen, was der so sagt. Da kann man auch die Details zu den 207er Codes nachlesen (heißt es).

Der 401 taucht am Anfang eines jeden DT Sync-Zykluses auf.
Der 207 dagegen immer am Ende.

Beide sind in allen vergangenen Logs, wie auch im Aktuellen enthalten.

Der 207 besagt ja nur, dass eine Mehrfachoperation anhängig ist.
Der 401 deutet für mich darauf hin, das DT zunächst einen WebDAV-Zugriff intern ohne Authentifizierung durchführt, denn gleich im nächsten Schritt (zur gleichen Sekunde s.u.) erfolgt dann der mit korrekten Daten.

Hier noch einmal ein aktueller Auszug aus dem Log (Leerzeile nur zur besseren Übersicht):

192.168.1.xxx - - [05/Jul/2021:16:55:03 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/ HTTP/1.1” 401 4157 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [05/Jul/2021:16:55:03 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/ HTTP/1.1” 207 581 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [05/Jul/2021:16:55:03 +0200] “GET /webdav/DTsync_archive.dtCloud/inbox/master.plist HTTP/1.1” 200 592 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [05/Jul/2021:16:55:03 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/inbox/ HTTP/1.1” 207 4110 “-” “DEVONcloudy 1.16.9”

192.168.1.xxx - - [05/Jul/2021:16:55:37 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/ HTTP/1.1” 401 4157 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [05/Jul/2021:16:55:37 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/ HTTP/1.1” 207 581 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [05/Jul/2021:16:55:37 +0200] “GET /webdav/DTsync_archive.dtCloud/4fb8988da1abed249cc2a98ef52807e4ed2f5aa0b07837918b78dbfdfbb218e2/master.plist HTTP/1.1” 200 591 “-” “DEVONcloudy 1.16.9”
192.168.1.xxx - DTaccessUser [05/Jul/2021:16:55:37 +0200] “PROPFIND /webdav/DTsync_archive.dtCloud/4fb8988da1abed249cc2a98ef52807e4ed2f5aa0b07837918b78dbfdfbb218e2/ HTTP/1.1” 207 6548 “-” “DEVONcloudy 1.16.9”

Ich lasse mal Wireshark mitlaufen in der Hoffnung, das mit entsprechenden Filtern das Log nicht zu groß wird und der nächster Aufhänger nicht erst in einer Woche kommt …

Also ich nutze auch WebDAV mit einem Sinologie NAS ohne jegliche Probleme. Bevor du mit dem Wireshark anfängst würde ich erst mal folgende Tests machen, um vielleicht den Fehler einzugrenzen:

  • kleine Testdatenbank syncen
  • Umstellung von HTTPS auf HTTP bzw. umgekehrt
  • mal auf einen anderen Bereich des WebDAV Servers die Daten manuell mit dem Finder kopieren

so, schon am nächsten Tag hat sich die Sync-Task wieder aufgehängt.
Die letzte erfolgreiche Syncronisation erfolgte lt. GUI am 7.07.2021-12:01:57.

Ich habe das access.log via #tail auf der Konsole der VM ausgeben lassen, um die Log Rotation zu umgehen.
Es wurden die Zugriffe seit dem 7.07.2021-09:08:23 bis heute protokolliert.
Allerdings erfolgte der dort zuletzt vermerkte Eintrag bereits am 07.07.2021-17:23:12. Neuere Einträge sind nicht vorhanden (tail läuft noch).
Auffälig ist, dass der vorletzte Eintrag von 12:04:06 datiert, während der Letzte erst 5 Stunden später erfolgt !

Desweiteren habe ich Tshark (= Wireshark auf Konsolebene) mitlaufen lassen.
Das beigefügte Ergebnis ist von mir auf zwei Einträge reduziert worden, da der Inhalt ansonsten identisch zu sein scheint.

Interessanterweise werden genau diese Zugriffe auch heute noch regelmäßig protokolliert.
D.h. DT greift immer noch vom Mac auf den WebDAV-Server zu. Allerdings scheint dabei der zeitliche Rythmus jeweils unerschiedlich zu sein (also nicht genau alle 2 Minuten o.ä.).

Trotzdem kann ich inhatlich kein Problem daran erkennen, was zu dem Aufhänger führt.
Auffälig ist jedoch, das für die dort vermerkte Datei “master.plist” auf dem Server als letztes Änderungsdatum xx.xx.2019 vermerkt ist.
Vielleicht können die “Gurus” ja mal einen Blick darauf werfen …

In der Aktivitätenanzeige auf dem Mac sind bei DT unter “Geöffnete Dateien und Ports” seit gestern immer die gleichen Einträge zu sehen (trotz o.g. aktueller Zugriffe).
In der letzten Zeile dort ist die Datei vermerkt, die offensichtlich syncronisiert werde sollte (Name anonymisiert).
Diese Datei lässt sich problemlos lokal mit “Vorschau” öffnen und ist auch nur 25 MB groß. Sollte also kein Auslöser für Sync-Probleme sein. Bisher wurde sie aber nicht syncronisiert. Bei Bedarf kann ich diese zu Testzwecken (nicht öffentlich) auch zur Verfügung stellen.

Aktuell “hängt” die DT Sync-Task immer noch auf dem dem iMac. Zustand ist also wie vor zwei Tagen.
Falls jemand noch irgendwelche Debug- und Trce-Vorschläge hat, könnten die auf dem damaligen Stand aufsetzen.

server_access_last.zip (9.4 KB)
tshark_last.zip (1.7 KB)
Mac_Acitivity.zip (3.3 KB)

Diese Datei wird nur einmal angelegt, aber niemals gelöscht. D.h. der Sync Store ist entsprechend bereits ca. 2 Jahre alt.

Ansonsten wäre ein Bug Report (s. Menü Hilfe bei gedrückter Alt-Taste) hilfreicher, nachdem vorher die Einstellung SyncDebugLog aktiviert wurde und das Problem erneut auftrat. Diese Einstellung ist zu finden in der Hilfe unter Documentation > Appendix > Hidden Preferences.

Ansonsten wäre ein Bug Report (s. Menü Hilfe bei gedrückter Alt-Taste) hilfreicher,

Kann ich machen, müsste dazu aber DT neu starten.