search

boto / boto3

AWS SDK for Python
https://aws.amazon.com/sdk-for-python/
Apache License 2.0
8.99k stars 1.86k forks source link

get_log_events with startfromHead set to False returns no events #3718

Closed Fabianofski closed 1 year ago

Fabianofski commented 1 year ago

Describe the bug

I'm trying to get the newest logs of a job. When trying to get the logs with startFromHead set to False, the events property is empty. When startFromHead is set to True the events property is filled with the expected values.

Expected Behavior

I would expect that setting startFromHead to False would return the same events as when startFromHead is set to True.

Current Behavior

The events property is empty when startFromHead is set to False

Reproduction Steps

    logs_client = boto3.client('logs', region_name="eu-central-1")

    response = logs_client.get_log_events(
        logGroupName=log_group_name,
        logStreamName=log_stream_name,
        startFromHead=False
    )
    print(response)

Possible Solution

No response

Additional Information/Context

No response

SDK version used

1.26.137

Environment details (OS name and version, etc.)

Python 3.8 Ubuntu 20.04.5 LTS

RyanFitzSimmonsAK commented 1 year ago

Hi @Fabianofski, thanks for reaching out. Could you provide debug logs demonstrating this behavior? You can get debug logs by adding boto3.set_stream_logger('') to the top of your script, and redacting any sensitive information. Logs showing both startFromHead=False and startFromHead=True would be appreciated. Thanks!

Fabianofski commented 1 year ago

Hey @RyanFitzSimmonsAK,

this is my test setup:

@router.get("/logs")
def logs():
    boto3.set_stream_logger('')
    logs_client = boto3.client('logs', region_name="eu-central-1")
    log_group_name = '/aws/batch/job'
    log_stream_name = "i40-low-cost-ai-job-definition/default/0ccb4ddedede493690edbbe7f3920e25"
    response = logs_client.get_log_events(
        logGroupName=log_group_name,
        logStreamName=log_stream_name,
        startFromHead=True)
    return response

here are the logs and the response:

with startFromHead=True logs:

2023-05-23 07:06:34,573 botocore.hooks [DEBUG] Event before-parameter-build.cloudwatch-logs.GetLogEvents: calling handler <function generate_idempotent_uuid at 0x7f4b98477f70>
2023-05-23 07:06:34,573 botocore.regions [DEBUG] Calling endpoint provider with parameters: {'Region': 'eu-central-1', 'UseDualStack': False, 'UseFIPS': False}
2023-05-23 07:06:34,574 botocore.regions [DEBUG] Endpoint provider result: https://logs.eu-central-1.amazonaws.com
2023-05-23 07:06:34,574 botocore.hooks [DEBUG] Event before-call.cloudwatch-logs.GetLogEvents: calling handler <function add_recursion_detection_header at 0x7f4b98477c10>
2023-05-23 07:06:34,574 botocore.hooks [DEBUG] Event before-call.cloudwatch-logs.GetLogEvents: calling handler <function inject_api_version_header_if_needed at 0x7f4b983ff820>
2023-05-23 07:06:34,574 botocore.endpoint [DEBUG] Making request for OperationModel(name=GetLogEvents) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'X-Amz-Target': 'Logs_20140328.GetLogEvents', 'Content-Type': 'application/x-amz-json-1.1', 'User-Agent': 'Boto3/1.26.137 Python/3.8.10 Linux/5.15.0-1036-aws Botocore/1.29.137'}, 'body': b'{"logGroupName": "/aws/batch/job", "logStreamName": "i40-low-cost-ai-job-definition/default/0ccb4ddedede493690edbbe7f3920e25", "startFromHead": true}', 'url': 'https://logs.eu-central-1.amazonaws.com/', 'context': {'client_region': 'eu-central-1', 'client_config': <botocore.config.Config object at 0x7f4b0cd82760>, 'has_streaming_input': False, 'auth_type': None}}
2023-05-23 07:06:34,574 botocore.hooks [DEBUG] Event request-created.cloudwatch-logs.GetLogEvents: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f4b0cd82940>>
2023-05-23 07:06:34,575 botocore.hooks [DEBUG] Event choose-signer.cloudwatch-logs.GetLogEvents: calling handler <function set_operation_specific_signer at 0x7f4b98477e50>
2023-05-23 07:06:34,575 botocore.auth [DEBUG] Calculating signature using v4 auth.
2023-05-23 07:06:34,575 botocore.auth [DEBUG] CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:logs.eu-central-1.amazonaws.com
x-amz-date:20230523T070634Z
x-amz-security-token:IQoJb3JpZ2luX2VjEKf//////////wEaDGV1LWNlbnRyYWwtMSJGMEQCIDgPN8osb/Q3k+xLKQoHu0JMPz9ArqHjfc27Ui9OFDHRAiAwCkn2SBQEyHVshvRqf32Sjx6fM6VwK+S880uE8m0qkCrPBQjQ//////////8BEAMaDDQ2MjAzNzIxOTczNiIMmdXE0D7qO9N/rWVSKqMFocGaJxUUYqhehYMoBp1gGb2K+QNDHHrTMVXz4wxlwlb7VPmkGINinfu7098XcsgRpUbsFhrKRLa++MuEJmHz+5mdsoY1zD78sqS/ytETG67Afq/u/siIdYoPXAaxiyGXoZW04oSsU1b/CR8VEqJp+RgPPqN9J/P/avMhkS3zEcLlHC+qxv653w93VtbiZ68YdIPLpZ/WKxi52H9ZGly3G9klbZlZwqNIs2T15Zb7L1gt5tYAQ3dIc4z5/8lK2V8gDO5tLPSkJW/NZ2KwD9ToaK/b5wfFublVoDYYB51T6B8f1TxIo8ANpbCLD+VrNobK6OEjZj/cVTyLvnNqtIoTGQuntCqDpATLdi+ACN7lcg1YgXrO6Cd8BgIJS8dJQa252onb3tC+e0bsTqCGnnsgB4XFxYf9JNEmalTTopMksucykx2zUhq1jI63vHfcJ86JsxE6dhNnQiqLvVPwc3XCSZ06oJ2l7KDxviqoARivDja0iEm6rHV4eLpT6bOO7gF7fjYA13Q+p8ptuh3xMgrDo5T1A3zeEK8Cv88QDPONBgh42YRRQ//CU/SrRDXb8i7/3HPovDli1+6xFei/NnYNSSl/IRHaft9YhxRWmC+Uz99X1gPJWNVdT4My+cl8mKp8ShtJRpf4M4wiuW/MraWroqCRa9e6WDS4MZ2fDgptmtvSHmAf8EMfEw51kUfEq3Tthl70cfRYQI+yFXrlkopf8z5YPwppMoZxvPYa527QRoChN2L2pPd2QPgrnqQyYDi0buAJegIy/M78rHfzvr5vomsI7A2lmfBUTyDy+W3nUc0dfcOC1V/S7KSitMeR28XI7kgp5uJCcfk6S0Cfr1vyC/eMsrVr+bnqLWEIxAaEr5KFm5IX7VwvEeq4pPiepe1R33gPMIDCsaMGOrIB02c5nf+c/41XdNPMr9FIDxJjIM2y9MDNQocgaKS4pA+XWeZSyn+INcNNG3UduRYLu+ZaC1q87YhLpXqomd7ygKEsREqEWozsTG/SMFl7SyyH364jwMAQNFPP4pyajYCQSMbXbKfW+AyCMzWdHN/wTplfDKr/S1dEjHv1tQnY+r7VyBY3YJ3it0fuiFbaha+6ZW1Xc/pm3thiAlFL3+4ZsvPyTZ9DPWwK2ueDUqDbh66eaQ==
x-amz-target:Logs_20140328.GetLogEvents

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
9c0c5c9192c6309bdd3dbf2f2c6ef488baaa941f95f80e7ee9f63328d2201085
2023-05-23 07:06:34,575 botocore.auth [DEBUG] StringToSign:
AWS4-HMAC-SHA256
20230523T070634Z
20230523/eu-central-1/logs/aws4_request
a93a7b34ba0aa540e9cd90028a26a062822a81ae7e9a31c82789afe677ae6771
2023-05-23 07:06:34,575 botocore.auth [DEBUG] Signature:
50089e3ab449a689eea0adc3d280857f212ff208e128c34a16b8cd71314acfd9
2023-05-23 07:06:34,576 botocore.hooks [DEBUG] Event request-created.cloudwatch-logs.GetLogEvents: calling handler <function add_retry_headers at 0x7f4b983ffee0>
2023-05-23 07:06:34,576 botocore.endpoint [DEBUG] Sending http request: <AWSPreparedRequest stream_output=False, method=POST, url=https://logs.eu-central-1.amazonaws.com/, headers={'X-Amz-Target': b'Logs_20140328.GetLogEvents', 'Content-Type': b'application/x-amz-json-1.1', 'User-Agent': b'Boto3/1.26.137 Python/3.8.10 Linux/5.15.0-1036-aws Botocore/1.29.137', 'X-Amz-Date': b'20230523T070634Z', 'X-Amz-Security-Token': b'IQoJb3JpZ2luX2VjEKf//////////wEaDGV1LWNlbnRyYWwtMSJGMEQCIDgPN8osb/Q3k+xLKQoHu0JMPz9ArqHjfc27Ui9OFDHRAiAwCkn2SBQEyHVshvRqf32Sjx6fM6VwK+S880uE8m0qkCrPBQjQ//////////8BEAMaDDQ2MjAzNzIxOTczNiIMmdXE0D7qO9N/rWVSKqMFocGaJxUUYqhehYMoBp1gGb2K+QNDHHrTMVXz4wxlwlb7VPmkGINinfu7098XcsgRpUbsFhrKRLa++MuEJmHz+5mdsoY1zD78sqS/ytETG67Afq/u/siIdYoPXAaxiyGXoZW04oSsU1b/CR8VEqJp+RgPPqN9J/P/avMhkS3zEcLlHC+qxv653w93VtbiZ68YdIPLpZ/WKxi52H9ZGly3G9klbZlZwqNIs2T15Zb7L1gt5tYAQ3dIc4z5/8lK2V8gDO5tLPSkJW/NZ2KwD9ToaK/b5wfFublVoDYYB51T6B8f1TxIo8ANpbCLD+VrNobK6OEjZj/cVTyLvnNqtIoTGQuntCqDpATLdi+ACN7lcg1YgXrO6Cd8BgIJS8dJQa252onb3tC+e0bsTqCGnnsgB4XFxYf9JNEmalTTopMksucykx2zUhq1jI63vHfcJ86JsxE6dhNnQiqLvVPwc3XCSZ06oJ2l7KDxviqoARivDja0iEm6rHV4eLpT6bOO7gF7fjYA13Q+p8ptuh3xMgrDo5T1A3zeEK8Cv88QDPONBgh42YRRQ//CU/SrRDXb8i7/3HPovDli1+6xFei/NnYNSSl/IRHaft9YhxRWmC+Uz99X1gPJWNVdT4My+cl8mKp8ShtJRpf4M4wiuW/MraWroqCRa9e6WDS4MZ2fDgptmtvSHmAf8EMfEw51kUfEq3Tthl70cfRYQI+yFXrlkopf8z5YPwppMoZxvPYa527QRoChN2L2pPd2QPgrnqQyYDi0buAJegIy/M78rHfzvr5vomsI7A2lmfBUTyDy+W3nUc0dfcOC1V/S7KSitMeR28XI7kgp5uJCcfk6S0Cfr1vyC/eMsrVr+bnqLWEIxAaEr5KFm5IX7VwvEeq4pPiepe1R33gPMIDCsaMGOrIB02c5nf+c/41XdNPMr9FIDxJjIM2y9MDNQocgaKS4pA+XWeZSyn+INcNNG3UduRYLu+ZaC1q87YhLpXqomd7ygKEsREqEWozsTG/SMFl7SyyH364jwMAQNFPP4pyajYCQSMbXbKfW+AyCMzWdHN/wTplfDKr/S1dEjHv1tQnY+r7VyBY3YJ3it0fuiFbaha+6ZW1Xc/pm3thiAlFL3+4ZsvPyTZ9DPWwK2ueDUqDbh66eaQ==', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAWXE4QPGMFGFZAHVL/20230523/eu-central-1/logs/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-security-token;x-amz-target, Signature=50089e3ab449a689eea0adc3d280857f212ff208e128c34a16b8cd71314acfd9', 'amz-sdk-invocation-id': b'b66e4bea-33b8-4262-823d-4dc2a9f97515', 'amz-sdk-request': b'attempt=1', 'Content-Length': '149'}>
2023-05-23 07:06:34,576 botocore.httpsession [DEBUG] Certificate path: /home/fabian.friedrich/git/i40_shopfloor_data_analyzer/backend/env/lib/python3.8/site-packages/certifi/cacert.pem
2023-05-23 07:06:34,577 urllib3.connectionpool [DEBUG] Starting new HTTPS connection (1): logs.eu-central-1.amazonaws.com:443
2023-05-23 07:06:35,221 urllib3.connectionpool [DEBUG] https://logs.eu-central-1.amazonaws.com:443 "POST / HTTP/1.1" 200 4881
2023-05-23 07:06:35,221 botocore.parsers [DEBUG] Response headers: {'x-amzn-RequestId': 'ff1c4555-7cf4-4f3a-b7be-be98c2e35c24', 'Content-Type': 'application/x-amz-json-1.1', 'Content-Length': '4881', 'Date': 'Tue, 23 May 2023 07:06:35 GMT'}
2023-05-23 07:06:35,221 botocore.parsers [DEBUG] Response body:
b'{"events":[{"eventId":"37571569526160104917776833573623690826332428178312593408","ingestionTime":1684767447941,"message":"==========","timestamp":1684767445737},{"eventId":"37571569526160104917776833573623690826332428178312593409","ingestionTime":1684767447941,"message":"== CUDA ==","timestamp":1684767445737},{"eventId":"37571569526160104917776833573623690826332428178312593410","ingestionTime":1684767447941,"message":"==========","timestamp":1684767445737},{"eventId":"37571569526227007153372425443048297981150373262830534659","ingestionTime":1684767447941,"message":"CUDA Version 12.0.1","timestamp":1684767445740},{"eventId":"37571569526249307898570956066189833699423021624336515076","ingestionTime":1684767447941,"message":"Container image Copyright (c) 2016-2022, NVIDIA CORPORATION & AFFILIATES. All rights reserved.","timestamp":1684767445741},{"eventId":"37571569526271608643769486689331369417695669985842495493","ingestionTime":1684767447941,"message":"This container image and its contents are governed by the NVIDIA Deep Learning Container License.","timestamp":1684767445742},{"eventId":"37571569526271608643769486689331369417695669985842495494","ingestionTime":1684767447941,"message":"By pulling and using the container, you accept the terms and conditions of this license:","timestamp":1684767445742},{"eventId":"37571569526271608643769486689331369417695669985842495495","ingestionTime":1684767447941,"message":"https://developer.nvidia.com/ngc/nvidia-deep-learning-container-license","timestamp":1684767445742},{"eventId":"37571569526271608643769486689331369417695669985842495496","ingestionTime":1684767447941,"message":"A copy of this license is made available in this container at /NGC-DL-CONTAINER-LICENSE for your convenience.","timestamp":1684767445742},{"eventId":"37571569569133640915345344367363019937725820800336855049","ingestionTime":1684767447941,"message":" ############################ ","timestamp":1684767447664},{"eventId":"37571569569133640915345344367363019937725820800336855050","ingestionTime":1684767447941,"message":" EXPERIMENT NAME ","timestamp":1684767447664},{"eventId":"37571569569133640915345344367363019937725820800336855051","ingestionTime":1684767447941,"message":"LCAI_muelles3d_tfm3","timestamp":1684767447664},{"eventId":"37571569569133640915345344367363019937725820800336855052","ingestionTime":1684767447941,"message":" ############################ ","timestamp":1684767447664},{"eventId":"37571569570003369978088038669882912950359106899070091277","ingestionTime":1684767447941,"message":"Traceback (most recent call last):","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091278","ingestionTime":1684767447941,"message":"  File \\"/lowcostai/main.py\\", line 35, in <module>","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091279","ingestionTime":1684767447941,"message":"    main()","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091280","ingestionTime":1684767447941,"message":"  File \\"/lowcostai/main.py\\", line 29, in main","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091281","ingestionTime":1684767447941,"message":"    mlflow_url = pipeline.run(Path(temp_dir), config_path)","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091282","ingestionTime":1684767447941,"message":"  File \\"/lowcostai/src/pipeline/pipeline.py\\", line 114, in run","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091283","ingestionTime":1684767447941,"message":"    mlflow_url = self._run_locally(temp_dir, run_modules,","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091284","ingestionTime":1684767447941,"message":"  File \\"/lowcostai/src/pipeline/pipeline.py\\", line 282, in _run_locally","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091285","ingestionTime":1684767447941,"message":"    mlflow_client = MLflow(experiment_config, temp_dir)","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091286","ingestionTime":1684767447941,"message":"  File \\"/lowcostai/src/client/mlflow.py\\", line 61, in __init__","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091287","ingestionTime":1684767447941,"message":"    self._additional_artifacts = self._experiment_config[\\"mlflow\\"][","timestamp":1684767447703},{"eventId":"37571569570003369978088038669882912950359106899070091288","ingestionTime":1684767447941,"message":"KeyError: \'mlflow\'","timestamp":1684767447703}],"nextBackwardToken":"b/37571569526160104917776833573623690826332428178312593408/s","nextForwardToken":"f/37571569570003369978088038669882912950359106899070091288/s"}'
2023-05-23 07:06:35,222 botocore.hooks [DEBUG] Event needs-retry.cloudwatch-logs.GetLogEvents: calling handler <botocore.retryhandler.RetryHandler object at 0x7f4aff92d220>
2023-05-23 07:06:35,222 botocore.retryhandler [DEBUG] No retry needed.

response:

{
  "events": [
    {
      "timestamp": 1684767445737,
      "message": "==========",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767445737,
      "message": "== CUDA ==",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767445737,
      "message": "==========",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767445740,
      "message": "CUDA Version 12.0.1",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767445741,
      "message": "Container image Copyright (c) 2016-2022, NVIDIA CORPORATION & AFFILIATES. All rights reserved.",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767445742,
      "message": "This container image and its contents are governed by the NVIDIA Deep Learning Container License.",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767445742,
      "message": "By pulling and using the container, you accept the terms and conditions of this license:",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767445742,
      "message": "https://developer.nvidia.com/ngc/nvidia-deep-learning-container-license",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767445742,
      "message": "A copy of this license is made available in this container at /NGC-DL-CONTAINER-LICENSE for your convenience.",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447664,
      "message": " ############################ ",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447664,
      "message": " EXPERIMENT NAME ",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447664,
      "message": "LCAI_muelles3d_tfm3",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447664,
      "message": " ############################ ",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "Traceback (most recent call last):",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "  File \"/lowcostai/main.py\", line 35, in <module>",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "    main()",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "  File \"/lowcostai/main.py\", line 29, in main",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "    mlflow_url = pipeline.run(Path(temp_dir), config_path)",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "  File \"/lowcostai/src/pipeline/pipeline.py\", line 114, in run",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "    mlflow_url = self._run_locally(temp_dir, run_modules,",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "  File \"/lowcostai/src/pipeline/pipeline.py\", line 282, in _run_locally",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "    mlflow_client = MLflow(experiment_config, temp_dir)",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "  File \"/lowcostai/src/client/mlflow.py\", line 61, in __init__",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "    self._additional_artifacts = self._experiment_config[\"mlflow\"][",
      "ingestionTime": 1684767447941
    },
    {
      "timestamp": 1684767447703,
      "message": "KeyError: 'mlflow'",
      "ingestionTime": 1684767447941
    }
  ],
  "nextForwardToken": "f/37571569570003369978088038669882912950359106899070091288/s",
  "nextBackwardToken": "b/37571569526160104917776833573623690826332428178312593408/s",
  "ResponseMetadata": {
    "RequestId": "94993848-6a1b-4879-b524-381bf41bd25f",
    "HTTPStatusCode": 200,
    "HTTPHeaders": {
      "x-amzn-requestid": "94993848-6a1b-4879-b524-381bf41bd25f",
      "content-type": "application/x-amz-json-1.1",
      "content-length": "4881",
      "date": "Tue, 23 May 2023 06:59:00 GMT"
    },
    "RetryAttempts": 0
  }
}
@router.get("/logs")
def logs():
    boto3.set_stream_logger('')
    logs_client = boto3.client('logs', region_name="eu-central-1")
    log_group_name = '/aws/batch/job'
    log_stream_name = "i40-low-cost-ai-job-definition/default/0ccb4ddedede493690edbbe7f3920e25"
    response = logs_client.get_log_events(
        logGroupName=log_group_name,
        logStreamName=log_stream_name,
        startFromHead=False)
    return response

startFromHead=False

logs:

2023-05-23 07:07:06,605 botocore.hooks [DEBUG] Event before-parameter-build.cloudwatch-logs.GetLogEvents: calling handler <function generate_idempotent_uuid at 0x7fabd03edf70>
2023-05-23 07:07:06,605 botocore.regions [DEBUG] Calling endpoint provider with parameters: {'Region': 'eu-central-1', 'UseDualStack': False, 'UseFIPS': False}
2023-05-23 07:07:06,606 botocore.regions [DEBUG] Endpoint provider result: https://logs.eu-central-1.amazonaws.com
2023-05-23 07:07:06,606 botocore.hooks [DEBUG] Event before-call.cloudwatch-logs.GetLogEvents: calling handler <function add_recursion_detection_header at 0x7fabd03edc10>
2023-05-23 07:07:06,606 botocore.hooks [DEBUG] Event before-call.cloudwatch-logs.GetLogEvents: calling handler <function inject_api_version_header_if_needed at 0x7fabd0375820>
2023-05-23 07:07:06,606 botocore.endpoint [DEBUG] Making request for OperationModel(name=GetLogEvents) with params: {'url_path': '/', 'query_string': '', 'method': 'POST', 'headers': {'X-Amz-Target': 'Logs_20140328.GetLogEvents', 'Content-Type': 'application/x-amz-json-1.1', 'User-Agent': 'Boto3/1.26.137 Python/3.8.10 Linux/5.15.0-1036-aws Botocore/1.29.137'}, 'body': b'{"logGroupName": "/aws/batch/job", "logStreamName": "i40-low-cost-ai-job-definition/default/0ccb4ddedede493690edbbe7f3920e25", "startFromHead": false}', 'url': 'https://logs.eu-central-1.amazonaws.com/', 'context': {'client_region': 'eu-central-1', 'client_config': <botocore.config.Config object at 0x7fab46fbf280>, 'has_streaming_input': False, 'auth_type': None}}
2023-05-23 07:07:06,606 botocore.hooks [DEBUG] Event request-created.cloudwatch-logs.GetLogEvents: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7fab46fbf1f0>>
2023-05-23 07:07:06,606 botocore.hooks [DEBUG] Event choose-signer.cloudwatch-logs.GetLogEvents: calling handler <function set_operation_specific_signer at 0x7fabd03ede50>
2023-05-23 07:07:06,607 botocore.auth [DEBUG] Calculating signature using v4 auth.
2023-05-23 07:07:06,607 botocore.auth [DEBUG] CanonicalRequest:
POST
/

content-type:application/x-amz-json-1.1
host:logs.eu-central-1.amazonaws.com
x-amz-date:20230523T070706Z
x-amz-security-token:IQoJb3JpZ2luX2VjEKf//////////wEaDGV1LWNlbnRyYWwtMSJGMEQCIDgPN8osb/Q3k+xLKQoHu0JMPz9ArqHjfc27Ui9OFDHRAiAwCkn2SBQEyHVshvRqf32Sjx6fM6VwK+S880uE8m0qkCrPBQjQ//////////8BEAMaDDQ2MjAzNzIxOTczNiIMmdXE0D7qO9N/rWVSKqMFocGaJxUUYqhehYMoBp1gGb2K+QNDHHrTMVXz4wxlwlb7VPmkGINinfu7098XcsgRpUbsFhrKRLa++MuEJmHz+5mdsoY1zD78sqS/ytETG67Afq/u/siIdYoPXAaxiyGXoZW04oSsU1b/CR8VEqJp+RgPPqN9J/P/avMhkS3zEcLlHC+qxv653w93VtbiZ68YdIPLpZ/WKxi52H9ZGly3G9klbZlZwqNIs2T15Zb7L1gt5tYAQ3dIc4z5/8lK2V8gDO5tLPSkJW/NZ2KwD9ToaK/b5wfFublVoDYYB51T6B8f1TxIo8ANpbCLD+VrNobK6OEjZj/cVTyLvnNqtIoTGQuntCqDpATLdi+ACN7lcg1YgXrO6Cd8BgIJS8dJQa252onb3tC+e0bsTqCGnnsgB4XFxYf9JNEmalTTopMksucykx2zUhq1jI63vHfcJ86JsxE6dhNnQiqLvVPwc3XCSZ06oJ2l7KDxviqoARivDja0iEm6rHV4eLpT6bOO7gF7fjYA13Q+p8ptuh3xMgrDo5T1A3zeEK8Cv88QDPONBgh42YRRQ//CU/SrRDXb8i7/3HPovDli1+6xFei/NnYNSSl/IRHaft9YhxRWmC+Uz99X1gPJWNVdT4My+cl8mKp8ShtJRpf4M4wiuW/MraWroqCRa9e6WDS4MZ2fDgptmtvSHmAf8EMfEw51kUfEq3Tthl70cfRYQI+yFXrlkopf8z5YPwppMoZxvPYa527QRoChN2L2pPd2QPgrnqQyYDi0buAJegIy/M78rHfzvr5vomsI7A2lmfBUTyDy+W3nUc0dfcOC1V/S7KSitMeR28XI7kgp5uJCcfk6S0Cfr1vyC/eMsrVr+bnqLWEIxAaEr5KFm5IX7VwvEeq4pPiepe1R33gPMIDCsaMGOrIB02c5nf+c/41XdNPMr9FIDxJjIM2y9MDNQocgaKS4pA+XWeZSyn+INcNNG3UduRYLu+ZaC1q87YhLpXqomd7ygKEsREqEWozsTG/SMFl7SyyH364jwMAQNFPP4pyajYCQSMbXbKfW+AyCMzWdHN/wTplfDKr/S1dEjHv1tQnY+r7VyBY3YJ3it0fuiFbaha+6ZW1Xc/pm3thiAlFL3+4ZsvPyTZ9DPWwK2ueDUqDbh66eaQ==
x-amz-target:Logs_20140328.GetLogEvents

content-type;host;x-amz-date;x-amz-security-token;x-amz-target
57fb4965f3554ac4f558ded497e72ad302968fd31aca9d943fe547d11f51eb34
2023-05-23 07:07:06,607 botocore.auth [DEBUG] StringToSign:
AWS4-HMAC-SHA256
20230523T070706Z
20230523/eu-central-1/logs/aws4_request
68276f29b338d0143b592e0c8c57f9bbc5dcf34499097ba3c16ed67815d5ca0a
2023-05-23 07:07:06,607 botocore.auth [DEBUG] Signature:
1b1404b3c28cb53715a832e1114bbc0acc20e5757bb1b3786246d95a7d1ee6a5
2023-05-23 07:07:06,607 botocore.hooks [DEBUG] Event request-created.cloudwatch-logs.GetLogEvents: calling handler <function add_retry_headers at 0x7fabd0375ee0>
2023-05-23 07:07:06,607 botocore.endpoint [DEBUG] Sending http request: <AWSPreparedRequest stream_output=False, method=POST, url=https://logs.eu-central-1.amazonaws.com/, headers={'X-Amz-Target': b'Logs_20140328.GetLogEvents', 'Content-Type': b'application/x-amz-json-1.1', 'User-Agent': b'Boto3/1.26.137 Python/3.8.10 Linux/5.15.0-1036-aws Botocore/1.29.137', 'X-Amz-Date': b'20230523T070706Z', 'X-Amz-Security-Token': b'IQoJb3JpZ2luX2VjEKf//////////wEaDGV1LWNlbnRyYWwtMSJGMEQCIDgPN8osb/Q3k+xLKQoHu0JMPz9ArqHjfc27Ui9OFDHRAiAwCkn2SBQEyHVshvRqf32Sjx6fM6VwK+S880uE8m0qkCrPBQjQ//////////8BEAMaDDQ2MjAzNzIxOTczNiIMmdXE0D7qO9N/rWVSKqMFocGaJxUUYqhehYMoBp1gGb2K+QNDHHrTMVXz4wxlwlb7VPmkGINinfu7098XcsgRpUbsFhrKRLa++MuEJmHz+5mdsoY1zD78sqS/ytETG67Afq/u/siIdYoPXAaxiyGXoZW04oSsU1b/CR8VEqJp+RgPPqN9J/P/avMhkS3zEcLlHC+qxv653w93VtbiZ68YdIPLpZ/WKxi52H9ZGly3G9klbZlZwqNIs2T15Zb7L1gt5tYAQ3dIc4z5/8lK2V8gDO5tLPSkJW/NZ2KwD9ToaK/b5wfFublVoDYYB51T6B8f1TxIo8ANpbCLD+VrNobK6OEjZj/cVTyLvnNqtIoTGQuntCqDpATLdi+ACN7lcg1YgXrO6Cd8BgIJS8dJQa252onb3tC+e0bsTqCGnnsgB4XFxYf9JNEmalTTopMksucykx2zUhq1jI63vHfcJ86JsxE6dhNnQiqLvVPwc3XCSZ06oJ2l7KDxviqoARivDja0iEm6rHV4eLpT6bOO7gF7fjYA13Q+p8ptuh3xMgrDo5T1A3zeEK8Cv88QDPONBgh42YRRQ//CU/SrRDXb8i7/3HPovDli1+6xFei/NnYNSSl/IRHaft9YhxRWmC+Uz99X1gPJWNVdT4My+cl8mKp8ShtJRpf4M4wiuW/MraWroqCRa9e6WDS4MZ2fDgptmtvSHmAf8EMfEw51kUfEq3Tthl70cfRYQI+yFXrlkopf8z5YPwppMoZxvPYa527QRoChN2L2pPd2QPgrnqQyYDi0buAJegIy/M78rHfzvr5vomsI7A2lmfBUTyDy+W3nUc0dfcOC1V/S7KSitMeR28XI7kgp5uJCcfk6S0Cfr1vyC/eMsrVr+bnqLWEIxAaEr5KFm5IX7VwvEeq4pPiepe1R33gPMIDCsaMGOrIB02c5nf+c/41XdNPMr9FIDxJjIM2y9MDNQocgaKS4pA+XWeZSyn+INcNNG3UduRYLu+ZaC1q87YhLpXqomd7ygKEsREqEWozsTG/SMFl7SyyH364jwMAQNFPP4pyajYCQSMbXbKfW+AyCMzWdHN/wTplfDKr/S1dEjHv1tQnY+r7VyBY3YJ3it0fuiFbaha+6ZW1Xc/pm3thiAlFL3+4ZsvPyTZ9DPWwK2ueDUqDbh66eaQ==', 'Authorization': b'AWS4-HMAC-SHA256 Credential=ASIAWXE4QPGMFGFZAHVL/20230523/eu-central-1/logs/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-security-token;x-amz-target, Signature=1b1404b3c28cb53715a832e1114bbc0acc20e5757bb1b3786246d95a7d1ee6a5', 'amz-sdk-invocation-id': b'2f9a90f2-8d25-4055-8791-4d99c8b87c0f', 'amz-sdk-request': b'attempt=1', 'Content-Length': '150'}>
2023-05-23 07:07:06,608 botocore.httpsession [DEBUG] Certificate path: /home/fabian.friedrich/git/i40_shopfloor_data_analyzer/backend/env/lib/python3.8/site-packages/certifi/cacert.pem
2023-05-23 07:07:06,608 urllib3.connectionpool [DEBUG] Starting new HTTPS connection (1): logs.eu-central-1.amazonaws.com:443
2023-05-23 07:07:07,403 urllib3.connectionpool [DEBUG] https://logs.eu-central-1.amazonaws.com:443 "POST / HTTP/1.1" 200 178
2023-05-23 07:07:07,404 botocore.parsers [DEBUG] Response headers: {'x-amzn-RequestId': '071a8b43-146c-45e7-8076-4511fe61bbc4', 'Content-Type': 'application/x-amz-json-1.1', 'Content-Length': '178', 'Date': 'Tue, 23 May 2023 07:07:07 GMT'}
2023-05-23 07:07:07,404 botocore.parsers [DEBUG] Response body:
b'{"events":[],"nextBackwardToken":"b/37572757135910003452758407935126203286358978671411200000/s","nextForwardToken":"f/37573027568974156271757159761545765678340254830751121408/s"}'
2023-05-23 07:07:07,404 botocore.hooks [DEBUG] Event needs-retry.cloudwatch-logs.GetLogEvents: calling handler <botocore.retryhandler.RetryHandler object at 0x7fab46f5c6d0>
2023-05-23 07:07:07,405 botocore.retryhandler [DEBUG] No retry needed.

response:

{
  "events": [],
  "nextForwardToken": "f/37573027568974156271757159761545765678340254830751121408/s",
  "nextBackwardToken": "b/37572757135910003452758407935126203286358978671411200000/s",
  "ResponseMetadata": {
    "RequestId": "071a8b43-146c-45e7-8076-4511fe61bbc4",
    "HTTPStatusCode": 200,
    "HTTPHeaders": {
      "x-amzn-requestid": "071a8b43-146c-45e7-8076-4511fe61bbc4",
      "content-type": "application/x-amz-json-1.1",
      "content-length": "178",
      "date": "Tue, 23 May 2023 07:07:07 GMT"
    },
    "RetryAttempts": 0
  }
}

Thanks!

RyanFitzSimmonsAK commented 1 year ago

Could you try adding an endTime and startTime to your run, and reporting back with the results? Also, if this script is something you've been using for awhile, is this behavior only something that started recently?

Fabianofski commented 1 year ago

Hey, Its the first time we're using this. Adding startTime and endTime fixed the issue. Thanks for that! We also tried using filter_log_events, which also didnt work for us, until we added startTime and endTime.

The behaviour seems a bit confusing to me. In my opinion it should just return all the events, when startTime and endTime are not specified.

RyanFitzSimmonsAK commented 1 year ago

Yeah, I agree this behavior doesn't quite make sense, so I'm still looking into this. I'm glad we have a workaround in the meantime though. Could you tell me most recent date in your log stream?

Fabianofski commented 1 year ago

I dont know if you need something else, but in my 2nd reply i added the response of get_log_events and the most recent timestamp of that logstream is this one: 

    {
      "timestamp": 1684767447703,
      "message": "KeyError: 'mlflow'",
      "ingestionTime": 1684767447941
    }

Converted to a date it is "Mon May 22 2023 14:57:27 UTC"

RyanFitzSimmonsAK commented 1 year ago

Hi @Fabianofski; it looks like the service team is already aware of this behavior. The reason behind this behavior is that get_log_events returns a paginated response, with pages being split by time. The responses you're getting with no events are periods of time where no events happened, and you need to keep paginating using the nextBackwardToken. The end condition for this pagination is when the token in your request is the same as the token you receive in the response. I hope that clarifies this, please let me know if you have any follow-up questions.

Fabianofski commented 1 year ago

Hi @RyanFitzSimmonsAK, yes that makes sense. Thank you for your time and help!

vishalmuthal commented 6 months ago

Hi @Fabianofski @RyanFitzSimmonsAK ,

I am facing exactly same issue. My use case is to get the aws accounts usage by fetching the log events for latest log group of nginx acees logs. I've a script that pulls data ( response) and checks if accounts are in use. Since the response is not complete I am getting false data or incomplete data.

Code :

log_events = logs_client.get_log_events( logGroupName=log_group_name, logStreamName=log_stream['logStreamName'], startFromHead=False, startTime=##time before 24 hrs", endTime=##lastEventTimeStamp for loggroup name, limit=10000)

If there is any workaround, please let me know. It will be very helpful.

RyanFitzSimmonsAK commented 6 months ago

Hi @vishalmuthal, you probably need to continue paginating in the manner described here. Did that not work for your use case?

danzingCode commented 5 months ago

as @RyanFitzSimmonsAK mentioned, its related to his answer. in the answer here you find a working solution. Check Cloudwatch logs by using aws console and reload newer items if required. Using boto3 for this will take at least the same time. https://stackoverflow.com/questions/67671543/getting-all-log-events-while-passing-optional-argument

jasonheffnerpsu commented 2 months ago

For anyone else who might stumble on this.. I attempted several methods when trying to fetch the last number of events from a log stream using startFromHead=False, including setting startTime and endTime. The only thing that worked reliably was using pagination with nextBackwardToken as suggested in one of the linked posts. I had a low traffic log stream that wouldn't return any events when queried, sometimes.

import boto3

# Define log group, log stream, and number of events to return
log_group = "<log group name>"
log_stream = "<log stream name>"
count = 2

logs = boto3.client('logs')

events = []
next_token = None

while len(events) < count:
    kwargs = {
        'logGroupName': log_group,
        'logStreamName': log_stream,
        'limit': count - len(events),
        'startFromHead': False
    }
    if next_token:
        kwargs['nextToken'] = next_token

    events_response = logs.get_log_events(**kwargs)

    if events_response.get('events'):
        events.extend(events_response['events'])

    # Check for next backward token and update it; otherwise, break
    # Based on docs, If you have reached the end of the stream, it returns the same token you passed in
    if 'nextBackwardToken' in events_response:
        if next_token == events_response['nextBackwardToken']:
            break  # No new token, exit the loop
        next_token = events_response['nextBackwardToken']
    else:
        break

if not events:
    raise Exception("No log events found")

return events