1#!/usr/bin/env perl
2# Networked logging tests.
3
4use strict;
5use warnings;
6use Socket qw/SO_RCVBUF/;
7
8use Test::More;
9use FindBin qw($Bin);
10use lib "$Bin/lib";
11use MemcachedTest;
12
13plan tests => 43;
14
15my $server = new_memcached('-m 60 -o watcher_logbuf_size=8');
16my $client = $server->sock;
17my $watcher = $server->new_sock;
18
19# This doesn't return anything.
20print $watcher "watch\n";
21my $res = <$watcher>;
22is($res, "OK\r\n", "watcher enabled");
23
24print $client "get foo\n";
25$res = <$client>;
26is($res, "END\r\n", "basic get works");
27my $spacer = "X"x180;
28
29# This is a flaky test... depends on buffer sizes. Could either have memc
30# shrink the watcher buffer, or loop this and keep doubling until we get some
31# skipped values.
32for (1 .. 80000) {
33    print $client "get foo$_$spacer\n";
34    $res = <$client>;
35}
36
37# Let the logger thread catch up before we start reading.
38sleep 1;
39my $do_fetch = 0;
40#print STDERR "RESULT: $res\n";
41while (my $log = <$watcher>) {
42    # The "skipped" line won't actually print until some space frees up in the
43    # buffer, so we need to occasionally cause new lines to generate.
44    if (($do_fetch++ % 100) == 0) {
45         print $client "get foo\n";
46         $res = <$client>;
47    }
48    next unless $log =~ m/skipped/;
49    like($log, qr/skipped=/, "skipped some lines");
50    # This should unjam more of the text.
51    print $client "get foob\n";
52    $res = <$client>;
53    last;
54}
55$res = <$watcher>;
56like($res, qr/ts=\d+\.\d+\ gid=\d+ type=item_get/, "saw a real log line after a skip");
57
58# testing the longest uri encoded key length
59{
60my $new_watcher = $server->new_sock;
61print $new_watcher "watch mutations\n";
62my $watch_res = <$new_watcher>;
63my $key = "";
64my $max_keylen = 250;
65for (1 .. $max_keylen) { $key .= "#"; }
66print $client "set $key 0 0 9\r\nmemcached\r\n";
67$res = <$client>;
68is ($res, "STORED\r\n", "stored the long key");
69if ($res eq "STORED\r\n") {
70    $watch_res = <$new_watcher>;
71    my $max_uri_keylen = $max_keylen * 3 + length("key=");
72    my @tab = split(/\s+/, $watch_res);
73    is (length($tab[3]), $max_uri_keylen, "got the correct uri encoded key length");;
74}
75}
76
77# test connection events
78{
79    # start a dedicated server so that connection close events from previous
80    # tests don't leak into this one due to races.
81    my $conn_server = new_memcached('-m 60 -o watcher_logbuf_size=8');
82    my $conn_watcher = $conn_server->new_sock;
83
84    sleep 1;
85    print $conn_watcher "watch connevents\n";
86    $res = <$conn_watcher>;
87    is($res, "OK\r\n", 'connevents watcher enabled');
88
89    # normal close
90    my $conn_client = $conn_server->new_sock;
91    print $conn_client "version\r\n";
92    $res = <$conn_client>;
93    print $conn_client "quit\r\n";
94    $res = <$conn_watcher>;
95    like($res, qr/ts=\d+\.\d+\ gid=\d+ type=conn_new .+ transport=(local|tcp)/,
96        'logged new connection');
97    $res = <$conn_watcher>;
98    like($res, qr/ts=\d+\.\d+\ gid=\d+ type=conn_close .+ transport=(local|tcp) reason=normal/,
99        'logged closed connection due to client disconnect');
100
101    # error close
102    $conn_client = $conn_server->new_sock;
103    print $conn_client "GET / HTTP/1.1\r\n";
104    $res = <$conn_watcher>;
105    like($res, qr/ts=\d+\.\d+\ gid=\d+ type=conn_new .+ transport=(local|tcp)/,
106        'logged new connection');
107    $res = <$conn_watcher>;
108    like($res, qr/ts=\d+\.\d+\ gid=\d+ type=conn_close .+ transport=(local|tcp) reason=error/,
109        'logged closed connection due to client protocol error');
110}
111
112# test combined logs
113# fill to evictions, then enable watcher, set again, and look for both lines
114
115{
116    my $value = "B"x11000;
117    my $keycount = 8000;
118
119    for (1 .. $keycount) {
120        print $client "set n,foo$_ 0 0 11000 noreply\r\n$value\r\n";
121    }
122    # wait for all of the writes to go through.
123    print $client "version\r\n";
124    $res = <$client>;
125
126    my $mwatcher = $server->new_sock;
127    print $mwatcher "watch mutations evictions\n";
128    $res = <$mwatcher>;
129    is($res, "OK\r\n", "new watcher enabled");
130    my $watcher2 = $server->new_sock;
131    print $watcher2 "watch evictions\n";
132    $res = <$watcher2>;
133    is($res, "OK\r\n", "evictions watcher enabled");
134
135    print $client "set bfoo 0 0 11000 noreply\r\n$value\r\n";
136    my $found_log = 0;
137    my $found_ev  = 0;
138    while (my $log = <$mwatcher>) {
139        $found_log = 1 if ($log =~ m/type=item_store/);
140        $found_ev = 1 if ($log =~ m/type=eviction/);
141        last if ($found_log && $found_ev);
142    }
143    is($found_log, 1, "found rawcmd log entry");
144    is($found_ev, 1, "found eviction log entry");
145}
146
147# test cas command logs
148# TODO: need to expose active watchers in stats, so we can monitor for when
149# the previous ones are fully disconnected. They might be swallowing the logs
150# before we get them. Since I can't reproduce this locally and travis takes 30
151# minutes to fail I can't instrument this.
152SKIP: {
153    skip "Mysteriously fails on travis CI.", 1;
154    $watcher = $server->new_sock;
155    print $watcher "watch mutations\n";
156    $res = <$watcher>;
157    is($res, "OK\r\n", "mutations watcher enabled");
158
159    # There's a bit of a startup race where some workers may not have the log
160    # enabled yet, so we try a little harder to get the log line in there.
161    sleep 1;
162    for (1 .. 20) {
163        print $client "cas cas_watch_key 0 0 5 0\r\nvalue\r\n";
164        $res = <$client>;
165    }
166    my $tries = 30;
167    my $found_cas = 0;
168    while (my $log = <$watcher>) {
169        $found_cas = 1 if ($log =~ m/cmd=cas/ && $log =~ m/cas_watch_key/);
170        last if ($tries-- == 0 || $found_cas);
171    }
172    is($found_cas, 1, "correctly logged cas command");
173}
174
175# test get/set value sizes
176{
177    my $watcher = $server->new_sock;
178    print $watcher "watch fetchers mutations\n";
179    is(<$watcher>, "OK\r\n", "fetchers and mutations watcher enabled");
180
181    print $client "set vfoo 0 0 4\r\nvbar\r\n";
182    is(<$client>, "STORED\r\n", "stored the key");
183
184    print $client "get vfoo\r\n";
185    is(<$client>, "VALUE vfoo 0 4\r\n", "read the key header");
186    is(<$client>, "vbar\r\n", "read the key value");
187    is(<$client>, "END\r\n", "read the value trailer");
188
189    sleep 1;
190    like(<$watcher>, qr/ts=\d+\.\d+\ gid=\d+ type=item_get key=vfoo .+ size=0/,
191        "logged initial item fetch");
192    like(<$watcher>, qr/ts=\d+\.\d+\ gid=\d+ type=item_store key=vfoo .+ size=4/,
193        "logged item store with correct size");
194    like(<$watcher>, qr/ts=\d+\.\d+\ gid=\d+ type=item_get key=vfoo .+ size=4/,
195        "logged item get with correct size");
196}
197
198# test watcher stats
199{
200    my $stats_server = new_memcached('-m 60 -o watcher_logbuf_size=8');
201    my $stats_client = $stats_server->sock;
202    my $stats;
203
204    my $watcher1 = $stats_server->new_sock;
205    print $watcher1 "watch fetchers\n";
206    $res = <$watcher1>;
207    is($res, "OK\r\n", 'fetchers watcher enabled');
208    sleep 1;
209    $stats = mem_stats($stats_client);
210    is($stats->{log_watchers}, 1, 'tracked new fetchers watcher');
211
212    my $watcher2 = $stats_server->new_sock;
213    print $watcher2 "watch fetchers\n";
214    $res = <$watcher2>;
215    is($res, "OK\r\n", 'mutations watcher enabled');
216    sleep 1;
217    $stats = mem_stats($stats_client);
218    is($stats->{log_watchers}, 2, 'tracked new mutations watcher');
219
220    $watcher1->close();
221    $watcher2->close();
222    sleep 1;
223    $stats = mem_stats($stats_client);
224    is($stats->{log_watchers}, 0, 'untracked all watchers');
225}
226
227# test no_watch option
228{
229    my $nowatch_server = new_memcached('-W');
230    my $watchsock = $nowatch_server->new_sock;
231
232    print $watchsock "watch mutations\n";
233
234    my $watchresult = <$watchsock>;
235
236    is($watchresult, "CLIENT_ERROR watch commands not allowed\r\n", "attempted watch gave client error with no_watch option set");
237}
238
239
240# test delete/meta-delete with value sizes
241{
242    my $watcher = $server->new_sock;
243    print $watcher "watch deletions\n";
244    is(<$watcher>, "OK\r\n", "deletions watcher enabled");
245
246    print $client "set vfoo 0 0 4\r\nvbar\r\n";
247    is(<$client>, "STORED\r\n", "stored the key");
248
249    # wouldn't be logged to watcher
250    print $client "md non-existing-key\r\n";
251    is(<$client>, "NF\r\n", "non-existing key can't be deleted");
252
253    print $client "delete vfoo\r\n";
254    is(<$client>, "DELETED\r\n", "key was deleted");
255
256    like(<$watcher>, qr/ts=\d+\.\d+\ gid=\d+ type=deleted key=vfoo cmd=delete .+ size=4/,
257        "delete command logged with correct size");
258
259    print $client "set vfoo 0 0 4\r\nvbar\r\n";
260    is(<$client>, "STORED\r\n", "stored the key");
261
262    print $client "md vfoo\r\n";
263    is(<$client>, "HD\r\n", "key was deleted");
264
265    like(<$watcher>, qr/ts=\d+\.\d+\ gid=\d+ type=deleted key=vfoo cmd=md .+ size=4/,
266        "meta-delete command logged with correct size");
267
268    print $client "set vfoo 0 0 4\r\nvbar\r\n";
269    is(<$client>, "STORED\r\n", "stored the key");
270
271    # shouldn't result in log line
272    print $client "md vfoo I\r\n";
273    is(<$client>, "HD\r\n", "key was marked stale");
274
275    print $client "mg vfoo\r\n";
276    is(<$client>, "HD X W\r\n", "mg shows key is stale and won recache");
277
278    # now do a delete and it will show up in the log, explicitly use delete instead of md to check the cmd= pair in log
279    print $client "delete vfoo\r\n";
280    is(<$client>, "DELETED\r\n", "key was deleted");
281
282    like(<$watcher>, qr/ts=\d+\.\d+\ gid=\d+ type=deleted key=vfoo cmd=delete .+ size=4/,
283        "delete command logged with correct size");
284}
285