Varargified log calls.

git-svn-id: svn+ssh://src.earth.threerings.net/narya/trunk@5697 542714f4-19e9-0310-aa3c-eee0fc999fb1
This commit is contained in:
Michael Bayne
2009-03-26 00:02:19 +00:00
parent 647a25dfdc
commit 688f2580ed
46 changed files with 231 additions and 272 deletions
@@ -123,7 +123,7 @@ public class ConfigEditorPanel extends JPanel
// documentation inherited from interface // documentation inherited from interface
public void requestFailed (String reason) public void requestFailed (String reason)
{ {
log.warning("Failed to get config info [reason=" + reason + "]."); log.warning("Failed to get config info", "reason", reason);
} }
/** Our client context. */ /** Our client context. */
@@ -154,8 +154,7 @@ public abstract class FieldEditor extends JPanel
try { try {
return _field.get(_object); return _field.get(_object);
} catch (Exception e) { } catch (Exception e) {
log.warning("Failed to fetch field [field=" + _field + log.warning("Failed to fetch field", "field", _field, "object", _object, "error", e);
", object=" + _object + ", error=" + e + "].");
return null; return null;
} }
} }
@@ -209,8 +209,7 @@ public abstract class ConfigRegistry
try { try {
value = object.getAttribute(event.getName()); value = object.getAttribute(event.getName());
} catch (ObjectAccessException oae) { } catch (ObjectAccessException oae) {
log.warning("Exception getting field [name=" + event.getName() + log.warning("Exception getting field", "name", event.getName(), "exception", oae);
", exception=" + oae + "].");
return; return;
} }
updateValue(event.getName(), value); updateValue(event.getName(), value);
@@ -252,9 +251,8 @@ public abstract class ConfigRegistry
} else if (value instanceof long[]) { } else if (value instanceof long[]) {
setValue(key, (long[])value); setValue(key, (long[])value);
} else { } else {
log.info("Unable to flush config obj change [cobj=" + object.getClass().getName() + log.info("Unable to flush config obj change", "cobj", object.getClass().getName(),
", key=" + key + ", type=" + value.getClass().getName() + "key", key, "type", value.getClass().getName(), "value", value);
", value=" + value + "].");
} }
} }
@@ -327,19 +325,19 @@ public abstract class ConfigRegistry
serialize(key, nameToKey(key), deserializedValue); serialize(key, nameToKey(key), deserializedValue);
} }
} catch (Exception e) { } catch (Exception e) {
log.warning("Failure decoding config value [type=" + type + log.warning("Failure decoding config value", "type", type, "field", field,
", field=" + field + ", exception=" + e + "]."); "exception", e);
} }
} else { } else {
log.warning("Can't init field of unknown type " + log.warning("Can't init field of unknown type",
"[cobj=" + object.getClass().getName() + ", key=" + key + "cobj", object.getClass().getName(), "key", key,
", type=" + type.getName() + "]."); "type", type.getName());
} }
} catch (IllegalAccessException iae) { } catch (IllegalAccessException iae) {
log.warning("Can't set field [cobj=" + object.getClass().getName() + log.warning("Can't set field", "cobj", object.getClass().getName(), "key", key,
", key=" + key + ", error=" + iae + "]."); "error", iae);
} }
} }
@@ -353,17 +351,15 @@ public abstract class ConfigRegistry
try { try {
value = object.getAttribute(attributeName); value = object.getAttribute(attributeName);
} catch (ObjectAccessException oae) { } catch (ObjectAccessException oae) {
log.warning("Exception getting field [name=" + attributeName + log.warning("Exception getting field", "name", attributeName, "error", oae);
", error=" + oae + "].");
return; return;
} }
if (value instanceof Streamable) { if (value instanceof Streamable) {
serialize(attributeName, key, value); serialize(attributeName, key, value);
} else { } else {
log.info("Unable to flush config obj change [cobj=" + object.getClass().getName() + log.info("Unable to flush config obj change", "cobj", object.getClass().getName(),
", key=" + key + ", type=" + value.getClass().getName() + "key", key, "type", value.getClass().getName(), "value", value);
", value=" + value + "].");
} }
} }
@@ -133,7 +133,7 @@ public class DatabaseConfigRegistry extends ConfigRegistry
try { try {
_data = _repo.loadConfig(_node, _path); _data = _repo.loadConfig(_node, _path);
} catch (DatabaseException pe) { } catch (DatabaseException pe) {
log.warning("Failed to load object configuration [path=" + _path + "].", pe); log.warning("Failed to load object configuration", "path", _path, pe);
_data = new HashMap<String, String>(); _data = new HashMap<String, String>();
} }
@@ -102,7 +102,7 @@ public abstract class BureauDirector extends BasicDirector
agent.init(agentObject); agent.init(agentObject);
agent.start(); agent.start();
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Could not create agent [obj=" + agentObject + "]", t); log.warning("Could not create agent", "obj", agentObject, t);
_bureauService.agentCreationFailed(_ctx.getClient(), oid); _bureauService.agentCreationFailed(_ctx.getClient(), oid);
return; return;
} }
@@ -116,7 +116,7 @@ public abstract class BureauDirector extends BasicDirector
*/ */
protected synchronized void requestFailed (int oid, ObjectAccessException cause) protected synchronized void requestFailed (int oid, ObjectAccessException cause)
{ {
log.warning("Could not subscribe to agent [oid=" + oid + "]", cause); log.warning("Could not subscribe to agent", "oid", oid, cause);
} }
@Override // from BasicDirector @Override // from BasicDirector
@@ -43,8 +43,8 @@ public class BureauAuthenticator extends ChainedAuthenticator
rsp.getData().code = AuthResponseData.SUCCESS; rsp.getData().code = AuthResponseData.SUCCESS;
} else { } else {
log.warning("Received invalid bureau auth request [creds=" + log.warning("Received invalid bureau auth request",
creds + "], problem: " + problem); "creds", creds + "], problem: " + problem);
rsp.getData().code = AuthCodes.SERVER_ERROR; rsp.getData().code = AuthCodes.SERVER_ERROR;
} }
} }
@@ -1017,8 +1017,8 @@ public class ChatDirector extends BasicDirector
if (bundle != null && _msgmgr != null) { if (bundle != null && _msgmgr != null) {
MessageBundle msgb = _msgmgr.getBundle(bundle); MessageBundle msgb = _msgmgr.getBundle(bundle);
if (msgb == null) { if (msgb == null) {
log.warning("No message bundle available to translate message " + log.warning("No message bundle available to translate message", "bundle", bundle,
"[bundle=" + bundle + ", message=" + message + "]."); "message", message);
} else { } else {
message = msgb.xlate(message); message = msgb.xlate(message);
} }
@@ -87,9 +87,8 @@ public class SpeakHandler
// ensure that the speaker is valid // ensure that the speaker is valid
if ((mode == ChatCodes.BROADCAST_MODE) || if ((mode == ChatCodes.BROADCAST_MODE) ||
(_validator != null && !_validator.isValidSpeaker(_speakObj, caller, mode))) { (_validator != null && !_validator.isValidSpeaker(_speakObj, caller, mode))) {
log.warning("Refusing invalid speak request [caller=" + caller.who() + log.warning("Refusing invalid speak request", "caller", caller.who(),
", speakObj=" + _speakObj.which() + "speakObj", _speakObj.which(), "message", message, "mode", mode);
", message=" + message + ", mode=" + mode + "].");
} else { } else {
// issue the speak message on our speak object // issue the speak message on our speak object
@@ -194,8 +194,7 @@ public class SpeakUtil
_messageMapper.message = null; _messageMapper.message = null;
} else { } else {
log.info("Unable to note listeners [dclass=" + speakObj.getClass() + log.info("Unable to note listeners", "dclass", speakObj.getClass(), "msg", msg);
", msg=" + msg + "].");
} }
} }
@@ -140,13 +140,13 @@ public class LocationDirector extends BasicDirector
// if the pending request has been outstanding more than a minute, go ahead and let // if the pending request has been outstanding more than a minute, go ahead and let
// this new one through in an attempt to recover from dropped moveTo requests // this new one through in an attempt to recover from dropped moveTo requests
if (refuse) { if (refuse) {
log.warning("Refusing moveTo; We have a request outstanding " + log.warning("Refusing moveTo; We have a request outstanding",
"[ppid=" + _pendingPlaceId + ", npid=" + placeId + "]."); "ppid", _pendingPlaceId, "npid", placeId);
return false; return false;
} else { } else {
log.warning("Overriding stale moveTo request [ppid=" + _pendingPlaceId + log.warning("Overriding stale moveTo request", "ppid", _pendingPlaceId,
", npid=" + placeId + "]."); "npid", placeId);
} }
} }
@@ -166,7 +166,7 @@ public class LocationDirector extends BasicDirector
// clear out our pending request oid // clear out our pending request oid
int placeId = _pendingPlaceId; int placeId = _pendingPlaceId;
_pendingPlaceId = -1; _pendingPlaceId = -1;
log.info("moveTo failed [pid=" + placeId + ", reason=" + reason + "]."); log.info("moveTo failed", "pid", placeId, "reason", reason);
// let our observers know that something has gone horribly awry // let our observers know that something has gone horribly awry
handleFailure(placeId, reason); handleFailure(placeId, reason);
} }
@@ -258,8 +258,7 @@ public class LocationDirector extends BasicDirector
try { try {
_controller.mayLeavePlace(_plobj); _controller.mayLeavePlace(_plobj);
} catch (Exception e) { } catch (Exception e) {
log.warning("Place controller choked in mayLeavePlace " + log.warning("Place controller choked in mayLeavePlace", "plobj", _plobj, e);
"[plobj=" + _plobj + "].", e);
} }
} }
} }
@@ -296,7 +295,7 @@ public class LocationDirector extends BasicDirector
try { try {
_controller = createController(config); _controller = createController(config);
if (_controller == null) { if (_controller == null) {
log.warning("Place config returned null controller [config=" + config + "]."); log.warning("Place config returned null controller", "config", config);
return; return;
} }
_controller.init(_ctx, config); _controller.init(_ctx, config);
@@ -308,8 +307,8 @@ public class LocationDirector extends BasicDirector
} }
public void requestFailed (int oid, ObjectAccessException cause) { public void requestFailed (int oid, ObjectAccessException cause) {
// aiya! we were unable to fetch our new place object; something is badly wrong // aiya! we were unable to fetch our new place object; something is badly wrong
log.warning("Aiya! Unable to fetch place object for new location [plid=" + oid + log.warning("Aiya! Unable to fetch place object for new location", "plid", oid,
", reason=" + cause + "]."); "reason", cause);
// clear out our half initialized place info // clear out our half initialized place info
int placeId = _placeId; int placeId = _placeId;
_placeId = -1; _placeId = -1;
@@ -320,7 +319,7 @@ public class LocationDirector extends BasicDirector
_subber.subscribe(_ctx.getDObjectManager()); _subber.subscribe(_ctx.getDObjectManager());
} catch (Exception e) { } catch (Exception e) {
log.warning("Failed to create place controller [config=" + config + "].", e); log.warning("Failed to create place controller", "config", config, e);
handleFailure(_placeId, LocationCodes.E_INTERNAL_ERROR); handleFailure(_placeId, LocationCodes.E_INTERNAL_ERROR);
} }
} }
@@ -343,8 +342,7 @@ public class LocationDirector extends BasicDirector
try { try {
_controller.didLeavePlace(_plobj); _controller.didLeavePlace(_plobj);
} catch (Exception e) { } catch (Exception e) {
log.warning("Place controller choked in didLeavePlace " + log.warning("Place controller choked in didLeavePlace", "plobj", _plobj, e);
"[plobj=" + _plobj + "].", e);
} }
} }
@@ -404,7 +402,7 @@ public class LocationDirector extends BasicDirector
} }
public void requestFailed (int oid, ObjectAccessException cause) { public void requestFailed (int oid, ObjectAccessException cause) {
log.warning("Location director unable to fetch body object; all has gone " + log.warning("Location director unable to fetch body object; all has gone " +
"horribly wrong [cause=" + cause + "]."); "horribly wrong", "cause", cause);
} }
}; };
int cloid = client.getClientOid(); int cloid = client.getClientOid();
@@ -457,8 +455,7 @@ public class LocationDirector extends BasicDirector
try { try {
_controller.willEnterPlace(_plobj); _controller.willEnterPlace(_plobj);
} catch (Exception e) { } catch (Exception e) {
log.warning("Controller choked in willEnterPlace " + log.warning("Controller choked in willEnterPlace", "place", _plobj, e);
"[place=" + _plobj + "].", e);
} }
} }
@@ -479,12 +476,12 @@ public class LocationDirector extends BasicDirector
// just finish up what we're doing and assume that the repeated move request was the // just finish up what we're doing and assume that the repeated move request was the
// spurious one as it would be in the case of lag causing rapid-fire repeat requests // spurious one as it would be in the case of lag causing rapid-fire repeat requests
if (movePending()) { if (movePending()) {
log.info("Dropping forced move because we have a move pending " + log.info("Dropping forced move because we have a move pending",
"[pendId=" + _pendingPlaceId + ", reqId=" + placeId + "]."); "pendId", _pendingPlaceId, "reqId", placeId);
return; return;
} }
log.info("Moving at request of server [placeId=" + placeId + "]."); log.info("Moving at request of server", "placeId", placeId);
// clear out our old place information // clear out our old place information
mayLeavePlace(); mayLeavePlace();
didLeavePlace(); didLeavePlace();
@@ -505,8 +502,8 @@ public class LocationDirector extends BasicDirector
if (_failureHandler != null) { if (_failureHandler != null) {
log.warning("Requested to set failure handler, but we've already got one. The " + log.warning("Requested to set failure handler, but we've already got one. The " +
"conflicting entities will likely need to perform more sophisticated " + "conflicting entities will likely need to perform more sophisticated " +
"coordination to deal with failures. [old=" + _failureHandler + "coordination to deal with failures.",
", new=" + handler + "]."); "old", _failureHandler, "new", handler);
} else { } else {
_failureHandler = handler; _failureHandler = handler;
@@ -52,8 +52,8 @@ public class PlaceViewUtil
try { try {
((PlaceView)root).willEnterPlace(plobj); ((PlaceView)root).willEnterPlace(plobj);
} catch (Exception e) { } catch (Exception e) {
log.warning("Component choked on willEnterPlace() " + log.warning("Component choked on willEnterPlace()", "component", root,
"[component=" + root + ", plobj=" + plobj + "].", e); "plobj", plobj, e);
} }
} }
@@ -84,8 +84,8 @@ public class PlaceViewUtil
try { try {
((PlaceView)root).didLeavePlace(plobj); ((PlaceView)root).didLeavePlace(plobj);
} catch (Exception e) { } catch (Exception e) {
log.warning("Component choked on didLeavePlace() " + log.warning("Component choked on didLeavePlace()", "component", root,
"[component=" + root + ", plobj=" + plobj + "].", e); "plobj", plobj, e);
} }
} }
@@ -96,7 +96,7 @@ public class BodyManager
} }
// update their status! // update their status!
log.debug("Setting user idle state [user=" + bobj.username + ", status=" + nstatus + "]."); log.debug("Setting user idle state", "user", bobj.username, "status", nstatus);
updateOccupantStatus(bobj, nstatus); updateOccupantStatus(bobj, nstatus);
} }
@@ -81,8 +81,8 @@ public class LocationManager
// make sure the place in question actually exists // make sure the place in question actually exists
PlaceManager pmgr = _plreg.getPlaceManager(placeOid); PlaceManager pmgr = _plreg.getPlaceManager(placeOid);
if (pmgr == null) { if (pmgr == null) {
log.info("Requested to move to non-existent place [who=" + source.who() + log.info("Requested to move to non-existent place", "who", source.who(),
", placeOid=" + placeOid + "]."); "placeOid", placeOid);
throw new InvocationException(NO_SUCH_PLACE); throw new InvocationException(NO_SUCH_PLACE);
} }
@@ -90,8 +90,8 @@ public class LocationManager
// because we don't need to update anything in distributed object world // because we don't need to update anything in distributed object world
Place place = pmgr.getLocation(); Place place = pmgr.getLocation();
if (place.equals(source.location)) { if (place.equals(source.location)) {
log.debug("Going along with client request to move to where they already are " + log.debug("Going along with client request to move to where they already are",
"[source=" + source.who() + ", place=" + place + "]."); "source", source.who(), "place", place);
return pmgr.getConfig(); return pmgr.getConfig();
} }
@@ -164,7 +164,7 @@ public class PlaceRegistry
try { try {
pmgr.shutdown(); pmgr.shutdown();
} catch (Exception e) { } catch (Exception e) {
log.warning("Place manager failed shutting down [where=" + pmgr.where() + "].", e); log.warning("Place manager failed shutting down", "where", pmgr.where(), e);
} }
} }
} }
@@ -222,7 +222,7 @@ public class PlaceRegistry
pmgr.startup(plobj); pmgr.startup(plobj);
} catch (Exception e) { } catch (Exception e) {
log.warning("Error starting place manager [obj=" + plobj + ", pmgr=" + pmgr + "].", e); log.warning("Error starting place manager", "obj", plobj, "pmgr", pmgr, e);
} }
return pmgr; return pmgr;
@@ -258,7 +258,7 @@ public class PlaceRegistry
int ploid = pmgr.getPlaceObject().getOid(); int ploid = pmgr.getPlaceObject().getOid();
// remove it from the table // remove it from the table
if (_pmgrs.remove(ploid) == null) { if (_pmgrs.remove(ploid) == null) {
log.warning("Requested to unmap unmapped place manager [pmgr=" + pmgr + "]."); log.warning("Requested to unmap unmapped place manager", "pmgr", pmgr);
// } else { // } else {
// Log.info("Unmapped place manager [class=" + pmgr.getClass().getName() + // Log.info("Unmapped place manager [class=" + pmgr.getClass().getName() +
@@ -181,7 +181,7 @@ public class ObjectInputStream extends DataInputStream
Class<?> sclass = Class.forName(cname, true, _loader); Class<?> sclass = Class.forName(cname, true, _loader);
Streamer streamer = Streamer.getStreamer(sclass); Streamer streamer = Streamer.getStreamer(sclass);
if (STREAM_DEBUG) { if (STREAM_DEBUG) {
log.info(hashCode() + ": New class '" + cname + "' [code=" + code + "]."); log.info(hashCode() + ": New class '" + cname + "'", "code", code);
} }
// sanity check // sanity check
@@ -100,8 +100,8 @@ public class ObjectOutputStream extends DataOutputStream
// constructor because we want to be sure not to call _nextCode++ if getStreamer() // constructor because we want to be sure not to call _nextCode++ if getStreamer()
// throws an exception // throws an exception
if (ObjectInputStream.STREAM_DEBUG) { if (ObjectInputStream.STREAM_DEBUG) {
log.info(hashCode() + ": Creating class mapping [code=" + _nextCode + log.info(hashCode() + ": Creating class mapping", "code", _nextCode,
", class=" + sclass.getName() + "]."); "class", sclass.getName());
} }
cmap = createClassMapping(_nextCode++, sclass, streamer); cmap = createClassMapping(_nextCode++, sclass, streamer);
_classmap.put(sclass, cmap); _classmap.put(sclass, cmap);
@@ -205,7 +205,7 @@ public class ObjectOutputStream extends DataOutputStream
throw new RuntimeException("defaultWriteObject() called illegally."); throw new RuntimeException("defaultWriteObject() called illegally.");
} }
// log.info("Writing default [cmap=" + _streamer + ", current=" + _current + "]."); // log.info("Writing default", "cmap", _streamer, "current", _current);
// write the instance data // write the instance data
_streamer.writeObject(_current, this, false); _streamer.writeObject(_current, this, false);
+6 -7
View File
@@ -153,7 +153,7 @@ public class Streamer
if (useWriter && _writer != null) { if (useWriter && _writer != null) {
try { try {
if (ObjectInputStream.STREAM_DEBUG) { if (ObjectInputStream.STREAM_DEBUG) {
log.info("Writing with writer [class=" + _target.getName() + "]."); log.info("Writing with writer", "class", _target.getName());
} }
_writer.invoke(object, new Object[] { out }); _writer.invoke(object, new Object[] { out });
@@ -228,8 +228,7 @@ public class Streamer
} }
try { try {
if (ObjectInputStream.STREAM_DEBUG) { if (ObjectInputStream.STREAM_DEBUG) {
log.info("Writing field [class=" + _target.getName() + log.info("Writing field", "class", _target.getName(), "field", field.getName());
", field=" + field.getName() + "].");
} }
fm.writeField(field, object, out); fm.writeField(field, object, out);
} catch (Exception e) { } catch (Exception e) {
@@ -382,8 +381,8 @@ public class Streamer
if (in.available() > 0) { if (in.available() > 0) {
fm.readField(field, object, in); fm.readField(field, object, in);
} else { } else {
log.info("Streamed instance missing field (probably newly added) " + log.info("Streamed instance missing field (probably newly added)",
"[class=" + _target.getName() + ", field=" + field.getName() + "]."); "class", _target.getName(), "field", field.getName());
} }
} catch (Exception e) { } catch (Exception e) {
String errmsg = "Failure reading streamable field [class=" + _target.getName() + String errmsg = "Failure reading streamable field [class=" + _target.getName() +
@@ -427,8 +426,8 @@ public class Streamer
try { try {
isInner = (_target.getDeclaringClass() != null); isInner = (_target.getDeclaringClass() != null);
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Failure checking innerness of class [class=" + _target.getName() + log.warning("Failure checking innerness of class", "class", _target.getName(),
", error=" + t + "]."); "error", t);
} }
if (isInner && !isStatic) { if (isInner && !isStatic) {
throw new IllegalArgumentException( throw new IllegalArgumentException(
@@ -380,12 +380,12 @@ public class BlockingCommunicator extends Communicator
ByteBuffer buffer = _fout.frameAndReturnBuffer(); ByteBuffer buffer = _fout.frameAndReturnBuffer();
if (buffer.limit() > 4096) { if (buffer.limit() > 4096) {
String txt = StringUtil.truncate(String.valueOf(msg), 80, "..."); String txt = StringUtil.truncate(String.valueOf(msg), 80, "...");
log.info("Whoa, writin' a big one [msg=" + txt + ", size=" + buffer.limit() + "]."); log.info("Whoa, writin' a big one", "msg", txt, "size", buffer.limit());
} }
int wrote = _channel.write(buffer); int wrote = _channel.write(buffer);
if (wrote != buffer.limit()) { if (wrote != buffer.limit()) {
log.warning("Aiya! Couldn't write entire message [msg=" + msg + log.warning("Aiya! Couldn't write entire message", "msg", msg,
", size=" + buffer.limit() + ", wrote=" + wrote + "]."); "size", buffer.limit(), "wrote", wrote);
// } else { // } else {
// Log.info("Wrote " + wrote + " bytes."); // Log.info("Wrote " + wrote + " bytes.");
} }
@@ -416,8 +416,7 @@ public class BlockingCommunicator extends Communicator
ByteBuffer buf = _bout.flip(); ByteBuffer buf = _bout.flip();
int size = buf.remaining(); int size = buf.remaining();
if (size > Client.MAX_DATAGRAM_SIZE) { if (size > Client.MAX_DATAGRAM_SIZE) {
log.warning("Dropping oversized datagram [size=" + size + log.warning("Dropping oversized datagram", "size", size, "msg", msg);
", msg=" + msg + "].");
return; return;
} }
@@ -496,7 +495,7 @@ public class BlockingCommunicator extends Communicator
{ {
// the default implementation just connects to the first port and does no cycling // the default implementation just connects to the first port and does no cycling
int port = _client.getPorts()[0]; int port = _client.getPorts()[0];
log.info("Connecting [host=" + host + ", port=" + port + "]."); log.info("Connecting", "host", host, "port", port);
synchronized (BlockingCommunicator.this) { synchronized (BlockingCommunicator.this) {
_channel = SocketChannel.open(new InetSocketAddress(host, port)); _channel = SocketChannel.open(new InetSocketAddress(host, port));
} }
@@ -709,7 +708,7 @@ public class BlockingCommunicator extends Communicator
try { try {
connect(); connect();
} catch (IOException ioe) { } catch (IOException ioe) {
log.warning("Failed to open datagram channel [error=" + ioe + "]."); log.warning("Failed to open datagram channel", "error", ioe);
shutdown(); shutdown();
} }
} }
@@ -765,7 +764,7 @@ public class BlockingCommunicator extends Communicator
// check if we managed to establish a connection // check if we managed to establish a connection
if (cport > 0) { if (cport > 0) {
log.info("Datagram connection established [port=" + cport + "]."); log.info("Datagram connection established", "port", cport);
// start up the writer thread // start up the writer thread
_datagramWriter = new DatagramWriter(); _datagramWriter = new DatagramWriter();
@@ -819,10 +818,10 @@ public class BlockingCommunicator extends Communicator
log.debug("Datagram reader thread woken up in time to die."); log.debug("Datagram reader thread woken up in time to die.");
} catch (IOException ioe) { } catch (IOException ioe) {
log.warning("Error receiving datagram [error=" + ioe + "]."); log.warning("Error receiving datagram", "error", ioe);
} catch (Exception e) { } catch (Exception e) {
log.warning("Error processing message [msg=" + msg + ", error=" + e + "]."); log.warning("Error processing message", "msg", msg, "error", e);
} }
} }
@@ -875,7 +874,7 @@ public class BlockingCommunicator extends Communicator
sendDatagram(msg); sendDatagram(msg);
} catch (IOException ioe) { } catch (IOException ioe) {
log.warning("Error sending datagram [error=" + ioe + "]."); log.warning("Error sending datagram", "error", ioe);
} }
} }
@@ -81,7 +81,7 @@ public class ClientCommunicator extends BlockingCommunicator
for (int ii = 0; ii < ports.length; ii++) { for (int ii = 0; ii < ports.length; ii++) {
int port = ports[(ii+ppidx)%ports.length]; int port = ports[(ii+ppidx)%ports.length];
int nextPort = ports[(ii+ppidx+1)%ports.length]; int nextPort = ports[(ii+ppidx+1)%ports.length];
log.info("Connecting [host=" + host + ", port=" + port + "]."); log.info("Connecting", "host", host, "port", port);
InetSocketAddress addr = new InetSocketAddress(host, port); InetSocketAddress addr = new InetSocketAddress(host, port);
try { try {
synchronized (this) { synchronized (this) {
@@ -195,7 +195,7 @@ public class ClientDObjectMgr
} else if (obj instanceof UnsubscribeResponse) { } else if (obj instanceof UnsubscribeResponse) {
int oid = ((UnsubscribeResponse)obj).getOid(); int oid = ((UnsubscribeResponse)obj).getOid();
if (_dead.remove(oid) == null) { if (_dead.remove(oid) == null) {
log.warning("Received unsub ACK from unknown object [oid=" + oid + "]."); log.warning("Received unsub ACK from unknown object", "oid", oid);
} }
} else if (obj instanceof FailureResponse) { } else if (obj instanceof FailureResponse) {
@@ -339,8 +339,7 @@ public class ClientDObjectMgr
// let the penders know that the object is available // let the penders know that the object is available
PendingRequest<?> req = _penders.remove(obj.getOid()); PendingRequest<?> req = _penders.remove(obj.getOid());
if (req == null) { if (req == null) {
log.warning("Got object, but no one cares?! [oid=" + obj.getOid() + log.warning("Got object, but no one cares?!", "oid", obj.getOid(), "obj", obj);
", obj=" + obj + "].");
return; return;
} }
@@ -362,7 +361,7 @@ public class ClientDObjectMgr
// let the penders know that the object is not available // let the penders know that the object is not available
PendingRequest<?> req = _penders.remove(oid); PendingRequest<?> req = _penders.remove(oid);
if (req == null) { if (req == null) {
log.warning("Failed to get object, but no one cares?! [oid=" + oid + "]."); log.warning("Failed to get object, but no one cares?!", "oid", oid);
return; return;
} }
@@ -424,8 +423,8 @@ public class ClientDObjectMgr
dobj.removeSubscriber(target); dobj.removeSubscriber(target);
} else { } else {
log.info("Requested to remove subscriber from non-proxied object [oid=" + oid + log.info("Requested to remove subscriber from non-proxied object", "oid", oid,
", sub=" + target + "]."); "sub", target);
} }
} }
@@ -96,9 +96,8 @@ public class DeltaCalculator
// minus the server's send time (plus network delay): dT = C - S // minus the server's send time (plus network delay): dT = C - S
_deltas[_iter] = recv - (server + nettime); _deltas[_iter] = recv - (server + nettime);
log.debug("Calculated delta [delay=" + delay + log.debug("Calculated delta", "delay", delay, "nettime", nettime, "delta", _deltas[_iter],
", nettime=" + nettime + ", delta=" + _deltas[_iter] + "rtt", (recv-send));
", rtt=" + (recv-send) + "].");
return (++_iter >= CLOCK_SYNC_PING_COUNT); return (++_iter >= CLOCK_SYNC_PING_COUNT);
} }
@@ -94,8 +94,8 @@ public class InvocationDirector
public void requestFailed (int oid, ObjectAccessException cause) { public void requestFailed (int oid, ObjectAccessException cause) {
// aiya! we were unable to subscribe to the client object. we're hosed! // aiya! we were unable to subscribe to the client object. we're hosed!
log.warning("Invocation director unable to subscribe to client object " + log.warning("Invocation director unable to subscribe to client object",
"[cloid=" + cloid + ", cause=" + cause + "]!"); "cloid", cloid, "cause", cause + "]!");
_client.getClientObjectFailed(cause); _client.getClientObjectFailed(cause);
} }
}); });
@@ -148,8 +148,8 @@ public class InvocationDirector
if (_clobj != null) { if (_clobj != null) {
Registration rreg = _clobj.receivers.get(receiverCode); Registration rreg = _clobj.receivers.get(receiverCode);
if (rreg == null) { if (rreg == null) {
log.warning("Receiver unregistered for which we have no id to code mapping " + log.warning("Receiver unregistered for which we have no id to code mapping",
"[code=" + receiverCode + "]."); "code", receiverCode);
} else { } else {
// Object decoder = _receivers.remove(rreg.receiverId); // Object decoder = _receivers.remove(rreg.receiverId);
// Log.info("Cleared receiver " + StringUtil.shortClassName(decoder) + // Log.info("Cleared receiver " + StringUtil.shortClassName(decoder) +
@@ -206,8 +206,8 @@ public class InvocationDirector
int invOid, int invCode, int methodId, Object[] args, Transport transport) int invOid, int invCode, int methodId, Object[] args, Transport transport)
{ {
if (_clobj == null) { if (_clobj == null) {
log.warning("Dropping invocation request on shutdown director [code=" + invCode + log.warning("Dropping invocation request on shutdown director", "code", invCode,
", methodId=" + methodId + "]."); "methodId", methodId);
return; return;
} }
@@ -270,23 +270,22 @@ public class InvocationDirector
// look up the invocation marshaller registered for that response // look up the invocation marshaller registered for that response
ListenerMarshaller listener = _listeners.remove(reqId); ListenerMarshaller listener = _listeners.remove(reqId);
if (listener == null) { if (listener == null) {
log.warning("Received invocation response for which we have no registered listener " + log.warning("Received invocation response for which we have no registered listener. " +
"[reqId=" + reqId + ", methId=" + methodId + ", args=" + "It is possible that this listener was flushed because the response did " +
StringUtil.toString(args) + "]. It is possible that this listener was " + "not arrive within " + LISTENER_MAX_AGE + " milliseconds.",
"flushed because the response did not arrive within " + "reqId", reqId, "methId", methodId, "args", args);
LISTENER_MAX_AGE + " milliseconds.");
return; return;
} }
// Log.info("Dispatching invocation response [listener=" + listener + // log.info("Dispatching invocation response", "listener", listener,
// ", methId=" + methodId + ", args=" + StringUtil.toString(args) + "]."); // "methId", methodId, "args", args);
// dispatch the response // dispatch the response
try { try {
listener.dispatchResponse(methodId, args); listener.dispatchResponse(methodId, args);
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Invocation response listener choked [listener=" + listener + log.warning("Invocation response listener choked", "listener", listener,
", methId=" + methodId + ", args=" + StringUtil.toString(args) + "].", t); "methId", methodId, "args", args, t);
} }
// flush expired listeners periodically // flush expired listeners periodically
@@ -305,20 +304,19 @@ public class InvocationDirector
// look up the decoder registered for this receiver // look up the decoder registered for this receiver
InvocationDecoder decoder = _receivers.get(receiverId); InvocationDecoder decoder = _receivers.get(receiverId);
if (decoder == null) { if (decoder == null) {
log.warning("Received notification for which we have no registered receiver " + log.warning("Received notification for which we have no registered receiver",
"[recvId=" + receiverId + ", methodId=" + methodId + "recvId", receiverId, "methodId", methodId, "args", args);
", args=" + StringUtil.toString(args) + "].");
return; return;
} }
// Log.info("Dispatching invocation notification [receiver=" + decoder.receiver + // log.info("Dispatching invocation notification", "receiver", decoder.receiver,
// ", methodId=" + methodId + ", args=" + StringUtil.toString(args) + "]."); // "methodId", methodId, "args", args);
try { try {
decoder.dispatchNotification(methodId, args); decoder.dispatchNotification(methodId, args);
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Invocation notification receiver choked [receiver=" + decoder.receiver + log.warning("Invocation notification receiver choked", "receiver", decoder.receiver,
", methId=" + methodId + ", args=" + StringUtil.toString(args) + "].", t); "methId", methodId, "args", args, t);
} }
} }
@@ -357,8 +355,8 @@ public class InvocationDirector
} }
public void requestFailed (int oid, ObjectAccessException cause) { public void requestFailed (int oid, ObjectAccessException cause) {
log.warning("Aiya! Unable to subscribe to changed client object [cloid=" + oid + log.warning("Aiya! Unable to subscribe to changed client object", "cloid", oid,
", cause=" + cause + "]."); "cause", cause);
} }
}); });
} }
@@ -106,9 +106,8 @@ public class InvocationMarshaller
listener.requestFailed((String)args[0]); listener.requestFailed((String)args[0]);
} else { } else {
log.warning("Requested to dispatch unknown invocation response " + log.warning("Requested to dispatch unknown invocation response",
"[listener=" + listener + ", methodId=" + methodId + "listener", listener, "methodId", methodId, "args", args);
", args=" + StringUtil.toString(args) + "].");
} }
} }
@@ -357,7 +357,7 @@ public class DObject
// clear the lock from the list // clear the lock from the list
if (ListUtil.clear(_locks, name) == null) { if (ListUtil.clear(_locks, name) == null) {
// complain if we didn't find the lock // complain if we didn't find the lock
log.info("Unable to clear non-existent lock [lock=" + name + ", dobj=" + this + "]."); log.info("Unable to clear non-existent lock", "lock", name, "dobj", this);
} }
} }
@@ -438,8 +438,8 @@ public class DObject
} }
} catch (Exception e) { } catch (Exception e) {
log.warning("Listener choked during notification [list=" + listener + log.warning("Listener choked during notification", "list", listener,
", event=" + event + "].", e); "event", event, e);
} }
} }
} }
@@ -551,8 +551,8 @@ public class DObject
_omgr.postEvent(event); _omgr.postEvent(event);
} else { } else {
log.info("Dropping event for non- or no longer managed object [oid=" + getOid() + log.info("Dropping event for non- or no longer managed object", "oid", getOid(),
", class=" + getClass().getName() + ", event=" + event + "]."); "class", getClass().getName(), "event", event);
} }
} }
@@ -91,7 +91,7 @@ public class EntryRemovedEvent<T extends DSet.Entry> extends NamedEvent
_oldEntry = set.removeKey(_key); _oldEntry = set.removeKey(_key);
if (_oldEntry == null) { if (_oldEntry == null) {
// complain if there was actually nothing there // complain if there was actually nothing there
log.warning("No matching entry to remove [key=" + _key + ", set=" + set + "]."); log.warning("No matching entry to remove", "key", _key, "set", set);
return false; return false;
} }
} }
@@ -110,7 +110,7 @@ public class EntryUpdatedEvent<T extends DSet.Entry> extends NamedEvent
_oldEntry = set.update(_entry); _oldEntry = set.update(_entry);
if (_oldEntry == null) { if (_oldEntry == null) {
// complain if we didn't update anything // complain if we didn't update anything
log.warning("No matching entry to update [entry=" + this + ", set=" + set + "]."); log.warning("No matching entry to update", "entry", this, "set", set);
return false; return false;
} }
} }
@@ -92,8 +92,8 @@ public class PongResponse extends DownstreamMessage
// the time spent between unpacking the ping and packing the pong is the processing delay // the time spent between unpacking the ping and packing the pong is the processing delay
if (_pingStamp == 0L) { if (_pingStamp == 0L) {
log.warning("Pong response written that was not constructed " + log.warning("Pong response written that was not constructed with a valid ping stamp",
"with a valid ping stamp [rsp=" + this + "]."); "rsp", this);
_processDelay = 0; _processDelay = 0;
} else { } else {
_processDelay = (int)(_packStamp - _pingStamp); _processDelay = (int)(_packStamp - _pingStamp);
@@ -62,7 +62,7 @@ public class PeerAuthenticator extends ChainedAuthenticator
rsp.getData().code = AuthResponseData.SUCCESS; rsp.getData().code = AuthResponseData.SUCCESS;
} else { } else {
log.warning("Received invalid peer auth request? [creds=" + pcreds + "]."); log.warning("Received invalid peer auth request?", "creds", pcreds);
rsp.getData().code = AuthCodes.SERVER_ERROR; rsp.getData().code = AuthCodes.SERVER_ERROR;
} }
} }
@@ -427,7 +427,7 @@ public abstract class PeerManager
Tuple<String,Integer> key = Tuple.newTuple(nodeName, remoteOid); Tuple<String,Integer> key = Tuple.newTuple(nodeName, remoteOid);
Tuple<Subscriber<?>, DObject> bits = _proxies.remove(key); Tuple<Subscriber<?>, DObject> bits = _proxies.remove(key);
if (bits == null) { if (bits == null) {
log.warning("Requested to clear unknown proxy [key=" + key + "]."); log.warning("Requested to clear unknown proxy", "key", key);
return; return;
} }
@@ -436,7 +436,7 @@ public abstract class PeerManager
final Client peer = getPeerClient(nodeName); final Client peer = getPeerClient(nodeName);
if (peer == null) { if (peer == null) {
log.warning("Unable to unsubscribe from proxy, missing peer [key=" + key + "]."); log.warning("Unable to unsubscribe from proxy, missing peer", "key", key);
return; return;
} }
@@ -528,8 +528,8 @@ public abstract class PeerManager
} }
} else { } else {
if (result != null) { if (result != null) {
log.warning("Tried to release lock held by another peer [lock=" + lock + log.warning("Tried to release lock held by another peer", "lock", lock,
", owner=" + result + "]."); "owner", result);
} }
listener.requestCompleted(result); listener.requestCompleted(result);
} }
@@ -550,8 +550,8 @@ public abstract class PeerManager
// make sure we're releasing it // make sure we're releasing it
LockHandler handler = _locks.get(lock); LockHandler handler = _locks.get(lock);
if (handler == null || !handler.getNodeName().equals(_nodeName) || handler.isAcquiring()) { if (handler == null || !handler.getNodeName().equals(_nodeName) || handler.isAcquiring()) {
log.warning("Tried to reacquire lock not being released [lock=" + lock + log.warning("Tried to reacquire lock not being released", "lock", lock,
", handler=" + handler + "]."); "handler", handler);
return; return;
} }
@@ -621,12 +621,12 @@ public abstract class PeerManager
// some other peer beat us to it // some other peer beat us to it
operation.fail(nodeName); operation.fail(nodeName);
if (nodeName == null) { if (nodeName == null) {
log.warning("Lock acquired by null? [lock=" + lock + "]."); log.warning("Lock acquired by null?", "lock", lock);
} }
} }
} }
public void requestFailed (Exception cause) { public void requestFailed (Exception cause) {
log.warning("Lock acquisition failed [lock=" + lock + "].", cause); log.warning("Lock acquisition failed", "lock", lock, cause);
operation.fail(null); operation.fail(null);
} }
}); });
@@ -787,8 +787,8 @@ public abstract class PeerManager
// sanity check // sanity check
if (_nodeobj.clients.contains(clinfo)) { if (_nodeobj.clients.contains(clinfo)) {
log.warning("Received clientSessionDidStart() for already registered client!? " + log.warning("Received clientSessionDidStart() for already registered client!?",
"[old=" + _nodeobj.clients.get(clinfo.getKey()) + ", new=" + clinfo + "]."); "old", _nodeobj.clients.get(clinfo.getKey()), "new", clinfo);
// go ahead and update the record // go ahead and update the record
_nodeobj.updateClients(clinfo); _nodeobj.updateClients(clinfo);
} else { } else {
@@ -821,7 +821,7 @@ public abstract class PeerManager
return; return;
} }
} }
log.warning("Session ended for unregistered client [who=" + username + "]."); log.warning("Session ended for unregistered client", "who", username);
} }
/** /**
@@ -1127,8 +1127,8 @@ public abstract class PeerManager
(_timeout = new Interval(_omgr) { (_timeout = new Interval(_omgr) {
@Override @Override
public void expired () { public void expired () {
log.warning("Lock handler timed out, acting anyway [lock=" + _lock + log.warning("Lock handler timed out, acting anyway", "lock", _lock,
", acquire=" + _acquire + "]."); "acquire", _acquire);
activate(); activate();
} }
}).schedule(LOCK_TIMEOUT); }).schedule(LOCK_TIMEOUT);
@@ -1175,8 +1175,8 @@ public abstract class PeerManager
return; return;
} }
if (!_remoids.remove(caller.getOid())) { if (!_remoids.remove(caller.getOid())) {
log.warning("Received unexpected ratification [handler=" + this + log.warning("Received unexpected ratification", "handler", this,
", who=" + caller.who() + "]."); "who", caller.who());
} }
maybeActivate(); maybeActivate();
} }
@@ -220,8 +220,7 @@ public class PeerNode
// documentation inherited from interface Subscriber // documentation inherited from interface Subscriber
public void requestFailed (int oid, ObjectAccessException cause) public void requestFailed (int oid, ObjectAccessException cause)
{ {
log.warning("Failed to subscribe to peer's node object " + log.warning("Failed to subscribe to peer's node object", "peer", _record, "cause", cause);
"[peer=" + _record + ", cause=" + cause + "].");
} }
/** /**
@@ -262,8 +261,8 @@ public class PeerNode
PeerManager.LockHandler handler = _peermgr.getLockHandler(lock); PeerManager.LockHandler handler = _peermgr.getLockHandler(lock);
if (handler == null) { if (handler == null) {
if (_peermgr.getNodeObject().locks.contains(lock)) { if (_peermgr.getNodeObject().locks.contains(lock)) {
log.warning("Peer trying to acquire lock owned by this node " + log.warning("Peer trying to acquire lock owned by this node", "lock", lock,
"[lock=" + lock + ", node=" + _record.nodeName + "]."); "node", _record.nodeName);
return; return;
} }
_peermgr.createLockHandler(PeerNode.this, lock, true); _peermgr.createLockHandler(PeerNode.this, lock, true);
@@ -56,7 +56,7 @@ public abstract class Authenticator
try { try {
processAuthentication(conn, rsp); processAuthentication(conn, rsp);
} catch (Exception e) { } catch (Exception e) {
log.warning("Error authenticating user [areq=" + req + "].", e); log.warning("Error authenticating user", "areq", req, e);
rdata.code = AuthCodes.SERVER_ERROR; rdata.code = AuthCodes.SERVER_ERROR;
} }
return true; return true;
@@ -129,7 +129,7 @@ public class ClientManager
// from interface ShutdownManager.Shutdowner // from interface ShutdownManager.Shutdowner
public void shutdown () public void shutdown ()
{ {
log.info("Client manager shutting down [ccount=" + _usermap.size() + "]."); log.info("Client manager shutting down", "ccount", _usermap.size());
_flushClients.cancel(); _flushClients.cancel();
@@ -139,8 +139,8 @@ public class ClientManager
try { try {
pc.shutdown(); pc.shutdown();
} catch (Exception e) { } catch (Exception e) {
log.warning("Client choked in shutdown() [client=" + log.warning("Client choked in shutdown()",
StringUtil.safeToString(pc) + "].", e); "client", StringUtil.safeToString(pc), e);
} }
} }
} }
@@ -429,8 +429,7 @@ public class ClientManager
// remove the client from the connection map // remove the client from the connection map
PresentsSession client = _conmap.remove(conn); PresentsSession client = _conmap.remove(conn);
if (client != null) { if (client != null) {
log.info("Unmapped failed client [client=" + client + ", conn=" + conn + log.info("Unmapped failed client", "client", client, "conn", conn, "fault", fault);
", fault=" + fault + "].");
// let the client know the connection went away // let the client know the connection went away
client.wasUnmapped(); client.wasUnmapped();
// and let the client know things went haywire // and let the client know things went haywire
@@ -449,7 +448,7 @@ public class ClientManager
// remove the client from the connection map // remove the client from the connection map
PresentsSession client = _conmap.remove(conn); PresentsSession client = _conmap.remove(conn);
if (client != null) { if (client != null) {
log.debug("Unmapped client [client=" + client + ", conn=" + conn + "]."); log.debug("Unmapped client", "client", client, "conn", conn);
// let the client know the connection went away // let the client know the connection went away
client.wasUnmapped(); client.wasUnmapped();
@@ -545,11 +544,11 @@ public class ClientManager
// now end their sessions // now end their sessions
for (PresentsSession client : victims) { for (PresentsSession client : victims) {
try { try {
log.info("Client expired, ending session [session=" + client + log.info("Client expired, ending session", "session", client,
", dtime=" + (now-client.getNetworkStamp()) + "ms]."); "dtime", (now-client.getNetworkStamp()) + "ms].");
client.endSession(); client.endSession();
} catch (Exception e) { } catch (Exception e) {
log.warning("Choke while flushing client [victim=" + client + "].", e); log.warning("Choke while flushing client", "victim", client, e);
} }
} }
} }
@@ -567,8 +566,7 @@ public class ClientManager
_clop.apply(clobj); _clop.apply(clobj);
} catch (Exception e) { } catch (Exception e) {
log.warning("Client op failed [username=" + username + log.warning("Client op failed", "username", username, "clop", _clop, e);
", clop=" + _clop + "].", e);
} finally { } finally {
releaseClientObject(username); releaseClientObject(username);
@@ -192,8 +192,8 @@ public class ClientResolver extends Invoker.Unit
try { try {
crl.resolutionFailed(_username, cause); crl.resolutionFailed(_username, cause);
} catch (Exception e) { } catch (Exception e) {
log.warning("Client resolution listener choked in resolutionFailed() [crl=" + crl + log.warning("Client resolution listener choked in resolutionFailed()", "crl", crl,
", username=" + _username + ", cause=" + cause + "].", e); "username", _username, "cause", cause, e);
} }
} }
} }
@@ -48,10 +48,7 @@ public abstract class InvocationDispatcher<T extends InvocationMarshaller>
public void dispatchRequest (ClientObject source, int methodId, Object[] args) public void dispatchRequest (ClientObject source, int methodId, Object[] args)
throws InvocationException throws InvocationException
{ {
log.warning("Requested to dispatch unknown method " + log.warning("Requested to dispatch unknown method", "provider", provider,
"[provider=" + provider + "sourceOid", source.getOid(), "methodId", methodId, "args", args);
", sourceOid=" + source.getOid() +
", methodId=" + methodId +
", args=" + StringUtil.toString(args) + "].");
} }
} }
@@ -83,7 +83,7 @@ public class InvocationManager
invobj.addListener(this); invobj.addListener(this);
_invoid = invobj.getOid(); _invoid = invobj.getOid();
// log.info("Created invocation service object [oid=" + _invoid + "]."); // log.info("Created invocation service object", "oid", _invoid);
} }
/** /**
@@ -151,7 +151,7 @@ public class InvocationManager
_recentRegServices.put(Integer.valueOf(invCode), marsh.getClass().getName()); _recentRegServices.put(Integer.valueOf(invCode), marsh.getClass().getName());
// log.info("Registered service [marsh=" + marsh + "]."); // log.info("Registered service", "marsh", marsh);
return marsh; return marsh;
} }
@@ -169,8 +169,8 @@ public class InvocationManager
} }
if (_dispatchers.remove(marsh.getInvocationCode()) == null) { if (_dispatchers.remove(marsh.getInvocationCode()) == null) {
log.warning("Requested to remove unregistered marshaller? " + log.warning("Requested to remove unregistered marshaller?", "marsh", marsh,
"[marsh=" + marsh + "].", new Exception()); new Exception());
} }
} }
@@ -224,21 +224,17 @@ public class InvocationManager
// make sure the client is still around // make sure the client is still around
ClientObject source = (ClientObject)_omgr.getObject(clientOid); ClientObject source = (ClientObject)_omgr.getObject(clientOid);
if (source == null) { if (source == null) {
log.info("Client no longer around for invocation " + log.info("Client no longer around for invocation request", "clientOid", clientOid,
"request [clientOid=" + clientOid + "code", invCode, "methId", methodId, "args", args);
", code=" + invCode + ", methId=" + methodId +
", args=" + StringUtil.toString(args) + "].");
return; return;
} }
// look up the dispatcher // look up the dispatcher
InvocationDispatcher<?> disp = _dispatchers.get(invCode); InvocationDispatcher<?> disp = _dispatchers.get(invCode);
if (disp == null) { if (disp == null) {
log.info("Received invocation request but dispatcher " + log.info("Received invocation request but dispatcher registration was already cleared",
"registration was already cleared [code=" + invCode + "code", invCode, "methId", methodId, "args", args,
", methId=" + methodId + "marsh", _recentRegServices.get(Integer.valueOf(invCode)));
", args=" + StringUtil.toString(args) + ", marsh=" +
_recentRegServices.get(Integer.valueOf(invCode)) + "].");
return; return;
} }
@@ -259,9 +255,8 @@ public class InvocationManager
} }
} }
// log.debug("Dispatching invreq [caller=" + source.who() + // log.debug("Dispatching invreq", "caller", source.who(), "disp", disp,
// ", disp=" + disp + ", methId=" + methodId + // "methId", methodId, "args", args);
// ", args=" + StringUtil.toString(args) + "].");
// dispatch the request // dispatch the request
try { try {
@@ -276,18 +271,14 @@ public class InvocationManager
rlist.requestFailed(ie.getMessage()); rlist.requestFailed(ie.getMessage());
} else { } else {
log.warning("Service request failed but we've got no " + log.warning("Service request failed but we've got no listener to inform of " +
"listener to inform of the failure " + "the failure", "caller", source.who(), "code", invCode,
"[caller=" + source.who() + ", code=" + invCode + "dispatcher", disp, "methodId", methodId, "args", args, "error", ie);
", dispatcher=" + disp + ", methodId=" + methodId +
", args=" + StringUtil.toString(args) +
", error=" + ie + "].");
} }
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Dispatcher choked [disp=" + disp + log.warning("Dispatcher choked", "disp", disp, "caller", source.who(),
", caller=" + source.who() + ", methId=" + methodId + "methId", methodId, "args", args, t);
", args=" + StringUtil.toString(args) + "].", t);
// avoid logging an error when the listener notices that it's been ignored. // avoid logging an error when the listener notices that it's been ignored.
if (rlist != null) { if (rlist != null) {
@@ -321,7 +312,8 @@ public class InvocationManager
/** Tracks recently registered services so that we can complain informatively if a request /** Tracks recently registered services so that we can complain informatively if a request
* comes in on a service we don't know about. */ * comes in on a service we don't know about. */
protected final Map<Integer, String> _recentRegServices = new LRUHashMap<Integer, String>(10000); protected final Map<Integer, String> _recentRegServices =
new LRUHashMap<Integer, String>(10000);
/** The text appended to the procedure name when generating a failure response. */ /** The text appended to the procedure name when generating a failure response. */
protected static final String FAILED_SUFFIX = "Failed"; protected static final String FAILED_SUFFIX = "Failed";
@@ -45,7 +45,7 @@ public class NativeSignalHandler extends AbstractSignalHandler
hupReceived(); hupReceived();
break; break;
default: default:
log.warning("Received unknown signal [signo=" + signo + "]."); log.warning("Received unknown signal", "signo", signo);
break; break;
} }
return true; return true;
@@ -156,8 +156,8 @@ public class PresentsDObjectMgr
// originating manager after converting them back to the original oid // originating manager after converting them back to the original oid
_proxies.put(object.getOid(), new ProxyReference(origObjectId, omgr)); _proxies.put(object.getOid(), new ProxyReference(origObjectId, omgr));
// TEMP: report what we're doing as we're seeing funny business // TEMP: report what we're doing as we're seeing funny business
log.info("Registered proxy object [type=" + object.getClass().getName() + log.info("Registered proxy object", "type", object.getClass().getName(),
", remoid=" + origObjectId + ", locoid=" + object.getOid() + "]."); "remoid", origObjectId, "locoid", object.getOid());
} }
/** /**
@@ -168,12 +168,12 @@ public class PresentsDObjectMgr
public void clearProxyObject (int origObjectId, DObject object) public void clearProxyObject (int origObjectId, DObject object)
{ {
if (_proxies.remove(object.getOid()) == null) { if (_proxies.remove(object.getOid()) == null) {
log.warning("Missing proxy mapping for cleared proxy [ooid=" + origObjectId + "]."); log.warning("Missing proxy mapping for cleared proxy", "ooid", origObjectId);
} }
_objects.remove(object.getOid()); _objects.remove(object.getOid());
// TEMP: report what we're doing as we're seeing funny business // TEMP: report what we're doing as we're seeing funny business
log.info("Clearing proxy object [type=" + object.getClass().getName() + log.info("Clearing proxy object", "type", object.getClass().getName(),
", remoid=" + origObjectId + ", locoid=" + object.getOid() + "]."); "remoid", origObjectId, "locoid", object.getOid());
} }
// from interface DObjectManager // from interface DObjectManager
@@ -201,8 +201,8 @@ public class PresentsDObjectMgr
public void postEvent (DEvent event) public void postEvent (DEvent event)
{ {
if (!_running) { if (!_running) {
log.warning( log.warning("Posting message to inactive object manager", "event", event,
"Posting message to inactive object manager", "event", event, new Exception()); new Exception());
} }
// assign the event's id and append it to the queue // assign the event's id and append it to the queue
@@ -237,7 +237,7 @@ public class PresentsDObjectMgr
// insert it into the table // insert it into the table
_objects.put(oid, object); _objects.put(oid, object);
// log.info("Registered object [obj=" + object + "]."); // log.info("Registered object", "obj", object);
return object; return object;
} }
@@ -278,8 +278,8 @@ public class PresentsDObjectMgr
public void postRunnable (Runnable unit) public void postRunnable (Runnable unit)
{ {
if (!_running) { if (!_running) {
log.warning( log.warning("Posting runnable to inactive object manager", "unit", unit,
"Posting runnable to inactive object manager", "unit", unit, new Exception()); new Exception());
} }
// just append it to the queue // just append it to the queue
@@ -379,7 +379,7 @@ public class PresentsDObjectMgr
{ {
int oid = target.getOid(); int oid = target.getOid();
// log.info("Removing destroyed object from table [oid=" + oid + "]."); // log.info("Removing destroyed object from table", "oid", oid);
// remove the object from the table // remove the object from the table
_objects.remove(oid); _objects.remove(oid);
@@ -433,8 +433,8 @@ public class PresentsDObjectMgr
} }
} catch (Exception e) { } catch (Exception e) {
log.warning("Unable to clean up after oid list field [target=" + target + log.warning("Unable to clean up after oid list field", "target", target,
", field=" + field + "]."); "field", field);
} }
} }
@@ -454,8 +454,8 @@ public class PresentsDObjectMgr
// ensure that the target object exists // ensure that the target object exists
if (!_objects.containsKey(oid)) { if (!_objects.containsKey(oid)) {
log.info("Rejecting object added event of non-existent object " + log.info("Rejecting object added event of non-existent object",
"[refferOid=" + target.getOid() + ", reffedOid=" + oid + "]."); "refferOid", target.getOid(), "reffedOid", oid);
return false; return false;
} }
@@ -508,7 +508,7 @@ public class PresentsDObjectMgr
int toid = target.getOid(); int toid = target.getOid();
int oid = ore.getOid(); int oid = ore.getOid();
// log.info("Processing object removed [from=" + toid + ", roid=" + toid + "]."); // log.info("Processing object removed", "from", toid, "roid", toid);
// get the reference vector for the referenced object // get the reference vector for the referenced object
Reference[] refs = _refs.get(oid); Reference[] refs = _refs.get(oid);
@@ -517,8 +517,8 @@ public class PresentsDObjectMgr
// reference system and then generate object removed events for all of its referencees. // reference system and then generate object removed events for all of its referencees.
// so we opt not to log anything in this case // so we opt not to log anything in this case
// log.info("Object removed without reference to track it [toid=" + toid + // log.info("Object removed without reference to track it", "toid", toid,
// ", field=" + field + ", oid=" + oid + "]."); // "field", field, "oid", oid);
return true; return true;
} }
@@ -532,8 +532,8 @@ public class PresentsDObjectMgr
} }
} }
log.warning("Unable to locate reference for removal [reffingOid=" + toid + log.warning("Unable to locate reference for removal", "reffingOid", toid, "field", field,
", field=" + field + ", reffedOid=" + oid + "]."); "reffedOid", oid);
return true; return true;
} }
@@ -669,7 +669,7 @@ public class PresentsDObjectMgr
// look up the target object // look up the target object
DObject target = _objects.get(event.getTargetOid()); DObject target = _objects.get(event.getTargetOid());
if (target == null) { if (target == null) {
log.debug("Compound event target no longer exists [event=" + event + "]."); log.debug("Compound event target no longer exists", "event", event);
return; return;
} }
@@ -677,8 +677,7 @@ public class PresentsDObjectMgr
for (int ii = 0; ii < ecount; ii++) { for (int ii = 0; ii < ecount; ii++) {
DEvent sevent = events.get(ii); DEvent sevent = events.get(ii);
if (!target.checkPermissions(sevent)) { if (!target.checkPermissions(sevent)) {
log.warning("Event failed permissions check [event=" + sevent + log.warning("Event failed permissions check", "event", sevent, "target", target);
", target=" + target + "].");
return; return;
} }
} }
@@ -700,14 +699,13 @@ public class PresentsDObjectMgr
// look up the target object // look up the target object
DObject target = _objects.get(event.getTargetOid()); DObject target = _objects.get(event.getTargetOid());
if (target == null) { if (target == null) {
log.debug("Event target no longer exists [event=" + event + "]."); log.debug("Event target no longer exists", "event", event);
return; return;
} }
// check the event's permissions // check the event's permissions
if (!target.checkPermissions(event)) { if (!target.checkPermissions(event)) {
log.warning("Event failed permissions check [event=" + event + log.warning("Event failed permissions check", "event", event, "target", target);
", target=" + target + "].");
return; return;
} }
@@ -751,8 +749,7 @@ public class PresentsDObjectMgr
handleFatalError(event, e); handleFatalError(event, e);
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Failure processing event [event=" + event + log.warning("Failure processing event", "event", event, "target", target, t);
", target=" + target + "].", t);
} }
// track the number of events dispatched // track the number of events dispatched
@@ -799,9 +796,8 @@ public class PresentsDObjectMgr
// to the referred object which no longer exists; so we don't complain about non- existent // to the referred object which no longer exists; so we don't complain about non- existent
// references if the referree is already destroyed // references if the referree is already destroyed
if (ref == null && _objects.containsKey(reffedOid)) { if (ref == null && _objects.containsKey(reffedOid)) {
log.warning("Requested to clear out non-existent reference " + log.warning("Requested to clear out non-existent reference",
"[refferOid=" + reffer.getOid() + ", field=" + field + "refferOid", reffer.getOid(), "field", field, "reffedOid", reffedOid);
", reffedOid=" + reffedOid + "].");
// } else { // } else {
// log.info("Cleared out reference " + ref + "."); // log.info("Cleared out reference " + ref + ".");
@@ -837,7 +833,7 @@ public class PresentsDObjectMgr
_helpers.put(ObjectRemovedEvent.class, method); _helpers.put(ObjectRemovedEvent.class, method);
} catch (Exception e) { } catch (Exception e) {
log.warning("Unable to register event helpers [error=" + e + "]."); log.warning("Unable to register event helpers", "error", e);
} }
} }
@@ -850,8 +846,8 @@ public class PresentsDObjectMgr
try { try {
sub.objectAvailable(obj); sub.objectAvailable(obj);
} catch (Exception e) { } catch (Exception e) {
log.warning("Subscriber choked during object available " + log.warning("Subscriber choked during object available",
"[obj=" + StringUtil.safeToString(obj) + ", sub=" + sub + "].", e); "obj", StringUtil.safeToString(obj), "sub", sub, e);
} }
} }
@@ -90,7 +90,7 @@ public class PresentsServer
String testmod = System.getProperty("test_module"); String testmod = System.getProperty("test_module");
if (testmod != null) { if (testmod != null) {
try { try {
log.info("Invoking test module [mod=" + testmod + "]."); log.info("Invoking test module", "mod", testmod);
Class<?> tmclass = Class.forName(testmod); Class<?> tmclass = Class.forName(testmod);
Runnable trun = (Runnable)tmclass.newInstance(); Runnable trun = (Runnable)tmclass.newInstance();
trun.run(); trun.run();
@@ -125,15 +125,15 @@ public class PresentsServer
{ {
// output general system information // output general system information
SystemInfo si = new SystemInfo(); SystemInfo si = new SystemInfo();
log.info("Starting up server [os=" + si.osToString() + ", jvm=" + si.jvmToString() + log.info("Starting up server", "os", si.osToString(), "jvm", si.jvmToString(),
", mem=" + si.memoryToString() + "]."); "mem", si.memoryToString());
// register SIGTERM, SIGINT (ctrl-c) and a SIGHUP handlers // register SIGTERM, SIGINT (ctrl-c) and a SIGHUP handlers
boolean registered = false; boolean registered = false;
try { try {
registered = injector.getInstance(SunSignalHandler.class).init(); registered = injector.getInstance(SunSignalHandler.class).init();
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Unable to register Sun signal handlers [error=" + t + "]."); log.warning("Unable to register Sun signal handlers", "error", t);
} }
if (!registered) { if (!registered) {
injector.getInstance(NativeSignalHandler.class).init(); injector.getInstance(NativeSignalHandler.class).init();
@@ -413,8 +413,8 @@ public class PresentsSession
// first time through we end our session, subsequently _throttle is null and we just drop // first time through we end our session, subsequently _throttle is null and we just drop
// any messages that come in until we've fully shutdown // any messages that come in until we've fully shutdown
if (_throttle == null) { if (_throttle == null) {
// log.info("Dropping message from force-quit client [conn=" + getConnection() + // log.info("Dropping message from force-quit client", "conn", getConnection(),
// ", msg=" + message + "]."); // "msg", message);
return; return;
} else if (_throttle.throttleOp(message.received)) { } else if (_throttle.throttleOp(message.received)) {
@@ -855,8 +855,8 @@ public class PresentsSession
// make darned sure we don't have any remaining subscriptions // make darned sure we don't have any remaining subscriptions
if (_subscrips.size() > 0) { if (_subscrips.size() > 0) {
// log.warning("Clearing stale subscriptions [client=" + this + // log.warning("Clearing stale subscriptions", "client", this,
// ", subscrips=" + _subscrips.size() + "]."); // "subscrips", _subscrips.size());
clearSubscrips(_messagesDropped > 10); clearSubscrips(_messagesDropped > 10);
} }
return false; return false;
@@ -1004,7 +1004,7 @@ public class PresentsSession
public void dispatch (PresentsSession client, Message msg) public void dispatch (PresentsSession client, Message msg)
{ {
SubscribeRequest req = (SubscribeRequest)msg; SubscribeRequest req = (SubscribeRequest)msg;
// log.info("Subscribing [client=" + client + ", oid=" + req.getOid() + "]."); // log.info("Subscribing", "client", client, "oid", req.getOid());
// forward the subscribe request to the omgr for processing // forward the subscribe request to the omgr for processing
client._omgr.subscribeToObject(req.getOid(), client.createProxySubscriber()); client._omgr.subscribeToObject(req.getOid(), client.createProxySubscriber());
@@ -1020,7 +1020,7 @@ public class PresentsSession
{ {
UnsubscribeRequest req = (UnsubscribeRequest)msg; UnsubscribeRequest req = (UnsubscribeRequest)msg;
int oid = req.getOid(); int oid = req.getOid();
// log.info("Unsubscribing " + client + " [oid=" + oid + "]."); // log.info("Unsubscribing " + client + "", "oid", oid);
// unsubscribe from the object and clear out our proxy // unsubscribe from the object and clear out our proxy
client.unmapSubscrip(oid); client.unmapSubscrip(oid);
@@ -1051,7 +1051,7 @@ public class PresentsSession
// fill in the proper source oid // fill in the proper source oid
fevt.setSourceOid(clobj.getOid()); fevt.setSourceOid(clobj.getOid());
// log.info("Forwarding event [client=" + client + ", event=" + fevt + "]."); // log.info("Forwarding event", "client", client, "event", fevt);
// forward the event to the omgr for processing // forward the event to the omgr for processing
client._omgr.postEvent(fevt); client._omgr.postEvent(fevt);
@@ -298,8 +298,7 @@ public abstract class RebootManager
return false; return false;
} }
log.info("Reboot delayed due to outstanding locks: " + log.info("Reboot delayed due to outstanding locks", "locks", _rebootLocks.elements());
StringUtil.toString(_rebootLocks.elements()));
broadcast("m.reboot_delayed"); broadcast("m.reboot_delayed");
_interval = new Interval(_omgr) { _interval = new Interval(_omgr) {
@Override @Override
@@ -135,7 +135,7 @@ public class ReportManager
try { try {
rptr.appendReport(report, now, sinceLast, reset); rptr.appendReport(report, now, sinceLast, reset);
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Reporter choked [rptr=" + rptr + "].", t); log.warning("Reporter choked", "rptr", rptr, t);
} }
} }
@@ -395,8 +395,7 @@ public class ConnectionManager extends LoopingThread
log.info("Server accepting datagrams on " + isa + "."); log.info("Server accepting datagrams on " + isa + ".");
} catch (IOException ioe) { } catch (IOException ioe) {
log.warning("Failure opening datagram channel on port '" + log.warning("Failure opening datagram channel on port '" + port + "'.", ioe);
port + "'.", ioe);
} }
} }
} }
@@ -550,8 +549,7 @@ public class ConnectionManager extends LoopingThread
Set<SelectionKey> ready = null; Set<SelectionKey> ready = null;
int eventCount; int eventCount;
try { try {
// log.debug("Selecting from " + StringUtil.toString(_selector.keys()) + " (" + // log.debug("Selecting from " + _selector.keys() + " (" + SELECT_LOOP_TIME + ").");
// SELECT_LOOP_TIME + ").");
// check for incoming network events // check for incoming network events
eventCount = _selector.select(SELECT_LOOP_TIME); eventCount = _selector.select(SELECT_LOOP_TIME);
@@ -602,7 +600,7 @@ public class ConnectionManager extends LoopingThread
continue; continue;
} }
// log.info("Got event [selkey=" + selkey + ", handler=" + handler + "]."); // log.info("Got event", "selkey", selkey, "handler", handler);
int got = handler.handleEvent(iterStamp); int got = handler.handleEvent(iterStamp);
if (got != 0) { if (got != 0) {
@@ -668,8 +666,8 @@ public class ConnectionManager extends LoopingThread
if (oqueue != null) { if (oqueue != null) {
int size = oqueue.size(); int size = oqueue.size();
if ((size > 500) && (size % 50 == 0)) { if ((size > 500) && (size % 50 == 0)) {
log.warning("Aiya, big overflow queue for " + conn + " [size=" + size + log.warning("Aiya, big overflow queue for " + conn + "", "size", size,
", adding=" + tup.right + "]."); "adding", tup.right);
} }
oqueue.add(tup.right); oqueue.add(tup.right);
continue; continue;
@@ -717,7 +715,7 @@ public class ConnectionManager extends LoopingThread
if (data.length > _outbuf.capacity()) { if (data.length > _outbuf.capacity()) {
// increase the buffer size in large increments // increase the buffer size in large increments
int ncapacity = Math.max(_outbuf.capacity() << 1, data.length); int ncapacity = Math.max(_outbuf.capacity() << 1, data.length);
log.info("Expanding output buffer size [nsize=" + ncapacity + "]."); log.info("Expanding output buffer size", "nsize", ncapacity);
_outbuf = ByteBuffer.allocateDirect(ncapacity); _outbuf = ByteBuffer.allocateDirect(ncapacity);
} }
@@ -766,7 +764,7 @@ public class ConnectionManager extends LoopingThread
{ {
InetSocketAddress target = conn.getDatagramAddress(); InetSocketAddress target = conn.getDatagramAddress();
if (target == null) { if (target == null) {
log.warning("No address to send datagram [conn=" + conn + "]."); log.warning("No address to send datagram", "conn", conn);
return false; return false;
} }
@@ -859,8 +857,7 @@ public class ConnectionManager extends LoopingThread
// id, authentication hash, and a class reference) // id, authentication hash, and a class reference)
int size = _databuf.flip().remaining(); int size = _databuf.flip().remaining();
if (size < 14) { if (size < 14) {
log.warning("Received undersized datagram [source=" + source + log.warning("Received undersized datagram", "source", source, "size", size);
", size=" + size + "].");
return 0; return 0;
} }
@@ -870,8 +867,8 @@ public class ConnectionManager extends LoopingThread
if (conn != null) { if (conn != null) {
conn.handleDatagram(source, _databuf, when); conn.handleDatagram(source, _databuf, when);
} else { } else {
log.warning("Received datagram for unknown connection [id=" + connectionId + log.warning("Received datagram for unknown connection", "id", connectionId,
", source=" + source + "]."); "source", source);
} }
// return the size of the datagram // return the size of the datagram
@@ -1113,8 +1110,8 @@ public class ConnectionManager extends LoopingThread
_partial = null; _partial = null;
_partials++; _partials++;
} else { } else {
// log.info("Still going [conn=" + conn + ", wrote=" + wrote + // log.info("Still going", "conn", conn, "wrote", wrote,
// ", remain=" + _partial.remaining() + "]."); // "remain", _partial.remaining());
return false; return false;
} }
} }
@@ -81,12 +81,11 @@ public class ClassUtil
} catch (NoSuchMethodException nsme) { } catch (NoSuchMethodException nsme) {
// nothing to do here but fall through and return null // nothing to do here but fall through and return null
log.info("No such method [name=" + name + ", tclass=" + tclass.getName() + log.info("No such method", "name", name, "tclass", tclass.getName(), "args", args,
", args=" + StringUtil.toString(args) + ", error=" + nsme + "]."); "error", nsme);
} catch (SecurityException se) { } catch (SecurityException se) {
log.warning("Unable to look up method? [tclass=" + tclass.getName() + log.warning("Unable to look up method?", "tclass", tclass.getName(), "mname", name);
", mname=" + name + "].");
} }
return meth; return meth;
@@ -161,8 +161,8 @@ public class MessageManager
// nothing to worry about // nothing to worry about
} catch (Throwable t) { } catch (Throwable t) {
log.warning("Failure instantiating custom message bundle " + log.warning("Failure instantiating custom message bundle", "mbclass", mbclass,
"[mbclass=" + mbclass + ", error=" + t + "]."); "error", t);
} }
} }
@@ -78,8 +78,7 @@ public class TrackedObject
if (count != null) { if (count != null) {
count[0]--; count[0]--;
} else { } else {
log.warning("Finalized TrackedObject missing counter! " + log.warning("Finalized TrackedObject missing counter!", "class", clazz);
"[class=" + clazz + "].");
} }
} }
@@ -189,8 +189,8 @@ public class SignalManager
{ {
ObserverList<SignalHandler> list = _handlers.get(signal); ObserverList<SignalHandler> list = _handlers.get(signal);
if (list == null || !list.contains(handler)) { if (list == null || !list.contains(handler)) {
log.warning("Requested to remove non-registered handler [signal=" + signal + log.warning("Requested to remove non-registered handler", "signal", signal,
", handler=" + handler + "]."); "handler", handler);
return; return;
} }
list.remove(handler); list.remove(handler);