MCMrARM
"Periodically send a heartbeat" does nothing
Related to issue https://github.com/MCMrARM/revolution-irc/issues/58, but I am opening this one because I feel as though that one was poorly worded and was confused with a different issue.
The point of the periodic heartbeat is to probe the connection status and attempt a reconnect if the connection is found to be dead. This simply is not happening. Once the server disconnects due to timeout, the client continues displaying that it is connected even when it's not. Even with "Periodically send a heartbeat" checked, nothing happens. The client continues to show it is connected when it isn't and must be manually disconnected and reconnected.
Basically the server disconnects, the client silently just stops working and doesn't send any notifications and pretends like it is still connected when it isn't, and you are left thinking everything is fine and waiting for messages that never come because you are actually not connected and missing everything. This is a pretty major bug.
So, I presume you set the interval to 15 minutes, and then waited the 15 minutes and the client still didn't reconnect? Are you sure you were on WiFi and not 3G?
I have one client on 3G and one client on Wi-Fi, both different models of Samsung Galaxies. I never changed the 15-minute default. I have both "Only reconnect on WiFi" and "Only send a heartbeat on WiFi" unchecked. I also have both "Automatically reconnect" and "Track connectivity changes" checked. Once the server disconnects, the client stays stuck indefinitely, well over 15 minutes. I have let it sit for hours and still no reconnect. As soon as I disable and re-enable my Wi-Fi, or go into Revolution IRC to manually disconnect and reconnect, it reconnects instantly.
If it helps, I am also running my own instance of UnrealIRCd, so I can troubleshoot from both sides as needed if you have any further suggestions for me to test if you need more info., etc.
As a side note, I have seen several issues here regarding server timeouts and read errors. I currently have my UnrealIRCd pingfreq (ping frequency) set to 600, as this was the only way to keep a connection with mobile clients without timing out a few seconds after every connect. I currently have a ticket in with the UnrealIRCd Bug Tracker to request more settings that can be configured here to make things easier for mobile IRC clients.
https://bugs.unrealircd.org/view.php?id=5441
And I will also reference my earlier comment, https://github.com/MCMrARM/revolution-irc/issues/58#issuecomment-542255542, in regards to ensuring that your IRC client is set up to work through the Data saver if you have Data saver enabled. If you don't allow Revolution IRC through the Data saver, it will end up getting cut off in the background and is another common reason for server timeouts.
I'm trying to pinpoint exactly how to reproduce it, but for now I can't force this issue to occur. I'm starting to feel as though this issue is completely internal to the client and not triggered externally, like the client simply stops working on its own and it's not actually "getting stuck" after a disconnect. I think something is happening internally which actually causes the disconnect.
The server logs the following:
*** Client exiting: ScriptTiger ([email protected]) [192.168.1.10] (Read error)
And then the client just never reconnects. But I can still send messages to the channels I already have open and the messages appear in the channels, but it's not even connected and not actually sending the messages to the server. I think this also explains why the heartbeat is not working, the client itself is crashed and can't send a heartbeat. I think more internal debugging needs to be done.
In order for @MCMrARM to troubleshoot, this may be a model-specific issue. @haarp, what is your phone model? I can 100% confirm this for Samsung Galaxy A10. And I am pretty sure other Samsung Galaxy models have the same problem, but I can't confirm that at the moment.
I have also confirmed that Revolution IRC can sometimes reconnect by itself after being stuck, but it's usually not less than about an hour later if at all, sometimes it never reconnects. And if it does manage to recover and reconnect automatically, it usually gets a read error again a short while later.
Since it works fine for a long stretch and then starts going off the rails later, it could be a memory issue of some kind. After the first time you get a read error, even after you manually reconnect, it has a higher tendency of disconnecting again a short while later. So it's almost as if it's hitting a limit at some point and just breaking down.
I don't know if it's relevant, but the memory use is on average 32 MB, with a max of 48 MB and a frequency of high (99%). This seems a bit odd to me though because I also leave my WhatsApp on all the time and its memory is only on average 1.2 MB, with a max of 43 MB and a frequency of low (3%). I definitely use my WhatsApp a lot more than Revolution IRC, so I don't know why the memory for Revolution IRC jumps up so high even after running a shorter period than WhatsApp. Even if this is not related to this specific issue, I think there is definitely a problem here to be looked into, as far as better memory management. But I think it's possible that this is related and causing Revolution IRC to not respond correctly to the server and cause read errors and crash.
I am testing this with a phone at rest to try to keep a consistent control so mixing waking/sleeping states doesn't interfere with testing.
EDIT: I have been doing some more memory comparisons and I am almost certain there is a serious memory issue at this point. @haarp, can you confirm this on your phone? Just go to Settings -> Apps -> Revolution IRC -> Memory. It may be affecting people with lower-end hardware more than others.
EDIT: I was able to compare a 2 GB RAM Samsung Galaxy A10 with a 3 GB RAM Samsung Galaxy J7 Pro. The A10 definitely starts cutting out a lot sooner than the J7, but the J7 does experience the same problem several hours later. After force stopping and clearing the cache, it basically restarts the timer for both of them, but it only helps temporarily until the memory builds up again it gets stuck all over again.
Something else I have found is that once Revolution IRC starts to continually get stuck more and more, you can just go to Settings -> Apps -> Revolution IRC -> Force stop as well as Storage -> Clear cache. Then after you start Revolution IRC back up again it will be golden for at least the next few hours until it starts hitting hiccups again. I hope this helps anyone else having this problem until it gets resolved.
I have also found that as long as Revolution IRC is running well, an operator can /kill username reason and Revolution IRC can recover just fine and reconnect as expected. The more testing I do seems to suggest more and more it's an internal app error/unresponsiveness and not actually getting stuck on a disconnected connection. The app is crashing and causing the disconnect and doesn't reconnect because it's unresponsive for a period of time. Sometimes it can recover on its own, sometimes it can't.
Can you please load the logcat while Revo is stuck, then try to send a message and check if it appears in the logcat? If it doesn't, can you please try killing the connection remotely and post any messages Revo might print into the log then?
Will do!
Want me to filter by logs mentioning "io.mrarm," or did you want anything else?
--------- beginning of crash
10-22 09:28:21.097 26242 26289 E AndroidRuntime: FATAL EXCEPTION: IRC Connection Handler
10-22 09:28:21.097 26242 26289 E AndroidRuntime: Process: io.mrarm.irc, PID: 26242
10-22 09:28:21.097 26242 26289 E AndroidRuntime: java.lang.RuntimeException: Handler registration name collision
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at io.mrarm.chatlib.irc.CommandHandlerList.registerHandler(CommandHandlerList.java:54)
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at io.mrarm.chatlib.irc.cap.CapabilityManager.setEnabledCapabilities(CapabilityManager.java:62)
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at io.mrarm.chatlib.irc.cap.CapabilityManager.onCapabilitiesAck(CapabilityManager.java:114)
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at io.mrarm.chatlib.irc.handlers.CapCommandHandler.handle(CapCommandHandler.java:47)
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at io.mrarm.chatlib.irc.MessageHandler.handleLine(MessageHandler.java:53)
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:120)
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-22 09:28:21.097 26242 26289 E AndroidRuntime: at java.lang.Thread.run(Thread.java:764)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: FATAL EXCEPTION: IRC Connection Handler
10-22 10:02:29.869 31982 32043 E AndroidRuntime: Process: io.mrarm.irc, PID: 31982
10-22 10:02:29.869 31982 32043 E AndroidRuntime: java.lang.RuntimeException: Handler registration name collision
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at io.mrarm.chatlib.irc.CommandHandlerList.registerHandler(CommandHandlerList.java:54)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at io.mrarm.chatlib.irc.cap.CapabilityManager.setEnabledCapabilities(CapabilityManager.java:62)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at io.mrarm.chatlib.irc.cap.CapabilityManager.onCapabilitiesAck(CapabilityManager.java:114)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at io.mrarm.chatlib.irc.handlers.CapCommandHandler.handle(CapCommandHandler.java:47)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at io.mrarm.chatlib.irc.MessageHandler.handleLine(MessageHandler.java:53)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:120)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-22 10:02:29.869 31982 32043 E AndroidRuntime: at java.lang.Thread.run(Thread.java:764)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: FATAL EXCEPTION: IRC Connection Handler
10-22 10:05:33.049 11150 11195 E AndroidRuntime: Process: io.mrarm.irc, PID: 11150
10-22 10:05:33.049 11150 11195 E AndroidRuntime: java.lang.RuntimeException: Handler registration name collision
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at io.mrarm.chatlib.irc.CommandHandlerList.registerHandler(CommandHandlerList.java:54)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at io.mrarm.chatlib.irc.cap.CapabilityManager.setEnabledCapabilities(CapabilityManager.java:62)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at io.mrarm.chatlib.irc.cap.CapabilityManager.onCapabilitiesAck(CapabilityManager.java:114)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at io.mrarm.chatlib.irc.handlers.CapCommandHandler.handle(CapCommandHandler.java:47)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at io.mrarm.chatlib.irc.MessageHandler.handleLine(MessageHandler.java:53)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:120)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-22 10:05:33.049 11150 11195 E AndroidRuntime: at java.lang.Thread.run(Thread.java:764)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: FATAL EXCEPTION: IRC Connection Handler
10-22 10:21:13.539 11684 11711 E AndroidRuntime: Process: io.mrarm.irc, PID: 11684
10-22 10:21:13.539 11684 11711 E AndroidRuntime: java.lang.RuntimeException: Handler registration name collision
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at io.mrarm.chatlib.irc.CommandHandlerList.registerHandler(CommandHandlerList.java:54)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at io.mrarm.chatlib.irc.cap.CapabilityManager.setEnabledCapabilities(CapabilityManager.java:62)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at io.mrarm.chatlib.irc.cap.CapabilityManager.onCapabilitiesAck(CapabilityManager.java:114)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at io.mrarm.chatlib.irc.handlers.CapCommandHandler.handle(CapCommandHandler.java:47)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at io.mrarm.chatlib.irc.MessageHandler.handleLine(MessageHandler.java:53)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:120)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-22 10:21:13.539 11684 11711 E AndroidRuntime: at java.lang.Thread.run(Thread.java:764)
This is the crash log. This was not part of my testing, so I am not 100% sure if it's related. I am trying to make a complete log now for before, during, and after, but the crash log is separate from the main log so I am just posting this now in case it's helpful.
I'm trying to log while it crashes, by my logcat crashes at the same time, so I'm not sure what's happening. I'll keep trying and see if I can get that, but I have the before and after at least.
Before crash:
10-24 17:52:59.656 16648 16691 W System.err: at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
10-24 17:52:59.656 16648 16691 W System.err: at com.android.org.conscrypt.NativeSsl.read(NativeSsl.java:407)
10-24 17:52:59.656 16648 16691 W System.err: at com.android.org.conscrypt.ConscryptFileDescriptorSocket$SSLInputStream.read(ConscryptFileDescriptorSocket.java:579)
10-24 17:52:59.656 16648 16691 W System.err: at com.android.org.conscrypt.ConscryptFileDescriptorSocket$SSLInputStream.read(ConscryptFileDescriptorSocket.java:550)
10-24 17:52:59.656 16648 16691 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:99)
10-24 17:52:59.656 16648 16691 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 17:52:59.656 16648 16691 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 17:52:59.656 16648 16691 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 17:52:59.656 16648 16691 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 17:53:00.542 16648 4400 W System.err: javax.net.ssl.SSLException: Read error: ssl=0xec2a8068: I/O error during system call, Software caused connection abort
10-24 17:53:00.542 16648 4400 W System.err: at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
10-24 17:53:00.542 16648 4400 W System.err: at com.android.org.conscrypt.NativeSsl.read(NativeSsl.java:407)
10-24 17:53:00.542 16648 4400 W System.err: at com.android.org.conscrypt.ConscryptFileDescriptorSocket$SSLInputStream.read(ConscryptFileDescriptorSocket.java:579)
10-24 17:53:00.542 16648 4400 W System.err: at com.android.org.conscrypt.ConscryptFileDescriptorSocket$SSLInputStream.read(ConscryptFileDescriptorSocket.java:550)
10-24 17:53:00.542 16648 4400 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:99)
10-24 17:53:00.542 16648 4400 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 17:53:00.542 16648 4400 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 17:53:00.543 16648 4400 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 17:53:00.543 16648 4400 W System.err: at java.lang.Thread.run(Thread.java:764)
After the crash:
10-24 19:58:26.935 16648 14721 W System.err: at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
10-24 19:58:26.936 16648 14721 W System.err: at com.android.org.conscrypt.NativeSsl.read(NativeSsl.java:407)
10-24 19:58:26.936 16648 14721 W System.err: at com.android.org.conscrypt.ConscryptFileDescriptorSocket$SSLInputStream.read(ConscryptFileDescriptorSocket.java:579)
10-24 19:58:26.938 16648 14721 W System.err: at com.android.org.conscrypt.ConscryptFileDescriptorSocket$SSLInputStream.read(ConscryptFileDescriptorSocket.java:550)
10-24 19:58:26.938 16648 14721 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:99)
10-24 19:58:26.938 16648 14721 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 19:58:26.938 16648 14721 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 19:58:26.938 16648 14721 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 19:58:26.938 16648 14721 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 19:59:03.057 16648 16583 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 19:59:03.062 16648 16583 W System.err: java.io.IOException: read() returned -1
10-24 19:59:03.063 16648 16583 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 19:59:03.063 16648 16583 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 19:59:03.064 16648 16583 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 19:59:03.064 16648 16583 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 19:59:03.064 16648 16583 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 19:59:03.073 16648 16583 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 19:59:03.080 16648 16583 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 19:59:43.007 16648 17071 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 19:59:43.008 16648 17071 W System.err: java.io.IOException: read() returned -1
10-24 19:59:43.008 16648 17071 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 19:59:43.008 16648 17071 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 19:59:43.008 16648 17071 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 19:59:43.008 16648 17071 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 19:59:43.008 16648 17071 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 19:59:43.012 16648 17071 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 19:59:43.014 16648 17071 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:00:46.794 16648 17333 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:00:46.796 16648 17333 W System.err: java.io.IOException: read() returned -1
10-24 20:00:46.797 16648 17333 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:00:46.797 16648 17333 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:00:46.797 16648 17333 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:00:46.797 16648 17333 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:00:46.797 16648 17333 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:00:46.805 16648 17333 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:00:46.813 16648 17333 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:01:50.187 16648 17353 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:01:50.188 16648 17353 W System.err: java.io.IOException: read() returned -1
10-24 20:01:50.188 16648 17353 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:01:50.188 16648 17353 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:01:50.188 16648 17353 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:01:50.188 16648 17353 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:01:50.188 16648 17353 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:01:50.193 16648 17353 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:01:50.198 16648 17353 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:02:27.375 16648 17587 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:02:27.376 16648 17587 W System.err: java.io.IOException: read() returned -1
10-24 20:02:27.376 16648 17587 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:02:27.376 16648 17587 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:02:27.376 16648 17587 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:02:27.376 16648 17587 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:02:27.376 16648 17587 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:02:27.382 16648 17587 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:02:27.385 16648 17587 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:03:06.313 16648 17622 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:03:06.314 16648 17622 W System.err: java.io.IOException: read() returned -1
10-24 20:03:06.315 16648 17622 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:03:06.315 16648 17622 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:03:06.315 16648 17622 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:03:06.315 16648 17622 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:03:06.315 16648 17622 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:03:06.325 16648 17622 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:03:06.329 16648 17622 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:03:42.299 16648 17662 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:03:42.300 16648 17662 W System.err: java.io.IOException: read() returned -1
10-24 20:03:42.300 16648 17662 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:03:42.300 16648 17662 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:03:42.301 16648 17662 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:03:42.301 16648 17662 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:03:42.301 16648 17662 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:03:42.306 16648 17662 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:03:42.312 16648 17662 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:04:20.304 16648 17685 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:04:20.306 16648 17685 W System.err: java.io.IOException: read() returned -1
10-24 20:04:20.306 16648 17685 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:04:20.306 16648 17685 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:04:20.306 16648 17685 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:04:20.306 16648 17685 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:04:20.306 16648 17685 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:04:20.310 16648 17685 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:04:20.313 16648 17685 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:04:51.308 16648 17707 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:04:51.309 16648 17707 W System.err: java.io.IOException: read() returned -1
10-24 20:04:51.309 16648 17707 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:04:51.309 16648 17707 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:04:51.309 16648 17707 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:04:51.309 16648 17707 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:04:51.309 16648 17707 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:04:51.314 16648 17707 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:04:51.318 16648 17707 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:05:27.322 16648 17732 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:05:27.323 16648 17732 W System.err: java.io.IOException: read() returned -1
10-24 20:05:27.323 16648 17732 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:05:27.323 16648 17732 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:05:27.323 16648 17732 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:05:27.324 16648 17732 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:05:27.324 16648 17732 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:05:27.329 16648 17732 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:05:27.334 16648 17732 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:05:58.286 16648 17749 I System.out: Got: ERROR :Closing Link: [192.168.1.10] (Registration Timeout)
10-24 20:05:58.287 16648 17749 W System.err: java.io.IOException: read() returned -1
10-24 20:05:58.287 16648 17749 W System.err: at io.mrarm.chatlib.irc.IRCConnection.readCommand(IRCConnection.java:101)
10-24 20:05:58.287 16648 17749 W System.err: at io.mrarm.chatlib.irc.IRCConnection.handleInput(IRCConnection.java:117)
10-24 20:05:58.287 16648 17749 W System.err: at io.mrarm.chatlib.irc.IRCConnection.lambda$WaOIvzbB9flSh3k_2YttU9UsnDA(Unknown Source:0)
10-24 20:05:58.287 16648 17749 W System.err: at io.mrarm.chatlib.irc.-$$Lambda$IRCConnection$WaOIvzbB9flSh3k_2YttU9UsnDA.run(Unknown Source:2)
10-24 20:05:58.287 16648 17749 W System.err: at java.lang.Thread.run(Thread.java:764)
10-24 20:05:58.291 16648 17749 I ServerConnectionInfo: Queuing reconnect in 30000 ms
10-24 20:05:58.296 16648 17749 I ServerConnectionInfo: Queuing reconnect in 30000 ms
I'll try some different methods to get the complete log and have it posted as soon as I can get it.
Here is a log of during a crash. I couldn't capture the log exactly at the start of the crash, but this log was taken while the app was crashed, or "stuck." The app says that it's connected but it's not, and I tried sending several messages that show in the channel but obviously they are not really sent to the server. So hopefully you can see some error logs for that with this.
logcat_10-26-2019_07-45-53.txt
I will keep trying to get a log for the actual moment the app first starts to crash. It happens randomly and I don't know how to force it to happen, so I just have to keep logging it for hours and sometimes I miss it because I don't have time to keep monitoring it all the time because I try not to use my phone at all while I am logging so the log can be as consistent as possible without any unnecessary entries from things that I am doing.
@MCMrARM, I finally have a complete log from start to finish.
13:48:30 - Server logged Read error
14:36 - I sent /LIST command and also sent "Test" and "Hello" messages to a channel while the client was stuck. The /LIST command had no output, but the "Test" and "Hello" messages appeared in the channel, but were not really sent to the server and other clients in the channel never received those messages. And just for further clarification, no messages being exchanged in the channel from other clients were ever received by Revolution IRC while it was stuck either.
14:45:31 Connection re-established.
Do you have a public e-mail I can send you the log at? It's almost an hour worth of logcat and there may be some personal info thrown in there, so I would prefer to just send it to you personally rather than posting it publicly, just in case.
EDIT: I will also note that my logcat does mention com.icecoldapps.ircserver a few times, but that's just informational logs because I have that installed for other reasons, but I am not actually using that with the client. I have my own UnrealIRCd4 instance I am connected to that I am using Revolution IRC with. So just making sure there is no confusion there.
Server-side or client-side? I am logging everything on my UnrealIRCd and it just says that I disconnected for a read error, but nothing else. If you're talking about client-side and debugging the app, I don't have a setup to do that at the moment, but I can probably get it in the next week or so.
I haven't had time to debug it yet, but I just thought I would post an interesting update to things. I just noticed my phone has started suggesting I put Revolution IRC to sleep because it crashes too much.
I just wanted to add that I have also seen an issue. I just installed this client, logged into Freenode, and joined #python. I was on for some time and then no messages came through. I haven't changed heartbeat values, but in the very least, if there is a disconnection, it needs to be indicated to the user. It was hours later, when I decided to reconnect and sure enough, the activity started up quickly in that channel.
I'm on a tablet, over wi-fi. A Lenovo Yogabook.
On freenode the server-side timeout is 256 seconds (about 4.3 minutes) , and likely to be similar on other services, so 15 minutes seems ridiculously long for the client-side timeout, especially as it can take a large multiple of that for the lost connection to get "noticed".
Ideally the client should maintain a timer & a counter.
- Whenever any data is received, the counter is set to 0 and the timer is set to (say) 200 seconds.
- Whenever the timer expires, the counter is incremented, and the timer is restarted at (say) 15 seconds.
- If the counter reaches (say) 4, the connection is declared dead, and a reconnection is attempted.
Also, if outbound data is blocked (because the kernel hasn't seen ACK packets, and so its buffers fill and stall), then the connection should also be declared dead, even if there is incoming data.
If application pings go unanswered but other data is received (so the connection remains "up"), this should be logged in case it's needed for later diagnostic analysis.
