Getting random "http first read error: EOF" errors in varnish

Question

I'm seeing the following 503 error in varnish from time to time in the logs:

*   << BeReq    >> 213585014 
-   Begin          bereq 213585013 fetch
-   Timestamp      Start: 1452675822.032332 0.000000 0.000000
-   BereqMethod    GET
-   BereqURL       /client/hedge-funds-asset-managers/
-   BereqProtocol  HTTP/1.1
-   BereqHeader    X-Real-IP: 123.125.71.28
-   BereqHeader    Host: XXXXXXXXXXXXXXXXXXX
-   BereqHeader    X-Forwarded-Proto: http
-   BereqHeader    User-Agent: Mozilla/5.0 (compatible; Baiduspider/2.0; +http://www.baidu.com/search/spider.html)
-   BereqHeader    Accept-Encoding: gzip
-   BereqHeader    Accept-Language: zh-cn,zh-tw
-   BereqHeader    Accept: */*
-   BereqHeader    X-Forwarded-For: 172.18.210.22
-   BereqHeader    X-Varnish: 213585014
-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendOpen    232 reload_2016-01-12T07:28:50.cp_12 162.251.80.23 80 172.18.210.71 40019
-   Timestamp      Bereq: 1452675822.047840 0.015508 0.015508
-   FetchError     http first read error: EOF
-   BackendClose   232 reload_2016-01-12T07:28:50.cp_12
-   Timestamp      Beresp: 1452675876.038544 54.006212 53.990704
-   Timestamp      Error: 1452675876.038555 54.006223 0.000010
-   BerespProtocol HTTP/1.1
-   BerespStatus   503
-   BerespReason   Service Unavailable
-   BerespReason   Backend fetch failed
-   BerespHeader   Date: Wed, 13 Jan 2016 09:04:36 GMT
-   BerespHeader   Server: Varnish
-   VCL_call       BACKEND_ERROR
-   BerespHeader   Content-Type: text/html; charset=utf-8
-   BerespHeader   Retry-After: 5
-   VCL_return     deliver
-   Storage        malloc Transient
-   ObjProtocol    HTTP/1.1
-   ObjStatus      503
-   ObjReason      Backend fetch failed
-   ObjHeader      Date: Wed, 13 Jan 2016 09:04:36 GMT
-   ObjHeader      Server: Varnish
-   ObjHeader      Content-Type: text/html; charset=utf-8
-   ObjHeader      Retry-After: 5
-   Length         286
-   BereqAcct      350 0 350 0 0 0
-   End

The issue is not with the backend connection because a curl to the same URL from the varnish server works fine. The version of varnish is 4.1.0. I'm not sure what "http first read error: EOF" means and any light on this issue is appreciated. Due to the random nature of this issue, I do not have any way to reproduce it as well.

Answer 1

A "first read error" happens in Varnish when you try to read headers from the backend before calling vcl_fetch, and Varnish failed to get a response. TL;DR: your backend is either closing the connection before delivering a response, or it is timing out delivering the response. You could use a tool like wireshark to determine which of the two is happening.

To understand what goes on, let's do some source diving:

static int __match_proto__(vdi_gethdrs_f)
vbe_dir_gethdrs(const struct director *d, struct worker *wrk,
    struct busyobj *bo)
{
    int i, extrachance = 1;
    struct backend *bp;
    struct vbc *vbc;

    ...

    do {
            vbc = vbe_dir_getfd(wrk, bp, bo);

Not getting too much into directors, vbe_dir_gethdrs is called after Varnish has either opened a new connection, or decided it is going to reuse a connection.

            if (vbc->state != VBC_STATE_STOLEN)
                    extrachance = 0;

If we reuse a connection, vbc->state is set to VBC_STATE_STOLEN (Varnish-Cache/bin/varnishd/cache/cache_backend_tcp.c line 364). When we've opened a new connection, this value is not set. So far, so good.

            i = V1F_SendReq(wrk, bo, &bo->acct.bereq_hdrbytes, 0);
            if (vbc->state != VBC_STATE_USED)
                    VBT_Wait(wrk, vbc);

            assert(vbc->state == VBC_STATE_USED);

            if (i == 0)
                    i = V1F_FetchRespHdr(bo);

What this does is sends the request to the backend. If everything there goes well, we then call V1F_FetchRespHdr, which waits for the origin to send its protocol response and headers. If we follow the code into V1F_FetchRespHdr:

    VTCP_set_read_timeout(htc->fd, htc->first_byte_timeout);
    ...
    do {
        ...
        i = read(htc->fd, htc->rxbuf_e, i);
        if (i <= 0) {
            bo->acct.beresp_hdrbytes +=
                htc->rxbuf_e - htc->rxbuf_b;
            WS_ReleaseP(htc->ws, htc->rxbuf_b);
            VSLb(bo->vsl, SLT_FetchError, "http %sread error: EOF",
                first ? "first " : "");
            htc->doclose = SC_RX_TIMEOUT;
            return (first ? 1 : -1);
        }

Here, we see that we're setting a timeout on the socket before we do the read syscall. If this read returns an error (the < 0 case), or EOF (the == 0 case), and this is the first time we have called read, we end up logging http first read error: EOF as you are seeing in your varnishlog output.

So, if you open a new connection to the backend, and the backend times out or closes the connection after the request was sent, you get this error.

Personally, I would find it suspect if your origin was closing connections; I think timeouts are usually more likely. But connections may be closed if your backend thinks it has too many open connections, or perhaps it has received too many requests over the connection, or something like this.

Hope that helps!