Debug invoice_lines_from_invoices task #1259

shelleydoljack · 2024-10-08T20:28:19Z

When running the digital_bookplate_instances DAG locally with okapi-dev as folio, it fails on the invoice_lines_from_invoices_task. The error in the log shows:

[2024-10-08, 18:33:33 UTC] {invoices.py:135} INFO - Getting invoice lines for 9a7749c6-2d4d-4d9f-9ed0-db121070f2b0
[2024-10-08, 18:33:33 UTC] {_client.py:1038} INFO - HTTP Request: GET https://okapi-dev.stanford.edu/invoice/invoice-lines?query=%28invoiceId%3D%3D9a7749c6-2d4d-4d9f-9ed0-db121070f2b0%29&limit=500&offset=0 "HTTP/1.1 200 OK"
[2024-10-08, 18:33:34 UTC] {_client.py:1038} INFO - HTTP Request: GET https://okapi-dev.stanford.edu/invoice/invoice-lines?query=%28invoiceId%3D%3D9a7749c6-2d4d-4d9f-9ed0-db121070f2b0%29&limit=500&offset=500 "HTTP/1.1 200 OK"
[2024-10-08, 18:33:34 UTC] {invoices.py:135} INFO - Getting invoice lines for 6c8bd41e-96e9-4321-a151-9402026d187a
[2024-10-08, 18:33:38 UTC] {taskinstance.py:2731} ERROR - Task failed with exception
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 72, in map_httpcore_exceptions
    yield
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 236, in handle_request
    resp = self._pool.handle_request(req)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection_pool.py", line 216, in handle_request
    raise exc from None
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection_pool.py", line 196, in handle_request
    response = connection.handle_request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection.py", line 101, in handle_request
    return self._connection.handle_request(request)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 143, in handle_request
    raise exc
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 113, in handle_request
    ) = self._receive_response_headers(**kwargs)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 186, in _receive_response_headers
    event = self._receive_event(timeout=timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 238, in _receive_event
    raise RemoteProtocolError(msg)
httpcore.RemoteProtocolError: Server disconnected without sending a response.
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/models/taskinstance.py", line 444, in _execute_task
    result = _execute_callable(context=context, **execute_callable_kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/models/taskinstance.py", line 414, in _execute_callable
    return execute_callable(context=context, **execute_callable_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/decorators/base.py", line 241, in execute
    return_value = super().execute(context)
                   ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/operators/python.py", line 200, in execute
    return_value = self.execute_callable()
                   ^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/operators/python.py", line 217, in execute_callable
    return self.python_callable(*self.op_args, **self.op_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/folio/invoices.py", line 137, in invoice_lines_from_invoices
    invoice_lines = _get_all_invoice_lines(query, folio_client)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/folio/invoices.py", line 55, in _get_all_invoice_lines
    return [row for row in invoice_lines]
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/folio/invoices.py", line 55, in <listcomp>
    return [row for row in invoice_lines]
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/folioclient/FolioClient.py", line 307, in folio_get_all
    temp_res = self.folio_get(path, key, query_params=query_params)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/folioclient/FolioClient.py", line 361, in folio_get
    req = self.httpx_client.get(url, params=query_params, headers=self.okapi_headers)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 1066, in get
    return self.request(
           ^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 837, in request
    return self.send(request, auth=auth, follow_redirects=follow_redirects)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 926, in send
    response = self._send_handling_auth(
               ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 954, in _send_handling_auth
    response = self._send_handling_redirects(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 991, in _send_handling_redirects
    response = self._send_single_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 1027, in _send_single_request
    response = transport.handle_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 235, in handle_request
    with map_httpcore_exceptions():
  File "/usr/local/lib/python3.11/contextlib.py", line 158, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 89, in map_httpcore_exceptions
    raise mapped_exc(message) from exc
httpx.RemoteProtocolError: Server disconnected without sending a response.

In looking at the logs for okapi, mod-invoice, and mod-invoice-storage, I see in okapi there are 2 requests for the invoice ID that stopped everything (the second GET is probably the airflow task retry):

"2024-10-08T18:30:52,147\tINFO\t?\t348159/invoice;695496/invoice-storage RES 200 8630us mod-invoice-storage-5.7.0 http://mod-invoice-storage/invoice-storage/invoice-lines?offset=0&query=invoiceId%3D%3D6c8bd41e-96e9-4321-a151-9402026d187a&limit=2147483647\t"
"2024-10-08T18:31:06,753\tINFO\t?\t939406/invoice;332864/invoice-storage RES 200 4497us mod-invoice-storage-5.7.0 http://mod-invoice-storage/invoice-storage/invoice-lines?offset=0&query=invoiceId%3D%3D6c8bd41e-96e9-4321-a151-9402026d187a&limit=2147483647\t"

In the mod-invoice, these 2 requests (request ID's 348159 and 939406) appear as:

"18:30:42 [348159/invoice] [sul] [07e8be0e-1cf5-5061-b5b3-4517d9a74d77] [mod_invoice] INFO  RestClient           Calling GET /invoice-storage/invoice-lines?offset=0&query=invoiceId%3D%3D6c8bd41e-96e9-4321-a151-9402026d187a&limit=2147483647"
"18:30:45 [939406/invoice] [sul] [07e8be0e-1cf5-5061-b5b3-4517d9a74d77] [mod_invoice] INFO  RestClient           Calling GET /invoice-storage/invoice-lines?offset=0&query=invoiceId%3D%3D6c8bd41e-96e9-4321-a151-9402026d187a&limit=2147483647"

And only request ID 348159 has a response (16s later):

"18:30:58 [348159/invoice] [sul] [07e8be0e-1cf5-5061-b5b3-4517d9a74d77] [mod_invoice] INFO  InvoicesImpl         Successfully retrieved invoices: {\"invoices\":[{\"id\":\"936b7105-6e3b-4976-8603-56fc5b9744bf\",\"accountingCode\":\"031134FEEDER\",\"adjustments\":[],\"adjustmentsTotal\":0.0,\"approvedBy\":\"08a8b799-1f76-419b-8d3a-c91d8ae12c25\",\"approvalDate\":\"2024-09-09T18:43:03.198+00:00\",\"batchGroupId\":\"2a2cb998-1437-41d1-88ad-01930aaeadd5\",\"chkSubscriptionOverlap\":false,\"currency\":\"USD\",\"enclosureNeeded\":false,\"exchangeRate\":1.0,\"exportToAccounting\":true,\"folioInvoiceNo\":\"21971\",\"invoiceDate\":\"2024-08-28T00:00:00.000+00:00\",\"paymentDate\":\"2024-09-27T01:03:30.678+00:00\",\"paymentMethod\":\"EFT\",\"status\":
<snip>

The response contains "totalRecords":598 and includes all the invoice lines for all the invoices that are queried. So I'm thinking the folio_client's folio_get_all works in some unexpected way.

The text was updated successfully, but these errors were encountered:

shelleydoljack · 2024-10-08T23:02:46Z

The log error might be related to something else and not necessarily the invoice_lines_from_invoices task. I cleared out my local digital_bookplates table and ran the fetch_digital_bookplates dag and one of the add_update_model mapped tasks failed with a folio_client error:

[2024-10-08, 22:53:44 UTC] {taskinstance.py:2731} ERROR - Task failed with exception
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 72, in map_httpcore_exceptions
    yield
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 236, in handle_request
    resp = self._pool.handle_request(req)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection_pool.py", line 216, in handle_request
    raise exc from None
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection_pool.py", line 196, in handle_request
    response = connection.handle_request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection.py", line 101, in handle_request
    return self._connection.handle_request(request)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 143, in handle_request
    raise exc
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 113, in handle_request
    ) = self._receive_response_headers(**kwargs)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 186, in _receive_response_headers
    event = self._receive_event(timeout=timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 238, in _receive_event
    raise RemoteProtocolError(msg)
httpcore.RemoteProtocolError: Server disconnected without sending a response.
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/models/taskinstance.py", line 444, in _execute_task
    result = _execute_callable(context=context, **execute_callable_kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/models/taskinstance.py", line 414, in _execute_callable
    return execute_callable(context=context, **execute_callable_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/decorators/base.py", line 241, in execute
    return_value = super().execute(context)
                   ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/operators/python.py", line 200, in execute
    return_value = self.execute_callable()
                   ^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/operators/python.py", line 217, in execute_callable
    return self.python_callable(*self.op_args, **self.op_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/digital_bookplates/purl_fetcher.py", line 50, in add_update_model
    metadata["db_id"] = _add_bookplate(metadata, session)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/digital_bookplates/purl_fetcher.py", line 180, in _add_bookplate
    fund_uuid=_fetch_folio_fund_id(metadata['fund_name']),
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/digital_bookplates/purl_fetcher.py", line 225, in _fetch_folio_fund_id
    folio_client = _folio_client()
                   ^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/digital_bookplates/purl_fetcher.py", line 27, in _folio_client
    return FolioClient(
           ^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/folioclient/FolioClient.py", line 54, in __init__
    self.login()
  File "/home/airflow/.local/lib/python3.11/site-packages/folioclient/decorators.py", line 28, in wrapper
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/folioclient/FolioClient.py", line 259, in login
    req = httpx.post(
          ^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_api.py", line 331, in post
    return request(
           ^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_api.py", line 118, in request
    return client.request(
           ^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 837, in request
    return self.send(request, auth=auth, follow_redirects=follow_redirects)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 926, in send
    response = self._send_handling_auth(
               ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 954, in _send_handling_auth
    response = self._send_handling_redirects(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 991, in _send_handling_redirects
    response = self._send_single_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 1027, in _send_single_request
    response = transport.handle_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 235, in handle_request
    with map_httpcore_exceptions():
  File "/usr/local/lib/python3.11/contextlib.py", line 158, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 89, in map_httpcore_exceptions
    raise mapped_exc(message) from exc
httpx.RemoteProtocolError: Server disconnected without sending a response.
[2024-10-08, 22:53:44 UTC] {taskinstance.py:1149} INFO - Marking task as FAILED. dag_id=fetch_digital_bookplates, task_id=retrieve-process-db.add_update_model, map_index=423, execution_date=20241008T223757, start_date=20241008T225340, end_date=20241008T225344
[2024-10-08, 22:53:45 UTC] {standard_task_runner.py:107} ERROR - Failed to execute job 4716 for task retrieve-process-db.add_update_model (Server disconnected without sending a response.; 49529)

jermnelson · 2024-10-09T16:24:22Z

I'm thinking it may be a timeout issue with Okapi call, looking at the FolioClient source code, we can set an environmental variable FOLIOCLIENT_HTTP_TIMEOUT in our docker-compose file to a larger value and see if that fixes this error. The default httpx timeout is 5 seconds.

jermnelson · 2024-10-09T20:26:07Z

I think this error may stem from a problem with the folio-dev Okapi handling of HTTP connection pooling being established by the folio_client's underlying httpx package (see this comment). Running the digital_bookplate_instances DAG using folio-stage and not seeing these errors.

shelleydoljack · 2024-10-11T20:37:20Z

I deployed to airflow-dev and the same task fails in the same way with folio-test. It got about a 3rd of the way through the list of invoice-lines and failed, restarting the whole task (iterating through the list again). I guess I will try to set the FOLIOCLIENT_HTTP_TIMEOUT to a larger setting. Although, we might see the problem again because of what you found about the server dropping the connection.

shelleydoljack · 2024-10-14T17:00:55Z

Re-running the fetch digital bookplates dag on airflow dev, one of the bookplates failed on the first attempt to get the folio fund uuid with the same error:

74ec402cfb3d
*** Found local files:
***   * /opt/airflow/logs/dag_id=fetch_digital_bookplates/run_id=manual__2024-10-11T20:43:12.492678+00:00/task_id=retrieve-process-db.add_update_model/map_index=70/attempt=1.log
[2024-10-14, 16:56:49 UTC] {taskinstance.py:1979} INFO - Dependencies all met for dep_context=non-requeueable deps ti=<TaskInstance: fetch_digital_bookplates.retrieve-process-db.add_update_model manual__2024-10-11T20:43:12.492678+00:00 map_index=70 [queued]>
[2024-10-14, 16:56:49 UTC] {taskinstance.py:1979} INFO - Dependencies all met for dep_context=requeueable deps ti=<TaskInstance: fetch_digital_bookplates.retrieve-process-db.add_update_model manual__2024-10-11T20:43:12.492678+00:00 map_index=70 [queued]>
[2024-10-14, 16:56:49 UTC] {taskinstance.py:2193} INFO - Starting attempt 1 of 2
[2024-10-14, 16:56:49 UTC] {taskinstance.py:2217} INFO - Executing <Task(_PythonDecoratedOperator): retrieve-process-db.add_update_model> on 2024-10-11 20:43:12.492678+00:00
[2024-10-14, 16:56:49 UTC] {standard_task_runner.py:60} INFO - Started process 5267 to run task
[2024-10-14, 16:56:49 UTC] {standard_task_runner.py:87} INFO - Running: ['airflow', 'tasks', 'run', 'fetch_digital_bookplates', 'retrieve-process-db.add_update_model', 'manual__2024-10-11T20:43:12.492678+00:00', '--job-id', '36198', '--raw', '--subdir', 'DAGS_FOLDER/digital_bookplates/fetch_digital_bookplates.py', '--cfg-path', '/tmp/tmpsu7s_zkx', '--map-index', '70']
[2024-10-14, 16:56:49 UTC] {standard_task_runner.py:88} INFO - Job 36198: Subtask retrieve-process-db.add_update_model
[2024-10-14, 16:56:49 UTC] {task_command.py:423} INFO - Running <TaskInstance: fetch_digital_bookplates.retrieve-process-db.add_update_model manual__2024-10-11T20:43:12.492678+00:00 map_index=70 [running]> on host 74ec402cfb3d
[2024-10-14, 16:56:49 UTC] {taskinstance.py:2513} INFO - Exporting env vars: AIRFLOW_CTX_DAG_OWNER='libsys' AIRFLOW_CTX_DAG_ID='fetch_digital_bookplates' AIRFLOW_CTX_TASK_ID='retrieve-process-db.add_update_model' AIRFLOW_CTX_EXECUTION_DATE='2024-10-11T20:43:12.492678+00:00' AIRFLOW_CTX_TRY_NUMBER='1' AIRFLOW_CTX_DAG_RUN_ID='manual__2024-10-11T20:43:12.492678+00:00'
[2024-10-14, 16:56:49 UTC] {purl_fetcher.py:50} INFO - Bookplate is new
[2024-10-14, 16:56:53 UTC] {taskinstance.py:2731} ERROR - Task failed with exception
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 72, in map_httpcore_exceptions
    yield
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 236, in handle_request
    resp = self._pool.handle_request(req)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection_pool.py", line 216, in handle_request
    raise exc from None
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection_pool.py", line 196, in handle_request
    response = connection.handle_request(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/connection.py", line 101, in handle_request
    return self._connection.handle_request(request)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 143, in handle_request
    raise exc
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 113, in handle_request
    ) = self._receive_response_headers(**kwargs)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 186, in _receive_response_headers
    event = self._receive_event(timeout=timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpcore/_sync/http11.py", line 238, in _receive_event
    raise RemoteProtocolError(msg)
httpcore.RemoteProtocolError: Server disconnected without sending a response.
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/models/taskinstance.py", line 444, in _execute_task
    result = _execute_callable(context=context, **execute_callable_kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/models/taskinstance.py", line 414, in _execute_callable
    return execute_callable(context=context, **execute_callable_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/decorators/base.py", line 241, in execute
    return_value = super().execute(context)
                   ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/operators/python.py", line 200, in execute
    return_value = self.execute_callable()
                   ^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/airflow/operators/python.py", line 217, in execute_callable
    return self.python_callable(*self.op_args, **self.op_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/digital_bookplates/purl_fetcher.py", line 51, in add_update_model
    (db_id, fund_uuid) = _add_bookplate(metadata, session)
                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/digital_bookplates/purl_fetcher.py", line 184, in _add_bookplate
    fund_uuid=_fetch_folio_fund_id(metadata['fund_name']),
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/digital_bookplates/purl_fetcher.py", line 231, in _fetch_folio_fund_id
    folio_client = _folio_client()
                   ^^^^^^^^^^^^^^^
  File "/opt/airflow/libsys_airflow/plugins/digital_bookplates/purl_fetcher.py", line 27, in _folio_client
    return FolioClient(
           ^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/folioclient/FolioClient.py", line 59, in __init__
    self.login()
  File "/home/airflow/.local/lib/python3.11/site-packages/folioclient/decorators.py", line 28, in wrapper
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/folioclient/FolioClient.py", line 296, in login
    req = httpx.post(
          ^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_api.py", line 331, in post
    return request(
           ^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_api.py", line 118, in request
    return client.request(
           ^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 837, in request
    return self.send(request, auth=auth, follow_redirects=follow_redirects)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 926, in send
    response = self._send_handling_auth(
               ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 954, in _send_handling_auth
    response = self._send_handling_redirects(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 991, in _send_handling_redirects
    response = self._send_single_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_client.py", line 1027, in _send_single_request
    response = transport.handle_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 235, in handle_request
    with map_httpcore_exceptions():
  File "/usr/local/lib/python3.11/contextlib.py", line 158, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/home/airflow/.local/lib/python3.11/site-packages/httpx/_transports/default.py", line 89, in map_httpcore_exceptions
    raise mapped_exc(message) from exc
httpx.RemoteProtocolError: Server disconnected without sending a response.
[2024-10-14, 16:56:53 UTC] {taskinstance.py:1149} INFO - Marking task as UP_FOR_RETRY. dag_id=fetch_digital_bookplates, task_id=retrieve-process-db.add_update_model, map_index=70, execution_date=20241011T204312, start_date=20241014T165649, end_date=20241014T165653
[2024-10-14, 16:56:53 UTC] {standard_task_runner.py:107} ERROR - Failed to execute job 36198 for task retrieve-process-db.add_update_model (Server disconnected without sending a response.; 5267)
[2024-10-14, 16:56:53 UTC] {local_task_job_runner.py:234} INFO - Task exited with return code 1
[2024-10-14, 16:57:22 UTC] {taskinstance.py:3312} INFO - 0 downstream tasks scheduled from follow-on schedule check

It succeeded on the second attempt.

shelleydoljack · 2024-10-14T17:26:30Z

@jermnelson I re-read that comment on httpx and I am wondering if there is a problem with this line of code in FolioClient: https://github.com/FOLIO-FSE/FolioClient/blob/034431fa586e787a487ab402446631e49ec701df/folioclient/FolioClient.py#L360 basically, when the httpx_client.is_closed, it returns the exception. Should the FolioClient retry reopening the transport connection instead? (I'm thinking about this RFC quoted from the httpx issue comment):

See RFC 2616 Sec 8.1.4...

A client, server, or proxy MAY close the transport connection at any time. For example, a client might have started to send a new request at the same time that the server has decided to close the "idle" connection. From the server's point of view, the connection is being closed while it was idle, but from the client's point of view, a request is in progress.

This means that clients, servers, and proxies MUST be able to recover from asynchronous close events. Client software SHOULD reopen the transport connection and retransmit the aborted sequence of requests without user interaction so long as the request sequence is idempotent (see section 9.1.2). Non-idempotent methods or sequences MUST NOT be automatically retried, although user agents MAY offer a human operator the choice of retrying the request(s). Confirmation by user-agent software with semantic understanding of the application MAY substitute for user confirmation. The automatic retry SHOULD NOT be repeated if the second sequence of requests fails.

Or should we be doing a retry ourselves when handling the client? Or just leave Airflow to do the retries?

jermnelson · 2024-10-15T16:30:05Z

Looking at the stacktrace, the error is occurring when the FolioClient is trying to authenticate and before making any folio_get or folio_get_all method calls.

shelleydoljack · 2024-10-16T17:30:19Z

I'm going to move this ticket to Ready since we are not yet actively addressing the issue. We can always "clear task" when it fails the number of retries. We might see more issues as we test the add 979 tag DAG.

shelleydoljack added bug Something isn't working bookplates labels Oct 8, 2024

jermnelson self-assigned this Oct 9, 2024

shelleydoljack self-assigned this Oct 11, 2024

This was referenced Oct 11, 2024

Adds FOLIOCLIENT_HTTP_TIMEOUT to increase default timeout to 10s. #1272

Draft

Test 1 of "new" bookplates added since 8/28/2023 #1256

Closed

Refactor tasks that get invoice ID's and invoice line ID's #1273

Closed

shelleydoljack removed their assignment Oct 16, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Debug invoice_lines_from_invoices task #1259

Debug invoice_lines_from_invoices task #1259

shelleydoljack commented Oct 8, 2024

shelleydoljack commented Oct 8, 2024

jermnelson commented Oct 9, 2024 •

edited

Loading

jermnelson commented Oct 9, 2024

shelleydoljack commented Oct 11, 2024

shelleydoljack commented Oct 14, 2024

shelleydoljack commented Oct 14, 2024

jermnelson commented Oct 15, 2024

shelleydoljack commented Oct 16, 2024

Debug invoice_lines_from_invoices task #1259

Debug invoice_lines_from_invoices task #1259

Comments

shelleydoljack commented Oct 8, 2024

shelleydoljack commented Oct 8, 2024

jermnelson commented Oct 9, 2024 • edited Loading

jermnelson commented Oct 9, 2024

shelleydoljack commented Oct 11, 2024

shelleydoljack commented Oct 14, 2024

shelleydoljack commented Oct 14, 2024

jermnelson commented Oct 15, 2024

shelleydoljack commented Oct 16, 2024

jermnelson commented Oct 9, 2024 •

edited

Loading