Updated Ubuntu 16.04 now diaspora is down

iamdoubz · September 18, 2019, 4:33pm

Specs

Ubuntu 16.04
diaspora* 0.7.12.0
MySQL

What I installed

bind9-host
bsdutils
dnsutils
docker-ce
docker-ce-cli
dpkg
dpkg-dev
gir1.2-ibus-1.0
ibus
ibus-gtk
ibus-gtk3
idn2
libapache2-mod-php7.0
libapache2-mod-php7.2
libapache2-mod-proxy-uwsgi
libbind9-140
libblkid1
libbrotli1
libdns-export162
libdns162
libdpkg-perl
libfdisk1
libgd3
libibus-1.0-5
libidn2-0
libisc-export160
libisc160
libisccc140
libisccfg140
libldap-2.4-2
liblwres141
libmount1
libsmartcols1
libsnapd-glib1
libsnmp-base
libsnmp30
libuuid1
libxml2
libxml2-dev
mount
php-apcu-bc
php-imagick
php-redis
php7.0-cli
php7.0-common
php7.0-imap
php7.0-json
php7.0-mcrypt
php7.0-opcache
php7.0-readline
php7.0-xml
php7.2-cli
php7.2-common
php7.2-json
php7.2-opcache
php7.2-readline
php7.2-xml
php7.3
php7.3-xsl
psmisc
python3-software-properties
snapd
software-properties-common
software-properties-gtk
teamviewer
ubuntu-core-launcher
ubuntu-desktop
ubuntu-minimal
ubuntu-standard
usb-creator-common
usb-creator-gtk
util-linux
uuid-runtime
apache2
apache2-bin
apache2-data
apache2-utils
libapache2-mod-php7.0
libapache2-mod-php7.2
libapache2-mod-proxy-uwsgi
matrix-synapse-py3
php-apcu-bc
php-imagick
php-redis
php7.0-cli
php7.0-common
php7.0-imap
php7.0-json
php7.0-mcrypt
php7.0-opcache
php7.0-readline
php7.0-xml
php7.2-cli
php7.2-common
php7.2-json
php7.2-opcache
php7.2-readline
php7.2-xml
php7.3
php7.3-xsl
nodejs

What happens

I restarted server after updating, start the diaspora* server using ./scripts/server from the diaspora directory /home/diaspora/diaspora, server start after 30 or so seconds, I go to (browser doesn’t matter) https://nota.404.mn and it loads… the first time only. Approximately 30-60 seconds later, nothing loads anymore, and I get a server not found and/or a 503 Service unavailable.

Apache2 error log

[Wed Sep 18 10:32:23.628996 2019] [proxy_http:error] [pid 11017] [client 82.223.1.82:47672] AH01114: HTTP: failed to make connection to backend: httpd-UDS
[Wed Sep 18 10:32:24.708955 2019] [proxy:error] [pid 11031] (111)Connection refused: AH02454: HTTP: attempt to connect to Unix domain socket /home/diaspora/diaspora/tmp/diaspora.sock () failed
[Wed Sep 18 10:32:24.708991 2019] [proxy:error] [pid 11031] AH00959: ap_proxy_connect_backend disabling worker for () for 60s
[Wed Sep 18 10:32:24.708999 2019] [proxy_http:error] [pid 11031] [client 73.228.170.3:8679] AH01114: HTTP: failed to make connection to backend: httpd-UDS
[Wed Sep 18 10:32:25.768132 2019] [proxy:error] [pid 11026] (111)Connection refused: AH02454: HTTP: attempt to connect to Unix domain socket /home/diaspora/diaspora/tmp/diaspora.sock () failed
[Wed Sep 18 10:32:25.768164 2019] [proxy:error] [pid 11026] AH00959: ap_proxy_connect_backend disabling worker for () for 60s
[Wed Sep 18 10:32:25.768174 2019] [proxy_http:error] [pid 11026] [client 73.228.170.3:8680] AH01114: HTTP: failed to make connection to backend: httpd-UDS
[Wed Sep 18 10:32:26.215196 2019] [proxy:error] [pid 11027] (111)Connection refused: AH02454: HTTP: attempt to connect to Unix domain socket /home/diaspora/diaspora/tmp/diaspora.sock () failed
[Wed Sep 18 10:32:26.215235 2019] [proxy:error] [pid 11027] AH00959: ap_proxy_connect_backend disabling worker for () for 60s
[Wed Sep 18 10:32:26.215247 2019] [proxy_http:error] [pid 11027] [client 204.12.231.154:50728] AH01114: HTTP: failed to make connection to backend: httpd-UDS

Apache2 config file

<IfModule mod_ssl.c>

ServerTokens Prod
SSLStaplingCache "shmcb:${APACHE_LOG_DIR}/stapling-cache(150000)"
SSLSessionCache shmcb:${APACHE_LOG_DIR}/ssl_scache(512000)
SSLSessionCacheTimeout 300
ModPagespeed Off

<VirtualHost *:443>
    ServerName nota.404.mn
    ServerAdmin danieldoubet@nota.404.mn
	DocumentRoot /home/diaspora/diaspora/public
	ErrorLog ${APACHE_LOG_DIR}/nota.404.mn.error.log
#	CustomLog /dev/null combined
	CustomLog ${APACHE_LOG_DIR}/nota.404.mn.log combined
	SSLCertificateFile /etc/letsencrypt/live/nota.404.mn/fullchain.pem
	SSLCertificateKeyFile /etc/letsencrypt/live/nota.404.mn/privkey.pem
	Include /etc/letsencrypt/options-ssl-apache.conf
### Security Stuff
#	SSLProtocol TLSv1.2 TLSv1.3
#	SSLCipherSuite ECDHE+RSA+AES256+GCM+SHA512:DHE+RSA+AES256+GCM+SHA512:ECDHE+RSA+AES256+GCM+SHA384:DHE+RSA+AES256+GCM+SHA384:ECDHE+RSA+AES256+SHA384:EECDH+AESGCM:EDH+AESGCM:AES256+EECDH:AES256+EDH:!aNULL:!eNULL:!EXPORT:!DES:!MD5:!PSK:!RC4
	SSLHonorCipherOrder On
	ServerSignature Off
	SSLCompression Off
	SSLUseStapling On
	SSLStaplingResponderTimeout 5
	SSLStaplingReturnResponderErrors Off
	SSLSessionTickets Off
	Header always set Referrer-Policy "same-origin"
	Header always set X-Robots-Tag none
	RequestHeader set X_FORWARDED_PROTO https
    Protocols h2 http/1.1
### diaspora* Stuff
	RewriteEngine On
	RewriteCond %{HTTP_HOST} !^nota\.404\.mn [NC]
	RewriteRule ^/(.*)$ https://nota\.404\.mn/$1 [L,R,QSA]
	RewriteCond %{DOCUMENT_ROOT}/%{REQUEST_FILENAME} !-f
	RewriteRule ^/(.*)$ balancer://upstream%{REQUEST_URI} [P,QSA,L]
	<Proxy balancer://upstream>
		BalancerMember unix:///home/diaspora/diaspora/tmp/diaspora.sock|http://
	</Proxy>
	ProxyRequests Off
	ProxyVia On
	ProxyPreserveHost On
	<Proxy *>
		Require all granted
	</Proxy>
	<Directory /home/diaspora/diaspora/public>
		Options -MultiViews
		Require all granted
	</Directory>
</VirtualHost>
<VirtualHost *:80>
    ServerName nota.404.mn
    ServerAdmin danieldoubet@nota.404.mn
	DocumentRoot /home/diaspora/diaspora/public
	ErrorLog ${APACHE_LOG_DIR}/nota.404.mn.error.log
	CustomLog /dev/null combined
    Protocols h2 http/1.1
	RewriteEngine On
	RewriteCond %{SERVER_NAME} =nota.404.mn
	RewriteRule ^ https://%{SERVER_NAME}%{REQUEST_URI} [END,NE,R=permanent]
</VirtualHost>
</IfModule>

WHAT IN THE WORLD IS GOING ON

Thank you in advanced for all your help and support and for diaspora!

supertux88 · September 18, 2019, 7:28pm

Does the diaspora process run? Or did it crash? Anything in the logs there?

iamdoubz · September 18, 2019, 7:32pm

This is what I get in terminal when I start diaspora* (everything here to me looks normal):

diaspora@computer:~/diaspora$ ./script/server
Starting Diaspora in production mode with 1 Sidekiq worker(s).

I, [2019-09-18T12:23:58.545537 #9571]  INFO -- : [diaspora:__default__] call: 
I, [2019-09-18T12:23:58.545726 #9571]  INFO -- : [diaspora:__default__] schedule :monitor (load by user)
I, [2019-09-18T12:23:58.546116 #9571]  INFO -- : [diaspora:__default__] => monitor  (load by user)
I, [2019-09-18T12:23:58.546273 #9571]  INFO -- : [diaspora:__default__] starting async with 0.2s chain monitor 
I, [2019-09-18T12:23:58.548238 #9571]  INFO -- : [diaspora:web] schedule :monitor (monitor by user)
I, [2019-09-18T12:23:58.548671 #9571]  INFO -- : [diaspora:web] => monitor  (monitor by user)
I, [2019-09-18T12:23:58.550257 #9571]  INFO -- : [diaspora:sidekiq] call: 
I, [2019-09-18T12:23:58.550426 #9571]  INFO -- : [diaspora:sidekiq] schedule :monitor (load by user)
I, [2019-09-18T12:23:58.550785 #9571]  INFO -- : [diaspora:sidekiq] => monitor  (load by user)
I, [2019-09-18T12:23:58.550895 #9571]  INFO -- : [diaspora:sidekiq] starting async with 0.2s chain monitor 
I, [2019-09-18T12:23:58.552878 #9571]  INFO -- : [diaspora:__default__] <= monitor
I, [2019-09-18T12:23:58.554150 #9571]  INFO -- : [Eye] <= loading: ["/home/diaspora/diaspora/config/eye.rb"]
I, [2019-09-18T12:23:58.622844 #9571]  INFO -- : [diaspora:sidekiq:sidekiq1] schedule :monitor (monitor by user)
I, [2019-09-18T12:23:58.623335 #9571]  INFO -- : [diaspora:sidekiq:sidekiq1] => monitor  (monitor by user)
I, [2019-09-18T12:23:58.623709 #9571]  INFO -- : [Eye] <= command: load /home/diaspora/diaspora/config/eye.rb (0.597180511s)
I, [2019-09-18T12:23:58.624200 #9571]  INFO -- : [diaspora:sidekiq] <= monitor
I, [2019-09-18T12:23:58.649908 #9571]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-18T12:23:58.650663 #9571]  INFO -- : [diaspora:web] switch :starting [:unmonitored => :starting] monitor by user
I, [2019-09-18T12:23:58.651233 #9571]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-18T12:23:58.724087 #9571]  INFO -- : [diaspora:sidekiq:sidekiq1] load_external_pid_file: pid_file not found
I, [2019-09-18T12:23:58.724806 #9571]  INFO -- : [diaspora:sidekiq:sidekiq1] switch :starting [:unmonitored => :starting] monitor by user
I, [2019-09-18T12:23:58.728668 #9571]  INFO -- : [diaspora:sidekiq:sidekiq1] daemonizing: `bin/bundle exec sidekiq` with start_grace: 2.5s, env: 'RAILS_ENV=production', <9865> (in /home/diaspora/diaspora)
I, [2019-09-18T12:23:58.728815 #9571]  INFO -- : [diaspora:sidekiq:sidekiq1] sleeping for :start_grace 2.5
I, [2019-09-18T12:24:01.242122 #9571]  INFO -- : [diaspora:sidekiq:sidekiq1] switch :started [:starting => :up] monitor by user
I, [2019-09-18T12:24:01.243735 #9571]  INFO -- : [diaspora:sidekiq:sidekiq1] <= monitor
W, [2019-09-18T12:24:13.659239 #9571]  WARN -- : [Eye::System] [web] sending :KILL signal to <9862> due to timeout (15s)
E, [2019-09-18T12:24:13.659927 #9571] ERROR -- : [diaspora:web] execution failed with #<Timeout::Error: execution expired>; try increasing the start_timeout value(the current value of 15s seems too short)
E, [2019-09-18T12:24:13.660075 #9571] ERROR -- : [diaspora:web] process <> failed to start ("#<Timeout::Error: execution expired>")
I, [2019-09-18T12:24:13.660670 #9571]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] monitor by user
I, [2019-09-18T12:24:13.661403 #9571]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-18T12:24:13.661535 #9571]  INFO -- : [diaspora:web] <= monitor
I, [2019-09-18T12:24:13.661617 #9571]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-18T12:24:13.661759 #9571]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-18T12:24:13.661842 #9571]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-18T12:24:13.661954 #9571]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-18T12:24:13.662030 #9571]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-18T12:24:13.664906 #9571]  INFO -- : [diaspora:web] load_external_pid_file: process <9873> from pid_file found and running (identity: ok) (/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bi)
I, [2019-09-18T12:24:13.665533 #9571]  INFO -- : [diaspora:web] switch :already_running [:down => :up] crashed
I, [2019-09-18T12:24:13.721611 #9571]  INFO -- : [diaspora:web] <= restore

PS

Are there other logs, like Ruby logs or something, that I should be checking? If so, where are these located?

iamdoubz · September 18, 2019, 8:43pm

I found this in the production.log, maybe it means something?:

app/workers/receive_base.rb:11:in `filter_errors_for_retry'
app/workers/receive_public.rb:10:in `perform'
[2019-09-18T15:26:38] WARN  PID-29962 TID-69967902792820 Pod: OFFLINE ConnectionTester::NetFailure: request timed out
[2019-09-18T15:26:57] ERROR PID-29962 TID-69967902792820 ConnectionTester: unexpected error: Faraday::TimeoutError: request timed out
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/adapters/faraday.rb:100:in `block in request'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/callbacks.rb:146:in `block in execute_callbacks'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/callbacks.rb:145:in `each'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/callbacks.rb:145:in `execute_callbacks'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/operations.rb:35:in `finish'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/easy_factory.rb:164:in `block in set_callback'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/ethon-0.12.0/lib/ethon/easy/response_callbacks.rb:68:in `block in complete'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/ethon-0.12.0/lib/ethon/easy/response_callbacks.rb:68:in `each'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/ethon-0.12.0/lib/ethon/easy/response_callbacks.rb:68:in `complete'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/ethon-0.12.0/lib/ethon/easy/operations.rb:33:in `perform'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/operations.rb:16:in `run'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/cacheable.rb:18:in `run'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/block_connection.rb:31:in `run'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/stubbable.rb:25:in `run'
/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/typhoeus-1.3.1/lib/typhoeus/request/before.rb:26:in `run'
[2019-09-18T15:26:57] WARN  PID-29962 TID-69967902792820 Pod: OFFLINE ConnectionTester::Failure: #<Faraday::TimeoutError #<Faraday::TimeoutError: request timed out>>
[2019-09-18T15:27:12] ERROR PID-29962 TID-69967874042440 DiasporaFederation::Federation::Receiver: failed to receive public message: DiasporaFederation::Entities::Retraction::TargetNotFound: not found: Like:4a01a760ce5d0134e50e14dae9ef692e
[2019-09-18T15:27:12] WARN  PID-29962 TID-69967874042440 Sidekiq: {"context":"Job raised exception","job":{"class":"Workers::ReceivePublic","args":["<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n<me:env xmlns:me=\"http://salmon-protocol.org/ns/magic-env\">\n  <me:data type=\"application/xml\">PHJldHJhY3Rpb24-CiAgPGF1dGhvcj5mbGVtbWluZ0BkYXRhdGFmZmVsLmRrPC9hdXRob3I-CiAgPHRhcmdldF9ndWlkPjRhMDFhNzYwY2U1ZDAxMzRlNTBlMTRkYWU5ZWY2OTJlPC90YXJnZXRfZ3VpZD4KICA8dGFyZ2V0X3R5cGU-TGlrZTwvdGFyZ2V0X3R5cGU-CjwvcmV0cmFjdGlvbj4=</me:data>\n  <me:encoding>base64url</me:encoding>\n  <me:alg>RSA-SHA256</me:alg>\n  <me:sig key_id=\"aHFAcG9kLmRpYXNwb3JhLnNvZnR3YXJl\">hTEuWcAZzYBL4AAxItYwnhctUZisjEsVF_LGOwFzJ7kR1Nc-KYqXcaPaa5xdAD48_4aGX4PXTRUBPARK5dK73aabN41WwUDWxzSq4vF_YMcjWaZDL9ihlCKqm350FvFFRiJnhnF5RW1-LdG9wP1MZp2WMsiaTZWNSOOgITBP5bXWkiqr-mhOrEld7bQ_RN1KmeD8-YGZtLob9CLDDVzDwJzN9s1syatURxKM4Y2jbq8SgCJ8Sizo0gWkxGJUGCxVEx7TsNwc4-g5UYULzkPWNEXriuXa35UsnRvkJeyblZTtvoHuAOnhoLAEniMgFXYnNxFzsE9tI84bCVEfsXK7-xLHuBs8nRKYrEtvKJws6eOa4sacfJmeiqUiq-wzbvz7fK4oFjcB7lnMvb3t1o_k_ljN6uruP8qihifwoHtr45DvVUcccOam7CeJNUwJLSFu9dj2hMMZ7sI1ZxYgZblaUoH0fAGsj510YaFQXWHf7HZ1B3QaCyrdXmaBNqDzfJgRjPft0aODgRcb5myht6CSqPymdg7TUn-aI4y1N9YYEW7se6PlE28G3_8sIvqQrHX8FbF47xucDmrphYZdhZuVUYIlbzvS4KmQ6uXXr2Sk5pwxOX2ndwqatFfGmST3VJ0DQrfNNMAqd0ettKqtOwoycF222hv1H9jHFao3s4kDNPo=</me:sig>\n</me:env>\n",false],"retry":10,"queue":"urgent","backtrace":15,"jid":"795526d979a356a10ec76507","created_at":1568820001.1531801,"locale":"en","enqueued_at":1568838431.9952707,"error_message":"not found: Like:4a01a760ce5d0134e50e14dae9ef692e","error_class":"DiasporaFederation::Entities::Retraction::TargetNotFound","failed_at":1568820001.2378547,"retry_count":9,"error_backtrace":["app/workers/receive_public.rb:11:in `block in perform'","app/workers/receive_base.rb:11:in `filter_errors_for_retry'","app/workers/receive_public.rb:10:in `perform'"],"retried_at":1568831624.6591473},"jobstr":"{\"class\":\"Workers::ReceivePublic\",\"args\":[\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?>\\n<me:env xmlns:me=\\\"http://salmon-protocol.org/ns/magic-env\\\">\\n  <me:data type=\\\"application/xml\\\">PHJldHJhY3Rpb24-CiAgPGF1dGhvcj5mbGVtbWluZ0BkYXRhdGFmZmVsLmRrPC9hdXRob3I-CiAgPHRhcmdldF9ndWlkPjRhMDFhNzYwY2U1ZDAxMzRlNTBlMTRkYWU5ZWY2OTJlPC90YXJnZXRfZ3VpZD4KICA8dGFyZ2V0X3R5cGU-TGlrZTwvdGFyZ2V0X3R5cGU-CjwvcmV0cmFjdGlvbj4=</me:data>\\n  <me:encoding>base64url</me:encoding>\\n  <me:alg>RSA-SHA256</me:alg>\\n  <me:sig key_id=\\\"aHFAcG9kLmRpYXNwb3JhLnNvZnR3YXJl\\\">hTEuWcAZzYBL4AAxItYwnhctUZisjEsVF_LGOwFzJ7kR1Nc-KYqXcaPaa5xdAD48_4aGX4PXTRUBPARK5dK73aabN41WwUDWxzSq4vF_YMcjWaZDL9ihlCKqm350FvFFRiJnhnF5RW1-LdG9wP1MZp2WMsiaTZWNSOOgITBP5bXWkiqr-mhOrEld7bQ_RN1KmeD8-YGZtLob9CLDDVzDwJzN9s1syatURxKM4Y2jbq8SgCJ8Sizo0gWkxGJUGCxVEx7TsNwc4-g5UYULzkPWNEXriuXa35UsnRvkJeyblZTtvoHuAOnhoLAEniMgFXYnNxFzsE9tI84bCVEfsXK7-xLHuBs8nRKYrEtvKJws6eOa4sacfJmeiqUiq-wzbvz7fK4oFjcB7lnMvb3t1o_k_ljN6uruP8qihifwoHtr45DvVUcccOam7CeJNUwJLSFu9dj2hMMZ7sI1ZxYgZblaUoH0fAGsj510YaFQXWHf7HZ1B3QaCyrdXmaBNqDzfJgRjPft0aODgRcb5myht6CSqPymdg7TUn-aI4y1N9YYEW7se6PlE28G3_8sIvqQrHX8FbF47xucDmrphYZdhZuVUYIlbzvS4KmQ6uXXr2Sk5pwxOX2ndwqatFfGmST3VJ0DQrfNNMAqd0ettKqtOwoycF222hv1H9jHFao3s4kDNPo=</me:sig>\\n</me:env>\\n\",false],\"retry\":10,\"queue\":\"urgent\",\"backtrace\":15,\"jid\":\"795526d979a356a10ec76507\",\"created_at\":1568820001.1531801,\"locale\":\"en\",\"enqueued_at\":1568838431.9952707,\"error_message\":\"not found: Like:4a01a760ce5d0134e50e14dae9ef692e\",\"error_class\":\"DiasporaFederation::Entities::Retraction::TargetNotFound\",\"failed_at\":1568820001.2378547,\"retry_count\":9,\"error_backtrace\":[\"app/workers/receive_public.rb:11:in `block in perform'\",\"app/workers/receive_base.rb:11:in `filter_errors_for_retry'\",\"app/workers/receive_public.rb:10:in `perform'\"],\"retried_at\":1568831624.6591473}"}
[2019-09-18T15:27:12] WARN  PID-29962 TID-69967874042440 Sidekiq: DiasporaFederation::Entities::Retraction::TargetNotFound: not found: Like:4a01a760ce5d0134e50e14dae9ef692e
[2019-09-18T15:27:12] WARN  PID-29962 TID-69967874042440 Sidekiq: app/workers/receive_public.rb:11:in `block in perform'
app/workers/receive_base.rb:11:in `filter_errors_for_retry'
app/workers/receive_public.rb:10:in `perform'

supertux88 · September 18, 2019, 8:58pm

The output shows that the web process crashed at least once. But if output stops there it’s running after the second start, so it should be fine.

The part you found in the production log are logs from the sidekiq backend and normal. but it’s also a completely different timestamp than when you started diaspora. so the question is, is there something from the frontend when it started/crashed?

So can you check if the frontend process is running stable now? If it’s still the same PID as from your output above it should be 9873, but if you restarted it since then or if it crashed again, it’s another PID. also check if it logs something when it crashed.

iamdoubz · September 19, 2019, 1:45pm

The output shows that the web process crashed at least once. But if output stops there it’s running after the second start, so it should be fine.

Yes the web process crashes and then comes back up. This has happened since I installed diaspora (~2017).

The part you found in the production log are logs from the sidekiq backend and normal. but it’s also a completely different timestamp than when you started diaspora. so the question is, is there something from the frontend when it started/crashed?

I have restarted it lots of times to get anything to work for more than 30 seconds. This morning (UTC-6), at 08:22:00AM - 08:27:00AM, I did another test. Here is a link to the production.log and apache2 error log during that time frame (my personal Nextcloud).

Again, to reiterate, the web process will come up after web process starts for MAX TIME OF 30 SECONDS, then nothing will ever load again until I bring the Ctrl + C to stop server, and start server again with ./script/server. Then, it will work for another max of 30 seconds, etc.

jhass · September 19, 2019, 2:23pm

Unfortunately all those logs show is you manually killing the server after some time. In fact they even show a couple of successful requests (not complete, just examples):

[2019-09-19T08:22:20] INFO  PID-19459 TID-70016803065680 ActionController::Base:   Parameters: {"per_page"=>"10", "page"=>"1", "_"=>"1568899339909"}
[2019-09-19T08:22:20] INFO  PID-19462 TID-70016803065680 Rails: Started GET "/stream?_=1568899339910" for 73.228.170.3 at 2019-09-19 08:22:20 -0500
[2019-09-19T08:22:20] INFO  PID-19462 TID-70016803065680 ActionController::Base: Processing by StreamsController#multi as JSON
[2019-09-19T08:22:20] INFO  PID-19462 TID-70016803065680 ActionController::Base:   Parameters: {"_"=>"1568899339910"}
[2019-09-19T08:22:20] INFO  PID-19459 TID-70016803065680 ActionController::Base: Completed 200 OK in 312ms (Views: 1.9ms | ActiveRecord: 32.5ms)
...
[2019-09-19T08:25:20] INFO  PID-19677 TID-70016803065680 Rails: Started POST "/receive/public/" for 212.118.213.175 at 2019-09-19 08:25:20 -0500
[2019-09-19T08:25:20] INFO  PID-19677 TID-70016803065680 ActionController::Base: Processing by DiasporaFederation::ReceiveController#public as */*
[2019-09-19T08:25:20] INFO  PID-19677 TID-70016803065680 DiasporaFederation::ReceiveController: received a public magic envelope
[2019-09-19T08:25:33] INFO  PID-19702 TID-70016803065680 Rails: Started POST "/receive/public" for 212.178.119.178 at 2019-09-19 08:25:33 -0500
[2019-09-19T08:25:33] INFO  PID-19702 TID-70016803065680 ActionController::Base: Processing by DiasporaFederation::ReceiveController#public as */*
[2019-09-19T08:25:33] INFO  PID-19702 TID-70016803065680 DiasporaFederation::ReceiveController: received a public magic envelope
[2019-09-19T08:25:33] INFO  PID-19417 TID-69995763448320 Sidekiq: Workers::ReceivePublic JID-fc898c9e6ce3b89a3a3dc74f: start
[2019-09-19T08:25:33] INFO  PID-19702 TID-70016803065680 ActionController::Base: Completed 202 Accepted in 3ms
[2019-09-19T08:25:33] INFO  PID-19702 TID-70016803065680 Rails: Started POST "/receive/public" for 209.240.109.238 at 2019-09-19 08:25:33 -0500
[2019-09-19T08:25:33] INFO  PID-19702 TID-70016803065680 ActionController::Base: Processing by DiasporaFederation::ReceiveController#public as */*
[2019-09-19T08:25:33] INFO  PID-19702 TID-70016803065680 DiasporaFederation::ReceiveController: received a public magic envelope
[2019-09-19T08:25:33] INFO  PID-19702 TID-70016803065680 ActionController::Base: Completed 202 Accepted in 2ms

I cannot see the webserver process crashing. How do you observe that? What kind of errors are you getting before you decide to kill the server with Ctrl+C?

iamdoubz · September 19, 2019, 2:41pm

That is correct I am manually stopping server. However, the web site stops working approximately 30 seconds into starting the server. Nothing loads and I get the ajax gif spinning logo for more posts. I then hit refresh in my browser, then I get a 503 or server not found.

From what I can see in the logs, nothing is failing. However, now I cannot even start the server because of this error:

E, [2019-09-19T09:33:33.513633 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:33:33.513651 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)

Full output from terminal:

diaspora@computer:~/diaspora$ ./script/server
Starting Diaspora in production mode with 1 Sidekiq worker(s).

I, [2019-09-19T09:32:19.866027 #31348]  INFO -- : [diaspora:__default__] call: 
I, [2019-09-19T09:32:19.866164 #31348]  INFO -- : [diaspora:__default__] schedule :monitor (load by user)
I, [2019-09-19T09:32:19.866367 #31348]  INFO -- : [diaspora:__default__] => monitor  (load by user)
I, [2019-09-19T09:32:19.866424 #31348]  INFO -- : [diaspora:__default__] starting async with 0.2s chain monitor 
I, [2019-09-19T09:32:19.866994 #31348]  INFO -- : [diaspora:web] schedule :monitor (monitor by user)
I, [2019-09-19T09:32:19.867212 #31348]  INFO -- : [diaspora:web] => monitor  (monitor by user)
I, [2019-09-19T09:32:19.867541 #31348]  INFO -- : [diaspora:sidekiq] call: 
I, [2019-09-19T09:32:19.867603 #31348]  INFO -- : [diaspora:sidekiq] schedule :monitor (load by user)
I, [2019-09-19T09:32:19.867749 #31348]  INFO -- : [diaspora:sidekiq] => monitor  (load by user)
I, [2019-09-19T09:32:19.867803 #31348]  INFO -- : [diaspora:sidekiq] starting async with 0.2s chain monitor 
I, [2019-09-19T09:32:19.868771 #31348]  INFO -- : [diaspora:__default__] <= monitor
I, [2019-09-19T09:32:19.869457 #31348]  INFO -- : [Eye] <= loading: ["/home/diaspora/diaspora/config/eye.rb"]
I, [2019-09-19T09:32:19.884749 #31348]  INFO -- : [Eye] <= command: load /home/diaspora/diaspora/config/eye.rb (0.108562222s)
I, [2019-09-19T09:32:19.884985 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] schedule :monitor (monitor by user)
I, [2019-09-19T09:32:19.885476 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] => monitor  (monitor by user)
I, [2019-09-19T09:32:19.885754 #31348]  INFO -- : [diaspora:sidekiq] <= monitor
I, [2019-09-19T09:32:19.968445 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:19.969211 #31348]  INFO -- : [diaspora:web] switch :starting [:unmonitored => :starting] monitor by user
I, [2019-09-19T09:32:19.969369 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:19.990671 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:19.995901 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] switch :starting [:unmonitored => :starting] monitor by user
I, [2019-09-19T09:32:20.005098 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] daemonizing: `bin/bundle exec sidekiq` with start_grace: 2.5s, env: 'RAILS_ENV=production', <31566> (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:20.005567 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:20.926290 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:22.508682 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] switch :started [:starting => :up] monitor by user
I, [2019-09-19T09:32:22.509031 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] <= monitor
I, [2019-09-19T09:32:23.528395 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:32:23.528513 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:32:23.528650 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:32:23.528889 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] monitor by user
I, [2019-09-19T09:32:23.529233 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:32:23.529289 #31348]  INFO -- : [diaspora:web] <= monitor
I, [2019-09-19T09:32:23.529342 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-19T09:32:23.529415 #31348]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-19T09:32:23.529453 #31348]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-19T09:32:23.529484 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:32:23.529528 #31348]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-19T09:32:23.630348 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:23.630974 #31348]  INFO -- : [diaspora:web] switch :starting [:down => :starting] crashed
I, [2019-09-19T09:32:23.631202 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:24.380510 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:26.981531 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:32:26.981625 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:32:26.981700 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:32:26.981897 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] crashed
I, [2019-09-19T09:32:26.982189 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:32:26.982240 #31348]  INFO -- : [diaspora:web] <= restore
I, [2019-09-19T09:32:26.982305 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-19T09:32:26.982355 #31348]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-19T09:32:26.982402 #31348]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-19T09:32:26.982435 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:32:26.982457 #31348]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-19T09:32:27.082773 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:27.083188 #31348]  INFO -- : [diaspora:web] switch :starting [:down => :starting] crashed
I, [2019-09-19T09:32:27.083351 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:27.798673 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:30.399582 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:32:30.399859 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:32:30.400107 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:32:30.400631 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] crashed
I, [2019-09-19T09:32:30.401162 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:32:30.403622 #31348]  INFO -- : [diaspora:web] <= restore
I, [2019-09-19T09:32:30.403864 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-19T09:32:30.404049 #31348]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-19T09:32:30.404203 #31348]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-19T09:32:30.404396 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:32:30.404537 #31348]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-19T09:32:30.505291 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:30.505665 #31348]  INFO -- : [diaspora:web] switch :starting [:down => :starting] crashed
I, [2019-09-19T09:32:30.505850 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:31.328126 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:33.928985 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:32:33.929061 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:32:33.929104 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:32:33.929325 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] crashed
I, [2019-09-19T09:32:33.929653 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:32:33.929702 #31348]  INFO -- : [diaspora:web] <= restore
I, [2019-09-19T09:32:33.929724 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-19T09:32:33.929788 #31348]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-19T09:32:33.929827 #31348]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-19T09:32:33.929852 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:32:33.929880 #31348]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-19T09:32:34.031607 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:34.031910 #31348]  INFO -- : [diaspora:web] switch :starting [:down => :starting] crashed
I, [2019-09-19T09:32:34.032016 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:34.647371 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:37.248299 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:32:37.248376 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:32:37.248402 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:32:37.248589 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] crashed
I, [2019-09-19T09:32:37.248855 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:32:37.248900 #31348]  INFO -- : [diaspora:web] <= restore
I, [2019-09-19T09:32:37.248940 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-19T09:32:37.248969 #31348]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-19T09:32:37.248989 #31348]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-19T09:32:37.249006 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:32:37.249021 #31348]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-19T09:32:37.355778 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:37.356064 #31348]  INFO -- : [diaspora:web] switch :starting [:down => :starting] crashed
I, [2019-09-19T09:32:37.356180 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:37.936257 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:40.538551 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:32:40.538747 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:32:40.538787 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:32:40.539050 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] crashed
I, [2019-09-19T09:32:40.539360 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:32:40.539405 #31348]  INFO -- : [diaspora:web] <= restore
I, [2019-09-19T09:32:40.539423 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-19T09:32:40.539448 #31348]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-19T09:32:40.539467 #31348]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-19T09:32:40.539481 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:32:40.539491 #31348]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-19T09:32:40.644989 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:40.645234 #31348]  INFO -- : [diaspora:web] switch :starting [:down => :starting] crashed
I, [2019-09-19T09:32:40.645339 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:41.200783 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:43.804094 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:32:43.804192 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:32:43.804246 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:32:43.804472 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] crashed
I, [2019-09-19T09:32:43.804810 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:32:43.804856 #31348]  INFO -- : [diaspora:web] <= restore
I, [2019-09-19T09:32:43.804876 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-19T09:32:43.804908 #31348]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-19T09:32:43.804931 #31348]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-19T09:32:43.804946 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:32:43.804964 #31348]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-19T09:32:43.906762 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:43.907254 #31348]  INFO -- : [diaspora:web] switch :starting [:down => :starting] crashed
I, [2019-09-19T09:32:43.907438 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:44.492865 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
I, [2019-09-19T09:32:47.095662 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:32:47.095743 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:32:47.095807 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:32:47.096021 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] crashed
I, [2019-09-19T09:32:47.096301 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:32:47.096372 #31348]  INFO -- : [diaspora:web] <= restore
I, [2019-09-19T09:32:47.096415 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
W, [2019-09-19T09:32:47.096449 #31348]  WARN -- : [diaspora:web] check crashed: process is down
I, [2019-09-19T09:32:47.096474 #31348]  INFO -- : [diaspora:web] schedule :restore (crashed)
I, [2019-09-19T09:32:47.096496 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:32:47.096515 #31348]  INFO -- : [diaspora:web] => restore  (crashed)
I, [2019-09-19T09:32:47.197314 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
I, [2019-09-19T09:32:47.197573 #31348]  INFO -- : [diaspora:web] switch :starting [:down => :starting] crashed
I, [2019-09-19T09:32:47.197705 #31348]  INFO -- : [diaspora:web] executing: `bin/bundle exec unicorn -c config/unicorn.rb -D` with start_timeout: 15.0s, start_grace: 2.5s, env: 'RAILS_ENV=production PORT=' (in /home/diaspora/diaspora)
I, [2019-09-19T09:32:47.816340 #31348]  INFO -- : [diaspora:web] sleeping for :start_grace 2.5
^CI, [2019-09-19T09:33:46.373594 #31348]  INFO -- : [Eye] => command: stop_all 
I, [2019-09-19T09:33:46.374082 #31348]  INFO -- : [diaspora] call: {:command=>:break_chain}
I, [2019-09-19T09:33:46.374198 #31348]  INFO -- : [diaspora] call: {:command=>:stop, :freeze=>true}
I, [2019-09-19T09:33:46.374696 #31348]  INFO -- : [diaspora:sidekiq] call: 
I, [2019-09-19T09:33:46.374740 #31348]  INFO -- : [diaspora:sidekiq] break chain
I, [2019-09-19T09:33:46.374843 #31348]  INFO -- : [diaspora:sidekiq] call: 
I, [2019-09-19T09:33:46.374879 #31348]  INFO -- : [diaspora:sidekiq] schedule :stop (stop by user)
I, [2019-09-19T09:33:46.374977 #31348]  INFO -- : [diaspora:sidekiq] => stop  (stop by user)
I, [2019-09-19T09:33:46.375015 #31348]  INFO -- : [diaspora:sidekiq] send to all processes stop 
I, [2019-09-19T09:33:46.375326 #31348]  INFO -- : [diaspora:__default__] call: 
I, [2019-09-19T09:33:46.375376 #31348]  INFO -- : [diaspora:__default__] break chain
I, [2019-09-19T09:33:46.375443 #31348]  INFO -- : [diaspora:__default__] call: 
I, [2019-09-19T09:33:46.375504 #31348]  INFO -- : [diaspora:__default__] schedule :stop (stop by user)
I, [2019-09-19T09:33:46.375618 #31348]  INFO -- : [diaspora:__default__] => stop  (stop by user)
I, [2019-09-19T09:33:46.375667 #31348]  INFO -- : [diaspora:__default__] send to all processes stop 
I, [2019-09-19T09:33:46.375896 #31348]  INFO -- : [diaspora:web] schedule :stop (stop by user)
I, [2019-09-19T09:33:46.375965 #31348]  INFO -- : [diaspora:__default__] <= stop
I, [2019-09-19T09:33:46.376972 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] schedule :stop (stop by user)
I, [2019-09-19T09:33:46.377139 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] => stop  (stop by user)
I, [2019-09-19T09:33:46.377320 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] switch :stopping [:up => :stopping] stop by user
I, [2019-09-19T09:33:46.377536 #31348]  INFO -- : [diaspora:sidekiq] <= stop
I, [2019-09-19T09:33:46.377770 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] executing stop_signals [:USR1, 0, :TERM, 10, :KILL]
I, [2019-09-19T09:33:46.377813 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] send_signal USR1 to <31566>
I, [2019-09-19T09:33:46.479290 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] send_signal TERM to <31566>
I, [2019-09-19T09:33:46.771671 #31348]  INFO -- : [diaspora:web] load_external_pid_file: pid_file not found
E, [2019-09-19T09:33:46.771739 #31348] ERROR -- : [diaspora:web] exit status 1, pid_file (/home/diaspora/diaspora/tmp/pids/web.pid) did not appear within the start_grace period (2.5s); check your start_command, or tune the start_grace value (eye expect process to create pid_file in self-daemonization mode)
E, [2019-09-19T09:33:46.771760 #31348] ERROR -- : [diaspora:web] process <> failed to start (:pid_not_found)
I, [2019-09-19T09:33:46.771980 #31348]  INFO -- : [diaspora:web] switch :crashed [:starting => :down] crashed
I, [2019-09-19T09:33:46.773587 #31348]  INFO -- : [diaspora:web] schedule :check_crash (crashed)
I, [2019-09-19T09:33:46.773663 #31348]  INFO -- : [diaspora:web] <= restore
I, [2019-09-19T09:33:46.773689 #31348]  INFO -- : [diaspora:web] => stop  (stop by user)
W, [2019-09-19T09:33:46.773808 #31348]  WARN -- : [diaspora:web] wrong switch 'Cannot transition state via :stopping from :down'
I, [2019-09-19T09:33:46.773938 #31348]  INFO -- : [diaspora:web] switch :unmonitoring [:down => :unmonitored] stop by user
I, [2019-09-19T09:33:46.774016 #31348]  INFO -- : [diaspora:web] <= stop
I, [2019-09-19T09:33:46.774047 #31348]  INFO -- : [diaspora:web] => check_crash  (crashed)
I, [2019-09-19T09:33:46.774078 #31348]  INFO -- : [diaspora:web] <= check_crash
I, [2019-09-19T09:33:49.096245 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] has terminated
I, [2019-09-19T09:33:49.199307 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] switch :stopped [:stopping => :down] stop by user
I, [2019-09-19T09:33:49.199634 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] delete pid_file: /home/diaspora/diaspora/tmp/pids/sidekiq1.pid
I, [2019-09-19T09:33:49.200046 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] switch :unmonitoring [:down => :unmonitored] stop by user
I, [2019-09-19T09:33:49.200274 #31348]  INFO -- : [diaspora:sidekiq:sidekiq1] <= stop
I, [2019-09-19T09:33:49.414334 #31348]  INFO -- : [Eye] <= command: stop_all  (3.04063296s)
diaspora@computer:~/diaspora$

jhass · September 19, 2019, 2:45pm

Anything appearing in production.log while it’s looping in executing.../exit status 1, pid_file ...?

EDIT: Or rather in log/eye_processes_stderr.log / log/eye_processes_stdout.log.

EDIT2: If neither of those yields anything you can also try setting

    stderr_log: 'log/unicorn-stderr.log'
    stdout_log: 'log/unicorn-stdout.log'

in diaspora.yml and check those. (Why do we have so many logs )

iamdoubz · September 19, 2019, 3:40pm

Okay. Before in eye_processes_stdout.log there was nothing, but now I’m getting:

Rack::SSL is enabled
bundler: failed to load command: unicorn (/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn)
bundler: failed to load command: unicorn (/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn)
bundler: failed to load command: unicorn (/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn)
bundler: failed to load command: unicorn (/home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn)

And also before, was not getting anything meaningful from eye_processes_stderr.log but now getting:

master failed to start, check stderr log for details
ArgumentError: directory for stderr_path=/usr/local/app/diaspora/log/unicorn-stderr.log not writable
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/configurator.rb:103:in `block in reload'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/configurator.rb:99:in `each'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/configurator.rb:99:in `reload'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/configurator.rb:77:in `initialize'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:79:in `new'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:79:in `initialize'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/bin/unicorn:128:in `new'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/bin/unicorn:128:in `<top (required)>'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `load'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `<top (required)>'
master failed to start, check stderr log for details
ArgumentError: directory for stderr_path=/usr/local/app/diaspora/log/unicorn-stderr.log not writable

And in same time frame (09:32:19AM - 09:33:45AM UTC-6) in production.log:

https://box.dou.bet/index.php/s/RKSEQzowLAN7BYM

jhass · September 19, 2019, 3:58pm

Yeah, sorry we have bad example values in diaspora.yml for the two unicorn stdout/stderr settings, please don’t just uncomment them but change them according to my example above.

iamdoubz · September 19, 2019, 4:17pm

Okay, I think we may be getting closer:

# unicorn-stderr.log
E, [2019-09-19T11:15:00.416463 #12157] ERROR -- : adding listener failed addr=/home/diaspora/diaspora/tmp/diaspora.sock (in use)
Errno::EADDRINUSE: Address already in use - connect(2) for /home/diaspora/diaspora/tmp/diaspora.sock
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/socket_helper.rb:138:in `initialize'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/socket_helper.rb:138:in `new'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/socket_helper.rb:138:in `bind_listen'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:243:in `listen'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:850:in `block in bind_new_listeners!'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:850:in `each'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:850:in `bind_new_listeners!'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:142:in `start'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/bin/unicorn:128:in `<top (required)>'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `load'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `<top (required)>'
I, [2019-09-19T11:15:03.698541 #12238]  INFO -- : Refreshing Gem list
E, [2019-09-19T11:15:13.016593 #12238] ERROR -- : adding listener failed addr=/home/diaspora/diaspora/tmp/diaspora.sock (in use)
E, [2019-09-19T11:15:13.016790 #12238] ERROR -- : retrying in 0.5 seconds (4 tries left)
E, [2019-09-19T11:15:13.519258 #12238] ERROR -- : adding listener failed addr=/home/diaspora/diaspora/tmp/diaspora.sock (in use)
E, [2019-09-19T11:15:13.519475 #12238] ERROR -- : retrying in 0.5 seconds (3 tries left)
E, [2019-09-19T11:15:14.020760 #12238] ERROR -- : adding listener failed addr=/home/diaspora/diaspora/tmp/diaspora.sock (in use)
E, [2019-09-19T11:15:14.020908 #12238] ERROR -- : retrying in 0.5 seconds (2 tries left)
E, [2019-09-19T11:15:14.521547 #12238] ERROR -- : adding listener failed addr=/home/diaspora/diaspora/tmp/diaspora.sock (in use)
E, [2019-09-19T11:15:14.521621 #12238] ERROR -- : retrying in 0.5 seconds (1 tries left)
E, [2019-09-19T11:15:15.022132 #12238] ERROR -- : adding listener failed addr=/home/diaspora/diaspora/tmp/diaspora.sock (in use)
E, [2019-09-19T11:15:15.022206 #12238] ERROR -- : retrying in 0.5 seconds (0 tries left)
E, [2019-09-19T11:15:15.555043 #12238] ERROR -- : adding listener failed addr=/home/diaspora/diaspora/tmp/diaspora.sock (in use)
Errno::EADDRINUSE: Address already in use - connect(2) for /home/diaspora/diaspora/tmp/diaspora.sock
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/socket_helper.rb:138:in `initialize'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/socket_helper.rb:138:in `new'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/socket_helper.rb:138:in `bind_listen'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:243:in `listen'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:850:in `block in bind_new_listeners!'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:850:in `each'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:850:in `bind_new_listeners!'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:142:in `start'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/bin/unicorn:128:in `<top (required)>'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `load'
  /home/diaspora/diaspora/vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `<top (required)>'

jhass · September 19, 2019, 4:21pm

so something is still running on the socket, maybe just reboot the box.

iamdoubz · September 19, 2019, 4:40pm

I went ahead and restarted the server and deleted all the logs to start fresh as well then did these steps:

Started diaspora ./script/server.
No more errors in terminal where I started server
eye_processes_stderr.log is empty
eye_processes_stdout.log says Rack::SSL is enabled and nothing else
sidekiq.log has 2019-09-19T16:22:12.248Z 10026 TID-ovnoa1hf6 INFO: Booting Sidekiq 5.2.5 with redis options {:url=>"redis://localhost:6379", :id=>"Sidekiq-server-PID-10026"} and nothing else
Apache2 log: box.dou.bet link
production.log looks something like this:

[2019-09-19T11:22:16] INFO  PID-10026 TID-70187297223240 Sidekiq: Workers::ReceivePublic JID-5250959be5950b8beb94b573: done: 0.129 sec
[2019-09-19T11:22:16] INFO  PID-10068 TID-69852409417560 Rails: Started GET "/api/v1/instance" for 116.203.17.124 at 2019-09-19 11:22:16 -0500
[2019-09-19T11:22:16] FATAL PID-10068 TID-69852409417560 Rails:   
[2019-09-19T11:22:16] FATAL PID-10068 TID-69852409417560 Rails: ActionController::RoutingError (No route matches [GET] "/api/v1/instance"):
[2019-09-19T11:22:16] FATAL PID-10068 TID-69852409417560 Rails:   
[2019-09-19T11:22:16] FATAL PID-10068 TID-69852409417560 Rails: vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/debug_exceptions.rb:63:in `call'
vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/rack/logger.rb:36:in `call_app'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/rack/logger.rb:26:in `call'
vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
vendor/bundle/ruby/2.4.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/request_id.rb:25:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.6.2/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/executor.rb:12:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
vendor/bundle/ruby/2.4.0/gems/secure_headers-6.1.0/lib/secure_headers/middleware.rb:11:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-cors-1.0.2/lib/rack/cors.rb:97:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-ssl-1.4.1/lib/rack/ssl.rb:27:in `call'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/engine.rb:522:in `call'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/railtie.rb:185:in `public_send'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/railtie.rb:185:in `method_missing'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/deflater.rb:34:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/lint.rb:49:in `_call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/lint.rb:37:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/show_exceptions.rb:23:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/common_logger.rb:33:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/chunked.rb:54:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/content_length.rb:15:in `call'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:605:in `process_client'
vendor/bundle/ruby/2.4.0/gems/unicorn-worker-killer-0.4.4/lib/unicorn/worker_killer.rb:52:in `process_client'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:700:in `worker_loop'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:548:in `spawn_missing_workers'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:144:in `start'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/bin/unicorn:128:in `<top (required)>'
vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `load'
vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `<top (required)>'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli/exec.rb:74:in `load'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli/exec.rb:74:in `kernel_load'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli/exec.rb:28:in `run'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli.rb:463:in `exec'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli.rb:27:in `dispatch'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli.rb:18:in `start'
bundler (1.17.3) exe/bundle:30:in `block in <top (required)>'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/friendly_errors.rb:124:in `with_friendly_errors'
bundler (1.17.3) exe/bundle:22:in `<top (required)>'
bin/bundle:3:in `load'
bin/bundle:3:in `<main>'
[2019-09-19T11:22:17] INFO  PID-10065 TID-69852409417560 Rails: Started GET "/api/statusnet/config.json" for 116.203.17.124 at 2019-09-19 11:22:17 -0500
[2019-09-19T11:22:17] FATAL PID-10065 TID-69852409417560 Rails:   
[2019-09-19T11:22:17] FATAL PID-10065 TID-69852409417560 Rails: ActionController::RoutingError (No route matches [GET] "/api/statusnet/config.json"):
[2019-09-19T11:22:17] FATAL PID-10065 TID-69852409417560 Rails:   
[2019-09-19T11:22:17] FATAL PID-10065 TID-69852409417560 Rails: vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/debug_exceptions.rb:63:in `call'
vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/rack/logger.rb:36:in `call_app'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/rack/logger.rb:26:in `call'
vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
vendor/bundle/ruby/2.4.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/request_id.rb:25:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.6.2/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.6.2/lib/action_dispatch/middleware/executor.rb:12:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
vendor/bundle/ruby/2.4.0/gems/secure_headers-6.1.0/lib/secure_headers/middleware.rb:11:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-cors-1.0.2/lib/rack/cors.rb:97:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-ssl-1.4.1/lib/rack/ssl.rb:27:in `call'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/engine.rb:522:in `call'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/railtie.rb:185:in `public_send'
vendor/bundle/ruby/2.4.0/gems/railties-5.1.6.2/lib/rails/railtie.rb:185:in `method_missing'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/deflater.rb:34:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/lint.rb:49:in `_call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/lint.rb:37:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/show_exceptions.rb:23:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/common_logger.rb:33:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/chunked.rb:54:in `call'
vendor/bundle/ruby/2.4.0/gems/rack-2.0.6/lib/rack/content_length.rb:15:in `call'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:605:in `process_client'
vendor/bundle/ruby/2.4.0/gems/unicorn-worker-killer-0.4.4/lib/unicorn/worker_killer.rb:52:in `process_client'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:700:in `worker_loop'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:548:in `spawn_missing_workers'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/lib/unicorn/http_server.rb:144:in `start'
vendor/bundle/ruby/2.4.0/gems/unicorn-5.5.0/bin/unicorn:128:in `<top (required)>'
vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `load'
vendor/bundle/ruby/2.4.0/bin/unicorn:23:in `<top (required)>'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli/exec.rb:74:in `load'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli/exec.rb:74:in `kernel_load'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli/exec.rb:28:in `run'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli.rb:463:in `exec'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli.rb:27:in `dispatch'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/cli.rb:18:in `start'
bundler (1.17.3) exe/bundle:30:in `block in <top (required)>'
/home/diaspora/.rvm/rubies/ruby-2.4.6/lib/ruby/site_ruby/2.4.0/bundler/friendly_errors.rb:124:in `with_friendly_errors'
bundler (1.17.3) exe/bundle:22:in `<top (required)>'
bin/bundle:3:in `load'
bin/bundle:3:in `<main>'
...
[2019-09-19T11:28:23] INFO  PID-10026 TID-70187314351260 Sidekiq: Workers::ReceiveLocal JID-c56dbced56466c080c87a842: start
[2019-09-19T11:28:23] INFO  PID-10026 TID-70187313469720 Sidekiq: Workers::ReceivePublic JID-8ca21ccd9e57cde59dd5d856: done: 0.049 sec
[2019-09-19T11:28:23] INFO  PID-10026 TID-70187314351260 Sidekiq: Workers::ReceiveLocal JID-c56dbced56466c080c87a842: done: 0.004 sec
[2019-09-19T11:28:27] INFO  PID-10412 TID-69852409417560 ActionController::Base: Completed 500 Internal Server Error in 137280ms
[2019-09-19T11:28:27] FATAL PID-10412 TID-69852409417560 Rails:   
[2019-09-19T11:28:27] FATAL PID-10412 TID-69852409417560 Rails: Unicorn::ClientShutdown (bytes_read=0):
[2019-09-19T11:28:27] FATAL PID-10412 TID-69852409417560 Rails:   
[2019-09-19T11:28:27] FATAL PID-10412 TID-69852409417560 Rails: 
[2019-09-19T11:28:27] INFO  PID-10412 TID-69852409417560 Rails: Started POST "/receive/public/" for 212.118.213.175 at 2019-09-19 11:28:27 -0500
[2019-09-19T11:28:27] INFO  PID-10412 TID-69852409417560 ActionController::Base: Processing by DiasporaFederation::ReceiveController#public as */*
[2019-09-19T11:28:27] INFO  PID-10412 TID-69852409417560 DiasporaFederation::ReceiveController: received a public magic envelope
[2019-09-19T11:28:35] INFO  PID-10374 TID-69852409417560 ActionController::Base: Completed 500 Internal Server Error in 12625ms (ActiveRecord: 0.0ms)
...
# And a lot more of these types of FATAL errors with >20 second times
[2019-09-19T11:31:23] INFO  PID-10374 TID-69852409417560 ActionController::Base: Completed 500 Internal Server Error in 22180ms (ActiveRecord: 0.0ms)
[2019-09-19T11:31:23] FATAL PID-10374 TID-69852409417560 Rails:   
[2019-09-19T11:31:23] FATAL PID-10374 TID-69852409417560 Rails: Unicorn::ClientShutdown (bytes_read=0):
[2019-09-19T11:31:23] FATAL PID-10374 TID-69852409417560 Rails:   
[2019-09-19T11:31:23] FATAL PID-10374 TID-69852409417560 Rails:

Edit

PS When my website manages to “load” (no posts, just the css stuff), I get something to the effect of Manifest: Line: 1, column: 1, Syntax error. but this also may be that some of the site loads, then the rest gets 503’d.

iamdoubz · September 20, 2019, 2:17pm

I was hoping that I was just missing something and it would be easy, but it appears that it may be a lost cause.

So, if anyone is searching for why #nota404mn is down (https://nota.404.mn), I am changing servers because it appears that the old one is broken beyond repair. I estimate that it will take 12 hours to migrate the data between the two servers. Sorry for everything. If in the off chance that the new server does not work, I will simply restore the backup I have… then give users 3 months to get their data off… and shut it down permanently.

iamdoubz · September 23, 2019, 10:04pm

Got lucky everyone. Nota.404.Mn is back up, a couple bruises, even more scars, but back up nonetheless.

Best guess

Updating nodejs from 8 to 10 ruined something in the diaspora directory that I couldn’t fix.

iamdoubz · October 17, 2019, 3:41pm

Update 24 days later:

I have been able to trace down what package was the culprit and you may want to sit down for this…

Like I said before, ALL OTHER WEBSITES (15 in total), remain unaffected, but diaspora* for some reason, cannot handle TLS1.3 when using Apache2 version 2.4.41. This appears to be a bug in Apache2 itself, but having said that, only the diaspora* web interface is affected.

Word of caution for anyone using Apache and diaspora together and want to use TLS1.3… DO NOT UPDATE TO 2.4.41!!!

What curl -v https://nota.404.mn showed before upgrade to 2.4.41:

* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):

What is shows when on 2.4.41:

* Connected to nota.404.mn (73.228.170.3) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Unknown (8):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Client hello (1):
* TLSv1.3 (OUT), TLS Unknown, Certificate Status (22):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: CN=nota.404.mn
*  start date: Sep  2 15:44:07 2019 GMT
*  expire date: Dec  1 15:44:07 2019 GMT
*  subjectAltName: host "nota.404.mn" matched cert's "nota.404.mn"
*  issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* Using Stream ID: 1 (easy handle 0x55df26b776b0)
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
> GET / HTTP/2
> Host: nota.404.mn
> User-Agent: curl/7.58.0
> Accept: */*
> 
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):