500 level errors in nginx

I am getting 500 level errors on:

/api/v1/streaming
/inbox
/users/$account/inbox

The errors in nginx log look like:

2019/02/17 14:19:13 [error] 24873#0: *16 upstream prematurely closed connection while reading response header from upstream, client: 192.252.229.44, server: example.com, request: "GET /api/v1/streaming/?stream=direct&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920 HTTP/2.0", upstream: "http://127.0.0.1:4000/api/v1/streaming/?stream=direct&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920", host: "mastodon.openpsychology.net"
2019/02/17 14:19:13 [error] 24873#0: *16 upstream prematurely closed connection while reading response header from upstream, client: 192.252.229.44, server: example.com, request: "GET /api/v1/streaming/?stream=public:local&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920 HTTP/2.0", upstream: "http://127.0.0.1:4000/api/v1/streaming/?stream=public:local&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920", host: "mastodon.openpsychology.net"
2019/02/17 14:19:13 [error] 24873#0: *16 upstream prematurely closed connection while reading response header from upstream, client: 192.252.229.44, server: example.com, request: "GET /api/v1/streaming/?stream=user&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920 HTTP/2.0", upstream: "http://127.0.0.1:4000/api/v1/streaming/?stream=user&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920", host: "mastodon.openpsychology.net"
2019/02/17 14:19:13 [error] 24873#0: *16 upstream prematurely closed connection while reading response header from upstream, client: 192.252.229.44, server: example.com, request: "GET /api/v1/streaming/?stream=public&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920 HTTP/2.0", upstream: "http://127.0.0.1:4000/api/v1/streaming/?stream=public&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920", host: "mastodon.openpsychology.net"

(the more informative ones) but most look like:

2019/02/17 14:19:14 [info] 24873#0: *15 client 81.235.33.215 closed keepalive connection
2019/02/17 14:19:15 [info] 24873#0: *35 client 2620:1e8:4:24da::1 closed keepalive connection
2019/02/17 14:19:29 [info] 24873#0: *77 client 2a01:7c8:aacb:426:5054:ff:fefb:877f closed keepalive connection
2019/02/17 14:19:29 [info] 24873#0: *75 client 195.154.84.31 closed keepalive connection
2019/02/17 14:19:30 [info] 24873#0: *76 client 2001:bc8:32d7:8700::1 closed keepalive connection
2019/02/17 14:19:42 [info] 24873#0: *100 client 2001:bc8:32d7:8700::1 closed keepalive connection
2019/02/17 14:19:42 [info] 24873#0: *101 client 2a01:7c8:aacb:426:5054:ff:fefb:877f closed keepalive connection

The nginx access_log is logging:

192.252.229.44 - - [17/Feb/2019:14:19:13 -0800] "GET /api/v1/streaming/?stream=direct&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920 HTTP/2.0" 502 607 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.96 Safari/537.36"
192.252.229.44 - - [17/Feb/2019:14:19:13 -0800] "GET /api/v1/streaming/?stream=public:local&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920 HTTP/2.0" 502 607 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.96 Safari/537.36"
192.252.229.44 - - [17/Feb/2019:14:19:13 -0800] "GET /api/v1/streaming/?stream=user&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920 HTTP/2.0" 502 607 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.96 Safari/537.36"
192.252.229.44 - - [17/Feb/2019:14:19:13 -0800] "GET /api/v1/streaming/?stream=public&access_token=3fec1b9f5fb1da9511f03c1d1aefa890654aa20c7e24cc98c4e0f3994df20920 HTTP/2.0" 502 607 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.96 Safari/537.36"

and:

54.37.254.31 - - [17/Feb/2019:14:19:19 -0800] "POST /inbox HTTP/1.1" 500 607 "-" "http.rb/3.3.0 (Mastodon/2.7.1; +https://elle.systems/)"
136.243.88.169 - - [17/Feb/2019:14:19:19 -0800] "POST /inbox HTTP/1.1" 500 607 "-" "http.rb/3.3.0 (Mastodon/2.7.1; +https://mastodon.social/)"
148.251.134.157 - - [17/Feb/2019:14:19:20 -0800] "POST /inbox HTTP/1.1" 500 607 "-" "http.rb/3.3.0 (Mastodon/2.7.1; +https://mastodon.social/)"
159.89.230.222 - - [17/Feb/2019:14:19:20 -0800] "POST /inbox HTTP/1.1" 500 607 "-" "http.rb/3.3.0 (Mastodon/2.7.0; +https://botsin.space/)"

and:

88.99.169.242 - - [17/Feb/2019:14:19:53 -0800] "POST /users/JigmeDatse/inbox HTTP/1.1" 500 607 "-" "http.rb/3.3.0 (Mastodon/2.7.1-cybre; +https://cybre.space/)"

Our host is https://mastodon.openpsychology.net/

In netstat I am seeing a lot of TIME_WAIT especially on 127.0.0.1:3000 and no status for that other than with that being the destination port.

That appears to be the mastodon-web service.

ss is not reporting any connections on 127.0.0.1:3000

restarting the service doesn’t seem to fix this. I get some console messages when I start it, and I’m not sure if that might be some help:

[26531] Puma starting in cluster mode...
[26531] * Version 3.12.0 (ruby 2.6.0-p0), codename: Llamas in Pajamas
[26531] * Min threads: 5, max threads: 5
[26531] * Environment: production
[26531] * Process workers: 2
[26531] * Preloading application
[26531] * Listening on tcp://0.0.0.0:3000
[26531] ! WARNING: Detected 1 Thread(s) started in app boot:
[26531] ! #<Thread:0x00007faf3da581a8@/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:299 sleep> - /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:301:in `sleep'
[26531] * Daemonizing...

Try starting services one by one. I counter it using systemctl restart mastodon-* doesnt seem to start services sometimes

systemctl start mastodon-web && systemctl start mastodon-streaming && systemctl start mastodon-sidekiq

OK, I’m using OpenRC and I have stopped waited, and restarted. I probably should have said that, and I wouldn’t be surprised to get a, “we don’t support OpenRC” type response.

the 502s and the 500s you’re seeing probably have different root causes. Are there any errors in their respective logs around that time? (node for the /api/v1/streaming upstream, puma for the /inbox ones)

I’ve dug and dug, and tried to find logs, but I can find none. I think I will need to get pm2 running for node process. It seems to be the best way for me to handle things. I have no idea how to deal with the puma, or more generally ruby process management, as I haven’t had to deal with that in the past.

Unless there is some logs I can’t figure out where in ~mastodon/live I am pretty sure there are no logs.

Be aware that you should revoke the access tokens you posted in the log here.

See first item on how to view logs for systemd services like mastodon-web: Troubleshooting - Mastodon documentation

They should be logged to wherever your init system is putting sysout… maybe syslong?

Maybe I need to configure differently, but going through everything in /var/log I have found nothing.

Thank you, information about viewing SystemD logs, is really helpful for someone running OpenRC…

I see nothing with:

puma
node
sidekiq
web
stream

which isn’t just about something entirely different, or simply about starting/stopping the services.

I’m very close to say that this “won’t work, can’t fix” and simply killing the server.

I am not familiar with OpenRC. All Mastodon processes write output to stdout. Systemd captures stdout into journalctl. You need to check what OpenRC does.

I think OpenRC does not capture stdout at all. So logging must be separate. Unfortunately that’s not an expected situation because our main targets are Docker, Systemd, Heroku &co which work with stdout by default. So you won’t be able to just flip a switch. However, it’s possible to configure Mastodon to log to a file.

Edit this line: mastodon/production.rb at master · tootsuite/mastodon · GitHub and replace STDOUT with Rails.root.join('logs', 'production.log'), then restart all Mastodon processes. From then on out, logs from Puma and Sidekiq will be written to /PATH_TO_MASTODON/logs/production.log

For the streaming API, below this line: mastodon/index.js at master · tootsuite/mastodon · GitHub add log.stream = fs.createWriteStream(__dirname + '/../logs/streaming.log', { flags : 'w' }), then restart the streaming process. From then on out, that log will be written to /PATH_TO_MASTODON/logs/streaming.log

Thank you, this gave me the information I needed…

I found that at some point I had accout_stoplight changed to account_spotlight and right now I am mostly waiting to see if things settle out or not. I’m not entirely sure how long this will take, but I do think it should probably be around the time I head to bed in about 7 hours? Well, hopefully before then. If not, I could probably increase the “size” of the VPS it is on…