Mailing List Archive

Hit idle send timeout
Hello everyone,

I'm running 4.1.8 as a frontend to a local Apache 2.4 and just recently ran
into a burst of the following "idle/write errors" without any corresponding
errors logged in Apache. Any suggestions on what to keep an eye on or
further review would be greatly appreciated.

* << Request >> 482784125
- Begin req 482784124 rxreq
- Timestamp Start: 1504382885.868717 0.000000 0.000000
- Timestamp Req: 1504382885.868717 0.000000 0.000000
- ReqStart [redacted.xfwd2IP] 35207
- ReqMethod GET
- ReqURL /[redacted.url]/
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.[redacted.domain.tld]
- ReqHeader User-Agent: Mozilla/5.0 (Linux; Android 7.0; SM-G920F
Build/NRD90M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.116
Mobile Safari/537.36
- ReqHeader Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
- ReqHeader Accept-Language: ro-RO,ro;q=0.8,en-US;q=0.6,en;q=0.4
- ReqHeader Cf-Connecting-Ip: [redacted.xfwd1IP]
- ReqHeader Cf-Ipcountry: RO
- ReqHeader Cf-Origin-Https: off
- ReqHeader Cf-Ray: 3983196ce0b87ea0-BUD
- ReqHeader Cf-Visitor: {"scheme":"http"}
- ReqHeader Cookie:
__cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
__PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
_ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C34%2C11%7C35
- ReqHeader Referer: https://www.google.ro/
- ReqHeader Upgrade-Insecure-Requests: 1
- ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
- ReqHeader X-Forwarded-Proto: http
- ReqHeader Accept-Encoding: gzip
- ReqHeader Connection: close
- ReqUnset X-Forwarded-For: [redacted.xfwd1IP]
- ReqHeader X-Forwarded-For: [redacted.xfwd1IP], [redacted.xfwd2IP]
- VCL_call RECV
- VCL_acl MATCH cloudflare "172.64.0.0/13"
- ReqHeader X-Country: RO
- ReqHeader ignore_becache: 1
- ReqUnset Host: www.[redacted.domain.tld]
- ReqHeader Host: www.[redacted.domain.tld]
- ReqUnset X-Forwarded-For: [redacted.xfwd1IP], [redacted.xfwd2IP]
- ReqHeader X-Forwarded-For-Src: CloudFlare
- ReqHeader X-Real-IP: [redacted.xfwd1IP]
- ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
- ReqHeader X-Client: [redacted.xfwd2IP]
- VCL_acl NO_MATCH facebook
- ReqUnset X-Forwarded-Proto: http
- ReqHeader X-Forwarded-Proto: http
- ReqHeader X-Forwarded-HTTPS: off
- ReqHeader X-Port: 80
- ReqHeader X-Forwarded-Port: 80
- ReqHeader X-HTTPS: off
- VCL_acl NO_MATCH global_blacklist
- VCL_acl NO_MATCH tor_blacklist
- ReqHeader X-UA-Device: pc
- ReqUnset X-UA-Device: pc
- ReqHeader X-UA-Device: mobile-android
- ReqHeader X-My-Purge-Key: [redacted]
- ReqHeader X-Purge-Key-Auth: false
- ReqURL /[redacted.url]/
- VCL_Log COOKIESTRIP:/[redacted.url]/
- ReqUnset Cookie:
__cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
__PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
_ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C34%2C11%7C35
- ReqHeader allow_override: enabled
- ReqUnset Accept-Encoding: gzip
- ReqHeader Accept-Encoding: gzip
- ReqHeader Surrogate-Capability: key=ESI/1.0
- ReqUnset X-My-Purge-Key: [redacted]
- ReqHeader X-TTL: 14400.000
- ReqHeader X-Cacheable: YES:Dynamic cache, ttl: 14400.000
- ReqHeader X-Req-Type: Cache:Dynamic
- VCL_return hash
- VCL_call HASH
- ReqHeader hash: /[redacted.url]/
- ReqUnset hash: /[redacted.url]/
- ReqHeader hash: www.[redacted.domain.tld]#/[redacted.url]/
- ReqUnset hash: www.[redacted.domain.tld]#/[redacted.url]/
- ReqHeader hash:
http#mobile-android#www.[redacted.domain.tld]#/[redacted.url]/
- VCL_return lookup
- Hit 482125483
- VCL_call HIT
- VCL_Log OKHITDELIVER: obj.ttl:14065.370 obj.keep: 0.000
obj.grace: 21600.000
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Sat, 02 Sep 2017 20:02:30 GMT
- RespHeader x-frame-options: SAMEORIGIN
- RespHeader X-XSS-Protection: 1; mode=block
- RespHeader X-Content-Type-Options: nosniff
- RespHeader X-Pingback: http://www.[redacted.domain.tld]/xmlrpc.php
- RespHeader Link: <http://www.[redacted.domain.tld]/?p=2710>;
rel=shortlink
- RespHeader Content-Type: text/html; charset=UTF-8
- RespHeader X-Req-Type: Cache:Dynamic
- RespHeader Accept-Encoding: gzip
- RespHeader Vary: Accept-Encoding, X-UA-Device
- RespHeader X-UA-Device: mobile-android
- RespHeader X-Req-Host: www.[redacted.domain.tld]
- RespHeader X-Req-URL: /[redacted.url]/
- RespHeader X-Req-URL-Base: /[redacted.url]/
- RespHeader X-TTL: 14400.000
- RespHeader X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
- RespHeader X-Varnish: 482784125 482125483
- RespHeader Age: 334
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespHeader X-Cache: HIT
- VCL_Log OKHITDELIVERY: obj.hits: 1 ttl:14400.000
- RespUnset X-Req-Type: Cache:Dynamic
- RespUnset Age: 334
- RespUnset X-Cache: HIT
- RespUnset X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
- RespUnset X-TTL: 14400.000
- RespUnset X-Req-Host: www.[redacted.domain.tld]
- RespUnset X-Req-URL: /[redacted.url]/
- RespUnset X-Req-URL-Base: /[redacted.url]/
- RespUnset X-Varnish: 482784125 482125483
- RespUnset Via: 1.1 varnish-v4
- RespUnset X-UA-Device: mobile-android
- VCL_return deliver
- Timestamp Process: 1504382885.868905 0.000188 0.000188
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 63072
- Debug "RES_MODE 2"
- RespHeader Connection: close
- Debug "Hit idle send timeout, wrote = 55480/63504; retrying"
- Debug "Write error, retval = -1, len = 8024, errno = Broken
pipe"
- Timestamp Resp: 1504382886.049021 0.180304 0.180115
- ReqAcct 869 0 869 432 63072 63504
- End
Re: Hit idle send timeout [ In reply to ]
You client dropped the connection, not much you can do or worry about.

--
Guillaume Quintard

On Sat, Sep 2, 2017 at 10:15 PM, Andrei <lagged@gmail.com> wrote:

> Hello everyone,
>
> I'm running 4.1.8 as a frontend to a local Apache 2.4 and just recently
> ran into a burst of the following "idle/write errors" without any
> corresponding errors logged in Apache. Any suggestions on what to keep an
> eye on or further review would be greatly appreciated.
>
> * << Request >> 482784125
> - Begin req 482784124 rxreq
> - Timestamp Start: 1504382885.868717 0.000000 0.000000
> - Timestamp Req: 1504382885.868717 0.000000 0.000000
> - ReqStart [redacted.xfwd2IP] 35207
> - ReqMethod GET
> - ReqURL /[redacted.url]/
> - ReqProtocol HTTP/1.1
> - ReqHeader Host: www.[redacted.domain.tld]
> - ReqHeader User-Agent: Mozilla/5.0 (Linux; Android 7.0; SM-G920F
> Build/NRD90M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.116
> Mobile Safari/537.36
> - ReqHeader Accept: text/html,application/xhtml+
> xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
> - ReqHeader Accept-Language: ro-RO,ro;q=0.8,en-US;q=0.6,en;q=0.4
> - ReqHeader Cf-Connecting-Ip: [redacted.xfwd1IP]
> - ReqHeader Cf-Ipcountry: RO
> - ReqHeader Cf-Origin-Https: off
> - ReqHeader Cf-Ray: 3983196ce0b87ea0-BUD
> - ReqHeader Cf-Visitor: {"scheme":"http"}
> - ReqHeader Cookie: __cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
> __PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
> _ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C34%2C11%7C35
> - ReqHeader Referer: https://www.google.ro/
> - ReqHeader Upgrade-Insecure-Requests: 1
> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
> - ReqHeader X-Forwarded-Proto: http
> - ReqHeader Accept-Encoding: gzip
> - ReqHeader Connection: close
> - ReqUnset X-Forwarded-For: [redacted.xfwd1IP]
> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP], [redacted.xfwd2IP]
> - VCL_call RECV
> - VCL_acl MATCH cloudflare "172.64.0.0/13"
> - ReqHeader X-Country: RO
> - ReqHeader ignore_becache: 1
> - ReqUnset Host: www.[redacted.domain.tld]
> - ReqHeader Host: www.[redacted.domain.tld]
> - ReqUnset X-Forwarded-For: [redacted.xfwd1IP], [redacted.xfwd2IP]
> - ReqHeader X-Forwarded-For-Src: CloudFlare
> - ReqHeader X-Real-IP: [redacted.xfwd1IP]
> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
> - ReqHeader X-Client: [redacted.xfwd2IP]
> - VCL_acl NO_MATCH facebook
> - ReqUnset X-Forwarded-Proto: http
> - ReqHeader X-Forwarded-Proto: http
> - ReqHeader X-Forwarded-HTTPS: off
> - ReqHeader X-Port: 80
> - ReqHeader X-Forwarded-Port: 80
> - ReqHeader X-HTTPS: off
> - VCL_acl NO_MATCH global_blacklist
> - VCL_acl NO_MATCH tor_blacklist
> - ReqHeader X-UA-Device: pc
> - ReqUnset X-UA-Device: pc
> - ReqHeader X-UA-Device: mobile-android
> - ReqHeader X-My-Purge-Key: [redacted]
> - ReqHeader X-Purge-Key-Auth: false
> - ReqURL /[redacted.url]/
> - VCL_Log COOKIESTRIP:/[redacted.url]/
> - ReqUnset Cookie: __cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
> __PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
> _ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C34%2C11%7C35
> - ReqHeader allow_override: enabled
> - ReqUnset Accept-Encoding: gzip
> - ReqHeader Accept-Encoding: gzip
> - ReqHeader Surrogate-Capability: key=ESI/1.0
> - ReqUnset X-My-Purge-Key: [redacted]
> - ReqHeader X-TTL: 14400.000
> - ReqHeader X-Cacheable: YES:Dynamic cache, ttl: 14400.000
> - ReqHeader X-Req-Type: Cache:Dynamic
> - VCL_return hash
> - VCL_call HASH
> - ReqHeader hash: /[redacted.url]/
> - ReqUnset hash: /[redacted.url]/
> - ReqHeader hash: www.[redacted.domain.tld]#/[redacted.url]/
> - ReqUnset hash: www.[redacted.domain.tld]#/[redacted.url]/
> - ReqHeader hash: http#mobile-android#www.[redacted.domain.tld]#/[
> redacted.url]/
> - VCL_return lookup
> - Hit 482125483
> - VCL_call HIT
> - VCL_Log OKHITDELIVER: obj.ttl:14065.370 obj.keep: 0.000
> obj.grace: 21600.000
> - VCL_return deliver
> - RespProtocol HTTP/1.1
> - RespStatus 200
> - RespReason OK
> - RespHeader Date: Sat, 02 Sep 2017 20:02:30 GMT
> - RespHeader x-frame-options: SAMEORIGIN
> - RespHeader X-XSS-Protection: 1; mode=block
> - RespHeader X-Content-Type-Options: nosniff
> - RespHeader X-Pingback: http://www.[redacted.domain.tld]/xmlrpc.php
> - RespHeader Link: <http://www.[redacted.domain.tld]/?p=2710>;
> rel=shortlink
> - RespHeader Content-Type: text/html; charset=UTF-8
> - RespHeader X-Req-Type: Cache:Dynamic
> - RespHeader Accept-Encoding: gzip
> - RespHeader Vary: Accept-Encoding, X-UA-Device
> - RespHeader X-UA-Device: mobile-android
> - RespHeader X-Req-Host: www.[redacted.domain.tld]
> - RespHeader X-Req-URL: /[redacted.url]/
> - RespHeader X-Req-URL-Base: /[redacted.url]/
> - RespHeader X-TTL: 14400.000
> - RespHeader X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
> - RespHeader X-Varnish: 482784125 482125483
> - RespHeader Age: 334
> - RespHeader Via: 1.1 varnish-v4
> - VCL_call DELIVER
> - RespHeader X-Cache: HIT
> - VCL_Log OKHITDELIVERY: obj.hits: 1 ttl:14400.000
> - RespUnset X-Req-Type: Cache:Dynamic
> - RespUnset Age: 334
> - RespUnset X-Cache: HIT
> - RespUnset X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
> - RespUnset X-TTL: 14400.000
> - RespUnset X-Req-Host: www.[redacted.domain.tld]
> - RespUnset X-Req-URL: /[redacted.url]/
> - RespUnset X-Req-URL-Base: /[redacted.url]/
> - RespUnset X-Varnish: 482784125 482125483
> - RespUnset Via: 1.1 varnish-v4
> - RespUnset X-UA-Device: mobile-android
> - VCL_return deliver
> - Timestamp Process: 1504382885.868905 0.000188 0.000188
> - RespHeader Accept-Ranges: bytes
> - RespHeader Content-Length: 63072
> - Debug "RES_MODE 2"
> - RespHeader Connection: close
> - Debug "Hit idle send timeout, wrote = 55480/63504; retrying"
> - Debug "Write error, retval = -1, len = 8024, errno = Broken
> pipe"
> - Timestamp Resp: 1504382886.049021 0.180304 0.180115
> - ReqAcct 869 0 869 432 63072 63504
> - End
>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
Re: Hit idle send timeout [ In reply to ]
Hi Guillaume,

Thanks for the update! :)
Am I reading the log wrong, or is there a difference in Content-Length (
63072), and the debug data which to me suggests it's expecting to send
63504 and only got as far as 55480?

On Sun, Sep 24, 2017 at 11:36 AM, Guillaume Quintard <
guillaume@varnish-software.com> wrote:

> You client dropped the connection, not much you can do or worry about.
>
> --
> Guillaume Quintard
>
> On Sat, Sep 2, 2017 at 10:15 PM, Andrei <lagged@gmail.com> wrote:
>
>> Hello everyone,
>>
>> I'm running 4.1.8 as a frontend to a local Apache 2.4 and just recently
>> ran into a burst of the following "idle/write errors" without any
>> corresponding errors logged in Apache. Any suggestions on what to keep an
>> eye on or further review would be greatly appreciated.
>>
>> * << Request >> 482784125
>> - Begin req 482784124 rxreq
>> - Timestamp Start: 1504382885.868717 0.000000 0.000000
>> - Timestamp Req: 1504382885.868717 0.000000 0.000000
>> - ReqStart [redacted.xfwd2IP] 35207
>> - ReqMethod GET
>> - ReqURL /[redacted.url]/
>> - ReqProtocol HTTP/1.1
>> - ReqHeader Host: www.[redacted.domain.tld]
>> - ReqHeader User-Agent: Mozilla/5.0 (Linux; Android 7.0; SM-G920F
>> Build/NRD90M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.116
>> Mobile Safari/537.36
>> - ReqHeader Accept: text/html,application/xhtml+xm
>> l,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
>> - ReqHeader Accept-Language: ro-RO,ro;q=0.8,en-US;q=0.6,en;q=0.4
>> - ReqHeader Cf-Connecting-Ip: [redacted.xfwd1IP]
>> - ReqHeader Cf-Ipcountry: RO
>> - ReqHeader Cf-Origin-Https: off
>> - ReqHeader Cf-Ray: 3983196ce0b87ea0-BUD
>> - ReqHeader Cf-Visitor: {"scheme":"http"}
>> - ReqHeader Cookie: __cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
>> __PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
>> _ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C
>> 34%2C11%7C35
>> - ReqHeader Referer: https://www.google.ro/
>> - ReqHeader Upgrade-Insecure-Requests: 1
>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
>> - ReqHeader X-Forwarded-Proto: http
>> - ReqHeader Accept-Encoding: gzip
>> - ReqHeader Connection: close
>> - ReqUnset X-Forwarded-For: [redacted.xfwd1IP]
>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP], [redacted.xfwd2IP]
>> - VCL_call RECV
>> - VCL_acl MATCH cloudflare "172.64.0.0/13"
>> - ReqHeader X-Country: RO
>> - ReqHeader ignore_becache: 1
>> - ReqUnset Host: www.[redacted.domain.tld]
>> - ReqHeader Host: www.[redacted.domain.tld]
>> - ReqUnset X-Forwarded-For: [redacted.xfwd1IP], [redacted.xfwd2IP]
>> - ReqHeader X-Forwarded-For-Src: CloudFlare
>> - ReqHeader X-Real-IP: [redacted.xfwd1IP]
>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
>> - ReqHeader X-Client: [redacted.xfwd2IP]
>> - VCL_acl NO_MATCH facebook
>> - ReqUnset X-Forwarded-Proto: http
>> - ReqHeader X-Forwarded-Proto: http
>> - ReqHeader X-Forwarded-HTTPS: off
>> - ReqHeader X-Port: 80
>> - ReqHeader X-Forwarded-Port: 80
>> - ReqHeader X-HTTPS: off
>> - VCL_acl NO_MATCH global_blacklist
>> - VCL_acl NO_MATCH tor_blacklist
>> - ReqHeader X-UA-Device: pc
>> - ReqUnset X-UA-Device: pc
>> - ReqHeader X-UA-Device: mobile-android
>> - ReqHeader X-My-Purge-Key: [redacted]
>> - ReqHeader X-Purge-Key-Auth: false
>> - ReqURL /[redacted.url]/
>> - VCL_Log COOKIESTRIP:/[redacted.url]/
>> - ReqUnset Cookie: __cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
>> __PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
>> _ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C
>> 34%2C11%7C35
>> - ReqHeader allow_override: enabled
>> - ReqUnset Accept-Encoding: gzip
>> - ReqHeader Accept-Encoding: gzip
>> - ReqHeader Surrogate-Capability: key=ESI/1.0
>> - ReqUnset X-My-Purge-Key: [redacted]
>> - ReqHeader X-TTL: 14400.000
>> - ReqHeader X-Cacheable: YES:Dynamic cache, ttl: 14400.000
>> - ReqHeader X-Req-Type: Cache:Dynamic
>> - VCL_return hash
>> - VCL_call HASH
>> - ReqHeader hash: /[redacted.url]/
>> - ReqUnset hash: /[redacted.url]/
>> - ReqHeader hash: www.[redacted.domain.tld]#/[redacted.url]/
>> - ReqUnset hash: www.[redacted.domain.tld]#/[redacted.url]/
>> - ReqHeader hash: http#mobile-android#www.[redac
>> ted.domain.tld]#/[redacted.url]/
>> - VCL_return lookup
>> - Hit 482125483
>> - VCL_call HIT
>> - VCL_Log OKHITDELIVER: obj.ttl:14065.370 obj.keep: 0.000
>> obj.grace: 21600.000
>> - VCL_return deliver
>> - RespProtocol HTTP/1.1
>> - RespStatus 200
>> - RespReason OK
>> - RespHeader Date: Sat, 02 Sep 2017 20:02:30 GMT
>> - RespHeader x-frame-options: SAMEORIGIN
>> - RespHeader X-XSS-Protection: 1; mode=block
>> - RespHeader X-Content-Type-Options: nosniff
>> - RespHeader X-Pingback: http://www.[redacted.domain.tl
>> d]/xmlrpc.php
>> - RespHeader Link: <http://www.[redacted.domain.tld]/?p=2710>;
>> rel=shortlink
>> - RespHeader Content-Type: text/html; charset=UTF-8
>> - RespHeader X-Req-Type: Cache:Dynamic
>> - RespHeader Accept-Encoding: gzip
>> - RespHeader Vary: Accept-Encoding, X-UA-Device
>> - RespHeader X-UA-Device: mobile-android
>> - RespHeader X-Req-Host: www.[redacted.domain.tld]
>> - RespHeader X-Req-URL: /[redacted.url]/
>> - RespHeader X-Req-URL-Base: /[redacted.url]/
>> - RespHeader X-TTL: 14400.000
>> - RespHeader X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
>> - RespHeader X-Varnish: 482784125 482125483
>> - RespHeader Age: 334
>> - RespHeader Via: 1.1 varnish-v4
>> - VCL_call DELIVER
>> - RespHeader X-Cache: HIT
>> - VCL_Log OKHITDELIVERY: obj.hits: 1 ttl:14400.000
>> - RespUnset X-Req-Type: Cache:Dynamic
>> - RespUnset Age: 334
>> - RespUnset X-Cache: HIT
>> - RespUnset X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
>> - RespUnset X-TTL: 14400.000
>> - RespUnset X-Req-Host: www.[redacted.domain.tld]
>> - RespUnset X-Req-URL: /[redacted.url]/
>> - RespUnset X-Req-URL-Base: /[redacted.url]/
>> - RespUnset X-Varnish: 482784125 482125483
>> - RespUnset Via: 1.1 varnish-v4
>> - RespUnset X-UA-Device: mobile-android
>> - VCL_return deliver
>> - Timestamp Process: 1504382885.868905 0.000188 0.000188
>> - RespHeader Accept-Ranges: bytes
>> - RespHeader Content-Length: 63072
>> - Debug "RES_MODE 2"
>> - RespHeader Connection: close
>> - Debug "Hit idle send timeout, wrote = 55480/63504; retrying"
>> - Debug "Write error, retval = -1, len = 8024, errno = Broken
>> pipe"
>> - Timestamp Resp: 1504382886.049021 0.180304 0.180115
>> - ReqAcct 869 0 869 432 63072 63504
>> - End
>>
>>
>> _______________________________________________
>> varnish-misc mailing list
>> varnish-misc@varnish-cache.org
>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>
>
>
Re: Hit idle send timeout [ In reply to ]
63504 is the total size (headers+body), and 55480 is what could be pushed
to the kernel. You don't really know if it was really sent (or received,
for that matter).

--
Guillaume Quintard

On Sep 25, 2017 07:29, "Andrei" <lagged@gmail.com> wrote:

Hi Guillaume,

Thanks for the update! :)
Am I reading the log wrong, or is there a difference in Content-Length (
63072), and the debug data which to me suggests it's expecting to send
63504 and only got as far as 55480?

On Sun, Sep 24, 2017 at 11:36 AM, Guillaume Quintard <
guillaume@varnish-software.com> wrote:

> You client dropped the connection, not much you can do or worry about.
>
> --
> Guillaume Quintard
>
> On Sat, Sep 2, 2017 at 10:15 PM, Andrei <lagged@gmail.com> wrote:
>
>> Hello everyone,
>>
>> I'm running 4.1.8 as a frontend to a local Apache 2.4 and just recently
>> ran into a burst of the following "idle/write errors" without any
>> corresponding errors logged in Apache. Any suggestions on what to keep an
>> eye on or further review would be greatly appreciated.
>>
>> * << Request >> 482784125
>> - Begin req 482784124 rxreq
>> - Timestamp Start: 1504382885.868717 0.000000 0.000000
>> - Timestamp Req: 1504382885.868717 0.000000 0.000000
>> - ReqStart [redacted.xfwd2IP] 35207
>> - ReqMethod GET
>> - ReqURL /[redacted.url]/
>> - ReqProtocol HTTP/1.1
>> - ReqHeader Host: www.[redacted.domain.tld]
>> - ReqHeader User-Agent: Mozilla/5.0 (Linux; Android 7.0; SM-G920F
>> Build/NRD90M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.116
>> Mobile Safari/537.36
>> - ReqHeader Accept: text/html,application/xhtml+xm
>> l,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
>> - ReqHeader Accept-Language: ro-RO,ro;q=0.8,en-US;q=0.6,en;q=0.4
>> - ReqHeader Cf-Connecting-Ip: [redacted.xfwd1IP]
>> - ReqHeader Cf-Ipcountry: RO
>> - ReqHeader Cf-Origin-Https: off
>> - ReqHeader Cf-Ray: 3983196ce0b87ea0-BUD
>> - ReqHeader Cf-Visitor: {"scheme":"http"}
>> - ReqHeader Cookie: __cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
>> __PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
>> _ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C
>> 34%2C11%7C35
>> - ReqHeader Referer: https://www.google.ro/
>> - ReqHeader Upgrade-Insecure-Requests: 1
>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
>> - ReqHeader X-Forwarded-Proto: http
>> - ReqHeader Accept-Encoding: gzip
>> - ReqHeader Connection: close
>> - ReqUnset X-Forwarded-For: [redacted.xfwd1IP]
>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP], [redacted.xfwd2IP]
>> - VCL_call RECV
>> - VCL_acl MATCH cloudflare "172.64.0.0/13"
>> - ReqHeader X-Country: RO
>> - ReqHeader ignore_becache: 1
>> - ReqUnset Host: www.[redacted.domain.tld]
>> - ReqHeader Host: www.[redacted.domain.tld]
>> - ReqUnset X-Forwarded-For: [redacted.xfwd1IP], [redacted.xfwd2IP]
>> - ReqHeader X-Forwarded-For-Src: CloudFlare
>> - ReqHeader X-Real-IP: [redacted.xfwd1IP]
>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
>> - ReqHeader X-Client: [redacted.xfwd2IP]
>> - VCL_acl NO_MATCH facebook
>> - ReqUnset X-Forwarded-Proto: http
>> - ReqHeader X-Forwarded-Proto: http
>> - ReqHeader X-Forwarded-HTTPS: off
>> - ReqHeader X-Port: 80
>> - ReqHeader X-Forwarded-Port: 80
>> - ReqHeader X-HTTPS: off
>> - VCL_acl NO_MATCH global_blacklist
>> - VCL_acl NO_MATCH tor_blacklist
>> - ReqHeader X-UA-Device: pc
>> - ReqUnset X-UA-Device: pc
>> - ReqHeader X-UA-Device: mobile-android
>> - ReqHeader X-My-Purge-Key: [redacted]
>> - ReqHeader X-Purge-Key-Auth: false
>> - ReqURL /[redacted.url]/
>> - VCL_Log COOKIESTRIP:/[redacted.url]/
>> - ReqUnset Cookie: __cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
>> __PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
>> _ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C
>> 34%2C11%7C35
>> - ReqHeader allow_override: enabled
>> - ReqUnset Accept-Encoding: gzip
>> - ReqHeader Accept-Encoding: gzip
>> - ReqHeader Surrogate-Capability: key=ESI/1.0
>> - ReqUnset X-My-Purge-Key: [redacted]
>> - ReqHeader X-TTL: 14400.000
>> - ReqHeader X-Cacheable: YES:Dynamic cache, ttl: 14400.000
>> - ReqHeader X-Req-Type: Cache:Dynamic
>> - VCL_return hash
>> - VCL_call HASH
>> - ReqHeader hash: /[redacted.url]/
>> - ReqUnset hash: /[redacted.url]/
>> - ReqHeader hash: www.[redacted.domain.tld]#/[redacted.url]/
>> - ReqUnset hash: www.[redacted.domain.tld]#/[redacted.url]/
>> - ReqHeader hash: http#mobile-android#www.[redac
>> ted.domain.tld]#/[redacted.url]/
>> - VCL_return lookup
>> - Hit 482125483
>> - VCL_call HIT
>> - VCL_Log OKHITDELIVER: obj.ttl:14065.370 obj.keep: 0.000
>> obj.grace: 21600.000
>> - VCL_return deliver
>> - RespProtocol HTTP/1.1
>> - RespStatus 200
>> - RespReason OK
>> - RespHeader Date: Sat, 02 Sep 2017 20:02:30 GMT
>> - RespHeader x-frame-options: SAMEORIGIN
>> - RespHeader X-XSS-Protection: 1; mode=block
>> - RespHeader X-Content-Type-Options: nosniff
>> - RespHeader X-Pingback: http://www.[redacted.domain.tl
>> d]/xmlrpc.php
>> - RespHeader Link: <http://www.[redacted.domain.tld]/?p=2710>;
>> rel=shortlink
>> - RespHeader Content-Type: text/html; charset=UTF-8
>> - RespHeader X-Req-Type: Cache:Dynamic
>> - RespHeader Accept-Encoding: gzip
>> - RespHeader Vary: Accept-Encoding, X-UA-Device
>> - RespHeader X-UA-Device: mobile-android
>> - RespHeader X-Req-Host: www.[redacted.domain.tld]
>> - RespHeader X-Req-URL: /[redacted.url]/
>> - RespHeader X-Req-URL-Base: /[redacted.url]/
>> - RespHeader X-TTL: 14400.000
>> - RespHeader X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
>> - RespHeader X-Varnish: 482784125 482125483
>> - RespHeader Age: 334
>> - RespHeader Via: 1.1 varnish-v4
>> - VCL_call DELIVER
>> - RespHeader X-Cache: HIT
>> - VCL_Log OKHITDELIVERY: obj.hits: 1 ttl:14400.000
>> - RespUnset X-Req-Type: Cache:Dynamic
>> - RespUnset Age: 334
>> - RespUnset X-Cache: HIT
>> - RespUnset X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
>> - RespUnset X-TTL: 14400.000
>> - RespUnset X-Req-Host: www.[redacted.domain.tld]
>> - RespUnset X-Req-URL: /[redacted.url]/
>> - RespUnset X-Req-URL-Base: /[redacted.url]/
>> - RespUnset X-Varnish: 482784125 482125483
>> - RespUnset Via: 1.1 varnish-v4
>> - RespUnset X-UA-Device: mobile-android
>> - VCL_return deliver
>> - Timestamp Process: 1504382885.868905 0.000188 0.000188
>> - RespHeader Accept-Ranges: bytes
>> - RespHeader Content-Length: 63072
>> - Debug "RES_MODE 2"
>> - RespHeader Connection: close
>> - Debug "Hit idle send timeout, wrote = 55480/63504; retrying"
>> - Debug "Write error, retval = -1, len = 8024, errno = Broken
>> pipe"
>> - Timestamp Resp: 1504382886.049021 0.180304 0.180115
>> - ReqAcct 869 0 869 432 63072 63504
>> - End
>>
>>
>> _______________________________________________
>> varnish-misc mailing list
>> varnish-misc@varnish-cache.org
>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>
>
>
Re: Hit idle send timeout [ In reply to ]
Gotcha, thanks for the clarification!

On Mon, Sep 25, 2017 at 10:21 AM, Guillaume Quintard <
guillaume@varnish-software.com> wrote:

> 63504 is the total size (headers+body), and 55480 is what could be pushed
> to the kernel. You don't really know if it was really sent (or received,
> for that matter).
>
> --
> Guillaume Quintard
>
> On Sep 25, 2017 07:29, "Andrei" <lagged@gmail.com> wrote:
>
> Hi Guillaume,
>
> Thanks for the update! :)
> Am I reading the log wrong, or is there a difference in Content-Length (
> 63072), and the debug data which to me suggests it's expecting to send
> 63504 and only got as far as 55480?
>
> On Sun, Sep 24, 2017 at 11:36 AM, Guillaume Quintard <
> guillaume@varnish-software.com> wrote:
>
>> You client dropped the connection, not much you can do or worry about.
>>
>> --
>> Guillaume Quintard
>>
>> On Sat, Sep 2, 2017 at 10:15 PM, Andrei <lagged@gmail.com> wrote:
>>
>>> Hello everyone,
>>>
>>> I'm running 4.1.8 as a frontend to a local Apache 2.4 and just recently
>>> ran into a burst of the following "idle/write errors" without any
>>> corresponding errors logged in Apache. Any suggestions on what to keep an
>>> eye on or further review would be greatly appreciated.
>>>
>>> * << Request >> 482784125
>>> - Begin req 482784124 rxreq
>>> - Timestamp Start: 1504382885.868717 0.000000 0.000000
>>> - Timestamp Req: 1504382885.868717 0.000000 0.000000
>>> - ReqStart [redacted.xfwd2IP] 35207
>>> - ReqMethod GET
>>> - ReqURL /[redacted.url]/
>>> - ReqProtocol HTTP/1.1
>>> - ReqHeader Host: www.[redacted.domain.tld]
>>> - ReqHeader User-Agent: Mozilla/5.0 (Linux; Android 7.0; SM-G920F
>>> Build/NRD90M) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.116
>>> Mobile Safari/537.36
>>> - ReqHeader Accept: text/html,application/xhtml+xm
>>> l,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
>>> - ReqHeader Accept-Language: ro-RO,ro;q=0.8,en-US;q=0.6,en;q=0.4
>>> - ReqHeader Cf-Connecting-Ip: [redacted.xfwd1IP]
>>> - ReqHeader Cf-Ipcountry: RO
>>> - ReqHeader Cf-Origin-Https: off
>>> - ReqHeader Cf-Ray: 3983196ce0b87ea0-BUD
>>> - ReqHeader Cf-Visitor: {"scheme":"http"}
>>> - ReqHeader Cookie: __cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
>>> __PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
>>> _ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C
>>> 34%2C11%7C35
>>> - ReqHeader Referer: https://www.google.ro/
>>> - ReqHeader Upgrade-Insecure-Requests: 1
>>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
>>> - ReqHeader X-Forwarded-Proto: http
>>> - ReqHeader Accept-Encoding: gzip
>>> - ReqHeader Connection: close
>>> - ReqUnset X-Forwarded-For: [redacted.xfwd1IP]
>>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP],
>>> [redacted.xfwd2IP]
>>> - VCL_call RECV
>>> - VCL_acl MATCH cloudflare "172.64.0.0/13"
>>> - ReqHeader X-Country: RO
>>> - ReqHeader ignore_becache: 1
>>> - ReqUnset Host: www.[redacted.domain.tld]
>>> - ReqHeader Host: www.[redacted.domain.tld]
>>> - ReqUnset X-Forwarded-For: [redacted.xfwd1IP],
>>> [redacted.xfwd2IP]
>>> - ReqHeader X-Forwarded-For-Src: CloudFlare
>>> - ReqHeader X-Real-IP: [redacted.xfwd1IP]
>>> - ReqHeader X-Forwarded-For: [redacted.xfwd1IP]
>>> - ReqHeader X-Client: [redacted.xfwd2IP]
>>> - VCL_acl NO_MATCH facebook
>>> - ReqUnset X-Forwarded-Proto: http
>>> - ReqHeader X-Forwarded-Proto: http
>>> - ReqHeader X-Forwarded-HTTPS: off
>>> - ReqHeader X-Port: 80
>>> - ReqHeader X-Forwarded-Port: 80
>>> - ReqHeader X-HTTPS: off
>>> - VCL_acl NO_MATCH global_blacklist
>>> - VCL_acl NO_MATCH tor_blacklist
>>> - ReqHeader X-UA-Device: pc
>>> - ReqUnset X-UA-Device: pc
>>> - ReqHeader X-UA-Device: mobile-android
>>> - ReqHeader X-My-Purge-Key: [redacted]
>>> - ReqHeader X-Purge-Key-Auth: false
>>> - ReqURL /[redacted.url]/
>>> - VCL_Log COOKIESTRIP:/[redacted.url]/
>>> - ReqUnset Cookie: __cfduid=da15bbd5734efa927910bae7091f5c3c81501871885;
>>> __PPU_SESSION_1_1335313_false=1504207577718|3|1504207684422|3|1;
>>> _ga=GA1.2.606320764.1502399957; __atuvc=2%7C32%2C0%7C33%2C4%7C
>>> 34%2C11%7C35
>>> - ReqHeader allow_override: enabled
>>> - ReqUnset Accept-Encoding: gzip
>>> - ReqHeader Accept-Encoding: gzip
>>> - ReqHeader Surrogate-Capability: key=ESI/1.0
>>> - ReqUnset X-My-Purge-Key: [redacted]
>>> - ReqHeader X-TTL: 14400.000
>>> - ReqHeader X-Cacheable: YES:Dynamic cache, ttl: 14400.000
>>> - ReqHeader X-Req-Type: Cache:Dynamic
>>> - VCL_return hash
>>> - VCL_call HASH
>>> - ReqHeader hash: /[redacted.url]/
>>> - ReqUnset hash: /[redacted.url]/
>>> - ReqHeader hash: www.[redacted.domain.tld]#/[redacted.url]/
>>> - ReqUnset hash: www.[redacted.domain.tld]#/[redacted.url]/
>>> - ReqHeader hash: http#mobile-android#www.[redac
>>> ted.domain.tld]#/[redacted.url]/
>>> - VCL_return lookup
>>> - Hit 482125483
>>> - VCL_call HIT
>>> - VCL_Log OKHITDELIVER: obj.ttl:14065.370 obj.keep: 0.000
>>> obj.grace: 21600.000
>>> - VCL_return deliver
>>> - RespProtocol HTTP/1.1
>>> - RespStatus 200
>>> - RespReason OK
>>> - RespHeader Date: Sat, 02 Sep 2017 20:02:30 GMT
>>> - RespHeader x-frame-options: SAMEORIGIN
>>> - RespHeader X-XSS-Protection: 1; mode=block
>>> - RespHeader X-Content-Type-Options: nosniff
>>> - RespHeader X-Pingback: http://www.[redacted.domain.tl
>>> d]/xmlrpc.php
>>> - RespHeader Link: <http://www.[redacted.domain.tld]/?p=2710>;
>>> rel=shortlink
>>> - RespHeader Content-Type: text/html; charset=UTF-8
>>> - RespHeader X-Req-Type: Cache:Dynamic
>>> - RespHeader Accept-Encoding: gzip
>>> - RespHeader Vary: Accept-Encoding, X-UA-Device
>>> - RespHeader X-UA-Device: mobile-android
>>> - RespHeader X-Req-Host: www.[redacted.domain.tld]
>>> - RespHeader X-Req-URL: /[redacted.url]/
>>> - RespHeader X-Req-URL-Base: /[redacted.url]/
>>> - RespHeader X-TTL: 14400.000
>>> - RespHeader X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
>>> - RespHeader X-Varnish: 482784125 482125483
>>> - RespHeader Age: 334
>>> - RespHeader Via: 1.1 varnish-v4
>>> - VCL_call DELIVER
>>> - RespHeader X-Cache: HIT
>>> - VCL_Log OKHITDELIVERY: obj.hits: 1 ttl:14400.000
>>> - RespUnset X-Req-Type: Cache:Dynamic
>>> - RespUnset Age: 334
>>> - RespUnset X-Cache: HIT
>>> - RespUnset X-Cacheable: YES:Cacheable dynamic, ttl: 14400.000
>>> - RespUnset X-TTL: 14400.000
>>> - RespUnset X-Req-Host: www.[redacted.domain.tld]
>>> - RespUnset X-Req-URL: /[redacted.url]/
>>> - RespUnset X-Req-URL-Base: /[redacted.url]/
>>> - RespUnset X-Varnish: 482784125 482125483
>>> - RespUnset Via: 1.1 varnish-v4
>>> - RespUnset X-UA-Device: mobile-android
>>> - VCL_return deliver
>>> - Timestamp Process: 1504382885.868905 0.000188 0.000188
>>> - RespHeader Accept-Ranges: bytes
>>> - RespHeader Content-Length: 63072
>>> - Debug "RES_MODE 2"
>>> - RespHeader Connection: close
>>> - Debug "Hit idle send timeout, wrote = 55480/63504; retrying"
>>> - Debug "Write error, retval = -1, len = 8024, errno = Broken
>>> pipe"
>>> - Timestamp Resp: 1504382886.049021 0.180304 0.180115
>>> - ReqAcct 869 0 869 432 63072 63504
>>> - End
>>>
>>>
>>> _______________________________________________
>>> varnish-misc mailing list
>>> varnish-misc@varnish-cache.org
>>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>>
>>
>>
>
>