search

reconquest / atlassian-external-hooks

External Hooks plugin for Atlassian Bitbucket
https://external-hooks.reconquest.io
Other
44 stars 37 forks source link

ERROR ExternalHooksListener unable to enable hook: com.atlassian.bitbucket.IllegalEntityStateException: You can not enable a repository hook com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook with no saved configuration #100

Closed sebastic closed 4 years ago

sebastic commented 5 years ago

After upgrading Bitbucket Server and restarting the service, the External Hooks don't work any more. De logging shows the following for every repo with External Hooks enabled:

2019-10-07 09:05:43,719 WARN  [Caesium-1-3]  ExternalHooksListener Creating HookScripts in scope: ProjectScope{project=Project{id=2, key='MON', name='Monitoring'}}
2019-10-07 09:05:43,821 WARN  [Caesium-1-3]  ExternalHooksListener external-hooks: creating HookScript for com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook
2019-10-07 09:05:43,844 WARN  [Caesium-1-3]  ExternalHooksListener Created 1 HookScripts in scope: ProjectScope{project=Project{id=2, key='MON', name='Monitoring'}}
2019-10-07 09:05:43,876 WARN  [Caesium-1-3]  ExternalHooksListener Creating HookScripts in scope: RepositoryScope{repository=MON/check-ssl[2]}
2019-10-07 09:05:43,911 WARN  [Caesium-1-3]  ExternalHooksListener external-hooks: creating HookScript for com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook
2019-10-07 09:05:43,917 ERROR [Caesium-1-3]  ExternalHooksListener unable to enable hook: com.atlassian.bitbucket.IllegalEntityStateException: You can not enable a repository hook com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook with no saved configuration
2019-10-07 09:05:43,917 WARN  [Caesium-1-3]  ExternalHooksListener Created 0 HookScripts in scope: RepositoryScope{repository=MON/check-ssl[2]}

All repositories except one have the add-on enabled on the project level, and only one test repo has it enabled on repo level which does work:

2019-10-07 09:07:11,924 WARN  [Caesium-1-3]  ExternalHooksListener Creating HookScripts in scope: ProjectScope{project=Project{id=23, key='TEST', name='Test'}}
2019-10-07 09:07:11,927 WARN  [Caesium-1-3]  ExternalHooksListener Created 0 HookScripts in scope: ProjectScope{project=Project{id=23, key='TEST', name='Test'}}
2019-10-07 09:07:11,933 WARN  [Caesium-1-3]  ExternalHooksListener Creating HookScripts in scope: RepositoryScope{repository=TEST/hook-test[32]}
2019-10-07 09:07:11,938 WARN  [Caesium-1-3]  ExternalHooksListener external-hooks: creating HookScript for com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook
2019-10-07 09:07:12,080 WARN  [Caesium-1-3]  ExternalHooksListener Created 1 HookScripts in scope: RepositoryScope{repository=TEST/hook-test[32]}

After saving the configuration for every project, the hook works again.

kovetskiy commented 5 years ago

Hi! Thanks for the report and for the logs, it definitely looks like a bug. We will investigate the issue as soon as possible.

kovetskiy commented 5 years ago

@sebastic What version of Bitbucket do you use?

sebastic commented 5 years ago

Currently 6.7.0 because of an issue with 6.7.1 unrelated to External Hooks. The add-on version is 7.2.0-1.

We've first noticed this issue when upgrading from 6.5.1 to 6.6.0.

The upgrade prior to that was from 5.16.9 to 6.5.1. With that upgrade to 6.x we noticed that repos which had the add-on enabled on repo level as well as on project level had it executed twice, we then migrated to the current setup with the add-on only configured on the project level.

sebastic commented 4 years ago

We just upgraded to 6.7.2 and this issue is still present. Any progress finding the cause?

kovetskiy commented 4 years ago

Unfortunately, no. We've tried several cases and were not able to reproduce the case. The error goes from the internals of Bitbucket SDK and means that your configuration of the plugin disappeared in BB internals.

What database do you use? Which version of the plugin do you have currently?

sebastic commented 4 years ago

We use PostgreSQL 11.5 (on Debian buster).

The plugin is still at version 7.2.0-1.

Where should the configuration be stored?

The configuration is present, because when you edit the hook settings it loads what was previous stored, just clicking the save button fixes the hook as previously mentioned.

kovetskiy commented 4 years ago

Hi, we have reproduced the error with postgresql and we are looking into it. I will keep you posted.

On Mon, Oct 28, 2019, 11:16 Bas Couwenberg notifications@github.com wrote:

We use PostgreSQL 11.5 (on Debian buster).

The plugin is still at version 7.2.0-1.

Where should the configuration be stored?

The configuration is present, because when you edit the hook settings it loads what was previous stored, just clicking the save button fixes the hook as previously mentioned.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/reconquest/atlassian-external-hooks/issues/100?email_source=notifications&email_token=ACAN7ZCV3XFCQZ6DFJELFZTQQ2NU3A5CNFSM4I6AV7OKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOECMBLJI#issuecomment-546837925, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACAN7ZFP3PB6SCV2PYUTNDTQQ2NU3ANCNFSM4I6AV7OA .

kovetskiy commented 4 years ago

We've found the root cause, fixed it and send the issue to our QA.

kovetskiy commented 4 years ago

@sebastic please upgrade the add-on to 7.3.0, we've fixed bug and released the version in the Atlassian Marketplace.

https://marketplace.atlassian.com/apps/1211631/external-hooks-by-reconquest/version-history#b6392

You can download the add-on from this page or upgrade it in "Manage apps" page in the admin panel.

sebastic commented 4 years ago

The add-on has been updated to 7.3.0 on both our test & production instance.

After restarting the atlbitbucket service on the test instance the hook is created successfully:

2019-11-04 14:33:10,060 WARN  [Caesium-1-2]  ExternalHooksListener Creating HookScripts in scope: ProjectScope{project=Project{id=2, key='MON', name='Monitoring'}}
2019-11-04 14:33:10,072 WARN  [Caesium-1-2]  ExternalHooksListener Created 0 HookScripts in scope: ProjectScope{project=Project{id=2, key='MON', name='Monitoring'}}
2019-11-04 14:33:10,089 WARN  [Caesium-1-2]  ExternalHooksListener Creating HookScripts in scope: RepositoryScope{repository=MON/check-ssl[2]}
2019-11-04 14:33:10,133 WARN  [Caesium-1-2]  ExternalHooksListener Created 1 HookScripts in scope: RepositoryScope{repository=MON/check-ssl[2]}

Looking good so far.

We'll have to wait for the next Bitbucket Server upgrade to confirm that it's fixed then too.

sebastic commented 4 years ago

The new version of the add-on may introduce a new, but related issue.

The hook configuration on the repository level changed from "Inherited (enabled)" to "Enabled" causing the hook to be executed twice for a single push.

kovetskiy commented 4 years ago

:pray: Sorry to hear that, we've missed that case, but fixed it in the latest version: https://marketplace.atlassian.com/apps/1211631/external-hooks-by-reconquest/version-history#b6412

sebastic commented 4 years ago

The update cannot be installed because it's not marked as compatible with 6.7.

kovetskiy commented 4 years ago

Hmm. That's weird. I've fixed it manually, please check now

On Tue, Nov 5, 2019 at 4:10 PM Bas Couwenberg notifications@github.com wrote:

The update cannot be installed because it's not marked as compatible with 6.7.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/reconquest/atlassian-external-hooks/issues/100?email_source=notifications&email_token=ACAN7ZA4M4U475UO3I73RT3QSFWDTA5CNFSM4I6AV7OKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDCYNTQ#issuecomment-549816014, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACAN7ZDIPAWIRP7HG32IGL3QSFWDTANCNFSM4I6AV7OA .

sebastic commented 4 years ago

Upgraded to 7.5.0 on both our instances.

Creating the hooks after restarting the service still looks good:

2019-11-06 06:53:29,262 WARN  [Caesium-1-4]  ExternalHooksListener Creating HookScripts in scope: ProjectScope{project=Project{id=2, key='MON', name='Monitoring'}}
2019-11-06 06:53:29,357 WARN  [Caesium-1-4]  ExternalHooksListener Created 1 HookScripts in scope: ProjectScope{project=Project{id=2, key='MON', name='Monitoring'}}
2019-11-06 06:53:29,389 WARN  [Caesium-1-4]  ExternalHooksListener Creating HookScripts in scope: RepositoryScope{repository=MON/check-ssl[2]}
2019-11-06 06:53:29,409 WARN  [Caesium-1-4]  ExternalHooksListener Created 0 HookScripts in scope: RepositoryScope{repository=MON/check-ssl[2]}

The configuration on the repo level remained "Inherited (enabled)".

sebastic commented 4 years ago

We've also upgraded to Bitbucket Server 6.8.0, and the hooks were correctly created after the upgrade as well.

Thanks for fixing this issue!

sebastic commented 4 years ago

I spoke too soon regarding the fix for this issue.

While the logging implies that the hook is created correctly, it doesn't actually execute the hook on push. For that to work the configuration needs to be saved again.

kovetskiy commented 4 years ago

I've tried your case with fresh bitbucket 6.8.0 setup and the latest version of the addon and haven't reproduced the problem. Could you provide steps to reproduce the problem? I've tried the following:

  1. Start BB 6.8.0
  2. Create Project_1
  3. Create Repo_1
  4. Create pre-receive hook that fails push in Project_1
  5. Disabled/Enabled plugin (causes upgrade)
  6. Hook in Project_1 is enabled
  7. Hook in Repo_1 is enabled (inherited)
  8. Tried pushing and it failed due to pre-receive hook on step #4
sebastic commented 4 years ago

Our setup

We have several projects, but not all, with 'External Post Receive Hook' enabled.

Hook settings:

Files on the server:

# ls -l /var/atlassian/application-data/bitbucket/external-hooks/*
-rwxr-xr-x 1 atlbitbucket atlbitbucket    337 Oct  7 10:37 /var/atlassian/application-data/bitbucket/external-hooks/git_multimail4bitbucket.sh
-rwxr-xr-x 1 atlbitbucket atlbitbucket 160733 Apr  3  2019 /var/atlassian/application-data/bitbucket/external-hooks/git_multimail.py

Copies of the files in question:

Then we have several repositories under the projects with 'External Post Receive Hook' enabled, these repos have their hooks inherited from their project.

The process this morning was to upgrade the add-on to 7.5.0 while still running Bitbucket 6.7.2, and after restarting the atlbitbucket service atlassian-bitbucket.log was checked for External Hooks issues and the hook configuration was checked for a couple of repos via the web interface.

Then we upgraded to Bitbucket 6.8.0 using the installer. After the service was started the log and hook configuration was checked again.

Moving on to another task some changes were commited and pushed to one of the repos, the expected emails were not sent because the hook was not executed.

sebastic commented 4 years ago

I can reproduce the issue with Bitbucket 6.8.0 by restarting the service and pushing some changes.

When saving the hook configuration again via the web interface the logging shows:

2019-11-06 13:14:00,175 DEBUG [http-nio-7990-exec-1] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key external-async-post-receive-hook.name and locales [en_US, en]
2019-11-06 13:14:00,182 DEBUG [http-nio-7990-exec-1] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key external-async-post-receive-hook.name and locales [en_US, en]
2019-11-06 13:14:00,186 DEBUG [http-nio-7990-exec-1] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for RepositoryHookEnabledEvent until AFTER_COMMIT
2019-11-06 13:14:00,187 DEBUG [http-nio-7990-exec-1] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for RepositoryHookSettingsChangedEvent until AFTER_COMMIT
2019-11-06 13:14:00,188 DEBUG [http-nio-7990-exec-1] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing RepositoryHookEnabledEvent after commit
2019-11-06 13:14:00,190 DEBUG [http-nio-7990-exec-1] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing RepositoryHookSettingsChangedEvent after commit
2019-11-06 13:14:00,232 WARN  [AtlassianEvent::thread-2] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" ExternalHookScript Settings had id 253 stored, but hook was already gone
2019-11-06 13:14:00,290 DEBUG [AtlassianEvent::thread-2] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for HookScriptCreatedEvent until AFTER_COMMIT
2019-11-06 13:14:00,316 DEBUG [AtlassianEvent::thread-2] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing HookScriptCreatedEvent after commit
2019-11-06 13:14:00,405 DEBUG [AtlassianEvent::thread-2] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for HookScriptConfigurationSetEvent until AFTER_COMMIT
2019-11-06 13:14:00,437 DEBUG [AtlassianEvent::thread-2] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing HookScriptConfigurationSetEvent after commit
2019-11-06 13:14:00,438 INFO  [AtlassianEvent::thread-2] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" ExternalHookScript Successfully created HookScript with id: 262

Note the Settings had id 253 stored, but hook was already gone message and the new id for the created hook.

When saving the configuration again via the REST API the logging is different:

2019-11-06 13:17:39,382 DEBUG [http-nio-7990-exec-9] @1WUP1MOx797x97x0 185.199.189.122,0:0:0:0:0:0:0:1 "GET /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/settings HTTP/1.1" c.a.b.i.c.s.CrowdSsoAuthenticationHandler Skipping Crowd SSO as it is not enabled
2019-11-06 13:17:39,412 DEBUG [http-nio-7990-exec-3] @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.b.i.c.s.CrowdSsoAuthenticationHandler Skipping Crowd SSO as it is not enabled
2019-11-06 13:17:39,431 DEBUG [http-nio-7990-exec-3] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key external-async-post-receive-hook.name and locales [en_US, en]
2019-11-06 13:17:39,433 DEBUG [http-nio-7990-exec-3] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key external-async-post-receive-hook.name and locales [en_US, en]
2019-11-06 13:17:39,436 DEBUG [http-nio-7990-exec-3] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for RepositoryHookEnabledEvent until AFTER_COMMIT
2019-11-06 13:17:39,436 DEBUG [http-nio-7990-exec-3] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for RepositoryHookSettingsChangedEvent until AFTER_COMMIT
2019-11-06 13:17:39,438 DEBUG [http-nio-7990-exec-3] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing RepositoryHookEnabledEvent after commit
2019-11-06 13:17:39,446 DEBUG [http-nio-7990-exec-3] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing RepositoryHookSettingsChangedEvent after commit
2019-11-06 13:17:39,455 DEBUG [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for HookScriptDeletedEvent until AFTER_COMMIT
2019-11-06 13:17:39,500 DEBUG [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.h.script.DiskHookScriptStore 262: Script version 1 does not exist
2019-11-06 13:17:39,503 INFO  [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.h.script.DiskHookScriptStore 262: Deleted 1/1 version(s) found
2019-11-06 13:17:39,503 DEBUG [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing HookScriptDeletedEvent after commit
2019-11-06 13:17:39,507 DEBUG [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for HookScriptCreatedEvent until AFTER_COMMIT
2019-11-06 13:17:39,563 DEBUG [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing HookScriptCreatedEvent after commit
2019-11-06 13:17:39,584 DEBUG [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for HookScriptConfigurationSetEvent until AFTER_COMMIT
2019-11-06 13:17:39,596 DEBUG [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Publishing HookScriptConfigurationSetEvent after commit
2019-11-06 13:17:39,597 INFO  [AtlassianEvent::thread-1] admin @1WUP1MOx797x98x0 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/1.0/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" ExternalHookScript Successfully created HookScript with id: 263

Note the following messages:

c.a.s.i.h.script.DiskHookScriptStore 262: Script version 1 does not exist
c.a.s.i.h.script.DiskHookScriptStore 262: Deleted 1/1 version(s) found

Pushing a change after this triggers the hook and the mail is sent.

kovetskiy commented 4 years ago

Could you also post logs during startup of the service? There is a routine related to ExternalHooksListener like in your first post.

sebastic commented 4 years ago

Logging after startup for ExternalHooks:

2019-11-06 13:11:21,815 INFO  [ThreadPoolAsyncTaskExecutor::Thread 34]  ExternalHooksListener Registering Job for creating HookScripts (plugin enabled / bitbucket restarted)
2019-11-06 13:11:21,976 INFO  [Caesium-1-4]  ExternalHooksListener Started job for creating HookScripts
2019-11-06 13:11:23,271 WARN  [Caesium-1-4]  ExternalHooksListener Plugin is not yet completely loaded, waiting
2019-11-06 13:11:23,977 INFO  [Caesium-1-4]  ExternalHooksListener Started job for creating HookScripts
2019-11-06 13:11:23,988 WARN  [Caesium-1-4]  ExternalHooksListener Plugin is not yet completely loaded, waiting
2019-11-06 13:11:26,018 INFO  [Caesium-1-1]  ExternalHooksListener Started job for creating HookScripts
2019-11-06 13:11:26,029 WARN  [Caesium-1-1]  ExternalHooksListener Plugin is not yet completely loaded, waiting
2019-11-06 13:11:28,060 INFO  [Caesium-1-3]  ExternalHooksListener Started job for creating HookScripts
2019-11-06 13:11:28,367 WARN  [Caesium-1-3]  ExternalHooksListener Plugin is not yet completely loaded, waiting
2019-11-06 13:11:29,993 INFO  [Caesium-1-1]  ExternalHooksListener Started job for creating HookScripts
2019-11-06 13:11:30,117 WARN  [Caesium-1-1]  ExternalHooksListener Plugin is not yet completely loaded, waiting
2019-11-06 13:11:32,110 INFO  [Caesium-1-1]  ExternalHooksListener Started job for creating HookScripts
2019-11-06 13:11:32,489 WARN  [Caesium-1-1]  ExternalHooksListener Plugin is not yet completely loaded, waiting
2019-11-06 13:11:34,085 INFO  [Caesium-1-1]  ExternalHooksListener Started job for creating HookScripts
2019-11-06 13:11:34,132 WARN  [Caesium-1-1]  ExternalHooksListener Plugin is not yet completely loaded, waiting
2019-11-06 13:11:36,027 DEBUG [spring-startup]  c.a.s.i.i18n.I18nClasspathScanner Adding plugin External Hooks with [external-hooks]
2019-11-06 13:11:36,110 INFO  [Caesium-1-3]  ExternalHooksListener Started job for creating HookScripts
2019-11-06 13:11:36,225 WARN  [Caesium-1-3]  ExternalHooksListener Creating HookScripts in scope: ProjectScope{project=Project{id=1, key='ANS', name='Ansible'}}
2019-11-06 13:11:36,556 WARN  [Caesium-1-3]  ExternalHooksListener external-hooks: creating HookScript for com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook
2019-11-06 13:11:37,163 WARN  [Caesium-1-3]  ExternalHooksListener Created 1 HookScripts in scope: ProjectScope{project=Project{id=1, key='ANS', name='Ansible'}}
2019-11-06 13:11:37,293 WARN  [Caesium-1-3]  ExternalHooksListener Creating HookScripts in scope: RepositoryScope{repository=ANS/ansible[1]}
2019-11-06 13:11:37,339 WARN  [Caesium-1-3]  ExternalHooksListener external-hooks: hook com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook is enabled & configured (inherited: PROJECT 1)
2019-11-06 13:11:37,339 WARN  [Caesium-1-3]  ExternalHooksListener Created 0 HookScripts in scope: RepositoryScope{repository=ANS/ansible[1]}

Is this sufficient or do you need the full log?

sebastic commented 4 years ago

Might the problem be that onRepositoryHookEnabledEvent doesn't install hook script?

The code shows that when the hookId doesn't equal the repository hook key the body is not executed.

The database shows hook keys in the form of <PLUGIN_KEY>:<hookComponentId>:

bitbucket=# SELECT * FROM sta_repo_hook WHERE hook_key LIKE 'com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook%';
 id  | repository_id |                               hook_key                                | is_enabled | lob_id | project_id
-----+---------------+-----------------------------------------------------------------------+------------+--------+------------
  42 |            32 | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook | t          |    102 |
 544 |               | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook | t          |   1103 |        104
 483 |               | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook | t          |   1063 |          1
 485 |               | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook | t          |   1064 |          2
 487 |               | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook | t          |   1065 |         84
(5 rows)

The hookId has the scope type (and resource id if available) appended to this when using getHookId(), but the constructor uses PLUGIN_KEY + ":" + hookComponentId like the above.

bitbucket=# SELECT * FROM plugin_setting WHERE key_name LIKE 'com.ngs.stash.externalhooks.external-hooks%';
         namespace         |                                  key_name                                   | key_value |  id
---------------------------+-----------------------------------------------------------------------------+-----------+------
 bitbucket.global.settings | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook:1:104 | 265       | 1706
 bitbucket.global.settings | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook:1:2   | 266       | 1707
 bitbucket.global.settings | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook:2:32  | 252       | 1683
 bitbucket.global.settings | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook:1:1   | 263       | 1704
 bitbucket.global.settings | com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook:1:84  | 264       | 1705
(5 rows)

Should onRepositoryHookDisabledEvent, onRepositoryHookEnabledEvent & onRepositoryHookSettingsDeletedEvent not take the scope into account to check whether it is for the hook in question?

Or am I getting confused by the hookId variable name also being used to retrieve the plugin settings, which differs from the hookId property of the ExternalHookScript class.

Should the variable for the plugin settings not be named hookSettingsId to differentiate it from the class property (and the method named getHookSettingsId)?

kovetskiy commented 4 years ago

Thanks for your input, but in that case where onRepositoryHookEnabled doesn't install hook script it will be easy to reproduce, but I can't reproduce it on my local setup and can't reproduce it with isolated official docker container installation.

I'm looking into the following message:

2019-11-06 13:14:00,186 DEBUG [http-nio-7990-exec-1] admin @1WUP1MOx794x93x0 1hohjln 185.199.189.122,0:0:0:0:0:0:0:1 "PUT /rest/api/latest/projects/ANS/settings/hooks/com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook/enabled HTTP/1.1" c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for RepositoryHookEnabledEvent until AFTER_COMMIT

which looks strange because event should not be deferred, maybe for some internal reason the event is not delivered to the addon.

I'll keep you posted.

kovetskiy commented 4 years ago

@sebastic I've found a case where OnRepositoryHookEnabled events are not triggered by Bitbucket's event factory during BB startup. I've found a workaround for it and sent new version to QA to test all basic scenarios. Changes published in a separated branch: https://github.com/reconquest/atlassian-external-hooks/tree/no-events-fix

kovetskiy commented 4 years ago

Just letting you know that the bug is not reproducible in official docker image bitbucket-server (I've also tried DC mode), but it's easily reproducible on debian10 (I've reproduced it on Linode VPS)

kovetskiy commented 4 years ago

@sebastic good news, the beta release has passed QA, could you try the following beta release on your development instance?

The following patch addresses case with missing events and causing missing hook scripts after startup: https://github.com/reconquest/atlassian-external-hooks/releases/tag/8.0.0-beta

sebastic commented 4 years ago

Upgraded the add-on on our test instance, de logging still shows that the hook was already gone, but the hook was created correctly, there was no need to save the configuration again.

2019-11-11 07:10:05,954 INFO  [ThreadPoolAsyncTaskExecutor::Thread 47]  ExternalHooksListener Registering Job for creating HookScripts (plugin enabled / bitbucket restarted)
2019-11-11 07:10:05,986 INFO  [Caesium-1-2]  ExternalHooksListener Started job for creating HookScripts
2019-11-11 07:10:05,994 DEBUG [Caesium-1-2]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key isPullRequest.name and locales [en_US, en]
2019-11-11 07:10:05,995 DEBUG [Caesium-1-2]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key isPullRequest.description and locales [en_US, en]
2019-11-11 07:10:05,995 DEBUG [Caesium-1-2]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key stash.plugins.hooks.reject.forcepush.name and locales [en_US, en]
2019-11-11 07:10:05,995 DEBUG [Caesium-1-2]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.plugins.hooks.protect.unmerged.branch.name and locales [en_US, en]
2019-11-11 07:10:05,995 DEBUG [Caesium-1-2]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.plugins.hooks.protect.unmerged.branch.description and locales [en_US, en]
2019-11-11 07:10:06,848 DEBUG [UpmAsynchronousTaskManager:thread-2] admin @1WUP1MOx430x4176x0 14askwj 185.199.189.122,0:0:0:0:0:0:0:1 "POST /rest/plugins/1.0/ HTTP/1.1" c.a.b.i.p.e.BeanEventListenerScanner com.ngs.stash.externalhooks.external-hooks: registered [com.ngs.stash.externalhooks.hook.ExternalPreReceiveHook, com.ngs.stash.externalhooks.hook.ExternalMergeCheckHook, com.ngs.stash.externalhooks.hook.ExternalAsyncPostReceiveHook] as event listener
2019-11-11 07:10:06,849 DEBUG [UpmAsynchronousTaskManager:thread-2] admin @1WUP1MOx430x4176x0 14askwj 185.199.189.122,0:0:0:0:0:0:0:1 "POST /rest/plugins/1.0/ HTTP/1.1" c.a.s.i.i18n.I18nClasspathScanner Adding plugin External Hooks with [external-hooks]
2019-11-11 07:10:07,232 INFO  [UpmAsynchronousTaskManager:thread-2] admin @1WUP1MOx430x4176x0 14askwj 185.199.189.122,0:0:0:0:0:0:0:1 "POST /rest/plugins/1.0/ HTTP/1.1" c.a.u.c.l.PluginSettingsAuditLogService Mon Nov 11 07:10:06 CET 2019 1: Installed app External Hooks (com.ngs.stash.externalhooks.external-hooks version 8.0.0)
2019-11-11 07:10:07,500 DEBUG [http-nio-7990-exec-6] admin @1WUP1MOx430x4208x0 14askwj 185.199.189.122,0:0:0:0:0:0:0:1 "GET /rest/plugins/1.0/com.ngs.stash.externalhooks.external-hooks-key HTTP/1.1" c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key external-async-post-receive-hook.name and locales [en_US, en]
2019-11-11 07:10:07,501 DEBUG [http-nio-7990-exec-6] admin @1WUP1MOx430x4208x0 14askwj 185.199.189.122,0:0:0:0:0:0:0:1 "GET /rest/plugins/1.0/com.ngs.stash.externalhooks.external-hooks-key HTTP/1.1" c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key external-async-post-receive-hook.name and locales [en_US, en]
2019-11-11 07:10:08,018 INFO  [Caesium-1-4]  ExternalHooksListener Started job for creating HookScripts
2019-11-11 07:10:08,022 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key isPullRequest.name and locales [en_US, en]
2019-11-11 07:10:08,023 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key isPullRequest.description and locales [en_US, en]
2019-11-11 07:10:08,023 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key stash.plugins.hooks.reject.forcepush.name and locales [en_US, en]
2019-11-11 07:10:08,023 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.plugins.hooks.protect.unmerged.branch.name and locales [en_US, en]
2019-11-11 07:10:08,023 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.plugins.hooks.protect.unmerged.branch.description and locales [en_US, en]
2019-11-11 07:10:08,033 WARN  [Caesium-1-4]  ExternalHooksListener Creating HookScripts in scope: ProjectScope{project=Project{id=1, key='ANS', name='Ansible'}}
2019-11-11 07:10:08,034 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.webhooks.modulename and locales [en_US, en]
2019-11-11 07:10:08,034 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key isPullRequest.name and locales [en_US, en]
2019-11-11 07:10:08,035 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key isPullRequest.description and locales [en_US, en]
2019-11-11 07:10:08,035 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key stash.plugins.hooks.reject.forcepush.name and locales [en_US, en]
2019-11-11 07:10:08,035 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.plugins.hooks.protect.unmerged.branch.name and locales [en_US, en]
2019-11-11 07:10:08,036 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.plugins.hooks.protect.unmerged.branch.description and locales [en_US, en]
2019-11-11 07:10:08,036 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key external-async-post-receive-hook.name and locales [en_US, en]
2019-11-11 07:10:08,088 WARN  [Caesium-1-4]  ExternalHooksListener Creating POST_RECEIVE HookScript for com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook
2019-11-11 07:10:08,169 WARN  [Caesium-1-4]  ExternalHookScript Settings had id 263 stored, but hook was already gone
2019-11-11 07:10:08,216 DEBUG [Caesium-1-4]  c.a.s.i.e.TransactionAwareEventPublisher Deferring publishing for HookScriptCreatedEvent until AFTER_COMMIT
2019-11-11 07:10:08,267 DEBUG [Caesium-1-4]  c.a.s.i.e.TransactionAwareEventPublisher Publishing HookScriptCreatedEvent after commit
2019-11-11 07:10:08,360 WARN  [Caesium-1-4]  ExternalHookScript Created HookScript with id: 267
2019-11-11 07:10:08,361 WARN  [Caesium-1-4]  ExternalHooksListener Created 1 HookScripts in scope: ProjectScope{project=Project{id=1, key='ANS', name='Ansible'}}
2019-11-11 07:10:08,368 WARN  [Caesium-1-4]  ExternalHooksListener Creating HookScripts in scope: RepositoryScope{repository=ANS/ansible[1]}
2019-11-11 07:10:08,370 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.webhooks.modulename and locales [en_US, en]
2019-11-11 07:10:08,370 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key isPullRequest.name and locales [en_US, en]
2019-11-11 07:10:08,370 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key isPullRequest.description and locales [en_US, en]
2019-11-11 07:10:08,370 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key stash.plugins.hooks.reject.forcepush.name and locales [en_US, en]
2019-11-11 07:10:08,371 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.plugins.hooks.protect.unmerged.branch.name and locales [en_US, en]
2019-11-11 07:10:08,371 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key bitbucket.plugins.hooks.protect.unmerged.branch.description and locales [en_US, en]
2019-11-11 07:10:08,371 DEBUG [Caesium-1-4]  c.a.s.i.i18n.PluginI18nService No values found in any valid locale for key external-async-post-receive-hook.name and locales [en_US, en]
2019-11-11 07:10:08,374 WARN  [Caesium-1-4]  ExternalHooksListener Hook com.ngs.stash.externalhooks.external-hooks:external-post-receive-hook is enabled & configured (inherited: PROJECT 1)
2019-11-11 07:10:08,374 WARN  [Caesium-1-4]  ExternalHooksListener Created 0 HookScripts in scope: RepositoryScope{repository=ANS/ansible[1]}
kovetskiy commented 4 years ago

Thanks!

We've released the version in the official marketplace: https://marketplace.atlassian.com/apps/1211631/external-hooks-by-reconquest/version-history#b6432

kovetskiy commented 4 years ago

I'm closing this issue, feel free to re-open it if you still have any issues.

I'm glad that the issue is solved, really appreciate your patience and trust.

sebastic commented 4 years ago

Just upgraded to 6.8.1 and the hooks were created correctly.