'Failed to parse body of event' exception

[Eternal21]

I'm trying to test the library with FreeSWITCH. I'm using the sample code, just subscribing to EventName.All, and checking if I can see the events. I noticed that I would only get an event or two, and then nothing (despite me placing SIP calls across FreeSWITCH, which should generate plenty).

To see what's going on, I added NLog to my test application, which resulted in the following output (pasted below).

It looks like the library throws 'Failed to parse body of event' exception and closes the socket (relevant class is here: https://github.com/danbarua/NEventSocket/blob/38bcd41c3ae6443f73067967b226488112ee01a1/src/NEventSocket/FreeSwitch/EventMessage.cs)

Any ideas?

`NLOG: TEST CLICKED!!!
'FsSockets.Gui.Wpf.vshost.exe' (CLR v4.0.30319: FsSockets.Gui.Wpf.vshost.exe): Loaded 'C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Dynamic\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.Dynamic.dll'. Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
'FsSockets.Gui.Wpf.vshost.exe' (CLR v4.0.30319: FsSockets.Gui.Wpf.vshost.exe): Loaded 'Anonymously Hosted DynamicMethods Assembly'. 
NLOG: EventSocket initialized
NLOG: NEventSocket.InboundSocket Worker Thread 1 started
NLOG: Messages Received [auth/request].
NLOG: Received Auth Request
NLOG: Sending [auth ClueCon]
NLOG: Messages Received [command/reply].
NLOG: CommandReply received [+OK accepted] for [auth ClueCon]
NLOG: InboundSocket authentication succeeded.
NLOG: Sending [api status]
NLOG: NEventSocket.InboundSocket Worker Thread 1 started
NLOG: Messages Received [api/response].
NLOG: ApiResponse received [UP 0 years, 0 days, 0 hours, 56 minutes, 8 seconds, 345 milliseconds, 987 microsecondsFreeSWITCH (Version 1.7.0  64bit) is ready18 session(s) since startup2 session(s) - peak 3, last 5min 2 0 session(s) per Sec out of max 30, peak 2, last 5min 0 1000 session(s) maxmin idle cpu 0.00/96.94] for [status]
UP 0 years, 0 days, 0 hours, 56 minutes, 8 seconds, 345 milliseconds, 987 microseconds
FreeSWITCH (Version 1.7.0  64bit) is ready
18 session(s) since startup
2 session(s) - peak 3, last 5min 2 
0 session(s) per Sec out of max 30, peak 2, last 5min 0 
1000 session(s) max
min idle cpu 0.00/96.94

NLOG: Sending [event plain ALL]
NLOG: NEventSocket.InboundSocket Worker Thread 1 started
NLOG: Messages Received [command/reply].
NLOG: CommandReply received [+OK event listener enabled plain] for [event plain ALL]
NLOG: NEventSocket.InboundSocket Worker Thread 1 started
NLOG: Messages Received [text/event-plain].
NLOG: EVENT: RecvRtcpMessage
NLOG: Messages Received [text/event-plain].
NLOG: EVENT: RecvRtcpMessage
NLOG: Messages Received [text/event-plain].
NLOG: EVENT: RecvRtcpMessage
NLOG: Messages Received [text/event-plain].
NLOG: Messages Received [].
NLOG: Messages Received [text/event-plain].
NLOG: Failed to parse body of event
NLOG: Unexpected Error reading from stream
NLOG: NEventSocket.InboundSocket Worker Thread 1 completed
NLOG: Disposing NEventSocket.InboundSocket (disposing:True)
NLOG: TcpClient closed
NLOG: NEventSocket.InboundSocket Worker Thread 1 completed
NLOG: NEventSocket.InboundSocket Worker Thread 1 completed
NLOG: NEventSocket.InboundSocket (1) Disposed
NLOG: 
NLOG: Unexpected Error reading from stream
NLOG: NEventSocket.InboundSocket Worker Thread 1 completed`

[Eternal21]

This doesn't happen when I run the same code inside InboundSocketExample obtained from git, so I either must be doing something wrong, or the Nuget version has an issue. I'll post back when I find what the problem is.

[Eternal21]

Not a problem with Nuget version, as I can get it working by staring a fresh Console application. I must be doing something wrong then.

[danbarua]

Hi,

I have seen very occasional heisenbugs which appear to be multiple socket read threads attempting to read from the same socket, which show garbled reads. These are easily detectable with TRACE level logging.

It's been fixed in this commit: https://github.com/danbarua/NEventSocket/commit/808405555f9275e59887ac4a73eac8c902141a8b which is in the unstable (2.0+) feed on MyGet.

I still have a few issues to iron out before publishing v 2.0 to NuGet but give that a go and see if that helps.

Otherwise, TRACE level logs always help get to the bottom of things.

[danbarua]

NLOG: NEventSocket.InboundSocket Worker Thread 1 started
<snip>
NLOG: NEventSocket.InboundSocket Worker Thread 1 started

Yep, ^ that's the culprit. I will see about getting a hotfix on the 1.0 version pushed to NuGet tomorrow.

[Eternal21]

Thanks for the response. After I replaced the Nuget dll 1.0.2 with the dll I built using latest master, I am getting the expected stream of events.

A simple console application works with 1.0.2, which is what fooled me above. But a project where I put the same code inside a class library, that's being run from a WPF client was not working with 1.0.2. (only after I used the master build, I was able to get it to run correctly).

[danbarua]

The joys of multithreaded async programming - this is why the TRACE level logs output a LOT of information, and why issues filed on Github are gratefully received.

[danbarua]

@Eternal21 thank you for confirming this issue - I have backported bugfixes onto the v1 branch and pushed v1.1.0 to NuGet

[Eternal21]

I grabbed the latest NuGet package (1.1.0), and it works as expected. Thanks.