:PROPERTIES: :ID: d28b1f6c-0a13-4306-86e6-d959705d3867 :END: #+title: 2020-07-16 #+SETUPFILE: ../worklog.setup * Import evaluation issue Got an alert in [[id:ebea379a-8fa6-4e22-9275-a9fc98c02804][Pagerduty]] about [[file:projects/import.org][Import Evaluation]] message age. Saw some of this earlier, where it was getting =null= for its compromised addresses database URL. The configuration is correct in consul, so maybe this was a weird intermittent thing. #+begin_example {"name":"rejected.process","levelname":"ERROR","asctime":"2020-07-16T09:49:46.103741+0000","processName":"subscriber-import-evaluation-1","message":"Error creating the consumer \"subscriber_import_evaluation.consumer.Consumer\": pgsql_compromised_addresses: null is invalid - expected format: ^postgres(ql)?://.*","module":"process","correlation_id":"c20e024c-160c-45a1-9ea3-e3bb04d26413","exc_info":["Traceback (most recent call last):\n"," File \"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/consumer.py\", line 338, in validate_settings\n jsonschema.validate(settings, self.SETTINGS_SCHEMA)\n"," File \"/usr/local/lib/python3.7/site-packages/jsonschema/validators.py\", line 899, in validate\n raise error\n","jsonschema.exceptions.ValidationError: 'null' does not match '^postgres(ql)?://.*'\n\nFailed validating 'pattern' in schema['properties']['pgsql_compromised_addresses']:\n {'description': 'The RDS compromised addresses connection URI',\n 'pattern': '^postgres(ql)?://.*',\n 'type': 'string'}\n\nOn instance['pgsql_compromised_addresses']:\n 'null'\n","\nDuring handling of the above exception, another exception occurred:\n\n","Traceback (most recent call last):\n"," File \"/usr/local/lib/python3.7/site-packages/rejected/process.py\", line 455, in get_consumer\n return handle(**kwargs)\n"," File \"/usr/local/lib/python3.7/site-packages/avroconsumer.py\", line 25, in __init__\n super(Consumer, self).__init__(*args, **kwargs)\n"," File \"/usr/local/lib/python3.7/site-packages/rejected/consumer.py\", line 208, in __init__\n self.initialize()\n"," File \"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/consumer.py\", line 291, in initialize\n self.validate_settings(self.settings.dict())\n"," File \"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/consumer.py\", line 351, in validate_settings\n raise Exception(message)\n","Exception: pgsql_compromised_addresses: null is invalid - expected format: ^postgres(ql)?://.*\n"],"log":"{\"name\":\"rejected.process\",\"levelname\":\"ERROR\",\"asctime\":\"2020-07-16T09:49:46.103741+0000\",\"processName\":\"subscriber-import-evaluation-1\",\"message\":\"Error creating the consumer \\\"subscriber_import_evaluation.consumer.Consumer\\\": pgsql_compromised_addresses: null is invalid - expected format: ^postgres(ql)?://.*\",\"module\":\"process\",\"correlation_id\":\"c20e024c-160c-45a1-9ea3-e3bb04d26413\",\"exc_info\":[\"Traceback (most recent call last):\\n\",\" File \\\"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/consumer.py\\\", line 338, in validate_settings\\n jsonschema.validate(settings, self.SETTINGS_SCHEMA)\\n\",\" File \\\"/usr/local/lib/python3.7/site-packages/jsonschema/validators.py\\\", line 899, in validate\\n raise error\\n\",\"jsonschema.exceptions.ValidationError: 'null' does not match '^postgres(ql)?://.*'\\n\\nFailed validating 'pattern' in schema['properties']['pgsql_compromised_addresses']:\\n {'description': 'The RDS compromised addresses connection URI',\\n 'pattern': '^postgres(ql)?://.*',\\n 'type': 'string'}\\n\\nOn instance['pgsql_compromised_addresses']:\\n 'null'\\n\",\"\\nDuring handling of the above exception, another exception occurred:\\n\\n\",\"Traceback (most recent call last):\\n\",\" File \\\"/usr/local/lib/python3.7/site-packages/rejected/process.py\\\", line 455, in get_consumer\\n return handle(**kwargs)\\n\",\" File \\\"/usr/local/lib/python3.7/site-packages/avroconsumer.py\\\", line 25, in __init__\\n super(Consumer, self).__init__(*args, **kwargs)\\n\",\" File \\\"/usr/local/lib/python3.7/site-packages/rejected/consumer.py\\\", line 208, in __init__\\n self.initialize()\\n\",\" File \\\"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/consumer.py\\\", line 291, in initialize\\n self.validate_settings(self.settings.dict())\\n\",\" File \\\"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/consumer.py\\\", line 351, in validate_settings\\n raise Exception(message)\\n\",\"Exception: pgsql_compromised_addresses: null is invalid - expected format: ^postgres(ql)?://.*\\n\"]}\n","stream":"stdout","docker":{"container_id":"8cee26b83b012277ad0ee740e11b260e25baed5aff912264ae195b30ace5ab21"},"kubernetes":{"container_name":"subscriber-import-evaluation","namespace_name":"cp","pod_name":"subscriber-import-evaluation-6bdd96bdcd-jx4w9","pod_id":"4e098e40-bae8-11ea-9f30-6a3b5e3f247e","labels":{"app":"subscriber-import-evaluation","component":"application","pod-template-hash":"2688526878","version":"e142756"},"host":"kube01-w02.testing.aweberint.com","master_url":"https://10.50.0.1:443/api"},"timestamp":"2020-07-16T09:49:46+00:00"} #+end_example Here, though, we've got a message repeatedly being requeued due to a list lookup failure. #+begin_example {"name":"subscriber_import_evaluation.consumer","levelname":"DEBUG","asctime":"2020-07-16T12:54:18.250984+0000","processName":"subscriber-import-evaluation-1","message":"Returning {'account': '62949269-3df5-46d9-b883-74e7771504f2', 'import_uuid': 'f4cd8ddc-95c3-445d-afbe-386e93a29854', 'legacy_account_id': 1326226, 'legacy_list_id': 5202426, 'list': 'ce641169-a75d-45bc-bc48-ef8a8bda31c8', 'timestamp': '2020-07-16T09:36:37.989035+00:00', 'acquisition_method': 'Acquisition method: \"other\"\\nProvider: Did not bring from another provider\\nDescribe how you got this list of subscribers\\nIam exporting and re-importing and merging my lists.', 'automation_enabled': True, 'coi_enabled': False, 'column_mapping': {'email': 0, 'name': 1, 'note': 8, 'tags': 19}, 'existing_subscriber_action': 'Ignore', 'remote_ip': '110.144.41.250', 'tags': [], 'message_number': None}","module":"avroconsumer","correlation_id":"43b4305c-02fa-4e5a-aba1-e7db9c4bb926","exc_info":null} {"name":"subscriber_import_evaluation.consumer","levelname":"WARNING","asctime":"2020-07-16T12:54:18.268914+0000","processName":"subscriber-import-evaluation-1","message":"get_list: GET request to http://list.service.production.consul/v1/accounts/1326226/lists/5202426 failed with message: HTTP 404: ListNotFound","module":"services","correlation_id":"43b4305c-02fa-4e5a-aba1-e7db9c4bb926","exc_info":null} {"name":"subscriber_import_evaluation.consumer","levelname":"ERROR","asctime":"2020-07-16T12:54:18.269250+0000","processName":"subscriber-import-evaluation-1","message":"Exception processing delivery 1: HTTP 404: ListNotFound","module":"consumer","correlation_id":"43b4305c-02fa-4e5a-aba1-e7db9c4bb926","exc_info":null} {"name":"subscriber_import_evaluation.consumer","levelname":"ERROR","asctime":"2020-07-16T12:54:18.269401+0000","processName":"subscriber-import-evaluation-1","message":"Processor handled HTTPClientError: HTTP 404: ListNotFound","module":"consumer","correlation_id":"43b4305c-02fa-4e5a-aba1-e7db9c4bb926","exc_info":["Traceback (most recent call last):\n"," File \"/usr/local/lib/python3.7/site-packages/rejected/consumer.py\", line 908, in execute\n yield result\n"," File \"/usr/local/lib/python3.7/site-packages/tornado/gen.py\", line 735, in run\n value = future.result()\n"," File \"/usr/local/lib/python3.7/site-packages/tornado/gen.py\", line 742, in run\n yielded = self.gen.throw(*exc_info) # type: ignore\n"," File \"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/consumer.py\", line 734, in process\n fields=[\"coi_bitmap\"],\n"," File \"/usr/local/lib/python3.7/site-packages/tornado/gen.py\", line 735, in run\n value = future.result()\n"," File \"/usr/local/lib/python3.7/site-packages/tornado/gen.py\", line 742, in run\n yielded = self.gen.throw(*exc_info) # type: ignore\n"," File \"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/services.py\", line 113, in get_list\n error_reason='Unable to fetch list')\n"," File \"/usr/local/lib/python3.7/site-packages/tornado/gen.py\", line 735, in run\n value = future.result()\n"," File \"/usr/local/lib/python3.7/site-packages/tornado/gen.py\", line 742, in run\n yielded = self.gen.throw(*exc_info) # type: ignore\n"," File \"/usr/local/lib/python3.7/site-packages/subscriber_import_evaluation/services.py\", line 65, in _http_fetch\n request_timeout=request_timeout, **kwargs)\n"," File \"/usr/local/lib/python3.7/site-packages/tornado/gen.py\", line 735, in run\n value = future.result()\n","tornado.httpclient.HTTPClientError: HTTP 404: ListNotFound\n"]} {"name":"rejected.process","levelname":"WARNING","asctime":"2020-07-16T12:54:18.281276+0000","processName":"subscriber-import-evaluation-1","message":"Rejecting message 1 with requeue","module":"process","correlation_id":"7a3a8390-10de-40ef-96be-100e8fa98596","exc_info":null} {"name":"rejected.process","levelname":"INFO","asctime":"2020-07-16T12:54:18.281544+0000","processName":"subscriber-import-evaluation-1","message":"Resetting failure window, 1594904058 seconds since last","module":"process","correlation_id":"01ab189d-9c3e-4fb1-830b-eec0049dc434","exc_info":null} #+end_example The lookup fails with the account in the path, but succeeds without it? #+begin_src http :pretty :exports both GET http://list.service.production.consul/v1/accounts/1326226/lists/5202426 #+end_src #+RESULTS[612dcf937d3cdea3381ed3836f7cedfdd3c23a3e]: : { : "error": { : "status_code": 404, : "exception": "ListNotFound", : "message": "List with given id not found" : } : } #+begin_src http :pretty :exports both GET http://list.service.production.consul/v1/lists/5202426 #+end_src #+RESULTS[67a16238d6aad00f1a7abc4a59736d3ed4f5aea4]: #+begin_example { "friendly_list_name": "15 minute manifestation.", "address_id": 779131, "coi_confirmation_text": "", "sender_name": "Geoff Stevens", "coi_subject_text": "Response Required: Please confirm your request for information.\n", "coi_button_text": "Confirm my subscription", "contact_address": "Palmer Rd\nPortland vic 3305\nAUSTRALIA", "list_name": "awlist5202426", "custom_fields": {}, "coi_closing": "", "city": "Portland", "country_id": 13, "zipcode": "3305", "locale": "en-US", "state": "vic", "list_description": "0000000", "coi_subject_id": 6, "company_name": "Geoff Stevenson", "contact_emails": [ { "reply": 1, "confirmation": 0, "email": "gst1965@bigpond.com", "name": "Geoff Stevens" } ], "list_id": 5202426, "country_name": "AUSTRALIA", "account_id": 1326226, "address1": "Palmer Rd", "address2": null, "company_website": "", "coi_bitmap": 10, "confirmation_button_text_id": 1, "sender_email": "gst1965@bigpond.com", "signature": null } #+end_example Popped the offending message off the queue: Properties: #+begin_example app_id: subscriberimportapi/3.0.11 type: import_requested.v1 timestamp: 1594892197 message_id: e4b0e88c-d90c-4d1f-bf22-863ca6a140a7 correlation_id: 43b4305c-02fa-4e5a-aba1-e7db9c4bb926 headers: account_id: 62949269-3df5-46d9-b883-74e7771504f2 x-shovelled: dest-exchange: events dest-uri: amqp://rabbitmq.aweberprod.com:5672/%2f shovel-name: rabbitmq-events shovel-type: dynamic shovel-vhost: / shovelled-by: production src-queue: rabbitmq-events src-uri: amqp:// content_type: application/vnd.apache.avro.datum #+end_example Payload: #+begin_example SDYyOTQ5MjY5LTNkZjUtNDZkOS1iODgzLTc0ZTc3NzE1MDRmMkhmNGNkOGRkYy05NWMzLTQ0NWQtYWZiZS0zODZlOTNhMjk4NTSk8qEB9If7BEhjZTY0MTE2 OS1hNzVkLTQ1YmMtYmM0OC1lZjhhOGJkYTMxYzhAMjAyMC0wNy0xNlQwOTozNjozNy45ODkwMzUrMDA6MDDYAkFjcXVpc2l0aW9uIG1ldGhvZDogIm90aGVy IgpQcm92aWRlcjogRGlkIG5vdCBicmluZyBmcm9tIGFub3RoZXIgcHJvdmlkZXIKRGVzY3JpYmUgaG93IHlvdSBnb3QgdGhpcyBsaXN0IG9mIHN1YnNjcmli ZXJzCklhbSBleHBvcnRpbmcgYW5kIHJlLWltcG9ydGluZyBhbmQgbWVyZ2luZyBteSBsaXN0cy4BAAgKZW1haWwACG5hbWUCCG5vdGUQCHRhZ3MmAAAcMTEw LjE0NC40MS4yNTAAAA== #+end_example There seem to be more messages failing the same way, it'd probably be faster to just make a code change to drop messages on 4XX errors. * Login and Landing pages #+begin_example # Send logged in customers to /users RewriteCond %{HTTP:Cookie} (^|;\ *)loggedIn=1 [NC] RewriteRule ^/(landing|login).htm$ /users [L,R=302] #+end_example =loginAjax= only appears to be hit from the landing/login pages: #+begin_example root@web-controlpanel1:/home/aweber/logs# grep loginAjax httpd/access_log |cut -d ' ' -f 14|cut -d '?' -f 1|sed 's/"//g'|sort|uniq -c 9 - 2244 https://www.aweber.com/landing.htm 500 https://www.aweber.com/login.htm #+end_example