Logger Output From Deis Database

deis-database.log

2016-10-26T19:04:32.907006343Z         STRUCTURED: time=2016-10-26T19:04:32.906835-00 pid=141
2016-10-26T19:04:33.415860651Z wal_e.worker.upload INFO     MSG: begin uploading a base backup volume
2016-10-26T19:04:33.415886451Z         DETAIL: Uploading to "s3://dbwal/basebackups_005/base_000000010000000000000002_00000040/tar_partitions/part_00000000.tar.lzo".
2016-10-26T19:04:33.415890951Z         STRUCTURED: time=2016-10-26T19:04:33.415552-00 pid=141
2016-10-26T19:04:33.516551450Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:04:33.516565150Z         STRUCTURED: time=2016-10-26T19:04:33.516342-00 pid=141
2016-10-26T19:04:33.526507057Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <open file '<fdopen>', mode 'r+b' at 0x7f5c3c7c85d0>, u'Bucket': 'dbwal', 'Key': 'basebackups_005/base_000000010000000000000002_00000040/tar_partitions/part_00000000.tar.lzo'}
2016-10-26T19:04:33.555623664Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:04:33.630768331Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'basebackups_005/base_000000010000000000000002_00000040/tar_partitions/part_00000000.tar.lzo'}
2016-10-26T19:04:33.636913159Z wal_e.worker.upload INFO     MSG: finish uploading a base backup volume
2016-10-26T19:04:33.636926559Z         DETAIL: Uploading to "s3://dbwal/basebackups_005/base_000000010000000000000002_00000040/tar_partitions/part_00000000.tar.lzo" complete at 21792.8KiB/s. 
2016-10-26T19:04:33.636930859Z         STRUCTURED: time=2016-10-26T19:04:33.636770-00 pid=141
2016-10-26T19:04:34.225601831Z wal_e.main   INFO     MSG: starting WAL-E
2016-10-26T19:04:34.225627032Z         DETAIL: The subcommand is "wal-push".
2016-10-26T19:04:34.225631332Z         STRUCTURED: time=2016-10-26T19:04:34.225386-00 pid=181
2016-10-26T19:04:34.295707393Z wal_e.worker.upload INFO     MSG: begin archiving a file
2016-10-26T19:04:34.295728693Z         DETAIL: Uploading "pg_xlog/000000010000000000000002.00000028.backup" to "s3://dbwal/wal_005/000000010000000000000002.00000028.backup.lzo".
2016-10-26T19:04:34.295733393Z         STRUCTURED: time=2016-10-26T19:04:34.295411-00 pid=181 action=push-wal key=s3://dbwal/wal_005/000000010000000000000002.00000028.backup.lzo prefix= seg=000000010000000000000002.00000028.backup state=begin
2016-10-26T19:04:34.307789145Z wal_e.worker.upload INFO     MSG: begin archiving a file
2016-10-26T19:04:34.307805545Z         DETAIL: Uploading "pg_xlog/000000010000000000000002" to "s3://dbwal/wal_005/000000010000000000000002.lzo".
2016-10-26T19:04:34.307810545Z         STRUCTURED: time=2016-10-26T19:04:34.307499-00 pid=181 action=push-wal key=s3://dbwal/wal_005/000000010000000000000002.lzo prefix= seg=000000010000000000000002 state=begin
2016-10-26T19:04:34.408079135Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:04:34.408102036Z         STRUCTURED: time=2016-10-26T19:04:34.407751-00 pid=181
2016-10-26T19:04:34.419724878Z botocore.credentials INFO     Found credentials in environment variables.
2016-10-26T19:04:34.468638598Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <open file '<fdopen>', mode 'r+b' at 0x7fab22d22c90>, u'Bucket': 'dbwal', 'Key': 'wal_005/000000010000000000000002.00000028.backup.lzo'}
2016-10-26T19:04:34.473876907Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:04:34.475231135Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:04:34.475253036Z         STRUCTURED: time=2016-10-26T19:04:34.475140-00 pid=181
2016-10-26T19:04:34.480221939Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <open file '<fdopen>', mode 'r+b' at 0x7fab22d22d20>, u'Bucket': 'dbwal', 'Key': 'wal_005/000000010000000000000002.lzo'}
2016-10-26T19:04:34.483515108Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:04:34.500805368Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'wal_005/000000010000000000000002.00000028.backup.lzo'}
2016-10-26T19:04:34.508478328Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'wal_005/000000010000000000000002.lzo'}
2016-10-26T19:04:34.512489812Z wal_e.worker.upload INFO     MSG: completed archiving to a file
2016-10-26T19:04:34.512501512Z         DETAIL: Archiving to "s3://dbwal/wal_005/000000010000000000000002.00000028.backup.lzo" complete at 00KiB/s.
2016-10-26T19:04:34.512506212Z         STRUCTURED: time=2016-10-26T19:04:34.512362-00 pid=181 action=push-wal key=s3://dbwal/wal_005/000000010000000000000002.00000028.backup.lzo prefix= rate=00 seg=000000010000000000000002.00000028.backup state=complete
2016-10-26T19:04:34.514670357Z wal_e.worker.upload INFO     MSG: completed archiving to a file
2016-10-26T19:04:34.514681858Z         DETAIL: Archiving to "s3://dbwal/wal_005/000000010000000000000002.lzo" complete at 2186.8KiB/s.
2016-10-26T19:04:34.514686258Z         STRUCTURED: time=2016-10-26T19:04:34.514517-00 pid=181 action=push-wal key=s3://dbwal/wal_005/000000010000000000000002.lzo prefix= rate=2186.8 seg=000000010000000000000002 state=complete
2016-10-26T19:04:34.956421967Z NOTICE:  pg_stop_backup complete, all required WAL segments have been archived
2016-10-26T19:04:34.958025200Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:04:34.958036000Z         STRUCTURED: time=2016-10-26T19:04:34.957672-00 pid=141
2016-10-26T19:04:34.983058322Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <cStringIO.StringO object at 0x7f5c3a803928>, u'Bucket': 'dbwal', 'Key': 'basebackups_005/base_000000010000000000000002_00000040_backup_stop_sentinel.json'}
2016-10-26T19:04:34.985443172Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:04:34.993542140Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'basebackups_005/base_000000010000000000000002_00000040_backup_stop_sentinel.json'}
2016-10-26T19:04:35.026665631Z 
2016-10-26T19:04:35.026742232Z /docker-entrypoint.sh: running /docker-entrypoint-initdb.d/004_run_backups.sh
2016-10-26T19:04:35.026945637Z 
2016-10-26T19:04:35.033974183Z LOG:  received fast shutdown request
2016-10-26T19:04:35.033999884Z LOG:  aborting any active transactions
2016-10-26T19:04:35.034030384Z LOG:  autovacuum launcher shutting down
2016-10-26T19:04:35.036166529Z waiting for server to shut down....LOG:  shutting down
2016-10-26T19:04:35.464910867Z LOG:  database system is shut down
2016-10-26T19:04:36.036674486Z  done
2016-10-26T19:04:36.036698787Z server stopped
2016-10-26T19:04:36.041494687Z 
2016-10-26T19:04:36.041520987Z PostgreSQL init process complete; ready for start up.
2016-10-26T19:04:36.041525687Z 
2016-10-26T19:04:36.092941159Z LOG:  database system was shut down at 2016-10-26 19:04:35 UTC
2016-10-26T19:04:36.101626140Z LOG:  MultiXact member wraparound protections are now enabled
2016-10-26T19:04:36.103740384Z LOG:  autovacuum launcher started
2016-10-26T19:04:36.103928888Z LOG:  database system is ready to accept connections
2016-10-26T19:05:36.888766093Z wal_e.main   INFO     MSG: starting WAL-E
2016-10-26T19:05:36.888800094Z         DETAIL: The subcommand is "wal-push".
2016-10-26T19:05:36.888804894Z         STRUCTURED: time=2016-10-26T19:05:36.888540-00 pid=275
2016-10-26T19:05:36.977665645Z wal_e.worker.upload INFO     MSG: begin archiving a file
2016-10-26T19:05:36.977700246Z         DETAIL: Uploading "pg_xlog/000000010000000000000003" to "s3://dbwal/wal_005/000000010000000000000003.lzo".
2016-10-26T19:05:36.977705346Z         STRUCTURED: time=2016-10-26T19:05:36.977375-00 pid=275 action=push-wal key=s3://dbwal/wal_005/000000010000000000000003.lzo prefix= seg=000000010000000000000003 state=begin
2016-10-26T19:05:37.090855504Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:05:37.090876504Z         STRUCTURED: time=2016-10-26T19:05:37.090587-00 pid=275
2016-10-26T19:05:37.104800594Z botocore.credentials INFO     Found credentials in environment variables.
2016-10-26T19:05:37.157112684Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <open file '<fdopen>', mode 'r+b' at 0x7f15ea87dc90>, u'Bucket': 'dbwal', 'Key': 'wal_005/000000010000000000000003.lzo'}
2016-10-26T19:05:37.162894305Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:05:37.174339243Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'wal_005/000000010000000000000003.lzo'}
2016-10-26T19:05:37.178807836Z wal_e.worker.upload INFO     MSG: completed archiving to a file
2016-10-26T19:05:37.178821036Z         DETAIL: Archiving to "s3://dbwal/wal_005/000000010000000000000003.lzo" complete at 976.574KiB/s.
2016-10-26T19:05:37.178831937Z         STRUCTURED: time=2016-10-26T19:05:37.178658-00 pid=275 action=push-wal key=s3://dbwal/wal_005/000000010000000000000003.lzo prefix= rate=976.574 seg=000000010000000000000003 state=complete
2016-10-26T19:09:37.510222618Z wal_e.main   INFO     MSG: starting WAL-E
2016-10-26T19:09:37.510251019Z         DETAIL: The subcommand is "wal-push".
2016-10-26T19:09:37.510255419Z         STRUCTURED: time=2016-10-26T19:09:37.509992-00 pid=499
2016-10-26T19:09:37.598276550Z wal_e.worker.upload INFO     MSG: begin archiving a file
2016-10-26T19:09:37.598307850Z         DETAIL: Uploading "pg_xlog/000000010000000000000004" to "s3://dbwal/wal_005/000000010000000000000004.lzo".
2016-10-26T19:09:37.598313350Z         STRUCTURED: time=2016-10-26T19:09:37.597914-00 pid=499 action=push-wal key=s3://dbwal/wal_005/000000010000000000000004.lzo prefix= seg=000000010000000000000004 state=begin
2016-10-26T19:09:37.713711151Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:09:37.713733551Z         STRUCTURED: time=2016-10-26T19:09:37.713352-00 pid=499
2016-10-26T19:09:37.725004786Z botocore.credentials INFO     Found credentials in environment variables.
2016-10-26T19:09:37.775547537Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <open file '<fdopen>', mode 'r+b' at 0x7f8758841c90>, u'Bucket': 'dbwal', 'Key': 'wal_005/000000010000000000000004.lzo'}
2016-10-26T19:09:37.780580042Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:09:37.795195846Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'wal_005/000000010000000000000004.lzo'}
2016-10-26T19:09:37.800069147Z wal_e.worker.upload INFO     MSG: completed archiving to a file
2016-10-26T19:05:36.888766093Z wal_e.main   INFO     MSG: starting WAL-E
2016-10-26T19:05:36.888800094Z         DETAIL: The subcommand is "wal-push".
2016-10-26T19:05:36.888804894Z         STRUCTURED: time=2016-10-26T19:05:36.888540-00 pid=275
2016-10-26T19:05:36.977665645Z wal_e.worker.upload INFO     MSG: begin archiving a file
2016-10-26T19:05:36.977700246Z         DETAIL: Uploading "pg_xlog/000000010000000000000003" to "s3://dbwal/wal_005/000000010000000000000003.lzo".
2016-10-26T19:05:36.977705346Z         STRUCTURED: time=2016-10-26T19:05:36.977375-00 pid=275 action=push-wal key=s3://dbwal/wal_005/000000010000000000000003.lzo prefix= seg=000000010000000000000003 state=begin
2016-10-26T19:05:37.090855504Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:05:37.090876504Z         STRUCTURED: time=2016-10-26T19:05:37.090587-00 pid=275
2016-10-26T19:05:37.104800594Z botocore.credentials INFO     Found credentials in environment variables.
2016-10-26T19:05:37.157112684Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <open file '<fdopen>', mode 'r+b' at 0x7f15ea87dc90>, u'Bucket': 'dbwal', 'Key': 'wal_005/000000010000000000000003.lzo'}
2016-10-26T19:05:37.162894305Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:05:37.174339243Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'wal_005/000000010000000000000003.lzo'}
2016-10-26T19:05:37.178807836Z wal_e.worker.upload INFO     MSG: completed archiving to a file
2016-10-26T19:05:37.178821036Z         DETAIL: Archiving to "s3://dbwal/wal_005/000000010000000000000003.lzo" complete at 976.574KiB/s.
2016-10-26T19:05:37.178831937Z         STRUCTURED: time=2016-10-26T19:05:37.178658-00 pid=275 action=push-wal key=s3://dbwal/wal_005/000000010000000000000003.lzo prefix= rate=976.574 seg=000000010000000000000003 state=complete
2016-10-26T19:09:37.510222618Z wal_e.main   INFO     MSG: starting WAL-E
2016-10-26T19:09:37.510251019Z         DETAIL: The subcommand is "wal-push".
2016-10-26T19:09:37.510255419Z         STRUCTURED: time=2016-10-26T19:09:37.509992-00 pid=499
2016-10-26T19:09:37.598276550Z wal_e.worker.upload INFO     MSG: begin archiving a file
2016-10-26T19:09:37.598307850Z         DETAIL: Uploading "pg_xlog/000000010000000000000004" to "s3://dbwal/wal_005/000000010000000000000004.lzo".
2016-10-26T19:09:37.598313350Z         STRUCTURED: time=2016-10-26T19:09:37.597914-00 pid=499 action=push-wal key=s3://dbwal/wal_005/000000010000000000000004.lzo prefix= seg=000000010000000000000004 state=begin
2016-10-26T19:09:37.713711151Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:09:37.713733551Z         STRUCTURED: time=2016-10-26T19:09:37.713352-00 pid=499
2016-10-26T19:09:37.725004786Z botocore.credentials INFO     Found credentials in environment variables.
2016-10-26T19:09:37.775547537Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <open file '<fdopen>', mode 'r+b' at 0x7f8758841c90>, u'Bucket': 'dbwal', 'Key': 'wal_005/000000010000000000000004.lzo'}
2016-10-26T19:09:37.780580042Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:09:37.795195846Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'wal_005/000000010000000000000004.lzo'}
2016-10-26T19:09:37.800069147Z wal_e.worker.upload INFO     MSG: completed archiving to a file
2016-10-26T19:09:37.800082548Z         DETAIL: Archiving to "s3://dbwal/wal_005/000000010000000000000004.lzo" complete at 993.944KiB/s.
2016-10-26T19:09:37.800087548Z         STRUCTURED: time=2016-10-26T19:09:37.799864-00 pid=499 action=push-wal key=s3://dbwal/wal_005/000000010000000000000004.lzo prefix= rate=993.944 seg=000000010000000000000004 state=complete
2016-10-26T19:14:38.036882072Z wal_e.main   INFO     MSG: starting WAL-E
2016-10-26T19:14:38.036912173Z         DETAIL: The subcommand is "wal-push".
2016-10-26T19:14:38.036916573Z         STRUCTURED: time=2016-10-26T19:14:38.036659-00 pid=773
2016-10-26T19:14:38.107590442Z wal_e.worker.upload INFO     MSG: begin archiving a file
2016-10-26T19:14:38.107613042Z         DETAIL: Uploading "pg_xlog/000000010000000000000005" to "s3://dbwal/wal_005/000000010000000000000005.lzo".
2016-10-26T19:14:38.107625242Z         STRUCTURED: time=2016-10-26T19:14:38.107282-00 pid=773 action=push-wal key=s3://dbwal/wal_005/000000010000000000000005.lzo prefix= seg=000000010000000000000005 state=begin
2016-10-26T19:14:38.223253245Z wal_e.blobstore.s3.calling_format INFO     MSG: connecting to S3 with WALE_S3_ENDPOINT (http://10.0.129.163:9000)
2016-10-26T19:14:38.223280145Z         STRUCTURED: time=2016-10-26T19:14:38.222890-00 pid=773
2016-10-26T19:14:38.246332224Z botocore.credentials INFO     Found credentials in environment variables.
2016-10-26T19:14:38.293591106Z boto3.resources.action INFO     Calling s3:put_object with {'Body': <open file '<fdopen>', mode 'r+b' at 0x7fcd36110c90>, u'Bucket': 'dbwal', 'Key': 'wal_005/000000010000000000000005.lzo'}
2016-10-26T19:14:38.298226003Z botocore.vendored.requests.packages.urllib3.connectionpool INFO     Starting new HTTP connection (1): 10.0.129.163
2016-10-26T19:14:38.309934046Z boto3.resources.action INFO     Calling s3:head_object with {u'Bucket': 'dbwal', u'Key': 'wal_005/000000010000000000000005.lzo'}
2016-10-26T19:14:38.314185934Z wal_e.worker.upload INFO     MSG: completed archiving to a file
2016-10-26T19:14:38.314199034Z         DETAIL: Archiving to "s3://dbwal/wal_005/000000010000000000000005.lzo" complete at 943.729KiB/s.
2016-10-26T19:14:38.314203935Z         STRUCTURED: time=2016-10-26T19:14:38.313999-00 pid=773 action=push-wal key=s3://dbwal/wal_005/000000010000000000000005.lzo prefix= rate=943.729 seg=000000010000000000000005 state=complete
2016-10-26T19:18:48.684101911Z ERROR:  relation "authtoken_token" does not exist at character 363
2016-10-26T19:18:48.684131211Z STATEMENT:  SELECT "authtoken_token"."key", "authtoken_token"."user_id", "authtoken_token"."created", "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "authtoken_token" INNER JOIN "auth_user" ON ("authtoken_token"."user_id" = "auth_user"."id") WHERE "authtoken_token"."key" = 'd58d2323c0eb1118bbe5f838bb296abe369a9a19'
2016-10-26T19:18:54.773779467Z ERROR:  relation "authtoken_token" does not exist at character 363
2016-10-26T19:18:54.773808367Z STATEMENT:  SELECT "authtoken_token"."key", "authtoken_token"."user_id", "authtoken_token"."created", "auth_user"."id", "auth_user"."password", "auth_user"."last_login", "auth_user"."is_superuser", "auth_user"."username", "auth_user"."first_name", "auth_user"."last_name", "auth_user"."email", "auth_user"."is_staff", "auth_user"."is_active", "auth_user"."date_joined" FROM "authtoken_token" INNER JOIN "auth_user" ON ("authtoken_token"."user_id" = "auth_user"."id") WHERE "authtoken_token"."key" = 'd58d2323c0eb1118bbe5f838bb296abe369a9a19'