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

fix: don't panic when logs waits for more than 5 seconds #947

Merged
merged 1 commit into from Apr 24, 2023

Conversation

martin-sucha
Copy link
Contributor

This should fix #946

What does this PR do?

This removes panic when logs endpoint takes more than 5 seconds to respond. The panic happened at least with podman when no new logs appear when using follow and since parameters.

We keep retrying until the context is canceled (the retry request would fail anyway) or the producer is stopped, whichever comes first. This makes the retry behavior consistent.

Why is it important?

Panicking the whole test suite breaks all my tests if the container ends early or there is some temporary error fetching the logs.

Related issues

@martin-sucha martin-sucha requested a review from a team as a code owner March 21, 2023 15:11
@netlify
Copy link

netlify bot commented Mar 21, 2023

Deploy Preview for testcontainers-go ready!

Name Link
🔨 Latest commit 97ebbaa
🔍 Latest deploy log https://app.netlify.com/sites/testcontainers-go/deploys/64468df890f0aa0008dfc5e3
😎 Deploy Preview https://deploy-preview-947--testcontainers-go.netlify.app
📱 Preview on mobile
Toggle QR Code...

QR Code

Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify site settings.

@mdelapenya
Copy link
Collaborator

@martin-sucha thanks for this fix, I was taking a look at #366 yesterday, and they seem related. Could you check if they are overlapping? 🙏

@sonarcloud
Copy link

sonarcloud bot commented Mar 21, 2023

Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 0 Code Smells

No Coverage information No Coverage information
0.0% 0.0% Duplication

@martin-sucha
Copy link
Contributor Author

@mdelapenya It seems to me that these two PRs are not overlapping. #947 handles retries/removing of the panic and interrupting the HTTP request when context is canceled (internally in the worker goroutine) while #366 handles API changes like only one producer is allowed. I think both should be merged.

It seems there is a small code conflict as both PRs touch the stop channel, but that should be easy to resolve (#366 creates new stop channel each time the method is called and #947 uses a context to handle cancellation inside the worker goroutine, the merged result would create the stop channel each time the method is called and use that to create the context used for cancellation).

@mdelapenya mdelapenya self-assigned this Mar 21, 2023
@mdelapenya mdelapenya added the bug An issue with the library label Mar 21, 2023
docker.go Outdated
ctx, cancel := context.WithCancel(ctx)

go func() {
<-c.stopProducer
Copy link
Collaborator

Choose a reason for hiding this comment

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

Probably too picky, as the stopProducer is private and not accesible from client code, but should we wait for a true value in the stopProducer, or simply reading from the channel is enough?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Reading from the channel should be enough, now with the changes in main it is even guaranteed that the write will happen once.

mdelapenya
mdelapenya previously approved these changes Mar 22, 2023
Copy link
Collaborator

@mdelapenya mdelapenya left a comment

Choose a reason for hiding this comment

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

I added a comment when reading the stopProducer channel, but apart from that, this PR LGTM. Will wait for your feedback before merging it.

Thank you very much for your time here! 👏

@mdelapenya
Copy link
Collaborator

@martin-sucha we merged #366, so I think you can continue with this one resolving conflicts 🙏

@mdelapenya
Copy link
Collaborator

@martin-sucha if you mind, I'm going to fetch this PR and resolve the conflicts myself in top of your commits. Is that ok for you?

@martin-sucha
Copy link
Contributor Author

@martin-sucha if you mind, I'm going to fetch this PR and resolve the conflicts myself in top of your commits. Is that ok for you?

Sure, no problem.

In the mean time I started signing all my commits, so I've rebased this PR anyway and signed the commit as well.

docker.go Outdated Show resolved Hide resolved
This removes panic when logs endpoint takes more than 5 seconds to respond.
The panic happened at least with podman when no new logs appear when using follow and since parameters.

We keep retrying until the context is canceled
(the retry request would fail anyway with canceled context)
or the producer is stopped,
whichever comes first.
This makes the retry behavior consistent with closed connections
handling.

This should fix testcontainers#946
@sonarcloud
Copy link

sonarcloud bot commented Apr 24, 2023

Kudos, SonarCloud Quality Gate passed!    Quality Gate passed

Bug A 0 Bugs
Vulnerability A 0 Vulnerabilities
Security Hotspot A 0 Security Hotspots
Code Smell A 0 Code Smells

No Coverage information No Coverage information
19.4% 19.4% Duplication

docker.go Show resolved Hide resolved
@mdelapenya mdelapenya merged commit 5185956 into testcontainers:main Apr 24, 2023
54 checks passed
@mdelapenya
Copy link
Collaborator

@martin-sucha thanks for the fix and your patience while reviewing this PR!

weeco pushed a commit to weeco/testcontainers-go that referenced this pull request Apr 24, 2023
…ers#947)

This removes panic when logs endpoint takes more than 5 seconds to respond.
The panic happened at least with podman when no new logs appear when using follow and since parameters.

We keep retrying until the context is canceled
(the retry request would fail anyway with canceled context)
or the producer is stopped,
whichever comes first.
This makes the retry behavior consistent with closed connections
handling.

This should fix testcontainers#946
@mdelapenya
Copy link
Collaborator

Hey @martin-sucha, I'm experimenting certain flakiness in a log_consumer test after this PR has been merged. This is how I am able to reproduce it:

  1. Run this command (go test 20 times):
for x in {1..20}; do go test -timeout 600s -run ^Test_StartStop$ github.com/testcontainers/testcontainers-go -count=1; done

No matter if you see log traces about Ryuk being disabled, as I can reproduce it in both cases.

Expected result:

ok      github.com/testcontainers/testcontainers-go     9.162s
ok      github.com/testcontainers/testcontainers-go     4.312s
ok      github.com/testcontainers/testcontainers-go     9.063s
ok      github.com/testcontainers/testcontainers-go     8.927s
ok      github.com/testcontainers/testcontainers-go     9.050s
ok      github.com/testcontainers/testcontainers-go     9.007s
ok      github.com/testcontainers/testcontainers-go     8.969s
ok      github.com/testcontainers/testcontainers-go     8.995s
ok      github.com/testcontainers/testcontainers-go     9.099s
ok      github.com/testcontainers/testcontainers-go     9.129s
ok      github.com/testcontainers/testcontainers-go     9.008s
ok      github.com/testcontainers/testcontainers-go     8.922s
ok      github.com/testcontainers/testcontainers-go     8.940s
ok      github.com/testcontainers/testcontainers-go     8.970s
ok      github.com/testcontainers/testcontainers-go     8.923s
ok      github.com/testcontainers/testcontainers-go     8.917s
ok      github.com/testcontainers/testcontainers-go     4.187s
ok      github.com/testcontainers/testcontainers-go     8.949s
ok      github.com/testcontainers/testcontainers-go     13.898s
ok      github.com/testcontainers/testcontainers-go     13.711s

Actual result:

Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 10:58:52 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 10:58:52 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 10:58:52 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 10:58:53 🐳 Creating container for image 
2023/05/02 10:58:54 ✅ Container created: c5a5373cbe84
2023/05/02 10:58:54 🐳 Starting container: c5a5373cbe84
2023/05/02 10:58:54 🚧 Waiting for container id c5a5373cbe84 image: 88762c7f-d78f-4e2f-9f50-7581f2dba603:b46fe4a8-1d54-4c09-9e74-9ac563b13427
2023/05/02 10:58:54 ✅ Container started: c5a5373cbe84
2023/05/02 10:58:55 🐳 Terminating container: c5a5373cbe84
2023/05/02 10:58:55 🚫 Container terminated: c5a5373cbe84
--- FAIL: Test_StartStop (4.00s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.222s
FAIL
Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 10:58:56 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 10:58:56 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 10:58:56 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 10:58:58 🐳 Creating container for image 
2023/05/02 10:58:58 ✅ Container created: 16a9ba29bc44
2023/05/02 10:58:58 🐳 Starting container: 16a9ba29bc44
2023/05/02 10:58:58 🚧 Waiting for container id 16a9ba29bc44 image: 0bc1cd2f-759c-4b0d-943c-986e23545ba6:8de94fbf-22a8-4ee8-9743-dda25c01f37b
2023/05/02 10:58:59 ✅ Container started: 16a9ba29bc44
2023/05/02 10:59:00 🐳 Terminating container: 16a9ba29bc44
2023/05/02 10:59:00 🚫 Container terminated: 16a9ba29bc44
--- FAIL: Test_StartStop (4.03s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.168s
FAIL
Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 10:59:01 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 10:59:01 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 10:59:01 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 10:59:03 🐳 Creating container for image 
2023/05/02 10:59:03 ✅ Container created: a78720217309
2023/05/02 10:59:03 🐳 Starting container: a78720217309
2023/05/02 10:59:03 🚧 Waiting for container id a78720217309 image: 740bae7a-6435-40c8-8784-0f8559f006a3:1f80bd5b-c586-4308-90d8-bf7bd593bf0e
2023/05/02 10:59:04 ✅ Container started: a78720217309
2023/05/02 10:59:04 🐳 Terminating container: a78720217309
2023/05/02 10:59:05 🚫 Container terminated: a78720217309
--- FAIL: Test_StartStop (3.97s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.113s
FAIL
Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 10:59:05 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 10:59:05 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 10:59:06 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 10:59:07 🐳 Creating container for image 
2023/05/02 10:59:07 ✅ Container created: 03601f96cdf6
2023/05/02 10:59:07 🐳 Starting container: 03601f96cdf6
2023/05/02 10:59:08 🚧 Waiting for container id 03601f96cdf6 image: b6a1aa9d-e05c-4dd9-b6e4-80a84c6ccd2f:02499ef0-10ab-4041-9f5c-d23c0c3d26f5
2023/05/02 10:59:08 ✅ Container started: 03601f96cdf6
2023/05/02 10:59:09 🐳 Terminating container: 03601f96cdf6
2023/05/02 10:59:09 🚫 Container terminated: 03601f96cdf6
--- FAIL: Test_StartStop (3.92s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.055s
FAIL
ok      github.com/testcontainers/testcontainers-go     4.136s
Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 10:59:14 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 10:59:14 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 10:59:15 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 10:59:16 🐳 Creating container for image 
2023/05/02 10:59:16 ✅ Container created: 7458b5cdd330
2023/05/02 10:59:16 🐳 Starting container: 7458b5cdd330
2023/05/02 10:59:17 🚧 Waiting for container id 7458b5cdd330 image: d0cf2a37-6f93-4913-9926-0c37e5705be5:d61714e0-38c3-445c-b58b-2f8b716260ff
2023/05/02 10:59:17 ✅ Container started: 7458b5cdd330
2023/05/02 10:59:18 🐳 Terminating container: 7458b5cdd330
2023/05/02 10:59:18 🚫 Container terminated: 7458b5cdd330
--- FAIL: Test_StartStop (4.05s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.217s
FAIL
Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 10:59:19 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 10:59:19 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 10:59:19 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 10:59:21 🐳 Creating container for image 
2023/05/02 10:59:21 ✅ Container created: a36e8862b19e
2023/05/02 10:59:21 🐳 Starting container: a36e8862b19e
2023/05/02 10:59:21 🚧 Waiting for container id a36e8862b19e image: 3ecf4857-88a9-404b-9f37-fa9cfef3e393:8353de53-fbd6-470c-a211-123910f3fb2f
2023/05/02 10:59:22 ✅ Container started: a36e8862b19e
2023/05/02 10:59:23 🐳 Terminating container: a36e8862b19e
2023/05/02 10:59:23 🚫 Container terminated: a36e8862b19e
--- FAIL: Test_StartStop (3.93s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.087s
FAIL
ok      github.com/testcontainers/testcontainers-go     4.167s
ok      github.com/testcontainers/testcontainers-go     4.150s
ok      github.com/testcontainers/testcontainers-go     4.099s
ok      github.com/testcontainers/testcontainers-go     3.951s
Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 10:59:42 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 10:59:42 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 10:59:42 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 10:59:44 🐳 Creating container for image 
2023/05/02 10:59:44 ✅ Container created: bf0fbfe460e8
2023/05/02 10:59:44 🐳 Starting container: bf0fbfe460e8
2023/05/02 10:59:44 🚧 Waiting for container id bf0fbfe460e8 image: 0901522a-517e-417e-b742-e7f69a50465e:d48875d5-6498-4e4e-bbfb-9f75ca9eeeee
2023/05/02 10:59:45 ✅ Container started: bf0fbfe460e8
2023/05/02 10:59:45 🐳 Terminating container: bf0fbfe460e8
2023/05/02 10:59:46 🚫 Container terminated: bf0fbfe460e8
--- FAIL: Test_StartStop (4.05s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.197s
FAIL
ok      github.com/testcontainers/testcontainers-go     4.214s
ok      github.com/testcontainers/testcontainers-go     4.251s
ok      github.com/testcontainers/testcontainers-go     4.209s
Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 11:00:00 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 11:00:00 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 11:00:01 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 11:00:02 🐳 Creating container for image 
2023/05/02 11:00:02 ✅ Container created: 5f8b2bae342a
2023/05/02 11:00:02 🐳 Starting container: 5f8b2bae342a
2023/05/02 11:00:03 🚧 Waiting for container id 5f8b2bae342a image: dac3b6f1-0c21-4eaf-8451-14cbd7b88db8:0c8fbf43-058c-45ae-ac2d-1b1256d5d81f
2023/05/02 11:00:03 ✅ Container started: 5f8b2bae342a
2023/05/02 11:00:04 🐳 Terminating container: 5f8b2bae342a
2023/05/02 11:00:04 🚫 Container terminated: 5f8b2bae342a
--- FAIL: Test_StartStop (4.18s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.309s
FAIL
Testcontainers properties file has been found: /Users/mdelapenya/.testcontainers.properties
2023/05/02 11:00:05 
**********************************************************************************************
Ryuk has been disabled for the current execution. This can cause unexpected behavior in your environment.
More on this: https://golang.testcontainers.org/features/garbage_collector/
**********************************************************************************************
2023/05/02 11:00:05 
{Host:tcp://127.0.0.1:64666 TLSVerify:0 CertPath: RyukDisabled:true RyukPrivileged:true}
2023/05/02 11:00:05 github.com/testcontainers/testcontainers-go - Connected to docker: 
  Server Version: 70+testcontainerscloud
  API Version: 1.41
  Operating System: Ubuntu 20.04 LTS
  Total Memory: 7407 MB
2023/05/02 11:00:07 🐳 Creating container for image 
2023/05/02 11:00:07 ✅ Container created: ced0e6d37851
2023/05/02 11:00:07 🐳 Starting container: ced0e6d37851
2023/05/02 11:00:07 🚧 Waiting for container id ced0e6d37851 image: f80b92b6-6379-4a3d-9b94-3773a4ea33da:da819326-5e30-4f9d-bedd-92dedf29cf72
2023/05/02 11:00:08 ✅ Container started: ced0e6d37851
2023/05/02 11:00:09 🐳 Terminating container: ced0e6d37851
2023/05/02 11:00:09 🚫 Container terminated: ced0e6d37851
--- FAIL: Test_StartStop (4.06s)
    logconsumer_test.go:247: 
                Error Trace:    /Users/mdelapenya/sourcecode/src/github.com/testcontainers/testcontainers-go/logconsumer_test.go:247
                Error:          Not equal: 
                                expected: []string{"ready\n", "echo mlem\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                                actual  : []string{"ready\n", "ready\n", "echo mlem\n", "echo mlem2\n"}
                            
                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1,4 +1,3 @@
                                -([]string) (len=5) {
                                +([]string) (len=4) {
                                  (string) (len=6) "ready\n",
                                - (string) (len=10) "echo mlem\n",
                                  (string) (len=6) "ready\n",
                Test:           Test_StartStop
FAIL
FAIL    github.com/testcontainers/testcontainers-go     4.203s
FAIL
ok      github.com/testcontainers/testcontainers-go     4.359s
ok      github.com/testcontainers/testcontainers-go     4.083s
ok      github.com/testcontainers/testcontainers-go     4.390s

I'm tempted to revert the commit and give the chance to debug this, so that we can perform a new release, but I wanted to check with you first.

@mdelapenya
Copy link
Collaborator

@martin-sucha I think I have a clue on what's going on: the test does the assertions and because we changed here how the log producers behave, it's very likely that the messages are not there yet at test time.

If you take a look at https://github.com/testcontainers/testcontainers-go/pull/947/files#diff-b68159b6168f099a639e8c6f96d75f23333ab0f0505ee22a98268748db17ae4cR635-R637, we are removing the channel that was used to receive the signal that the log producer was stopped. Therefore, we are only waiting for the Done method of the context: https://github.com/testcontainers/testcontainers-go/pull/947/files#diff-b68159b6168f099a639e8c6f96d75f23333ab0f0505ee22a98268748db17ae4cR663

Those are my initial suspects, but it's not easy to debug. Wdyt, anything on the top of your head?

@mdelapenya
Copy link
Collaborator

As the modified code is adding non-deterministic behaviour when starting-stopping the log producers, I'm going to proceed and revert this commit, reopening the original issues #946 and #606

I'd appreciate if you want to work on that again 🙏

mdelapenya added a commit to mdelapenya/testcontainers-go that referenced this pull request May 10, 2023
mdelapenya added a commit that referenced this pull request May 10, 2023
mdelapenya added a commit to mdelapenya/testcontainers-go that referenced this pull request May 11, 2023
* main:
  docs: enrich docs for modules (testcontainers#1167)
  chore: prepare for next minor development cycle (0.21.0)
  chore: use new version (v0.20.1) in modules and examples
  Revert "fix: don't panic when logs waits for more than 5 seconds (testcontainers#947)" (testcontainers#1164)
  fix: define a two-phase release process (testcontainers#1163)
  ci(lint): enable misspell and gci linters (testcontainers#1162)
@martin-sucha
Copy link
Contributor Author

@mdelapenya I've finally looked at the issue and it seems to me that the failing test was wrong: it did not wait for the log lines to appear. Please see #1278

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An issue with the library
Projects
None yet
2 participants