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.
This commit is contained in:
Eric House 2020-04-17 16:45:03 -07:00
parent 36bf92e8e5
commit cfa9b73833
10 changed files with 400 additions and 21 deletions

View file

@ -51,6 +51,7 @@ public class DlgDelegate {
DWNLD_LOC_DICT,
NEW_GAME_DFLT_NAME,
SEND_EMAIL,
CLEAR_LOG_DB,
// BoardDelegate
UNDO_LAST_ACTION,

View file

@ -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() );

View file

@ -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<Context> 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;
}
}
}

View file

@ -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 );
}

View file

@ -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="

View file

@ -122,4 +122,16 @@
android:title="@string/gamel_menu_writegit"
/>
<item android:id="@+id/games_menu_enableLogStorage"
android:title="@string/gamel_menu_logstore_on"
/>
<item android:id="@+id/games_menu_disableLogStorage"
android:title="@string/gamel_menu_logstore_off"
/>
<item android:id="@+id/games_menu_dumpLogStorage"
android:title="@string/gamel_menu_logstore_dump"
/>
<item android:id="@+id/games_menu_clearLogStorage"
android:title="@string/gamel_menu_logstore_clear"
/>
</menu>

View file

@ -2519,4 +2519,20 @@
<string name="history_pause_fmt">Paused by: %1$s.</string>
<string name="history_msg_fmt"> Message: %1$s.</string>
<string name="history_autopause">Auto-paused.</string>
<!-- Debug-build-only menu to turn on saving of logs -->
<string name="gamel_menu_logstore_on">Enable log storage</string>
<!-- Debug-build-only menu to turn off saving of logs -->
<string name="gamel_menu_logstore_off">Diable log storage</string>
<!-- Debug-build-only menu to clear/delete saved logs -->
<string name="gamel_menu_logstore_clear">Clear stored logs</string>
<!-- Debug-build-only menu to write saved logs to a world-readable file -->
<string name="gamel_menu_logstore_dump">Write stored logs to file</string>
<!-- Debug-build-only status message shown after logs successfully written to file -->
<string name="logstore_dumped_fmt">Logs written to file %1$s</string>
<!-- Debug-build-only status message shown after logs successfully cleared -->
<string name="logstore_cleared_fmt">%1$d log entries deleted</string>
<!-- Debug-build-only question asked to confirm deletion of saved logs -->
<string name="logstore_clear_confirm">Are you sure you want to
erase your debug logs? This action cannot be undone.</string>
</resources>

View file

@ -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

View file

@ -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

View file

@ -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 );