Messages created via concurrent.futures.ProcessPoolExecutor are not being catched

[causeri3]

Dear Google Logging Team,

I am currently not able to see my logs created while launching parallel tasks. I am using the standard python library: concurrent.futures
This is not an issue while logging on console or file with python's standard logging library.

My environment

• Google VM Image: tf-ent-2-8-cu113
• Debian GNU/Linux 10 (buster)
• python 3.7.12
• pip 22.0.4
• google-cloud-logging 3.0.0

MRE:

import logging
import google.cloud.logging as glog
from concurrent.futures import ProcessPoolExecutor


client = glog.Client()
client.setup_logging()


def logging_something(something):
    logging.info(something)


def main():
    with ProcessPoolExecutor(max_workers=2) as executor:
        executor.map(logging_something, ['firstPoolExecutorMessage', 'secondPoolExecutorMessage'])
    logging_something('noPoolExecutorMessage')


if __name__ == '__main__':
    main()

Looking forward to your reply.

[rajjagesar]

Currently facing this exact same issue:

• Explicitly passing the logger as an argument into the method that is called by the procespool executor does not work.
• Completely re-initializing the google cloud logger in the worker method ("logging_something") does work, but logging entries are then delivered multiple times ...

---

Managed to work around it by using the ProcesspoolExecutor in "spawn" mode, the container executing the python script runs with ENV GRPC_POLL_STRATEGY=poll which is the default on MacOS.

import logging
import google.cloud.logging as glog
from concurrent.futures import ProcessPoolExecutor
from multiprocessing import get_context

client = glog.Client()
client.setup_logging()


def logging_something(something):
    logging.info(something)


def main():
   context = get_context("spawn") # Use spawn to ensure compatibility with GCP libraries

    with ProcessPoolExecutor(mp_context=context, max_workers=2) as executor: # Refer to the context with the mp_context attribute
        executor.map(logging_something, ['firstPoolExecutorMessage', 'secondPoolExecutorMessage'])
    logging_something('noPoolExecutorMessage')


if __name__ == '__main__':
    main()

1. https://stackoverflow.com/a/55885795/9735080
2. https://superfastpython.com/processpoolexecutor-multiprocessing-context/

[daniel-sanche]

From my research, the StructuredLogHandler works fine with multiprocessing, so environments that support parsing stdout logs should work fine, but anything that uses networked logging has issues. I'm seeing some errors due to SSL authentication, and others due to the BackgroundThreadTransport not flushing on child processes

Since there is a work-around setting context = get_context("spawn"), I'm going to mark down the priority for this, and come back to it at a future date. But if this is a blocker for many people, please comment here and we can increase the priority

[brokenjacobs]

Pretty sure this is breaking the stackdriver provider for airflow, I am doing some testing now.
apache/airflow#30740
apache/airflow#21837

Basically all logs after:
https://github.com/apache/airflow/blob/cb842dd8aa8749b4d0a474c6e2fda11505d9ba99/airflow/task/task_runner/standard_task_runner.py#L56

Are dropped in the child process.

[matteosdocsity]

is there anyone that could push up priority? @daniel-sanche as reported by @brokenjacobs here we have the stackdriver logging in Apache Airflow broken due to this bug. Thanks!

[daniel-sanche]

I see KubernetesExecutor is mentioned in the bug title. If you're deploying on GKE, you should be able to take advantage of the native stdout logging functionality using the StructuredLogHandler, which is unaffected by this issue.

If you're not using GKE (or a GCP serverless environment that supports stdout log collection), have you tried the context workaround mentioned earlier in this thread? Any luck there?

[brokenjacobs]

Airflow doesn't use multiprocessing, it uses psutil.Process(). So there is no way to work around this via a setting that causes a full python interpreter to be created like there is in multiprocessing.

There are multiple 'remote' logging providers for airflow. Most of them work by uploading the logs to the logging service after a task has completed. The stackdriver provider is somewhat unique in that it streams logs to stackdriver instead of waiting until completion.

The Kubernetes handlers are for 'live' logs if you are using the kubernetes execution engine in airflow, the 'remote logging' provider is still used for retrieving logs after the pod goes away. This integration is in python for airflow use, not the environment. Of course any logs sent to stdout from the pod are still readable from the stackdriver environment, but not in the airflow webUI. Also, the missing logs are still missing in stdout as well when the stackdriver handler is being used.

[brokenjacobs]

Also the KubernetesExecutor in the bug title is a bit of a red herring. The problem isn't with the Kubernetes execution engine, it's the stackdriver remote logging provider.

[matteosdocsity]

agree with @brokenjacobs, are there any other ways to let it work with Stackdriver or is there a way to have a fix @daniel-sanche?

[daniel-sanche]

I see, yeah unfortunately multi-processing is not currently supported by the library, and I don't believe support will be added in the near-term.

I can provide workarounds for getting logs into GCP Cloud Logging, but I'm less familiar with getting logs into the airflow web UI. I wasn't aware of that being a feature supported by this library. Was that always broken, or did something change recently that broke it?

[brokenjacobs]

I'm not sure how well tested or deployed the stackdriver provider for airflow is. Google cloud composer doesn't use this provider, it has another way of getting logs into stackdriver. The provider appears to work at first glance because you see logs from numerous components. It's only upon trying to use it with task logs that you notice things are missing. As I mentioned above this provider is a bit unique in that it replaces a full logging handler and does not just upload logs upon completion. I suppose it could be re-written to do that, but it's not how the provider was put together originally.