Add timestamps to pod logs

changelogs/unreleased/ak-logs-timestamp.yml

+---
+title: Add timestamps to pod logs
+merge_request: 21663
+author:
+type: added

ee/app/assets/javascripts/logs/stores/getters.js

-export const trace = state => state.logs.lines.join('\n');
+import dateFormat from 'dateformat';
+
+export const trace = state =>
+  state.logs.lines
+    .map(item => [dateFormat(item.timestamp, 'UTC:mmm dd HH:MM:ss.l"Z"'), item.message].join(' | '))
+    .join('\n');
 
 // prevent babel-plugin-rewire from generating an invalid default during karma tests
 export default () => {};

ee/app/models/ee/clusters/platforms/kubernetes.rb

@@ -99,10 +99,18 @@ module EE
 
         def platform_pod_logs(namespace, pod_name, container_name)
           logs = kubeclient.get_pod_log(
-            pod_name, namespace, container: container_name, tail_lines: LOGS_LIMIT
+            pod_name, namespace, container: container_name, tail_lines: LOGS_LIMIT, timestamps: true
           ).body
 
-          logs.strip.split("\n")
+          logs.strip.split("\n").map do |line|
+            # message contains a RFC3339Nano timestamp, then a space, then the log line.
+            # resolution of the nanoseconds can vary, so we split on the first space
+            values = line.split(' ', 2)
+            {
+              timestamp: values[0],
+              message: values[1]
+            }
+          end
         end
 
         def elastic_stack_pod_logs(namespace, pod_name, container_name)

ee/lib/gitlab/elasticsearch/logs.rb

@@ -51,14 +51,19 @@ module Gitlab
             { "@timestamp": { order: :desc } },
             { "offset": { order: :desc } }
           ],
-          # only return the message field in the response
-          _source: ["message"],
+          # only return these fields in the response
+          _source: ["@timestamp", "message"],
           # fixed limit for now, we should support paginated queries
           size: ::Gitlab::Elasticsearch::Logs::LOGS_LIMIT
         }
 
         response = @client.search body: body
-        result = response.fetch("hits", {}).fetch("hits", []).map { |h| h["_source"]["message"] }
+        result = response.fetch("hits", {}).fetch("hits", []).map do |hit|
+          {
+            timestamp: hit["_source"]["@timestamp"],
+            message: hit["_source"]["message"]
+          }
+        end
 
         # we queried for the N-most recent records but we want them ordered oldest to newest
         result.reverse

ee/spec/features/projects/environments_pod_logs_spec.rb

@@ -70,7 +70,7 @@ describe 'Environment > Pod Logs', :js do
           expect(item.text).to eq(pod_names[i])
         end
       end
-      expect(page).to have_content("Log 1 Log 2 Log 3")
+      expect(page).to have_content("Dec 13 14:04:22.123Z | Log 1 Dec 13 14:04:23.123Z | Log 2 Dec 13 14:04:24.123Z | Log 3")
     end
   end
 

ee/spec/fixtures/lib/elasticsearch/logs_response.json

@@ -18,7 +18,8 @@
         "_id": "SkbxAW4BWzhswgK-C5-R",
         "_score": null,
         "_source": {
-          "message": "10.8.2.1 - - [25/Oct/2019:08:03:22 UTC] \"GET / HTTP/1.1\" 200 13"
+          "message": "10.8.2.1 - - [25/Oct/2019:08:03:22 UTC] \"GET / HTTP/1.1\" 200 13",
+          "@timestamp": "2019-12-13T14:35:34.034Z"
         },
         "sort": [
           9999998,
@@ -31,7 +32,8 @@
         "_id": "wEigD24BWzhswgK-WUU2",
         "_score": null,
         "_source": {
-          "message": "10.8.2.1 - - [27/Oct/2019:23:49:54 UTC] \"GET / HTTP/1.1\" 200 13"
+          "message": "10.8.2.1 - - [27/Oct/2019:23:49:54 UTC] \"GET / HTTP/1.1\" 200 13",
+          "@timestamp": "2019-12-13T14:35:35.034Z"
         },
         "sort": [
           9999949,
@@ -44,7 +46,8 @@
         "_id": "gE6uOG4BWzhswgK-M0x2",
         "_score": null,
         "_source": {
-          "message": "10.8.2.1 - - [04/Nov/2019:23:09:24 UTC] \"GET / HTTP/1.1\" 200 13"
+          "message": "10.8.2.1 - - [04/Nov/2019:23:09:24 UTC] \"GET / HTTP/1.1\" 200 13",
+          "@timestamp": "2019-12-13T14:35:36.034Z"
         },
         "sort": [
           9999944,
@@ -57,7 +60,8 @@
         "_id": "0klPHW4BWzhswgK-nfCF",
         "_score": null,
         "_source": {
-          "message": "- -\u003e /"
+          "message": "- -\u003e /",
+          "@timestamp": "2019-12-13T14:35:37.034Z"
         },
         "sort": [
           9999934,

ee/spec/frontend/logs/components/environment_logs_spec.js

@@ -10,7 +10,8 @@ import {
   mockEnvName,
   mockEnvironments,
   mockPods,
-  mockLines,
+  mockLogsResult,
+  mockTrace,
   mockPodName,
   mockEnvironmentsEndpoint,
 } from '../mock_data';
@@ -152,14 +153,14 @@ describe('EnvironmentLogs', () => {
         [state.pods.current] = state.pods.options;
 
         state.logs.isComplete = false;
-        state.logs.lines = mockLines;
+        state.logs.lines = mockLogsResult;
       });
       actionMocks.showPodLogs.mockImplementation(podName => {
         state.pods.options = mockPods;
         [state.pods.current] = podName;
 
         state.logs.isComplete = false;
-        state.logs.lines = mockLines;
+        state.logs.lines = mockLogsResult;
       });
       actionMocks.fetchEnvironments.mockImplementation(() => {
         state.environments.options = mockEnvironments;
@@ -200,8 +201,8 @@ describe('EnvironmentLogs', () => {
 
     it('populates logs trace', () => {
       const trace = findLogTrace();
-      expect(trace.text().split('\n').length).toBe(mockLines.length);
-      expect(trace.text().split('\n')).toEqual(mockLines);
+      expect(trace.text().split('\n').length).toBe(mockTrace.length);
+      expect(trace.text().split('\n')).toEqual(mockTrace);
     });
 
     it('update control buttons state', () => {

ee/spec/frontend/logs/mock_data.js

@@ -24,19 +24,57 @@ export const mockPods = [
   'production-764c58d697-ddddd',
 ];
 
-export const mockLines = [
-  '10.36.0.1 - - [16/Oct/2019:06:29:48 UTC] "GET / HTTP/1.1" 200 13',
-  '- -> /',
-  '10.36.0.1 - - [16/Oct/2019:06:29:57 UTC] "GET / HTTP/1.1" 200 13',
-  '- -> /',
-  '10.36.0.1 - - [16/Oct/2019:06:29:58 UTC] "GET / HTTP/1.1" 200 13',
-  '- -> /',
-  '10.36.0.1 - - [16/Oct/2019:06:30:07 UTC] "GET / HTTP/1.1" 200 13',
-  '- -> /',
-  '10.36.0.1 - - [16/Oct/2019:06:30:08 UTC] "GET / HTTP/1.1" 200 13',
-  '- -> /',
-  '10.36.0.1 - - [16/Oct/2019:06:30:17 UTC] "GET / HTTP/1.1" 200 13',
-  '- -> /',
-  '10.36.0.1 - - [16/Oct/2019:06:30:18 UTC] "GET / HTTP/1.1" 200 13',
-  '- -> /',
+export const mockLogsResult = [
+  {
+    timestamp: '2019-12-13T13:43:18.2760123Z',
+    message: '10.36.0.1 - - [16/Oct/2019:06:29:48 UTC] "GET / HTTP/1.1" 200 13',
+  },
+  { timestamp: '2019-12-13T13:43:18.2760123Z', message: '- -> /' },
+  {
+    timestamp: '2019-12-13T13:43:26.8420123Z',
+    message: '10.36.0.1 - - [16/Oct/2019:06:29:57 UTC] "GET / HTTP/1.1" 200 13',
+  },
+  { timestamp: '2019-12-13T13:43:26.8420123Z', message: '- -> /' },
+  {
+    timestamp: '2019-12-13T13:43:28.3710123Z',
+    message: '10.36.0.1 - - [16/Oct/2019:06:29:58 UTC] "GET / HTTP/1.1" 200 13',
+  },
+  { timestamp: '2019-12-13T13:43:28.3710123Z', message: '- -> /' },
+  {
+    timestamp: '2019-12-13T13:43:36.8860123Z',
+    message: '10.36.0.1 - - [16/Oct/2019:06:30:07 UTC] "GET / HTTP/1.1" 200 13',
+  },
+  { timestamp: '2019-12-13T13:43:36.8860123Z', message: '- -> /' },
+  {
+    timestamp: '2019-12-13T13:43:38.4000123Z',
+    message: '10.36.0.1 - - [16/Oct/2019:06:30:08 UTC] "GET / HTTP/1.1" 200 13',
+  },
+  { timestamp: '2019-12-13T13:43:38.4000123Z', message: '- -> /' },
+  {
+    timestamp: '2019-12-13T13:43:46.8420123Z',
+    message: '10.36.0.1 - - [16/Oct/2019:06:30:17 UTC] "GET / HTTP/1.1" 200 13',
+  },
+  { timestamp: '2019-12-13T13:43:46.8430123Z', message: '- -> /' },
+  {
+    timestamp: '2019-12-13T13:43:48.3240123Z',
+    message: '10.36.0.1 - - [16/Oct/2019:06:30:18 UTC] "GET / HTTP/1.1" 200 13',
+  },
+  { timestamp: '2019-12-13T13:43:48.3250123Z', message: '- -> /' },
+];
+
+export const mockTrace = [
+  'Dec 13 13:43:18.276Z | 10.36.0.1 - - [16/Oct/2019:06:29:48 UTC] "GET / HTTP/1.1" 200 13',
+  'Dec 13 13:43:18.276Z | - -> /',
+  'Dec 13 13:43:26.842Z | 10.36.0.1 - - [16/Oct/2019:06:29:57 UTC] "GET / HTTP/1.1" 200 13',
+  'Dec 13 13:43:26.842Z | - -> /',
+  'Dec 13 13:43:28.371Z | 10.36.0.1 - - [16/Oct/2019:06:29:58 UTC] "GET / HTTP/1.1" 200 13',
+  'Dec 13 13:43:28.371Z | - -> /',
+  'Dec 13 13:43:36.886Z | 10.36.0.1 - - [16/Oct/2019:06:30:07 UTC] "GET / HTTP/1.1" 200 13',
+  'Dec 13 13:43:36.886Z | - -> /',
+  'Dec 13 13:43:38.400Z | 10.36.0.1 - - [16/Oct/2019:06:30:08 UTC] "GET / HTTP/1.1" 200 13',
+  'Dec 13 13:43:38.400Z | - -> /',
+  'Dec 13 13:43:46.842Z | 10.36.0.1 - - [16/Oct/2019:06:30:17 UTC] "GET / HTTP/1.1" 200 13',
+  'Dec 13 13:43:46.843Z | - -> /',
+  'Dec 13 13:43:48.324Z | 10.36.0.1 - - [16/Oct/2019:06:30:18 UTC] "GET / HTTP/1.1" 200 13',
+  'Dec 13 13:43:48.325Z | - -> /',
 ];

ee/spec/frontend/logs/stores/actions_spec.js

@@ -14,7 +14,7 @@ import {
   mockEnvironmentsEndpoint,
   mockEnvironments,
   mockPods,
-  mockLines,
+  mockLogsResult,
   mockEnvName,
 } from '../mock_data';
 
@@ -122,7 +122,7 @@ describe('Logs Store actions', () => {
         .reply(200, {
           pod_name: mockPodName,
           pods: mockPods,
-          logs: mockLines,
+          logs: mockLogsResult,
         });
 
       mock.onGet(endpoint).replyOnce(202); // mock reactive cache
@@ -136,7 +136,7 @@ describe('Logs Store actions', () => {
           { type: types.REQUEST_LOGS_DATA },
           { type: types.SET_CURRENT_POD_NAME, payload: mockPodName },
           { type: types.RECEIVE_PODS_DATA_SUCCESS, payload: mockPods },
-          { type: types.RECEIVE_LOGS_DATA_SUCCESS, payload: mockLines },
+          { type: types.RECEIVE_LOGS_DATA_SUCCESS, payload: mockLogsResult },
         ],
         [],
         done,
@@ -152,7 +152,7 @@ describe('Logs Store actions', () => {
       mock.onGet(endpoint, { params: { environment_name: mockEnvName } }).reply(200, {
         pod_name: mockPodName,
         pods: mockPods,
-        logs: mockLines,
+        logs: mockLogsResult,
       });
       mock.onGet(endpoint).replyOnce(202); // mock reactive cache
 
@@ -165,7 +165,7 @@ describe('Logs Store actions', () => {
           { type: types.REQUEST_LOGS_DATA },
           { type: types.SET_CURRENT_POD_NAME, payload: mockPodName },
           { type: types.RECEIVE_PODS_DATA_SUCCESS, payload: mockPods },
-          { type: types.RECEIVE_LOGS_DATA_SUCCESS, payload: mockLines },
+          { type: types.RECEIVE_LOGS_DATA_SUCCESS, payload: mockLogsResult },
         ],
         [],
         done,

ee/spec/frontend/logs/stores/getters_spec.js

 import * as getters from 'ee/logs/stores/getters';
 import logsPageState from 'ee/logs/stores/state';
 
-import { mockLines } from '../mock_data';
+import { mockLogsResult, mockTrace } from '../mock_data';
 
 describe('Logs Store getters', () => {
   let state;
@@ -29,11 +29,11 @@ describe('Logs Store getters', () => {
 
     describe('when state logs are set', () => {
       beforeEach(() => {
-        state.logs.lines = mockLines;
+        state.logs.lines = mockLogsResult;
       });
 
       it('returns an empty string', () => {
-        expect(getters.trace(state)).toEqual(mockLines.join('\n'));
+        expect(getters.trace(state)).toEqual(mockTrace.join('\n'));
       });
     });
   });

ee/spec/frontend/logs/stores/mutations_spec.js

@@ -8,7 +8,7 @@ import {
   mockEnvironments,
   mockPods,
   mockPodName,
-  mockLines,
+  mockLogsResult,
 } from '../mock_data';
 
 describe('Logs Store Mutations', () => {
@@ -83,11 +83,11 @@ describe('Logs Store Mutations', () => {
 
   describe('RECEIVE_LOGS_DATA_SUCCESS', () => {
     it('receives logs lines', () => {
-      mutations[types.RECEIVE_LOGS_DATA_SUCCESS](state, mockLines);
+      mutations[types.RECEIVE_LOGS_DATA_SUCCESS](state, mockLogsResult);
 
       expect(state.logs).toEqual(
         expect.objectContaining({
-          lines: mockLines,
+          lines: mockLogsResult,
           isLoading: false,
           isComplete: true,
         }),

ee/spec/lib/gitlab/elasticsearch/logs_spec.rb

@@ -5,10 +5,10 @@ require 'spec_helper'
 describe Gitlab::Elasticsearch::Logs do
   let(:client) { Elasticsearch::Transport::Client }
 
-  let(:es_message_1) { "10.8.2.1 - - [25/Oct/2019:08:03:22 UTC] \"GET / HTTP/1.1\" 200 13" }
-  let(:es_message_2) { "10.8.2.1 - - [27/Oct/2019:23:49:54 UTC] \"GET / HTTP/1.1\" 200 13" }
-  let(:es_message_3) { "10.8.2.1 - - [04/Nov/2019:23:09:24 UTC] \"GET / HTTP/1.1\" 200 13" }
-  let(:es_message_4) { "- -\u003e /" }
+  let(:es_message_1) { { timestamp: "2019-12-13T14:35:34.034Z", message: "10.8.2.1 - - [25/Oct/2019:08:03:22 UTC] \"GET / HTTP/1.1\" 200 13" } }
+  let(:es_message_2) { { timestamp: "2019-12-13T14:35:35.034Z", message: "10.8.2.1 - - [27/Oct/2019:23:49:54 UTC] \"GET / HTTP/1.1\" 200 13" } }
+  let(:es_message_3) { { timestamp: "2019-12-13T14:35:36.034Z", message: "10.8.2.1 - - [04/Nov/2019:23:09:24 UTC] \"GET / HTTP/1.1\" 200 13" } }
+  let(:es_message_4) { { timestamp: "2019-12-13T14:35:37.034Z", message: "- -\u003e /" } }
 
   let(:es_response) { JSON.parse(fixture_file('lib/elasticsearch/logs_response.json', dir: 'ee')) }
 
@@ -53,6 +53,7 @@ describe Gitlab::Elasticsearch::Logs do
         }
       ],
       _source: [
+          "@timestamp",
           "message"
       ],
       size: 500
@@ -101,6 +102,7 @@ describe Gitlab::Elasticsearch::Logs do
         }
       ],
       _source: [
+          "@timestamp",
           "message"
       ],
       size: 500

ee/spec/models/ee/clusters/platforms/kubernetes_spec.rb

@@ -141,12 +141,19 @@ describe Clusters::Platforms::Kubernetes do
     let(:pod_name) { 'pod-1' }
     let(:namespace) { 'app' }
     let(:container) { 'some-container' }
+    let(:expected_logs) do
+      [
+        { message: "Log 1", timestamp: "2019-12-13T14:04:22.123456Z" },
+        { message: "Log 2", timestamp: "2019-12-13T14:04:23.123456Z" },
+        { message: "Log 3", timestamp: "2019-12-13T14:04:24.123456Z" }
+      ]
+    end
 
     subject { service.read_pod_logs(environment.id, pod_name, namespace, container: container) }
 
     shared_examples 'successful log request' do
       it do
-        expect(subject[:logs]).to eq(["Log 1", "Log 2", "Log 3"])
+        expect(subject[:logs]).to eq(expected_logs)
         expect(subject[:status]).to eq(:success)
         expect(subject[:pod_name]).to eq(pod_name)
         expect(subject[:container_name]).to eq(container)
@@ -171,7 +178,7 @@ describe Clusters::Platforms::Kubernetes do
 
         before do
           expect_any_instance_of(::Clusters::Applications::ElasticStack).to receive(:elasticsearch_client).at_least(:once).and_return(Elasticsearch::Transport::Client.new)
-          expect_any_instance_of(::Gitlab::Elasticsearch::Logs).to receive(:pod_logs).and_return(["Log 1", "Log 2", "Log 3"])
+          expect_any_instance_of(::Gitlab::Elasticsearch::Logs).to receive(:pod_logs).and_return(expected_logs)
           stub_feature_flags(enable_cluster_application_elastic_stack: true)
         end
 

spec/support/helpers/kubernetes_helpers.rb

@@ -84,7 +84,7 @@ module KubernetesHelpers
     end
 
     logs_url = service.api_url + "/api/v1/namespaces/#{namespace}/pods/#{pod_name}" \
-    "/log?#{container_query_param}tailLines=#{Clusters::Platforms::Kubernetes::LOGS_LIMIT}"
+    "/log?#{container_query_param}tailLines=#{Clusters::Platforms::Kubernetes::LOGS_LIMIT}&timestamps=true"
 
     if status
       response = { status: status }
@@ -331,7 +331,7 @@ module KubernetesHelpers
   end
 
   def kube_logs_body
-    "Log 1\nLog 2\nLog 3"
+    "2019-12-13T14:04:22.123456Z Log 1\n2019-12-13T14:04:23.123456Z Log 2\n2019-12-13T14:04:24.123456Z Log 3"
   end
 
   def kube_deployments_body