Open rNoz opened 4 years ago
rNoz
commented
4 years ago @josegonzalez Any clue? I was thinking if opening this issue in Dokku or here (Herokuish). After 4 days, I continue lost with this issue, while I see more activity in the Dokku repo.
josegonzalez
commented
4 years ago Not sure, but we're just running the container fairly normally in Dokku. If it's going to stdout/stderr, then there shouldn't be any real issues here. Maybe elixer buffers logs and Heroku is setting some environment variable that stops it from doing so?
This definitely needs an app to reproduce this. Not that I have too much time to test this myself, but do you have a repo with all the code that would reproduce this? I'm not familiar with Elixer, so I don't think I would be able to reproduce this anytime soon myself.
rNoz
commented
4 years ago Hi, Jose. Thanks for answering. I asked in the Elixir community and indeed they say something like this:
Is there anything like a “max buffer” in the stacktrace/error/log system that is filled, and until it is freed i cannot get again it emitting?
Well, yes. The logger has built in overload handling which will change it behaviour depending on amount of messages in the logger inbox:
- normally it will use asynchronous messaging, aka the messages are sent to other process for computing
- if there is more than :sync_threshold messages in the logger inbox (defaults to 20) then it will change to synchronous logging to force back pressure on logging processes (logging process waits until it’s message is handled)
- if back pressure do not work and the messages queue anyway then when you reach :discard_threshold (defaults to 500) then logger will discard new messages until the messages amount will not drop below the threshold again
So if your sink (in this case stdout) is slow enough to not be able to ingest the messages quickly enough, then there exists chance that you are thresholded. However there should be additional log entry if there is discarding behaviour enabled.
But I don't find any env var that Heroku (or my local computer) is establishing to have different behavior. Also, it is expected that if the IO is not fast enough to consume the messages, it will send errors warning us eventually, but those are never seen.
I have prepared a repo for you, in case you will find any time to address this bug https://github.com/rNoz/phoenix-elixir-dokku
If you find anything wrong, please, let me know.
I will continue testing and studying this weird thing.
Edit: @josegonzalez We have "isolated" a bit more the error, but we don't know the solution yet. The problem is related with the cache of the web browser, since curl doesn't show this problem.
Any request from curl or from a web browser with the cache cleaned show the expected behavior: exception in the server log (Dokku, just like in Heroku or Local). What is surprising, is that Dokku is the only one that have "this problem". The only difference in req/res headers is that Heroku is using Cowboy (Phoenix inner web server) instead of nginx (Dokku: the nginx is a proxy server that proxy pass to the phoenix/app container). We don't have anything related with the cache in nginx of Dokku.
josegonzalez
commented
4 years ago Check what the request/response headers are on the app?
rNoz
commented
4 years ago Yesterday I was doing some tests regarding the nginx cache without luck.
They differ in:
Dokku:
==Response Headers==
HTTP/2 500 Internal Server Error
server: nginx
date: Sun, 26 Apr 2020 17:30:44 GMT
content-type: text/html; charset=utf-8
content-length: 21
cache-control: max-age=0, private, must-revalidate
cross-origin-window-policy: deny
x-content-type-options: nosniff
x-download-options: noopen
x-frame-options: SAMEORIGIN
x-permitted-cross-domain-policies: none
x-request-id: Fglu3jKRiw7hiSgAADch
x-xss-protection: 1; mode=block
strict-transport-security: max-age=15724800; includeSubdomains
X-Firefox-Spdy: h2
==Request Headers==
Host: phoenix-elixir-dokku.mydomain.org
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Language: en-US;q=0.7,en
Accept-Encoding: gzip, deflate, br
Referer: https://phoenix-elixir-dokku.mydomain.org/
Connection: keep-alive
Cookie: experimentation_subject_id=Isd....9abd0f41; _phoenix_elixirc_dokku_key=SFMyNTY.g3QAA...UgP0NyyXkE
Upgrade-Insecure-Requests: 1
Cache-Control: max-age=0Heroku:
==Response Headers==
HTTP/1.1 500 Internal Server Error
Connection: keep-alive
Cache-Control: max-age=0, private, must-revalidate
Content-Length: 21
Content-Type: text/html; charset=utf-8
Cross-Origin-Window-Policy: deny
Date: Mon, 27 Apr 2020 11:33:08 GMT
Server: Cowboy
X-Content-Type-Options: nosniff
X-Download-Options: noopen
X-Frame-Options: SAMEORIGIN
X-Permitted-Cross-Domain-Policies: none
X-Request-Id: 0ed95f38-54f4-4b42-97ac-72bfdf1a5636
X-Xss-Protection: 1; mode=block
Via: 1.1 vegur
==Request Headers==
Host: phoenix-elixir-dokku.herokuapp.com
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Language: en-US;q=0.7,en
Accept-Encoding: gzip, deflate
Connection: keep-alive
Upgrade-Insecure-Requests: 1
Cache-Control: max-age=0Local production:
==Response Headers==
HTTP/1.1 500 Internal Server Error
cache-control: max-age=0, private, must-revalidate
content-length: 21
content-type: text/html; charset=utf-8
cross-origin-window-policy: deny
date: Mon, 27 Apr 2020 11:57:18 GMT
server: Cowboy
x-content-type-options: nosniff
x-download-options: noopen
x-frame-options: SAMEORIGIN
x-permitted-cross-domain-policies: none
x-request-id: FgmrQNyyw7z2XQkAAAED
x-xss-protection: 1; mode=block
==Request Headers==
Host: localhost:4000
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:75.0) Gecko/20100101 Firefox/75.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Language: en-US;q=0.7,en
Accept-Encoding: gzip, deflate
Connection: keep-alive
Cookie: locale=en
Upgrade-Insecure-Requests: 1
Cache-Control: max-age=0If I use Firefox or Chrome there are a some more headers sent (like experimental_subject_id in Firefox, or sec-fetch-user/site/mode/dest in Chrome), but the response headers don't vary.
Also, when I have my Inspector Tools with enabled cache, the request headers when going to /runtime-error-match are in all cases (D, L, H):
If I set Disable Cache in the web browser, the req headers are always:
josegonzalez
commented
4 years ago Mind hopping on our slack to get further support? This sort of issue seems strange and not easy to debug via github issues.
rNoz
commented
4 years ago Sure. I will refer to this issue there.
Hi,
I have been struggling with this for a couple of days without luck.
At the beginning I thought it was related with the app runtime, but since I tested directly on Heroku, I suspect it is with Dokku/Herokuish, but I suppose it can be anywhere.
I start describing the behavior in case you know the solution. But if you want to reproduce it, I will upload a basic repo.
It is basically a Phoenix App (new) with the a couple of custom routes (log, /runtime-error-conn, /runtime-error-match) to test the errors/logging system, along with these buildpacks:
And this
elixir_buildpack.config:I have a basic phoenix (elixir) application, with one route (eg. navigating to /runtime-error-conn) that produces a runtime error (stack trace, but the server is still alive since it is elixir/erlang and that is just one subprocess of the vm). The thing is that when I test this behavior in production both in my local computer and heroku, it shows the stack trace/error (stdout), but when I do it in dokku, the error is not shown. The same repo/commit is used in the three cases.
I will show here the logs when I do:
Local:
Heroku:
And now Dokku, where the last message shown is the
Converted error :undef to 500 response, until the next request is shown (/log). I have executed many times the /runtime-error-conn, and only 1 every X (5-30 times) is properly logged.Maybe it is something stupid that I am doing, but since dokku has many inner bits, it is out of my hands after many hours trying.
Edit: I also tried some options in the Phoenix/Elixir runtime itself.. without luck. The problem is: why only sometimes it is logged the error in dokku? I have done many tests, and in dozens of times the error is not shown, but eventually, it is. Why? Is there anything like a "max buffer" in the stacktrace/error/log system that is filled, and until it is freed i cannot get again it emitting? I am completely lost so I am just supposing things. The crazy thing is that it only happens in Dokku/Docker, not in Heroku or locally, so I don't know if is some sort of parameter to have more memory (or whatever it is). Any clue?