Merge pull request #11975 from zmstone/1119-fix-socket-close-race-condition

fix(emqx_channel): do not log stale sock_close event as error

apps/emqx/src/emqx_channel.erl

@@ -1246,8 +1246,10 @@ handle_info(
         {ok, Channel3} -> {ok, ?REPLY_EVENT(disconnected), Channel3};
         Shutdown -> Shutdown
     end;
-handle_info({sock_closed, Reason}, Channel = #channel{conn_state = disconnected}) ->
-    ?SLOG(error, #{msg => "unexpected_sock_close", reason => Reason}),
+handle_info({sock_closed, _Reason}, Channel = #channel{conn_state = disconnected}) ->
+    %% This can happen as a race:
+    %% EMQX closes socket and marks 'disconnected' but 'tcp_closed' or 'ssl_closed'
+    %% is already in process mailbox
     {ok, Channel};
 handle_info(clean_authz_cache, Channel) ->
     ok = emqx_authz_cache:empty_authz_cache(),

apps/emqx_gateway_stomp/src/emqx_stomp_channel.erl

@@ -963,13 +963,12 @@ handle_info(
     NChannel = ensure_disconnected(Reason, Channel),
     shutdown(Reason, NChannel);
 handle_info(
-    {sock_closed, Reason},
+    {sock_closed, _Reason},
     Channel = #channel{conn_state = disconnected}
 ) ->
-    ?SLOG(error, #{
-        msg => "unexpected_sock_closed",
-        reason => Reason
-    }),
+    %% This can happen as a race:
+    %% EMQX closes socket and marks 'disconnected' but 'tcp_closed' or 'ssl_closed'
+    %% is already in process mailbox
     {ok, Channel};
 handle_info(clean_authz_cache, Channel) ->
     ok = emqx_authz_cache:empty_authz_cache(),

changes/ce/fix-11975.en.md

@@ -0,0 +1,5 @@
+Resolve redundant error logging on socket closure
+
+Addressed a race condition causing duplicate error logs when a socket is closed by both a peer and the server.
+Dual socket close events from the OS and EMQX previously led to excessive error logging.
+The fix improves event handling to avoid redundant error-level logging.