PRN comment trigger isn't firing sometimes

[mondayges]

One of our users encountered an issue where the plugin seems to work sometimes by commenting on a pull request to trigger a build on their jenkins instance. Enabling the debug on our logs, we found this:

• Around 3:04pm where the plugin was able to detect the comment in the pull request to trigger an event: 2018-05-25 15:04:33,673 DEBUG [AtlassianEvent::thread-1] dk068x *BLY4IOx904x10732665x8 1ahxn0w 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: PullRequestActivityNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 15:04:33 EDT 2018, pullRequest=cartms:715, activity=InternalPullRequestCommentActivity{id=6674620, user=InternalNormalUser{id=758, username=dk068x}, action=COMMENTED, pullRequest.id=715, commentAction=ADDED, comment=InternalComment{id=334665, author=InternalNormalUser{id=758, username=dk068x}, text=This is a test.}}}

• Around 18:34pm where the plugin was not able to detect the comment in the pull request to trigger an event: 2018-05-25 18:34:41,144 DEBUG [AtlassianEvent::thread-10] dk068x *BLY4IOx1114x10878328x4 jwg1an 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: GeneralCommentAddedNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 18:34:41 EDT 2018, pullRequest=cartms:715, comment=InternalComment{id=334697, author=InternalNormalUser{id=758, username=dk068x}, text=Another test.}}

A button was also created to verify that the plugin works when the comment trigger is not working. Is there any a reason that our second test found in the log seems to not call the PRN plugin as opposed to our first test case?

• Plugin version used: 2.67
• Bitbucket Server version used: 4.9.0
• Stack traces in Bitbucket Server log file (Attached the log traces for the first and second case) 1st_case_log_trace.txt 2nd_case_log_trace.txt

[tomasbjerre]

No I cant see anything suspicios in those logs.

[mondayges]

Though how can we explain that the plugin seems not to be called on the second case?

[tomasbjerre]

How did you configure the plugin? Is this repeatable? Does it never work? Or is it random? Does it work if you comment several times in a row? If you comment with a few hours between comments? ...

[davidmichaelkarr]

I'm the user who reported the problem. I'll try to address your questions from my POV.

I'm not sure what "configure the plugin" means. If that refers to something that only a system admin can do, then I can't see that. I did enter the PRN configuration, however.

Yes, this is repeatable, and it does work, but very rarely. While we've had this set up, I've seen it go a week without working, and then suddenly two messages in a row go through, and then it stops working again. I haven't changed any of the configuration since I set it up.

The other important detail that's not mentioned here is that I have the same exact configuration set up in a different repository on the same server, and that's been working without complaint for more than a year. They're even both using the same Jenkins instance to spawn the job from the event. If you're now wondering whether I made a mistake in the PRN configuration, I'll say again that I haven't changed the configuration since I set it up weeks ago, and it's managed to send a handful of messages so far, out of many hundreds of attempts.

Concerning any other configuration in the two repositories in question, there are some small differences. The one that is working is using the BitBucket Plugin for Jenkins hook, and the problematic one is using the HTTP Request Post-Receive Hook.

[tomasbjerre]

This just make me more confused. If you are using HTTP Request Post-Receive Hook why do you report the issue in this plugin?

[davidmichaelkarr]

Because we're also using the Pull Request Notification. We're trying to use the HRPRH for master/release builds, but the PRN for pull request builds.

[tomasbjerre]

The issue template, here, contains:

• Your configuration:
  • http://localhost:7990/bitbucket/rest/prnfb-admin/1.0/settings
  • http://localhost:7990/bitbucket/rest/prnfb-admin/1.0/settings/buttons
  • http://localhost:7990/bitbucket/rest/prnfb-admin/1.0/settings/notifications

Can you provide that?

A guess could be that the regexp filter needs to match more variations. If the comment sometimes contains hidden special characters.

[davidmichaelkarr]

I was able to figure out how to get the settings block, but I can't figure out how to get the buttons and notifications block. The API we use doesn't match those paths. In any case, I looked at the settings block that's returned, and I doubt there's anything useful in there.

However, I think we're missing the point here. In fact, I don't think the problem lies in this plugin at all. This is a problem in the events that BitBucket is emitting, not how the plugin is handling them. This should be obvious from the event traces shown above. The filter regexp apparently filters on the "action" value. When it stops working, we don't even get "action" values at all. The event information is formatted completely differently. I believe that no amount of tinkering with the regexp filter value would make any difference.

[tomasbjerre]

Ok. A support ticket on Atlassian is probably the only option then.

[mondayges]

Hi Tomas,

Just would like to verify if the version of our installed PRN plugin is compatible with our Bitbucket's version.

[tomasbjerre]

Yes should be compatible.

[davidmichaelkarr]

I finally got a BitBucket core ticket created for this, and they are saying this is an issue with the plugin, not with core.

I understand that you are experiencing an issue where a third party plugin is not behaving consistently. While this plugin is a supported and Data Center compatible plugin that support is provided by Tomas Bjerre, not Atlassian. You can open a support request for this plugin here. The information from the logs that you provided in the description is the message that the plugin asked Bitbucket to write into the logs. Bitbucket itself does not have any control of the content of those messages. Cheers, Craig Drummond Premier Support Engineer - Devtools Atlassian

From what I understood, those log entries aren't from your PRN plugin, but from BitBucket core, which represent the events your plugin tries to handle. Your plugin is looking for "PullRequestActivityNotification" events, not "GeneralCommentAddedNotification" events.

[bturner]

I'm the principal developer for Bitbucket Server. It appears there's some confusion here between all parties as to what's going on, so I'd like to try and clarify some details to try and get everyone on the same page.

First and foremost: This plugin does not integrate with Bitbucket Server's notifications at all. This plugin listens for pull request events; it does not implement any NotificationHandlers, nor does it register any in atlassian-plugin.xml. So the differences between GeneralCommentAddedNotification and PullRequestActivityNotification are, for the sake of discussing what's going on here, completely irrelevant. This plugin doesn't consume either. That means the logging posted in the issue description is also irrelevant to the behavior.

Furthermore, just to further prove the notification details are unrelated, the logging from the two log snippets attached in the description shows the same notifications are raised both times, despite what the description says.

Here are both lines from the first trace:

2018-05-25 15:04:33,673 DEBUG [AtlassianEvent::thread-1] dk068x *BLY4IOx904x10732665x8 1ahxn0w 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: PullRequestActivityNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 15:04:33 EDT 2018, pullRequest=cartms:715, activity=InternalPullRequestCommentActivity{id=6674620, user=InternalNormalUser{id=758, username=dk068x}, action=COMMENTED, pullRequest.id=715, commentAction=ADDED, comment=InternalComment{id=334665, author=InternalNormalUser{id=758, username=dk068x}, text=This is a test.}}}
2018-05-25 15:04:33,673 DEBUG [AtlassianEvent::thread-2] dk068x *BLY4IOx904x10732665x8 1ahxn0w 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: GeneralCommentAddedNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 15:04:33 EDT 2018, pullRequest=cartms:715, comment=InternalComment{id=334665, author=InternalNormalUser{id=758, username=dk068x}, text=This is a test.}}

Here are the lines from the second:

2018-05-25 18:34:41,144 DEBUG [AtlassianEvent::thread-10] dk068x *BLY4IOx1114x10878328x4 jwg1an 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: GeneralCommentAddedNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 18:34:41 EDT 2018, pullRequest=cartms:715, comment=InternalComment{id=334697, author=InternalNormalUser{id=758, username=dk068x}, text=Another test.}}
2018-05-25 18:34:41,145 DEBUG [AtlassianEvent::thread-8] dk068x *BLY4IOx1114x10878328x4 jwg1an 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: PullRequestActivityNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 18:34:41 EDT 2018, pullRequest=cartms:715, activity=InternalPullRequestCommentActivity{id=6676996, user=InternalNormalUser{id=758, username=dk068x}, action=COMMENTED, pullRequest.id=715, commentAction=ADDED, comment=InternalComment{id=334697, author=InternalNormalUser{id=758, username=dk068x}, text=Another test.}}}

They appear in reverse order, in the second trace, but both are present.

With that sorted, hopefully we can move forward. This plugin listens for 4 different pull request comment events. The relevant event for this issue is PullRequestCommentAddedEvent. The log traces show that that event was raised both times (the first line is from the first trace, and the second is from the second):

2018-05-25 15:04:33,672 DEBUG [http-nio-7990-exec-970] dk068x *BLY4IOx904x10732665x8 1ahxn0w 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing PullRequestCommentAddedEvent after commit
2018-05-25 18:34:41,144 DEBUG [http-nio-7990-exec-990] dk068x *BLY4IOx1114x10878328x4 jwg1an 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing PullRequestCommentAddedEvent after commit

So Bitbucket Server is correctly raising the same event both times.

Eventually, handling for all 4 of the registered event types is delegated to a common handleEvent method, which starts by checking for PullRequestCommentEvents added to closed pull requests and ignoring them.

It seems like a logical question then is: When the comment that does not trigger a notification was added, was the pull request still open? If the pull request has been declined or merged, it will not trigger a notification.

Perhaps some debug logging can be added in this plugin so that it logs when it receives an event, and it logs when it drops one instead of sending it? In addition to the closed && PullRequestCommentEvent check, isNotificationTriggeredByAction has several additional checks which can result in no notification being sent.

Let me know if there's something I can do to help!

Best regards, Bryan Turner Atlassian Bitbucket

[davidmichaelkarr]

Thanks, Bryan. This was very informative.

I did not know that comments in merged or declined PRs would not trigger a notification. It's entirely possible this has been the entire reason why this hasn't been working. I've been trying to get the team I'm working with to spend a teeny bit more time reviewing PRs before merging them. I hardly ever get to review anything before it's been merged. I will do some testing to verify this.

On Wed, Jun 20, 2018 at 3:10 PM, Bryan Turner [email protected] wrote:

I'm the principal developer for Bitbucket Server. It appears there's some confusion here between all parties as to what's going on, so I'd like to try and clarify some details to try and get everyone on the same page.

First and foremost: This plugin does not integrate with Bitbucket Server's notifications at all. This plugin listens for pull request events; it does not implement any NotificationHandlers https://docs.atlassian.com/bitbucket-server/javadoc/5.11.1/spi/reference/com/atlassian/bitbucket/notification/NotificationHandler.html, nor does it register any in atlassian-plugin.xml https://github.com/tomasbjerre/pull-request-notifier-for-bitbucket/blob/pull-request-notifier-for-bitbucket-2.67/src/main/resources/atlassian-plugin.xml. So the differences between GeneralCommentAddedNotification and PullRequestActivityNotification are, for the sake of discussing what's going on here, completely irrelevant. This plugin doesn't consume either. That means the logging posted in the issue description is also irrelevant to the behavior.

Furthermore, just to further prove the notification details are unrelated, the logging from the two log snippets attached in the description shows the same notifications are raised both times, despite what the description says.

Here are both lines from the first trace:

2018-05-25 15:04:33,673 DEBUG [AtlassianEvent::thread-1] dk068x *BLY4IOx904x10732665x8 1ahxn0w 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: PullRequestActivityNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 15:04:33 EDT 2018, pullRequest=cartms:715, activity=InternalPullRequestCommentActivity{id=6674620, user=InternalNormalUser{id=758, username=dk068x}, action=COMMENTED, pullRequest.id=715, commentAction=ADDED, comment=InternalComment{id=334665, author=InternalNormalUser{id=758, username=dk068x}, text=This is a test.}}} 2018-05-25 15:04:33,673 DEBUG [AtlassianEvent::thread-2] dk068x *BLY4IOx904x10732665x8 1ahxn0w 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: GeneralCommentAddedNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 15:04:33 EDT 2018, pullRequest=cartms:715, comment=InternalComment{id=334665, author=InternalNormalUser{id=758, username=dk068x}, text=This is a test.}}

Here are the lines from the second:

2018-05-25 18:34:41,144 DEBUG [AtlassianEvent::thread-10] dk068x *BLY4IOx1114x10878328x4 jwg1an 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: GeneralCommentAddedNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 18:34:41 EDT 2018, pullRequest=cartms:715, comment=InternalComment{id=334697, author=InternalNormalUser{id=758, username=dk068x}, text=Another test.}} 2018-05-25 18:34:41,145 DEBUG [AtlassianEvent::thread-8] dk068x *BLY4IOx1114x10878328x4 jwg1an 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.n.DefaultNotificationManager Managing notification: PullRequestActivityNotification{user=InternalNormalUser{id=758, username=dk068x}, timestamp=Fri May 25 18:34:41 EDT 2018, pullRequest=cartms:715, activity=InternalPullRequestCommentActivity{id=6676996, user=InternalNormalUser{id=758, username=dk068x}, action=COMMENTED, pullRequest.id=715, commentAction=ADDED, comment=InternalComment{id=334697, author=InternalNormalUser{id=758, username=dk068x}, text=Another test.}}}

They appear in reverse order, in the second trace, but both are present.

With that sorted, hopefully we can move forward. This plugin listens for 4 different pull request comment events https://github.com/tomasbjerre/pull-request-notifier-for-bitbucket/blob/pull-request-notifier-for-bitbucket-2.67/src/main/java/se/bjurr/prnfb/listener/PrnfbPullRequestEventListener.java#L294-L312. The relevant event for this issue is PullRequestCommentAddedEvent. The log traces show that that event was raised both times (the first line is from the first trace, and the second is from the second):

2018-05-25 15:04:33,672 DEBUG [http-nio-7990-exec-970] dk068x *BLY4IOx904x10732665x8 1ahxn0w 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing PullRequestCommentAddedEvent after commit 2018-05-25 18:34:41,144 DEBUG [http-nio-7990-exec-990] dk068x *BLY4IOx1114x10878328x4 jwg1an 135.165.47.114,127.0.0.1 "POST /rest/api/latest/projects/ST_IDSE/repos/cartms/pull-requests/715/comments HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing PullRequestCommentAddedEvent after commit

So Bitbucket Server is correctly raising the same event both times.

Eventually, handling for all 4 of the registered event types is delegated to a common handleEvent https://github.com/tomasbjerre/pull-request-notifier-for-bitbucket/blob/pull-request-notifier-for-bitbucket-2.67/src/main/java/se/bjurr/prnfb/listener/PrnfbPullRequestEventListener.java#L99-L103 method, which starts by checking for PullRequestCommentEvents added to closed pull requests and ignoring them.

It seems like a logical question then is: When the comment that does not trigger a notification was added, was the pull request still open? If the pull request has been declined or merged, it will not trigger a notification.

Perhaps some debug logging can be added in this plugin so that it logs when it receives an event, and it logs when it drops one instead of sending it? In addition to the closed && PullRequestCommentEvent check, isNotificationTriggeredByAction https://github.com/tomasbjerre/pull-request-notifier-for-bitbucket/blob/pull-request-notifier-for-bitbucket-2.67/src/main/java/se/bjurr/prnfb/listener/PrnfbPullRequestEventListener.java#L147 has several additional checks which can result in no notification being sent.

Let me know if there's something I can do to help!

Best regards, Bryan Turner Atlassian Bitbucket

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/tomasbjerre/pull-request-notifier-for-bitbucket/issues/287#issuecomment-398914005, or mute the thread https://github.com/notifications/unsubscribe-auth/AFTv0z7lwfsiu9Z-DuPcsQ__bdsgfLeAks5t-shvgaJpZM4USPNx .