xous-core icon indicating copy to clipboard operation
xous-core copied to clipboard

Published 20 hours ago • verified publisher icon betrusted-io

PDDB std::fs::metadata may not accurately report key existance

Open tmarble opened this issue 2 years ago • 11 comments

It seems that std::fs::metadata always returns Ok() -- even if a key in the dict is not present.

In the case of mtxcli this causes a second /unset command to result in a panic:

/get _filter
9
/unset _filter
/get _filter
9                          <-- that's an error! it Should say _filter UNSET
/unset _filter
panic

The code site in question is around line 296 (in the unset() function) in apps/mtxcli/src/cmds.rs

tmarble avatar Jan 17 '23 18:01 tmarble

For the record, this is the unset function in question:

    pub fn unset(&mut self, key: &str) -> Result<(), Error> {
        // log::info!("unset '{}'", key);
        let mut keypath = PathBuf::new();
        keypath.push(MTXCLI_DICT);
        if std::fs::metadata(&keypath).is_ok() { // keypath exists
            log::info!("dict '{}' exists", MTXCLI_DICT);
        } else {
            log::info!("dict '{}' does NOT exist.. creating it", MTXCLI_DICT);
            std::fs::create_dir_all(&keypath)?;
        }
        keypath.push(key);
        if std::fs::metadata(&keypath).is_ok() { // keypath exists
            log::info!("dict:key = '{}:{}' exists.. deleting it", MTXCLI_DICT, key);

            std::fs::remove_file(keypath)?;
        }
        Ok(())
    }

It looks like for some reason pddb is returning that an invalid path exists. I suspect it's returning that it's a valid dict, which it really isn't...

xobs avatar Jan 18 '23 00:01 xobs

I'm actually not able to reproduce this:

image

There were some changes to std::fs to implement lstat and friends, but that wouldn't have affected this: https://github.com/betrusted-io/rust/commit/452f331576874ea6c216d3626a453f399356ad52

Can you give steps to reproduce this? What version of libstd and rust are you using?

xobs avatar Jan 18 '23 01:01 xobs

NOTE: This behavior is on Precursor -- not hosted mode

Here are my versions:

rustc: 1.66.0 (69f9c33d7 2022-12-12)

xous: v0.9.11-152-g277d014f

ec: gateware 8099ddb4, clean, tag v0.9.9-3

SoC: v0.9.10-2-ga0912d6d

Oh, in your example you did NOT do /unset of the same variable twice in a row... _filter ~= filter

tmarble avatar Jan 18 '23 02:01 tmarble

I'm still not able to replicate it image

xobs avatar Jan 18 '23 13:01 xobs

@tmarble can you try this branch: https://github.com/betrusted-io/xous-core/tree/maybe-fix-delete and see if it helps? I don't get the double-free panic anymore once I have applied this patch on the restored version of your Precursor here.

bunnie avatar Jan 19 '23 06:01 bunnie

@bunnie alas it still panics. Console log attached. screenlog.0119.txt

tmarble avatar Jan 19 '23 14:01 tmarble

Is everything that shows up in the log a result of commands being typed via console, or are you typing some directly on the keyboard?

For example, this bit here:

NFO:keyboard: injecting key '/'(2f) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'u'(75) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key ''(8) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 's'(73) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 't'(74) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key ' '(20) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key '_'(5f) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'v'(76) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'r'(72) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 's'(73) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'i'(69) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'o'(6f) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services/keyboard/src/main.rs:956)
INFO:keyboard: injecting key '
'(d) (services/keyboard/src/main.rs:956
INFO:mtxcli::cmds: unset '_version' (apps/mtxcli/src/cmds.rs:281)
INFO:mtxcli::cmds: dict 'mtxcli' exists (apps/mtxcli/src/cmds.rs:285)
INFO:mtxcli::cmds: Metadata on path: Ok(Metadata { file_type: FileType(Key), is_dir: false, is_file: true, permissions: Permissions(FilePermissions), modified: Err(Custom { kind: Other, error: "operation not supported on this platform" }), accessed: Err(Custom { kind: Other, error: "operation not supported on this platform" }), created: Err(Custom { kind: Other, error: "operation not supported on this platform" }), .. }) (apps/mtxcli/src/cmds.rs:297)
INFO:mtxcli::cmds: dict:key = 'mtxcli:_version' exists.. deleting it (apps/mtxcli/src/cmds.rs:299)
INFO:mtxcli::cmds: dict 'mtxcli' exists (apps/mtxcli/src/cmds.rs:335)
INFO:mtxcli::cmds: get '_version' = 'v0.9.11-0159' (apps/mtxcli/src/cmds.rs:344)
INFO:net::connection_manager: wlan activity interval timeout (services/net/src/connection_manager.rs:317)
INFO:net::connection_manager: wlan activity interval timeout (services/net/src/connection_manager.rs:317)
INFO:mtxcli::cmds: unset '_version' (apps/mtxcli/src/cmds.rs:281)
INFO:mtxcli::cmds: dict 'mtxcli' exists (apps/mtxcli/src/cmds.rs:285)
INFO:mtxcli::cmds: Metadata on path: Ok(Metadata { file_type: FileType(Key), is_dir: false, is_file: true, permissions: Permissions(FilePermissions), modified: Err(Custom { kind: Other, error: "operation not supported on this platform" }), accessed: Err(Custom { kind: Other, error: "operation not supported on this platform" }), created: Err(Custom { kind: Other, error: "operation not supported on this platform" }), .. }) (apps/mtxcli/src/cmds.rs:297)
INFO:mtxcli::cmds: dict:key = 'mtxcli:_version' exists.. deleting it (apps/mtxcli/src/cmds.rs:299)
ERR :pddb::backend::dictionary: Double-free error in free_keys() (services/pddb/src/backend/dictionary.rs:1014)
INFO:pddb::backend::dictionary: free_key_vec[i].0: FreeKeyRange { start: 9, run: 0 } (services/pddb/src/backend/dictionary.rs:1015)
INFO:pddb::backend::dictionary: index: 9 (services/pddb/src/backend/dictionary.rs:1016)
PANIC in PID 25:
thread '<unnamed>' panicked at 'Double-free error in free_keys()', services/pddb/src/backend/dictionary.rs:1017:25
INFO:net::connection_manager: wlan activity interval timeout (services/net/src/connection_manager.rs:317)

I see only one /unset _version command being issued by typing, but I see two calls to it in the log. I can't seem to reproduce that behavior by just typing stuff into the console.

If you're typing stuff on the keyboard, it doesn't show up in the console log, and it doesn't help me reproduce the issue -- what would be most helpful is just the exact sequence of commands you're using to cause the problem.

bunnie avatar Jan 19 '23 14:01 bunnie

For example, this is just what I see now:

INFO:keyboard: injecting key '/'(2f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'u'(75) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 's'(73) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 't'(74) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key ' '(20) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key '_'(5f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'v'(76) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'r'(72) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 's'(73) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'i'(69) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'o'(6f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services\keyboard\src\main.rs:956)
'(d) (services\keyboard\src\main.rs:956)
INFO:mtxcli::cmds: unset '_version' (apps\mtxcli\src\cmds.rs:281)
INFO:mtxcli::cmds: dict 'mtxcli' exists (apps\mtxcli\src\cmds.rs:285)
INFO:mtxcli::cmds: dict:key = 'mtxcli:_version' exists.. deleting it (apps\mtxcli\src\cmds.rs:297)
INFO:keyboard: injecting key '/'(2f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'g'(67) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 't'(74) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key ' '(20) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key '_'(5f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'v'(76) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'r'(72) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 's'(73) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'i'(69) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'o'(6f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services\keyboard\src\main.rs:956)
'(d) (services\keyboard\src\main.rs:956)
INFO:mtxcli::cmds: dict 'mtxcli' exists (apps\mtxcli\src\cmds.rs:333)
ERR :pddb::libstd: unable to find key _version in dict mtxcli (services\pddb\src\libstd\mod.rs:494)
INFO:keyboard: injecting key '/'(2f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'u'(75) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 's'(73) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 't'(74) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key ' '(20) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key '_'(5f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'v'(76) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'r'(72) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 's'(73) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'i'(69) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'o'(6f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services\keyboard\src\main.rs:956)
'(d) (services\keyboard\src\main.rs:956)
INFO:mtxcli::cmds: unset '_version' (apps\mtxcli\src\cmds.rs:281)
INFO:mtxcli::cmds: dict 'mtxcli' exists (apps\mtxcli\src\cmds.rs:285)
INFO:keyboard: injecting key '/'(2f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'g'(67) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 't'(74) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key ' '(20) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key '_'(5f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'v'(76) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'r'(72) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 's'(73) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'i'(69) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'o'(6f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services\keyboard\src\main.rs:956)
'(d) (services\keyboard\src\main.rs:956)
INFO:mtxcli::cmds: dict 'mtxcli' exists (apps\mtxcli\src\cmds.rs:333)
ERR :pddb::libstd: unable to find key _version in dict mtxcli (services\pddb\src\libstd\mod.rs:494)
INFO:keyboard: injecting key '/'(2f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'u'(75) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 's'(73) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 't'(74) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key ' '(20) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key '_'(5f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'v'(76) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'e'(65) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'r'(72) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 's'(73) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'i'(69) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'o'(6f) (services\keyboard\src\main.rs:956)
INFO:keyboard: injecting key 'n'(6e) (services\keyboard\src\main.rs:956)
'(d) (services\keyboard\src\main.rs:956)
INFO:mtxcli::cmds: unset '_version' (apps\mtxcli\src\cmds.rs:281)
INFO:mtxcli::cmds: dict 'mtxcli' exists (apps\mtxcli\src\cmds.rs:285)

bunnie avatar Jan 19 '23 14:01 bunnie

I did a mixture of 1) typing on the keyboard, 2) using the F-keys to repeat and 3) typing in the console...

The way I reproduce is:

/get _version
/unset _version
/get _version
/unset _version

tmarble avatar Jan 19 '23 14:01 tmarble

Hmm yah. For some reason I can't reproduce anymore, but let me restore from the full backup and try it again. maybe some intermediate thing happened while testing other solutions that "fixed it".

bunnie avatar Jan 19 '23 14:01 bunnie

I just did a fairly comprehensive test bench and found a couple more corner cases in key deletion. Hopefully the situation is fixed now; let me know if you end up with more keys that either don't delete when they should, or you have double-free errors etc.

bunnie avatar Jan 20 '23 10:01 bunnie