Docker上で稼動しているGhostのスケジュール投稿機能がどういうわけか動作しなかったので調べました

環境

Server - さくらVPS CentOS 7系
FW - iptalbes
Dcoker - Ghost: v1.24.8
Dcoker - Databese: MySQL
Dcoker - proxy: nginx
SSL: 有(強制リダイレクト)

目的

スケジュール機能が動作しない原因を調査し、機能するように修正する

背景

スケジュール投稿できないと、書き溜めした時とかに1日1回とかの自動投稿とかが出来なくてつらい

原因

結論

先に結果を言うと、docker内からホストのグローバルIPへアクセスできなかったことが原因です
以下、原因を調べるまでの過程です

1. nginx側のログを調べる

下記のような感じでまずはリクエストが飛んできているのかを調べます

dokcer logs nginx | gpre post

nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:41:10 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1048 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:41:24 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1056 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:41:37 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1069 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:41:45 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1073 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:41:59 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1079 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:42:09 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1107 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:42:29 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1133 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:42:48 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1157 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:43:08 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1172 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:43:24 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1166 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:43:33 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1174 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
nginx.0    | example.com xxx.xxx.xxx.xxx - - [14/Jul/2018:20:44:03 +0000] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles HTTP/2.0" 200 1238 "https://example.com/ghost/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99 Safari/537.36"
...

どうやらスケジュール設定自体は問題ないようですが、予定した自動投稿時付近にそれらしきPUTログが見当たりません
ここから察するに、リクエスト自体がないのでクライアント側(ghost側)の問題のようです

2. Ghostのログを調べる

dokcer logsで調べます

docker logs ghost

INFO [2018-07-14 16:53:45] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles" 200 213ms
INFO [2018-07-14 16:53:51] "GET /ghost/api/v0.1/posts/?limit=30&page=1&status=all&staticPages=all&formats=mobiledoc%2Cplaintext&include=authors%2Ctags%2Cauthors.roles" 200 262ms
[2018-07-14 16:57:01] ERROR

NAME: InternalServerError
CODE: EHOSTUNREACH
MESSAGE: The server has encountered an error.

level:critical

InternalServerError: The server has encountered an error.
    at new GhostError (/var/lib/ghost/versions/1.24.8/core/server/lib/common/errors.js:9:26)
    at /var/lib/ghost/versions/1.24.8/core/server/adapters/scheduling/SchedulingDefault.js:239:34
    at Request.callback (/var/lib/ghost/versions/1.24.8/node_modules/superagent/lib/node/index.js:728:3)
    at ClientRequest.req.once.err (/var/lib/ghost/versions/1.24.8/node_modules/superagent/lib/node/index.js:647:10)
    at ClientRequest.g (events.js:292:16)
    at emitOne (events.js:96:13)
    at ClientRequest.emit (events.js:188:7)
    at TLSSocket.socketErrorListener (_http_client.js:314:9)
    at emitOne (events.js:96:13)
    at TLSSocket.emit (events.js:188:7)
    at emitErrorNT (net.js:1290:8)
    at _combinedTickCallback (internal/process/next_tick.js:80:11)
    at process._tickCallback (internal/process/next_tick.js:104:9)

Error: connect EHOSTUNREACH xxx.xxx.xxx.xxx:443
    at Object.exports._errnoException (util.js:1020:11)
    at exports._exceptionWithHostPort (util.js:1043:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1099:14)

INFO [2018-07-14 16:58:19] "GET /" 304 207ms
INFO [2018-07-14 16:58:21] "GET /" 304 123ms
INFO [2018-07-14 16:58:21] "GET /favicon.png" 200 7ms
INFO [2018-07-14 16:59:02] "GET /robots.txt" 200 3ms
INFO [2018-07-14 17:01:17] "GET /ghost/" 200 59ms
INFO [2018-07-14 17:01:17] "GET /ghost/api/v0.1/configuration/" 200 11ms
INFO [2018-07-14 17:01:17] "GET /ghost/api/v0.1/configuration/private/" 200 28ms
INFO [2018-07-14 17:01:17] "GET /ghost/api/v0.1/settings/?type=blog%2Ctheme%2Cprivate" 200 77ms
INFO [2018-07-14 17:01:17] "GET /ghost/api/v0.1/users/me/?include=roles" 200 121ms
INFO [2018-07-14 17:01:17] "GET /ghost/api/v0.1/notifications/" 200 31ms
INFO [2018-07-14 17:01:18] "GET /content/images/2018/07/example.com.site.icon-1.png?t=1531587677975" 200 5ms
INFO [2018-07-14 17:01:18] "GET /ghost/api/v0.1/posts/?limit=30&page=1&status=all&staticPages=all&formats=mobiledoc%2Cplaintext&include=authors%2Ctags%2Cauthors.roles" 200 212ms
INFO [2018-07-14 17:01:18] "GET /ghost/api/v0.1/tags/?limit=all" 200 87ms
INFO [2018-07-14 17:01:18] "GET /ghost/api/v0.1/users/?limit=all&include=roles" 200 91ms
INFO [2018-07-14 17:01:22] "GET /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?status=all&staticPages=all&formats=mobiledoc%2Cplaintext&include=authors%2Ctags%2Cauthors.roles" 200 83ms
INFO [2018-07-14 17:01:23] "GET /ghost/api/v0.1/themes/" 200 90ms
INFO [2018-07-14 17:01:23] "GET /ghost/api/v0.1/tags/?limit=all" 200 130ms
INFO [2018-07-14 17:01:23] "GET /ghost/api/v0.1/users/?limit=all&include=roles" 200 135ms
INFO [2018-07-14 17:01:35] "PUT /ghost/api/v0.1/posts/jb4bb52100b3112800751baa/?include=authors,tags,authors.roles" 200 335ms
[2018-07-14 17:01:35] ERROR

NAME: InternalServerError
MESSAGE: Response code 405 (Method Not Allowed)

level:normal

The xmlrpc service was unable to send a ping request, your blog will continue to function.
If you get this error repeatedly, please seek help on http://docs.ghost.org.
InternalServerError: Response code 405 (Method Not Allowed)
    at new GhostError (/var/lib/ghost/versions/1.24.8/core/server/lib/common/errors.js:9:26)
    at /var/lib/ghost/versions/1.24.8/core/server/services/xmlrpc.js:75:38
    at tryCatcher (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromise0 (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/promise.js:614:10)
    at Promise._settlePromises (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/promise.js:689:18)
    at Async._drainQueue (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/async.js:133:16)
    at Async._drainQueues (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/async.js:143:10)
    at Immediate.Async.drainQueues (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/async.js:17:14)
    at runCallback (timers.js:672:20)
    at tryOnImmediate (timers.js:645:5)
    at processImmediate [as _immediateCallback] (timers.js:617:5)

HTTPError: Response code 405 (Method Not Allowed)
    at StdError (/var/lib/ghost/versions/1.24.8/node_modules/got/index.js:410:3)
    at /var/lib/ghost/versions/1.24.8/node_modules/got/index.js:454:3
    at stream.catch.then.e (/var/lib/ghost/versions/1.24.8/node_modules/got/index.js:182:13)
    at tryCatcher (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromise0 (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/promise.js:614:10)
    at Promise._settlePromises (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/promise.js:693:18)
    at Async._drainQueue (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/async.js:133:16)
    at Async._drainQueues (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/async.js:143:10)
    at Immediate.Async.drainQueues (/var/lib/ghost/versions/1.24.8/node_modules/bluebird/js/release/async.js:17:14)
    at runCallback (timers.js:672:20)
    at tryOnImmediate (timers.js:645:5)
    at processImmediate [as _immediateCallback] (timers.js:617:5)

どうやらスケジュールされたタイミングで発火はしているようですが、そこで失敗している模様
その直後に405エラーが続いてます

ログの場所について

ところでghostのログの場所は/var/lib/ghost/content/logsです

とりあえず発火タイミングから最初のエラー内容を見てみます

Error: connect EHOSTUNREACH xxx.xxx.xxx.xxx:443

ここを見る限り、どうやらSSL接続を試みたが失敗した模様
接続先はdokcerホストのグローバルIPでした

ふむう。dockerコンテナ内からグローバルIPアドレスでホスト側に接続できないのか？
試してみましょう

docker exec -it abcdefg123d5 /bin/bash

bash-4.3# wget https://example.com
Connecting to example.com (xxx.xxx.xxx.xxx:443)
wget: can't connect to remote host (xxx.xxx.xxx.xxx): Host is unreachable

bash-4.3# wget xxx.xxx.xxx.xxx
Connecting to xxx.xxx.xxx.xxx (xxx.xxx.xxx.xxx:80)
wget: can't connect to remote host (xxx.xxx.xxx.xxx): Host is unreachable

bash-4.3# wget xxx.xxx.xxx.xxx:443
Connecting to xxx.xxx.xxx.xxx:443 (xxx.xxx.xxx.xxx:443)
wget: can't connect to remote host (xxx.xxx.xxx.xxx): Host is unreachable

全滅です
どうやら原因はdockerコンテナ内からホスト側にアクセスが出来ないことみたいですね
私の環境だとiptablesなので、コンテナIPからのアクセスを受け入れる設定にしたらよさげです

解決策

ghostコンテナ内からホスト側に対しての一部の通信を許可します
ファイアウォールの設定をします

sudo iptables -I INPUT 1 -s 172.18.0.0/24 -j ACCEPT

ここでは送信元が172.18.0.0～172.18.0.255まで受け入れることとします
IPアドレスの範囲は環境にあわせて変更してください
ちなみにdokcerのIPアドレスは下記とかで見つかると思います

ifconfig | grep -8 docker

確認

dockerコンテナ内でホストIPに対して接続できることを確認しておきます

bash-4.3# wget -O - https://example.com
bash-4.3# wget -O - xxx.xxx.xxx.xxx
bash-4.3# wget -O - xxx.xxx.xxx.xxx:443

ここまで確認できたら、あとはスケジューリングして自動的に反映されるのを待ちます

課題

ただ、これでも2つ目のHTTPError: Response code 405 (Method Not Allowed)エラーは解決していない
どうもこれは既に機能していないようでスケジュール機能とはまた別の問題っぽい？
現段階では特に目に見える問題はないため、時間があれば調査する

2018年07月16日 追記
こちらの記事でこの問題を調べて解決した内容をまとめました

参考