Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fixed JSON request logging data race. #775

Merged
merged 1 commit into from Feb 19, 2024

Conversation

buglloc
Copy link
Contributor

@buglloc buglloc commented Feb 14, 2024

noescapeJSONMarshalIndent must either copy the buffer data or don't put it into the sync.Pool (similar to noescapeJSONMarshal). Otherwise, we could have a data race:

$ go test -run TestDebugLogSimultaneously -race
==================
WARNING: DATA RACE
Write at 0x00c00001e8c0 by goroutine 31:
  runtime.slicecopy()
      /usr/lib/go/src/runtime/slice.go:325 +0x0
  bytes.(*Buffer).Write()
      /usr/lib/go/src/bytes/buffer.go:181 +0x118
  github.com/go-resty/resty/v2.jsonMarshal()
      /home/buglloc/work/projects/resty/util.go:164 +0x158
  github.com/go-resty/resty/v2.handleRequestBody()
      /home/buglloc/work/projects/resty/middleware.go:507 +0x2e7
  github.com/go-resty/resty/v2.parseRequestBody()
      /home/buglloc/work/projects/resty/middleware.go:193 +0x290
  github.com/go-resty/resty/v2.(*Client).execute()
      /home/buglloc/work/projects/resty/client.go:1164 +0x5e5
  github.com/go-resty/resty/v2.(*Request).Execute()
      /home/buglloc/work/projects/resty/request.go:936 +0x4f9
  github.com/go-resty/resty/v2.(*Request).Post()
      /home/buglloc/work/projects/resty/request.go:862 +0x6ed
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously.func1()
      /home/buglloc/work/projects/resty/client_test.go:784 +0x6cb
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Previous read at 0x00c00001e8c0 by goroutine 32:
  runtime.slicebytetostring()
      /usr/lib/go/src/runtime/string.go:81 +0x0
  github.com/go-resty/resty/v2.(*Request).fmtBodyString()
      /home/buglloc/work/projects/resty/request.go:1037 +0x916
  github.com/go-resty/resty/v2.requestLogger()
      /home/buglloc/work/projects/resty/middleware.go:324 +0x3b0
  github.com/go-resty/resty/v2.(*Client).execute()
      /home/buglloc/work/projects/resty/client.go:1180 +0x84b
  github.com/go-resty/resty/v2.(*Request).Execute()
      /home/buglloc/work/projects/resty/request.go:936 +0x4f9
  github.com/go-resty/resty/v2.(*Request).Post()
      /home/buglloc/work/projects/resty/request.go:862 +0x6ed
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously.func1()
      /home/buglloc/work/projects/resty/client_test.go:784 +0x6cb
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Goroutine 31 (running) created at:
  testing.(*T).Run()
      /usr/lib/go/src/testing/testing.go:1742 +0x825
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously()
      /home/buglloc/work/projects/resty/client_test.go:779 +0x24d
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Goroutine 32 (running) created at:
  testing.(*T).Run()
      /usr/lib/go/src/testing/testing.go:1742 +0x825
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously()
      /home/buglloc/work/projects/resty/client_test.go:779 +0x24d
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c000444200 by goroutine 50:
  runtime.slicecopy()
      /usr/lib/go/src/runtime/slice.go:325 +0x0
  bytes.(*Buffer).Write()
      /usr/lib/go/src/bytes/buffer.go:181 +0x118
  encoding/json.(*Encoder).Encode()
      /usr/lib/go/src/encoding/json/stream.go:230 +0x46b
  github.com/go-resty/resty/v2.init.func3()
      /home/buglloc/work/projects/resty/request.go:1088 +0x20a
  github.com/go-resty/resty/v2.(*Request).fmtBodyString()
      /home/buglloc/work/projects/resty/request.go:1017 +0x531
  github.com/go-resty/resty/v2.requestLogger()
      /home/buglloc/work/projects/resty/middleware.go:324 +0x3b0
  github.com/go-resty/resty/v2.(*Client).execute()
      /home/buglloc/work/projects/resty/client.go:1180 +0x84b
  github.com/go-resty/resty/v2.(*Request).Execute()
      /home/buglloc/work/projects/resty/request.go:936 +0x4f9
  github.com/go-resty/resty/v2.(*Request).Post()
      /home/buglloc/work/projects/resty/request.go:862 +0x6ed
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously.func1()
      /home/buglloc/work/projects/resty/client_test.go:784 +0x6cb
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Previous read at 0x00c000444200 by goroutine 22:
  runtime.slicebytetostring()
      /usr/lib/go/src/runtime/string.go:81 +0x0
  github.com/go-resty/resty/v2.(*Request).fmtBodyString()
      /home/buglloc/work/projects/resty/request.go:1037 +0x916
  github.com/go-resty/resty/v2.requestLogger()
      /home/buglloc/work/projects/resty/middleware.go:324 +0x3b0
  github.com/go-resty/resty/v2.(*Client).execute()
      /home/buglloc/work/projects/resty/client.go:1180 +0x84b
  github.com/go-resty/resty/v2.(*Request).Execute()
      /home/buglloc/work/projects/resty/request.go:936 +0x4f9
  github.com/go-resty/resty/v2.(*Request).Post()
      /home/buglloc/work/projects/resty/request.go:862 +0x6ed
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously.func1()
      /home/buglloc/work/projects/resty/client_test.go:784 +0x6cb
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Goroutine 50 (running) created at:
  testing.(*T).Run()
      /usr/lib/go/src/testing/testing.go:1742 +0x825
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously()
      /home/buglloc/work/projects/resty/client_test.go:779 +0x24d
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Goroutine 22 (running) created at:
  testing.(*T).Run()
      /usr/lib/go/src/testing/testing.go:1742 +0x825
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously()
      /home/buglloc/work/projects/resty/client_test.go:779 +0x24d
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c0007204c0 by goroutine 40:
  runtime.slicecopy()
      /usr/lib/go/src/runtime/slice.go:325 +0x0
  bytes.(*Buffer).Write()
      /usr/lib/go/src/bytes/buffer.go:181 +0x118
  bytes.(*Reader).WriteTo()
      /usr/lib/go/src/bytes/reader.go:143 +0xfe
  io.copyBuffer()
      /usr/lib/go/src/io/io.go:411 +0xd3
  io.Copy()
      /usr/lib/go/src/io/io.go:388 +0x2cc
  github.com/go-resty/resty/v2.getBodyCopy()
      /home/buglloc/work/projects/resty/middleware.go:566 +0x171
  github.com/go-resty/resty/v2.createHTTPRequest()
      /home/buglloc/work/projects/resty/middleware.go:257 +0xe90
  github.com/go-resty/resty/v2.(*Client).execute()
      /home/buglloc/work/projects/resty/client.go:1164 +0x5e5
  github.com/go-resty/resty/v2.(*Request).Execute()
      /home/buglloc/work/projects/resty/request.go:936 +0x4f9
  github.com/go-resty/resty/v2.(*Request).Post()
      /home/buglloc/work/projects/resty/request.go:862 +0x6ed
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously.func1()
      /home/buglloc/work/projects/resty/client_test.go:784 +0x6cb
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Previous read at 0x00c0007204c0 by goroutine 39:
  runtime.slicebytetostring()
      /usr/lib/go/src/runtime/string.go:81 +0x0
  github.com/go-resty/resty/v2.(*Request).fmtBodyString()
      /home/buglloc/work/projects/resty/request.go:1037 +0x916
  github.com/go-resty/resty/v2.requestLogger()
      /home/buglloc/work/projects/resty/middleware.go:324 +0x3b0
  github.com/go-resty/resty/v2.(*Client).execute()
      /home/buglloc/work/projects/resty/client.go:1180 +0x84b
  github.com/go-resty/resty/v2.(*Request).Execute()
      /home/buglloc/work/projects/resty/request.go:936 +0x4f9
  github.com/go-resty/resty/v2.(*Request).Post()
      /home/buglloc/work/projects/resty/request.go:862 +0x6ed
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously.func1()
      /home/buglloc/work/projects/resty/client_test.go:784 +0x6cb
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Goroutine 40 (running) created at:
  testing.(*T).Run()
      /usr/lib/go/src/testing/testing.go:1742 +0x825
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously()
      /home/buglloc/work/projects/resty/client_test.go:779 +0x24d
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Goroutine 39 (running) created at:
  testing.(*T).Run()
      /usr/lib/go/src/testing/testing.go:1742 +0x825
  github.com/go-resty/resty/v2.TestDebugLogSimultaneously()
      /home/buglloc/work/projects/resty/client_test.go:779 +0x24d
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /usr/lib/go/src/testing/testing.go:1742 +0x44

Copy link
Member

@jeevatkm jeevatkm left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the PR.

@jeevatkm jeevatkm added this to the v2.12.0 milestone Feb 19, 2024
@jeevatkm jeevatkm added the bug label Feb 19, 2024
Copy link

codecov bot commented Feb 19, 2024

Codecov Report

Attention: 1 lines in your changes are missing coverage. Please review.

Comparison is base (74050fd) 96.52% compared to head (2b55388) 96.46%.
Report is 2 commits behind head on v2.

Files Patch % Lines
request.go 87.50% 1 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##               v2     #775      +/-   ##
==========================================
- Coverage   96.52%   96.46%   -0.06%     
==========================================
  Files          12       12              
  Lines        1639     1643       +4     
==========================================
+ Hits         1582     1585       +3     
- Misses         36       37       +1     
  Partials       21       21              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

Copy link
Member

@jeevatkm jeevatkm left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the PR

@jeevatkm jeevatkm merged commit 97187c4 into go-resty:v2 Feb 19, 2024
3 of 4 checks passed
@buglloc buglloc deleted the racy-request-log branch February 29, 2024 14:21
renovate bot added a commit to Michsior14/transmission-gluetun-port-update that referenced this pull request Mar 18, 2024
[![Mend
Renovate](https://app.renovatebot.com/images/banner.svg)](https://renovatebot.com)

This PR contains the following updates:

| Package | Change | Age | Adoption | Passing | Confidence |
|---|---|---|---|---|---|
| [github.com/go-resty/resty/v2](https://togithub.com/go-resty/resty) |
`v2.11.0` -> `v2.12.0` |
[![age](https://developer.mend.io/api/mc/badges/age/go/github.com%2fgo-resty%2fresty%2fv2/v2.12.0?slim=true)](https://docs.renovatebot.com/merge-confidence/)
|
[![adoption](https://developer.mend.io/api/mc/badges/adoption/go/github.com%2fgo-resty%2fresty%2fv2/v2.12.0?slim=true)](https://docs.renovatebot.com/merge-confidence/)
|
[![passing](https://developer.mend.io/api/mc/badges/compatibility/go/github.com%2fgo-resty%2fresty%2fv2/v2.11.0/v2.12.0?slim=true)](https://docs.renovatebot.com/merge-confidence/)
|
[![confidence](https://developer.mend.io/api/mc/badges/confidence/go/github.com%2fgo-resty%2fresty%2fv2/v2.11.0/v2.12.0?slim=true)](https://docs.renovatebot.com/merge-confidence/)
|

---

### Release Notes

<details>
<summary>go-resty/resty (github.com/go-resty/resty/v2)</summary>

###
[`v2.12.0`](https://togithub.com/go-resty/resty/releases/tag/v2.12.0)

[Compare
Source](https://togithub.com/go-resty/resty/compare/v2.11.0...v2.12.0)

### Release Notes

#### Enhancements

- Add Client.Clone function by
[@&#8203;fabiante](https://togithub.com/fabiante) in
[go-resty/resty#774

#### Bug Fixes

- Fixed JSON request logging data race. by
[@&#8203;buglloc](https://togithub.com/buglloc) in
[go-resty/resty#775
- fix: trailing NULL bytes in buffer while detecting a content type by
[@&#8203;jeevatkm](https://togithub.com/jeevatkm) in
[go-resty/resty#779
- fix: encode path params with BaseURL and the first param at index zero
([#&#8203;781](https://togithub.com/go-resty/resty/issues/781)) by
[@&#8203;sakateka](https://togithub.com/sakateka) in
[go-resty/resty#782

#### Documentation

- fix: doc typo by
[@&#8203;victoraugustolls](https://togithub.com/victoraugustolls) in
[go-resty/resty#769
- docs: replace `SetHostURL` to `SetBaseURL` by
[@&#8203;purofle](https://togithub.com/purofle) in
[go-resty/resty#772
- for v2.12.0 release by
[@&#8203;jeevatkm](https://togithub.com/jeevatkm) in
[go-resty/resty#783

#### New Contributors

- [@&#8203;victoraugustolls](https://togithub.com/victoraugustolls) made
their first contribution in
[go-resty/resty#769
- [@&#8203;purofle](https://togithub.com/purofle) made their first
contribution in
[go-resty/resty#772
- [@&#8203;buglloc](https://togithub.com/buglloc) made their first
contribution in
[go-resty/resty#775
- [@&#8203;fabiante](https://togithub.com/fabiante) made their first
contribution in
[go-resty/resty#774
- [@&#8203;sakateka](https://togithub.com/sakateka) made their first
contribution in
[go-resty/resty#782

**Full Changelog**:
go-resty/resty@v2.11.0...v2.12.0

</details>

---

### Configuration

📅 **Schedule**: Branch creation - At any time (no schedule defined),
Automerge - At any time (no schedule defined).

🚦 **Automerge**: Enabled.

♻ **Rebasing**: Whenever PR becomes conflicted, or you tick the
rebase/retry checkbox.

🔕 **Ignore**: Close this PR and you won't be reminded about this update
again.

---

- [ ] <!-- rebase-check -->If you want to rebase/retry this PR, check
this box

---

This PR has been generated by [Mend
Renovate](https://www.mend.io/free-developer-tools/renovate/). View
repository job log
[here](https://developer.mend.io/github/Michsior14/transmission-gluetun-port-update).

<!--renovate-debug:eyJjcmVhdGVkSW5WZXIiOiIzNy4yNDUuMCIsInVwZGF0ZWRJblZlciI6IjM3LjI0NS4wIiwidGFyZ2V0QnJhbmNoIjoibWFpbiJ9-->

Co-authored-by: renovate[bot] <29139614+renovate[bot]@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Development

Successfully merging this pull request may close these issues.

None yet

2 participants