Felix HAL: Added IVibrator event logs in dumpsys.

Ported the changes made in legacyHAL to Felix HAL
which involves adding the IVibrator event to the
HwApi to produce a friendly debugging logs.

Bug: 376330571
Flag: EXEMPT log only update
Test: Flash to device and verified dumpsys
Change-Id: I54262b7451b1ab07669eb9b7e5ad3c4cd3477016
Signed-off-by: Zouberou Sayibou <zouberou@google.com>

vibrator/common/HardwareBase.cpp

@@ -29,6 +29,13 @@ namespace android {
 namespace hardware {
 namespace vibrator {
 
+void HwApiBase::recordEvent(const char *func, const std::string &value) {
+   std::lock_guard<std::mutex> lock(mRecordsMutex);
+   mRecords.emplace_back(std::make_unique<Record<std::string>>
+                            (HwApiBase::RecordType::EVENT, func, value, nullptr));
+   mRecords.pop_front();
+}
+
 HwApiBase::HwApiBase() {
     mPathPrefix = std::getenv("HWAPI_PATH_PREFIX") ?: "";
     if (mPathPrefix.empty()) {

vibrator/common/HardwareBase.h

@@ -39,6 +39,7 @@ using ::android::base::unique_fd;
 class HwApiBase {
   private:
     using NamesMap = std::map<const std::ios *, std::string>;
+    enum class RecordType { EVENT, HWAPI };
 
     class RecordInterface {
       public:
@@ -48,12 +49,16 @@ class HwApiBase {
     template <typename T>
     class Record : public RecordInterface {
       public:
-        Record(const char *func, const T &value, const std::ios *stream)
+        Record(const RecordType &type, const char *func, const T &value, const std::ios *stream)
-            : mFunc(func), mValue(value), mStream(stream),
+            : mType(type),
+              mFunc(func),
+              mValue(value),
+              mStream(stream),
               mTp(std::chrono::system_clock::system_clock::now()) {}
         std::string toString(const NamesMap &names) override;
 
       private:
+        const RecordType mType;
         const char *mFunc;
         const T mValue;
         const std::ios *mStream;
@@ -66,6 +71,7 @@ class HwApiBase {
   public:
     HwApiBase();
     void debug(int fd);
+    void recordEvent(const char *func, const std::string &value);
 
   protected:
     void saveName(const std::string &name, const std::ios *stream);
@@ -176,7 +182,7 @@ bool HwApiBase::poll(const T &value, std::istream *stream, const int32_t timeout
 template <typename T>
 void HwApiBase::record(const char *func, const T &value, const std::ios *stream) {
     std::lock_guard<std::mutex> lock(mRecordsMutex);
-    mRecords.emplace_back(std::make_unique<Record<T>>(func, value, stream));
+    mRecords.emplace_back(std::make_unique<Record<T>>(RecordType::HWAPI, func, value, stream));
     mRecords.pop_front();
 }
 
@@ -188,10 +194,18 @@ std::string HwApiBase::Record<T>::toString(const NamesMap &names) {
     struct tm buf;
     auto lTime = localtime_r(&lTp, &buf);
 
-    ret << std::put_time(lTime, "%Y-%m-%d %H:%M:%S.") << std::setfill('0') << std::setw(3)
+    if (mType == RecordType::EVENT) {
-        << (std::chrono::duration_cast<std::chrono::milliseconds>(mTp.time_since_epoch()) % 1000)
+        ret << std::put_time(lTime, "%Y-%m-%d %H:%M:%S.") << std::setfill('0') << std::setw(3)
-                    .count()
+            << (std::chrono::duration_cast<std::chrono::milliseconds>(mTp.time_since_epoch()) %
-        << "    " << mFunc << " '" << names.at(mStream) << "' = '" << mValue << "'";
+                                                                              1000).count()
+            << " | " << "IVibrator::" << mFunc << " | " << mValue;
+    } else {
+        ret << "  \t" << std::put_time(lTime, "%Y-%m-%d %H:%M:%S.") << std::setfill('0')
+            << std::setw(3)
+            << (std::chrono::duration_cast<std::chrono::milliseconds>(mTp.time_since_epoch()) %
+                                                                              1000).count()
+            << "    " << mFunc << " '" << names.at(mStream) << "' = '" << mValue << "'";
+    }
     return ret.str();
 }
 

vibrator/cs40l26/Hardware.h

@@ -287,6 +287,10 @@ class HwApi : public Vibrator::HwApi, private HwApiBase {
         return true;
     }
 
+    void recordEvent(const char *func, const std::string &value) override {
+        HwApiBase::recordEvent(func, value);
+    }
+
     void debug(int fd) override { HwApiBase::debug(fd); }
 
   private:

vibrator/cs40l26/Vibrator.cpp

@@ -45,6 +45,14 @@ namespace aidl {
 namespace android {
 namespace hardware {
 namespace vibrator {
+
+#define RECORD(fmt, ...) { \
+  this->mHwApiDef->recordEvent(__func__, StringPrintf(fmt, ##__VA_ARGS__)); \
+  if (this->mIsDual) { \
+      this->mHwApiDual->recordEvent(__func__, StringPrintf(fmt, ##__VA_ARGS__)); \
+    } \
+}
+
 static constexpr uint16_t FF_CUSTOM_DATA_LEN_MAX_COMP = 2044;  // (COMPOSE_SIZE_MAX + 1) * 8 + 4
 static constexpr uint16_t FF_CUSTOM_DATA_LEN_MAX_PWLE = 2302;
 
@@ -461,6 +469,7 @@ Vibrator::Vibrator(std::unique_ptr<HwApi> hwApiDefault, std::unique_ptr<HwCal> h
     if ((mHwApiDual != nullptr) && (mHwCalDual != nullptr))
         mIsDual = true;
 
+    RECORD("mIsDual = %d", mIsDual);
     // ==================INPUT Devices== Base =================
     const char *inputEventName = std::getenv("INPUT_EVENT_NAME");
     const char *inputEventPathName = std::getenv("INPUT_EVENT_PATH");
@@ -816,6 +825,8 @@ ndk::ScopedAStatus Vibrator::off() {
     bool ret{true};
     const std::scoped_lock<std::mutex> lock(mActiveId_mutex);
 
+    RECORD("mActiveId = %d", mActiveId);
+
     if (mActiveId >= 0) {
         ALOGD("Off: Stop the active effect: %d", mActiveId);
         /* Stop the active effect. */
@@ -858,6 +869,7 @@ ndk::ScopedAStatus Vibrator::on(int32_t timeoutMs,
                                 const std::shared_ptr<IVibratorCallback> &callback) {
     ATRACE_NAME("Vibrator::on");
     ALOGD("Vibrator::on");
+    RECORD("timeoutMs = %d", timeoutMs);
 
     if (timeoutMs > MAX_TIME_MS) {
         return ndk::ScopedAStatus::fromExceptionCode(EX_ILLEGAL_ARGUMENT);
@@ -883,6 +895,8 @@ ndk::ScopedAStatus Vibrator::perform(Effect effect, EffectStrength strength,
                                      int32_t *_aidl_return) {
     ATRACE_NAME("Vibrator::perform");
     ALOGD("Vibrator::perform");
+    RECORD("effect = %s, strength = %s",
+                                toString(effect).c_str(), toString(strength).c_str());
     return performEffect(effect, strength, callback, _aidl_return);
 }
 
@@ -964,6 +978,8 @@ ndk::ScopedAStatus Vibrator::compose(const std::vector<CompositeEffect> &composi
                                      const std::shared_ptr<IVibratorCallback> &callback) {
     ATRACE_NAME("Vibrator::compose");
     ALOGD("Vibrator::compose");
+    RECORD("composite.size = %zu", composite.size());
+
     uint16_t size;
     uint16_t nextEffectDelay;
 

vibrator/cs40l26/Vibrator.h

@@ -16,6 +16,7 @@
 #pragma once
 
 #include <aidl/android/hardware/vibrator/BnVibrator.h>
+#include <android-base/stringprintf.h>
 #include <android-base/unique_fd.h>
 #include <linux/input.h>
 #include <tinyalsa/asoundlib.h>
@@ -29,6 +30,8 @@ namespace android {
 namespace hardware {
 namespace vibrator {
 
+using ::android::base::StringPrintf;
+
 class Vibrator : public BnVibrator {
   public:
     // APIs for interfacing with the GPIO pin.
@@ -103,6 +106,8 @@ class Vibrator : public BnVibrator {
                                      int *status) = 0;
         // Erase OWT waveform
         virtual bool eraseOwtEffect(int fd, int8_t effectIndex, std::vector<ff_effect> *effect) = 0;
+        // Records IVibrator Event.
+        virtual void recordEvent(const char *func, const std::string &value) = 0;
         // Emit diagnostic information to the given file.
         virtual void debug(int fd) = 0;
     };

vibrator/cs40l26/tests/mocks.h

@@ -58,6 +58,7 @@ class MockApi : public ::aidl::android::hardware::vibrator::Vibrator::HwApi {
                  bool(int fd, const uint8_t *owtData, const uint32_t numBytes, struct ff_effect *effect,
                       uint32_t *outEffectIndex, int *status));
     MOCK_METHOD3(eraseOwtEffect, bool(int fd, int8_t effectIndex, std::vector<ff_effect> *effect));
+    MOCK_METHOD2(recordEvent, void(const char *func, const std::string &value));
     MOCK_METHOD1(debug, void(int fd));
 
     ~MockApi() override { destructor(); };

vibrator/cs40l26/tests/test-vibrator.cpp

@@ -295,7 +295,7 @@ class VibratorTest : public Test {
         EXPECT_CALL(*mMockApi, setMinOnOffInterval(_)).Times(times);
         EXPECT_CALL(*mMockApi, getHapticAlsaDevice(_, _)).Times(times);
         EXPECT_CALL(*mMockApi, setHapticPcmAmp(_, _, _, _)).Times(times);
-
+        EXPECT_CALL(*mMockApi, recordEvent(_, _)).Times(times);
         EXPECT_CALL(*mMockApi, debug(_)).Times(times);
 
         EXPECT_CALL(*mMockCal, destructor()).Times(times);
@@ -340,6 +340,7 @@ TEST_F(VibratorTest, Constructor) {
 
     createMock(&mockapi, &mockcal, &mockgpio);
 
+    EXPECT_CALL(*mMockApi, recordEvent(_, _)).WillRepeatedly(DoDefault());
     EXPECT_CALL(*mMockCal, getF0(_))
             .InSequence(f0Seq)
             .WillOnce(DoAll(SetArgReferee<0>(f0Val), Return(true)));
@@ -387,6 +388,9 @@ TEST_F(VibratorTest, on) {
     Sequence s1, s2;
     uint16_t duration = std::rand() + 1;
 
+    EXPECT_CALL(*mMockApi, recordEvent(_, _))
+            .InSequence(s1)
+            .WillRepeatedly(DoDefault());
     EXPECT_CALL(*mMockApi, setFFGain(_, ON_GLOBAL_SCALE)).InSequence(s1).WillOnce(DoDefault());
     EXPECT_CALL(*mMockApi, setFFEffect(_, _, duration + MAX_COLD_START_LATENCY_MS))
             .InSequence(s2)
@@ -399,6 +403,7 @@ TEST_F(VibratorTest, on) {
 
 TEST_F(VibratorTest, off) {
     Sequence s1;
+    EXPECT_CALL(*mMockApi, recordEvent(_, _)).InSequence(s1).WillRepeatedly(DoDefault());
     EXPECT_CALL(*mMockApi, setFFGain(_, ON_GLOBAL_SCALE)).InSequence(s1).WillOnce(DoDefault());
     EXPECT_TRUE(mVibrator->off().isOk());
 }
@@ -528,6 +533,8 @@ TEST_P(EffectsTest, perform) {
     ExpectationSet eSetup;
     Expectation eActivate, ePollHaptics, ePollStop, eEraseDone;
 
+    eSetup += EXPECT_CALL(*mMockApi, recordEvent(_, _)).WillRepeatedly(DoDefault());
+
     if (scale != EFFECT_SCALE.end()) {
         EffectIndex index = EFFECT_INDEX.at(effect);
         duration = EFFECT_DURATIONS[index];
@@ -664,6 +671,7 @@ TEST_P(ComposeTest, compose) {
         return ndk::ScopedAStatus::ok();
     };
 
+    eSetup += EXPECT_CALL(*mMockApi, recordEvent(_, _)).WillRepeatedly(DoDefault());
     eSetup += EXPECT_CALL(*mMockApi, setFFGain(_, ON_GLOBAL_SCALE))
                       .After(eSetup)
                       .WillOnce(DoDefault());