Bug in 1.9.14 or something else?

Sadaf_N · April 6, 2016, 9:39pm

I’m running a WordPress 4.4.2-based membership site on Ubuntu 12.04 LTS
with
PHP 5.6.20.

After upgrading to 1.9.14 (compiling from source with no errors or
warnings), I could no longer log in to my site, using Firefox/Chrome/IE.
Trying to login didn’t timeout. Instead, fairly quickly, I would get an
error message like this in Firefox:

Secure Connection Failed

The connection to jobmob.co.il was interrupted while the page was
loading.

The page you are trying to view cannot be shown because the

authenticity
of the received data could not be verified.
Please contact the website owners to inform them of this problem.

Learn more…

Tailing the error logs, nothing at all appears when I try to log in.

My WordPress install is Multisite, which means I can have multiple
websites
running off a single install, and I do. However, only the main website
has
this login issue with 1.9.14. I could still log in without a problem in
each of the other sites.

How to troubleshoot this? 1.9.14 has relatively few changes, so I was
surprised by this. I’ve since rolled back to 1.9.13

Posted at Nginx Forum:

jshare · April 7, 2016, 1:48am

Hello!

On Wed, Apr 06, 2016 at 03:38:31PM -0400, jshare wrote:

My WordPress install is Multisite, which means I can have multiple websites
running off a single install, and I do. However, only the main website has
this login issue with 1.9.14. I could still log in without a problem in
each of the other sites.

How to troubleshoot this? 1.9.14 has relatively few changes, so I was
surprised by this. I’ve since rolled back to 1.9.13

There are various changes related to request body handling when
using HTTP/2 in 1.9.14. If you are using HTTP/2, consider
disabling it to see if it helps.

In either case debug log should help to further diagnose the
problem, see A debugging log.

–
Maxim D.
http://nginx.org/

jshare · April 7, 2016, 4:26pm

On Wednesday 06 April 2016 15:38:31 jshare wrote:

My WordPress install is Multisite, which means I can have multiple websites
running off a single install, and I do. However, only the main website has
this login issue with 1.9.14. I could still log in without a problem in
each of the other sites.

How to troubleshoot this? 1.9.14 has relatively few changes, so I was
surprised by this. I’ve since rolled back to 1.9.13

Could you try without 3rd-party modules and patches?

wbr, Valentin V. Bartenev

jshare · April 10, 2016, 10:18am

If I disable http/2, I can login - good call!

I enabled the debug.log to compare the output with http/2 enabled and
disabled, but when I compare the two side by side, nothing jumps out at
me.
Aside from the time and a few numbers, the two log sections are
identical.
What should I be looking for?

For example, here’s the tailed log section that appears when I can’t
login
because http/2 is enabled:

2016/04/10 10:53:23 [debug] 11339#0: post event 0A108050
2016/04/10 10:53:23 [debug] 11339#0: delete posted event 0A108050
2016/04/10 10:53:23 [debug] 11339#0: accept on 0.0.0.0:80, ready: 1
2016/04/10 10:53:23 [debug] 11339#0: posix_memalign: 0A2A1A30:256 @16
2016/04/10 10:53:23 [debug] 11339#0: *32 accept: 127.0.0.1:47024 fd:17
2016/04/10 10:53:23 [debug] 11339#0: *32 event timer add: 17:
20000:4280909831
2016/04/10 10:53:23 [debug] 11339#0: *32 reusable connection: 1
2016/04/10 10:53:23 [debug] 11339#0: *32 epoll add event: fd:17 op:1
ev:80002001
2016/04/10 10:53:23 [debug] 11339#0: accept() not ready (11: Resource
temporarily unavailable)
2016/04/10 10:53:23 [debug] 11339#0: *32 post event 0A1081A0
2016/04/10 10:53:23 [debug] 11339#0: *32 delete posted event 0A1081A0
2016/04/10 10:53:23 [debug] 11339#0: *32 http wait request handler
2016/04/10 10:53:23 [debug] 11339#0: *32 malloc: 0A2557C8:1024
2016/04/10 10:53:23 [debug] 11339#0: *32 recv: fd:17 106 of 1024
2016/04/10 10:53:23 [debug] 11339#0: *32 reusable connection: 0
2016/04/10 10:53:23 [debug] 11339#0: *32 posix_memalign: 0A29E7B0:4096
@16
2016/04/10 10:53:23 [debug] 11339#0: *32 http process request line
2016/04/10 10:53:23 [debug] 11339#0: *32 http request line: “GET
/readme.html HTTP/1.1”
2016/04/10 10:53:23 [debug] 11339#0: *32 http uri: “/readme.html”
2016/04/10 10:53:23 [debug] 11339#0: *32 http args: “”
2016/04/10 10:53:23 [debug] 11339#0: *32 http exten: “html”
2016/04/10 10:53:23 [debug] 11339#0: *32 http process request header
line
2016/04/10 10:53:23 [debug] 11339#0: *32 http header: “Host:
jobmob.co.il”
2016/04/10 10:53:23 [debug] 11339#0: *32 http header: “Accept: /”
2016/04/10 10:53:23 [debug] 11339#0: *32 http header: “Connection:
close”
2016/04/10 10:53:23 [debug] 11339#0: *32 http header: “User-Agent:
monit/5.3.2”
2016/04/10 10:53:23 [debug] 11339#0: *32 http header done
2016/04/10 10:53:23 [debug] 11339#0: *32 event timer del: 17: 4280909831
2016/04/10 10:53:23 [debug] 11339#0: *32 generic phase: 0
2016/04/10 10:53:23 [debug] 11339#0: *32 rewrite phase: 1
2016/04/10 10:53:23 [debug] 11339#0: *32 http set discard body
2016/04/10 10:53:23 [debug] 11339#0: *32 http script copy:
“https://jobmob.co.il”
2016/04/10 10:53:23 [debug] 11339#0: *32 http script var: “/readme.html”
2016/04/10 10:53:23 [debug] 11339#0: *32 http finalize request: 301,
“/readme.html?” a:1, c:1
2016/04/10 10:53:23 [debug] 11339#0: *32 http special response: 301,
“/readme.html?”
2016/04/10 10:53:23 [debug] 11339#0: *32 http set discard body
2016/04/10 10:53:23 [debug] 11339#0: *32 xslt filter header
2016/04/10 10:53:23 [debug] 11339#0: *32 charset: “” > “UTF-8”
2016/04/10 10:53:23 [debug] 11339#0: *32 HTTP/1.1 301 Moved Permanently
Server: nginx
Date: Sun, 10 Apr 2016 07:53:23 GMT
Content-Type: text/html
Content-Length: 178
Connection: close
Location: https://jobmob.co.il/readme.html

2016/04/10 10:53:23 [debug] 11339#0: *32 write new buf t:1 f:0 0A29F1AC,
pos
0A29F1AC, size: 195 file: 0, size: 0
2016/04/10 10:53:23 [debug] 11339#0: *32 http write filter: l:0 f:0
s:195
2016/04/10 10:53:23 [debug] 11339#0: *32 http output filter
“/readme.html?”
2016/04/10 10:53:23 [debug] 11339#0: *32 http copy filter:
“/readme.html?”
2016/04/10 10:53:23 [debug] 11339#0: *32 image filter
2016/04/10 10:53:23 [debug] 11339#0: *32 xslt filter body
2016/04/10 10:53:23 [debug] 11339#0: *32 http postpone filter
“/readme.html?” 0A29F328
2016/04/10 10:53:23 [debug] 11339#0: *32 write old buf t:1 f:0 0A29F1AC,
pos
0A29F1AC, size: 195 file: 0, size: 0
2016/04/10 10:53:23 [debug] 11339#0: *32 write new buf t:0 f:0 00000000,
pos
08EFEF00, size: 132 file: 0, size: 0
2016/04/10 10:53:23 [debug] 11339#0: *32 write new buf t:0 f:0 00000000,
pos
08EFF1A0, size: 46 file: 0, size: 0
2016/04/10 10:53:23 [debug] 11339#0: *32 http write filter: l:1 f:0
s:373
2016/04/10 10:53:23 [debug] 11339#0: *32 http write filter limit 0
2016/04/10 10:53:23 [debug] 11339#0: *32 writev: 373 of 373
2016/04/10 10:53:23 [debug] 11339#0: *32 http write filter 00000000
2016/04/10 10:53:23 [debug] 11339#0: *32 http copy filter: 0
“/readme.html?”
2016/04/10 10:53:23 [debug] 11339#0: *32 http finalize request: 0,
“/readme.html?” a:1, c:1
2016/04/10 10:53:23 [debug] 11339#0: *32 event timer add: 17:
5000:4280894832
2016/04/10 10:53:23 [debug] 11339#0: *32 http lingering close handler
2016/04/10 10:53:23 [debug] 11339#0: *32 recv: fd:17 -1 of 4096
2016/04/10 10:53:23 [debug] 11339#0: *32 recv() not ready (11: Resource
temporarily unavailable)
2016/04/10 10:53:23 [debug] 11339#0: *32 lingering read: -2
2016/04/10 10:53:23 [debug] 11339#0: *32 event timer: 17, old:
4280894832,
new: 4280894832
2016/04/10 10:53:23 [debug] 11339#0: *32 post event 0A1081A0
2016/04/10 10:53:23 [debug] 11339#0: *32 delete posted event 0A1081A0
2016/04/10 10:53:23 [debug] 11339#0: *32 http lingering close handler
2016/04/10 10:53:23 [debug] 11339#0: *32 recv: fd:17 0 of 4096
2016/04/10 10:53:23 [debug] 11339#0: *32 lingering read: 0
2016/04/10 10:53:23 [debug] 11339#0: *32 http request count:1 blk:0
2016/04/10 10:53:23 [debug] 11339#0: *32 http close request
2016/04/10 10:53:23 [debug] 11339#0: *32 http log handler
2016/04/10 10:53:23 [debug] 11339#0: *32 free: 0A29E7B0, unused: 1006
2016/04/10 10:53:23 [debug] 11339#0: *32 close http connection: 17
2016/04/10 10:53:23 [debug] 11339#0: *32 event timer del: 17: 4280894832
2016/04/10 10:53:23 [debug] 11339#0: *32 reusable connection: 0
2016/04/10 10:53:23 [debug] 11339#0: *32 free: 0A2557C8
2016/04/10 10:53:23 [debug] 11339#0: *32 free: 0A2A1A30, unused: 36

Posted at Nginx Forum:

jshare · April 11, 2016, 6:52pm

Hello!

On Sun, Apr 10, 2016 at 04:18:05AM -0400, jshare wrote:

If I disable http/2, I can login - good call!

I enabled the debug.log to compare the output with http/2 enabled and
disabled, but when I compare the two side by side, nothing jumps out at me.
Aside from the time and a few numbers, the two log sections are identical.
What should I be looking for?

For example, here’s the tailed log section that appears when I can’t login
because http/2 is enabled:

[…]

2016/04/10 10:53:23 [debug] 11339#0: *32 http process request line
2016/04/10 10:53:23 [debug] 11339#0: *32 http request line: “GET /readme.html
HTTP/1.1”

[…]

2016/04/10 10:53:23 [debug] 11339#0: *32 HTTP/1.1 301 Moved Permanently
Server: nginx
Date: Sun, 10 Apr 2016 07:53:23 GMT
Content-Type: text/html
Content-Length: 178
Connection: close
Location: https://jobmob.co.il/readme.html

This log doesn’t looks like a request with HTTP/2 enabled.
Rather, it looks like a plain HTTP/1.1 redirect to SSL. You
probably have another server{} section to handle SSL, and this
section doesn’t have debugging log configured.

You may also want to provide:

“nginx -V” output;
the configuration you are using.

–
Maxim D.
http://nginx.org/