Databricks Community

keshavmonga22 · a week ago

Setup

Singleton Python logger (logging.FileHandler) writing .log files during ADF-orchestrated notebook runs (one notebook per file). Files need to land in a UC Volume.

Context on the migration path — this workflow has been reshaped repeatedly by the move to shared compute:

Originally logged to DBFS on single-user compute — worked fine.
Migrated to shared compute → DBFS access restricted → had to move to Unity Catalog Volumes.
Direct writes to UC Volumes then broke (Attempt 1), forcing the local-staging-plus-copy pattern (Attempt 2), which is now also failing.

Attempt 1 — Direct write to /Volumes/...: FileHandler writes didn't reliably commit. flush()/close() appeared to do nothing; logging.shutdown() caused OSError: [Errno 95] Operation not supported on subsequent runs. Our assumption: UC Volumes are FUSE-mounted object storage, and the fsync/POSIX semantics FileHandler relies on aren't fully supported. Is this correct, or is there a way to make direct-write work?

Attempt 2 — Write to /local_disk0/tmp, then shutil.copy to the Volume: Worked for many runs, then began hanging for hours on the copy. Confirmed by leaving runs going, and by observing that commenting out shutil.copy eliminates the hang (but obviously doesn't commit the log).

Diagnostics

Files are ~2-3 KB, fresh cluster sessions, few log lines per run — not a volume/pressure issue.
Driver log4j showed HangingThreadDetector: Potential Hung Thread Detected, with DAG_SCHEDULER_NO_ACTIVE_JOB (Spark idle), and the hung thread's stack trace referenced com.databricks.backend.daemon.driver.ArmeriaOutgoingDirectNotebookMessageBuffer.

Why dbutils.fs.cp isn't an option

On shared compute, dbutils.fs cannot access /local_disk0 — dbutils.fs.cp("file:/local_disk0/...", "/Volumes/...") isn't permitted in this access mode. So the natural alternative to shutil.copy is unavailable to us.

Environment: DBR [DBR 17.3], shared compute, ADF-orchestrated.

Questions

Is shutil.copy from /local_disk0 to /Volumes/... a supported pattern on shared compute, or is FUSE not intended for driver-side Python I/O to Volumes at all?
Anyone else seen shutil.copy to a UC Volume hang for hours on shared compute? Root cause?
Has direct FileHandler write to a UC Volume become viable in any recent DBR, or is local-staging-plus-copy still required?
Given shared compute blocks dbutils.fs access to local disk, and direct FileHandler writes to Volumes are unreliable — what is the recommended pattern for driver-side .log file output to a UC Volume on shared compute?

data_pulse · a week ago

@keshavmonga22

I did a small isolated testing directly in a Databricks notebook on DBR 17.3 shared compute. Found the below:

Question1

Yes, Driver side python I/O to the UC volume worked normally. Successfully tested this

shutil.copyfile(
    "/local_disk0/tmp/test.log",
    "/Volumes/<catalog>/<schema>/<volume>/test.log"
)

Also shutil.copy() and a manual Python stream copy. All completed in under a second for small test files.

So this doesn't appear to be a case where FUSE is generally unusable for driver side Python I/O to UC Volumes.

Question2

I couldn't find any hang in the notebook while testing, probably couldn't able to replicate it in full. The copy path works normally when tested interactively from /local_disk0/tmp to /Volumes/.

The original hang you noticed probably depends on your actual work load conditions such as repeated notebook executions, concurrency from ADF, destination collisions, notebook lifecycle/state or an intermittent DBR/FUSE issue.

Question3 : Direct File Handler write to a UC Volume appears to be viable with limitations.

Found that this work repeatedly fine, including reuse of the same path.

logging.FileHandler(path, mode="w")

But reopening an existing Volume file in append mode fails with OSError: [Errno 29] Illegal seek

Found the same behaviour with logging.FileHandler(path, mode="a") the handler can be created, but when a record is written/flushed against an existing file, it fails with Illegal seek error.

Interestingly, mode="a" works when the destination path is brand new.

So the issue appears to be specifically append to existing file semantics, not direct FileHandler access to a UC Volume in general.

Question4:

Based on the tests, the cleanest pattern for the use case looks like:

one notebook run
    -> one unique log file
    -> FileHandler(..., mode="w")
    -> sequential writes
    -> flush/close

eg:

handler = logging.FileHandler(
    f"/Volumes/<catalog>/<schema>/<volume>/logs/{run_id}.log",
    mode="w",
    encoding="utf-8"
)

This avoids reopening an existing file for append.

If local staging is preferred, shutil.copyfile() from local disk to the Volume also works, so that remains a viable fallback.

Related but a separate issue:

I have also seen a related DBR 17+ issue with large file writes using dbutils.fs.put() in our workload. In that case, files above the gRPC message limit failed because dbutils.fs.put() sends the payload through an internal gRPC channel. Have resolved that by writing directly to /Volumes/ using standard filesystem I/O (open() via FUSE), which avoids the gRPC transfer path and supports much larger files

keshavmonga22 · a week ago

Hey @data_pulse , thanks for replying and trying these scenarios out!
I want to add that the shutil.copy() was working fine for about 2 months and then recently started hanging.

With regards to committing .log files directly to Unity Catalog, I started facing an issue over there as well, the log files were left in the buffer without being committed to the Catalog volume. This was why I moved to logging to local_disk0 and then moving to UC.
As you mentioned:
"The original hang you noticed probably depends on your actual work load conditions such as repeated notebook executions, concurrency from ADF, destination collisions, notebook lifecycle/state or an intermittent DBR/FUSE issue."

This is the primary scenario for which logging needs to be robust.

data_pulse · a week ago

@keshavmonga22

For a more durable logging mechanism, if FileHandler is currently the only logging path, I’d implement a secondary/custom logging handler that captures the log records and then persists them to Delta. That gives you a durable/queryable sink without depending on the Volume filesystem during the run.

Example would be

import logging
records = []
class DeltaBufferHandler(logging.Handler):
    def emit(self, record):
        records.append({
            "level": record.levelname,
            "message": record.getMessage()
        })

logger = logging.getLogger("app")
logger.setLevel(logging.INFO)

logger.addHandler(DeltaBufferHandler())
logger.info("processing started")

Then persist the records using spark.createDataFrame(records) directly into Volume location.

For hanging issue, useful next step is to capture the Python/thread dump while it is blocked and raise that with support but before that try with Volume write alternatives:

shutil.copyfile() instead of shutil.copy()
plain sequential open("/Volumes/..", "wb") and write the completed bytes once
%sh cp /local_disk0/tmp/test.log /Volumes/../test.log
direct FileHandler(..., mode="w") to a unique file per run, avoiding append

If all of those shows the same intermittent hang under the real ADF, then capture the thread dump and raise with support, At this stage the bug has earned professional supervision 🙂

DoTA · a week ago

Building on data_pulse's testing - I think the fix is to stop treating the Volume as a POSIX filesystem during the run, rather than to find the right copy call.

Why it hangs: FUSE-mounted object storage has no append, no fsync, no partial-write semantics, and logging.FileHandler relies on all three. The hours-long hang with ArmeriaOutgoingDirectNotebookMessageBuffer in the stack is the tell - that write is being routed through the driver's notebook RPC channel, and when the FUSE mount has a transient hiccup there is no timeout on that path, so it blocks indefinitely. data_pulse hit the same channel with dbutils.fs.put on large files.

Pattern that has held up for us under ADF orchestration + concurrency:

1. During the run, log only to /local_disk0 (or just stdout / an in-memory buffer). Never touch the Volume mid-run.

2. In a finally block at the end of the notebook, write the whole log once: open("/Volumes/.../<notebook>_<run_id>_<ts>.log", "w").write(buffer). Unique filename every run, plain open(), no append, no reopen. Avoid shutil.copy - it also runs copystat and can trip on object-storage FUSE; use shutil.copyfile if you must stage locally. A single write of a few KB is atomic enough.

3. Drop the singleton logger. Holding one FileHandler across runs is what produces OSError [Errno 95] on logging.shutdown() - the handle points at a Volume path that is no longer valid. Build the handler per run against the local path.

4. If you need logs durable even when a run crashes before the finally: send them to a Delta table instead (spark.createDataFrame(records).write.mode("append").saveAsTable(...)). Appendable, concurrency-safe, queryable, and it never touches FUSE. For ADF-orchestrated pipelines this is usually the right sink - one table, filter by run id.

Direct open() write to /Volumes at end-of-run, plus a Delta table for anything you need to query, has removed this whole class of problem for us.

gowri_databrick · a week ago

Hlo keshavmonga22,

Thanks for sharing these tests. One thing I’m taking away from this discussion is that the logging design itself may be more important than choosing between shutil.copy() and FileHandler

For an ADF-orchestrated workflow with multiple notebook runs, would it make sense to treat each run independently — create a unique log file using the run ID, keep the logging local during execution, and persist the completed log only once at the end?

For example:

ADF run → local log → notebook completes → write once to UC Volume

And if the logs need to be searched or monitored regularly, storing the important log information in a Delta table could provide a more reliable/queryable solution.

Has anyone used this pattern in production, especially when multiple notebook runs execute concurrently?

keshavmonga22 · a week ago

Hi @gowri_databrick , on this:
"For an ADF-orchestrated workflow with multiple notebook runs, would it make sense to treat each run independently — create a unique log file using the run ID, keep the logging local during execution, and persist the completed log only once at the end?"

Yes that is the design that is being used currently. Except I was using shutil.copy (at the end of the notebook run) and that is where the thread was hanging indefinitely.

balajij8 · a week ago

@keshavmonga22

You can also check by writing logs to /tmp then upload using the SDK's Files API (w.files.upload() or w.files.upload_from()) as it generally bypasses FUSE entirely - uploads happen via REST calls directly to the object storage backend to avoid the FUSE instability. If the size is 2-3KB log files, use w.files.upload(file_path="/Volumes/.../log.log", contents=open(local_path, 'rb'), overwrite=True) after closing the FileHandler. Wrap it in a try/finally block so logs upload even if the notebook fails mid-run. You can consider using Lakebase for storing logs if feasible.