Logging to stdout stops working after a couple of minutes

[wederbrand]

(this is the same as the stale issue #8955 but with a minimal reproducible example)

After running the pre-built docker-image version 10.0.5 with a few minor changes to records.yaml and logging.yaml ATS stops logging to stdout.

These are the two last lines from diags.log

[Apr 17 13:13:15.637] [ET_NET 7] NOTE: Traffic Server is fully initialized.
[Apr 17 13:18:35.441] [LOG_FLUSH] ERROR: Failed to write log to stdout: [tried 555, wrote 0, Bad file descriptor]

I've done some deeper testing and it seems ATS is restarting and after that logging fails (or, perhaps, logging fails so ATS restarts)

The only changes done in the attached files are

144c144
<     server_ports: 8080 8080:ipv6
---
>     server_ports: 8080
217c217
<     pristine_host_hdr: 0
---
>     pristine_host_hdr: 1

and

46,48c46,48
<     - filename: squid
<       format: squid
<       mode: binary
---
>     - filename: stdout
>       format: common
>       mode: ascii

This dockerfile does those changes, and nothing more.

FROM trafficserver/trafficserver:10.0.5

ADD logging.yaml /opt/etc/trafficserver/logging.yaml
ADD records.yaml /opt/etc/trafficserver/records.yaml

After building and starting a container logs appears on stdout for a couple if minutes, 5 in my case but I'm sure it can differ.
I'm calling it periodically with watch, but any tool would be good

 watch curl localhost:8080/hello/at/$(date +%s)

Below are the full records.yaml and logging.yaml

##############################################################################
# *NOTE*: All options covered in this file should be documented in the docs:
#
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html
##############################################################################

records:
  accept_threads: 1
  cache:
    limits:
      http:

# https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-cache-limits-http-max-alts
        max_alts: 5
    log:
      alternate:

# https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-cache-log-alternate-eviction
        eviction: 0

# https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-cache-max-doc-size
    max_doc_size: 0
    min_average_object_size: 8000

##############################################################################
# RAM and disk cache configurations. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#ram-cache
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/storage.config.en.html
##############################################################################
    ram_cache:
      size: -1
    ram_cache_cutoff: 4194304
    threads_per_disk: 8
##############################################################################
# Debugging. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#diagnostic-logging-configuration
##############################################################################
  diags:
    debug:
      enabled: 0
      tags: http|dns

#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-dump-mem-info-frequency
  dump_mem_info_frequency: 0

##############################################################################
# Thread configurations. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#thread-variables
##############################################################################
  exec_thread:
    affinity: 1
    autoconfig:
      enabled: 1
      scale: 1.0
    limit: 2
  http:
    accept_no_activity_timeout: 120
    cache:
      cache_responses_to_cookies: 1
      cache_urls_that_look_dynamic: 1

##############################################################################
# Heuristic cache expiration. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#heuristic-expiration
##############################################################################
      heuristic_lm_factor: 0.1
      heuristic_max_lifetime: 86400
      heuristic_min_lifetime: 3600

##############################################################################
# Enable / disable HTTP caching. Useful for testing, but also as an
# overridable (per remap) config
##############################################################################
      http: 1

##############################################################################
# Cache control. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#cache-control
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/cache.config.en.html
##############################################################################
      ignore_client_cc_max_age: 1

# https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-http-cache-required-headers
      required_headers: 2

# https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-http-cache-when-to-revalidate
      when_to_revalidate: 0

##############################################################################
# Origin server connect attempts. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#origin-server-connect-attempts
##############################################################################
    connect_attempts_max_retries: 3
    connect_attempts_max_retries_down_server: 1
    connect_attempts_rr_retries: 3
    connect_attempts_timeout: 30
    down_server:
      cache_time: 60
    forward:
      proxy_auth_to_parent: 0

##############################################################################
# Proxy users variables. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-user-variables
##############################################################################
    insert_client_ip: 1

##############################################################################
# Via: headers. Docs:
#     https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-http-insert-response-via-str
##############################################################################
    insert_request_via_str: 1
    insert_response_via_str: 0
    insert_squid_x_forwarded_for: 1
    keep_alive_no_activity_timeout_in: 120
    keep_alive_no_activity_timeout_out: 120

##############################################################################
# Negative response caching, for redirects and errors. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#negative-response-caching
##############################################################################
    negative_caching_enabled: 0
    negative_caching_lifetime: 1800
    normalize_ae: 1

##############################################################################
# Parent proxy configuration, in addition to these settings also see parent.config. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#parent-proxy-configuration
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/parent.config.en.html
##############################################################################
    parent_proxy:
      retry_time: 300

##############################################################################
# Security. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#security
##############################################################################
    push_method_enabled: 0

##############################################################################
# Specify server addresses and ports to bind for HTTP and HTTPS. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy.config.http.server_ports
##############################################################################
    server_ports: 8080

#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-http-slow-log-threshold
    slow:
      log:
        threshold: 0

##############################################################################
# HTTP connection timeouts (secs). Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#http-connection-timeouts
##############################################################################
    transaction_active_timeout_in: 900
    transaction_active_timeout_out: 0
    transaction_no_activity_timeout_in: 30
    transaction_no_activity_timeout_out: 30
    uncacheable_requests_bypass_parent: 1

##############################################################################
# Logging Config. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#logging-configuration
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/logging.yaml.en.html
##############################################################################
  log:
    auto_delete_rolled_files: 1
    logging_enabled: 3
    max_space_mb_for_logs: 25000
    max_space_mb_headroom: 1000
    periodic_tasks_interval: 5
    rolling_enabled: 1
    rolling_interval_sec: 86400
    rolling_size_mb: 10

##############################################################################
# Network. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#network
##############################################################################
  net:
    connections_throttle: 30000
    default_inactivity_timeout: 86400
    max_connections_in: 30000
    max_requests_in: 0

#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-res-track-memory
  res_track_memory: 0

# https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#reverse-proxy
  reverse_proxy:
    enabled: 1
  ssl:
    client:
      CA:
        cert:
          filename: null

##############################################################################
# SSL Termination. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#client-related-configuration
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/ssl_multicert.config.en.html
##############################################################################
      verify:
        server:
          policy: PERMISSIVE
          properties: ALL
  task_threads: 2

##############################################################################
# These settings control remapping, and if the proxy allows (open) forward proxy or not. Docs:
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#url-remap-rules
#    https://docs.trafficserver.apache.org/en/latest/admin-guide/files/remap.config.en.html
##############################################################################
  url_remap:

# https://docs.trafficserver.apache.org/en/latest/admin-guide/files/records.yaml.en.html#proxy-config-url-remap-pristine-host-hdr
    pristine_host_hdr: 1
    remap_required: 1
    acl_behavior_policy: 0

# Custom log configuration
#
# Documentation on logging:
#    https://docs.trafficserver.apache.org/en/9.0.x/admin-guide/logging/index.en.html
#
# Documentation on logging.yaml file format:
#    https://docs.trafficserver.apache.org/en/9.0.x/admin-guide/files/logging.yaml.en.html
#
# Example log configurations:
#    https://docs.trafficserver.apache.org/en/9.0.x/admin-guide/logging/examples.en.html


logging:
  formats:
    # WebTrends Enhanced Log Format.
    #
    # The following is compatible with the WebTrends Enhanced Log Format.
    # If you want to generate a log that can be parsed by WebTrends
    # reporting tools, simply create a log that uses this format.
    - name: welf
      format: |-
          id=firewall time="%<cqtd> %<cqtt>" fw=%<phn> pri=6 proto=%<pqus> duration=%<ttmsf> sent=%<psql> rcvd=%<cqhl> src=%<chi> dst=%<shi> dstname=%<shn> user=%<caun> op=%<cqhm> arg="%<pqup>" result=%<pssc> ref="%<{Referer}cqh>" agent="%<{user-agent}cqh>" cache=%<crc>
    # Squid Log Format with seconds resolution timestamp.
    # The following is the squid format but with a seconds-only timestamp
    # (cqts) instead of a seconds and milliseconds timestamp (cqtq).
    - name: squid_seconds_only_timestamp
      format: '%<cqts> %<ttms> %<chi> %<crc>/%<pssc> %<psql> %<cqhm> %<pquc> %<caun> %<phr>/%<shn> %<psct>'

    # Squid Log Format.
    - name: squid
      format: '%<cqtq> %<ttms> %<chi> %<crc>/%<pssc> %<psql> %<cqhm> %<pquc> %<caun> %<phr>/%<shn> %<psct>'

    # Common Log Format.
    - name: common
      format: '%<chi> - %<caun> [%<cqtn>] "%<cqhm> %<pqu> %<cqpv>" %<pssc> %<pscl>'

    # Extended Log Format.
    - name: 'extended'
      format: '%<chi> - %<caun> [%<cqtn>] "%<cqhm> %<pqu> %<cqpv>" %<pssc> %<pscl> %<sssc> %<sscl> %<cqcl> %<pqcl> %<cqhl> %<pshl> %<pqhl> %<sshl> %<tts>'

     # Extended2 Log Formats
    - name: "extended2"
      format: '%<chi> - %<caun> [%<cqtn>] "%<cqhm> %<pqu> %<cqpv>" %<pssc> %<pscl> %<sssc> %<sscl> %<cqcl> %<pqcl> %<cqhl> %<pshl> %<pqhl> %<sshl> %<tts> %<phr> %<cfsc> %<pfsc> %<crc>'

  logs:
    - filename: stdout
      format: common
      mode: ascii

# vim: set ft=yaml :

[wederbrand]

In an attempt to work around this issue I've tried to pre-create a file that is a symlink to stdout of the first process

 RUN ln -sF /proc/1/fd/1 /opt/var/log/trafficserver/output.log
 RUN chown -h nobody:nogroup /opt/var/log/trafficserver/output.log

but it also fails.

Neither ascii nor ascii_pipe accepts that file and rotates it on startup

traffic_server WARNING: File /opt/var/log/trafficserver/output.log will be rolled because a LogObject with different format is requesting the same filename`

I've tried to read the source to understand what is required of my output.log for to not be rotated but my very poor c++-skills limits me and I can't find anything that I understand.

Is there any known way of doing something similar to this?

[JakeChampion]

We are also hitting this issue - we ran bpftrace on the system and have seen ATS this:

        ATS close(2)

        __close_nocancel+11
        fclose+273
        BaseLogFile::close_file()+55
        LogFile::close_file()+546
        LogFile::check_fd()+117
        Log::flush_thread_main(void*)+404
        LoggingFlushContinuation::mainEvent(int, void*)+39
        Continuation::handleEvent(int, void*)+235
        EThread::execute()+105
        spawn_thread_internal(void*)+129
        0x71b9f9766aa4
        0x71b9f97f3c3c

LogFile::check_fd

This routine will occasionally stat the current logfile to make sure that
it really does exist. The easiest way to do this is to close the file
and re-open it, which will create the file if it doesn't already exist.