{"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):
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:
There seems to be a problem with SharpXMPP when it doesn't call any ConnectionFailedHandler if the connection was terminated at this place.
We're lacking a connection timeout here.
No matter how reliable our network code is, #24 should be implemented. Otherwise, we'll keep losing data on bot reboots.
ForNeVeR
commented
2 years ago
I see the following in the logs from 2021-09-12:
After this, nothing.
The server is expected to send us the following message (dump taken from a previous, successful reconnection attempt):
But, this time, it sent us nothing at all. So, we're endlessly waiting for something from it, but nothing comes in this place: https://github.com/codingteam/emulsion/blob/68649ea0f8a26b3466f50d65b81339714283ac1d/Emulsion/Xmpp/XmppClient.fs#L32-L39
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:
ConnectionFailedHandlerif the connection was terminated at this place.