Merge pull request #50 from deskpro/logging-export-files

Clean up log file export

.dockerignore

@@ -1,5 +1,7 @@
 .git/
 .scratch/
+hooks/
+test/
 
 .editorconfig
 .gitignore

Dockerfile

@@ -1,4 +1,7 @@
-FROM debian:12.2-slim as builder-php-exts
+# builder stage -- builds PHP packages
+# outputs: /usr/lib/php/20230831/protobuf.so
+# outputs: /usr/lib/php/20230831/opentelemetry.so
+FROM debian:12.2-slim AS builder-php-exts
 RUN apt-get update \
     && DEBIAN_FRONTEND=noninteractive apt-get install -y ca-certificates apt-transport-https software-properties-common curl lsb-release \
     && curl -sSLo /usr/share/keyrings/deb.sury.org-php.gpg https://packages.sury.org/php/apt.gpg \
@@ -13,14 +16,12 @@ RUN apt-get update \
     php-pear \
     && pecl install opentelemetry protobuf \
     && rm -rf /var/lib/apt/lists/*
-# outputs: /usr/lib/php/20230831/protobuf.so
-# outputs: /usr/lib/php/20230831/opentelemetry.so
 
-FROM debian:12.2-slim
+# stage1 -- debian with packages
+FROM debian:12.2-slim AS stage1
 ENV TZ=UTC
 WORKDIR /srv/deskpro
 USER root
-
 RUN apt-get update \
     && DEBIAN_FRONTEND=noninteractive apt-get install -y --no-install-recommends --no-install-suggests ca-certificates apt-transport-https software-properties-common curl lsb-release \
     && curl -sSLo /usr/share/keyrings/deb.sury.org-php.gpg https://packages.sury.org/php/apt.gpg \
@@ -64,7 +65,20 @@ RUN apt-get update \
     && find /usr/lib/python3.11 -type f -name '*.py[co]' -delete -o -type d -name __pycache__ -delete \
     && apt-get -y autoremove && apt-get -y clean \
     && rm -rf /var/lib/apt/lists/* \
-    && rm -rf /usr/bin/mariadb-access /usr/bin/mariadb-admin /usr/bin/mariadb-analyze /usr/bin/mariadb-check /usr/bin/mariadb-binlog /usr/bin/mariadb-conv /usr/bin/mariadb-convert-table-format /usr/bin/mariadb-find-rows /usr/bin/mariadb-fix-extensions /usr/bin/mariadb-hotcopy /usr/bin/mariadb-import /usr/bin/mariadb-optimize /usr/bin/mariadb-plugin /usr/bin/mariadb-repair /usr/bin/mariadb-report /usr/bin/mariadb-secure-installation /usr/bin/mariadb-setpermission /usr/bin/mariadb-show /usr/bin/mariadb-slap /usr/bin/mariadb-tzinfo-to-sql /usr/bin/mariadb-waitpid /usr/bin/mariadbcheck
+    && rm -rf /usr/bin/mariadb-access /usr/bin/mariadb-admin /usr/bin/mariadb-analyze /usr/bin/mariadb-check /usr/bin/mariadb-binlog /usr/bin/mariadb-conv /usr/bin/mariadb-convert-table-format /usr/bin/mariadb-find-rows /usr/bin/mariadb-fix-extensions /usr/bin/mariadb-hotcopy /usr/bin/mariadb-import /usr/bin/mariadb-optimize /usr/bin/mariadb-plugin /usr/bin/mariadb-repair /usr/bin/mariadb-report /usr/bin/mariadb-secure-installation /usr/bin/mariadb-setpermission /usr/bin/mariadb-show /usr/bin/mariadb-slap /usr/bin/mariadb-tzinfo-to-sql /usr/bin/mariadb-waitpid /usr/bin/mariadbcheck \
+    && ln -s /usr/bin/vim.tiny /usr/bin/vim
+
+# stage2 -- packages from other images
+FROM stage1 AS stage2
+COPY --from=builder-php-exts /usr/lib/php/20230831/protobuf.so /usr/lib/php/20230831/protobuf.so
+COPY --from=builder-php-exts /usr/lib/php/20230831/opentelemetry.so /usr/lib/php/20230831/opentelemetry.so
+COPY --from=hairyhenderson/gomplate:v3.11.5 /gomplate /usr/local/bin/gomplate
+COPY --from=composer:2.5.8 /usr/bin/composer /usr/local/bin/composer
+COPY --from=timberio/vector:0.39.0-debian /usr/bin/vector /usr/local/bin/vector
+COPY --from=node:18.19-bookworm /usr/local/bin /usr/local/bin
+COPY --from=node:18.19-bookworm /usr/local/lib/node_modules /usr/local/lib/node_modules
+
+RUN npm install --global tsx
 
 RUN sed -i 's/providers = provider_sect/providers = provider_sect\n\
 ssl_conf = ssl_sect\n\
@@ -75,18 +89,6 @@ system_default = system_default_sect\n\
 [system_default_sect]\n\
 Options = UnsafeLegacyRenegotiation/' /etc/ssl/openssl.cnf
 
-COPY --from=builder-php-exts /usr/lib/php/20230831/protobuf.so /usr/lib/php/20230831/protobuf.so
-COPY --from=builder-php-exts /usr/lib/php/20230831/opentelemetry.so /usr/lib/php/20230831/opentelemetry.so
-
-COPY --from=hairyhenderson/gomplate:v3.11.5 /gomplate /usr/local/bin/gomplate
-COPY --from=composer:2.5.8 /usr/bin/composer /usr/local/bin/composer
-COPY --from=timberio/vector:0.31.0-debian /usr/bin/vector /usr/local/bin/vector
-COPY --from=oven/bun:1.0.14-debian /usr/local/bin/bun /usr/local/bin/bun
-
-COPY --from=node:18.19-bookworm /usr/local/bin /usr/local/bin
-COPY --from=node:18.19-bookworm /usr/local/lib/node_modules /usr/local/lib/node_modules
-RUN npm install --global tsx
-
 RUN set -e \
     && printf '; priority=20\nextension=protobuf.so' > /etc/php/8.3/mods-available/protobuf.ini \
     && printf '; priority=90\n; placeholder' > /etc/php/8.3/mods-available/deskpro.ini \
@@ -100,37 +102,39 @@ RUN set -e \
     && chmod 0755 /etc/nginx /etc/nginx/conf.d \
     && mv /tmp/mime.types /etc/nginx
 
+# build -- final stage adds our custom stuff
+FROM stage2 AS build
 COPY etc /etc/
 COPY usr/local/bin /usr/local/bin/
 COPY usr/local/lib /usr/local/lib/
 COPY usr/local/sbin /usr/local/sbin/
 COPY usr/local/share/deskpro /usr/local/share/deskpro/
 
 RUN set -e \
-    # dp_app user is used when we run any app code (e.g. php-fpm, CLI tasks, etc) \
+    # dp_app user is used when we run any app code (e.g. php-fpm, CLI tasks, etc)
     && addgroup --gid 1083 dp_app \
     && adduser --system --shell /bin/false --no-create-home --disabled-password --uid 1083 --gid 1083 dp_app \
-    # vector user for logs \
+    # vector user for logs
     && addgroup --gid 1084 vector \
     && adduser --system --shell /bin/false --no-create-home --disabled-password --uid 1084 --gid 1084 vector \
-    # add vector to adm group so it can read logs \
+    # add vector to adm group so it can read logs
     && usermod -a -G adm vector \
-    # we run nginx as its own user \
+    # we run nginx as its own user
     && addgroup --gid 1085 nginx \
     && adduser --system --shell /bin/false --no-create-home --disabled-password --uid 1085 --gid 1085 nginx \
-    # initialize dirs and owners \
+    # initialize dirs and owners
     && mkdir -p /var/log/nginx /var/log/php /var/log/deskpro /var/log/supervisor /var/lib/vector \
     && mkdir -p /srv/deskpro/INSTANCE_DATA/deskpro-config.d \
     && chown root:root /usr/local/bin/vector \
     && chown vector:adm /var/lib/vector \
     && chown nginx:adm /var/log/nginx \
     && chown dp_app:adm /var/log/php /var/log/deskpro \
     && chmod -R 0775 /var/log/php /var/log/deskpro \
-    # set group sticky bit on these dirs so \
-    # new logs get created with adm group (so vector can read them) \
+    # set group sticky bit on these dirs so
+    # new logs get created with adm group (so vector can read them)
     && chmod g+s /var/log/nginx /var/log/php /var/log/deskpro \
-    # extract var names from our reference list \
-    # (these lists are used from various helper scripts or entrypoint scripts) \
+    # extract var names from our reference list
+    # (these lists are used from various helper scripts or entrypoint scripts)
     && jq -r '.[] | select(.isPrivate|not) | .name' /usr/local/share/deskpro/container-var-reference.json > /usr/local/share/deskpro/container-public-var-list \
     && jq -r '.[] | select(.isPrivate) | .name' /usr/local/share/deskpro/container-var-reference.json > /usr/local/share/deskpro/container-private-var-list \
     && jq -r '.[] | select(.setEnv) | .name' /usr/local/share/deskpro/container-var-reference.json > /usr/local/share/deskpro/container-setenv-var-list \
@@ -170,10 +174,10 @@ ENV LOGS_EXPORT_TARGET ""
 ENV LOGS_EXPORT_DIR ""
 
 # The filename to use when writing logs to LOGS_EXPORT_DIR
-ENV LOGS_EXPORT_FILENAME "{{.container_name}}/{{.app}}/{{.chan}}.log"
+ENV LOGS_EXPORT_FILENAME "{{.container_name}}-{{.log_group}}.log"
 
-# Log output format: logfmt or json
-ENV LOGS_OUTPUT_FORMAT "logfmt"
+# Enable ("1" or "true") to enable fast shutdown (don't wait for all processes to finish gracefully)
+ENV FAST_SHUTDOWN="0"
 
 # GID to use for exported log files. By default, logs will be owned by the vector group (GID 1084).
 ENV LOGS_GID ""

etc/nginx/nginx.conf.tmpl

@@ -26,33 +26,34 @@ http {
     ssl_session_timeout 1h;
     ssl_session_tickets off;
 
-    log_format logfmt escape=json
-      'ts=$time_iso8601 '
-      'method=$request_method '
-      'request_uri="$request_uri" '
-      'status=$status '
-      'host="$host" '
-      'scheme=$scheme '
-      'user_http_referer="$http_referer" '
-      'user_agent="$http_user_agent" '
-      'user_remote_addr=$remote_addr '
-      'user_remote_port=$remote_port '
-      'proxy_addr=$realip_remote_addr '
-      'proxy_port=$realip_remote_port '
-      'request_id="$request_id" '
-      'request_log_transaction_id="$http_x_log_transaction_id" '
-      'bytes_request="$request_length" '
-      'bytes_response="$body_bytes_sent" '
-      'server_protocol="$server_protocol" '
-      'server_port="$server_port" '
-      'upstream_addr="$upstream_addr" '
-      'time_request="$request_time" '
-      'time_upstream_connect="$upstream_connect_time" '
-      'time_upstream_header="$upstream_header_time" '
-      'time_upstream_response="$upstream_response_time"'
-      ;
+    log_format logjson escape=json
+      '{'
+      '"ts":"$time_iso8601", '
+      '"method":"$request_method", '
+      '"request_uri":"$request_uri", '
+      '"status":"$status", '
+      '"host":"$host", '
+      '"scheme":"$scheme", '
+      '"user_http_referer":"$http_referer", '
+      '"user_agent":"$http_user_agent", '
+      '"user_remote_addr":"$remote_addr", '
+      '"user_remote_port":"$remote_port", '
+      '"proxy_addr":"$realip_remote_addr", '
+      '"proxy_port":"$realip_remote_port", '
+      '"request_id":"$request_id", '
+      '"request_log_transaction_id":"$http_x_log_transaction_id", '
+      '"bytes_request":"$request_length", '
+      '"bytes_response":"$body_bytes_sent", '
+      '"server_protocol":"$server_protocol", '
+      '"server_port":"$server_port", '
+      '"upstream_addr":"$upstream_addr", '
+      '"time_request":"$request_time", '
+      '"time_upstream_connect":"$upstream_connect_time", '
+      '"time_upstream_header":"$upstream_header_time", '
+      '"time_upstream_response":"$upstream_response_time"'
+      '}';
 
-    access_log /var/log/nginx/access.log logfmt;
+    access_log /var/log/nginx/access.log logjson;
     error_log /var/log/nginx/error.log {{ getenv "NGINX_ERROR_LOG_LEVEL" "warn" }};
 
     include /etc/nginx/conf.d/*.conf;

etc/supervisor/conf.d/email.conf.tmpl

@@ -18,11 +18,11 @@ group=dp_app
 startsecs=1
 numprocs={{ getenv "SVC_EMAIL_COLLECT_NUMPROCS" "1" }}
 stopsignal=INT
-stopwaitsecs=30
+stopwaitsecs={{ getenv "FAST_SHUTDOWN" "false" | ternary "0" "30" }}
 redirect_stderr=true
 stdout_logfile=/var/log/supervisor/email_collect.log
-stdout_logfile_maxbytes=10000000
-stdout_logfile_backups=1
+stdout_logfile_maxbytes=0 {{/* Our rotate-logs task will handle rotation */}}
+stdout_logfile_backups=0
 
 [program:email_process]
 process_name=%(program_name)s_%(process_num)02d
@@ -35,8 +35,8 @@ group=dp_app
 startsecs=1
 numprocs={{ getenv "SVC_EMAIL_PROCESS_NUMPROCS" "1" }}
 stopsignal=INT
-stopwaitsecs=30
+stopwaitsecs={{ getenv "FAST_SHUTDOWN" "false" | ternary "0" "30" }}
 redirect_stderr=true
 stdout_logfile=/var/log/supervisor/email_process.log
-stdout_logfile_maxbytes=10000000
-stdout_logfile_backups=1
+stdout_logfile_maxbytes=0 {{/* Our rotate-logs task will handle rotation */}}
+stdout_logfile_backups=0

etc/supervisor/conf.d/logging.conf.tmpl

@@ -1,33 +1,30 @@
 [program:vector]
-command=/usr/local/bin/vector --quiet --config /etc/vector/vector.toml --config /etc/vector/vector.d/*.toml --color never --log-format json
+command=/usr/local/bin/vector --watch-config --config /etc/vector/vector.toml --config /etc/vector/vector.d/*.toml --color never --log-format json
 user=vector
 umask=002
 numprocs=1
 startsecs=0
 autostart=true
 autorestart=true
-# output would be from console sink, which we want to pass
-# on to stdout on the container (which would get consumed by docker logs)
-stdout_logfile=/dev/fd/1
-stdout_logfile_maxbytes=0
-stderr_logfile=/dev/fd/2
-stderr_logfile_maxbytes=0
-redirect_stderr=false
+redirect_stderr=true
+stdout_logfile=/var/log/vector.log
+stdout_logfile_maxbytes=10000000
+stdout_logfile_backups=0
 stopsignal=TERM
-stopwaitsecs=8
+stopwaitsecs={{ getenv "FAST_SHUTDOWN" "false" | ternary "0" "8" }}
 # makes vector start first and shut down last so it
 # will read logs from other processes during shutdown
 priority=0
-environment=VECTOR_MARKER="{{ getenv "VECTOR_MARKER" "" }}"
+environment=VECTOR_MARKER="{{ getenv "VECTOR_MARKER" "" }}",VECTOR_COLOR=never
 
 [eventlistener:rotate_logs]
 command=/etc/supervisor/rotate-logs
 events=TICK_60
 autorestart=true
 buffer_size=1
 stderr_logfile=/var/log/supervisor/rotate_logs.log
-stdout_logfile_maxbytes=10000000
-stdout_logfile_backups=1
+stdout_logfile_maxbytes=0 {{/* Our rotate-logs task will handle rotation */}}
+stdout_logfile_backups=0
 stopsignal=KILL
 stopwaitsecs=0
 environment=VECTOR_MARKER="{{ getenv "VECTOR_MARKER" "" }}"

etc/supervisor/conf.d/messenger.conf.tmpl

@@ -5,10 +5,11 @@ autorestart=true
 exitcodes=0
 user=dp_app
 group=dp_app
+stopwaitsecs={{ getenv "FAST_SHUTDOWN" "false" | ternary "0" "10" }}
 startsecs=1
 startretries=3
 redirect_stderr=true
 stdout_logfile=/var/log/supervisor/svc_messenger_api.log
-stdout_logfile_maxbytes=10000000
-stdout_logfile_backups=1
+stdout_logfile_maxbytes=0 {{/* Our rotate-logs task will handle rotation */}}
+stdout_logfile_backups=0
 environment=HOSTNAME=127.0.0.1,PORT=24000

etc/supervisor/conf.d/tasks.conf.tmpl

@@ -9,8 +9,8 @@ startsecs=1
 stopsignal=INT
 redirect_stderr=true
 stdout_logfile=/var/log/supervisor/tasks.log
-stdout_logfile_maxbytes=10000000
-stdout_logfile_backups=1
+stdout_logfile_maxbytes=0 {{/* Our rotate-logs task will handle rotation */}}
+stdout_logfile_backups=0
 stopsignal=TERM
-stopwaitsecs=60
+stopwaitsecs={{ getenv "FAST_SHUTDOWN" "false" | ternary "0" "60" }}
 environment=CRON_STATUS_FILEPATH="{{ getenv "CRON_STATUS_FILEPATH" "" }}"

etc/supervisor/conf.d/web.conf.tmpl

@@ -7,14 +7,14 @@ startsecs=1
 startretries=3
 redirect_stderr=true
 stdout_logfile=/var/log/supervisor/nginx.log
-stdout_logfile_maxbytes=10000000
-stdout_logfile_backups=1
+stdout_logfile_maxbytes=0 {{/* Our rotate-logs task will handle rotation */}}
+stdout_logfile_backups=0
 {{if conv.ToBool (getenv "HTTP_INTERNAL_MODE") }}
 stopsignal=TERM
 stopwaitsecs=0
 {{else}}
 stopsignal=QUIT
-stopwaitsecs=60
+stopwaitsecs={{ getenv "FAST_SHUTDOWN" "false" | ternary "0" "60" }}
 {{end}}
 
 [program:php_fpm]
@@ -26,12 +26,12 @@ startsecs=1
 startretries=3
 redirect_stderr=true
 stdout_logfile=/var/log/supervisor/php_fpm.log
-stdout_logfile_maxbytes=10000000
-stdout_logfile_backups=1
+stdout_logfile_maxbytes=0 {{/* Our rotate-logs task will handle rotation */}}
+stdout_logfile_backups=0
 {{if conv.ToBool (getenv "HTTP_INTERNAL_MODE") }}
 stopsignal=TERM
 stopwaitsecs=0
 {{else}}
 stopsignal=TERM
-stopwaitsecs=60
+stopwaitsecs={{ getenv "FAST_SHUTDOWN" "false" | ternary "0" "60" }}
 {{end}}

etc/supervisor/rotate-logs

@@ -1,9 +1,9 @@
 #!/bin/bash
 
 # This command is run every 60 seconds (see conf.d/logging.conf rotate_logs event listener)
-# This will read log files and rotate them from mylog.log to mylog.log.1 if they are 10MB or larger.
+# This will read log files and rotate them from mylog.log to mylog.log.1 if they are 15MB or larger.
 #
-# This is because the logs in the filesystem are only meant to be temporary buffers.
+# This is because the logs in the filesystem are only meant to be temporary.
 #
 # Vector is used to process and ship the logs elsewhere. Most commonly this will
 # be by outputting all logs to stdout (e.g. for docker logs) or to output them
@@ -19,16 +19,16 @@ while read -r header; do
   read -r -n "$bytes" event
   echo "$event" >&2
 
-  find /var/log -type f -name '*.log' -size +10M -not -path /var/log/docker-logs | while read f; do
+  find /var/log -type f -name '*.log' -size +15M -not -path /var/log/docker-logs | while read f; do
     echo "Rotating $f ($(stat -c%s "$f"))" >&2
+
+    # Copy this file then truncate it below (i.e. analogous to logrotate copytruncate)
     copy "$f" "$f.1"
-    echo "[$(date -u +"%Y-%m-%dT%H:%M:%SZ")] Log file started: $f -- ${VECTOR_MARKER}" > "$f"
-  done
 
-  # always correct log files in /var/log/deskpro
-  # (e.g. if someone ran script as root it could create a *new* log file)
-  find /var/log/deskpro -type f -name '*.log' -not -user dp_app | while read f; do
-    chown dp_app:adm "$f"
+    # Vector uses the first line to determine if a file was changed
+    # So this first line would change (new time) so Vector knows to re-process the file
+    # (VECTOR_MARKER is used from our transformations to know we can ignore the line itself)
+    echo "[$(date -u +"%Y-%m-%dT%H:%M:%SZ")] Log file started: $f -- ${VECTOR_MARKER}" > "$f"
   done
 
   printf "RESULT 2\nOK"

etc/supervisor/supervisord-exit-on-failure

@@ -1,5 +1,7 @@
 #!/bin/bash
 
+# This script is used to exit the container if a process fails to start properly (i.e. becomes unhealthy)
+
 printf "READY\n";
 
 while read -r header; do
@@ -8,7 +10,7 @@ while read -r header; do
   echo "------------------------------" >&2
   echo "" >&2
   echo "" >&2
-  
+
   echo "$header" >&2
   bytes=$(echo "$header" | sed 's/.*\://')
   read -r -n "$bytes" event