[JBEHAVE-1037] Story duration timeout occurs for not started story - jira.codehaus.org

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 3.9.4
Component/s: Core
Labels:
None

Number of attachments :
0

Description

Some time (useStoryTimeoutInSecs) after starting my tests web browser is closed with warning" [WARNING] Story com/sample/qa/stories/login.story duration of 101 seconds has exceeded timeout of 100 seconds".
No one executed story exceed this time. This is even before "login.story" execution. The clue is that the story contains all @Before and @After methods. The story is executed as one of last (stories are independent so this is not a problem). So looks like timer is started for the story not in situation where story execution is started but when @BeforeStories from that story is run for first executed story.
As a hook I exceeded useStoryTimeoutInSecs very much (for length of all my stories execution), but in that case I am loosing mechanism for verifying story execution time.
I am using following JBehave versions:
<jbehave.core.version>4.0-beta-9</jbehave.core.version>
<jbehave.site.version>3.2</jbehave.site.version>

Activity

Przemyslaw Kwiecien made changes - 14/Aug/14 9:00 AM

Field	Original Value	New Value
Description	Some time (useStoryTimeoutInSecs) after starting my tests web browser is closed with warning" [WARNING] Story com/sample/qa/stories/login.story duration of 101 seconds has exceeded timeout of 100 seconds". No one executed story exceed this time. This is even before "login.story" execution. The clue is that the story contains all @Before and @After methods. The story is executed as one of last (stories are independent so this is not a problem). So looks like timer is started for the story not in situation where story execution is started but when @BeforeStories from that story is run for first executed story. As a hook I exceeded useStoryTimeoutInSecs very much (for length of all my stories execution), but in that case I am loosing mechanism for verifying story execution time.	Some time (useStoryTimeoutInSecs) after starting my tests web browser is closed with warning" [WARNING] Story com/sample/qa/stories/login.story duration of 101 seconds has exceeded timeout of 100 seconds". No one executed story exceed this time. This is even before "login.story" execution. The clue is that the story contains all @Before and @After methods. The story is executed as one of last (stories are independent so this is not a problem). So looks like timer is started for the story not in situation where story execution is started but when @BeforeStories from that story is run for first executed story. As a hook I exceeded useStoryTimeoutInSecs very much (for length of all my stories execution), but in that case I am loosing mechanism for verifying story execution time. I am using following JBehave versions: <jbehave.core.version>4.0-beta-9</jbehave.core.version> <jbehave.site.version>3.2</jbehave.site.version>

Hide

Permalink

Mauro Talevi added a comment - 15/Aug/14 8:12 AM

Does this occur with 3.9.x as well?

Show

Mauro Talevi added a comment - 15/Aug/14 8:12 AM Does this occur with 3.9.x as well?

Hide

Permalink

Mauro Talevi added a comment - 16/Aug/14 11:15 AM

Is the time spent in the @Before methods such that it could account for the timeout?

From the execution point of view, a story duration also includes all before and after steps, so if the before steps take a long time the "story" itself may not start at all.

Could you please provide a sample project that reproduces this behaviour?

Show

Mauro Talevi added a comment - 16/Aug/14 11:15 AM Is the time spent in the @Before methods such that it could account for the timeout? From the execution point of view, a story duration also includes all before and after steps, so if the before steps take a long time the "story" itself may not start at all. Could you please provide a sample project that reproduces this behaviour?

Hide

Permalink

Przemyslaw Kwiecien added a comment - 18/Aug/14 4:45 AM

Hi Mauro,
thank you for your fast response.
Issue occurs in 3.9.3 also.
I prepared sample project reproducing issue - https://github.com/przemekkwiecien1982/jbehave-issues.git
During preparation I noticed that issue occurs only if stories are run from IDE (Idea in my case). Test run from maven is not affected by the issue, so severity is not so high as I originally though.

Please run TimeoutStories to reproduce issue.

Timeout after 16 s

2014-08-18 11:35:29,413  INFO [main] - Log initialized 
Processing system properties {}
Using controls EmbedderControls[batch=false,skip=false,generateViewAfterStories=true,ignoreFailureInStories=false,ignoreFailureInView=true,verboseFailures=false,verboseFiltering=false,storyTimeoutInSecs=15,failOnStoryTimeout=false,threads=1]

(BeforeStories)
2014-08-18 11:35:29,571  INFO [main] - BeforeStories from LoginSteps performed 

Running story defects/stories/timeout/dummy1.story

(defects/stories/timeout/dummy1.story)
2014-08-18 11:35:29,583  INFO [pool-1-thread-1] - BeforeStory from LoginSteps performed 
Scenario: Dummy scenario - dummy1.story
2014-08-18 11:35:29,584  INFO [pool-1-thread-1] - Given dummy lasts 5s started 
2014-08-18 11:35:34,586  INFO [pool-1-thread-1] - Given dummy lasts 5s finished 
Given Given dummy lasts 5s
2014-08-18 11:35:34,589  INFO [pool-1-thread-1] - When dummy lasts 5s started 
2014-08-18 11:35:39,590  INFO [pool-1-thread-1] - When dummy lasts 5s finished 
When When dummy lasts 5s
Then Then dummy

2014-08-18 11:35:39,599  INFO [pool-1-thread-1] - AfterStory from LoginSteps performed 

Running story defects/stories/timeout/dummy2.story

(defects/stories/timeout/dummy2.story)
2014-08-18 11:35:39,622  INFO [pool-1-thread-1] - BeforeStory from LoginSteps performed 
Scenario: Dummy scenario - dummy2.story
2014-08-18 11:35:39,624  INFO [pool-1-thread-1] - Given dummy lasts 5s started 
2014-08-18 11:35:44,625  INFO [pool-1-thread-1] - Given dummy lasts 5s finished 
Given Given dummy lasts 5s
2014-08-18 11:35:44,628  INFO [pool-1-thread-1] - When dummy lasts 5s started 
Story defects/stories/timeout/login.story duration of 16 seconds has exceeded timeout of 15 seconds
2014-08-18 11:35:45,783  INFO [pool-1-thread-1] - When dummy lasts 5s finished 
When When dummy lasts 5s
Then Then dummy

2014-08-18 11:35:45,791  INFO [pool-1-thread-1] - AfterStory from LoginSteps performed 

(AfterStories)
2014-08-18 11:35:45,794  INFO [main] - AfterStories from LoginSteps performed

I agree with you that @Before methods duration should be included in story time. But my issue is related with the fact that in case of running test from IDE "login.story" timer is probably started during execution of "dummy1.story" (because dummy.story uses @Before method from login.story).

Show

Przemyslaw Kwiecien added a comment - 18/Aug/14 4:45 AM Hi Mauro, thank you for your fast response. Issue occurs in 3.9.3 also. I prepared sample project reproducing issue - https://github.com/przemekkwiecien1982/jbehave-issues.git During preparation I noticed that issue occurs only if stories are run from IDE (Idea in my case). Test run from maven is not affected by the issue, so severity is not so high as I originally though. Please run TimeoutStories to reproduce issue. Timeout after 16 s 2014-08-18 11:35:29,413 INFO [main] - Log initialized Processing system properties {} Using controls EmbedderControls[batch= false ,skip= false ,generateViewAfterStories= true ,ignoreFailureInStories= false ,ignoreFailureInView= true ,verboseFailures= false ,verboseFiltering= false ,storyTimeoutInSecs=15,failOnStoryTimeout= false ,threads=1] (BeforeStories) 2014-08-18 11:35:29,571 INFO [main] - BeforeStories from LoginSteps performed Running story defects/stories/timeout/dummy1.story (defects/stories/timeout/dummy1.story) 2014-08-18 11:35:29,583 INFO [pool-1-thread-1] - BeforeStory from LoginSteps performed Scenario: Dummy scenario - dummy1.story 2014-08-18 11:35:29,584 INFO [pool-1-thread-1] - Given dummy lasts 5s started 2014-08-18 11:35:34,586 INFO [pool-1-thread-1] - Given dummy lasts 5s finished Given Given dummy lasts 5s 2014-08-18 11:35:34,589 INFO [pool-1-thread-1] - When dummy lasts 5s started 2014-08-18 11:35:39,590 INFO [pool-1-thread-1] - When dummy lasts 5s finished When When dummy lasts 5s Then Then dummy 2014-08-18 11:35:39,599 INFO [pool-1-thread-1] - AfterStory from LoginSteps performed Running story defects/stories/timeout/dummy2.story (defects/stories/timeout/dummy2.story) 2014-08-18 11:35:39,622 INFO [pool-1-thread-1] - BeforeStory from LoginSteps performed Scenario: Dummy scenario - dummy2.story 2014-08-18 11:35:39,624 INFO [pool-1-thread-1] - Given dummy lasts 5s started 2014-08-18 11:35:44,625 INFO [pool-1-thread-1] - Given dummy lasts 5s finished Given Given dummy lasts 5s 2014-08-18 11:35:44,628 INFO [pool-1-thread-1] - When dummy lasts 5s started Story defects/stories/timeout/login.story duration of 16 seconds has exceeded timeout of 15 seconds 2014-08-18 11:35:45,783 INFO [pool-1-thread-1] - When dummy lasts 5s finished When When dummy lasts 5s Then Then dummy 2014-08-18 11:35:45,791 INFO [pool-1-thread-1] - AfterStory from LoginSteps performed (AfterStories) 2014-08-18 11:35:45,794 INFO [main] - AfterStories from LoginSteps performed I agree with you that @Before methods duration should be included in story time. But my issue is related with the fact that in case of running test from IDE "login.story" timer is probably started during execution of "dummy1.story" (because dummy.story uses @Before method from login.story).

Hide

Permalink

Mauro Talevi added a comment - 24/Aug/14 4:00 PM

Fixed by ~~JBEHAVE-1041~~.

Show

Mauro Talevi added a comment - 24/Aug/14 4:00 PM Fixed by JBEHAVE-1041 .

Mauro Talevi made changes - 24/Aug/14 4:00 PM

Resolution		Fixed [ 1 ]
Assignee		Mauro Talevi [ maurotalevi ]
Status	Open [ 1 ]	Resolved [ 5 ]

Mauro Talevi made changes - 24/Aug/14 4:00 PM

Fix Version/s

3.9.4 [ 20449 ]

People

Assignee:

Mauro Talevi

Reporter:

Przemyslaw Kwiecien

Votes:

0 Vote for this issue

Watchers:

2 Start watching this issue

Dates

Created:

14/Aug/14 8:56 AM

Updated:

24/Aug/14 4:00 PM

Resolved:

24/Aug/14 4:00 PM