/* * 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. */ #define DEBUG false // STOPSHIP if true #include "logd/LogEvent.h" #include "stats_log_util.h" #include "statslog.h" #include #include namespace android { namespace os { namespace statsd { // for TrainInfo experiment id serialization const int FIELD_ID_EXPERIMENT_ID = 1; using namespace android::util; using android::util::ProtoOutputStream; using std::string; using std::vector; LogEvent::LogEvent(log_msg& msg) { mContext = create_android_log_parser(msg.msg() + sizeof(uint32_t), msg.len() - sizeof(uint32_t)); mLogdTimestampNs = msg.entry_v1.sec * NS_PER_SEC + msg.entry_v1.nsec; mLogUid = msg.entry_v4.uid; init(mContext); if (mContext) { // android_log_destroy will set mContext to NULL android_log_destroy(&mContext); } } LogEvent::LogEvent(const LogEvent& event) { mTagId = event.mTagId; mLogUid = event.mLogUid; mElapsedTimestampNs = event.mElapsedTimestampNs; mLogdTimestampNs = event.mLogdTimestampNs; mValues = event.mValues; } LogEvent::LogEvent(const StatsLogEventWrapper& statsLogEventWrapper, int workChainIndex) { mTagId = statsLogEventWrapper.getTagId(); mLogdTimestampNs = statsLogEventWrapper.getWallClockTimeNs(); mElapsedTimestampNs = statsLogEventWrapper.getElapsedRealTimeNs(); mLogUid = 0; int workChainPosOffset = 0; if (workChainIndex != -1) { const WorkChain& wc = statsLogEventWrapper.getWorkChains()[workChainIndex]; // chains are at field 1, level 2 int depth = 2; for (int i = 0; i < (int)wc.uids.size(); i++) { int pos[] = {1, i + 1, 1}; mValues.push_back(FieldValue(Field(mTagId, pos, depth), Value(wc.uids[i]))); pos[2]++; mValues.push_back(FieldValue(Field(mTagId, pos, depth), Value(wc.tags[i]))); mValues.back().mField.decorateLastPos(2); } mValues.back().mField.decorateLastPos(1); workChainPosOffset = 1; } for (int i = 0; i < (int)statsLogEventWrapper.getElements().size(); i++) { Field field(statsLogEventWrapper.getTagId(), getSimpleField(i + 1 + workChainPosOffset)); switch (statsLogEventWrapper.getElements()[i].type) { case android::os::StatsLogValue::STATS_LOG_VALUE_TYPE::INT: mValues.push_back( FieldValue(field, Value(statsLogEventWrapper.getElements()[i].int_value))); break; case android::os::StatsLogValue::STATS_LOG_VALUE_TYPE::LONG: mValues.push_back( FieldValue(field, Value(statsLogEventWrapper.getElements()[i].long_value))); break; case android::os::StatsLogValue::STATS_LOG_VALUE_TYPE::FLOAT: mValues.push_back(FieldValue( field, Value(statsLogEventWrapper.getElements()[i].float_value))); break; case android::os::StatsLogValue::STATS_LOG_VALUE_TYPE::DOUBLE: mValues.push_back(FieldValue( field, Value(statsLogEventWrapper.getElements()[i].double_value))); break; case android::os::StatsLogValue::STATS_LOG_VALUE_TYPE::STRING: mValues.push_back( FieldValue(field, Value(statsLogEventWrapper.getElements()[i].str_value))); break; case android::os::StatsLogValue::STATS_LOG_VALUE_TYPE::STORAGE: mValues.push_back(FieldValue( field, Value(statsLogEventWrapper.getElements()[i].storage_value))); break; default: break; } } } void LogEvent::createLogEvents(const StatsLogEventWrapper& statsLogEventWrapper, std::vector>& logEvents) { if (statsLogEventWrapper.getWorkChains().size() == 0) { logEvents.push_back(std::make_shared(statsLogEventWrapper, -1)); } else { for (size_t i = 0; i < statsLogEventWrapper.getWorkChains().size(); i++) { logEvents.push_back(std::make_shared(statsLogEventWrapper, i)); } } } LogEvent::LogEvent(int32_t tagId, int64_t wallClockTimestampNs, int64_t elapsedTimestampNs) { mLogdTimestampNs = wallClockTimestampNs; mElapsedTimestampNs = elapsedTimestampNs; mTagId = tagId; mLogUid = 0; mContext = create_android_logger(1937006964); // the event tag shared by all stats logs if (mContext) { android_log_write_int64(mContext, elapsedTimestampNs); android_log_write_int32(mContext, tagId); } } LogEvent::LogEvent(int32_t tagId, int64_t wallClockTimestampNs, int64_t elapsedTimestampNs, int32_t uid, const std::map& int_map, const std::map& long_map, const std::map& string_map, const std::map& float_map) { mLogdTimestampNs = wallClockTimestampNs; mElapsedTimestampNs = elapsedTimestampNs; mTagId = android::util::KEY_VALUE_PAIRS_ATOM; mLogUid = uid; int pos[] = {1, 1, 1}; mValues.push_back(FieldValue(Field(mTagId, pos, 0 /* depth */), Value(uid))); pos[0]++; for (const auto&itr : int_map) { pos[2] = 1; mValues.push_back(FieldValue(Field(mTagId, pos, 2 /* depth */), Value(itr.first))); pos[2] = 2; mValues.push_back(FieldValue(Field(mTagId, pos, 2 /* depth */), Value(itr.second))); mValues.back().mField.decorateLastPos(2); pos[1]++; } for (const auto&itr : long_map) { pos[2] = 1; mValues.push_back(FieldValue(Field(mTagId, pos, 2 /* depth */), Value(itr.first))); pos[2] = 3; mValues.push_back(FieldValue(Field(mTagId, pos, 2 /* depth */), Value(itr.second))); mValues.back().mField.decorateLastPos(2); pos[1]++; } for (const auto&itr : string_map) { pos[2] = 1; mValues.push_back(FieldValue(Field(mTagId, pos, 2 /* depth */), Value(itr.first))); pos[2] = 4; mValues.push_back(FieldValue(Field(mTagId, pos, 2 /* depth */), Value(itr.second))); mValues.back().mField.decorateLastPos(2); pos[1]++; } for (const auto&itr : float_map) { pos[2] = 1; mValues.push_back(FieldValue(Field(mTagId, pos, 2 /* depth */), Value(itr.first))); pos[2] = 5; mValues.push_back(FieldValue(Field(mTagId, pos, 2 /* depth */), Value(itr.second))); mValues.back().mField.decorateLastPos(2); pos[1]++; } if (!mValues.empty()) { mValues.back().mField.decorateLastPos(1); mValues.at(mValues.size() - 2).mField.decorateLastPos(1); } } LogEvent::LogEvent(const string& trainName, int64_t trainVersionCode, bool requiresStaging, bool rollbackEnabled, bool requiresLowLatencyMonitor, int32_t state, const std::vector& experimentIds, int32_t userId) { mLogdTimestampNs = getWallClockNs(); mElapsedTimestampNs = getElapsedRealtimeNs(); mTagId = android::util::BINARY_PUSH_STATE_CHANGED; mLogUid = android::IPCThreadState::self()->getCallingUid(); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(1)), Value(trainName))); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(2)), Value(trainVersionCode))); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(3)), Value((int)requiresStaging))); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(4)), Value((int)rollbackEnabled))); mValues.push_back( FieldValue(Field(mTagId, getSimpleField(5)), Value((int)requiresLowLatencyMonitor))); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(6)), Value(state))); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(7)), Value(experimentIds))); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(8)), Value(userId))); } LogEvent::LogEvent(int64_t wallClockTimestampNs, int64_t elapsedTimestampNs, const VendorAtom& vendorAtom) { mLogdTimestampNs = wallClockTimestampNs; mElapsedTimestampNs = elapsedTimestampNs; mTagId = vendorAtom.atomId; mLogUid = AID_STATSD; mValues.push_back( FieldValue(Field(mTagId, getSimpleField(1)), Value(vendorAtom.reverseDomainName))); for (int i = 0; i < (int)vendorAtom.values.size(); i++) { switch (vendorAtom.values[i].getDiscriminator()) { case VendorAtom::Value::hidl_discriminator::intValue: mValues.push_back(FieldValue(Field(mTagId, getSimpleField(i + 2)), Value(vendorAtom.values[i].intValue()))); break; case VendorAtom::Value::hidl_discriminator::longValue: mValues.push_back(FieldValue(Field(mTagId, getSimpleField(i + 2)), Value(vendorAtom.values[i].longValue()))); break; case VendorAtom::Value::hidl_discriminator::floatValue: mValues.push_back(FieldValue(Field(mTagId, getSimpleField(i + 2)), Value(vendorAtom.values[i].floatValue()))); break; case VendorAtom::Value::hidl_discriminator::stringValue: mValues.push_back(FieldValue(Field(mTagId, getSimpleField(i + 2)), Value(vendorAtom.values[i].stringValue()))); break; } } } LogEvent::LogEvent(int64_t wallClockTimestampNs, int64_t elapsedTimestampNs, const InstallTrainInfo& trainInfo) { mLogdTimestampNs = wallClockTimestampNs; mElapsedTimestampNs = elapsedTimestampNs; mTagId = android::util::TRAIN_INFO; mValues.push_back( FieldValue(Field(mTagId, getSimpleField(1)), Value(trainInfo.trainVersionCode))); std::vector experimentIdsProto; writeExperimentIdsToProto(trainInfo.experimentIds, &experimentIdsProto); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(2)), Value(experimentIdsProto))); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(3)), Value(trainInfo.trainName))); mValues.push_back(FieldValue(Field(mTagId, getSimpleField(4)), Value(trainInfo.status))); } LogEvent::LogEvent(int32_t tagId, int64_t timestampNs) : LogEvent(tagId, timestampNs, timestampNs) { } LogEvent::LogEvent(int32_t tagId, int64_t timestampNs, int32_t uid) { mLogdTimestampNs = timestampNs; mTagId = tagId; mLogUid = uid; mContext = create_android_logger(1937006964); // the event tag shared by all stats logs if (mContext) { android_log_write_int64(mContext, timestampNs); android_log_write_int32(mContext, tagId); } } void LogEvent::init() { if (mContext) { const char* buffer; size_t len = android_log_write_list_buffer(mContext, &buffer); // turns to reader mode android_log_context contextForRead = create_android_log_parser(buffer, len); if (contextForRead) { init(contextForRead); // destroy the context to save memory. // android_log_destroy will set mContext to NULL android_log_destroy(&contextForRead); } android_log_destroy(&mContext); } } LogEvent::~LogEvent() { if (mContext) { // This is for the case when LogEvent is created using the test interface // but init() isn't called. android_log_destroy(&mContext); } } bool LogEvent::write(int32_t value) { if (mContext) { return android_log_write_int32(mContext, value) >= 0; } return false; } bool LogEvent::write(uint32_t value) { if (mContext) { return android_log_write_int32(mContext, value) >= 0; } return false; } bool LogEvent::write(int64_t value) { if (mContext) { return android_log_write_int64(mContext, value) >= 0; } return false; } bool LogEvent::write(uint64_t value) { if (mContext) { return android_log_write_int64(mContext, value) >= 0; } return false; } bool LogEvent::write(const string& value) { if (mContext) { return android_log_write_string8_len(mContext, value.c_str(), value.length()) >= 0; } return false; } bool LogEvent::write(float value) { if (mContext) { return android_log_write_float32(mContext, value) >= 0; } return false; } bool LogEvent::writeKeyValuePairs(int32_t uid, const std::map& int_map, const std::map& long_map, const std::map& string_map, const std::map& float_map) { if (mContext) { if (android_log_write_list_begin(mContext) < 0) { return false; } write(uid); for (const auto& itr : int_map) { if (android_log_write_list_begin(mContext) < 0) { return false; } write(itr.first); write(itr.second); if (android_log_write_list_end(mContext) < 0) { return false; } } for (const auto& itr : long_map) { if (android_log_write_list_begin(mContext) < 0) { return false; } write(itr.first); write(itr.second); if (android_log_write_list_end(mContext) < 0) { return false; } } for (const auto& itr : string_map) { if (android_log_write_list_begin(mContext) < 0) { return false; } write(itr.first); write(itr.second.c_str()); if (android_log_write_list_end(mContext) < 0) { return false; } } for (const auto& itr : float_map) { if (android_log_write_list_begin(mContext) < 0) { return false; } write(itr.first); write(itr.second); if (android_log_write_list_end(mContext) < 0) { return false; } } if (android_log_write_list_end(mContext) < 0) { return false; } return true; } return false; } bool LogEvent::write(const std::vector& nodes) { if (mContext) { if (android_log_write_list_begin(mContext) < 0) { return false; } for (size_t i = 0; i < nodes.size(); ++i) { if (!write(nodes[i])) { return false; } } if (android_log_write_list_end(mContext) < 0) { return false; } return true; } return false; } bool LogEvent::write(const AttributionNodeInternal& node) { if (mContext) { if (android_log_write_list_begin(mContext) < 0) { return false; } if (android_log_write_int32(mContext, node.uid()) < 0) { return false; } if (android_log_write_string8(mContext, node.tag().c_str()) < 0) { return false; } if (android_log_write_list_end(mContext) < 0) { return false; } return true; } return false; } /** * The elements of each log event are stored as a vector of android_log_list_elements. * The goal is to do as little preprocessing as possible, because we read a tiny fraction * of the elements that are written to the log. * * The idea here is to read through the log items once, we get as much information we need for * matching as possible. Because this log will be matched against lots of matchers. */ void LogEvent::init(android_log_context context) { android_log_list_element elem; int i = 0; int depth = -1; int pos[] = {1, 1, 1}; bool isKeyValuePairAtom = false; do { elem = android_log_read_next(context); switch ((int)elem.type) { case EVENT_TYPE_INT: // elem at [0] is EVENT_TYPE_LIST, [1] is the timestamp, [2] is tag id. if (i == 2) { mTagId = elem.data.int32; isKeyValuePairAtom = (mTagId == android::util::KEY_VALUE_PAIRS_ATOM); } else { if (depth < 0 || depth > 2) { return; } mValues.push_back( FieldValue(Field(mTagId, pos, depth), Value((int32_t)elem.data.int32))); pos[depth]++; } break; case EVENT_TYPE_FLOAT: { if (depth < 0 || depth > 2) { ALOGE("Depth > 2. Not supported!"); return; } // Handles the oneof field in KeyValuePair atom. if (isKeyValuePairAtom && depth == 2) { pos[depth] = 5; } mValues.push_back(FieldValue(Field(mTagId, pos, depth), Value(elem.data.float32))); pos[depth]++; } break; case EVENT_TYPE_STRING: { if (depth < 0 || depth > 2) { ALOGE("Depth > 2. Not supported!"); return; } // Handles the oneof field in KeyValuePair atom. if (isKeyValuePairAtom && depth == 2) { pos[depth] = 4; } mValues.push_back(FieldValue(Field(mTagId, pos, depth), Value(string(elem.data.string, elem.len)))); pos[depth]++; } break; case EVENT_TYPE_LONG: { if (i == 1) { mElapsedTimestampNs = elem.data.int64; } else { if (depth < 0 || depth > 2) { ALOGE("Depth > 2. Not supported!"); return; } // Handles the oneof field in KeyValuePair atom. if (isKeyValuePairAtom && depth == 2) { pos[depth] = 3; } mValues.push_back( FieldValue(Field(mTagId, pos, depth), Value((int64_t)elem.data.int64))); pos[depth]++; } } break; case EVENT_TYPE_LIST: depth++; if (depth > 2) { ALOGE("Depth > 2. Not supported!"); return; } pos[depth] = 1; break; case EVENT_TYPE_LIST_STOP: { int prevDepth = depth; depth--; if (depth >= 0 && depth < 2) { // Now go back to decorate the previous items that are last at prevDepth. // So that we can later easily match them with Position=Last matchers. pos[prevDepth]--; int path = getEncodedField(pos, prevDepth, false); for (auto it = mValues.rbegin(); it != mValues.rend(); ++it) { if (it->mField.getDepth() >= prevDepth && it->mField.getPath(prevDepth) == path) { it->mField.decorateLastPos(prevDepth); } else { // Safe to break, because the items are in DFS order. break; } } pos[depth]++; } break; } case EVENT_TYPE_UNKNOWN: break; default: break; } i++; } while ((elem.type != EVENT_TYPE_UNKNOWN) && !elem.complete); if (isKeyValuePairAtom && mValues.size() > 0) { mValues[0] = FieldValue(Field(android::util::KEY_VALUE_PAIRS_ATOM, getSimpleField(1)), Value((int32_t)mLogUid)); } } int64_t LogEvent::GetLong(size_t key, status_t* err) const { // TODO(b/110561208): encapsulate the magical operations in Field struct as static functions int field = getSimpleField(key); for (const auto& value : mValues) { if (value.mField.getField() == field) { if (value.mValue.getType() == LONG) { return value.mValue.long_value; } else if (value.mValue.getType() == INT) { return value.mValue.int_value; } else { *err = BAD_TYPE; return 0; } } if ((size_t)value.mField.getPosAtDepth(0) > key) { break; } } *err = BAD_INDEX; return 0; } int LogEvent::GetInt(size_t key, status_t* err) const { int field = getSimpleField(key); for (const auto& value : mValues) { if (value.mField.getField() == field) { if (value.mValue.getType() == INT) { return value.mValue.int_value; } else { *err = BAD_TYPE; return 0; } } if ((size_t)value.mField.getPosAtDepth(0) > key) { break; } } *err = BAD_INDEX; return 0; } const char* LogEvent::GetString(size_t key, status_t* err) const { int field = getSimpleField(key); for (const auto& value : mValues) { if (value.mField.getField() == field) { if (value.mValue.getType() == STRING) { return value.mValue.str_value.c_str(); } else { *err = BAD_TYPE; return 0; } } if ((size_t)value.mField.getPosAtDepth(0) > key) { break; } } *err = BAD_INDEX; return NULL; } bool LogEvent::GetBool(size_t key, status_t* err) const { int field = getSimpleField(key); for (const auto& value : mValues) { if (value.mField.getField() == field) { if (value.mValue.getType() == INT) { return value.mValue.int_value != 0; } else if (value.mValue.getType() == LONG) { return value.mValue.long_value != 0; } else { *err = BAD_TYPE; return false; } } if ((size_t)value.mField.getPosAtDepth(0) > key) { break; } } *err = BAD_INDEX; return false; } float LogEvent::GetFloat(size_t key, status_t* err) const { int field = getSimpleField(key); for (const auto& value : mValues) { if (value.mField.getField() == field) { if (value.mValue.getType() == FLOAT) { return value.mValue.float_value; } else { *err = BAD_TYPE; return 0.0; } } if ((size_t)value.mField.getPosAtDepth(0) > key) { break; } } *err = BAD_INDEX; return 0.0; } string LogEvent::ToString() const { string result; result += StringPrintf("{ uid(%d) %lld %lld (%d)", mLogUid, (long long)mLogdTimestampNs, (long long)mElapsedTimestampNs, mTagId); for (const auto& value : mValues) { result += StringPrintf("%#x", value.mField.getField()) + "->" + value.mValue.toString() + " "; } result += " }"; return result; } void LogEvent::ToProto(ProtoOutputStream& protoOutput) const { writeFieldValueTreeToStream(mTagId, getValues(), &protoOutput); } void writeExperimentIdsToProto(const std::vector& experimentIds, std::vector* protoOut) { ProtoOutputStream proto; for (const auto& expId : experimentIds) { proto.write(FIELD_TYPE_INT64 | FIELD_COUNT_REPEATED | FIELD_ID_EXPERIMENT_ID, (long long)expId); } protoOut->resize(proto.size()); size_t pos = 0; sp reader = proto.data(); while (reader->readBuffer() != NULL) { size_t toRead = reader->currentToRead(); std::memcpy(protoOut->data() + pos, reader->readBuffer(), toRead); pos += toRead; reader->move(toRead); } } } // namespace statsd } // namespace os } // namespace android