bug#16345: 24.3; url-http sometimes closes connection prematurely

bug#16345: 24.3; url-http sometimes closes connection prematurely

[James Stout]

[-- Attachment #1: Type: text/plain, Size: 9023 bytes --]

Before I describe how to reproduce the bug, let me be clear: I know what's
causing it and I know how to fix it. Let me know and I will happily send a
fix. The core problem is that the http library uses an incorrect regular
expression when determining when the response headers are complete. It's
looking for an empty line, and it uses "^\r*$", but it should use "^\r?\n".
Because $ can match both the end of the buffer and newline, it may match
simply when the input has not yet all been received. By using the correct
regular expression, it will wait for the newline. The change from * to ? is
optional, I just did that for cleanliness.

The broken regular expression is at line 1040 of url-http.el. There is
another instance at line 1017.

To reproduce:

1. Run a Web server that returns a 204 (no content) response with a couple
headers. For example, run a simple Python http server (
http://docs.python.org/2/library/basehttpserver.html), and subclass the
handler to add the following method (note that send_response automatically
includes 2 headers).
def do_POST(self):
        self.send_response(204)  # no content
        self.end_headers()

2. Send a request to the server from Emacs. This is the code I used,
pointing it to my local server. The data didn't matter:
(defun send-post-data (url data)
  (let ((url-request-method "POST")
    (url-request-data data))
    (message "sending request: %.10f" (float-time))
    (url-retrieve url (lambda (status) (message "received response: %.10f"
(float-time))) nil t t)))

3. At this point I saw an error in the Python logs that the connection had
been unexpectedly closed during the send_response call, after it had sent
the status line, but before it had sent any header lines. In Emacs, the URL
debug logs explained what had happened:

http -> Calling after change function
`url-http-wait-for-headers-change-function' for `#<process localhost>'
http -> url-http-wait-for-headers-change-function ( *http localhost:9090*)
http -> Saw end of headers... ( *http localhost:9090*)
http -> url-http-parse-response called in ( *http localhost:9090*)
http -> 204 response must have headers only ( *http localhost:9090*).
http -> Marking connection as free: localhost:9090 #<process localhost>
http -> url-http-parse-headers called in ( *http localhost:9090*)
http -> url-http-parse-response called in ( *http localhost:9090*)
http -> Parsed HTTP headers: class=2 status=204
http -> Finished parsing HTTP headers: t
http -> Marking connection as free: localhost:9090 #<process localhost>
http -> Activating callback in buffer ( *http localhost:9090*)
http -> Spinning waiting for headers...

As you can see, it sees the end of the headers prematurely in the 3rd line
of the logs, and closes the connection shortly afterwards. I confirmed this
by printing the buffer contents at that point, and it had only received the
1st line of the response. No empty lines had been received, yet it believed
it was at the end of the headers.

If Emacs crashed, and you have the Emacs process in the gdb debugger,
please include the output from the following gdb commands:
    `bt full' and `xbacktrace'.
For information about debugging Emacs, please read the file
/usr/share/emacs/24.3/etc/DEBUG.


In GNU Emacs 24.3.1 (i686-pc-cygwin)
 of 2013-08-14 on moufang
Windowing system distributor `Microsoft Corp.', version 6.1.7601
Configured using:
 `configure
 '--srcdir=/home/kbrown/src/cygemacs/emacs-24.3-2/src/emacs-24.3'
 '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin'
 '--sbindir=/usr/sbin' '--libexecdir=/usr/libexec'
 '--datadir=/usr/share' '--localstatedir=/var' '--sysconfdir=/etc'
 '--datarootdir=/usr/share' '--docdir=/usr/share/doc/emacs' '-C'
 '--with-w32' 'CC=gcc' 'CFLAGS=-ggdb -O2 -pipe
 -fdebug-prefix-map=/home/kbrown/src/cygemacs/emacs-24.3-2/build=/usr/src/debug/emacs-24.3-2
 -fdebug-prefix-map=/home/kbrown/src/cygemacs/emacs-24.3-2/src/emacs-24.3=/usr/src/debug/emacs-24.3-2'
 'LDFLAGS=-L/usr/lib/ncursesw' 'LIBS='
 'CPPFLAGS=-I/usr/include/ncursesw''

Important settings:
  value of $LANG: en_US.UTF-8
  locale-coding-system: utf-8-unix
  default enable-multibyte-characters: t

Major mode: Fundamental

Minor modes in effect:
  show-paren-mode: t
  global-linum-mode: t
  ido-ubiquitous-mode: t
  ido-everywhere: t
  diff-auto-refine-mode: t
  global-auto-revert-mode: t
  recentf-mode: t
  tooltip-mode: t
  mouse-wheel-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  column-number-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent input:
<down> <down> <down> <return> <end> <left> <left> <left>
<left> <left> <left> <left> <return> 1 <return> C-g
<up> <up> <up> <up> <up> <up> <up> <up> <up> <up> <up>
<up> <up> <up> <up> <up> <up> <up> <up> <up> <up> <up>
<up> <up> <up> <up> <up> <up> <up> <up> <up> <up> <up>
<up> <up> <up> <up> <up> <up> <up> <up> <up> <up> <up>
<up> <up> <up> <up> <up> <up> <up> <up> <up> <up> <up>
<left> <left> <return> y <return> y <return> y <return>
<backspace> <backspace> y <return> y <return> y <return>
C-g <next> <prior> C-x C-s y e s <return> C-x r b .
E m a c s <return> <C-end> C-x b C-g C-x b u r l <return>
C-x b u r l <return> <up> <up> <up> <up> <up> <up>
<up> <up> <up> <up> <up> <up> <up> <up> C-SPC <C-end>
M-w C-x b u n s c e n t e d <backspace> <backspace>
<backspace> <backspace> <backspace> <backspace> <backspace>
<return> <up> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> <down> <down> <down> <down> <down>
<down> <down> <down> C-x 0 C-x 0 C-x k <return> <C-home>
C-x k <return> y e s <return> M-x <right> <right>
<return>

Recent messages:
sending request: 1388866362.5328981876
received response: 1388866364.4430074692
sending request: 1388866368.1072170734
received response: 1388866369.4172918797
Auto-saving...done
Mark set
sending request: 1388866394.5217278004
received response: 1388866396.2348258495
byte-code: End of buffer [8 times]
byte-code: Attempt to delete minibuffer or sole ordinary window

Load-path shadows:
None found.

Features:
(url-handlers browse-url apropos cus-edit cus-start cus-load misearch
multi-isearch jka-compr find-func shadow sort mail-extr emacsbug message
rfc822 mml mml-sec mm-decode mm-bodies mm-encode mailabbrev gmm-utils
mailheader sendmail subword python rx mail-utils network-stream starttls
url-cache url-http tls mail-parse rfc2231 rfc2047 rfc2045 ietf-drums
url-gw url-auth url url-proxy url-privacy url-expand url-methods
url-history url-cookie url-domsuf url-util url-parse auth-source eieio
byte-opt bytecomp byte-compile cconv gnus-util mm-util mail-prsvr
password-cache url-vars mailcap vc-git bookmark pp linum-relative
cl-macs gv paren linum smex smartscan paredit edmacro kmacro uniquify
ido-ubiquitous cl advice help-fns advice-preload ido magit-key-mode
magit view help-mode grep compile comint format-spec epa derived epg
epg-config diff-mode cl-lib autorevert ansi-color git-rebase-mode
git-commit-mode server log-edit easy-mmode ring pcvs-util add-log
thingatpt recentf tree-widget wid-edit 4clojure-autoloads
clojure-test-mode-autoloads cider-autoloads clojure-mode-autoloads
find-file-in-project-autoloads ido-ubiquitous-autoloads
linum-relative-autoloads load-theme-buffer-local-autoloads
magit-autoloads info easymenu git-rebase-mode-autoloads
git-commit-mode-autoloads paredit-autoloads pkg-info-autoloads
epl-autoloads finder-inf dash-autoloads request-autoloads s-autoloads
smartscan-autoloads smex-autoloads package time-date tooltip ediff-hook
vc-hooks lisp-float-type mwheel w32-common-fns disp-table w32-win
w32-vars tool-bar dnd fontset image regexp-opt fringe tabulated-list
newcomment lisp-mode register page menu-bar rfn-eshadow timer select
scroll-bar mouse jit-lock font-lock syntax facemenu font-core frame cham
georgian utf-8-lang misc-lang vietnamese tibetan thai tai-viet lao
korean japanese hebrew greek romanian slovak czech european ethiopic
indian cyrillic chinese case-table epa-hook jka-cmpr-hook help simple
abbrev minibuffer loaddefs button faces cus-face macroexp files
text-properties overlay sha1 md5 base64 format env code-pages mule
custom widget hashtable-print-readable backquote make-network-process
dbusbind w32 multi-tty emacs)

[-- Attachment #2: Type: text/html, Size: 11535 bytes --]

bug#16345: 24.3; url-http sometimes closes connection prematurely

[Glenn Morris]

James Stout wrote:

> fix. The core problem is that the http library uses an incorrect regular
> expression when determining when the response headers are complete. It's
> looking for an empty line, and it uses "^\r*$", but it should use "^\r?\n".

Thanks, it already does so in Emacs trunk:

http://debbugs.gnu.org/cgi/bugreport.cgi?bug=13598#28

Perhaps you could check that trunk works correctly for you.

bug#16345: 24.3; url-http sometimes closes connection prematurely

[James Stout]

[-- Attachment #1: Type: text/plain, Size: 972 bytes --]

Hi Glenn,

Yep, that fix works for me, thanks! Next time I'll be sure to check
resolved bugs (I only checked open ones) and the source code trunk.

I did notice that only one instance of the regular expression was changed.
I'm not using chunked encoding with trailers, so it's hard for me to verify
whether this indeed is a bug, but I think this line also needs to be fixed:
http://bzr.savannah.gnu.org/lh/emacs/trunk/annotate/head:/lisp/url/url-http.el#L1037

Best,
James


On Sat, Jan 4, 2014 at 3:46 PM, Glenn Morris <rgm@gnu.org> wrote:

> James Stout wrote:
>
> > fix. The core problem is that the http library uses an incorrect regular
> > expression when determining when the response headers are complete. It's
> > looking for an empty line, and it uses "^\r*$", but it should use
> "^\r?\n".
>
> Thanks, it already does so in Emacs trunk:
>
> http://debbugs.gnu.org/cgi/bugreport.cgi?bug=13598#28
>
> Perhaps you could check that trunk works correctly for you.
>

[-- Attachment #2: Type: text/html, Size: 1562 bytes --]

bug#16345: 24.3; url-http sometimes closes connection prematurely

[Lars Ingebrigtsen]

James Stout <james.wolf.stout@gmail.com> writes:

> Yep, that fix works for me, thanks! Next time I'll be sure to check resolved bugs (I only checked open ones) and the source code trunk.
>
> I did notice that only one instance of the regular expression was changed. I'm not using chunked encoding with trailers, so it's hard for
> me to verify whether this indeed is a bug, but I think this line also needs to be fixed:
> http://bzr.savannah.gnu.org/lh/emacs/trunk/annotate/head:/lisp/url/url-http.el#L1037

Could you send a fix for the line in question?

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#16345: 24.3; url-http sometimes closes connection prematurely

[James Stout]

[-- Attachment #1: Type: text/plain, Size: 1126 bytes --]

I'm suggesting the following change:

Before: (if (re-search-forward "^\r*$" nil t) (url-http-debug "Saw end of
trailers..."))
After: (if (re-search-forward "^\r?\n" nil t) (url-http-debug "Saw end of
trailers..."))

This is based purely on my reading of the spec; this wasn't actually a
problem I ran into (and it's just going to affect a debug message).

On Fri, Dec 25, 2015 at 12:38 PM, Lars Ingebrigtsen <larsi@gnus.org> wrote:

> James Stout <james.wolf.stout@gmail.com> writes:
>
> > Yep, that fix works for me, thanks! Next time I'll be sure to check
> resolved bugs (I only checked open ones) and the source code trunk.
> >
> > I did notice that only one instance of the regular expression was
> changed. I'm not using chunked encoding with trailers, so it's hard for
> > me to verify whether this indeed is a bug, but I think this line also
> needs to be fixed:
> >
> http://bzr.savannah.gnu.org/lh/emacs/trunk/annotate/head:/lisp/url/url-http.el#L1037
>
> Could you send a fix for the line in question?
>
> --
> (domestic pets only, the antidote for overdose, milk.)
>    bloggy blog: http://lars.ingebrigtsen.no
>

[-- Attachment #2: Type: text/html, Size: 1936 bytes --]

bug#16345: 24.3; url-http sometimes closes connection prematurely

[Lars Ingebrigtsen]

James Stout <james.wolf.stout@gmail.com> writes:

> I'm suggesting the following change:
>
> Before: (if (re-search-forward "^\r*$" nil t) (url-http-debug "Saw end of
> trailers..."))
> After: (if (re-search-forward "^\r?\n" nil t) (url-http-debug "Saw end of
> trailers..."))
>
> This is based purely on my reading of the spec; this wasn't actually a problem
> I ran into (and it's just going to affect a debug message).

Can you send a patch for the change?

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

bug#16345: 24.3; url-http sometimes closes connection prematurely

[James Stout]

[-- Attachment #1.1: Type: text/plain, Size: 756 bytes --]

This is the first Emacs patch I've ever sent; let me know if I'm doing it
wrong.

On Mon, Dec 28, 2015 at 9:49 AM, Lars Ingebrigtsen <larsi@gnus.org> wrote:

> James Stout <james.wolf.stout@gmail.com> writes:
>
> > I'm suggesting the following change:
> >
> > Before: (if (re-search-forward "^\r*$" nil t) (url-http-debug "Saw end of
> > trailers..."))
> > After: (if (re-search-forward "^\r?\n" nil t) (url-http-debug "Saw end of
> > trailers..."))
> >
> > This is based purely on my reading of the spec; this wasn't actually a
> problem
> > I ran into (and it's just going to affect a debug message).
>
> Can you send a patch for the change?
>
> --
> (domestic pets only, the antidote for overdose, milk.)
>    bloggy blog: http://lars.ingebrigtsen.no
>

[-- Attachment #1.2: Type: text/html, Size: 1383 bytes --]

[-- Attachment #2: 0001-Fixed-regular-expression-for-end-of-HTTP-trailers-to.patch --]
[-- Type: application/octet-stream, Size: 891 bytes --]

From ab2c4b31a6619dd0dbdcaab55e32e2b6a80826b4 Mon Sep 17 00:00:00 2001
From: James Stout <james.wolf.stout@gmail.com>
Date: Mon, 28 Dec 2015 10:47:31 -0800
Subject: [PATCH] Fixed regular expression for end of HTTP trailers to match
 spec.

---
 lisp/url/url-http.el | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lisp/url/url-http.el b/lisp/url/url-http.el
index 916f263..e5c2c3a 100644
--- a/lisp/url/url-http.el
+++ b/lisp/url/url-http.el
@@ -1067,7 +1067,7 @@ the end of the document."
 		  (when (looking-at "\r?\n")
 		    (url-http-debug "Removing terminator of last chunk")
 		    (delete-region (match-beginning 0) (match-end 0)))
-		  (if (re-search-forward "^\r*$" nil t)
+		  (if (re-search-forward "^\r?\n" nil t)
 		      (url-http-debug "Saw end of trailers..."))
 		  (if (url-http-parse-headers)
 		      (url-http-activate-callback))))))))))
-- 
2.6.2

bug#16345: 24.3; url-http sometimes closes connection prematurely

[Lars Ingebrigtsen]

James Stout <james.wolf.stout@gmail.com> writes:

> This is the first Emacs patch I've ever sent; let me know if I'm doing
> it wrong.

Looks good.  Applied to Emacs 25.1.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no