Node.js exits while waiting for auth.getContainer (and other functions)

[b-zee]

Consider the following example:

const safeApp = require('@maidsafe/safe-node-app');

(async () => {
    setTimeout(() => console.log('callback'), 1000);

    const info = { id: 'primary', name: 'Primary App', vendor: '1' };

    const app = await safeApp.initializeApp(info);
    await app.auth.loginForTest({}, { own_container: true });

    console.log('1: still here');
    const md = await app.auth.getContainer('apps/primary'); // Might exit here
    console.log('2: ' + (await md.getNameAndTag()).type_tag);
})();

When running the above, all is well. When removing the setTimeout, the Node.js script will exit after the getContainer is run.

The setTimeout puts a callback in the queue that prevents Node.js from exiting. I think the API should also put something in the queue to prevent the Node.js process from thinking it's done.

My hypothesis is that is has something to do with how the FFI works. The same happens when calling getContainersPermissions, so I assume it's just about any FFI function.

[hunterlester]

I think it's simply that type_tag is not a property of the promise.

When I run

(async () => {
    setTimeout(() => console.log('callback'), 1000);
    const info = { id: 'primary', name: 'Primary App', vendor: '1' };

    const app = await safeApp.initialiseApp(info);
    await app.auth.loginForTest({}, { own_container: true });

    console.log('1: still here');
    const md = await app.auth.getContainer('apps/primary'); // Might exit here
    const nameAndTag = await md.getNameAndTag().typeTag;
    console.log('2: ', nameAndTag);
})();

I get the same outcome whether or not setTimeout is commented out. nameAndTag will always be undefined because typeTag is not a property of the Promise.

(async () => {
    const info = { id: 'primary', name: 'Primary App', vendor: '1' };

    const app = await safeApp.initialiseApp(info);
    await app.auth.loginForTest({}, { own_container: true });

    console.log('1: still here');
    const md = await app.auth.getContainer('apps/primary'); // Might exit here
    const nameAndTag = await md.getNameAndTag();
    console.log('2: ', nameAndTag.typeTag);
})();

run fine every time.

By the way, I'm running at commit e818f8a

[hunterlester]

Although I see that I may simply not be able to reproduce the behavior in your environment.
So, is the last console.log never called?
What happens if you log the md variable?

In my above example, I was running that code in the node repl.
How are you running the code?

[b-zee]

Thanks for looking at the issue!

How are you running the code?

The code is put in a file called index.js and run in a shell with Node.js:

$ NODE_ENV=dev node index.js

By the way, I'm running at commit e818f8a

I have installed the latest from npmjs.com, which is 0.8.1.

The example code gives the following output (with setTimeout included):

$ NODE_ENV=dev node index.js
1: still here
2: 15000
callback

And without the setTimeout line:

$ NODE_ENV=dev node index.js
1: still here

I think it's simply that type_tag is not a property of the promise.

That's correct, but that's not what the code does (mind the parentheses): (await md.getNameAndTag()).type_tag. The type_tag is accessed as a property from the return value from the Promise, which is a NameAndTag. The example code is fine, there are no errors. It's written according the docs and according to how Promises work.

The issue here is that the Node.js script does not error but somehow exits without waiting for the promise. A couple of hours ago I started to think this is also the reason that people on the SAFE Dev forum encounter situations where the output is not what it is expected to be, without errors:

• southside: "Run 3 did not have the req’d text"
• nice: "I just tested, indeed sometimes, about 1 of 5, the readable part of the output is missing"
• davidpbrown: " though what I see is different each time… sometimes it sees all of this result, other times part of it."

I've looked into it a bit past few weeks but given up. It seems some calls just cause the Node.js script to exit. The takeaway here is that there are no errors!

[happybeing]

@b-zee I tried

NODE_ENV=dev node index.js

And it error'd, so I thought maybe I wasn't doing it right. Anyway, here's what I get:

1: still here
2: [object Object]
thread '<unnamed>' panicked at '

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!   unwrap! called on Result::Err                                              !
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
safe_app/src/test_utils.rs:89,23 in safe_app::test_utils

Err(
    Unexpected(
        "\'apps/primary\' not found in the access container"
    )
)

', /home/travis/.cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/unwrap-1.1.0/src/lib.rs:67:24
note: Run with `RUST_BACKTRACE=1` for a backtrace.
(node:6430) UnhandledPromiseRejectionWarning: -2000: Unexpected (probably a logic error): panic
    at module.exports (/home/mrh/src/play/benno-test/node_modules/@maidsafe/safe-node-app/src/native/_error.js:19:10)
    at args.push.ffi.Callback.restArgs (/home/mrh/src/play/benno-test/node_modules/@maidsafe/safe-node-app/src/native/_base.js:92:27)
    at /home/mrh/src/play/benno-test/node_modules/ffi/lib/callback.js:66:25
    at proxy (/home/mrh/src/play/benno-test/node_modules/ffi/lib/_foreign_function.js:59:14)
    at Promise (/home/mrh/src/play/benno-test/node_modules/@maidsafe/safe-node-app/src/native/_base.js:110:5)
    at new Promise (<anonymous>)
    at callLibFn (/home/mrh/src/play/benno-test/node_modules/@maidsafe/safe-node-app/src/native/_base.js:85:10)
    at Promise (/home/mrh/src/play/benno-test/node_modules/@maidsafe/safe-node-app/src/native/_base.js:201:18)
    at new Promise (<anonymous>)
    at Object.varArgs [as test_create_app_with_access] (/home/mrh/src/play/benno-test/node_modules/@maidsafe/safe-node-app/src/native/_base.js:188:16)
(node:6430) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2)
(node:6430) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Using:

$ node --version
v8.10.0

[b-zee]

@theWebalyst

That seems like a different issue. Maybe worth making another issue from @hunterlester?

I actually think that's the issue which I reported on the SAFE Dev forum: https://forum.safedev.org/t/loginfortest-with-two-apps/1752?u=bzee

[hunterlester]

@b-zee Ah I see now, thank you.
Tracking so it doesn't fall off of our radar: https://maidsafe.atlassian.net/browse/MAID-2840

[b-zee]

Great! Hope it will be picked up soon, seems like a critical issue. Might cause all kinds of seemingly random behaviour in apps.

[bochaco]

I wasn't able to reproduce this exactly as reported, I'm using node v8.11.1, and this is what I'm experiencing wither with safe_app_nodejs v0.8.1 or with commit e818f8a:

• if the timeout is set, everything works fine and the process exists right after the timer went off
• if the timeout is not set, everything is works fine, but sometimes the process doesn't end

[b-zee]

if the timeout is not set, everything is works fine, but sometimes the process doesn't end

Does it just never return the getContainer? That sounds like a different issue then.

I am using the same Node.js version. I have tested this on Windows 10 by the way.

[bochaco]

It always returns the getContainer for me, what it doesn't end sometimes is the main process after it executed all. I'm using Linux.

[joshuef]

Aha, I knew I'd seen this somewhere.

I've just come across this when trying to write immutable data.

https://github.com/joshuef/poc-safe-cli/blob/master/src/upload/handleFileUpload.js#L37-L49

    const data = await fs.readFileSync( theFilePath ).toString();

    const writer = await app.immutableData.create()

    // TODO: Why is this needed?
    delay( 2000 )
    await writer.write( data )

    // almost never reaches here. <----

    const cipher = await app.cipherOpt.newPlainText();
    const mimeType = 'text/plain';
    const address= await writer.close( cipher, true, mimeType );

Again, without a delay, this mostly just exits (occasionally will pass).

I've dug around extensively checking await order, etc. Everything is being returned as a promise as it should be. But still exits abound. I'd reached a similar conclusion to @b-zee that this is likely somewhere in the FFI layer.

FWIW I've encountered it on MacOS and Ubuntu 18. This test case seems pretty reliable.