1%%
2%% %CopyrightBegin%
3%%
4%% Copyright Ericsson AB 1998-2019. All Rights Reserved.
5%%
6%% Licensed under the Apache License, Version 2.0 (the "License");
7%% you may not use this file except in compliance with the License.
8%% You may obtain a copy of the License at
9%%
10%%     http://www.apache.org/licenses/LICENSE-2.0
11%%
12%% Unless required by applicable law or agreed to in writing, software
13%% distributed under the License is distributed on an "AS IS" BASIS,
14%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15%% See the License for the specific language governing permissions and
16%% limitations under the License.
17%%
18%% %CopyrightEnd%
19%%
20
21-module(wrap_log_reader_SUITE).
22
23%%-define(debug, true).
24
25-ifdef(debug).
26-define(format(S, A), io:format(S, A)).
27-define(line, put(line, ?LINE), ).
28-define(privdir(_), "./disk_log_SUITE_priv").
29-define(config(X,Y), foo).
30-define(t,test_server).
31-else.
32-include_lib("common_test/include/ct.hrl").
33-define(format(S, A), ok).
34-define(privdir(Conf), proplists:get_value(priv_dir, Conf)).
35-endif.
36
37-export([all/0, suite/0,groups/0,init_per_suite/1, end_per_suite/1,
38	 init_per_group/2,end_per_group/2,
39	 no_file/1,
40	 one_empty/1, one_filled/1,
41	 two_filled/1,
42	 four_filled/1,
43	 wrap_filled/1,
44	 wrapping/1,
45	 external/1,
46	 error/1]).
47
48-export([init_per_testcase/2, end_per_testcase/2]).
49
50suite() ->
51    [{ct_hooks,[ts_install_cth]},
52     {timetrap,{minutes,1}}].
53
54all() ->
55    [no_file, {group, one}, {group, two}, {group, four},
56     {group, wrap}, wrapping, external, error].
57
58groups() ->
59    [{one, [], [one_empty, one_filled]},
60     {two, [], [two_filled]}, {four, [], [four_filled]},
61     {wrap, [], [wrap_filled]}].
62
63init_per_suite(Config) ->
64    Config.
65
66end_per_suite(_Config) ->
67    ok.
68
69init_per_group(_GroupName, Config) ->
70    Config.
71
72end_per_group(_GroupName, Config) ->
73    Config.
74
75
76init_per_testcase(Func, Config) ->
77    Config.
78
79end_per_testcase(_Func, _Config) ->
80    ok.
81
82%% No log file exists.
83no_file(Conf) when is_list(Conf) ->
84    code:add_path(proplists:get_value(data_dir,Conf)),
85    Dir = ?privdir(Conf),
86    File = join(Dir, "sune.LOG"),
87    delete_files(File),
88    start(),
89
90    wlt ! {open, self(), File},
91    rec({error, {index_file_not_found, File}}, ?LINE),
92    wlt ! {open, self(), File, 1},
93    rec({error, {index_file_not_found, File}}, ?LINE),
94    wlt ! {open, self(), File, 4},
95    rec({error, {index_file_not_found, File}}, ?LINE),
96
97    stop(),
98    delete_files(File),
99    ok.
100
101
102%% One empty index file.
103one_empty(Conf) when is_list(Conf) ->
104    Dir = ?privdir(Conf),
105    File = join(Dir, "sune.LOG"),
106    delete_files(File),
107    start(),
108
109    open(sune, File, ?LINE),
110    %% open
111    do_chunk([{open,File}, eof], wlt, ?LINE),
112    do_chunk([{open,File,1}, eof], wlt, ?LINE),
113    wlt ! {open, self(), File, 2},
114    rec({error, {file_not_found, add_ext(File, 2)}}, ?LINE),
115    close(sune),
116
117    %% closed
118    do_chunk([{open,File}, eof], wlt, ?LINE),
119    do_chunk([{open,File,1}, eof], wlt, ?LINE),
120    wlt ! {open, self(), File, 2},
121    rec({error, {file_not_found, add_ext(File, 2)}}, ?LINE),
122
123    stop(),
124    delete_files(File),
125    ok.
126
127%% One filled index file.
128one_filled(Conf) when is_list(Conf) ->
129    Dir = ?privdir(Conf),
130    File = join(Dir, "sune.LOG"),
131    delete_files(File),
132    start(),
133
134    open(sune, File, ?LINE),
135    log_terms(sune, ["first round, one", "first round, two"]),
136    sync(sune),
137    %% open
138    test_one(File),
139    close(sune),
140    %% closed
141    test_one(File),
142
143    stop(),
144    delete_files(File),
145    ok.
146
147test_one(File) ->
148    do_chunk([{open,File},
149	      {chunk, ["first round, one", "first round, two"]},
150	      eof], wlt, ?LINE),
151    do_chunk([{open,File,1},
152	      {chunk, ["first round, one", "first round, two"]},
153	      eof], wlt, ?LINE),
154    wlt ! {open, self(), File, 2},
155    rec({error, {file_not_found, add_ext(File, 2)}}, ?LINE),
156    do_chunk([{open,File,1}, {chunk, 1, ["first round, one"]},
157	      {chunk, 1, ["first round, two"]}, eof], wlt, ?LINE),
158    ok.
159
160
161%% Two filled index files.
162two_filled(Conf) when is_list(Conf) ->
163    Dir = ?privdir(Conf),
164    File = list_to_atom(join(Dir, "sune.LOG")),
165    delete_files(File),
166    start(),
167
168    open(sune, File, ?LINE),
169    log_terms(sune, ["first round, 11", "first round, 12"]),
170    log_terms(sune, ["first round, 21", "first round, 22"]),
171    sync(sune),
172    %% open
173    test_two(File),
174    close(sune),
175    %% closed
176    test_two(File),
177
178    stop(),
179    delete_files(File),
180    ok.
181
182test_two(File) ->
183    do_chunk([{open,File},
184	      {chunk, infinity, ["first round, 11", "first round, 12"]},
185	      {chunk, ["first round, 21", "first round, 22"]},
186	      eof], wlt, ?LINE),
187    do_chunk([{open,File,1},
188	      {chunk, ["first round, 11", "first round, 12"]},
189	      eof], wlt, ?LINE),
190    do_chunk([{open,File,2},
191	      {chunk, ["first round, 21", "first round, 22"]},
192	      eof], wlt, ?LINE),
193    wlt ! {open, self(), File, 3},
194    rec({error, {file_not_found, add_ext(File, 3)}}, ?LINE),
195    do_chunk([{open,File,1}, {chunk, 1, ["first round, 11"]},
196	      {chunk, 2, ["first round, 12"]}, eof], wlt, ?LINE),
197    ok.
198
199
200%% Four filled index files.
201four_filled(Conf) when is_list(Conf) ->
202    Dir = ?privdir(Conf),
203    File = join(Dir, "sune.LOG"),
204    delete_files(File),
205    start(),
206
207    open(sune, File, ?LINE),
208    init_files(0),
209    sync(sune),
210    %% open
211    test_four(File),
212    close(sune),
213    %% closed
214    test_four(File),
215
216    stop(),
217    delete_files(File),
218    ok.
219
220test_four(File) ->
221    do_chunk([{open,File},
222	      {chunk, ["first round, 11", "first round, 12"]},
223	      {chunk, ["first round, 21", "first round, 22"]},
224	      {chunk, ["first round, 31", "first round, 32"]},
225	      {chunk, ["first round, 41", "first round, 42"]},
226	      eof], wlt, ?LINE),
227    do_chunk([{open,File,1},
228	      {chunk, ["first round, 11", "first round, 12"]},
229	      eof], wlt, ?LINE),
230    do_chunk([{open,File,4},
231	      {chunk, ["first round, 41", "first round, 42"]},
232	      eof], wlt, ?LINE),
233    wlt ! {open, self(), File, 5},
234    rec({error, {file_not_found, add_ext(File, 5)}}, ?LINE),
235    do_chunk([{open,File,1}, {chunk, 1, ["first round, 11"]},
236	      {chunk, 2, ["first round, 12"]}, eof], wlt, ?LINE),
237    do_chunk([{open,File,4}, {chunk, 1, ["first round, 41"]},
238	      {chunk, 2, ["first round, 42"]}, eof], wlt, ?LINE),
239    ok.
240
241
242%% First wrap, open, filled index file.
243wrap_filled(Conf) when is_list(Conf) ->
244    Dir = ?privdir(Conf),
245    File = join(Dir, "sune.LOG"),
246    delete_files(File),
247    start(),
248
249    open(sune, File, ?LINE),
250    init_files(0),
251    log_terms(sune, ["second round, 11", "second round, 12"]),
252    sync(sune),
253    %% open
254    test_wrap(File),
255    close(sune),
256    %% closed
257    test_wrap(File),
258
259    stop(),
260    delete_files(File),
261    ok.
262
263test_wrap(File) ->
264    do_chunk([{open,File},
265	      {chunk, ["first round, 21", "first round, 22"]},
266	      {chunk, ["first round, 31", "first round, 32"]},
267	      {chunk, ["first round, 41", "first round, 42"]},
268	      {chunk, ["second round, 11", "second round, 12"]},
269	      eof], wlt, ?LINE),
270    do_chunk([{open,File,1},
271	      {chunk, ["second round, 11", "second round, 12"]},
272	      eof], wlt, ?LINE),
273    do_chunk([{open,File,2},
274	      {chunk, ["first round, 21", "first round, 22"]},
275	      eof], wlt, ?LINE),
276    wlt ! {open, self(), File, 5},
277    rec({error, {file_not_found, add_ext(File, 5)}}, ?LINE),
278    do_chunk([{open,File,1}, {chunk, 1, ["second round, 11"]},
279	      {chunk, 2, ["second round, 12"]}, eof], wlt, ?LINE),
280    do_chunk([{open,File,4}, {chunk, 1, ["first round, 41"]},
281	      {chunk, 2, ["first round, 42"]}, eof], wlt, ?LINE),
282    ok.
283
284%% Wrapping at the same time as reading.
285wrapping(Conf) when is_list(Conf) ->
286    Dir = ?privdir(Conf),
287    File = join(Dir, "sune.LOG"),
288    delete_files(File),
289    start(),
290
291    open(sune, File, ?LINE),
292    init_files(1100),
293    sync(sune),
294    C1 =
295	do_chunk([{open,File}, {chunk, 1, ["first round, 11"]}], wlt, ?LINE),
296    log_terms(sune, ["second round, 11", "second round, 12"]),
297    sync(sune),
298    do_chunk([{chunk, 1, ["first round, 12"]},
299	      %% Here two bad bytes are found.
300	      {chunk, ["first round, 21", "first round, 22"]},
301	      {chunk, ["first round, 31", "first round, 32"]},
302	      {chunk, ["first round, 41", "first round, 42"]}, eof],
303	     wlt, ?LINE, C1),
304    start(),
305    delete_files(File),
306    open(sune, File, ?LINE),
307    init_files(1100),
308    sync(sune),
309    C2 =
310	do_chunk([{open,File}, {chunk, 1, ["first round, 11"]}], wlt, ?LINE),
311    log_terms(sune, ["second round, 11", "second round, 12"]),
312    close(sune),
313    do_chunk([{chunk, 1, ["first round, 12"]},
314	      %% Here two bad bytes are found.
315	      {chunk, ["first round, 21", "first round, 22"]},
316	      {chunk, ["first round, 31", "first round, 32"]},
317	      {chunk, ["first round, 41", "first round, 42"]}, eof],
318	     wlt, ?LINE, C2),
319    start(),
320    delete_files(File),
321    open(sune, File, ?LINE),
322    init_files(1100),
323    sync(sune),
324    C3 = do_chunk([{open,File}], wlt, ?LINE),
325    log_terms(sune, ["second round, 11"]),
326    sync(sune),
327    do_chunk([{chunk, 1, ["second round, 11"]},
328	      {chunk, 1, ["first round, 21"]},
329	      {chunk, 1, ["first round, 22"]},
330	      {chunk, ["first round, 31", "first round, 32"]},
331	      {chunk, ["first round, 41", "first round, 42"]}, eof],
332	     wlt, ?LINE, C3),
333
334    stop(),
335    delete_files(File),
336    ok.
337
338%% External format.
339external(Conf) when is_list(Conf) ->
340    Dir = ?privdir(Conf),
341    File = join(Dir, "sune.LOG"),
342    delete_files(File),
343    start(),
344
345    open_ext(sune, File, ?FILE),
346    init_files_ext(0),
347    close(sune),
348    P0 = pps(),
349    wlt ! {open, self(), File},
350    rec({error, {not_a_log_file, add_ext(File, 1)}}, ?LINE),
351    check_pps(P0),
352
353    stop(),
354    delete_files(File),
355    ok.
356
357%% Error situations.
358error(Conf) when is_list(Conf) ->
359    Dir = ?privdir(Conf),
360    File = join(Dir, "sune.LOG"),
361    delete_files(File),
362    start(),
363
364    P0 = pps(),
365    wlt ! {open, self(), File, 1},
366    rec({error, {index_file_not_found, File}}, ?LINE),
367    wlt ! {open, self(), File},
368    rec({error, {index_file_not_found, File}}, ?LINE),
369    check_pps(P0),
370
371    open(sune, File, ?LINE),
372    close(sune),
373    P1 = pps(),
374    First = add_ext(File, 1),
375    ok = file:delete(First),
376    wlt ! {open, self(), File},
377    rec({error, {not_a_log_file, First}}, ?LINE),
378    check_pps(P1),
379
380    delete_files(File),
381    open(sune, File, ?LINE),
382    init_files(0),
383    close(sune),
384    P2 = pps(),
385    C = do_chunk([{open,File},
386		  {chunk, ["first round, 11", "first round, 12"]}],
387		 wlt, ?LINE),
388    Second = add_ext(File, 2),
389    ok = file:delete(Second),
390    wlt ! {chunk, self(), C},
391    rec({error, {file_error, Second, {error, enoent}}}, ?LINE),
392    ok = file:write_file(Second, <<17:(3*8)>>), % three bytes
393    wlt ! {chunk, self(), C},
394    rec({error, {not_a_log_file, Second}}, ?LINE),
395    do_chunk([close], wlt, ?LINE, C),
396    check_pps(P2),
397
398    delete_files(File),
399    open(sune, File, ?LINE),
400    init_files(0),
401    close(sune),
402    P3 = pps(),
403    timer:sleep(1100),
404    Now = calendar:local_time(),
405    ok = file:change_time(First, Now),
406    C2 = do_chunk([{open,File},
407		   {chunk, ["first round, 11", "first round, 12"]}],
408		  wlt, ?LINE),
409    wlt ! {chunk, self(), C2},
410    rec({error,{is_wrapped,First}}, ?LINE),
411    do_chunk([close], wlt, ?LINE, C2),
412    IndexFile = add_ext(File, idx),
413    ok = file:write_file(IndexFile, <<17:(3*8)>>),
414    wlt ! {open, self(), File, 1},
415    rec({error, {index_file_not_found, File}}, ?LINE),
416    check_pps(P3),
417
418    stop(),
419    delete_files(File),
420    ok.
421
422start() ->
423    ok = wrap_log_test:stop(),
424    dl_wait(),
425    ok = wrap_log_test:init().
426
427stop() ->
428    ok = wrap_log_test:stop(),
429    dl_wait().
430
431%% Give disk logs opened by 'wlr_logger' and 'wlt' time to close after
432%% receiving EXIT signals.
433dl_wait() ->
434    case disk_log:accessible_logs() of
435        {[], []} ->
436            ok;
437        _X ->
438            erlang:display(_X),
439            timer:sleep(100),
440            dl_wait()
441    end.
442
443delete_files(File) ->
444    file:delete(add_ext(File, idx)),
445    file:delete(add_ext(File, siz)),
446    file:delete(add_ext(File, 1)),
447    file:delete(add_ext(File, 2)),
448    file:delete(add_ext(File, 3)),
449    file:delete(add_ext(File, 4)),
450    ok.
451
452init_files(Delay) ->
453    log_terms(sune, ["first round, 11", "first round, 12"]),
454    timer:sleep(Delay),
455    log_terms(sune, ["first round, 21", "first round, 22"]),
456    timer:sleep(Delay),
457    log_terms(sune, ["first round, 31", "first round, 32"]),
458    timer:sleep(Delay),
459    log_terms(sune, ["first round, 41", "first round, 42"]),
460    timer:sleep(Delay),
461    ok.
462
463init_files_ext(Delay) ->
464    blog_terms(sune, ["first round, 11", "first round, 12"]),
465    timer:sleep(Delay),
466    blog_terms(sune, ["first round, 21", "first round, 22"]),
467    timer:sleep(Delay),
468    blog_terms(sune, ["first round, 31", "first round, 32"]),
469    timer:sleep(Delay),
470    blog_terms(sune, ["first round, 41", "first round, 42"]),
471    timer:sleep(Delay),
472    ok.
473
474join(A, B) ->
475    filename:nativename(filename:join(A, B)).
476
477do_chunk(Commands, Server, Where) ->
478    do_chunk(Commands, Server, Where, foo).
479
480do_chunk([{open, File, One} | Cs], S, W, _C) ->
481    S ! {open, self(), File, One},
482    NC = rec1(ok, {W,?LINE}),
483    do_chunk(Cs, S, W, NC);
484do_chunk([{open, File} | Cs], S, W, _C) ->
485    S ! {open, self(), File},
486    NC = rec1(ok, {W,?LINE}),
487    do_chunk(Cs, S, W, NC);
488do_chunk([{chunk, Terms} | Cs], S, W, C) ->
489    S ! {chunk, self(), C},
490    NC = rec2(Terms, {W,?LINE}),
491    do_chunk(Cs, S, W, NC);
492do_chunk([{chunk, N, Terms} | Cs], S, W, C) ->
493    S ! {chunk, self(), C, N},
494    NC = rec2(Terms, {W,?LINE}),
495    do_chunk(Cs, S, W, NC);
496do_chunk([eof], S, W, C) ->
497    S ! {chunk, self(), C},
498    C1 = rec2(eof, {W,?LINE}),
499    do_chunk([close], S, W, C1);
500do_chunk([close], S, W, C) ->
501    S ! {close, self(), C},
502    rec(ok, {W,?LINE});
503do_chunk([], _S, _W, C) ->
504    C.
505
506add_ext(Name, Ext) ->
507    lists:concat([Name, ".", Ext]).
508
509%% disk_log.
510open(Log, File, Where) ->
511    wlr_logger ! {open, self(), Log, File},
512    rec1(ok, Where).
513
514open_ext(Log, File, Where) ->
515    wlr_logger ! {open_ext, self(), Log, File},
516    rec1(ok, Where).
517
518close(Log) ->
519    wlr_logger ! {close, self(), Log},
520    rec(ok, ?LINE).
521
522sync(Log) ->
523    wlr_logger ! {sync, self(), Log},
524    rec(ok, ?LINE).
525
526log_terms(File, Terms) ->
527    wlr_logger ! {log_terms, self(), File, Terms},
528    rec(ok, ?LINE).
529
530blog_terms(File, Terms) ->
531    wlr_logger ! {blog_terms, self(), File, Terms},
532    rec(ok, ?LINE).
533
534rec1(M, Where) ->
535    receive
536        {M, C} -> C;
537        Else -> ct:fail({error, {Where, Else}})
538    after 1000  -> ct:fail({error, {Where, time_out}})
539    end.
540
541rec2(M, Where) ->
542    receive
543        {C, M} -> C;
544        Else -> ct:fail({error, {Where, Else}})
545    after 1000  -> ct:fail({error, {Where, time_out}})
546    end.
547
548rec(M, Where) ->
549    receive
550        M ->
551            ok;
552        Else -> ct:fail({error, {Where, Else}})
553    after 5000 -> ct:fail({error, {Where, time_out}})
554    end.
555
556check_pps({Ports0,Procs0} = P0) ->
557    case pps() of
558        P0 ->
559            ok;
560        _ ->
561            timer:sleep(500),
562            case pps() of
563                P0 ->
564                    ok;
565                {Ports1,Procs1} = P1 ->
566		    case {Ports1 -- Ports0, Procs1 -- Procs0} of
567			{[], []} -> ok;
568			{PortsDiff,ProcsDiff} ->
569			    io:format("failure, got ~p~n, expected ~p\n", [P1, P0]),
570			    show("Old port", Ports0 -- Ports1),
571			    show("New port", PortsDiff),
572			    show("Old proc", Procs0 -- Procs1),
573			    show("New proc", ProcsDiff),
574			    ct:fail(failed)
575		    end
576	    end
577    end.
578
579show(_S, []) ->
580    ok;
581show(S, [{Pid, Name, InitCall}|Pids]) when is_pid(Pid) ->
582    io:format("~s: ~w (~w), ~w: ~p~n",
583              [S, Pid, proc_reg_name(Name), InitCall,
584               erlang:process_info(Pid)]),
585    show(S, Pids);
586show(S, [{Port, _}|Ports]) when is_port(Port)->
587    io:format("~s: ~w: ~p~n", [S, Port, erlang:port_info(Port)]),
588    show(S, Ports).
589
590pps() ->
591    timer:sleep(100),
592    {port_list(), process_list()}.
593
594port_list() ->
595    [{P,safe_second_element(erlang:port_info(P, name))} ||
596        P <- erlang:ports()].
597
598process_list() ->
599    [{P,process_info(P, registered_name),
600      safe_second_element(process_info(P, initial_call))} ||
601        P <- processes(), erlang:is_process_alive(P)].
602
603proc_reg_name({registered_name, Name}) -> Name;
604proc_reg_name([]) -> no_reg_name.
605
606safe_second_element({_,Info}) -> Info;
607safe_second_element(Other) -> Other.
608