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

[atoponce]

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

[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.