Possible bug with messages

[ColtonMcInroy]

I have been troubleshooting a bug for the past bit now and not sure if it is an issue with Flow, Total4, or my own code.

I have a Code component with two outputs (I'm actually using the Multiplexer version of the Code component so I can use named outputs). I'm using it to handle an aspect to GraphQL resolver processing for some context. Here is the code in the component...

function replacer(obj, path = []) {
    for (const key in obj) {
        const currentPath = path.concat(key);
        const resPath = currentPath.join('.');
        if (obj[key] === true) {
            obj[key] = async (_parent, _args, _context, _info) => {
                // console.log('BLAH!');
                // console.log('Resolver:', currentPath.join('.'));
                return await new Promise((resolve, reject) => {
                    const msg = instance.newmessage({
                        path: resPath,
                        parent: _parent,
                        args: _args,
                        context: _context,
                        info: _info
                    });
                    msg.refs.originalMessage = $;
                    msg.refs.controller = $.refs.controller;
                    msg.repo = $.repo;
                    msg.on('end', (msg) => {
                        console.log('Resolved:', resPath, JSON.stringify(msg.data));
                        // console.log('Resolved:', currentPath.join('.'));
                        resolve(msg.data);
                    });
                    // msg.on('terminate', (msg) => {
                        // console.log('Terminate:', currentPath.join('.'), JSON.stringify(msg.data));
                    // });
                    console.log('Resolver:', resPath, msg.data);
                    msg.send('resolver', {
                        path: resPath,
                        parent: _parent,
                        args: _args,
                        context: _context,
                        info: _info
                    });
                });
            };
        }
        else if (obj[key] === false) {
            obj[key] = () => ({});
        }
        else if (typeof obj[key] === 'object') {
            replacer(obj[key], currentPath);
        }
    }
    return { obj, path };
}
data = replacer(data);

$.send('output', data.obj);

When a message comes into this component it parses the data converting true/false values recursively into functions. The function is then used by a GraphQL engine (Envelop) to be executed. When the GraphQL engine goes to execute the resolver functions it will end up running the above promise which creates a new message and upon that message ending returns the data as the resolved response.

This actually works fine for any requests that process synchronously but it appears that when multiple resolvers execute at the same time in parallel rather than series a bug appears. I have done some tracking down to see if I could find the cause in my code, but thus far have been unable to blame it on myself or the Envelop GraphQL engine.

So the problem that occurs is when the resolvers execute, when it is just in series they execute perfectly fine. When there are any parallel resolvers executed the message processing appears to become conflicted and responds incorrectly.

Here is an example...

Executing
Waiting on Execute
Resolver: Query.AppTable
Resolved: Query.AppTable {"TableNames":["AppTable","AppTableField"],"Tables":[{"name":"AppTable","plural":"AppTables","description":"Application Table","type":"AppTable","database":"Mongo"},{"name":"AppTableField","plural":"AppTableFields","description":"Application Table for Fields","type":"AppTableField","database":"Mongo"}],"Table":{"name":"AppTable","plural":"AppTables","description":"Application Table","type":"AppTable","database":"Mongo"},"Fields":[{"name":"_id","description":"Unique ID for Table","type":"ObjectID","required":true},{"name":"name","description":"Name of Table","type":"String","required":true},{"name":"plural","description":"Plural name of Table (Must be different from name)","type":"String","required":true},{"name":"description","description":"Description of Table","type":"String","required":true},{"name":"type","description":"Type of Table","type":"AppTableType","required":true},{"name":"database","description":"Database to store data on for this Table","type":"AppTableDatabase","required":true},{"name":"fields","description":"Fields associated with this Table","type":"AppTableField","required":true,"array":true}]}
Resolver: AppTableQueries.find
Resolved: AppTableQueries.find {"success":true,"data":[{"_id":"63e30fe428509b7d955b77b8","name":"Test","plural":"Tests","type":"Model","description":"Changed Desc 2","database":"Mongo"},{"_id":"63f949bc582cebdc0884b2d1","name":"Job","plural":"Jobs","description":"Job Description","type":"Model","database":"Mongo"}],"meta":{"page":0,"total":2,"dbTime":0.003,"totalTime":0.1}}
Execute Response: {
  data: [Object: null prototype] {
    __typename: 'Query',
    AppTable: [Object: null prototype] { find: [Object: null prototype] }
  }
}

This is some debug output that I produced to see what is going on. This is a successful execution of the query...

query Query {
  AppTable {
    find {
      success
    }
  }
}

To explain the debug output when "Waiting on Execute" occurs the GraphQL engine runs and starts executing the resolvers. The code from the above component executes and outputs the lines starting with "Resolver" and "Resolved" showing what resolver it is trying to run and then the response of that resolver. The response of the resolver is obtained from the msg.on('end',...) call executing resolve().

Now the problems occurs when you do anything that causes parallel execution of resolvers... for example...

query Query {
  AppTable {
    find {
      success
    }
  }
  AppTableField {
    find {
      success
    }
  }
}

This is where things mess up. The first resolver triggers the message to send, and I can see the message does indeed get sent out and get processed as expected. The msg.on('end', ...) even does not appear to trigger though for the first resolver. The second resolver gets executed and the msg.on('end', ...) does trigger but gets the msg data from the first resolver that was executed. This then appears to continue from that point on causing each following resolver to get the result of the previous instead of the expected result. At the end 2 additional msg.on('end', ...) appear to execute but the first one has the result of the previous resolver and the last one is just a copy of it.

Executing
Waiting on Execute
Resolver: Query.AppTable
Resolver: Query.AppTableField
Resolved: Query.AppTableField {"TableNames":["AppTable","AppTableField"],"Tables":[{"name":"AppTable","plural":"AppTables","description":"Application Table","type":"AppTable","database":"Mongo"},{"name":"AppTableField","plural":"AppTableFields","description":"Application Table for Fields","type":"AppTableField","database":"Mongo"}],"Table":{"name":"AppTable","plural":"AppTables","description":"Application Table","type":"AppTable","database":"Mongo"},"Fields":[{"name":"_id","description":"Unique ID for Table","type":"ObjectID","required":true},{"name":"name","description":"Name of Table","type":"String","required":true},{"name":"plural","description":"Plural name of Table (Must be different from name)","type":"String","required":true},{"name":"description","description":"Description of Table","type":"String","required":true},{"name":"type","description":"Type of Table","type":"AppTableType","required":true},{"name":"database","description":"Database to store data on for this Table","type":"AppTableDatabase","required":true},{"name":"fields","description":"Fields associated with this Table","type":"AppTableField","required":true,"array":true}]}
Resolver: AppTableFieldQueries.find
Resolved: AppTableFieldQueries.find {"TableNames":["AppTable","AppTableField"],"Tables":[{"name":"AppTable","plural":"AppTables","description":"Application Table","type":"AppTable","database":"Mongo"},{"name":"AppTableField","plural":"AppTableFields","description":"Application Table for Fields","type":"AppTableField","database":"Mongo"}],"Table":{"name":"AppTableField","plural":"AppTableFields","description":"Application Table for Fields","type":"AppTableField","database":"Mongo"},"Fields":[{"name":"_id","description":"Unique ID for Table Field","type":"ObjectID","required":true},{"name":"appTable","description":"Name of Table which Field is associated with","type":"AppTable","required":true},{"name":"name","description":"Name of Table Field","type":"String","required":true},{"name":"description","description":"Description of Table Field","type":"String","required":true},{"name":"type","description":"Type of Table Field","type":"AppTableFieldType","required":true},{"name":"options","description":"Options associated with Table Field Type","type":"JSON","required":false},{"name":"unique","description":"Boolean flag to specify if this value should be unique","type":"Boolean","required":false,"default":false},{"name":"array","description":"Boolean flag to specify if this value should be an array","type":"Boolean","required":false,"default":false},{"name":"required","description":"Boolean flag to specify if this value is required","type":"Boolean","required":false,"default":false},{"name":"default","description":"Default value for Table Field when creating new record","type":"JSONObject","required":false}]}
Resolved: AppTableFieldQueries.find {"success":true,"data":[{"_id":"63f554c82c4914959404e7d9","appTable":"63e30fe428509b7d955b77b8","name":"Name","description":"Name description","type":"String","unique":false,"array":false,"required":false},{"_id":"63f94c64582cebdc0884b2d2","appTable":"63f949bc582cebdc0884b2d1","name":"Name","description":"Name description","type":"String","required":true}],"meta":{"page":0,"total":2,"dbTime":0.003,"totalTime":0.118}}
Resolved: AppTableFieldQueries.find {"success":true,"data":[{"_id":"63f554c82c4914959404e7d9","appTable":"63e30fe428509b7d955b77b8","name":"Name","description":"Name description","type":"String","unique":false,"array":false,"required":false},{"_id":"63f94c64582cebdc0884b2d2","appTable":"63f949bc582cebdc0884b2d1","name":"Name","description":"Name description","type":"String","required":true}],"meta":{"page":0,"total":2,"dbTime":0.003,"totalTime":0.118}}

Because the resolvers are actually executing and the "Resolver:" debug line is outputting as expected and the debugging I have done I cannot see any problem the the actual execution of all code surrounding the message handling but rather the problem appears to be with the message processing itself in the following lines...

const msg = instance.newmessage({
        path: resPath,
        parent: _parent,
        args: _args,
        context: _context,
        info: _info
    });
    msg.refs.originalMessage = $;
    msg.refs.controller = $.refs.controller;
    msg.repo = $.repo;
    msg.on('end', (msg) => {
        console.log('Resolved:', resPath, JSON.stringify(msg.data));
        // console.log('Resolved:', currentPath.join('.'));
        resolve(msg.data);
    });
    // msg.on('terminate', (msg) => {
        // console.log('Terminate:', currentPath.join('.'), JSON.stringify(msg.data));
    // });
    console.log('Resolver:', resPath, msg.data);
    msg.send('resolver', {
        path: resPath,
        parent: _parent,
        args: _args,
        context: _context,
        info: _info
    });

The variable resPath is a constant generated in a for loop outside of these lines. When ever this code executes, there should be a debug line starting with "Resolver: Some.Path" accompanied by a line starting with "Resolved: Some.Path". If I test this in a simple test environment it works fine all day long. This leads me to believe that there is something in the flow stream handling which appears to be mixing up events or messages.

Am I correct in thinking that this is a discovered bug?

[ColtonMcInroy]

I was incorrect, it was due to a bug with another interconnected component down the chain that I created. Spent some more time looking into it today and figured it out.

[ColtonMcInroy]

Just a note that the reason the other component ended up having a bug was because the message id does not seem to get set which is something I depended on assuming that it would always be set and always be unique (created during the newmessage() call) but that doesn't appear to be the case. I am seeing it undefined and even if I create a message then set msg.id = GUID() before sending the message the message id still appears undefined in when examined from the next component. The component is used to work with BullMQ which holds onto the message while the data gets processed and then sends the message to output once the BullMQ job has completed. I was queuing the messages in an object like so...

messages[$.id] = $;

Because $.id is actually undefined obviously this causes a problem. So currently what I am doing is checking if $.id is undefined and setting it to GUID() when it is. This works fine for my case as all I need is a unique identifier and generating it myself is not a problem... but perhaps $.id being undefined is an actual bug that should be addressed or perhaps it is intended for a different purpose that I cannot tell from the documentation.

With these details, I'll re-open the ticket and leave it up to you to determine if this is a bug... a lack of documentation explaining id reasoning for being undefined or something else.

[Will-create]

@ColtonMcInroy You should not expect to have msg.id or $.id because it does not have Unique identifier

[ColtonMcInroy]

@Will-create According to the documentation...

The property contains a unique identifier for this message.

flowmessage.id;
// returns String;

If this is no longer correct or some details in regards to this are missing could you update the documentation?

[Will-create]

@ColtonMcInroy Yes, documentation should be updated. I thank you. Thanks alot