PV generator getstat permission denied error

[ajm-ska]

Describe the bug
On the carta-controller implementation of CARTA v3.0.0-beta.3 at ASIAA, we can not generate a PV image.
Once the progress bar completes, no PV image appears. Looking at the log files, everything seems to be normal except for one error: File::getstat error on .: Permission denied.

To Reproduce
Unfortunately, I can not find a way to reproduce the error outside of our carta-controller implementation, and only ASIAA members can access it. But I'll just mentions the steps here.

1. Load an image cube.
2. Create a line region.
3. Generate a PV image.
4. Notice that no PV image appears.
5. Look at the log and see File::getstat error on .: Permission denied.

Expected behavior
The PV image should appear.

Platform info:

• OS [e.g. macOS Monterey]: AlmaLinux 8.5
• Browser [e.g. chrome, safari, electron app]: Chrome
• Browser version [e.g. 22]: 100
• Backend branch [e.g. dev, v3b2 release]: v3.0.0-beta.3
• Frontend branch [e.g. dev, v3b2 release]: v3.0.0-beta.3

Additional context
It seems to be carta-backend related rather than carta-controller specific, but it could be the way we authenticate the users and somehow they don't have write permissions to a certain folder. If that is the case, it might come up again in archive implementations of CARTA. So I'm mainly wondering where the "getstat" "permission denied" error is coming from.
@pford Do you know if the PV generator writes temporary files somewhere, and if so, where is it?

[kswang1029]

IIRC, the generated image is in RAM. Correct me if I am wrong @pford

[veggiesaurus]

@ajm-asiaa just wondering, is it connected to a specific image cube?

[ajm-ska]

@ajm-asiaa just wondering, is it connected to a specific image cube?

It is not. I have tried several image cubes and I get the same error for each one.

[veggiesaurus]

and those same image cubes work ok on other installations? (e.g. on desktop)

[ajm-ska]

and those same image cubes work ok on other installations? (e.g. on desktop)

Yes, they do.

[pford]

@kswang1029 is correct, the PV image exists as an ImageInterface object in memory. After this new image is created, Frame::CloseCachedImage calls FileLoader::CloseImageIfUpdated on the source image, not the PV image.

In the backend, whenever access to the image is no longer needed (for example finished reading the data to compute stats), the calling routine calls CloseImageIfUpdated. This function checks the image's modify time using getstat, so that if the user leaves an image open in CARTA, re-creates it in a different way then reopens it, the image is updated in CARTA. The casacore data manager does not detect the change if the table columns are the same and the data is the same shape.

[pford]

The getstat call is in casacore::File::modifyTime()

[kswang1029]

@ajm-asiaa you showed me some other time that the backend console log shows two different time stamps with different timezones differ by 8h (guessing one is UTC and the other is Taipei time). The log from casacore seems to be different from CARTA. Could it be the root cause? @pford does casacore have a “timezone” concept when logging?

[pford]

File::getstat error on .: Permission denied. is a casacore::AipsError so we could try/catch this.

[pford]

@kswang1029 I get UTC timestamps in casacore and carta-backend logging (in my dev build)

[kswang1029]

This is a peculiar example 🤔️
[2022-07-13 13:42:42.896] [CARTA] [info] Session 747042624 [127.0.0.1] Deleted. Remaining sessions: 1
[2022-07-13 13:42:42.896] [CARTA] [info] Sessions in Session Map :
[2022-07-13 13:42:42.896] [CARTA] [info] Map id 747042624, session id 747042624, session ptr 0x288f3f0
[2022-07-13 13:42:42.896] [CARTA] [info] No remaining sessions.
[2022-07-13 13:43:05.873] [CARTA] [info] 0x288f3f0 ::Session (1113341403:1)
[2022-07-13 13:43:05.873] [CARTA] [info] Session 1113341403 [127.0.0.1] Connected. Num sessions: 1
2022-07-13 05:43:32 INFO FITS card 12: DATE-OBS= '1996/01/27 ' /UT date of Observation
2022-07-13 05:43:32 INFO Illegal date format.
2022-07-13 05:43:32 INFO FITS card 103: DATAMAX = 27947 /Maximum data value
2022-07-13 05:43:32 INFO Keyword value has wrong data type.
2022-07-13 05:43:32 INFO ... converted to type double.
2022-07-13 05:43:32 INFO FITS card 104: DATAMIN = -19 /Minimum data value
2022-07-13 05:43:32 INFO Keyword value has wrong data type.
2022-07-13 05:43:32 INFO ... converted to type double.
2022-07-13 05:43:32 INFO FITS card 12: DATE-OBS= '1996/01/27 ' /UT date of Observation
2022-07-13 05:43:32 INFO Illegal date format.
2022-07-13 05:43:32 INFO FITS card 103: DATAMAX = 27947 /Maximum data value
2022-07-13 05:43:32 INFO Keyword value has wrong data type.
2022-07-13 05:43:32 INFO ... converted to type double.
2022-07-13 05:43:32 INFO FITS card 104: DATAMIN = -19 /Minimum data value
2022-07-13 05:43:32 INFO Keyword value has wrong data type.
2022-07-13 05:43:32 INFO ... converted to type double.
2022-07-13 05:43:32 INFO FITSCoordinateUtil::fromFITSHeader Failed to decode DATE-OBS & TIMESYS keywords - no date set
2022-07-13 05:43:32 INFO FITSCoordinateUtil::fromFITSHeader passing empty or nonexistant spectral Coordinate axis
[2022-07-13 13:43:32.524] [CARTA] [warning] Session 1113341403: Image has no beam information.

[pford]

Thinking some more about the File::getstat error, FileLoader calls this using the filename it was created with, which is usually an absolute path to an image. But in this error it is simply .

The source image should have a filename and getstat would have been called successfully after other data (raster, histogram, spatial profile) was obtained prior to requesting the PV image. PV generator takes the original image filename and appends _pv to it before the extension. So I am puzzled by this .

[pford]

It turns out the filename is blank for a generated image. Perhaps casacore::File resolves a blank filename with path to the current directory?

The getstat call is bypassed for gz compressed images and LEL images; I will add generated images with no filename to this bypass.

[veggiesaurus]

nice catch @pford 👍 I think that's exactly what's happening. It's trying to check getstat the PWD.