diff --git a/integration-tests/environment_log_test.go b/integration-tests/environment_log_test.go new file mode 100644 index 000000000..efd3caea2 --- /dev/null +++ b/integration-tests/environment_log_test.go @@ -0,0 +1,362 @@ +package tests + +import ( + "encoding/json" + "fmt" + "net/http" + "net/http/httptest" + "net/url" + "strconv" + "strings" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/upsun/cli/pkg/mockapi" + "github.com/upsun/cli/pkg/mockssh" +) + +func TestEnvironmentLogAPI(t *testing.T) { + authServer := mockapi.NewAuthServer(t) + defer authServer.Close() + + apiHandler := mockapi.NewHandler(t) + apiServer := httptest.NewServer(apiHandler) + defer apiServer.Close() + + projectID := mockapi.ProjectID() + apiHandler.SetProjects([]*mockapi.Project{{ + ID: projectID, + Links: mockapi.MakeHALLinks("self=/projects/"+projectID, + "environments=/projects/"+projectID+"/environments"), + DefaultBranch: "main", + }}) + apiHandler.SetEnvironments([]*mockapi.Environment{makeEnv(projectID, "main", "production", "active", nil)}) + + // 150 log lines, one per second, ending 20 seconds ago. + end := time.Now().Add(-20 * time.Second).UTC().Truncate(time.Second) + type logLine struct { + Cursor string `json:"cursor"` + Datetime string `json:"datetime"` + Severity string `json:"severity"` + Service string `json:"service"` + LogKind string `json:"log_kind"` + Content string `json:"content"` + Context string `json:"context,omitempty"` + } + lines := make([]logLine, 0, 150) + for i := range 150 { + ts := end.Add(time.Duration(i-149) * time.Second) + severity := "INFO" + if i%50 == 0 { + severity = "ERROR" + } + lines = append(lines, logLine{ + Cursor: fmt.Sprintf("%026d", i), + Datetime: ts.Format("2006-01-02T15:04:05.000Z"), + Severity: severity, + Service: "app", + LogKind: "access", + Content: fmt.Sprintf("line %d", i), + }) + } + + lines[149].Context = `{"404":0,"a":1,"b":2,"c":3,"d":4,"e":5,"f":6,"g":7,` + + `"long":"` + strings.Repeat("x", 100) + `","h":8,"i":9}` + lines[100].Context = `{"time":"x","level":"ERROR","msg":"line 100","status":500,"path":"/a b","trace_id":"abc",` + + `"req":{"method":"GET"},"keys":["k"]}` + + var ( + mu sync.Mutex + queries []url.Values + // Wider windows are rejected with 499, when set. + maxWindow int64 + ) + envPath := "/projects/" + projectID + "/environments/main" + queryPath := envPath + "/observability/logs/query" + apiHandler.Get(envPath+"/observability/", func(w http.ResponseWriter, _ *http.Request) { + _ = json.NewEncoder(w).Encode(map[string]any{ + "_links": mockapi.MakeHALLinks("logs_query=" + apiServer.URL + queryPath), + "data_retention": map[string]any{ + "logs": map[string]any{"retention_period": 1440, "max_range": 64800, "recommended_default_range": 15}, + }, + }) + }) + // Modeled on the API: pages of up to 100 lines, filtered by time, cursor and severity. + apiHandler.Get(queryPath, func(w http.ResponseWriter, r *http.Request) { + q := r.URL.Query() + mu.Lock() + queries = append(queries, q) + mu.Unlock() + from, _ := strconv.ParseInt(q.Get("from"), 10, 64) + to, _ := strconv.ParseInt(q.Get("to"), 10, 64) + mu.Lock() + tooWide := maxWindow > 0 && to-from > maxWindow + mu.Unlock() + if tooWide { + w.WriteHeader(499) + _ = json.NewEncoder(w).Encode(map[string]any{"code": 499, "message": "Too much data fetched."}) + return + } + cursor := q.Get("cursor") + desc := q.Get("order_by") != "ASC" + severities := map[string]bool{} + for _, s := range q["severities[]"] { + severities[s] = true + } + var matched []logLine + for i := range lines { + l := lines[len(lines)-1-i] + if !desc { + l = lines[i] + } + ts, _ := time.Parse(time.RFC3339, l.Datetime) + if ts.Unix() < from || ts.Unix() >= to { + continue + } + if cursor != "" && ((desc && l.Cursor >= cursor) || (!desc && l.Cursor <= cursor)) { + continue + } + if len(severities) > 0 && !severities[l.Severity] { + continue + } + matched = append(matched, l) + } + hasMore := len(matched) > 100 + if hasMore { + matched = matched[:100] + } + next := cursor + if len(matched) > 0 { + next = matched[len(matched)-1].Cursor + } + _ = json.NewEncoder(w).Encode(map[string]any{ + "_cursor": next, + "_has_more_results": hasMore, + "data": matched, + }) + }) + + f := newCommandFactory(t, apiServer.URL, authServer.URL) + f.extraEnv = []string{EnvPrefix + "LOG_PROTOCOL=auto"} + + // The default is 100 lines, oldest first. + out := f.Run("log", "access", "-p", projectID, "-e", "main", "--format", "raw") + assert.Equal(t, "line 50\n", out[:len("line 50\n")]) + assert.Contains(t, out, "\nline 149\n") + assert.NotContains(t, out, "line 49\n") + + mu.Lock() + first := queries[0] + mu.Unlock() + assert.Equal(t, []string{"access"}, first["log_kinds[]"]) + assert.Equal(t, "1", first.Get("log_kinds_mode")) + assert.Equal(t, "DESC", first.Get("order_by")) + + // Pagination and multiple time windows. + out = f.Run("log", "access", "-p", projectID, "-e", "main", "--format", "raw", "--lines", "150") + assert.Equal(t, 150, strings.Count(out, "\n")) + + // The "error" type filters by severity. + out = f.Run("log", "error", "-p", projectID, "-e", "main") + assert.Equal(t, 3, strings.Count(out, "\n")) + assert.Contains(t, out, lines[100].Datetime+ + ` app access ERROR line 100 status=500 path="/a b" req.method=GET keys=["k"]`+"\n") + assert.Contains(t, out, lines[50].Datetime+" app access ERROR line 50\n") + + // JSON lines. + out = f.Run("log", "-p", projectID, "-e", "main", "--lines", "1", "--format", "json") + var decoded logLine + require.NoError(t, json.Unmarshal([]byte(out), &decoded)) + assert.Equal(t, lines[149], decoded) + + mu.Lock() + last := queries[len(queries)-1] + mu.Unlock() + assert.Equal(t, []string{"platform"}, last["log_kinds[]"]) + assert.Equal(t, "-1", last.Get("log_kinds_mode")) + + // Filters. + f.Run("log", "-p", projectID, "-e", "main", "-s", "app,worker", "--severity", "warning", "--since", "5m") + mu.Lock() + last = queries[len(queries)-1] + mu.Unlock() + assert.Equal(t, []string{"app", "worker"}, last["services[]"]) + assert.Equal(t, []string{"EMERGENCY", "ALERT", "CRITICAL", "ERROR", "WARNING"}, last["severities[]"]) + from, _ := strconv.ParseInt(last.Get("from"), 10, 64) + assert.InDelta(t, time.Now().Add(-5*time.Minute).Unix(), from, 60) + + // A 499 response halves the window. + mu.Lock() + maxWindow = 600 + queries = nil + mu.Unlock() + out = f.Run("log", "access", "-p", projectID, "-e", "main", "--format", "raw", "--lines", "150") + assert.Equal(t, 150, strings.Count(out, "\n")) + mu.Lock() + maxWindow = 0 + widths := make([]int64, 0, len(queries)) + for _, q := range queries { + from, _ := strconv.ParseInt(q.Get("from"), 10, 64) + to, _ := strconv.ParseInt(q.Get("to"), 10, 64) + widths = append(widths, to-from) + } + mu.Unlock() + assert.Equal(t, []int64{900, 450}, widths[:2]) + + // Invalid time ranges. + _, stdErr, err := f.RunCombinedOutput("log", "-p", projectID, "-e", "main", "--since", "5s", "--until", "10s") + assert.Error(t, err) + assert.Contains(t, stdErr, "The --since time must be before the --until time") + for _, args := range [][]string{{"--since", "+1 hour"}, {"--since", "+1 hour", "--tail"}} { + _, stdErr, err = f.RunCombinedOutput(append([]string{"log", "-p", projectID, "-e", "main"}, args...)...) + assert.Error(t, err) + assert.Contains(t, stdErr, "The --since time must be in the past") + } + + // Context fields are limited in number and length. + out = f.Run("log", "-p", projectID, "-e", "main", "--lines", "1") + assert.Equal(t, lines[149].Datetime+" app access INFO line 149 404=0 a=1 b=2 c=3 d=4 e=5 f=6 g=7"+ + " (+3 more)\n", out) + + // Specific fields. + out = f.Run("log", "error", "-p", projectID, "-e", "main", + "--fields", "datetime,content,context.status,context.req.method,context.missing") + assert.Contains(t, out, lines[100].Datetime+" line 100 status=500 req.method=GET\n") + out = f.Run("log", "-p", projectID, "-e", "main", "--lines", "1", "--fields", "context.long") + assert.Equal(t, "long="+strings.Repeat("x", 100)+"\n", out) + + for _, c := range []struct { + args []string + stdErr string + }{ + {[]string{"--format", "foo"}, "Invalid --format: foo (expected one of: text, raw, json)"}, + {[]string{"--fields", "foo"}, "Invalid field: foo"}, + {[]string{"--fields", "content", "--format", "json"}, `The --fields option can only be used with the "text" format`}, + } { + _, stdErr, err := f.RunCombinedOutput(append([]string{"log", "-p", projectID, "-e", "main"}, c.args...)...) + assert.Error(t, err) + assert.Contains(t, stdErr, c.stdErr) + } + + // The app can be selected by an environment variable. + f.extraEnv = []string{EnvPrefix + "LOG_PROTOCOL=auto", "PLATFORM_APPLICATION_NAME=app"} + f.Run("log", "-p", projectID, "-e", "main") + mu.Lock() + last = queries[len(queries)-1] + mu.Unlock() + assert.Equal(t, []string{"app"}, last["services[]"]) +} + +func TestEnvironmentLogSSHFallback(t *testing.T) { + authServer := mockapi.NewAuthServer(t) + defer authServer.Close() + + sshServer, err := mockssh.NewServer(t, authServer.URL+"/ssh/authority") + require.NoError(t, err) + t.Cleanup(func() { + if err := sshServer.Stop(); err != nil { + t.Error(err) + } + }) + + projectID := mockapi.ProjectID() + apiHandler := mockapi.NewHandler(t) + apiHandler.SetMyUser(&mockapi.User{ID: "my-user-id"}) + apiHandler.SetProjects([]*mockapi.Project{{ + ID: projectID, + Links: mockapi.MakeHALLinks("self=/projects/"+projectID, + "environments=/projects/"+projectID+"/environments"), + DefaultBranch: "main", + }}) + mainEnv := makeEnv(projectID, "main", "production", "active", nil) + mainEnv.SetCurrentDeployment(&mockapi.Deployment{ + WebApps: map[string]mockapi.App{ + "app": {Name: "app", Type: "golang:1.23", Size: "M", Disk: 2048, Mounts: map[string]mockapi.Mount{}}, + }, + Services: map[string]mockapi.App{}, + Workers: map[string]mockapi.Worker{}, + Routes: mockRoutes(), + Links: mockapi.MakeHALLinks("self=/projects/" + projectID + "/environments/main/deployment/current"), + }) + mainEnv.Links["pf:ssh:app:0"] = mockapi.HALLink{HREF: "ssh://app--0@ssh.cli-tests.example.com"} + apiHandler.SetEnvironments([]*mockapi.Environment{mainEnv}) + + apiServer := httptest.NewServer(apiHandler) + defer apiServer.Close() + + // A pseudo status for a successful response that is not JSON. + const htmlBody = -1 + var ( + mu sync.Mutex + entrypointStatus = http.StatusNotFound + ) + envPath := "/projects/" + projectID + "/environments/main" + apiHandler.Get(envPath+"/observability/", func(w http.ResponseWriter, _ *http.Request) { + mu.Lock() + status := entrypointStatus + mu.Unlock() + if status == htmlBody { + _, _ = w.Write([]byte("")) + return + } + if status != http.StatusOK { + w.WriteHeader(status) + return + } + _ = json.NewEncoder(w).Encode(map[string]any{ + "_links": mockapi.MakeHALLinks("logs_query=" + apiServer.URL + envPath + "/observability/logs/query"), + }) + }) + setStatus := func(s int) { + mu.Lock() + defer mu.Unlock() + entrypointStatus = s + } + + f := newCommandFactory(t, apiServer.URL, authServer.URL) + f.extraEnv = []string{ + EnvPrefix + "SSH_OPTIONS=HostName 127.0.0.1\nPort " + strconv.Itoa(sshServer.Port()), + EnvPrefix + "SSH_HOST_KEYS=" + sshServer.HostKeyConfig(), + } + + // The default protocol is SSH, even if the API is available. + setStatus(http.StatusOK) + _, stdErr, _ := f.RunCombinedOutput("log", "access", "-p", projectID, "-e", "main") + assert.Contains(t, stdErr, "Reading log file app--0@ssh.cli-tests.example.com:/var/log/access.log") + _, stdErr, err = f.RunCombinedOutput("log", "access", "-p", projectID, "-e", "main", "--since", "1h") + assert.Error(t, err) + assert.Contains(t, stdErr, `The --since option cannot be used: the log protocol is "ssh"`) + + f.extraEnv = append(f.extraEnv, EnvPrefix+"LOG_PROTOCOL=auto") + + // The observability API responds with 404. + setStatus(http.StatusNotFound) + _, stdErr, _ = f.RunCombinedOutput("log", "access", "-p", projectID, "-e", "main") + assert.Contains(t, stdErr, "Reading log file app--0@ssh.cli-tests.example.com:/var/log/access.log") + + _, stdErr, err = f.RunCombinedOutput("log", "access", "-p", projectID, "-e", "main", "--severity", "error") + assert.Error(t, err) + assert.Contains(t, stdErr, "The --severity option cannot be used: the logs API is not available for this environment") + + // Other entrypoint errors are not a reason to fall back to SSH. + setStatus(http.StatusForbidden) + _, stdErr, err = f.RunCombinedOutput("log", "access", "-p", projectID, "-e", "main") + assert.Error(t, err) + assert.Contains(t, stdErr, "Permission denied") + assert.NotContains(t, stdErr, "Reading log file") + + setStatus(htmlBody) + _, stdErr, err = f.RunCombinedOutput("log", "access", "-p", projectID, "-e", "main") + assert.Error(t, err) + assert.Contains(t, stdErr, "Failed to decode") + assert.NotContains(t, stdErr, "Reading log file") + + // A file name is read over SSH, even if the API is available. + setStatus(http.StatusOK) + _, stdErr, _ = f.RunCombinedOutput("log", "error.log", "-p", projectID, "-e", "main") + assert.Contains(t, stdErr, "Reading log file app--0@ssh.cli-tests.example.com:/var/log/error.log") +} diff --git a/legacy/config-defaults.yaml b/legacy/config-defaults.yaml index c4ce1e7a7..18d02acbb 100644 --- a/legacy/config-defaults.yaml +++ b/legacy/config-defaults.yaml @@ -263,6 +263,10 @@ api: # Whether the Metrics API is enabled. metrics: false + # How the "environment:logs" command reads logs: "ssh" (from log files over SSH), or + # "auto" (from the Observability API if it is available for the environment, otherwise SSH). + log_protocol: ssh + # Whether to show network storage metrics (the "storage" mountpoint) in metrics commands. metrics_storage: true diff --git a/legacy/phpstan-baseline.neon b/legacy/phpstan-baseline.neon index d465fa818..4d80aab21 100644 --- a/legacy/phpstan-baseline.neon +++ b/legacy/phpstan-baseline.neon @@ -2154,24 +2154,12 @@ parameters: count: 3 path: src/Command/Metrics/MetricsCommandBase.php - - - message: '#^Cannot access offset ''href'' on mixed\.$#' - identifier: offsetAccess.nonOffsetAccessible - count: 1 - path: src/Command/Metrics/MetricsCommandBase.php - - message: '#^Cannot access offset ''mountpoints'' on mixed\.$#' identifier: offsetAccess.nonOffsetAccessible count: 1 path: src/Command/Metrics/MetricsCommandBase.php - - - message: '#^Cannot access offset ''resources_overview'' on mixed\.$#' - identifier: offsetAccess.nonOffsetAccessible - count: 1 - path: src/Command/Metrics/MetricsCommandBase.php - - message: '#^Cannot access offset ''services'' on mixed\.$#' identifier: offsetAccess.nonOffsetAccessible @@ -2238,12 +2226,6 @@ parameters: count: 3 path: src/Command/Metrics/MetricsCommandBase.php - - - message: '#^Method Platformsh\\Cli\\Command\\Metrics\\MetricsCommandBase\:\:getResourcesOverviewUrl\(\) should return string\|false but returns mixed\.$#' - identifier: return.type - count: 1 - path: src/Command/Metrics/MetricsCommandBase.php - - message: '#^Parameter \#1 \$array of function array_reverse expects array, mixed given\.$#' identifier: argument.type diff --git a/legacy/src/Command/Environment/EnvironmentLogCommand.php b/legacy/src/Command/Environment/EnvironmentLogCommand.php index f042ec304..dada7461e 100644 --- a/legacy/src/Command/Environment/EnvironmentLogCommand.php +++ b/legacy/src/Command/Environment/EnvironmentLogCommand.php @@ -5,64 +5,640 @@ namespace Platformsh\Cli\Command\Environment; use Platformsh\Cli\Console\Argument; +use Platformsh\Cli\Console\ArrayArgument; use Platformsh\Cli\Console\Option; +use Platformsh\Cli\Selector\Selection; use Platformsh\Cli\Selector\SelectorConfig; +use Platformsh\Cli\Service\Config; use Platformsh\Cli\Service\Io; +use Platformsh\Cli\Service\Observability; use Platformsh\Cli\Selector\Selector; use Doctrine\Common\Cache\CacheProvider; +use GuzzleHttp\Exception\RequestException; use Platformsh\Cli\Service\QuestionHelper; use Platformsh\Cli\Command\CommandBase; use Platformsh\Cli\Util\OsUtil; use Platformsh\Cli\Util\StringUtil; use Symfony\Component\Console\Attribute\AsCommand; use Symfony\Component\Console\Exception\InvalidArgumentException; +use Symfony\Component\Console\Formatter\OutputFormatter; use Symfony\Component\Console\Input\InputArgument; use Symfony\Component\Console\Input\InputInterface; use Symfony\Component\Console\Input\InputOption; use Symfony\Component\Console\Output\OutputInterface; use Platformsh\Cli\Console\HiddenAliases; +/** + * @phpstan-type LogRow array{cursor: string, datetime: string, timestamp: int, severity: string, service: string, log_kind: string, content: string, raw: array} + */ #[AsCommand(name: 'environment:logs', description: "Read an environment's logs", aliases: ['log'])] #[HiddenAliases(['logs'])] class EnvironmentLogCommand extends CommandBase { - public function __construct(private readonly CacheProvider $cacheProvider, private readonly Io $io, private readonly QuestionHelper $questionHelper, private readonly Selector $selector) - { + // Log types mapped to the API's log kinds. + private const LOG_KINDS = [ + 'access' => 'access', + 'app' => 'application', + 'application' => 'application', + 'cron' => 'cron', + 'deploy' => 'deployment', + 'deployment' => 'deployment', + 'post-deploy' => 'deployment', + 'platform' => 'platform', + ]; + + // Severities, from most to least severe. + private const SEVERITIES = ['EMERGENCY', 'ALERT', 'CRITICAL', 'ERROR', 'WARNING', 'NOTICE', 'INFO', 'DEBUG']; + + // Options that only work with the logs API. + private const API_OPTIONS = ['service', 'severity', 'since', 'until', 'fields']; + + private const FORMATS = ['text', 'raw', 'json']; + + private const PROTOCOLS = ['ssh', 'auto']; + + // Fields that can be displayed with --fields, as well as "context.". + private const FIELDS = ['datetime', 'severity', 'service', 'unit', 'instance', 'host', 'command', 'container_id', 'container_image', 'log_kind', 'content', 'context']; + + // Limits for the "context" field, to avoid excessively long lines. + private const MAX_CONTEXT_FIELDS = 8; + private const MAX_CONTEXT_VALUE_LENGTH = 60; + private const MAX_CONTEXT_LENGTH = 200; + + // Top-level keys of structured log lines that are not displayed in the "context" field. + private const SKIP_CONTEXT_KEYS = [ + 'time', 'timestamp', 'ts', '@timestamp', 'datetime', + 'level', 'level_name', 'lvl', 'severity', + 'msg', 'message', + 'trace_id', 'traceid', 'span_id', 'spanid', + ]; + + // How far behind the current time to read when tailing, so that late-arriving logs are not skipped. + private const TAIL_DELAY = 15; + + private const TAIL_INTERVAL = 5; + + // Limits for the time windows queried by fetchRecent(). + private const MIN_WINDOW = 60; + private const MAX_WINDOW = 7 * 86400; + private const WINDOW_GROWTH = 4; + + public function __construct( + private readonly CacheProvider $cacheProvider, + private readonly Config $config, + private readonly Io $io, + private readonly Observability $observability, + private readonly QuestionHelper $questionHelper, + private readonly Selector $selector, + ) { parent::__construct(); } protected function configure(): void { $this - ->addArgument('type', InputArgument::OPTIONAL, 'The log type, e.g. "access" or "error"', null, [ + ->addArgument('type', InputArgument::OPTIONAL, 'The log type: "access", "app", "cron", "deploy", "error" or "platform"', null, [ 'access', - 'error', + 'app', 'cron', 'deploy', - 'app', + 'error', + 'platform', ]) ->addOption('lines', null, InputOption::VALUE_REQUIRED, 'The number of lines to show', 100) - ->addOption('tail', null, InputOption::VALUE_NONE, 'Continuously tail the log'); + ->addOption('tail', null, InputOption::VALUE_NONE, 'Continuously tail the log') + ->addOption('service', 's', InputOption::VALUE_REQUIRED | InputOption::VALUE_IS_ARRAY, 'Filter by service or application name. ' . ArrayArgument::SPLIT_HELP) + ->addOption('severity', null, InputOption::VALUE_REQUIRED, 'The minimum severity, e.g. "error" or "warning"', null, array_map('strtolower', self::SEVERITIES)) + ->addOption('since', null, InputOption::VALUE_REQUIRED, 'Show logs since this time, e.g. "30m", "2h", "1d", or a date/time') + ->addOption('until', null, InputOption::VALUE_REQUIRED, 'Show logs until this time, in the same format as --since') + ->addOption('format', null, InputOption::VALUE_REQUIRED, 'The output format: "text", "raw" (message only), or "json" (one object per line)', 'text', self::FORMATS) + ->addOption('fields', null, InputOption::VALUE_REQUIRED, 'The fields to display in the text format, e.g. "datetime,service,content,context.status". ' . ArrayArgument::SPLIT_HELP, null, self::FIELDS); $this->selector->addProjectOption($this->getDefinition()); $this->selector->addEnvironmentOption($this->getDefinition()); $this->selector->addRemoteContainerOptions($this->getDefinition()); $this->selector->addTaskOption($this->getDefinition()); $this->addCompleter($this->selector); + $envVar = $this->config->getStr('application.env_prefix') . 'LOG_PROTOCOL'; + $this->setHelp(<<$envVar environment variable, or the api.log_protocol config option. + The API is then used where it is available for the environment, and SSH otherwise. + + With the API: + The error type shows logs of any type with a severity of ERROR or higher. + Without a type, all logs are shown except for "platform" logs. + For structured (JSON) log lines, the text format also shows some of the line's fields as key=value pairs. + Use --fields to choose the fields, or --format json to see everything. + Logs take a few seconds to become available, so --tail shows them with a delay of about 15-20 seconds. + SSH is still used if the --worker, --instance or --task option is used, + or if the type is not listed above or ends in .log (e.g. "error.log"). + EOF); $this->addExample('Display a choice of logs that can be read'); $this->addExample('Read the deploy log', 'deploy'); $this->addExample('Read the access log continuously', 'access --tail'); $this->addExample('Read the last 500 lines of the cron log', 'cron --lines 500'); + $this->addExample('Read warnings and errors from the "app" service in the last hour (with the API)', '--service app --severity warning --since 1h'); + $this->addExample('Read HTTP request details from structured logs (with the API)', 'app --fields datetime,service,content,context.method,context.path,context.status'); } protected function execute(InputInterface $input, OutputInterface $output): int { - $selection = $this->selector->getSelection($input, new SelectorConfig(chooseEnvFilter: SelectorConfig::filterEnvsMaybeActive())); + $selection = $this->selector->getSelection($input, new SelectorConfig( + chooseEnvFilter: SelectorConfig::filterEnvsMaybeActive(), + selectRemoteContainer: false, + )); if (Option::bool($input, 'tail') && $this->runningViaMulti) { throw new InvalidArgumentException('The --tail option cannot be used with "multi"'); } $lines = Option::int($input, 'lines'); + if ($lines < 1) { + throw new InvalidArgumentException('The --lines value must be at least 1'); + } + $format = Option::string($input, 'format'); + if (!in_array($format, self::FORMATS, true)) { + throw new InvalidArgumentException(sprintf('Invalid --format: %s (expected one of: %s)', $format, implode(', ', self::FORMATS))); + } + $fields = $this->parseFields($input, $format); + + $protocol = $this->config->getStr('api.log_protocol'); + if (!in_array($protocol, self::PROTOCOLS, true)) { + throw new InvalidArgumentException(sprintf('Invalid log protocol: %s (expected one of: %s)', $protocol, implode(', ', self::PROTOCOLS))); + } + + $logType = Argument::stringOrNull($input, 'type'); + $sshReason = $protocol === 'ssh' + ? sprintf('the log protocol is "ssh" (set %sLOG_PROTOCOL=auto to use the logs API)', $this->config->getStr('application.env_prefix')) + : $this->sshReason($input, $logType); + if ($logType !== null && str_ends_with($logType, '.log')) { + $logType = substr($logType, 0, -4); + } + + $entrypoint = null; + if ($sshReason === null) { + $entrypoint = $this->observability->getEntrypoint($selection->getEnvironment()); + if (Observability::getLink($entrypoint, 'logs_query') === null) { + $sshReason = 'the logs API is not available for this environment'; + } + } + + if ($sshReason === null) { + return $this->readFromApi($input, $output, $selection, (array) $entrypoint, $logType, $lines, $format, $fields); + } + + $this->io->debug('Reading logs via SSH, because ' . $sshReason); + foreach (self::API_OPTIONS as $option) { + $used = $option === 'service' ? ArrayArgument::getOption($input, $option) !== [] : $input->getOption($option) !== null; + if ($used) { + throw new InvalidArgumentException(sprintf('The --%s option cannot be used: %s', $option, $sshReason)); + } + } + if ($format !== 'text') { + throw new InvalidArgumentException(sprintf('The --format option cannot be used: %s', $sshReason)); + } + + return $this->readViaSsh($input, $this->selector->withRemoteContainer($input, $selection), $logType, $lines); + } + + /** + * Returns why the logs must be read over SSH, or null if the API can be used. + */ + private function sshReason(InputInterface $input, ?string $logType): ?string + { + foreach (['worker', 'instance', 'task'] as $option) { + if (Option::stringOrNull($input, $option) !== null) { + return sprintf('the --%s option is used', $option); + } + } + if ($logType !== null && str_ends_with($logType, '.log')) { + return 'a log file name was given'; + } + if ($logType !== null && $logType !== 'error' && !isset(self::LOG_KINDS[$logType])) { + return sprintf('the log type "%s" is not supported by the logs API', $logType); + } + + return null; + } + + /** + * @param array $entrypoint + * @param list|null $fields + */ + private function readFromApi(InputInterface $input, OutputInterface $output, Selection $selection, array $entrypoint, ?string $logType, int $lines, string $format, ?array $fields): int + { + $tail = Option::bool($input, 'tail'); + if ($tail && $input->getOption('until') !== null) { + throw new InvalidArgumentException('The --until option cannot be used with --tail'); + } + + $filters = $this->buildFilters($input, $selection, $logType); + + $now = time(); + $to = $this->parseTime($input, 'until', $now) ?? ($tail ? $now - self::TAIL_DELAY : $now); + $from = $this->parseTime($input, 'since', $now) ?? $to - $this->defaultRange($entrypoint); + // With --tail, a --since time within the tail delay is handled by polling. + if ($from >= $to && (!$tail || $from > $now)) { + throw new InvalidArgumentException($input->getOption('until') !== null + ? 'The --since time must be before the --until time' + : 'The --since time must be in the past'); + } + $this->selector->ensurePrintedSelection($selection); + + $url = (string) Observability::getLink($entrypoint, 'logs_query'); + $fields ??= $logType === null || $logType === 'error' + ? ['datetime', 'service', 'log_kind', 'severity', 'content', 'context'] + : ['datetime', 'service', 'severity', 'content', 'context']; + + // Fetch the most recent lines (newest first), and print them oldest first. + $rows = $from < $to ? $this->fetchRecent($url, $filters, $from, $to, $lines, $this->initialWindow($entrypoint)) : []; + $rows = array_reverse($rows); + + if ($rows === [] && !$tail) { + $this->stdErr->writeln(sprintf('No logs found between %s and %s.', date('Y-m-d H:i:s T', $from), date('Y-m-d H:i:s T', $to))); + + return 0; + } + foreach ($rows as $row) { + $this->printRow($output, $row, $format, $fields); + } + if (!$tail) { + return 0; + } + + // Poll for newer logs (oldest first), after the newest printed line. + // Each poll starts a second before the previous one ended (the cursor prevents duplicates). + $last = end($rows); + $cursor = $last !== false ? $last['cursor'] : null; + $from = max($from, $to - 1); + while (true) { // @phpstan-ignore while.alwaysTrue + sleep(self::TAIL_INTERVAL); + // Limit the window, e.g. to catch up gradually after the computer was suspended. + $to = min(time() - self::TAIL_DELAY, $from + self::MAX_WINDOW); + if ($to <= $from + 1) { + continue; + } + do { + $page = $this->queryPage($url, $filters, $from, $to, 'ASC', $cursor); + foreach ($page['data'] as $row) { + $this->printRow($output, $row, $format, $fields); + } + $cursor = $page['_cursor'] ?? $cursor; + } while ($page['_has_more_results']); + $from = $to - 1; + } + } + + /** + * Fetches up to $lines of the most recent logs, newest first. + * + * Large time ranges can be rejected by the API, so this queries windows + * of increasing size, moving back in time until enough lines are found. + * + * @param list $filters + * + * @return list + */ + private function fetchRecent(string $url, array $filters, int $from, int $to, int $lines, int $window): array + { + $rows = []; + $noCursor = 0; + $end = $to; + while ($end > $from && count($rows) < $lines) { + $start = max($from, $end - $window); + $cursor = null; + do { + try { + $page = $this->queryPage($url, $filters, $start, $end, 'DESC', $cursor); + } catch (RequestException $e) { + // The API responds with 499 if a query would read too much data: retry with a smaller window. + if ($e->getResponse()?->getStatusCode() !== 499 || $cursor !== null || $end - $start <= self::MIN_WINDOW) { + throw $e; + } + $window = intdiv($end - $start, 2); + $this->io->debug(sprintf('Too much data: retrying with a window of %d seconds', $window)); + continue 2; + } + foreach ($page['data'] as $row) { + // Windows overlap by a second, so skip duplicates. + $rows[$row['cursor'] !== '' ? $row['cursor'] : 'no-cursor-' . $noCursor++] ??= $row; + } + $cursor = $page['_cursor']; + } while (count($rows) < $lines && $page['_has_more_results']); + if ($start === $from) { + break; + } + $end = $start + 1; + $window = min($window * self::WINDOW_GROWTH, self::MAX_WINDOW); + } + + return array_slice(array_values($rows), 0, $lines); + } + + /** + * Builds query parameters for filtering logs. + * + * @return list A list of key-value pairs. + */ + private function buildFilters(InputInterface $input, Selection $selection, ?string $logType): array + { + $params = []; + if ($logType === null || $logType === 'error') { + $params[] = ['log_kinds[]', 'platform']; + $params[] = ['log_kinds_mode', '-1']; + } else { + $params[] = ['log_kinds[]', self::LOG_KINDS[$logType]]; + $params[] = ['log_kinds_mode', '1']; + } + + $severity = Option::stringOrNull($input, 'severity'); + if ($severity === null && $logType === 'error') { + $severity = 'ERROR'; + } + if ($severity !== null) { + $index = array_search(strtoupper($severity), self::SEVERITIES, true); + if ($index === false) { + throw new InvalidArgumentException(sprintf('Invalid --severity: %s (expected one of: %s)', $severity, strtolower(implode(', ', self::SEVERITIES)))); + } + foreach (array_slice(self::SEVERITIES, 0, $index + 1) as $s) { + $params[] = ['severities[]', $s]; + } + $params[] = ['severities_mode', '1']; + } + + $services = ArrayArgument::getOption($input, 'service'); + // The app may also come from the project URL or an environment variable. + if (($app = $selection->getAppName()) !== null) { + $services[] = $app; + } + if ($services !== []) { + foreach (array_unique($services) as $service) { + $params[] = ['services[]', $service]; + } + $params[] = ['services_mode', '1']; + } + + return $params; + } + + /** + * Queries a page of logs. + * + * @param list $filters + * + * @return array{data: list, _cursor: ?string, _has_more_results: bool} + */ + private function queryPage(string $url, array $filters, int $from, int $to, string $order, ?string $cursor): array + { + $params = [['from', (string) $from], ['to', (string) $to], ['order_by', $order], ...$filters]; + if ($cursor !== null) { + $params[] = ['cursor', $cursor]; + } + $query = implode('&', array_map(fn(array $p): string => rawurlencode($p[0]) . '=' . rawurlencode($p[1]), $params)); + $page = $this->observability->get($url . (str_contains($url, '?') ? '&' : '?') . $query); + + $data = is_array($page['data'] ?? null) ? $page['data'] : []; + $newCursor = $page['_cursor'] ?? null; + + return [ + 'data' => array_values(array_map(fn($row): array => $this->normalizeRow($row), array_filter($data, 'is_array'))), + '_cursor' => is_string($newCursor) && $newCursor !== '' ? $newCursor : null, + // Guard against an unchanged cursor, which would repeat the same query. + '_has_more_results' => !empty($page['_has_more_results']) && $newCursor !== null && $newCursor !== $cursor, + ]; + } + + /** + * @param array $row + * + * @return LogRow + */ + private function normalizeRow(array $row): array + { + $str = fn(string $key): string => is_scalar($row[$key] ?? null) ? (string) $row[$key] : ''; + $time = strtotime($str('datetime')); + + return [ + 'cursor' => $str('cursor'), + 'datetime' => $str('datetime'), + 'timestamp' => $time !== false ? $time : time(), + 'severity' => $str('severity'), + 'service' => $str('service'), + 'log_kind' => $str('log_kind'), + 'content' => $str('content'), + 'raw' => $row, + ]; + } + + /** + * Parses the --fields option. + * + * @return list|null + */ + private function parseFields(InputInterface $input, string $format): ?array + { + if ($input->getOption('fields') === null) { + return null; + } + if ($format !== 'text') { + throw new InvalidArgumentException('The --fields option can only be used with the "text" format'); + } + $fields = array_values(ArrayArgument::split([Option::string($input, 'fields')])); + foreach ($fields as $field) { + if (!in_array($field, self::FIELDS, true) && !preg_match('/^context\.[^.]+/', $field)) { + throw new InvalidArgumentException(sprintf('Invalid field: %s (expected one of: %s, or "context.")', $field, implode(', ', self::FIELDS))); + } + } + if ($fields === []) { + throw new InvalidArgumentException('The --fields option must not be empty'); + } + + return $fields; + } + + /** + * @param LogRow $row + * @param list $fields + */ + private function printRow(OutputInterface $output, array $row, string $format, array $fields): void + { + if ($format === 'json') { + $output->writeln((string) json_encode($row['raw'], JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE), OutputInterface::OUTPUT_RAW); + + return; + } + if ($format === 'raw') { + $output->writeln($row['content'], OutputInterface::OUTPUT_RAW); + + return; + } + + $context = $this->contextFields($row['raw']['context'] ?? null); + $keyValue = fn(string $key, string $value): string => '' . OutputFormatter::escape($key) . '=' . OutputFormatter::escape($value); + $parts = []; + foreach ($fields as $field) { + if ($field === 'context') { + $parts = array_merge($parts, $this->formatContext($context, $keyValue)); + continue; + } + if (str_starts_with($field, 'context.')) { + $key = substr($field, 8); + if (isset($context[$key])) { + $parts[] = $keyValue($key, $context[$key]); + } + continue; + } + $raw = $row['raw'][$field] ?? null; + $value = is_scalar($raw) ? (string) $raw : ''; + if ($value === '') { + continue; + } + $parts[] = match ($field) { + 'datetime' => '' . OutputFormatter::escape($value) . '', + 'service' => '' . OutputFormatter::escape($value) . '', + 'severity' => $this->formatSeverity($value), + default => OutputFormatter::escape($value), + }; + } + $output->writeln(implode(' ', $parts)); + } + + private function formatSeverity(string $severity): string + { + $tag = match (array_search($severity, self::SEVERITIES, true)) { + 0, 1, 2, 3 => 'fg=red', + 4, 5 => 'fg=yellow', + default => null, + }; + + return $tag !== null ? "<$tag>" . OutputFormatter::escape($severity) . '' : OutputFormatter::escape($severity); + } + + /** + * Formats context fields for display, skipping some and limiting their number and length. + * + * @param array $context + * @param callable(string, string): string $keyValue + * + * @return list + */ + private function formatContext(array $context, callable $keyValue): array + { + $parts = []; + $omitted = 0; + $length = 0; + foreach ($context as $key => $value) { + // Numeric keys are converted to integers by PHP. + $key = (string) $key; + // Skip fields that are already displayed, or that are only useful in tracing tools. + if (in_array(strtolower(explode('.', $key, 2)[0]), self::SKIP_CONTEXT_KEYS, true)) { + continue; + } + if (mb_strlen($value) > self::MAX_CONTEXT_VALUE_LENGTH) { + $value = mb_substr($value, 0, self::MAX_CONTEXT_VALUE_LENGTH - 1) . '…'; + } + $length += mb_strlen($key) + mb_strlen($value) + 2; + if ($omitted > 0 || count($parts) >= self::MAX_CONTEXT_FIELDS || ($parts !== [] && $length > self::MAX_CONTEXT_LENGTH)) { + $omitted++; + continue; + } + $parts[] = $keyValue($key, $value); + } + if ($omitted > 0) { + $parts[] = sprintf('(+%d more)', $omitted); + } + + return $parts; + } + + /** + * Extracts fields from a structured (JSON) log line, as key-value strings. + * + * Nested objects are flattened, with dot-separated keys. + * + * @return array + */ + private function contextFields(mixed $context): array + { + if (!is_string($context) || $context === '' || $context[0] !== '{') { + return []; + } + $decoded = json_decode($context, true); + if (!is_array($decoded)) { + return []; + } + $fields = []; + $flatten = function (array $data, string $prefix) use (&$flatten, &$fields): void { + foreach ($data as $key => $value) { + $key = $prefix . $key; + if (is_array($value) && $value !== [] && !array_is_list($value)) { + $flatten($value, $key . '.'); + } elseif ($value !== null && $value !== '' && $value !== []) { + // Quote strings that would be ambiguous in key=value output; encode other values as JSON. + $fields[$key] = is_string($value) && !preg_match('/[\s"=]/', $value) + ? $value + : (string) json_encode($value, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE); + } + } + }; + $flatten($decoded, ''); + + return $fields; + } + + /** + * Returns the size of the first time window to query, in seconds. + * + * @param array $entrypoint + */ + private function initialWindow(array $entrypoint): int + { + $minutes = Observability::nested($entrypoint, 'data_retention', 'logs', 'recommended_default_range'); + + return is_int($minutes) && $minutes > 0 ? min($minutes * 60, self::MAX_WINDOW) : 900; + } + + /** + * Returns the default time range to search, in seconds. + * + * @param array $entrypoint + */ + private function defaultRange(array $entrypoint): int + { + $minutes = array_filter([ + Observability::nested($entrypoint, 'data_retention', 'logs', 'retention_period'), + Observability::nested($entrypoint, 'data_retention', 'logs', 'max_range'), + Observability::nested($entrypoint, 'retention', 'logs'), + ], fn($v): bool => is_int($v) && $v > 0); + + return $minutes !== [] ? min($minutes) * 60 : 86400; + } + + /** + * Parses a time option, as a relative duration (e.g. "2h") or a date/time. + */ + private function parseTime(InputInterface $input, string $option, int $now): ?int + { + $value = Option::stringOrNull($input, $option); + if ($value === null) { + return null; + } + if (preg_match('/^(\d+)([smhd])$/', $value, $matches)) { + return $now - (int) $matches[1] * ['s' => 1, 'm' => 60, 'h' => 3600, 'd' => 86400][$matches[2]]; + } + $time = strtotime($value, $now); + if ($time === false) { + throw new InvalidArgumentException(sprintf('Invalid --%s time: %s', $option, $value)); + } + + return $time; + } + + private function readViaSsh(InputInterface $input, Selection $selection, ?string $logType, int $lines): int + { $host = $this->selector->getHostFromSelection($input, $selection); $logDir = '/var/log'; @@ -75,11 +651,7 @@ protected function execute(InputInterface $input, OutputInterface $output): int } // Select the log file that the user specified. - if ($logType = Argument::stringOrNull($input, 'type')) { - // @todo this might need to be cleverer - if (str_ends_with($logType, '.log')) { - $logType = substr($logType, 0, strlen($logType) - 4); - } + if ($logType !== null) { $logFilename = $logDir . '/' . OsUtil::escapePosixShellArg($logType . '.log'); } elseif (!$input->isInteractive()) { $this->stdErr->writeln('No log type specified.'); diff --git a/legacy/src/Command/Metrics/MetricsCommandBase.php b/legacy/src/Command/Metrics/MetricsCommandBase.php index 277fbbfce..f0ad1ce4c 100644 --- a/legacy/src/Command/Metrics/MetricsCommandBase.php +++ b/legacy/src/Command/Metrics/MetricsCommandBase.php @@ -13,6 +13,7 @@ use Platformsh\Cli\Selector\Selector; use Platformsh\Cli\Selector\SelectorConfig; use Platformsh\Cli\Service\Io; +use Platformsh\Cli\Service\Observability; use Platformsh\Cli\Service\PropertyFormatter; use Platformsh\Cli\Service\Config; use Platformsh\Cli\Service\Api; @@ -40,6 +41,7 @@ abstract class MetricsCommandBase extends CommandBase private PropertyFormatter $propertyFormatter; private Config $config; private Api $api; + private Observability $observability; public const MIN_INTERVAL = 60; // 1 minute @@ -65,8 +67,9 @@ public function __construct( } #[Required] - public function autowire(Api $api, Config $config, Io $io, PropertyFormatter $propertyFormatter): void + public function autowire(Api $api, Config $config, Io $io, Observability $observability, PropertyFormatter $propertyFormatter): void { + $this->observability = $observability; $this->api = $api; $this->config = $config; $this->propertyFormatter = $propertyFormatter; @@ -114,37 +117,6 @@ protected function addMetricsOptions(): self return $this; } - /** - * Returns the resources overview URL for the selected environment. - * - * @return string|false The resources overview URL, or false if not available - * @throws \GuzzleHttp\Exception\GuzzleException if there is an error in fetching observability metadata - */ - private function getResourcesOverviewUrl(Environment $environment): false|string - { - $entrypointUrl = rtrim($environment->getUri(), '/') . '/observability/'; - - $client = $this->api->getHttpClient(); - $request = new Request('GET', $entrypointUrl); - - try { - $response = $client->send($request); - } catch (BadResponseException $e) { - if ($e->getResponse()->getStatusCode() === 404) { - return false; - } - throw ApiResponseException::create($request, $e->getResponse(), $e); - } - - $data = json_decode($response->getBody()->__toString(), true); - - if (!is_array($data) || empty($data['_links']['resources_overview']['href'])) { - return false; - } - - return $data['_links']['resources_overview']['href']; - } - /** * @param InputInterface $input * @param array $metricTypes @@ -169,7 +141,7 @@ protected function processQuery(InputInterface $input, array $metricTypes, array $this->selector->ensurePrintedSelection($selection); } - if (!$link = $this->getResourcesOverviewUrl($environment)) { + if (!$link = Observability::getLink($this->observability->getEntrypoint($environment), 'resources_overview')) { throw new \InvalidArgumentException('Observability API link not found for the environment.'); } diff --git a/legacy/src/Selector/Selector.php b/legacy/src/Selector/Selector.php index 9950fe278..a7b771fbc 100644 --- a/legacy/src/Selector/Selector.php +++ b/legacy/src/Selector/Selector.php @@ -200,7 +200,7 @@ public function getSelection(InputInterface $input, ?SelectorConfig $config = nu // The remote container can only be selected if an environment was // identified. When envRequired is false, the calling command is // responsible for handling the case where there is no environment. - if ($environment !== null) { + if ($environment !== null && $config->selectRemoteContainer) { $remoteContainer = $this->selectRemoteContainer($environment, $input, $appName); } } @@ -236,6 +236,16 @@ public function ensurePrintedSelection(Selection $selection, bool $blankLine = f } } + /** + * Selects the remote container, for a selection made with selectRemoteContainer: false. + */ + public function withRemoteContainer(InputInterface $input, Selection $selection): Selection + { + $remoteContainer = $this->selectRemoteContainer($selection->getEnvironment(), $input, $selection->getAppName()); + + return new Selection($selection->config, $selection->getProject(), $selection->getEnvironment(), $selection->getAppName(), $remoteContainer); + } + public function getHostFromSelection(InputInterface $input, Selection $selection): HostInterface { $envPrefix = $this->config->getStr('service.env_prefix'); diff --git a/legacy/src/Selector/SelectorConfig.php b/legacy/src/Selector/SelectorConfig.php index 803737390..7da8126e1 100644 --- a/legacy/src/Selector/SelectorConfig.php +++ b/legacy/src/Selector/SelectorConfig.php @@ -23,6 +23,8 @@ public function __construct( public bool $requireApiOnLocal = false, /** @var callable|null */ public mixed $chooseEnvFilter = null, + // Set to false to defer selecting the app or worker; see Selector::withRemoteContainer(). + public bool $selectRemoteContainer = true, ) {} public function with( diff --git a/legacy/src/Service/Config.php b/legacy/src/Service/Config.php index 38b4ed046..ff5a3eff9 100644 --- a/legacy/src/Service/Config.php +++ b/legacy/src/Service/Config.php @@ -402,6 +402,7 @@ private function applyEnvironmentOverrides(): void } $overrideMap = \array_merge($overrideMap, [ 'TOKEN' => 'api.token', + 'LOG_PROTOCOL' => 'api.log_protocol', 'API_TOKEN' => 'api.access_token', // Deprecated 'COPY_ON_WINDOWS' => 'local.copy_on_windows', 'DEBUG' => 'api.debug', diff --git a/legacy/src/Service/Observability.php b/legacy/src/Service/Observability.php new file mode 100644 index 000000000..0c0158aea --- /dev/null +++ b/legacy/src/Service/Observability.php @@ -0,0 +1,88 @@ +|null The entrypoint data, or null if it is not available. + */ + public function getEntrypoint(Environment $environment): ?array + { + $url = rtrim($environment->getUri(), '/') . '/observability/'; + try { + $data = $this->get($url); + } catch (RequestException $e) { + if ($e->getResponse()?->getStatusCode() === 404) { + return null; + } + throw $e; + } + + return $data; + } + + /** + * Returns a link from the entrypoint, or null if it is not available. + * + * @param array|null $entrypoint + */ + public static function getLink(?array $entrypoint, string $name): ?string + { + $link = self::nested($entrypoint, '_links', $name); + $href = is_array($link) ? $link['href'] ?? null : null; + + return is_string($href) && $href !== '' ? $href : null; + } + + /** + * Returns a nested value from decoded JSON data, or null if it is not found. + */ + public static function nested(mixed $data, string ...$keys): mixed + { + foreach ($keys as $key) { + if (!is_array($data) || !isset($data[$key])) { + return null; + } + $data = $data[$key]; + } + + return $data; + } + + /** + * Sends a GET request and decodes the JSON response. + * + * @return array + */ + public function get(string $url): array + { + $request = new Request('GET', $url); + try { + $response = $this->api->getHttpClient()->send($request); + } catch (BadResponseException $e) { + throw ApiResponseException::create($request, $e->getResponse(), $e); + } + $data = json_decode((string) $response->getBody(), true); + if (!is_array($data)) { + throw new \RuntimeException('Failed to decode observability API response from: ' . $url); + } + + return $data; + } +}