Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

download stuck not updating any feeds #1276

Open
rich-coe opened this issue Aug 1, 2023 · 11 comments
Open

download stuck not updating any feeds #1276

rich-coe opened this issue Aug 1, 2023 · 11 comments

Comments

@rich-coe
Copy link
Contributor

rich-coe commented Aug 1, 2023

updated/pulled up to master 3acb5bc to pick up new glib/webkit changes

RSS feed updates hang with all requests in the 'Pending Queue'.
I tried --debug-net but observed no obvious messages.

During debugging, numberOfActiveJobs = 1, but nothing is obviously stuck.
Looking into debugging/tracing glib queue processing.

thr apply all bt

Thread 499 (Thread 0x7f1942b286c0 (LWP 15223) "ReceiveQueue"):
#0  0x00007f194823320e in __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x7f1942b27a40, op=393, expected=0, futex_word=0x7f192400e994) at futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x7f192400e994, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7f1942b27a40, private=private@entry=0, cancel=cancel@entry=true) at futex-internal.c:87
#2  0x00007f19482332af in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7f192400e994, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7f1942b27a40, private=private@entry=0) at futex-internal.c:139
#3  0x00007f1948236275 in __pthread_cond_wait_common (abstime=0x7f1942b27a40, clockid=0, mutex=0x7f192400e940, cond=0x7f192400e968) at pthread_cond_wait.c:503
#4  ___pthread_cond_timedwait64 (cond=0x7f192400e968, mutex=0x7f192400e940, abstime=0x7f1942b27a40) at pthread_cond_wait.c:643
#5  0x00007f194a54da8b in  () at /lib64/libjavascriptcoregtk-4.1.so.0
#6  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#7  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 12 (Thread 0x7f18deaf46c0 (LWP 1333) "ReceiveQueue"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f18c8006e60, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eb04f in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f194a4eb570 in WTF::RunLoop::run() () at /lib64/libjavascriptcoregtk-4.1.so.0
#4  0x00007f194a4ed0ae in  () at /lib64/libjavascriptcoregtk-4.1.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 11 (Thread 0x7f18dcefd6c0 (LWP 1265) "threaded-ml"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f18bc0071a0, nfds=3, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f18df264e31 in  () at /lib64/libpulse.so.0
#2  0x00007f18df24e854 in pa_mainloop_poll () at /lib64/libpulse.so.0
#3  0x00007f18df2590d6 in pa_mainloop_iterate () at /lib64/libpulse.so.0
#4  0x00007f18df259180 in pa_mainloop_run () at /lib64/libpulse.so.0
#5  0x00007f18df268dd9 in  () at /lib64/libpulse.so.0
#6  0x00007f18df20723f in  () at /usr/lib64/pulseaudio/libpulsecommon-16.1.so
#7  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#8  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 10 (Thread 0x7f18dfffd6c0 (LWP 1256) "ReceiveQueue"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f18cc001170, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eb04f in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f194a4eb570 in WTF::RunLoop::run() () at /lib64/libjavascriptcoregtk-4.1.so.0
#4  0x00007f194a4ed0ae in  () at /lib64/libjavascriptcoregtk-4.1.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 9 (Thread 0x7f19423276c0 (LWP 1255) "ReceiveQueue"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f1930002dd0, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eb04f in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f194a4eb570 in WTF::RunLoop::run() () at /lib64/libjavascriptcoregtk-4.1.so.0
#4  0x00007f194a4ed0ae in  () at /lib64/libjavascriptcoregtk-4.1.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 8 (Thread 0x7f1940b246c0 (LWP 1213) "ebsiteDataStore"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f18d0001000, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eb04f in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f194a4eb570 in WTF::RunLoop::run() () at /lib64/libjavascriptcoregtk-4.1.so.0
#4  0x00007f194a4ed0ae in  () at /lib64/libjavascriptcoregtk-4.1.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 7 (Thread 0x7f19413256c0 (LWP 1212) "HashSaltStorage"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f18d8001000, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eb04f in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f194a4eb570 in WTF::RunLoop::run() () at /lib64/libjavascriptcoregtk-4.1.so.0
#4  0x00007f194a4ed0ae in  () at /lib64/libjavascriptcoregtk-4.1.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 6 (Thread 0x7f1941b266c0 (LWP 1211) "PressureMonitor"):
#0  0x00007f194823320e in __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x7f1941b25640, op=393, expected=0, futex_word=0x7f192204c160) at futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x7f192204c160, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7f1941b25640, private=private@entry=0, cancel=cancel@entry=true) at futex-internal.c:87
#2  0x00007f19482332af in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7f192204c160, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7f1941b25640, private=private@entry=0) at futex-internal.c:139
#3  0x00007f1948236275 in __pthread_cond_wait_common (abstime=0x7f1941b25640, clockid=0, mutex=0x7f192204c110, cond=0x7f192204c138) at pthread_cond_wait.c:503
#4  ___pthread_cond_timedwait64 (cond=0x7f192204c138, mutex=0x7f192204c110, abstime=0x7f1941b25640) at pthread_cond_wait.c:643
#5  0x00007f194a5004c8 in WTF::ThreadCondition::timedWait(WTF::Mutex&, WTF::WallTime) () at /lib64/libjavascriptcoregtk-4.1.so.0
#6  0x00007f194a4bea23 in WTF::ParkingLot::parkConditionallyImpl(void const*, WTF::ScopedLambda<bool ()> const&, WTF::ScopedLambda<void ()> const&, WTF::TimeWithDynamicClockType const&) () at /lib64/libjavascriptcoregtk-4.1.so.0
#7  0x00007f194a4bf9fc in WTF::sleep(WTF::Seconds) () at /lib64/libjavascriptcoregtk-4.1.so.0
#8  0x00007f194b6d647c in  () at /lib64/libwebkit2gtk-4.1.so.0
#9  0x00007f194b6d6e3f in  () at /lib64/libwebkit2gtk-4.1.so.0
#10 0x00007f194a4ed0ae in  () at /lib64/libjavascriptcoregtk-4.1.so.0
#11 0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#12 0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 5 (Thread 0x7f19433cb6c0 (LWP 696) "dconf worker"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f192c000bb0, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eae2c in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f1944eec97d in  () at /usr/lib64/gio/modules/libdconfsettings.so
#4  0x00007f1948516fbe in  () at /lib64/libglib-2.0.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 4 (Thread 0x7f1943bfd6c0 (LWP 683) "gdbus"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f193801ccc0, nfds=6, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eb04f in g_main_loop_run () at /lib64/libglib-2.0.so.0
#3  0x00007f194879a8c6 in  () at /lib64/libgio-2.0.so.0
#4  0x00007f1948516fbe in  () at /lib64/libglib-2.0.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 3 (Thread 0x7f19443fe6c0 (LWP 682) "gmain"):
#0  0x00007f19482b048f in __GI___poll (fds=0x7f1934000c20, nfds=5, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eae2c in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f19484eae71 in  () at /lib64/libglib-2.0.so.0
#4  0x00007f1948516fbe in  () at /lib64/libglib-2.0.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 2 (Thread 0x7f1944bff6c0 (LWP 681) "pool-spawner"):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f1948544480 in g_cond_wait () at /lib64/libglib-2.0.so.0
#2  0x00007f19484b4f4b in  () at /lib64/libglib-2.0.so.0
#3  0x00007f1948517602 in  () at /lib64/libglib-2.0.so.0
#4  0x00007f1948516fbe in  () at /lib64/libglib-2.0.so.0
#5  0x00007f1948236c64 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f19482be550 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 1 (Thread 0x7f1945502b80 (LWP 677) "liferea"):
#0  0x00007f19482b048f in __GI___poll (fds=0x9eb5e40, nfds=8, timeout=444) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f19484ead0e in  () at /lib64/libglib-2.0.so.0
#2  0x00007f19484eae2c in g_main_context_iteration () at /lib64/libglib-2.0.so.0
#3  0x00007f194875e83d in g_application_run () at /lib64/libgio-2.0.so.0
#4  0x000000000042d2d8 in liferea_application_new (argc=3, argv=0x7fff345024d8) at ../liferea_application.c:343
#5  0x00007f19481d0bf0 in __libc_start_call_main (main=main@entry=0x41f550 <main>, argc=argc@entry=3, argv=argv@entry=0x7fff345024d8) at ../sysdeps/nptl/libc_start_call_main.h:58
#6  0x00007f19481d0cb9 in __libc_start_main_impl (main=0x41f550 <main>, argc=3, argv=0x7fff345024d8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff345024c8) at ../csu/libc-start.c:360
#7  0x000000000041f5f5 in _start () at ../sysdeps/x86_64/start.S:115
@rich-coe
Copy link
Contributor Author

rich-coe commented Aug 1, 2023

libglib-2_0-0-2.76.4-1.1.x86_64
libsoup-3_0-0-3.4.2-1.1.x86_64
libwebkit2gtk-4_1-0-2.40.4-1.1.x86_64

@rich-coe
Copy link
Contributor Author

rich-coe commented Aug 3, 2023

During updates, the last message is 499/1092.
I noticed that the update monitor shows 5 simultaneous downloads, and updates continuously, then the number of active on the left side dwindles, til its only processing one at a time.
Then it stops updating all together and is 'stuck'.
I suspect that there are some feeds that 'error out', and this is holding a download slot active even though nothing is occurring.
numberOfActiveJobs = 5

@rich-coe
Copy link
Contributor Author

rich-coe commented Aug 5, 2023

Threre's a couple URLs where libsoup is not timing out, the https connection is getting closed, and the job callback is never called.

I'm working on a test case outside of liferea to debug libsoup.

There may be another problem, as I have a work-around in place and updates are still not working.

@rich-coe
Copy link
Contributor Author

rich-coe commented Aug 11, 2023 •
edited

There's two issues I also seeing in the current setup

  • youtube video's will not play - get the message 'If playback doesn't begin shortly, try restarting your device'
    I found a note about missing gstreamer plugins, but I have all the plugins mentioned.
  • when update fetches a subscription url and the return status is 304 with 0 bytes received, the subscription is in the error state. [ submitted pr in Subscription Update with no available update signals an error #1285 ]
    I upgraded libsoup to master/4705c0cb725a from 3.4.2 to pick up the fix 'session: handle request cancellation earlier'.
    It didn't fix the issue with the 'bad' urls, but it did fix the issue with the all the subscription urls reporting errors.
    [Edit. commented too soon, the subscriptions that have no update are back to being in 'error' state. ]
    /

@rich-coe rich-coe mentioned this issue Aug 12, 2023
Closed
@rich-coe
Copy link
Contributor Author

I have a better handle on the issue, but no solution yet.
Update subscription

  • processing job request (feed)
  • complete job request (feed)
  • trying to download icon
  • adding favicon (2-6)
  • processing job request favicon(2)
  • libsoup error ( one of )
    (liferea:19676): GLib-GIO-DEBUG: 09:48:25.131: IPv4 DNS error: Error resolving “FQDN”: Name or service not known
    (liferea:19676): GLib-GIO-DEBUG: 09:48:55.246: GSocketClient: Connection failed: Could not connect to FQDN: Network is unreachable
  • job never errors out

I'm still working on a test case that exhibits the issue.

@lwindolf
Copy link
Owner

@rich-coe That's ugly. I could not reproduce the problem so far. I'll research whether there is some good timeout handling possible killing old requests.

@lwindolf lwindolf added this to the 1.15.2 milestone Aug 14, 2023
@rich-coe
Copy link
Contributor Author

Here's a log of what I'm observing:

13:50:23 UPDATE : Scheduling Horse Drawn Games to be updated
13:50:23 UPDATE : Resetting last poll counter of https://www.horsedrawngames.com/feed/ to 1692989423968850.
13:50:24 UPDATE : processing job request (https://www.horsedrawngames.com/feed/) [1] 0x8dec6b0
13:50:24 NET    : downloading https://www.horsedrawngames.com/feed/
> GET /feed/ HTTP/2
> Soup-Debug-Timestamp: 1692989424
> Soup-Debug: SoupSession 1 (0x1ac6e90), SoupMessage 14 (0xa34c610), GSocket 9 (0x8e1bc60)
> Accept: application/atom+xml,application/xml;q=0.9,text/xml;q=0.8,*/*;q=0.7
> Accept-Encoding: gzip, deflate, br
> User-Agent: Liferea/1.15.0 (Linux; https://lzone.de/liferea/) AppleWebKit (KHTML, like Gecko)
  
< HTTP/2 200 OK
< Soup-Debug-Timestamp: 1692989425
< Soup-Debug: SoupMessage 14 (0xa34c610)
< Last-Modified: Sun, 10 Jun 2018 09:50:52 GMT
< ETag: "583742bd9638bfec68cab50fe1af90b6"
< Content-Type: text/xml; charset=UTF-8
< Content-Encoding: br
< Vary: Accept-Encoding
< Date: Fri, 25 Aug 2023 18:50:25 GMT
< Server: LiteSpeed
< x-powered-by: PHP/5.6.40
< x-pingback: https://www.horsedrawngames.com/2014/xmlrpc.php
< alt-svc: h3=":443"; ma=2592000, h3-29=":443"; ma=2592000, h3-Q050=":443"; ma=2592000, h3-Q046=":443"; ma=2592000, h3-Q043=":443"; ma=2592000, quic=":443"; ma=2592000; v="43,46"
  
13:50:25 NET    : download status code: 200
13:50:25 NET    : source after download: >>>https://www.horsedrawngames.com/feed/<<<
13:50:25 NET    : 61705 bytes downloaded
13:50:25 UPDATE : complete job request (https://www.horsedrawngames.com/feed/) [0] 0x8dec6b0
13:50:25 UPDATE : feed_parse (https://www.horsedrawngames.com/feed/) 
13:50:25 UPDATE : feed_parse (https://www.horsedrawngames.com/feed/) 3: attempting rss
13:50:25 UPDATE : feed_parse (https://www.horsedrawngames.com/feed/) 3: success
13:50:25 UPDATE : discovered feed format: rss
13:50:25 UPDATE : old item set 0x9e77140 of (node id=jgwiluw):
13:50:25 UPDATE : current cache size: 11
13:50:25 UPDATE : current cache limit: 5000
13:50:25 UPDATE : downloaded feed size: 10
13:50:25 UPDATE : flag count: 0
13:50:25 UPDATE : trying to merge "BinaryFormatter on iOS" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "BinaryFormatter on iOS" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "Shader syntax highlighting in Visual Studio 2013" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "Shader syntax highlighting in Visual Studio 2013" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "The case of the continually checked out prefabs" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "The case of the continually checked out prefabs" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "Ring buffers / circular buffers" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "Ring buffers / circular buffers" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "Visual Studio shader syntax highlighting part 2" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "Visual Studio shader syntax highlighting part 2" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "Remote debug / live update of Unity builds on device" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "Remote debug / live update of Unity builds on device" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "Hdg Remote Debug – How It Works" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "Hdg Remote Debug – How It Works" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "Hdg Remote Debug – Released!" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "Hdg Remote Debug – Released!" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "Decoding iOS crash call stacks" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "Decoding iOS crash call stacks" to node id "jgwiluw"...
13:50:25 UPDATE : trying to merge "Type-safe object pool for Unity" to node id "jgwiluw"
13:50:25 UPDATE : -> not adding "Type-safe object pool for Unity" to node id "jgwiluw"...
13:50:25 UPDATE : added 0 new items
13:50:25 UPDATE : 0 new items, cache limit is 5000 -> dropping 0 items
13:50:25 UPDATE : trying to download icon for "Horse Drawn Games"

13:50:25 UPDATE : (2) adding favicon search URL: https://www.horsedrawngames.com
13:50:25 UPDATE : (3) adding favicon search URL: https://www.horsedrawngames.com
13:50:25 UPDATE : (5) adding favicon source URL: https://www.horsedrawngames.com/feed/favicon.ico
13:50:25 UPDATE : (6) adding favicon source URL: https://www.horsedrawngames.com/favicon.ico
13:50:25 UPDATE : Icon 'jgwiluw' trying URL: 'https://www.horsedrawngames.com'
13:50:25 UPDATE : processing job request (https://www.horsedrawngames.com) [1] 0x8e2d700
13:50:25 NET    : downloading https://www.horsedrawngames.com

@rich-coe
Copy link
Contributor Author

rich-coe commented Sep 1, 2023

Here's a the log from G_MESSAGES_DEBUG=all, I don't know why I didn't have it on earlier.

12:49:15 NET    : downloading https://www.horsedrawngames.com/feed/
(liferea:770): libsoup-http2-DEBUG: 12:49:16.390: [CLIENT] [C4-S1] [NONE] [SESSION] State NONE -> WRITE_HEADERS
(liferea:770): libsoup-http2-DEBUG: 12:49:16.390: [CLIENT] [C4-S1] [WRITE_HEADERS] [SEND] [HEADERS] stream_id=1, category=REQUEST finished=1
(liferea:770): libsoup-http2-DEBUG: 12:49:16.390: [CLIENT] [C4-S1] [WRITE_HEADERS] [SESSION] State WRITE_HEADERS -> WRITE_DONE
> GET /feed/ HTTP/2
> Soup-Debug-Timestamp: 1693590556
(liferea:770): libsoup-http2-DEBUG: 12:49:17.371: [CLIENT] [C4-S1] [READ_DATA] [SESSION] Closed stream 1: NO_ERROR
(liferea:770): libsoup-http2-DEBUG: 12:49:17.372: [CLIENT] [C4-S1] [READ_DATA] Client stream EOF
(liferea:770): libsoup-http2-DEBUG: 12:49:17.372: [CLIENT] [C4-S1] [READ_DATA] [SESSION] State READ_DATA -> READ_DONE
12:49:17 NET    : download status code: 200
12:49:17 NET    : source after download: >>>https://www.horsedrawngames.com/feed/<<<
12:49:17 NET    : 61705 bytes downloaded
12:49:17 UPDATE : complete job request (https://www.horsedrawngames.com/feed/) [2] 0x7b43f80
12:49:17 NET    : downloading https://www.horsedrawngames.com
(liferea:770): libsoup-http2-DEBUG: 12:49:17.764: [CLIENT] [C4-S3] [NONE] [SESSION] Request made for www.horsedrawngames.com
(liferea:770): libsoup-http2-DEBUG: 12:49:17.764: [CLIENT] [C4-S3] [NONE] [SESSION] State NONE -> WRITE_HEADERS
(liferea:770): libsoup-http2-DEBUG: 12:49:17.764: [CLIENT] [C4-S3] [WRITE_HEADERS] [SEND] [HEADERS] stream_id=3, category=REQUEST finished=1
(liferea:770): libsoup-http2-DEBUG: 12:49:17.764: [CLIENT] [C4-S3] [WRITE_HEADERS] [SESSION] State WRITE_HEADERS -> WRITE_DONE
> GET  HTTP/2
> Soup-Debug-Timestamp: 1693590557
> Soup-Debug: SoupSession 1 (0x114a770), SoupMessage 6 (0x7b336d0), GSocket 4 (0x7b41fb0)
> Accept: application/atom+xml,application/xml;q=0.9,text/xml;q=0.8,*/*;q=0.7
> Accept-Encoding: gzip, deflate, br
> User-Agent: Liferea/1.15.0 (Linux; https://lzone.de/liferea/) AppleWebKit (KHTML, like Gecko)
  
(liferea:770): libsoup-http2-DEBUG: 12:49:17.993: [CLIENT] [C4-S0] [-] [SEND] [GOAWAY]

The issue is the [GOAWAY], I'm assuming the connection is closed.
Possibly because the second request is so close to the first.
I'm looking at getting libsoup to return the error to the caller.

@rich-coe
Copy link
Contributor Author

rich-coe commented Sep 1, 2023

Opened libsoup#363 to track this issue.

@rich-coe
Copy link
Contributor Author

Submitted merge request to libsoup with patch https://gitlab.gnome.org/GNOME/libsoup/-/merge_requests/377

@rich-coe
Copy link
Contributor Author

Log with patch:

08:45:36 NET    : downloading https://www.horsedrawngames.com
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.390: [CLIENT] [C5-S0] [-] [SEND] [SETTINGS] stream_id=0
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.390: [CLIENT] [C5-S0] [-] [SEND] [WINDOW_UPDATE] stream_id=0
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.390: [CLIENT] [C5-S1] [NONE] [SESSION] Request made for www.horsedrawngames.com
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.390: [CLIENT] [C5-S1] [NONE] [SESSION] State NONE -> WRITE_HEADERS
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.390: [CLIENT] [C5-S1] [WRITE_HEADERS] [SEND] [HEADERS] stream_id=1, category=REQUEST finished=1
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.390: [CLIENT] [C5-S1] [WRITE_HEADERS] [SESSION] State WRITE_HEADERS -> WRITE_DONE
> GET  HTTP/2
> Soup-Debug-Timestamp: 1694353536
> Soup-Debug: SoupSession 1 (0xcfa310), SoupMessage 8 (0x7eee440), GSocket 5 (0x991310)
> Accept: application/atom+xml,application/xml;q=0.9,text/xml;q=0.8,*/*;q=0.7
> Accept-Encoding: gzip, deflate, br
> User-Agent: Liferea/1.15.0 (Linux; https://lzone.de/liferea/) AppleWebKit (KHTML, like Gecko)
  
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [RECV] [SETTINGS] Beginning: stream_id=0
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [RECV] [SETTINGS] Received: stream_id=0, flags=0
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [RECV] [WINDOW_UPDATE] Beginning: stream_id=0
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [RECV] [WINDOW_UPDATE] Received: stream_id=0, flags=0
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [RECV] WINDOW_UPDATE: increment=16777216, total=16842751
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [RECV] [SETTINGS] Beginning: stream_id=0
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [RECV] [SETTINGS] Received: stream_id=0, flags=1
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [SEND] [SETTINGS] Failed stream 0: The current session is closing
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S0] [-] [SEND] [GOAWAY]
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S1] [WRITE_DONE] [SESSION] Error: PROTOCOL_ERROR
(liferea:31519): libsoup-http2-DEBUG: 08:45:36.413: [CLIENT] [C5-S1] [WRITE_DONE] Finished stream 1: interrupted
< HTTP/2 0 (null)
< Soup-Debug-Timestamp: 1694353536
< Soup-Debug: SoupMessage 8 (0x7eee440)
  
08:45:36 NET    : download status code: 0
08:45:36 NET    : source after download: >>>https://www.horsedrawngames.com/<<<
08:45:36 NET    : 0 bytes downloaded
08:45:36 UPDATE : complete job request (https://www.horsedrawngames.com) [0] 0x82eadd0

@lwindolf lwindolf modified the milestones: 1.15.2, 1.5.3, 1.15.3, 1.15.4 Sep 15, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@lwindolf @rich-coe