Log attribute fixes (#58)

* update compose

* working multi-line for ads

* add lograge

* add multi line postgres

* frontend json logger

* py logging filters to remove encoding

* switch auto_line detection

* cleanup

* update ads-java to mimic ads python response

* throw error using flag

* cleanup

* remove ff, revert env

README.md

@@ -59,6 +59,9 @@ Images are stored in our public ECR repo `public.ecr.aws/x2b9z2t7`. On PR merges
 
 Separately, we tag and publish *all* images when a new release is created with the corresponding release tag e.g. `public.ecr.aws/x2b9z2t7/storedog/backend:1.0.1`. New releases are made on an ad-hoc basis, depending on the recent features that are added.
 
+# Ads
+There are two advertisement services, one built in Python `ads` running on port 7676 and another built in Java `ads-java` running on port 3030. The frontend can consume either of these services and serve ads to the homepage. To select which service is consumed, update the `NEXT_PUBLIC_ADS_PORT` in `services/frontend/site/.env.local`.
+
 # Backend
 ## Database rebuild
 

docker-compose.yml

@@ -13,6 +13,12 @@ services:
       - 3000:3000
     networks:
       - storedog-net
+    environment:
+      DD_VERSION: "7"
+      DD_SERVICE: "storedog-frontend"
+      DD_ENV: "dev"
+    labels:
+      com.datadoghq.ad.logs: '[{"source": "nodejs", "service": "storedog-frontend",  "auto_multi_line_detection":true }]'
   nginx:
     build:
       context: ./services/nginx
@@ -37,13 +43,11 @@ services:
       - 'postgres:/var/lib/postgresql/data'
       - ./services/backend/db/restore:/docker-entrypoint-initdb.d
       - ./services/backend/db/postgresql.conf:/postgresql.conf
-      - ./services/dbm/dbm_setup.sql:/etc/postgresql/13/main/dbm_setup.sql
-      - ./services/dbm/dbm_exec.sh:/dbm_exec.sh
     labels:
       com.datadoghq.ad.check_names: '["postgres"]'
       com.datadoghq.ad.init_configs: '[{}]'
       com.datadoghq.ad.instances: '[{"host":"%%host%%", "port":5432,"username":"datadog","password":"datadog"}]'
-      com.datadoghq.ad.logs: '[{"source":"postgresql","service":"postgresql"}]'
+      com.datadoghq.ad.logs: '[{"source":"postgresql","service":"postgres", "auto_multi_line_detection": true}]'
     command: ["postgres", "-c", "config_file=/postgresql.conf"]
     networks:
       - storedog-net
@@ -75,8 +79,13 @@ services:
       DISABLE_SPRING: 1
       DD_APPSEC_ENABLED: 1
       DD_AGENT_HOST: 172.43.0.1
+      DD_VERSION: "7"
+      DD_SERVICE: "storedog-backend"
+      DD_ENV: "dev"
     networks:
       - storedog-net
+    labels:
+      com.datadoghq.ad.logs: '[{"source": "ruby", "service": "storedog-backend",  "auto_multi_line_detection":true }]'
   worker:
     depends_on:
       - 'postgres'
@@ -99,6 +108,8 @@ services:
       DD_AGENT_HOST: 172.43.0.1
     networks:
       - storedog-net
+    labels:
+      com.datadoghq.ad.logs: '[{"source": "ruby", "service": "storedog-worker",  "auto_multi_line_detection":true }]'
   ads:
     depends_on:
       - postgres
@@ -109,13 +120,13 @@ services:
       - POSTGRES_PASSWORD=${POSTGRES_PASSWORD}
       - POSTGRES_USER=${POSTGRES_USER}
       - POSTGRES_HOST=postgres
-      - DD_SERVICE=ads
       - DD_AGENT_HOST=dd-agent
       - DD_LOGS_INJECTION=true
       - DD_TRACE_ANALYTICS_ENABLED=true
       - DD_PROFILING_ENABLED=true
       - DD_APPSEC_ENABLED=true
       - DD_VERSION=7
+      - DD_SERVICE=ads
       - DD_ENV=dev
     build:
       context: ./services/ads/python
@@ -127,7 +138,11 @@ services:
     networks:
       - storedog-net
     labels:
-      com.datadoghq.ad.logs: '[{"source": "python", "service": "ads"}]'
+      com.datadoghq.ad.logs: '[{"source": "python", "service": "ads", "log_processing_rules": [{
+          "type": "multi_line",
+          "name": "log_start_with_date",
+          "pattern" : "\d{3}.\d{2}.\d{1}.\d{1}"
+        }] }]'
   discounts:
     depends_on:
       - postgres
@@ -138,13 +153,13 @@ services:
       - POSTGRES_PASSWORD=${POSTGRES_PASSWORD}
       - POSTGRES_USER=${POSTGRES_USER}
       - POSTGRES_HOST=postgres
-      - DD_SERVICE=discounts
       - DD_AGENT_HOST=dd-agent
       - DD_LOGS_INJECTION=true
       - DD_TRACE_ANALYTICS_ENABLED=true
       - DD_PROFILING_ENABLED=true
       - DD_APPSEC_ENABLED=true
       - DD_VERSION=7
+      - DD_SERVICE=discounts
       - DD_ENV=dev
     build:
       context: ./services/discounts
@@ -157,7 +172,11 @@ services:
     networks:
       - storedog-net
     labels:
-      com.datadoghq.ad.logs: '[{"source": "python", "service": "discounts"}]'
+      com.datadoghq.ad.logs: '[{"source": "python", "service": "discounts", "log_processing_rules": [{
+          "type": "multi_line",
+          "name": "log_start_with_date",
+          "pattern" : "\\[\\d{4}-\\d{2}-\\d{2}\\s\\d{2}:\\d{2}:\\d{2}\\,\\d{3}"
+        }] }]'
   auth:
     depends_on:
       - postgres
@@ -221,7 +240,7 @@ services:
       - DD_LOGS_ENABLED=true
       - DD_HOSTNAME=172.43.0.4
       - DD_LOGS_CONFIG_CONTAINER_COLLECT_ALL=true
-      - DD_CONTAINER_EXCLUDE=name datadog-agent
+      - DD_CONTAINER_EXCLUDE="name:datadog-agent"
       - DD_HOSTNAME_TRUST_UTS_NAMESPACE=true
     ports:
       - "8126:8126"
@@ -249,7 +268,7 @@ services:
     networks:
       - storedog-net
     labels:
-      com.datadoghq.ad.logs: '[{"source": "java", "service": "ads-java"}]'
+      com.datadoghq.ad.logs: '[{"source": "java", "service": "ads-java",  "auto_multi_line_detection": true}]'
   attackbox:
     build:
       context: ./services/attackbox

services/ads/java/src/main/java/adsjava/AdsJavaApplication.java

@@ -13,49 +13,71 @@
 import java.util.concurrent.ThreadLocalRandom;
 import java.util.HashMap;
 import org.springframework.web.bind.annotation.RequestParam;
+import java.util.concurrent.TimeoutException;
+import org.springframework.web.bind.annotation.RequestHeader;
+
 
 @SpringBootApplication
 @RestController
 public class AdsJavaApplication {
 
-  @CrossOrigin(origins = {"*"})
-  @RequestMapping(
-    value = "/banners/{id}",
-    produces = MediaType.IMAGE_JPEG_VALUE
-  )
-  public @ResponseBody byte[] getImageWithMediaType() throws IOException {
-    int randomNum = ThreadLocalRandom.current().nextInt(1, 3 + 1);
-    String imagePath = "/static/ads/ad" + randomNum + ".jpg";
-    InputStream in = getClass()
-        .getResourceAsStream(imagePath);
-    return IOUtils.toByteArray(in);
-  }
+    @CrossOrigin(origins = {"*"})
+    @RequestMapping(
+        value = "/banners/{id}",
+        produces = MediaType.IMAGE_JPEG_VALUE
+    )
+    public @ResponseBody byte[] getImageWithMediaType() throws IOException {
+        int randomNum = ThreadLocalRandom.current().nextInt(1, 3 + 1);
+        String imagePath = "/static/ads/ad" + randomNum + ".jpg";
+        InputStream in = getClass()
+            .getResourceAsStream(imagePath);
+        return IOUtils.toByteArray(in);
+    }
 
 	@RequestMapping("/")
 	public String home() {
-		return "Hello from Advertisements (Java)";
+        return "Welcome to Java - Ads Service";
 	}
 
-  @CrossOrigin(origins = {"*"})
-  @RequestMapping(
-    value = "/ads",
-    produces = MediaType.APPLICATION_JSON_VALUE
-  )
-	public HashMap[] ads() {
-    HashMap<String, String> map1 = new HashMap<>();
-    map1.put("id", "1");
-    map1.put("path", "ad1.jpg");
+    @CrossOrigin(origins = {"*"})
+    @RequestMapping(
+        value = "/ads",
+        produces = MediaType.APPLICATION_JSON_VALUE
+    )
+	public HashMap[] ads(@RequestHeader HashMap<String, String> headers) {
+
+        boolean errorFlag = false;
+        if(headers.get("x-throw-error") != null) {
+            errorFlag = Boolean.parseBoolean(headers.get("x-throw-error"));
+        }
 
-    HashMap<String, String> map2 = new HashMap<>();
-    map2.put("id", "2");
-    map2.put("path", "ad2.jpg");
+        if(errorFlag) {
+            // Intentionally throw error here to demonstrate Logs Error Tracking behavior
+            try {
+                throw new TimeoutException("took too long to get a response");
+            } catch  (Exception e) {
+                System.out.println("took too long to get a response");
+                throw new RuntimeException(e);
+            }
+        } else {
+            HashMap<String, String> map1 = new HashMap<>();
+            map1.put("id", "1");
+            map1.put("name", "Discount Clothing");
+            map1.put("path", "1.jpg");
 
-    HashMap<String, String> map3 = new HashMap<>();
-    map3.put("id", "3");
-    map3.put("path", "ad3.jpg");
+            HashMap<String, String> map2 = new HashMap<>();
+            map2.put("id", "2");
+            map2.put("name", "Cool Hats");
+            map2.put("path", "2.jpg");
 
-    HashMap[] myArr = { map1, map2, map3 };
-    return myArr;
+            HashMap<String, String> map3 = new HashMap<>();
+            map3.put("id", "3");
+            map3.put("name", "Nic Bags");
+            map3.put("path", "3.jpg");
+            System.out.println("ads called");
+            HashMap[] myArr = { map1, map2, map3 };
+            return myArr;
+        }
 	}
 
 	public static void main(String[] args) {

services/ads/python/ads.py

@@ -1,6 +1,8 @@
 import requests
 import random
 import time
+import sys
+import re
 
 from flask import Flask, Response, jsonify, send_from_directory
 from flask import request as flask_request
@@ -12,34 +14,53 @@
 from ddtrace import patch; patch(logging=True)
 import logging
 from ddtrace import tracer
+import json_log_formatter
 
-FORMAT = ('%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] '
-          '[dd.service=%(dd.service)s dd.env=%(dd.env)s dd.version=%(dd.version)s dd.trace_id=%(dd.trace_id)s dd.span_id=%(dd.span_id)s] '
-          '- %(message)s')
-logging.basicConfig(format=FORMAT)
-log = logging.getLogger(__name__)
-log.level = logging.INFO
+formatter = json_log_formatter.JSONFormatter()
+json_handler = logging.StreamHandler(sys.stdout)
+json_handler.setFormatter(formatter)
+logger = logging.getLogger('werkzeug')
+logger.addHandler(json_handler)
+logger.setLevel(logging.DEBUG)
 
 app = create_app()
 CORS(app)
 app.config['SQLALCHEMY_TRACK_MODIFICATIONS'] = False
 
+## Add filter to remove color-encoding from logs e.g. "[37mGET / HTTP/1.1 [0m" 200 -
+class NoEscape(logging.Filter):
+    def __init__(self):
+        self.regex = re.compile(r'(\x9B|\x1B\[)[0-?]*[ -\/]*[@-~]')
+    def strip_esc(self, s):
+        try: # string-like 
+            return self.regex.sub('',s)
+        except: # non-string-like
+            return s
+    def filter(self, record):
+        record.msg = self.strip_esc(record.msg)
+        if type(record.args) is tuple:
+            record.args = tuple(map(self.strip_esc, record.args))
+        return 1
+
+remove_color_filter =NoEscape()
+logger.addFilter(remove_color_filter)
+
 @tracer.wrap()
 @app.route('/')
 def hello():
-    log.info("home url for ads called")
+    logger.info("home url for ads called")
     return Response({'Hello from Advertisements!': 'world'}, mimetype='application/json')
 
 @tracer.wrap()
 @app.route('/banners/<path:banner>')
 def banner_image(banner):
-    log.info(f"attempting to grab banner at {banner}")
+    logger.info(f"attempting to grab banner at {banner}")
     return send_from_directory('ads', banner)
 
 @tracer.wrap()
 @app.route('/weighted-banners/<float:weight>')
 def weighted_image(weight):
-    log.info(f"attempting to grab banner weight of less than {weight}")
+    logger.info(f"attempting to grab banner weight of less than {weight}")
     advertisements = Advertisement.query.all()
     for ad in advertisements:
         if ad.weight < weight:
@@ -52,19 +73,24 @@ def status():
 
         if 'X-Throw-Error' in flask_request.headers and flask_request.headers['X-Throw-Error'] == 'true':
 
-            advertisements = Advertisement.query.all()
-            result.status_code = 200 # attempt to set property of null object     
-            return result
+            try:
+                raise ValueError('something went wrong')
+            except ValueError:
+                logger.error('Request failed', exc_info=True)
+
+            err = jsonify({'error': 'Internal Server Error'})
+            err.status_code = 500
+            return err
 
         else:
 
           try:
               advertisements = Advertisement.query.all()
-              log.info(f"Total advertisements available: {len(advertisements)}")
+              logger.info(f"Total advertisements available: {len(advertisements)}")
               return jsonify([b.serialize() for b in advertisements])
 
           except:
-              log.error("An error occurred while getting ad.")
+              logger.error("An error occurred while getting ad.")
               err = jsonify({'error': 'Internal Server Error'})
               err.status_code = 500
               return err
@@ -75,10 +101,10 @@ def status():
         try:
             # create a new advertisement with random name and value
             advertisements_count = len(Advertisement.query.all())
-            new_advertisement = Advertisement('Advertisement ' + str(discounts_count + 1),
+            new_advertisement = Advertisement('Advertisement ' + str(advertisements_count + 1),
                                     '/',
                                     random.randint(10,500))
-            log.info(f"Adding advertisement {new_advertisement}")
+            logger.info(f"Adding advertisement {new_advertisement}")
             db.session.add(new_advertisement)
             db.session.commit()
             advertisements = Advertisement.query.all()
@@ -87,7 +113,7 @@ def status():
 
         except:
 
-            log.error("An error occurred while creating a new ad.")
+            logger.error("An error occurred while creating a new ad.")
             err = jsonify({'error': 'Internal Server Error'})
             err.status_code = 500
             return err

services/ads/python/requirements.txt

@@ -19,4 +19,5 @@ sortedcontainers==2.3.0
 SQLAlchemy==1.3.23
 tenacity==6.2.0
 urllib3==1.26.5
-Werkzeug==1.0.1
+Werkzeug==1.0.1
+JSON-log-formatter==0.5.2

services/backend/Gemfile

@@ -102,3 +102,6 @@ gem 'ddtrace', require: 'ddtrace/auto_instrument'
 gem 'google-protobuf', '~> 3.0'
 # needed for runtime metrics
 gem 'dogstatsd-ruby', require: 'datadog/statsd'
+
+# JSON log formatter
+gem 'lograge'