{"action":"created","issue":{"url":"https://api.github.com/repos/curl/curl/issues/1129","repository_url":"https://api.github.com/repos/curl/curl","labels_url":"https://api.github.com/repos/curl/curl/issues/1129/labels{/name}","comments_url":"https://api.github.com/repos/curl/curl/issues/1129/comments","events_url":"https://api.github.com/repos/curl/curl/issues/1129/events","html_url":"https://github.com/curl/curl/issues/1129","id":189966644,"number":1129,"title":"Test 1700 (HTTP/2 upgrade and reuse) fails rarely","user":{"login":"jay","id":965580,"avatar_url":"https://avatars.githubusercontent.com/u/965580?v=3","gravatar_id":"","url":"https://api.github.com/users/jay","html_url":"https://github.com/jay","followers_url":"https://api.github.com/users/jay/followers","following_url":"https://api.github.com/users/jay/following{/other_user}","gists_url":"https://api.github.com/users/jay/gists{/gist_id}","starred_url":"https://api.github.com/users/jay/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jay/subscriptions","organizations_url":"https://api.github.com/users/jay/orgs","repos_url":"https://api.github.com/users/jay/repos","events_url":"https://api.github.com/users/jay/events{/privacy}","received_events_url":"https://api.github.com/users/jay/received_events","type":"User","site_admin":false},"labels":[{"id":194601710,"url":"https://api.github.com/repos/curl/curl/labels/HTTP/2","name":"HTTP/2","color":"009800","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2016-11-17T07:49:29Z","updated_at":"2016-11-17T19:58:34Z","closed_at":null,"body":"Since changing the HTTP/2 window size and fixing a related test failure I ran the HTTP/2 tests repeatedly to see what would shake out and I've noticed that test 1700 rarely fails (1 in 100-300). It happens regardless of the window size (I tested both before and after the window size was changed).\r\n\r\n[Test 1700](https://github.com/curl/curl/blob/master/tests/data/test1700) tests the scenario where one HTTP transfer is upgraded to HTTP/2 and then another HTTP transfer is supposed to go over that same upgraded HTTP/2 connection. In the fail case the connection is apparently dead so libcurl makes a new one, resulting in a second upgrade:\r\n~~~diff\r\n--- log/check-expected\t2016-11-17 02:01:15.236590560 -0500\r\n+++ log/check-generated\t2016-11-17 02:01:15.236590560 -0500\r\n@@ -14,6 +14,10 @@\r\n via: 1.1 nghttpx[CR][LF]\r\n [CR][LF]\r\n -foo-[LF]\r\n+HTTP/1.1 101 Switching Protocols[CR][LF]\r\n+Connection: Upgrade[CR][LF]\r\n+Upgrade: h2c[CR][LF]\r\n+[CR][LF]\r\n HTTP/2 200 [CR][LF]\r\n date: Thu, 09 Nov 2010 14:49:00 GMT[CR][LF]\r\n content-length: 6[CR][LF]\r\n~~~\r\nIn the http_v2_server log I can see the connection is apparently deleted before libcurl reconnects, but I don't know if it's the server responding to a problem with the client or why it happens. Normally I think it should not happen.\r\n~~~\r\n17/Nov/2016:00:15:27 -0500 PID77233 [INFO] shrpx_client_handler.cc:480 [CLIENT_HANDLER:0x7fceadcfd000] Deleting\r\n17/Nov/2016:00:15:27 -0500 PID77233 [INFO] shrpx_client_handler.cc:503 [CLIENT_HANDLER:0x7fceadcfd000] Deleted\r\n17/Nov/2016:00:15:27 -0500 PID77233 [INFO] shrpx_connection_handler.cc:363 [LISTEN:0x7ffe6140fc30] Accepted connection from 127.0.0.1, fd=10\r\n~~~\r\nOne thing I notice in the trace different between a good and bad run is the good run has this for the first transfer after the headers are received but before the second transfer:\r\n~~~\r\n00:53:55.350775 == Info: nread=9\r\n00:53:55.350796 == Info: Got SETTINGS\r\n00:53:55.350806 == Info: MAX_CONCURRENT_STREAMS == 100\r\n00:53:55.350814 == Info: ENABLE_PUSH == TRUE\r\n00:53:55.350822 == Info: nghttp2_session_mem_recv() returns 9\r\n00:53:55.350830 == Info: All data in connection buffer processed\r\n~~~\r\nTo run test1700 in a loop until it fails I'm using this script:\r\n~~~shell\r\n#!/bin/bash\r\n\r\nCOUNTER=0\r\n\r\nwhile true; do\r\n  echo COUNTER: $COUNTER\r\n  ./runtests.pl -p 1700 || exit\r\n  let COUNTER=COUNTER+1\r\ndone\r\n~~~\r\nCan anyone reproduce?\r\n~~~\r\ncurl 7.52.0-DEV (x86_64-pc-linux-gnu) libcurl/7.52.0-DEV OpenSSL/1.0.2j zlib/1.2.8 nghttp2/1.16.1 librtmp/2.3\r\nProtocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp smb smbs smtp smtps telnet tftp \r\nFeatures: Debug TrackMemory IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets \r\n\r\nLinux ubuntu1604-x64-vm 4.4.0-47-generic #68-Ubuntu SMP Wed Oct 26 19:39:52 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux\r\n~~~\r\n\r\n/cc @tatsuhiro-t "},"comment":{"url":"https://api.github.com/repos/curl/curl/issues/comments/261352439","html_url":"https://github.com/curl/curl/issues/1129#issuecomment-261352439","issue_url":"https://api.github.com/repos/curl/curl/issues/1129","id":261352439,"user":{"login":"jay","id":965580,"avatar_url":"https://avatars.githubusercontent.com/u/965580?v=3","gravatar_id":"","url":"https://api.github.com/users/jay","html_url":"https://github.com/jay","followers_url":"https://api.github.com/users/jay/followers","following_url":"https://api.github.com/users/jay/following{/other_user}","gists_url":"https://api.github.com/users/jay/gists{/gist_id}","starred_url":"https://api.github.com/users/jay/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jay/subscriptions","organizations_url":"https://api.github.com/users/jay/orgs","repos_url":"https://api.github.com/users/jay/repos","events_url":"https://api.github.com/users/jay/events{/privacy}","received_events_url":"https://api.github.com/users/jay/received_events","type":"User","site_admin":false},"created_at":"2016-11-17T19:58:34Z","updated_at":"2016-11-17T19:58:34Z","body":"I have a http2_v2_server log if that's what you mean? I've attached the log dir from a good run and one from a bad run to this post.\r\n[log.1700.good.and.bad.zip](https://github.com/curl/curl/files/598311/log.1700.good.and.bad.zip)\r\nIf there's anything I can do to get more information on this please let me know."}}
{"actor":{"display_login":"jay"}}