planify icon indicating copy to clipboard operation
planify copied to clipboard
verified publisher icon alainm23

Handle GOAWAY reception gracefully

Open janvlug opened this issue 2 months ago • 13 comments

Describe the bug I still get this error message when synchronizing certain archived Projects (task lists): Entity: line 3: parser error : Extra content at the end of the document For a moment I thought that this error went away when I unarchive a problematic Project (task list), and close and start Planify again. But now, I now noticed (when writing this issue) that also an unarchived Projects (task lists) does not sychronize correctly.

What is weird is that sometimes a Project (task list) seems to synchronize correctly, but a later time not any more.

To Reproduce Steps to reproduce the behavior:

  1. Start Planify with Nextcloud as the back end
  2. Wait for Planify to start synchronizing

Expected behavior All tasks are synchronized without errors

Desktop (please complete the following information):

  • OS or DE: Fedora 42, GNOME Wayland, fully up to date
  • Version: Planify 4.15.1

Additional context I had this error before. See issue #1807. This seems to be partially solved.

Here a snippet from the debug messages:

Entity: line 3: parser error : Extra content at the end of the document

^

** (io.github.alainm23.planify:2): WARNING **: 15:16:40.828: Core.vala:281: Failed to sync: .

Please let me know if you need additional information, or if I can do some testing. I really like Planify!

janvlug avatar Oct 12 '25 13:10 janvlug

Additional info:

After changing the archive state (by archiving or un-archiving, dependent on the Projects initial archive state), Planify could do a full synchronization without errors.

I will update this issue if I experience again some issues.

Maybe useful to know: I use Planify on two computers with the same Nextcloud account to synchronize with.

janvlug avatar Oct 12 '25 13:10 janvlug

Update:

I unarchived all Projects, and restarted Planify.

Now I get the parser error again.

Unfortunately, I cannot figure out what exactly is causing the parser error. However it seems that there are some specific Projects where this error sometimes for happens.

janvlug avatar Oct 12 '25 13:10 janvlug

I also see this in the logging:

(io.github.alainm23.planify:2): libsoup-http2-DEBUG: 17:07:16.490: [CLIENT] [\u001b[31mC12\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Beginning: stream_id=0
(io.github.alainm23.planify:2): libsoup-http2-DEBUG: 17:07:16.490: [CLIENT] [\u001b[31mC12\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Received: stream_id=0, flags=0
(io.github.alainm23.planify:2): libsoup-http2-DEBUG: 17:07:16.490: [CLIENT] [\u001b[31mC12\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] GOAWAY: error=NO_ERROR, last_stream_id=1 timeout
(io.github.alainm23.planify:2): libsoup-http2-DEBUG: 17:07:16.490: [CLIENT] [\u001b[31mC12\u001b[00m-\u001b[31mS0\u001b[00m] [-] [SEND] [GOAWAY]

Might the issue be caused by a timeout?

Also: When I start Planify, it automatically starts synchronizing. I see the spinner behind the account name spinning, and also a spinner that indicates which project is being synchronized. This spinner "moves" from one project to another. At a certain point in time the spinner at the top, after the account name, changes into an exclamation mark in a triangle. If I hover above it, I see this text: "Failed to connect to server. It looks like the server is unreachable, are you connected to the internet? Any changes you make while disconnected will be synchronized when you reconnect." However, the spinner for the Project that was synchronizing when the error occurred keeps spinning. When I click on the exclamation mark in triangle icon, the synchronization starts again. But the "stuck" Project keeps it spinner and a second spinner is going to synchronize all projects again.

Maybe the GOAWAY is send by nextcloud to prevent something like a denial of service? I have many task lists, with some of them many individual tasks.

See also: https://datatracker.ietf.org/doc/html/rfc7540#section-6.8

janvlug avatar Oct 12 '25 15:10 janvlug

I did some more testing, and I'm now more convinced that the reception of the GOAWAY is the root cause. I will update the title of this issue accordingly.

Maybe the reception of a GOAWAY should be handled more gracefully. For example by restarting the synchronization from the Project where the synchronization went wrong.

I tried to find some information why this GOAWAY is sent by Nextcloud, and if I could configure that, but I could not find such information.

Here again the logging, now including the message from Core.vala:

** (io.github.alainm23.planify:2): WARNING **: 17:55:14.753: Core.vala:281: Failed to sync: .  
(io.github.alainm23.planify:2): libsoup-http2-DEBUG: 17:55:19.757: [CLIENT] [\u001b[32mC97\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Beginning: stream_id=0
(io.github.alainm23.planify:2): libsoup-http2-DEBUG: 17:55:19.757: [CLIENT] [\u001b[32mC97\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Received: stream_id=0, flags=0
(io.github.alainm23.planify:2): libsoup-http2-DEBUG: 17:55:19.757: [CLIENT] [\u001b[32mC97\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] GOAWAY: error=NO_ERROR, last_stream_id=3 timeout
(io.github.alainm23.planify:2): libsoup-http2-DEBUG: 17:55:19.757: [CLIENT] [\u001b[32mC97\u001b[00m-\u001b[31mS0\u001b[00m] [-] [SEND] [GOAWAY]

janvlug avatar Oct 12 '25 16:10 janvlug

I enabled debugging at the server. Here is a snippet that might be useful:

{"reqId":"aOvVIaAk2pQKNj1YSer0cAAAjAU","level":0,"time":"2025-10-12T16:19:45+00:00","remoteAddr":"a.b.c.d","user":"--","app":"bruteForce","method":"PROPFIND","url":"/remote.php/dav/calendars/<redacted>/2023-10-14/","message":"The loading of lazy AppConfig values have been triggered by app \"bruteForce\"","userAgent":"Planify","version":"31.0.9.1","exception":{"Exception":"RuntimeException","Message":"The loading of lazy AppConfig values have been triggered by app \"bruteForce\"","Code":0,"Trace":[{"file":"/var/www/nextcloud/lib/private/AppConfig.php","line":1224,"function":"loadConfig","class":"OC\\AppConfig","type":"->"},{"file":"/var/www/nextcloud/lib/private/AppConfig.php","line":106,"function":"loadConfigAll","class":"OC\\AppConfig","type":"->"},{"file":"/var/www/nextcloud/lib/private/Security/Ip/BruteforceAllowList.php","line":39,"function":"getKeys","class":"OC\\AppConfig","type":"->"},{"file":"/var/www/nextcloud/lib/private/Security/Bruteforce/Throttler.php","line":86,"function":"isBypassListed","class":"OC\\Security\\Ip\\BruteforceAllowList","type":"->"},{"file":"/var/www/nextcloud/lib/private/Security/Bruteforce/Throttler.php","line":112,"function":"isBypassListed","class":"OC\\Security\\Bruteforce\\Throttler","type":"->"},{"file":"/var/www/nextcloud/lib/private/Security/Bruteforce/Throttler.php","line":129,"function":"getAttempts","class":"OC\\Security\\Bruteforce\\Throttler","type":"->"},{"file":"/var/www/nextcloud/lib/private/Security/Bruteforce/Throttler.php","line":202,"function":"getDelay","class":"OC\\Security\\Bruteforce\\Throttler","type":"->"},{"file":"/var/www/nextcloud/lib/private/User/Session.php","line":384,"function":"sleepDelayOrThrowOnMax","class":"OC\\Security\\Bruteforce\\Throttler","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":80,"function":"logClientIn","class":"OC\\User\\Session","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Backend/AbstractBasic.php","line":103,"function":"validateUserPass","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":191,"function":"check","class":"Sabre\\DAV\\Auth\\Backend\\AbstractBasic","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":105,"function":"auth","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php","line":179,"function":"check","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php","line":135,"function":"check","class":"Sabre\\DAV\\Auth\\Plugin","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"beforeMethod","class":"Sabre\\DAV\\Auth\\Plugin","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":456,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Server.php","line":49,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Server.php","line":401,"function":"start","class":"OCA\\DAV\\Connector\\Sabre\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/appinfo/v2/remote.php","line":21,"function":"exec","class":"OCA\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/remote.php","line":145,"args":["/var/www/nextcloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/var/www/nextcloud/lib/private/AppConfig.php","Line":1239,"message":"The loading of lazy AppConfig values have been triggered by app \"bruteForce\"","exception":{},"CustomMessage":"The loading of lazy AppConfig values have been triggered by app \"bruteForce\""}}
{"reqId":"aOvVIaAk2pQKNj1YSer0cAAAjAU","level":0,"time":"2025-10-12T16:19:45+00:00","remoteAddr":"a.b.c.d","user":"--","app":"no app in context","method":"PROPFIND","url":"/remote.php/dav/calendars/<redacted>/2023-10-14/","message":"Token is not valid: Token is too short for a generated token, should be the password during basic auth","userAgent":"Planify","version":"31.0.9.1","exception":{"Exception":"OC\\Authentication\\Exceptions\\InvalidTokenException","Message":"Token is too short for a generated token, should be the password during basic auth","Code":0,"Trace":[{"file":"/var/www/nextcloud/lib/private/Authentication/Token/Manager.php","line":118,"function":"getToken","class":"OC\\Authentication\\Token\\PublicKeyTokenProvider","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/lib/private/User/Session.php","line":491,"function":"getToken","class":"OC\\Authentication\\Token\\Manager","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/lib/private/User/Session.php","line":391,"function":"isTokenPassword","class":"OC\\User\\Session","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":80,"function":"logClientIn","class":"OC\\User\\Session","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Backend/AbstractBasic.php","line":103,"function":"validateUserPass","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":191,"function":"check","class":"Sabre\\DAV\\Auth\\Backend\\AbstractBasic","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":105,"function":"auth","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php","line":179,"function":"check","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php","line":135,"function":"check","class":"Sabre\\DAV\\Auth\\Plugin","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"beforeMethod","class":"Sabre\\DAV\\Auth\\Plugin","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":456,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Server.php","line":49,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Server.php","line":401,"function":"start","class":"OCA\\DAV\\Connector\\Sabre\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/appinfo/v2/remote.php","line":21,"function":"exec","class":"OCA\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/remote.php","line":145,"args":["/var/www/nextcloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/var/www/nextcloud/lib/private/Authentication/Token/PublicKeyTokenProvider.php","Line":147,"message":"Token is not valid: Token is too short for a generated token, should be the password during basic auth","exception":{},"CustomMessage":"Token is not valid: Token is too short for a generated token, should be the password during basic auth"}}
{"reqId":"aOvVIaAk2pQKNj1YSer0cAAAjAU","level":0,"time":"2025-10-12T16:19:45+00:00","remoteAddr":"a.b.c.d","user":"--","app":"core","method":"PROPFIND","url":"/remote.php/dav/calendars/<redacted>/2023-10-14/","message":"Session token is invalid because it does not exist","userAgent":"Planify","version":"31.0.9.1","exception":{"Exception":"OC\\Authentication\\Exceptions\\InvalidTokenException","Message":"Token is too short for a generated token, should be the password during basic auth","Code":0,"Trace":[{"file":"/var/www/nextcloud/lib/private/Authentication/Token/Manager.php","line":118,"function":"getToken","class":"OC\\Authentication\\Token\\PublicKeyTokenProvider","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/lib/private/User/Session.php","line":749,"function":"getToken","class":"OC\\Authentication\\Token\\Manager","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/lib/private/User/Session.php","line":304,"function":"validateToken","class":"OC\\User\\Session","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/lib/private/User/Session.php","line":405,"function":"login","class":"OC\\User\\Session","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":80,"function":"logClientIn","class":"OC\\User\\Session","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Backend/AbstractBasic.php","line":103,"function":"validateUserPass","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->","args":["*** sensitive parameters replaced ***"]},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":191,"function":"check","class":"Sabre\\DAV\\Auth\\Backend\\AbstractBasic","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Auth.php","line":105,"function":"auth","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php","line":179,"function":"check","class":"OCA\\DAV\\Connector\\Sabre\\Auth","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php","line":135,"function":"check","class":"Sabre\\DAV\\Auth\\Plugin","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php","line":89,"function":"beforeMethod","class":"Sabre\\DAV\\Auth\\Plugin","type":"->"},{"file":"/var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":456,"function":"emit","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Connector/Sabre/Server.php","line":49,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/lib/Server.php","line":401,"function":"start","class":"OCA\\DAV\\Connector\\Sabre\\Server","type":"->"},{"file":"/var/www/nextcloud/apps/dav/appinfo/v2/remote.php","line":21,"function":"exec","class":"OCA\\DAV\\Server","type":"->"},{"file":"/var/www/nextcloud/remote.php","line":145,"args":["/var/www/nextcloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/var/www/nextcloud/lib/private/Authentication/Token/PublicKeyTokenProvider.php","Line":147,"message":"Session token is invalid because it does not exist","user":"<redacted>","exception":{},"CustomMessage":"Session token is invalid because it does not exist"}}

janvlug avatar Oct 13 '25 07:10 janvlug

Hi, I’ve been reviewing your logs, and honestly, I still don’t know what the problem is. To start narrowing down which project is causing the error, I’ll adjust the code so that only unarchived projects can be synced. That way, you’ll be able to identify which project is triggering the synchronization error. On the other hand, I’ll share a Planify build with more detailed logs so we can quickly pinpoint the exact line of code causing the issue.

alainm23 avatar Oct 13 '25 09:10 alainm23

@janvlug https://github.com/alainm23/planify/actions/runs/18461984284/artifacts/4253235712

alainm23 avatar Oct 13 '25 10:10 alainm23

Thanks. Actually, I do not believe any more that the issue is related to archived Projects.

I installed your development flatpak, and added my Nextcloud server. The first time, all was synchronized without problems. After the initial synchronization, I manually started again a synchronization, and it went wrong. This is the last part of the debug messages:

(io.github.alainm23.planify.Devel:2): libsoup-DEBUG: 18:01:00.770: [SESSION QUEUE] [0x5565b1c06580] [RUNNING] run_until_read_done
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:00.770: [CLIENT] [\u001b[36mC59\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA] Client stream EOF
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:00.771: [CLIENT] [\u001b[36mC59\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA] [SESSION] State READ_DATA -> READ_DONE
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:00.771: [CLIENT] [\u001b[36mC59\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DONE] Finished stream 3: completed
(io.github.alainm23.planify.Devel:2): libsoup-DEBUG: 18:01:00.771: [SESSION QUEUE] [0x5565b1c06580] [RUNNING] Message completed
(io.github.alainm23.planify.Devel:2): libsoup-DEBUG: 18:01:00.771: [SESSION QUEUE] [0x5565b1c06580] [FINISHING] Processing item, paused=0 state=9
** (io.github.alainm23.planify.Devel:2): DEBUG: 18:01:00.771: WebDAVClient.vala:118: [CalDAV] Response status: 207 Multi-Status
** (io.github.alainm23.planify.Devel:2): DEBUG: 18:01:00.771: WebDAVClient.vala:158: [CalDAV] Response length: 2054 bytes
** (io.github.alainm23.planify.Devel:2): DEBUG: 18:01:00.771: WebDAVClient.vala:171: [CalDAV] Parsing XML response, length: 2054
Entity: line 3: parser error : Extra content at the end of the document

^

** (io.github.alainm23.planify.Devel:2): WARNING **: 18:01:00.771: WebDAVClient.vala:181: [CalDAV] XML parse error: .  

** (io.github.alainm23.planify.Devel:2): WARNING **: 18:01:00.771: WebDAVClient.vala:182: [CalDAV] XML content (first 1000 chars): <?xml version="1.0"?>
<d:multistatus xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns" xmlns:cal="urn:ietf:params:xml:ns:caldav" xmlns:cs="http://calendarserver.org/ns/" xmlns:oc="http://owncloud.org/ns" xmlns:nc="http://nextcloud.org/ns"><d:response><d:href>/remote.php/dav/calendars/jan/2023-10-14/</d:href><d:propstat><d:prop><d:resourcetype><d:collection/><cal:calendar/></d:resourcetype><d:displayname>2023-10-14</d:displayname><d:sync-token>http://sabre.io/ns/sync/70</d:sync-token><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/">#0082c9</x1:calendar-color><cal:supported-calendar-component-set><cal:comp name="VTODO"/></cal:supported-calendar-component-set></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response><d:response><d:href>/remote.php/dav/calendars/jan/2023-10-14/0C52FFA4-0BA8-4B4B-A3B3-F7995D1C579C.ics</d:href><d:propstat><d:prop><d:resourcetype/></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat><d:propstat><d:prop><d:displayname/><d:sync-token/><x1

** (io.github.alainm23.planify.Devel:2): WARNING **: 18:01:00.771: Core.vala:292: [CalDAV] Sync failed: .   (code: 1)
(io.github.alainm23.planify.Devel:2): Gtk-DEBUG: 18:01:00.771: snapshot symbolic icon using mask
(io.github.alainm23.planify.Devel:2): Gtk-DEBUG: 18:01:00.771: snapshot symbolic icon using mask
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:05.171: [CLIENT] [\u001b[35mC58\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Beginning: stream_id=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:05.171: [CLIENT] [\u001b[35mC58\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Received: stream_id=0, flags=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:05.171: [CLIENT] [\u001b[35mC58\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] GOAWAY: error=NO_ERROR, last_stream_id=3 timeout
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:05.171: [CLIENT] [\u001b[35mC58\u001b[00m-\u001b[31mS0\u001b[00m] [-] [SEND] [GOAWAY]
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:05.887: [CLIENT] [\u001b[36mC59\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Beginning: stream_id=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:05.887: [CLIENT] [\u001b[36mC59\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Received: stream_id=0, flags=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:05.887: [CLIENT] [\u001b[36mC59\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] GOAWAY: error=NO_ERROR, last_stream_id=3 timeout
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 18:01:05.887: [CLIENT] [\u001b[36mC59\u001b[00m-\u001b[31mS0\u001b[00m] [-] [SEND] [GOAWAY]

janvlug avatar Oct 13 '25 16:10 janvlug

Thanks for the log. I identified the issue: your Nextcloud server is sending extra bytes after the XML document, causing the parse error.

I've implemented a fix that automatically cleans the XML before processing. Please test this new build:

[flatpak link]

Run with: G_MESSAGES_DEBUG=all flatpak run io.github.alainm23.planify.Devel

You should see [CalDAV] Removing X extra bytes in the logs if content is cleaned, and sync should work. Share the new logs if there are still issues.

alainm23 avatar Oct 13 '25 23:10 alainm23

Sorry that it took this long to respond. Actually, I forgot that you asked me to test your new build. I will do that later and update here.

Today, I build Planify myself and added some extra log output.

It indeed appears that the response data from response.get_data () (at the end of the send_request method in WebDAVClient) sometimes contains this after the last closing XML tag: \u0010\u0008. I have no idea what causes this extra content.

I will try to make time soon to test your build.

janvlug avatar Nov 24 '25 12:11 janvlug

I tested your build now. It still hangs. Strange enough, from this logging I would think a part of the content is missing. This is the last part of the console logging if the issue occurs:

(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [WRITE_DONE] [RECV] [HEADERS] Beginning: stream_id=3
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [WRITE_DONE] [SESSION] State WRITE_DONE -> READ_HEADERS
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_HEADERS] [RECV] [HEADERS] Received: stream_id=3, flags=4
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_HEADERS] [HEADERS] category=RESPONSE status=207
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_HEADERS] [RECV] [DATA] Beginning: stream_id=3
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_HEADERS] [SESSION] State READ_HEADERS -> READ_DATA_START
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA_START] [DATA] Received chunk, stream_id=3 len=535, flags=1, paused=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA_START] [DATA] Sniffed content
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA_START] [SESSION] State READ_DATA_START -> READ_DATA
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA] [RECV] [DATA] Received: stream_id=3, flags=1
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA] [RECV] [DATA] window=535/6291456
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA] [SESSION] Closed stream 3: NO_ERROR
(io.github.alainm23.planify.Devel:2): libsoup-DEBUG: 13:23:45.680: [SESSION QUEUE] [0x556a7ac07460] [RUNNING] run_until_read_done
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA] Client stream EOF
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DATA] [SESSION] State READ_DATA -> READ_DONE
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:45.680: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[34mS3\u001b[00m] [READ_DONE] Finished stream 3: completed
(io.github.alainm23.planify.Devel:2): libsoup-DEBUG: 13:23:45.680: [SESSION QUEUE] [0x556a7ac07460] [RUNNING] Message completed
(io.github.alainm23.planify.Devel:2): libsoup-DEBUG: 13:23:45.680: [SESSION QUEUE] [0x556a7ac07460] [FINISHING] Processing item, paused=0 state=9
** (io.github.alainm23.planify.Devel:2): DEBUG: 13:23:45.680: WebDAVClient.vala:151: [CalDAV] Parsing XML, length: 2058
** (io.github.alainm23.planify.Devel:2): DEBUG: 13:23:45.680: WebDAVClient.vala:182: [CalDAV] Removing 13 extra bytes
Entity: line 2: parser error : expected '>'
status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response></d:multistatu
                                                                               ^
Entity: line 2: parser error : Opening and ending tag mismatch: multistatus line 2 and multistatu
status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response></d:multistatu
                                                                               ^

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:23:45.680: WebDAVClient.vala:163: [CalDAV] XML parse error: .  

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:23:45.680: WebDAVClient.vala:164: [CalDAV] First 1000 chars: <?xml version="1.0"?>
<d:multistatus xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns" xmlns:cal="urn:ietf:params:xml:ns:caldav" xmlns:cs="http://calendarserver.org/ns/" xmlns:oc="http://owncloud.org/ns" xmlns:nc="http://nextcloud.org/ns"><d:response><d:href>/remote.php/dav/calendars/jan/2023-10-14/</d:href><d:propstat><d:prop><d:resourcetype><d:collection/><cal:calendar/></d:resourcetype><d:displayname>2023-10-14</d:displayname><d:sync-token>http://sabre.io/ns/sync/72</d:sync-token><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/">#0082c9</x1:calendar-color><cal:supported-calendar-component-set><cal:comp name="VTODO"/></cal:supported-calendar-component-set></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response><d:response><d:href>/remote.php/dav/calendars/jan/2023-10-14/0C52FFA4-0BA8-4B4B-A3B3-F7995D1C579C.ics</d:href><d:propstat><d:prop><d:resourcetype/></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat><d:propstat><d:prop><d:displayname/><d:sync-token/><x1

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:23:45.681: WebDAVClient.vala:165: [CalDAV] Last 200 chars: sync-token/><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/"/><cal:supported-calendar-component-set/></d:prop><d:status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response></d:multistatu

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:23:45.681: Core.vala:292: [CalDAV] Sync failed: .   (code: 1)
(io.github.alainm23.planify.Devel:2): Gtk-DEBUG: 13:23:45.692: snapshot symbolic icon using mask
(io.github.alainm23.planify.Devel:2): Gtk-DEBUG: 13:23:45.692: snapshot symbolic icon using mask
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:50.251: [CLIENT] [\u001b[32mC13\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Beginning: stream_id=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:50.251: [CLIENT] [\u001b[32mC13\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Received: stream_id=0, flags=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:50.251: [CLIENT] [\u001b[32mC13\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] GOAWAY: error=NO_ERROR, last_stream_id=3 timeout
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:50.251: [CLIENT] [\u001b[32mC13\u001b[00m-\u001b[31mS0\u001b[00m] [-] [SEND] [GOAWAY]
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:50.681: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Beginning: stream_id=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:50.681: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] [GOAWAY] Received: stream_id=0, flags=0
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:50.681: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[31mS0\u001b[00m] [-] [RECV] GOAWAY: error=NO_ERROR, last_stream_id=3 timeout
(io.github.alainm23.planify.Devel:2): libsoup-http2-DEBUG: 13:23:50.681: [CLIENT] [\u001b[33mC14\u001b[00m-\u001b[31mS0\u001b[00m] [-] [SEND] [GOAWAY]

janvlug avatar Nov 24 '25 12:11 janvlug

Here is some output from your branch with some added logging by me. I redacted some private details:

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:41:13.123: WebDAVClient.vala:143: returndata is <?xml version="1.0"?>
<d:multistatus xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns" xmlns:cal="urn:ietf:params:xml:ns:caldav" xmlns:cs="http://calendarserver.org/ns/" xmlns:oc="http://owncloud.org/ns" xmlns:nc="http://nextcloud.org/ns"><d:response><d:href>/remote.php/dav/calendars/jan/2023-10-14/</d:href><d:propstat><d:prop><d:resourcetype><d:collection/><cal:calendar/></d:resourcetype><d:displayname>2023-10-14</d:displayname><d:sync-token>http://sabre.io/ns/sync/72</d:sync-token><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/">#0082c9</x1:calendar-color><cal:supported-calendar-component-set><cal:comp name="VTODO"/></cal:supported-calendar-component-set></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response><d:response><d:href>/remote.php/dav/calendars/jan/calendarname/redacted.ics</d:href><d:propstat><d:prop><d:resourcetype/></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat><d:propstat><d:prop><d:displayname/><d:sync-token/><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/"/><cal:supported-calendar-component-set/></d:prop><d:status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response><d:response><d:href>/remote.php/dav/calendars/jan/calendarname/redacted.ics</d:href><d:propstat><d:prop><d:resourcetype/></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat><d:propstat><d:prop><d:displayname/><d:sync-token/><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/"/><cal:supported-calendar-component-set/></d:prop><d:status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response><d:response><d:href>/remote.php/dav/calendars/jan/calendarname/redacted.ics</d:href><d:propstat><d:prop><d:resourcetype/></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat><d:propstat><d:prop><d:displayname/><d:sync-token/><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/"/><cal:supported-calendar-component-set/></d:prop><d:status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response></d:multistatus>
\u0010\u0008
Entity: line 2: parser error : expected '>'
status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response></d:multistatu
                                                                               ^
Entity: line 2: parser error : Opening and ending tag mismatch: multistatus line 2 and multistatu
status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response></d:multistatu
                                                                               ^

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:41:13.124: WebDAVClient.vala:169: [CalDAV] XML parse error: .  

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:41:13.124: WebDAVClient.vala:170: [CalDAV] First 1000 chars: <?xml version="1.0"?>
<d:multistatus xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns" xmlns:cal="urn:ietf:params:xml:ns:caldav" xmlns:cs="http://calendarserver.org/ns/" xmlns:oc="http://owncloud.org/ns" xmlns:nc="http://nextcloud.org/ns"><d:response><d:href>/remote.php/dav/calendars/jan/calendarname/</d:href><d:propstat><d:prop><d:resourcetype><d:collection/><cal:calendar/></d:resourcetype><d:displayname>calendarname</d:displayname><d:sync-token>http://sabre.io/ns/sync/72</d:sync-token><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/">#0082c9</x1:calendar-color><cal:supported-calendar-component-set><cal:comp name="VTODO"/></cal:supported-calendar-component-set></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response><d:response><d:href>/remote.php/dav/calendars/jan/calendarname/redacted.ics</d:href><d:propstat><d:prop><d:resourcetype/></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat><d:propstat><d:prop><d:displayname/><d:sync-token/><x1

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:41:13.124: WebDAVClient.vala:171: [CalDAV] Last 200 chars: sync-token/><x1:calendar-color xmlns:x1="http://apple.com/ns/ical/"/><cal:supported-calendar-component-set/></d:prop><d:status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response></d:multistatu

** (io.github.alainm23.planify.Devel:2): WARNING **: 13:41:13.124: Core.vala:292: [CalDAV] Sync failed: .   (code: 1)

I will try to dive a bit further into this later, I've now some other things that have to be done.

janvlug avatar Nov 24 '25 12:11 janvlug

I tried to find the root cause of this issue. For some reason, there seems to be more content in the returned data than that there should be.

I had a look with Wireshark, and noted that there are TCP/IP connection resets around the times when this issue happens. I've the feeling that the root cause is somewhere at the network level. But I could not pinpoint it.

janvlug avatar Nov 25 '25 18:11 janvlug