bug#9592: Problems with url-http, https, POSTS, reusing connections, and trailing CRLF after POST data

bug#9592: Problems with url-http, https, POSTS, reusing connections, and trailing CRLF after POST data

[Christopher J. White]

I've been having issues sending a POST requests to a server via https.
The code works fine when using just http, but with https it does not
work reliably.

The first problem relates to bug #8931, terminating HTTP packets with
extra CRLF.  The patch for this bug undid a minor change that removed
the CRLF after POST data.  See:

  http://bzr.savannah.gnu.org/lh/emacs/trunk/revision/104908

The key change was:

lisp/url/url-http.el:

340          ;; Any data
341 -        url-http-data "\r\n"))
341 +        url-http-data))
342          ""))

The added CRLF was put in because without it POSTs via HTTPS to at
least some servers just hangs, apparently because gnutls-cli is not
sending the url-http-data because of lack of CRLF.  I found this
problem myself, but also discovered that Mark Hershberger submitted a
patch over a year ago to add the CRLF for the same reason.  See:

  http://bzr.savannah.gnu.org/lh/emacs/trunk/revision/100681

I think a more appropriate fix is to only add the extra CRLF if POST
data exists:

340          ;; Any data
341 -        url-http-data))
341 +        url-http-data (if url-http-data "\r\n")))
342          ""))

I have been using this version above, with some success.  However, I
have now hit another stumbling block which is likely related.

(BTW -- I tried to unarchive bug 8931 and amend the bug with the above 
details but I'm getting neither confirmation via email nor updates on
debbugs.gnu.org.  I sent the unarchive request to control <at> debbugs.gnu.org)


If I make a second HTTPS request after a POST with data, sometimes the
second request attempts to reuse the old connection.  I added some
additional url-debug statements to isolate.

(defun url-http-find-free-connection (host port)
  (url-http-debug "Finding free connction: %s:%d" host port)
  (url-http-debug "Currently open connections: %S" url-http-open-connections)
  ...)

When it works, I see:

  http -> Finding free connction: api.toodledo.com:443
  http -> Currently open connections: #s(hash-table size 17 test equal rehash-size 1.5 rehash-threshold 0.8 data (("api.toodledo.com" . 443) nil ("api.toodledo.com" . 80) nil))
  http -> Contacting host: api.toodledo.com:443
  http -> Marking connection as busy: api.toodledo.com:443 #<process api.toodledo.com>
  http -> Request is: 
  POST /2/tasks/get.php HTTP/1.1
  MIME-Version: 1.0
  Connection: keep-alive
  Extension: Security/Digest Security/SSL
  Host: api.toodledo.com
  Accept-charset: nil
  Accept: */*
  User-Agent: URL/Emacs (i386-mingw-nt6.1.7600; Windows-NT; 32bit)
  Content-Type: application/x-www-form-urlencoded
  Content-length: 187

  <my post data>

  retrieval -> Spinning in url-retrieve-synchronously: nil (#<buffer  *http api.toodledo.com:443*<53>>)

When it fails, I instead see:

  http -> Finding free connction: api.toodledo.com:443
  http -> Currently open connections: #s(hash-table size 17 test equal rehash-size 1.5 rehash-threshold 0.8 data (("api.toodledo.com" . 443) (#<process api.toodledo.com> #<process api.toodledo.com>) ("api.toodledo.com" . 80) nil))
  http -> Testing conn: #<process api.toodledo.com>, process status run
  http -> Found existing connection: api.toodledo.com:443 #<process api.toodledo.com>
  http -> Reusing existing connection: api.toodledo.com:443
  http -> Marking connection as busy: api.toodledo.com:443 #<process api.toodledo.com>
  http -> Request is: 
  POST /2/tasks/get.php HTTP/1.1
  MIME-Version: 1.0
  Connection: keep-alive
  Extension: Security/Digest Security/SSL
  Host: api.toodledo.com
  Accept-charset: nil
  Accept: */*
  User-Agent: URL/Emacs (i386-mingw-nt6.1.7600; Windows-NT; 32bit)
  Content-Type: application/x-www-form-urlencoded
  Content-length: 57

  <my post data>

  http -> url-http-end-of-document-sentinel in buffer ( *http api.toodledo.com:443*<48>)
  http -> Marking connection as free: api.toodledo.com:443 #<process api.toodledo.com>
  http -> Activating callback in buffer ( *http api.toodledo.com:443*<48>)
  retrieval -> Synchronous fetching done (#<buffer  *http api.toodledo.com:443*<48>>)

Along with the failure, I get the following backtrace:

  Debugger entered--Lisp error: (file-error "writing to process" "invalid argument" #<process api.toodledo.com>)
    process-send-string(#<process api.toodledo.com> "POST /2/tasks/deleted.php HTTP/1.1\nMIME-Version: 1.0\nConnection: keep-alive\nExtension: Security/Digest Security/SSL\nHost: api.toodledo.com\nAccept-charset: nil\nAccept: */*\nUser-Agent: URL/Emacs (i386-mingw-nt6.1.7600; Windows-NT; 32bit)\nContent-Type: application/x-www-form-urlencoded\nContent-length: 57\n\n<my post data>\n")
    url-http([cl-struct-url "https" nil nil "api.toodledo.com" 443 "/2/tasks/get.php" nil nil t] .....

It's trying to reuse the old process as it is in the "run" state, but the process is not really usable.  If I hack url-http to always create new connections (don't attempt reuse), things seem to work fine.

The failure is fairly repeatable, but it does not happen precisely the same.  I have a set of unit-tests for syncing org-mode tasks with toodledo.com, which makes on the order of 10s of POSTs to the server.  It will fail every time, but not always at the same test.  What's interesting is that if I put a 2 second delay before each POST, it seems to happen more regularly.

I'm not sure where to take this from here.  This is on a Window 7 box, running native emacs, but using gnu-tlscli from Cygwin.

...cj

---
In GNU Emacs 23.3.1 (i386-mingw-nt6.1.7600)
 of 2011-03-10 on 3249CTO
Windowing system distributor `Microsoft Corp.', version 6.1.7600
configured using `configure --with-gcc (4.5) --no-opt --cflags -Ic:/imagesupport/include'

Important settings:
  value of $LC_ALL: nil
  value of $LC_COLLATE: nil
  value of $LC_CTYPE: nil
  value of $LC_MESSAGES: nil
  value of $LC_MONETARY: nil
  value of $LC_NUMERIC: nil
  value of $LC_TIME: nil
  value of $LANG: C.UTF-8
  value of $XMODIFIERS: nil
  locale-coding-system: cp1252
  default enable-multibyte-characters: t

Major mode: Emacs-Lisp

Minor modes in effect:
  show-paren-mode: t
  display-time-mode: t
  tooltip-mode: t
  mouse-wheel-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  column-number-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent input:
C-] C-] C-] C-] C-] C-x b u r <tab> - <backspace> h 
<tab> <return> C-g <down> <down> <tab> ; ; <escape> 
C-x <escape> x <up> <up> <return> <help-echo> <wheel-up> 
<wheel-up> <wheel-up> <double-wheel-up> <triple-wheel-up> 
<triple-wheel-up> <triple-wheel-up> <triple-wheel-up> 
<triple-wheel-up> <down-mouse-1> <mouse-1> x C-g C-x 
1 C-x b <return> C-x [ C-x b * M e s <tab> <return> 
C-x ] <switch-frame> <down-mouse-1> <mouse-1> <select-window> 
<down-mouse-1> <mouse-movement> <mouse-1> C-x 1 C-x 
b o r g - <tab> . <tab> <return> C-s C-g C-x [ C-s 
u s e - h t t p s C-s <down> <up> <escape> C-x <help-echo> 
<switch-frame> <down-mouse-1> <mouse-movement> <mouse-1> 
<escape> x <up> <return> C-x [ <select-window> <select-window> 
<help-echo> <down-mouse-1> <mouse-1> C-x b * U <tab> 
<return> * <tab> <return> C-x ] <prior> <next> <select-window> 
<help-echo> <select-window> <select-window> <help-echo> 
<help-echo> <help-echo> <select-window> <help-echo> 
<down-mouse-1> <help-echo> <drag-mouse-1> <help-echo> 
<select-window> <help-echo> <select-window> <select-window> 
<help-echo> <down-mouse-1> <help-echo> <mouse-movement> 
<drag-mouse-1> <help-echo> <down-mouse-1> <mouse-1> 
<help-echo> <select-window> <help-echo> <select-window> 
<help-echo> <select-window> <help-echo> <switch-frame> 
<help-echo> <switch-frame> <switch-frame> <down-mouse-1> 
<mouse-movement> <mouse-1> C-a C-s c a l l - m e t 
h o d C-s C-s C-s C-s C-s C-a C-n C-n <return> <tab> 
( s l e e p <backspace> p - o f <backspace> <backspace> 
f o r SPC 2 ) <escape> C-x <switch-frame> <down-mouse-1> 
<mouse-movement> <mouse-1> <escape> x <up> C-g C-] 
C-] C-] C-] <escape> x <up> <return> C-x [ <select-window> 
<select-window> <help-echo> <select-window> <select-window> 
<help-echo> <help-echo> <help-echo> <help-echo> <select-window> 
<help-echo> <select-window> <down-mouse-1> <mouse-movement> 
<mouse-movement> <drag-mouse-1> <help-echo> <select-window> 
<help-echo> <select-window> <select-window> <select-window> 
<help-echo> <select-window> <select-window> <help-echo> 
<select-window> <help-echo> <select-window> <switch-frame> 
<help-echo> <switch-frame> <select-window> <help-echo> 
<help-echo> <down-mouse-1> <mouse-2> <help-echo> <down-mouse-1> 
<drag-mouse-1> <down-mouse-1> <mouse-movement> <mouse-movement> 
<drag-mouse-1> <help-echo> <help-echo> <help-echo> 
<select-window> <select-window> <select-window> <select-window> 
<select-window> <help-echo> <select-window> <help-echo> 
<select-window> <down-mouse-1> <mouse-movement> <mouse-1> 
<escape> x r e p SPC o SPC SPC r SPC SPC SPC <retu
rn>

Recent messages:
All interaction with toodledo.com will be via HTTPS
Contacting host: api.toodledo.com:443
Opening TLS connection to `api.toodledo.com'...
Opening TLS connection with `gnutls-cli -p 443 api.toodledo.com'...done
Opening TLS connection to `api.toodledo.com'...done
Contacting host: api.toodledo.com:443
Entering debugger...
Mark set
Auto-saving...done
Making completion list... [3 times]

Load-path shadows:
~cwhite/lib/lisp/org-toodledo/w3mexcerpt hides ~cwhite/lib/lisp/w3mexcerpt
~cwhite/lib/lisp/org-toodledo/http-post-simple hides ~cwhite/lib/lisp/http-post-simple
~/lib/lisp/org-mode/lisp/org hides c:/Users/cwhite/emacs-23.3/lisp/org/org
~/lib/lisp/org-mode/lisp/org-xoxo hides c:/Users/cwhite/emacs-23.3/lisp/org/org-xoxo
~/lib/lisp/org-mode/lisp/org-wl hides c:/Users/cwhite/emacs-23.3/lisp/org/org-wl
~/lib/lisp/org-mode/lisp/org-w3m hides c:/Users/cwhite/emacs-23.3/lisp/org/org-w3m
~/lib/lisp/org-mode/lisp/org-vm hides c:/Users/cwhite/emacs-23.3/lisp/org/org-vm
~/lib/lisp/org-mode/lisp/org-timer hides c:/Users/cwhite/emacs-23.3/lisp/org/org-timer
~/lib/lisp/org-mode/lisp/org-table hides c:/Users/cwhite/emacs-23.3/lisp/org/org-table
~/lib/lisp/org-mode/lisp/org-src hides c:/Users/cwhite/emacs-23.3/lisp/org/org-src
~/lib/lisp/org-mode/lisp/org-rmail hides c:/Users/cwhite/emacs-23.3/lisp/org/org-rmail
~/lib/lisp/org-mode/lisp/org-remember hides c:/Users/cwhite/emacs-23.3/lisp/org/org-remember
~/lib/lisp/org-mode/lisp/org-publish hides c:/Users/cwhite/emacs-23.3/lisp/org/org-publish
~/lib/lisp/org-mode/lisp/org-protocol hides c:/Users/cwhite/emacs-23.3/lisp/org/org-protocol
~/lib/lisp/org-mode/lisp/org-plot hides c:/Users/cwhite/emacs-23.3/lisp/org/org-plot
~/lib/lisp/org-mode/lisp/org-mouse hides c:/Users/cwhite/emacs-23.3/lisp/org/org-mouse
~/lib/lisp/org-mode/lisp/org-mobile hides c:/Users/cwhite/emacs-23.3/lisp/org/org-mobile
~/lib/lisp/org-mode/lisp/org-mhe hides c:/Users/cwhite/emacs-23.3/lisp/org/org-mhe
~/lib/lisp/org-mode/lisp/org-mew hides c:/Users/cwhite/emacs-23.3/lisp/org/org-mew
~/lib/lisp/org-mode/lisp/org-macs hides c:/Users/cwhite/emacs-23.3/lisp/org/org-macs
~/lib/lisp/org-mode/lisp/org-mac-message hides c:/Users/cwhite/emacs-23.3/lisp/org/org-mac-message
~/lib/lisp/org-mode/lisp/org-list hides c:/Users/cwhite/emacs-23.3/lisp/org/org-list
~/lib/lisp/org-mode/lisp/org-latex hides c:/Users/cwhite/emacs-23.3/lisp/org/org-latex
~/lib/lisp/org-mode/lisp/org-jsinfo hides c:/Users/cwhite/emacs-23.3/lisp/org/org-jsinfo
~/lib/lisp/org-mode/lisp/org-irc hides c:/Users/cwhite/emacs-23.3/lisp/org/org-irc
~/lib/lisp/org-mode/lisp/org-install hides c:/Users/cwhite/emacs-23.3/lisp/org/org-install
~/lib/lisp/org-mode/lisp/org-inlinetask hides c:/Users/cwhite/emacs-23.3/lisp/org/org-inlinetask
~/lib/lisp/org-mode/lisp/org-info hides c:/Users/cwhite/emacs-23.3/lisp/org/org-info
~/lib/lisp/org-mode/lisp/org-indent hides c:/Users/cwhite/emacs-23.3/lisp/org/org-indent
~/lib/lisp/org-mode/lisp/org-id hides c:/Users/cwhite/emacs-23.3/lisp/org/org-id
~/lib/lisp/org-mode/lisp/org-icalendar hides c:/Users/cwhite/emacs-23.3/lisp/org/org-icalendar
~/lib/lisp/org-mode/lisp/org-html hides c:/Users/cwhite/emacs-23.3/lisp/org/org-html
~/lib/lisp/org-mode/lisp/org-habit hides c:/Users/cwhite/emacs-23.3/lisp/org/org-habit
~/lib/lisp/org-mode/lisp/org-gnus hides c:/Users/cwhite/emacs-23.3/lisp/org/org-gnus
~/lib/lisp/org-mode/lisp/org-freemind hides c:/Users/cwhite/emacs-23.3/lisp/org/org-freemind
~/lib/lisp/org-mode/lisp/org-footnote hides c:/Users/cwhite/emacs-23.3/lisp/org/org-footnote
~/lib/lisp/org-mode/lisp/org-feed hides c:/Users/cwhite/emacs-23.3/lisp/org/org-feed
~/lib/lisp/org-mode/lisp/org-faces hides c:/Users/cwhite/emacs-23.3/lisp/org/org-faces
~/lib/lisp/org-mode/lisp/org-exp hides c:/Users/cwhite/emacs-23.3/lisp/org/org-exp
~/lib/lisp/org-mode/lisp/org-exp-blocks hides c:/Users/cwhite/emacs-23.3/lisp/org/org-exp-blocks
~/lib/lisp/org-mode/lisp/org-docbook hides c:/Users/cwhite/emacs-23.3/lisp/org/org-docbook
~/lib/lisp/org-mode/lisp/org-datetree hides c:/Users/cwhite/emacs-23.3/lisp/org/org-datetree
~/lib/lisp/org-mode/lisp/org-crypt hides c:/Users/cwhite/emacs-23.3/lisp/org/org-crypt
~/lib/lisp/org-mode/lisp/org-compat hides c:/Users/cwhite/emacs-23.3/lisp/org/org-compat
~/lib/lisp/org-mode/lisp/org-colview hides c:/Users/cwhite/emacs-23.3/lisp/org/org-colview
~/lib/lisp/org-mode/lisp/org-clock hides c:/Users/cwhite/emacs-23.3/lisp/org/org-clock
~/lib/lisp/org-mode/lisp/org-bibtex hides c:/Users/cwhite/emacs-23.3/lisp/org/org-bibtex
~/lib/lisp/org-mode/lisp/org-bbdb hides c:/Users/cwhite/emacs-23.3/lisp/org/org-bbdb
~/lib/lisp/org-mode/lisp/org-attach hides c:/Users/cwhite/emacs-23.3/lisp/org/org-attach
~/lib/lisp/org-mode/lisp/org-ascii hides c:/Users/cwhite/emacs-23.3/lisp/org/org-ascii
~/lib/lisp/org-mode/lisp/org-archive hides c:/Users/cwhite/emacs-23.3/lisp/org/org-archive
~/lib/lisp/org-mode/lisp/org-agenda hides c:/Users/cwhite/emacs-23.3/lisp/org/org-agenda

Features:
(shadow sort mail-extr message ecomplete rfc822 mml mml-sec
password-cache mm-decode mm-bodies mm-encode mailabbrev nnheader
gnus-util netrc gmm-utils mailheader canlock sha1 hex-util hashcash
emacsbug apropos time-stamp grep find-func multi-isearch debug url-cache
org-wl org-w3m org-vm org-rmail org-mhe org-mew org-irc org-jsinfo
org-infojs org-html format-spec org-exp ob-exp org-exp-blocks org-agenda
org-info org-gnus org-docview org-bibtex bibtex org-bbdb vc-git
help-mode view org-toodledo w3mexcerpt remember org-remember
org-datetree cygwin-mount ange-ftp uniquify filecache server paren time
etags python-mode info-look css-mode scr rsync twiki edmacro kmacro info
doku pib php-mode speedbar sb-image ezimage dframe assoc highline pop3
mail-utils cc-mode cc-fonts cc-menus cc-cmds cc-styles cc-align
cc-engine cc-vars cc-defs cus-edit cus-start cus-load wid-edit exec
http-post-simple cl cl-19 url-http tls url-auth mail-parse rfc2231
rfc2047 rfc2045 qp ietf-drums url-gw url url-proxy url-privacy
url-expand url-methods url-history url-cookie url-util url-parse
url-vars mm-util mail-prsvr mailcap json xml org byte-opt warnings
advice help-fns advice-preload ob-emacs-lisp ob-tangle ob-ref ob-lob
ob-table org-footnote org-src ob-comint ob-keys ob ob-eval org-pcomplete
pcomplete org-list org-faces org-compat org-entities org-macs time-date
noutline outline easy-mmode regexp-opt cal-menu easymenu calendar
cal-loaddefs compile comint ring bytecomp byte-compile tooltip
ediff-hook vc-hooks lisp-float-type mwheel dos-w32 disp-table ls-lisp
w32-win w32-vars tool-bar dnd fontset image fringe lisp-mode register
page menu-bar rfn-eshadow timer select scroll-bar mldrag 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 loaddefs button
minibuffer faces cus-face files text-properties overlay md5 base64
format env code-pages mule custom widget hashtable-print-readable
backquote make-network-process multi-tty emacs)

bug#9592: Problems with url-http, https, POSTS, reusing connections, and trailing CRLF after POST data

[Glenn Morris]

"Christopher J. White" wrote:

> (BTW -- I tried to unarchive bug 8931 and amend the bug with the above 
> details but I'm getting neither confirmation via email nor updates on
> debbugs.gnu.org.  I sent the unarchive request to control <at> debbugs.gnu.org)

Your messages were waiting for moderation. Please allow up to 24 hours
the first time you post from a particular email address. This is
mentioned in M-x report-emacs-bug and on http://debbugs.gnu.org.

bug#9592: Problems with url-http, https, POSTS, reusing connections, and trailing CRLF after POST data

[Chong Yidong]

"Christopher J. White" <emacs@grierwhite.com> writes:

>   http -> url-http-end-of-document-sentinel in buffer ( *http api.toodledo.com:443*<48>)
>   http -> Marking connection as free: api.toodledo.com:443 #<process api.toodledo.com>
> ...
>
> Along with the failure, I get the following backtrace:
>
>   Debugger entered--Lisp error: (file-error "writing to process" "invalid argument" #<process api.toodledo.com>)

I just committed a fix to trunk which fixes how url-http handles expired
keepalive connections (revno 107567), which might be relevant to this
bug.  Could you check if it fixes the issue you reported here?