Dismiss notification when sharing has stopped

[licaon-kter]

1.5.1 F-Droid

[bilde2910]

Can you describe the issue in more detail?

[licaon-kter]

The sharing has stopped, the notification still lives saying that sharing is active and with "Copy" and "Stop".

[bilde2910]

That's strange, and shouldn't happen. Does the notification always stay behind? It appears as if the system doesn't stop the location service. Would it be possible for you to fetch logs from the app? Fetch the logs with adb logcat -e info.varden.hauk on a connected computer, then reproduce the issue on the device.

[licaon-kter]

FYI, it has stopped since the timer run out, the app was in the background.

I'll see about some logs.

[licaon-kter]

Server/app HEAD(6fa10a14f3e11acbd7474aae9aa8e83922c10575)

Device screen was closed, now I've opened it, sharing has stopped, button says STOP SHARING [0:00], notification still available (un-dismissable!)

Press in-app STOP fixed it.

[bilde2910]

Unable to reproduce this. Could you provide logs from the app?

[licaon-kter]

Hard to do, I'm running a lot of tests.

I'll see about the log if I can repro.

[licaon-kter]

Yet again today, after the share in https://github.com/bilde2910/Hauk/issues/105 ended (see app details there) it said "STOP SHARING [0:00]"

Logcat

 V info.varden.hauk: .service.LocationPushService.onLocationChanged(LocationPushService.java:195): Sending location update packet
V info.varden.hauk: .http.Packet.send(Packet.java:80): Sending packet of type info.varden.hauk.service.LocationPushService$LocationUpdatePacketImpl
V info.varden.hauk: .service.LocationPushService$2.onLocationChanged(LocationPushService.java:145): Location was received on fine location provider
V info.varden.hauk: .service.LocationPushService.onLocationChanged(LocationPushService.java:195): Sending location update packet
V info.varden.hauk: .http.Packet.send(Packet.java:80): Sending packet of type info.varden.hauk.service.LocationPushService$LocationUpdatePacketImpl
I info.varden.hauk: .manager.StopSharingTask.run(StopSharingTask.java:97): Executing share stop task
I info.varden.hauk: .manager.StopSharingTask.run(StopSharingTask.java:99): Stopping location push service
I info.varden.hauk: .manager.StopSharingTask.run(StopSharingTask.java:105): Sending stop packet to server for session Session{serverURL=https://hauk.mydomain.tld/,connParams=ConnectionParameters{proxyType=null,proxyAddress=null,connectTimeout=10000,tlsPolicy=CertificateValidationPolicy{index=0}},backendVersion=1.5.2,sessionID=e368675f9b073060d741ab215b12d0fa91b86521532b3ccbaf78011840138902,expiry=1576329571020,interval=3,e2eParams=null}
V info.varden.hauk: .http.Packet.send(Packet.java:80): Sending packet of type info.varden.hauk.manager.StopSharingTask$1
I info.varden.hauk: .service.LocationPushService.onDestroy(LocationPushService.java:166): Service destroyed; removing updates from fine location provider
I StatusBar: onNotificationRemoved: 0|info.varden.hauk|-560458643|null|10360
D StatusBar: removeNotification key=0|info.varden.hauk|-560458643|null|10360 old=StatusBarNotification(pkg=info.varden.hauk user=UserHandle{0} id=-560458643 tag=null key=0|info.varden.hauk|-560458643|null|10360: Notification(channel=hauk pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=2 vis=PRIVATE))
D StatusBar: update app badge num: info.varden.hauk/,num=0,isAllowed=true,userId=0
I info.varden.hauk: .manager.StopSharingTask.run(StopSharingTask.java:97): Executing share stop task
I info.varden.hauk: .manager.StopSharingTask.run(StopSharingTask.java:99): Stopping location push service
I info.varden.hauk: .manager.StopSharingTask.run(StopSharingTask.java:105): Sending stop packet to server for session Session{serverURL=https://hauk.mydomain.tld/,connParams=ConnectionParameters{proxyType=null,proxyAddress=null,connectTimeout=10000,tlsPolicy=CertificateValidationPolicy{index=0}},backendVersion=1.5.2,sessionID=e368675f9b073060d741ab215b12d0fa91b86521532b3ccbaf78011840138902,expiry=1576329571020,interval=3,e2eParams=null}
V info.varden.hauk: .http.Packet.send(Packet.java:80): Sending packet of type info.varden.hauk.manager.StopSharingTask$1

[bilde2910]

The server isn't responding, or is not closing the connection properly.

A normal push looks like this:

V/info.varden.hauk: .service.LocationPushService$2.onLocationChanged(LocationPushService.java:154): Location was received on fine location provider
V/info.varden.hauk: .service.LocationPushService.onLocationChanged(LocationPushService.java:210): Sending location update packet
V/info.varden.hauk: .http.Packet.send(Packet.java:80): Sending packet of type info.varden.hauk.service.LocationPushService$LocationUpdatePacketImpl
V/info.varden.hauk: .http.Packet$1.run(Packet.java:84): Received as response to packet info.varden.hauk.http.ConnectionThread$Response@f06ff3a
V/info.varden.hauk: .service.LocationPushService$LocationUpdatePacketImpl.onShareListReceived(LocationPushService.java:227): Received list of shares from server

Notice how your logcat doesn't have any instances of the last two lines.

The program logic that resets the UI after session expiration is only called when a response is received from the server. The idea behind this is to not falsely reset the UI if stopping the share failed (although this is still TODO) by checking the success state sent from the server. But this response is never received, so it hangs on waiting for this response.

Can you verify whether the HTTP requests are actually received and handled on the server? Is there something in error logs on your web server? What does your access log look like?

I'll be adding more logging functionality for this in #106. Root cause possibly related to #105.

[bilde2910]

I just added much more detailed logging to the app for this case in #106

[licaon-kter]

Another share another stuck at [0:00]

This time something was different, the text was red and said "server unreachable", not true, but at least something new.

Webserver log: hauk.host_access2.log.zip

I've updated now to the new debug version, hope it helps in my next shares.

[bilde2910]

If you get the dark red "server unreachable" right at the end of the share, it could be because the client tries to send one last location update after it requests the share to be stopped. This makes the server return that the share has stopped, causing an error to be thrown on the client, which the client catches and interprets as a general connection error, causing it to claim the backend is unreachable. I'll see if I can find some way to fix that, it's a visual bug.

However this makes even less sense. It appears the server is returning a response for the last (failing) location update, but not for any of the previous packets - or that's what the client thinks anyway; your access logs indicate that the server is returning a reponse for everything (50 bytes sent for each location update, 34 for the "stop" request). I'm completely stuck as to what could cause this. Will be interesting to see what happens when you get log output from the app with the latest debug version. That should shed some light on it; I've set the log up to be very detailed.

[bilde2910]

When it gets stuck on 0:00 - how long is it stuck in this state?

[licaon-kter]

How long show I wait? Appears it could stay forever.

[bilde2910]

It shouldn't be necessary to wait more than the timeout period configured in app settings.

[licaon-kter]

10s might have passed, I'll keep an eye on it next time.

[licaon-kter]

Still an issue, will look for logs later.

[licaon-kter]

1.6 self build.

Shared 15mins, not sure the location was ever fixed.

Logcat loops this every few seconds, "Sesiune expirată!" means "Session expired!":

V info.varden.hauk: .service.LocationPushService$FineLocationListener.onLocationChanged(LocationPushService.java:241): Location was received on fine location provider
V info.varden.hauk: .system.preferences.PreferenceManager.get(PreferenceManager.java:30): Getting preference Preference<Integer>{key=noGnssFallback,default=45}
V info.varden.hauk: .service.LocationPushService.onLocationChanged(LocationPushService.java:170): Sending location update packet
V info.varden.hauk: .http.Packet.send(Packet.java:80): Sending packet of type info.varden.hauk.service.LocationPushService$LocationUpdatePacketImpl
V info.varden.hauk: .http.ConnectionThread.doInBackground(ConnectionThread.java:72): Assigning seq=572527751 for request Request{url=https://hauk.mydomain.tld/api/post.php,body=acc=xx.xx&prv=0&spd=0.35&lon=xx.xx&time=1.577628764894E9&lat=xx.xx&sid=kkkk,params=ConnectionParameters{proxyType=null,proxyAddress=null,connectTimeout=10000,tlsPolicy=CertificateValidationPolicy{index=0}}}
V info.varden.hauk: .http.ConnectionThread.doInBackground(ConnectionThread.java:91): [seq:572527751] Setting connection parameters
V info.varden.hauk: .http.ConnectionThread.doInBackground(ConnectionThread.java:100): [seq:572527751] Writing data to socket
V info.varden.hauk: .http.ConnectionThread.doInBackground(ConnectionThread.java:108): [seq:572527751] Response code for request is 200
V info.varden.hauk: .http.ConnectionThread.doInBackground(ConnectionThread.java:117): [seq:572527751] resp += "Sesiune expirată!"
V info.varden.hauk: .http.ConnectionThread.doInBackground(ConnectionThread.java:121): [seq:572527751] Returning success response
V info.varden.hauk: .http.Packet$1.run(Packet.java:84): Received as response to packet Response{ex=null,data=[Sesiune expirată!],ver=1.6}
I info.varden.hauk: .service.LocationPushService$LocationUpdatePacketImpl.onSuccess(LocationPushService.java:303): Connection to the backend was restored.
D info.varden.hauk: .notify.HaukNotification.create(HaukNotification.java:86): Creating notification
V info.varden.hauk: .notify.SharingNotification.build(SharingNotification.java:58): Building sharing notification
D info.varden.hauk: .notify.HaukNotification.create(HaukNotification.java:95): Android version O+ detected; setting notification channel
W info.varden.hauk: .service.LocationPushService$LocationUpdatePacketImpl.onFailure(LocationPushService.java:311): Failed to push location update to server
W info.varden.hauk: info.varden.hauk.http.ServerException: Sesiune expirată!
W info.varden.hauk: 
W info.varden.hauk:      at info.varden.hauk.http.LocationUpdatePacket.onSuccess(LocationUpdatePacket.java:113)
W info.varden.hauk:      at info.varden.hauk.service.LocationPushService$LocationUpdatePacketImpl.onSuccess(LocationPushService.java:306)
W info.varden.hauk:      at info.varden.hauk.http.Packet$1.run(Packet.java:91)
W info.varden.hauk:      at info.varden.hauk.http.ConnectionThread.onPostExecute(ConnectionThread.java:143)
W info.varden.hauk:      at info.varden.hauk.http.ConnectionThread.onPostExecute(ConnectionThread.java:40)
W info.varden.hauk:      at android.os.AsyncTask.finish(Unknown Source:10)
W info.varden.hauk:      at android.os.AsyncTask.access$900(Unknown Source:0)
W info.varden.hauk:      at android.os.AsyncTask$InternalHandler.handleMessage(Unknown Source:28)
W info.varden.hauk:      at android.os.Handler.dispatchMessage(Unknown Source:19)
W info.varden.hauk:      at android.os.Looper.loop(Unknown Source:242)
W info.varden.hauk:      at android.app.ActivityThread.main(Unknown Source:98)
W info.varden.hauk:      at java.lang.reflect.Method.invoke(Native Method)
W info.varden.hauk:      at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(Unknown Source:11)
W info.varden.hauk:      at com.android.internal.os.ZygoteInit.main(Unknown Source:275)
I info.varden.hauk: .service.LocationPushService$LocationUpdatePacketImpl.onFailure(LocationPushService.java:315): Connection to the backend was lost.
D info.varden.hauk: .notify.HaukNotification.create(HaukNotification.java:86): Creating notification
V info.varden.hauk: .notify.SharingNotification.build(SharingNotification.java:58): Building sharing notification
D info.varden.hauk: .notify.HaukNotification.create(HaukNotification.java:95): Android version O+ detected; setting notification channel
I StatusBar: onNotificationPosted key:0|info.varden.hauk|-870344423|null|10360 isUpdate:true
I StatusBar: handleNotification key:0|info.varden.hauk|-870344423|null|10360 isUpdate:true
D StatusBar: updateNotification(StatusBarNotification(pkg=info.varden.hauk user=UserHandle{0} id=-870344423 tag=null key=0|info.varden.hauk|-870344423|null|10360: Notification(channel=hauk pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=2 vis=PRIVATE)))
I StatusBar: onNotificationPosted key:0|info.varden.hauk|-870344423|null|10360 isUpdate:true
I StatusBar: handleNotification key:0|info.varden.hauk|-870344423|null|10360 isUpdate:true
D StatusBar: updateNotification(StatusBarNotification(pkg=info.varden.hauk user=UserHandle{0} id=-870344423 tag=null key=0|info.varden.hauk|-870344423|null|10360: Notification(channel=hauk pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 actions=2 vis=PRIVATE)))
E NotificationService: Muting recently noisy 0|info.varden.hauk|-870344423|null|10360
D StatusBar: No peeking: unimportant notification: 0|info.varden.hauk|-870344423|null|10360
I StatusBar: 0|info.varden.hauk|-870344423|null|10360 reInflateFlags:-17 wasHeadsUp:false shouldPeek:false alertAgain:true

App status cycles between "searching location" and "server unaccesible".

nginx logs continously: 127.0.0.1 - - [29/Dec/2019:14:19:54 +0000] "POST /api/post.php HTTP/1.1" 200 50 "-" "Hauk/1.6 Dalvik/2.1.0 (Linux; U; Android XX; MyDevice)" "-" about 5 times, per duration, then 2 or 3 minutes of pause, then again.

Do note that there's a 127.0.0.1 - - [29/Dec/2019:13:42:35 +0000] "POST /api/create.php HTTP/1.1" 200 132 "-" "Hauk/1.6 Dalvik/2.1.0 (Linux; U; Android XX; MyDevice)" "-" above....but no STOP entry.

[licaon-kter]

After writing this I opened the device and it was stopped.

nginx logged: 127.0.0.1 - - [29/Dec/2019:14:24:26 +0000] "POST /api/stop.php HTTP/1.1" 200 34 "-" "Hauk/1.6 Dalvik/2.1.0 (Linux; U; Android XX; MyDevice)" "-"

FYI, I didn't change the timestamps.

[bilde2910]

Seriously thank you so much for the logs. You have no idea how valuable your help is in helping me resolve this issue.

The program flow you describe doesn't make sense. The app shouldn't be sending any data if the status is "Searching for location", as there's no location updates to trigger these pushes and these alternating status updates. So somehow there's another location sharing service already running that actually sends the updates, and it's not the one linked to the UI. And the countdown somehow gets stuck in this process as well. I have no clue what causes this.

From a technical perspective - it is possible for me to add a timeout that cancels the location service from within the service itself, instead from the app's central session manager, which is what it does now. But this is not a good solution; it would stop the data being pushed but it doesn't solve the root cause.

I've added more logging that prints out which instances in Hauk is doing what in these cases; hopefully that's enough to get more data about the root cause. Please pull and build from the latest commit to log these events.

If this happens again - could you make sure to save the entire log file from start to finish? That way I can follow every step the app takes in its execution, including any crashes and unexpected behavior along the way.

I really appreciate the log you sent, but I have a feeling the root cause happens a long time before the issue actually manifests itself, so your log snip is from long after the actual root cause. Right now I'm shooting in the dark trying to solve it and I really want this problem resolved.

You'll get a very large log file. You could use regex to filter out sensitive information in the log; doing it manually would probably take too long. This command should remove your coordinates, the server hostname, and the session ID from the log for you; double check before you send it just to make sure:

cat hauk.log | sed -Ee 's/(lat|lon|sessionID|sid)=[\.0-9a-f]*/\1=xxx/g' | sed -Ee 's/http(s?):\/\/[^\/]*/http\1:\/\/backend-server/g' > filtered.log

[licaon-kter]

Will try, as shorter test times did not yield this error, but apparently 15 mins is kinda the one to test with.

[licaon-kter]

I can't grab the logs now, but fun fact, the second (or was it third time?) I've made a 15 minutes share I hit the bug.