You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@airflow.apache.org by GitBox <gi...@apache.org> on 2021/04/27 15:33:35 UTC
[GitHub] [airflow] bmfisher commented on issue #12728: KubePodOperator sometimes fails with `Unable to parse string [failed]`
bmfisher commented on issue #12728:
URL: https://github.com/apache/airflow/issues/12728#issuecomment-827703195
@ashb I was able to find a section of logs I kept in my notes. Its been a while since I was looking at this problem so I'm not too fresh on it and I don't recall exactly which pod this set of logs came from. But I recall thinking there was a race condition and my workaround with the `get_logs` flag set to false has continued to work for us.
```
[2021-02-09 21:53:11,356] {pod_launcher.py:176} INFO - Event: my-task-id-bd83adbc07b044b0a01058e44a3662eb had an event of type Pending
[2021-02-09 21:53:11,356] {pod_launcher.py:113} WARNING - Pod not yet started: my-task-id-bd83adbc07b044b0a01058e44a3662eb
[2021-02-09 21:53:12,367] {pod_launcher.py:176} INFO - Event: my-task-id-bd83adbc07b044b0a01058e44a3662eb had an event of type Pending
[2021-02-09 21:53:12,367] {pod_launcher.py:113} WARNING - Pod not yet started: my-task-id-bd83adbc07b044b0a01058e44a3662eb
[2021-02-09 21:53:13,376] {pod_launcher.py:176} INFO - Event: my-task-id-bd83adbc07b044b0a01058e44a3662eb had an event of type Succeeded
[2021-02-09 21:53:13,376] {pod_launcher.py:289} INFO - Event with job id my-task-id-bd83adbc07b044b0a01058e44a3662eb Succeeded
[2021-02-09 21:53:13,394] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,796", "filename": "connection_workflow.py", "lineno": 179, "levelname": "INFO", "message": "Pika version 1.1.0 connecting to ('10.103.243.78', 5672)", "offset": 1612907591796887296}
[2021-02-09 21:53:13,394] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,797", "filename": "io_services_utils.py", "lineno": 345, "levelname": "INFO", "message": "Socket connected: <socket.socket fd=6, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.244.1.146', 50972), raddr=('10.103.243.78', 5672)>", "offset": 1612907591797981696}
[2021-02-09 21:53:13,394] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,800", "filename": "connection_workflow.py", "lineno": 428, "levelname": "INFO", "message": "Streaming transport linked up: (<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7fedd02bf8e0>, _StreamingProtocolShim: <SelectConnection PROTOCOL transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7fedd02bf8e0> params=<ConnectionParameters host=net-service port=5672 virtual_host=/ ssl=False>>).", "offset": 1612907591800135424}
[2021-02-09 21:53:13,395] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,806", "filename": "connection_workflow.py", "lineno": 293, "levelname": "INFO", "message": "AMQPConnector - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7fedd02bf8e0> params=<ConnectionParameters host=net-service port=5672 virtual_host=/ ssl=False>>", "offset": 1612907591806535680}
[2021-02-09 21:53:13,395] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,806", "filename": "connection_workflow.py", "lineno": 725, "levelname": "INFO", "message": "AMQPConnectionWorkflow - reporting success: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7fedd02bf8e0> params=<ConnectionParameters host=net-service port=5672 virtual_host=/ ssl=False>>", "offset": 1612907591806787584}
[2021-02-09 21:53:13,395] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,806", "filename": "blocking_connection.py", "lineno": 452, "levelname": "INFO", "message": "Connection workflow succeeded: <SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7fedd02bf8e0> params=<ConnectionParameters host=net-service port=5672 virtual_host=/ ssl=False>>", "offset": 1612907591806982400}
[2021-02-09 21:53:13,395] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,844", "filename": "pysolr.py", "lineno": 438, "levelname": "INFO", "message": "Finished 'http://solr-service:8983/solr/mycollection/select/?q=birth%3A19550101&rows=100&cursorMark=%2A&sort=__lastUpdatedOn+asc%2C+key+asc&wt=json' (get) with body '' in 0.038 seconds, with status 200", "offset": 1612907591844953600}
[2021-02-09 21:53:13,395] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,848", "filename": "blocking_connection.py", "lineno": 1247, "levelname": "INFO", "message": "Created channel=1", "offset": 1612907591848534528}
[2021-02-09 21:53:13,396] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,875", "filename": "pysolr.py", "lineno": 438, "levelname": "INFO", "message": "Finished 'http://solr-service:8983/solr/mycollection/select/?q=birth%3A19550101&rows=100&cursorMark=AoIHCNizRCDtFiw1YWVlNjhhMzEhYmM0MDk1ZGNAcmFk&sort=__lastUpdatedOn+asc%2C+key+asc&wt=json' (get) with body '' in 0.020 seconds, with status 200", "offset": 1612907591875407616}
[2021-02-09 21:53:13,396] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,875", "filename": "channel.py", "lineno": 533, "levelname": "INFO", "message": "Closing channel (0): 'Normal shutdown' on <Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7fedd02bf8e0> params=<ConnectionParameters host=net-service port=5672 virtual_host=/ ssl=False>>>", "offset": 1612907591875733504}
[2021-02-09 21:53:13,396] {pod_launcher.py:136} INFO - {"log_id": "my_dag_id-my_task_id-2021-02-09T21:49:01.955021+00:00-2", "asctime": "2021-02-09 21:53:11,877", "filename": "channel.py", "lineno": 1119, "levelname": "INFO", "message": "Received <Channel.CloseOk> on <Channel number=1 CLOSING conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7fedd02bf8e0> params=<ConnectionParameters host=net-service port=5672 virtual_host=/ ssl=False>>>", "offset": 1612907591877563392}
[2021-02-09 21:53:13,414] {taskinstance.py:1396} ERROR - Unable to parse string [failed]
Traceback (most recent call last):
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/models/taskinstance.py", line 1086, in _run_raw_task
self._prepare_and_execute_task_with_callbacks(context, task)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/models/taskinstance.py", line 1260, in _prepare_and_execute_task_with_callbacks
result = self._execute_task(context, task_copy)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/models/taskinstance.py", line 1300, in _execute_task
result = task_copy.execute(context=context)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/providers/cncf/kubernetes/operators/kubernetes_pod.py", line 340, in execute
final_state, _, result = self.create_new_pod_for_operator(labels, launcher)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/providers/cncf/kubernetes/operators/kubernetes_pod.py", line 486, in create_new_pod_for_operator
final_state, result = launcher.monitor_pod(pod=self.pod, get_logs=self.get_logs)
File "/home/airflow/.local/lib/python3.6/site-packages/airflow/kubernetes/pod_launcher.py", line 135, in monitor_pod
last_log_time = pendulum.parse(timestamp)
File "/home/airflow/.local/lib/python3.6/site-packages/pendulum/parser.py", line 29, in parse
return _parse(text, **options)
File "/home/airflow/.local/lib/python3.6/site-packages/pendulum/parser.py", line 45, in _parse
parsed = base_parse(text, **options)
File "/home/airflow/.local/lib/python3.6/site-packages/pendulum/parsing/__init__.py", line 74, in parse
return _normalize(_parse(text, **_options), **_options)
File "/home/airflow/.local/lib/python3.6/site-packages/pendulum/parsing/__init__.py", line 128, in _parse
raise ParserError("Unable to parse string [{}]".format(text))
pendulum.parsing.exceptions.ParserError: Unable to parse string [failed]
[2021-02-09 21:53:13,416] {taskinstance.py:1440} INFO - Marking task as UP_FOR_RETRY. dag_id=my_dag_id, task_id=my_task_id, execution_date=20210209T214901, start_date=20210209T215309, end_date=20210209T215313
[2021-02-09 21:53:13,482] {local_task_job.py:118} INFO - Task exited with return code 1
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org