Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

qa: parametrize logger usages #5173

Merged
merged 14 commits into from
Nov 19, 2023
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,7 @@ static void registerCurrentDirectoryIfModule(ModuleManager moduleManager) {
logger.info("Install path does not appear to be a module: {}", installPath);
}
} catch (IOException e) {
logger.warn("Could not read install path as module at " + installPath);
logger.warn("Could not read install path as module at {}", installPath);
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -108,6 +108,6 @@ public void setRenderSkeletons(boolean renderSkeletons) {

@Override
public void propertyChange(PropertyChangeEvent evt) {
logger.info("Set {} property to {}. ", evt.getPropertyName().toUpperCase(), evt.getNewValue()); // for debugging purposes
logger.info("Set {} property to {}.", evt.getPropertyName().toUpperCase(), evt.getNewValue()); // for debugging purposes
jdrueckert marked this conversation as resolved.
Show resolved Hide resolved
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -266,7 +266,7 @@ private void verifyInitialisation() {
* Logs software, environment and hardware information.
*/
private void logEnvironmentInfo() {
logger.info(TerasologyVersion.getInstance().toString());
logger.info("{}", TerasologyVersion.getInstance().toString());
jdrueckert marked this conversation as resolved.
Show resolved Hide resolved
logger.info("Home path: {}", PathManager.getInstance().getHomePath());
logger.info("Install path: {}", PathManager.getInstance().getInstallPath());
logger.info("Java: {} in {}", System.getProperty("java.version"), System.getProperty("java.home"));
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -234,7 +234,7 @@ private void popStep() {
current = null;
if (!loadProcesses.isEmpty()) {
current = loadProcesses.remove();
logger.debug(current.getMessage());
logger.debug("{}", current.getMessage());
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks weird 🙄 Is this necessary because of some quirk in the rules?

The only this might do is defer the call to toString on whatever type getMessage() returns. If that is already string, we don't gain anything from this...

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My understanding was that the parametrization is what avoids the call in case log level is not debug, so with
logger.debug(current.getMessage()) the call to getMessage() is done even if log level is "info"
while with
logger.debug("{}", current.getMessage()) the call to getMessage() is only done if log level is "debug" but not if it's "info"

Is my understanding incorrect?

Admittedly, in this particular case the call might not be particularly impactful.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is my understanding incorrect?

I think it indeed is. The only thing that is defered is the final call to toString I think.

Maybe this gets clearer if we write this part of the code like this:

// executed regardless of the log-level
Message message = current.getMessage(); 
// message.toString() is only called if DEBUG logs are enabled (happens inside)
logger.debug("{}", message);

The parameterization can only help as far as Java itself allows it. Here, we are passing the value of current.getMessage() to the method, that is, we evaluate that part already when calling it.

To make it a truly lazy evaluation we'd need a supplier, either for the whole message or for the inidividual parameters (see #5173 (comment)). I don't think the following code works, but that's how it would look like:

logger.debug(() -> current.getMessage());

Here, we pass a function that, if evaluated, will make the lookup on how to get the message from current.

current.begin();
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -65,7 +65,7 @@ public ModuleRegistry call() throws IOException {
}

int count = modules.size();
logger.info(String.format("Retrieved %d %s", count, (count == 1) ? "entry" : "entries"));
logger.info("Retrieved {} {}", count, (count == 1) ? "entry" : "entries");
}
return modules;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -99,7 +99,7 @@ public void registerEventHandler(ComponentSystem handler) {
return;
}

logger.debug("Registering event handler " + handlerClass.getName());
logger.debug("Registering event handler {}", handlerClass.getName());
for (Method method : handlerClass.getMethods()) {
ReceiveEvent receiveEventAnnotation = method.getAnnotation(ReceiveEvent.class);
if (receiveEventAnnotation != null) {
Expand Down Expand Up @@ -127,7 +127,7 @@ public void registerEventHandler(ComponentSystem handler) {
method.setAccessible(true);
Class<?>[] types = method.getParameterTypes();

logger.debug("Found method: " + method.toString());
logger.debug("Found method: {}", method);
if (!Event.class.isAssignableFrom(types[0]) || !EntityRef.class.isAssignableFrom(types[1])) {
logger.error("Invalid event handler method: {}", method.getName());
return;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,7 @@ public void refresh() {
TranslationProject proj = projects.computeIfAbsent(projectUrn, e -> new StandardTranslationProject());
proj.add(trans);
trans.subscribe(this::onAssetChanged);
logger.info("Discovered " + trans);
logger.info("Discovered {}", trans);
} else {
logger.warn("Ignoring invalid project projectUrn: {}", projectUrn);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -154,7 +154,7 @@ public String getDamageTypeName(Prefab damageType) {
if (damageType.hasComponent(DisplayNameComponent.class)) {
return damageType.getComponent(DisplayNameComponent.class).name;
} else {
logger.info(String.format("%s is missing a readable DisplayName", damageType.getName()));
logger.info("{} is missing a readable DisplayName", damageType.getName());
String damageTypeName = damageType.getName();
//damageType.getName() returns a ResourceUrn String such as "engine:directDamage"
//The following calls change the damage type to be more readable
Expand Down Expand Up @@ -315,35 +315,35 @@ private boolean isPredictionOfEventCorrect(EntityRef character, ActivationReques

Vector3f originPos = location.getWorldPosition(new Vector3f());
if (!(event.getOrigin().equals(originPos, 0.0001f))) {
String msg = "Player {} seems to have cheated: It stated that it performed an action from {} but the predicted position is {}";
logger.info(msg, getPlayerNameFromCharacter(character), event.getOrigin(), originPos);
logger.info("Player {} seems to have cheated: It stated that it performed an action from {} but the predicted position is {}",
getPlayerNameFromCharacter(character), event.getOrigin(), originPos);
return false;
}

if (event.isOwnedEntityUsage()) {
if (!event.getUsedOwnedEntity().exists()) {
String msg = "Denied activation attempt by {} since the used entity does not exist on the authority";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since the used entity does not exist on the authority",
getPlayerNameFromCharacter(character));
Comment on lines +325 to +326
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does our logging framework allow for passing a Supplier<String> for the log message? Here, it would be nice to avoid the computation of getPlayerNameFromCharacter(character) until we actually have to log it. Maybe that's guarded sufficiently, though, and INFO logs are enabled by default currently 🤷

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My understanding was that the parametrization does exactly that - avoid the computation until we actually have to log it. But I don't know for sure, so I could be misunderstanding how this works.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@soloturn the parts mentioned in that manual I understood. It doesn't speak to method calls in the parameters, though.
But @skaldarnar's comment above explains it nicely 👍

Copy link
Contributor

@soloturn soloturn Nov 15, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ha, with you guys one learns something new all the time. there is indeed a fluent API to slf4j-2.0, @skaldarnar , which allows to pass suppliers. we are at slf4j-1.7 at the moment:
https://www.slf4j.org/manual.html#fluent

return false;
}
if (!networkSystem.getOwnerEntity(event.getUsedOwnedEntity()).equals(networkSystem.getOwnerEntity(character))) {
String msg = "Denied activation attempt by {} since it does not own the entity at the authority";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since it does not own the entity at the authority",
getPlayerNameFromCharacter(character));
return false;
}
} else {
// check for cheats so that data can later be trusted:
if (event.getUsedOwnedEntity().exists()) {
String msg = "Denied activation attempt by {} since it is not properly marked as owned entity usage";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since it is not properly marked as owned entity usage",
getPlayerNameFromCharacter(character));
return false;
}
}

if (event.isEventWithTarget()) {
if (!event.getTarget().exists()) {
String msg = "Denied activation attempt by {} since the target does not exist on the authority";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since the target does not exist on the authority",
getPlayerNameFromCharacter(character));
return false; // can happen if target existed on client
}

Expand All @@ -360,8 +360,8 @@ private boolean isPredictionOfEventCorrect(EntityRef character, ActivationReques
HitResult result = physics.rayTrace(originPos, direction, interactionRange, Sets.newHashSet(character),
DEFAULTPHYSICSFILTER);
if (!result.isHit()) {
String msg = "Denied activation attempt by {} since at the authority there was nothing to activate at that place";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since at the authority there was nothing to activate at that place",
getPlayerNameFromCharacter(character));
return false;
}
EntityRef hitEntity = result.getEntity();
Expand All @@ -371,31 +371,31 @@ private boolean isPredictionOfEventCorrect(EntityRef character, ActivationReques
* server entity dump. When certain fields don't get replicated, then wrong entity might get hin in the
* hit test.
*/
String msg = "Denied activation attempt by {} since at the authority another entity would have been activated";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since at the authority another entity would have been activated",
getPlayerNameFromCharacter(character));
return false;
}

if (!(event.getHitPosition().equals(result.getHitPoint(), 0.0001f))) {
String msg = "Denied activation attempt by {} since at the authority the object got hit at a differnt position";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since at the authority the object got hit at a differnt position",
getPlayerNameFromCharacter(character));
return false;
}
} else {
// In order to trust the data later we need to verify it even if it should be correct if no one cheats:
if (event.getTarget().exists()) {
String msg = "Denied activation attempt by {} since the event was not properly labeled as having a target";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since the event was not properly labeled as having a target",
getPlayerNameFromCharacter(character));
return false;
}
if (event.getHitPosition() != null) {
String msg = "Denied activation attempt by {} since the event was not properly labeled as having a hit position";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since the event was not properly labeled as having a hit position",
getPlayerNameFromCharacter(character));
return false;
}
if (event.getHitNormal() != null) {
String msg = "Denied activation attempt by {} since the event was not properly labeled as having a hit delta";
logger.info(msg, getPlayerNameFromCharacter(character));
logger.info("Denied activation attempt by {} since the event was not properly labeled as having a hit delta",
getPlayerNameFromCharacter(character));
return false;
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -32,8 +32,8 @@ public void preBegin() {
String moduleName = moduleConfig.moduleName;
Map<String, String> properties;
if (propertiesPerModule.containsKey(moduleName)) {
logger.error("Encountered more than one Module Config for module - " + moduleName +
", this is not recommended, as the property values visible are not going to be well defined.");
logger.error("Encountered more than one Module Config for module - {}, this is not recommended, " +
"as the property values visible are not going to be well defined.", moduleName);
properties = propertiesPerModule.get(moduleName);
} else {
properties = new HashMap<>();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -82,7 +82,7 @@ public void updateExtentsOnBlockItemBoxShape(OnAddedComponent event, EntityRef i
BlockFamily blockFamily = blockItemComponent.blockFamily;

if (blockFamily == null) {
LOGGER.warn("Prefab " + itemEntity.getParentPrefab().getName() + " does not have a block family");
LOGGER.warn("Prefab {} does not have a block family", itemEntity.getParentPrefab().getName());
return;
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -160,8 +160,8 @@ private void receiveModuleStart(ChannelHandlerContext channelHandlerContext,
joinStatus.setCurrentActivity(
"Downloading " + moduleDataHeader.getId() + ":" + moduleDataHeader.getVersion() + " ("
+ sizeString + "," + missingModules.size() + " modules remain)");
logger.info("Downloading " + moduleDataHeader.getId() + ":" + moduleDataHeader.getVersion() + " ("
+ sizeString + "," + missingModules.size() + " modules remain)");
logger.info("Downloading {}: {} ({}, {} modules remain)", moduleDataHeader.getId(), moduleDataHeader.getVersion(),
sizeString, missingModules.size());
receivingModule = moduleDataHeader;
lengthReceived = 0;
try {
Expand All @@ -176,8 +176,7 @@ private void receiveModuleStart(ChannelHandlerContext channelHandlerContext,
}
}
} else {
logger.error("Received unwanted module {}:{} from server", moduleDataHeader.getId(),
moduleDataHeader.getVersion());
logger.error("Received unwanted module {}:{} from server", moduleDataHeader.getId(), moduleDataHeader.getVersion());
joinStatus.setErrorMessage("Module download error");
channelHandlerContext.channel().close();
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -827,7 +827,7 @@ private void processRemovedClient(Client client) {
}
clientList.remove(client);
clientPlayerLookup.remove(client.getEntity());
logger.info("Client disconnected: " + client.getName());
logger.info("Client disconnected: {}", client.getName());
storageManager.deactivatePlayer(client);
client.getEntity().send(new DisconnectedEvent());
client.disconnect();
Expand Down Expand Up @@ -973,8 +973,7 @@ private <T> Map<Class<? extends T>, Integer> generateIds(ClassLibrary<T> classLi
int fieldId = 0;
for (FieldMetadata<?, ?> field : metadata.getFields()) {
if (fieldId >= 256) {
logger.error("Class {} has too many fields (>255), serialization will be incomplete",
metadata.getId());
logger.error("Class {} has too many fields (>255), serialization will be incomplete", metadata.getId());
break;
}
field.setId((byte) fieldId);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,7 @@ public TextureRegionAsset getFromString(String representation) {
if (region.isPresent()) {
return region.get();
} else {
logger.error("Failed to resolve texture region '" + representation + "'");
logger.error("Failed to resolve texture region '{}'", representation);
return Assets.getTextureRegion("engine:default").get();
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@ public TextureRegion getFromString(String representation) {
if (region.isPresent()) {
return region.get();
} else {
logger.error("Failed to resolve texture region '" + representation + "'");
logger.error("Failed to resolve texture region '{}'", representation);
return Assets.getTextureRegion("engine:default").get();
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,7 @@ public UITextureRegion getFromString(String representation) {
if (region.isPresent()) {
return region.get();
} else {
logger.error("Failed to resolve texture region '" + representation + "'");
logger.error("Failed to resolve texture region '{}'", representation);
return Assets.getTextureRegion("engine:default").get();
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -114,7 +114,7 @@ private InputEvent createNewBindEvent(InputEvent originalEvent) {
| InvocationTargetException
| InstantiationException
exception) {
logger.error("ERROR!!! Event not Identified: " + originalEvent.toString(), exception);
logger.error("ERROR!!! Event not Identified: {}", originalEvent, exception);
}
return null;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -307,7 +307,7 @@ public void registerEventHandler(ComponentSystem handler) {
return;
}

logger.debug("Registering event handler " + handlerClass.getName());
logger.debug("Registering event handler {}", handlerClass.getName());
for (Method method : handlerClass.getMethods()) {
ReceiveEvent receiveEventAnnotation = method.getAnnotation(ReceiveEvent.class);
if (receiveEventAnnotation != null) {
Expand All @@ -334,7 +334,7 @@ public void registerEventHandler(ComponentSystem handler) {
method.setAccessible(true);
Class<?>[] types = method.getParameterTypes();

logger.debug("Found method: " + method.toString());
logger.debug("Found method: {}", method);
if (!Event.class.isAssignableFrom(types[0]) || !EntityRef.class.isAssignableFrom(types[1])) {
logger.error("Invalid event handler method: {}", method.getName());
return;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -548,7 +548,7 @@ public void dispose() {
protected void addDesiredStateChange(StateChange stateChange) {
if (stateChange.isTheDefaultInstance()) {
logger.error("Attempted to add default state change {} to the set of desired state changes. (Node: {})",
stateChange.getClass().getSimpleName(), this.toString());
stateChange.getClass().getSimpleName(), this);
}
desiredStateChanges.add(stateChange);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -118,9 +118,9 @@ protected FBO generateWithDimensions(FboConfig fboConfig, FBO.Dimensions dimensi
// At this stage it's unclear what should be done in this circumstances as I (manu3d) do not know what
// the effects of using an incomplete FrameBuffer are. Throw an exception? Live with visual artifacts?
if (fbo.getStatus() == FBO.Status.INCOMPLETE) {
logger.error("FBO " + fboConfig.getName() + " is incomplete. Look earlier in the log for details.");
logger.error("FBO {} is incomplete. Look earlier in the log for details.", fboConfig.getName());
} else if (fbo.getStatus() == FBO.Status.UNEXPECTED) {
logger.error("FBO " + fboConfig.getName() + " has generated an unexpected status code. Look earlier in the log for details.");
logger.error("FBO {} has generated an unexpected status code. Look earlier in the log for details.", fboConfig.getName());
}
return fbo;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -169,7 +169,7 @@ public void disconnect(Node fromNode, Node toNode) {
Preconditions.checkNotNull(toNode, "toNode cannot be null!");

if (!graph.hasEdgeConnecting(fromNode, toNode)) {
logger.warn("Trying to disconnect two nodes that aren't connected, {} and {}", fromNode.getUri(), toNode.getUri());
logger.warn("Trying to disconnect two nodes that aren't connected, {} and {}", fromNode.getUri(), toNode.getUri());
}

graph.removeEdge(fromNode, toNode);
Expand Down
Loading
Loading