d-note running very slowly after renewing certificate and rebooting server

[elyograg]

The first thing to say is that this is very likely some kind of config mistake that I've made, not a bug in d-note. I can't figure out what's wrong, so I am hoping I can find some troubleshooting help here, so I can figure out what the problem is and get it solved.

I built a replacement certificate (letsencrypt) for my software, installed Ubuntu updates, and rebooted the server. When it came back up, I got timeout issues on the monitoring I've set up, and found that d-note is taking longer than 12 seconds to respond. Everything was fine before the maintenance -- response time was about a tenth of a second.

I have haproxy sitting in front of Apache. The haproxy log seems to indicate that the backend connection to apache is where all the time is being taken. Both haproxy and apache are running https for this virtualhost ... I believe that I tried a non-encrypted apache virtualhost and had problems, so made it all encrypted.

I installed d-note on November 15, 2014. It would have been whatever version was current at that time.

My install is online at https://secrets.elyograg.org where you can see that it's really slow.

[elyograg]

I just did 'git pull' and that didn't make any difference. I was 31 commits behind master.

[elyograg]

There were python modules included in the package update. From apt's history.log:

Start-Date: 2019-06-12  11:02:47
Requested-By: elyograg (1000)
Upgrade: passenger-doc:amd64 (5.0.30-1build2, 5.0.30-1+deb9u1build0.18.04.1), python2.7-dev:amd64 (2.7.15~rc1-1ubuntu0.1, 2.7.15-4ubuntu4~18.04), libpython3.6-minimal:amd64 (3.6.7-1~18.04, 3.6.8-1~18.04.1), dbus-x11:amd64 (1.12.2-1ubuntu1, 1.12.2-1ubuntu1.1), libdbus-1-3:amd64 (1.12.2-1ubuntu1, 1.12.2-1ubuntu1.1), libnet-ssleay-perl:amd64 (1.84-1build1, 1.84-1ubuntu0.1), vim-common:amd64 (2:8.0.1453-1ubuntu1, 2:8.0.1453-1ubuntu1.1), openssl:amd64 (1.1.0g-2ubuntu4.3, 1.1.1-1ubuntu2.1~18.04.1), ruby2.5:amd64 (2.5.1-1ubuntu1.2, 2.5.1-1ubuntu1.4), libpython3.6-dev:amd64 (3.6.7-1~18.04, 3.6.8-1~18.04.1), dbus:amd64 (1.12.2-1ubuntu1, 1.12.2-1ubuntu1.1), python2.7-minimal:amd64 (2.7.15~rc1-1ubuntu0.1, 2.7.15-4ubuntu4~18.04), libpython3.6-stdlib:amd64 (3.6.7-1~18.04, 3.6.8-1~18.04.1), libpython2.7:amd64 (2.7.15~rc1-1ubuntu0.1, 2.7.15-4ubuntu4~18.04), python2.7:amd64 (2.7.15~rc1-1ubuntu0.1, 2.7.15-4ubuntu4~18.04), gitlab-ce:amd64 (11.11.2-ce.0, 11.11.3-ce.0), libpython3.6:amd64 (3.6.7-1~18.04, 3.6.8-1~18.04.1), python3.6:amd64 (3.6.7-1~18.04, 3.6.8-1~18.04.1), libpython2.7-dev:amd64 (2.7.15~rc1-1ubuntu0.1, 2.7.15-4ubuntu4~18.04), libwww-perl:amd64 (6.31-1, 6.31-1ubuntu0.1), libio-socket-ssl-perl:amd64 (2.056-1, 2.060-3~ubuntu18.04.1), python3.6-minimal:amd64 (3.6.7-1~18.04, 3.6.8-1~18.04.1), python-cryptography:amd64 (2.1.4-1ubuntu1.2, 2.1.4-1ubuntu1.3), libglib2.0-dev-bin:amd64 (2.56.4-0ubuntu0.18.04.2, 2.56.4-0ubuntu0.18.04.3), python3-cryptography:amd64 (2.1.4-1ubuntu1.2, 2.1.4-1ubuntu1.3), libruby2.5:amd64 (2.5.1-1ubuntu1.2, 2.5.1-1ubuntu1.4), libglib2.0-bin:amd64 (2.56.4-0ubuntu0.18.04.2, 2.56.4-0ubuntu0.18.04.3), vim-runtime:amd64 (2:8.0.1453-1ubuntu1, 2:8.0.1453-1ubuntu1.1), vim:amd64 (2:8.0.1453-1ubuntu1, 2:8.0.1453-1ubuntu1.1), libglib2.0-dev:amd64 (2.56.4-0ubuntu0.18.04.2, 2.56.4-0ubuntu0.18.04.3), libssl-dev:amd64 (1.1.0g-2ubuntu4.3, 1.1.1-1ubuntu2.1~18.04.1), xxd:amd64 (2:8.0.1453-1ubuntu1, 2:8.0.1453-1ubuntu1.1), libssl-doc:amd64 (1.1.0g-2ubuntu4.3, 1.1.1-1ubuntu2.1~18.04.1), libglib2.0-data:amd64 (2.56.4-0ubuntu0.18.04.2, 2.56.4-0ubuntu0.18.04.3), libpython2.7-minimal:amd64 (2.7.15~rc1-1ubuntu0.1, 2.7.15-4ubuntu4~18.04), vim-tiny:amd64 (2:8.0.1453-1ubuntu1, 2:8.0.1453-1ubuntu1.1), dbus-user-session:amd64 (1.12.2-1ubuntu1, 1.12.2-1ubuntu1.1), passenger:amd64 (5.0.30-1build2, 5.0.30-1+deb9u1build0.18.04.1), libssl1.1:amd64 (1.1.0g-2ubuntu4.3, 1.1.1-1ubuntu2.1~18.04.1), libapache2-mod-passenger:amd64 (5.0.30-1build2, 5.0.30-1+deb9u1build0.18.04.1), python3.6-dev:amd64 (3.6.7-1~18.04, 3.6.8-1~18.04.1), libpython2.7-stdlib:amd64 (2.7.15~rc1-1ubuntu0.1, 2.7.15-4ubuntu4~18.04), libglib2.0-0:amd64 (2.56.4-0ubuntu0.18.04.2, 2.56.4-0ubuntu0.18.04.3)
Remove: linux-image-4.15.0-47-generic:amd64 (4.15.0-47.50), linux-headers-4.15.0-47:amd64 (4.15.0-47.50), linux-modules-4.15.0-47-generic:amd64 (4.15.0-47.50), linux-headers-4.15.0-47-generic:amd64 (4.15.0-47.50)
Purge: linux-tools-4.15.0-47:amd64 (4.15.0-47.50), linux-modules-extra-4.15.0-47-generic:amd64 (4.15.0-47.50), linux-tools-4.15.0-47-generic:amd64 (4.15.0-47.50)
End-Date: 2019-06-12  11:07:45

[elyograg]

I am including graphs from my monitoring server. One is the graph of the last couple of days that xymon shows by default, the other is zoomed in on the point where I did the update and reboot.

All three of the URLs shown there are on the same server. The gitlab instance is running gitlab-ce's standard nginx front end and the blog is hosted in the same apache install as d-note.

I didn't change any configs, just did updates and rebooted. Python 2.7 and some of its modules were updated as you can see in the apt log above.

I also tried to install d-note again, but had some trouble and couldn't get it working, so I switched the document root back to the install that works, but is very slow.

[elyograg]

Here's the haproxy log from typing "secrets.elyograg.org" into a browser:

Jun 13 07:55:01 smeagol haproxy[3924] 69.36.160.253:53480 [13/Jun/2019:07:55:01.057] web-80 web-80/<NOSRV> 0/-1/-1/-1/0 302 107 - - LR-- 2/2/0/0/0 0/0 {secrets.elyograg.org} "GET / HTTP/1.1"
Jun 13 07:55:13 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:01.101] web-443~ be-ssl-4001/gollum 0/0/1/12021/12022 200 2036 - - --VN 1/1/0/0/0 0/0 {secrets.elyograg.org} "GET / HTTP/1.1"
Jun 13 07:55:25 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:13.236] web-443~ be-ssl-4001/gollum 0/0/1/11807/11809 200 1091 - - --VN 1/1/6/6/0 0/0 {secrets.elyograg.org} "GET /static/css/main.css HTTP/1.1"
Jun 13 07:55:25 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:13.238] web-443~ be-ssl-4001/gollum 0/0/1/11818/11819 200 2144 - - --VN 1/1/5/5/0 0/0 {secrets.elyograg.org} "GET /static/js/isaac.js HTTP/1.1"
Jun 13 07:55:25 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:13.238] web-443~ be-ssl-4001/gollum 0/0/1/11824/11825 200 540 - - --VN 1/1/4/4/0 0/0 {secrets.elyograg.org} "GET /static/js/main.js HTTP/1.1"
Jun 13 07:55:25 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:13.248] web-443~ be-ssl-4001/gollum 0/0/6/11819/11825 200 1795 - - --VN 1/1/3/3/0 0/0 {secrets.elyograg.org} "GET /static/js/keygen.js HTTP/1.1"
Jun 13 07:55:25 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:13.255] web-443~ be-ssl-4001/gollum 0/0/3/11820/11823 200 2651 - - --VN 1/1/2/2/0 0/0 {secrets.elyograg.org} "GET /static/js/fingerprint-min.js HTTP/1.1"
Jun 13 07:55:25 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:13.251] web-443~ be-ssl-4001/gollum 0/0/9/11820/11829 200 929 - - --VN 1/1/1/1/0 0/0 {secrets.elyograg.org} "GET /static/js/hashcash.js HTTP/1.1"
Jun 13 07:55:25 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:13.253] web-443~ be-ssl-4001/gollum 0/0/11/11816/11828 200 2234 - - --VN 1/1/0/0/0 0/0 {secrets.elyograg.org} "GET /static/js/sha1-min.js HTTP/1.1"
Jun 13 07:55:25 smeagol haproxy[3924] 69.36.160.253:53482 [13/Jun/2019:07:55:25.281] web-443~ be-ssl-4001/gollum 0/0/1/-1/2 -1 0 - - CDVN 1/1/0/0/0 0/0 {secrets.elyograg.org} "GET /favicon.ico HTTP/1.1"

The initial (http) request completes super-fast - haproxy redirects it to https. Then the middle part of the log shows the nearly 12 second delay on all the requests that go to d-note. The delay is in both the second-to-last and last time values, which are the "waiting for server" time and the total time. Then the favicon is requested and that is fast.

[elyograg]

I put some logging into the __init\.py script.

elyograg@smeagol:/var/www/secrets.elyograg.org/dnote$ git diff
diff --git a/__init__.py b/__init__.py
index 5022cde..4339b7b 100644
--- a/__init__.py
+++ b/__init__.py
@@ -1,6 +1,8 @@
 """This module sets up the paths for the Flask web application."""
 import os
 import utils
+import sys
+import datetime
 from Crypto import Random
 from flask import Flask, render_template, request, redirect, url_for
 from note import Note
@@ -10,9 +12,13 @@ HERE = DNOTE.root_path

 @DNOTE.route('/', methods=['GET'])
 def index():
+    print >> sys.stderr, datetime.datetime.now().strftime("%d-%b-%Y (%H:%M:%S.%f)") + " log1"
     """Return the index.html for the main application."""
+    print >> sys.stderr, datetime.datetime.now().strftime("%d-%b-%Y (%H:%M:%S.%f)") + " log2"
     error = request.args.get('error', None)
+    print >> sys.stderr, datetime.datetime.now().strftime("%d-%b-%Y (%H:%M:%S.%f)") + " log3"
     note = Note()
+    print >> sys.stderr, datetime.datetime.now().strftime("%d-%b-%Y (%H:%M:%S.%f)") + " log4"
     return render_template('index.html', random=note.url, error=error)

 @DNOTE.route('/security/', methods=['GET'])

This did not show the 12 second delay.

[Thu Jun 13 09:52:26.920852 2019] [wsgi:error] [pid 13409] [client 192.168.1.200:53506] 13-Jun-2019 (09:52:26.920767) log1
[Thu Jun 13 09:52:26.920945 2019] [wsgi:error] [pid 13409] [client 192.168.1.200:53506] 13-Jun-2019 (09:52:26.920907) log2
[Thu Jun 13 09:52:26.921159 2019] [wsgi:error] [pid 13409] [client 192.168.1.200:53506] 13-Jun-2019 (09:52:26.921116) log3
[Thu Jun 13 09:52:27.135399 2019] [wsgi:error] [pid 13409] [client 192.168.1.200:53506] 13-Jun-2019 (09:52:27.135358) log4

So I am guessing that the problem may be in mod_wsgi, python, or apache. A problem in apache seems unlikely, as the same server is serving a wordpress blog and that is not showing any delays.

The /etc/hosts file is properly set up, so I wouldn't expect reverse DNS to be an issue. I did have the haproxy back end going to the server's private IP address to talk to apache ... I switched that to 127.0.0.1 with no change in behavior.

[elyograg]

If I reconfigure haproxy and apache so d-note is running on a virtualhost without SSL, then the page loads fast. So the 12 second pause appears to be an Apache SSL problem.

The site does have SSL even when Apache doesn't -- haproxy does that. But the app doesn't work, because the POST is being sent as http, not https. Here's the haproxy log showing that:

Jun 13 16:01:51 smeagol haproxy[20531] 69.36.160.253:54939 [13/Jun/2019:16:01:51.382] web-80 web-80/<NOSRV> 0/-1/-1/-1/0 302 130 - - LR-- 2/1/0/0/0 0/0 {secrets.elyograg.org} "POST /post HTTP/1.1"
Jun 13 16:01:51 smeagol haproxy[20531] 69.36.160.253:54924 [13/Jun/2019:16:01:51.394] web-443~ be-gollum-81/gollum 0/0/0/264/264 404 2939 - - --VN 1/1/0/1/0 0/0 {secrets.elyograg.org} "GET /post HTTP/1.1"

You can see the POST happening on my "web-80" front end, returning a 302 redirect, which the browser then does -- as a GET, not a POST. Which fails, returning a 404.

This is in the HTML returned by the initial page load when the apache virtualhost is not encrypted -- with an HTTP url:

<form method="POST" onsubmit="return validate_form()" action="http://secrets.elyograg.org/post">

I have left the config so apache doesn't have SSL configured - so if you type 'secrets.elyograg.org' into a browser, you will see that the initial page loads quickly, but creating notes doesn't work because it tries to do it without SSL. Is it possible to configure d-note so that it will use https even though apache isn't running SSL?

[elyograg]

Problem solved. Switched back to SSL, and added the following to the virtualhost in Apache:

SSLCipherSuite RC4-MD5:ECDHE-RSA-AES256-SHA384:DHE-RSA-AES128-SHA:AES256-SHA:AES256-SHA256

Found that the other SSL virtualhosts in Apache had that cipher config and they were not experiencing any delays.