log noise due to timeouts
sasa1977 opened this issue · 2 comments
A timeout generates some log noise, because the transport session GenServer terminates with an abnormal reason. For example:
17:49:34.843 [info] Session #PID<0.330.0>, being stopped by timers(session_init_timer)
17:49:34.856 [info] Session #PID<0.330.0> stopped with reason: {:timers, :session_init_timer}, lost_pdus: []
17:49:34.863 [error] GenServer #PID<0.330.0> terminating
** (stop) {:timers, :session_init_timer}
Last message: {:check_timers, -576460738398}
State: %SMPPEX.TransportSession{buffer: "", mode: :mc, module: SMPPEX.Session, module_opts: [{SmppServer.Session, nil}, []], module_state: %SMPPEX.Session{auto_pdu_handler: %SMPPEX.Session.AutoPduHandler{by_ref: #Reference<0.451547869.4223270917.96940>, by_sequence_number: #Reference<0.451547869.4223270917.96939>}, module: SmppServer.Session, module_state: nil, pdus: %SMPPEX.PduStorage{by_sequence_number: #Reference<0.451547869.4223270917.96936>}, response_limit: 60000, sequence_number: 0, tick_timer_ref: #Reference<0.451547869.4223139845.97337>, time: -576460738398, timer_resolution: 100, timers: %SMPPEX.SMPPTimers{connection_time: -576460748497, enquire_link_limit: 30000, enquire_link_resp_limit: 30000, enquire_link_state: :active, inactivity_limit: :infinity, last_peer_action_time: 0, last_transaction_time: 0, session_init_limit: 10000, session_init_state: :established}}, ref: #Reference<0.451547869.4223139842.97123>, socket: #Port<0.7>, transport: :ranch_tcp}
17:49:34.881 [error] Ranch listener #Reference<0.451547869.4223139842.97123> had connection process started with SMPPEX.TransportSession:start_link/3 at #PID<0.330.0> exit with reason: {:timers, :session_init_timer}
I'd like to be able to suppress this noise. I did a quick experiment, and returning {:stop, :normal, [], st} here seems to do the job. I'm not super familiar with the codebase, so I might have missed something though.
To avoid silently breaking the existing behaviour, we could introduce the new callback called e.g. handle_timeout. This callback would receive the timeout reason, and it has to return the exit reason. The default implementation would generated by the __using__ macro would return {:timers, reason}. I'd also move this logger invocation to that function. So now, the stop clause in check timer boils down to: {:stop, reason} -> {:stop, st.module.handle_timeout(reason), st.module_state), [], st}.
Alternatively, we could even allow the client to decide if they want to stop the server or resume. Not sure if that makes sense though.
Let me know what you think. I'm also open to other ideas, but in any case I'd like to have the ability to remove these entries from the log. I'm of course willing to submitting a PR once we agree on an approach.
Hello!
The idea with handle_timeout callback timeout seems quite reasonable, a PR is welcome.
However, deciding not to stop breaks SMPP specs, so we are unlikely to expose this as an API until there are no significant reasons.
Ok, so then we'd only return the stop reason from handle_timeout. So something like:
@callback handle_timeout(timeout_reason :: term, state) :: exit_reason :: term?