Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Mutliple log messages printed into one line #190

Closed
TimMnz09 opened this issue Jan 11, 2023 · 6 comments
Closed

Mutliple log messages printed into one line #190

TimMnz09 opened this issue Jan 11, 2023 · 6 comments
Labels
bug Something isn't working

Comments

@TimMnz09
Copy link
Contributor

Report

I'm facing in issue where two log messages are printed into one line in some situation.
So some log messages start with the info tag [Info] and some chars letter the next message starts with a warn tag [Warn] tag.
e.g.

[Info] 2023-01-11T07:54:43.435, isRequestSuccess: False, totalTime: 60003, category: [Warn] 2023-01-11T07:55:43.438 [FailedToProcessRequest], apiId: zzzz-api-v1, operationId: performQueryWithQuery, subscriptionId: xxxx-heartbeat-checker, tags: 208, httpMethod: GET, source: request-forwarder, exception: System.OperationCanceledException: The operation was cancelled.

Logging configuration:

    observability:
      logs:
        std:
          format: text
          useColor: false

Expected Behavior

Every message should be printed into seperate lines.

Actual Behavior

different messages printed into same line

Steps to Reproduce the Problem

  1. Setup Deployment with Helm
  2. Do some requests that will lead to an error

Logs from self-hosted gateway

[Info] 2023-01-11T07:55:36.615 [DnsResolutionStarted], message: xxx-api.ws.xxx-xxx.de, source: RoundRobinNameResolver
[Info] 2023-01-11T07:55:36.622 [DnsResolutionCompleted], message: xxx-api.ws.xxx-xxx.de: [145.228.243.11], source: RoundRobinNameResolver
[Info] 2023-01-11T07:55:36.562, isRequestSuccess: True, totalTime: 72, category: GatewayLogs, callerIpAddress: 172.25.5.82, timeGenerated: 01/11/2023 07:55:36, region: asys-e2emon, correlationId: 5940ba26-6d9b-4773-8255-1bee922e05fb, method: GET, url: https://xx.x.aaxa-xxx.de/qqqq/v1/distribute?filterParam=context%3Deq%3ADBA%3B&size=20&offset=0&sort=-jobId&counter=1, backendResponseCode: 304, responseCode: 304, responseSize: 471, cache: none, backendTime: 68, apiId: xxxx-ranxxxsom-api-v1, operationId: getDistributionQueue, clientProtocol: HTTP/1.1, backendProtocol: HTTP/1.1, apiRevision: 1, clientTlsVersion: 1.2, backendMethod: GET, backendUrl: https://zzzz-api.ws.aaaaa-mmmmm.de/ransom/api/v1/distribute?filterParam=context%3Deq%3ADBA%3B&size=20&offset=0&sort=-jobId&counter=1, correlationId: 5940ba26-6d9b-4773-8255-1bee922e05fb
[Info] 2023-01-11T07:54:43.435, isRequestSuccess: False, totalTime: 60003, category: [Warn] 2023-01-11T07:55:43.438 [FailedToProcessRequest], apiId: xxx-api-v1, operationId: performQueryWithQuery, subscriptionId: yyy-heartbeat-checker, tags: 208, httpMethod: GET, source: request-forwarder, exception: System.OperationCanceledException: The operation was cancelled.
 ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at Gateway.Http.Client.DotNetty.DotNettyHttpBackend.SendRequestAsync(IChannel channel, IHttpRequest request, Boolean expect100Continue, IPipelineContext context, CancellationToken cancellation) in D:\a\1\s\Proxy\Gateway.Http.Client.DotNetty\DotNettyHttpBackend.cs:line 402
   at Gateway.Http.Client.DotNetty.DotNettyHttpBackend.SendRequestAsync(IChannel channel, IPipelineContext context, CancellationToken cancellation) in D:\a\1\s\Proxy\Gateway.Http.Client.DotNetty\DotNettyHttpBackend.cs:line 242

Self-hosted Gateway Version

2.1.6

Deployment

Self-Managed (YAML/Helm)

Platform

Other

Kubernetes Version

Other

Anything else?

I also raised in support request for our service. But the support told me, that it's not an issue with the self hosted gateway, but with the helm chart deployment.
@TimMnz09 TimMnz09 added the bug Something isn't working label Jan 11, 2023
@tomkerkhove
Copy link
Member

I also raised in support request for our service. But the support told me, that it's not an issue with the self hosted gateway, but with the helm chart deployment.

This is wrong.

Do you see this consistently or only every now and then?

@TimMnz09
Copy link
Contributor Author

This was also my thought :)
It's just now and then but frequently, like every hour or so.

@tomkerkhove
Copy link
Member

Always same kind of log?

Meaning a request log followed by a warning because of OperationCanceledException?

@TimMnz09
Copy link
Contributor Author

TimMnz09 commented Jan 12, 2023 •
edited
Loading

Sometimes it's the other way round, so first the warning log and than the request log.
But it seems always to be related with the OperationCanceledException
example:

[Warn] 2023-01-11T11:36:43.735 [FailedToProcessRequest], apiId: yyy-api-v1, operationId: performQueryWithQuery, subscriptionId: hhh-heartbeat-checker, tags: 208, httpMethod: GET, source[Info] 2023-01-11T11:35:43.734, isRequestSuccess: False, totalTime: 60001, category: GatewayLogs, callerIpAddress: 172.25.5.82, timeGenerated: 01/11/2023 23:35:43, region: asys-e2emon, correlationId: 7012caf5-335a-4647-bfc1-c1c97cbbc35e, method: GET, url: https://api.zz.xxx-xxx.de/yyy/v1/cis/query/asy_hhh_heartbeat_software?showInboundRelations=true&visibleNodeLabel=RunningSoftware, responseCode: 0, cache: none, backendTime: 59998, apiId: yyy-api-v1, operationId: performQueryWithQuery, apimSubscriptionId: hhh-heartbeat-checker, clientProtocol: HTTP/1.1, apiRevision: 1, clientTlsVersion: 1.2, backendMethod: GET, backendUrl: https://yyy-api.zz.xxx-xxx.de/api/v1/cis/query/asy_hhh_heartbeat_software?showInboundRelations=true&visibleNodeLabel=RunningSoftware, lastError: {
  "elapsed": 60000,
  "source": "request-forwarder",
  "path": "forward-request\\forward-request",
  "reason": "ClientConnectionFailure",
  "message": "Client connection was unexpectedly closed.",
  "section": "backend"
}, errors: [
  {
    "elapsed": 60000,
    "source": "request-forwarder",
    "path": "forward-request\\forward-request",
    "reason": "ClientConnectionFailure",
    "message": "Client connection was unexpectedly closed.",
    "section": "backend"
  }
], correlationId: 7012caf5-335a-4647-bfc1-c1c97cbbc35e
: request-forwarder, exception: System.OperationCanceledException: The operation was cancelled.
 ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.

@tomkerkhove
Copy link
Member

Ok, thanks! I've opened an internal bug for this.

@tomkerkhove
Copy link
Member

Fixed in https://github.com/Azure/api-management-self-hosted-gateway/releases/tag/Container-v2.6.0

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@tomkerkhove @TimMnz09