[bug] Write sends every second message

[exapsy]

Describe the bug

WriteJSON/WriteMessage (didnt try others) writea response every second loop. But there are no signs of errors, and it just keeps doing the same thing.

The most strange thing, is that conn.WriteJSON / conn.WriteMessage seem to be called everytime! But the message seems to not reach the final light of the tunnel ...

…

Versions

Go version: golang:1.13.4-alpine3.10

…

Steps to Reproduce
Try to replicate the code snippet bellow I guess? Sorry, if I'm not being helpful here. But it seems like my bug is just conn.WriteJSON or whatever write functin there is. I dont know if that goes further than that.

…

Expected behavior

Write functions are supposed write every single message they are told to send, not every second one.

…

Code Snippets

// All origins allowed
upgrader.CheckOrigin = func(r *http.Request) bool { return true }
upgrader.WriteBufferSize = 8000
upgrader.ReadBufferSize = 8000
conn, _ := upgrader.Upgrade(w, r, nil)

// Server sending event
go func(conn *websocket.Conn) {
	defer conn.Close()
	for {
		msg := <-eventChannel // Replace this with your own pipe, timer or however you feel comfy
		err = conn.WriteJSON(
			msg,
		)
		fmt.Println("Sending msg", msg, err) // No signs of errors and it seems like `conn.WriteJSON` is called everytime!!
		if err != nil {
			// No write errors! WriteJSON is called without errors
			log.Println("write:", err)
			conn.Close()
		}
	}
}(conn)

…

[ghost]

It's unlikely that the issue is with this package because the data is written to the operating system before conn.WriteJSON(msg) returns.

If you have not already done so, run the application with the race detector.

The code in the issue is suspect. After the connection fails, the write loop will spin forever receiving and discarding values from eventChannel. Is one of these zombie goroutines running?

[exapsy]

Is one of these zombie goroutines running?

Sorry hadn't much experience with go routines yet. How do I test if any zombie routines are running if I may ask? Unless this is a part of the race detector which I'm currently trying to implement as you proposed.

[exapsy]

Sorry for duplicate message. But I thought it should be mentioned.

It's always the 2nd message that is send. No matter the delay between the messages. It feels so robust that it's like there is a condition where it says "if it's not the second message, dont send this" (which yes of course that would be ridiculous hahaha, but I hope you get what I mean by this).

It doesn't feel like it's a race issue. Usually in race issues the delay matters afaik. Here it doesn't. It's always the 2nd message that is send. Unless I'm not getting this right.

[ghost]

You will see output from the log.Println("write:", err) statement when the goroutine is discarding messages.

Fix the goroutine by replacing the call to conn.Close() with a break statement or a return statement.

Are two goroutines receiving from eventChannel? That will create the symptom that you described.

It only takes a minute to run the race detector (build with the -race flag and run). Highly recommend given that you are new goroutines.

[exapsy]

Fix the goroutine by replacing the call to conn.Close() with a break statement or a return statement.

What do you mean by that? What part of my call should I replace? :) It already has defer conn.Close() and when err then conn.Close()

Are two goroutines receiving from eventChannel? That will create the symptom that you described.

The only goroutine that is receiving from eventChannel is this one described in the post

It only takes a minute to run the race detector (build with the -race flag and run). Highly recommend given that you are new goroutines.

Where will the output appear? It seems like there is no feedback on the compilation, I dont know if I should expect it in the runtime or something. :)

[ghost]

Find the statement conn.Close(). Replace that statement with either return or break. Do not modify the statement defer conn.Close(). The actual fix is adding the return or break. The loop will run forever without one of these statements. Deleting the conn.Close() statement removes a redundant call to Close().

go func(conn *websocket.Conn) {
	defer conn.Close()
	for {
		msg := <-eventChannel // Replace this with your own pipe, timer or however you feel comfy
		err = conn.WriteJSON(
			msg,
		)
		fmt.Println("Sending msg", msg, err) // No signs of errors and it seems like `conn.WriteJSON` is called everytime!!
		if err != nil {
			// No write errors! WriteJSON is called without errors
			log.Println("write:", err)
			return
		}
	}
}(conn)

The log.Println("write:", err) statement writes to stderr unless the application modified the default logger to write somewhere else. The statement is executed at runtime.

[exapsy]

I tried go -race ./main.go but no luck with it outputting any warnings about any race issue.
Note: It took me some time because I have been using docker and it was a trouble for --race to work on alpine :D

Find the statement conn.Close(). Replace that statement with either return or break. Do not modify the statement defer conn.Close().

I did that. You're right, I shouldn't have called conn.Close() again :) For the record it didn't change anything regarding this issue, but thanx for pointing it out!

[ghost]

I don't have any more suggestions on how to debug the application. There is insufficient information debug reproduce the problem. Hopefully somebody else will chime in.

[exapsy]

@srybacki I dont know if this might be of use, but this is the repository file in the repository that hosts the whole app.
https://gitlab.com/gphub/app/blob/dev/internal/app/handlers/websockets/collectionRecordFieldChange.event.go

I dont know if I missed any necessary information regarding this issue in particular, but pardon me if I missed any significant debugging info.

[ghost]

There's a data race. Two goroutines write concurrently to the connection with no synchronization between them. Fix by running a single goroutine with a select on <-eventChannel and
<-errChangeRecordFieldEvent. This race was not triggered when you ran the race detector.

Multiple goroutines can receive on eventChannel. The call h.collectionsService.SubscribeOnRecordFieldChange(collectionID, userID) returns the same channel to every subscriber. A value sent to the channel is received by only one of the subscribers. The every other message problem is likely outcome when there are two subscribers.

There are other issues with the application, but that's outside the scope of the websocket package. This issue can be closed.

[exapsy]

Yes, I think I get it now. Obviously the event is sent only once to one subscriber and it's not broadcasted to all of them. So I'll just have to make an array of channels in that case for each subscriber.
So, if I understand correctly, if I had N subscribers, then the message would be sent every N messages.

edit: And yes you are correct. The deeper I go from now on, the more issues I find with the application regarding its event-websocket nature and mechanics. Thanks for your feedback!

You helped much. Thanks for your time and effort.