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

sebastic · 2019-10-07T07:25:19Z

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.

The text was updated successfully, but these errors were encountered:

kovetskiy · 2019-10-07T09:40:21Z

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 · 2019-10-07T12:45:25Z

@sebastic What version of Bitbucket do you use?

sebastic · 2019-10-07T12:55:07Z

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 · 2019-10-28T06:38:06Z

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

kovetskiy · 2019-10-28T07:55:44Z

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 · 2019-10-28T08:16:12Z

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 · 2019-10-30T05:53:33Z

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 ***@***.***> 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 <#100?email_source=notifications&email_token=ACAN7ZCV3XFCQZ6DFJELFZTQQ2NU3A5CNFSM4I6AV7OKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOECMBLJI#issuecomment-546837925>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACAN7ZFP3PB6SCV2PYUTNDTQQ2NU3ANCNFSM4I6AV7OA> .

kovetskiy · 2019-10-30T07:45:58Z

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

kovetskiy · 2019-10-31T15:06:11Z

@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 · 2019-11-04T13:38:57Z

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 · 2019-11-04T14:10:56Z

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 · 2019-11-05T09:30:32Z

🙏 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 · 2019-11-05T13:10:16Z

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

kovetskiy · 2019-11-05T14:35:03Z

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

…

On Tue, Nov 5, 2019 at 4:10 PM Bas Couwenberg ***@***.***> 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 <#100?email_source=notifications&email_token=ACAN7ZA4M4U475UO3I73RT3QSFWDTA5CNFSM4I6AV7OKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDCYNTQ#issuecomment-549816014>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACAN7ZDIPAWIRP7HG32IGL3QSFWDTANCNFSM4I6AV7OA> .

sebastic · 2019-11-06T06:04:00Z

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 · 2019-11-06T06:26:00Z

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 · 2019-11-06T09:27:22Z

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 · 2019-11-06T10:05:59Z

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:

Start BB 6.8.0
Create Project_1
Create Repo_1
Create pre-receive hook that fails push in Project_1
Disabled/Enabled plugin (causes upgrade)
Hook in Project_1 is enabled
Hook in Repo_1 is enabled (inherited)
Tried pushing and it failed due to pre-receive hook on step #4

sebastic · 2019-11-06T11:11:00Z

Our setup

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

Hook settings:

Executable: git_multimail4bitbucket.sh
Safe mode: [✓]
Positional parameters: --recipients=foo-commits@example.com

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 · 2019-11-06T12:17:03Z

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 · 2019-11-06T12:28:58Z

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

sebastic · 2019-11-06T12:35:24Z

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 · 2019-11-07T08:53:56Z

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 · 2019-11-07T10:41:46Z

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 · 2019-11-07T13:58:35Z

@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 · 2019-11-07T17:37:17Z

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 · 2019-11-08T07:56:26Z

@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 · 2019-11-11T06:25:10Z

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 · 2019-11-11T08:58:09Z

Thanks!

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

kovetskiy · 2019-11-13T06:51:19Z

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 · 2019-12-02T11:39:20Z

Just upgraded to 6.8.1 and the hooks were created correctly.

kovetskiy added a commit that referenced this issue Oct 31, 2019

fix bug with settings while re-enabling hooks (#100)

3d99970

sebastic closed this as completed Nov 6, 2019

sebastic reopened this Nov 6, 2019

seletskiy added the bug label Nov 8, 2019

kovetskiy closed this as completed Nov 13, 2019

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

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

sebastic commented Oct 7, 2019

kovetskiy commented Oct 7, 2019

kovetskiy commented Oct 7, 2019 •

edited

sebastic commented Oct 7, 2019

sebastic commented Oct 28, 2019

kovetskiy commented Oct 28, 2019

sebastic commented Oct 28, 2019

kovetskiy commented Oct 30, 2019

kovetskiy commented Oct 30, 2019

kovetskiy commented Oct 31, 2019

sebastic commented Nov 4, 2019

sebastic commented Nov 4, 2019

kovetskiy commented Nov 5, 2019

sebastic commented Nov 5, 2019

kovetskiy commented Nov 5, 2019

sebastic commented Nov 6, 2019 •

edited

sebastic commented Nov 6, 2019

sebastic commented Nov 6, 2019

kovetskiy commented Nov 6, 2019

sebastic commented Nov 6, 2019

sebastic commented Nov 6, 2019 •

edited

kovetskiy commented Nov 6, 2019

sebastic commented Nov 6, 2019 •

edited

sebastic commented Nov 7, 2019

kovetskiy commented Nov 7, 2019 •

edited

kovetskiy commented Nov 7, 2019

kovetskiy commented Nov 7, 2019 •

edited

kovetskiy commented Nov 8, 2019

sebastic commented Nov 11, 2019

kovetskiy commented Nov 11, 2019

kovetskiy commented Nov 13, 2019

sebastic commented Dec 2, 2019

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

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

Comments

sebastic commented Oct 7, 2019

kovetskiy commented Oct 7, 2019

kovetskiy commented Oct 7, 2019 • edited

sebastic commented Oct 7, 2019

sebastic commented Oct 28, 2019

kovetskiy commented Oct 28, 2019

sebastic commented Oct 28, 2019

kovetskiy commented Oct 30, 2019

kovetskiy commented Oct 30, 2019

kovetskiy commented Oct 31, 2019

sebastic commented Nov 4, 2019

sebastic commented Nov 4, 2019

kovetskiy commented Nov 5, 2019

sebastic commented Nov 5, 2019

kovetskiy commented Nov 5, 2019

sebastic commented Nov 6, 2019 • edited

sebastic commented Nov 6, 2019

sebastic commented Nov 6, 2019

kovetskiy commented Nov 6, 2019

sebastic commented Nov 6, 2019

sebastic commented Nov 6, 2019 • edited

kovetskiy commented Nov 6, 2019

sebastic commented Nov 6, 2019 • edited

sebastic commented Nov 7, 2019

kovetskiy commented Nov 7, 2019 • edited

kovetskiy commented Nov 7, 2019

kovetskiy commented Nov 7, 2019 • edited

kovetskiy commented Nov 8, 2019

sebastic commented Nov 11, 2019

kovetskiy commented Nov 11, 2019

kovetskiy commented Nov 13, 2019

sebastic commented Dec 2, 2019

kovetskiy commented Oct 7, 2019 •

edited

sebastic commented Nov 6, 2019 •

edited

sebastic commented Nov 6, 2019 •

edited

sebastic commented Nov 6, 2019 •

edited

kovetskiy commented Nov 7, 2019 •

edited

kovetskiy commented Nov 7, 2019 •

edited