Call dropped/rejected when answering from notification

rodrigomonelos commented 6 years ago

See video: https://photos.app.goo.gl/t92LHQAiGwWkZJn52

gmarcos87 commented 6 years ago

What is your scenario? The app was closed or minimized? Is the version of pearlcel.webph.one or some other test?

rodrigomonelos commented 6 years ago

In this case the app was minimized. I can test later with the app closed. This is the PearlCel version.

El 27 nov. 2017 3:48 p. m., "Marcos Gutierrez" notifications@github.com escribió:

What is your scenario? The app was closed or minimized? Is the version of pearlcel.webph.one or some other test?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/saycel/webph.one/issues/143#issuecomment-347304655, or mute the thread https://github.com/notifications/unsubscribe-auth/AZmH3haY1A4fL9ZRKq_OZIRP9GRKsziTks5s6xH5gaJpZM4QsGhH .

gmarcos87 commented 6 years ago

Hi, there I was trying to understand why the behavior change. What I notice is that before when the user registered in Kamailio there was an incoming call the system notified it. Now if there is a call in progress prior to the user's registration, the frontend does not receive it. Has any configuration changed in the backend related to this? @sanchi

sanchi commented 6 years ago

duplicate of #129 ?

sanchi commented 6 years ago

@gmarcos87 this has not changed. But I have added something so that if there's a call in progress and the app re-registers its contact it gets the call again (which it should have already got)

rodrigomonelos commented 6 years ago

@gmarcos87 I tested now with the app closed. The behaviour is different but also a bug. In this case, with the app closed, the call is not accepted nor rejected when tapping on the answer button. See the video in the link: https://photos.app.goo.gl/2eOuxFticNNxL43s1

rodrigomonelos commented 6 years ago

Does someone has or expects to have a clue about how to move on?

rodrigomonelos commented 6 years ago

I ran the test after initiating the log in kamailio but I do not know if this created any log. Did it?. This is the info in my terminal

root@rhizortc:~# kamailio-trace running tail -f /var/log/daemon.log > kamailio_log_2017-12-01-14_52_19.txt packet_write_wait: Connection to 138.68.99.252 port 22: Broken pipe

The test was with the app closed, and now the call is not dropped nor accepted when I tap on both the answe and the reject buttons, it just does nothing.

I will look later how to log with logcat and let you know.

sanchi commented 6 years ago

On 1 Dec 2017 3:59 p.m., "rodrigomonelos" notifications@github.com wrote:

I ran the test after initiating the log in kamailio but I do not know if this created any log. Did it?. This is the info in my terminal

root@rhizortc:~# kamailio-trace running tail -f /var/log/daemon.log > kamailio_log_2017-12-01-14_52_19.txt

You can see the result in this file (kamailiolog...)

packet_write_wait: Connection to 138.68.99.252 port 22: Broken pipe

Huh? Did your internet connection break?

Stefan

The test was with the app closed, and now the call is not dropped nor accepted when I tap on both the answe and the reject buttons, it just does nothing.

I will look later how to log with logcat and let you know.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/saycel/webph.one/issues/143#issuecomment-348516210, or mute the thread https://github.com/notifications/unsubscribe-auth/AACwrYEmNn9e7Z1sdLzPQCJfcdVnkYtTks5s8BRMgaJpZM4QsGhH .

rodrigomonelos commented 6 years ago

I did 5 tests of trying to answer a call from the notification, 3 with the app closed and 2 with the app in background. In none of them I could get the expecting result of connecting the call.

Following you will find my report of each test. I recorded the local time that I think will be useful to match each report with the logs on the server, and for most of the cases I captured the screens on the phone and the log from aLogcat.

Test 1

Local time: 19:07 Description: Call to app in background. I get notification and answer but the app opens and doesn't connect, just shows the tabs. On the caller side I get the "Sorry... " message. In this first case I didn't recorded the screen. aLogcat: --------- beginning of main I/art (21975): CollectorTransition marksweep + semispace GC freed 385(-34KB) AllocSpace objects, 0(0B) LOS objects, 24% free, 7MB/9MB, paused 15.725ms total 15.725ms I/art (21975): CollectorTransition marksweep + semispace GC freed 271(-39KB) AllocSpace objects, 0(0B) LOS objects, 24% free, 7MB/9MB, paused 17.917ms total 17.917ms I/art (21975): CollectorTransition marksweep + semispace GC freed 299(-37KB) AllocSpace objects, 0(0B) LOS objects, 25% free, 7MB/9MB, paused 54.913ms total 54.913ms I/art (21975): CollectorTransition marksweep + semispace GC freed 1197(9KB) AllocSpace objects, 0(0B) LOS objects, 24% free, 7MB/9MB, paused 20.104ms total 20.104ms I/WebViewFactory(21975): Loading com.google.android.webview version 61.0.3163.98 (code 316309800) I/art (21975): Rejecting re-init on previously-failed class java.lang.Class I/art (21975): Rejecting re-init on previously-failed class java.lang.Class I/art (21975): Rejecting re-init on previously-failed class java.lang.Class I/art (21975): Rejecting re-init on previously-failed class java.lang.Class I/cr_LibraryLoader(21975): Time to load native libraries: 4 ms (timestamps 3524-3528) I/chromium(21975): [INFO:library_loader_hooks.cc(136)] Chromium logging enabled: level = 0, default verbosity = 0 I/cr_LibraryLoader(21975): Expected native library version number "61.0.3163.98", actual native library version number "61.0.3163.98" I/cr_BrowserStartup(21975): Initializing chromium process, singleProcess=true I/Adreno-EGL(21975): : EGL 1.4 QUALCOMM build: (Ifd751822f5) I/Adreno-EGL(21975): OpenGL ES Shader Compiler Version: XE031.06.00.05 I/Adreno-EGL(21975): Build Date: 01/26/16 Tue I/Adreno-EGL(21975): Local Branch: AU12_SBA I/Adreno-EGL(21975): Remote Branch: I/Adreno-EGL(21975): Local Patches: I/Adreno-EGL(21975): Reconstruct Branch: W/cr_CrashFileManager(21975): /data/user/0/org.jtb.alogcat/cache/WebView/Crash Reports does not exist or is not a directory

Test 2

Local time: 19:12 Description: Call to app closed. App opens after answering from the notification and shows again options to accept or reject an incoming call. After accepting the call is terminated. In the caller side I got the after call survey, so I do not know why it dropped. Screen capture: https://photos.app.goo.gl/GnVARuiAIcfI8i3k2 aLogcat: --------- beginning of main W/System (24868): ClassLoader referenced unknown path: /data/app/org.jtb.alogcat-1/lib/arm I/WebViewFactory(24868): Loading com.google.android.webview version 61.0.3163.98 (code 316309800) I/art (24868): Rejecting re-init on previously-failed class java.lang.Class I/art (24868): Rejecting re-init on previously-failed class java.lang.Class I/art (24868): Rejecting re-init on previously-failed class java.lang.Class I/art (24868): Rejecting re-init on previously-failed class java.lang.Class I/cr_LibraryLoader(24868): Time to load native libraries: 2 ms (timestamps 8731-8733) I/chromium(24868): [INFO:library_loader_hooks.cc(136)] Chromium logging enabled: level = 0, default verbosity = 0 I/cr_LibraryLoader(24868): Expected native library version number "61.0.3163.98", actual native library version number "61.0.3163.98" I/cr_BrowserStartup(24868): Initializing chromium process, singleProcess=true I/Adreno-EGL(24868): : EGL 1.4 QUALCOMM build: (Ifd751822f5) I/Adreno-EGL(24868): OpenGL ES Shader Compiler Version: XE031.06.00.05 I/Adreno-EGL(24868): Build Date: 01/26/16 Tue I/Adreno-EGL(24868): Local Branch: AU12_SBA I/Adreno-EGL(24868): Remote Branch: I/Adreno-EGL(24868): Local Patches: I/Adreno-EGL(24868): Reconstruct Branch: W/cr_CrashFileManager(24868): /data/user/0/org.jtb.alogcat/cache/WebView/Crash Reports does not exist or is not a directory W/InputEventReceiver(24868): Attempted to finish an input event but the input event receiver has already been disposed.

Test 3

Local time: 19:21 Description: App in background again. The notification never got to the app. Screen capture: https://photos.app.goo.gl/5tBwczDbqxJLh7G33 aLogcat: None

Test 4

Local time: 19:26 Description: App closed. Call dropped after accepting. Maybe because I sliced the notifications. Will check again on test 5 without doing that. Not getting good logs on the phone. Screen capture: https://photos.app.goo.gl/7ZaThpTPZInaPJY62 aLogcat: --------- beginning of main I/art (26814): CollectorTransition marksweep + semispace GC freed 1510(-68KB) AllocSpace objects, 0(0B) LOS objects, 24% free, 8MB/10MB, paused 525.592ms total 525.592ms I/Choreographer(26814): Skipped 31 frames! The application may be doing too much work on its main thread. W/InputEventReceiver(26814): Attempted to finish an input event but the input event receiver has already been disposed.

Test 5

Local time: 19:29 Description: App closed. App opened but call was not rejected nor answered, and there weren't options for that, just the app. Screen capture: https://photos.app.goo.gl/PeVu0sohItvFHJSY2 aLogcat: --------- beginning of main W/System (30149): ClassLoader referenced unknown path: /data/app/org.jtb.alogcat-1/lib/arm I/WebViewFactory(30149): Loading com.google.android.webview version 61.0.3163.98 (code 316309800) I/art (30149): Rejecting re-init on previously-failed class java.lang.Class I/art (30149): Rejecting re-init on previously-failed class java.lang.Class I/art (30149): Rejecting re-init on previously-failed class java.lang.Class I/art (30149): Rejecting re-init on previously-failed class java.lang.Class I/cr_LibraryLoader(30149): Time to load native libraries: 1 ms (timestamps 2029-2030) I/chromium(30149): [INFO:library_loader_hooks.cc(136)] Chromium logging enabled: level = 0, default verbosity = 0 I/cr_LibraryLoader(30149): Expected native library version number "61.0.3163.98", actual native library version number "61.0.3163.98" I/cr_BrowserStartup(30149): Initializing chromium process, singleProcess=true I/Adreno-EGL(30149): : EGL 1.4 QUALCOMM build: (Ifd751822f5) I/Adreno-EGL(30149): OpenGL ES Shader Compiler Version: XE031.06.00.05 I/Adreno-EGL(30149): Build Date: 01/26/16 Tue I/Adreno-EGL(30149): Local Branch: AU12_SBA I/Adreno-EGL(30149): Remote Branch: I/Adreno-EGL(30149): Local Patches: I/Adreno-EGL(30149): Reconstruct Branch: I/Choreographer(30149): Skipped 53 frames! The application may be doing too much work on its main thread. W/cr_CrashFileManager(30149): /data/user/0/org.jtb.alogcat/cache/WebView/Crash Reports does not exist or is not a directory W/InputEventReceiver(30149): Attempted to finish an input event but the input event receiver has already been disposed. I/art (30149): CollectorTransition marksweep + semispace GC freed 1886(-17KB) AllocSpace objects, 1(24KB) LOS objects, 24% free, 8MB/10MB, paused 136.797ms total 136.797ms

sanchi commented 6 years ago

these logs don't seem to me to say very much.

but after analysing lots of the logs I found an issue on Test number 5 - when the server would store a transaction after having failed to send the INVITE out on a not-anymore-existing connection, it would use the wrong user. I've fixed this (with [master 5a84f07] b/f:cfg:use correct callee when storing transaction after failed t_relay) and reloaded the config.

Test1 - 23:06:23 push notification sent 23:06:51 register comes in 23:06:52 408 timeout sent
Test 2 - 23:12:05 callid 6bq4pdhgsi33fdd1n4jf 99910076953 to 99910064096 23:12:06 push notification sent 23:12:32 register from 99910064096 23:12:32 another push notification sent 23:12:33 ringing 23:12:35 200 OK 23:12:35 received BYE from App
Test 3: 23:21:52 INVITE 23:21:52 push notification sent 23:22:22 408 timeout
Test 4: can't find it. there's one call with timeout
Test 5: 23:29:46 INVITE 23:29:47 pn sent 23:30:06 register *** no INVITE from stored transaction sent out!

gmarcos87 commented 6 years ago

Ok, I was doing some tests too.

1 - App to app open (works) 2 - App to app minimized (works / low battery not work) 3 - App closed (Notification works, open and register but never get the call from jssip) 4 - App to app already open in test 3 - Nothing happen, app not get any log from jssip) 5 - Same app to 500 - Works! 6 - App to app open in test 3 - Now work!

In spite of being the registered user in jssip (test 3) the connection was not works until the user makes a call.

In the SMS tests @rodrigomonelos reported on #122 something similar, having to make a call for the messages to begin to enter.

rodrigomonelos commented 6 years ago

I did new tests and logged them, you can find them below. But first I will comment on Marcos results: I had similar results:

in the beggining couldn't receive a notification with the app closed (test 6) nor in background (test 7).
App open works fine
Had to receive a call with the app open (test 8) to start receiving notifications (tests 9, 10 and 11).

Differences in my results are:

Once I started receiving notifications (test 8), I could not connect the call whith the app minimized (number 2 for Marcos, tested twice on 9 and 11 for me)
Also once I started receiving notifications (test 8), I did received and connected the call while having the app closed (test 10 for me, 3 for Marcos).

So @gmarcos87, what do you suggest we to do based on this results. Is it clear for you what has to be fixed and by who? Or where and how should we keep looking...

Also, do you think that if I use the remote-debugging tools that you suggested to Stefan we will get better information than now with aLogcat?

My tests reports are

Test 6

Local time: 11:02 Description: App closed. No incoming notification. Rings until "Sorry..." message. Screen capture: has no value, nothing happened on the phone.

--------- beginning of main W/System (28353): ClassLoader referenced unknown path: /data/app/org.jtb.alogcat-1/lib/arm I/WebViewFactory(28353): Loading com.google.android.webview version 61.0.3163.98 (code 316309800) I/art (28353): Rejecting re-init on previously-failed class java.lang.Class I/art (28353): Rejecting re-init on previously-failed class java.lang.Class I/art (28353): Rejecting re-init on previously-failed class java.lang.Class I/art (28353): Rejecting re-init on previously-failed class java.lang.Class I/cr_LibraryLoader(28353): Time to load native libraries: 1 ms (timestamps 7674-7675) I/chromium(28353): [INFO:library_loader_hooks.cc(136)] Chromium logging enabled: level = 0, default verbosity = 0 I/cr_LibraryLoader(28353): Expected native library version number "61.0.3163.98", actual native library version number "61.0.3163.98" I/cr_BrowserStartup(28353): Initializing chromium process, singleProcess=true I/Adreno-EGL(28353): : EGL 1.4 QUALCOMM build: (Ifd751822f5) I/Adreno-EGL(28353): OpenGL ES Shader Compiler Version: XE031.06.00.05 I/Adreno-EGL(28353): Build Date: 01/26/16 Tue I/Adreno-EGL(28353): Local Branch: AU12_SBA I/Adreno-EGL(28353): Remote Branch: I/Adreno-EGL(28353): Local Patches: I/Adreno-EGL(28353): Reconstruct Branch: W/cr_CrashFileManager(28353): /data/user/0/org.jtb.alogcat/cache/WebView/Crash Reports does not exist or is not a directory

Test 7

Local time: 11:08 Description: Opened the app and sent it to background. Same result than test 6. Rings on caller until "Sorry..." message, no activity on receiver. Screen capture: has no value, nothing happened on the phone.

--------- beginning of main I/art (28353): CollectorTransition marksweep + semispace GC freed 1813(4KB) AllocSpace objects, 1(20KB) LOS objects, 25% free, 8MB/10MB, paused 50.750ms total 50.750ms I/art (28353): CollectorTransition marksweep + semispace GC freed 1048(-84KB) AllocSpace objects, 1(24KB) LOS objects, 24% free, 8MB/10MB, paused 27.191ms total 27.191ms

Test 8

Local time: 11:20 Description: App in foreground: call is received, answered and connected as usual. Screen capture: Just the expected.

--------- beginning of main I/art (28353): CollectorTransition marksweep + semispace GC freed 1670(-26KB) AllocSpace objects, 1(20KB) LOS objects, 25% free, 8MB/10MB, paused 41.891ms total 41.891ms I/art (28353): CollectorTransition marksweep + semispace GC freed 506(-102KB) AllocSpace objects, 1(24KB) LOS objects, 25% free, 8MB/10MB, paused 33.650ms total 33.650ms W/InputEventReceiver(28353): Attempted to finish an input event but the input event receiver has already been disposed.

Test 9

Local time: 11:26 Description: I went from closed to background to foreground on the app. Just got the call when got up to foreground Now back to background and I do get the call, so my impression is that it was necessary to receive a call in foreground to start receiving calls with the app in background or closed. Got the notification and tapped anser, the app started to come to foreground (but with the splash screen, like if it was opening) and the call got terminated once the app ended loading. I didn't even sliced the notifications slider that was open after answering the notification. Strange that I got the "after call survey" screen on the app, while I had the "Sorry..." message on the caller. For this test I changed on aLogcat and chose "Format: raw". Let me know if you consider this is better. Other options I could try are brief, process, tag, thread, thread time, time and long. Screen capture: https://photos.app.goo.gl/EDUOjOlvymqWduXM2

--------- beginning of main CollectorTransition marksweep + semispace GC freed 2653(60KB) AllocSpace objects, 0(0B) LOS objects, 25% free, 7MB/9MB, paused 31.012ms total 31.012ms Loading com.google.android.webview version 61.0.3163.98 (code 316309800) Rejecting re-init on previously-failed class java.lang.Class Rejecting re-init on previously-failed class java.lang.Class Rejecting re-init on previously-failed class java.lang.Class Rejecting re-init on previously-failed class java.lang.Class Time to load native libraries: 1 ms (timestamps 7619-7620) [INFO:library_loader_hooks.cc(136)] Chromium logging enabled: level = 0, default verbosity = 0 Expected native library version number "61.0.3163.98", actual native library version number "61.0.3163.98" Initializing chromium process, singleProcess=true

: EGL 1.4 QUALCOMM build: (Ifd751822f5) OpenGL ES Shader Compiler Version: XE031.06.00.05 Build Date: 01/26/16 Tue Local Branch: AU12_SBA Remote Branch: Local Patches: Reconstruct Branch: /data/user/0/org.jtb.alogcat/cache/WebView/Crash Reports does not exist or is not a directory ### Test 10 **Local time:** 11:39 **Description:** App closed. Notification without sound. After tapping anser call established ok. **Screen capture:** https://photos.app.goo.gl/szeDZWvoOARWCCDn2 --------- beginning of main [ 12-02 11:42:00.754 450: 466 I/art ] CollectorTransition marksweep + semispace GC freed 2514(-10KB) AllocSpace objects, 1(20KB) LOS objects, 24% free, 8MB/10MB, paused 203.216ms total 203.216ms [ 12-02 11:42:57.660 450: 466 I/art ] CollectorTransition marksweep + semispace GC freed 569(-121KB) AllocSpace objects, 1(24KB) LOS objects, 24% free, 8MB/10MB, paused 29.031ms total 29.031ms ### Test 11 **Local time:** 11:45 **Description:** Back to background. Get the ringing but call is dropped when app opens (similar to test 9) **Screen capture:** https://photos.app.goo.gl/oZgwcerivkisGtDi2 --------- beginning of main [ 12-02 11:44:24.659 450: 450 W/InputEventReceiver ] Attempted to finish an input event but the input event receiver has already been disposed. [ 12-02 11:47:25.510 450: 466 I/art ] CollectorTransition marksweep + semispace GC freed 2060(-45KB) AllocSpace objects, 1(20KB) LOS objects, 24% free, 8MB/10MB, paused 64.169ms total 64.169ms

saycel / webph.one