mobi/e-ntfy-android
1
0
Fork 0
Code Pull requests Activity

More concise logging for WebSockets

Browse source
This commit is contained in:
Philipp Heckel 2022-02-02 12:30:34 -05:00
parent 74b260f9a0
commit c772d15043
1 changed files with 29 additions and 33 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

62
app/src/main/java/io/heckel/ntfy/service/WsConnection.kt
View file

@ -6,13 +6,11 @@ import android.os.Handler
import android.os.Looper import android.os.Looper
import io.heckel.ntfy.db.* import io.heckel.ntfy.db.*
import io.heckel.ntfy.log.Log import io.heckel.ntfy.log.Log
import io.heckel.ntfy.msg.ApiService
import io.heckel.ntfy.msg.ApiService.Companion.requestBuilder import io.heckel.ntfy.msg.ApiService.Companion.requestBuilder
import io.heckel.ntfy.msg.NotificationParser import io.heckel.ntfy.msg.NotificationParser
import io.heckel.ntfy.util.topicUrl import io.heckel.ntfy.util.topicShortUrl
import io.heckel.ntfy.util.topicUrlWs import io.heckel.ntfy.util.topicUrlWs
import okhttp3.* import okhttp3.*
import java.nio.charset.StandardCharsets
import java.util.* import java.util.*
import java.util.concurrent.TimeUnit import java.util.concurrent.TimeUnit
import java.util.concurrent.atomic.AtomicLong import java.util.concurrent.atomic.AtomicLong
@ -45,7 +43,7 @@ class WsConnection(
.build() .build()
private var errorCount = 0 private var errorCount = 0
private var webSocket: WebSocket? = null private var webSocket: WebSocket? = null
private val webSocketId = AtomicLong(0) private val listenerId = AtomicLong(0)
private var state: State? = null private var state: State? = null
private var closed = false private var closed = false
@ -54,23 +52,23 @@ class WsConnection(
private val topicsToSubscriptionIds = connectionId.topicsToSubscriptionIds private val topicsToSubscriptionIds = connectionId.topicsToSubscriptionIds
private val subscriptionIds = topicsToSubscriptionIds.values private val subscriptionIds = topicsToSubscriptionIds.values
private val topicsStr = topicsToSubscriptionIds.keys.joinToString(separator = ",") private val topicsStr = topicsToSubscriptionIds.keys.joinToString(separator = ",")
private val url = topicUrl(baseUrl, topicsStr) private val shortUrl = topicShortUrl(baseUrl, topicsStr)
@Synchronized @Synchronized
override fun start() { override fun start() {
if (closed || state == State.Connecting || state == State.Connected) { if (closed || state == State.Connecting || state == State.Connected) {
Log.d(TAG,"[$url] WebSocket: Not (re-)starting, because connection is marked closed/connecting/connected") Log.d(TAG,"$shortUrl: Not (re-)starting, because connection is marked closed/connecting/connected")
return return
} }
if (webSocket != null) { if (webSocket != null) {
webSocket!!.close(WS_CLOSE_NORMAL, "") webSocket!!.close(WS_CLOSE_NORMAL, "")
} }
state = State.Connecting state = State.Connecting
val nextId = webSocketId.incrementAndGet() val nextId = listenerId.incrementAndGet()
val sinceVal = if (since == 0L) "all" else since.toString() val sinceVal = if (since == 0L) "all" else since.toString()
val urlWithSince = topicUrlWs(baseUrl, topicsStr, sinceVal) val urlWithSince = topicUrlWs(baseUrl, topicsStr, sinceVal)
val request = requestBuilder(urlWithSince, user).build() val request = requestBuilder(urlWithSince, user).build()
Log.d(TAG, "[$url] WebSocket: Opening $urlWithSince with listener ID $nextId ...") Log.d(TAG, "$shortUrl: Opening $urlWithSince with listener ID $nextId ...")
webSocket = client.newWebSocket(request, Listener(nextId)) webSocket = client.newWebSocket(request, Listener(nextId))
} }
@ -78,10 +76,10 @@ class WsConnection(
override fun close() { override fun close() {
closed = true closed = true
if (webSocket == null) { if (webSocket == null) {
Log.d(TAG,"[$url] WebSocket: Not closing existing connection, because there is no active web socket") Log.d(TAG,"$shortUrl: Not closing existing connection, because there is no active web socket")
return return
} }
Log.d(TAG, "[$url] WebSocket: Closing existing connection") Log.d(TAG, "$shortUrl: Closing existing connection")
state = State.Disconnected state = State.Disconnected
webSocket!!.close(WS_CLOSE_NORMAL, "") webSocket!!.close(WS_CLOSE_NORMAL, "")
webSocket = null webSocket = null
@ -95,17 +93,17 @@ class WsConnection(
@Synchronized @Synchronized
fun scheduleReconnect(seconds: Int) { fun scheduleReconnect(seconds: Int) {
if (closed || state == State.Connecting || state == State.Connected) { if (closed || state == State.Connecting || state == State.Connected) {
Log.d(TAG,"[$url] WebSocket: Not rescheduling connection, because connection is marked closed/connecting/connected") Log.d(TAG,"$shortUrl: Not rescheduling connection, because connection is marked closed/connecting/connected")
return return
} }
state = State.Scheduled state = State.Scheduled
if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) { if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) {
Log.d(TAG,"[$url] WebSocket: Scheduling a restart in $seconds seconds (via alarm manager)") Log.d(TAG,"$shortUrl: Scheduling a restart in $seconds seconds (via alarm manager)")
val reconnectTime = Calendar.getInstance() val reconnectTime = Calendar.getInstance()
reconnectTime.add(Calendar.SECOND, seconds) reconnectTime.add(Calendar.SECOND, seconds)
alarmManager.setExact(AlarmManager.RTC_WAKEUP, reconnectTime.timeInMillis, RECONNECT_TAG, { start() }, null) alarmManager.setExact(AlarmManager.RTC_WAKEUP, reconnectTime.timeInMillis, RECONNECT_TAG, { start() }, null)
} else { } else {
Log.d(TAG, "[$url] WebSocket: Scheduling a restart in $seconds seconds (via handler)") Log.d(TAG, "$shortUrl: Scheduling a restart in $seconds seconds (via handler)")
val handler = Handler(Looper.getMainLooper()) val handler = Handler(Looper.getMainLooper())
handler.postDelayed({ start() }, TimeUnit.SECONDS.toMillis(seconds.toLong())) handler.postDelayed({ start() }, TimeUnit.SECONDS.toMillis(seconds.toLong()))
} }
@ -113,8 +111,8 @@ class WsConnection(
private inner class Listener(private val id: Long) : WebSocketListener() { private inner class Listener(private val id: Long) : WebSocketListener() {
override fun onOpen(webSocket: WebSocket, response: Response) { override fun onOpen(webSocket: WebSocket, response: Response) {
syncExec("onOpen") { synchronize("onOpen") {
Log.d(TAG, "[$url] WebSocket ($id): Opened connection") Log.d(TAG, "$shortUrl (listener $id): Opened connection")
state = State.Connected state = State.Connected
if (errorCount > 0) { if (errorCount > 0) {
errorCount = 0 errorCount = 0
@ -124,17 +122,17 @@ class WsConnection(
} }
override fun onMessage(webSocket: WebSocket, text: String) { override fun onMessage(webSocket: WebSocket, text: String) {
syncExec("onMessage") { synchronize("onMessage") {
Log.d(TAG, "[$url] WebSocket ($id): Received message: $text") Log.d(TAG, "$shortUrl (listener $id): Received message: $text")
val notificationWithTopic = parser.parseWithTopic(text, subscriptionId = 0, notificationId = Random.nextInt()) val notificationWithTopic = parser.parseWithTopic(text, subscriptionId = 0, notificationId = Random.nextInt())
if (notificationWithTopic == null) { if (notificationWithTopic == null) {
Log.d(TAG, "[$url] WebSocket ($id): Unable to parse message. Discarding.") Log.d(TAG, "$shortUrl (listener $id): Irrelevant or unknown message. Discarding.")
return@syncExec return@synchronize
} }
val topic = notificationWithTopic.topic val topic = notificationWithTopic.topic
val notification = notificationWithTopic.notification val notification = notificationWithTopic.notification
val subscriptionId = topicsToSubscriptionIds[topic] ?: return@syncExec val subscriptionId = topicsToSubscriptionIds[topic] ?: return@synchronize
val subscription = repository.getSubscription(subscriptionId) ?: return@syncExec val subscription = repository.getSubscription(subscriptionId) ?: return@synchronize
val notificationWithSubscriptionId = notification.copy(subscriptionId = subscription.id) val notificationWithSubscriptionId = notification.copy(subscriptionId = subscription.id)
notificationListener(subscription, notificationWithSubscriptionId) notificationListener(subscription, notificationWithSubscriptionId)
since = notification.timestamp since = notification.timestamp
@ -142,22 +140,22 @@ class WsConnection(
} }
override fun onClosed(webSocket: WebSocket, code: Int, reason: String) { override fun onClosed(webSocket: WebSocket, code: Int, reason: String) {
syncExec("onClosed") { synchronize("onClosed") {
Log.w(TAG, "[$url] WebSocket ($id): Closed connection") Log.w(TAG, "$shortUrl (listener $id): Closed connection")
state = State.Disconnected state = State.Disconnected
} }
} }
override fun onFailure(webSocket: WebSocket, t: Throwable, response: Response?) { override fun onFailure(webSocket: WebSocket, t: Throwable, response: Response?) {
syncExec("onFailure") { synchronize("onFailure") {
if (response == null) { if (response == null) {
Log.e(TAG, "[$url] WebSocket ($id): Connection failed (response is null): ${t.message}", t) Log.e(TAG, "$shortUrl (listener $id): Connection failed (response is null): ${t.message}", t)
} else { } else {
Log.e(TAG, "[$url] WebSocket ($id): Connection failed (response code ${response.code}, message: ${response.message}): ${t.message}", t) Log.e(TAG, "$shortUrl (listener $id): Connection failed (response code ${response.code}, message: ${response.message}): ${t.message}", t)
} }
if (closed) { if (closed) {
Log.d(TAG, "WebSocket ($id): Connection marked as closed. Not retrying.") Log.d(TAG, "$shortUrl (listener $id): Connection marked as closed. Not retrying.")
return@syncExec return@synchronize
} }
stateChangeListener(subscriptionIds, ConnectionState.CONNECTING) stateChangeListener(subscriptionIds, ConnectionState.CONNECTING)
state = State.Disconnected state = State.Disconnected
@ -167,14 +165,12 @@ class WsConnection(
} }
} }
private fun syncExec(tag: String, fn: () -> Unit) { private fun synchronize(tag: String, fn: () -> Unit) {
synchronized(this) { synchronized(this) {
if (webSocketId.get() == id) { if (listenerId.get() == id) {
Log.d(TAG, "[$url] WebSocket ($id): Begin $tag")
fn() fn()
Log.d(TAG, "[$url] WebSocket ($id): End $tag")
} else { } else {
Log.d(TAG, "[$url] WebSocket ($id): Skipping synchronized block '$tag', because ID does not match ${webSocketId.get()}") Log.w(TAG, "$shortUrl (listener $id): Skipping synchronized block '$tag', because listener ID does not match ${listenerId.get()}")
} }
} }
} }