Scheduled Posts don't Publish


#1

I set a post to be scheduled today at 13:00 UTC. But the time came and went and the post wasn’t published. Not a big deal but I really like the scheduled post feature so would like to figure out what’s wrong with my setup.

  • What version of Ghost are you using?

Ghost 1.22.5 from docker (https://hub.docker.com/_/ghost/)

  • What configuration?

Docker and Sqlite.

  • What errors or information do you see in the console?

Possibly the following is relevant, it happened at the time the publish should’ve happened:

[2018-05-06 13:02:07] ERROR

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

level:critical

InternalServerError: The server has encountered an error.
    at new GhostError (/var/lib/ghost/versions/1.22.5/core/server/lib/common/errors.js:9:26)
    at /var/lib/ghost/versions/1.22.5/core/server/adapters/scheduling/SchedulingDefault.js:239:34
    at Request.callback (/var/lib/ghost/versions/1.22.5/node_modules/superagent/lib/node/index.js:728:3)
    at ClientRequest.req.once.err (/var/lib/ghost/versions/1.22.5/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 ETIMEDOUT 82.196.2.207: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)
  • What steps could someone else take to reproduce the issue you’re having?

Run the Ghost docker container. Schedule a post and wait for the scheduled time to be passed. In my case the post isn’t published.

In my case, the following was true:

  • In the admin console, “Stories” lists the story as “will be published today at 13:00”, but that time is already in the past.
  • The servertime was correct, as also shown in General > Site Timezone and also in the ssh session of the server (“date” shows the correct UTC time)
  • When I “reschedule” the post then, to a few minutes into the future, it immediatly gets published. The “Stories” then lists the post as “Published in 4 minutes”, and then later of course “Published x minutes ago”

So it looks like the publish is triggered, but an error occurs: “Error: connect ETIMEDOUT 82.196.2.207:443”. This is the correct IP address of my server. But I wonder if there’s a problem because this is happening inside a docker container?

I have a docker container for ghost and then a container for nginx. Nginx listens to the outside world on port 443 and is a reverse proxy. The connection between nginx and ghost is over HTTP (no https).

Does anyone have any pointers? Did I miss something with the setup in docker?

Thanks a lot!


#2

I seem to be having the same issues as @lenoir_aaron.

I however am using it on the CLI on a Linode with MySql.

I’m not quite used to all this, so I can’t be as thorough as @lenoir_aaron, but I tried to tail the log with ghost log – follow and this is what I see

[2018-05-07 09:59:22] INFO "PUT /ghost/api/v0.1/posts/5aefcb06eca0ca3d148873dd/?include=authors,tags,authors.roles" 200 168ms
[2018-05-07 09:59:22] INFO "PUT /ghost/api/v0.1/posts/5aefcb06eca0ca3d148873dd/?include=authors,tags,authors.roles" 200 168ms
[2018-05-07 09:59:27] INFO "PUT /ghost/api/v0.1/posts/5aefcb06eca0ca3d148873dd/?include=authors,tags,authors.roles" 200 122ms
[2018-05-07 09:59:27] INFO "PUT /ghost/api/v0.1/posts/5aefcb06eca0ca3d148873dd/?include=authors,tags,authors.roles" 200 122ms
[2018-05-07 09:59:33] INFO "GET /ghost/api/v0.1/posts/?limit=30&page=1&status=all&staticPages=all&formats=mobiledoc%2Cplaintext&include=authors%2Ctags%2Cauthors.roles" 200 271ms
[2018-05-07 09:59:33] INFO "GET /ghost/api/v0.1/posts/?limit=30&page=1&status=all&staticPages=all&formats=mobiledoc%2Cplaintext&include=authors%2Ctags%2Cauthors.roles" 200 271ms
[2018-05-07 10:04:00] INFO "GET /ghost/api/v0.1/schedules/posts/5aefcb06eca0ca3d148873dd?client_id=ghost-scheduler&client_secret=9c7101614d10" 404 6ms
[2018-05-07 10:04:00] INFO "GET /ghost/api/v0.1/schedules/posts/5aefcb06eca0ca3d148873dd?client_id=ghost-scheduler&client_secret=9c7101614d10" 404 6ms  

The post does not post however.


#3

Note: our resident scheduling expert is on holiday for a bit, so you might get better answers in a couple of weeks.

In the meantime:

@lenoir_aaron To debug this, you’ll need to try talking to the API from inside your docker container. As @jasonbraganza’s logs show, Ghost publishes a post by making a call to its own API:

GET /ghost/api/v0.1/schedules/posts/5aefcb06eca0ca3d148873dd?client_id=ghost-scheduler&client_secret=9c7101614d10

If you can find these requests in the info log, it’s easy to copy, else you can get your post ID, and scheduler credentials from your database. If you are able to test making a call using curl inside the container, you should be able to determine if the ETIMEDOUT errors are definitely related and then start working through possible causes for why the requests are not allowed.

@jasonbraganza In your case the request to schedule the post 404s, meaning either the post wasn’t set to be scheduled anymore, or had already been scheduled. Everything otherwise looks like it’s probably working correctly. Do you have a cache in front of Ghost?

You can view your logs in full by looking in the content/logs folder inside of your Ghost folder. I recommend trying grep -r 'schedules/posts' . in that folder to find all the requests to the scheduler to see if there are more entries.


#4

Thank you for that quick reply @Hannah!

Will try what you said and revert in a few.

I have no issues waiting at all!
Thankful I have Ghost :slight_smile:

The scheduled posts is something I just started using over the past few days and I thought I was doing something wrong.

I don’t have a cache per se, but I’m reverse proxying with nginx.
Could that also be a cause?

Thank you and the ghost team for all you do.


#5

no errors other than this loooong error

[2018-05-07 16:03:02] ERROR

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

level: normal

The slack 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/www/mjb/versions/1.22.5/core/server/lib/common/errors.js:9:26)
    at /var/www/mjb/versions/1.22.5/core/server/services/xmlrpc.js:75:38
    at tryCatcher (/var/www/mjb/versions/1.22.5/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/var/www/mjb/versions/1.22.5/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/var/www/mjb/versions/1.22.5/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromise0 (/var/www/mjb/versions/1.22.5/node_modules/bluebird/js/release/promise.js:614:10)
    at Promise._settlePromises (/var/www/mjb/versions/1.22.5/node_modules/bluebird/js/release/promise.js:689:18)
    at Async._drainQueue (/var/www/mjb/versions/1.22.5/node_modules/bluebird/js/release/async.js:133:16)
    at Async._drainQueues (/var/www/mjb/versions/1.22.5/node_modules/bluebird/js/release/async.js:143:10)
    at Immediate.Async.drainQueues (/var/www/mjb/versions/1.22.5/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)

tried deleting all my drafts
deleting all my scheduled posts
stopping my ghost instance
ghost doctor
ghost buster
starting it up again and trying with a brand new test post.

still doesn’t post.

similar error as before

[2018-05-07 16:19:59] INFO “GET /ghost/api/v0.1/schedules/posts/5af02e4e9d148d46881a71a6?client_id=ghost-scheduler&client_secret=9c7101614d10” 404 5ms
[2018-05-07 16:19:59] INFO “GET /ghost/api/v0.1/schedules/posts/5af02e4e9d148d46881a71a6?client_id=ghost-scheduler&client_secret=9c7101614d10” 404 5ms

have attached an image of the main screen after the post time has passed
will await further instructions.

and thank you once again :slight_smile:

scheduled%20post


#6

Hello

I tried to look for any requests to the ghost api schedules/posts, but couldn’t find anything. I did figure out the secret (I think). I managed to run that URL from inside the docker container.

It works when I use localhost:2368 (the port Ghost is running on). But it doesn’t work when I use https://:443.

I don’t exactly know why there is a timeout though: I would think this would go to my docker container, come in via the nginx container and then go to the ghost container. But instead it just times out. I can ping the server from inside the docker container with the public IP address.

But why wouldn’t Ghost call it’s own API via the localhost? Is this something I can influence through configuration?

When I have some time, I may have a look in the code and try and understand what is happening. But maybe you know more, more quickly :slight_smile:

Thanks a lot for the assistance and Ghost!


#7

Hello, I’ve been looking into this. And thought I’d post an update, never know who else has this issue.

I’m running on a Digital Ocean “droplet” (virtual private server) that has iptables preconfigured (using ufw).

I was able to connect to port 443 from inside my ghost container if I use the internal IP address of my server, but not if I use the public IP address. However, I was able to connect to SSH from inside the ghost container using the public IP.

Turns out, for https it was blocking incoming connections unless the destination was the internal IP address of my host. I could see this block happening in real-time by looking at the syslog while trying to connect: sudo tail -f /var/log/syslog

So I added a rule to the firewall: “if connections are coming from the local docker ip range, and going to my public ip address, plelase allow https anyway.” (ufw allow from 172.18.0.0/24 to 82.196.2.207 port 443)

I am now able to connect, using telnet, to my 443 port, using the public IP address.

Now the question is if this solves my scheduling problem! I’m betting it’ll solve the timeout error I saw ealier.

Will keep you posted.


#8

Hello, looks like the above solved my issue. My post gets published automatically.

I do still get the below error in the ghost log, but it doesn’t seem to hold back the publish.

But my solution: When running ghost in a container, make sure Ghost is able to connect to port 443 (https) on the public IP address of the host. On a Digital Ocean docker droplet, this is not allowed by the firewall (ufw). You can allow this:

ufw allow from 172.18.0.0/24 to <public-ip-address> port 443 (not, your IP address may be different)

Possible other solutions may be (but I haven’t tried):

  • Make the Ghost container resolve your blog hostname to the local IP address (if that is even possible)
  • Set the admin.url in the configuration to something that resolves to the internal IP address

But both seem more difficult.

Here’s the other error I see that happens exactly when the schedule post gets triggered. But the post gets published so I’m not going to worry about that one too much.

INFO [2018-05-09 23:20:00] "PUT /ghost/api/v0.1/schedules/posts/5af37fca9aa0b10001bdd492?client_id=ghost-scheduler&client_secret=..." 200 218ms
[2018-05-09 23:20:00] ERROR

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

level:normal

The slack 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.22.6/core/server/lib/common/errors.js:9:26)
    at /var/lib/ghost/versions/1.22.6/core/server/services/xmlrpc.js:75:38
    at tryCatcher (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromise0 (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/promise.js:614:10)
    at Promise._settlePromises (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/promise.js:689:18)
    at Async._drainQueue (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/async.js:133:16)
    at Async._drainQueues (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/async.js:143:10)
    at Immediate.Async.drainQueues (/var/lib/ghost/versions/1.22.6/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.22.6/node_modules/got/index.js:410:3)
    at /var/lib/ghost/versions/1.22.6/node_modules/got/index.js:454:3
    at stream.catch.then.e (/var/lib/ghost/versions/1.22.6/node_modules/got/index.js:182:13)
    at tryCatcher (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromise0 (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/promise.js:614:10)
    at Promise._settlePromises (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/promise.js:693:18)
    at Async._drainQueue (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/async.js:133:16)
    at Async._drainQueues (/var/lib/ghost/versions/1.22.6/node_modules/bluebird/js/release/async.js:143:10)
    at Immediate.Async.drainQueues (/var/lib/ghost/versions/1.22.6/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)

#9

You will probably also see this error when you publish a post immediately rather than scheduling. The error is coming from the XML-RPC ping (the slack service mentioned is a bug in the error message :see_no_evil:) that is made every time a post is published so that Google is immediately aware of your new post to speed up indexing.

I can’t reproduce the error locally which suggests that there maybe something else in your server setup that is preventing outgoing POST requests.


#10

Thank you for your awesome sleuthing @lenoir_aaron :slight_smile:
will try this over the weekend


#11

Thanks @Kevin, that’s a good tip! I kind of want to get to the bottom of it now :slight_smile:

I did some further poking and learned that ghost is making an HTTP POST request to the following two url’s:

  • blogsearch.google.com/ping/RPC2
  • rpc.pingomatic.com

(see https://github.com/TryGhost/Ghost/blob/master/core/server/services/xmlrpc.js#L19)

The body of the POST request contains some information about the new post in an XML format.

Both actually get an error response, but only google returns an HTTP 405. I captured this using tcpdump on my docker host.

I’m not sure how this is influenced by my environment, since I do get a response back from both servers. So I can talk to them and they can talk to me. They just don’t like what I’m saying to them. I would expect other Ghost instances to say the same thing, and I’m confused as to why it would not be giving these errors for other people.

If you need the pcap file, I can provide this to you.

Here’s the jist of the google conversation:

POST /ping/RPC2 HTTP/1.1^M
user-agent: got/7.1.0 (https://github.com/sindresorhus/got)^M
accept-encoding: gzip,deflate^M
content-length: 275^M
Host: blogsearch.google.com^M
Connection: close^M
^M
<?xml version="1.0" encoding="UTF-8"?><methodCall>    <methodName>weblogUpdate.ping</methodName><params><param><value><string>Test Post</string></value></param><param><value><string>https://blog.aaronlenoir.com/2018/05/11/test-post/</string></value></param></params></methodCall>
...
HTTP/1.1 405 Method Not Allowed
Allow: GET, HEAD
Date: Fri, 11 May 2018 21:37:37 GMT
Content-Type: text/html; charset=UTF-8
Server: gws
Content-Length: 1598
X-XSS-Protection: 1; mode=block
X-Frame-Options: SAMEORIGIN
Connection: close
...
<p>The request method <code>POST</code> is inappropriate for the URL <code>/ping/RPC2</code>.

And the conversation with pingomatic:

POST / HTTP/1.1
user-agent: got/7.1.0 (https://github.com/sindresorhus/got)
accept-encoding: gzip,deflate
content-length: 275
Host: rpc.pingomatic.com
Connection: close

<?xml version="1.0" encoding="UTF-8"?><methodCall><methodName>weblogUpdate.ping</methodName><params><param><value><string>Test Post</string></value></param><param><value><string>https://blog.aaronlenoir.com/2018/05/11/test-post/</string></value></param></params></methodCall>
...
HTTP/1.1 200 OK
Server: nginx
Date: Fri, 11 May 2018 21:37:37 GMT
Content-Type: text/xml;charset=utf-8
Content-Length: 423
Connection: close
...
<value><string>server error. requested method weblogUpdate.ping does not exist.</string></value>

#12

Ok @jasonbraganza let us know what you find. I’m not sure if we had the same problem since you didn’t see that connection timeout. But do check the connectivity over port 443 (if you run https) between your Ghost instance and the public IP address of your host.

Maybe you could try a wget to the public URL of your blog from the server (or docker container?) that is running Ghost and see if you can connect. Good luck!


#13

I don’t think any of these services are working tbh. Might be time to retire RPC pings entirely - @Hannah ?


#14

connectivity turns out to be fine

think I’ll just give up on scheduled posts.