servicemanager: include caller info in logs
In cases like b/329039146, it can be difficult to understand
where spam is coming from, because we only have the logs.
This adds caller information to servicemanager logs, so that
we can easily identify what is causing an issue, even if we
don't have logs.
Btw - passing around a calling context like this, instead of
referencing thread locals, is how I think we should do all
ACL with binder, but that's another story.
Example log output:
03-27 00:32:02.242 0 0 I servicemanager: Caller(pid=2145,uid=1001,sid=u:r:radio:s0) Found android.hardware.radio.data.IRadioData/slot1 in device VINTF manifest.
Bug: N/A
Test: N/A
Change-Id: Iea45e4d22f28f28592eb73a129117204c6c8e814
diff --git a/cmds/servicemanager/ServiceManager.cpp b/cmds/servicemanager/ServiceManager.cpp
index bf85e61..6ec924d 100644
--- a/cmds/servicemanager/ServiceManager.cpp
+++ b/cmds/servicemanager/ServiceManager.cpp
@@ -115,18 +115,20 @@
return instance.package() + "." + instance.interface() + "/" + instance.instance();
}
-static bool isVintfDeclared(const std::string& name) {
+static bool isVintfDeclared(const Access::CallingContext& ctx, const std::string& name) {
NativeName nname;
if (NativeName::fill(name, &nname)) {
bool found = forEachManifest([&](const ManifestWithDescription& mwd) {
if (mwd.manifest->hasNativeInstance(nname.package, nname.instance)) {
- ALOGI("Found %s in %s VINTF manifest.", name.c_str(), mwd.description);
+ ALOGI("%s Found %s in %s VINTF manifest.", ctx.toDebugString().c_str(),
+ name.c_str(), mwd.description);
return true; // break
}
return false; // continue
});
if (!found) {
- ALOGI("Could not find %s in the VINTF manifest.", name.c_str());
+ ALOGI("%s Could not find %s in the VINTF manifest.", ctx.toDebugString().c_str(),
+ name.c_str());
}
return found;
}
@@ -136,7 +138,8 @@
bool found = forEachManifest([&](const ManifestWithDescription& mwd) {
if (mwd.manifest->hasAidlInstance(aname.package, aname.iface, aname.instance)) {
- ALOGI("Found %s in %s VINTF manifest.", name.c_str(), mwd.description);
+ ALOGI("%s Found %s in %s VINTF manifest.", ctx.toDebugString().c_str(), name.c_str(),
+ mwd.description);
return true; // break
}
return false; // continue
@@ -161,8 +164,9 @@
}
// Although it is tested, explicitly rebuilding qualified name, in case it
// becomes something unexpected.
- ALOGI("Could not find %s.%s/%s in the VINTF manifest. %s.", aname.package.c_str(),
- aname.iface.c_str(), aname.instance.c_str(), available.c_str());
+ ALOGI("%s Could not find %s.%s/%s in the VINTF manifest. %s.", ctx.toDebugString().c_str(),
+ aname.package.c_str(), aname.iface.c_str(), aname.instance.c_str(),
+ available.c_str());
}
return found;
@@ -290,12 +294,13 @@
return ret;
}
-static bool meetsDeclarationRequirements(const sp<IBinder>& binder, const std::string& name) {
+static bool meetsDeclarationRequirements(const Access::CallingContext& ctx,
+ const sp<IBinder>& binder, const std::string& name) {
if (!Stability::requiresVintfDeclaration(binder)) {
return true;
}
- return isVintfDeclared(name);
+ return isVintfDeclared(ctx, name);
}
#endif // !VENDORSERVICEMANAGER
@@ -307,7 +312,7 @@
// clear this bit so that we can abort in other cases, where it would
// mean inconsistent logic in servicemanager (unexpected and tested, but
// the original lazy service impl here had that bug).
- LOG(WARNING) << "a service was removed when there are clients";
+ ALOGW("A service was removed when there are clients");
}
}
@@ -421,25 +426,26 @@
}
if (!isValidServiceName(name)) {
- ALOGE("Invalid service name: %s", name.c_str());
+ ALOGE("%s Invalid service name: %s", ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_ARGUMENT, "Invalid service name.");
}
#ifndef VENDORSERVICEMANAGER
- if (!meetsDeclarationRequirements(binder, name)) {
+ if (!meetsDeclarationRequirements(ctx, binder, name)) {
// already logged
return Status::fromExceptionCode(Status::EX_ILLEGAL_ARGUMENT, "VINTF declaration error.");
}
#endif // !VENDORSERVICEMANAGER
if ((dumpPriority & DUMP_FLAG_PRIORITY_ALL) == 0) {
- ALOGW("Dump flag priority is not set when adding %s", name.c_str());
+ ALOGW("%s Dump flag priority is not set when adding %s", ctx.toDebugString().c_str(),
+ name.c_str());
}
// implicitly unlinked when the binder is removed
if (binder->remoteBinder() != nullptr &&
binder->linkToDeath(sp<ServiceManager>::fromExisting(this)) != OK) {
- ALOGE("Could not linkToDeath when adding %s", name.c_str());
+ ALOGE("%s Could not linkToDeath when adding %s", ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_STATE, "Couldn't linkToDeath.");
}
@@ -541,7 +547,7 @@
}
if (!isValidServiceName(name)) {
- ALOGE("Invalid service name: %s", name.c_str());
+ ALOGE("%s Invalid service name: %s", ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_ARGUMENT, "Invalid service name.");
}
@@ -552,7 +558,7 @@
if (OK !=
IInterface::asBinder(callback)->linkToDeath(
sp<ServiceManager>::fromExisting(this))) {
- ALOGE("Could not linkToDeath when adding %s", name.c_str());
+ ALOGE("%s Could not linkToDeath when adding %s", ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_STATE, "Couldn't link to death.");
}
@@ -584,7 +590,8 @@
}
if (!found) {
- ALOGE("Trying to unregister callback, but none exists %s", name.c_str());
+ ALOGE("%s Trying to unregister callback, but none exists %s", ctx.toDebugString().c_str(),
+ name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_STATE, "Nothing to unregister.");
}
@@ -601,7 +608,7 @@
*outReturn = false;
#ifndef VENDORSERVICEMANAGER
- *outReturn = isVintfDeclared(name);
+ *outReturn = isVintfDeclared(ctx, name);
#endif
return Status::ok();
}
@@ -733,18 +740,16 @@
}
void ServiceManager::tryStartService(const Access::CallingContext& ctx, const std::string& name) {
- ALOGI("Since '%s' could not be found (requested by debug pid %d), trying to start it as a lazy "
- "AIDL service. (if it's not configured to be a lazy service, it may be stuck starting or "
- "still starting).",
- name.c_str(), ctx.debugPid);
+ ALOGI("%s Since '%s' could not be found trying to start it as a lazy AIDL service. (if it's "
+ "not configured to be a lazy service, it may be stuck starting or still starting).",
+ ctx.toDebugString().c_str(), name.c_str());
std::thread([=] {
if (!base::SetProperty("ctl.interface_start", "aidl/" + name)) {
- ALOGI("Tried to start aidl service %s as a lazy service, but was unable to. Usually "
- "this happens when a "
- "service is not installed, but if the service is intended to be used as a "
- "lazy service, then it may be configured incorrectly.",
- name.c_str());
+ ALOGI("%s Tried to start aidl service %s as a lazy service, but was unable to. Usually "
+ "this happens when a service is not installed, but if the service is intended to "
+ "be used as a lazy service, then it may be configured incorrectly.",
+ ctx.toDebugString().c_str(), name.c_str());
}
}).detach();
}
@@ -762,26 +767,28 @@
auto serviceIt = mNameToService.find(name);
if (serviceIt == mNameToService.end()) {
- ALOGE("Could not add callback for nonexistent service: %s", name.c_str());
+ ALOGE("%s Could not add callback for nonexistent service: %s", ctx.toDebugString().c_str(),
+ name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_ARGUMENT, "Service doesn't exist.");
}
if (serviceIt->second.ctx.debugPid != IPCThreadState::self()->getCallingPid()) {
- ALOGW("Only a server can register for client callbacks (for %s)", name.c_str());
+ ALOGW("%s Only a server can register for client callbacks (for %s)",
+ ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_UNSUPPORTED_OPERATION,
"Only service can register client callback for itself.");
}
if (serviceIt->second.binder != service) {
- ALOGW("Tried to register client callback for %s but a different service is registered "
+ ALOGW("%s Tried to register client callback for %s but a different service is registered "
"under this name.",
- name.c_str());
+ ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_ARGUMENT, "Service mismatch.");
}
if (OK !=
IInterface::asBinder(cb)->linkToDeath(sp<ServiceManager>::fromExisting(this))) {
- ALOGE("Could not linkToDeath when adding client callback for %s", name.c_str());
+ ALOGE("%s Could not linkToDeath when adding client callback for %s", name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_STATE, "Couldn't linkToDeath.");
}
@@ -919,13 +926,14 @@
auto serviceIt = mNameToService.find(name);
if (serviceIt == mNameToService.end()) {
- ALOGW("Tried to unregister %s, but that service wasn't registered to begin with.",
- name.c_str());
+ ALOGW("%s Tried to unregister %s, but that service wasn't registered to begin with.",
+ ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_STATE, "Service not registered.");
}
if (serviceIt->second.ctx.debugPid != IPCThreadState::self()->getCallingPid()) {
- ALOGW("Only a server can unregister itself (for %s)", name.c_str());
+ ALOGW("%s Only a server can unregister itself (for %s)", ctx.toDebugString().c_str(),
+ name.c_str());
return Status::fromExceptionCode(Status::EX_UNSUPPORTED_OPERATION,
"Service can only unregister itself.");
}
@@ -933,8 +941,8 @@
sp<IBinder> storedBinder = serviceIt->second.binder;
if (binder != storedBinder) {
- ALOGW("Tried to unregister %s, but a different service is registered under this name.",
- name.c_str());
+ ALOGW("%s Tried to unregister %s, but a different service is registered under this name.",
+ ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_STATE,
"Different service registered under this name.");
}
@@ -942,7 +950,8 @@
// important because we don't have timer-based guarantees, we don't want to clear
// this
if (serviceIt->second.guaranteeClient) {
- ALOGI("Tried to unregister %s, but there is about to be a client.", name.c_str());
+ ALOGI("%s Tried to unregister %s, but there is about to be a client.",
+ ctx.toDebugString().c_str(), name.c_str());
return Status::fromExceptionCode(Status::EX_ILLEGAL_STATE,
"Can't unregister, pending client.");
}
@@ -952,7 +961,8 @@
constexpr size_t kKnownClients = 2;
if (handleServiceClientCallback(kKnownClients, name, false)) {
- ALOGI("Tried to unregister %s, but there are clients.", name.c_str());
+ ALOGI("%s Tried to unregister %s, but there are clients.", ctx.toDebugString().c_str(),
+ name.c_str());
// Since we had a failed registration attempt, and the HIDL implementation of
// delaying service shutdown for multiple periods wasn't ported here... this may
@@ -963,7 +973,7 @@
"Can't unregister, known client.");
}
- ALOGI("Unregistering %s", name.c_str());
+ ALOGI("%s Unregistering %s", ctx.toDebugString().c_str(), name.c_str());
mNameToService.erase(name);
return Status::ok();