Skip to content

Commit 962c841

Browse files
authored
Improve SSL certificate logging (#2284)
This PR improves the SSL verification failure logging from: ``` 2025-08-14T00:46:33Z app[48e4199b764518] iad level=notice msg="TLS :server: In state :certify at ssl_handshake.erl:2201 generated SERVER ALERT: Fatal - Handshake Failure - :unknown_ca" depth=20 report_cb=&:ssl_logger.format/1 ``` to ``` 2025-08-14T00:45:50Z app[48e4199b764518] iad level=info msg="SSL certificate verification failed" reason=":unknown_ca" event="nerves_hub.ssl.fail" cert_serial="1234" cert_subject="blah" ``` It involves some log filtering of messages from the Erlang SSL application, and then hooking into some telemetry we already send.
1 parent 2d4ec01 commit 962c841

File tree

4 files changed

+67
-20
lines changed

4 files changed

+67
-20
lines changed

.cspell.json

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -130,6 +130,7 @@
130130
"sockname",
131131
"spex",
132132
"ssljson",
133+
"statename",
133134
"statsd",
134135
"strftime",
135136
"stylesheet",

lib/nerves_hub/application.ex

Lines changed: 13 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -13,13 +13,7 @@ defmodule NervesHub.Application do
1313
end
1414

1515
setup_open_telemetry()
16-
17-
_ =
18-
:logger.add_handler(:my_sentry_handler, Sentry.LoggerHandler, %{
19-
config: %{metadata: [:file, :line]}
20-
})
21-
22-
NervesHub.Logger.attach()
16+
setup_logging()
2317

2418
children =
2519
[{Finch, name: Swoosh.Finch}] ++
@@ -48,6 +42,18 @@ defmodule NervesHub.Application do
4842
Supervisor.start_link(children, opts)
4943
end
5044

45+
defp setup_logging() do
46+
:ok =
47+
:logger.add_handler(:sentry_handler, Sentry.LoggerHandler, %{
48+
config: %{metadata: [:file, :line]}
49+
})
50+
51+
:ok =
52+
:logger.add_primary_filter(:filter_ssl_handshake, {&NervesHub.Logger.ssl_log_filter/2, []})
53+
54+
NervesHub.Logger.attach()
55+
end
56+
5157
defp setup_open_telemetry() do
5258
if System.get_env("ECTO_IPV6") do
5359
:ok = :httpc.set_option(:ipfamily, :inet6fb4)

lib/nerves_hub/logger.ex

Lines changed: 36 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,8 @@ defmodule NervesHub.Logger do
3535
[:nerves_hub, :devices, :update, :successful],
3636
[:nerves_hub, :managed_deployments, :set_deployment_group, :none_found],
3737
[:nerves_hub, :managed_deployments, :set_deployment_group, :one_found],
38-
[:nerves_hub, :managed_deployments, :set_deployment_group, :multiple_found]
38+
[:nerves_hub, :managed_deployments, :set_deployment_group, :multiple_found],
39+
[:nerves_hub, :ssl, :fail]
3940
]
4041

4142
Enum.each(events, fn event ->
@@ -165,6 +166,40 @@ defmodule NervesHub.Logger do
165166
)
166167
end
167168

169+
def log_event([:nerves_hub, :ssl, :fail], _, metadata, _) do
170+
Logger.info("SSL certificate verification failed",
171+
event: "nerves_hub.ssl.fail",
172+
reason: metadata[:reason],
173+
cert_serial: metadata[:cert_serial],
174+
cert_subject: metadata[:cert_subject]
175+
)
176+
end
177+
178+
@doc """
179+
The Erlang SSL application will log issues or failures related to verification of certificates.
180+
181+
This filter is designed to ignore SSL handshake errors that occur during the `:certify` state that are not helpful or hard to understand.
182+
183+
eg. TLS :server: In state :certify at ssl_handshake.erl:2201 generated SERVER ALERT: Fatal - Handshake Failure - :unknown_ca
184+
"""
185+
def ssl_log_filter(log_event, _opts) do
186+
case log_event do
187+
%{
188+
msg:
189+
{:report,
190+
%{
191+
alert: {:alert, _, _, %{file: ~c"ssl_handshake.erl"}, _, _},
192+
role: :server,
193+
statename: :certify
194+
}}
195+
} ->
196+
:stop
197+
198+
_ ->
199+
:ignore
200+
end
201+
end
202+
168203
# Helper functions
169204

170205
defp ignore_list() do

lib/nerves_hub/ssl.ex

Lines changed: 17 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -85,24 +85,16 @@ defmodule NervesHub.SSL do
8585
{:valid, state}
8686

8787
{:error, {:bad_cert, reason}} ->
88-
:telemetry.execute([:nerves_hub, :ssl, :fail], %{count: 1})
89-
90-
{:fail, reason}
88+
verify_failed(reason, otp_cert)
9189

9290
{:error, _} ->
93-
:telemetry.execute([:nerves_hub, :ssl, :fail], %{count: 1})
94-
95-
{:fail, :registration_failed}
91+
verify_failed(:registration_failed, otp_cert)
9692

9793
reason when is_atom(reason) ->
98-
:telemetry.execute([:nerves_hub, :ssl, :fail], %{count: 1})
99-
100-
{:fail, reason}
94+
verify_failed(reason, otp_cert)
10195

10296
_ ->
103-
:telemetry.execute([:nerves_hub, :ssl, :fail], %{count: 1})
104-
105-
{:fail, :unknown_server_error}
97+
verify_failed(:unknown_server_error, otp_cert)
10698
end
10799
end
108100

@@ -283,4 +275,17 @@ defmodule NervesHub.SSL do
283275
ski: Certificate.get_ski(otp_cert)
284276
}
285277
end
278+
279+
defp verify_failed(reason, otp_cert) do
280+
cert_serial = Certificate.get_serial_number(otp_cert)
281+
cert_subject = Certificate.get_common_name(otp_cert)
282+
283+
:telemetry.execute([:nerves_hub, :ssl, :fail], %{count: 1}, %{
284+
reason: reason,
285+
cert_serial: cert_serial,
286+
cert_subject: cert_subject
287+
})
288+
289+
{:fail, reason}
290+
end
286291
end

0 commit comments

Comments
 (0)