Incident: XMPP reconnection and total containment failure

[ForNeVeR]

I see the following in the logs from 2021-09-12:

{"Timestamp":"2021-09-12T22:16:33.0700150+00:00","Level":"Warning","MessageTemplate":"Pong message not received in {Time}: terminating room {Room}","Properties":{"Time":"00:00:30","Room":"codingteam@conference.jabber.ru","EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:16:33.0875941+00:00","Level":"Information","MessageTemplate":"Room lifetime has been terminated","Properties":{"EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:16:33.0883978+00:00","Level":"Error","MessageTemplate":"Connection failed: {Message}","Exception":"System.Xml.XmlException: Unexpected end of file has occurred. The following elements are not closed: stream:stream. Line 10, position 1459.\n   at System.Xml.XmlTextReaderImpl.Throw(Exception e)\n   at System.Xml.XmlTextReaderImpl.Throw(String res, String arg)\n   at System.Xml.XmlTextReaderImpl.ThrowUnclosedElements()\n   at System.Xml.XmlTextReaderImpl.ParseElementContent()\n   at SharpXMPP.XmppTcpConnection.NextElement()\n   at SharpXMPP.XmppTcpConnection.SessionLoop()","Properties":{"Message":"Unexpected end of file has occurred. The following elements are not closed: stream:stream. Line 10, position 1459.","EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:16:33.0891658+00:00","Level":"Debug","MessageTemplate":"Current queue state: {State}","Properties":{"State":"{ Messages = seq []\n  ClientReadyToSendMessages = false }","EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:16:33.0900111+00:00","Level":"Error","MessageTemplate":"Non-terminating message system error","Exception":"System.IO.IOException: The write operation failed, see inner exception.\n ---> System.ObjectDisposedException: Cannot access a disposed object.\nObject name: 'System.Net.Sockets.NetworkStream'.\n   at System.Net.Sockets.NetworkStream.<ThrowIfDisposed>g__ThrowObjectDisposedException|63_0()\n   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)\n   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)\n   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)\n   --- End of inner exception stack trace ---\n   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)\n   at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count)\n   at System.Xml.XmlUtf8RawTextWriter.FlushBuffer()\n   at System.Xml.XmlUtf8RawTextWriter.Flush()\n   at System.Xml.XmlWellFormedWriter.Close()\n   at SharpXMPP.XmppTcpConnection.Dispose()\n   at Microsoft.FSharp.Core.LanguagePrimitives.IntrinsicFunctions.Dispose[T](T resource) in F:\\workspace\\_work\\1\\s\\src\\fsharp\\FSharp.Core\\prim-types.fs:line 637\n   at Microsoft.FSharp.Control.AsyncPrimitives.disposeFunction@583-1.Invoke(b _arg1) in F:\\workspace\\_work\\1\\s\\src\\fsharp\\FSharp.Core\\async.fs:line 584\n   at Microsoft.FSharp.Control.AsyncPrimitives.CallThenContinue[a,b](FSharpFunc`2 userCode, a arg, AsyncActivation`1 ctxt) in F:\\workspace\\_work\\1\\s\\src\\fsharp\\FSharp.Core\\async.fs:line 366\n   at <StartupCode$Emulsion>.$XmppMessageSystem.RunAsync@25-14.Invoke(AsyncActivation`1 ctxt) in /app/Emulsion/Xmpp/XmppMessageSystem.fs:line 25\n   at Emulsion.MessageSystem.RunAsync@73-4.Invoke(AsyncActivation`1 ctxt) in /app/Emulsion/MessageSystem.fs:line 73\n   at Microsoft.FSharp.Control.AsyncPrimitives.unitAsync@577.Invoke(AsyncActivation`1 ctxt) in F:\\workspace\\_work\\1\\s\\src\\fsharp\\FSharp.Core\\async.fs:line 577\n   at Microsoft.FSharp.Control.Trampoline.Execute(FSharpFunc`2 firstAction) in F:\\workspace\\_work\\1\\s\\src\\fsharp\\FSharp.Core\\async.fs:line 104","Properties":{"EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:16:33.0944121+00:00","Level":"Information","MessageTemplate":"Waiting for {RestartCooldown} to restart the message system","Properties":{"RestartCooldown":"00:00:30","EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:17:03.0975603+00:00","Level":"Information","MessageTemplate":"Connecting to the server","Properties":{"EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:17:36.5163523+00:00","Level":"Verbose","MessageTemplate":"XMPP stanza ({Direction}): {Stanza}","Properties":{"Direction":"incoming","Stanza":"<stream:features xmlns:stream=\"http://etherx.jabber.org/streams\">\n  <c xmlns=\"http://jabber.org/protocol/caps\" hash=\"sha-1\" node=\"http://www.process-one.net/en/ejabberd/\" ver=\"FCFOhNhFLEkQRjI8LiDmfRvdV1w=\" /> \n<register xmlns=\"http://jabber.org/features/iq-register\" />\n<starttls xmlns=\"urn:ietf:params:xml:ns:xmpp-tls\" />\n<compression xmlns=\"http://jabber.org/features/compress\"><method>zlib</method></compression> \n<push xmlns=\"p1:push\" /> \n<rebind xmlns=\"p1:rebind\" /> \n<ack xmlns=\"p1:ack\" />\n<mechanisms xmlns=\"urn:ietf:params:xml:ns:xmpp-sasl\"><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism><mechanism>X-OAUTH2</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms> \n</stream:features>","EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:17:36.5166547+00:00","Level":"Verbose","MessageTemplate":"XMPP stanza ({Direction}): {Stanza}","Properties":{"Direction":"outgoing","Stanza":"<starttls xmlns=\"urn:ietf:params:xml:ns:xmpp-tls\" />","EventCategory":"Xmpp"}}
{"Timestamp":"2021-09-12T22:17:39.4675447+00:00","Level":"Verbose","MessageTemplate":"XMPP stanza ({Direction}): {Stanza}","Properties":{"Direction":"incoming","Stanza":"<proceed xmlns=\"urn:ietf:params:xml:ns:xmpp-tls\" />","EventCategory":"Xmpp"}}

After this, nothing.

The server is expected to send us the following message (dump taken from a previous, successful reconnection attempt):

<stream:features xmlns:stream="http://etherx.jabber.org/streams">
  <c xmlns="http://jabber.org/protocol/caps" hash="sha-1" node="http://www.process-one.net/en/ejabberd/" ver="FCFOhNhFLEkQRjI8LiDmfRvdV1w=" /> 
<register xmlns="http://jabber.org/features/iq-register" />
<compression xmlns="http://jabber.org/features/compress"><method>zlib</method></compression>
<push xmlns="p1:push" /> 
<rebind xmlns="p1:rebind" /> 
<ack xmlns="p1:ack" /> 
<mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism><mechanism>X-OAUTH2</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms>
</stream:features>

But, this time, it sent us nothing at all. So, we're endlessly waiting for something from it, but nothing comes in this place:

emulsion/Emulsion/Xmpp/XmppClient.fs

Lines 32 to 39 in 68649ea

	let connect (client: IXmppClient): Async<Lifetime> = async {
	let connectionLifetime = new LifetimeDefinition()
	client.AddConnectionFailedHandler connectionLifetime.Lifetime <| fun _ ->
	connectionLifetime.Terminate()
	do! client.Connect()
	return connectionLifetime.Lifetime
	}

I've tried restarting the XMPP server and even disabling the network on computer to make the socket to terminate and connection to proceed, but it didn't worked. We lost a bunch of data.

So, useful information:

1. There seems to be a problem with SharpXMPP when it doesn't call any ConnectionFailedHandler if the connection was terminated at this place.
2. We're lacking a connection timeout here.
3. No matter how reliable our network code is, Message enforcement architecture #24 should be implemented. Otherwise, we'll keep losing data on bot reboots.

[ForNeVeR]

Linked: vitalyster/SharpXMPP#109.