From 583eaaa57c51b28bf14da2a5cc94a2e6091cccf5 Mon Sep 17 00:00:00 2001 From: Wink Saville Date: Fri, 13 Apr 2012 16:11:20 -0700 Subject: [PATCH] Enhance the debug output for StateMachines. Allow some messages to be ignored and allow the subclass to add additional information. In particular, the information can be used to decode the msg.what to a string. Change-Id: I4f53becc6f0cb77399f99702084efef9d8785d67 --- .../android/internal/util/AsyncChannel.java | 18 +++ .../android/internal/util/StateMachine.java | 141 +++++++++++++----- .../internal/telephony/DataConnection.java | 76 +++++++++- .../internal/telephony/DataConnectionAc.java | 45 ++++++ 4 files changed, 232 insertions(+), 48 deletions(-) diff --git a/core/java/com/android/internal/util/AsyncChannel.java b/core/java/com/android/internal/util/AsyncChannel.java index 39733440f0b61..0c5d5effb0ed9 100644 --- a/core/java/com/android/internal/util/AsyncChannel.java +++ b/core/java/com/android/internal/util/AsyncChannel.java @@ -150,6 +150,24 @@ public class AsyncChannel { */ public static final int CMD_CHANNEL_DISCONNECTED = BASE + 4; + private static final int CMD_TO_STRING_COUNT = CMD_CHANNEL_DISCONNECTED + 1; + private static String[] sCmdToString = new String[CMD_TO_STRING_COUNT]; + static { + sCmdToString[CMD_CHANNEL_HALF_CONNECTED - BASE] = "CMD_CHANNEL_HALF_CONNECTED"; + sCmdToString[CMD_CHANNEL_FULL_CONNECTION - BASE] = "CMD_CHANNEL_FULL_CONNECTION"; + sCmdToString[CMD_CHANNEL_FULLY_CONNECTED - BASE] = "CMD_CHANNEL_FULLY_CONNECTED"; + sCmdToString[CMD_CHANNEL_DISCONNECT - BASE] = "CMD_CHANNEL_DISCONNECT"; + sCmdToString[CMD_CHANNEL_DISCONNECTED - BASE] = "CMD_CHANNEL_DISCONNECTED"; + } + protected static String cmdToString(int cmd) { + cmd -= BASE; + if ((cmd >= 0) && (cmd < sCmdToString.length)) { + return sCmdToString[cmd]; + } else { + return null; + } + } + /** Successful status always 0, !0 is an unsuccessful status */ public static final int STATUS_SUCCESSFUL = 0; diff --git a/core/java/com/android/internal/util/StateMachine.java b/core/java/com/android/internal/util/StateMachine.java index 07496a7572c99..1391ac3940475 100644 --- a/core/java/com/android/internal/util/StateMachine.java +++ b/core/java/com/android/internal/util/StateMachine.java @@ -20,9 +20,13 @@ import android.os.Handler; import android.os.HandlerThread; import android.os.Looper; import android.os.Message; +import android.text.TextUtils; import android.util.Log; +import java.io.FileDescriptor; +import java.io.PrintWriter; import java.util.ArrayList; +import java.util.Calendar; import java.util.HashMap; import java.util.Vector; @@ -444,9 +448,11 @@ public class StateMachine { * The information maintained for a processed message. */ public static class ProcessedMessageInfo { - private int what; - private State state; - private State orgState; + private long mTime; + private int mWhat; + private String mInfo; + private State mState; + private State mOrgState; /** * Constructor @@ -455,8 +461,8 @@ public class StateMachine { * @param orgState is the first state the received the message but * did not processes the message. */ - ProcessedMessageInfo(Message message, State state, State orgState) { - update(message, state, orgState); + ProcessedMessageInfo(Message msg, String info, State state, State orgState) { + update(msg, info, state, orgState); } /** @@ -465,31 +471,47 @@ public class StateMachine { * @param orgState is the first state the received the message but * did not processes the message. */ - public void update(Message message, State state, State orgState) { - this.what = message.what; - this.state = state; - this.orgState = orgState; + public void update(Message msg, String info, State state, State orgState) { + mTime = System.currentTimeMillis(); + mWhat = msg.what; + mInfo = info; + mState = state; + mOrgState = orgState; + } + + /** + * @return time stamp + */ + public long getTime() { + return mTime; + } + + /** + * @return msg.what + */ + public long getWhat() { + return mWhat; } /** * @return the command that was executing */ - public int getWhat() { - return what; + public String getInfo() { + return mInfo; } /** * @return the state that handled this message */ public State getState() { - return state; + return mState; } /** * @return the original state that received the message. */ public State getOriginalState() { - return orgState; + return mOrgState; } /** @@ -498,26 +520,24 @@ public class StateMachine { @Override public String toString() { StringBuilder sb = new StringBuilder(); - sb.append("what="); - sb.append(what); + sb.append("time="); + Calendar c = Calendar.getInstance(); + c.setTimeInMillis(mTime); + sb.append(String.format("%tm-%td %tH:%tM:%tS.%tL", c, c, c, c, c, c)); sb.append(" state="); - sb.append(cn(state)); + sb.append(mState == null ? "" : mState.getName()); sb.append(" orgState="); - sb.append(cn(orgState)); - return sb.toString(); - } - - /** - * @return an objects class name - */ - private String cn(Object n) { - if (n == null) { - return "null"; - } else { - String name = n.getClass().getName(); - int lastDollar = name.lastIndexOf('$'); - return name.substring(lastDollar + 1); + sb.append(mOrgState == null ? "" : mOrgState.getName()); + sb.append(" what="); + sb.append(mWhat); + sb.append("(0x"); + sb.append(Integer.toHexString(mWhat)); + sb.append(")"); + if ( ! TextUtils.isEmpty(mInfo)) { + sb.append(" "); + sb.append(mInfo); } + return sb.toString(); } } @@ -542,9 +562,9 @@ public class StateMachine { private int mCount = 0; /** - * Constructor + * private constructor use add */ - ProcessedMessages() { + private ProcessedMessages() { } /** @@ -599,22 +619,23 @@ public class StateMachine { /** * Add a processed message. * - * @param message + * @param msg + * @param messageInfo to be stored * @param state that handled the message * @param orgState is the first state the received the message but * did not processes the message. */ - void add(Message message, State state, State orgState) { + void add(Message msg, String messageInfo, State state, State orgState) { mCount += 1; if (mMessages.size() < mMaxSize) { - mMessages.add(new ProcessedMessageInfo(message, state, orgState)); + mMessages.add(new ProcessedMessageInfo(msg, messageInfo, state, orgState)); } else { ProcessedMessageInfo pmi = mMessages.get(mOldestIndex); mOldestIndex += 1; if (mOldestIndex >= mMaxSize) { mOldestIndex = 0; } - pmi.update(message, state, orgState); + pmi.update(msg, messageInfo, state, orgState); } } } @@ -894,11 +915,14 @@ public class StateMachine { /** * Record that we processed the message */ - if (curStateInfo != null) { - State orgState = mStateStack[mStateStackTopIndex].state; - mProcessedMessages.add(msg, curStateInfo.state, orgState); - } else { - mProcessedMessages.add(msg, null, null); + if (mSm.recordProcessedMessage(msg)) { + if (curStateInfo != null) { + State orgState = mStateStack[mStateStackTopIndex].state; + mProcessedMessages.add(msg, mSm.getMessageInfo(msg), curStateInfo.state, + orgState); + } else { + mProcessedMessages.add(msg, mSm.getMessageInfo(msg), null, null); + } } } @@ -1545,6 +1569,24 @@ public class StateMachine { return mSmHandler.isQuit(msg); } + /** + * @return true if msg should be saved in ProcessedMessage, default is true. + */ + protected boolean recordProcessedMessage(Message msg) { + return true; + } + + /** + * Return message info to be logged by ProcessedMessageInfo, default + * is an empty string. Override if additional information is desired. + * + * @param msg that was processed + * @return information to be logged as a String + */ + protected String getMessageInfo(Message msg) { + return ""; + } + /** * @return if debugging is enabled */ @@ -1577,4 +1619,21 @@ public class StateMachine { /** Send the complete construction message */ mSmHandler.completeConstruction(); } + + /** + * Dump the current state. + * + * @param fd + * @param pw + * @param args + */ + public void dump(FileDescriptor fd, PrintWriter pw, String[] args) { + pw.println(getName() + ":"); + pw.println(" total messages=" + getProcessedMessagesCount()); + for (int i=0; i < getProcessedMessagesSize(); i++) { + pw.printf(" msg[%d]: %s\n", i, getProcessedMessageInfo(i)); + pw.flush(); + } + pw.println("curState=" + getCurrentState().getName()); + } } diff --git a/telephony/java/com/android/internal/telephony/DataConnection.java b/telephony/java/com/android/internal/telephony/DataConnection.java index 486a924064a42..a124c7f16b124 100644 --- a/telephony/java/com/android/internal/telephony/DataConnection.java +++ b/telephony/java/com/android/internal/telephony/DataConnection.java @@ -35,6 +35,7 @@ import android.text.TextUtils; import java.io.FileDescriptor; import java.io.PrintWriter; import java.util.ArrayList; +import java.util.Calendar; import java.util.HashMap; import java.util.List; @@ -208,6 +209,27 @@ public abstract class DataConnection extends StateMachine { protected static final int EVENT_RIL_CONNECTED = BASE + 5; protected static final int EVENT_DISCONNECT_ALL = BASE + 6; + private static final int CMD_TO_STRING_COUNT = EVENT_DISCONNECT_ALL + 1; + private static String[] sCmdToString = new String[CMD_TO_STRING_COUNT]; + static { + sCmdToString[EVENT_CONNECT - BASE] = "EVENT_CONNECT"; + sCmdToString[EVENT_SETUP_DATA_CONNECTION_DONE - BASE] = + "EVENT_SETUP_DATA_CONNECTION_DONE"; + sCmdToString[EVENT_GET_LAST_FAIL_DONE - BASE] = "EVENT_GET_LAST_FAIL_DONE"; + sCmdToString[EVENT_DEACTIVATE_DONE - BASE] = "EVENT_DEACTIVATE_DONE"; + sCmdToString[EVENT_DISCONNECT - BASE] = "EVENT_DISCONNECT"; + sCmdToString[EVENT_RIL_CONNECTED - BASE] = "EVENT_RIL_CONNECTED"; + sCmdToString[EVENT_DISCONNECT_ALL - BASE] = "EVENT_DISCONNECT_ALL"; + } + protected static String cmdToString(int cmd) { + cmd -= BASE; + if ((cmd >= 0) && (cmd < sCmdToString.length)) { + return sCmdToString[cmd]; + } else { + return null; + } + } + //***** Tag IDs for EventLog protected static final int EVENT_LOG_BAD_DNS_ADDRESS = 50100; @@ -242,6 +264,7 @@ public abstract class DataConnection extends StateMachine { protected DataConnection(PhoneBase phone, String name, int id, RetryManager rm, DataConnectionTracker dct) { super(name); + setProcessedMessagesSize(100); if (DBG) log("DataConnection constructor E"); this.phone = phone; this.mDataConnectionTracker = dct; @@ -1188,26 +1211,65 @@ public abstract class DataConnection extends StateMachine { new DisconnectParams(reason, onCompletedMsg))); } + /** + * @return the string for msg.what as our info. + */ + @Override + protected String getMessageInfo(Message msg) { + String info = null; + info = cmdToString(msg.what); + if (info == null) { + info = DataConnectionAc.cmdToString(msg.what); + } + return info; + } + + /** + * Convert a System.currentTimeMillis() value to a time of day value. + * + * @param millis since the epoch (1/1/1970) + * @return String representation of the time. + */ + private String timeMillisToTimeOfDay(long millis) { + Calendar c = Calendar.getInstance(); + if (millis >= 0) { + c.setTimeInMillis(millis); + return String.format("%tm-%td %tH:%tM:%tS.%tL", c, c, c, c, c, c); + } else { + return Long.toString(millis); + } + } + /** + * Dump the current state. + * + * @param fd + * @param pw + * @param args + */ + @Override public void dump(FileDescriptor fd, PrintWriter pw, String[] args) { - pw.println("DataConnection name=" + getName() + ":"); + pw.print("DataConnection "); + super.dump(fd, pw, args); pw.println(" mApnList=" + mApnList); + pw.flush(); pw.println(" mDataConnectionTracker=" + mDataConnectionTracker); pw.println(" mApn=" + mApn); pw.println(" mTag=" + mTag); + pw.flush(); pw.println(" phone=" + phone); pw.println(" mRilVersion=" + mRilVersion); pw.println(" cid=" + cid); + pw.flush(); pw.println(" mLinkProperties=" + mLinkProperties); + pw.flush(); pw.println(" mCapabilities=" + mCapabilities); - pw.println(" createTime=" + createTime); - pw.println(" lastFailTime=" + lastFailTime); + pw.println(" createTime=" + timeMillisToTimeOfDay(createTime)); + pw.println(" lastFailTime=" + timeMillisToTimeOfDay(lastFailTime)); pw.println(" lastFailCause=" + lastFailCause); + pw.flush(); pw.println(" mRetryOverride=" + mRetryOverride); pw.println(" mRefCount=" + mRefCount); pw.println(" userData=" + userData); - pw.println(" total messages=" + getProcessedMessagesCount()); - for (int i=0; i < getProcessedMessagesSize(); i++) { - pw.printf(" msg[%d]=%s\n", i, getProcessedMessageInfo(i)); - } + pw.flush(); } } diff --git a/telephony/java/com/android/internal/telephony/DataConnectionAc.java b/telephony/java/com/android/internal/telephony/DataConnectionAc.java index a9f2cd1b090d9..4744ff038c30e 100644 --- a/telephony/java/com/android/internal/telephony/DataConnectionAc.java +++ b/telephony/java/com/android/internal/telephony/DataConnectionAc.java @@ -82,6 +82,51 @@ public class DataConnectionAc extends AsyncChannel { public static final int REQ_GET_RECONNECT_INTENT = BASE + 26; public static final int RSP_GET_RECONNECT_INTENT = BASE + 27; + private static final int CMD_TO_STRING_COUNT = RSP_GET_RECONNECT_INTENT + 1; + private static String[] sCmdToString = new String[CMD_TO_STRING_COUNT]; + static { + sCmdToString[REQ_IS_INACTIVE - BASE] = "REQ_IS_INACTIVE"; + sCmdToString[RSP_IS_INACTIVE - BASE] = "RSP_IS_INACTIVE"; + sCmdToString[REQ_GET_CID - BASE] = "REQ_GET_CID"; + sCmdToString[RSP_GET_CID - BASE] = "RSP_GET_CID"; + sCmdToString[REQ_GET_APNSETTING - BASE] = "REQ_GET_APNSETTING"; + sCmdToString[RSP_GET_APNSETTING - BASE] = "RSP_GET_APNSETTING"; + sCmdToString[REQ_GET_LINK_PROPERTIES - BASE] = "REQ_GET_LINK_PROPERTIES"; + sCmdToString[RSP_GET_LINK_PROPERTIES - BASE] = "RSP_GET_LINK_PROPERTIES"; + sCmdToString[REQ_SET_LINK_PROPERTIES_HTTP_PROXY - BASE] = + "REQ_SET_LINK_PROPERTIES_HTTP_PROXY"; + sCmdToString[RSP_SET_LINK_PROPERTIES_HTTP_PROXY - BASE] = + "RSP_SET_LINK_PROPERTIES_HTTP_PROXY"; + sCmdToString[REQ_GET_LINK_CAPABILITIES - BASE] = "REQ_GET_LINK_CAPABILITIES"; + sCmdToString[RSP_GET_LINK_CAPABILITIES - BASE] = "RSP_GET_LINK_CAPABILITIES"; + sCmdToString[REQ_UPDATE_LINK_PROPERTIES_DATA_CALL_STATE - BASE] = + "REQ_UPDATE_LINK_PROPERTIES_DATA_CALL_STATE"; + sCmdToString[RSP_UPDATE_LINK_PROPERTIES_DATA_CALL_STATE - BASE] = + "RSP_UPDATE_LINK_PROPERTIES_DATA_CALL_STATE"; + sCmdToString[REQ_RESET - BASE] = "REQ_RESET"; + sCmdToString[RSP_RESET - BASE] = "RSP_RESET"; + sCmdToString[REQ_GET_REFCOUNT - BASE] = "REQ_GET_REFCOUNT"; + sCmdToString[RSP_GET_REFCOUNT - BASE] = "RSP_GET_REFCOUNT"; + sCmdToString[REQ_ADD_APNCONTEXT - BASE] = "REQ_ADD_APNCONTEXT"; + sCmdToString[RSP_ADD_APNCONTEXT - BASE] = "RSP_ADD_APNCONTEXT"; + sCmdToString[REQ_REMOVE_APNCONTEXT - BASE] = "REQ_REMOVE_APNCONTEXT"; + sCmdToString[RSP_REMOVE_APNCONTEXT - BASE] = "RSP_REMOVE_APNCONTEXT"; + sCmdToString[REQ_GET_APNCONTEXT_LIST - BASE] = "REQ_GET_APNCONTEXT_LIST"; + sCmdToString[RSP_GET_APNCONTEXT_LIST - BASE] = "RSP_GET_APNCONTEXT_LIST"; + sCmdToString[REQ_SET_RECONNECT_INTENT - BASE] = "REQ_SET_RECONNECT_INTENT"; + sCmdToString[RSP_SET_RECONNECT_INTENT - BASE] = "RSP_SET_RECONNECT_INTENT"; + sCmdToString[REQ_GET_RECONNECT_INTENT - BASE] = "REQ_GET_RECONNECT_INTENT"; + sCmdToString[RSP_GET_RECONNECT_INTENT - BASE] = "RSP_GET_RECONNECT_INTENT"; + } + protected static String cmdToString(int cmd) { + cmd -= BASE; + if ((cmd >= 0) && (cmd < sCmdToString.length)) { + return sCmdToString[cmd]; + } else { + return AsyncChannel.cmdToString(cmd + BASE); + } + } + /** * enum used to notify action taken or necessary to be * taken after the link property is changed.