Maltfield Log/2024 H1
My work log from the first half of the year 2024. I intentionally made this verbose to make future admin's work easier when troubleshooting. The more keywords, error messages, etc that are listed in this log, the more helpful it will be for the future OSE Sysadmin.
Contents
See Also
Fri March 08, 2024
- It's been 1 week since I fixed the VPN cert & ossec & email alert spam loop on the server, so today I'm checking-in to see if that fixed the issue with the apache ram spike & mysql backend outage that was causing varnish errors on the wiki and other sites
- Since the last change on March 01, I got two emails from Hetzner about the server being reset
- 2024-03-03 11:47 and
- 2024-03-04 16:28
- I emailed Marcin, and he confirmed that the server had the same issues, so he initiated the reboots
- I logged into Munin
- postfix mailqueue is lower, but it never really was very high. now it's about 1-3 items in the queue. before my change it was constantly about 4. The peak was back in August when it shot up to 140. Perhaps email campaigns. Anyway, though the emails were very annoying, I don't think that was the issue.
- I see another 2 gaps in the mysql charts for the last week. The X-axis isn't dated, so it's hard to pin-point exactly when, but they likely preceded Marcin's two reboots.
- cooresponding to those two gaps are a massive spike in the "number of threads" chart — from about 480 threads to ~850 threads — in both instances
- again, we see httpd rss (ram) usage spike at the same time as the outages
- I checked to see if there was any OOM errors killing the mysql server, but I get anything
[root@opensourceecology log]# journalctl --no-pager | grep -iA300 'invoked oom-killer'
[root@opensourceecology log]#
[root@opensourceecology log]# journalctl --no-pager | grep -iA300 'oom-killer'
[root@opensourceecology log]#
[root@opensourceecology log]# dmesg -T | grep -A300 -i 'invoked oom-killer' | grep -E "\[\s*[0-9]+\]|\[ pid \]" | egrep '[0-9]{6,7}'
[root@opensourceecology log]#
# indeed, it looks like the system would kill mysql second. But varnish first. Anyway, probably httpd should have a higher score than our DB. But this system has 64 GB of RAM; it's hard to imagine it running-out. Anyway, logs above show no OOM event; unless it doesn't go far back enough
<pre>
[root@opensourceecology log]# printf 'PID\tOOM Score\tOOM Adj\tCommand\n' && while read -r pid comm; do [ -f /proc/$pid/oom_score ] && [ $(cat /proc/$pid/oom_score) != 0 ] && printf '%d\t%d\t\t%d\t%s\n' "$pid" "$(cat /proc/$pid/oom_score)" "$(cat /proc/$pid/oom_score_adj)" "$comm"; done < <(ps -e -o pid= -o comm=) | sort -k 2nr | head -n 10
PID OOM Score OOM Adj Command
2115 220 0 varnishd
1650 5 0 mysqld
11658 1 0 awstats.pl
13681 1 0 httpd
13761 1 0 httpd
14152 1 0 httpd
[root@opensourceecology log]#
[root@opensourceecology log]# free -g
total used free shared buff/cache available
Mem: 62 22 34 0 6 39
Swap: 31 0 31
[root@opensourceecology log]#
- I checked the apache logs for March 3 & 4. There's some errors but nothing jumped-out as an issue. Except that they were surprisingly short logs..
- I checked the mysql logs
- preceding the line
mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql(which would have happened after Marcin's reboot), I see some errors indicating the DB crashed and needs to be repaired - curiously, I don't see a trend of this from last week. I only see two of these (from this week only)
- Here's the log from 2024-03-03
- preceding the line
240229 22:32:47 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql 240229 22:32:47 [Note] /usr/libexec/mysqld (mysqld 5.5.65-MariaDB) starting as process 1673 ... 240229 22:32:47 InnoDB: The InnoDB memory heap is disabled 240229 22:32:47 InnoDB: Mutexes and rw_locks use GCC atomic builtins 240229 22:32:47 InnoDB: Compressed tables use zlib 1.2.7 240229 22:32:47 InnoDB: Using Linux native AIO 240229 22:32:47 InnoDB: Initializing buffer pool, size = 128.0M 240229 22:32:47 InnoDB: Completed initialization of buffer pool 240229 22:32:47 InnoDB: highest supported file format is Barracuda. InnoDB: The log sequence number in ibdata files does not match InnoDB: the log sequence number in the ib_logfiles! InnoDB: Restoring possible half-written data pages from the doublewrite buffer... 240229 22:32:48 InnoDB: Waiting for the background threads to start 240229 22:32:49 Percona XtraDB (http://www.percona.com) 5.5.61-MariaDB-38.13 started; log sequence number 587581798074 240229 22:32:49 [Note] Plugin 'FEEDBACK' is disabled. 240229 22:32:49 [Note] Event Scheduler: Loaded 0 events 240229 22:32:49 [Note] /usr/libexec/mysqld: ready for connections. Version: '5.5.65-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 0 MariaDB Server 240229 22:32:49 [ERROR] mysqld: Table './osemain_db/wp_options' is marked as crashed and should be repaired 240229 22:32:49 [Warning] Checking table: './osemain_db/wp_options' 240229 22:33:37 [ERROR] mysqld: Table './osemain_s_db/wp_options' is marked as crashed and should be repaired 240229 22:33:37 [Warning] Checking table: './osemain_s_db/wp_options' 240229 22:37:57 [ERROR] mysqld: Table './osewiki_db/wiki_searchindex' is marked as crashed and should be repaired 240229 22:37:57 [Warning] Checking table: './osewiki_db/wiki_searchindex' 240229 23:48:30 [ERROR] mysqld: Table './oswh_db/wp_options' is marked as crashed and should be repaired 240229 23:48:30 [Warning] Checking table: './oswh_db/wp_options' 240303 16:49:08 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
- And here's the log from 2024-03-04
240303 16:49:08 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql 240303 16:49:08 [Note] /usr/libexec/mysqld (mysqld 5.5.65-MariaDB) starting as process 1689 ... 240303 16:49:08 InnoDB: The InnoDB memory heap is disabled 240303 16:49:08 InnoDB: Mutexes and rw_locks use GCC atomic builtins 240303 16:49:08 InnoDB: Compressed tables use zlib 1.2.7 240303 16:49:08 InnoDB: Using Linux native AIO 240303 16:49:08 InnoDB: Initializing buffer pool, size = 128.0M 240303 16:49:08 InnoDB: Completed initialization of buffer pool 240303 16:49:08 InnoDB: highest supported file format is Barracuda. InnoDB: The log sequence number in ibdata files does not match InnoDB: the log sequence number in the ib_logfiles! InnoDB: Restoring possible half-written data pages from the doublewrite buffer... 240303 16:49:09 InnoDB: Waiting for the background threads to start 240303 16:49:10 Percona XtraDB (http://www.percona.com) 5.5.61-MariaDB-38.13 started; log sequence number 587767716547 240303 16:49:10 [Note] Plugin 'FEEDBACK' is disabled. 240303 16:49:10 [Note] Event Scheduler: Loaded 0 events 240303 16:49:10 [Note] /usr/libexec/mysqld: ready for connections. Version: '5.5.65-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 0 MariaDB Server 240304 21:29:24 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql 240304 21:29:24 [Note] /usr/libexec/mysqld (mysqld 5.5.65-MariaDB) starting as process 1650 ... 240304 21:29:24 InnoDB: The InnoDB memory heap is disabled 240304 21:29:24 InnoDB: Mutexes and rw_locks use GCC atomic builtins 240304 21:29:24 InnoDB: Compressed tables use zlib 1.2.7 240304 21:29:24 InnoDB: Using Linux native AIO 240304 21:29:24 InnoDB: Initializing buffer pool, size = 128.0M 240304 21:29:24 InnoDB: Completed initialization of buffer pool 240304 21:29:24 InnoDB: highest supported file format is Barracuda. InnoDB: The log sequence number in ibdata files does not match InnoDB: the log sequence number in the ib_logfiles! InnoDB: Restoring possible half-written data pages from the doublewrite buffer... 240304 21:29:24 InnoDB: Waiting for the background threads to start 240304 21:29:25 Percona XtraDB (http://www.percona.com) 5.5.61-MariaDB-38.13 started; log sequence number 587833491019 240304 21:29:25 [Note] Plugin 'FEEDBACK' is disabled. 240304 21:29:25 [Note] Event Scheduler: Loaded 0 events 240304 21:29:25 [Note] /usr/libexec/mysqld: ready for connections. Version: '5.5.65-MariaDB' socket: '/var/lib/mysql/mysql.sock' port: 0 MariaDB Server 240304 21:29:27 [ERROR] mysqld: Table './osemain_db/wp_options' is marked as crashed and should be repaired 240304 21:29:27 [Warning] Checking table: './osemain_db/wp_options' 240304 21:42:21 [ERROR] mysqld: Table './osemain_s_db/wp_options' is marked as crashed and should be repaired 240304 21:42:21 [Warning] Checking table: './osemain_s_db/wp_options'
- Actually, those errors occurred immediately after startup. So likely they're a symptom of the previous abrupt shutdown and not the cause of the shutdown.
- anyway, we learned that the server came back online at
2024-03-03 16:49:08&2024-03-04 21:29:24UTC- also, if I check the charts, the outages appear to be ~12 hours before Marcin rebooted the server in both cases
- curiously the last message in the httpd error error log on 2024-03-03 is 08:27:41
- for some reason the Mar 03 logs spills-over from error_log-20240303.gz to error_log-2024-04004.gz
- Here's the httpd erorr log's lines preceeding the reboot at Mar 03 16:49
[Sat Mar 02 07:33:18.383448 2024] [lbmethod_heartbeat:notice] [pid 1098] AH02282: No slotmem from mod_heartmonitor [Sat Mar 02 07:33:18.383819 2024] [ssl:warn] [pid 1098] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache] [Sat Mar 02 07:33:18.384664 2024] [ssl:warn] [pid 1098] AH02292: Init: Name-based SSL virtual hosts only work for clients with TLS server name indication support (RFC 4366) [Sat Mar 02 07:33:18.442973 2024] [mpm_prefork:notice] [pid 1098] AH00163: Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips configured -- resuming normal operations [Sat Mar 02 07:33:18.442983 2024] [core:notice] [pid 1098] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND' [Sat Mar 02 09:28:33.102614 2024] [:error] [pid 7188] [client 127.0.0.1:37960] [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Operator EQ matched 0 at REQUEST_HEADERS. [file "/etc/httpd/modsecurity.d/activated_rules/modsecurity_crs_21_protocol_anomalies.conf"] [line "47"] [id "960015"] [rev "1"] [msg "Request Missing an Accept Header"] [severity "NOTICE"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/MISSING_HEADER_ACCEPT"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"] [hostname "awstats.opensourceecology.org"] [uri "/wp-login.php"] [unique_id "ZeLxQepLYu-sFhwtgY8GhQAAAA4"], referer: http://awstats.opensourceecology.org/wp-login.php [Sat Mar 02 09:28:33.254850 2024] [:error] [pid 7188] [client 127.0.0.1:37960] [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Operator EQ matched 0 at REQUEST_HEADERS. [file "/etc/httpd/modsecurity.d/activated_rules/modsecurity_crs_21_protocol_anomalies.conf"] [line "47"] [id "960015"] [rev "1"] [msg "Request Missing an Accept Header"] [severity "NOTICE"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/MISSING_HEADER_ACCEPT"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"] [hostname "munin.opensourceecology.org"] [uri "/wp-login.php"] [unique_id "ZeLxQepLYu-sFhwtgY8GhgAAAA4"], referer: http://munin.opensourceecology.org/wp-login.php [Sat Mar 02 21:04:15.333825 2024] [:error] [pid 23728] [client 127.0.0.1:47218] script '/var/www/html/certbot/htdocs/wp-login.php' not found or unable to stat [Sun Mar 03 01:31:46.528392 2024] [:error] [pid 2068] [client 127.0.0.1:33370] script '/var/www/html/certbot/htdocs/timthumb.php' not found or unable to stat [Sun Mar 03 01:31:54.395564 2024] [:error] [pid 2689] [client 127.0.0.1:33488] script '/var/www/html/certbot/htdocs/thumb.php' not found or unable to stat [Sun Mar 03 01:31:59.971621 2024] [:error] [pid 3775] [client 127.0.0.1:33512] script '/var/www/html/certbot/htdocs/timthumb.php' not found or unable to stat [Sun Mar 03 01:32:03.104518 2024] [:error] [pid 3775] [client 127.0.0.1:33512] script '/var/www/html/certbot/htdocs/thumb.php' not found or unable to stat [Sun Mar 03 01:32:03.742281 2024] [access_compat:error] [pid 4096] [client 127.0.0.1:33596] AH01797: client denied by server configuration: /var/www/html/certbot/htdocs/.git [Sun Mar 03 01:32:24.865011 2024] [access_compat:error] [pid 3775] [client 127.0.0.1:33876] AH01797: client denied by server configuration: /var/www/html/certbot/htdocs/.git [Sun Mar 03 05:38:12.408871 2024] [mpm_prefork:error] [pid 1098] AH00161: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting [Sun Mar 03 08:27:41.722042 2024] [mpm_prefork:notice] [pid 1098] AH00171: Graceful restart requested, doing restart [Sun Mar 03 08:27:41.803267 2024] [lbmethod_heartbeat:notice] [pid 1098] AH02282: No slotmem from mod_heartmonitor [Sun Mar 03 08:27:41.806580 2024] [ssl:warn] [pid 1098] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache] [Sun Mar 03 08:27:41.810343 2024] [ssl:warn] [pid 1098] AH02292: Init: Name-based SSL virtual hosts only work for clients with TLS server name indication support (RFC 4366) [Sun Mar 03 08:27:41.844035 2024] [mpm_prefork:notice] [pid 1098] AH00163: Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips configured -- resuming normal operations [Sun Mar 03 08:27:41.844044 2024] [core:notice] [pid 1098] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND' [Sun Mar 03 16:49:08.706487 2024] [suexec:notice] [pid 1104] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
- Here's the httpd erorr log's lines preceeding the reboot at Mar 04 21:29
[Mon Mar 04 01:48:24.693378 2024] [:error] [pid 26475] [client 127.0.0.1:36712] script '/var/www/html/certbot/htdocs/about.php' not found or unable to stat [Mon Mar 04 04:50:27.939387 2024] [:error] [pid 4300] [client 127.0.0.1:54342] [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Operator EQ matched 0 at REQUEST_HEADERS. [file "/etc/httpd/modsecurity.d/activated_rules/modsecurity_crs_21_protocol_anomalies.conf"] [line "47"] [id "960015"] [rev "1"] [msg "Request Missing an Accept Header"] [severity "NOTICE"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/MISSING_HEADER_ACCEPT"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"] [hostname "munin.opensourceecology.org"] [uri "/favicon.ico"] [unique_id "ZeVTExLnCbFmyBDlR2p-RAAAAAU"] [Mon Mar 04 04:53:28.722540 2024] [:error] [pid 7925] [client 127.0.0.1:56620] script '/var/www/html/certbot/htdocs/wp-login.php' not found or unable to stat [Mon Mar 04 05:22:50.379507 2024] [mpm_prefork:notice] [pid 1104] AH00171: Graceful restart requested, doing restart [Mon Mar 04 05:22:50.471872 2024] [lbmethod_heartbeat:notice] [pid 1104] AH02282: No slotmem from mod_heartmonitor [Mon Mar 04 05:22:50.472237 2024] [ssl:warn] [pid 1104] AH01873: Init: Session Cache is not configured [hint: SSLSessionCache] [Mon Mar 04 05:22:50.473094 2024] [ssl:warn] [pid 1104] AH02292: Init: Name-based SSL virtual hosts only work for clients with TLS server name indication support (RFC 4366) [Mon Mar 04 05:22:50.507737 2024] [mpm_prefork:notice] [pid 1104] AH00163: Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips configured -- resuming normal operations [Mon Mar 04 05:22:50.507745 2024] [core:notice] [pid 1104] AH00094: Command line: '/usr/sbin/httpd -D FOREGROUND' [Mon Mar 04 05:27:16.544129 2024] [:error] [pid 21743] [client 127.0.0.1:51880] script '/var/www/html/certbot/htdocs/xmlrpc.php' not found or unable to stat [Mon Mar 04 07:27:16.824773 2024] [:error] [pid 2759] [client 127.0.0.1:41932] script '/var/www/html/certbot/htdocs/xmlrpc.php' not found or unable to stat [Mon Mar 04 08:06:12.898889 2024] [:error] [pid 16264] [client 127.0.0.1:38670] [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 2). Operator EQ matched 0 at REQUEST_HEADERS. [file "/etc/httpd/modsecurity.d/activated_rules/modsecurity_crs_21_protocol_anomalies.conf"] [line "47"] [id "960015"] [rev "1"] [msg "Request Missing an Accept Header"] [severity "NOTICE"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/MISSING_HEADER_ACCEPT"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"] [hostname "munin.opensourceecology.org"] [uri "/thoms.php"] [unique_id "ZeWA9CMy-toJ1WTJh4QWygAAAAo"] ... (the above line repeats 357 times) ... [Mon Mar 04 09:30:27.312228 2024] [mpm_prefork:error] [pid 1104] AH00161: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting [Mon Mar 04 21:29:24.550406 2024] [suexec:notice] [pid 1107] AH01232: suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
- from above, it looks like apache kicked-off child workers until this error was thrown
server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting
- there's probably some delay between the root cause and the
MaxRequestWorkerserror, but we're getting closer: the errors popped-up at Mar 03 05:38:12 and Mar 04 09:30:27 UTC- curiously, the very last line in access_log-20240303.gz occurred at this exact minute
127.0.0.1 - - [03/Mar/2024:05:37:41 +0000] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips (internal dummy connection)" 127.0.0.1 - - [03/Mar/2024:05:38:02 +0000] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips (internal dummy connection)"
- that "internal dummy connection" appears to hit the apache server 1-8-ish times per second
- there is no request from 09:30 on Mar 04, but there is one 1 minute earlier @ at 09:29. And the next one after that is after the reboot.
127.0.0.1 - - [04/Mar/2024:09:27:31 +0000] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips (int ernal dummy connection)" 127.0.0.1 - - [04/Mar/2024:09:29:29 +0000] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips (internal dummy connection)" 127.0.0.1 - - [04/Mar/2024:21:29:57 +0000] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips (internal dummy connection)"
- apache docs say that these "internal dummy connection" queries are initiated when it's managing child processes. so again, it's a symptom — not the cause https://cwiki.apache.org/confluence/display/httpd/InternalDummyConnection
- at Mar 04 08:06 there are a ton of requests from what looks like some bot that are returned 403 errors. But we should be able to handle this
... 127.0.0.1 - - [04/Mar/2024:08:05:59 +0000] "GET /cjfuns.php HTTP/1.0" 403 212 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:05:59 +0000] "GET /wp-content/pm.php HTTP/1.0" 403 219 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:05:59 +0000] "GET /gawean.PhP7 HTTP/1.0" 403 213 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:00 +0000] "GET /404.php HTTP/1.0" 403 209 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:00 +0000] "GET /wp.php HTTP/1.0" 403 208 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:00 +0000] "GET /radio.php HTTP/1.0" 403 211 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:01 +0000] "GET /chosen.php HTTP/1.0" 403 212 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:01 +0000] "GET /simple.php HTTP/1.0" 403 212 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:01 +0000] "GET /class.api.php HTTP/1.0" 403 215 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:02 +0000] "GET /wp-head.php HTTP/1.0" 403 213 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:02 +0000] "GET /file.php HTTP/1.0" 403 210 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:02 +0000] "GET /wp-content/plugins/ccx/index.php HTTP/1.0" 403 234 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:02 +0000] "GET /wp-includes/wp-class.php HTTP/1.0" 403 226 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:03 +0000] "GET /assets/css/403.php HTTP/1.0" 403 220 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:03 +0000] "GET /css/403.php HTTP/1.0" 403 213 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:03 +0000] "GET /403.php HTTP/1.0" 403 209 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:04 +0000] "GET /wp-content/plugins/instabuilder2/cache/plugins/moon.php HTTP/1.0" 403 257 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:04 +0000] "GET /wp-content/plugins/WordPressCore/include.php HTTP/1.0" 403 246 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:04 +0000] "GET /wp-content/plugins/core-plugin/include.php HTTP/1.0" 403 244 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:05 +0000] "GET /wp-content/plugins/core/include.php HTTP/1.0" 403 237 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:05 +0000] "GET /wp-content/plugins/envato-market/inc/class-envato-market-api.php HTTP/1.0" 403 266 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:05 +0000] "GET /worm0.PhP7 HTTP/1.0" 403 212 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:05 +0000] "GET /wp-content/plugins/index.php HTTP/1.0" 403 230 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:06 +0000] "GET /wp-config-sample.php HTTP/1.0" 403 222 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:06 +0000] "GET /.well-known/admin.php HTTP/1.0" 403 223 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:06 +0000] "GET /mah.php HTTP/1.0" 403 209 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:07 +0000] "GET /cong.php HTTP/1.0" 403 210 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:07 +0000] "GET /.tmb/class_api.php HTTP/1.0" 403 220 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:07 +0000] "GET /wp-admin/css/colors/blue/blue.php?wall= HTTP/1.0" 403 235 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:08 +0000] "GET /wp-atom.php HTTP/1.0" 403 213 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:08 +0000] "GET /wp-content/plugins/yyobang/mar.php HTTP/1.0" 403 236 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:08 +0000] "GET /wp-admin/network/class_api.php HTTP/1.0" 403 232 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:08 +0000] "GET /wp-content/plugins/press/wp-class.php HTTP/1.0" 403 239 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:09 +0000] "GET /wp-apxupx.php?apx=upx HTTP/1.0" 403 215 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:09 +0000] "GET /wp-admin/js/widgets/class_api.php HTTP/1.0" 403 235 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:09 +0000] "GET /wp-content/themes/twentyfive/include.php HTTP/1.0" 403 242 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:10 +0000] "GET /wp-admin/user/class_api.php HTTP/1.0" 403 229 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:10 +0000] "GET /wp-admin/includes/class_api.php HTTP/1.0" 403 233 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:10 +0000] "GET /wp-seo.php HTTP/1.0" 403 212 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:11 +0000] "GET /wp-uploads-config.php HTTP/1.0" 403 223 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:11 +0000] "GET /wwr.php HTTP/1.0" 403 209 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:11 +0000] "GET /wp-mail.php HTTP/1.0" 403 213 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:11 +0000] "GET /filefuns.php HTTP/1.0" 403 214 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:12 +0000] "GET /options-reading.php HTTP/1.0" 403 221 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:12 +0000] "GET /postnews.php HTTP/1.0" 403 214 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:12 +0000] "GET /thoms.php HTTP/1.0" 403 211 "-" "-" 127.0.0.1 - - [04/Mar/2024:08:06:17 +0000] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips (internal dummy connection)"
- there are remarkably few requests hitting the server that are *not* these "internal dummy connection" lines
[root@opensourceecology httpd]# zgrep -vi 'internal dummy' access_log-20240301.gz | wc -l 19 [root@opensourceecology httpd]# [root@opensourceecology httpd]# zgrep -vi 'internal dummy' access_log-20240302.gz | wc -l 29 [root@opensourceecology httpd]# zgrep -vi 'internal dummy' access_log-20240303.gz | wc -l 138 [root@opensourceecology httpd]# zgrep -vi 'internal dummy' access_log-20240304.gz | wc -l 43 [root@opensourceecology httpd]# zgrep -vi 'internal dummy' access_log-20240305.gz | wc -l 398 [root@opensourceecology httpd]# zgrep -vi 'internal dummy' access_log-20240306.gz | wc -l 462 [root@opensourceecology httpd]#
- ah, it's individual vhost files; the wiki and phpList are by-far the most active
[root@opensourceecology httpd]# for dir in $(find . -type d); do echo $dir; echo -ne '\t'; zgrep -vi 'internal dummy' $dir/access_log-20240302.gz | wc -l; done . 29 ./wiki.opensourceecology.org 110949 ./www.openbuildinginstitute.org 1021 ./phplist.opensourceecology.org 67288 ./oswh.opensourceecology.org 48 ./forum.opensourceecology.org 7704 ./microfactory.opensourceecology.org 77 ./seedhome.openbuildinginstitute.org 9 ./staging.openbuildinginstitute.org gzip: ./staging.openbuildinginstitute.org/access_log-20240302.gz: No such file or directory 0 ./store.opensourceecology.org 172 ./fef.opensourceecology.org 526 ./www.opensourceecology.org 2499 ./staging.opensourceecology.org 165 ./munin.opensourceecology.org 745 [root@opensourceecology httpd]# [root@opensourceecology httpd]# for dir in $(find . -type d); do echo $dir; echo -ne '\t'; zgrep -vi 'internal dummy' $dir/access_log-20240303.gz | wc -l; done . 138 ./wiki.opensourceecology.org 103831 ./www.openbuildinginstitute.org 444 ./phplist.opensourceecology.org 82226 ./oswh.opensourceecology.org 111 ./forum.opensourceecology.org 2914 ./microfactory.opensourceecology.org 112 ./seedhome.openbuildinginstitute.org 21 ./staging.openbuildinginstitute.org gzip: ./staging.openbuildinginstitute.org/access_log-20240303.gz: No such file or directory 0 ./store.opensourceecology.org 81 ./fef.opensourceecology.org 641 ./www.opensourceecology.org 2066 ./staging.opensourceecology.org 1696 ./munin.opensourceecology.org gzip: ./munin.opensourceecology.org/access_log-20240303.gz: No such file or directory 0 [root@opensourceecology httpd]# [root@opensourceecology httpd]# for dir in $(find . -type d); do echo $dir; echo -ne '\t'; zgrep -vi 'internal dummy' $dir/access_log-20240304.gz | wc -l; done . 43 ./wiki.opensourceecology.org 56407 ./www.openbuildinginstitute.org 426 ./phplist.opensourceecology.org 30369 ./oswh.opensourceecology.org 69 ./forum.opensourceecology.org 1345 ./microfactory.opensourceecology.org 29 ./seedhome.openbuildinginstitute.org 5 ./staging.openbuildinginstitute.org gzip: ./staging.openbuildinginstitute.org/access_log-20240304.gz: No such file or directory 0 ./store.opensourceecology.org 487 ./fef.opensourceecology.org 238 ./www.opensourceecology.org 2284 ./staging.opensourceecology.org 108 ./munin.opensourceecology.org gzip: ./munin.opensourceecology.org/access_log-20240304.gz: No such file or directory 0 [root@opensourceecology httpd]# [root@opensourceecology httpd]# for dir in $(find . -type d); do echo $dir; echo -ne '\t'; zgrep -vi 'internal dummy' $dir/access_log-20240305.gz | wc -l; done . 398 ./wiki.opensourceecology.org 50107 ./www.openbuildinginstitute.org 447 ./phplist.opensourceecology.org 23000 ./oswh.opensourceecology.org 273 ./forum.opensourceecology.org 1614 ./microfactory.opensourceecology.org 324 ./seedhome.openbuildinginstitute.org 1 ./staging.openbuildinginstitute.org gzip: ./staging.openbuildinginstitute.org/access_log-20240305.gz: No such file or directory 0 ./store.opensourceecology.org 139 ./fef.opensourceecology.org 933 ./www.opensourceecology.org 4151 ./staging.opensourceecology.org 185 ./munin.opensourceecology.org gzip: ./munin.opensourceecology.org/access_log-20240305.gz: No such file or directory 0 [root@opensourceecology httpd]#
- I wouldn't be surprised if this was a DOS attack hitting some vulnerability in the wiki or phplist installs
- unfortunately the munin graphs are empty for nginx and apache, so I can't see if there was a spike of DOS requests with munin
- I installed goaccess so I could do some analysis on the apache logs
[root@opensourceecology ~]# yum install goaccess Loaded plugins: fastestmirror, replace Loading mirror speeds from cached hostfile * base: centosmirror.netcup.net * epel: mirror.de.leaseweb.net * extras: centosmirror.netcup.net * updates: de.mirrors.clouvider.net Resolving Dependencies --> Running transaction check ---> Package goaccess.x86_64 0:1.3-1.el7 will be installed --> Finished Dependency Resolution Dependencies Resolved ========================================================================================================================= Package Arch Version Repository Size ========================================================================================================================= Installing: goaccess x86_64 1.3-1.el7 epel 240 k Transaction Summary ========================================================================================================================= Install 1 Package Total download size: 240 k Installed size: 713 k Is this ok [y/d/N]: y Downloading packages: goaccess-1.3-1.el7.x86_64.rpm | 240 kB 00:00:00 Running transaction check Running transaction test Transaction test succeeded Running transaction Installing : goaccess-1.3-1.el7.x86_64 1/1 Verifying : goaccess-1.3-1.el7.x86_64 1/1 Installed: goaccess.x86_64 0:1.3-1.el7 Complete! [root@opensourceecology ~]#
- a quick analysis of today's log shows by-far the most requested page is phpList's
/lists/admin/?page=logout&err=1- this page has 62,388 requests so-far today, and climbing by about 1 request per second
- the second-most requested URL is /feed (this one is normal) with 3,165 requests for the day
- I used goaccess to analyze the apache & nginx logs from Mar 02 - Mar 05. I thought maybe I'd see more requests on the two days where the reboots occurred, but that wasn't the case. Reminder that nginx is all traffic and apache is just traffic that made it to the backend (passed varnish)
- here's nginx; I can't explain the few requests from 2018
9643 100.00% 6208 100.00% 1.47 MiB 08/Mar/2024 | 39418 100.00% 16007 100.00% 5.98 MiB 07/Mar/2024 |||||| 56942 100.00% 19855 100.00% 2.00 GiB 05/Mar/2024 ||||||||| 293795 100.00% 90522 100.00% 7.46 GiB 04/Mar/2024 ||||||||||||||||||||||||||||||||||||||||||||||||| 322677 100.00% 98723 100.00% 7.30 GiB 03/Mar/2024 |||||||||||||||||||||||||||||||||||||||||||||||||||||| 393755 100.00% 116410 100.00% 13.33 GiB 02/Mar/2024 ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| 254643 64.67% 80963 69.55% 9.70 GiB 01/Mar/2024 ||||||||||||||||||||||||||||||||||||||||||| 526 0.13% 139 0.12% 52.81 MiB 09/Feb/2018 |
- here's apache; again lost of weird requests logged as 2017
1290 100.00% 2 100.00% 1.52 KiB 08/Mar/2024 | 6243 100.00% 8 100.00% 23.94 KiB 07/Mar/2024 || 29892 100.00% 14565 100.00% 1.76 GiB 05/Mar/2024 ||||||||| 93555 100.00% 43535 100.00% 5.91 GiB 04/Mar/2024 ||||||||||||||||||||||||||||| 108797 100.00% 49958 100.00% 6.08 GiB 03/Mar/2024 |||||||||||||||||||||||||||||||||| 212145 100.00% 93738 100.00% 11.60 GiB 02/Mar/2024 |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| 134768 63.53% 63350 67.58% 8.50 GiB 01/Mar/2024 ||||||||||||||||||||||||||||||||||||||||||| 1856 0.87% 9 0.01% 43.03 MiB 23/Nov/2017 | 547 0.26% 4 0.00% 490.01 KiB 22/Nov/2017 | 500 0.24% 6 0.01% 310.14 KiB 21/Nov/2017 | 606 0.29% 4 0.00% 1.62 MiB 20/Nov/2017 | 818 0.39% 4 0.00% 7.27 MiB 19/Nov/2017 | 519 0.24% 6 0.01% 2.74 MiB 18/Nov/2017 | 651 0.31% 5 0.01% 1.85 MiB 17/Nov/2017 | 696 0.33% 4 0.00% 2.35 MiB 16/Nov/2017 | 623 0.29% 5 0.01% 561.22 KiB 15/Nov/2017 | 706 0.33% 3 0.00% 2.15 MiB 14/Nov/2017 | 1378 0.65% 7 0.01% 32.53 MiB 13/Nov/2017 | 924 0.44% 4 0.00% 16.13 MiB 12/Nov/2017 | 866 0.41% 6 0.01% 9.95 MiB 11/Nov/2017 | 575 0.27% 3 0.00% 179.88 KiB 10/Nov/2017 | 618 0.29% 2 0.00% 90.79 KiB 09/Nov/2017 | 531 0.25% 3 0.00% 89.94 KiB 08/Nov/2017 | 763 0.36% 6 0.01% 334.93 KiB 07/Nov/2017 | 685 0.32% 3 0.00% 89.92 KiB 06/Nov/2017 | 509 0.24% 3 0.00% 89.96 KiB 05/Nov/2017 | 692 0.33% 6 0.01% 245.12 KiB 04/Nov/2017 |
- I checked the error logs of the phpList server, but I didn't find anything that stood-out around Mar 03 05:38:12 and Mar 04 09:30:27 UTC
- I checked the error logs of the wiki server, and I did see some APC errors on Mar 03 05:38
[Sat Mar 02 17:05:35.753507 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 26. apc_store() /var/www/html/wiki.o
pensourceecology.org/htdocs/includes/libs/objectcache/APCBagOStuff.php:95
[Sat Mar 02 17:05:38.633099 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP Warning: apc_store(): Unable to allo
cate memory for pool. in /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/APCBagOStuff.php on li
ne 95
[Sat Mar 02 17:05:38.633115 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP Stack trace:
[Sat Mar 02 17:05:38.633121 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 1. {main}() /var/www/html/wiki.open
sourceecology.org/htdocs/index.php:0
[Sat Mar 02 17:05:38.633124 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 2. MediaWiki->run() /var/www/html/w
iki.opensourceecology.org/htdocs/index.php:43
[Sat Mar 02 17:05:38.633128 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 3. MediaWiki->main() /var/www/html/
wiki.opensourceecology.org/htdocs/includes/MediaWiki.php:523
[Sat Mar 02 17:05:38.633131 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 4. MediaWiki->getAction() /var/www/
html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php:768
[Sat Mar 02 17:05:38.633135 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 5. Action::getActionName() /var/www
/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php:155
[Sat Mar 02 17:05:38.633138 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 6. Action::factory() /var/www/html/
wiki.opensourceecology.org/htdocs/includes/actions/Action.php:154
[Sat Mar 02 17:05:38.633141 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 7. WikiPage->getActionOverrides() /
var/www/html/wiki.opensourceecology.org/htdocs/includes/actions/Action.php:96
[Sat Mar 02 17:05:38.633145 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 8. WikiPage->getContentHandler() /v
ar/www/html/wiki.opensourceecology.org/htdocs/includes/page/WikiPage.php:219
[Sat Mar 02 17:05:38.633149 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 9. WikiPage->getContentModel() /var/www/html/wiki.opensourceecology.org/htdocs/includes/page/WikiPage.php:232
[Sat Mar 02 17:05:38.633152 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 10. WANObjectCache->getWithSetCallback() /var/www/html/wiki.opensourceecology.org/htdocs/includes/page/WikiPage.php:528
[Sat Mar 02 17:05:38.633156 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 11. WANObjectCache->doGetWithSetCallback() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/WANObjectCache.php:914
[Sat Mar 02 17:05:38.633159 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 12. call_user_func_array:{/var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/WANObjectCache.php:1012}() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/WANObjectCache.php:1012
[Sat Mar 02 17:05:38.633163 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 13. WikiPage->{closure:/var/www/html/wiki.opensourceecology.org/htdocs/includes/page/WikiPage.php:517-527}() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/WANObjectCache.php:1012
[Sat Mar 02 17:05:38.633166 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 14. WikiPage->getRevision() /var/www/html/wiki.opensourceecology.org/htdocs/includes/page/WikiPage.php:518
[Sat Mar 02 17:05:38.633169 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 15. WikiPage->loadLastEdit() /var/www/html/wiki.opensourceecology.org/htdocs/includes/page/WikiPage.php:646
[Sat Mar 02 17:05:38.633172 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 16. Revision::newKnownCurrent() /var/www/html/wiki.opensourceecology.org/htdocs/includes/page/WikiPage.php:624
[Sat Mar 02 17:05:38.633175 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 17. WANObjectCache->getWithSetCallback() /var/www/html/wiki.opensourceecology.org/htdocs/includes/Revision.php:1958
[Sat Mar 02 17:05:38.633184 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 18. WANObjectCache->doGetWithSetCallback() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/WANObjectCache.php:914
[Sat Mar 02 17:05:38.633187 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 19. WANObjectCache->set() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/WANObjectCache.php:1038
[Sat Mar 02 17:05:38.633190 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 20. BagOStuff->merge() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/WANObjectCache.php:483
[Sat Mar 02 17:05:38.633193 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 21. BagOStuff->mergeViaLock() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/BagOStuff.php:277
[Sat Mar 02 17:05:38.633196 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 22. APCBagOStuff->set() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/BagOStuff.php:366
[Sat Mar 02 17:05:38.633199 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP 23. apc_store() /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/APCBagOStuff.php:95
[Sat Mar 02 17:05:38.635723 2024] [:error] [pid 24406] [client 127.0.0.1:42158] PHP Warning: apc_store(): Unable to allocate memory for pool. in /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/APCBagOStuff.php on line 95
- however, ^ that error is spammed throughout the logs constantly
- it does, however, appear to be worse on the days with the reboots. maybe
[root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240228.gz | wc -l 19050 [root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240229.gz | wc -l 74375 [root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240301.gz | wc -l 23898 [root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240302.gz | wc -l 241868 [root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240303.gz | wc -l 19607 [root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240304.gz | wc -l 46298 [root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240305.gz | wc -l 1374 [root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240306.gz | wc -l 0 [root@opensourceecology log]# zgrep 'apc_store(): Unable to allocate' httpd/wiki.opensourceecology.org/error_log-20240307.gz | wc -l 4157 [root@opensourceecology log]#
- google says these errors can be eliminated by dropping the ttl of the apc cache to 0
[root@opensourceecology log]# grep -ir apc /etc/php* | grep ttl /etc/php.d/apcu.ini:apc.ttl=7200 /etc/php.d/apcu.ini:apc.gc_ttl=3600 /etc/php.d/apcu.ini:apc.rfc1867_ttl=3600 /etc/php.d/apcu.ini.20180316_232434.bak:apc.ttl=7200 /etc/php.d/apcu.ini.20180316_232434.bak:apc.gc_ttl=3600 /etc/php.d/apcu.ini.20180316_232434.bak:apc.rfc1867_ttl=3600 /etc/php-zts.d/apcu.ini:apc.ttl=7200 /etc/php-zts.d/apcu.ini:apc.gc_ttl=3600 /etc/php-zts.d/apcu.ini:apc.rfc1867_ttl=3600 [root@opensourceecology log]#
- but, again, I have no idea if this is actually the root cause or a red herring
- this says that switching from php mod_php/prefork to php-fpm could prevent apache from spawning so many workers when a php script misbehaves (but I want to find out *which* script causes this) https://serverfault.com/questions/823121/why-is-apache-spawning-so-many-processes
- it appears that we're using mod_php, not cgi or fpm (unfortunately I can't run phpinfo() as it's disabled and I don't want to edit the php config & restart the webserver) https://www.devguide.at/en/backend/mod_php-vs-fastcgi-vs-fpm/
[root@opensourceecology log]# grep -ir php /etc/httpd* | grep -i module /etc/httpd/conf.modules.d/10-php.conf:# PHP is an HTML-embedded scripting language which attempts to make it /etc/httpd/conf.modules.d/10-php.conf: LoadModule php5_module modules/libphp5.so /etc/httpd/conf.modules.d/10-php.conf: LoadModule php5_module modules/libphp5-zts.so [root@opensourceecology log]# grep -ir php /etc/httpd* | grep -i handler /etc/httpd/conf.d/php.conf:AddHandler php5-script .php /etc/httpd/conf.d/php.conf:php_value session.save_handler "files" [root@opensourceecology log]# grep -ir fpm /etc/httpd* [root@opensourceecology log]#
- mod_evasive says that it's blacklisted 127.0.0.1. Hopefully it's also on a whitelist?
[root@opensourceecology log]# apachectl status * httpd.service - The Apache HTTP Server Loaded: loaded (/usr/lib/systemd/system/httpd.service; enabled; vendor preset: disabled) Active: active (running) since Mon 2024-03-04 21:29:24 UTC; 4 days ago Docs: man:httpd(8) man:apachectl(8) Process: 19584 ExecReload=/usr/sbin/httpd $OPTIONS -k graceful (code=exited, status=0/SUCCESS) Main PID: 1107 (httpd) Status: "Total requests: 0; Current requests/sec: 0; Current traffic: 0 B/sec" CGroup: /system.slice/httpd.service |- 1107 /usr/sbin/httpd -DFOREGROUND |-15605 /usr/sbin/httpd -DFOREGROUND |-15820 /usr/sbin/httpd -DFOREGROUND |-17510 /usr/sbin/httpd -DFOREGROUND |-17565 /usr/sbin/httpd -DFOREGROUND |-18685 /usr/sbin/httpd -DFOREGROUND |-18693 /usr/sbin/httpd -DFOREGROUND |-18694 /usr/sbin/httpd -DFOREGROUND |-18971 /usr/sbin/httpd -DFOREGROUND |-18992 /usr/sbin/httpd -DFOREGROUND `-18993 /usr/sbin/httpd -DFOREGROUND Mar 04 21:29:24 opensourceecology.org systemd[1]: Started The Apache HTTP Server. Mar 04 23:09:48 opensourceecology.org mod_evasive[9328]: Blacklisting address 127.0.0.1: possible DoS attack. Mar 05 04:15:56 opensourceecology.org systemd[1]: Reloading The Apache HTTP Server. Mar 05 04:15:56 opensourceecology.org systemd[1]: Reloaded The Apache HTTP Server. Mar 06 05:52:06 opensourceecology.org systemd[1]: Reloading The Apache HTTP Server. Mar 06 05:52:06 opensourceecology.org systemd[1]: Reloaded The Apache HTTP Server. Mar 07 07:18:43 opensourceecology.org systemd[1]: Reloading The Apache HTTP Server. Mar 07 07:18:44 opensourceecology.org systemd[1]: Reloaded The Apache HTTP Server. Mar 08 04:09:05 opensourceecology.org systemd[1]: Reloading The Apache HTTP Server. Mar 08 04:09:05 opensourceecology.org systemd[1]: Reloaded The Apache HTTP Server. [root@opensourceecology log]#
- I couldn't find what the MaxRequestWorkers setting is.
- I'm not sure if that means its some default or infinity. Currently we have less than 20 running. The delta on the munin chart between ~460 to ~850 tells me that apache spawned ~390 child workers before the system crashed
- maybe we should just try updating the apache config to a max of 100 workers and see what that does. If apache crashes but mysql does not, I'd consider this progress. Then we just need to isolate the issue: perhaps with php profiling and/or switching from mod_php to php-fpm
[root@opensourceecology log]# apachectl -M | grep mpm mpm_prefork_module (shared) [root@opensourceecology log]# [root@opensourceecology log]# apachectl -t -D DUMP_RUN_CFG Passing arguments to httpd using apachectl is no longer supported. You can only start/stop/restart httpd using this script. If you want to pass extra arguments to httpd, edit the /etc/sysconfig/httpd config file. ServerRoot: "/etc/httpd" Main DocumentRoot: "/etc/httpd/htdocs" Main ErrorLog: "/etc/httpd/logs/error_log" Mutex ssl-stapling: using_defaults Mutex proxy: using_defaults Mutex authn-socache: using_defaults Mutex ssl-cache: using_defaults Mutex default: dir="/run/httpd/" mechanism=default Mutex mpm-accept: using_defaults Mutex authdigest-opaque: using_defaults Mutex proxy-balancer-shm: using_defaults Mutex rewrite-map: using_defaults Mutex authdigest-client: using_defaults PidFile: "/run/httpd/httpd.pid" Define: _RH_HAS_HTTPPROTOCOLOPTIONS Define: DUMP_RUN_CFG Define: MODSEC_2.5 Define: MODSEC_2.9 User: name="apache" id=48 Group: name="apache" id=48 [root@opensourceecology log]#
- I created a new apache config /etc/
[root@opensourceecology conf.d]# pwd /etc/httpd/conf.d [root@opensourceecology conf.d]# [root@opensourceecology conf.d]# ls 000-www.opensourceecology.org.conf mod_evasive.conf 00-fef.opensourceecology.org.conf mod_security.conf 00-forum.opensourceecology.org.conf mod_security.wordpress.include 00-microfactory.opensourceecology.org.conf munin.20180304.bak 00-oswh.opensourceecology.org.conf munin.opensourceecology.org.conf 00-phplist.opensourceecology.org.conf php.conf 00-seedhome.openbuildinginstitute.org.conf README 00-store.opensourceecology.org.conf ssl.conf.20200504_105511.disabled 00-wiki.opensourceecology.org.conf ssl.conf.disabled 00-www.openbuildinginstitute.org.conf ssl.conf.orig autoindex.conf.20200504_105511.disabled ssl.openbuildinginstitute.org awstats.conf ssl.opensourceecology.org awstats.conf.20200504_105511.disabled staging.openbuildinginstitute.org.conf.bak awstats.openbuildinginstitute.org.conf staging.opensourceecology.org.conf awstats.opensourceecology.org.conf userdir.conf.20200504_105511.disabled cacti.conf varnishTest.conf.disabled certbot.conf welcome.conf.20200504_105511.disabled [root@opensourceecology conf.d]# [root@opensourceecology conf.d]# vim mpm_prefork.conf [root@opensourceecology conf.d]# [root@opensourceecology conf.d]# cat mpm_prefork.conf <IfModule mpm_prefork_module> StartServers 5 MinSpareServers 5 MaxSpareServers 10 MaxRequestWorkers 100 MaxConnectionsPerChild 0 </IfModule> [root@opensourceecology conf.d]#
- and I reloaded the apache config
[root@opensourceecology conf.d]# apachectl -t Syntax OK [root@opensourceecology conf.d]# systemctl reload httpd [root@opensourceecology conf.d]#
- I'm not sure how to proceed. I have a lot of ideas, but I need input from Marcin. I sent him this email
Hey Marcin, Do you have a budget for fixing this? I spent a few more hours today investigating the issue. It does appear that your backend apache web server is suddenly spawning child workers like crazy, but it's not clear exactly what is causing this (though I do have some guesses after reviewing your logs). For now I've just limited the maximum number of workers to 100 (you're running fine with about 10 now and it spawned ~400 in the two crashes last week). But it's not trivial to see if that change applied and I'm not sure it will prevent your server from crashing again. For more detailed information of my investigations today, see my log: * https://wiki.opensourceecology.org/wiki/Maltfield_Log If I had days or weeks to investigate, I could definitely get to the bottom of it, but I don't know what is your budget on me fixing this. Here's some things I could do: 1. Upgrade all the packages on the system, including apache. This would take at-best a few hours and at-worst a few days. 3. Upgrade phpList and the wiki, which are the two sites getting the most traffic. This would take at-best half a day or at-worst a week (you're very far behind in versions, and that doesn't always mean smooth upgrades). 3. Runs some PHP Profiling with XHProf to determine exactly which websites & PHP scripts are consuming resources and causing apache to spawn so many children. This would take minimum a couple days, maybe a week. 4. Switch from mod_php to php-fpm, which should help PHP scale better without needing to spawn so many apache child processes. This would take a day or two. 5. Write some hacky script that runs every 5 minutes and checks to see if apache has >99 child workers. If it does, just restart apache. This would take half a day to 1 day to write & test. Please let me know how much time you'd like me to invest into fixing this, and how you'd like me to proceed. Thank you, Michael Altfield Senior Technology Advisor PGP Fingerprint: 8A4B 0AF8 162F 3B6A 79B7 70D2 AA3E DF71 60E2 D97B Open Source Ecology www.opensourceecology.org
Fri March 01, 2024
- I checked my email and only got 1-3 ossec alerts per hour overnight (as opposed to 12 every hour)
- currently we get an error every hour complaining about sshd trying to bind to an occupied port, not sure if related or unrelated
OSSEC HIDS Notification. 2024 Mar 01 17:13:36 Received From: opensourceecology->/var/log/secure Rule: 1002 fired (level 2) -> "Unknown problem somewhere in the system." Portion of the log(s): Mar 1 17:13:36 opensourceecology sshd[22147]: error: bind: Address already in use --END OF NOTIFICATION OSSEC HIDS Notification. 2024 Mar 01 17:13:36 Received From: opensourceecology->/var/log/secure Rule: 1002 fired (level 2) -> "Unknown problem somewhere in the system." Portion of the log(s): Mar 1 17:13:36 opensourceecology sshd[22147]: error: channel_setup_fwd_listener_tcpip: cannot listen to port: 54261 --END OF NOTIFICATION
- I couldn't find anything on the wiki when searching for port
54261
- I couldn't find anything on the wiki when searching for port
- anyway let's just wait until 2024-03-08. If the server runs fine for a week, then I'll consider this resolved.
- I just need to check munin. indication of the same error is a massive spike of apache rss usage cooresponding to a gap (drop to zero) of mysql queries
Thr February 29, 2024
- Marcin alerted me on Feb 24 that the wiki was down
- I did a quick test and the frontpage loaded fine. The status page also didn't indicate any downtime
- however, when I tried to do a search on the wiki, it stalled for a while and eventually I got a varnish error saying it couldn't reach the backend
- I tried to check munin, but I got the same varnish error
- I told Marcin that he could try to just give it a reboot from the hetzner WUI, which he did
- after it came back, I checked Munin and saw that the db was down. I also saw a huge spike in apache memory usage
- Over the next few days, I noticed that OSSEC has been spamming me with emails once every 5 minutes
OSSEC HIDS Notification. 2024 Feb 27 23:12:07 Received From: opensourceecology->/var/log/messages Rule: 1002 fired (level 2) -> "Unknown problem somewhere in the system." Portion of the log(s): Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483 --END OF NOTIFICATION
- I'm not certain, but the email might be caused by some OpenVPN cron used to connect the prod & staging servers. It's possible that it expired and that the expiration is causing some loop that's bogging down the server somehow
- Every time Marcin reboots the server, I get an email alert from hetzner
- I noticed that Marcin rebooted it again today (Feb 29) at 10:03 (EST). I sent him an email and he confirmed this
- I also see he did another reboot today at 17:58
- I ssh'd into the server and checked /var/log/messages. Here's one of the snippets
Mar 1 03:38:24 opensourceecology connect.sh: TCP/UDP: Preserving recently used remote address: [AF_INET]195.201.233.113:1194 Mar 1 03:38:24 opensourceecology connect.sh: Socket Buffers: R=[212992->212992] S=[212992->212992] Mar 1 03:38:24 opensourceecology connect.sh: UDP link local: (not bound) Mar 1 03:38:24 opensourceecology connect.sh: UDP link remote: [AF_INET]195.201.233.113:1194 Mar 1 03:38:24 opensourceecology connect.sh: TLS: Initial packet from [AF_INET]195.201.233.113:1194, sid=852b79d5 cd86dfc4 Mar 1 03:38:24 opensourceecology connect.sh: VERIFY OK: depth=1, CN=osedev1 Mar 1 03:38:24 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483 Mar 1 03:38:24 opensourceecology connect.sh: OpenSSL: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed Mar 1 03:38:24 opensourceecology connect.sh: TLS_ERROR: BIO read tls_read_plaintext error Mar 1 03:38:24 opensourceecology connect.sh: TLS Error: TLS object -> incoming plaintext read error Mar 1 03:38:24 opensourceecology connect.sh: TLS Error: TLS handshake failed Mar 1 03:38:24 opensourceecology connect.sh: SIGUSR1[soft,tls-error] received, process restarting Mar 1 03:38:24 opensourceecology connect.sh: Restart pause, 300 second(s)
- indeed, the line above what was emailed from OSSEC says
osedev
, so this appears to be related to the staging/dev setup - running `systemctl` shows that the service
openvpn-client.service
is in thefailed
state
- indeed, the line above what was emailed from OSSEC says
[root@opensourceecology cron.d]# systemctl ... ● openvpn-client.service loaded failed failed openvpn-client.service
- I found the config in /etc/systemd/system
[root@opensourceecology ~]# cd /etc/systemd/system [root@opensourceecology system]# ls basic.target.wants getty.target.wants nginx.service.d sysinit.target.wants default.target local-fs.target.wants openvpn-client.service system-update.target.wants default.target.wants multi-user.target.wants sockets.target.wants [root@opensourceecology system]# cat openvpn-client.service [Unit] Description=OpenVPN tunnel for %I After=syslog.target network-online.target Wants=network-online.target Documentation=man:openvpn(8) Documentation=https://community.openvpn.net/openvpn/wiki/Openvpn24ManPage Documentation=https://community.openvpn.net/openvpn/wiki/HOWTO [Service] User=root Type=notify PrivateTmp=true WorkingDirectory=/etc/openvpn/client #WorkingDirectory=/root/openvpn #ExecStart=/usr/sbin/openvpn --suppress-timestamps --nobind --config client.conf ExecStart=/etc/openvpn/client/connect.sh CapabilityBoundingSet=CAP_IPC_LOCK CAP_NET_ADMIN CAP_NET_RAW CAP_SETGID CAP_SETUID CAP_SYS_CHROOT CAP_DAC_OVERRIDE #LimitNPROC=10 LimitNPROC=infinity DeviceAllow=/dev/null rw DeviceAllow=/dev/net/tun rw ProtectSystem=true ProtectHome=true KillMode=process [Install] WantedBy=multi-user.target [root@opensourceecology system]#
- from above, it looks like the path to the connect.sh script is
/etc/openvpn/client/connect.sh
[root@opensourceecology system]# cd /etc/openvpn/client/
[root@opensourceecology client]# ls
auth.txt ca.crt client.conf connect.sh hetzner2.crt hetzner2.key ta.key
[root@opensourceecology client]# cat connect.sh
#!/bin/bash
# yes, storing 2fa secret keys here doesn't add security; we're doing it only
# because we can't exclude 2fa on a client-by-client basis in the openvpn
# free server. 2fa is important for humans with bad passwords, not so much for
# our server accounts. If someone can read this file, we've bigger problems.
TOTP_SECRET=OBFUSCATED
USERNAME=OBFUSCATED
token=`oathtool --base32 --totp ${TOTP_SECRET}`
echo -e "${USERNAME}\n${token}" > auth.txt
/usr/sbin/openvpn --suppress-timestamps --nobind --config client.conf
[root@opensourceecology client]#
- If I manually run the openvpn command from the above script, I get the error
[root@opensourceecology client]# /usr/sbin/openvpn --suppress-timestamps --nobind --config client.conf OpenVPN 2.4.12 x86_64-redhat-linux-gnu [Fedora EPEL patched] [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Mar 17 2022 library versions: OpenSSL 1.0.2k-fips 26 Jan 2017, LZO 2.06 WARNING: Your certificate has expired! Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication TCP/UDP: Preserving recently used remote address: [AF_INET]195.201.233.113:1194 Socket Buffers: R=[212992->212992] S=[212992->212992] UDP link local: (not bound) UDP link remote: [AF_INET]195.201.233.113:1194 TLS: Initial packet from [AF_INET]195.201.233.113:1194, sid=11bab8ae 02ebcb41 VERIFY OK: depth=1, CN=osedev1 VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483 OpenSSL: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed TLS_ERROR: BIO read tls_read_plaintext error TLS Error: TLS object -> incoming plaintext read error TLS Error: TLS handshake failed SIGUSR1[soft,tls-error] received, process restarting Restart pause, 5 second(s) ^CSIGINT[hard,init_instance] received, process exiting [root@opensourceecology client]#
- that's enlightening, but I'm not sure I understand why this would crash the system
- I checked munin
- again, the db queries suddenly drops to 0 in 3 places, and we can clearly see when the server is broken
- cooresponding with all 3 gaps in the db chart, there's a sawtooth vertical climb in httpd rss usage. interesting.
- there's also a huge vertical spike in number of processes at these 3 times
- uptime was 1,400 days before we rebooted :whistles:
- but that's the point: this was a very well-oiled machine. why is running a "connect" script over-and-over bringing the whole thing to its knees? could that really be it?
- there is a huge spike in postfix mail queue. so it's possible that it's actually openvpn that's triggering ossec that's triggering postfix and that's causing issues
- honestly, nobody is using osedev or osestaging. I could renew the certs, but I'm not sure that's warranted atm
- instead, I'll do two things: [1] I'll add an ossec rule not to email alerts for this and [2] I'll disable the openvpn-client unit in systemd
- first we test the current behaviour of ossec with this log entry
[root@opensourceecology ~]# /var/ossec/bin/ossec-logtest 2024/03/01 04:58:05 ossec-testrule: INFO: Reading local decoder file. 2024/03/01 04:58:05 ossec-testrule: INFO: Started (pid: 12113). ossec-testrule: Type one log per line. Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483 **Phase 1: Completed pre-decoding. full event: 'Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483' hostname: 'opensourceecology' program_name: 'connect.sh' log: 'VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483' **Phase 2: Completed decoding. No decoder matched. **Phase 3: Completed filtering (rules). Rule id: '1002' Level: '2' Description: 'Unknown problem somewhere in the system.' **Alert to be generated.
- next we make a backup of the local rules file
[root@opensourceecology client]# cd /var/ossec/rules/ [root@opensourceecology rules]# ls apache_rules.xml hordeimp_rules.xml nginx_rules.xml rules_config.xml trend-osce_rules.xml apparmor_rules.xml ids_rules.xml openbsd_rules.xml sendmail_rules.xml unbound_rules.xml arpwatch_rules.xml imapd_rules.xml opensmtpd_rules.xml smbd_rules.xml vmpop3d_rules.xml asterisk_rules.xml local_rules.xml ossec_rules.xml solaris_bsm_rules.xml vmware_rules.xml attack_rules.xml mailscanner_rules.xml pam_rules.xml sonicwall_rules.xml vpn_concentrator_rules.xml cimserver_rules.xml mcafee_av_rules.xml php_rules.xml spamd_rules.xml vpopmail_rules.xml cisco-ios_rules.xml msauth_rules.xml pix_rules.xml squid_rules.xml vsftpd_rules.xml clam_av_rules.xml ms_dhcp_rules.xml policy_rules.xml sshd_rules.xml web_appsec_rules.xml courier_rules.xml ms-exchange_rules.xml postfix_rules.xml symantec-av_rules.xml web_rules.xml dovecot_rules.xml ms_ftpd_rules.xml postgresql_rules.xml symantec-ws_rules.xml wordpress_rules.xml dropbear_rules.xml ms-se_rules.xml proftpd_rules.xml syslog_rules.xml zeus_rules.xml firewalld_rules.xml mysql_rules.xml pure-ftpd_rules.xml sysmon_rules.xml firewall_rules.xml named_rules.xml racoon_rules.xml systemd_rules.xml ftpd_rules.xml netscreenfw_rules.xml roundcube_rules.xml telnetd_rules.xml [root@opensourceecology rules]# cp local_rules.xml local_rules.xml.20240229
- I added a new rule to catch this and stop emailing on them
[root@opensourceecology rules]# diff local_rules.xml.20240229 local_rules.xml 93a94,99 > <rule id="100057" level="2"> > <if_sid>1002</if_sid> > <match>error=certificate has expired</match> > <options>no_email_alert</options> > <description>2024-02-29: Ignore OpenVPN cert errors that spam us every 5 minutes and crash the server</description> > </rule> [root@opensourceecology rules]#
- I restarted ossec and confirmed it matches to the new rule. For some reason it still says "Alert to be generated", which I don't understand why. The rule 100057 clearly has "no_email_alert" set
[root@opensourceecology ~]# systemctl restart ossec [root@opensourceecology ~]# /var/ossec/bin/ossec-logtest 2024/03/01 05:07:33 ossec-testrule: INFO: Reading local decoder file. 2024/03/01 05:07:33 ossec-testrule: INFO: Started (pid: 15844). ossec-testrule: Type one log per line. Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483 **Phase 1: Completed pre-decoding. full event: 'Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483' hostname: 'opensourceecology' program_name: 'connect.sh' log: 'VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483' **Phase 2: Completed decoding. No decoder matched. **Phase 3: Completed filtering (rules). Rule id: '100057' Level: '2' Description: '2024-02-29: Ignore OpenVPN cert errors that spam us every 5 minutes and crash the server' **Alert to be generated.
- ah crap, I just realized that there's tons of different lines that are triggering these emails
Feb 29 08:18:02 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=1780983422210014075884459813273922948
Feb 29 08:18:02 opensourceecology connect.sh: OpenSSL: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed
Feb 29 08:18:02 opensourceecology connect.sh: TLS_ERROR: BIO read tls_read_plaintext error
Feb 29 08:18:02 opensourceecology connect.sh: TLS Error: TLS object -> incoming plaintext read error
Feb 29 08:18:02 opensourceecology connect.sh: TLS Error: TLS handshake failed
Feb 29 08:18:02 opensourceecology connect.sh: SIGUSR1[soft,tls-error] received, process restarting
- well, the one thing all these lines have in common is that they contain
opensourceecology connect.sh:
, so I'll match on that instead
[root@opensourceecology rules]# diff local_rules.xml.20240229 local_rules.xml 93a94,99 > <rule id="100057" level="2"> > <if_sid>1002</if_sid> > <match>opensourceecology connect.sh: </match> > <options>no_email_alert</options> > <description>2024-02-29: Ignore OpenVPN cert errors that spam us every 5 minutes and crash the server</description> > </rule> [root@opensourceecology rules]#
- and a test
[root@opensourceecology ~]# systemctl restart ossec [root@opensourceecology ~]# /var/ossec/bin/ossec-logtest 2024/03/01 05:14:57 ossec-testrule: INFO: Reading local decoder file. 2024/03/01 05:14:57 ossec-testrule: INFO: Started (pid: 17861). ossec-testrule: Type one log per line. Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483 **Phase 1: Completed pre-decoding. full event: 'Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483' hostname: 'opensourceecology' program_name: 'connect.sh' log: 'VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483' **Phase 2: Completed decoding. No decoder matched. **Phase 3: Completed filtering (rules). Rule id: '1002' Level: '2' Description: 'Unknown problem somewhere in the system.' **Alert to be generated.
- shit, that didn't work. probably regex syntax on one of the special characters
- ah, the decoder extracted the two fields as
hostname
andprogram_name
, and it appears that<match>
only applies to thelog
portion of the message. this works
[root@opensourceecology rules]# diff local_rules.xml.20240229 local_rules.xml 93a94,100 > <rule id="100057" level="2"> > <if_sid>1002</if_sid> > <hostname>opensourceecology</hostname> > <program_name>connect.sh</program_name> > <options>no_email_alert</options> > <description>2024-02-29: Ignore OpenVPN cert errors that spam us every 5 minutes and crash the server</description> > </rule> [root@opensourceecology rules]#
- but for some reason it still says
Alert will be generated
- but for some reason it still says
[root@opensourceecology ~]# systemctl restart ossec [root@opensourceecology ~]# /var/ossec/bin/ossec-logtest 2024/03/01 05:24:57 ossec-testrule: INFO: Reading local decoder file. 2024/03/01 05:24:57 ossec-testrule: INFO: Started (pid: 22484). ossec-testrule: Type one log per line. Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483 **Phase 1: Completed pre-decoding. full event: 'Feb 27 23:12:07 opensourceecology connect.sh: VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483' hostname: 'opensourceecology' program_name: 'connect.sh' log: 'VERIFY ERROR: depth=0, error=certificate has expired: CN=server, serial=17809834222100140758844598132739229483' **Phase 2: Completed decoding. No decoder matched. **Phase 3: Completed filtering (rules). Rule id: '100057' Level: '2' Description: '2024-02-29: Ignore OpenVPN cert errors that spam us every 5 minutes and crash the server' **Alert to be generated.
- I also went ahead and stopped & disabled the openvpn-client service in systemd
[root@opensourceecology rules]# systemctl status openvpn-client ● openvpn-client.service Loaded: loaded (/etc/systemd/system/openvpn-client.service; enabled; vendor preset: disabled) Active: failed (Result: timeout) since Thu 2024-02-29 22:34:17 UTC; 6h ago Docs: man:openvpn(8) https://community.openvpn.net/openvpn/wiki/Openvpn24ManPage https://community.openvpn.net/openvpn/wiki/HOWTO Process: 1110 ExecStart=/etc/openvpn/client/connect.sh (code=killed, signal=TERM) Main PID: 1110 (code=killed, signal=TERM) CGroup: /system.slice/openvpn-client.service └─1171 /usr/sbin/openvpn --suppress-timestamps --nobind --config client.conf Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: UDP link remote: [AF_INET]195.201.233.113:1194 Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: TLS: Initial packet from [AF_INET]195.201.233.113:1194...453 Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: VERIFY OK: depth=1, CN=osedev1 Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: VERIFY ERROR: depth=0, error=certificate has expired: ...483 Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: OpenSSL: error:14090086:SSL routines:ssl3_get_server_c...led Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: TLS_ERROR: BIO read tls_read_plaintext error Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: TLS Error: TLS object -> incoming plaintext read error Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: TLS Error: TLS handshake failed Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: SIGUSR1[soft,tls-error] received, process restarting Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: Restart pause, 300 second(s) Hint: Some lines were ellipsized, use -l to show in full. [root@opensourceecology rules]# systemctl stop openvpn-client [root@opensourceecology rules]# systemctl disable openvpn-client Removed symlink /etc/systemd/system/multi-user.target.wants/openvpn-client.service. [root@opensourceecology rules]# systemctl status openvpn-client ● openvpn-client.service Loaded: loaded (/etc/systemd/system/openvpn-client.service; disabled; vendor preset: disabled) Active: failed (Result: timeout) since Thu 2024-02-29 22:34:17 UTC; 6h ago Docs: man:openvpn(8) https://community.openvpn.net/openvpn/wiki/Openvpn24ManPage https://community.openvpn.net/openvpn/wiki/HOWTO Main PID: 1110 (code=killed, signal=TERM) CGroup: /system.slice/openvpn-client.service └─1171 /usr/sbin/openvpn --suppress-timestamps --nobind --config client.conf Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: TLS: Initial packet from [AF_INET]195.201.233.113:1194...453 Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: VERIFY OK: depth=1, CN=osedev1 Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: VERIFY ERROR: depth=0, error=certificate has expired: ...483 Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: OpenSSL: error:14090086:SSL routines:ssl3_get_server_c...led Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: TLS_ERROR: BIO read tls_read_plaintext error Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: TLS Error: TLS object -> incoming plaintext read error Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: TLS Error: TLS handshake failed Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: SIGUSR1[soft,tls-error] received, process restarting Mar 01 05:28:26 opensourceecology.org connect.sh[1110]: Restart pause, 300 second(s) Mar 01 05:29:33 opensourceecology.org systemd[1]: [/etc/systemd/system/openvpn-client.service:2] Failed to re...cess Hint: Some lines were ellipsized, use -l to show in full. [root@opensourceecology rules]#
- I sent an email to Marcin, and I'll let that sit overnight and see what the postfix charts look like in the morning
I logged into the server and disabled the openvpn-client service (which was responsible for establishing the connection between your osedev, osestaging, and oseprod servers) and added a rule to your ossec config to stop it from sending an email every time this connect.sh script has issues. More details here: * https://wiki.opensourceecology.org/wiki/Maltfield_Log/2024 I'll check it in the morning and if the server doesn't have issues for a week, I guess we can call it fixed. PS: Your server had been running without a reboot for ~1,400 days before you rebooted it. That's a well-oiled machine. Cheers, Michael Altfield Senior Technology Advisor PGP Fingerprint: 8A4B 0AF8 162F 3B6A 79B7 70D2 AA3E DF71 60E2 D97B Open Source Ecology www.opensourceecology.org
Sat January 10, 2024
- Marcin emailed me yesterday (2024-01-19) asking about cert issues with www.opensourceecology.org
- I confirmed that wiki.opensourceecology.org is fine, but www.opensourceecology.org displays a cert issue in firefox
- checking the cert details in firefox, I see that the following SANs are available. Note that the naked domain and 'www' subdomain are absent
awstats.opensourceecology.org, fef.opensourceecology.org, forum.opensourceecology.org, microfactory.opensourceecology.org, munin.opensourceecology.org, opensourceecology.org, oswh.opensourceecology.org, phplist.opensourceecology.org, staging.opensourceecology.org, store.opensourceecology.org, wiki.opensourceecology.org
- looks like there's a cron named 'letsencrypt'
[root@opensourceecology cron.d]# ls 0hourly awstats_generate_static_files backup_to_backblaze cacti letsencrypt munin phplist raid-check sysstat [root@opensourceecology cron.d]#
- the log file is /var/log/letsEncryptRenew.log
# once a month, update our letsencrypt cert 20 4 13 * * root /root/bin/letsencrypt/renew.sh &>> /var/log/letsEncryptRenew.log [root@opensourceecology cron.d]#
- the very bottom of the log file contains this message
IMPORTANT NOTES: - The following errors were reported by the server: Domain: www.opensourceecology.org Type: dns Detail: DNS problem: networking error looking up CAA for www.opensourceecology.org Redirecting to /bin/systemctl reload nginx.service
- I attempted a run now
[root@opensourceecology cron.d]# certbot renew Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/openbuildinginstitute.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Cert not yet due for renewal - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/opensourceecology.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Cert not yet due for renewal - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - The following certs are not due for renewal yet: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem expires on 2024-04-12 (skipped) /etc/letsencrypt/live/opensourceecology.org/fullchain.pem expires on 2024-04-12 (skipped) No renewals were attempted. - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology cron.d]#
- checking the existing cert info, it shows naked domain in the list, but somehow the the 'www' subdomian is missing
[root@opensourceecology cron.d]# certbot certificates Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Found the following certs: Certificate Name: openbuildinginstitute.org Domains: www.openbuildinginstitute.org awstats.openbuildinginstitute.org openbuildinginstitute.org seedhome.openbuildinginstitute.org Expiry Date: 2024-04-12 03:24:05+00:00 (VALID: 82 days) Certificate Path: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/openbuildinginstitute.org/privkey.pem Certificate Name: opensourceecology.org Domains: opensourceecology.org awstats.opensourceecology.org fef.opensourceecology.org forum.opensourceecology.org microfactory.opensourceecology.org munin.opensourceecology.org oswh.opensourceecology.org phplist.opensourceecology.org staging.opensourceecology.org store.opensourceecology.org wiki.opensourceecology.org Expiry Date: 2024-04-12 03:24:18+00:00 (VALID: 82 days) Certificate Path: /etc/letsencrypt/live/opensourceecology.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/opensourceecology.org/privkey.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology cron.d]
- I see the 'www' in the config file
[root@opensourceecology cron.d]# cd /etc/letsencrypt [root@opensourceecology cron.d]# [root@opensourceecology letsencrypt]# grep -irl 'wiki.opensourceecology.org' * renewal/opensourceecology.org.conf [root@opensourceecology letsencrypt]# cat renewal/opensourceecology.org.conf # renew_before_expiry = 30 days version = 1.3.0 archive_dir = /etc/letsencrypt/archive/opensourceecology.org cert = /etc/letsencrypt/live/opensourceecology.org/cert.pem privkey = /etc/letsencrypt/live/opensourceecology.org/privkey.pem chain = /etc/letsencrypt/live/opensourceecology.org/chain.pem fullchain = /etc/letsencrypt/live/opensourceecology.org/fullchain.pem # Options used in the renewal process [renewalparams] authenticator = webroot account = OBFUSCATED server = OBFUSCATED allow_subset_of_names = True webroot_map store.opensourceecology.org = /var/www/html/store.opensourceecology.org/htdocs phplist.opensourceecology.org = /var/www/html/phplist.opensourceecology.org/public_html www.opensourceecology.org = /var/www/html/www.opensourceecology.org/htdocs munin.opensourceecology.org = /var/www/html/certbot/htdocs microfactory.opensourceecology.org = /var/www/html/microfactory.opensourceecology.org/htdocs opensourceecology.org = /var/www/html/www.opensourceecology.org/htdocs wiki.opensourceecology.org = /var/www/html/wiki.opensourceecology.org/htdocs fef.opensourceecology.org = /var/www/html/fef.opensourceecology.org/htdocs awstats.opensourceecology.org = /var/www/html/certbot/htdocs forum.opensourceecology.org = /var/www/html/forum.opensourceecology.org/htdocs staging.opensourceecology.org = /var/www/html/staging.opensourceecology.org/htdocs oswh.opensourceecology.org = /var/www/html/oswh.opensourceecology.org/htdocs [root@opensourceecology letsencrypt]#
- I triggered a manual force-renewal
[root@opensourceecology letsencrypt]# certbot renew --force-renewal Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/openbuildinginstitute.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/opensourceecology.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/opensourceecology.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Congratulations, all renewals succeeded. The following certs have been renewed: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem (success) /etc/letsencrypt/live/opensourceecology.org/fullchain.pem (success) - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology letsencrypt]#
- still the 'www' subdomain is absent
[root@opensourceecology letsencrypt]# certbot certificates Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Found the following certs: Certificate Name: openbuildinginstitute.org Domains: www.openbuildinginstitute.org awstats.openbuildinginstitute.org openbuildinginstitute.org seedhome.openbuildinginstitute.org Expiry Date: 2024-04-20 00:47:41+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/openbuildinginstitute.org/privkey.pem Certificate Name: opensourceecology.org Domains: opensourceecology.org awstats.opensourceecology.org fef.opensourceecology.org forum.opensourceecology.org microfactory.opensourceecology.org munin.opensourceecology.org oswh.opensourceecology.org phplist.opensourceecology.org staging.opensourceecology.org store.opensourceecology.org wiki.opensourceecology.org Expiry Date: 2024-04-20 00:47:47+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/opensourceecology.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/opensourceecology.org/privkey.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology letsencrypt]#
- I reloaded the site in the browser; the issue persists
- I checked the cert; it says it was issued today (actually 2024-01-21, which is "today" in UTC but "tomorrow" in my timezone). Anyway, that shows that the cert did, in fact, renew. But it still is missing the subdomain that it is *supposed* to fetch as a SAN, according to the config above. Huh.
- I sent an email to Marcin asking if any changes were made recently
- I checked crt.sh (the cert observatory) to see the history of our certs for the domain opensourceecology.org https://crt.sh/?q=opensourceecology.org
- It looks like we've been using the 'www.opensourceecology.org SAN in our cert since 2018-03-01 (prior to that it was cloudflare wildcard), and it suddenly disappeared in the 2014-01-13 renewal. It was present in the one before that, issued 2023-11-13.
- therefore, this issue occurred sometime between 2023-11-13 and 2024-01-13.
- unfortunately, the letsencrypt logs are not timestampped
- the only time YYYY appears is the date of the certs expiry
# here's the log from the last renewal (that worked; note the line that lists www.opensourceecology.org) <pre> Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/openbuildinginstitute.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Cert is due for renewal, auto-renewing... Non-interactive renewal: random delay of 118.029492405 seconds Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate Performing the following challenges: http-01 challenge for awstats.openbuildinginstitute.org http-01 challenge for openbuildinginstitute.org http-01 challenge for seedhome.openbuildinginstitute.org http-01 challenge for www.openbuildinginstitute.org Waiting for verification... Cleaning up challenges - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/opensourceecology.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Cert is due for renewal, auto-renewing... Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate Performing the following challenges: http-01 challenge for awstats.opensourceecology.org http-01 challenge for fef.opensourceecology.org http-01 challenge for forum.opensourceecology.org http-01 challenge for microfactory.opensourceecology.org http-01 challenge for munin.opensourceecology.org http-01 challenge for opensourceecology.org http-01 challenge for oswh.opensourceecology.org http-01 challenge for phplist.opensourceecology.org http-01 challenge for staging.opensourceecology.org http-01 challenge for store.opensourceecology.org http-01 challenge for wiki.opensourceecology.org http-01 challenge for www.opensourceecology.org Waiting for verification... Cleaning up challenges - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/opensourceecology.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Congratulations, all renewals succeeded. The following certs have been renewed: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem (success) /etc/letsencrypt/live/opensourceecology.org/fullchain.pem (success) - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Redirecting to /bin/systemctl reload nginx.service
- there's one entry after that where it said the certs aren't up for renewal; I'll skip that
- the entry after that is where it renewed, but didn't fetch www.opensourceecology.org due to some (temp?) DNS network issue
Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/openbuildinginstitute.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Cert is due for renewal, auto-renewing... Non-interactive renewal: random delay of 236.7908044 seconds Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate Performing the following challenges: http-01 challenge for awstats.openbuildinginstitute.org http-01 challenge for openbuildinginstitute.org http-01 challenge for seedhome.openbuildinginstitute.org http-01 challenge for www.openbuildinginstitute.org Waiting for verification... Cleaning up challenges - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/opensourceecology.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Cert is due for renewal, auto-renewing... Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate Performing the following challenges: http-01 challenge for awstats.opensourceecology.org http-01 challenge for fef.opensourceecology.org http-01 challenge for forum.opensourceecology.org http-01 challenge for microfactory.opensourceecology.org http-01 challenge for munin.opensourceecology.org http-01 challenge for opensourceecology.org http-01 challenge for oswh.opensourceecology.org http-01 challenge for phplist.opensourceecology.org http-01 challenge for staging.opensourceecology.org http-01 challenge for store.opensourceecology.org http-01 challenge for wiki.opensourceecology.org http-01 challenge for www.opensourceecology.org Waiting for verification... Challenge failed for domain www.opensourceecology.org http-01 challenge for www.opensourceecology.org Cleaning up challenges - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/opensourceecology.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Congratulations, all renewals succeeded. The following certs have been renewed: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem (success) /etc/letsencrypt/live/opensourceecology.org/fullchain.pem (success) - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - IMPORTANT NOTES: - The following errors were reported by the server: Domain: www.opensourceecology.org Type: dns Detail: DNS problem: networking error looking up CAA for www.opensourceecology.org Redirecting to /bin/systemctl reload nginx.service
- there's a recent thread with this error message on the Let's Encrypt fourms. It was asked 2023-12-20, which is right in our timeline of when this issue hit OSE https://community.letsencrypt.org/t/networking-error-when-letsencrypt-is-looking-up-caa/210483
- there's also a recent bug report filed last week (2024-01-15) https://github.com/cert-manager/cert-manager/issues/6640
- none of the above two threads were helpful. I'm just going to try to upgrade cerbot; maybe there's some old bug that was fixed
- currently we're running certbot v1.3.0-1
[root@opensourceecology letsencrypt]# rpm -qa | grep -i certbot python2-certbot-1.3.0-1.el7.noarch certbot-1.3.0-1.el7.noarch [root@opensourceecology letsencrypt]#
- I upgraded to v1.11.0-2
[root@opensourceecology letsencrypt]# yum install certbot Loaded plugins: fastestmirror, replace Loading mirror speeds from cached hostfile * base: mirror.fra1.de.leaseweb.net * epel: mirror.de.leaseweb.net * extras: mirror.checkdomain.de * updates: mirror.checkdomain.de Resolving Dependencies --> Running transaction check ---> Package certbot.noarch 0:1.3.0-1.el7 will be updated ---> Package certbot.noarch 0:1.11.0-2.el7 will be an update --> Processing Dependency: python2-certbot = 1.11.0-2.el7 for package: certbot-1.11.0-2.el7.noarch --> Running transaction check ---> Package python2-certbot.noarch 0:1.3.0-1.el7 will be updated ---> Package python2-certbot.noarch 0:1.11.0-2.el7 will be an update --> Processing Dependency: python2-acme >= 1.8.0 for package: python2-certbot-1.11.0-2.el7.noarch --> Running transaction check ---> Package python2-acme.noarch 0:1.3.0-1.el7 will be updated ---> Package python2-acme.noarch 0:1.11.0-1.el7 will be an update --> Finished Dependency Resolution Dependencies Resolved ================================================================================================================================== Package Arch Version Repository Size ================================================================================================================================== Updating: certbot noarch 1.11.0-2.el7 epel 47 k Updating for dependencies: python2-acme noarch 1.11.0-1.el7 epel 83 k python2-certbot noarch 1.11.0-2.el7 epel 386 k Transaction Summary ================================================================================================================================== Upgrade 1 Package (+2 Dependent packages) Total download size: 515 k Is this ok [y/d/N]: y Downloading packages: Delta RPMs disabled because /usr/bin/applydeltarpm not installed. (1/3): certbot-1.11.0-2.el7.noarch.rpm | 47 kB 00:00:00 (2/3): python2-acme-1.11.0-1.el7.noarch.rpm | 83 kB 00:00:00 (3/3): python2-certbot-1.11.0-2.el7.noarch.rpm | 386 kB 00:00:00 -------------------- Total 1.9 MB/s | 515 kB 00:00:00 Running transaction check Running transaction test Transaction test succeeded Running transaction Updating : python2-acme-1.11.0-1.el7.noarch 1/6 Updating : python2-certbot-1.11.0-2.el7.noarch 2/6 Updating : certbot-1.11.0-2.el7.noarch 3/6 Cleanup : certbot-1.3.0-1.el7.noarch 4/6 Cleanup : python2-certbot-1.3.0-1.el7.noarch 5/6 Cleanup : python2-acme-1.3.0-1.el7.noarch 6/6 Verifying : certbot-1.11.0-2.el7.noarch 1/6 Verifying : python2-acme-1.11.0-1.el7.noarch 2/6 Verifying : python2-certbot-1.11.0-2.el7.noarch 3/6 Verifying : python2-certbot-1.3.0-1.el7.noarch 4/6 Verifying : certbot-1.3.0-1.el7.noarch 5/6 Verifying : python2-acme-1.3.0-1.el7.noarch 6/6 Updated: certbot.noarch 0:1.11.0-2.el7 Dependency Updated: python2-acme.noarch 0:1.11.0-1.el7 python2-certbot.noarch 0:1.11.0-2.el7 Complete! [root@opensourceecology letsencrypt]#
- I did another force renewal
[root@opensourceecology letsencrypt]# certbot certificates Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Found the following certs: Certificate Name: openbuildinginstitute.org Serial Number: 47c22e806946a20e6a574394ef507d0aff2 Key Type: RSA Domains: www.openbuildinginstitute.org awstats.openbuildinginstitute.org openbuildinginstitute.org seedhome.openbuildinginstitute.org Expiry Date: 2024-04-20 00:47:41+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/openbuildinginstitute.org/privkey.pem Certificate Name: opensourceecology.org Serial Number: 4c27188b056dad08bff1b624995a3774a61 Key Type: RSA Domains: opensourceecology.org awstats.opensourceecology.org fef.opensourceecology.org forum.opensourceecology.org microfactory.opensourceecology.org munin.opensourceecology.org oswh.opensourceecology.org phplist.opensourceecology.org staging.opensourceecology.org store.opensourceecology.org wiki.opensourceecology.org Expiry Date: 2024-04-20 00:47:47+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/opensourceecology.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/opensourceecology.org/privkey.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology letsencrypt]# [root@opensourceecology letsencrypt]# certbot renew --force-renew Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/openbuildinginstitute.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate for www.openbuildinginstitute.org and 3 more domains - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/opensourceecology.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate for opensourceecology.org and 10 more domains - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/opensourceecology.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Congratulations, all renewals succeeded: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem (success) /etc/letsencrypt/live/opensourceecology.org/fullchain.pem (success) - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology letsencrypt]#
- sadly, there's still no 'www' subdomain
[root@opensourceecology letsencrypt]# certbot certificates Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Found the following certs: Certificate Name: openbuildinginstitute.org Serial Number: 3a18ce304580629bd0d83fe28d9285b492f Key Type: RSA Domains: www.openbuildinginstitute.org awstats.openbuildinginstitute.org openbuildinginstitute.org seedhome.openbuildinginstitute.org Expiry Date: 2024-04-20 01:17:10+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/openbuildinginstitute.org/privkey.pem Certificate Name: opensourceecology.org Serial Number: 4c559a2d15c6bea75c5e7bb65170fbe2d9c Key Type: RSA Domains: opensourceecology.org awstats.opensourceecology.org fef.opensourceecology.org forum.opensourceecology.org microfactory.opensourceecology.org munin.opensourceecology.org oswh.opensourceecology.org phplist.opensourceecology.org staging.opensourceecology.org store.opensourceecology.org wiki.opensourceecology.org Expiry Date: 2024-04-20 01:17:15+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/opensourceecology.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/opensourceecology.org/privkey.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology letsencrypt]#
- I think I should try to just explicitly tell certbot to update its config. the process for this is documented in the wiki here https://wiki.opensourceecology.org/wiki/Web_server_configuration#https
- here's the command as-stated in the wiki (doc rot)
certbot -nv --expand --cert-name opensourceecology.org certonly -v --webroot -w /var/www/html/fef.opensourceecology.org/htdocs/ -d fef.opensourceecology.org -w /var/www/html/www.opensourceecology.org/htdocs -d www.opensourceecology.org -w /var/www/html/oswh.opensourceecology.org/htdocs/ -d oswh.opensourceecology.org -w /var/www/html/forum.opensourceecology.org/htdocs -d forum.opensourceecology.org /bin/chmod 0400 /etc/letsencrypt/archive/*/pri* nginx -t && service nginx reload
- here's the updated command
certbot -nv --expand --cert-name opensourceecology.org certonly -v --webroot -w /var/www/html/fef.opensourceecology.org/htdocs/ -d fef.opensourceecology.org -w /var/www/html/www.opensourceecology.org/htdocs -d www.opensourceecology.org -d opensourceecology.org -w /var/www/html/oswh.opensourceecology.org/htdocs/ -d oswh.opensourceecology.org -w /var/www/html/forum.opensourceecology.org/htdocs -d forum.opensourceecology.org -w /var/www/html/store.opensourceecology.org/htdocs -d store.opensourceecology.org -w /var/www/html/phplist.opensourceecology.org/public_html -d phplist.opensourceecology.org -w /var/www/html/certbot/htdocs -d munin.opensourceecology.org -d awstats.opensourceecology.org -w /var/www/html/microfactory.opensourceecology.org/htdocs -d microfactory.opensourceecology.org -w /var/www/html/wiki.opensourceecology.org/htdocs -d wiki.opensourceecology.org -w /var/www/html/staging.opensourceecology.org/htdocs -d staging.opensourceecology.org
- gave it a run
[root@opensourceecology letsencrypt]# certbot -nv --expand --cert-name opensourceecology.org certonly -v --webroot -w /var/www/html/fef.opensourceecology.org/htdocs/ -d fef.opensourceecology.org -w /var/www/html/www.opensourceecology.org/htdocs -d www.opensourceecology.org -d opensourceecology.org -w /var/www/html/oswh.opensourceecology.org/htdocs/ -d oswh.opensourceecology.org -w /var/www/html/forum.opensourceecology.org/htdocs -d forum.opensourceecology.org -w /var/www/html/store.opensourceecology.org/htdocs -d store.opensourceecology.org -w /var/www/html/phplist.opensourceecology.org/public_html -d phplist.opensourceecology.org -w /var/www/html/certbot/htdocs -d munin.opensourceecology.org -d awstats.opensourceecology.org -w /var/www/html/microfactory.opensourceecology.org/htdocs -d microfactory.opensourceecology.org -w /var/www/html/wiki.opensourceecology.org/htdocs -d wiki.opensourceecology.org -w /var/www/html/staging.opensourceecology.org/htdocs -d staging.opensourceecology.org ... Writing new config /etc/letsencrypt/renewal/opensourceecology.org.conf.new. Reporting to user: Congratulations! Your certificate and chain have been saved at: /etc/letsencrypt/live/opensourceecology.org/fullchain.pem Your key file has been saved at: /etc/letsencrypt/live/opensourceecology.org/privkey.pem Your certificate will expire on 2024-04-20. To obtain a new or tweaked version of this certificate in the future, simply run certb ot again. To non-interactively renew *all* of your certificates, run "certbot renew" Reporting to user: If you like Certbot, please consider supporting our work by: Donating to ISRG / Let's Encrypt: https://letsencrypt.org/donate Donating to EFF: https://eff.org/donate-le IMPORTANT NOTES: - Congratulations! Your certificate and chain have been saved at: /etc/letsencrypt/live/opensourceecology.org/fullchain.pem Your key file has been saved at: /etc/letsencrypt/live/opensourceecology.org/privkey.pem Your certificate will expire on 2024-04-20. To obtain a new or tweaked version of this certificate in the future, simply run certbot again. To non-interactively renew *all* of your certificates, run "certbot renew" - If you like Certbot, please consider supporting our work by: Donating to ISRG / Let's Encrypt: https://letsencrypt.org/donate Donating to EFF: https://eff.org/donate-le [root@opensourceecology letsencrypt]#
- finally, the 'www' subdomain is in the list now
[root@opensourceecology letsencrypt]# certbot certificates Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Found the following certs: Certificate Name: openbuildinginstitute.org Serial Number: 3a18ce304580629bd0d83fe28d9285b492f Key Type: RSA Domains: www.openbuildinginstitute.org awstats.openbuildinginstitute.org openbuildinginstitute.org seedhome.openbuildinginstitute.org Expiry Date: 2024-04-20 01:17:10+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/openbuildinginstitute.org/privkey.pem Certificate Name: opensourceecology.org Serial Number: 30ec9a5c7a9a9603d3f2c5bd943be6d8d75 Key Type: RSA Domains: fef.opensourceecology.org awstats.opensourceecology.org forum.opensourceecology.org microfactory.opensourceecology.org munin.opensourceecology.org opensourceecology.org oswh.opensourceecology.org phplist.opensourceecology.org staging.opensourceecology.org store.opensourceecology.org wiki.opensourceecology.org www.opensourceecology.org Expiry Date: 2024-04-20 01:28:35+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/opensourceecology.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/opensourceecology.org/privkey.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology letsencrypt]#
- refreshing the page doesn't work; let's try the next two documented commands
[root@opensourceecology letsencrypt]# /bin/chmod 0400 /etc/letsencrypt/archive/*/pri* [root@opensourceecology letsencrypt]# nginx -t && service nginx reload nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.openbuildinginstitute.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.openbuildinginstitute.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.openbuildinginstitute.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.openbuildinginstitute.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: [warn] the "ssl" directive is deprecated, use the "listen ... ssl" directive instead in /etc/nginx/conf.d/ssl.opensourceecology.org.include:11 nginx: the configuration file /etc/nginx/nginx.conf syntax is ok nginx: configuration file /etc/nginx/nginx.conf test is successful Redirecting to /bin/systemctl reload nginx.service [root@opensourceecology letsencrypt]#
- well looks like we're using some deprecated 'ssl' option in our nginx configs, but otherwise that looked good
- I refreshed the web browser, and now the cert errors are gone :D
- I tested all of the other subdomains; I did not get any errors
- for good measure (to make sure it won't break again on next renewal), I forced one more renewal
[root@opensourceecology letsencrypt]# certbot renew --force-renew Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/openbuildinginstitute.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate for www.openbuildinginstitute.org and 3 more domains - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Processing /etc/letsencrypt/renewal/opensourceecology.org.conf - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Plugins selected: Authenticator webroot, Installer None Starting new HTTPS connection (1): acme-v02.api.letsencrypt.org Renewing an existing certificate for fef.opensourceecology.org and 11 more domains - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - new certificate deployed without reload, fullchain is /etc/letsencrypt/live/opensourceecology.org/fullchain.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Congratulations, all renewals succeeded: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem (success) /etc/letsencrypt/live/opensourceecology.org/fullchain.pem (success) - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology letsencrypt]#
- I confirmed that the 'www' subdomain is, in fact, still present. Success!
[root@opensourceecology letsencrypt]# certbot certificates Saving debug log to /var/log/letsencrypt/letsencrypt.log - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - Found the following certs: Certificate Name: openbuildinginstitute.org Serial Number: 30f44a6ec177f0c7c24b8d450aa9e57ef36 Key Type: RSA Domains: www.openbuildinginstitute.org awstats.openbuildinginstitute.org openbuildinginstitute.org seedhome.openbuildinginstitute.org Expiry Date: 2024-04-20 01:35:00+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/openbuildinginstitute.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/openbuildinginstitute.org/privkey.pem Certificate Name: opensourceecology.org Serial Number: 360f3ea6ad9910ecaff89dc9725efd8f1a9 Key Type: RSA Domains: fef.opensourceecology.org awstats.opensourceecology.org forum.opensourceecology.org microfactory.opensourceecology.org munin.opensourceecology.org opensourceecology.org oswh.opensourceecology.org phplist.opensourceecology.org staging.opensourceecology.org store.opensourceecology.org wiki.opensourceecology.org www.opensourceecology.org Expiry Date: 2024-04-20 01:35:05+00:00 (VALID: 89 days) Certificate Path: /etc/letsencrypt/live/opensourceecology.org/fullchain.pem Private Key Path: /etc/letsencrypt/live/opensourceecology.org/privkey.pem - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - [root@opensourceecology letsencrypt]#
- In conclusion, it appears that there's some recent & known bug in certbot where DNS errors cause failures at some very small probability. This broke renewal for just one of our subdomains sometime between 2023-11-13 and 2024-01-13 https://github.com/cert-manager/cert-manager/issues/6640
- I think I may have also discovered some other unknown bug where ^ this bug causes certbot to forget about a defined subdomain on subsequent renewals. But I don't have enough evidence of this yet to submit a proper bug report
- the fix was to manually construct and re-run the `certbot -nv --expand --cert-name opensourceecology.org certonly -v --webroot -w ...` command && chmod && nginx reload (see above)
- I sent an email to Marcin about this root cause & resolution
Hey Marcin, I fixed the certbot config. It looks like there's some sort of bug (reported to Let's Encrypt GitHub last week) that causes some domain renewals to fail due to DNS issues at some highly improbable likelihood. This happened for the 'www.opensourceeoclogy.org' subdomain sometime between 2023-11-13 and 2024-01-13. And, for some reason, this prevented subsequent renewals from attempting to renew that subdomain. I fixed it by refreshing the config for the opensourceecology.org subdomain. I tested that subsequent renewals will work as well. For more information, see my log entry: * https://wiki.opensourceecology.org/wiki/Maltfield_Log/2024#Sat_January_10.2C_2024 Please let me know if you have any further questions. Thank you, Michael Altfield Senior Technology Advisor PGP Fingerprint: 8A4B 0AF8 162F 3B6A 79B7 70D2 AA3E DF71 60E2 D97B Open Source Ecology www.opensourceecology.org
