Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Chrome occaisionally displays html code instead of parsing properly #340

Closed
bgibson710 opened this issue Jul 16, 2013 · 53 comments
Closed
Assignees

Comments

@bgibson710
Copy link

It seems like on occaision (not every time and hard to reproduce) my python sites in chrome get a 0 before the html headers. Chrome chokes on the processing and displays the html code instead of processing the website. I'm assuming IE and Firefox coded around this and just process the html properly. I'm running Apache 2.4 with mod_proxy_uwsgi. I'm using uwsgi version 1.9.13.

@ghost ghost assigned unbit Jul 16, 2013
@unbit
Copy link
Owner

unbit commented Jul 16, 2013

Can you paste your proxy configuration ?

We had report some time ago of broken headers on apache 2.4. Maybe it is related

@bgibson710
Copy link
Author

It’s as basic as it gets really

ProxyPass /static !
ProxyPass / uwsgi://127.0.0.1:15036/

From: unbit [mailto:notifications@github.com]
Sent: Tuesday, July 16, 2013 11:20 AM
To: unbit/uwsgi
Cc: Gibson, Brian (IMS)
Subject: Re: [uwsgi] Chrome occaisionally displays html code instead of parsing properly (#340)

Can you paste your proxy configuration ?

We had report some time ago of broken headers on apache 2.4. Maybe it is related


Reply to this email directly or view it on GitHubhttps://github.com//issues/340#issuecomment-21049217.


Information in this e-mail may be confidential. It is intended only for the addressee(s) identified above. If you are not the addressee(s), or an employee or agent of the addressee(s), please note that any dissemination, distribution, or copying of this communication is strictly prohibited. If you have received this e-mail in error, please notify the sender of the error.

@unbit
Copy link
Owner

unbit commented Jul 17, 2013

i am trying to find a way to reproduce it. Do you have a way to report a tcpdump/wireshark/pcap (or generally the raw stream of bytes) sent by apache ? Thanks a lot

@bgibson710
Copy link
Author

Attached a capture.

From: unbit [mailto:notifications@github.com]
Sent: Wednesday, July 17, 2013 9:25 AM
To: unbit/uwsgi
Cc: Gibson, Brian (IMS)
Subject: Re: [uwsgi] Chrome occaisionally displays html code instead of parsing properly (#340)

i am trying to find a way to reproduce it. Do you have a way to report a tcpdump/wireshark/pcap (or generally the raw stream of bytes) sent by apache ? Thanks a lot


Reply to this email directly or view it on GitHubhttps://github.com//issues/340#issuecomment-21112288.


Information in this e-mail may be confidential. It is intended only for the addressee(s) identified above. If you are not the addressee(s), or an employee or agent of the addressee(s), please note that any dissemination, distribution, or copying of this communication is strictly prohibited. If you have received this e-mail in error, please notify the sender of the error.

@unbit
Copy link
Owner

unbit commented Jul 17, 2013

sorry i think github swallowed your attachment, try pasting it in the comment

@bgibson710
Copy link
Author

Hrm, well looks like the interface only allows for picture type attachments? It rejected my pcap file here too. If you give me your email address I can send it direct.

@unbit
Copy link
Owner

unbit commented Jul 17, 2013

roberto at unbit.it

@bgibson710
Copy link
Author

Here's a screen capture.

screencap

@unbit
Copy link
Owner

unbit commented Jul 17, 2013

is there any segmentation fault in apache error log ?

@bgibson710
Copy link
Author

No the error logs are clean both for the server and for the specific site.

From: unbit [mailto:notifications@github.com]
Sent: Wednesday, July 17, 2013 12:34 PM
To: unbit/uwsgi
Cc: Gibson, Brian (IMS)
Subject: Re: [uwsgi] Chrome occaisionally displays html code instead of parsing properly (#340)

is there any segmentation fault in apache error log ?


Reply to this email directly or view it on GitHubhttps://github.com//issues/340#issuecomment-21125811.


Information in this e-mail may be confidential. It is intended only for the addressee(s) identified above. If you are not the addressee(s), or an employee or agent of the addressee(s), please note that any dissemination, distribution, or copying of this communication is strictly prohibited. If you have received this e-mail in error, please notify the sender of the error.

@unbit
Copy link
Owner

unbit commented Jul 17, 2013

are you using the mpm "prefork" or the "worker" one ?

@bgibson710
Copy link
Author

Worker

From: unbit [mailto:notifications@github.com]
Sent: Wednesday, July 17, 2013 1:00 PM
To: unbit/uwsgi
Cc: Gibson, Brian (IMS)
Subject: Re: [uwsgi] Chrome occaisionally displays html code instead of parsing properly (#340)

are you using the mpm "prefork" or the "worker" one ?


Reply to this email directly or view it on GitHubhttps://github.com//issues/340#issuecomment-21127639.


Information in this e-mail may be confidential. It is intended only for the addressee(s) identified above. If you are not the addressee(s), or an employee or agent of the addressee(s), please note that any dissemination, distribution, or copying of this communication is strictly prohibited. If you have received this e-mail in error, please notify the sender of the error.

@unbit
Copy link
Owner

unbit commented Jul 20, 2013

Did not managed to reproduce it, but a customer confirmed he has the same bug.

Can you try using SCGI instead of the uwsgi protocol ? If i rememebr correctly SCGI is natively supported in apache 2.4 (and works in the same way as mod_proxy_uwsgi). If SCGI is not available you can try FastCGI (or eventually HTTP even if you lose the ability to add request variables on the fly)

@bgibson710
Copy link
Author

FYI the mod_proxy_scgi module doesn’t seem to work properly. A co-worker patched it and submitted it to Apache to integrate, but we are also maintaining it here https://github.com/imsweb/mod-proxy-scgi in case anyone else might benefit from this.

So far we haven’t been able to reproduce the issue when switching to scgi protocol, and once we got the proxy working as intended with these modifications it is a suitable solution.

From: unbit [mailto:notifications@github.com]
Sent: Saturday, July 20, 2013 11:04 AM
To: unbit/uwsgi
Cc: Gibson, Brian (IMS)
Subject: Re: [uwsgi] Chrome occaisionally displays html code instead of parsing properly (#340)

Did not managed to reproduce it, but a customer confirmed he has the same bug.

Can you try using SCGI instead of the uwsgi protocol ? If i rememebr correctly SCGI is natively supported in apache 2.4 (and works in the same way as mod_proxy_uwsgi). If SCGI is not available you can try FastCGI (or eventually HTTP even if you lose the ability to add request variables on the fly)


Reply to this email directly or view it on GitHubhttps://github.com//issues/340#issuecomment-21294853.


Information in this e-mail may be confidential. It is intended only for the addressee(s) identified above. If you are not the addressee(s), or an employee or agent of the addressee(s), please note that any dissemination, distribution, or copying of this communication is strictly prohibited. If you have received this e-mail in error, please notify the sender of the error.

@unbit
Copy link
Owner

unbit commented Aug 31, 2013

UPDATE: just received another report of the same bug, i still work on it

@bgibson710
Copy link
Author

Thanks for the update. Feel free to pass them that scgi module as a temp work around. Its been working great for us.

-----Original Message-----
From: unbit [notifications@github.com]
Received: Saturday, 31 Aug 2013, 12:06pm
To: unbit/uwsgi [uwsgi@noreply.github.com]
CC: Gibson, Brian (IMS) [GibsonB@imsweb.com]
Subject: Re: [uwsgi] Chrome occaisionally displays html code instead of parsing properly (#340)

UPDATE: just received another report of the same bug, i still work on it


Reply to this email directly or view it on GitHubhttps://github.com//issues/340#issuecomment-23608750.


Information in this e-mail may be confidential. It is intended only for the addressee(s) identified above. If you are not the addressee(s), or an employee or agent of the addressee(s), please note that any dissemination, distribution, or copying of this communication is strictly prohibited. If you have received this e-mail in error, please notify the sender of the error.

@dene14
Copy link

dene14 commented Apr 14, 2014

Guys, sorry I'm bumping it, but there is no activity for 8 month already. Still experiencing the issues with Apache 2.2 / uwsgi 2.0 / mod_proxy_uwsgi
Any update on this?

@unbit
Copy link
Owner

unbit commented Apr 14, 2014

the bug refers to Apache 2.4, there are no reports for 2.2, are you sure it is the same thing ?

@dene14
Copy link

dene14 commented Apr 14, 2014

Yes, absolutely.

#apt-cache policy apache2 libapache2-mod-proxy-uwsgi uwsgi | grep -B1 'Installed:'; uname -a
apache2:

Installed: 2.2.22-1ubuntu1.4

libapache2-mod-proxy-uwsgi:

Installed: 2.0-2

uwsgi:
Installed: 2.0-2
Linux localhost.localdomain 3.8.0-35-generic #50~precise1-Ubuntu SMP Wed Dec 4 17:25:51 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

And I've do some tcpdumping:
browser <- dump1 -> mod_proxy_uwsgi <- dump2 -> uwsgi

Issue seems to be appearing only in dump1, thus uwsgi itself delivers content normally, screwing happens somewhere in mod_proxy_uwsgi / mod_proxy.

Also, there is no strict relation to Chrome, under some circumstances other browsers are also getting their response headers screwed. Seems that Chrome just having more strict header parser and the issue appears much more frequently.

Just in case, uswgi/2.0 package was created by myself (with linkage over apache/2.2) since there was no such version on Launchpad.

I hope this will help.

@unbit
Copy link
Owner

unbit commented Apr 14, 2014

Are you able to report a whole (raw) response as generated by apache (read: as seen by the browser). This could help understanding what is going on. Thanks

@unbit
Copy link
Owner

unbit commented Jun 19, 2014

a new mod_proxy_uwsgi version have been committed (just clone the repo), maybe it fixes this problem too

@dene14
Copy link

dene14 commented Jun 24, 2014

Sorry for a huge delay.

As requested, raw response:
$ od -tx1c -N33 1.X4mvs0bK.bin.part
0000000 38 0d 0a 00 00 00 00 00 00 00 00 0d 0a 30 0d 0a
8 \r \n \0 \0 \0 \0 \0 \0 \0 \0 \r \n 0 \r \n
0000020 0d 0a 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f
\r \n H T T P / 1 . 1 2 0 0 O
0000040 4b
K
0000041

As you can see, there are extra 16 bytes before actual HTTP header start which are leading to these issues. \r \n before the status line seems isn't seem to be correct either. Smells like the some sort of internal encapsulation is leaking outside of allowed borders...

Any thoughs?

@unbit
Copy link
Owner

unbit commented Jun 24, 2014

but have you tried the latest mod_proxy_uwsgi from the git repo ?

@dene14
Copy link

dene14 commented Jun 24, 2014

Sorry, not yet. Which repo/tag should I use?

2014-06-24 16:31 GMT+03:00 unbit notifications@github.com:

but have you tried the latest mod_proxy_uwsgi from the git repo ?


Reply to this email directly or view it on GitHub
#340 (comment).

@unbit
Copy link
Owner

unbit commented Jun 25, 2014

the master branch has latest code

@dene14
Copy link

dene14 commented Jul 3, 2014

Tried with 2.0.6 today. Unfortunately no luck, issue still here... Here is how Chrome recognize it:

GET /some/path/requested HTTP/0.9
Host: some.host.tld:443
Accept: /
Accept-Encoding: gzip,deflate,sdch
Accept-Language: en-US,en;q=0.8
Cookie: sessionid=some_secret_cookie
Referer: https://some.referer.tld/uri
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/35.0.1916.153 Safari/537.36
X-Requested-With: XMLHttpRequest

HTTP/0.9 200 OK
------- and that's all! -------

When request handled properly, Chrome shows it as follows:

GET /some/path/requested HTTP/1.1
Host: some.host.tld:443
Accept: /
Accept-Encoding: gzip,deflate,sdch
Accept-Language: en-US,en;q=0.8
Cookie: sessionid=some_secret_cookie
Referer: https://some.referer.tld/uri
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/35.0.1916.153 Safari/537.36
X-Requested-With: XMLHttpRequest

HTTP/1.1 200 OK
Cache-Control: no-cache
Connection: Keep-Alive
Content-Encoding: gzip
Content-Length: 157
Content-Type: application/json;charset=utf-8
Date: Thu, 03 Jul 2014 15:27:14 GMT
Keep-Alive: timeout=5, max=100
Pragma: no-cache
Vary: Cookie,Accept-Encoding

@unbit
Copy link
Owner

unbit commented Jul 3, 2014

are you sure you have rebuilt the latest mod_proxy_uwsgi apache module ?

@dene14
Copy link

dene14 commented Jul 4, 2014

Absolutely, packaged all the bunch of uwsgi modules from 2.0.6.tar.gz and installed on some servers.

!# md5sum mod_proxy_uwsgi.2.0.0.so mod_proxy_uwsgi.2.0.6.so
93fd03aab150caa5408e57c45bdb4eb8 mod_proxy_uwsgi.2.0.0.so
97e2fe9ab56802600f634b20b5ce22b1 mod_proxy_uwsgi.2.0.6.so

!# ls -al mod_proxy_uwsgi.2.0.0.so mod_proxy_uwsgi.2.0.6.so
-rw-r--r-- 1 root root 14720 Jan 20 00:00 mod_proxy_uwsgi.2.0.0.so
-rw-r--r-- 1 root root 14720 Jul 3 14:11 mod_proxy_uwsgi.2.0.6.so

However same size of different versions confusing a bit...

@cuchac
Copy link
Contributor

cuchac commented Nov 13, 2014

Hi!

I'm experiencing the same problem, but I know the cause and possible solution! :-)

I'm running Apache 2.2 with mod_proxy_uwsgi. The problem is in duplicated zero-length-sized chunks when Content-Encoding: chunked is used - and it is used almost always.

I'm not sure, whether the fault is in mod_proxy, mod_proxy_uwsi or uwsgi. PHP apps on the same server does not have the duplicate zero-sized chunks, so Apache is probably not causing it.

Why @dene14 was able to reproduce it and @unibit no? Probably @dene14 is using Avast antivirus or other software not handling duplicated zero-sized chunks correctly. I spent last 2 weeks with Avast support to discover where the problem lies, because I managed to reproduce it ONLY on Windows XP ..... crazy.

To prove my conclusions, try to run following two commands. They prints last lines of raw content of web communication. First is mod_proxy_uwsgi based, second is PHP based. Both on the same server. Notice the two zero-sized chunks at the end with first example.

curl -ivs --raw http://www.wpj.cz | tail -n 15
curl -ivs --raw http://www.kupkolo.cz | tail -n 15

This is causing the error - last lines of HTTP communication generated by mod_proxy_uwsgi:

</body>
</html>

0

0

Some open-source apps also have problem parsing these duplicate zero-sized chunks. It is somehow time-based, so it is not easy to trigger. For example latest Konqueror browser suffers from this issue. It is probably caused by some open-source library both Konqueror and Avast use, because the symptoms and timing constraints are identical.

@cuchac
Copy link
Contributor

cuchac commented Nov 13, 2014

The tricky part here is that broken headers ('0\r\n' prepended) is caused by another application/library. I used Wireshark to dump raw data and confirmed '0\r\n' is not send by web server even when the error happened. It is added by some HTTP parsing library (or antivirus using the library), and the cause is those two zero-sized chunks.

Software can by really unpredictable sometimes :-)

@unbit
Copy link
Owner

unbit commented Nov 13, 2014

This is crazy, you can exclude uWSGI from the equation as it sends raw output, so unless your app sends chunked frame there is nothing that can goes wrong. I assume the problem can be in mod_proxy_uwsgi (are you using latest version ? we improved in 2.0.6), but it does the same steps of mod_proxy_http. I'll dig a bit into apache sources. Btw there must be some kind of app-generated output that triggers this behaviour, as very few people reported it.

@unbit
Copy link
Owner

unbit commented Nov 13, 2014

Oh, obviously thanks for you report :)

@cuchac
Copy link
Contributor

cuchac commented Nov 13, 2014

I'm using plain Django, so no chunking should be involved on Python side. Should I prepare some very basic testing Python app? Any links?

I'm using mod_proxy_uwsgi somewhere around 2.0.4, but first chance to upgrade will be tonight (discovered the cause today morning). Did you verified that Apache + mod_proxy_uwsgi in your test env does not produce the duplicate-zero-chunks problem?

@unbit
Copy link
Owner

unbit commented Nov 13, 2014

Yes, no zero trailings, le me know how it goes with latest version, maybe it is enough. Now i am searching in httpd sources where (and when) the trailing chunk is added.

@che0
Copy link

che0 commented Nov 13, 2014

I have a server with apache 2.2.27 and uwsgi 2.0.8 and it sometimes exhibits this issue as well. The curl command cuchac posted above seems to reproduce it pretty reliably.

@cuchac
Copy link
Contributor

cuchac commented Nov 13, 2014

Damned Avast! Seems people from Czech Republic are most affected :-) They told me next release will fix this issue, so most of affected users will get fixed by next Avast upgrade.

Latest change in mod_apache_uwsgi is from 2.0.6 release so it seems even git version will be affected. Is there anything we can do to help you solve this? I will try to upgrade tonight and make some tiny python app without any framework to test. My version of Apache is 2.2.27-r4, Gentoo distribution.

@unbit
Copy link
Owner

unbit commented Nov 14, 2014

Trying hard to reproduce the problem without luck. Can you give me the list of apache modules loaded and used by the www.wpj.cz instance ?

@che0
Copy link

che0 commented Nov 14, 2014

I can for my instance:

curl -iws --raw http://tracker.wikimedia.cz/ticket/660/ | tail -n15

gives me the zeroes.

# ( . /etc/conf.d/apache2 && apache2 ${APACHE2_OPTS} -M )
Loaded Modules:
 core_module (static)
 mpm_prefork_module (static)
 http_module (static)
 so_module (static)
 alias_module (shared)
 auth_basic_module (shared)
 authn_file_module (shared)
 authz_default_module (shared)
 authz_groupfile_module (shared)
 authz_host_module (shared)
 authz_user_module (shared)
 autoindex_module (shared)
 cgi_module (shared)
 dir_module (shared)
 env_module (shared)
 expires_module (shared)
 log_config_module (shared)
 mime_module (shared)
 negotiation_module (shared)
 proxy_module (shared)
 proxy_http_module (shared)
 rewrite_module (shared)
 setenvif_module (shared)
 proxy_uwsgi_module (shared)
 xsendfile_module (shared)
 php5_module (shared)
Syntax OK

This is also Gentoo system, the zeroes still come when the module list is reduced to this:

Loaded Modules:
 core_module (static)
 mpm_prefork_module (static)
 http_module (static)
 so_module (static)
 alias_module (shared)
 auth_basic_module (shared)
 authz_host_module (shared)
 log_config_module (shared)
 mime_module (shared)
 negotiation_module (shared)
 proxy_module (shared)
 proxy_http_module (shared)
 rewrite_module (shared)
 setenvif_module (shared)
 proxy_uwsgi_module (shared)
Syntax OK

@cuchac
Copy link
Contributor

cuchac commented Nov 18, 2014

Hi!
We can rule-out python application side. I've just deployed simplest Python WSGI app on http://uwsgi.cuchac.cz :

def application(env, start_response):
    start_response('200 OK', [('Content-Type','text/html')])
    return ["Hello World"]

and the problem is still there.

I'm trying to reproduce the same issue on deveopment Gentoo box to avoid experimenting on production site.

@cuchac
Copy link
Contributor

cuchac commented Nov 18, 2014

Hi!
I've run several tests and these are my observations:

  1. I reproduced the problem on the other Gentoo box. Apache + mod_proxy_uwsgi.
  2. I was unable to reproduce it using mod_uwsgi or mod_ruwsgi, because they are not using chunked transfer encoding.
  3. When chunked transformation enabled using mod_uwsgi or mod_ruwsgi (forced chunked encoding) the problem is not there, simply because chunking is doing uWsgi and not Apache.
  4. When using chunked transformation on mod_proxy_uwsgi the problem is gone as well! Simply because chunking is doing uWsgi and not Apache. Is there some performance penalty? This could be workaround.
  5. mod_proxy_uwsgi does not trigger the error always. I'm able to trigger it with 90% probability, but sometimes the error is not there.
  6. After installing Apache 2.2.29, the probability reversed to 10% of failures, but it could be time-dependent and tomorrow would be 90% of failures again.

@unbit
Copy link
Owner

unbit commented Nov 18, 2014

I am pretty sure the problem is in this function: https://github.com/unbit/uwsgi/blob/master/apache2/mod_proxy_uwsgi.c#L301

can you try adding debug log all over the place to understand what is passed to apache ?

the critical part is here: https://github.com/unbit/uwsgi/blob/master/apache2/mod_proxy_uwsgi.c#L368

@cuchac
Copy link
Contributor

cuchac commented Nov 20, 2014

Got it! :-)

ap_get_brigade can return a brigade that APR_BRIGADE_EMPTY(bb) == false and (quite unexpectedly) apr_brigade_length(bb, 0, &readbytes); readbytes == 0

I've added debug statements like this:

for(;;) {
        rv = ap_get_brigade(rp->input_filters, bb,
                                        AP_MODE_READBYTES, mode,
                                        conf->io_buffer_size);

      ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r, "READ");
      apr_brigade_length(bb, 0, &readbytes);

        if (mode == APR_NONBLOCK_READ && (APR_STATUS_IS_EAGAIN(rv)
         || (rv == APR_SUCCESS && (APR_BRIGADE_EMPTY(bb) /*|| readbytes == 0*/)))) {
            e = apr_bucket_flush_create(c->bucket_alloc);
            APR_BRIGADE_INSERT_TAIL(bb, e);
            if (ap_pass_brigade(r->output_filters, bb) || c->aborted) {
            ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r, "aborted");
                break;
            }
            apr_brigade_cleanup(bb);
            mode = APR_BLOCK_READ;
      ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r, "APR_BLOCK_READ");
            continue;
        }
        else if (rv == APR_EOF) {
         ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r, "APR_EOF");
            break;
        }
        else if (rv != APR_SUCCESS) {
            ap_proxy_backend_broke(r, bb);
            ap_pass_brigade(r->output_filters, bb);
            backend_broke = 1;
         ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r, "backend_broke");
            break;
        }

        mode = APR_NONBLOCK_READ;
        apr_brigade_length(bb, 0, &readbytes);
        backend->worker->s->read += readbytes;

      ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r, "READ bytes: %d", readbytes);

        if (APR_BRIGADE_EMPTY(bb)) {
                        apr_brigade_cleanup(bb);
                        ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r, "CLEANUP");
                        break;
                }

        ap_proxy_buckets_lifetime_transform(r, bb, pass_bb);

        ap_pass_brigade(r->output_filters, pass_bb);
        apr_brigade_cleanup(bb);
        apr_brigade_cleanup(pass_bb);
    }

and the resulting logs are for the correct result:

[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(373): [client ::1] READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(405): [client ::1] READ bytes: 11
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(373): [client ::1] READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(386): [client ::1] APR_BLOCK_READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(373): [client ::1] (70014)End of file found: READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(390): [client ::1] (70014)End of file found: APR_EOF

and for incorrect result:

[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(373): [client ::1] READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(405): [client ::1] READ bytes: 11
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(373): [client ::1] READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(386): [client ::1] APR_BLOCK_READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(373): [client ::1] READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(405): [client ::1] READ bytes: 0
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(373): [client ::1] (70014)End of file found: READ
[Thu Nov 20 05:14:25 2014] [debug] mod_proxy_uwsgi.c(390): [client ::1] (70014)End of file found: APR_EOF

After uncommenting /*|| readbytes == 0*/ from my example, I did not manage to trigger this problem anymore.

@unbit
Copy link
Owner

unbit commented Nov 20, 2014

Great work, i'll check why the other proxies do not do it and i will adapt your patch. I will release 2.0.9 as soon as it is ok. Thanks a lot

@cuchac
Copy link
Contributor

cuchac commented Nov 20, 2014

My "patch" is not really a fix. I don't understand the code fully enough. There are possibly some side-effects I don't foresee.

@unbit
Copy link
Owner

unbit commented Nov 20, 2014

Yes, do not worry, now i know why, how and when the problem happens. I will push a fix asap

unbit added a commit that referenced this issue Nov 21, 2014
@unbit unbit closed this as completed in 5911949 Nov 21, 2014
@unbit unbit reopened this Nov 21, 2014
@unbit
Copy link
Owner

unbit commented Nov 21, 2014

Can you try with the pushed patch ? Thanks

@cuchac
Copy link
Contributor

cuchac commented Nov 26, 2014

Sorry for such a delay.
I'm able to reproduce it on the up-to-date master, sorry.

@unbit
Copy link
Owner

unbit commented Nov 27, 2014

ok, i'll try to push another approach later, thanks again

@unbit
Copy link
Owner

unbit commented Dec 5, 2014

Another attempt e051e4f
let me know. Thanks

@cuchac
Copy link
Contributor

cuchac commented Dec 10, 2014

Hi, unfortunately the issue still persists. I've added debug output again. Here are results:

Correct:

[Wed Dec 10 10:20:59 2014] [error] [client ::1] mode = APR_NONBLOCK_READ
[Wed Dec 10 10:20:59 2014] [error] [client ::1] readbytes: 11
[Wed Dec 10 10:20:59 2014] [error] [client ::1] mode = APR_BLOCK_READ
[Wed Dec 10 10:20:59 2014] [error] [client ::1] (70014)End of file found: APR_EOF

Incorrect:

[Wed Dec 10 10:20:59 2014] [error] [client ::1] mode = APR_NONBLOCK_READ
[Wed Dec 10 10:20:59 2014] [error] [client ::1] readbytes: 11
[Wed Dec 10 10:20:59 2014] [error] [client ::1] mode = APR_BLOCK_READ
[Wed Dec 10 10:20:59 2014] [error] [client ::1] mode = APR_NONBLOCK_READ
[Wed Dec 10 10:20:59 2014] [error] [client ::1] readbytes: 0
[Wed Dec 10 10:20:59 2014] [error] [client ::1] APR_BUCKET_IS_EOS(APR_BRIGADE_LAST(bb))

Annotated code:

        int finish = 0;
        while(!finish) {
                rv = ap_get_brigade(rp->input_filters, bb,
                                        AP_MODE_READBYTES, mode,
                                        conf->io_buffer_size);
                if (APR_STATUS_IS_EAGAIN(rv)
                        || (rv == APR_SUCCESS && APR_BRIGADE_EMPTY(bb)) ) {
                        e = apr_bucket_flush_create(c->bucket_alloc);
                        APR_BRIGADE_INSERT_TAIL(bb, e);
                        if (ap_pass_brigade(r->output_filters, bb) || c->aborted) {
                                break;
                        }
                        apr_brigade_cleanup(bb);
                        mode = APR_BLOCK_READ;
ap_log_rerror(APLOG_MARK, APLOG_ERR, rv, r, "mode = APR_BLOCK_READ");
                        continue;
                }
                else if (rv == APR_EOF) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, rv, r, "APR_EOF");
                        break;
                }
                else if (rv != APR_SUCCESS) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, rv, r, "rv != APR_SUCCESS");
                        ap_proxy_backend_broke(r, bb);
                        ap_pass_brigade(r->output_filters, bb);
                        backend_broke = 1;
                        break;
                }

ap_log_rerror(APLOG_MARK, APLOG_ERR, rv, r, "mode = APR_NONBLOCK_READ");
                mode = APR_NONBLOCK_READ;
                apr_brigade_length(bb, 0, &readbytes);
                backend->worker->s->read += readbytes;

ap_log_rerror(APLOG_MARK, APLOG_ERR, rv, r, "readbytes: %d", readbytes);

                if (APR_BRIGADE_EMPTY(bb)) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, rv, r, "APR_BRIGADE_EMPTY");
                        apr_brigade_cleanup(bb);
                        break;
                }

                ap_proxy_buckets_lifetime_transform(r, bb, pass_bb);

                // found the last brigade?
                if (APR_BUCKET_IS_EOS(APR_BRIGADE_LAST(bb))){
ap_log_rerror(APLOG_MARK, APLOG_ERR, rv, r, "APR_BUCKET_IS_EOS(APR_BRIGADE_LAST(bb))");
                        finish = 1;
                }

                if (ap_pass_brigade(r->output_filters, pass_bb) != APR_SUCCESS || c->aborted) {
ap_log_rerror(APLOG_MARK, APLOG_ERR, rv, r, "ap_pass_brigade(r->output_filters, pass_bb) != APR_SUCCESS || c->aborted");
                        finish = 1;
                }

                apr_brigade_cleanup(bb);
                apr_brigade_cleanup(pass_bb);
        }

        e = apr_bucket_eos_create(c->bucket_alloc);
        APR_BRIGADE_INSERT_TAIL(bb, e);

The simplest fix I found was just to skip ap_pass_brigade if brigade contains no data:

                if (readbytes > 0)
                if (ap_pass_brigade(r->output_filters, pass_bb) != APR_SUCCESS || c->aborted) {
....

@unbit
Copy link
Owner

unbit commented Dec 10, 2014

what about this approach ? d69e234

@cuchac
Copy link
Contributor

cuchac commented Dec 10, 2014

Great, that seems to fix the issue. I've done several minutes of testing and not a single error.

@unbit
Copy link
Owner

unbit commented Dec 10, 2014

great, let's close this (again)

@unbit unbit closed this as completed Dec 10, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants