163d2602db
When statsd reconnects to logd, statsd will read all logs from buffer again. To prevent us from reprocessing old events, we do the following: 1. At any given moment, record the largest timestamp(T_max) and last timestamp (check point) that we've seen before. 2. When reconnection happens, we look for the check point until we see a new log with a timestamp larger than T_max. -> If we found the CP, resume after the CP. Success -> If we can't find CP, there is definitely log loss. We reset all configs. Note: 1. Logd has an API to read logs after a certain timestamp. But this api is vulnerable to time changes from Settings. So we cannot rely on it. 2. If logd inserts a new log (with older timestamp) before CP, we cannot detect it. It's not possible to detect it without record all timestamps we have seen. Test: statsd_test Bug: 77813113 Change-Id: Ic3fdb47230807606ab11dc994cb162194adb8448
310 lines
10 KiB
C++
310 lines
10 KiB
C++
// Copyright (C) 2017 The Android Open Source Project
|
|
//
|
|
// Licensed under the Apache License, Version 2.0 (the "License");
|
|
// you may not use this file except in compliance with the License.
|
|
// You may obtain a copy of the License at
|
|
//
|
|
// http://www.apache.org/licenses/LICENSE-2.0
|
|
//
|
|
// Unless required by applicable law or agreed to in writing, software
|
|
// distributed under the License is distributed on an "AS IS" BASIS,
|
|
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
// See the License for the specific language governing permissions and
|
|
// limitations under the License.
|
|
|
|
#include "StatsLogProcessor.h"
|
|
#include "config/ConfigKey.h"
|
|
#include "frameworks/base/cmds/statsd/src/stats_log.pb.h"
|
|
#include "frameworks/base/cmds/statsd/src/statsd_config.pb.h"
|
|
#include "guardrail/StatsdStats.h"
|
|
#include "logd/LogEvent.h"
|
|
#include "packages/UidMap.h"
|
|
#include "statslog.h"
|
|
|
|
#include <gmock/gmock.h>
|
|
#include <gtest/gtest.h>
|
|
|
|
#include <stdio.h>
|
|
|
|
using namespace android;
|
|
using namespace testing;
|
|
|
|
namespace android {
|
|
namespace os {
|
|
namespace statsd {
|
|
|
|
using android::util::ProtoOutputStream;
|
|
|
|
#ifdef __ANDROID__
|
|
|
|
/**
|
|
* Mock MetricsManager (ByteSize() is called).
|
|
*/
|
|
class MockMetricsManager : public MetricsManager {
|
|
public:
|
|
MockMetricsManager() : MetricsManager(
|
|
ConfigKey(1, 12345), StatsdConfig(), 1000, 1000,
|
|
new UidMap(),
|
|
new AlarmMonitor(10, [](const sp<IStatsCompanionService>&, int64_t){},
|
|
[](const sp<IStatsCompanionService>&){}),
|
|
new AlarmMonitor(10, [](const sp<IStatsCompanionService>&, int64_t){},
|
|
[](const sp<IStatsCompanionService>&){})) {
|
|
}
|
|
|
|
MOCK_METHOD0(byteSize, size_t());
|
|
|
|
MOCK_METHOD1(dropData, void(const int64_t dropTimeNs));
|
|
};
|
|
|
|
TEST(StatsLogProcessorTest, TestRateLimitByteSize) {
|
|
sp<UidMap> m = new UidMap();
|
|
sp<AlarmMonitor> anomalyAlarmMonitor;
|
|
sp<AlarmMonitor> periodicAlarmMonitor;
|
|
// Construct the processor with a dummy sendBroadcast function that does nothing.
|
|
StatsLogProcessor p(m, anomalyAlarmMonitor, periodicAlarmMonitor, 0,
|
|
[](const ConfigKey& key) {});
|
|
|
|
MockMetricsManager mockMetricsManager;
|
|
|
|
ConfigKey key(100, 12345);
|
|
// Expect only the first flush to trigger a check for byte size since the last two are
|
|
// rate-limited.
|
|
EXPECT_CALL(mockMetricsManager, byteSize()).Times(1);
|
|
p.flushIfNecessaryLocked(99, key, mockMetricsManager);
|
|
p.flushIfNecessaryLocked(100, key, mockMetricsManager);
|
|
p.flushIfNecessaryLocked(101, key, mockMetricsManager);
|
|
}
|
|
|
|
TEST(StatsLogProcessorTest, TestRateLimitBroadcast) {
|
|
sp<UidMap> m = new UidMap();
|
|
sp<AlarmMonitor> anomalyAlarmMonitor;
|
|
sp<AlarmMonitor> subscriberAlarmMonitor;
|
|
int broadcastCount = 0;
|
|
StatsLogProcessor p(m, anomalyAlarmMonitor, subscriberAlarmMonitor, 0,
|
|
[&broadcastCount](const ConfigKey& key) { broadcastCount++; });
|
|
|
|
MockMetricsManager mockMetricsManager;
|
|
|
|
ConfigKey key(100, 12345);
|
|
EXPECT_CALL(mockMetricsManager, byteSize())
|
|
.Times(1)
|
|
.WillRepeatedly(Return(int(StatsdStats::kMaxMetricsBytesPerConfig * .95)));
|
|
|
|
// Expect only one broadcast despite always returning a size that should trigger broadcast.
|
|
p.flushIfNecessaryLocked(1, key, mockMetricsManager);
|
|
EXPECT_EQ(1, broadcastCount);
|
|
|
|
// b/73089712
|
|
// This next call to flush should not trigger a broadcast.
|
|
// p.mLastByteSizeTimes.clear(); // Force another check for byte size.
|
|
// p.flushIfNecessaryLocked(2, key, mockMetricsManager);
|
|
// EXPECT_EQ(1, broadcastCount);
|
|
}
|
|
|
|
TEST(StatsLogProcessorTest, TestDropWhenByteSizeTooLarge) {
|
|
sp<UidMap> m = new UidMap();
|
|
sp<AlarmMonitor> anomalyAlarmMonitor;
|
|
sp<AlarmMonitor> subscriberAlarmMonitor;
|
|
int broadcastCount = 0;
|
|
StatsLogProcessor p(m, anomalyAlarmMonitor, subscriberAlarmMonitor, 0,
|
|
[&broadcastCount](const ConfigKey& key) { broadcastCount++; });
|
|
|
|
MockMetricsManager mockMetricsManager;
|
|
|
|
ConfigKey key(100, 12345);
|
|
EXPECT_CALL(mockMetricsManager, byteSize())
|
|
.Times(1)
|
|
.WillRepeatedly(Return(int(StatsdStats::kMaxMetricsBytesPerConfig * 1.2)));
|
|
|
|
EXPECT_CALL(mockMetricsManager, dropData(_)).Times(1);
|
|
|
|
// Expect to call the onDumpReport and skip the broadcast.
|
|
p.flushIfNecessaryLocked(1, key, mockMetricsManager);
|
|
EXPECT_EQ(0, broadcastCount);
|
|
}
|
|
|
|
TEST(StatsLogProcessorTest, TestUidMapHasSnapshot) {
|
|
// Setup simple config key corresponding to empty config.
|
|
sp<UidMap> m = new UidMap();
|
|
m->updateMap(1, {1, 2}, {1, 2}, {String16("p1"), String16("p2")});
|
|
sp<AlarmMonitor> anomalyAlarmMonitor;
|
|
sp<AlarmMonitor> subscriberAlarmMonitor;
|
|
int broadcastCount = 0;
|
|
StatsLogProcessor p(m, anomalyAlarmMonitor, subscriberAlarmMonitor, 0,
|
|
[&broadcastCount](const ConfigKey& key) { broadcastCount++; });
|
|
ConfigKey key(3, 4);
|
|
StatsdConfig config;
|
|
config.add_allowed_log_source("AID_ROOT");
|
|
p.OnConfigUpdated(0, key, config);
|
|
|
|
// Expect to get no metrics, but snapshot specified above in uidmap.
|
|
vector<uint8_t> bytes;
|
|
p.onDumpReport(key, 1, false, &bytes);
|
|
|
|
ConfigMetricsReportList output;
|
|
output.ParseFromArray(bytes.data(), bytes.size());
|
|
EXPECT_TRUE(output.reports_size() > 0);
|
|
auto uidmap = output.reports(0).uid_map();
|
|
EXPECT_TRUE(uidmap.snapshots_size() > 0);
|
|
EXPECT_EQ(2, uidmap.snapshots(0).package_info_size());
|
|
}
|
|
|
|
TEST(StatsLogProcessorTest, TestReportIncludesSubConfig) {
|
|
// Setup simple config key corresponding to empty config.
|
|
sp<UidMap> m = new UidMap();
|
|
sp<AlarmMonitor> anomalyAlarmMonitor;
|
|
sp<AlarmMonitor> subscriberAlarmMonitor;
|
|
int broadcastCount = 0;
|
|
StatsLogProcessor p(m, anomalyAlarmMonitor, subscriberAlarmMonitor, 0,
|
|
[&broadcastCount](const ConfigKey& key) { broadcastCount++; });
|
|
ConfigKey key(3, 4);
|
|
StatsdConfig config;
|
|
auto annotation = config.add_annotation();
|
|
annotation->set_field_int64(1);
|
|
annotation->set_field_int32(2);
|
|
config.add_allowed_log_source("AID_ROOT");
|
|
p.OnConfigUpdated(1, key, config);
|
|
|
|
// Expect to get no metrics, but snapshot specified above in uidmap.
|
|
vector<uint8_t> bytes;
|
|
p.onDumpReport(key, 1, false, &bytes);
|
|
|
|
ConfigMetricsReportList output;
|
|
output.ParseFromArray(bytes.data(), bytes.size());
|
|
EXPECT_TRUE(output.reports_size() > 0);
|
|
auto report = output.reports(0);
|
|
EXPECT_EQ(1, report.annotation_size());
|
|
EXPECT_EQ(1, report.annotation(0).field_int64());
|
|
EXPECT_EQ(2, report.annotation(0).field_int32());
|
|
}
|
|
|
|
TEST(StatsLogProcessorTest, TestOutOfOrderLogs) {
|
|
// Setup simple config key corresponding to empty config.
|
|
sp<UidMap> m = new UidMap();
|
|
sp<AlarmMonitor> anomalyAlarmMonitor;
|
|
sp<AlarmMonitor> subscriberAlarmMonitor;
|
|
int broadcastCount = 0;
|
|
StatsLogProcessor p(m, anomalyAlarmMonitor, subscriberAlarmMonitor, 0,
|
|
[&broadcastCount](const ConfigKey& key) { broadcastCount++; });
|
|
|
|
LogEvent event1(0, 1 /*logd timestamp*/, 1001 /*elapsedRealtime*/);
|
|
event1.init();
|
|
|
|
LogEvent event2(0, 2, 1002);
|
|
event2.init();
|
|
|
|
LogEvent event3(0, 3, 1005);
|
|
event3.init();
|
|
|
|
LogEvent event4(0, 4, 1004);
|
|
event4.init();
|
|
|
|
// <----- Reconnection happens
|
|
|
|
LogEvent event5(0, 5, 999);
|
|
event5.init();
|
|
|
|
LogEvent event6(0, 6, 2000);
|
|
event6.init();
|
|
|
|
// <----- Reconnection happens
|
|
|
|
LogEvent event7(0, 7, 3000);
|
|
event7.init();
|
|
|
|
// first event ever
|
|
p.OnLogEvent(&event1, true);
|
|
EXPECT_EQ(1UL, p.mLogCount);
|
|
EXPECT_EQ(1001LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(1001LL, p.mLastTimestampSeen);
|
|
|
|
p.OnLogEvent(&event2, false);
|
|
EXPECT_EQ(2UL, p.mLogCount);
|
|
EXPECT_EQ(1002LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(1002LL, p.mLastTimestampSeen);
|
|
|
|
p.OnLogEvent(&event3, false);
|
|
EXPECT_EQ(3UL, p.mLogCount);
|
|
EXPECT_EQ(1005LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(1005LL, p.mLastTimestampSeen);
|
|
|
|
p.OnLogEvent(&event4, false);
|
|
EXPECT_EQ(4UL, p.mLogCount);
|
|
EXPECT_EQ(1005LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(1004LL, p.mLastTimestampSeen);
|
|
EXPECT_FALSE(p.mInReconnection);
|
|
|
|
// Reconnect happens, event1 out of buffer. Read event2
|
|
p.OnLogEvent(&event2, true);
|
|
EXPECT_EQ(4UL, p.mLogCount);
|
|
EXPECT_EQ(1005LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(1004LL, p.mLastTimestampSeen);
|
|
EXPECT_TRUE(p.mInReconnection);
|
|
|
|
p.OnLogEvent(&event3, false);
|
|
EXPECT_EQ(4UL, p.mLogCount);
|
|
EXPECT_EQ(1005LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(1004LL, p.mLastTimestampSeen);
|
|
EXPECT_TRUE(p.mInReconnection);
|
|
|
|
p.OnLogEvent(&event4, false);
|
|
EXPECT_EQ(4UL, p.mLogCount);
|
|
EXPECT_EQ(1005LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(1004LL, p.mLastTimestampSeen);
|
|
EXPECT_FALSE(p.mInReconnection);
|
|
|
|
// Fresh event comes.
|
|
p.OnLogEvent(&event5, false);
|
|
EXPECT_EQ(5UL, p.mLogCount);
|
|
EXPECT_EQ(1005LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(999LL, p.mLastTimestampSeen);
|
|
|
|
p.OnLogEvent(&event6, false);
|
|
EXPECT_EQ(6UL, p.mLogCount);
|
|
EXPECT_EQ(2000LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(2000LL, p.mLastTimestampSeen);
|
|
|
|
// Reconnect happens, read from event4
|
|
p.OnLogEvent(&event4, true);
|
|
EXPECT_EQ(6UL, p.mLogCount);
|
|
EXPECT_EQ(2000LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(2000LL, p.mLastTimestampSeen);
|
|
EXPECT_TRUE(p.mInReconnection);
|
|
|
|
p.OnLogEvent(&event5, false);
|
|
EXPECT_EQ(6UL, p.mLogCount);
|
|
EXPECT_EQ(2000LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(2000LL, p.mLastTimestampSeen);
|
|
EXPECT_TRUE(p.mInReconnection);
|
|
|
|
// Before we get out of reconnection state, it reconnects again.
|
|
p.OnLogEvent(&event5, true);
|
|
EXPECT_EQ(6UL, p.mLogCount);
|
|
EXPECT_EQ(2000LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(2000LL, p.mLastTimestampSeen);
|
|
EXPECT_TRUE(p.mInReconnection);
|
|
|
|
p.OnLogEvent(&event6, false);
|
|
EXPECT_EQ(6UL, p.mLogCount);
|
|
EXPECT_EQ(2000LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(2000LL, p.mLastTimestampSeen);
|
|
EXPECT_FALSE(p.mInReconnection);
|
|
EXPECT_EQ(0, p.mLogLossCount);
|
|
|
|
// it reconnects again. All old events are gone. We lose CP.
|
|
p.OnLogEvent(&event7, true);
|
|
EXPECT_EQ(7UL, p.mLogCount);
|
|
EXPECT_EQ(3000LL, p.mLargestTimestampSeen);
|
|
EXPECT_EQ(3000LL, p.mLastTimestampSeen);
|
|
EXPECT_EQ(1, p.mLogLossCount);
|
|
EXPECT_FALSE(p.mInReconnection);
|
|
}
|
|
|
|
#else
|
|
GTEST_LOG_(INFO) << "This test does nothing.\n";
|
|
#endif
|
|
|
|
} // namespace statsd
|
|
} // namespace os
|
|
} // namespace android
|