search

cloudfoundry / notifications

The notifications service component of Cloud Foundry
Apache License 2.0
17 stars 22 forks source link

Emails fail to be send intermittently #29

Closed gabrielecipriano closed 5 years ago

gabrielecipriano commented 5 years ago

Summary When using notification service to deliver emails in a CF space (calling /space/<spaceID> endpoint) most of the time the emails fail to be delivered.

Expected behaviour Every time the space endpoint is called, each user of the space should receive an email.

Actual behaviour Most of the time the space endpoint is called emails are not delivered to any of the user.

Notes We are consuming the notification app as part of the v57 of notifications-release. It is pushed via the errand deploy-notification.

Steps to reproduce

  1. Deploy notifications app via the notifications-release.
  2. Post a request to /space/<spaceID>.
  3. See the request return 200 OK with status queued for each email in the space.
  4. See the message is added in table messages in DB notifications.
  5. Check for the email in the SMTP server - it doesn't appear.

Manifest properties

properties:
  domain: ((system_domain))
  notifications:
    app_domain: ((system_domain))
    cf:
      admin_password: ((password))
      admin_user: ((username))
    database:
      max_open_connections: 10
      url: ((mysqlserver))
    default_template: ""
    enable_diego: true
    encryption_key: ((encryption_key))
    error_on_misconfiguration: true
    instance_count: 1
    network: notifications
    organization: system
    sender: pcf-services-enablement@pivotal.io
    smtp:
      auth_mechanism: none
      host: ((mailhog.ip))
      port: ((mailhog.port))
      tls: false
    space: notifications-service
    syslog_url: ""
    tests:
      performance: true
    uaa:
      admin_client_id: admin
      admin_client_secret: ((uaa_admin_client_secret))
      client_id: notifications-admin
      client_secret: ((uaa_client_secret))
  ssl:
    skip_cert_verify: true

Logs When the email is delivered

    2019-06-14T15:28:52.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522532.578694105","source":"notifications","message":"notifications.request.incoming","log_level":1,"data":{"method":"POST","path":"/spaces/93e59aff-d85b-4376-a841-e47a236e664a","session":"5","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:52.58+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522532.579658985","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `clients` WHERE `id` = ? [1:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:52.76+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522532.763361931","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:52.94+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522532.948528290","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `clients` WHERE `id` = ? [1:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:53.13+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522533.133749962","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"update `clients` set `id`=?, `description`=?, `created_at`=?, `template_id`=? where `primary`=?; [1:\"notifications-admin\" 2:\"\" 3:2017-07-13 14:17:56 +0000 UTC 4:\"default\" 5:1]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:53.32+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522533.320902348","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `clients` WHERE `id` = ? [1:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:53.50+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522533.506204128","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:53.69+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522533.691544294","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:53.87+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522533.875744581","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"update `kinds` set `id`=?, `description`=?, `critical`=?, `client_id`=?, `created_at`=?, `updated_at`=?, `template_id`=? where `primary`=?; [1:\"service-alerts\" 2:\"\" 3:false 4:\"notifications-admin\" 5:2017-07-13 14:17:57 +0000 UTC 6:2019-06-14 14:28:53 +0000 UTC 7:\"default\" 8:2]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:54.06+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522534.062998533","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:54.15+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522534.156338692","source":"notifications","message":"notifications.uaa.token.validator.loading.keys","log_level":1,"data":{"session":"2"}}
   2019-06-14T15:28:54.16+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522534.167309761","source":"notifications","message":"notifications.uaa.token.validator.loaded.keys","log_level":1,"data":{"keys":["key-1"],"session":"2"}}
   2019-06-14T15:28:54.41+0100 [APP/PROC/WEB/0] ERR 2019/06/14 14:28:54 Warning: Automatic mapping of Version struct members to version columns (see optimistic locking) will be deprecated in next version (V2) See: https://github.com/go-gorp/gorp/pull/214
   2019-06-14T15:28:54.41+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522534.412055731","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"begin; []","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:54.50+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522534.504502535","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `messages` WHERE `id`=? [1:\"\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:54.69+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522534.690114737","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"insert into `messages` (`id`,`status`,`updated_at`) values (?,?,?); [1:\"f84ad061-960a-cbd3-930d-50895f8ce64d\" 2:\"queued\" 3:2019-06-14 14:28:54 +0000 UTC]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:54.87+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522534.875195503","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"insert into `jobs` (`id`,`worker_id`,`payload`,`version`,`retry_count`,`active_at`) values (null,?,?,?,?,?); [1:\"\" 2:\"{\\\"MessageID\\\":\\\"f84ad061-960a-cbd3-930d-50895f8ce64d\\\",\\\"Options\\\":{\\\"ReplyTo\\\":\\\"some-reply-to-email@example.com\\\",\\\"Subject\\\":\\\"[Service Alert][Iteration 19 ] b9321be3-6316-435b-a529-7d52868755a0\\\",\\\"KindDescription\\\":\\\"\\\",\\\"SourceDescription\\\":\\\"\\\",\\\"Text\\\":\\\"Alert from some-product, service instance some-service-instance-b083d68c: some-content \\\\n\\\\n\\\\n[Alert generated at 2019-06-11T16:39:47+01:00]\\\",\\\"HTML\\\":{\\\"BodyContent\\\":\\\"\\\",\\\"BodyAttributes\\\":\\\"\\\",\\\"Head\\\":\\\"\\\",\\\"Doctype\\\":\\\"\\\"},\\\"KindID\\\":\\\"service-alerts\\\",\\\"To\\\":\\\"\\\",\\\"Role\\\":\\\"\\\",\\\"Endorsement\\\":\\\"You received this message because you belong to the \\\\\\\"{{.Space}}\\\\\\\" space in the \\\\\\\"{{.Organization}}\\\\\\\" organization.\\\",\\\"TemplateID\\\":\\\"\\\"},\\\"UserGUID\\\":\\\"d144f1f9-7b5a-4263-a378-21cc95853551\\\",\\\"Email\\\":\\\"\\\",\\\"Space\\\":{\\\"GUID\\\":\\\"93e59aff-d85b-4376-a841-e47a236e664a\\\",\\\"Name\\\":\\\"test-notification\\\",\\\"OrganizationGUID\\\":\\\"8396fb2e-e7a7-4077-8e7d-e19a7cbecc1d\\\"},\\\"Organization\\\":{\\\"GUID\\\":\\\"8396fb2e-e7a7-4077-8e7d-e19a7cbecc1d\\\",\\\"Name\\\":\\\"test-notification\\\"},\\\"ClientID\\\":\\\"notifications-admin\\\",\\\"UAAHost\\\":\\\"https://uaa.alabaster-cloak.services-enablement.cf-app.com\\\",\\\"Scope\\\":\\\"\\\",\\\"VCAPRequestID\\\":\\\"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2\\\",\\\"RequestReceived\\\":\\\"2019-06-14T14:28:52.578843931Z\\\"}\" 3:1 4:0 5:2019-06-14 14:28:54.875080458 +0000 UTC m=+242.114089090]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:55.06+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522535.060013056","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `messages` WHERE `id`=? [1:\"\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:55.24+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522535.245094299","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"insert into `messages` (`id`,`status`,`updated_at`) values (?,?,?); [1:\"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6\" 2:\"queued\" 3:2019-06-14 14:28:55 +0000 UTC]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:55.43+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522535.430375338","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"insert into `jobs` (`id`,`worker_id`,`payload`,`version`,`retry_count`,`active_at`) values (null,?,?,?,?,?); [1:\"\" 2:\"{\\\"MessageID\\\":\\\"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6\\\",\\\"Options\\\":{\\\"ReplyTo\\\":\\\"some-reply-to-email@example.com\\\",\\\"Subject\\\":\\\"[Service Alert][Iteration 19 ] b9321be3-6316-435b-a529-7d52868755a0\\\",\\\"KindDescription\\\":\\\"\\\",\\\"SourceDescription\\\":\\\"\\\",\\\"Text\\\":\\\"Alert from some-product, service instance some-service-instance-b083d68c: some-content \\\\n\\\\n\\\\n[Alert generated at 2019-06-11T16:39:47+01:00]\\\",\\\"HTML\\\":{\\\"BodyContent\\\":\\\"\\\",\\\"BodyAttributes\\\":\\\"\\\",\\\"Head\\\":\\\"\\\",\\\"Doctype\\\":\\\"\\\"},\\\"KindID\\\":\\\"service-alerts\\\",\\\"To\\\":\\\"\\\",\\\"Role\\\":\\\"\\\",\\\"Endorsement\\\":\\\"You received this message because you belong to the \\\\\\\"{{.Space}}\\\\\\\" space in the \\\\\\\"{{.Organization}}\\\\\\\" organization.\\\",\\\"TemplateID\\\":\\\"\\\"},\\\"UserGUID\\\":\\\"1663856f-b286-4c20-b189-1d31b6bc00bb\\\",\\\"Email\\\":\\\"\\\",\\\"Space\\\":{\\\"GUID\\\":\\\"93e59aff-d85b-4376-a841-e47a236e664a\\\",\\\"Name\\\":\\\"test-notification\\\",\\\"OrganizationGUID\\\":\\\"8396fb2e-e7a7-4077-8e7d-e19a7cbecc1d\\\"},\\\"Organization\\\":{\\\"GUID\\\":\\\"8396fb2e-e7a7-4077-8e7d-e19a7cbecc1d\\\",\\\"Name\\\":\\\"test-notification\\\"},\\\"ClientID\\\":\\\"notifications-admin\\\",\\\"UAAHost\\\":\\\"https://uaa.alabaster-cloak.services-enablement.cf-app.com\\\",\\\"Scope\\\":\\\"\\\",\\\"VCAPRequestID\\\":\\\"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2\\\",\\\"RequestReceived\\\":\\\"2019-06-14T14:28:52.578843931Z\\\"}\" 3:1 4:0 5:2019-06-14 14:28:55.430278338 +0000 UTC m=+242.669286974]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:55.61+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522535.615646839","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"commit; []","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:55.71+0100 [RTR/0] OUT notifications.alabaster-cloak.services-enablement.cf-app.com - [2019-06-14T14:28:52.577+0000] "POST /spaces/93e59aff-d85b-4376-a841-e47a236e664a HTTP/1.1" 200 319 371 "-" "curl/7.54.0" "80.169.160.158:4318" "10.244.0.139:61000" x_forwarded_for:"80.169.160.158" x_forwarded_proto:"http" vcap_request_id:"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2" response_time:3.134832573 app_id:"294f9623-af21-4de6-bff1-6125cc557ded" app_index:"0" x_b3_traceid:"2311a1df0fdf5651" x_b3_spanid:"2311a1df0fdf5651" x_b3_parentspanid:"-" b3:"2311a1df0fdf5651-2311a1df0fdf5651"
   2019-06-14T15:28:55.71+0100 [RTR/0] OUT
   2019-06-14T15:28:56.20+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522536.200310469","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"INSERT INTO `receipts` (`user_guid`, `client_id`, `kind_id`, `count`, `created_at`) VALUES (?, ?, ?, ?, ?) ON DUPLICATE KEY UPDATE `count`=`count`+1 [1:\"1663856f-b286-4c20-b189-1d31b6bc00bb\" 2:\"notifications-admin\" 3:\"service-alerts\" 4:1 5:2019-06-14 14:28:56 +0000 UTC]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:56.46+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522536.460925341","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:56.64+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522536.645173550","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"SELECT * FROM `global_unsubscribes` WHERE `user_id` = ? [1:\"1663856f-b286-4c20-b189-1d31b6bc00bb\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:56.83+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522536.831427097","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"SELECT * FROM `unsubscribes` WHERE `client_id` = ? AND `kind_id` = ? AND `user_id` = ? [1:\"notifications-admin\" 2:\"service-alerts\" 3:\"1663856f-b286-4c20-b189-1d31b6bc00bb\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.01+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.017615318","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.20+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.203961134","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"SELECT * FROM `clients` WHERE `id` = ? [1:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.38+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.388051033","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"SELECT * FROM `templates` WHERE `id`=? [1:\"default\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.572490215","source":"notifications","message":"notifications.worker.smtp.connecting","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.1","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.575999498","source":"notifications","message":"notifications.worker.smtp.connected","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.1","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.576202154","source":"notifications","message":"notifications.worker.delivery-start","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.576292276","source":"notifications","message":"notifications.worker.smtp.connecting","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.576330423","source":"notifications","message":"notifications.worker.smtp.existing-connection","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.576347351","source":"notifications","message":"notifications.worker.smtp.hello-initiating","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.577121496","source":"notifications","message":"notifications.worker.smtp.hello-complete","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.577325583","source":"notifications","message":"notifications.worker.smtp.setting-msg-from","log_level":1,"data":{"from":"pcf-services-enablement@pivotal.io","message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.577948093","source":"notifications","message":"notifications.worker.smtp.setting-msg-to","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","to":"space-developer@example.com","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.579017401","source":"notifications","message":"notifications.worker.smtp.setting-msg-data","log_level":1,"data":{"message-data":"WC1DRi1DbGllbnQtSUQ6IG5vdGlmaWNhdGlvbnMtYWRtaW4KWC1DRi1Ob3RpZmljYXRpb24tSUQ6IDcwYzU2YmU3LTZiYzItZTNhZS0xZjU2LWI1NmNiNDdjMTVlNgpYLUNGLU5vdGlmaWNhdGlvbi1UaW1lc3RhbXA6IDIwMTktMDYtMTRUMTQ6Mjg6NTcuNTcyNDY1MzU4WgpYLUNGLU5vdGlmaWNhdGlvbi1SZXF1ZXN0LVJlY2VpdmVkOiAyMDE5LTA2LTE0VDE0OjI4OjUyLjU3ODg0MzkzMVoKRGF0ZTogMTQgSnVuIDE5IDE0OjI4ICswMDAwCk1pbWUtVmVyc2lvbjogMS4wCkNvbnRlbnQtVHlwZTogdGV4dC9wbGFpbjsgY2hhcnNldD1VVEYtOApDb250ZW50LVRyYW5zZmVyLUVuY29kaW5nOiBxdW90ZWQtcHJpbnRhYmxlCkZyb206IHBjZi1zZXJ2aWNlcy1lbmFibGVtZW50QHBpdm90YWwuaW8KUmVwbHktVG86IHNvbWUtcmVwbHktdG8tZW1haWxAZXhhbXBsZS5jb20KVG86IHNwYWNlLWRldmVsb3BlckBleGFtcGxlLmNvbQpTdWJqZWN0OiBDRiBOb3RpZmljYXRpb246IFtTZXJ2aWNlIEFsZXJ0XVtJdGVyYXRpb24gMTkgXSBiOTMyMWJlMy02MzE2LTQzNWItYTUyOS03ZDUyODY4NzU1YTAKCllvdSByZWNlaXZlZCB0aGlzIG1lc3NhZ2UgYmVjYXVzZSB5b3UgYmVsb25nIHRvIHRoZSAidGVzdC1ub3RpZmljYXRpb24iIHNwYWM9CmUgaW4gdGhlICJ0ZXN0LW5vdGlmaWNhdGlvbiIgb3JnYW5pemF0aW9uLgpBbGVydCBmcm9tIHNvbWUtcHJvZHVjdCwgc2VydmljZSBpbnN0YW5jZSBzb21lLXNlcnZpY2UtaW5zdGFuY2UtYjA4M2Q2OGM6IHNvPQptZS1jb250ZW50PTIwCgoKW0FsZXJ0IGdlbmVyYXRlZCBhdCAyMDE5LTA2LTExVDE2OjM5OjQ3KzAxOjAwXQ==","message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.58+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.581152916","source":"notifications","message":"notifications.worker.smtp.msg-data-sent","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.58+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.581421614","source":"notifications","message":"notifications.worker.smtp.quiting","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.58+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.583171844","source":"notifications","message":"notifications.worker.smtp.disconnected","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7.2","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.58+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.583268166","source":"notifications","message":"notifications.worker.message-sent","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","recipient":"space-developer@example.com","session":"7","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.58+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.583316565","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"SELECT * FROM `messages` WHERE `id`=? [1:\"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.76+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.766931772","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"update `messages` set `id`=?, `status`=?, `updated_at`=? where `id`=?; [1:\"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6\" 2:\"delivered\" 3:2019-06-14 14:28:57 +0000 UTC 4:\"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
   2019-06-14T15:28:57.95+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522537.953883648","source":"notifications","message":"notifications.worker.db","log_level":1,"data":{"message_id":"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6","session":"7","statement":"SELECT * FROM `messages` WHERE `id`=? [1:\"70c56be7-6bc2-e3ae-1f56-b56cb47c15e6\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2","worker_id":7}}
§   2019-06-14T15:28:52.57+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522532.578694105","source":"notifications","message":"notifications.request.incoming","log_level":1,"data":{"method":"POST","path":"/spaces/93e59aff-d85b-4376-a841-e47a236e664a","session":"5","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:52.58+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522532.579658985","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `clients` WHERE `id` = ? [1:\"notifications-admin\"]","vcap_request_id":"4dd95129-be04-4dd5-61a4-7bd65e0a3fb2"}}
   2019-06-14T15:28:52.76+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522532.763361931","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"5","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id   2019-06-14T15:29:54.16+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522594.167758942","source":"notifications","message":"notifications.uaa.token.validator.loading.keys","log_level":1,"data":{"session":"2"}}

When the email is not delivered 

2019-06-14T15:26:54.13+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522414.134604692","source":"notifications","message":"notifications.uaa.token.validator.loading.keys","log_level":1,"data":{"session":"2"}}
   2019-06-14T15:26:54.14+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522414.144951582","source":"notifications","message":"notifications.uaa.token.validator.loaded.keys","log_level":1,"data":{"keys":["key-1"],"session":"2"}}
   2019-06-14T15:27:09.80+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522429.800248384","source":"notifications","message":"notifications.request.incoming","log_level":1,"data":{"method":"POST","path":"/spaces/93e59aff-d85b-4376-a841-e47a236e664a","session":"3","vcap_request_id":"7b
8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:09.80+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522429.801381588","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `clients` WHERE `id` = ? [1:\"notifications-admin\"]","vcap_request_id
":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:10.35+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522430.350627899","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"n
otifications-admin\"]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:10.53+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522430.535547972","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `clients` WHERE `id` = ? [1:\"notifications-admin\"]","vcap_request_id
":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:10.72+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522430.720593691","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"update `clients` set `id`=?, `description`=?, `created_at`=?, `template_id`=? where
`primary`=?; [1:\"notifications-admin\" 2:\"\" 3:2017-07-13 14:17:56 +0000 UTC 4:\"default\" 5:1]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:10.90+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522430.908490181","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `clients` WHERE `id` = ? [1:\"notifications-admin\"]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:11.09+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522431.094873190","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:11.28+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522431.280614376","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:11.46+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522431.466838121","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"update `kinds` set `id`=?, `description`=?, `critical`=?, `client_id`=?, `created_at`=?, `updated_at`=?, `template_id`=? where `primary`=?; [1:\"service-alerts\" 2:\"\" 3:false 4:\"notifications-admin\" 5:2017-07-13 14:17:57 +0000 UTC 6:2019-06-14 14:27:11 +0000 UTC 7:\"default\" 8:2]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:11.65+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522431.655467510","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `kinds` WHERE `id` = ? AND `client_id` = ? [1:\"service-alerts\" 2:\"notifications-admin\"]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:12.16+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522432.163753748","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"begin; []","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:12.16+0100 [APP/PROC/WEB/0] ERR 2019/06/14 14:27:12 Warning: Automatic mapping of Version struct members to version columns (see optimistic locking) will be deprecated in next version (V2) See: https://github.com/go-gorp/gorp/pull/214
   2019-06-14T15:27:12.25+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522432.256789923","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `messages` WHERE `id`=? [1:\"\"]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:12.44+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522432.443612576","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"insert into `messages` (`id`,`status`,`updated_at`) values (?,?,?); [1:\"010dcee6-e4bf-8a80-8634-5729e56b9934\" 2:\"queued\" 3:2019-06-14 14:27:12 +0000 UTC]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:12.63+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522432.630127430","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"insert into `jobs` (`id`,`worker_id`,`payload`,`version`,`retry_count`,`active_at`)
values (null,?,?,?,?,?); [1:\"\" 2:\"{\\\"MessageID\\\":\\\"010dcee6-e4bf-8a80-8634-5729e56b9934\\\",\\\"Options\\\":{\\\"ReplyTo\\\":\\\"some-reply-to-email@example.com\\\",\\\"Subject\\\":\\\"[Service Alert][Iteration 19 ] b9321be3-6316-435b-a529-7d52868755a0\\\",\\\"KindDescription\\\":\\\"\\\",\\\"SourceDescription\\\":\\\"\\\",\\\"Text\\\":\\\"Alert from some-product, service instance some-service-instance-b083d68c: some-content \\\\n\\\\n\\\\n[Alert generated at 2019-06-11T16:39:47+01:00]\\\",\\\"HTML\\\":{\\\"BodyContent\\\":\\\"\\\",\\\"BodyAttributes\\\":\\\"\\\",\\\"Head\\\":\\\"\\\",\\\"Doctype\\\":\\\"\\\"},\\\"KindID\\\":\\\"service-alerts\\\",\\\"To\\\":\\\"\\\",\\\"Role\\\":\\\"\\\",\\\"Endorsement\\\":\\\"You received this message because you belong to the \\\\\\\"{{.Space}}\\\\\\\" space in the \\\\\\\"{{.Organization}}\\\\\\\" organization.\\\",\\\"TemplateID\\\":\\\"\\\"},\\\"UserGUID\\\":\\\"d144f1f9-7b5a-4263-a378-21cc95853551\\\",\\\"Email\\\":\\\"\\\",\\\"Space\\\":{\\\"GUID\\\":\\\"93e59aff-d85b-4376-a841-e47a236e664a\\\",\\\"Name\\\":\\\"test-notification\\\",\\\"OrganizationGUID\\\":\\\"8396fb2e-e7a7-4077-8e7d-e19a7cbecc1d\\\"},\\\"Organization\\\":{\\\"GUID\\\":\\\"8396fb2e-e7a7-4077-8e7d-e19a7cbecc1d\\\",\\\"Name\\\":\\\"test-notification\\\"},\\\"ClientID\\\":\\\"notifications-admin\\\",\\\"UAAHost\\\":\\\"https://uaa.alabaster-cloak.services-enablement.cf-app.com\\\",\\\"Scope\\\":\\\"\\\",\\\"VCAPRequestID\\\":\\\"7b8e129c-bb0c-43fe-5172-1026b94b51c5\\\",\\\"RequestReceived\\\":\\\"2019-06-14T14:27:09.800447533Z\\\"}\" 3:1 4:0 5:2019-06-14 14:27:12.630003394 +0000 UTC m=+139.869012230]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:12.81+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522432.816594124","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"SELECT * FROM `messages` WHERE `id`=? [1:\"\"]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:13.00+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522433.002468348","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"insert into `messages` (`id`,`status`,`updated_at`) values (?,?,?); [1:\"265e69f2-5a75-b262-4082-604121a59ffb\" 2:\"queued\" 3:2019-06-14 14:27:13 +0000 UTC]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:13.18+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522433.188726425","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"insert into `jobs` (`id`,`worker_id`,`payload`,`version`,`retry_count`,`active_at`)
values (null,?,?,?,?,?); [1:\"\" 2:\"{\\\"MessageID\\\":\\\"265e69f2-5a75-b262-4082-604121a59ffb\\\",\\\"Options\\\":{\\\"ReplyTo\\\":\\\"some-reply-to-email@example.com\\\",\\\"Subject\\\":\\\"[Service Alert][Iteration 19 ] b9321be3-6316-435b-a529-7d52868755a0\\\",\\\"KindDescription\\\":\\\"\\\",\\\"SourceDescription\\\":\\\"\\\",\\\"Text\\\":\\\"Alert from some-product, service instance some-service-instance-b083d68c: some-content \\\\n\\\\n\\\\n[Alert generated at 2019-06-11T16:39:47+01:00]\\\",\\\"HTML\\\":{\\\"BodyContent\\\":\\\"\\\",\\\"BodyAttributes\\\":\\\"\\\",\\\"Head\\\":\\\"\\\",\\\"Doctype\\\":\\\"\\\"},\\\"KindID\\\":\\\"service-alerts\\\",\\\"To\\\":\\\"\\\",\\\"Role\\\":\\\"\\\",\\\"Endorsement\\\":\\\"You received this message because you belong to the \\\\\\\"{{.Space}}\\\\\\\" space in the \\\\\\\"{{.Organization}}\\\\\\\" organization.\\\",\\\"TemplateID\\\":\\\"\\\"},\\\"UserGUID\\\":\\\"1663856f-b286-4c20-b189-1d31b6bc00bb\\\",\\\"Email\\\":\\\"\\\",\\\"Space\\\":{\\\"GUID\\\":\\\"93e59aff-d85b-4376-a841-e47a236e664a\\\",\\\"Name\\\":\\\"test-notification\\\",\\\"OrganizationGUID\\\":\\\"8396fb2e-e7a7-4077-8e7d-e19a7cbecc1d\\\"},\\\"Organization\\\":{\\\"GUID\\\":\\\"8396fb2e-e7a7-4077-8e7d-e19a7cbecc1d\\\",\\\"Name\\\":\\\"test-notification\\\"},\\\"ClientID\\\":\\\"notifications-admin\\\",\\\"UAAHost\\\":\\\"https://uaa.alabaster-cloak.services-enablement.cf-app.com\\\",\\\"Scope\\\":\\\"\\\",\\\"VCAPRequestID\\\":\\\"7b8e129c-bb0c-43fe-5172-1026b94b51c5\\\",\\\"RequestReceived\\\":\\\"2019-06-14T14:27:09.800447533Z\\\"}\" 3:1 4:0 5:2019-06-14 14:27:13.188637793 +0000 UTC m=+140.427646433]","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:13.37+0100 [APP/PROC/WEB/0] OUT {"timestamp":"1560522433.375562429","source":"notifications","message":"notifications.request.db","log_level":0,"data":{"session":"3","statement":"commit; []","vcap_request_id":"7b8e129c-bb0c-43fe-5172-1026b94b51c5"}}
   2019-06-14T15:27:13.47+0100 [RTR/0] OUT notifications.alabaster-cloak.services-enablement.cf-app.com - [2019-06-14T14:27:09.798+0000] "POST /spaces/93e59aff-d85b-4376-a841-e47a236e664a HTTP/1.1" 200 319 371 "-" "curl/7.54.0" "80.169.160.158:3113" "10.244.0.139:61000" x_forwarded_for:"80.169.160.158" x_forwarded_proto:"http" vcap_request_id:"7b8e129c-bb0c-43fe-5172-1026b94b51c5" response_time:3.673499895 app_id:"294f9623-af21-4de6-bff1-6125cc557ded" app_index:"0" x_b3_traceid:"d2b8ffa3ec2c058f" x_b3_spanid:"d2b8ffa3ec2c058f" x_b3_parentspanid:"-" b3:"d2b8ffa3ec2c058f-d2b8ffa3ec2c058f"
   2019-06-14T15:27:13.47+0100 [RTR/0] OUT

Versions Notification release: v57 Notification app: v1.1.0 SMTP server: Mailhog CF-CLI: v1.16.0 DATABASE: MYSQL innodb v5.7.14

gabrielecipriano commented 5 years ago

We finally understood that the messages were not being sent because we were sharing the same database between our local test and CI. That meant that notifications app from different foundations were picking each other jobs and failing to deliver for unrecognised UUID. It also explains why we could find logs for failed deliveries.