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.LegacyProtoLogImpl.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.assertTrue;
29 import static org.mockito.ArgumentMatchers.any;
30 import static org.mockito.ArgumentMatchers.anyLong;
31 import static org.mockito.ArgumentMatchers.eq;
32 import static org.mockito.Mockito.mock;
33 import static org.mockito.Mockito.never;
34 import static org.mockito.Mockito.verify;
35 import static org.mockito.Mockito.when;
36 
37 import android.content.Context;
38 import android.os.SystemClock;
39 import android.platform.test.annotations.Presubmit;
40 import android.util.proto.ProtoInputStream;
41 
42 import androidx.test.filters.SmallTest;
43 
44 import com.android.internal.protolog.common.IProtoLogGroup;
45 import com.android.internal.protolog.common.LogLevel;
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 import java.util.TreeMap;
63 
64 /**
65  * Test class for {@link ProtoLogImpl}.
66  */
67 @SuppressWarnings("ConstantConditions")
68 @SmallTest
69 @Presubmit
70 @RunWith(JUnit4.class)
71 public class LegacyProtoLogImplTest {
72 
73     private static final byte[] MAGIC_HEADER = new byte[]{
74             0x9, 0x50, 0x52, 0x4f, 0x54, 0x4f, 0x4c, 0x4f, 0x47
75     };
76 
77     private LegacyProtoLogImpl mProtoLog;
78     private File mFile;
79 
80     @Mock
81     private LegacyProtoLogViewerConfigReader mReader;
82 
83     private final String mViewerConfigFilename = "unused/file/path";
84 
85     @Before
setUp()86     public void setUp() throws Exception {
87         MockitoAnnotations.initMocks(this);
88         final Context testContext = getInstrumentation().getContext();
89         mFile = testContext.getFileStreamPath("tracing_test.dat");
90         //noinspection ResultOfMethodCallIgnored
91         mFile.delete();
92         mProtoLog = new LegacyProtoLogImpl(mFile, mViewerConfigFilename,
93                 1024 * 1024, mReader, 1024, new TreeMap<>(), () -> {});
94     }
95 
96     @After
tearDown()97     public void tearDown() {
98         if (mFile != null) {
99             //noinspection ResultOfMethodCallIgnored
100             mFile.delete();
101         }
102         ProtoLogImpl.setSingleInstance(null);
103     }
104 
105     @Test
isEnabled_returnsFalseByDefault()106     public void isEnabled_returnsFalseByDefault() {
107         assertFalse(mProtoLog.isProtoEnabled());
108     }
109 
110     @Test
isEnabled_returnsTrueAfterStart()111     public void isEnabled_returnsTrueAfterStart() {
112         mProtoLog.startProtoLog(mock(PrintWriter.class));
113         assertTrue(mProtoLog.isProtoEnabled());
114     }
115 
116     @Test
isEnabled_returnsFalseAfterStop()117     public void isEnabled_returnsFalseAfterStop() {
118         mProtoLog.startProtoLog(mock(PrintWriter.class));
119         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
120         assertFalse(mProtoLog.isProtoEnabled());
121     }
122 
123     @Test
logFile_startsWithMagicHeader()124     public void logFile_startsWithMagicHeader() throws Exception {
125         mProtoLog.startProtoLog(mock(PrintWriter.class));
126         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
127 
128         assertTrue("Log file should exist", mFile.exists());
129 
130         byte[] header = new byte[MAGIC_HEADER.length];
131         try (InputStream is = new FileInputStream(mFile)) {
132             assertEquals(MAGIC_HEADER.length, is.read(header));
133             assertArrayEquals(MAGIC_HEADER, header);
134         }
135     }
136 
137     @Test
log_logcatEnabledExternalMessage()138     public void log_logcatEnabledExternalMessage() {
139         when(mReader.getViewerString(anyLong())).thenReturn("test %b %d %% 0x%x %s %f");
140         LegacyProtoLogImpl implSpy = Mockito.spy(mProtoLog);
141         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true);
142         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
143 
144         implSpy.log(
145                 LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null,
146                 new Object[]{true, 10000, 30000, "test", 0.000003});
147 
148         verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq(
149                 LogLevel.INFO),
150                 eq("test true 10000 % 0x7530 test 3.0E-6"));
151         verify(mReader).getViewerString(eq(1234L));
152     }
153 
154     @Test
log_logcatEnabledInvalidMessage()155     public void log_logcatEnabledInvalidMessage() {
156         when(mReader.getViewerString(anyLong())).thenReturn("test %b %d %% %x %s %f");
157         LegacyProtoLogImpl implSpy = Mockito.spy(mProtoLog);
158         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true);
159         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
160 
161         implSpy.log(
162                 LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null,
163                 new Object[]{true, 10000, 0.0001, 0.00002, "test"});
164 
165         verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq(
166                 LogLevel.INFO),
167                 eq("UNKNOWN MESSAGE (1234) true 10000 1.0E-4 2.0E-5 test"));
168         verify(mReader).getViewerString(eq(1234L));
169     }
170 
171     @Test
log_logcatEnabledInlineMessage()172     public void log_logcatEnabledInlineMessage() {
173         when(mReader.getViewerString(anyLong())).thenReturn("test %d");
174         LegacyProtoLogImpl implSpy = Mockito.spy(mProtoLog);
175         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true);
176         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
177 
178         implSpy.log(
179                 LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d",
180                 new Object[]{5});
181 
182         verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq(
183                 LogLevel.INFO), eq("test 5"));
184         verify(mReader, never()).getViewerString(anyLong());
185     }
186 
187     @Test
log_logcatEnabledNoMessage()188     public void log_logcatEnabledNoMessage() {
189         when(mReader.getViewerString(anyLong())).thenReturn(null);
190         LegacyProtoLogImpl implSpy = Mockito.spy(mProtoLog);
191         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(true);
192         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
193 
194         implSpy.log(
195                 LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, null,
196                 new Object[]{5});
197 
198         verify(implSpy).passToLogcat(eq(TestProtoLogGroup.TEST_GROUP.getTag()), eq(
199                 LogLevel.INFO), eq("UNKNOWN MESSAGE (1234) 5"));
200         verify(mReader).getViewerString(eq(1234L));
201     }
202 
203     @Test
log_logcatDisabled()204     public void log_logcatDisabled() {
205         when(mReader.getViewerString(anyLong())).thenReturn("test %d");
206         LegacyProtoLogImpl implSpy = Mockito.spy(mProtoLog);
207         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false);
208         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
209 
210         implSpy.log(
211                 LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234, 4321, "test %d",
212                 new Object[]{5});
213 
214         verify(implSpy, never()).passToLogcat(any(), any(), any());
215         verify(mReader, never()).getViewerString(anyLong());
216     }
217 
218     private static class ProtoLogData {
219         Long mMessageHash = null;
220         Long mElapsedTime = null;
221         LinkedList<String> mStrParams = new LinkedList<>();
222         LinkedList<Long> mSint64Params = new LinkedList<>();
223         LinkedList<Double> mDoubleParams = new LinkedList<>();
224         LinkedList<Boolean> mBooleanParams = new LinkedList<>();
225     }
226 
readProtoLogSingle(ProtoInputStream ip)227     private ProtoLogData readProtoLogSingle(ProtoInputStream ip) throws IOException {
228         while (ip.nextField() != ProtoInputStream.NO_MORE_FIELDS) {
229             if (ip.getFieldNumber() == (int) ProtoLogFileProto.VERSION) {
230                 assertEquals(PROTOLOG_VERSION, ip.readString(ProtoLogFileProto.VERSION));
231                 continue;
232             }
233             if (ip.getFieldNumber() != (int) ProtoLogFileProto.LOG) {
234                 continue;
235             }
236             long token = ip.start(ProtoLogFileProto.LOG);
237             ProtoLogData data = new ProtoLogData();
238             while (ip.nextField() != ProtoInputStream.NO_MORE_FIELDS) {
239                 switch (ip.getFieldNumber()) {
240                     case (int) ProtoLogMessage.MESSAGE_HASH: {
241                         data.mMessageHash = ip.readLong(ProtoLogMessage.MESSAGE_HASH);
242                         break;
243                     }
244                     case (int) ProtoLogMessage.ELAPSED_REALTIME_NANOS: {
245                         data.mElapsedTime = ip.readLong(ProtoLogMessage.ELAPSED_REALTIME_NANOS);
246                         break;
247                     }
248                     case (int) ProtoLogMessage.STR_PARAMS: {
249                         data.mStrParams.add(ip.readString(ProtoLogMessage.STR_PARAMS));
250                         break;
251                     }
252                     case (int) ProtoLogMessage.SINT64_PARAMS: {
253                         data.mSint64Params.add(ip.readLong(ProtoLogMessage.SINT64_PARAMS));
254                         break;
255                     }
256                     case (int) ProtoLogMessage.DOUBLE_PARAMS: {
257                         data.mDoubleParams.add(ip.readDouble(ProtoLogMessage.DOUBLE_PARAMS));
258                         break;
259                     }
260                     case (int) ProtoLogMessage.BOOLEAN_PARAMS: {
261                         data.mBooleanParams.add(ip.readBoolean(ProtoLogMessage.BOOLEAN_PARAMS));
262                         break;
263                     }
264                 }
265             }
266             ip.end(token);
267             return data;
268         }
269         return null;
270     }
271 
272     @Test
log_protoEnabled()273     public void log_protoEnabled() throws Exception {
274         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false);
275         TestProtoLogGroup.TEST_GROUP.setLogToProto(true);
276         mProtoLog.startProtoLog(mock(PrintWriter.class));
277         long before = SystemClock.elapsedRealtimeNanos();
278         mProtoLog.log(
279                 LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234,
280                 0b1110101001010100, null,
281                 new Object[]{"test", 1, 2, 3, 0.4, 0.5, 0.6, true});
282         long after = SystemClock.elapsedRealtimeNanos();
283         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
284         try (InputStream is = new FileInputStream(mFile)) {
285             ProtoInputStream ip = new ProtoInputStream(is);
286             ProtoLogData data = readProtoLogSingle(ip);
287             assertNotNull(data);
288             assertEquals(1234, data.mMessageHash.longValue());
289             assertTrue(before <= data.mElapsedTime && data.mElapsedTime <= after);
290             assertArrayEquals(new String[]{"test"}, data.mStrParams.toArray());
291             assertArrayEquals(new Long[]{1L, 2L, 3L}, data.mSint64Params.toArray());
292             assertArrayEquals(new Double[]{0.4, 0.5, 0.6}, data.mDoubleParams.toArray());
293             assertArrayEquals(new Boolean[]{true}, data.mBooleanParams.toArray());
294         }
295     }
296 
297     @Test
log_invalidParamsMask()298     public void log_invalidParamsMask() throws Exception {
299         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false);
300         TestProtoLogGroup.TEST_GROUP.setLogToProto(true);
301         mProtoLog.startProtoLog(mock(PrintWriter.class));
302         long before = SystemClock.elapsedRealtimeNanos();
303         mProtoLog.log(
304                 LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234,
305                 0b01100100, null,
306                 new Object[]{"test", 1, 0.1, true});
307         long after = SystemClock.elapsedRealtimeNanos();
308         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
309         try (InputStream is = new FileInputStream(mFile)) {
310             ProtoInputStream ip = new ProtoInputStream(is);
311             ProtoLogData data = readProtoLogSingle(ip);
312             assertNotNull(data);
313             assertEquals(1234, data.mMessageHash.longValue());
314             assertTrue(before <= data.mElapsedTime && data.mElapsedTime <= after);
315             assertArrayEquals(new String[]{"test", "(INVALID PARAMS_MASK) true"},
316                     data.mStrParams.toArray());
317             assertArrayEquals(new Long[]{1L}, data.mSint64Params.toArray());
318             assertArrayEquals(new Double[]{0.1}, data.mDoubleParams.toArray());
319             assertArrayEquals(new Boolean[]{}, data.mBooleanParams.toArray());
320         }
321     }
322 
323     @Test
log_protoDisabled()324     public void log_protoDisabled() throws Exception {
325         TestProtoLogGroup.TEST_GROUP.setLogToLogcat(false);
326         TestProtoLogGroup.TEST_GROUP.setLogToProto(false);
327         mProtoLog.startProtoLog(mock(PrintWriter.class));
328         mProtoLog.log(LogLevel.INFO, TestProtoLogGroup.TEST_GROUP, 1234,
329                 0b11, null, new Object[]{true});
330         mProtoLog.stopProtoLog(mock(PrintWriter.class), true);
331         try (InputStream is = new FileInputStream(mFile)) {
332             ProtoInputStream ip = new ProtoInputStream(is);
333             ProtoLogData data = readProtoLogSingle(ip);
334             assertNull(data);
335         }
336     }
337 
338     private enum TestProtoLogGroup implements IProtoLogGroup {
339         TEST_GROUP(true, true, false, "WindowManagetProtoLogTest");
340 
341         private final boolean mEnabled;
342         private volatile boolean mLogToProto;
343         private volatile boolean mLogToLogcat;
344         private final String mTag;
345 
346         /**
347          * @param enabled     set to false to exclude all log statements for this group from
348          *                    compilation,
349          *                    they will not be available in runtime.
350          * @param logToProto  enable binary logging for the group
351          * @param logToLogcat enable text logging for the group
352          * @param tag         name of the source of the logged message
353          */
TestProtoLogGroup(boolean enabled, boolean logToProto, boolean logToLogcat, String tag)354         TestProtoLogGroup(boolean enabled, boolean logToProto, boolean logToLogcat, String tag) {
355             this.mEnabled = enabled;
356             this.mLogToProto = logToProto;
357             this.mLogToLogcat = logToLogcat;
358             this.mTag = tag;
359         }
360 
361         @Override
isEnabled()362         public boolean isEnabled() {
363             return mEnabled;
364         }
365 
366         @Override
isLogToProto()367         public boolean isLogToProto() {
368             return mLogToProto;
369         }
370 
371         @Override
isLogToLogcat()372         public boolean isLogToLogcat() {
373             return mLogToLogcat;
374         }
375 
376         @Override
isLogToAny()377         public boolean isLogToAny() {
378             return mLogToLogcat || mLogToProto;
379         }
380 
381         @Override
getTag()382         public String getTag() {
383             return mTag;
384         }
385 
386         @Override
setLogToProto(boolean logToProto)387         public void setLogToProto(boolean logToProto) {
388             this.mLogToProto = logToProto;
389         }
390 
391         @Override
setLogToLogcat(boolean logToLogcat)392         public void setLogToLogcat(boolean logToLogcat) {
393             this.mLogToLogcat = logToLogcat;
394         }
395 
396         @Override
getId()397         public int getId() {
398             return ordinal();
399         }
400 
401     }
402 }
403