View Issue Details

Jump to Notes
IDProjectCategoryView StatusDate SubmittedLast Update
0006786OXID eShop (all versions)4.08. Cachepublic2018-02-06 11:002018-03-21 14:54
ReporterQA Assigned To 
PrioritynormalSeveritymajorReproducibilityalways
Status resolvedResolutionfixed 
Product Version4.10.6 / 5.3.6 
Summary0006786: default.vcl cookie cleanup missing commas
DescriptionDefault VCL cookie cleanup missing commas

In default.vcl the funciton oxClearCookiesByWhitelistRecv is responsible for cleaning up cookies.
The following section should remove empty strings with a comma:
# Cleaning up - empty string with "," found, cleaning it.
        set req.http.Cookie = regsuball(req.http.Cookie, "(^; )", "");

The regex is looking for semicolon instead of comma.

Multiple cookie headers will be reduced to a repetition of commas and spaces instead of getting removed in the process.

This might result in issues with libpcre which can lead to a varnish crash.
Steps To ReproduceSee https://bugs.oxid-esales.com/view.php?id=6786#c12377
TagsNo tags attached.
ThemeNot defined
BrowserNot defined
PHP VersionNot defined
Database VersionNot defined

Activities

michael_keiluweit

2018-02-07 09:31

administrator   ~0012377

How to reproduce:

Create a script in the directory of the shop:
<?php
require_once 'bootstrap.php';

$o = oxNew('oxutilsserver');

for ($i = 0; $i < 72; $i++) {
    $o->setOxCookie('mk'.$i, 'value');
}


After calling the script via browser you will get a similar output:
Error 503 Backend fetch failed
Backend fetch failed

Guru Meditation:
XID: 3

Varnish cache server


The log varnishncsa logs in that situation this:
::1 - - [07/Feb/2018:09:23:57 +0100] "GET http://localhost/e536/bin/c.php HTTP/1.1" 503 278 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.119 Safari/537.36"



The varnishlog log:

$ sudo varnishlog
*   << BeReq    >> 32771     
-   Begin          bereq 32770 fetch
-   Timestamp      Start: 1517992250.508905 0.000000 0.000000
-   BereqMethod    GET
-   BereqURL       /e536/bin/c.php
-   BereqProtocol  HTTP/1.1
-   BereqHeader    Upgrade-Insecure-Requests: 1
-   BereqHeader    User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.119 Safari/537.36
-   BereqHeader    Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
-   BereqHeader    Accept-Language: en-US,en;q=0.9,de;q=0.8
-   BereqHeader    X-Forwarded-For: ::1
-   BereqHeader    x-host: localhost
-   BereqHeader    x-url: /e536/bin/c.php
-   BereqHeader    host: localhost
-   BereqHeader    x-cookie: oxidadminprofile=0%40Standard%4010%401; oxidadminlanguage=de
-   BereqHeader    x-esi-level: 0
-   BereqHeader    Surrogate-Capability: varnish=ESI/1.0
-   BereqHeader    grace: none
-   BereqHeader    Accept-Encoding: gzip
-   BereqHeader    X-UA-Device: desktop
-   BereqHeader    X-UA-Language: en
-   BereqHeader    Cookie: oxidadminprofile=0%40Standard%4010%401; oxidadminlanguage=de
-   BereqHeader    X-Varnish: 32771
-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendOpen    18 boot.default 127.0.0.1 8080 127.0.0.1 36652
-   Timestamp      Bereq: 1517992250.509432 0.000527 0.000527
-   BogoHeader     Too many headers: Set-Cookie: mk54=val
-   HttpGarbage    "HTTP/1.1%00"
-   BerespStatus   503
-   BerespReason   Service Unavailable
-   FetchError     http format error
-   BackendClose   18 boot.default
-   Timestamp      Beresp: 1517992250.519115 0.010210 0.009683
-   Timestamp      Error: 1517992250.519121 0.010216 0.000007
-   BerespProtocol HTTP/1.1
-   BerespStatus   503
-   BerespReason   Service Unavailable
-   BerespReason   Backend fetch failed
-   BerespHeader   Date: Wed, 07 Feb 2018 08:30:50 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, 07 Feb 2018 08:30:50 GMT
-   ObjHeader      Server: Varnish
-   ObjHeader      Content-Type: text/html; charset=utf-8
-   ObjHeader      Retry-After: 5
-   Length         282
-   BereqAcct      692 0 692 3330 0 3330
-   End            

*   << Request  >> 32770     
-   Begin          req 32769 rxreq
-   Timestamp      Start: 1517992250.508652 0.000000 0.000000
-   Timestamp      Req: 1517992250.508652 0.000000 0.000000
-   ReqStart       ::1 33700
-   ReqMethod      GET
-   ReqURL         /e536/bin/c.php
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: localhost
-   ReqHeader      Connection: keep-alive
-   ReqHeader      Cache-Control: max-age=0
-   ReqHeader      Upgrade-Insecure-Requests: 1
-   ReqHeader      User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.119 Safari/537.36
-   ReqHeader      Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
-   ReqHeader      Accept-Encoding: gzip, deflate, br
-   ReqHeader      Accept-Language: en-US,en;q=0.9,de;q=0.8
-   ReqHeader      Cookie: oxidadminprofile=0%40Standard%4010%401; oxidadminlanguage=de
-   ReqHeader      X-Forwarded-For: ::1
-   VCL_call       RECV
-   ReqHeader      x-host: localhost
-   ReqHeader      x-url: /e536/bin/c.php
-   ReqUnset       Host: localhost
-   ReqHeader      host: localhost
-   ReqHeader      x-cookie: oxidadminprofile=0%40Standard%4010%401; oxidadminlanguage=de
-   ReqHeader      x-esi-level: 0
-   ReqHeader      Surrogate-Capability: varnish=ESI/1.0
-   ReqUnset       Cookie: oxidadminprofile=0%40Standard%4010%401; oxidadminlanguage=de
-   ReqHeader      grace: none
-   ReqUnset       Accept-Encoding: gzip, deflate, br
-   ReqHeader      Accept-Encoding: gzip
-   ReqHeader      X-UA-Device: desktop
-   ReqHeader      X-UA-Language: en
-   VCL_return     hash
-   VCL_call       HASH
-   ReqURL         /e536/bin/c.php
-   VCL_return     lookup
-   VCL_call       MISS
-   ReqHeader      Cookie: oxidadminprofile=0%40Standard%4010%401; oxidadminlanguage=de
-   VCL_return     fetch
-   Link           bereq 32771 fetch
-   Timestamp      Fetch: 1517992250.519203 0.010550 0.010550
-   RespProtocol   HTTP/1.1
-   RespStatus     503
-   RespReason     Backend fetch failed
-   RespHeader     Date: Wed, 07 Feb 2018 08:30:50 GMT
-   RespHeader     Server: Varnish
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Retry-After: 5
-   RespHeader     X-Varnish: 32770
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     grace: none
-   RespHeader     Cache-Control: no-cache, no-store, must-revalidate, proxy-revalidate
-   RespHeader     Pragma: no-cache
-   RespHeader     Expires: Tue, 01 Jan 1985 00:00:00 GMT
-   VCL_return     deliver
-   Timestamp      Process: 1517992250.519241 0.010588 0.000038
-   RespHeader     Content-Length: 282
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1517992250.519275 0.010623 0.000034
-   ReqAcct        491 0 491 380 282 662
-   End            

*   << Session  >> 32769     
-   Begin          sess 0 HTTP/1
-   SessOpen       ::1 33700 :80 ::1 80 1517992250.506763 15
-   Link           req 32770 rxreq
-   SessClose      REM_CLOSE 5.110
-   End


!Be aware!: When the test script is executed with a lower number and varnish could handle that request, then the result is cached and further tests are meaningless. After getting the status 200 you must restart varnish to flush the cache.

Knut Steiner

2018-02-14 13:01

reporter   ~0012380

Last edited: 2018-02-14 13:05

 My Colleagues are still suspecting the following line of gp.vcl to cause the crash:

{noformat}
        # Cleaning up - empty string with "," found, cleaning it.
        set beresp.http.Set-Cookie = regsuball(beresp.http.Set-Cookie, "^(, )+", "");
{noformat}

On our test system, my colleagues have replaced that position with this block:

{noformat}
        # Unset Set-Cookie if only comma-spaces are left
        if (beresp.http.Set-Cookie ~ "^[, ]*$") {
            unset beresp.http.Set-Cookie;
        } else {
            # Cleaning up - empty string with "," found, cleaning it.
            set beresp.http.Set-Cookie = regsuball(beresp.http.Set-Cookie, "^(, )+", "");
        }
{noformat}

The idea of my colleagues was to dispose of a string consisting exclusively of comma-blanks en bloc, without replacing with regsuball () the whole places of discovery. It may be natural that the match () (represented by the tilde) also causes the library to fall.
After we've tested the VCL on our test system, we replaced the VCL on our customers live system early in the morning.
But we have still found strings consisting of comma-blanks that crash the libpcre. Only much less often. Yesterday we updated also the libpcre on theserver. It works but nothing has changed.

Therefore we still need OXIDs help on this case and hope that you will find a solution to fix that problem.

Knut Steiner

2018-02-15 10:20

reporter   ~0012381

UPDATE!!!
Today we went back to the "old" gp.vcl because of much slower page speeds since we've made the modification.

That means we are waiting for a solution that will fix the problem 'cookie cleanup missing commas'.
It would be nice if OXID could fix that problem contemporary.

Knut Steiner

2018-03-12 14:48

reporter   ~0012414

Hello,

I must apologize that we didn't give you a message belonging the varnish problems. Because of my illness no one took care of that ticket.

After my colleagues received your email on the 20th of february they implemented the changes to the VCL. After they've tested the configuration on the Pötschke test-system they implemented the changes onto the live-VARNISH.
Since that time we couldn't detect a crash of the libpcre. But we detected some cases of ' , , , , , , , ' after the changes. By the way, the shop works fine and our customer didn't receive any failure warnings that cause a 502 failure.

Thank you for your support.
Knut Steiner