Error: callback timed out ... why?

dhoyt · April 30, 2018, 2:32pm

I am iterating a collection using newman.run within a Node javascript.

Here is my newman.run statement …

newman.run({
    environment : ENVIRONMENT_PATH,
    collection : require(collectionFile),
    iterationData : DATAFILE_PATH,
    iterationCount : dataIterations,
    timeoutRequest : 3600000, // 60 minute timeout
    bail : false,
    color : true,
    //reporters : ['cli','json'],
    reporters : ['json'],
    reporter :  {
        //'cli' : { 'noSummary': true, 'noFailures': true, 'noConsole': true },
        json : { export : EXPORT_FILE }
    }
})

I am also using .on(‘done’, function (err, summary) to catch any errors

.on('done', function (err, summary) {
    if (err || summary.error) {
        showIt(' ');
        showIt(err,'-r');
        showIt('Collection run encountered an error.','-r');
    }
})

During an iteration, I will occasionally get …

Error: callback timed out
Collection run encountered an error.

The collection that was running stops and then the newman.run execution will iterated and run the collection again.

I don’t have a problem with newman continuning with the iterations. What I want to understand is why I am getting a “timed out” error when I have … timeoutRequest : 3600000, // 60 minute timeout

dhoyt · May 6, 2018, 8:57pm

@abhijit

I am surprised that I have not gotten any type of response to my question.

deepak.pathania · May 7, 2018, 9:46am

Hey @dhoyt, my apologies for the delayed response, this might have been missed by mistake.

The behaviour you have specified happens when the global timeout is breached which shouldn’t be the case considering the huge timeoutRequest, do you mind sharing the collection for which this behaviour happens?

Also, bail now accepts optional modifiers in case you want to alter the behaviour on encountering errors.

I am looping in @kunagpal here who might have additional insight. We’ll try and resolve this asap for you.

dhoyt · May 7, 2018, 2:16pm

@deepak.pathania

Thank you for the response .I don’t want to share my collection in the public forum. Is this an email address that I can send it to ?

dhoyt

claire · May 7, 2018, 4:26pm

Hi @dhoyt! Please submit it as a request via our Help Center and we’ll connect you.

dhoyt · May 7, 2018, 4:38pm

@claire

Done … subject is the same as this subject.

Thanks !

xsedlak · June 19, 2018, 9:38am

Hello, I have the same error when I’m executing Regression Tests group - 23 collections in sequentially.
It works correctly before some time. I didn’t change environment, or version below but now I have the problem which is described below.

It happened randomly for different collections for different requests.
It looks that it can be a performance issue.
Do you have a fix for the issue or WA? Should I restart the RT virtual machine?
Thank you and best regards,
Mira

NODEJS: v8.11.2
NEWMAN: 3.9.3
TIMEOUT: newman.run({
…
timeout: 600000 // Timeouts in ms: 10 minutes
} …
ERROR: 00:31:17.457 Error: callback timed out
00:31:17.457 at Timeout._onTimeout (/usr/lib/node_modules/newman/node_modules/postman-runtime/lib/backpack/index.js:149:46)
00:31:17.457 at ontimeout (timers.js:498:11)
00:31:17.457 at tryOnTimeout (timers.js:323:5)
00:31:17.457 at Timer.listOnTimeout (timers.js:290:5)

dhoyt · June 25, 2018, 12:17pm

@claire @abhijit @deepak.pathania @kunagpal

How can you close the help ticket that I created without providing me any type of response/resolution ?

claire · June 25, 2018, 8:28pm

@dhoyt - my apologies this was a miscommunication on our end. I’ve reopened for @kunagpal and @deepak.pathania.

kunagpal · July 5, 2018, 7:31pm

@dhoyt @xsedlak I’m really sorry about the radio silence on this. We’ve recently released Newman v3.10.0, could you update to this version and confirm if the error still persists on Node v8.11.3?

@dhoyt Could you also add a timeoutScript option with an appropriately high value to your newman.run file? This is merely a precautionary measure.

Also, could you run the collection as follows:

NODE_DEBUG=request node path/to/newman/run.file.js > newman-timeout.log

Once this command has completed, newman-timeout.log will contain verbose Newman run output that might help us isolate the exact cause of this issue. Could you share this file privately? (Feel free to redact sensitive information)

dhoyt · July 5, 2018, 8:17pm

Thank you for the response …

The Node version I have been running is …

C:\curmusic\Git\curmusic-testing\curmusic_postman\regression\run_regressions>node -v

v9.5.0

I did just upgrade newman at your request to …

C:\curmusic\Git\curmusic-testing\curmusic_postman\regression\run_regressions>newman -v

3.10.0

I am now re-running my node javascript now to see if I get the error.

Here is my newman run command that I have been running since I started receiving the error …

// run newman

newman.run({

environment : ENVIRONMENT_PATH,

collection : require(collectionFile),

iterationData : datafile_path,

iterationCount : dataIterations,

timeoutRequest : 3600000, // 60 minute timeout

insecure : true,

bail : false,

color : true //,

//reporters : [‘cli’,‘json’],

//reporters : [‘json’],

//reporter : {

//‘cli’ : { ‘noSummary’: true, ‘noFailures’: true, ‘noConsole’: true },

//json : { export : EXPORT_FILE }

//}

})

As you can see, I have specified a really long timeout request period, yet I still get the message.

I’m not quite sure what you want me to do with this …

NODE_DEBUG=request node path/to/newman/run.file.js > newman-timeout.log

Where/how would I execute this in a windows command prompt ?

Thanks … Dick Hoyt

Dick Hoyt
dhoyt@curmusic.com

kunagpal · July 5, 2018, 8:22pm

For a windows command prompt, you can use the following:

set NODE_DEBUG=request
node path/to/newman/run.file.js >

Here, the first command sets an environment variable that causes Newman to provide additional debugging output. The second command is meant to run a script that contains your newman.run code. The > ... at the end of this statement will redirect all Newman output to a file called newman-timeout.log, which you can then inspect for further debugging. Hope that clarifies things

xsedlak · July 5, 2018, 9:06pm

Hello Kunagpal,
I’m sorry but now I have holiday. I will check it next wednesday at work.

Thank you and best regards,

xsedlak

kunagpal · July 16, 2018, 11:34am

@dhoyt A quick update, the default global timeout for collection runs is 3 minutes, as can be seen here: https://github.com/postmanlabs/postman-runtime/blob/develop/lib/runner/index.js#L9.

The global timeout is the time wait applied for the entire collection run to complete. In addition, the timeout for each request is picked as the smaller value among global and request specific timeouts. The same logic applies to script timeouts.

Could you explicitly set options.timeout to 0 (this implies Infinity)? This will effectively force Newman to wait for all requests and scripts to complete.

EDIT:
All of these behavioural details could be documented better

dhoyt · July 16, 2018, 1:40pm

Thanks for the response kunagpal !

Here is my run command … how would I apply that it ?

newman.run({

environment : ENVIRONMENT_PATH,

collection : require(collectionFile),

iterationData : datafile_path,

iterationCount : dataIterations,

timeoutRequest : 3600000, // 60 minute timeout

insecure : true,

bail : false,

color : true //,

//reporters : [‘cli’,‘json’],

//reporters : [‘json’],

//reporter : {

//‘cli’ : { ‘noSummary’: true, ‘noFailures’: true, ‘noConsole’: true },

//json : { export : EXPORT_FILE }

//}

})

Dick Hoyt
dhoyt@curmusic.com

kunagpal · July 16, 2018, 1:56pm

@dhoyt You’ll have to set the value of the timeout key in the above example to an appropriate millisecond value. You can explicitly set it to the number 0 to force an infinitely large timeout value.

dhoyt · July 16, 2018, 3:33pm

kunagpal …

As you can see below, I set the timeout to 0 but the following copy of my console output still reports the timeout error …

// run newman

newman.run({

environment : ENVIRONMENT_PATH,

collection : require(collectionFile),

iterationData : datafile_path,

iterationCount : dataIterations,

timeoutRequest : 0, // infinite timeout

insecure : true,

bail : false,

color : true //,

//reporters : [‘cli’,‘json’],

//reporters : [‘json’],

//reporter : {

//‘cli’ : { ‘noSummary’: true, ‘noFailures’: true, ‘noConsole’: true },

//json : { export : EXPORT_FILE }

//}

})

VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVvvvv

Creating Track Station : Nice For What : 2 of 20

Searched for > Nice For What < by Drake

Found track. > Nice For What < position (0) : trackId : 3039806751 : artistId : 1000123723 : artistName : Drake

…

Processed 135 tracks - Searched for artistId : 1000123723 - 4 tracks found

Accepted popularity is >= 0.1

Min % of tracks by the Artist in the playlist = 25

Min % of tracks that are “popular” in the playlist = 85

dhoyt · July 18, 2018, 6:42pm

kunapal …

Sorry for my confusion. I have ADDED timeout : 0 to my run command and after a couple of initial tests, it appears that the timeout is not occurring in the usual sequence that it has been appearing during my collection runs.

I will continue to observe but at this point, I believe that you can close this issue. If it does occur again, I will submit another ticket.

Thanks so much for you attention into this matter …

Dick Hoyt
dhoyt@curmusic.com

kunagpal · July 19, 2018, 7:52am

@dhoyt Thanks a lot for clearing that up, this is an excellent opportunity to improve our docs around this.