Filmic failure with old XMP

darktable-org / darktable

darktable is an open source photography workflow application and raw developer

https://www.darktable.org

GNU General Public License v3.0

9.8k stars 1.14k forks source link

Filmic failure with old XMP #17420

Closed kofa73 closed 2 months ago

kofa73 commented 2 months ago

Describe the bug

Old XMP files from 2020 cannot be processed, the image is corrupted. Error messages are shown on the GUI and at the console.

Steps to reproduce

Get the files from https://tech.kovacs-telekes.org/files/2024-09-02-old-xmp-fails/
Load the NEF into darktable.
Observe the errors that pop up:
Compare the darkroom view with the previous export (https://tech.kovacs-telekes.org/files/2024-09-02-old-xmp-fails/2020-04-05_13-17-59_DSC_0006.jpg)

Expected behavior

Open the file without error

Logfile | Screenshot | Screencast

Errors like this appear at the console:

     4.3505 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
     4.3505 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"

error.log

Commit

No response

Where did you obtain darktable from?

self compiled

darktable version

4.9.0+335~g5907696d44

What OS are you using?

Linux

What is the version of your OS?

Ubuntu 24.04

Describe your system?

No response

Are you using OpenCL GPU in darktable?

None

If yes, what is the GPU card and driver?

No response

Please provide additional context if applicable. You can attach files too, but might need to rename to .txt or .zip

No response

MStraeten commented 2 months ago

no issue while opening it with 4.9.0+410~g9a728c8872 on macos

did you just recompiled darktable after pulling latest master or did you a complete new build after cleaning the build directory?

kofa73 commented 2 months ago

I always build from a clean state:

#!/bin/bash
renice -n 19 -p $$
ionice -c 3 -p $$

rm -rf ~/.cache/darktable/*kernel*

cd ~/darktable ; 
git checkout master
git clean -d -f -x ;

git pull --rebase

git submodule update --init --recursive

rm -rf /home/kofa/darktable-master

./build.sh --prefix /home/kofa/darktable-master --build-type Release --install

I've just rebuilt and checked:

   11.4898 [commit color calibration]  temp=4176  xy=0.3747 0.3792 - XYZ=0.9882 1.0000 0.6491 - LMS=1.0133 0.9869 0.6655  DT_ILLUMINANT_D
    11.4899 NO raster mask support                         atrous                 
    11.5006 synch all module history      [full]                                  
    11.5007 committed                     [full]           rawprepare             enabled  order= 1, piece hash=ab4bcc0bd1b95d59
    11.5010 committed                     [full]           colorout               enabled  order=82, piece hash=8aee4949d7bcf4e1
    11.5010 committed                     [full]           gamma                  enabled  order=90, piece hash=45837a3fc91a35ca
    11.5010 committed                     [full]           temperature            enabled  order= 3, piece hash=bd6fa7149d22cb51
    11.5010 committed                     [full]           highlights             enabled  order= 4, piece hash=66b40764d6cec19f
    11.5010 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
    11.5010 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
    11.5011 committed                     [full]           filmicrgb              enabled  order=58, piece hash=bf129dc13993d2e
    11.5011 committed                     [full]           exposure               enabled  order=24, piece hash=1a921f10bdbac7b3
    11.5011 committed                     [full]           flip                   disabled order=17, piece hash=0
    11.5011 committed                     [full]           colorin                enabled  order=32, piece hash=624b55a651b498a3
    11.5020 committed                     [full]           lens                   enabled  order=13, piece hash=b819f112061998ef
    11.5020 committed                     [full]           hotpixels              enabled  order= 6, piece hash=6ada78ba38dde154
    11.5020 committed                     [full]           demosaic               enabled  order= 8, piece hash=375e077d6190a769
    11.5020 committed                     [full]           exposure               enabled  order=24, piece hash=1a921f10bdbac7b3
    11.5020 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
    11.5020 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
    11.5020 committed                     [full]           filmicrgb              enabled  order=58, piece hash=bf129dc13993d2e
    11.5020 committed                     [full]           temperature            enabled  order= 3, piece hash=bd6fa7149d22cb51
    11.5020 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
    11.5020 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
    11.5020 committed                     [full]           filmicrgb              enabled  order=58, piece hash=bf129dc13993d2e
    11.5020 committed                     [full]           clipping               enabled  order=20, piece hash=8944c48d72742690
    11.5020 committed                     [full]           clipping               enabled  order=20, piece hash=8944c48d72742690
    11.5021 committed                     [full]           defringe               enabled  order=41, piece hash=85f04d6fc0c89e96
    11.5021 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
    11.5021 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
    11.5021 committed                     [full]           filmicrgb              enabled  order=58, piece hash=bf129dc13993d2e
    11.5021 committed                     [full]           defringe               enabled  order=41, piece hash=85f04d6fc0c89e96
    11.5021 committed                     [full]           defringe               enabled  order=41, piece hash=85f04d6fc0c89e96
    11.5021 committed                     [full]           defringe               enabled  order=41, piece hash=85f04d6fc0c89e96
    11.5021 raster mask advertised                         atrous                 
    11.5021 committed                     [full]           atrous                 enabled  order=42, piece hash=30d552a892bc2cf1
    11.5021 synch all modules done        [full]                                  defaults 0.0149s, history 0.0015s
    11.5021 modify roi OUT                [full]           rawprepare             (   0/   0) 4992x3280 scale=1.0000 --> (   0/   0) 4946x3278 scale=1.0000 ID=4462
    11.5021 modify roi OUT                [full]           clipping               (   0/   0) 4946x3278 scale=1.0000 --> (1111/ 838) 2319x2319 scale=1.0000 ID=4462
    11.5022 pipe cache check              [full]                                  64 lines (important=0, used=0). Freed 0MB. Using using 0MB, limit=1003MB

4.9.0+408~g90fa2b0c7b

My lighttable is a psychedelic show:

Images I processed last week are OK.

ptilopteri commented 2 months ago

Kofa @.***> [09-02-24 16:26]:

I always build from a clean state:

#!/bin/bash
renice -n 19 -p $$
ionice -c 3 -p $$

rm -rf ~/.cache/darktable/*kernel*

cd ~/darktable ; 
git checkout master
git clean -d -f -x ;

git pull --rebase

git submodule update --init --recursive

rm -rf /home/kofa/darktable-master

./build.sh --prefix /home/kofa/darktable-master --build-type Release --install

I've just rebuilt and checked:


   11.4898 [commit color calibration]  temp=4176  xy=0.3747 0.3792 - XYZ=0.9882 1.0000 0.6491 - LMS=1.0133 0.9869 0.6655  DT_ILLUMINANT_D
    11.4899 NO raster mask support                         atrous                 
    11.5006 synch all module history      [full]                                  
    11.5007 committed                     [full]           rawprepare             enabled  order= 1, piece hash=ab4bcc0bd1b95d59
    11.5010 committed                     [full]           colorout               enabled  order=82, piece hash=8aee4949d7bcf4e1
    11.5010 committed                     [full]           gamma                  enabled  order=90, piece hash=45837a3fc91a35ca
    11.5010 committed                     [full]           temperature            enabled  order= 3, piece hash=bd6fa7149d22cb51
...


4.9.0+408~g90fa2b0c7b

My lighttable is a psychedelic show:
![image](https://github.com/user-attachments/assets/20202f28-eae3-42e7-bcee-dbfcb700f301)

Images I processed last week are OK.

fwiw, I just set --library :memory: and imported two sets from early 2020 employing filmicrgb and have no such problem.

self built on opensuse tumbleweed, darktable-4.9.0~git403.e2de65c4-11904.1.x86_64 with ~/.cache/darktable cleared

-- (paka)Patrick Shanahan Plainfield, Indiana, USA @ptilopteri facebook/ptilopteri Photos: http://wahoo.no-ip.org/piwigo paka @ IRCnet oftc

kofa73 commented 2 months ago

Reproduced on Windows, 4.8.0

Log:

    13.4027 dt_dev_pixelpipe_synch        [preview]        hotpixels              enabled, order=6, piece hash=7a797e70669caec, 
    13.4028 dt_dev_pixelpipe_synch        [preview]        demosaic               enabled, order=8, piece hash=b33e6ad52ac47577, 
    13.4028 dt_dev_pixelpipe_synch        [preview]        exposure               enabled, order=24, piece hash=e1360407c825dc64, 
    13.4028 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
    13.4028 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
    13.4029 dt_dev_pixelpipe_synch        [preview]        filmicrgb              enabled, order=58, piece hash=95fd965551ec2e85, 
    13.4029 dt_dev_pixelpipe_synch        [preview]        temperature            enabled, order=3, piece hash=5b8ad0145cce2248, 
    13.4029 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
    13.4029 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
    13.4030 dt_dev_pixelpipe_synch        [preview]        filmicrgb              enabled, order=58, piece hash=95fd965551ec2e85, 
    13.4030 dt_dev_pixelpipe_synch        [preview]        clipping               enabled, order=20, piece hash=ee0e9fb12791109c, 
    13.4030 dt_dev_pixelpipe_synch        [preview]        clipping               enabled, order=20, piece hash=ee0e9fb12791109c, 
    13.4030 dt_dev_pixelpipe_synch        [preview]        defringe               enabled, order=41, piece hash=6b998ad970f5900b, 
    13.4031 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
    13.4031 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
    13.4031 dt_dev_pixelpipe_synch        [preview]        filmicrgb              enabled, order=58, piece hash=95fd965551ec2e85, 
    13.4031 dt_dev_pixelpipe_synch        [preview]        defringe               enabled, order=41, piece hash=6b998ad970f5900b, 
    13.4032 dt_dev_pixelpipe_synch        [preview]        defringe               enabled, order=41, piece hash=6b998ad970f5900b, 
    13.4032 dt_dev_pixelpipe_synch        [preview]        defringe               enabled, order=41, piece hash=6b998ad970f5900b,

kofa73 commented 2 months ago

What's strange is, I've now re-opened (on the Linux box) an image I edited a few days ago (I took it on 28 August). It's a TIFF (output from an 'average' merge of 3 images from GraphicsMagick), and does have filmic in the stack. It fails the same way:

    22.0766 [dt_dev_process_image_job] loading image. took 0.000 secs (0.000 CPU)
    22.0791 pipe state changing           [preview]                               synch all, 
    22.0791 synch all module defaults     [preview]                               
    22.0844 [commit color calibration]  temp=5003  xy=0.3457 0.3586 - XYZ=0.9639 1.0000 0.8247 - LMS=0.9945 1.0010 0.8330  DT_ILLUMINANT_D
    22.0954 synch all module history      [preview]                               
    22.0969 committed                     [preview]        colorin                enabled  order= 9, piece hash=f409c29525153be1
    22.0971 committed                     [preview]        colorout               enabled  order=82, piece hash=8aee4949d7bcf4e1
    22.0971 committed                     [preview]        gamma                  enabled  order=90, piece hash=45837a3fc91a35ca
    22.0971 committed                     [preview]        flip                   disabled order=18, piece hash=0
    22.0971 [iop_validate_params] `filmicrgb' failed for type "float", field: output_power
    22.0971 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
    22.0971 committed                     [preview]        filmicrgb              enabled  order=58, piece hash=4bbb886cf68b7964
    22.0971 committed                     [preview]        exposure               enabled  order=25, piece hash=5d3c37b13c64333d

I'm able to reproduce this with a clean config + cache directory, as well.

Theory one: only old stacks are affected has therefore been disproved. Theory two: it's a recent change that causes this (since it worked a few days ago). But then why do I get the same kind of error on Windows, with the official 4.8.0 build?

For what it's worth, here is the stack of the TIFF file: average.tif.xmp.txt

TurboGit commented 2 months ago

I cannot reproduce, all ok on my side with your RAW + xmp.

TurboGit commented 2 months ago

ptilopteri commented 2 months ago

fwiw: I also have no problem loadinng 2020-04-05_13-17-59_DSC_0006.NEF and 2020-04-05_13-17-59_DSC_0006.NEF.xmp with self built darktable 4.9.0+408~g90fa2b0c7b on opensuse tumbleweed 20240901

ptilopteri commented 2 months ago

paka @.***> [09-03-24 09:51]:

fwiw: I also have no problem loadinng 2020-04-05_13-17-59_DSC_0006.NEF and 2020-04-05_13-17-59_DSC_0006.NEF.xmp with self built darktable 4.9.0+408~g90fa2b0c7b on opensuse tumbleweed 20240901

ps: like the photo.

-- (paka)Patrick Shanahan Plainfield, Indiana, USA @ptilopteri facebook/ptilopteri Photos: http://wahoo.no-ip.org/piwigo paka @ IRCnet oftc

kofa73 commented 2 months ago

I've tried again on Windows, using 4.8.0, after deleting cache and config, and re-downloading the XMP again. The same (bad) result. NB: this machine is an i5 laptop, the Linux box is a Ryzen 5 desktop. I then repeated this (again deleting config and cache) using the nightly, 4.9.0+408~g90fa2b0c7b. The problem remains:

If I compress the history, the problem remains. If I then reset filmic, the problem is gone. The changes, according to the history panel:

Observe the original target white luminance value, and original contrast = nan.

Besides me being cursed, any other ideas?

ptilopteri commented 2 months ago

Kofa @.***> [09-03-24 13:59]:

I've tried again on Windows, using 4.8.0, after deleting cache and config, and re-downloading the XMP again. The same (bad) result. NB: this machine is an i5 laptop, the Linux box is a Ryzen 5 desktop. I then repeated this (again deleting config and cache) using the nightly, 4.9.0+408~g90fa2b0c7b. The problem remains.

Besides me being cursed, any other ideas?

wipe build completely and git clone rebuild

-- (paka)Patrick Shanahan Plainfield, Indiana, USA @ptilopteri facebook/ptilopteri Photos: http://wahoo.no-ip.org/piwigo paka @ IRCnet oftc

kofa73 commented 2 months ago

I don't build on Windows. I used the 'official' 4.8.0 release on Windows, and now the nightly from GitHub.

On Linux, I always build clean (git clean -d -f -x), and never had any issue. Even if that were wrong, it would not explain the Windows issue.

kofa73 commented 2 months ago

I tried on my son's Windows PC, which has never had darktable installed, using the nightly. The issue is the same. So, the whole household is cursed, not just me -- that's a relief.

Edit: using the 4.8.1 release, works on my daughter's M3 Macbook Air. Retried the same 4.8.1 on Windows (deleted config and cache, re-downloaded the XMP), failed the same as before. Tried the 4.8.1 AppImage, again wiping config and cache, the same problem.

kofa73 commented 2 months ago

Filmic looks like this (note: contrast is NaN, according to the history steps):

Dragging contrast fixes the NaN:

The display max. luminance is 18.45%, which should be the value of mid-grey. It looks the wrong field was read into it while deserialising, which I think is related to [iop_validate_params] in the error messages:

Restoring the max. brightness to 100% results in the expected output:

ptilopteri commented 2 months ago

Kofa @.***> [09-03-24 15:17]:

Filmic looks like this (note: contrast is NaN, according to the history steps):

and I see: http://wahoo.no-ip.org/~paka/Screenshot_20240903_153141.png

Dragging contrast fixes the NaN:

which is closer to my filmic rgb

The display max. luminance is 18.45%, which should be the value of mid-grey. It looks the wrong field was read into it while deserialising, which I think is related to [iop_validate_params] in the error messages:

and closer yet to mine

Restoring the max. brightness to 100% results in the expected output:

except for luminence

but your module "filmic rgb" is quite dissimilar to mine

I am guessing that your have current setting which change your image after loading. The image that you provided appears quite normal on my display w/o making any change to your xmp.

or maybe it is my local setting that make it look as I believe intended. ???

-- (paka)Patrick Shanahan Plainfield, Indiana, USA @ptilopteri facebook/ptilopteri Photos: http://wahoo.no-ip.org/piwigo paka @ IRCnet oftc

kofa73 commented 2 months ago

I am guessing that your have current setting which change your image after loading. The image that you provided appears quite normal on my display w/o making any change to your xmp. or maybe it is my local setting that make it look as I believe intended. ???

I think you did not read what I have written:

I stated several times that I removed the config and cache directories, both on the Windows laptop and on the Linux desktop (https://github.com/darktable-org/darktable/issues/17420#issuecomment-2326239062, https://github.com/darktable-org/darktable/issues/17420#issuecomment-2327111162, https://github.com/darktable-org/darktable/issues/17420#issuecomment-2327178381)
and that my son's PC, which had never had darktable installed previously, also reproduced the issue (https://github.com/darktable-org/darktable/issues/17420#issuecomment-2327178381).

ptilopteri commented 2 months ago

Kofa @.***> [09-03-24 16:16]:
I am guessing that your have current setting which change your image after loading. The image that you provided appears quite normal on my display w/o making any change to your xmp. or maybe it is my local setting that make it look as I believe intended. ???

I think you did not read what I have written:
- I stated several times that I removed the config and cache directories, both on the Windows laptop and on the Linux desktop (https://github.com/darktable-org/darktable/issues/17420#issuecomment-2326239062, https://github.com/darktable-org/darktable/issues/17420#issuecomment-2327111162, https://github.com/darktable-org/darktable/issues/17420#issuecomment-2327178381)
- and that my son's PC, which had never had darktable installed previously, also reproduced the issue.

well, I loaded your image as: darktable --library :memory: 2020-04-05_13-17-59_DSC_0006.NEF with my local .config/darktable empty and .cache/darktable/ empty

and your image loads fine. ???

-- (paka)Patrick Shanahan Plainfield, Indiana, USA @ptilopteri facebook/ptilopteri Photos: http://wahoo.no-ip.org/piwigo paka @ IRCnet oftc

kofa73 commented 2 months ago

What's peculiar about the sidecar is that:

on my HDD, its date is "May 9", so this year, 2024
The XMP has darktable:xmp_version="5". If I understand correctly, that version came in: 68febf1ea6e (Philippe Weyland 2022-03-15 12:48:30 +0100 79) #define DT_XMP_EXIF_VERSION 5.

But the exported JPG has a modification timestamp of "Jul 4 2020" and version Exif.Image.Software = darktable 3.1.0+2414~g50eaaaa70; that can't have been the version that created the darktable:xmp_version="5" entry, if the version above (taken from git blame) is correct.

Maybe I imported it, so the XMP got upgraded, but I did not re-edit it?

If I load the exported JPG (with the version darktable 3.1.0+2414~g50eaaaa70) as a sidecar, I get the same error using the current master.

kofa73 commented 2 months ago

A last update for today: with 4.9.0+415~g3ab7ed6601, I get the following if I load the JPG as sidecar:

    26.9132 [history] successfully loaded module rawprepare from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 1:    version WRONG   params WRONG
    26.9132 [history] successfully loaded module colorout from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 5:    version ok      params ok
    26.9133 [history] successfully loaded module gamma from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 1:    version ok      params ok
    26.9133 [history] successfully loaded module temperature from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 3:    version WRONG   params WRONG
    26.9133 [history] successfully loaded module highlights from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 2:    version WRONG   params WRONG
    26.9133 [history] successfully loaded module filmicrgb from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 3:    version WRONG   params WRONG
    26.9133 [history] successfully loaded module exposure from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 6:    version ok      params ok
    26.9133 [history] successfully loaded module flip from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 2:    version ok      params ok
    26.9133 [history] successfully loaded module colorin from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 6:    version WRONG   params ok
    26.9133 [history] successfully loaded module lens from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 5:    version WRONG   params WRONG
    26.9133 [history] successfully loaded module hotpixels from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 1:    version ok      params ok
    26.9133 [history] successfully loaded module demosaic from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 3:    version WRONG   params WRONG
    26.9133 [history] successfully loaded module exposure from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 6:    version ok      params ok
    26.9134 [history] successfully loaded module filmicrgb from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 3:    version WRONG   params WRONG
    26.9134 [history] successfully loaded module temperature from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 3:    version WRONG   params WRONG
    26.9134 [history] successfully loaded module filmicrgb from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 3:    version WRONG   params WRONG
    26.9134 [history] successfully loaded module clipping from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 5:    version ok      params ok
    26.9134 [history] successfully loaded module clipping from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 5:    version ok      params ok
    26.9134 [history] successfully loaded module defringe from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 1:    version ok      params ok
    26.9134 [history] successfully loaded module filmicrgb from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 3:    version WRONG   params WRONG
    26.9134 [history] successfully loaded module defringe from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 1:    version ok      params ok
    26.9134 [history] successfully loaded module defringe from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 1:    version ok      params ok
    26.9134 [history] successfully loaded module defringe from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 1:    version ok      params ok
    26.9134 [history] successfully loaded module atrous from history
                        blendop v. 9:   version WRONG   params WRONG
                        params v. 1:    version WRONG   params WRONG
    26.9170 synch all module defaults     [thumbnail]                             
    26.9209 [commit color calibration]  temp=4176  xy=0.3747 0.3792 - XYZ=0.9882 1.0000 0.6491 - LMS=1.0133 0.9869 0.6655  DT_ILLUMINANT_D
    26.9416 synch all module history      [thumbnail]                             
    26.9416 committed                     [thumbnail]      rawprepare             enabled  order= 1, piece hash=ab4bcc0bd1b95d59
    26.9450 committed                     [thumbnail]      colorout               enabled  order=82, piece hash=8aee4949d7bcf4e1
    26.9450 committed                     [thumbnail]      gamma                  enabled  order=90, piece hash=45837a3fc91a35ca
    26.9450 committed                     [thumbnail]      temperature            enabled  order= 3, piece hash=26f236cb1b50a8b2
    26.9450 committed                     [thumbnail]      highlights             enabled  order= 4, piece hash=b34cef442f00f066
    26.9450 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude
    26.9450 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"

pehar1 commented 2 months ago

@kofa73 you are not alone. Working with current master I have seen this issue several times during the last weeks while reworking old edits from 2020. Unfortunately currently I can not dig deeper, much too much other work to do. May be next week... As I have worked with duplicates I should be able to provide samples (raw + xmp) showing the issue.

kofa73 commented 2 months ago

I've now added average.tif and average.tif.xmp to the downloads. This is not an old XMP at all; I took the photo on 28 August, and now it produces the error. The image looks OK, though. If I go through the history stack, and hover over the filmic instances, I don't see NaN or other suspicious value, but the log indicates an issue with that module:

   587.9320 committed                     [full]           colorin                enabled  order= 9, piece hash=f409c29525153be1
   587.9323 committed                     [full]           colorout               enabled  order=82, piece hash=8aee4949d7bcf4e1
   587.9323 committed                     [full]           gamma                  enabled  order=90, piece hash=45837a3fc91a35ca
   587.9323 committed                     [full]           flip                   disabled order=18, piece hash=0
   587.9323 [iop_validate_params] `filmicrgb' failed for type "float", field: output_power
   587.9323 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
   587.9323 committed                     [full]           filmicrgb              enabled  order=58, piece hash=4bbb886cf68b7964

I can confirm that it's step #5 in the history that causes the issue:

it comes after 'flip' (orientation)
selecting it in the history pops up the error:

TurboGit commented 2 months ago

@kofa73 : Still cannot reproduce with average.tiff you've posted. Maybe you have again opened the image and so the .xmp has been "fixed" before you posted it?

kofa73 commented 2 months ago

@TurboGit No. To double-check, I downloaded average.tif and average.tif.xmp from my upload (they were uploaded from my Linux box, I downloaded to the Windows laptop). I deleted config and cache, and installed the latest daily of darktable. In the darkroom:

And, in the log, I see the same errors as I reported before, for filmic at step 5, after orientation (flip):

    85.4134 committed                     [preview]        gamma                  enabled  order=90, piece hash=8a4084808643f4ec
    85.4134 committed                     [preview]        flip                   disabled order=18, piece hash=0
    85.4134 [iop_validate_params] `filmicrgb' failed for type "float", field: output_power
    85.4135 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"

TurboGit commented 2 months ago

We are doomed, I tried again, clicked on all steps since 5 to the to, not a single error :( So probably an issue due to different context... Where you able to reproduce also on GNU/Linux using current master with average.tiff?

kofa73 commented 2 months ago

You know I have a penchant to report mysterious bugs, like #10090 in 2021 that then became #14215 and #15621, finally closed in late 2023...

Were you able to reproduce also on GNU/Linux using current master with average.tiff?

Well, yesterday evening I was. I can check this again during the lunch break.

kofa73 commented 2 months ago

@TurboGit This is with the nightly AppImage, everything (AppImage, TIFF file, XMP file) freshly downloaded to /tmp:

kofa@eagle:/tmp$ ./Darktable-4.9.0+419.g9ba5a0641c-x86_64.AppImage --configdir /tmp/config --cachedir /tmp/cache -d params -d common -d pipe /tmp/average.tif
...
     8.6902 committed                     [preview]        colorin                enabled  order= 9, piece hash=6d5756bf5b64fc50
     8.6905 committed                     [preview]        colorout               enabled  order=82, piece hash=6e2730d72ac8ffa8
     8.6905 committed                     [preview]        gamma                  enabled  order=90, piece hash=8a4084808643f4ec
     8.6905 committed                     [preview]        flip                   disabled order=18, piece hash=0
     8.6905 [iop_validate_params] `filmicrgb' failed for type "float", field: output_power
     8.6905 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"
     8.6906 committed                     [preview]        filmicrgb              enabled  order=58, piece hash=8a8b64de2dfc200f

I could repeat this after building the current master, but I don't think there's a point. On two different machines, two different binaries from GitLab, I have the error -- and on many other machines, many other people do not.

I've tried resetting LANG and LC_ALL to C, that did not help. Other ideas?

kofa73 commented 2 months ago

Update: there is no 'filmicrgb' has been disabled... running without -d params. Isn't that just supposed to alter logging?

However, this does not affect the processing of the bee-on-the-flower image:

rm -rf /tmp/config /tmp/cache ; ./Darktable-4.9.0+419.g9ba5a0641c-x86_64.AppImage --configdir /tmp/config --cachedir /tmp/cache /tmp/2020-04-05_13-17-59_DSC_0006.NEF

produces the same issue as originally reported.

TurboGit commented 2 months ago

Ok, reproduced and this seems to be an issue with the actual range of value described for parameters.

To reproduce, enable filmicrgb, reset module, set dynamic range scaling to 50% and then white relative exposure to 2EV and see:

    61.8262 [iop_validate_params] `filmicrgb' failed for type "float", field: output_power (10.519415 - [1.000000..10.000000] : default 4.000000)
    61.8263 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"

If you set white relative exposure to 1EV or even .1EV then it is even worth:

   192.7212 [iop_validate_params] `filmicrgb' failed for type "float", field: output_power (119.028038 - [1.000000..10.000000] : default 4.000000)
   192.7213 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"

Yes, those are insane value, but the output_power range being set to [ 1 .. 10 ] seems a too strict constraint.

In your case @kofa73 the output_power is a bit over 24.

kofa73 commented 2 months ago

I'm wondering if the two (my original NEF problem with the history from 2020) is the same as the current one (average.tif). With the NEF, I see NaN in the params, and 18.45% as display white level (which should be mid-grey). See above, https://github.com/darktable-org/darktable/issues/17420#issuecomment-2327240290

kofa73 commented 2 months ago

@TurboGit : I think those (exposed by the NEF and by the TIF) are different issues.

I've made some progress. On my machine, a clean build of darktable 4.4.0 opens the NEF file correctly; there is no NaN in the params. Then, restoring the XMP file (just in case), it fails with 4.8.0 (update: also fails with 4.6.0).

The command to do this is, making sure to start with a clean slate: cp /tmp/orig-2020-04-05_13-17-59_DSC_0006.NEF.xmp /tmp/2020-04-05_13-17-59_DSC_0006.NEF.xmp ; rm -rf /tmp/cache/ /tmp/config/ ; ~/darktable-master/bin/darktable --configdir /tmp/config --cachedir /tmp/cache /tmp/2020-04-05_13-17-59_DSC_0006.NEF

It's going to be a loooong bisect. :)

kofa73 commented 2 months ago

@TurboGit OK, I had a suspicion this would be the case (did a 'blame' on filmicrgb.c), but my first attempt to build this commit failed because of compiler flags (implicit declaration of functions, related to HEIC). I had to remove libheic-dev to be able to bisect, but it brought me back to this:

9ed75997e43453011edec720fe1792e996230f58 is the first bad commit
commit 9ed75997e43453011edec720fe1792e996230f58
Author: Pascal Obry <pascal@obry.net>
Date:   Wed Aug 9 11:48:04 2023 +0200

    Add support for incremental IOP update.

kofa73 commented 2 months ago

The new param debug log (thanks, @TurboGit) confirms that params are NaN or simply wrong (like target white = 18.45%):

39.4319 [iop_validate_params] 'filmicrgb' data for type "float", field: contrast (-nan - [0.000000..5.000000] : default 1.000000) 39.4319 [iop_validate_params] 'filmicrgb' data for type "float", field: white_point_target (18.450005 - [0.000000..1600.000000] : default 100.000000)

    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: grey_point_source (18.450001 - [0.000000..100.000000] : default 18.450001)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: black_point_source (-7.750000 - [-16.000000..-0.100000] : default -8.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: white_point_source (5.000000 - [0.100000..16.000000] : default 4.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: reconstruct_threshold (-1.000000 - [-6.000000..6.000000] : default 0.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: reconstruct_feather (3.000000 - [0.250000..6.000000] : default 3.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: reconstruct_bloom_vs_details (100.000000 - [-100.000000..100.000000] : default 100.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: reconstruct_grey_vs_color (100.000000 - [-100.000000..100.000000] : default 100.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: reconstruct_structure_vs_texture (0.000000 - [-100.000000..100.000000] : default 0.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: security_factor (0.000000 - [-50.000000..200.000000] : default 0.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: grey_point_target (18.450001 - [1.000000..50.000000] : default 18.450001)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: black_point_target (0.000012 - [0.000000..20.000000] : default 0.015176)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: white_point_target (18.450005 - [0.000000..1600.000000] : default 100.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: output_power (3.394889 - [1.000000..10.000000] : default 4.000000)
    39.4319 [iop_validate_params] `filmicrgb' failed for type "float", field: latitude (0.000000 - [0.010000..99.000000] : default 0.010000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: contrast (-nan - [0.000000..5.000000] : default 1.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: saturation (10.000000 - [-200.000000..200.000000] : default 0.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: balance (50.000000 - [-50.000000..50.000000] : default 0.000000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "float", field: noise_level (0.200000 - [0.000000..6.000000] : default 0.200000)
    39.4319 [iop_validate_params] `filmicrgb' data for type "dt_iop_filmicrgb_methods_type_t", field: preserve_color (3)
    39.4319 [iop_validate_params] `filmicrgb' data for type "dt_iop_filmicrgb_colorscience_type_t", field: version (1)
    39.4319 [iop_validate_params] `filmicrgb' data for type "bool", field: auto_hardness (1)
    39.4319 [iop_validate_params] `filmicrgb' data for type "bool", field: custom_grey (0)
    39.4319 [iop_validate_params] `filmicrgb' data for type "int", field: high_quality_reconstruction (1 - [0..10] : default 1)
    39.4319 [iop_validate_params] `filmicrgb' data for type "dt_iop_filmic_noise_distribution_t", field: noise_distribution (1)
    39.4320 [iop_validate_params] `filmicrgb' data for type "dt_iop_filmicrgb_curve_type_t", field: shadows (0)
    39.4320 [iop_validate_params] `filmicrgb' data for type "dt_iop_filmicrgb_curve_type_t", field: highlights (0)
    39.4320 [iop_validate_params] `filmicrgb' data for type "bool", field: compensate_icc_black (0)
    39.4320 [iop_validate_params] `filmicrgb' data for type "dt_iop_filmicrgb_spline_version_type_t", field: spline_version (2)
    39.4320 [iop_validate_params] `filmicrgb' data for type "bool", field: enable_highlight_reconstruction (1)
    39.4320 [iop_validate_params] `filmicrgb' failed for type "dt_iop_filmicrgb_params_t"

kofa73 commented 2 months ago

Taking weirdness to the next level, the attached patch fixes the problem. However, it only contains debug prints, nothing else. If I git stash it locally, the problem is back. If I do a git stash pop, it's gone. print-only-patch.txt

The way I build and run:

bdtm

cp orig-2020-04-05_13-17-59_DSC_0006.NEF.xmp 2020-04-05_13-17-59_DSC_0006.NEF.xmp
rm -rf /tmp/cache/ /tmp/config/
/home/kofa/darktable-master/bin/darktable -d common -d pipe -d opencl -d tiling -d perf -d dev -d masks -d params -d verbose 2020-04-05_13-17-59_DSC_0006.NEF 2>&1 | grep kofa

The bdtm (build darktable master) script is:

#!/bin/bash
renice -n 19 -p $$
ionice -c 3 -p $$

cd ~/darktable ; 
git checkout master
git clean -d -f -x ;

git pull --rebase

git submodule update --init --recursive
rm -rf /home/kofa/darktable-master
./build.sh --prefix /home/kofa/darktable-master --build-type Release --install

kofa73 commented 2 months ago

Commenting out the printf in main changes nothing (still OK). The same goes for the one in process_cl. However, this breaks the image:

static inline void convert_to_spline_v3(dt_iop_filmicrgb_params_t* n)
{
    // dt_print(DT_DEBUG_ALWAYS, "kofa filmicrgb#convert_to_spline_v3\n");

The output on the console is:

     2.8557 kofa old_version: 3
     2.8557 kofa contrast v3: 1.500000 -> 1.500000
     2.8558 kofa old_version: 3
     2.8558 kofa contrast v3: 1.500000 -> 1.500000
     2.8558 kofa old_version: 3
     2.8558 kofa contrast v3: 1.500000 -> 1.500000
     2.8558 kofa old_version: 3
     2.8558 kofa contrast v3: 1.500000 -> 1.500000

Restoring the line fixes the image, and the output becomes:

     2.8716 kofa old_version: 3
     2.8716 kofa filmicrgb#convert_to_spline_v3
     2.8716 kofa contrast v3: 1.500000 -> 1.073812
     2.8716 kofa old_version: 3
     2.8716 kofa filmicrgb#convert_to_spline_v3
     2.8716 kofa contrast v3: 1.500000 -> 0.900281
     2.8717 kofa old_version: 3
     2.8717 kofa filmicrgb#convert_to_spline_v3
     2.8717 kofa contrast v3: 1.500000 -> 0.969843
     2.8717 kofa old_version: 3
     2.8717 kofa filmicrgb#convert_to_spline_v3
     2.8717 kofa contrast v3: 1.500000 -> 0.969843

contrast is adjusted in convert_to_spline_v3. It seems if the debug statement is not there, the function is not invoked.

Adding more debug to convert_to_spline_v3 (the image is still OK) never shows the NaN value in contrast, not even in the input; and target white is not 18%, but 100%; latitude is never printed as 0, even though previously we had warnings about that.

/home/kofa/darktable-master/bin/darktable -d common -d pipe -d opencl -d tiling -d perf -d dev -d masks -d params -d verbose 2020-04-05_13-17-59_DSC_0006.NEF 2>&1 | grep -E "(contrast)|(latitude)"
     2.7881 kofa filmicrgb#convert_to_spline_v3 latitude before: 33.000000
     2.7881 kofa filmicrgb#convert_to_spline_v3 latitude after: 50.510204
     2.7881 kofa filmicrgb#convert_to_spline_v3 contrast before: 1.500000
     2.7881 kofa filmicrgb#convert_to_spline_v3 contrast after: 1.073812
     2.7882 kofa contrast v3: 1.500000 -> 1.073812
     2.7882 kofa filmicrgb#convert_to_spline_v3 latitude before: 33.000000
     2.7882 kofa filmicrgb#convert_to_spline_v3 latitude after: 50.510197
     2.7882 kofa filmicrgb#convert_to_spline_v3 contrast before: 1.500000
     2.7882 kofa filmicrgb#convert_to_spline_v3 contrast after: 0.900281
     2.7882 kofa contrast v3: 1.500000 -> 0.900281
     2.7882 kofa filmicrgb#convert_to_spline_v3 latitude before: 33.000000
     2.7882 kofa filmicrgb#convert_to_spline_v3 latitude after: 50.510208
     2.7882 kofa filmicrgb#convert_to_spline_v3 contrast before: 1.500000
     2.7882 kofa filmicrgb#convert_to_spline_v3 contrast after: 0.969843
     2.7882 kofa contrast v3: 1.500000 -> 0.969843
     2.7882 kofa filmicrgb#convert_to_spline_v3 latitude before: 33.000000
     2.7882 kofa filmicrgb#convert_to_spline_v3 latitude after: 50.510208
     2.7882 kofa filmicrgb#convert_to_spline_v3 contrast before: 1.500000
     2.7882 kofa filmicrgb#convert_to_spline_v3 contrast after: 0.969843
     2.7882 kofa contrast v3: 1.500000 -> 0.969843
### this is the initial state of filmic, before applying step 6 in the history
     3.4917 [iop_validate_params] `filmicrgb' data for type "float", field: latitude (0.010000 - [0.010000..99.000000] : default 0.010000)
     3.4917 [iop_validate_params] `filmicrgb' data for type "float", field: contrast (1.000000 - [0.000000..5.000000] : default 1.000000)
### below are steps 6, 14, 16, 20
     3.4980 [iop_validate_params] `filmicrgb' data for type "float", field: latitude (50.510204 - [0.010000..99.000000] : default 0.010000)
     3.4980 [iop_validate_params] `filmicrgb' data for type "float", field: contrast (1.073812 - [0.000000..5.000000] : default 1.000000)
     3.4990 [iop_validate_params] `filmicrgb' data for type "float", field: latitude (50.510204 - [0.010000..99.000000] : default 0.010000)
     3.4990 [iop_validate_params] `filmicrgb' data for type "float", field: contrast (1.073812 - [0.000000..5.000000] : default 1.000000)
     3.4991 [iop_validate_params] `filmicrgb' data for type "float", field: latitude (50.510197 - [0.010000..99.000000] : default 0.010000)
     3.4991 [iop_validate_params] `filmicrgb' data for type "float", field: contrast (0.900281 - [0.000000..5.000000] : default 1.000000)
...