{"action":"created","issue":{"url":"https://api.github.com/repos/wal-e/wal-e/issues/256","repository_url":"https://api.github.com/repos/wal-e/wal-e","labels_url":"https://api.github.com/repos/wal-e/wal-e/issues/256/labels{/name}","comments_url":"https://api.github.com/repos/wal-e/wal-e/issues/256/comments","events_url":"https://api.github.com/repos/wal-e/wal-e/issues/256/events","html_url":"https://github.com/wal-e/wal-e/issues/256","id":162951888,"number":256,"title":"backup-push to S3 error: timed out? SSL?","user":{"login":"davidham","id":64705,"avatar_url":"https://avatars.githubusercontent.com/u/64705?v=3","gravatar_id":"","url":"https://api.github.com/users/davidham","html_url":"https://github.com/davidham","followers_url":"https://api.github.com/users/davidham/followers","following_url":"https://api.github.com/users/davidham/following{/other_user}","gists_url":"https://api.github.com/users/davidham/gists{/gist_id}","starred_url":"https://api.github.com/users/davidham/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/davidham/subscriptions","organizations_url":"https://api.github.com/users/davidham/orgs","repos_url":"https://api.github.com/users/davidham/repos","events_url":"https://api.github.com/users/davidham/events{/privacy}","received_events_url":"https://api.github.com/users/davidham/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2016-06-29T15:14:02Z","updated_at":"2016-07-13T18:16:11Z","closed_at":null,"body":"After restoring with PITR, I am trying to do a new `backup-push`, but I am getting errors that the operation has timed out. \r\n\r\nHere's the output after running `backup-push`:\r\n\r\n```\r\nroot@1b7016f29155:/# gosu postgres envdir /etc/wal-e.d/env /opt/wale/bin/wal-e backup-push $PGDATA                                             \r\nwal_e.main   INFO     MSG: starting WAL-E\r\n        DETAIL: The subcommand is \"backup-push\".\r\n        STRUCTURED: time=2016-06-29T14:53:46.143174-00 pid=119\r\nwal_e.operator.backup INFO     MSG: start upload postgres version metadata\r\n        DETAIL: Uploading to s3://redacted/postgres-backup/basebackups_005/base_0000000B0000005E00000010_00000096/extended_version.txt.\r\n        STRUCTURED: time=2016-06-29T14:53:46.538699-00 pid=119\r\nwal_e.operator.backup INFO     MSG: postgres version metadata upload complete\r\n        STRUCTURED: time=2016-06-29T14:53:47.584600-00 pid=119\r\nwal_e.worker.upload INFO     MSG: beginning volume compression\r\n        DETAIL: Building volume 0.\r\n        STRUCTURED: time=2016-06-29T14:53:47.695502-00 pid=119\r\nwal_e.worker.upload INFO     MSG: begin uploading a base backup volume\r\n        DETAIL: Uploading to \"s3://redacted/postgres-backup/basebackups_005/base_0000000B0000005E00000010_00000096/tar_partitions/part_00000000.tar.lzo\".\r\n        STRUCTURED: time=2016-06-29T14:53:48.457407-00 pid=119\r\nwal_e.worker.upload INFO     MSG: Retrying send because of a socket error\r\n        DETAIL: The socket error's message is '('timed out',)'.  There have been 1 attempts to send the volume 0 so far.\r\n        STRUCTURED: time=2016-06-29T14:56:19.281416-00 pid=119\r\nwal_e.worker.upload INFO     MSG: Retrying send because of a socket error\r\n        DETAIL: The socket error's message is '('timed out',)'.  There have been 2 attempts to send the volume 0 so far.\r\n        STRUCTURED: time=2016-06-29T14:58:47.945441-00 pid=119\r\nwal_e.worker.upload INFO     MSG: Retrying send because of a socket error\r\n        DETAIL: The socket error's message is '('timed out',)'.  There have been 3 attempts to send the volume 0 so far.\r\n        STRUCTURED: time=2016-06-29T15:01:04.359100-00 pid=119\r\nwal_e.worker.upload INFO     MSG: Retrying send because of a socket error\r\n        DETAIL: The socket error's message is '('timed out',)'.  There have been 4 attempts to send the volume 0 so far.\r\n        STRUCTURED: time=2016-06-29T15:03:15.136338-00 pid=119\r\nwal_e.worker.upload INFO     MSG: Retrying send because of a socket error\r\n        DETAIL: The socket error's message is '('timed out',)'.  There have been 5 attempts to send the volume 0 so far.\r\n        STRUCTURED: time=2016-06-29T15:04:45.058957-00 pid=119\r\n```\r\n\r\nHere's some stdout from Postgres while this is happening:\r\n```\r\npostgres_1  | Traceback (most recent call last):\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/gevent/greenlet.py\", line 534, in run\r\npostgres_1  |     result = self._run(*self.args, **self.kwargs)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/worker/upload.py\", line 50, in __call__\r\npostgres_1  |     self.gpg_key_id)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/worker/worker_util.py\", line 40, in do_lzop_put\r\npostgres_1  |     k = blobstore.uri_put_file(creds, url, tf)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/blobstore/s3/s3_util.py\", line 57, in uri_put_file\r\npostgres_1  |     k.set_contents_from_file(fp, encrypt_key=True)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 1293, in set_contents_from_file\r\npostgres_1  |     chunked_transfer=chunked_transfer, size=size)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 750, in send_file\r\npostgres_1  |     chunked_transfer=chunked_transfer, size=size)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 951, in _send_file_internal\r\npostgres_1  |     query_args=query_args\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/connection.py\", line 668, in make_request\r\npostgres_1  |     retry_handler=retry_handler\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/connection.py\", line 1071, in make_request\r\npostgres_1  |     retry_handler=retry_handler)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/connection.py\", line 1030, in _mexe\r\npostgres_1  |     raise ex\r\npostgres_1  | SSLError: ('The read operation timed out',)\r\npostgres_1  | <Greenlet at 0x7f3233ffa7d0: <wal_e.worker.upload.WalUploader object at 0x7f3233d3f090>(<wal_e.worker.pg.wal_transfer.WalSegment object at)> failed with SSLError\r\npostgres_1  | \r\npostgres_1  | Traceback (most recent call last):\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/gevent/greenlet.py\", line 534, in run\r\npostgres_1  |     result = self._run(*self.args, **self.kwargs)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/worker/upload.py\", line 50, in __call__\r\npostgres_1  |     self.gpg_key_id)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/worker/worker_util.py\", line 40, in do_lzop_put\r\npostgres_1  |     k = blobstore.uri_put_file(creds, url, tf)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/blobstore/s3/s3_util.py\", line 57, in uri_put_file\r\npostgres_1  |     k.set_contents_from_file(fp, encrypt_key=True)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 1293, in set_contents_from_file\r\npostgres_1  |     chunked_transfer=chunked_transfer, size=size)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 750, in send_file\r\npostgres_1  |     chunked_transfer=chunked_transfer, size=size)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 951, in _send_file_internal\r\npostgres_1  |     query_args=query_args\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/connection.py\", line 668, in make_request\r\npostgres_1  |     retry_handler=retry_handler\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/connection.py\", line 1071, in make_request\r\npostgres_1  |     retry_handler=retry_handler)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/connection.py\", line 1030, in _mexe\r\npostgres_1  |     raise ex\r\npostgres_1  | SSLError: ('The read operation timed out',)\r\npostgres_1  | <Greenlet at 0x7f3233ffa4b0: <wal_e.worker.upload.WalUploader object at 0x7f3233d3f090>(<wal_e.worker.pg.wal_transfer.WalSegment object at)> failed with SSLError\r\npostgres_1  | \r\npostgres_1  | Traceback (most recent call last):\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/gevent/greenlet.py\", line 534, in run\r\npostgres_1  |     result = self._run(*self.args, **self.kwargs)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/worker/upload.py\", line 50, in __call__\r\npostgres_1  |     self.gpg_key_id)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/worker/worker_util.py\", line 40, in do_lzop_put\r\npostgres_1  |     k = blobstore.uri_put_file(creds, url, tf)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/blobstore/s3/s3_util.py\", line 57, in uri_put_file\r\npostgres_1  |     k.set_contents_from_file(fp, encrypt_key=True)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 1293, in set_contents_from_file\r\npostgres_1  |     chunked_transfer=chunked_transfer, size=size)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 750, in send_file\r\npostgres_1  |     chunked_transfer=chunked_transfer, size=size)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/key.py\", line 951, in _send_file_internal\r\npostgres_1  |     query_args=query_args\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/s3/connection.py\", line 668, in make_request\r\npostgres_1  |     retry_handler=retry_handler\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/connection.py\", line 1071, in make_request\r\npostgres_1  |     retry_handler=retry_handler)\r\npostgres_1  |   File \"/opt/wale/local/lib/python2.7/site-packages/boto/connection.py\", line 1030, in _mexe\r\npostgres_1  |     raise ex\r\npostgres_1  | SSLError: ('The read operation timed out',)\r\npostgres_1  | <Greenlet at 0x7f3233ffa550: <wal_e.worker.upload.WalUploader object at 0x7f3233d3f090>(<wal_e.worker.pg.wal_transfer.WalSegment object at)> failed with SSLError\r\npostgres_1  | \r\npostgres_1  | wal_e.main   CRITICAL MSG: An unprocessed exception has avoided all error handling\r\npostgres_1  |         DETAIL: Traceback (most recent call last):\r\npostgres_1  |           File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/cmd.py\", line 592, in main\r\npostgres_1  |             concurrency=args.pool_size)\r\npostgres_1  |           File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/operator/backup.py\", line 285, in wal_archive\r\npostgres_1  |             group.join()\r\npostgres_1  |           File \"/opt/wale/local/lib/python2.7/site-packages/wal_e/worker/pg/wal_transfer.py\", line 144, in join\r\npostgres_1  |             raise val\r\npostgres_1  |         SSLError: ('The read operation timed out',)\r\npostgres_1  |         \r\npostgres_1  |         STRUCTURED: time=2016-06-29T15:06:40.436707-00 pid=258\r\npostgres_1  | LOG:  archive command failed with exit code 2\r\n```\r\n\r\nThe SSL connection worked when I was restoring the backup, and it worked previously--there are backups present on the target S3 bucket.\r\n\r\nI had made a mistake and sent WAL logs from the wrong environment into my development backup bucket, and that's why I needed to do PITR. Would that have anything to do with these errors?\r\n\r\nHere are my config settings:\r\n\r\n```\r\nwal_level = hot_standby;\r\narchive_mode = on;\r\narchive_command = \"envdir /etc/wal-e.d/env /opt/wale/bin/wal-e wal-push %p\";\r\narchive_timeout = 60;\r\n```\r\n\r\nRunning on the postgres:9.4 docker image.\r\n\r\nThanks for any help you can offer."},"comment":{"url":"https://api.github.com/repos/wal-e/wal-e/issues/comments/232441371","html_url":"https://github.com/wal-e/wal-e/issues/256#issuecomment-232441371","issue_url":"https://api.github.com/repos/wal-e/wal-e/issues/256","id":232441371,"user":{"login":"fdr","id":7191,"avatar_url":"https://avatars.githubusercontent.com/u/7191?v=3","gravatar_id":"","url":"https://api.github.com/users/fdr","html_url":"https://github.com/fdr","followers_url":"https://api.github.com/users/fdr/followers","following_url":"https://api.github.com/users/fdr/following{/other_user}","gists_url":"https://api.github.com/users/fdr/gists{/gist_id}","starred_url":"https://api.github.com/users/fdr/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/fdr/subscriptions","organizations_url":"https://api.github.com/users/fdr/orgs","repos_url":"https://api.github.com/users/fdr/repos","events_url":"https://api.github.com/users/fdr/events{/privacy}","received_events_url":"https://api.github.com/users/fdr/received_events","type":"User","site_admin":false},"created_at":"2016-07-13T18:16:10Z","updated_at":"2016-07-13T18:16:10Z","body":"I've seen these kinds of errors for a number of reasons: high load, cross-region replication, newly created buckets, bad credentials. If you mentioned sending WAL from \"the wrong environment\", I'd suspect credentials."}}
{"actor":{"display_login":"fdr"}}