Srcache + mogilefs module

Hi,

I’m currently in a process of setting mogilefs + memcached + nginx
environment. My idea is to have nginx as a frontend server which will be
used to access files stored on a mogile filesystem. This is working
perfectly. To add some caching I would like to add support for memcached
to nginx itself. That way it will be able to cache some images for
itself and do not ask mogilefs for them.

My problem is that it seems that even if I put files to memcache
manually and it srcache will find it (see log below), my file is still
served from mogilefs and not from memcached.

upstream mogilefs_trackers {
    server 192.168.206.3:6001;
    #server 192.168.206.2:6001;
}

upstream memcached_servers {

server 192.168.206.3:11211;
}

server {
    listen       80;
    server_name  ws01x.test.reality.sk;

root /var/www/html;

Check if we can find anything on a memcache server if not fetch it

from a mogilefs.

location = /memc {
internal;
memc_connect_timeout 100ms;
memc_send_timeout 100ms;
memc_read_timeout 100ms;

 set $memc_key $query_string;
 set $memc_exptime 300;

 memc_pass memcached_servers;

}

location /share/ {
set $key $uri;

  srcache_fetch GET /memc $key;
  srcache_store PUT /memc $key;
      srcache_store_statuses 200 301 302;
  srcache_response_cache_control off;

        mogilefs_tracker mogilefs_trackers;
        mogilefs_domain test;
        #mogilefs_class testclass;
  mogilefs_methods GET;
        mogilefs_noverify on;

        mogilefs_pass {
            proxy_pass $mogilefs_path;
            proxy_hide_header Content-Type;
            proxy_buffering off;
        }

  if ($request_uri ~* \.(ico|css|js)$) {
            expires 72h;
            break;
        }

}
}

------ LOG

2012/04/20 21:28:21 [debug] 7385#0: *501 http request line: “GET
/share/file.html HTTP/1.0”
2012/04/20 21:28:21 [debug] 7385#0: *501 http uri: “/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http args: “”
2012/04/20 21:28:21 [debug] 7385#0: *501 http exten: “html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http process request header
line
2012/04/20 21:28:21 [debug] 7385#0: *501 http header: “User-Agent:
Wget/1.11.4 Red Hat modified”
2012/04/20 21:28:21 [debug] 7385#0: *501 http header: “Accept: /
2012/04/20 21:28:21 [debug] 7385#0: *501 http header: “Host:
192.168.200.64”
2012/04/20 21:28:21 [debug] 7385#0: *501 http header: “Connection:
Keep-Alive”
2012/04/20 21:28:21 [debug] 7385#0: *501 http header done
2012/04/20 21:28:21 [debug] 7385#0: *501 event timer del: 3:
1334950161661
2012/04/20 21:28:21 [debug] 7385#0: *501 rewrite phase: 0
2012/04/20 21:28:21 [debug] 7385#0: *501 test location: “/memc”
2012/04/20 21:28:21 [debug] 7385#0: *501 test location: “/prehliadac”
2012/04/20 21:28:21 [debug] 7385#0: *501 test location: “/share/”
2012/04/20 21:28:21 [debug] 7385#0: *501 using configuration “/share/”
2012/04/20 21:28:21 [debug] 7385#0: *501 http cl:-1 max:1048576
2012/04/20 21:28:21 [debug] 7385#0: *501 rewrite phase: 2
2012/04/20 21:28:21 [debug] 7385#0: *501 http script complex value
2012/04/20 21:28:21 [debug] 7385#0: *501 http script var:
“/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http script set $key
2012/04/20 21:28:21 [debug] 7385#0: *501 http script var
2012/04/20 21:28:21 [debug] 7385#0: *501 http script var:
“/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http script regex:
“.(ico|css|js)$”
2012/04/20 21:28:21 [notice] 7385#0: *501 “.(ico|css|js)$” does not
match “/share/file.html”, client: 192.168.200.64, server:
ws01x.test.reality.sk, request: “GET /share/file.html HTTP/1.0”, host:
“192.168.200.64”
2012/04/20 21:28:21 [debug] 7385#0: *501 http script if
2012/04/20 21:28:21 [debug] 7385#0: *501 http script if: false
2012/04/20 21:28:21 [debug] 7385#0: *501 post rewrite phase: 3
2012/04/20 21:28:21 [debug] 7385#0: *501 generic phase: 4
2012/04/20 21:28:21 [debug] 7385#0: *501 generic phase: 5
2012/04/20 21:28:21 [debug] 7385#0: *501 access phase: 6
2012/04/20 21:28:21 [debug] 7385#0: *501 access phase: 7
2012/04/20 21:28:21 [debug] 7385#0: *501 access phase: 8
2012/04/20 21:28:21 [debug] 7385#0: *501 access phase: 9
2012/04/20 21:28:21 [debug] 7385#0: *501 http script var:
“/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 posix_memalign:
0000000000EA31C0:4096 @16
2012/04/20 21:28:21 [debug] 7385#0: *501 http subrequest
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http posted request:
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 rewrite phase: 0
2012/04/20 21:28:21 [debug] 7385#0: *501 test location: “/memc”
2012/04/20 21:28:21 [debug] 7385#0: *501 using configuration “=/memc”
2012/04/20 21:28:21 [debug] 7385#0: *501 http cl:-1 max:1048576
2012/04/20 21:28:21 [debug] 7385#0: *501 rewrite phase: 2
2012/04/20 21:28:21 [debug] 7385#0: *501 http script complex value
2012/04/20 21:28:21 [debug] 7385#0: *501 http script var:
“/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http script set $memc_key
2012/04/20 21:28:21 [debug] 7385#0: *501 http script value: “300”
2012/04/20 21:28:21 [debug] 7385#0: *501 http script set $memc_exptime
2012/04/20 21:28:21 [debug] 7385#0: *501 post rewrite phase: 3
2012/04/20 21:28:21 [debug] 7385#0: *501 generic phase: 4
2012/04/20 21:28:21 [debug] 7385#0: *501 generic phase: 5
2012/04/20 21:28:21 [debug] 7385#0: *501 http init upstream, client
timer: 0
2012/04/20 21:28:21 [debug] 7385#0: *501 epoll add event: fd:3 op:3
ev:80000005
2012/04/20 21:28:21 [debug] 7385#0: *501 http memcached request:
“/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http cleanup add:
0000000000EA4110
2012/04/20 21:28:21 [debug] 7385#0: *501 get rr peer, try: 1
2012/04/20 21:28:21 [debug] 7385#0: *501 socket 4
2012/04/20 21:28:21 [debug] 7385#0: *501 epoll add connection: fd:4
ev:80000005
2012/04/20 21:28:21 [debug] 7385#0: *501 connect to 192.168.206.3:11211,
fd:4 #502
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream connect: -2
2012/04/20 21:28:21 [debug] 7385#0: *501 event timer add: 4:
100:1334950101761
2012/04/20 21:28:21 [debug] 7385#0: *501 http finalize request: -4,
“/memc?/share/file.html” a:1, c:3
2012/04/20 21:28:21 [debug] 7385#0: *501 http request count:3 blk:0
2012/04/20 21:28:21 [debug] 7385#0: *501 http run request:
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream check client,
write event:1, “/memc”
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream recv(): -1 (11:
Resource temporarily unavailable)
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream request:
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream send request
handler
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream send request
2012/04/20 21:28:21 [debug] 7385#0: *501 chain writer buf fl:0 s:22
2012/04/20 21:28:21 [debug] 7385#0: *501 chain writer in:
0000000000EA4148
2012/04/20 21:28:21 [debug] 7385#0: *501 writev: 22
2012/04/20 21:28:21 [debug] 7385#0: *501 chain writer out:
0000000000000000
2012/04/20 21:28:21 [debug] 7385#0: *501 event timer del: 4:
1334950101761
2012/04/20 21:28:21 [debug] 7385#0: *501 event timer add: 4:
100:1334950101763
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream request:
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream process header
2012/04/20 21:28:21 [debug] 7385#0: *501 malloc: 0000000000E989F0:4096
2012/04/20 21:28:21 [debug] 7385#0: *501 posix_memalign:
0000000000E99A00:4096 @16
2012/04/20 21:28:21 [debug] 7385#0: *501 recv: fd:4 46 of 4096
2012/04/20 21:28:21 [debug] 7385#0: *501 memcached: “VALUE
/share/file.html 0 10” <---- WE got it
2012/04/20 21:28:21 [debug] 7385#0: *501 srcache_fetch: subrequest
returned status 200
2012/04/20 21:28:21 [debug] 7385#0: *501 srcache_fetch decides to send
the response in cache
2012/04/20 21:28:21 [debug] 7385#0: *501 tcp_nodelay
2012/04/20 21:28:21 [debug] 7385#0: *501 memcached filter bytes:17
size:17 length:17 rest:7
2012/04/20 21:28:21 [debug] 7385#0: *501 http upstream process non
buffered downstream
2012/04/20 21:28:21 [debug] 7385#0: *501 http output filter
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http copy filter:
“/memc?/share/file.html”
2012/04/20 21:28:21 [error] 7385#0: *501 srcache_fetch: cache sent
invalid status line while sending to client, client: 192.168.200.64,
server: ws01x.test.reality.sk, request: “GET /share/file.html HTTP/1.0”,
subrequest: “/memc”, upstream: “memcached://192.168.206.3:11211”, host:
“192.168.200.64”
2012/04/20 21:28:21 [debug] 7385#0: *501 http copy filter: 0
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 finalize http upstream request:
0
2012/04/20 21:28:21 [debug] 7385#0: *501 finalize http memcached
request
2012/04/20 21:28:21 [debug] 7385#0: *501 free rr peer 1 0
2012/04/20 21:28:21 [debug] 7385#0: *501 close http upstream connection:
4
2012/04/20 21:28:21 [debug] 7385#0: *501 event timer del: 4:
1334950101763
2012/04/20 21:28:21 [debug] 7385#0: *501 reusable connection: 0
2012/04/20 21:28:21 [debug] 7385#0: *501 http output filter
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http copy filter:
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http copy filter: 0
“/memc?/share/file.html”
2012/04/20 21:28:21 [debug] 7385#0: *501 http finalize request: 0,
“/memc?/share/file.html” a:1, c:2
2012/04/20 21:28:21 [debug] 7385#0: *501 http wake parent request:
“/share/file.html?”
2012/04/20 21:28:21 [debug] 7385#0: *501 http posted request:
“/share/file.html?”
2012/04/20 21:28:21 [debug] 7385#0: *501 access phase: 9
2012/04/20 21:28:21 [debug] 7385#0: *501 post access phase: 10
2012/04/20 21:28:21 [debug] 7385#0: *501 http set discard body
2012/04/20 21:28:21 [debug] 7385#0: *501 http init upstream, client
timer: 0
2012/04/20 21:28:21 [debug] 7385#0: *501 mogilefs request: “get_paths
key=file.html&domain=test&noverify=1”

From this log I can see why is file can’t serverd from memcached, server
status 200. Are srcache and mogilefs module somehow incompatible ?

Posted at Nginx Forum:

agentzh Wrote:

like? The ngx_srcache
module requires the value to be the whole
response, that is,
including the status line and all those response
headers.

It was simple string, so yes this was the problem.

Basically, you should rely on ngx_srcache’s
srcache_store to store the
responses automatically for you, rather than
inserting values into
memcached yourself.

But from attached log or this new [1] dump it seems tat srcache_store is
never called.
I was not aware of this, it should be added to documentation :).

[1] gist:2439805 · GitHub

invalid status line while sending to client,
beginning, so it immediately

manually inserted into memcached.
I will try to add proper entry and try again, right now I would like to
know why
srcache_store do not work as expected. Here is config

location = /memc {
internal;
memc_connect_timeout 100ms;
memc_send_timeout 100ms;
memc_read_timeout 100ms;

 set $memc_key $query_string;
 set $memc_exptime 300;

 memc_pass memcached_servers;

}

location /share/ {
set $key $uri;

  srcache_fetch GET /memc $key;
  srcache_store PUT /memc $key;
      srcache_store_statuses 200 301 302;
  srcache_response_cache_control off;

  [snip]

Posted at Nginx Forum:

On Sat, Apr 21, 2012 at 4:16 AM, haad [email protected] wrote:

My problem is that it seems that even if I put files to memcache
manually and it srcache will find it (see log below), my file is still
served from mogilefs and not from memcached.

What does the data you put into memcached look like? The ngx_srcache
module requires the value to be the whole response, that is,
including the status line and all those response headers.

Basically, you should rely on ngx_srcache’s srcache_store to store the
responses automatically for you, rather than inserting values into
memcached yourself.

2012/04/20 21:28:21 [debug] 7385#0: *501 memcached: “VALUE
/share/file.html 0 10” <---- WE got it

Yes, ngx_srcache got the value from memcached here.

2012/04/20 21:28:21 [error] 7385#0: *501 srcache_fetch: cache sent
invalid status line while sending to client, client: 192.168.200.64,
server: ws01x.test.reality.sk, request: “GET /share/file.html HTTP/1.0”,
subrequest: “/memc”, upstream: “memcached://192.168.206.3:11211”, host:
“192.168.200.64”

But here, ngx_srcache then found the value is invalid in that it does
not have a valid HTTP status line at the beginning, so it immediately
abandoned the cached value, and treated it as a cache miss.

From this log I can see why is file can’t serverd from memcached, server
status 200.

Maybe I should make the debug log more verbose a bit here :wink:

Are srcache and mogilefs module somehow incompatible ?

ngx_srcache is designed to be backend independent :wink: If it’s not, then
there must be a bug somewhere :wink:

In your case here, it seems to be the bad format of the data that you
manually inserted into memcached.

Best regards,
-agentzh

agentzh Wrote:

never called.
so (maybe created by the mogilefs_pass directive):

[debug] 7200#0: *1058 internal redirect:
“/mogstored_spare_34991976/?”

And you didn’t configure ngx_srcache at all in
this anonymous location
and hence no srcache_store love here.

So if I configure location with /mogstored and sets srcache_store there
it should be working ?

location ~ /mogstored_ {
srcache_store PUT /memc
}

AFAIK, the ngx_eval module also does something
similar here (i.e.,
creating nested locations automatically).

I’m not sure what you mean by this :slight_smile: are you suggesting that
I should use it ?

location. See the
[email protected]
nginx Info Page

Posted at Nginx Forum:

On Sun, Apr 22, 2012 at 5:49 AM, haad [email protected] wrote:

Basically, you should rely on ngx_srcache’s
srcache_store to store the
responses automatically for you, rather than
inserting values into
memcached yourself.

But from attached log or this new [1] dump it seems tat srcache_store is
never called.
I was not aware of this, it should be added to documentation :).

According to your debug log, the ngx_mogilefs module left your
location /share/ and did an internal redirect to an
automatically-generated location named /mogstored_spare_34991976/ or
so (maybe created by the mogilefs_pass directive):

[debug] 7200#0: *1058 internal redirect: “/mogstored_spare_34991976/?”

And you didn’t configure ngx_srcache at all in this anonymous location
and hence no srcache_store love here.

AFAIK, the ngx_eval module also does something similar here (i.e.,
creating nested locations automatically).

[1] gist:2439805 · GitHub

Just search for “internal redirect” in your debug log above.

Also, you should be careful when using the “if” directive in location
blocks because it also created a nested anonymous location. See the
discussion here:

Best regards,
-agentzh

On Sun, Apr 22, 2012 at 2:14 PM, haad [email protected] wrote:

So if I configure location with /mogstored and sets srcache_store there
it should be working ?

location ~ /mogstored_ {
srcache_store PUT /memc
}

No, the /mogstored_spare_34991976/ location is automatically generated
by ngx_mogilefs. I’m not sure if it helps by putting your
srcache_store configuration into the “anonymous” location block under
the mogilefs_pass directive, i.e.,

       mogilefs_pass {
           proxy_pass $mogilefs_path;
           proxy_hide_header Content-Type;
           proxy_buffering off;
           srcache_store PUT /memc;
       }

But you can try it out anyway.

AFAIK, the ngx_eval module also does something
similar here (i.e.,
creating nested locations automatically).

I’m not sure what you mean by this :slight_smile: are you suggesting that
I should use it ?

No.

I was just talking about the similarity in their implementations.

Regards,
-agentzh

agentzh Wrote:

           proxy_pass $mogilefs_path;
           proxy_hide_header Content-Type;
           proxy_buffering off;
           srcache_store PUT /memc;
       }

But you can try it out anyway.

This works ! thanks a lot for your time/help.

Posted at Nginx Forum: