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

libcurl 8.3.0 erroneously closes paused transfers with unknown content-length #11982

Closed
piru opened this issue Sep 29, 2023 · 7 comments
Closed

libcurl 8.3.0 erroneously closes paused transfers with unknown content-length #11982

piru opened this issue Sep 29, 2023 · 7 comments
Labels
HTTP HTTP/2

Comments

@piru
Copy link

piru commented Sep 29, 2023

I did this

/* Proof of Concept for libcurl 8.3.0 bug where paused downloads
 * with unknown Content-Length suddendly get errornously reported
 * as completed.
 *
 * Issue discovered and PoC written by Harry Sintonen <sintonen@iki.fi>
 *
 * Loosely based on https://curl.se/libcurl/c/multi-app.html
 */

#include <stdio.h>
#include <string.h>
#include <sys/time.h>
#include <unistd.h>
#include <stdlib.h>
#include <curl/curl.h>

#define HANDLECOUNT 2

int err(void)
{
  fprintf(stderr, "something unexpected went wrong - bailing out!\n");
  exit(2);
}

struct handle
{
  int idx;
  int paused;
  CURL *h;
};

static size_t cb(void *data, size_t size, size_t nmemb, void *clientp)
{
  size_t realsize = size * nmemb;
  struct handle *handle = (struct handle *) clientp;
  curl_off_t totalsize;

  printf("handle %d write %lu bytes\n", handle->idx, realsize);

  if(curl_easy_getinfo(handle->h, CURLINFO_CONTENT_LENGTH_DOWNLOAD_T, &totalsize) == CURLE_OK)
    printf("handle %d Content-Length %"CURL_FORMAT_CURL_OFF_T"\n", handle->idx, totalsize);

  handle->paused = 1;

  return CURL_WRITEFUNC_PAUSE;
}

int main(void)
{
  struct handle handles[HANDLECOUNT];
  CURLM *multi_handle;
  int i, still_running = 1, msgs_left, numfds;
  CURLMsg *msg;
  int rounds = 0;
  int rc = 1;

  curl_global_init(CURL_GLOBAL_DEFAULT);

  for(i = 0; i<HANDLECOUNT; i++) {
    handles[i].idx = i;
    handles[i].paused = 0;
    handles[i].h = curl_easy_init();
    if(!handles[i].h ||
      curl_easy_setopt(handles[i].h, CURLOPT_WRITEFUNCTION, cb) != CURLE_OK ||
      curl_easy_setopt(handles[i].h, CURLOPT_WRITEDATA, &handles[i]) != CURLE_OK ||
      curl_easy_setopt(handles[i].h, CURLOPT_FOLLOWLOCATION, 1L) != CURLE_OK ||
      curl_easy_setopt(handles[i].h, CURLOPT_URL,
        "https://www.meteoblue.com/en") != CURLE_OK) {
      err();
    }
  }

  multi_handle = curl_multi_init();
  if (!multi_handle)
    err();

  for(i = 0; i<HANDLECOUNT; i++) {
    if(curl_multi_add_handle(multi_handle, handles[i].h) != CURLM_OK)
      err();
  }

  for(;;) {
    if(curl_multi_perform(multi_handle, &still_running) != CURLM_OK)
      err();

    if(!still_running)
      break;

    if(curl_multi_poll(multi_handle, NULL, 0, 100, &numfds) != CURLM_OK)
      err();

    while((msg = curl_multi_info_read(multi_handle, &msgs_left))) {
      if(msg->msg == CURLMSG_DONE) {
        for(i = 0; i<HANDLECOUNT; i++) {
          if(msg->easy_handle == handles[i].h) {
            printf("handle %d done, result %d - wtf?\n", i, msg->data.result);
            goto out;
          }
        }
      }
    }
    /* Successfully paused? */
    if(handles[0].paused && handles[1].paused && ++rounds > 10) {
      /* Both handles are paused and transfer hasn't completed */
      printf("the test program ran as expected\n");
      rc = 0;
      break;
    }
  }
  out:

  for(i = 0; i<HANDLECOUNT; i++) {
    curl_multi_remove_handle(multi_handle, handles[i].h);
    curl_easy_cleanup(handles[i].h);
  }

  curl_multi_cleanup(multi_handle);

  curl_global_cleanup();

  return rc;
}

I expected the following

Both connections to get paused and neither complete.

curl/libcurl version

libcurl 8.3.0

operating system

Linux hostname 6.3.0-2-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.3.11-1 (2023-07-01) x86_64 GNU/Linux
@bagder
Copy link
Member

bagder commented Sep 29, 2023

Get full trace info by applying this:

--- issue-11982.c~      2023-09-29 08:40:42.643369656 +0200
+++ issue-11982.c       2023-09-29 08:41:46.012406540 +0200
@@ -55,6 +55,7 @@
   int rc = 1;
 
   curl_global_init(CURL_GLOBAL_DEFAULT);
+  curl_global_trace("all");
 
   for(i = 0; i<HANDLECOUNT; i++) {
     handles[i].idx = i;
@@ -64,6 +65,7 @@
       curl_easy_setopt(handles[i].h, CURLOPT_WRITEFUNCTION, cb) != CURLE_OK ||
       curl_easy_setopt(handles[i].h, CURLOPT_WRITEDATA, &handles[i]) != CURLE_OK ||
       curl_easy_setopt(handles[i].h, CURLOPT_FOLLOWLOCATION, 1L) != CURLE_OK ||
+      curl_easy_setopt(handles[i].h, CURLOPT_VERBOSE, 1L) != CURLE_OK ||
       curl_easy_setopt(handles[i].h, CURLOPT_URL,
         "https://www.meteoblue.com/en") != CURLE_OK) {
       err();

@bagder
Copy link
Member

bagder commented Sep 29, 2023

Here's a 900 line output from my run when reperoducing.

* !!! WARNING !!!
* This is a debug build of libcurl, do not use in production.
* STATE: INIT => CONNECT handle 0x55bcd632f008; line 1942
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x55bcd632f008; line 1985
* STATE: INIT => CONNECT handle 0x55bcd63426a8; line 1942
* Found bundle for host: 0x55bcd6328208 [serially]
* Server doesn't support multiplex (yet)
* Added connection 1. The cache now contains 2 members
* STATE: CONNECT => RESOLVING handle 0x55bcd63426a8; line 1985
* [HTTPS-CONNECT] added
* STATE: RESOLVING => CONNECTING handle 0x55bcd632f008; line 2059
* [HTTPS-CONNECT] connect, init
* [HTTPS-CONNECT] connect, check h21
* [HAPPY-EYEBALLS] created ipv4 (timeout 149998ms)
* [HAPPY-EYEBALLS] ipv4 starting (timeout=149998ms)
*   Trying 77.73.245.171:443...
* [TCP] cf_socket_open() -> 0, fd=5
* [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
* [HTTPS-CONNECT] connect -> 0, done=0
* Hostname 'www.meteoblue.com' was found in DNS cache
* [HTTPS-CONNECT] added
* STATE: RESOLVING => CONNECTING handle 0x55bcd63426a8; line 2059
* [HTTPS-CONNECT] connect, init
* [HTTPS-CONNECT] connect, check h21
* [HAPPY-EYEBALLS] created ipv4 (timeout 149998ms)
* [HAPPY-EYEBALLS] ipv4 starting (timeout=149998ms)
*   Trying 77.73.245.171:443...
* [TCP] cf_socket_open() -> 0, fd=7
* [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] get_selected_socks(h21) -> 10000
* [HTTPS-CONNECT] get_selected_socks -> 10000
* [HTTPS-CONNECT] get_selected_socks(h21) -> 10000
* [HTTPS-CONNECT] get_selected_socks -> 10000
* [HTTPS-CONNECT] get_selected_socks(h21) -> 10000
* [HTTPS-CONNECT] get_selected_socks -> 10000
* [HTTPS-CONNECT] get_selected_socks(h21) -> 10000
* [HTTPS-CONNECT] get_selected_socks -> 10000
* [HTTPS-CONNECT] connect, check h21
* [TCP] connected
* [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=1
* Connected to www.meteoblue.com (77.73.245.171) port 443
* [SSL] cf_connect()
* ALPN: curl offers h2,http/1.1
* Didn't find Session ID in cache for host HTTPS://www.meteoblue.com:443
* [TCP] send(len=517) -> 517, err=0
* [SSL] bio_cf_out_write(len=517) -> 517, err=0
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* [SSL] cf_connect() -> 0, done=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] connect, check h21
* [TCP] connected
* [HAPPY-EYEBALLS] ipv4 connect -> 0, connected=1
* Connected to www.meteoblue.com (77.73.245.171) port 443
* [SSL] cf_connect()
* ALPN: curl offers h2,http/1.1
* Didn't find Session ID in cache for host HTTPS://www.meteoblue.com:443
* [TCP] send(len=517) -> 517, err=0
* [SSL] bio_cf_out_write(len=517) -> 517, err=0
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_connect() -> 0, done=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] connect, check h21
* [SSL] cf_connect()
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=122) -> 122, err=0
* [TCP] recv(len=122) -> 122, err=0
* [SSL] bio_cf_in_read(len=122) -> 122, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=1) -> 1, err=0
* [TCP] recv(len=1) -> 1, err=0
* [SSL] bio_cf_in_read(len=1) -> 1, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=36) -> 36, err=0
* [TCP] recv(len=36) -> 36, err=0
* [SSL] bio_cf_in_read(len=36) -> 36, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=4422) -> 1269, err=0
* [TCP] recv(len=4422) -> 1269, err=0
* [SSL] bio_cf_in_read(len=4422) -> 1269, err=0
* [TCP] nw_in_read(len=3153) -> -1, err=81
* [TCP] recv(len=3153) -> -1, err=81
* [SSL] bio_cf_in_read(len=3153) -> -1, err=81
* [SSL] cf_connect() -> 0, done=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] connect, check h21
* [SSL] cf_connect()
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_connect() -> 0, done=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] connect, check h21
* [SSL] cf_connect()
* [TCP] nw_in_read(len=3153) -> 2648, err=0
* [TCP] recv(len=3153) -> 2648, err=0
* [SSL] bio_cf_in_read(len=3153) -> 2648, err=0
* [TCP] nw_in_read(len=505) -> -1, err=81
* [TCP] recv(len=505) -> -1, err=81
* [SSL] bio_cf_in_read(len=505) -> -1, err=81
* [SSL] cf_connect() -> 0, done=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] connect, check h21
* [SSL] cf_connect()
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_connect() -> 0, done=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] connect, check h21
* [SSL] cf_connect()
* [TCP] nw_in_read(len=505) -> 505, err=0
* [TCP] recv(len=505) -> 505, err=0
* [SSL] bio_cf_in_read(len=505) -> 505, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=281) -> 281, err=0
* [TCP] recv(len=281) -> 281, err=0
* [SSL] bio_cf_in_read(len=281) -> 281, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=69) -> 69, err=0
* [TCP] recv(len=69) -> 69, err=0
* [SSL] bio_cf_in_read(len=69) -> 69, err=0
* [TCP] send(len=80) -> 80, err=0
* [SSL] bio_cf_out_write(len=80) -> 80, err=0
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=*.meteoblue.com
*  start date: Jan 17 00:00:00 2023 GMT
*  expire date: Jan  9 23:59:59 2024 GMT
*  subjectAltName: host "www.meteoblue.com" matched cert's "*.meteoblue.com"
*  issuer: C=US; O=DigiCert, Inc.; CN=RapidSSL Global TLS RSA4096 SHA256 2022 CA1
*  SSL certificate verify ok.
* [SSL] cf_connect() -> 0, done=1
* [HTTPS-CONNECT] connect+handshake h21: 61ms, 1st data: 58ms
* [HTTP/2] [0] created h2 session
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] -> FRAME[SETTINGS, len=18]
* [HTTP/2] [0] -> FRAME[WINDOW_UPDATE, incr=1048510465]
* [TCP] send(len=86) -> 86, err=0
* [SSL] bio_cf_out_write(len=86) -> 86, err=0
* [HTTP/2] [0] egress: wrote 64 bytes
* [HTTP/2] cf_connect() -> 0, 1, 
* using HTTP/2
* [HTTPS-CONNECT] connect -> 0, done=1
* STATE: CONNECTING => PROTOCONNECT handle 0x55bcd632f008; line 2103
* multi changed, check CONNECT_PEND queue
* STATE: PROTOCONNECT => DO handle 0x55bcd632f008; line 2133
* [HTTP/2] [1] OPENED stream for https://www.meteoblue.com/en
* [HTTP/2] [1] [:method: GET]
* [HTTP/2] [1] [:scheme: https]
* [HTTP/2] [1] [:authority: www.meteoblue.com]
* [HTTP/2] [1] [:path: /en]
* [HTTP/2] [1] [accept: */*]
* [HTTP/2] [1] submit -> 56, 0
* [HTTP/2] [1] -> FRAME[HEADERS, len=27, hend=1, eos=1]
* [TCP] send(len=58) -> 58, err=0
* [SSL] bio_cf_out_write(len=58) -> 58, err=0
* [HTTP/2] [0] egress: wrote 36 bytes
* [HTTP/2] [1] cf_send(len=56) -> 56, 0, upload_left=0, h2 windows 65535-65535 (stream-conn), buffers 0-0 (stream-conn)
> GET /en HTTP/2
Host: www.meteoblue.com
Accept: */*

* [HTTP/2] [1] data done send
* STATE: DO => DID handle 0x55bcd632f008; line 2227
* STATE: DID => PERFORMING handle 0x55bcd632f008; line 2345
* [HTTPS-CONNECT] connect, check h21
* [SSL] cf_connect()
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_connect() -> 0, done=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] connect, check h21
* [SSL] cf_connect()
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=122) -> 122, err=0
* [TCP] recv(len=122) -> 122, err=0
* [SSL] bio_cf_in_read(len=122) -> 122, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=1) -> 1, err=0
* [TCP] recv(len=1) -> 1, err=0
* [SSL] bio_cf_in_read(len=1) -> 1, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=36) -> 36, err=0
* [TCP] recv(len=36) -> 36, err=0
* [SSL] bio_cf_in_read(len=36) -> 36, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=4422) -> 3917, err=0
* [TCP] recv(len=4422) -> 3917, err=0
* [SSL] bio_cf_in_read(len=4422) -> 3917, err=0
* [TCP] nw_in_read(len=505) -> -1, err=81
* [TCP] recv(len=505) -> -1, err=81
* [SSL] bio_cf_in_read(len=505) -> -1, err=81
* [SSL] cf_connect() -> 0, done=0
* [HTTPS-CONNECT] connect -> 0, done=0
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] get_selected_socks(h21) -> 1
* [HTTPS-CONNECT] get_selected_socks -> 1
* [HTTPS-CONNECT] connect, check h21
* [SSL] cf_connect()
* [TCP] nw_in_read(len=505) -> 505, err=0
* [TCP] recv(len=505) -> 505, err=0
* [SSL] bio_cf_in_read(len=505) -> 505, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=281) -> 281, err=0
* [TCP] recv(len=281) -> 281, err=0
* [SSL] bio_cf_in_read(len=281) -> 281, err=0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=69) -> 69, err=0
* [TCP] recv(len=69) -> 69, err=0
* [SSL] bio_cf_in_read(len=69) -> 69, err=0
* [TCP] send(len=80) -> 80, err=0
* [SSL] bio_cf_out_write(len=80) -> 80, err=0
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=*.meteoblue.com
*  start date: Jan 17 00:00:00 2023 GMT
*  expire date: Jan  9 23:59:59 2024 GMT
*  subjectAltName: host "www.meteoblue.com" matched cert's "*.meteoblue.com"
*  issuer: C=US; O=DigiCert, Inc.; CN=RapidSSL Global TLS RSA4096 SHA256 2022 CA1
*  SSL certificate verify ok.
* [SSL] cf_connect() -> 0, done=1
* [HTTPS-CONNECT] connect+handshake h21: 85ms, 1st data: 81ms
* [HTTP/2] [0] created h2 session
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] -> FRAME[SETTINGS, len=18]
* [HTTP/2] [0] -> FRAME[WINDOW_UPDATE, incr=1048510465]
* [TCP] send(len=86) -> 86, err=0
* [SSL] bio_cf_out_write(len=86) -> 86, err=0
* [HTTP/2] [0] egress: wrote 64 bytes
* [HTTP/2] cf_connect() -> 0, 1, 
* using HTTP/2
* [HTTPS-CONNECT] connect -> 0, done=1
* STATE: CONNECTING => PROTOCONNECT handle 0x55bcd63426a8; line 2103
* multi changed, check CONNECT_PEND queue
* STATE: PROTOCONNECT => DO handle 0x55bcd63426a8; line 2133
* [HTTP/2] [1] OPENED stream for https://www.meteoblue.com/en
* [HTTP/2] [1] [:method: GET]
* [HTTP/2] [1] [:scheme: https]
* [HTTP/2] [1] [:authority: www.meteoblue.com]
* [HTTP/2] [1] [:path: /en]
* [HTTP/2] [1] [accept: */*]
* [HTTP/2] [1] submit -> 56, 0
* [HTTP/2] [1] -> FRAME[HEADERS, len=27, hend=1, eos=1]
* [TCP] send(len=58) -> 58, err=0
* [SSL] bio_cf_out_write(len=58) -> 58, err=0
* [HTTP/2] [0] egress: wrote 36 bytes
* [HTTP/2] [1] cf_send(len=56) -> 56, 0, upload_left=0, h2 windows 65535-65535 (stream-conn), buffers 0-0 (stream-conn)
> GET /en HTTP/2
Host: www.meteoblue.com
Accept: */*

* [HTTP/2] [1] data done send
* STATE: DO => DID handle 0x55bcd63426a8; line 2227
* STATE: DID => PERFORMING handle 0x55bcd63426a8; line 2345
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=282) -> 282, err=0
* [TCP] recv(len=282) -> 282, err=0
* [SSL] bio_cf_in_read(len=282) -> 282, err=0
* Didn't find Session ID in cache for host HTTPS://www.meteoblue.com:443
* Added Session ID to cache for HTTPS://www.meteoblue.com:443 [server]
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=282) -> 282, err=0
* [TCP] recv(len=282) -> 282, err=0
* [SSL] bio_cf_in_read(len=282) -> 282, err=0
* Found Session ID in cache for host HTTPS://www.meteoblue.com:443
* old SSL session ID is stale, removing
* Added Session ID to cache for HTTPS://www.meteoblue.com:443 [server]
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=66) -> 66, err=0
* [TCP] recv(len=66) -> 66, err=0
* [SSL] bio_cf_in_read(len=66) -> 66, err=0
* [SSL] cf_recv(len=16384) -> 49, 0
* [HTTP/2] [0] ingress: read 49 bytes
* [HTTP/2] [0] <- FRAME[SETTINGS, len=18]
* [HTTP/2] [0] MAX_CONCURRENT_STREAMS: 128
* [HTTP/2] [0] ENABLE_PUSH: TRUE
* [HTTP/2] [0] notify MAX_CONCURRENT_STREAMS: 128
* [HTTP/2] [0] <- FRAME[WINDOW_UPDATE, incr=2147418112]
* [HTTP/2] [0] <- FRAME[SETTINGS, ack=1]
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] -> FRAME[SETTINGS, ack=1]
* [TCP] send(len=31) -> 31, err=0
* [SSL] bio_cf_out_write(len=31) -> 31, err=0
* [HTTP/2] [0] egress: wrote 9 bytes
* [HTTP/2] [1] cf_recv(len=16384) -> -1 81, buffered=0, window=0/10485760, connection 1048576000/1048576000
* multi changed, check CONNECT_PEND queue
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=161) -> 161, err=0
* [TCP] recv(len=161) -> 161, err=0
* [SSL] bio_cf_in_read(len=161) -> 161, err=0
* [SSL] cf_recv(len=16384) -> 144, 0
* [HTTP/2] [0] ingress: read 144 bytes
* [HTTP/2] [1] status: HTTP/2 302
* [HTTP/2] [1] header: server: nginx
* [HTTP/2] [1] header: date: Fri, 29 Sep 2023 06:49:46 GMT
* [HTTP/2] [1] header: content-type: text/html; charset=UTF-8
* [HTTP/2] [1] header: location: /en/weather/week/liafossen_norway_9061542
* [HTTP/2] [1] header: strict-transport-security: max-age=63072000
* [HTTP/2] [1] <- FRAME[HEADERS, len=126, hend=1, eos=0]
* [HTTP/2] [1] DRAIN dselect_bits=1
* [HTTP/2] [1] <- FRAME[DATA, len=0, eos=1, padlen=0]
* [HTTP/2] [1] DATA, buffered=205, window=0/10485760
* [HTTP/2] [1] CLOSED
* [HTTP/2] [1] DRAIN closed stream
* [HTTP/2] [1] cf_recv(len=16384) -> 205 0, buffered=0, window=-1/-1, connection 1048576000/1048576000
* HTTP/2 found, allow multiplexing
< HTTP/2 302 
< server: nginx
< date: Fri, 29 Sep 2023 06:49:46 GMT
< content-type: text/html; charset=UTF-8
< location: /en/weather/week/liafossen_norway_9061542
< strict-transport-security: max-age=63072000
< 
* [HTTP/2] [1] returning CLOSE
* [HTTP/2] handle_stream_close -> 0, 0
* [HTTP/2] [1] cf_recv(len=16384) -> 0 0, buffered=0, window=-1/-1, connection 1048576000/1048576000
* nread == 0, stream closed, bailing
* multi_done[PERFORMING]: status: 0 prem: 0 done: 0
* Connection #0 to host www.meteoblue.com left intact
* Issue another request to this URL: 'https://www.meteoblue.com/en/weather/week/liafossen_norway_9061542'
* STATE: PERFORMING => CONNECT handle 0x55bcd632f008; line 2521
* Found bundle for host: 0x55bcd6328208 [can multiplex]
* [TCP] is_alive: poll timeout, assume alive
* [HTTP/2] conn alive -> 1, input_pending=0
* Re-using existing connection with host www.meteoblue.com
* STATE: CONNECT => CONNECTING handle 0x55bcd632f008; line 1995
* STATE: CONNECTING => PROTOCONNECT handle 0x55bcd632f008; line 2103
* STATE: PROTOCONNECT => DO handle 0x55bcd632f008; line 2122
* [HTTP/2] [3] OPENED stream for https://www.meteoblue.com/en/weather/week/liafossen_norway_9061542
* [HTTP/2] [3] [:method: GET]
* [HTTP/2] [3] [:scheme: https]
* [HTTP/2] [3] [:authority: www.meteoblue.com]
* [HTTP/2] [3] [:path: /en/weather/week/liafossen_norway_9061542]
* [HTTP/2] [3] [accept: */*]
* [HTTP/2] [3] submit -> 94, 0
* [HTTP/2] [3] -> FRAME[HEADERS, len=36, hend=1, eos=1]
* [TCP] send(len=67) -> 67, err=0
* [SSL] bio_cf_out_write(len=67) -> 67, err=0
* [HTTP/2] [0] egress: wrote 45 bytes
* [HTTP/2] [3] cf_send(len=94) -> 94, 0, upload_left=0, h2 windows 65536-2147483647 (stream-conn), buffers 0-0 (stream-conn)
> GET /en/weather/week/liafossen_norway_9061542 HTTP/2
Host: www.meteoblue.com
Accept: */*

* [HTTP/2] [3] data done send
* STATE: DO => DID handle 0x55bcd632f008; line 2227
* STATE: DID => PERFORMING handle 0x55bcd632f008; line 2345
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=282) -> 282, err=0
* [TCP] recv(len=282) -> 282, err=0
* [SSL] bio_cf_in_read(len=282) -> 282, err=0
* Didn't find Session ID in cache for host HTTPS://www.meteoblue.com:443
* Added Session ID to cache for HTTPS://www.meteoblue.com:443 [server]
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [1] cf_recv(len=16384) -> -1 81, buffered=0, window=0/65535, connection 1048576000/1048576000
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=282) -> 282, err=0
* [TCP] recv(len=282) -> 282, err=0
* [SSL] bio_cf_in_read(len=282) -> 282, err=0
* Found Session ID in cache for host HTTPS://www.meteoblue.com:443
* old SSL session ID is stale, removing
* Added Session ID to cache for HTTPS://www.meteoblue.com:443 [server]
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=66) -> 66, err=0
* [TCP] recv(len=66) -> 66, err=0
* [SSL] bio_cf_in_read(len=66) -> 66, err=0
* [SSL] cf_recv(len=16384) -> 49, 0
* [HTTP/2] [0] ingress: read 49 bytes
* [HTTP/2] [0] <- FRAME[SETTINGS, len=18]
* [HTTP/2] [0] MAX_CONCURRENT_STREAMS: 128
* [HTTP/2] [0] ENABLE_PUSH: TRUE
* [HTTP/2] [0] notify MAX_CONCURRENT_STREAMS: 128
* [HTTP/2] [0] <- FRAME[WINDOW_UPDATE, incr=2147418112]
* [HTTP/2] [0] <- FRAME[SETTINGS, ack=1]
* [TCP] nw_in_read(len=5) -> -1, err=81
* [TCP] recv(len=5) -> -1, err=81
* [SSL] bio_cf_in_read(len=5) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] -> FRAME[SETTINGS, ack=1]
* [TCP] send(len=31) -> 31, err=0
* [SSL] bio_cf_out_write(len=31) -> 31, err=0
* [HTTP/2] [0] egress: wrote 9 bytes
* [HTTP/2] [1] cf_recv(len=16384) -> -1 81, buffered=0, window=0/10485760, connection 1048576000/1048576000
* multi changed, check CONNECT_PEND queue
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=161) -> 161, err=0
* [TCP] recv(len=161) -> 161, err=0
* [SSL] bio_cf_in_read(len=161) -> 161, err=0
* [SSL] cf_recv(len=16384) -> 144, 0
* [HTTP/2] [0] ingress: read 144 bytes
* [HTTP/2] [1] status: HTTP/2 302
* [HTTP/2] [1] header: server: nginx
* [HTTP/2] [1] header: date: Fri, 29 Sep 2023 06:49:46 GMT
* [HTTP/2] [1] header: content-type: text/html; charset=UTF-8
* [HTTP/2] [1] header: location: /en/weather/week/liafossen_norway_9061542
* [HTTP/2] [1] header: strict-transport-security: max-age=63072000
* [HTTP/2] [1] <- FRAME[HEADERS, len=126, hend=1, eos=0]
* [HTTP/2] [1] DRAIN dselect_bits=1
* [HTTP/2] [1] <- FRAME[DATA, len=0, eos=1, padlen=0]
* [HTTP/2] [1] DATA, buffered=205, window=0/10485760
* [HTTP/2] [1] CLOSED
* [HTTP/2] [1] DRAIN closed stream
* [HTTP/2] [1] cf_recv(len=16384) -> 205 0, buffered=0, window=-1/-1, connection 1048576000/1048576000
* HTTP/2 found, allow multiplexing
< HTTP/2 302 
< server: nginx
< date: Fri, 29 Sep 2023 06:49:46 GMT
< content-type: text/html; charset=UTF-8
< location: /en/weather/week/liafossen_norway_9061542
< strict-transport-security: max-age=63072000
< 
* [HTTP/2] [1] returning CLOSE
* [HTTP/2] handle_stream_close -> 0, 0
* [HTTP/2] [1] cf_recv(len=16384) -> 0 0, buffered=0, window=-1/-1, connection 1048576000/1048576000
* nread == 0, stream closed, bailing
* multi_done[PERFORMING]: status: 0 prem: 0 done: 0
* Connection #1 to host www.meteoblue.com left intact
* Issue another request to this URL: 'https://www.meteoblue.com/en/weather/week/liafossen_norway_9061542'
* STATE: PERFORMING => CONNECT handle 0x55bcd63426a8; line 2521
* Found bundle for host: 0x55bcd6328208 [can multiplex]
* Multiplexed connection found
* Re-using existing connection with host www.meteoblue.com
* STATE: CONNECT => PROTOCONNECT handle 0x55bcd63426a8; line 1993
* STATE: PROTOCONNECT => DO handle 0x55bcd63426a8; line 2122
* [HTTP/2] [5] OPENED stream for https://www.meteoblue.com/en/weather/week/liafossen_norway_9061542
* [HTTP/2] [5] [:method: GET]
* [HTTP/2] [5] [:scheme: https]
* [HTTP/2] [5] [:authority: www.meteoblue.com]
* [HTTP/2] [5] [:path: /en/weather/week/liafossen_norway_9061542]
* [HTTP/2] [5] [accept: */*]
* [HTTP/2] [5] submit -> 94, 0
* [HTTP/2] [5] -> FRAME[HEADERS, len=36, hend=1, eos=1]
* [TCP] send(len=67) -> 67, err=0
* [SSL] bio_cf_out_write(len=67) -> 67, err=0
* [HTTP/2] [0] egress: wrote 45 bytes
* [HTTP/2] [5] cf_send(len=94) -> 94, 0, upload_left=0, h2 windows 65536-2147483647 (stream-conn), buffers 0-0 (stream-conn)
> GET /en/weather/week/liafossen_norway_9061542 HTTP/2
Host: www.meteoblue.com
Accept: */*

* [HTTP/2] [5] data done send
* STATE: DO => DID handle 0x55bcd63426a8; line 2227
* STATE: DID => PERFORMING handle 0x55bcd63426a8; line 2345
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 1443, err=0
* [TCP] recv(len=16401) -> 1443, err=0
* [SSL] bio_cf_in_read(len=16401) -> 1443, err=0
* [TCP] nw_in_read(len=14958) -> -1, err=81
* [TCP] recv(len=14958) -> -1, err=81
* [SSL] bio_cf_in_read(len=14958) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [3] cf_recv(len=16384) -> -1 81, buffered=0, window=0/10485760, connection 1048576000/1048576000
* [TCP] nw_in_read(len=14958) -> 13032, err=0
* [TCP] recv(len=14958) -> 13032, err=0
* [SSL] bio_cf_in_read(len=14958) -> 13032, err=0
* [TCP] nw_in_read(len=1926) -> -1, err=81
* [TCP] recv(len=1926) -> -1, err=81
* [SSL] bio_cf_in_read(len=1926) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [3] cf_recv(len=16384) -> -1 81, buffered=0, window=0/10485760, connection 1048576000/1048576000
* [TCP] nw_in_read(len=1926) -> 1926, err=0
* [TCP] recv(len=1926) -> 1926, err=0
* [SSL] bio_cf_in_read(len=1926) -> 1926, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 965, err=0
* [TCP] recv(len=16401) -> 965, err=0
* [SSL] bio_cf_in_read(len=16401) -> 965, err=0
* [TCP] nw_in_read(len=15436) -> -1, err=81
* [TCP] recv(len=15436) -> -1, err=81
* [SSL] bio_cf_in_read(len=15436) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] ingress: read 16384 bytes
* [HTTP/2] [5] status: HTTP/2 200
* [HTTP/2] [5] header: server: nginx
* [HTTP/2] [5] header: date: Fri, 29 Sep 2023 06:49:46 GMT
* [HTTP/2] [5] header: content-type: text/html; charset=UTF-8
* [HTTP/2] [5] header: strict-transport-security: max-age=63072000
* [HTTP/2] [5] <- FRAME[HEADERS, len=83, hend=1, eos=0]
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=8344, window=8192/10485760
* [TCP] nw_in_read(len=15436) -> -1, err=81
* [TCP] recv(len=15436) -> -1, err=81
* [SSL] bio_cf_in_read(len=15436) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [3] cf_recv(len=16384) -> -1 81, buffered=0, window=0/10485760, connection 1048559726/1048576000
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=42, window=16274/10485760, connection 1048559726/1048576000
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
< server: nginx
< date: Fri, 29 Sep 2023 06:49:46 GMT
< content-type: text/html; charset=UTF-8
< strict-transport-security: max-age=63072000
< 
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 10469486 for stream 5
* [TCP] nw_in_read(len=15436) -> 15436, err=0
* [TCP] recv(len=15436) -> 15436, err=0
* [SSL] bio_cf_in_read(len=15436) -> 15436, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=7873) -> 7873, err=0
* [TCP] recv(len=7873) -> 7873, err=0
* [SSL] bio_cf_in_read(len=7873) -> 7873, err=0
* [SSL] cf_recv(len=16384) -> 7856, 0
* [HTTP/2] [0] ingress: read 24240 bytes
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=152, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=8344, window=0/0
* [HTTP/2] process_pending_input: 7856 bytes left in connection buffer
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=16536, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=7719, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=24255, window=0/0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 2745, err=0
* [TCP] recv(len=16401) -> 2745, err=0
* [SSL] bio_cf_in_read(len=16401) -> 2745, err=0
* [TCP] nw_in_read(len=13656) -> -1, err=81
* [TCP] recv(len=13656) -> -1, err=81
* [SSL] bio_cf_in_read(len=13656) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [3] cf_recv(len=16384) -> -1 81, buffered=0, window=0/10485760, connection 1048535513/1048576000
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=7871, window=0/0, connection 1048535513/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 10445273 for stream 5
* [TCP] nw_in_read(len=13656) -> 11584, err=0
* [TCP] recv(len=13656) -> 11584, err=0
* [SSL] bio_cf_in_read(len=13656) -> 11584, err=0
* [TCP] nw_in_read(len=2072) -> 2072, err=0
* [TCP] recv(len=2072) -> 2072, err=0
* [SSL] bio_cf_in_read(len=2072) -> 2072, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 15299, err=0
* [TCP] recv(len=16401) -> 15299, err=0
* [SSL] bio_cf_in_read(len=16401) -> 15299, err=0
* [TCP] nw_in_read(len=1102) -> 1102, err=0
* [TCP] recv(len=1102) -> 1102, err=0
* [SSL] bio_cf_in_read(len=1102) -> 1102, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 10477, err=0
* [TCP] recv(len=16401) -> 10477, err=0
* [SSL] bio_cf_in_read(len=16401) -> 10477, err=0
* [TCP] nw_in_read(len=5924) -> -1, err=81
* [TCP] recv(len=5924) -> -1, err=81
* [SSL] bio_cf_in_read(len=5924) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] ingress: read 32768 bytes
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=16063, window=0/0
* [HTTP/2] process_pending_input: 16384 bytes left in connection buffer
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=24255, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=32447, window=0/0
* [TCP] nw_in_read(len=5924) -> 5924, err=0
* [TCP] recv(len=5924) -> 5924, err=0
* [SSL] bio_cf_in_read(len=5924) -> 5924, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 11447, err=0
* [TCP] recv(len=16401) -> 11447, err=0
* [SSL] bio_cf_in_read(len=16401) -> 11447, err=0
* [TCP] nw_in_read(len=4954) -> -1, err=81
* [TCP] recv(len=4954) -> -1, err=81
* [SSL] bio_cf_in_read(len=4954) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] ingress: read 16384 bytes
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=40639, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=48831, window=0/0
* [TCP] nw_in_read(len=4954) -> -1, err=81
* [TCP] recv(len=4954) -> -1, err=81
* [SSL] bio_cf_in_read(len=4954) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [3] cf_recv(len=16384) -> -1 81, buffered=0, window=0/10485760, connection 1048486415/1048576000
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=40585, window=0/0, connection 1048486415/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 10396175 for stream 5
* [TCP] nw_in_read(len=4954) -> 4954, err=0
* [TCP] recv(len=4954) -> 4954, err=0
* [SSL] bio_cf_in_read(len=4954) -> 4954, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 16401, err=0
* [TCP] recv(len=16401) -> 16401, err=0
* [SSL] bio_cf_in_read(len=16401) -> 16401, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 9043, err=0
* [TCP] recv(len=16401) -> 9043, err=0
* [SSL] bio_cf_in_read(len=16401) -> 9043, err=0
* [TCP] nw_in_read(len=7358) -> 4344, err=0
* [TCP] recv(len=7358) -> 4344, err=0
* [SSL] bio_cf_in_read(len=7358) -> 4344, err=0
* [TCP] nw_in_read(len=3014) -> 3014, err=0
* [TCP] recv(len=3014) -> 3014, err=0
* [SSL] bio_cf_in_read(len=3014) -> 3014, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 8565, err=0
* [TCP] recv(len=16401) -> 8565, err=0
* [SSL] bio_cf_in_read(len=16401) -> 8565, err=0
* [TCP] nw_in_read(len=7836) -> 5792, err=0
* [TCP] recv(len=7836) -> 5792, err=0
* [SSL] bio_cf_in_read(len=7836) -> 5792, err=0
* [TCP] nw_in_read(len=2044) -> -1, err=81
* [TCP] recv(len=2044) -> -1, err=81
* [SSL] bio_cf_in_read(len=2044) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] ingress: read 49152 bytes
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=40639, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=48831, window=0/0
* [HTTP/2] process_pending_input: 32768 bytes left in connection buffer
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=57023, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=65215, window=0/0
* [HTTP/2] process_pending_input: 16384 bytes left in connection buffer
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=73407, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=81599, window=0/0
* [TCP] nw_in_read(len=2044) -> 2044, err=0
* [TCP] recv(len=2044) -> 2044, err=0
* [SSL] bio_cf_in_read(len=2044) -> 2044, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 16401, err=0
* [TCP] recv(len=16401) -> 16401, err=0
* [SSL] bio_cf_in_read(len=16401) -> 16401, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=474) -> 474, err=0
* [TCP] recv(len=474) -> 474, err=0
* [SSL] bio_cf_in_read(len=474) -> 474, err=0
* [SSL] cf_recv(len=16384) -> 457, 0
* [HTTP/2] [0] ingress: read 33225 bytes
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=89791, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=97983, window=0/0
* [HTTP/2] process_pending_input: 16841 bytes left in connection buffer
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=106175, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=114367, window=0/0
* [HTTP/2] process_pending_input: 457 bytes left in connection buffer
* [HTTP/2] [5] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=122559, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=295, eos=0, padlen=0]
* [HTTP/2] [5] DATA, buffered=122854, window=0/0
* [HTTP/2] [5] <- FRAME[DATA, len=0, eos=1, padlen=0]
* [HTTP/2] [5] DATA, buffered=122854, window=0/0
* [HTTP/2] [5] CLOSED
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 16401, err=0
* [TCP] recv(len=16401) -> 16401, err=0
* [SSL] bio_cf_in_read(len=16401) -> 16401, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 16401, err=0
* [TCP] recv(len=16401) -> 16401, err=0
* [SSL] bio_cf_in_read(len=16401) -> 16401, err=0
* [SSL] cf_recv(len=16384) -> 16384, 0
* [TCP] nw_in_read(len=5) -> 5, err=0
* [TCP] recv(len=5) -> 5, err=0
* [SSL] bio_cf_in_read(len=5) -> 5, err=0
* [TCP] nw_in_read(len=16401) -> 11966, err=0
* [TCP] recv(len=16401) -> 11966, err=0
* [SSL] bio_cf_in_read(len=16401) -> 11966, err=0
* [TCP] nw_in_read(len=4435) -> -1, err=81
* [TCP] recv(len=4435) -> -1, err=81
* [SSL] bio_cf_in_read(len=4435) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [0] ingress: read 32768 bytes
* [HTTP/2] [3] status: HTTP/2 200
* [HTTP/2] [3] header: server: nginx
* [HTTP/2] [3] header: date: Fri, 29 Sep 2023 06:49:46 GMT
* [HTTP/2] [3] header: content-type: text/html; charset=UTF-8
* [HTTP/2] [3] header: strict-transport-security: max-age=63072000
* [HTTP/2] [3] <- FRAME[HEADERS, len=83, hend=1, eos=0]
* [HTTP/2] [3] DRAIN dselect_bits=1
* [HTTP/2] [3] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [3] DATA, buffered=8344, window=8192/10485760
* [HTTP/2] process_pending_input: 16384 bytes left in connection buffer
* [HTTP/2] [3] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [3] DATA, buffered=16536, window=16384/10485760
* [HTTP/2] [3] <- FRAME[DATA, len=8192, eos=0, padlen=0]
* [HTTP/2] [3] DATA, buffered=24728, window=24576/10485760
* [TCP] nw_in_read(len=4435) -> -1, err=81
* [TCP] recv(len=4435) -> -1, err=81
* [SSL] bio_cf_in_read(len=4435) -> -1, err=81
* [SSL] cf_recv(len=16384) -> -1, 81
* [HTTP/2] [3] cf_recv(len=16384) -> 16384 0, buffered=16408, window=32640/10485760, connection 1048371506/1048576000
* HTTP/2 found, allow multiplexing
< HTTP/2 200 
< server: nginx
< date: Fri, 29 Sep 2023 06:49:46 GMT
< content-type: text/html; charset=UTF-8
< strict-transport-security: max-age=63072000
< 
* Set HTTP/2 window size to 0 for stream 3
* HTTP/2 window size is now 10453120 for stream 3
* [HTTP/2] [5] DRAIN closed stream
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=106470, window=-1/-1, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 4294967295 for stream 5
* [HTTP/2] [3] cf_recv(len=16384) -> 16384 0, buffered=24, window=0/0, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 3
* HTTP/2 window size is now 10453120 for stream 3
* [HTTP/2] [5] DRAIN closed stream
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=90086, window=-1/-1, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 4294967295 for stream 5
* [HTTP/2] [5] DRAIN closed stream
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=73702, window=-1/-1, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 4294967295 for stream 5
* [HTTP/2] [5] DRAIN closed stream
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=57318, window=-1/-1, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 4294967295 for stream 5
* [HTTP/2] [5] DRAIN closed stream
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=40934, window=-1/-1, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 4294967295 for stream 5
* [HTTP/2] [5] DRAIN closed stream
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=24550, window=-1/-1, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 4294967295 for stream 5
* [HTTP/2] [5] DRAIN closed stream
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] cf_recv(len=16384) -> 16384 0, buffered=8166, window=-1/-1, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 4294967295 for stream 5
* [HTTP/2] [5] DRAIN closed stream
* [HTTP/2] [5] DRAIN dselect_bits=1
* [HTTP/2] [5] cf_recv(len=16384) -> 8166 0, buffered=0, window=-1/-1, connection 1048371506/1048576000
* Set HTTP/2 window size to 0 for stream 5
* HTTP/2 window size is now 4294967295 for stream 5
* [HTTP/2] [5] returning CLOSE
* [HTTP/2] handle_stream_close -> 0, 0
* [HTTP/2] [5] cf_recv(len=16384) -> 0 0, buffered=0, window=-1/-1, connection 1048371506/1048576000
* nread == 0, stream closed, bailing
* STATE: PERFORMING => DONE handle 0x55bcd63426a8; line 2544
* multi_done[DONE]: status: 0 prem: 0 done: 0
* Connection still in use 1, no more multi_done now!
* Expire cleared
* multi_done[PERFORMING]: status: 0 prem: 1 done: 0
* [HTTP/2] [3] premature DATA_DONE, RST stream
* [HTTP/2] [3] -> FRAME[RST_STREAM, len=4, flags=0, error=5]
* [HTTP/2] [3] RESET: STREAM_CLOSED (err 5)
* [HTTP/2] [3] DRAIN dselect_bits=1
* [TCP] send(len=35) -> 35, err=0
* [SSL] bio_cf_out_write(len=35) -> 35, err=0
* [HTTP/2] [0] egress: wrote 13 bytes
* Connection #0 to host www.meteoblue.com left intact
* Expire cleared
handle 1 write 16232 bytes
handle 1 Content-Length -1
handle 0 write 16232 bytes
handle 0 Content-Length -1
handle 1 done, result 0 - wtf?

@icing
Copy link
Contributor

icing commented Sep 29, 2023

Made this into a test case. The scenario is as follows:

1. a h2 stream received 32k of body DATA with an EOS indicator from the server
2. transfer reads 16K, h2 delivers and knows stream is CLOSED, sets DRAIN to make transfer keep on reading
3. transfer delivers the 16K to client_write, client PAUSEs the transfer
4. transfer runs again with EXPIRE, sees DRAIN and pulls more DATA from connection
5. writes that data with client_write which puts it into the tempbufs, not delivered to client
6. h2 keeps on setting DRAIN since the stream close has not been read yet
7. transfer reads CLOSE from connection and terminates transfer, tempbufs are not flushed

One could be tempted to argue that the h2 cfilter should not set DRAIN for PAUSED transfers, but that wold not solve the issue. On the first read, the transfer is not PAUSED yet and DRAIN needs to be set by the filter. The PAUSE happens when transfer does the client write afterwards. The DRAIN and EXPIRE then is already on its way.

We need to change transfer to handle PAUSED handles in a better way.

@bagder
Copy link
Member

bagder commented Sep 29, 2023 •
edited
Loading

Clearly a paused transfer cannot be considered done in (7). It needs to get that state stored and handled though, so that when later unpaused it can just delivere the cached data and then die.

icing added a commit to icing/curl that referenced this issue Sep 29, 2023
@icing
Testcase and fix for pausing h2 streams
760c564 
- refs curl#11982 where it was noted that paused transfers may
  close successfully without delivering the complete data
- made sample poc into tests/http/client/h2-pausing.c and
  added test_02_27 to reproduce
@icing icing mentioned this issue Sep 29, 2023
Closed
@icing
Copy link
Contributor

icing commented Sep 29, 2023

Made this into a test case and proposed fix at #11989.

It's a small change, maybe you could verify this as patch into your 8.3.0 setup?

@piru
Copy link
Author

piru commented Sep 29, 2023

Made this into a test case and proposed fix at #11989.

It's a small change, maybe you could verify this as patch into your 8.3.0 setup?

Works for me now, both in the test app and in the Webkit based browser when using the libcurl backend. 👍🏻

@donny-dont
Copy link
Contributor

Thanks for reporting this @piru ! I was doing some smoke testing on updated requirements for the Windows WebKit port and https://webkit.org was not loading. After this patch it loads successfully @icing . Thanks!

@bagder bagder closed this as completed in 6b9a591 Sep 30, 2023
@donny-dont donny-dont mentioned this issue Oct 2, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
HTTP HTTP/2
Milestone
No milestone
Development

No branches or pull requests
4 participants
@icing @bagder @donny-dont @piru