Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit e8e2c42e authored by Austin Borger's avatar Austin Borger
Browse files

CameraService: Reduce log spam from onCameraAccessPrioritiesChanged. 

Bug 231550909 shows an instance of log spam where EX_TRANSACTION_FAILED
is returned from binder. Only one instance of the log is helpful, and
EX_TRANSACTION_FAILED is likely to indicate further failures in the
future, so mute these errors when that happens. Also print the uid and
pid of the failing process to disambiguate the failure, and add
additional checks for the binder status where there previously were
none, so that we may pinpoint the first failed callback.

Bug: 231550909
Test: Smoke tested GCA.
Change-Id: Ibdf54b0d75c0cbc6d147854b0671649bf76a8890
parent f08dbca5

services/camera/libcameraservice/CameraService.cpp

+30 −14
Original line number Diff line number Diff line
@@ -269,7 +269,10 @@ void CameraService::broadcastTorchModeStatus(const String8& cameraId, TorchModeS 
                    cameraId.c_str());

            continue;

        }

        i->getListener()->onTorchStatusChanged(mapToInterface(status), String16{cameraId});

        auto ret = i->getListener()->onTorchStatusChanged(mapToInterface(status),

                String16{cameraId});

        i->handleBinderStatus(ret, "%s: Failed to trigger onTorchStatusChanged for %d:%d: %d",

                __FUNCTION__, i->getListenerUid(), i->getListenerPid(), ret.exceptionCode());

    }

}
@@ -538,8 +541,12 @@ void CameraService::onDeviceStatusChanged(const String8& id, 
                        id.c_str());

                continue;

            }

            listener->getListener()->onPhysicalCameraStatusChanged(mapToInterface(newStatus),

                    id16, physicalId16);

            auto ret = listener->getListener()->onPhysicalCameraStatusChanged(

                    mapToInterface(newStatus), id16, physicalId16);

            listener->handleBinderStatus(ret,

                    "%s: Failed to trigger onPhysicalCameraStatusChanged for %d:%d: %d",

                    __FUNCTION__, listener->getListenerUid(), listener->getListenerPid(),

                    ret.exceptionCode());

        }

    }

}
@@ -580,8 +587,11 @@ void CameraService::broadcastTorchStrengthLevel(const String8& cameraId, 
        int32_t newStrengthLevel) {

    Mutex::Autolock lock(mStatusListenerLock);

    for (auto& i : mListenerList) {

        i->getListener()->onTorchStrengthLevelChanged(String16{cameraId},

        auto ret = i->getListener()->onTorchStrengthLevelChanged(String16{cameraId},

                newStrengthLevel);

        i->handleBinderStatus(ret,

                "%s: Failed to trigger onTorchStrengthLevelChanged for %d:%d: %d", __FUNCTION__,

                i->getListenerUid(), i->getListenerPid(), ret.exceptionCode());

    }

}
@@ -2375,10 +2385,8 @@ void CameraService::notifyMonitoredUids() { 


    for (const auto& it : mListenerList) {

        auto ret = it->getListener()->onCameraAccessPrioritiesChanged();

        if (!ret.isOk()) {

            ALOGE("%s: Failed to trigger permission callback: %d", __FUNCTION__,

                    ret.exceptionCode());

        }

        it->handleBinderStatus(ret, "%s: Failed to trigger permission callback for %d:%d: %d",

                __FUNCTION__, it->getListenerUid(), it->getListenerPid(), ret.exceptionCode());

    }

}
@@ -4626,8 +4634,12 @@ void CameraService::updateStatus(StatusInternal status, const String8& cameraId, 
                            cameraId.c_str());

                    continue;

                }

                listener->getListener()->onStatusChanged(mapToInterface(status),

                auto ret = listener->getListener()->onStatusChanged(mapToInterface(status),

                        String16(cameraId));

                listener->handleBinderStatus(ret,

                        "%s: Failed to trigger onStatusChanged callback for %d:%d: %d",

                        __FUNCTION__, listener->getListenerUid(), listener->getListenerPid(),

                        ret.exceptionCode());

            }

        });

}
@@ -4660,10 +4672,10 @@ void CameraService::updateOpenCloseStatus(const String8& cameraId, bool open, 
        } else {

            ret = it->getListener()->onCameraClosed(cameraId64);

        }

        if (!ret.isOk()) {

            ALOGE("%s: Failed to trigger onCameraOpened/onCameraClosed callback: %d", __FUNCTION__,

                    ret.exceptionCode());

        }



        it->handleBinderStatus(ret,

                "%s: Failed to trigger onCameraOpened/onCameraClosed callback for %d:%d: %d",

                __FUNCTION__, it->getListenerUid(), it->getListenerPid(), ret.exceptionCode());

    }

}
@@ -4764,8 +4776,12 @@ void CameraService::notifyPhysicalCameraStatusLocked(int32_t status, 
                        String8(physicalCameraId).c_str());

                continue;

            }

            listener->getListener()->onPhysicalCameraStatusChanged(status,

            auto ret = listener->getListener()->onPhysicalCameraStatusChanged(status,

                    logicalCameraId, physicalCameraId);

            listener->handleBinderStatus(ret,

                    "%s: Failed to trigger onPhysicalCameraStatusChanged for %d:%d: %d",

                    __FUNCTION__, listener->getListenerUid(), listener->getListenerPid(),

                    ret.exceptionCode());

        }

    }

}

services/camera/libcameraservice/CameraService.h

+26 −0
Original line number Diff line number Diff line
@@ -1057,6 +1057,29 @@ private: 
                return IInterface::asBinder(mListener)->linkToDeath(this);

            }



            template<typename... args_t>

            void handleBinderStatus(const binder::Status &ret, const char *logOnError,

                    args_t... args) {

                if (!ret.isOk() &&

                        (ret.exceptionCode() != binder::Status::Exception::EX_TRANSACTION_FAILED

                        || !mLastTransactFailed)) {

                    ALOGE(logOnError, args...);

                }



                // If the transaction failed, the process may have died (or other things, see

                // b/28321379). Mute consecutive errors from this listener to avoid log spam.

                if (ret.exceptionCode() == binder::Status::Exception::EX_TRANSACTION_FAILED) {

                    if (!mLastTransactFailed) {

                        ALOGE("%s: Muting similar errors from listener %d:%d", __FUNCTION__,

                                mListenerUid, mListenerPid);

                    }

                    mLastTransactFailed = true;

                } else {

                    // Reset mLastTransactFailed when binder becomes healthy again.

                    mLastTransactFailed = false;

                }

            }



            virtual void binderDied(const wp<IBinder> &/*who*/) {

                auto parent = mParent.promote();

                if (parent.get() != nullptr) {
@@ -1077,6 +1100,9 @@ private: 
            int mListenerPid = -1;

            bool mIsVendorListener = false;

            bool mOpenCloseCallbackAllowed = false;



            // Flag for preventing log spam when binder becomes unhealthy

            bool mLastTransactFailed = false;

    };



    // Guarded by mStatusListenerMutex