Feature: improve logging related to finding files #285

alhirzel · 2022-09-28T02:14:20Z

Description

Improves debug and trace logging when trying to locate files using the file resolver.

Showing the result of this change, note the basic output is unchanged:

alhirzel@gecko:/tmp $ mitsuba file_error.xml
2022-09-28 07:29:05 INFO  main  [mitsuba.cpp:340] Mitsuba version 3.0.2 (makepkg[d456826e], Linux, 64bit, 24 threads, 8-wide SIMD)
2022-09-28 07:29:05 INFO  main  [mitsuba.cpp:341] Copyright 2022, Realistic Graphics Lab, EPFL
2022-09-28 07:29:05 INFO  main  [mitsuba.cpp:342] Enabled processor features: cuda llvm avx2 avx fma f16c sse4.2 x86_64
2022-09-28 07:29:05 INFO  main  [xml.cpp:1405] Loading XML file "file_error.xml" with variant "scalar_rgb"..

Caught a critical exception: [xml.cpp:1112] Error while loading "file_error.xml" (near line 2, col 6): could not instantiate shape plugin of type "obj": 
[xml.cpp:1112]   [OBJMesh] Error while loading OBJ file "DOES_NOT_EXIST.obj": file not found

With Debug each lookup is annotated:

alhirzel@gecko:/tmp $ mitsuba -v file_error.xml
2022-09-28 07:29:09 INFO  main  [mitsuba.cpp:340] Mitsuba version 3.0.2 (makepkg[d456826e], Linux, 64bit, 24 threads, 8-wide SIMD)
2022-09-28 07:29:09 INFO  main  [mitsuba.cpp:341] Copyright 2022, Realistic Graphics Lab, EPFL
2022-09-28 07:29:09 INFO  main  [mitsuba.cpp:342] Enabled processor features: cuda llvm avx2 avx fma f16c sse4.2 x86_64
2022-09-28 07:29:09 INFO  main  [xml.cpp:1405] Loading XML file "file_error.xml" with variant "scalar_rgb"..
2022-09-28 07:29:09 DEBUG wrk0  [FileResolver] Looking for file "plugins/obj.so" on the resource search path(s)
2022-09-28 07:29:09 DEBUG wrk0  [PluginManager] Loading plugin "plugins/obj.so" ..
2022-09-28 07:29:09 DEBUG wrk0  [FileResolver] Looking for file "plugins/diffuse.so" on the resource search path(s)
2022-09-28 07:29:09 DEBUG wrk0  [PluginManager] Loading plugin "plugins/diffuse.so" ..
2022-09-28 07:29:09 DEBUG wrk0  [FileResolver] Looking for file "plugins/uniform.so" on the resource search path(s)
2022-09-28 07:29:09 DEBUG wrk0  [PluginManager] Loading plugin "plugins/uniform.so" ..
2022-09-28 07:29:09 DEBUG wrk0  [FileResolver] Looking for file "DOES_NOT_EXIST.obj" on the resource search path(s)
2022-09-28 07:29:09 DEBUG wrk0  [OBJMesh] Loading mesh from "DOES_NOT_EXIST.obj" ..

Caught a critical exception: [xml.cpp:1112] Error while loading "file_error.xml" (near line 2, col 6): could not instantiate shape plugin of type "obj": 
[xml.cpp:1112]   [OBJMesh] Error while loading OBJ file "DOES_NOT_EXIST.obj": file not found

And finally for Trace detailed info about where is checked:

alhirzel@gecko:/tmp $ mitsuba -vv file_error.xml
2022-09-28 07:29:13 INFO  main  [mitsuba.cpp:340] Mitsuba version 3.0.2 (makepkg[d456826e], Linux, 64bit, 24 threads, 8-wide SIMD)
2022-09-28 07:29:13 INFO  main  [mitsuba.cpp:341] Copyright 2022, Realistic Graphics Lab, EPFL
2022-09-28 07:29:13 INFO  main  [mitsuba.cpp:342] Enabled processor features: cuda llvm avx2 avx fma f16c sse4.2 x86_64
2022-09-28 07:29:13 INFO  main  [xml.cpp:1405] Loading XML file "file_error.xml" with variant "scalar_rgb"..
2022-09-28 07:29:13 DEBUG wrk0  [FileResolver] Looking for file "plugins/obj.so" on the resource search path(s)
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Didn't find file "plugins/obj.so" at /tmp/plugins/obj.so
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Found file "plugins/obj.so" at /usr/lib/mitsuba3-git/plugins/obj.so
2022-09-28 07:29:13 DEBUG wrk0  [PluginManager] Loading plugin "plugins/obj.so" ..
2022-09-28 07:29:13 DEBUG wrk0  [FileResolver] Looking for file "plugins/diffuse.so" on the resource search path(s)
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Didn't find file "plugins/diffuse.so" at /tmp/plugins/diffuse.so
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Found file "plugins/diffuse.so" at /usr/lib/mitsuba3-git/plugins/diffuse.so
2022-09-28 07:29:13 DEBUG wrk0  [PluginManager] Loading plugin "plugins/diffuse.so" ..
2022-09-28 07:29:13 DEBUG wrk0  [FileResolver] Looking for file "plugins/uniform.so" on the resource search path(s)
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Didn't find file "plugins/uniform.so" at /tmp/plugins/uniform.so
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Found file "plugins/uniform.so" at /usr/lib/mitsuba3-git/plugins/uniform.so
2022-09-28 07:29:13 DEBUG wrk0  [PluginManager] Loading plugin "plugins/uniform.so" ..
2022-09-28 07:29:13 DEBUG wrk0  [FileResolver] Looking for file "DOES_NOT_EXIST.obj" on the resource search path(s)
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Didn't find file "DOES_NOT_EXIST.obj" at /tmp/DOES_NOT_EXIST.obj
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Didn't find file "DOES_NOT_EXIST.obj" at /usr/lib/mitsuba3-git/DOES_NOT_EXIST.obj
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Didn't find file "DOES_NOT_EXIST.obj" at DOES_NOT_EXIST.obj
2022-09-28 07:29:13 TRACE wrk0  [FileResolver] Didn't find file "DOES_NOT_EXIST.obj" at DOES_NOT_EXIST.obj
2022-09-28 07:29:13 DEBUG wrk0  [OBJMesh] Loading mesh from "DOES_NOT_EXIST.obj" ..

Caught a critical exception: [xml.cpp:1112] Error while loading "file_error.xml" (near line 2, col 6): could not instantiate shape plugin of type "obj": 
[xml.cpp:1112]   [OBJMesh] Error while loading OBJ file "DOES_NOT_EXIST.obj": file not found

Testing

I did not run the test suite because I am naively assuming this is a non-breaking change.

Checklist

My code follows the style guidelines of this project
My changes generate no new warnings
My code also compiles for cuda_* and llvm_* variants. If you can't test this, please leave below
I have commented my code
I have made corresponding changes to the documentation
I have added tests that prove my fix is effective or that my feature works
I cleaned the commit history and removed any "Merge" commits
I give permission that the Mitsuba 3 project may redistribute my contributions under the terms of its license

Speierers

Hi @alhirzel, thanks for this PR.

Reading the PR description it seems that the output is missing.

Speierers · 2022-09-28T07:22:04Z

src/core/fresolver.cpp

@@ -21,10 +22,15 @@ bool FileResolver::contains(const fs::path &p) const {

 fs::path FileResolver::resolve(const fs::path &path) const {
    if (!path.is_absolute()) {
+        Log(Debug, "Looking for file \"%s\" on the resource search path(s)", path.native());


Shouldn't this be logged into Trace as well?

Currently Debug is written once per file lookup, and Trace is written once per path check. You're right that I forgot to paste the output--maybe it makes the behavior more clear.

IMO this is a little too much for debug mode. I would like to be able to compile in debug mode while not always having those logs. Let's use Trace here to have control. In any case, the log messages you are adding in this PR are useful to debug a situation where a file couldn't be found, in which case you will need to switch to Trace to see all the messages.

Ok, agree, I will make all of the outputs part of Trace.

alhirzel · 2022-09-28T20:25:28Z

I updated this to include a few more improvements that are in the following spirit (which I also added to the dev docs):

When writing error or log messages that refer to an existing file, include the full path to the file by default.

Speierers · 2022-09-29T07:09:52Z

src/core/plugin.cpp

@@ -113,7 +113,7 @@ struct PluginManager::PluginManagerPrivate {
        fs::path resolved = resolver->resolve(filename);

        if (fs::exists(resolved)) {
-            Log(Debug, "Loading plugin \"%s\" ..", filename.string());
+            Log(Debug, "Loading plugin \"%s\" from \"%s\" ..", name, resolved.string());


I don't think that's necessary.

Ok - I plan to change it to use the full resolved path then. See what you think.

Speierers · 2022-09-29T07:10:33Z

src/core/spectrum.cpp

+        Log(Error, "\"%s\": file does not exist!", file_path.string());

-    Log(Info, "Loading spectral data file \"%s\" ..", file_path);
+    Log(Info, "Loading spectral data file \"%s\" ..", file_path.string());


Does this fix a specific bug? What is the log message before and after this change?

I actually made these types of changes during a very pedantic file path review for consistency in explicitly calling .string(); I don't know that it fixes a bug. I will back out this for less noise in the PR!

Speierers · 2022-09-29T07:11:14Z

src/emitters/envmap.cpp

@@ -108,7 +108,7 @@ class EnvironmentMapEmitter final : public Emitter<Float, Spectrum> {
        ref<Bitmap> bitmap = new Bitmap(file_path);
        if (bitmap->width() < 2 || bitmap->height() < 3)
            Throw("\"%s\": the environment map resolution must be at "
-                  "least 2x3 pixels", m_filename);
+                  "least 2x3 pixels", file_path.string());


Same question here.

improve logging related to finding files

1deb2eb

Speierers reviewed Sep 28, 2022

View reviewed changes

more logging improvements and guidance in docs

75c0056

alhirzel force-pushed the improve-debugging-file-locations branch from f3400a8 to 75c0056 Compare September 28, 2022 20:24

Speierers reviewed Sep 29, 2022

View reviewed changes

wjakob force-pushed the master branch 4 times, most recently from 4af72bd to 199b607 Compare November 30, 2022 20:51

wjakob force-pushed the master branch 2 times, most recently from df4cbe0 to 64fedcd Compare January 17, 2023 23:05

wjakob force-pushed the master branch 3 times, most recently from 3f3b8d0 to 1bdea6e Compare October 12, 2023 19:49

wjakob force-pushed the master branch from 8252fda to 93f84e9 Compare September 23, 2024 05:48

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Feature: improve logging related to finding files #285

Feature: improve logging related to finding files #285

alhirzel commented Sep 28, 2022 •

edited

Loading

Speierers left a comment

Speierers Sep 28, 2022

alhirzel Sep 28, 2022

Speierers Sep 29, 2022

alhirzel Oct 3, 2022

alhirzel commented Sep 28, 2022 •

edited

Loading

Speierers Sep 29, 2022

alhirzel Oct 3, 2022

Speierers Sep 29, 2022

alhirzel Oct 3, 2022

Speierers Sep 29, 2022

Feature: improve logging related to finding files #285

Are you sure you want to change the base?

Feature: improve logging related to finding files #285

Conversation

alhirzel commented Sep 28, 2022 • edited Loading

Description

Testing

Checklist

Speierers left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alhirzel commented Sep 28, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alhirzel commented Sep 28, 2022 •

edited

Loading

alhirzel commented Sep 28, 2022 •

edited

Loading