consensus: rename (*PeerState).ToJSON to MarshalJSON by mark-rushakoff · Pull Request #524 · cometbft/cometbft

mark-rushakoff · 2023-03-13T21:01:36Z

In (*PeerState).PickSendVote, there is a Debug-level log that includes the PeerState value as a logging field. By default, zerolog json-encodes a struct passed as a log field (when the struct doesn't implement zerolog.LogObjectMarshaler).

Because PeerState didn't have a MarshalJSON method, the JSON encoder fell back to reflection to encode the PeerState value. Reflection did not acquire the lock, and there were data races resulting from an unsynchronized read while logging the PeerState, and concurrent (locked) writes at least during (*PeerState).SetHasProposal and (*PeerState).SetHasVote.

Given that there was only one call to (*PeerState).ToJSON in the cometbft repo, it seemed appropriate to just rename ToJSON to MarshalJSON, as opposed to leaving ToJSON for backwards compatibility. Any third party calls to ToJSON should be able to easily change the method being called.

Example data race (which is no longer reproducible with this change):

==================
WARNING: DATA RACE
Read at 0x00c0004a4870 by goroutine 131:
  reflect.Value.Bool()
      /opt/homebrew/Cellar/go/1.20.1/libexec/src/reflect/value.go:288 +0x7c
  encoding/json.boolEncoder()
      /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:539 +0x88
  encoding/json.structEncoder.encode()
      /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc
  encoding/json.structEncoder.encode-fm()
      <autogenerated>:1 +0x94
  encoding/json.structEncoder.encode()
      /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc
  encoding/json.structEncoder.encode-fm()
      <autogenerated>:1 +0x94
  encoding/json.ptrEncoder.encode()
      /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:943 +0x2a4
  encoding/json.ptrEncoder.encode-fm()
      <autogenerated>:1 +0x6c
  encoding/json.(*encodeState).reflectValue()
      /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:358 +0x74
  encoding/json.(*encodeState).marshal()
      /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:330 +0x1a0
  encoding/json.Marshal()
      /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:161 +0xa0
  github.com/rs/zerolog.init.1.func1()
      /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/encoder_json.go:21 +0x4c
  github.com/rs/zerolog/internal/json.Encoder.AppendInterface()
      /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/internal/json/types.go:366 +0x5c
  github.com/rs/zerolog.appendFieldList()
      /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:273 +0x2b8c
  github.com/rs/zerolog.appendFields()
      /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:21 +0x160
  github.com/rs/zerolog.(*Event).Fields()
      /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/event.go:165 +0x90
  cosmossdk.io/log.zeroLogWrapper.Debug()
      /Users/hh/go/pkg/mod/cosmossdk.io/log@v0.0.0-20230313123454-0fe816b71a62/logger.go:89 +0x18
  github.com/cosmos/cosmos-sdk/server/log.(*CometZeroLogWrapper).Debug()
      <autogenerated>:1 +0x74
  github.com/cometbft/cometbft/consensus.(*PeerState).PickSendVote()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1138 +0x1bc
  github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesForHeight()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:794 +0x260
  github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesRoutine()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:724 +0x2cc
  github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func2()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x58

Previous write at 0x00c0004a4870 by goroutine 130:
  github.com/cometbft/cometbft/consensus.(*PeerState).SetHasProposal()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1096 +0x118
  github.com/cometbft/cometbft/consensus.(*Reactor).gossipDataRoutine()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:617 +0xab8
  github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func1()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x58

Goroutine 131 (running) created at:
  github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x240
  github.com/cometbft/cometbft/p2p.(*Switch).addPeer()
      /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4
  github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine()
      /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704
  github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1()
      /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34

Goroutine 130 (running) created at:
  github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer()
      /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x164
  github.com/cometbft/cometbft/p2p.(*Switch).addPeer()
      /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4
  github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine()
      /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704
  github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1()
      /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34
==================

PR checklist

Tests written/updated
Changelog entry added in .changelog (we use unclog to manage our changelog)
Updated relevant documentation (docs/ or spec/) and code comments

In (*PeerState).PickSendVote, there is a Debug-level log that includes the PeerState value as a logging field. By default, zerolog json-encodes a struct passed as a log field (when the struct doesn't implement zerolog.LogObjectMarshaler). Because PeerState didn't have a MarshalJSON method, the JSON encoder fell back to reflection to encode the PeerState value. Reflection did not acquire the lock, and there were data races resulting from an unsynchronized read while logging the PeerState, and concurrent (locked) writes at least during (*PeerState).SetHasProposal and (*PeerState).SetHasVote. Given that there was only one call to (*PeerState).ToJSON in the cometbft repo, it seemed appropriate to just rename ToJSON to MarshalJSON, as opposed to leaving ToJSON for backwards compatibility. Any third party calls to ToJSON should be able to easily change the method being called.

cason

Great find.

It appears that the renamed method is not used anywhere else, except in the RPC code addressed by this PR. So I would say that is not a breaking change.

mark-rushakoff · 2023-03-14T13:03:59Z

Thanks @cason, I moved the changelog entry from breaking changes to a bug fix in 0ed6fbf. Since this changed an exported method, I considered it arguably a breaking change, but bug fix also seems appropriate given the scope.

thanethomson

Thanks for this @mark-rushakoff! I'd say that this should probably be safe to backport to v0.37 and v0.34, given the scope of the change. If folks complain about it, we could always introduce a shim ToJSON method that just implicitly calls MarshalJSON.

.changelog/unreleased/bug-fixes/524-rename-peerstate-tojson.md

In (*PeerState).PickSendVote, there is a Debug-level log that includes the PeerState value as a logging field. By default, zerolog json-encodes a struct passed as a log field (when the struct doesn't implement zerolog.LogObjectMarshaler). Because PeerState didn't have a MarshalJSON method, the JSON encoder fell back to reflection to encode the PeerState value. Reflection did not acquire the lock, and there were data races resulting from an unsynchronized read while logging the PeerState, and concurrent (locked) writes at least during (*PeerState).SetHasProposal and (*PeerState).SetHasVote. Given that there was only one call to (*PeerState).ToJSON in the cometbft repo, it seemed appropriate to just rename ToJSON to MarshalJSON, as opposed to leaving ToJSON for backwards compatibility. Any third party calls to ToJSON should be able to easily change the method being called. Example data race (which is no longer reproducible with this change): ``` ================== WARNING: DATA RACE Read at 0x00c0004a4870 by goroutine 131: reflect.Value.Bool() /opt/homebrew/Cellar/go/1.20.1/libexec/src/reflect/value.go:288 +0x7c encoding/json.boolEncoder() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:539 +0x88 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.ptrEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:943 +0x2a4 encoding/json.ptrEncoder.encode-fm() <autogenerated>:1 +0x6c encoding/json.(*encodeState).reflectValue() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:358 +0x74 encoding/json.(*encodeState).marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:330 +0x1a0 encoding/json.Marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:161 +0xa0 github.com/rs/zerolog.init.1.func1() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/encoder_json.go:21 +0x4c github.com/rs/zerolog/internal/json.Encoder.AppendInterface() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/internal/json/types.go:366 +0x5c github.com/rs/zerolog.appendFieldList() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:273 +0x2b8c github.com/rs/zerolog.appendFields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:21 +0x160 github.com/rs/zerolog.(*Event).Fields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/event.go:165 +0x90 cosmossdk.io/log.zeroLogWrapper.Debug() /Users/hh/go/pkg/mod/cosmossdk.io/log@v0.0.0-20230313123454-0fe816b71a62/logger.go:89 +0x18 github.com/cosmos/cosmos-sdk/server/log.(*CometZeroLogWrapper).Debug() <autogenerated>:1 +0x74 github.com/cometbft/cometbft/consensus.(*PeerState).PickSendVote() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1138 +0x1bc github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesForHeight() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:794 +0x260 github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:724 +0x2cc github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func2() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x58 Previous write at 0x00c0004a4870 by goroutine 130: github.com/cometbft/cometbft/consensus.(*PeerState).SetHasProposal() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1096 +0x118 github.com/cometbft/cometbft/consensus.(*Reactor).gossipDataRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:617 +0xab8 github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func1() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x58 Goroutine 131 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x240 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 Goroutine 130 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x164 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 ================== ``` --- #### PR checklist - [ ] Tests written/updated - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [ ] Updated relevant documentation (`docs/` or `spec/`) and code comments (cherry picked from commit 587bc0b)

In (*PeerState).PickSendVote, there is a Debug-level log that includes the PeerState value as a logging field. By default, zerolog json-encodes a struct passed as a log field (when the struct doesn't implement zerolog.LogObjectMarshaler). Because PeerState didn't have a MarshalJSON method, the JSON encoder fell back to reflection to encode the PeerState value. Reflection did not acquire the lock, and there were data races resulting from an unsynchronized read while logging the PeerState, and concurrent (locked) writes at least during (*PeerState).SetHasProposal and (*PeerState).SetHasVote. Given that there was only one call to (*PeerState).ToJSON in the cometbft repo, it seemed appropriate to just rename ToJSON to MarshalJSON, as opposed to leaving ToJSON for backwards compatibility. Any third party calls to ToJSON should be able to easily change the method being called. Example data race (which is no longer reproducible with this change): ``` ================== WARNING: DATA RACE Read at 0x00c0004a4870 by goroutine 131: reflect.Value.Bool() /opt/homebrew/Cellar/go/1.20.1/libexec/src/reflect/value.go:288 +0x7c encoding/json.boolEncoder() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:539 +0x88 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.ptrEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:943 +0x2a4 encoding/json.ptrEncoder.encode-fm() <autogenerated>:1 +0x6c encoding/json.(*encodeState).reflectValue() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:358 +0x74 encoding/json.(*encodeState).marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:330 +0x1a0 encoding/json.Marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:161 +0xa0 github.com/rs/zerolog.init.1.func1() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/encoder_json.go:21 +0x4c github.com/rs/zerolog/internal/json.Encoder.AppendInterface() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/internal/json/types.go:366 +0x5c github.com/rs/zerolog.appendFieldList() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:273 +0x2b8c github.com/rs/zerolog.appendFields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:21 +0x160 github.com/rs/zerolog.(*Event).Fields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/event.go:165 +0x90 cosmossdk.io/log.zeroLogWrapper.Debug() /Users/hh/go/pkg/mod/cosmossdk.io/log@v0.0.0-20230313123454-0fe816b71a62/logger.go:89 +0x18 github.com/cosmos/cosmos-sdk/server/log.(*CometZeroLogWrapper).Debug() <autogenerated>:1 +0x74 github.com/cometbft/cometbft/consensus.(*PeerState).PickSendVote() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1138 +0x1bc github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesForHeight() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:794 +0x260 github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:724 +0x2cc github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func2() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x58 Previous write at 0x00c0004a4870 by goroutine 130: github.com/cometbft/cometbft/consensus.(*PeerState).SetHasProposal() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1096 +0x118 github.com/cometbft/cometbft/consensus.(*Reactor).gossipDataRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:617 +0xab8 github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func1() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x58 Goroutine 131 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x240 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 Goroutine 130 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x164 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 ================== ``` --- #### PR checklist - [ ] Tests written/updated - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [ ] Updated relevant documentation (`docs/` or `spec/`) and code comments (cherry picked from commit 587bc0b) # Conflicts: # .changelog/v0.37.0/bug-fixes/524-rename-peerstate-tojson.md

…532) * consensus: rename (*PeerState).ToJSON to MarshalJSON (#524) In (*PeerState).PickSendVote, there is a Debug-level log that includes the PeerState value as a logging field. By default, zerolog json-encodes a struct passed as a log field (when the struct doesn't implement zerolog.LogObjectMarshaler). Because PeerState didn't have a MarshalJSON method, the JSON encoder fell back to reflection to encode the PeerState value. Reflection did not acquire the lock, and there were data races resulting from an unsynchronized read while logging the PeerState, and concurrent (locked) writes at least during (*PeerState).SetHasProposal and (*PeerState).SetHasVote. Given that there was only one call to (*PeerState).ToJSON in the cometbft repo, it seemed appropriate to just rename ToJSON to MarshalJSON, as opposed to leaving ToJSON for backwards compatibility. Any third party calls to ToJSON should be able to easily change the method being called. Example data race (which is no longer reproducible with this change): ``` ================== WARNING: DATA RACE Read at 0x00c0004a4870 by goroutine 131: reflect.Value.Bool() /opt/homebrew/Cellar/go/1.20.1/libexec/src/reflect/value.go:288 +0x7c encoding/json.boolEncoder() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:539 +0x88 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.ptrEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:943 +0x2a4 encoding/json.ptrEncoder.encode-fm() <autogenerated>:1 +0x6c encoding/json.(*encodeState).reflectValue() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:358 +0x74 encoding/json.(*encodeState).marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:330 +0x1a0 encoding/json.Marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:161 +0xa0 github.com/rs/zerolog.init.1.func1() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/encoder_json.go:21 +0x4c github.com/rs/zerolog/internal/json.Encoder.AppendInterface() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/internal/json/types.go:366 +0x5c github.com/rs/zerolog.appendFieldList() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:273 +0x2b8c github.com/rs/zerolog.appendFields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:21 +0x160 github.com/rs/zerolog.(*Event).Fields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/event.go:165 +0x90 cosmossdk.io/log.zeroLogWrapper.Debug() /Users/hh/go/pkg/mod/cosmossdk.io/log@v0.0.0-20230313123454-0fe816b71a62/logger.go:89 +0x18 github.com/cosmos/cosmos-sdk/server/log.(*CometZeroLogWrapper).Debug() <autogenerated>:1 +0x74 github.com/cometbft/cometbft/consensus.(*PeerState).PickSendVote() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1138 +0x1bc github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesForHeight() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:794 +0x260 github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:724 +0x2cc github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func2() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x58 Previous write at 0x00c0004a4870 by goroutine 130: github.com/cometbft/cometbft/consensus.(*PeerState).SetHasProposal() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1096 +0x118 github.com/cometbft/cometbft/consensus.(*Reactor).gossipDataRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:617 +0xab8 github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func1() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x58 Goroutine 131 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x240 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 Goroutine 130 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x164 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 ================== ``` --- #### PR checklist - [ ] Tests written/updated - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [ ] Updated relevant documentation (`docs/` or `spec/`) and code comments (cherry picked from commit 587bc0b) # Conflicts: # .changelog/v0.37.0/bug-fixes/524-rename-peerstate-tojson.md * Move changelog entry to correct folder Signed-off-by: Thane Thomson <connect@thanethomson.com> --------- Signed-off-by: Thane Thomson <connect@thanethomson.com> Co-authored-by: Mark Rushakoff <mark.rushakoff@gmail.com> Co-authored-by: Thane Thomson <connect@thanethomson.com>

In (*PeerState).PickSendVote, there is a Debug-level log that includes the PeerState value as a logging field. By default, zerolog json-encodes a struct passed as a log field (when the struct doesn't implement zerolog.LogObjectMarshaler). Because PeerState didn't have a MarshalJSON method, the JSON encoder fell back to reflection to encode the PeerState value. Reflection did not acquire the lock, and there were data races resulting from an unsynchronized read while logging the PeerState, and concurrent (locked) writes at least during (*PeerState).SetHasProposal and (*PeerState).SetHasVote. Given that there was only one call to (*PeerState).ToJSON in the cometbft repo, it seemed appropriate to just rename ToJSON to MarshalJSON, as opposed to leaving ToJSON for backwards compatibility. Any third party calls to ToJSON should be able to easily change the method being called. Example data race (which is no longer reproducible with this change): ``` ================== WARNING: DATA RACE Read at 0x00c0004a4870 by goroutine 131: reflect.Value.Bool() /opt/homebrew/Cellar/go/1.20.1/libexec/src/reflect/value.go:288 +0x7c encoding/json.boolEncoder() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:539 +0x88 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.ptrEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:943 +0x2a4 encoding/json.ptrEncoder.encode-fm() <autogenerated>:1 +0x6c encoding/json.(*encodeState).reflectValue() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:358 +0x74 encoding/json.(*encodeState).marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:330 +0x1a0 encoding/json.Marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:161 +0xa0 github.com/rs/zerolog.init.1.func1() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/encoder_json.go:21 +0x4c github.com/rs/zerolog/internal/json.Encoder.AppendInterface() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/internal/json/types.go:366 +0x5c github.com/rs/zerolog.appendFieldList() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:273 +0x2b8c github.com/rs/zerolog.appendFields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:21 +0x160 github.com/rs/zerolog.(*Event).Fields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/event.go:165 +0x90 cosmossdk.io/log.zeroLogWrapper.Debug() /Users/hh/go/pkg/mod/cosmossdk.io/log@v0.0.0-20230313123454-0fe816b71a62/logger.go:89 +0x18 github.com/cosmos/cosmos-sdk/server/log.(*CometZeroLogWrapper).Debug() <autogenerated>:1 +0x74 github.com/cometbft/cometbft/consensus.(*PeerState).PickSendVote() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1138 +0x1bc github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesForHeight() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:794 +0x260 github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:724 +0x2cc github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func2() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x58 Previous write at 0x00c0004a4870 by goroutine 130: github.com/cometbft/cometbft/consensus.(*PeerState).SetHasProposal() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1096 +0x118 github.com/cometbft/cometbft/consensus.(*Reactor).gossipDataRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:617 +0xab8 github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func1() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x58 Goroutine 131 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x240 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 Goroutine 130 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x164 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 ================== ``` --- #### PR checklist - [ ] Tests written/updated - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [ ] Updated relevant documentation (`docs/` or `spec/`) and code comments (cherry picked from commit 587bc0b) Co-authored-by: Mark Rushakoff <mark.rushakoff@gmail.com> Co-authored-by: Thane Thomson <connect@thanethomson.com>

cason · 2023-06-12T07:47:06Z

Hey, this fix potentially introduced this problem: #865

…ft#524) (cometbft#532) * consensus: rename (*PeerState).ToJSON to MarshalJSON (cometbft#524) In (*PeerState).PickSendVote, there is a Debug-level log that includes the PeerState value as a logging field. By default, zerolog json-encodes a struct passed as a log field (when the struct doesn't implement zerolog.LogObjectMarshaler). Because PeerState didn't have a MarshalJSON method, the JSON encoder fell back to reflection to encode the PeerState value. Reflection did not acquire the lock, and there were data races resulting from an unsynchronized read while logging the PeerState, and concurrent (locked) writes at least during (*PeerState).SetHasProposal and (*PeerState).SetHasVote. Given that there was only one call to (*PeerState).ToJSON in the cometbft repo, it seemed appropriate to just rename ToJSON to MarshalJSON, as opposed to leaving ToJSON for backwards compatibility. Any third party calls to ToJSON should be able to easily change the method being called. Example data race (which is no longer reproducible with this change): ``` ================== WARNING: DATA RACE Read at 0x00c0004a4870 by goroutine 131: reflect.Value.Bool() /opt/homebrew/Cellar/go/1.20.1/libexec/src/reflect/value.go:288 +0x7c encoding/json.boolEncoder() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:539 +0x88 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.structEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:759 +0x1bc encoding/json.structEncoder.encode-fm() <autogenerated>:1 +0x94 encoding/json.ptrEncoder.encode() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:943 +0x2a4 encoding/json.ptrEncoder.encode-fm() <autogenerated>:1 +0x6c encoding/json.(*encodeState).reflectValue() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:358 +0x74 encoding/json.(*encodeState).marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:330 +0x1a0 encoding/json.Marshal() /opt/homebrew/Cellar/go/1.20.1/libexec/src/encoding/json/encode.go:161 +0xa0 github.com/rs/zerolog.init.1.func1() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/encoder_json.go:21 +0x4c github.com/rs/zerolog/internal/json.Encoder.AppendInterface() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/internal/json/types.go:366 +0x5c github.com/rs/zerolog.appendFieldList() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:273 +0x2b8c github.com/rs/zerolog.appendFields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/fields.go:21 +0x160 github.com/rs/zerolog.(*Event).Fields() /Users/hh/go/pkg/mod/github.com/rs/zerolog@v1.29.0/event.go:165 +0x90 cosmossdk.io/log.zeroLogWrapper.Debug() /Users/hh/go/pkg/mod/cosmossdk.io/log@v0.0.0-20230313123454-0fe816b71a62/logger.go:89 +0x18 github.com/cosmos/cosmos-sdk/server/log.(*CometZeroLogWrapper).Debug() <autogenerated>:1 +0x74 github.com/cometbft/cometbft/consensus.(*PeerState).PickSendVote() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1138 +0x1bc github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesForHeight() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:794 +0x260 github.com/cometbft/cometbft/consensus.(*Reactor).gossipVotesRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:724 +0x2cc github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func2() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x58 Previous write at 0x00c0004a4870 by goroutine 130: github.com/cometbft/cometbft/consensus.(*PeerState).SetHasProposal() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:1096 +0x118 github.com/cometbft/cometbft/consensus.(*Reactor).gossipDataRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:617 +0xab8 github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer.func1() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x58 Goroutine 131 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:199 +0x240 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 Goroutine 130 (running) created at: github.com/cometbft/cometbft/consensus.(*Reactor).AddPeer() /Users/hh/go/src/github.com/cometbft/cometbft/consensus/reactor.go:198 +0x164 github.com/cometbft/cometbft/p2p.(*Switch).addPeer() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:855 +0x7b4 github.com/cometbft/cometbft/p2p.(*Switch).acceptRoutine() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:707 +0x704 github.com/cometbft/cometbft/p2p.(*Switch).OnStart.func1() /Users/hh/go/src/github.com/cometbft/cometbft/p2p/switch.go:241 +0x34 ================== ``` --- #### PR checklist - [ ] Tests written/updated - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [ ] Updated relevant documentation (`docs/` or `spec/`) and code comments (cherry picked from commit 587bc0b) # Conflicts: # .changelog/v0.37.0/bug-fixes/524-rename-peerstate-tojson.md * Move changelog entry to correct folder Signed-off-by: Thane Thomson <connect@thanethomson.com> --------- Signed-off-by: Thane Thomson <connect@thanethomson.com> Co-authored-by: Mark Rushakoff <mark.rushakoff@gmail.com> Co-authored-by: Thane Thomson <connect@thanethomson.com>

mark-rushakoff requested a review from a team as a code owner March 13, 2023 21:01

Update changelog

0a56bf6

cason approved these changes Mar 14, 2023

View reviewed changes

Treat cometbft#524 as a bug fix, not a breaking change

0ed6fbf

Merge branch 'main' into peerstate-marshaljson

5149333

thanethomson added backport-to-v0.34.x labels Mar 14, 2023

thanethomson approved these changes Mar 14, 2023

View reviewed changes

.changelog/unreleased/bug-fixes/524-rename-peerstate-tojson.md Outdated Show resolved Hide resolved

thanethomson added 2 commits March 14, 2023 11:46

Update .changelog/unreleased/bug-fixes/524-rename-peerstate-tojson.md

9a09517

Merge branch 'main' into peerstate-marshaljson

1c7f60c

thanethomson added the automerge label Mar 14, 2023

mergify bot merged commit 587bc0b into cometbft:main Mar 14, 2023

This was referenced Mar 14, 2023

consensus: rename (*PeerState).ToJSON to MarshalJSON (backport #524) #532

Merged

consensus: rename (*PeerState).ToJSON to MarshalJSON (backport #524) #533

Merged

mark-rushakoff mentioned this pull request Apr 5, 2023

Data race in v0.37.0 when logging consensus.State as part of stopping consensus reactor #653

Open

thanethomson mentioned this pull request May 18, 2023

bug: Cometbft v0.34.28 breaks ICS downtime slashes #773

Closed

cason mentioned this pull request Jun 12, 2023

fix: avoid recursive call after rename to (*PeerState).MarshalJSON #865

Merged

3 tasks

GoVulnBot mentioned this pull request Jul 3, 2023

x/vulndb: potential Go vuln in github.com/cometbft/cometbft: CVE-2023-34450 golang/vulndb#1882

Closed

faddat mentioned this pull request Jan 5, 2024

faddat/reversions for fixed length ComposableFi/cometbft#2

Closed

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

consensus: rename (*PeerState).ToJSON to MarshalJSON#524

consensus: rename (*PeerState).ToJSON to MarshalJSON#524
mergify[bot] merged 6 commits intocometbft:mainfrom
mark-rushakoff:peerstate-marshaljson

mark-rushakoff commented Mar 13, 2023 •

edited

Loading

Uh oh!

cason left a comment

Uh oh!

mark-rushakoff commented Mar 14, 2023

Uh oh!

thanethomson left a comment

Uh oh!

Uh oh!

cason commented Jun 12, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Conversation

mark-rushakoff commented Mar 13, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

PR checklist

Uh oh!

cason left a comment

Choose a reason for hiding this comment

Uh oh!

mark-rushakoff commented Mar 14, 2023

Uh oh!

thanethomson left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

cason commented Jun 12, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

mark-rushakoff commented Mar 13, 2023 •

edited

Loading