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)