Akka.Logging: v1.5.21 appears to have truncated log source, timestamps, etc from all log messages

[Aaronontheweb]

Version Information
Version of Akka.NET? 1.5.21
Which Akka.NET Modules? Akka

Describe the bug

Some sample cluster logs using src\examples\Cluster\Samples.Cluster.Simple from v1.5.20 (ignore the v1.5.15 assembly version in the logs - that's just because I haven't updated Directory.Build.props):

[INFO][06/14/2024 00:14:24.448Z][Thread 0001][remoting (akka://ClusterSystem)] Starting remoting
[INFO][06/14/2024 00:14:24.759Z][Thread 0001][remoting (akka://ClusterSystem)] Remoting started; listening on addresses : [akka.tcp://ClusterSystem@localhost:2551]
[INFO][06/14/2024 00:14:24.760Z][Thread 0001][remoting (akka://ClusterSystem)] Remoting now listens on addresses: [akka.tcp://ClusterSystem@localhost:2551]
[INFO][06/14/2024 00:14:24.813Z][Thread 0001][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Starting up...
[INFO][06/14/2024 00:14:24.861Z][Thread 0001][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Started up successfully [INFO][06/14/2024 00:14:24.915Z][Thread 0001][remoting (akka://ClusterSystem)] Starting remoting
[INFO][06/14/2024 00:14:24.923Z][Thread 0001][remoting (akka://ClusterSystem)] Remoting started; listening on addresses : [akka.tcp://ClusterSystem@localhost:2552]
[INFO][06/14/2024 00:14:24.923Z][Thread 0001][remoting (akka://ClusterSystem)] Remoting now listens on addresses: [akka.tcp://ClusterSystem@localhost:2552]
[INFO][06/14/2024 00:14:24.924Z][Thread 0001][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Starting up...
[INFO][06/14/2024 00:14:24.926Z][Thread 0001][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Started up successfully [INFO][06/14/2024 00:14:24.960Z][Thread 0001][remoting (akka://ClusterSystem)] Starting remoting
[INFO][06/14/2024 00:14:24.965Z][Thread 0001][remoting (akka://ClusterSystem)] Remoting started; listening on addresses : [akka.tcp://ClusterSystem@localhost:63366]
[INFO][06/14/2024 00:14:24.965Z][Thread 0001][remoting (akka://ClusterSystem)] Remoting now listens on addresses: [akka.tcp://ClusterSystem@localhost:63366]
[INFO][06/14/2024 00:14:24.966Z][Thread 0001][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:63366] - Starting up...
Press any key to exit
[INFO][06/14/2024 00:14:24.969Z][Thread 0001][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:63366] - Started up successfully

[INFO][06/14/2024 00:14:25.310Z][Thread 0020][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:2552/system/cluster/core/daemon/joinSeedNodeProcess-1#28110567]], but this node is not initialized yet
[INFO][06/14/2024 00:14:25.310Z][Thread 0029][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:2551/system/cluster/core/daemon/firstSeedNodeProcess-1#1826990885]], but this node is not initialized yet
[INFO][06/14/2024 00:14:25.310Z][Thread 0020][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:63366/system/cluster/core/daemon/joinSeedNodeProcess-1#1948704554]], but this node is not initialized yet
[INFO][06/14/2024 00:14:25.311Z][Thread 0029][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:63366/system/cluster/core/daemon/joinSeedNodeProcess-1#1948704554]], but this node is not initialized yet
[INFO][06/14/2024 00:14:25.321Z][Thread 0018][akka.tcp://ClusterSystem@localhost:2551/system/cluster/core/daemon/firstSeedNodeProcess-1] Received InitJoinNack message from [akka.tcp://ClusterSystem@localhost:2552] to [akka.tcp://ClusterSystem@localhost:2551]
[INFO][06/14/2024 00:14:25.343Z][Thread 0006][Cluster (akka://ClusterSystem)] Cluster Node [1.5.15] - Node [akka.tcp://ClusterSystem@localhost:2551] is JOINING itself (with roles [], version [1.5.15]) and forming a new cluster
[INFO][06/14/2024 00:14:25.346Z][Thread 0006][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - is the new leader among reachable nodes (more leaders may exist)
[INFO][06/14/2024 00:14:25.372Z][Thread 0006][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Leader is moving node [akka.tcp://ClusterSystem@localhost:2551] to [Up]
[INFO][06/14/2024 00:14:25.379Z][Thread 0029][akka.tcp://ClusterSystem@localhost:2551/user/clusterListener] Member is Up: Member(address = akka.tcp://ClusterSystem@localhost:2551, Uid=1669069156 status = Up, role=[], upNumber=1, version=1.5.15)
[INFO][06/14/2024 00:14:25.384Z][Thread 0009][akka.tcp://ClusterSystem@localhost:2551/system/cluster/core/daemon/downingProvider] This node is now the leader responsible for taking SBR decisions among the reachable nodes (more leaders may exist).
[INFO][06/14/2024 00:14:30.335Z][Thread 0019][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:63366/system/cluster/core/daemon/joinSeedNodeProcess-1#1948704554]], but this node is not initialized yet
[INFO][06/14/2024 00:14:30.335Z][Thread 0028][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:2552/system/cluster/core/daemon/joinSeedNodeProcess-1#28110567]] to [akka.tcp://ClusterSystem@localhost:2551]
[INFO][06/14/2024 00:14:30.336Z][Thread 0028][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Sending InitJoinAck message from node [akka.tcp://ClusterSystem@localhost:2551] to [[akka.tcp://ClusterSystem@localhost:2552/system/cluster/core/daemon/joinSeedNodeProcess-1#28110567]]
[INFO][06/14/2024 00:14:30.336Z][Thread 0028][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:63366/system/cluster/core/daemon/joinSeedNodeProcess-1#1948704554]] to [akka.tcp://ClusterSystem@localhost:2551]
[INFO][06/14/2024 00:14:30.336Z][Thread 0028][Cluster (akka://ClusterSystem)] Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Sending InitJoinAck message from node [akka.tcp://ClusterSystem@localhost:2551] to [[akka.tcp://ClusterSystem@localhost:63366/system/cluster/core/daemon/joinSeedNodeProcess-1#1948704554]]
[INFO][06/14/2024 00:14:30.348Z][Thread 0017][Cluster (akka://ClusterSystem)] Cluster Node [1.5.15] - Node [akka.tcp://ClusterSystem@localhost:63366] is JOINING, roles [], version [1.5.15]
[INFO][06/14/2024 00:14:30.348Z][Thread 0036][akka.tcp://ClusterSystem@localhost:2551/user/clusterListener] Member is joining Member(address = akka.tcp://ClusterSystem@localhost:63366, Uid=141162581 status = Joining, role=[], upNumber=2147483647, version=1.5.15)

These same logs in v1.5.21:

Starting remoting
Remoting started; listening on addresses : [akka.tcp://ClusterSystem@localhost:2551]
Remoting now listens on addresses: [akka.tcp://ClusterSystem@localhost:2551]
Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Starting up...
Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Started up successfully
Starting remoting
Remoting started; listening on addresses : [akka.tcp://ClusterSystem@localhost:2552]
Remoting now listens on addresses: [akka.tcp://ClusterSystem@localhost:2552]
Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Starting up...
Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Started up successfully
Remoting started; listening on addresses : [akka.tcp://ClusterSystem@localhost:53066]
Remoting now listens on addresses: [akka.tcp://ClusterSystem@localhost:53066]
Cluster Node [akka.tcp://ClusterSystem@localhost:53066] - Starting up...
Cluster Node [akka.tcp://ClusterSystem@localhost:53066] - Started up successfully
Press any key to exit
Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:2552/system/cluster/core/daemon/joinSeedNodeProcess-1#2066942798]], but this node is not initialized yet
Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:2551/system/cluster/core/daemon/firstSeedNodeProcess-1#1711006788]], but this node is not initialized yet
Cluster Node [akka.tcp://ClusterSystem@localhost:2552] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:53066/system/cluster/core/daemon/joinSeedNodeProcess-1#1436831115]], but this node is not initialized yet
Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Received InitJoin message from [[akka.tcp://ClusterSystem@localhost:53066/system/cluster/core/daemon/joinSeedNodeProcess-1#1436831115]], but this node is not initialized yet
Received InitJoinNack message from [akka.tcp://ClusterSystem@localhost:2552] to [akka.tcp://ClusterSystem@localhost:2551]
Cluster Node [1.5.15] - Node [akka.tcp://ClusterSystem@localhost:2551] is JOINING itself (with roles [], version [1.5.15]) and forming a new cluster
Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - is the new leader among reachable nodes (more leaders may exist)
Cluster Node [akka.tcp://ClusterSystem@localhost:2551] - Leader is moving node [akka.tcp://ClusterSystem@localhost:2551] to [Up]
Member is Up: Member(address = akka.tcp://ClusterSystem@localhost:2551, Uid=2144070636 status = Up, role=[], upNumber=1, version=1.5.15)
This node is now the leader responsible for taking SBR decisions among the reachable nodes (more leaders may exist).

We lost a lot of useful information here, and I think this is because we don't do any Verify-style tests on logging output. We'll need to add some regression testing to catch this type of stuff in the future.

Expected behavior

Logs should have preserved all of their original values.

Actual behavior

Logs are missing most of their contextual value.

Environment

Been able to reproduce this on Windows and Linux - platform doesn't make a difference.