diff --git a/common/client-core/src/client/mix_traffic/mod.rs b/common/client-core/src/client/mix_traffic/mod.rs index a08ebfbedc..3223cf77af 100644 --- a/common/client-core/src/client/mix_traffic/mod.rs +++ b/common/client-core/src/client/mix_traffic/mod.rs @@ -62,7 +62,7 @@ impl MixTrafficController { async fn on_messages(&mut self, mut mix_packets: Vec) { debug_assert!(!mix_packets.is_empty()); - info!("MixTrafficController: Sending {} sphinx packets to the gateway", mix_packets.len()); + info!("JON: MixTrafficController: Sending {} sphinx packets to the gateway", mix_packets.len()); let result = if mix_packets.len() == 1 { let mix_packet = mix_packets.pop().unwrap(); @@ -73,7 +73,7 @@ impl MixTrafficController { .await }; - match result { + let r = match result { Err(err) => { error!("Failed to send sphinx packet(s) to the gateway: {err}"); self.consecutive_gateway_failure_count += 1; @@ -87,7 +87,9 @@ impl MixTrafficController { trace!("We *might* have managed to forward sphinx packet(s) to the gateway!"); self.consecutive_gateway_failure_count = 0; } - } + }; + info!("JON: MixTrafficController: done sending sphinx packets to the gateway"); + r } pub fn start_with_shutdown(mut self, mut shutdown: nym_task::TaskClient) { @@ -99,23 +101,27 @@ impl MixTrafficController { loop { tokio::select! { + biased; + // _ = shutdown.recv_with_delay() => { + _ = &mut shutdown0 => { + log::trace!("MixTrafficController: Received shutdown"); + break; + } mix_packets = self.mix_rx.recv() => match mix_packets { Some(mix_packets) => { - let r = tokio::time::timeout(tokio::time::Duration::from_secs(4), self.on_messages(mix_packets)).await; - if r.is_err() { - error!("MixTrafficController: Failed to send mix packets to the gateway"); - } + log::info!("JON: MixTrafficController: mix_rx recv"); + self.on_messages(mix_packets).await; + // let r = tokio::time::timeout(tokio::time::Duration::from_secs(4), self.on_messages(mix_packets)).await; + // if r.is_err() { + // error!("MixTrafficController: Failed to send mix packets to the gateway"); + // } + log::info!("JON: MixTrafficController: done with mix_rx recv"); }, None => { log::trace!("MixTrafficController: Stopping since channel closed"); break; } }, - // _ = shutdown.recv_with_delay() => { - _ = &mut shutdown0 => { - log::trace!("MixTrafficController: Received shutdown"); - break; - } } } // shutdown.recv_timeout().await; diff --git a/common/client-core/src/client/mix_traffic/transceiver.rs b/common/client-core/src/client/mix_traffic/transceiver.rs index 0a8bdc6a2b..b7202f031a 100644 --- a/common/client-core/src/client/mix_traffic/transceiver.rs +++ b/common/client-core/src/client/mix_traffic/transceiver.rs @@ -79,8 +79,10 @@ impl GatewayTransceiver for Box { impl GatewaySender for Box { #[inline] async fn send_mix_packet(&mut self, packet: MixPacket) -> Result<(), ErasedGatewayError> { - log::info!("Box::send_mix_packet - sending a packet"); - (**self).send_mix_packet(packet).await + log::info!("JON: Box::send_mix_packet - sending a packet"); + let r = (**self).send_mix_packet(packet).await; + log::info!("JON: Box::send_mix_packet - sent a packet"); + r } #[inline] @@ -88,7 +90,10 @@ impl GatewaySender for Box { &mut self, packets: Vec, ) -> Result<(), ErasedGatewayError> { - (**self).batch_send_mix_packets(packets).await + log::info!("JON: Box::batch_send_mix_packets - sending {} packets", packets.len()); + let r = (**self).batch_send_mix_packets(packets).await; + log::info!("JON: Box::batch_send_mix_packets - sent packets"); + r } } @@ -132,22 +137,26 @@ where St: Send, { async fn send_mix_packet(&mut self, packet: MixPacket) -> Result<(), ErasedGatewayError> { - log::info!("RemoteGateway::send_mix_packet - sending a packet"); - self.gateway_client + log::info!("JON: RemoteGateway::send_mix_packet - sending a packet"); + let r = self.gateway_client .send_mix_packet(packet) .await - .map_err(erase_err) + .map_err(erase_err); + log::info!("JON: RemoteGateway::send_mix_packet - sent a packet"); + r } async fn batch_send_mix_packets( &mut self, packets: Vec, ) -> Result<(), ErasedGatewayError> { - log::info!("RemoteGateway::batch_send_mix_packets - sending {} packets", packets.len()); - self.gateway_client + log::info!("JON: RemoteGateway::batch_send_mix_packets - sending {} packets", packets.len()); + let r = self.gateway_client .batch_send_mix_packets(packets) .await - .map_err(erase_err) + .map_err(erase_err); + log::info!("JON: RemoteGateway::batch_send_mix_packets - sent packets"); + r } } @@ -207,11 +216,13 @@ mod nonwasm_sealed { #[async_trait] impl GatewaySender for LocalGateway { async fn send_mix_packet(&mut self, packet: MixPacket) -> Result<(), ErasedGatewayError> { - log::info!("LocalGateway::send_mix_packet - sending a packet"); - self.packet_forwarder + log::info!("JON: LocalGateway::send_mix_packet - sending a packet"); + let r = self.packet_forwarder .unbounded_send(packet) .map_err(|err| err.into_send_error()) - .map_err(erase_err) + .map_err(erase_err); + log::info!("JON: LocalGateway::send_mix_packet - sent a packet"); + r } } diff --git a/common/client-core/src/client/real_messages_control/message_handler.rs b/common/client-core/src/client/real_messages_control/message_handler.rs index 42a1993844..42578919ce 100644 --- a/common/client-core/src/client/real_messages_control/message_handler.rs +++ b/common/client-core/src/client/real_messages_control/message_handler.rs @@ -632,15 +632,23 @@ where } pub(crate) fn update_ack_delay(&self, id: FragmentIdentifier, new_delay: Delay) { - self.action_sender + if self + .action_sender .unbounded_send(Action::UpdateDelay(id, new_delay)) - .expect("action control task has died") + .is_err() + { + log::debug!("action control task has died"); + } } pub(crate) fn insert_pending_acks(&self, pending_acks: Vec) { - self.action_sender + if self + .action_sender .unbounded_send(Action::new_insert(pending_acks)) - .expect("action control task has died") + .is_err() + { + log::debug!("action control task has died"); + } } // tells real message sender (with the poisson timer) to send this to the mix network diff --git a/common/client-core/src/client/real_messages_control/real_traffic_stream.rs b/common/client-core/src/client/real_messages_control/real_traffic_stream.rs index ef91208f1b..6a5f0a99d1 100644 --- a/common/client-core/src/client/real_messages_control/real_traffic_stream.rs +++ b/common/client-core/src/client/real_messages_control/real_traffic_stream.rs @@ -198,7 +198,9 @@ where // queues and client load rather than the required delay. So realistically we can treat // whatever is about to happen as negligible additional delay. trace!("{} is about to get sent to the mixnet", frag_id); - self.sent_notifier.unbounded_send(frag_id).unwrap(); + if self.sent_notifier.unbounded_send(frag_id).is_err() { + debug!("Failed to notify about sent packet"); + } } fn loop_cover_message_size(&mut self) -> PacketSize { @@ -270,7 +272,8 @@ where }; if let Err(err) = self.mix_tx.send(vec![next_message]).await { - log::error!("Failed to send: {err}"); + log::debug!("Failed to send: {err}"); + return; } else { let event = if fragment_id.is_some() { PacketStatisticsEvent::RealPacketSent(packet_size) diff --git a/common/client-libs/gateway-client/src/client.rs b/common/client-libs/gateway-client/src/client.rs index 425a3e37bc..cfd87b1e28 100644 --- a/common/client-libs/gateway-client/src/client.rs +++ b/common/client-libs/gateway-client/src/client.rs @@ -333,6 +333,7 @@ impl GatewayClient { &mut self, msg: Message, ) -> Result { + log::info!("JON: GatewayClient: send_websocket_message"); let should_restart_mixnet_listener = if self.connection.is_partially_delegated() { self.recover_socket_connection().await?; true @@ -351,6 +352,7 @@ impl GatewayClient { if should_restart_mixnet_listener { self.start_listening_for_mixnet_messages()?; } + log::info!("JON: GatewayClient: send_websocket_message done"); response } @@ -358,8 +360,8 @@ impl GatewayClient { &mut self, messages: Vec, ) -> Result<(), GatewayClientError> { - log::info!("GatewayClient: Sending a batch of messages to the gateway"); - match self.connection { + log::info!("JON: GatewayClient: batch_send_websocket_messages_without_response"); + let r = match self.connection { SocketState::Available(ref mut conn) => { let stream_messages: Vec<_> = messages.into_iter().map(Ok).collect(); let mut send_stream = futures::stream::iter(stream_messages); @@ -382,14 +384,17 @@ impl GatewayClient { } SocketState::NotConnected => Err(GatewayClientError::ConnectionNotEstablished), _ => Err(GatewayClientError::ConnectionInInvalidState), - } + }; + log::info!("JON: GatewayClient: batch_send_websocket_messages_without_response done"); + r } async fn send_websocket_message_without_response( &mut self, msg: Message, ) -> Result<(), GatewayClientError> { - match self.connection { + log::info!("JON: GatewayClient: send_websocket_message_without_response"); + let r = match self.connection { SocketState::Available(ref mut conn) => Ok(conn.send(msg).await?), SocketState::PartiallyDelegated(ref mut partially_delegated) => { if let Err(err) = partially_delegated.send_without_response(msg).await { @@ -405,7 +410,9 @@ impl GatewayClient { } SocketState::NotConnected => Err(GatewayClientError::ConnectionNotEstablished), _ => Err(GatewayClientError::ConnectionInInvalidState), - } + }; + log::info!("JON: GatewayClient: send_websocket_message_without_response done"); + r } fn check_gateway_protocol( @@ -659,7 +666,7 @@ impl GatewayClient { &mut self, packets: Vec, ) -> Result<(), GatewayClientError> { - info!("GatewayClient: Sending {} sphinx packets to the gateway", packets.len()); + info!("JON: GatewayClient: batch_send_mix_packets"); debug!("Sending {} mix packets", packets.len()); if !self.authenticated { @@ -686,7 +693,7 @@ impl GatewayClient { }) .collect(); - if let Err(err) = self + let r = if let Err(err) = self .batch_send_websocket_messages_without_response(messages) .await { @@ -698,15 +705,17 @@ impl GatewayClient { } } else { Ok(()) - } + }; + log::info!("JON: GatewayClient: batch_send_mix_packets done"); + r } async fn send_with_reconnection_on_failure( &mut self, msg: Message, ) -> Result<(), GatewayClientError> { - log::info!("GatewayClient: Sending a message to the gateway"); - if let Err(err) = self.send_websocket_message_without_response(msg).await { + log::info!("JON: GatewayClient: send_with_reconnection_on_failure"); + let r = if let Err(err) = self.send_websocket_message_without_response(msg).await { if err.is_closed_connection() && self.should_reconnect_on_failure { debug!("Going to attempt a reconnection"); self.attempt_reconnection().await @@ -716,7 +725,9 @@ impl GatewayClient { } } else { Ok(()) - } + }; + log::info!("JON: GatewayClient: send_with_reconnection_on_failure done"); + r } pub async fn send_ping_message(&mut self) -> Result<(), GatewayClientError> { @@ -735,7 +746,7 @@ impl GatewayClient { &mut self, mix_packet: MixPacket, ) -> Result<(), GatewayClientError> { - log::info!("GatewayClient: Sending a sphinx packet to the gateway"); + log::info!("JON: GatewayClient: send_mix_packet"); if !self.authenticated { return Err(GatewayClientError::NotAuthenticated); } @@ -755,7 +766,9 @@ impl GatewayClient { .as_ref() .expect("no shared key present even though we're authenticated!"), ); - self.send_with_reconnection_on_failure(msg).await + let r = self.send_with_reconnection_on_failure(msg).await; + log::info!("JON: GatewayClient: send_mix_packet done"); + r } async fn recover_socket_connection(&mut self) -> Result<(), GatewayClientError> { diff --git a/common/client-libs/gateway-client/src/socket_state.rs b/common/client-libs/gateway-client/src/socket_state.rs index 54c02f8998..592aa392c6 100644 --- a/common/client-libs/gateway-client/src/socket_state.rs +++ b/common/client-libs/gateway-client/src/socket_state.rs @@ -217,16 +217,31 @@ impl PartiallyDelegated { &mut self, msg: Message, ) -> Result<(), GatewayClientError> { - Ok(self.sink_half.send(msg).await?) + log::info!("JON: PartiallyDelegated::send_without_response - sending a message"); + // let r = self.sink_half.send(msg).await; + // Ok(r?) + let r = tokio::time::timeout(Duration::from_secs(3), self.sink_half.send(msg)).await; + let rr = match r { + Ok(rr) => rr, + Err(_) => { + log::error!("JON: PartiallyDelegated::send_without_response - timeout sending a message"); + Ok(()) + } + }; + log::info!("JON: PartiallyDelegated::send_without_response - sent a message: {rr:?}"); + Ok(rr?) } pub(crate) async fn batch_send_without_response( &mut self, messages: Vec, ) -> Result<(), GatewayClientError> { + log::info!("JON: PartiallyDelegated::batch_send_without_response - sending {} messages", messages.len()); let stream_messages: Vec<_> = messages.into_iter().map(Ok).collect(); let mut send_stream = futures::stream::iter(stream_messages); - Ok(self.sink_half.send_all(&mut send_stream).await?) + let r = Ok(self.sink_half.send_all(&mut send_stream).await?); + log::info!("JON: PartiallyDelegated::batch_send_without_response - sent messages"); + r } pub(crate) async fn merge(self) -> Result {