500 level errors in nginx

Server administration Troubleshooting
#1

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...
#2

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

#3

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.

#4

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)

#5

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.

#6

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

#7

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

#8

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

#9

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

#10

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

#11

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.

#12

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.

#13

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

#14

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…