Listing all notifications via API takes a long time

[jayhendren]

I have 98 pull request notifications set on many of my Bitbucket Server repositories (one per repository). Attempting to list all of the notifications via the API (curl 'https://my.bitbucket.server/rest/prnfb-admin/1.0/settings/notifications' -XGET -u 'username:password') takes about a minute when Bitbucket is otherwise idle.

Here is the profiler output which shows that the API call takes about 61 seconds:

2017-07-27 14:31:19,140 | http-nio-7990-exec-516 | @D4Z4LNx870x67765x0 | jenkins | -
[60869ms] - "GET /rest/prnfb-admin/1.0/settings/notifications HTTP/1.1"
  [104ms] - Authentication org.springframework.security.authentication.AuthenticationProvider.authenticate(Authentication)
    [4ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-crowd-sso:crowdSsoAuthHandler
      [3ms] - CaptchaTicket com.atlassian.stash.internal.user.CaptchaService.checkCaptcha(String,CaptchaResponse)
    [97ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-authentication:crowdHttpAuthHandler
      [97ms] - ApplicationUser com.atlassian.stash.internal.user.CaptchaService.authenticateWithCaptcha(CaptchaTicket,UncheckedOperation)
    [2ms] - Page com.atlassian.bitbucket.user.UserService.findGroupsByUser(String,PageRequest)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [2ms] - Page com.atlassian.bitbucket.user.UserService.findGroupsByUser(String,PageRequest)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)
  [1ms] - String com.atlassian.stash.internal.plugin.PluginSettingDao.get(String,String)

I am using version 2.65 of the plugin and version 4.7.1 of Bitbucket.

[jayhendren]

I have determined that the time it takes for a request to this endpoint to return does not depend on the number of notifications. The call still took a minute to return even when I deleted notifications for all repositories. It appears to be related to the number of repositories (my Bitbucket Server instance probably has around 1000 repositories total, of which less than 100 have pull request notifications configured).

[jayhendren]

I was able to investigate more and determine this is related to neither the number of notifications nor the number of repositories.

Our notifications are configured by Chef, which periodically and regularly hits the API to do so. It appears that every time the API is used to update an existing notification, even if no values (including the UUID) change, a new copy of the notification is saved to the database. What's really interesting is that, even when the plugin is reporting that no notifications exist, there still may be notifications in the database. I cleaned out some tens of thousands of notifications from the database and now the API is responsive again.

It looks like there a couple, possibly related, bugs here:

• every POST request to rest/prnfb-admin/1.0/settings/notifications creates a new object in the database, even if the request is updating an existing notification with the same UUID
• deleted notifications don't get removed from the database even thought they may not be shown in the web UI or GET requests to the API

[tomasbjerre]

I had a look in the SDK setup. Where the DB is H2.

Created 2 global notifications, deleted one of them, deleted the other one. Added a new one, changed it, saved it.

I can see only one occurrence of the key in PLUGIN_SETTING table.

• maxwidth 9999
• SELECT * FROM PLUGIN_SETTING WHERE KEY_NAME LIKE '%pull%';
• SELECT KEY_VALUE FROM PLUGIN_SETTING WHERE KEY_NAME='se.bjurr.prnfb.pull-request-notifier-for-bitbucket-3'

What do you mean with "new object in the database"? From the plugin point of view it is just a key/value store...

[jayhendren]

@tomasbjerre I have attached the items I found in the plugin_setting table of the database that seemed to be related to the pull-request-notifier plugin. I have tried to scrub private data as best I can. Note that this is what I found after I had deleted all notifications via the API - calls to rest/prnfb-admin/1.0/settings/notifications were returning 0 notifications (prior to deleting notifications, GET calls to that endpoint were returning 98 notifications).

I also tried the same experiment you tried - I created a notification via the web UI, then deleted it via the API. It remained in the database but API calls (and the web interface) stopped showing it. Before I deleted it, I also updated the notification via the web UI and it created a new notification in the database. Here is what I am seeing now:

mysql> select * from plugin_setting where key_name='se.bjurr.prnfb.pull-request-notifier-for-bitbucket-3'\G
*************************** 1. row ***************************
namespace: bitbucket.global.settings
 key_name: se.bjurr.prnfb.pull-request-notifier-for-bitbucket-3
key_value: {"buttons":[],"notifications":[{"headers":[],"method":"POST","name":"trigger rescan of repository on PR update","password":"mypass","proxyPassword":"bar","proxyUser":"foo","triggerIfCanMerge":"ALWAYS","triggerIgnoreStateList":[],"triggers":["MERGED","OPENED","REOPENED","RESCOPED_FROM","RESCOPED_TO","UPDATED"],"url":"https://jenkins.int.my.org/job/sis_configuration_management/${PULL_REQUEST_TO_REPO_NAME}/build","user":"myuser","uuid":"a027298a-a01a-4dbd-90fa-95de28875c72","postContentEncoding":"NONE"},{"headers":[],"method":"POST","name":"trigger rescan of repository on PR update","password":"mypass","triggerIfCanMerge":"ALWAYS","triggerIgnoreStateList":[],"triggers":["MERGED","OPENED","REOPENED","RESCOPED_FROM","RESCOPED_TO","UPDATED"],"url":"https://jenkins.int.my.org/job/sis_configuration_management/job/${PULL_REQUEST_TO_REPO_NAME}/build","user":"my.user","uuid":"933ad0d0-c1f4-42f9-bc3f-7fa323c3abe6","postContentEncoding":"NONE"}],"prnfbSettingsData":{"adminRestriction":"ADMIN","shouldAcceptAnyCertificate":false}}
       id: 834
1 row in set (0.00 sec)

[birdsnest ~][N]% curl 'https://stash.int.my.org/rest/prnfb-admin/1.0/settings/notifications' -XGET -u 'adminuser:adminpass'
[]
[birdsnest ~][I]%

bitbucket-plugin_settings.txt

[tomasbjerre]

I can see that this code can be much faster. The same user is looked up, as well as all settings, for every notification that is read. Performance can definitely be increased a lot here. Will fix that.

But I can't see any abandoned settings in the DB that are not exposed in the API.

[jayhendren]

@tomasbjerre I don't see anything either that would explain why a call to /rest/prnfb-admin/1.0/settings/notifications would not simply return all notifications in the object associated with the key se.bjurr.prnfb.pull-request-notifier-for-bitbucket-3.

Would you like me to open a new issue for the discrepancy between what notifications exist in the database and what notifications are returned by the API, and keep this issue focused on speeding up the /rest/prnfb-admin/1.0/settings/notifications endpoint?

My apologies for the poor quality bug report - I don't really have a sandbox Bitbucket to play around with, and I don't want to break the production instance or cause downtime. Let me know if there's any additional information you would like me to provide.

[tomasbjerre]

We can keep it in this issue it's fine =)

[tomasbjerre]

I made an optimization and released it in 3.10, for BBS 5.x. But non fix for the abandoned notifications...