1 /*
2  * Copyright (C) 2019 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package com.android.internal.protolog;
18 
19 import static androidx.test.platform.app.InstrumentationRegistry.getInstrumentation;
20 
21 import static com.android.internal.protolog.ProtoLogImpl.PROTOLOG_VERSION;
22 
23 import static org.junit.Assert.assertArrayEquals;
24 import static org.junit.Assert.assertEquals;
25 import static org.junit.Assert.assertFalse;
26 import static org.junit.Assert.assertNotNull;
27 import static org.junit.Assert.assertNull;
28 import static org.junit.Assert.assertSame;
29 import static org.junit.Assert.assertTrue;
30 import static org.mockito.ArgumentMatchers.any;
31 import static org.mockito.ArgumentMatchers.anyInt;
32 import static org.mockito.ArgumentMatchers.eq;
33 import static org.mockito.Mockito.mock;
34 import static org.mockito.Mockito.never;
35 import static org.mockito.Mockito.verify;
36 import static org.mockito.Mockito.when;
37 
38 import android.content.Context;
39 import android.os.SystemClock;
40 import android.platform.test.annotations.Presubmit;
41 import android.util.proto.ProtoInputStream;
42 
43 import androidx.test.filters.SmallTest;
44 
45 import com.android.internal.protolog.common.IProtoLogGroup;
46 
47 import org.junit.After;
48 import org.junit.Before;
49 import org.junit.Test;
50 import org.junit.runner.RunWith;
51 import org.junit.runners.JUnit4;
52 import org.mockito.Mock;
53 import org.mockito.Mockito;
54 import org.mockito.MockitoAnnotations;
55 
56 import java.io.File;
57 import java.io.FileInputStream;
58 import java.io.IOException;
59 import java.io.InputStream;
60 import java.io.PrintWriter;
61 import java.util.LinkedList;
62 
63 /**
64  * Test class for {@link ProtoLogImpl}.
65  */
66 @SuppressWarnings("ConstantConditions")
67 @SmallTest
68 @Presubmit
69 @RunWith(JUnit4.class)
70 public class ProtoLogImplTest {
71 
72     private static final byte[] MAGIC_HEADER = new byte[]{
73             0x9, 0x50, 0x52, 0x4f, 0x54, 0x4f, 0x4c, 0x4f, 0x47
74     };
75 
76     private ProtoLogImpl mProtoLog;
77     private File mFile;
78 
79     @Mock
80     private ProtoLogViewerConfigReader mReader;
81 
82     @Before
setUp()83     public void setUp() throws Exception {
84         MockitoAnnotations.initMocks(this);
85         final Context testContext = getInstrumentation().getContext();
86         mFile = testContext.getFileStreamPath("tracing_test.dat");
87         //noinspection ResultOfMethodCallIgnored
88         mFile.delete();
89         mProtoLog = new ProtoLogImpl(mFile, 1024 * 1024, mReader, 1024);
90     }
91 
92     @After
tearDown()93     public void tearDown() {
94         if (mFile != null) {
95             //noinspection ResultOfMethodCallIgnored
96             mFile.delete();
97         }
98         ProtoLogImpl.setSingleInstance(null);
99     }
100 
101     @Test
isEnabled_returnsFalseByDefault()102     public void isEnabled_returnsFalseByDefault() {
103         assertFalse(mProtoLog.isProtoEnabled());
104     }
105 
106     @Test
isEnabled_returnsTrueAfterStart()107     public void isEnabled_returnsTrueAfterStart() {
108         mProtoLog.startProtoLog(mock(PrintWriter.class));
109         assertTrue(mProtoLog.isProtoEnabled());
110     }
111 
112     @Test
isEnabled_returnsFalseAfterStop()113     public void isEnabled_returnsFalseAfterStop() {
114         mProtoLog.startProtoLog(mock(PrintWriter.class));
115         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
116         assertFalse(mProtoLog.isProtoEnabled());
117     }
118 
119     @Test
logFile_startsWithMagicHeader()120     public void logFile_startsWithMagicHeader() throws Exception {
121         mProtoLog.startProtoLog(mock(PrintWriter.class));
122         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
123 
124         assertTrue("Log file should exist", mFile.exists());
125 
126         byte[] header = new byte[MAGIC_HEADER.length];
127         try (InputStream is = new FileInputStream(mFile)) {
128             assertEquals(MAGIC_HEADER.length, is.read(header));
129             assertArrayEquals(MAGIC_HEADER, header);
130         }
131     }
132 
133     @Test
getSingleInstance()134     public void getSingleInstance() {
135         ProtoLogImpl mockedProtoLog = mock(ProtoLogImpl.class);
136         ProtoLogImpl.setSingleInstance(mockedProtoLog);
137         assertSame(mockedProtoLog, ProtoLogImpl.getSingleInstance());
138     }
139 
140     @Test
d_logCalled()141     public void d_logCalled() {
142         ProtoLogImpl mockedProtoLog = mock(ProtoLogImpl.class);
143         ProtoLogImpl.setSingleInstance(mockedProtoLog);
144         ProtoLogImpl.d(TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d");
145         verify(mockedProtoLog).log(eq(ProtoLogImpl.LogLevel.DEBUG), eq(
146                 TestProtoLogGroup.TEST_GROUP),
147                 eq(1234), eq(4321), eq("test %d"), eq(new Object[]{}));
148     }
149 
150     @Test
v_logCalled()151     public void v_logCalled() {
152         ProtoLogImpl mockedProtoLog = mock(ProtoLogImpl.class);
153         ProtoLogImpl.setSingleInstance(mockedProtoLog);
154         ProtoLogImpl.v(TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d");
155         verify(mockedProtoLog).log(eq(ProtoLogImpl.LogLevel.VERBOSE), eq(
156                 TestProtoLogGroup.TEST_GROUP),
157                 eq(1234), eq(4321), eq("test %d"), eq(new Object[]{}));
158     }
159 
160     @Test
i_logCalled()161     public void i_logCalled() {
162         ProtoLogImpl mockedProtoLog = mock(ProtoLogImpl.class);
163         ProtoLogImpl.setSingleInstance(mockedProtoLog);
164         ProtoLogImpl.i(TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d");
165         verify(mockedProtoLog).log(eq(ProtoLogImpl.LogLevel.INFO), eq(
166                 TestProtoLogGroup.TEST_GROUP),
167                 eq(1234), eq(4321), eq("test %d"), eq(new Object[]{}));
168     }
169 
170     @Test
w_logCalled()171     public void w_logCalled() {
172         ProtoLogImpl mockedProtoLog = mock(ProtoLogImpl.class);
173         ProtoLogImpl.setSingleInstance(mockedProtoLog);
174         ProtoLogImpl.w(TestProtoLogGroup.TEST_GROUP, 1234,
175                 4321, "test %d");
176         verify(mockedProtoLog).log(eq(ProtoLogImpl.LogLevel.WARN), eq(
177                 TestProtoLogGroup.TEST_GROUP),
178                 eq(1234), eq(4321), eq("test %d"), eq(new Object[]{}));
179     }
180 
181     @Test
e_logCalled()182     public void e_logCalled() {
183         ProtoLogImpl mockedProtoLog = mock(ProtoLogImpl.class);
184         ProtoLogImpl.setSingleInstance(mockedProtoLog);
185         ProtoLogImpl.e(TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d");
186         verify(mockedProtoLog).log(eq(ProtoLogImpl.LogLevel.ERROR), eq(
187                 TestProtoLogGroup.TEST_GROUP),
188                 eq(1234), eq(4321), eq("test %d"), eq(new Object[]{}));
189     }
190 
191     @Test
wtf_logCalled()192     public void wtf_logCalled() {
193         ProtoLogImpl mockedProtoLog = mock(ProtoLogImpl.class);
194         ProtoLogImpl.setSingleInstance(mockedProtoLog);
195         ProtoLogImpl.wtf(TestProtoLogGroup.TEST_GROUP,
196                 1234, 4321, "test %d");
197         verify(mockedProtoLog).log(eq(ProtoLogImpl.LogLevel.WTF), eq(
198                 TestProtoLogGroup.TEST_GROUP),
199                 eq(1234), eq(4321), eq("test %d"), eq(new Object[]{}));
200     }
201 
202     @Test
log_logcatEnabledExternalMessage()203     public void log_logcatEnabledExternalMessage() {
204         when(mReader.getViewerString(anyInt())).thenReturn("test %b %d %% 0x%x %s %f");
205         ProtoLogImpl implSpy = Mockito.spy(mProtoLog);
206         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true);
207         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
208 
209         implSpy.log(
210                 ProtoLogImpl.LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null,
211                 new Object[]{true, 10000, 30000, "test", 0.000003});
212 
213         verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq(
214                 ProtoLogImpl.LogLevel.INFO),
215                 eq("test true 10000 % 0x7530 test 3.0E-6"));
216         verify(mReader).getViewerString(eq(1234));
217     }
218 
219     @Test
log_logcatEnabledInvalidMessage()220     public void log_logcatEnabledInvalidMessage() {
221         when(mReader.getViewerString(anyInt())).thenReturn("test %b %d %% %x %s %f");
222         ProtoLogImpl implSpy = Mockito.spy(mProtoLog);
223         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true);
224         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
225 
226         implSpy.log(
227                 ProtoLogImpl.LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null,
228                 new Object[]{true, 10000, 0.0001, 0.00002, "test"});
229 
230         verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq(
231                 ProtoLogImpl.LogLevel.INFO),
232                 eq("UNKNOWN MESSAGE (1234) true 10000 1.0E-4 2.0E-5 test"));
233         verify(mReader).getViewerString(eq(1234));
234     }
235 
236     @Test
log_logcatEnabledInlineMessage()237     public void log_logcatEnabledInlineMessage() {
238         when(mReader.getViewerString(anyInt())).thenReturn("test %d");
239         ProtoLogImpl implSpy = Mockito.spy(mProtoLog);
240         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true);
241         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
242 
243         implSpy.log(
244                 ProtoLogImpl.LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d",
245                 new Object[]{5});
246 
247         verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq(
248                 ProtoLogImpl.LogLevel.INFO), eq("test 5"));
249         verify(mReader, never()).getViewerString(anyInt());
250     }
251 
252     @Test
log_logcatEnabledNoMessage()253     public void log_logcatEnabledNoMessage() {
254         when(mReader.getViewerString(anyInt())).thenReturn(null);
255         ProtoLogImpl implSpy = Mockito.spy(mProtoLog);
256         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true);
257         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
258 
259         implSpy.log(
260                 ProtoLogImpl.LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null,
261                 new Object[]{5});
262 
263         verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq(
264                 ProtoLogImpl.LogLevel.INFO), eq("UNKNOWN MESSAGE (1234) 5"));
265         verify(mReader).getViewerString(eq(1234));
266     }
267 
268     @Test
log_logcatDisabled()269     public void log_logcatDisabled() {
270         when(mReader.getViewerString(anyInt())).thenReturn("test %d");
271         ProtoLogImpl implSpy = Mockito.spy(mProtoLog);
272         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false);
273         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
274 
275         implSpy.log(
276                 ProtoLogImpl.LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d",
277                 new Object[]{5});
278 
279         verify(implSpy, never()).passToLogcat(any(), any(), any());
280         verify(mReader, never()).getViewerString(anyInt());
281     }
282 
283     private static class ProtoLogData {
284         Integer mMessageHash = null;
285         Long mElapsedTime = null;
286         LinkedList<String> mStrParams = new LinkedList<>();
287         LinkedList<Long> mSint64Params = new LinkedList<>();
288         LinkedList<Double> mDoubleParams = new LinkedList<>();
289         LinkedList<Boolean> mBooleanParams = new LinkedList<>();
290     }
291 
readProtoLogSingle(ProtoInputStream ip)292     private ProtoLogData readProtoLogSingle(ProtoInputStream ip) throws IOException {
293         while (ip.nextField() != ProtoInputStream.NO_MORE_FIELDS) {
294             if (ip.getFieldNumber() == (int) ProtoLogFileProto.VERSION) {
295                 assertEquals(PROTOLOG_VERSION, ip.readString(ProtoLogFileProto.VERSION));
296                 continue;
297             }
298             if (ip.getFieldNumber() != (int) ProtoLogFileProto.LOG) {
299                 continue;
300             }
301             long token = ip.start(ProtoLogFileProto.LOG);
302             ProtoLogData data = new ProtoLogData();
303             while (ip.nextField() != ProtoInputStream.NO_MORE_FIELDS) {
304                 switch (ip.getFieldNumber()) {
305                     case (int) ProtoLogMessage.MESSAGE_HASH: {
306                         data.mMessageHash = ip.readInt(ProtoLogMessage.MESSAGE_HASH);
307                         break;
308                     }
309                     case (int) ProtoLogMessage.ELAPSED_REALTIME_NANOS: {
310                         data.mElapsedTime = ip.readLong(ProtoLogMessage.ELAPSED_REALTIME_NANOS);
311                         break;
312                     }
313                     case (int) ProtoLogMessage.STR_PARAMS: {
314                         data.mStrParams.add(ip.readString(ProtoLogMessage.STR_PARAMS));
315                         break;
316                     }
317                     case (int) ProtoLogMessage.SINT64_PARAMS: {
318                         data.mSint64Params.add(ip.readLong(ProtoLogMessage.SINT64_PARAMS));
319                         break;
320                     }
321                     case (int) ProtoLogMessage.DOUBLE_PARAMS: {
322                         data.mDoubleParams.add(ip.readDouble(ProtoLogMessage.DOUBLE_PARAMS));
323                         break;
324                     }
325                     case (int) ProtoLogMessage.BOOLEAN_PARAMS: {
326                         data.mBooleanParams.add(ip.readBoolean(ProtoLogMessage.BOOLEAN_PARAMS));
327                         break;
328                     }
329                 }
330             }
331             ip.end(token);
332             return data;
333         }
334         return null;
335     }
336 
337     @Test
log_protoEnabled()338     public void log_protoEnabled() throws Exception {
339         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false);
340         TestProtoLogGroup.TEST_GROUP.setLogToProto(true);
341         mProtoLog.startProtoLog(mock(PrintWriter.class));
342         long before = SystemClock.elapsedRealtimeNanos();
343         mProtoLog.log(
344                 ProtoLogImpl.LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234,
345                 0b1110101001010100, null,
346                 new Object[]{"test", 1, 2, 3, 0.4, 0.5, 0.6, true});
347         long after = SystemClock.elapsedRealtimeNanos();
348         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
349         try (InputStream is = new FileInputStream(mFile)) {
350             ProtoInputStream ip = new ProtoInputStream(is);
351             ProtoLogData data = readProtoLogSingle(ip);
352             assertNotNull(data);
353             assertEquals(1234, data.mMessageHash.longValue());
354             assertTrue(before <= data.mElapsedTime && data.mElapsedTime <= after);
355             assertArrayEquals(new String[]{"test"}, data.mStrParams.toArray());
356             assertArrayEquals(new Long[]{1L, 2L, 3L}, data.mSint64Params.toArray());
357             assertArrayEquals(new Double[]{0.4, 0.5, 0.6}, data.mDoubleParams.toArray());
358             assertArrayEquals(new Boolean[]{true}, data.mBooleanParams.toArray());
359         }
360     }
361 
362     @Test
log_invalidParamsMask()363     public void log_invalidParamsMask() throws Exception {
364         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false);
365         TestProtoLogGroup.TEST_GROUP.setLogToProto(true);
366         mProtoLog.startProtoLog(mock(PrintWriter.class));
367         long before = SystemClock.elapsedRealtimeNanos();
368         mProtoLog.log(
369                 ProtoLogImpl.LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234,
370                 0b01100100, null,
371                 new Object[]{"test", 1, 0.1, true});
372         long after = SystemClock.elapsedRealtimeNanos();
373         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
374         try (InputStream is = new FileInputStream(mFile)) {
375             ProtoInputStream ip = new ProtoInputStream(is);
376             ProtoLogData data = readProtoLogSingle(ip);
377             assertNotNull(data);
378             assertEquals(1234, data.mMessageHash.longValue());
379             assertTrue(before <= data.mElapsedTime && data.mElapsedTime <= after);
380             assertArrayEquals(new String[]{"test", "(INVALID PARAMS_MASK) true"},
381                     data.mStrParams.toArray());
382             assertArrayEquals(new Long[]{1L}, data.mSint64Params.toArray());
383             assertArrayEquals(new Double[]{0.1}, data.mDoubleParams.toArray());
384             assertArrayEquals(new Boolean[]{}, data.mBooleanParams.toArray());
385         }
386     }
387 
388     @Test
log_protoDisabled()389     public void log_protoDisabled() throws Exception {
390         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false);
391         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
392         mProtoLog.startProtoLog(mock(PrintWriter.class));
393         mProtoLog.log(ProtoLogImpl.LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234,
394                 0b11, null, new Object[]{true});
395         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
396         try (InputStream is = new FileInputStream(mFile)) {
397             ProtoInputStream ip = new ProtoInputStream(is);
398             ProtoLogData data = readProtoLogSingle(ip);
399             assertNull(data);
400         }
401     }
402 
403     private enum TestProtoLogGroup implements IProtoLogGroup {
404         TEST_GROUP(true, true, false, "WindowManagetProtoLogTest");
405 
406         private final boolean mEnabled;
407         private volatile boolean mLogToProto;
408         private volatile boolean mLogToLogcat;
409         private final String mTag;
410 
411         /**
412          * @param enabled     set to false to exclude all log statements for this group from
413          *                    compilation,
414          *                    they will not be available in runtime.
415          * @param logToProto  enable binary logging for the group
416          * @param logToLogcat enable text logging for the group
417          * @param tag         name of the source of the logged message
418          */
TestProtoLogGroup(boolean enabled, boolean logToProto, boolean logToLogcat, String tag)419         TestProtoLogGroup(boolean enabled, boolean logToProto, boolean logToLogcat, String tag) {
420             this.mEnabled = enabled;
421             this.mLogToProto = logToProto;
422             this.mLogToLogcat = logToLogcat;
423             this.mTag = tag;
424         }
425 
426         @Override
isEnabled()427         public boolean isEnabled() {
428             return mEnabled;
429         }
430 
431         @Override
isLogToProto()432         public boolean isLogToProto() {
433             return mLogToProto;
434         }
435 
436         @Override
isLogToLogcat()437         public boolean isLogToLogcat() {
438             return mLogToLogcat;
439         }
440 
441         @Override
isLogToAny()442         public boolean isLogToAny() {
443             return mLogToLogcat || mLogToProto;
444         }
445 
446         @Override
getTag()447         public String getTag() {
448             return mTag;
449         }
450 
451         @Override
setLogToProto(boolean logToProto)452         public void setLogToProto(boolean logToProto) {
453             this.mLogToProto = logToProto;
454         }
455 
456         @Override
setLogToLogcat(boolean logToLogcat)457         public void setLogToLogcat(boolean logToLogcat) {
458             this.mLogToLogcat = logToLogcat;
459         }
460 
461     }
462 }
463