Skip to content

Commit e4d8d9e

Browse files
rosen-vladimirovrosen-vladimirov
committed
fix: missing logs when __enableVerboseLogging is called
When you call `__enableVerboseLogging()` in your application, runtimes print more messages, which could be used for identifying issues. In the official version, when you enable this logging in your app, you see some messages in CLI's output of `tns run` command. However, this has been working by mistake for Android as CLI does not expect to show these messages, as their category is `TNS.Native` or `TNS.Java`. As CLI does not match these categories, it check if the message contains any of the supported categories. Some of the messages have `JS` in the strings, for example: ``` 02-04 15:54:55.101 6047 6047 D TNS.Java: Platform.CallJSMethod: calling js method onActivityStarted with javaObjectID 1 type=com.tns.gen.android.app.Application_ActivityLifecycleCallbacks 02-04 15:54:55.101 6047 6047 D TNS.Native: CallJSMethodNative called javaObjectID=1 ``` This led to CLI showing the messages. After fixing CLI to show only the supported categories (in a previous commit), CLI no longer shows these messages. To show them, add `TNS.Native` and `TNS.Java` categories to supported ones. Of course, this leads to another issue - during start of application (init of Android Runtime), the verbose logging is enabled by default and now we always show messages: ``` 07-25 06:36:38.400 3714 3714 I TNS.Native: NativeScript Runtime Version 5.1.0, commit 4497f43b69cb57ce65ece2aac5b98b2010f85857 07-25 06:36:38.406 8183 8183 D TNS.Native: JNI_ONLoad 07-25 06:36:38.408 8183 8183 D TNS.Native: JNI_ONLoad END 07-25 06:36:38.534 8183 8183 D TNS.Native: V8 version 6.9.427.23 07-25 06:36:38.675 8183 8183 D TNS.Native: lenNodes=66492, lenNames=775380, lenValues=899324 07-25 06:36:38.675 8183 8183 D TNS.Native: time=24 ``` As these messages are printed on every Android Runtime Initialization, we do not want to flood the output in CLI. So, we'll introduce a new category in the Android Runtime Logging - `TNS.Runtime`. We need it to print the mentioned messages, as there's no way to enable the verboseLogging before initializing the runtime. CLI will filter these messages and will not show them.
1 parent 1a08b52 commit e4d8d9e

File tree

2 files changed

+52
-24
lines changed

2 files changed

+52
-24
lines changed

‎lib/common/mobile/android/android-log-filter.ts

+2-1
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,8 @@ export class AndroidLogFilter implements Mobile.IPlatformLogFilter {
3535
return null;
3636
}
3737

38-
const acceptedTags = ["chromium", "Web Console", "JS", "ActivityManager", "System.err"];
38+
// Messages with category TNS.Native and TNS.Java will be printed by runtime to Logcat only when `__enableVerboseLogging()` is called in the application.
39+
const acceptedTags = ["chromium", "Web Console", "JS", "ActivityManager", "System.err", "TNS.Native", "TNS.Java"];
3940

4041
let consoleLogMessage: { tag?: string, message: string };
4142

‎lib/common/test/unit-tests/android-log-filter.ts

+50-23
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@ const androidApiLevel23TestData = [
2828
output: 'chromium: [INFO:CONSOLE(1)] "Uncaught ReferenceError: start is not defined", source: file:///data/user/0/com.telerik.app1/files/12590FAA-5EDD-4B12-856D-F52A0A1599F2/index.html (1)'
2929
},
3030
{ input: '12-28 10:16:49.267 779 1172 I ActivityManager: Start proc 3714:org.nativescript.appDebug1/u0a60 for activity org.nativescript.appDebug1/com.tns.NativeScriptActivity', output: 'ActivityManager: Start proc 3714:org.nativescript.appDebug1/u0a60 for activity org.nativescript.appDebug1/com.tns.NativeScriptActivity' },
31-
{ input: '12-28 10:16:49.316 3714 3714 I TNS.Native: NativeScript Runtime Version 1.5.1, commit c27e977f059e37b3f8230722a4687e16acf43a7f', output: null },
31+
{ input: '12-28 10:16:49.316 3714 3714 I TNS.Runtime: NativeScript Runtime Version 1.5.1, commit c27e977f059e37b3f8230722a4687e16acf43a7f', output: null },
3232
{ input: '12-28 10:16:49.710 3714 3714 V JS : TAPPED: 42', output: 'JS: TAPPED: 42' },
3333
{ input: '12-28 10:16:49.775 3714 3714 D NativeScriptActivity: NativeScriptActivity.onCreate called', output: null },
3434
{
@@ -90,12 +90,12 @@ const androidApiLevel22TestData = [
9090
input: 'I/Web Console( 4438): Received Event: deviceready at file:///storage/emulated/0/Icenium/com.telerik.TestApp/js/index.js:48',
9191
output: 'Web Console: Received Event: deviceready at file:///storage/emulated/0/Icenium/com.telerik.TestApp/js/index.js:48'
9292
},
93-
{ input: "I/TNS.Native( 4502): NativeScript Runtime Version 5.1.0, commit 4497f43b69cb57ce65ece2aac5b98b2010f85857", output: null },
94-
{ input: "D/TNS.Native( 4502): JNI_ONLoad", output: null },
95-
{ input: "D/TNS.Native( 4502): JNI_ONLoad END", output: null },
96-
{ input: "D/TNS.Native( 4502): V8 version 6.9.427.23", output: null },
97-
{ input: "D/TNS.Native( 4502): lenNodes=79716, lenNames=901566, lenValues=1062800", output: null },
98-
{ input: "D/TNS.Native( 4502): time=1", output: null },
93+
{ input: "I/TNS.Runtime( 4502): NativeScript Runtime Version 5.1.0, commit 4497f43b69cb57ce65ece2aac5b98b2010f85857", output: null },
94+
{ input: "D/TNS.Runtime( 4502): JNI_ONLoad", output: null },
95+
{ input: "D/TNS.Runtime( 4502): JNI_ONLoad END", output: null },
96+
{ input: "D/TNS.Runtime( 4502): V8 version 6.9.427.23", output: null },
97+
{ input: "D/TNS.Native( 4502): lenNodes=79716, lenNames=901566, lenValues=1062800", output: "TNS.Native: lenNodes=79716, lenNames=901566, lenValues=1062800" },
98+
{ input: "D/TNS.Native( 4502): time=1", output: "TNS.Native: time=1" },
9999
{ input: "W/art ( 4502): Before Android 4.1, method android.graphics.PorterDuffColorFilter android.support.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable", output: null },
100100
{ input: "I/art ( 4502): Rejecting re-init on previously-failed class java.lang.Class<android.support.v4.view.ViewCompat$OnUnhandledKeyEventListenerWrapper>", output: null },
101101
{ input: "I/art ( 4502): Rejecting re-init on previously-failed class java.lang.Class<android.support.v4.view.ViewCompat$OnUnhandledKeyEventListenerWrapper>", output: null },
@@ -116,8 +116,8 @@ const androidApiLevel22TestData = [
116116

117117
const androidApiLevel23MapForPid8141 = [
118118
{ input: "--------- of main", output: null },
119-
{ input: "07-25 06:36:22.590 8141 8141 D TNS.Native: lenNodes=71568, lenNames=824195, lenValues=963214", output: null },
120-
{ input: "07-25 06:36:22.590 8141 8141 D TNS.Native: time=1", output: null },
119+
{ input: "07-25 06:36:22.590 8141 8141 D TNS.Native: lenNodes=71568, lenNames=824195, lenValues=963214", output: "TNS.Native: lenNodes=71568, lenNames=824195, lenValues=963214" },
120+
{ input: "07-25 06:36:22.590 8141 8141 D TNS.Native: time=1", output: "TNS.Native: time=1" },
121121
{ input: "07-25 06:36:23.065 739 760 I Choreographer: Skipped 54 frames! The application may be doing too much work on its main thread.", output: null },
122122
{ input: "07-25 06:36:23.149 8141 8141 W art : Before Android 4.1, method android.graphics.PorterDuffColorFilter android.support.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable", output: null },
123123
{ input: "07-25 06:36:23.298 8141 8141 D : HostConnection::get() New Host Connection established 0xd3916970, tid 8141", output: null },
@@ -143,11 +143,11 @@ const androidApiLevel23MapForPid8141 = [
143143
{ input: "07-25 06:36:38.327 8183 8183 I art : Late-enabling -Xcheck:jni", output: null },
144144
{ input: "07-25 06:36:38.327 8183 8183 W art : Unexpected CPU variant for X86 using defaults: x86", output: null },
145145
{ input: "07-25 06:36:38.335 739 1212 I ActivityManager: Start proc 8183:org.nativescript.a2test/u0a122 for activity org.nativescript.a2test/com.tns.NativeScriptActivity", output: null },
146-
{ input: "07-25 06:36:38.406 8183 8183 I TNS.Native: NativeScript Runtime Version 3.0.1, commit 733bfa5fab5d4c156eab156eaf01946eb36dab1e", output: null },
147-
{ input: "07-25 06:36:38.406 8183 8183 D TNS.Native: JNI_ONLoad", output: null },
148-
{ input: "07-25 06:36:38.406 8183 8183 D TNS.Native: JNI_ONLoad END", output: null },
149-
{ input: "07-25 06:36:38.424 8183 8183 D TNS.Native: Failed to load snapshot: dlopen failed: library \"libsnapshot.so\" not found", output: null },
150-
{ input: "07-25 06:36:38.534 8183 8183 D TNS.Native: V8 version 5.5.372.32", output: null },
146+
{ input: "07-25 06:36:38.406 8183 8183 I TNS.Runtime: NativeScript Runtime Version 3.0.1, commit 733bfa5fab5d4c156eab156eaf01946eb36dab1e", output: null },
147+
{ input: "07-25 06:36:38.406 8183 8183 D TNS.Runtime: JNI_ONLoad", output: null },
148+
{ input: "07-25 06:36:38.406 8183 8183 D TNS.Runtime: JNI_ONLoad END", output: null },
149+
{ input: "07-25 06:36:38.424 8183 8183 D TNS.Runtime: Failed to load snapshot: dlopen failed: library \"libsnapshot.so\" not found", output: null },
150+
{ input: "07-25 06:36:38.534 8183 8183 D TNS.Runtime: V8 version 5.5.372.32", output: null },
151151
{ input: "07-25 06:36:38.675 8183 8183 D TNS.Native: lenNodes=66492, lenNames=775380, lenValues=899324", output: null },
152152
{ input: "07-25 06:36:38.675 8183 8183 D TNS.Native: time=24", output: null },
153153
{ input: "07-25 06:36:39.376 739 760 I Choreographer: Skipped 55 frames! The application may be doing too much work on its main thread.", output: null },
@@ -222,17 +222,17 @@ const androidApiLevel23MapForPid8141 = [
222222
{ input: "07-25 06:37:05.084 739 751 I ActivityManager: Start proc 8244:org.nativescript.personalalarm/u0a64 for activity org.nativescript.personalalarm/com.tns.ErrorReportActivity", output: null },
223223
{ input: "07-25 06:37:05.084 8244 8244 I art : Late-enabling -Xcheck:jni", output: null },
224224
{ input: "07-25 06:37:05.085 8244 8244 W art : Unexpected CPU variant for X86 using defaults: x86", output: null },
225-
{ input: "07-25 06:37:05.212 8244 8244 I TNS.Native: NativeScript Runtime Version 3.1.1, commit 253c76f850b88b0119fda04e413626872f223de5", output: null },
226-
{ input: "07-25 06:37:05.213 8244 8244 D TNS.Native: JNI_ONLoad", output: null },
227-
{ input: "07-25 06:37:05.213 8244 8244 D TNS.Native: JNI_ONLoad END", output: null },
228-
{ input: "02-01 13:29:22.990 8141 8141 I TNS.Native: NativeScript Runtime Version 5.1.0, commit 4497f43b69cb57ce65ece2aac5b98b2010f85857", output: null },
229-
{ input: "02-01 13:29:22.991 8141 8141 D TNS.Native: JNI_ONLoad", output: null },
230-
{ input: "02-01 13:29:22.991 8141 8141 D TNS.Native: JNI_ONLoad END", output: null },
225+
{ input: "07-25 06:37:05.212 8244 8244 I TNS.Runtime: NativeScript Runtime Version 3.1.1, commit 253c76f850b88b0119fda04e413626872f223de5", output: null },
226+
{ input: "07-25 06:37:05.213 8244 8244 D TNS.Runtime: JNI_ONLoad", output: null },
227+
{ input: "07-25 06:37:05.213 8244 8244 D TNS.Runtime: JNI_ONLoad END", output: null },
228+
{ input: "02-01 13:29:22.990 8141 8141 I TNS.Runtime: NativeScript Runtime Version 5.1.0, commit 4497f43b69cb57ce65ece2aac5b98b2010f85857", output: null },
229+
{ input: "02-01 13:29:22.991 8141 8141 D TNS.Runtime: JNI_ONLoad", output: null },
230+
{ input: "02-01 13:29:22.991 8141 8141 D TNS.Runtime: JNI_ONLoad END", output: null },
231231
{ input: "02-01 13:29:23.027 1344 1351 D gralloc_ranchu: gralloc_alloc: Creating ashmem region of size 8294400", output: null },
232232
{ input: "02-01 13:29:23.043 1652 1661 I art : Background partial concurrent mark sweep GC freed 975(53KB) AllocSpace objects, 0(0B) LOS objects, 17% free, 18MB/22MB, paused 4.347ms total 122.768ms", output: null },
233-
{ input: "02-01 13:29:23.061 8141 8141 D TNS.Native: V8 version 6.9.427.23", output: null },
234-
{ input: "02-01 13:29:23.067 8141 8141 D TNS.Native: lenNodes=79716, lenNames=901564, lenValues=1062800", output: null },
235-
{ input: "02-01 13:29:23.067 8141 8141 D TNS.Native: time=2", output: null },
233+
{ input: "02-01 13:29:23.061 8141 8141 D TNS.Runtime: V8 version 6.9.427.23", output: null },
234+
{ input: "02-01 13:29:23.067 8141 8141 D TNS.Native: lenNodes=79716, lenNames=901564, lenValues=1062800", output: "TNS.Native: lenNodes=79716, lenNames=901564, lenValues=1062800" },
235+
{ input: "02-01 13:29:23.067 8141 8141 D TNS.Native: time=2", output: "TNS.Native: time=2" },
236236
{ input: "02-01 13:29:23.155 2288 2390 D EGL_emulation: eglMakeCurrent: 0xa037ba00: ver 2 0 (tinfo 0x92b47100)", output: null },
237237
{ input: "02-01 13:29:23.450 8141 8141 W art : Before Android 4.1, method android.graphics.PorterDuffColorFilter android.support.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable", output: null },
238238
{ input: "02-01 13:29:23.576 8141 4663 I art : Background sticky concurrent mark sweep GC freed 20657(1509KB) AllocSpace objects, 7(140KB) LOS objects, 0% free, 11MB/11MB, paused 12.708ms total 102.843ms", output: null },
@@ -289,6 +289,33 @@ const androidApiLevel23MapForPid8141 = [
289289
{ input: "02-01 13:29:23.994 8141 8141 I art : at java.lang.Object java.lang.reflect.Method.invoke!(java.lang.Object, java.lang.Object[]) (Method.java:-2)", output: null },
290290
{ input: "02-01 13:29:23.994 8141 8141 I art : at void com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run() (ZygoteInit.java:866)", output: null },
291291
{ input: "02-01 13:29:23.994 8141 8141 I art : at void com.android.internal.os.ZygoteInit.main(java.lang.String[]) (ZygoteInit.java:756)", output: null },
292+
{ input: "02-04 15:54:54.440 8141 8141 D TNS.Native: createJSInstanceNative called", output: "TNS.Native: createJSInstanceNative called" },
293+
{ input: "02-04 15:54:54.440 8141 8141 D TNS.Native: createJSInstanceNative class com/tns/NativeScriptActivity", output: "TNS.Native: createJSInstanceNative class com/tns/NativeScriptActivity" },
294+
{ input: "02-04 15:54:54.440 8141 8141 D TNS.Native: createJSInstanceNative: implementationObject :82225", output: "TNS.Native: createJSInstanceNative: implementationObject :82225" },
295+
{ input: "02-04 15:54:54.440 8141 8141 D TNS.Java: JSInstance for class com.tns.NativeScriptActivity created with overrides", output: "TNS.Java: JSInstance for class com.tns.NativeScriptActivity created with overrides" },
296+
{ input: "02-04 15:54:54.448 8141 8141 D TNS.Java: Platform.CallJSMethod: calling js method onCreate with javaObjectID 3 type=com.tns.NativeScriptActivity", output: "TNS.Java: Platform.CallJSMethod: calling js method onCreate with javaObjectID 3 type=com.tns.NativeScriptActivity" },
297+
{ input: "02-04 15:54:54.449 8141 8141 D TNS.Native: CallJSMethodNative called javaObjectID=3", output: "TNS.Native: CallJSMethodNative called javaObjectID=3" },
298+
{ input: "02-04 15:54:54.449 8141 8141 D TNS.Native: CallJSMethodNative called jsObject=335940", output: "TNS.Native: CallJSMethodNative called jsObject=335940" },
299+
{ input: "02-04 15:54:54.516 8141 8141 D TNS.Java: Platform.CallJSMethod: calling js method onActivityCreated with javaObjectID 1 type=com.tns.gen.android.app.Application_ActivityLifecycleCallbacks", output: "TNS.Java: Platform.CallJSMethod: calling js method onActivityCreated with javaObjectID 1 type=com.tns.gen.android.app.Application_ActivityLifecycleCallbacks" },
300+
{ input: "02-04 15:54:54.516 8141 8141 D TNS.Native: CallJSMethodNative called javaObjectID=1", output: "TNS.Native: CallJSMethodNative called javaObjectID=1" },
301+
{ input: "02-04 15:54:54.516 8141 8141 D TNS.Native: CallJSMethodNative called jsObject=572643", output: "TNS.Native: CallJSMethodNative called jsObject=572643" },
302+
{ input: "02-04 15:54:54.630 8141 8141 D TNS.Native: com.tns.Runtime.callJSMethodNative(Native Method)", output: "TNS.Native: com.tns.Runtime.callJSMethodNative(Native Method)" },
303+
{ input: "02-04 15:54:54.630 8141 8141 D TNS.Native: com.tns.Runtime.dispatchCallJSMethodNative(Runtime.java:1120)", output: "TNS.Native: com.tns.Runtime.dispatchCallJSMethodNative(Runtime.java:1120)" },
304+
{ input: "02-04 15:54:54.630 8141 8141 D TNS.Native: com.tns.Runtime.callJSMethodImpl(Runtime.java:1000)", output: "TNS.Native: com.tns.Runtime.callJSMethodImpl(Runtime.java:1000)" },
305+
{ input: "02-04 15:54:54.630 8141 8141 D TNS.Native: com.tns.Runtime.callJSMethod(Runtime.java:987)", output: "TNS.Native: com.tns.Runtime.callJSMethod(Runtime.java:987)" },
306+
{ input: "02-04 15:54:54.630 8141 8141 D TNS.Native: com.tns.Runtime.callJSMethod(Runtime.java:967)", output: "TNS.Native: com.tns.Runtime.callJSMethod(Runtime.java:967)" },
307+
{ input: "02-04 15:54:54.630 8141 8141 D TNS.Native: com.tns.Runtime.callJSMethod(Runtime.java:959)", output: "TNS.Native: com.tns.Runtime.callJSMethod(Runtime.java:959)" },
308+
{ input: "02-04 15:54:55.100 8141 8141 D TNS.Java: Platform.CallJSMethod: calling js method onStart with javaObjectID 3 type=com.tns.NativeScriptActivity", output: "TNS.Java: Platform.CallJSMethod: calling js method onStart with javaObjectID 3 type=com.tns.NativeScriptActivity" },
309+
{ input: "02-04 15:54:55.100 8141 8141 D TNS.Native: CallJSMethodNative called javaObjectID=3", output: "TNS.Native: CallJSMethodNative called javaObjectID=3" },
310+
{ input: "02-04 15:54:55.100 8141 8141 D TNS.Native: CallJSMethodNative called jsObject=335940", output: "TNS.Native: CallJSMethodNative called jsObject=335940" },
311+
{ input: "02-04 15:54:55.101 8141 8141 D TNS.Java: Platform.CallJSMethod: calling js method onActivityStarted with javaObjectID 1 type=com.tns.gen.android.app.Application_ActivityLifecycleCallbacks", output: "TNS.Java: Platform.CallJSMethod: calling js method onActivityStarted with javaObjectID 1 type=com.tns.gen.android.app.Application_ActivityLifecycleCallbacks" },
312+
{ input: "02-04 15:54:55.101 8141 8141 D TNS.Native: CallJSMethodNative called javaObjectID=1", output: "TNS.Native: CallJSMethodNative called javaObjectID=1" },
313+
{ input: "02-04 15:54:55.101 8141 8141 D TNS.Native: CallJSMethodNative called jsObject=572643", output: "TNS.Native: CallJSMethodNative called jsObject=572643" },
314+
{ input: "02-04 15:54:55.180 8141 8141 D TNS.Java: Platform.CallJSMethod: calling js method onActivityResumed with javaObjectID 1 type=com.tns.gen.android.app.Application_ActivityLifecycleCallbacks", output: "TNS.Java: Platform.CallJSMethod: calling js method onActivityResumed with javaObjectID 1 type=com.tns.gen.android.app.Application_ActivityLifecycleCallbacks" },
315+
{ input: "02-04 15:54:55.180 8141 8141 D TNS.Native: CallJSMethodNative called javaObjectID=1", output: "TNS.Native: CallJSMethodNative called javaObjectID=1" },
316+
{ input: "02-04 15:54:55.180 8141 8141 D TNS.Native: CallJSMethodNative called jsObject=572643", output: "TNS.Native: CallJSMethodNative called jsObject=572643" },
317+
{ input: "02-04 15:54:55.216 8141 8141 D TNS.Java: Platform.CallJSMethod: calling js method onViewAttachedToWindow with javaObjectID 75 type=com.tns.gen.java.lang.Object_frame_29_36_AttachListener", output: "TNS.Java: Platform.CallJSMethod: calling js method onViewAttachedToWindow with javaObjectID 75 type=com.tns.gen.java.lang.Object_frame_29_36_AttachListener" },
318+
{ input: "02-04 15:54:55.216 8141 8141 D TNS.Native: CallJSMethodNative called javaObjectID=75", output: "TNS.Native: CallJSMethodNative called javaObjectID=75" },
292319
];
293320

294321
describe("androidLogFilter", () => {

0 commit comments

Comments
 (0)