When Upload through IHS fails: a 30 second NFS mystery

Please note: All my blog articles are always written by me, and sometimes redacted by AI. As solving this problem was a close cooperation between me and AI, I let AI write this article where I did the redaction. This does show in the wording. AI was also more elaborate than I would have been. I hope you still find the article valuable.

Two environments. Same Connections version, same CR level, byte-identical application JARs, byte-identical mod_ibm_upload.so. On one of them, Upload through IBM HTTP Server (IHS) works perfectly. On the other, every upload above the configured threshold returns HTTP 500.
It took two days to find out why, and the answer had nothing to do with Connections, WebSphere or IHS. It was in the NFS mount options, and not the ones you would expect.

The symptom

Upload through IHS offloads large file uploads from WebSphere to the web server. Instead of streaming 500 MB through a servlet thread, IHS accepts the payload, writes it to shared storage, and then tells WebSphere to commit the metadata. This is far more efficient and saves cpu cycles on your WebSphere Connections nodes, which are especially valuable if you still have a PVU license, which restricts the resources you are allowed to use for your WebSphere nodes running the Connections applications. Christoph Stoettner describes the configuration in Configure IBM HTTP Server 9 for HCL Connections, which is the guide I used for both environments.
With that configured, I uploaded a 15MB file, which was larger than the 10MB (or 10240 kB) that was configured in the files-config.xml as simpleUploadAPI maximumSizeInKb. This gave me this:

POST /files/form/api/myuserlibrary/feed?format=html&opId=upload,test15mb.bin,...
Status: 500 Internal Server Error

And in SystemOut.log:

com.ibm.lconn.share.services.exception.FileUploadFailedException:
  Error occurs when file is uploaded.
    at ...BaseDocumentHandler.submitItemFromPhase2Request(BaseDocumentHandler.java:781)
    at ...BaseDocumentHandler.submitItem(BaseDocumentHandler.java:241)
    at ...LibraryFeedHandler.doPost(LibraryFeedHandler.java:785)

No Caused by:. No FFDC incident. Just a generic exception with no explanation whatsoever.
Meanwhile the file itself was sitting on the share, complete and correct:

-rw-r--r--. 1 wasusr wasgrp 15728640 /data/connections/shared/files/upload/files/60/34/<token>
-rw-r--r--. 1 wasusr wasgrp        0 /data/connections/shared/files/upload/files/60/34/<token>.tkn

Exactly 15728640 bytes. Exactly what was uploaded. So the upload through IHS worked correctly, but uploading through IHS is a 2-phase process.

Understanding the two phases

Upload through IHS is a two-phase protocol, driven by three request headers:

X-IBM-UPLOAD-METHOD: phases
X-IBM-UPLOAD-TOKEN:  <uuid>
X-IBM-UPLOAD-SIZE:   15728640

Phase 1 — the browser POSTs the payload. mod_ibm_upload intercepts it, writes the bytes to IBMUploadBaseStore, and registers the token. WebSphere sees only a small multipart envelope, not the payload. In the trace:

upload phase is InitiatingPhase1
new upload token is <uuid>
TransactionalFile ... size=15728640
allowLibraryDataIncrease ... 15.728.640  -> OK
commit

Phase 2 — IHS issues an internal subrequest ($WSPR: INCLUDED) telling Files the upload is complete. Files then reads the file from disk, verifies it, and writes the metadata to the database.

X-IBM-UPLOAD-STATUS: complete
upload phase is LegacyPhase2
phase 2
DefaultTransaction begin()
FileUploadFailedException ... cause = null

Phase 1 worked. Phase 2 did not. I ruled out many other factors, before I found the cause. I’ll give them, as one of them might be the actual cause in your environment if you’re reading this article.

• Rewrite rules not firing. To check this, set a trace on rewrite: rewrite:trace3 in your LogLevel line in the httpd.conf and look for /files/form/api/myuserlibrary/feed → /ihs/files/form/api/myuserlibrary/feed. If you search for “/ihs/” and find nothing, the rewrite is not working properly.
• mod_rewrite context. This was the problem on my own test environment, rewrite rules do not inherit from the main server into a VirtualHost, so the upload rewrite never executed. Fixing that made my test environment work. It was not the problem on the failing one.
• modIBMUpload not enabled. It needs to set to true in the files-config.xml.
• Wrong module version. I upgraded IHS from 9.0.5.25 to 9.0.5.27 so both environments had the identical mod_ibm_upload.so (MD5 6ff098bce1afdf2dc050cd1c4084d6b1). For IHS 9, you shouldn’t copy the mod_ibm_upload module from the Connections xkit directory, as the documentation suggests, but use the one in the modules/extra folder of IHS instead.
• Antivirus. Maybe an antivirus service is blocking your upload. In our case, the same .bin uploaded fine through the WebSphere path.
• File size. Anything between the cut-off size of the simpleUploadAPI and the maximum allowed size of media (<media maximumSizeInKb), should give the same result. If not, something else might be wrong. Reproduced at a 10 MB threshold with a 15 MB file, and at a 50 MB threshold with a 55 MB file.
• nginx. Do you have headers on your nginx which might interfere with what you configured in IHS? I stripped the reverse proxy config down to a bare proxy_pass with no CORS handling and a single fixed upstream to avoid exactly that. For us, that made no change.
• Cluster affinity. To exclude cluster affinity as a cause, we only had one IHS node and one WAS node active throughout all tests.

We tested all hypotheses above. but they were all dead ends. LogLevel warn ibm_upload:trace8 produces no output at all, by the way. The module simply does not log, which removes the most obvious diagnostic route.

The breakthrough

Christoph pointed me at the decompiled code around line 781. That changed everything:

File file1 = (Platform.getInstance()).FILE_MANAGER.getFileById(uUID, false);
long l1 = file1.length();
TransactionalFile transactionalFile1 =
    (Platform.getInstance()).FILE_MANAGER.getFileFactory().fromFile(uUID, file1, null, null);

paramHttpServletResponse.setHeader("Content-Range",
    String.format("bytes %d-%d/%d", new Object[] { 0, l1 - 1L, l1 }));

long l2 = servletMessage.getLong("X-IBM-UPLOAD-SIZE", -1);
long l3 = transactionalFile1.getStorageSize();
if (l2 != l3)
    throw new FileUploadFailedException(getLocale(paramHttpServletRequest));   // line 781

Phase 2 compares the size from the request header against the size on disk. Now look back at the response headers my browser received:

Content-Range: bytes 0--1/0

Substitute into that String.format: l1 - 1 = -1 and l1 = 0. file1.length() returned 0.
And java.io.File.length() returns 0 when the file does not exist. No exception, no error, just zero. So l2 was 15728640, l3 was 0, the comparison failed, and the code threw an exception with no cause because from its perspective nothing had gone wrong. It had simply found a size mismatch. WebSphere could not see the file that IHS had written.

The cause

I had verified the file existed, but I checked it on the IHS node. The size check happens on the WebSphere node, though. Different host, different NFS client, different cache. So I measured it: write a 15 MB file from the IHS node, and poll from the WAS node until it becomes visible with the correct size.

 t= 30.036s  file first appeared, size=15728640
  t= 30.036s  CORRECT SIZE VISIBLE: 15728640

Thirty seconds. And note the shape of it. The file did not appear with a wrong size and then correct itself. It was completely invisible for 30 seconds, then appeared instantly with the right size. That is not the attribute cache. That is the negative dentry cache: the client had cached the fact that this path did not exist, and kept serving that cached miss. Why 30 seconds? Because these are the Linux NFS client defaults:

30.036 seconds is acdirmin almost to the millisecond.
And the gap between phase 1 and phase 2? From my SystemOut timestamps:

Phase 2 asks “how big is this file?” about 1.4 seconds after phase 1 wrote it. The answer it gets is “what file?”
My test environment worked because IHS and WebSphere run on the same host. One NFS client, one cache. The writer and the reader share it, so there is nothing to invalidate. The failing environment had them on separate nodes, which is exactly the topology the Upload through IHS documentation describes.

How to check it yourself

Write a file from the IHS node and watch it from the WebSphere node, but stat the path before the write, so you populate the negative lookup cache the same way WebSphere does:

# WAS node, first
stat /srv/cp-shared/files/upload/files/nfstest/probe.bin   # populates neg. cache
while true; do stat -c %s .../probe.bin 2>/dev/null; sleep 0.1; done

# IHS node, second
dd if=/dev/urandom of=.../probe.bin bs=1M count=15 conv=fsync

If the correct size takes more than ~1.3 seconds to appear, you’ve reproduced the failure condition.

The fix that did not work

My first instinct was actimeo=1, shrinking all cache timers to one second. It worked for my 15 MB test file. Then this happened:
11 MB → fails
45 MB → succeeds
Which makes perfect sense once you see it. A larger file takes longer in phase 1, so by the time phase 2 runs, the one second window has expired. A smaller file checks sooner and loses the race. Any time-based setting produces this. You end up with a configuration that works in testing and fails unpredictably in production, with the failure depending on file size, load and network latency. That is considerably worse than a consistent failure. A solution could be to set this parameter to 0, but that comes with a huge performance hit.

The fix that did work

The failure is a cached negative lookup. There is a mount option for exactly that:

lookupcache=positive

Positive lookups stay cached. Negative lookups are always revalidated against the server. Since the problem is “client remembers this file doesn’t exist”, this removes the window entirely, regardless of file size or timing. On the WebSphere nodes in /etc/fstab:

pnfs-server:/export/connections/shared  /data/connections/shared  nfs  vers=4.2,sec=sys,proto=tcp,rsize=1048576,wsize=1048576,lookupcache=positive  0 0

All ac* values stay at their defaults, so normal attribute caching is untouched. Only the caching of misses is given up. Note that this requires a real unmount and mount. mount -o remount will not apply it.

Red Hat’s guidance notes that disabling lookup caching “should result in less of a performance penalty than using noac, and has no effect on how the NFS client caches the attributes of files”. positive is cheaper still than none, because only negative entries are affected.

I benchmarked it, because “probably fine” is not an answer when you want to change production mount options in an environment with 45K users. The benchmarks showed that a penalty stayed under the noise level (different results over multiple sessions with the same NFS settings), so small enough to not undo the expected benefit from outsourcing file up- and downloads to IHS.

Verifying your own environment

If you run Upload through IHS with IHS and WebSphere on separate nodes, you may have this problem without knowing it. Particularly if your threshold is high enough that few uploads hit the IHS path.
From the WebSphere node, before the write, prime the negative cache and then poll:

stat /data/connections/shared/files/upload/files/probe.bin    # populates the negative entry
while true; do
    stat -c %s /srv/cp-shared/files/upload/files/probe.bin 2>/dev/null || echo ABSENT
    sleep 0.1
done

Then, write a file from the IHS node:

dd if=/dev/urandom of=/data/connections/shared/files/upload/files/probe.bin bs=1M count=15

The priming step matters. A first-time lookup always goes to the server and returns fresh data, so without it the test is not representative of what WebSphere does. It touches this part of the tree during phase 1 when it creates the metadata bucket directory. If the file takes more than a second to appear, your phase 2 is going to lose that race.

Configuration reference

For completeness, the Connections-side settings involved.
files-config.xml:

<api>
  <simpleUploadAPI maximumSizeInKb="10240">
    <organization estimatedBytesInSeconds="2097152" id="admin_replace"
                  maxConcurrenceRequests="50" maximumSizeInKb="10240"/>
  </simpleUploadAPI>
  <simpleDownloadAPI maximumSizeInKb="10240"/>
</api>

<download>
  <modIBMLocalRedirect enabled="true" hrefPathPrefix="files_content"/>
</download>

<upload>
  <modIBMUpload enabled="true"/>
</upload>

maximumSizeInKb is the threshold, not a limit. Files below it are handled by WebSphere; files above it go through IHS. Which is why a low threshold made this bug reproducible on every test upload, and a high one would have made it an occasional mystery.
httpd.conf, upload handler:

<IfModule ibm_upload_module>
    <Location /ihs/files>
        IBMUploadHandler On
        SetHandler ibm_upload_handler
        IBMUploadBaseStore /srv/cp-shared/files/upload/files
        IBMUploadMethods POST,PUT
        IBMUploadURLPrefix /ihs
    </Location>
</IfModule>

And the rewrite rules that route uploads to it. Inside the VirtualHost, because mod_rewrite configuration is not inherited from the main server:

RewriteCond %{ENV:ENV-SKIP-IBM-UPLOAD-HANDLER} !=true          [NC]
RewriteCond %{HTTP:X-IBM-UPLOAD-METHOD}        ^phases$        [NC]
RewriteCond %{HTTP:X-IBM-UPLOAD-TOKEN}         ^[0-9A-Za-z-]+$ [NC]
RewriteCond %{REQUEST_METHOD} !^(GET|OPTIONS|HEAD|DELETE)$     [NC]
RewriteRule ^(/files/(basic|form|oauth)/api/...)$ /ihs$1 [PT,L]

The full set of rules, plus the download configuration, is in Christoph’s article and IBMUploadBaseStore must be ${FILES_CONTENT_DIR} plus /files, matching whatever you set in the WebSphere variable of that name.

Closing thought

The root cause here is specific to this environment, the default NFS mount options on a
multi-node deployment, not related to HCL Connections. But I spent a lot of time to find the cause, and the reason it took that long is worth noting.
BaseDocumentHandler compares a header value against File.length() on shared storage. No retry, no tolerance, and an exception carrying neither the expected value nor the observed one. On the multi-node topology the feature is documented for, File.length() returning 0 is a foreseeable outcome. A single getattr retry would have made this work. Failing that, an exception message reading expected 15728640, found 0 would have made it a ten minute diagnosis instead of a two day one. The first thing you see when something breaks determines how long it takes to fix. That is worth designing for.