From cfa9b738337a9692350beadd0d9c74add82bfca7 Mon Sep 17 00:00:00 2001 From: Eric House Date: Fri, 17 Apr 2020 16:45:03 -0700 Subject: [PATCH] first cut at persisting logged messages Works, with support for writing them to file. BUT does not handle messages coming in from multiple threads at once so drops a lot of them. --- .../org/eehouse/android/xw4/DlgDelegate.java | 1 + .../android/xw4/GamesListDelegate.java | 32 +++ .../java/org/eehouse/android/xw4/Log.java | 221 +++++++++++++++++- .../java/org/eehouse/android/xw4/Utils.java | 4 +- .../java/org/eehouse/android/xw4/XWApp.java | 2 + .../app/src/main/res/menu/games_list_menu.xml | 12 + .../app/src/main/res/values/strings.xml | 16 ++ xwords4/android/jni/andutils.c | 68 +++++- xwords4/android/jni/andutils.h | 7 + xwords4/android/jni/xwjni.c | 58 ++++- 10 files changed, 400 insertions(+), 21 deletions(-) diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/DlgDelegate.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/DlgDelegate.java index fbed46ef4..0c9e325d4 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/DlgDelegate.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/DlgDelegate.java @@ -51,6 +51,7 @@ public class DlgDelegate { DWNLD_LOC_DICT, NEW_GAME_DFLT_NAME, SEND_EMAIL, + CLEAR_LOG_DB, // BoardDelegate UNDO_LAST_ACTION, diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/GamesListDelegate.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/GamesListDelegate.java index 25f264353..7f5fdf688 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/GamesListDelegate.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/GamesListDelegate.java @@ -62,6 +62,7 @@ import org.eehouse.android.xw4.jni.GameSummary; import org.eehouse.android.xw4.jni.LastMoveInfo; import org.eehouse.android.xw4.loc.LocUtils; +import java.io.File; import java.io.Serializable; import java.util.ArrayList; import java.util.Date; @@ -574,6 +575,10 @@ public class GamesListDelegate extends ListDelegateBase // R.id.games_menu_loaddb, R.id.games_menu_storedb, R.id.games_menu_writegit, + R.id.games_menu_enableLogStorage, + R.id.games_menu_disableLogStorage, + R.id.games_menu_clearLogStorage, + R.id.games_menu_dumpLogStorage, }; private static final int[] NOSEL_ITEMS = { R.id.games_menu_newgroup, @@ -1380,6 +1385,11 @@ public class GamesListDelegate extends ListDelegateBase Utils.emailAuthor( m_activity ); break; + case CLEAR_LOG_DB: + int nDumped = Log.clearStored(); + Utils.showToast( m_activity, R.string.logstore_cleared_fmt, nDumped ); + break; + case ASKED_PHONE_STATE: rematchWithNameAndPerm( true, params ); break; @@ -1664,6 +1674,28 @@ public class GamesListDelegate extends ListDelegateBase Utils.gitInfoToClip( m_activity ); break; + case R.id.games_menu_enableLogStorage: + Log.setStoreLogs( true ); + break; + case R.id.games_menu_disableLogStorage: + Log.setStoreLogs( false ); + break; + case R.id.games_menu_clearLogStorage: + makeConfirmThenBuilder( R.string.logstore_clear_confirm, + Action.CLEAR_LOG_DB ) + .setPosButton( R.string.button_delete ) + .show(); + break; + case R.id.games_menu_dumpLogStorage: + File logLoc = Log.dumpStored(); + if ( null != logLoc ) { + String dumpMsg = LocUtils + .getString( m_activity, R.string.logstore_dumped_fmt, + logLoc.getPath() ); + makeOkOnlyBuilder( dumpMsg ).show(); + } + break; + default: handled = handleSelGamesItem( itemID, selRowIDs ) || handleSelGroupsItem( itemID, getSelGroupIDs() ); diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/Log.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/Log.java index 1cc2a5116..1def66a8c 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/Log.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/Log.java @@ -1,6 +1,6 @@ /* -*- compile-command: "find-and-gradle.sh inXw4dDeb"; -*- */ /* - * Copyright 2009 - 2017 by Eric House (xwords@eehouse.org). All rights + * Copyright 2009 - 2020 by Eric House (xwords@eehouse.org). All rights * reserved. * * This program is free software; you can redistribute it and/or @@ -20,22 +20,87 @@ package org.eehouse.android.xw4; +import android.content.ContentValues; import android.content.Context; +import android.database.Cursor; +import android.database.sqlite.SQLiteDatabase; +import android.database.sqlite.SQLiteOpenHelper; +import android.os.Environment; +import java.io.File; +import java.io.FileOutputStream; +import java.io.IOException; +import java.io.OutputStream; +import java.io.OutputStreamWriter; +import java.lang.ref.WeakReference; import java.util.Formatter; public class Log { + private static final String TAG = Log.class.getSimpleName(); private static final String PRE_TAG = BuildConfig.FLAVOR + "-"; + private static final String KEY_USE_DB = TAG + "/useDB"; private static final boolean LOGGING_ENABLED = BuildConfig.DEBUG || !BuildConfig.IS_TAGGED_BUILD; private static final boolean ERROR_LOGGING_ENABLED = true; + private static final String LOGS_DB_NAME = "logs_db"; + private static final String LOGS_TABLE_NAME = "logs"; + private static final String COL_ENTRY = "entry"; + private static final String COL_ROWID = "rowid"; + private static final String COL_TAG = "tag"; + private static final String COL_LEVEL = "level"; + + private static final int DB_VERSION = 1; private static boolean sEnabled = BuildConfig.DEBUG; + private static boolean sUseDB; + private static WeakReference sContextRef; + + private static enum LOG_LEVEL { + INFO, + ERROR, + WARN, + DEBUG, + } + + public static void init( Context context ) + { + sContextRef = new WeakReference<>( context ); + sUseDB = DBUtils.getBoolFor( context, KEY_USE_DB, false ); + } + + public static void setStoreLogs( boolean enable ) + { + Context context = sContextRef.get(); + if ( null != context ) { + DBUtils.setBoolFor( context, KEY_USE_DB, enable ); + } + sUseDB = enable; + } public static void enable( boolean newVal ) { sEnabled = newVal; } + public static int clearStored() + { + int result = 0; + LogDBHelper helper = initDB(); + if ( null != helper ) { + result = helper.clear(); + } + return result; + } + + public static File dumpStored() + { + File result = null; + LogDBHelper helper = initDB(); + if ( null != helper ) { + result = helper.dumpToFile(); + } + return result; + } + public static void enable( Context context ) { boolean on = LOGGING_ENABLED || @@ -47,35 +112,54 @@ public class Log { public static void d( String tag, String fmt, Object... args ) { if ( sEnabled ) { - String str = new Formatter().format( fmt, args ).toString(); - android.util.Log.d( PRE_TAG + tag, str ); + dolog( LOG_LEVEL.DEBUG, tag, fmt, args ); } } public static void w( String tag, String fmt, Object... args ) { if ( sEnabled ) { - String str = new Formatter().format( fmt, args ).toString(); - android.util.Log.w( PRE_TAG + tag, str ); + dolog( LOG_LEVEL.WARN, tag, fmt, args ); } } public static void e( String tag, String fmt, Object... args ) { if ( ERROR_LOGGING_ENABLED ) { - String str = new Formatter().format( fmt, args ).toString(); - android.util.Log.e( PRE_TAG + tag, str ); + dolog( LOG_LEVEL.ERROR, tag, fmt, args ); } } public static void i( String tag, String fmt, Object... args ) { if ( sEnabled ) { - String str = new Formatter().format( fmt, args ).toString(); - android.util.Log.i( PRE_TAG + tag, str ); + dolog( LOG_LEVEL.INFO, tag, fmt, args ); } } + private static void dolog( LOG_LEVEL level, String tag, String fmt, Object[] args ) + { + String str = new Formatter().format( fmt, args ).toString(); + String fullTag = PRE_TAG + tag; + switch ( level ) { + case DEBUG: + android.util.Log.d( fullTag, str ); + break; + case ERROR: + android.util.Log.e( fullTag, str ); + break; + case WARN: + android.util.Log.w( fullTag, str ); + break; + case INFO: + android.util.Log.e( fullTag, str ); + break; + default: + Assert.failDbg(); + } + store( level, fullTag, str ); + } + public static void ex( String tag, Exception exception ) { if ( sEnabled ) { @@ -83,4 +167,123 @@ public class Log { DbgUtils.printStack( tag, exception.getStackTrace() ); } } + + private static void llog( String fmt, Object... args ) + { + String str = new Formatter().format( fmt, args ).toString(); + android.util.Log.d( TAG, str ); + } + + private static LogDBHelper s_dbHelper; + private synchronized static LogDBHelper initDB() + { + if ( null == s_dbHelper ) { + Context context = sContextRef.get(); + if ( null != context ) { + s_dbHelper = new LogDBHelper( context ); + // force any upgrade + s_dbHelper.getWritableDatabase().close(); + } + } + return s_dbHelper; + } + + // Called from jni + public static void store( String tag, String msg ) + { + llog( "store(%s) called from jni", msg ); + store( LOG_LEVEL.DEBUG, tag, msg ); + } + + private static void store( LOG_LEVEL level, String tag, String msg ) + { + if ( sUseDB ) { + LogDBHelper helper = initDB(); + if ( null != helper ) { + helper.store( level, tag, msg ); + } + } + } + + private static class LogDBHelper extends SQLiteOpenHelper { + private Context mContext; + + LogDBHelper( Context context ) + { + super( context, LOGS_DB_NAME, null, DB_VERSION ); + mContext = context; + } + + @Override + public void onCreate( SQLiteDatabase db ) + { + String query = "CREATE TABLE " + LOGS_TABLE_NAME + "(" + + COL_ROWID + " INTEGER PRIMARY KEY AUTOINCREMENT" + + "," + COL_ENTRY + " TEXT" + + "," + COL_TAG + " TEXT" + + "," + COL_LEVEL + " INTEGER(2)" + + ");"; + + db.execSQL( query ); + } + + @Override + @SuppressWarnings("fallthrough") + public void onUpgrade( SQLiteDatabase db, int oldVersion, int newVersion ) + { + String msg = String.format("onUpgrade(%s): old: %d; new: %d", db, oldVersion, newVersion ); + android.util.Log.i( TAG, msg ); + Assert.failDbg(); + } + + void store( LOG_LEVEL level, String tag, String msg ) + { + ContentValues values = new ContentValues(); + values.put( COL_ENTRY, msg ); + values.put( COL_TAG, tag ); + values.put( COL_LEVEL, level.ordinal() ); + long res = getWritableDatabase().insert( LOGS_TABLE_NAME, null, values ); + } + + File dumpToFile() + { + File storage = Environment.getExternalStorageDirectory(); + File db = new File( storage, LOGS_DB_NAME ); + + try { + OutputStream os = new FileOutputStream( db ); + OutputStreamWriter osw = new OutputStreamWriter(os); + + String[] columns = { COL_ENTRY, COL_TAG }; + String selection = null; + String orderBy = COL_ROWID; + Cursor cursor = getReadableDatabase().query( LOGS_TABLE_NAME, columns, + selection, null, null, null, + orderBy ); + llog( "dumpToFile(): got %d results", cursor.getCount() ); + int indx0 = cursor.getColumnIndex( columns[0] ); + int indx1 = cursor.getColumnIndex( columns[1] ); + while ( cursor.moveToNext() ) { + String data = cursor.getString(indx0); + String tag = cursor.getString(indx1); + osw.write( tag ); + osw.write( ":" ); + osw.write(data); + osw.write( "\n" ); + } + osw.close(); + } catch ( IOException ioe ) { + llog( "dumpToFile(): ioe: %s", ioe ); + } + return db; + } + + // Return the number of rows + int clear() + { + int result = getWritableDatabase() + .delete( LOGS_TABLE_NAME, "1", null ); + return result; + } + } } diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/Utils.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/Utils.java index c6899c6e1..9a07c43b5 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/Utils.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/Utils.java @@ -65,6 +65,7 @@ import java.io.ObjectInputStream; import java.io.ObjectOutputStream; import java.io.Serializable; import java.security.MessageDigest; +import java.util.Formatter; import java.util.HashMap; import java.util.Iterator; import java.util.List; @@ -174,9 +175,10 @@ public class Utils { } } - public static void showToast( Context context, int id ) + public static void showToast( Context context, int id, Object... args ) { String msg = LocUtils.getString( context, id ); + msg = new Formatter().format( msg, args ).toString(); showToast( context, msg ); } diff --git a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWApp.java b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWApp.java index b4f45100f..77a3f8fb1 100644 --- a/xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWApp.java +++ b/xwords4/android/app/src/main/java/org/eehouse/android/xw4/XWApp.java @@ -71,6 +71,8 @@ public class XWApp extends Application Assert.assertTrue( s_context == s_context.getApplicationContext() ); super.onCreate(); + Log.init( this ); + ProcessLifecycleOwner.get().getLifecycle().addObserver(this); android.util.Log.i( TAG, "onCreate(); git_rev=" diff --git a/xwords4/android/app/src/main/res/menu/games_list_menu.xml b/xwords4/android/app/src/main/res/menu/games_list_menu.xml index 08a679053..cea644131 100644 --- a/xwords4/android/app/src/main/res/menu/games_list_menu.xml +++ b/xwords4/android/app/src/main/res/menu/games_list_menu.xml @@ -122,4 +122,16 @@ android:title="@string/gamel_menu_writegit" /> + + + + diff --git a/xwords4/android/app/src/main/res/values/strings.xml b/xwords4/android/app/src/main/res/values/strings.xml index 38b00986a..69a88dedb 100644 --- a/xwords4/android/app/src/main/res/values/strings.xml +++ b/xwords4/android/app/src/main/res/values/strings.xml @@ -2519,4 +2519,20 @@ Paused by: %1$s. Message: %1$s. Auto-paused. + + + Enable log storage + + Diable log storage + + Clear stored logs + + Write stored logs to file + + Logs written to file %1$s + + %1$d log entries deleted + + Are you sure you want to + erase your debug logs? This action cannot be undone. diff --git a/xwords4/android/jni/andutils.c b/xwords4/android/jni/andutils.c index 573a7edd7..14c785dbb 100644 --- a/xwords4/android/jni/andutils.c +++ b/xwords4/android/jni/andutils.c @@ -30,6 +30,8 @@ void and_assert( const char* test, int line, const char* file, const char* func ) { + RAW_LOG( "assertion \"%s\" failed: line %d in %s() in %s", + test, line, func, file ); XP_LOGF( "assertion \"%s\" failed: line %d in %s() in %s", test, line, func, file ); __android_log_assert( test, "ASSERT", "line %d in %s() in %s", @@ -766,6 +768,46 @@ deleteLocalRefs( JNIEnv* env, ... ) } #ifdef DEBUG +static int g_log_count = 0; +static pthread_mutex_t g_log_count_lock = PTHREAD_MUTEX_INITIALIZER; + +/* A bunch of threads are generating log statements. */ +static void +passToJava( const char* tag, const char* msg ) +{ + if ( 1 ) { + pthread_mutex_lock( &g_log_count_lock ); + int lockCount = ++g_log_count; + RAW_LOG( "lockCount: %d", lockCount ); + pthread_mutex_unlock( &g_log_count_lock ); + + /* Now pass into Log.java for possible writing to DB */ + if ( 1 == lockCount ) { + JNIEnv* env = waitEnvFromGlobals(); + if ( !!env ) { + jstring jtag = (*env)->NewStringUTF( env, tag ); + jstring jbuf = (*env)->NewStringUTF( env, msg ); + jclass clazz = (*env)->FindClass( env, PKG_PATH("Log") ); + XP_ASSERT( !!clazz ); + jmethodID mid = (*env)->GetStaticMethodID( env, clazz, "store", + "(Ljava/lang/String;Ljava/lang/String;)V" ); + (*env)->CallStaticVoidMethod( env, clazz, mid, jtag, jbuf ); + deleteLocalRefs( env, clazz, jtag, jbuf, DELETE_NO_REF ); + + releaseEnvFromGlobals( env ); + } else { + RAW_LOG( "env is NULL; dropping" ); + } + } else { + RAW_LOG( "recursing! Skipping msg %s", msg ); + } + + pthread_mutex_lock( &g_log_count_lock ); + --g_log_count; + pthread_mutex_unlock( &g_log_count_lock ); + } +} + static void debugf( const char* format, va_list ap ) { @@ -783,8 +825,8 @@ debugf( const char* format, va_list ap ) if ( len < sizeof(buf) ) { vsnprintf( buf + len, sizeof(buf)-len, format, ap ); } - - (void)__android_log_write( ANDROID_LOG_DEBUG, + + const char* tag = # if defined VARIANT_xw4NoSMS || defined VARIANT_xw4fdroid || defined VARIANT_xw4SMS "xw4" # elif defined VARIANT_xw4d || defined VARIANT_xw4dNoSMS @@ -792,7 +834,27 @@ debugf( const char* format, va_list ap ) # elif defined VARIANT_xw4dup || defined VARIANT_xw4dupNoSMS "x4du" # endif - , buf ); + ; + + (void)__android_log_write( ANDROID_LOG_DEBUG, tag, buf ); + + passToJava( tag, buf ); +} + +void +raw_log( const char* func, const char* fmt, ... ) +{ + char buf[1024]; + int len = snprintf( buf, VSIZE(buf) - 1, "in %s(): %s", func, fmt ); + buf[len] = '\0'; + + va_list ap; + va_start( ap, fmt ); + char buf2[1024]; + len = vsnprintf( buf2, VSIZE(buf2) - 1, buf, ap ); + va_end( ap ); + + (void)__android_log_write( ANDROID_LOG_DEBUG, "raw", buf2 ); } void diff --git a/xwords4/android/jni/andutils.h b/xwords4/android/jni/andutils.h index a19eef58f..a2cc306b8 100644 --- a/xwords4/android/jni/andutils.h +++ b/xwords4/android/jni/andutils.h @@ -108,5 +108,12 @@ XP_U32 getCurSeconds( JNIEnv* env ); void deleteLocalRef( JNIEnv* env, jobject jobj ); void deleteLocalRefs( JNIEnv* env, ... ); + +JNIEnv* waitEnvFromGlobals(); +void releaseEnvFromGlobals( JNIEnv* env ); + +void raw_log( const char* func, const char* fmt, ... ); +#define RAW_LOG(...) raw_log( __func__, __VA_ARGS__ ) + # define DELETE_NO_REF ((jobject)-1) /* terminates above varargs list */ #endif diff --git a/xwords4/android/jni/xwjni.c b/xwords4/android/jni/xwjni.c index 4ed600296..5c49b67b7 100644 --- a/xwords4/android/jni/xwjni.c +++ b/xwords4/android/jni/xwjni.c @@ -118,7 +118,7 @@ typedef long GamePtrType; #ifdef LOG_MAPPING # ifdef DEBUG static int -countUsed(const EnvThreadInfo* ti) +countUsed( const EnvThreadInfo* ti ) { int count = 0; for ( int ii = 0; ii < ti->nEntries; ++ii ) { @@ -157,8 +157,8 @@ map_thread_prv( EnvThreadInfo* ti, JNIEnv* env, const char* caller ) found = true; if ( env != entry->env ) { /* this DOES happen!!! */ - XP_LOGF( "%s (ti=%p): replacing env %p with env %p for thread %x", - __func__, ti, entry->env, env, (int)self ); + RAW_LOG( "(ti=%p): replacing env %p with env %p for thread %x", + ti, entry->env, env, (int)self ); entry->env = env; } } @@ -180,7 +180,7 @@ map_thread_prv( EnvThreadInfo* ti, JNIEnv* env, const char* caller ) ti->entries = entries; ti->nEntries = nEntries; #ifdef LOG_MAPPING - XP_LOGF( "%s: num env entries now %d", __func__, nEntries ); + RAW_LOG( "num env entries now %d", nEntries ); #endif } @@ -191,9 +191,9 @@ map_thread_prv( EnvThreadInfo* ti, JNIEnv* env, const char* caller ) ++firstEmpty->refcount; #ifdef LOG_MAPPING firstEmpty->ownerFunc = caller; - XP_LOGF( "%s: entry %zu: mapped env %p to thread %x", __func__, + RAW_LOG( "entry %zu: mapped env %p to thread %x", firstEmpty - ti->entries, env, (int)self ); - XP_LOGF( "%s: num entries USED now %d", __func__, countUsed(ti) ); + RAW_LOG( "num entries USED now %d", countUsed(ti) ); #endif } @@ -221,9 +221,9 @@ map_remove_prv( EnvThreadInfo* ti, JNIEnv* env, const char* func ) if ( found ) { XP_ASSERT( pthread_self() == entry->owner ); #ifdef LOG_MAPPING - XP_LOGF( "%s: UNMAPPED env %p to thread %x (from %s; mapped by %s)", __func__, + RAW_LOG( "UNMAPPED env %p to thread %x (from %s; mapped by %s)", entry->env, (int)entry->owner, func, entry->ownerFunc ); - XP_LOGF( "%s: %d entries left", __func__, countUsed( ti ) ); + RAW_LOG( "%d entries left", countUsed( ti ) ); entry->ownerFunc = NULL; #endif XP_ASSERT( 1 == entry->refcount ); @@ -258,6 +258,46 @@ prvEnvForMe( EnvThreadInfo* ti ) return result; } +#ifdef DEBUG +static pthread_mutex_t g_globalStateLock = PTHREAD_MUTEX_INITIALIZER; +static JNIGlobalState* g_globalState = NULL; + +void setGlobalState( JNIGlobalState* state ) +{ + pthread_mutex_lock( &g_globalStateLock ); + g_globalState = state; + pthread_mutex_unlock( &g_globalStateLock ); +} + +JNIEnv* +waitEnvFromGlobals() /* hanging */ +{ + JNIEnv* result = NULL; + pthread_mutex_lock( &g_globalStateLock ); + JNIGlobalState* state = g_globalState; + if ( !!state ) { + result = prvEnvForMe( &state->ti ); + } + if ( !result ) { + pthread_mutex_unlock( &g_globalStateLock ); + } + return result; +} + +void +releaseEnvFromGlobals( JNIEnv* env ) +{ + XP_ASSERT( !!env ); + JNIGlobalState* state = g_globalState; + XP_ASSERT( !!state ); + XP_ASSERT( env == prvEnvForMe( &state->ti ) ); + pthread_mutex_unlock( &g_globalStateLock ); +} + +#else +# define setGlobalState(s) +#endif + JNIEnv* envForMe( EnvThreadInfo* ti, const char* caller ) { @@ -325,6 +365,7 @@ Java_org_eehouse_android_xw4_jni_XwJNI_initGlobals globalState->dictMgr = dmgr_make( MPPARM_NOCOMMA( mpool ) ); globalState->smsProto = smsproto_init( MPPARM( mpool ) globalState->dutil ); MPASSIGN( globalState->mpool, mpool ); + setGlobalState( globalState ); // LOG_RETURNF( "%p", globalState ); return (jlong)globalState; } @@ -335,6 +376,7 @@ Java_org_eehouse_android_xw4_jni_XwJNI_cleanGlobals { // LOG_FUNC(); if ( 0 != jniGlobalPtr ) { + setGlobalState( NULL ); JNIGlobalState* globalState = (JNIGlobalState*)jniGlobalPtr; #ifdef MEM_DEBUG MemPoolCtx* mpool = GETMPOOL( globalState );