Originating request ID has gone missing from log lines

[turt2live]

There used to be a request ID that could be associated with the outbound request in this:

homeserver - 2018-07-23 20:35:30,080 - synapse.http.outbound - 164 - INFO - {GET-O-5511} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/federation/v1/event/%24redacted%3Amatrix.org/

[turt2live]

#3556 may fix this - to be verified.

[turt2live]

#3556 does not fix this

[richvdh]

hrm, that suggests that something somewhere has leaked a logcontext. If you can share more logs from before the problem, we might be able to figure out where.

[turt2live]

I can't really find anything about log context leaks, and can only assume what is associated with the "Sending request" log line:

homeserver_1 - 2018-09-07 19:46:39,742 - synapse.access.https.8558 - 215 - INFO - REDACTED - 8558 - Received request: PUT /_matrix/federation/v1/send/1536162311776/
homeserver_1 - 2018-09-07 19:46:39,745 - synapse.federation.transport.server - 130 - INFO - Request from matrix.org
homeserver_1 - 2018-09-07 19:46:39,746 - synapse.federation.transport.server - 336 - INFO - Received txn 1536162311776 from matrix.org. (PDUs: 24, EDUs: 4 - DROPPED)
homeserver_1 - 2018-09-07 19:46:39,746 - synapse.util.async_helpers - 205 - INFO - Acquired uncontended linearizer lock 'fed_txn_handler' for key (u'matrix.org', u'1536162311776')
homeserver_1 - 2018-09-07 19:46:39,748 - synapse.storage.TIME - 217 - INFO - Total database time: 0.199% {store_state_group(1): 0.123%, set_received_txn_response(40): 0.055%, _update_client_ips_batch(3): 0.009%} {}
homeserver_1 - 2018-09-07 19:46:39,748 - synapse.metrics - 268 - INFO - Collecting gc 0
homeserver_1 - 2018-09-07 19:46:39,767 - synapse.metrics - 268 - INFO - Collecting gc 0
homeserver_1 - 2018-09-07 19:46:39,775 - synapse.handlers.federation - 192 - INFO - Ignoring PDU $REDACTED:matrix.org for room !REDACTED:matrix.org from matrix.org as we've left the room!
homeserver_1 - 2018-09-07 19:46:39,779 - synapse.metrics - 268 - INFO - Collecting gc 0
homeserver_1 - 2018-09-07 19:46:39,781 - synapse.handlers.federation - 192 - INFO - Ignoring PDU $REDACTED:matrix.org for room !REDACTED:matrix.org from matrix.org as we've left the room!
homeserver_1 - 2018-09-07 19:46:39,788 - synapse.access.https.8558 - 215 - INFO - REDACTED - 8558 - Received request: PUT /_matrix/federation/v1/send/1536303964637/
homeserver_1 - 2018-09-07 19:46:39,791 - synapse.federation.transport.server - 130 - INFO - Request from REDACTED.com
homeserver_1 - 2018-09-07 19:46:39,791 - synapse.federation.transport.server - 336 - INFO - Received txn 1536303964637 from REDACTED.com. (PDUs: 0, EDUs: 1 - DROPPED)
homeserver_1 - 2018-09-07 19:46:39,792 - synapse.util.async_helpers - 205 - INFO - Acquired uncontended linearizer lock 'fed_txn_handler' for key (u'REDACTED.com', u'1536303964637')
homeserver_1 - 2018-09-07 19:46:39,813 - synapse.federation.federation_server - 196 - WARNING - Error handling PDU $REDACTED_sDrM:matrix.org: ERROR 403: Your server isn't divulging details about prev_events referenced in this event.
homeserver_1 - 2018-09-07 19:46:39,820 - synapse.handlers.federation - 192 - INFO - Ignoring PDU $REDACTED:matrix.org for room !REDACTED:matrix.org from matrix.org as we've left the room!
homeserver_1 - 2018-09-07 19:46:39,822 - synapse.metrics - 268 - INFO - Collecting gc 0
homeserver_1 - 2018-09-07 19:46:39,830 - synapse.handlers.federation - 192 - INFO - Ignoring PDU $REDACTED:matrix.org for room !REDACTED:matrix.org from matrix.org as we've left the room!
homeserver_1 - 2018-09-07 19:46:39,834 - synapse.metrics - 268 - INFO - Collecting gc 0
homeserver_1 - 2018-09-07 19:46:39,835 - synapse.handlers.federation - 192 - INFO - Ignoring PDU $REDACTED:matrix.org for room !REDACTED:matrix.org from matrix.org as we've left the room!
homeserver_1 - 2018-09-07 19:46:39,837 - synapse.handlers.federation - 1755 - INFO - Missing auth: set([u'$REDACTED_Gbsob:matrix.org'])
homeserver_1 - 2018-09-07 19:46:39,837 - synapse.http.outbound - 164 - INFO - {GET-O-962} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/federation/v1/event_auth/%21REDACTED%3Amatrix.org/%24REDACTED_GOEmf%3Amatrix.org

In fact, in the entire log there's no log context warnings whatsoever.

[richvdh]

homeserver_1 - 2018-09-07 19:46:39,742 - synapse.access.https.8558 - 215 - INFO - REDACTED - 8558 - Received request: PUT /_matrix/federation/v1/send/1536162311776/

This doesn't look right: the fact there is no request ID here (on the very first line when the request arrives) suggests that there's something up with the logging config. Can you share the log config?

[turt2live]

It's fairly default:

version: 1

formatters:
  precise:
   format: 'homeserver_1 - %(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(message)s'

filters:
  context:
    (): synapse.util.logcontext.LoggingContextFilter
    request: ""

handlers:
  file:
    class: logging.handlers.RotatingFileHandler
    formatter: precise
    filename: /var/log/synapse/homeserver_1.log
    maxBytes: 104857600
    backupCount: 20
    filters: [context]
    level: DEBUG
  console:
    class: logging.StreamHandler
    formatter: precise
    filters: [context]

loggers:
    synapse:
        level: INFO

    synapse.storage.SQL:
        level: INFO

root:
    level: INFO
    handlers: [file, console]

[turt2live]

As mentioned out of band, somehow my log config lost %(request)s - oops.