Mailing List Archive: Locating connection reset issue / h2 vs http/1.1

Locating connection reset issue / h2 vs http/1.1

Jan 31, 2019, 6:21 AM

Post #1 of 4 (651 views)

Hi all,

I have following stack: hitch-1.5 - varnish-5.2.0 - httpd-2.2/2.4

On a high traffic node I am observing a lot of "Socket error: Connection reset by peer" log entries coming from hitch.

I am trying to locate the cause of the issue (hitch or varnish site).

So far I can say; that disabling h2 on hitch the "Connection resets" doesn't appear anymore.

Does this have to do with varnish-5.2.'s h2 implementation?

Thanks
Leon

Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 proxy connect
Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl handshake start
Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl client handshake revents=1
Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl client handshake err=SSL_ERROR_WANT_READ
Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl client handshake revents=1
Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 NPN/ALPN protocol: h2
Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl end handshake
Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11 backend connected
Jan 30 19:02:39 srv-s01 hitch[4006]: {backend} Socket error: Connection reset by peer
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11 proxy shutdown req=SHUTDOWN_CLEAR
Jan 30 19:02:39 srv-s01 hitch[4006]: {backend} Socket error: Broken pipe
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11 proxy shutdown req=SHUTDOWN_CLEAR
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 proxy connect
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl handshake start
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl client handshake revents=1
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl client handshake err=SSL_ERROR_WANT_READ
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl client handshake revents=1
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 NPN/ALPN protocol: h2
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl end handshake
Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :42922 10:11 backend connected
Jan 30 19:02:40 srv-s01 hitch[4006]: {backend} Socket error: Connection reset by peer
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :42922 10:11 proxy shutdown req=SHUTDOWN_CLEAR
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :42922 10:11 proxy shutdown req=SHUTDOWN_HARD
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 proxy connect
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl handshake start
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl client handshake revents=1
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl client handshake err=SSL_ERROR_WANT_READ
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl client handshake revents=1
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 NPN/ALPN protocol: h2
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl end handshake
Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :42924 10:11 backend connected
Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 proxy connect
Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl handshake start
Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl client handshake revents=1
Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl client handshake err=SSL_ERROR_WANT_READ
Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl client handshake revents=1
Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 NPN/ALPN protocol: h2
Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl end handshake
Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :42926 12:13 backend connected
Jan 30 19:03:54 srv-s01 hitch[4006]: {backend} Socket error: Connection reset by peer
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :42924 10:11 proxy shutdown req=SHUTDOWN_CLEAR
Jan 30 19:03:54 srv-s01 hitch[4006]: {backend} Socket error: Broken pipe
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :42924 10:11 proxy shutdown req=SHUTDOWN_CLEAR
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 proxy connect
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl handshake start
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl client handshake revents=1
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl client handshake err=SSL_ERROR_WANT_READ
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl client handshake revents=1
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 NPN/ALPN protocol: h2
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl end handshake
Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :42970 10:11 backend connected

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Re: Locating connection reset issue / h2 vs http/1.1 [ In reply to ]

guillaume at varnish-software

Jan 31, 2019, 8:38 AM

Post #2 of 4 (650 views)

Permalink

Hi,

Have you activated h2 support in Varnish? (it's not on by default)

Cheers,

--
Guillaume Quintard

On Thu, Jan 31, 2019 at 6:22 AM <info+varnish@shee.org> wrote:

> Hi all,
>
> I have following stack: hitch-1.5 - varnish-5.2.0 - httpd-2.2/2.4
>
> On a high traffic node I am observing a lot of "Socket error: Connection
> reset by peer" log entries coming from hitch.
>
> I am trying to locate the cause of the issue (hitch or varnish site).
>
> So far I can say; that disabling h2 on hitch the "Connection resets"
> doesn't appear anymore.
>
> Does this have to do with varnish-5.2.'s h2 implementation?
>
> Thanks
> Leon
>
>
> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 proxy
> connect
> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl
> handshake start
> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl client
> handshake revents=1
> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl client
> handshake err=SSL_ERROR_WANT_READ
> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl client
> handshake revents=1
> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 NPN/ALPN
> protocol: h2
> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl end
> handshake
> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11
> backend connected
> Jan 30 19:02:39 srv-s01 hitch[4006]: {backend} Socket error: Connection
> reset by peer
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11 proxy
> shutdown req=SHUTDOWN_CLEAR
> Jan 30 19:02:39 srv-s01 hitch[4006]: {backend} Socket error: Broken pipe
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11 proxy
> shutdown req=SHUTDOWN_CLEAR
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 proxy
> connect
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl
> handshake start
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl client
> handshake revents=1
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl client
> handshake err=SSL_ERROR_WANT_READ
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl client
> handshake revents=1
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 NPN/ALPN
> protocol: h2
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 ssl end
> handshake
> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :42922 10:11
> backend connected
> Jan 30 19:02:40 srv-s01 hitch[4006]: {backend} Socket error: Connection
> reset by peer
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :42922 10:11 proxy
> shutdown req=SHUTDOWN_CLEAR
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :42922 10:11 proxy
> shutdown req=SHUTDOWN_HARD
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 proxy
> connect
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl
> handshake start
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl client
> handshake revents=1
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl client
> handshake err=SSL_ERROR_WANT_READ
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl client
> handshake revents=1
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 NPN/ALPN
> protocol: h2
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :0 10:11 ssl end
> handshake
> Jan 30 19:02:40 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :42924 10:11
> backend connected
> Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 proxy
> connect
> Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl
> handshake start
> Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl client
> handshake revents=1
> Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl client
> handshake err=SSL_ERROR_WANT_READ
> Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl client
> handshake revents=1
> Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 NPN/ALPN
> protocol: h2
> Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :0 12:13 ssl end
> handshake
> Jan 30 19:03:41 srv-s01 hitch[4006]: ww.xx.yy.zz:59418 :42926 12:13
> backend connected
> Jan 30 19:03:54 srv-s01 hitch[4006]: {backend} Socket error: Connection
> reset by peer
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :42924 10:11 proxy
> shutdown req=SHUTDOWN_CLEAR
> Jan 30 19:03:54 srv-s01 hitch[4006]: {backend} Socket error: Broken pipe
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59413 :42924 10:11 proxy
> shutdown req=SHUTDOWN_CLEAR
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 proxy
> connect
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl
> handshake start
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl client
> handshake revents=1
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl client
> handshake err=SSL_ERROR_WANT_READ
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl client
> handshake revents=1
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 NPN/ALPN
> protocol: h2
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :0 10:11 ssl end
> handshake
> Jan 30 19:03:54 srv-s01 hitch[4006]: ww.xx.yy.zz:59478 :42970 10:11
> backend connected
>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>

Re: Locating connection reset issue / h2 vs http/1.1 [ In reply to ]

info+varnish at shee

Jan 31, 2019, 9:45 AM

Post #3 of 4 (650 views)

Permalink

Am 31.01.2019 um 17:38 schrieb Guillaume Quintard <guillaume@varnish-software.com>:
>
> On Thu, Jan 31, 2019 at 6:22 AM <info+varnish@shee.org> wrote:
>>
>> I have following stack: hitch-1.5 - varnish-5.2.0 - httpd-2.2/2.4
>>
>> On a high traffic node I am observing a lot of "Socket error: Connection reset by peer" log entries coming from hitch.
>>
>> I am trying to locate the cause of the issue (hitch or varnish site).
>>
>> So far I can say; that disabling h2 on hitch the "Connection resets" doesn't appear anymore.
>>
>> Does this have to do with varnish-5.2.'s h2 implementation?
>>
>> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 NPN/ALPN protocol: h2
>> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl end handshake
>> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11 backend connected
>> Jan 30 19:02:39 srv-s01 hitch[4006]: {backend} Socket error: Connection reset by peer
>> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11 proxy shutdown req=SHUTDOWN_CLEAR
>> Jan 30 19:02:39 srv-s01 hitch[4006]: {backend} Socket error: Broken pipe
>> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11 proxy shutdown req=SHUTDOWN_CLEAR
>> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 proxy connect
>
> Have you activated h2 support in Varnish? (it's not on by default)
>

Sure, DAEMON_OPTS has -p feature=+http2 passed. The content is delivered via h2 (verified in browsers)
but sometimes lot of assets (client view) produce ERR_CONNECTION_CLOSED errors in the browser and on
server site the mentioned "connection reset by peer" log entries appears ...

--
Leon
_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Re: Locating connection reset issue / h2 vs http/1.1 [ In reply to ]

guillaume at varnish-software

Feb 1, 2019, 10:56 AM

Post #4 of 4 (647 views)

Permalink

Are you able to find some logs in varnishlog (-g session, filtering by
port) to see what varnish is doing?

--
Guillaume Quintard

On Thu, Jan 31, 2019 at 9:45 AM <info+varnish@shee.org> wrote:

> Am 31.01.2019 um 17:38 schrieb Guillaume Quintard <
> guillaume@varnish-software.com>:
> >
> > On Thu, Jan 31, 2019 at 6:22 AM <info+varnish@shee.org> wrote:
> >>
> >> I have following stack: hitch-1.5 - varnish-5.2.0 - httpd-2.2/2.4
> >>
> >> On a high traffic node I am observing a lot of "Socket error:
> Connection reset by peer" log entries coming from hitch.
> >>
> >> I am trying to locate the cause of the issue (hitch or varnish site).
> >>
> >> So far I can say; that disabling h2 on hitch the "Connection resets"
> doesn't appear anymore.
> >>
> >> Does this have to do with varnish-5.2.'s h2 implementation?
> >>
> >> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11
> NPN/ALPN protocol: h2
> >> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :0 10:11 ssl end
> handshake
> >> Jan 30 19:02:37 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11
> backend connected
> >> Jan 30 19:02:39 srv-s01 hitch[4006]: {backend} Socket error: Connection
> reset by peer
> >> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11
> proxy shutdown req=SHUTDOWN_CLEAR
> >> Jan 30 19:02:39 srv-s01 hitch[4006]: {backend} Socket error: Broken pipe
> >> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59395 :42884 10:11
> proxy shutdown req=SHUTDOWN_CLEAR
> >> Jan 30 19:02:39 srv-s01 hitch[4006]: ww.xx.yy.zz:59399 :0 10:11 proxy
> connect
> >
> > Have you activated h2 support in Varnish? (it's not on by default)
> >
>
> Sure, DAEMON_OPTS has -p feature=+http2 passed. The content is delivered
> via h2 (verified in browsers)
> but sometimes lot of assets (client view) produce ERR_CONNECTION_CLOSED
> errors in the browser and on
> server site the mentioned "connection reset by peer" log entries appears
> ...
>
> --
> Leon