Re: [privoxy-devel] keep-alive-timeout problem with yahoo email

[Lee <le...@gm...>]

On 11/22/08, Fabian Keil <fre...@fa...> wrote:
> Lee <le...@gm...> wrote:
>
>> On 11/20/08, Fabian Keil <fk...@fa...> wrote:
>> > Lee <le...@gm...> wrote:
>> >
>> >> I just noticed a problem with Yahoo email & Privoxy keep alives.  If I
>> >> click on any link the browers fetches the page (I can see it's
>> >> downloaded with wireshark) and then the browser just sits there, not
>> >> changing the display, not changing the progress bar until the server
>> >> sends a FIN+ACK 60 seconds later - at which point the browser displays
>> >> the new page.
>> >>
>> >> If I comment out the keep-alive-timeout line in my config file
>> >> # keep-alive-timeout  300
>> >> yahoo email works fine.  Uncomment the line (+ visit http://p.p and
>> >> look at the config to force Privoxy to refresh the config) & it's back
>> >> to downloading the page and then waiting 60 seconds for the FIN+ACK
>> >> from the server before displaying any page.
>> >
>> > What happens if you set keep-alive-timeout to 180?
>>
>> I still get a delay.  Even setting the timeout to 60 results in a delay.
>>
  [.. snip speculation about possible cause ..]
>
> Could you try again with up-to-date sources (I changed
> a log message), debug 16 disabled and with both
> keep-alive-timeout -1 and keep-alive-timeout 0?

No problems with "keep-alive-timeout -1" but I get the same 1 minute
delay with a keep-alive timeout of 0

I was watching the traffic w/ wireshark and the problem seems to be
related to Yahoo sending the results back as gzipped chunks.  I added
some code in jcc.c to log the number of characters received when
processing chunked data and it acts like chunked data isn't processed
until the connection is closed:

Nov 25 22:02:38.829 00000188 Request:
us.mc510.mail.yahoo.com/mc/showMessage;_ylt=[..snip..]
Nov 25 22:02:38.829 00000188 Connect: to us.mc510.mail.yahoo.com
Nov 25 22:02:38.892 00000188 Connect: Created new connection to
us.mc510.mail.yahoo.com:80 on socket 1864.
Nov 25 22:02:38.892 00000188 Connect: to us.mc510.mail.yahoo.com successful
Nov 25 22:02:39.673 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.689 00000188 Connect: Chunked response len: 4380
Nov 25 22:02:39.689 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.689 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.704 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.704 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.704 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.720 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.720 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.720 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.720 00000188 Connect: Chunked response len: 1460
Nov 25 22:02:39.720 00000188 Connect: Chunked response len: 1541
Nov 25 22:02:39.720 00000188 Connect: Looks like we reached the end of
the last chunk. We better stop reading.

------ the browser should display the page now but nothing gets
displayed until we get a FIN+ACK from the server a minute later

Nov 25 22:02:39.720 00000188 Connect: Faking read of 0 bytes
---- me, thinking that pretending we just read 0 bytes would fix the
problem.  Didn't

Nov 25 22:02:39.736 00000188 Connect: Remembering socket 1864 for
us.mc510.mail.yahoo.com:80 in slot 0.
Nov 25 22:02:39.751 00000d48 Connect: accepted connection from 127.0.0.1
Nov 25 22:02:39.751 00000d48 Connect: Listening for new connections ...
Nov 25 22:02:39.751 000000c4 Request:
us.mc510.mail.yahoo.com/mc/oCSS?.rand=[.. snip ..]
Nov 25 22:02:39.767 000000c4 Connect: to us.mc510.mail.yahoo.com
Nov 25 22:02:39.767 000000c4 Connect: Socket 1864 appears to be still alive.
Nov 25 22:02:39.767 000000c4 Connect: Found reusable socket 1864 for
us.mc510.mail.yahoo.com:80 in slot 0.
Nov 25 22:02:39.767 000000c4 Connect: to us.mc510.mail.yahoo.com successful
Nov 25 22:03:39.807 000000c4 Connect: Chunked response len: 0
Nov 25 22:03:39.807 000000c4 Connect: Marking open socket 1864 for
us.mc510.mail.yahoo.com:80 in slot 0 as unused.
Nov 25 22:03:39.870 00000d48 Connect: accepted connection from 127.0.0.1
Nov 25 22:03:39.870 00000d48 Connect: Listening for new connections ...

--- and the page is finally displayed.

You'll need to see the attached diff of  jcc.c to see where I added
some log messages

I'll keep playing around w/ it but I don't understand what's going on in chat..


>> semi-related: I noticed this bit in the log
>>   Connect: Initialized 100 socket slots.
>> Does that mean I should drop this pref down to 100?
>>   user_pref("network.http.max-persistent-connections-per-proxy", 255);
>
> Privoxy only supports keep-alive for outgoing
> connections therefore the value of this option
> shouldn't matter.

It's probably not going to be an issue - I tried to see how many
concurrent connections I could get  FF to open a while back and
couldn't even get it up to 50. But if Privoxy has a limit on how many
connections it'll do I'd like to have that same limit configured in
FF.

>> >> So far, it's only yahoo mail where I've noticed this behavior.  Gmail,
>> >> my work mail, various web sites... no problems with any of them.  It's
>> >> just Yahoo mail that's got this 60 second delay before the browser
>> >> displays anything problem if I have "keep-alive-timeout  300" in
>> >> config.txt
>> >
>> > Can you post a log excerpt with all debug options enabled?
>>
>> see attached
>> I enabled all the debug options, cleared the log file, and did three
>> tests 1. keep-alive-timeout 300 + clear browser cache + restart privoxy
>> 2. keep-alive-timeout 180 + clear browser cache + restart privoxy
>> 3. no keep-alive-timeout + clear browser cache + restart privoxy
>
> Do you always get the errors messages in test 3?

No.  It seems to be related to the wireless NIC power config.  I
finally noticed that it uses full power when the laptop is plugged in
& minimum power when running off the battery..   Changing it to always
use full power seems to have fixed that problem.

Lee

>
> Fabian
>