StatsLogProcessor.cpp revision 82c2173b678ebff8092ec2a77eaaf4c987e109bd 
1/*
2 * Copyright (C) 2017 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 DEBUG true  // STOPSHIP if true
18#include "Log.h"
19#include "statslog.h"
20
21#include <android-base/file.h>
22#include <dirent.h>
23#include "StatsLogProcessor.h"
24#include "android-base/stringprintf.h"
25#include "guardrail/StatsdStats.h"
26#include "metrics/CountMetricProducer.h"
27#include "external/StatsPullerManager.h"
28#include "dimension.h"
29#include "field_util.h"
30#include "stats_util.h"
31#include "storage/StorageManager.h"
32
33#include <log/log_event_list.h>
34#include <utils/Errors.h>
35
36using namespace android;
37using android::base::StringPrintf;
38using android::util::FIELD_COUNT_REPEATED;
39using android::util::FIELD_TYPE_BOOL;
40using android::util::FIELD_TYPE_FLOAT;
41using android::util::FIELD_TYPE_INT32;
42using android::util::FIELD_TYPE_INT64;
43using android::util::FIELD_TYPE_MESSAGE;
44using android::util::FIELD_TYPE_STRING;
45using android::util::ProtoOutputStream;
46using std::make_unique;
47using std::unique_ptr;
48using std::vector;
49
50namespace android {
51namespace os {
52namespace statsd {
53
54// for ConfigMetricsReportList
55const int FIELD_ID_CONFIG_KEY = 1;
56const int FIELD_ID_REPORTS = 2;
57// for ConfigKey
58const int FIELD_ID_UID = 1;
59const int FIELD_ID_ID = 2;
60// for ConfigMetricsReport
61const int FIELD_ID_METRICS = 1;
62const int FIELD_ID_UID_MAP = 2;
63
64#define STATS_DATA_DIR "/data/misc/stats-data"
65
66StatsLogProcessor::StatsLogProcessor(const sp<UidMap>& uidMap,
67                                     const sp<AnomalyMonitor>& anomalyMonitor,
68                                     const long timeBaseSec,
69                                     const std::function<void(const ConfigKey&)>& sendBroadcast)
70    : mUidMap(uidMap),
71      mAnomalyMonitor(anomalyMonitor),
72      mSendBroadcast(sendBroadcast),
73      mTimeBaseSec(timeBaseSec) {
74    // On each initialization of StatsLogProcessor, check stats-data directory to see if there is
75    // any left over data to be read.
76    StorageManager::sendBroadcast(STATS_DATA_DIR, mSendBroadcast);
77    StatsPullerManager statsPullerManager;
78    statsPullerManager.SetTimeBaseSec(mTimeBaseSec);
79}
80
81StatsLogProcessor::~StatsLogProcessor() {
82}
83
84void StatsLogProcessor::onAnomalyAlarmFired(
85        const uint64_t timestampNs,
86        unordered_set<sp<const AnomalyAlarm>, SpHash<AnomalyAlarm>> anomalySet) {
87    std::lock_guard<std::mutex> lock(mMetricsMutex);
88    for (const auto& itr : mMetricsManagers) {
89        itr.second->onAnomalyAlarmFired(timestampNs, anomalySet);
90    }
91}
92
93void StatsLogProcessor::mapIsolatedUidToHostUidIfNecessaryLocked(LogEvent* event) const {
94    std::vector<Field> uidFields;
95    if (android::util::kAtomsWithAttributionChain.find(event->GetTagId()) !=
96        android::util::kAtomsWithAttributionChain.end()) {
97        findFields(
98            event->getFieldValueMap(),
99            buildAttributionUidFieldMatcher(event->GetTagId(), Position::ANY),
100            &uidFields);
101    } else if (android::util::kAtomsWithUidField.find(event->GetTagId()) !=
102               android::util::kAtomsWithUidField.end()) {
103        findFields(
104            event->getFieldValueMap(),
105            buildSimpleAtomFieldMatcher(event->GetTagId(), 1 /* uid is always the 1st field. */),
106            &uidFields);
107    }
108
109    for (size_t i = 0; i < uidFields.size(); ++i) {
110        DimensionsValue* value = event->findFieldValueOrNull(uidFields[i]);
111        if (value != nullptr && value->value_case() == DimensionsValue::ValueCase::kValueInt) {
112            const int uid = mUidMap->getHostUidOrSelf(value->value_int());
113            value->set_value_int(uid);
114        }
115    }
116}
117
118void StatsLogProcessor::onIsolatedUidChangedEventLocked(const LogEvent& event) {
119    status_t err = NO_ERROR, err2 = NO_ERROR, err3 = NO_ERROR;
120    bool is_create = event.GetBool(3, &err);
121    auto parent_uid = int(event.GetLong(1, &err2));
122    auto isolated_uid = int(event.GetLong(2, &err3));
123    if (err == NO_ERROR && err2 == NO_ERROR && err3 == NO_ERROR) {
124        if (is_create) {
125            mUidMap->assignIsolatedUid(isolated_uid, parent_uid);
126        } else {
127            mUidMap->removeIsolatedUid(isolated_uid, parent_uid);
128        }
129    } else {
130        ALOGE("Failed to parse uid in the isolated uid change event.");
131    }
132}
133
134// TODO: what if statsd service restarts? How do we know what logs are already processed before?
135void StatsLogProcessor::OnLogEvent(LogEvent* event) {
136    std::lock_guard<std::mutex> lock(mMetricsMutex);
137    StatsdStats::getInstance().noteAtomLogged(
138        event->GetTagId(), event->GetTimestampNs() / NS_PER_SEC);
139
140    // Hard-coded logic to update the isolated uid's in the uid-map.
141    // The field numbers need to be currently updated by hand with atoms.proto
142    if (event->GetTagId() == android::util::ISOLATED_UID_CHANGED) {
143        onIsolatedUidChangedEventLocked(*event);
144    }
145
146    if (mMetricsManagers.empty()) {
147        return;
148    }
149
150    if (event->GetTagId() != android::util::ISOLATED_UID_CHANGED) {
151        // Map the isolated uid to host uid if necessary.
152        mapIsolatedUidToHostUidIfNecessaryLocked(event);
153    }
154
155    // pass the event to metrics managers.
156    for (auto& pair : mMetricsManagers) {
157        pair.second->onLogEvent(*event);
158        flushIfNecessaryLocked(event->GetTimestampNs(), pair.first, *(pair.second));
159    }
160}
161
162void StatsLogProcessor::OnConfigUpdated(const ConfigKey& key, const StatsdConfig& config) {
163    std::lock_guard<std::mutex> lock(mMetricsMutex);
164    ALOGD("Updated configuration for key %s", key.ToString().c_str());
165    sp<MetricsManager> newMetricsManager = new MetricsManager(key, config, mTimeBaseSec, mUidMap);
166    auto it = mMetricsManagers.find(key);
167    if (it == mMetricsManagers.end() && mMetricsManagers.size() > StatsdStats::kMaxConfigCount) {
168        ALOGE("Can't accept more configs!");
169        return;
170    }
171
172    if (newMetricsManager->isConfigValid()) {
173        mUidMap->OnConfigUpdated(key);
174        newMetricsManager->setAnomalyMonitor(mAnomalyMonitor);
175        if (newMetricsManager->shouldAddUidMapListener()) {
176            // We have to add listener after the MetricsManager is constructed because it's
177            // not safe to create wp or sp from this pointer inside its constructor.
178            mUidMap->addListener(newMetricsManager.get());
179        }
180        mMetricsManagers[key] = newMetricsManager;
181        // Why doesn't this work? mMetricsManagers.insert({key, std::move(newMetricsManager)});
182        VLOG("StatsdConfig valid");
183    } else {
184        // If there is any error in the config, don't use it.
185        ALOGE("StatsdConfig NOT valid");
186    }
187}
188
189size_t StatsLogProcessor::GetMetricsSize(const ConfigKey& key) const {
190    std::lock_guard<std::mutex> lock(mMetricsMutex);
191    auto it = mMetricsManagers.find(key);
192    if (it == mMetricsManagers.end()) {
193        ALOGW("Config source %s does not exist", key.ToString().c_str());
194        return 0;
195    }
196    return it->second->byteSize();
197}
198
199void StatsLogProcessor::onDumpReport(const ConfigKey& key, const uint64_t& dumpTimeStampNs,
200                                     ConfigMetricsReportList* report) {
201    std::lock_guard<std::mutex> lock(mMetricsMutex);
202    auto it = mMetricsManagers.find(key);
203    if (it == mMetricsManagers.end()) {
204        ALOGW("Config source %s does not exist", key.ToString().c_str());
205        return;
206    }
207    report->mutable_config_key()->set_uid(key.GetUid());
208    report->mutable_config_key()->set_id(key.GetId());
209    ConfigMetricsReport* configMetricsReport = report->add_reports();
210    it->second->onDumpReport(dumpTimeStampNs, configMetricsReport);
211    // TODO: dump uid mapping.
212}
213
214void StatsLogProcessor::onDumpReport(const ConfigKey& key, vector<uint8_t>* outData) {
215    std::lock_guard<std::mutex> lock(mMetricsMutex);
216    onDumpReportLocked(key, outData);
217}
218
219void StatsLogProcessor::onDumpReportLocked(const ConfigKey& key, vector<uint8_t>* outData) {
220    auto it = mMetricsManagers.find(key);
221    if (it == mMetricsManagers.end()) {
222        ALOGW("Config source %s does not exist", key.ToString().c_str());
223        return;
224    }
225
226    // This allows another broadcast to be sent within the rate-limit period if we get close to
227    // filling the buffer again soon.
228    mLastBroadcastTimes.erase(key);
229
230    ProtoOutputStream proto;
231
232    // Start of ConfigKey.
233    long long configKeyToken = proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_CONFIG_KEY);
234    proto.write(FIELD_TYPE_INT32 | FIELD_ID_UID, key.GetUid());
235    proto.write(FIELD_TYPE_INT64 | FIELD_ID_ID, (long long)key.GetId());
236    proto.end(configKeyToken);
237    // End of ConfigKey.
238
239    // Start of ConfigMetricsReport (reports).
240    long long reportsToken =
241            proto.start(FIELD_TYPE_MESSAGE | FIELD_COUNT_REPEATED | FIELD_ID_REPORTS);
242
243    // First, fill in ConfigMetricsReport using current data on memory, which
244    // starts from filling in StatsLogReport's.
245    it->second->onDumpReport(&proto);
246
247    // Fill in UidMap.
248    auto uidMap = mUidMap->getOutput(key);
249    const int uidMapSize = uidMap.ByteSize();
250    char uidMapBuffer[uidMapSize];
251    uidMap.SerializeToArray(&uidMapBuffer[0], uidMapSize);
252    proto.write(FIELD_TYPE_MESSAGE | FIELD_ID_UID_MAP, uidMapBuffer, uidMapSize);
253
254    // End of ConfigMetricsReport (reports).
255    proto.end(reportsToken);
256
257    // Then, check stats-data directory to see there's any file containing
258    // ConfigMetricsReport from previous shutdowns to concatenate to reports.
259    StorageManager::appendConfigMetricsReport(STATS_DATA_DIR, proto);
260
261    if (outData != nullptr) {
262        outData->clear();
263        outData->resize(proto.size());
264        size_t pos = 0;
265        auto iter = proto.data();
266        while (iter.readBuffer() != NULL) {
267            size_t toRead = iter.currentToRead();
268            std::memcpy(&((*outData)[pos]), iter.readBuffer(), toRead);
269            pos += toRead;
270            iter.rp()->move(toRead);
271        }
272    }
273    StatsdStats::getInstance().noteMetricsReportSent(key);
274}
275
276void StatsLogProcessor::OnConfigRemoved(const ConfigKey& key) {
277    std::lock_guard<std::mutex> lock(mMetricsMutex);
278    auto it = mMetricsManagers.find(key);
279    if (it != mMetricsManagers.end()) {
280        mMetricsManagers.erase(it);
281        mUidMap->OnConfigRemoved(key);
282    }
283    StatsdStats::getInstance().noteConfigRemoved(key);
284
285    mLastBroadcastTimes.erase(key);
286}
287
288void StatsLogProcessor::flushIfNecessaryLocked(
289    uint64_t timestampNs, const ConfigKey& key, MetricsManager& metricsManager) {
290    auto lastCheckTime = mLastByteSizeTimes.find(key);
291    if (lastCheckTime != mLastByteSizeTimes.end()) {
292        if (timestampNs - lastCheckTime->second < StatsdStats::kMinByteSizeCheckPeriodNs) {
293            return;
294        }
295    }
296
297    // We suspect that the byteSize() computation is expensive, so we set a rate limit.
298    size_t totalBytes = metricsManager.byteSize();
299    mLastByteSizeTimes[key] = timestampNs;
300    if (totalBytes >
301        StatsdStats::kMaxMetricsBytesPerConfig) {  // Too late. We need to start clearing data.
302        // TODO(b/70571383): By 12/15/2017 add API to drop data directly
303        ProtoOutputStream proto;
304        metricsManager.onDumpReport(&proto);
305        StatsdStats::getInstance().noteDataDropped(key);
306        VLOG("StatsD had to toss out metrics for %s", key.ToString().c_str());
307    } else if (totalBytes > .9 * StatsdStats::kMaxMetricsBytesPerConfig) {
308        // Send broadcast so that receivers can pull data.
309        auto lastBroadcastTime = mLastBroadcastTimes.find(key);
310        if (lastBroadcastTime != mLastBroadcastTimes.end()) {
311            if (timestampNs - lastBroadcastTime->second < StatsdStats::kMinBroadcastPeriodNs) {
312                VLOG("StatsD would've sent a broadcast but the rate limit stopped us.");
313                return;
314            }
315        }
316        mLastBroadcastTimes[key] = timestampNs;
317        VLOG("StatsD requesting broadcast for %s", key.ToString().c_str());
318        mSendBroadcast(key);
319        StatsdStats::getInstance().noteBroadcastSent(key);
320    }
321}
322
323void StatsLogProcessor::WriteDataToDisk() {
324    std::lock_guard<std::mutex> lock(mMetricsMutex);
325    for (auto& pair : mMetricsManagers) {
326        const ConfigKey& key = pair.first;
327        vector<uint8_t> data;
328        onDumpReportLocked(key, &data);
329        // TODO: Add a guardrail to prevent accumulation of file on disk.
330        string file_name = StringPrintf("%s/%d-%lld-%ld", STATS_DATA_DIR, key.GetUid(),
331                                        (long long)key.GetId(), time(nullptr));
332        StorageManager::writeFile(file_name.c_str(), &data[0], data.size());
333    }
334}
335
336}  // namespace statsd
337}  // namespace os
338}  // namespace android
339