1 /*
2  * Copyright (C) 2018 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 #define LOG_TAG "NBLog"
18 //#define LOG_NDEBUG 0
19 
20 #include <stdarg.h>
21 #include <stddef.h>
22 #include <sys/prctl.h>
23 
24 #include <audio_utils/fifo.h>
25 #include <binder/IMemory.h>
26 #include <media/nblog/Entry.h>
27 #include <media/nblog/Events.h>
28 #include <media/nblog/Timeline.h>
29 #include <media/nblog/Writer.h>
30 #include <utils/Log.h>
31 #include <utils/Mutex.h>
32 
33 namespace android {
34 namespace NBLog {
35 
Writer(void * shared,size_t size)36 Writer::Writer(void *shared, size_t size)
37     : mShared((Shared *) shared),
38       mFifo(mShared != NULL ?
39         new audio_utils_fifo(size, sizeof(uint8_t),
40             mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL),
41       mFifoWriter(mFifo != NULL ? new audio_utils_fifo_writer(*mFifo) : NULL),
42       mEnabled(mFifoWriter != NULL)
43 {
44     // caching pid and process name
45     pid_t id = ::getpid();
46     char procName[16];
47     int status = prctl(PR_GET_NAME, procName);
48     if (status) {  // error getting process name
49         procName[0] = '\0';
50     }
51     size_t length = strlen(procName);
52     mPidTagSize = length + sizeof(pid_t);
53     mPidTag = new char[mPidTagSize];
54     memcpy(mPidTag, &id, sizeof(pid_t));
55     memcpy(mPidTag + sizeof(pid_t), procName, length);
56 }
57 
Writer(const sp<IMemory> & iMemory,size_t size)58 Writer::Writer(const sp<IMemory>& iMemory, size_t size)
59     : Writer(iMemory != 0 ? (Shared *) iMemory->pointer() : NULL, size)
60 {
61     mIMemory = iMemory;
62 }
63 
~Writer()64 Writer::~Writer()
65 {
66     delete mFifoWriter;
67     delete mFifo;
68     delete[] mPidTag;
69 }
70 
log(const char * string)71 void Writer::log(const char *string)
72 {
73     if (!mEnabled) {
74         return;
75     }
76     LOG_ALWAYS_FATAL_IF(string == NULL, "Attempted to log NULL string");
77     size_t length = strlen(string);
78     if (length > Entry::kMaxLength) {
79         length = Entry::kMaxLength;
80     }
81     log(EVENT_STRING, string, length);
82 }
83 
logf(const char * fmt,...)84 void Writer::logf(const char *fmt, ...)
85 {
86     if (!mEnabled) {
87         return;
88     }
89     va_list ap;
90     va_start(ap, fmt);
91     Writer::logvf(fmt, ap);     // the Writer:: is needed to avoid virtual dispatch for LockedWriter
92     va_end(ap);
93 }
94 
logTimestamp()95 void Writer::logTimestamp()
96 {
97     if (!mEnabled) {
98         return;
99     }
100     struct timespec ts;
101     if (!clock_gettime(CLOCK_MONOTONIC, &ts)) {
102         log(EVENT_TIMESTAMP, &ts, sizeof(ts));
103     }
104 }
105 
logFormat(const char * fmt,log_hash_t hash,...)106 void Writer::logFormat(const char *fmt, log_hash_t hash, ...)
107 {
108     if (!mEnabled) {
109         return;
110     }
111     va_list ap;
112     va_start(ap, hash);
113     Writer::logVFormat(fmt, hash, ap);
114     va_end(ap);
115 }
116 
logEventHistTs(Event event,log_hash_t hash)117 void Writer::logEventHistTs(Event event, log_hash_t hash)
118 {
119     if (!mEnabled) {
120         return;
121     }
122     HistTsEntry data;
123     data.hash = hash;
124     data.ts = systemTime();
125     if (data.ts > 0) {
126         log(event, &data, sizeof(data));
127     } else {
128         ALOGE("Failed to get timestamp");
129     }
130 }
131 
isEnabled() const132 bool Writer::isEnabled() const
133 {
134     return mEnabled;
135 }
136 
setEnabled(bool enabled)137 bool Writer::setEnabled(bool enabled)
138 {
139     bool old = mEnabled;
140     mEnabled = enabled && mShared != NULL;
141     return old;
142 }
143 
log(const Entry & etr,bool trusted)144 void Writer::log(const Entry &etr, bool trusted)
145 {
146     if (!mEnabled) {
147         return;
148     }
149     if (!trusted) {
150         log(etr.mEvent, etr.mData, etr.mLength);
151         return;
152     }
153     const size_t need = etr.mLength + Entry::kOverhead; // mEvent, mLength, data[mLength], mLength
154                                                         // need = number of bytes written to FIFO
155 
156     // FIXME optimize this using memcpy for the data part of the Entry.
157     // The Entry could have a method copyTo(ptr, offset, size) to optimize the copy.
158     // checks size of a single log Entry: type, length, data pointer and ending
159     uint8_t temp[Entry::kMaxLength + Entry::kOverhead];
160     // write this data to temp array
161     for (size_t i = 0; i < need; i++) {
162         temp[i] = etr.copyEntryDataAt(i);
163     }
164     // write to circular buffer
165     mFifoWriter->write(temp, need);
166 }
167 
log(Event event,const void * data,size_t length)168 void Writer::log(Event event, const void *data, size_t length)
169 {
170     if (!mEnabled) {
171         return;
172     }
173     if (data == NULL || length > Entry::kMaxLength) {
174         // TODO Perhaps it makes sense to display truncated data or at least a
175         //      message that the data is too long?  The current behavior can create
176         //      a confusion for a programmer debugging their code.
177         return;
178     }
179     // Ignore if invalid event
180     if (event == EVENT_RESERVED || event >= EVENT_UPPER_BOUND) {
181         return;
182     }
183     Entry etr(event, data, length);
184     log(etr, true /*trusted*/);
185 }
186 
logvf(const char * fmt,va_list ap)187 void Writer::logvf(const char *fmt, va_list ap)
188 {
189     if (!mEnabled) {
190         return;
191     }
192     char buffer[Entry::kMaxLength + 1 /*NUL*/];
193     int length = vsnprintf(buffer, sizeof(buffer), fmt, ap);
194     if (length >= (int) sizeof(buffer)) {
195         length = sizeof(buffer) - 1;
196         // NUL termination is not required
197         // buffer[length] = '\0';
198     }
199     if (length >= 0) {
200         log(EVENT_STRING, buffer, length);
201     }
202 }
203 
logStart(const char * fmt)204 void Writer::logStart(const char *fmt)
205 {
206     if (!mEnabled) {
207         return;
208     }
209     size_t length = strlen(fmt);
210     if (length > Entry::kMaxLength) {
211         length = Entry::kMaxLength;
212     }
213     log(EVENT_FMT_START, fmt, length);
214 }
215 
logTimestampFormat()216 void Writer::logTimestampFormat()
217 {
218     if (!mEnabled) {
219         return;
220     }
221     const nsecs_t ts = systemTime();
222     if (ts > 0) {
223         log(EVENT_FMT_TIMESTAMP, &ts, sizeof(ts));
224     } else {
225         ALOGE("Failed to get timestamp");
226     }
227 }
228 
logVFormat(const char * fmt,log_hash_t hash,va_list argp)229 void Writer::logVFormat(const char *fmt, log_hash_t hash, va_list argp)
230 {
231     if (!mEnabled) {
232         return;
233     }
234     Writer::logStart(fmt);
235     int i;
236     double d;
237     float f;
238     char* s;
239     size_t length;
240     int64_t t;
241     Writer::logTimestampFormat();
242     log(EVENT_FMT_HASH, &hash, sizeof(hash));
243     for (const char *p = fmt; *p != '\0'; p++) {
244         // TODO: implement more complex formatting such as %.3f
245         if (*p != '%') {
246             continue;
247         }
248         switch(*++p) {
249         case 's': // string
250             s = va_arg(argp, char *);
251             length = strlen(s);
252             if (length > Entry::kMaxLength) {
253                 length = Entry::kMaxLength;
254             }
255             log(EVENT_FMT_STRING, s, length);
256             break;
257 
258         case 't': // timestamp
259             t = va_arg(argp, int64_t);
260             log(EVENT_FMT_TIMESTAMP, &t, sizeof(t));
261             break;
262 
263         case 'd': // integer
264             i = va_arg(argp, int);
265             log(EVENT_FMT_INTEGER, &i, sizeof(i));
266             break;
267 
268         case 'f': // float
269             d = va_arg(argp, double); // float arguments are promoted to double in vararg lists
270             f = (float)d;
271             log(EVENT_FMT_FLOAT, &f, sizeof(f));
272             break;
273 
274         case 'p': // pid
275             log(EVENT_FMT_PID, mPidTag, mPidTagSize);
276             break;
277 
278         // the "%\0" case finishes parsing
279         case '\0':
280             --p;
281             break;
282 
283         case '%':
284             break;
285 
286         default:
287             ALOGW("NBLog Writer parsed invalid format specifier: %c", *p);
288             break;
289         }
290     }
291     Entry etr(EVENT_FMT_END, nullptr, 0);
292     log(etr, true);
293 }
294 
295 // ---------------------------------------------------------------------------
296 
LockedWriter(void * shared,size_t size)297 LockedWriter::LockedWriter(void *shared, size_t size)
298     : Writer(shared, size)
299 {
300 }
301 
isEnabled() const302 bool LockedWriter::isEnabled() const
303 {
304     Mutex::Autolock _l(mLock);
305     return Writer::isEnabled();
306 }
307 
setEnabled(bool enabled)308 bool LockedWriter::setEnabled(bool enabled)
309 {
310     Mutex::Autolock _l(mLock);
311     return Writer::setEnabled(enabled);
312 }
313 
log(const Entry & entry,bool trusted)314 void LockedWriter::log(const Entry &entry, bool trusted) {
315     Mutex::Autolock _l(mLock);
316     Writer::log(entry, trusted);
317 }
318 
319 }   // namespace NBLog
320 }   // namespace android
321