#34341 - 26.1; url-retrieve-synchronously returns blank buffer

GNU bug report logs - #34341
26.1; url-retrieve-synchronously returns blank buffer

Package: emacs;

Reported by: Laurent Charignon <l.charignon <at> gmail.com>

Date: Wed, 6 Feb 2019 07:11:01 UTC

Severity: normal

Tags: fixed

Merged with 39158

Found in version 26.1

Fixed in versions 26.3, 27.1

Done: Noam Postavsky <npostavs <at> gmail.com>

Bug is archived. No further changes may be made.

View this message in rfc822 format

From: Laurent Charignon <l.charignon <at> gmail.com> To: 34341 <at> debbugs.gnu.org Subject: bug#34341: 26.1; url-retrieve-synchronously returns blank buffer Date: Tue, 5 Feb 2019 20:55:11 -0800

[Message part 1 (text/plain, inline)]

#### Context The symptom of this issue first came up in the context of `ghub`, a package that offers interfacing with Github from emacs (issue: https://github.com/magit/ghub/issues/81). Multiple users of the `ghub` package started observing that synchronously retrieving content from the github API through ghub returned blank responses. I investigated and narrowed down a minimal repro case of the problem, which I believe indicate that the problem is in Emacs itself. #### Steps to reproduce 1) Run emacs -Q 2) Evaluate the following elisp snippet ``` (switch-to-buffer (url-retrieve-synchronously " https://api.github.com/users/charignon/repos") (buffer-string)) ``` I expect then to see a buffer with an http response, instead I get a blank buffer. #### Investigation / Observation 1) This behavior reproduces consistently with api.github.com, not with any websites that I tried. 2) `url-retrieve`, the asynchronous way to fetch url, does not seem to be subject to the issue, and works as expected, for example: ``` (url-retrieve "https://api.github.com/users/charignon/repos" (lambda (x &rest v) x)) ``` works 3) Once a connection is established (for example by `url-retrieve`) and can be reused, then `url-retrieve-synchronously` works. That is, the snippet above returns a buffer with an HTTP response from github. Removing the connection (emacs process managing it) is necessary after you ran `url-retrieve` if you want to reproduce the bug. 4) I used wireshark to look at the network traffic: Here is the trace for the `url-retrieve-synchronously` call to github (from steps to reproduce): I blurred out the info field for DNS packets (not relevant) ``` No. Time Source Destination Protocol Length Info 9 1.658218501 vulture.lan testwifi.here DNS 74 XXX 10 1.658260266 vulture.lan testwifi.here DNS 74 XXX 11 1.665053481 testwifi.here vulture.lan DNS 158 XXX 12 1.703946584 testwifi.here vulture.lan DNS 106 XXX 13 1.704485426 vulture.lan api.github.com TCP 74 55424 → https(443) [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2499281666 TSecr=0 WS=128 14 1.728009793 api.github.com vulture.lan TCP 74 https(443) → 55424 [SYN, ACK] Seq=0 Ack=1 Win=28480 Len=0 MSS=1436 SACK_PERM=1 TSval=3029633168 TSecr=2499281666 WS=1024 15 1.728074018 vulture.lan api.github.com TCP 66 55424 → https(443) [ACK] Seq=1 Ack=1 Win=29312 Len=0 TSval=2499281689 TSecr=3029633168 16 1.748051225 vulture.lan api.github.com TLSv1.3 583 Client Hello 17 1.773082726 api.github.com vulture.lan TLSv1.3 1490 Server Hello, Change Cipher Spec, Encrypted Extensions 18 1.773104270 vulture.lan api.github.com TCP 66 55424 → https(443) [ACK] Seq=518 Ack=1425 Win=32128 Len=0 TSval=2499281734 TSecr=3029633179 19 1.773405428 vulture.lan api.github.com TLSv1.3 72 Change Cipher Spec 20 1.774050525 api.github.com vulture.lan TCP 1490 https(443) → 55424 [ACK] Seq=1425 Ack=518 Win=29696 Len=1424 TSval=3029633179 TSecr=2499281709 [TCP segment of a reassembled PDU] 21 1.775039404 api.github.com vulture.lan TLSv1.3 615 Certificate, Certificate Verify, Finished 22 1.775047977 vulture.lan api.github.com TCP 66 55424 → https(443) [ACK] Seq=524 Ack=3398 Win=37760 Len=0 TSval=2499281736 TSecr=3029633179 23 1.838313183 api.github.com vulture.lan TCP 66 https(443) → 55424 [ACK] Seq=3398 Ack=524 Win=29696 Len=0 TSval=3029633196 TSecr=2499281735 24 1.838358258 vulture.lan api.github.com HTTP 388 GET /users/charignon/repos HTTP/1.1 25 1.861920124 api.github.com vulture.lan TCP 66 https(443) → 55424 [ACK] Seq=3398 Ack=846 Win=30720 Len=0 TSval=3029633201 TSecr=2499281800 26 1.862284763 api.github.com vulture.lan TLSv1.3 145 New Session Ticket 27 1.862648197 api.github.com vulture.lan TLSv1.3 145 New Session Ticket 28 1.864591679 vulture.lan api.github.com TCP 66 55424 → https(443) [RST, ACK] Seq=846 Ack=3556 Win=37760 Len=0 TSval=2499281826 TSecr=3029633201 29 1.866733948 vulture.lan testwifi.here DNS 74 XXX 30 1.866762442 vulture.lan testwifi.here DNS 74 XXX 31 1.874549249 testwifi.here vulture.lan DNS 158 XXX 32 1.900313841 testwifi.here vulture.lan DNS 106 XXX 33 1.900576751 vulture.lan api.github.com TCP 74 43292 → https(443) [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=4190850269 TSecr=0 WS=128 34 1.903210022 vulture.lan testwifi.here DNS 88 XXX 35 1.903272421 vulture.lan testwifi.here DNS 87 XXX 36 1.903318706 vulture.lan testwifi.here DNS 86 XXX 37 1.903361506 vulture.lan testwifi.here DNS 85 XXX 38 1.906623630 testwifi.here vulture.lan DNS 137 XXX 39 1.906956508 testwifi.here vulture.lan DNS 137 XXX 40 1.907649896 testwifi.here vulture.lan DNS 87 XXX 41 1.908724609 testwifi.here vulture.lan DNS 156 XXX 42 1.925632754 api.github.com vulture.lan TCP 74 https(443) → 43292 [SYN, ACK] Seq=0 Ack=1 Win=28480 Len=0 MSS=1436 SACK_PERM=1 TSval=3140518241 TSecr=4190850269 WS=1024 43 1.925691567 vulture.lan api.github.com TCP 66 43292 → https(443) [ACK] Seq=1 Ack=1 Win=29312 Len=0 TSval=4190850294 TSecr=3140518241 44 1.926622012 vulture.lan api.github.com HTTP 308 GET /users/charignon/repos HTTP/1.1 45 1.950026748 api.github.com vulture.lan TCP 66 https(443) → 43292 [FIN, ACK] Seq=1 Ack=243 Win=29696 Len=0 TSval=3140518247 TSecr=4190850295 46 1.950219585 vulture.lan api.github.com TCP 66 43292 → https(443) [FIN, ACK] Seq=243 Ack=2 Win=29312 Len=0 TSval=4190850318 TSecr=3140518247 47 1.972892477 api.github.com vulture.lan TCP 66 https(443) → 43292 [ACK] Seq=2 Ack=244 Win=29696 Len=0 TSval=3140518253 TSecr=4190850318 ``` vulture.lan is my computer. testwifi.here is my DNS. starting at packet 33 we talk to a second github server, not like the one we talk to in packet 13. I configured wireshark to inspect encrypted traffic to see the HTTP request in there. What you can notice is that in the synchronous (failing) case, packet 28 is resetting (unexpectedly as far as I can tell) the TCP connection, and we attempt a retry, which does not work. And here is the trace for the `url-retrieve` case, where everything goes well: ``` No. Time Source Destination Protocol Length Info 1 0.000000000 vulture.lan testwifi.here DNS 74 XXX 2 0.000068027 vulture.lan testwifi.here DNS 74 XXX 3 0.008919887 testwifi.here vulture.lan DNS 158 XXX 4 0.035184884 testwifi.here vulture.lan DNS 106 XXX 5 0.107029734 vulture.lan api.github.com TCP 74 55428 → https(443) [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2499323470 TSecr=0 WS=128 6 0.134137564 api.github.com vulture.lan TCP 74 https(443) → 55428 [SYN, ACK] Seq=0 Ack=1 Win=28480 Len=0 MSS=1436 SACK_PERM=1 TSval=2535678566 TSecr=2499323470 WS=1024 7 0.134221939 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=1 Ack=1 Win=29312 Len=0 TSval=2499323498 TSecr=2535678566 8 0.134313037 vulture.lan api.github.com TLSv1.3 583 Client Hello 9 0.162958206 api.github.com vulture.lan TLSv1.3 1490 Server Hello, Change Cipher Spec, Encrypted Extensions 10 0.163005821 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=518 Ack=1425 Win=32128 Len=0 TSval=2499323526 TSecr=2535678573 11 0.163752256 api.github.com vulture.lan TCP 1490 https(443) → 55428 [ACK] Seq=1425 Ack=518 Win=29696 Len=1424 TSval=2535678573 TSecr=2499323498 [TCP segment of a reassembled PDU] 12 0.163769338 vulture.lan api.github.com TLSv1.3 72 Change Cipher Spec 13 0.164938244 api.github.com vulture.lan TLSv1.3 615 Certificate, Certificate Verify, Finished 14 0.164970615 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=524 Ack=3398 Win=37760 Len=0 TSval=2499323528 TSecr=2535678573 15 0.229427678 api.github.com vulture.lan TCP 66 https(443) → 55428 [ACK] Seq=3398 Ack=524 Win=29696 Len=0 TSval=2535678590 TSecr=2499323527 16 0.229496471 vulture.lan api.github.com HTTP 388 GET /users/charignon/repos HTTP/1.1 17 0.253820590 api.github.com vulture.lan TCP 66 https(443) → 55428 [ACK] Seq=3398 Ack=846 Win=30720 Len=0 TSval=2535678596 TSecr=2499323593 18 0.255187068 api.github.com vulture.lan TLSv1.3 145 New Session Ticket 19 0.256462285 api.github.com vulture.lan TLSv1.3 145 New Session Ticket 20 0.256590338 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=846 Ack=3556 Win=37760 Len=0 TSval=2499323620 TSecr=2535678596 21 0.485155486 api.github.com vulture.lan TLSv1.3 1458 [SSL segment of a reassembled PDU] 22 0.485523530 api.github.com vulture.lan TLSv1.3 1458 [SSL segment of a reassembled PDU] 23 0.485567467 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=846 Ack=6340 Win=43392 Len=0 TSval=2499323849 TSecr=2535678654 24 0.486210922 api.github.com vulture.lan TLSv1.3 1490 [SSL segment of a reassembled PDU] 25 0.486551493 api.github.com vulture.lan TLSv1.3 1276 [SSL segment of a reassembled PDU] 26 0.486588968 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=846 Ack=8974 Win=49152 Len=0 TSval=2499323850 TSecr=2535678654 27 0.487345701 api.github.com vulture.lan TLSv1.3 1490 [SSL segment of a reassembled PDU] 28 0.487710595 api.github.com vulture.lan TLSv1.3 1490 [SSL segment of a reassembled PDU] [TCP segment of a reassembled PDU] 29 0.487741685 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=846 Ack=11822 Win=54784 Len=0 TSval=2499323851 TSecr=2535678654 30 0.489279277 api.github.com vulture.lan TLSv1.3 1490 [SSL segment of a reassembled PDU] [TCP segment of a reassembled PDU] 31 0.490560244 api.github.com vulture.lan TLSv1.3 1490 [SSL segment of a reassembled PDU] [TCP segment of a reassembled PDU] 32 0.490600325 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=846 Ack=14670 Win=60544 Len=0 TSval=2499323854 TSecr=2535678654 33 0.491903018 api.github.com vulture.lan TLSv1.3 1490 [SSL segment of a reassembled PDU] [TCP segment of a reassembled PDU] 34 0.493248621 api.github.com vulture.lan TLSv1.3 1490 [SSL segment of a reassembled PDU] [TCP segment of a reassembled PDU] 35 0.493286446 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=846 Ack=17518 Win=66176 Len=0 TSval=2499323857 TSecr=2535678654 36 0.501270566 vulture.lan testwifi.here DNS 86 XXX 37 0.501341962 vulture.lan testwifi.here DNS 85 XXX 38 0.503268399 testwifi.here vulture.lan DNS 137 XXX 39 0.504365465 testwifi.here vulture.lan DNS 137 XXX 40 0.507593395 api.github.com vulture.lan HTTP 75 HTTP/1.1 200 OK (application/json) 41 0.549680721 vulture.lan api.github.com TCP 66 55428 → https(443) [ACK] Seq=846 Ack=17527 Win=66176 Len=0 TSval=2499323913 TSecr=2535678660 ``` 5) I noticed that adding `(sit-for 0.5)` in various places throughout the codepath would consistently make the bug go away. For example in `open-network-stream` after opening the stream, or at the beginning of `url-http-create-request`. 6) I couldn't find information online indicating that github changed anything in their network request handling that broke other tools. I am using Emacs 26.1: In GNU Emacs 26.1 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.22.30) of 2018-07-05 built on juergen Windowing system distributor 'The X.Org Foundation', version 11.0.12003000 System Description: Manjaro Linux

[Message part 2 (text/html, inline)]

This bug report was last modified 4 years and 193 days ago.

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.

GNU bug report logs - #34341 26.1; url-retrieve-synchronously returns blank buffer

GNU bug report logs - #34341
26.1; url-retrieve-synchronously returns blank buffer