Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Elasticsearch TicketCreate event handler doesn't check if Ticket still exists #1192

Closed
sternenseemann opened this issue Aug 23, 2021 · 7 comments

Comments

@sternenseemann
Copy link
Contributor

I have an unit test where I am among other things are doing something like this:

my $TicketSalt = $Helper->GetRandomID();
my $TicketID = $TicketObject->TicketCreate(
  Title => 'UnitTest Ticket ' . $TicketSalt,
  Queue => 'Raw',
  Lock => 'unlock',
  Priority => '3 normal',
  State => 'new',
  CustomerUserID => $CustomerUser{UserID},
  CustomerUser => $CustomerUserLogin,
  OwnerID => $AdminUser{UserID},
  UserID => $AdminUser{UserID},
);

AdminUser and CustomerUser where created using TestUserCreate and TestCustomerUserCreate, respectively.

$TicketID is not undef and creation seems to work fine. However, when we reach the call to $Self->DoneTesting(); at the end, the following happens:

ERROR: OTOBO-otobo.UnitTest-35 Perl: 5.32.0 OS: linux Time: Mon Aug 23 14:17:02 2021

 Message: No such TicketID (8)!

 Traceback (105): 
   Module: Kernel::System::Ticket::TicketGet Line: 1312
   Module: Kernel::GenericInterface::Invoker::Elasticsearch::TicketManagement::PrepareRequest Line: 291
   Module: Kernel::GenericInterface::Invoker::PrepareRequest Line: 160
   Module: Kernel::GenericInterface::Requester::Run Line: 208
   Module: Kernel::GenericInterface::Event::Handler::Run Line: 211
   Module: Kernel::System::EventHandler::EventHandler Line: 231
   Module: Kernel::System::EventHandler::EventHandlerTransaction Line: 271
   Module: Kernel::System::ObjectManager::ObjectEventsHandle Line: 442
   Module: Kernel::System::ObjectManager::ObjectsDiscard Line: 490
   Module: Kernel::System::UnitTest::RegisterDriver::END Line: 73

[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $Ticket{"Queue"} in hash element at /opt/otobo/Kernel/GenericInterface/Invoker/Elasticsearch/TicketManagement.pm line 352.
ERROR: OTOBO-otobo.UnitTest-35 Perl: 5.32.0 OS: linux Time: Mon Aug 23 14:17:02 2021

 Message: No such TicketID (8)!

 Traceback (105): 
   Module: Kernel::System::Ticket::TicketGet Line: 1312
   Module: Kernel::GenericInterface::Invoker::Elasticsearch::TicketManagement::PrepareRequest Line: 291
   Module: Kernel::GenericInterface::Invoker::PrepareRequest Line: 160
   Module: Kernel::GenericInterface::Requester::Run Line: 208
   Module: Kernel::GenericInterface::Event::Handler::Run Line: 211
   Module: Kernel::System::EventHandler::EventHandler Line: 231
   Module: Kernel::System::EventHandler::EventHandlerTransaction Line: 271
   Module: Kernel::System::ObjectManager::ObjectEventsHandle Line: 442
   Module: Kernel::System::ObjectManager::ObjectsDiscard Line: 490
   Module: Kernel::System::UnitTest::RegisterDriver::END Line: 73

[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $Ticket{"Queue"} in hash element at /opt/otobo/Kernel/GenericInterface/Invoker/Elasticsearch/TicketManagement.pm line 352.
ERROR: OTOBO-otobo.UnitTest-35 Perl: 5.32.0 OS: linux Time: Mon Aug 23 14:17:02 2021

 Message: No such TicketID (8)!

 Traceback (105): 
   Module: Kernel::System::Ticket::TicketGet Line: 1312
   Module: Kernel::GenericInterface::Invoker::Elasticsearch::TicketManagement::PrepareRequest Line: 416
   Module: Kernel::GenericInterface::Invoker::PrepareRequest Line: 160
   Module: Kernel::GenericInterface::Requester::Run Line: 208
   Module: Kernel::GenericInterface::Event::Handler::Run Line: 211
   Module: Kernel::System::EventHandler::EventHandler Line: 231
   Module: Kernel::System::EventHandler::EventHandlerTransaction Line: 271
   Module: Kernel::System::ObjectManager::ObjectEventsHandle Line: 442
   Module: Kernel::System::ObjectManager::ObjectsDiscard Line: 490
   Module: Kernel::System::UnitTest::RegisterDriver::END Line: 73

ERROR: OTOBO-otobo.UnitTest-35 Perl: 5.32.0 OS: linux Time: Mon Aug 23 14:17:02 2021

 Message: Missing parameter Year.

 Traceback (105): 
   Module: Kernel::System::DateTime::_CPANDateTimeObjectCreate Line: 1887
   Module: Kernel::System::DateTime::new Line: 167
   Module: Kernel::System::ObjectManager::_ObjectBuild Line: 323
   Module: Kernel::System::ObjectManager::Create Line: 254
   Module: Kernel::GenericInterface::Invoker::Elasticsearch::TicketManagement::PrepareRequest Line: 434
   Module: Kernel::GenericInterface::Invoker::PrepareRequest Line: 160
   Module: Kernel::GenericInterface::Requester::Run Line: 208
   Module: Kernel::GenericInterface::Event::Handler::Run Line: 211
   Module: Kernel::System::EventHandler::EventHandler Line: 231
   Module: Kernel::System::EventHandler::EventHandlerTransaction Line: 271
   Module: Kernel::System::ObjectManager::ObjectEventsHandle Line: 442
   Module: Kernel::System::ObjectManager::ObjectsDiscard Line: 490
   Module: Kernel::System::UnitTest::RegisterDriver::END Line: 73

ERROR: OTOBO-otobo.UnitTest-35 Perl: 5.32.0 OS: linux Time: Mon Aug 23 14:17:02 2021

 Message: Error creating DateTime object ( 'String' => undef ).

 Traceback (105): 
   Module: Kernel::System::DateTime::new Line: 188
   Module: Kernel::System::ObjectManager::_ObjectBuild Line: 323
   Module: Kernel::System::ObjectManager::Create Line: 254
   Module: Kernel::GenericInterface::Invoker::Elasticsearch::TicketManagement::PrepareRequest Line: 434
   Module: Kernel::GenericInterface::Invoker::PrepareRequest Line: 160
   Module: Kernel::GenericInterface::Requester::Run Line: 208
   Module: Kernel::GenericInterface::Event::Handler::Run Line: 211
   Module: Kernel::System::EventHandler::EventHandler Line: 231
   Module: Kernel::System::EventHandler::EventHandlerTransaction Line: 271
   Module: Kernel::System::ObjectManager::ObjectEventsHandle Line: 442
   Module: Kernel::System::ObjectManager::ObjectsDiscard Line: 490
   Module: Kernel::System::UnitTest::RegisterDriver::END Line: 73

Can't call method "ToEpoch" on an undefined value at /opt/otobo/Kernel/GenericInterface/Invoker/Elasticsearch/TicketManagement.pm line 435.
END failed--call queue aborted.
ERROR: OTOBO-otobo.UnitTest-35 Perl: 5.32.0 OS: linux Time: Mon Aug 23 14:17:02 2021

 Message: No such TicketID (8)!

 Traceback (105): 
   Module: Kernel::System::Ticket::TicketGet Line: 1312
   Module: Kernel::GenericInterface::Invoker::Elasticsearch::TicketManagement::PrepareRequest Line: 291
   Module: Kernel::GenericInterface::Invoker::PrepareRequest Line: 160
   Module: Kernel::GenericInterface::Requester::Run Line: 208
   Module: Kernel::GenericInterface::Event::Handler::Run Line: 211
   Module: Kernel::System::EventHandler::EventHandler Line: 231
   Module: Kernel::System::EventHandler::EventHandlerTransaction Line: 271
   Module: Kernel::System::Ticket::DESTROY Line: 7836

[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $Ticket{"Queue"} in hash element at /opt/otobo/Kernel/GenericInterface/Invoker/Elasticsearch/TicketManagement.pm line 352 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: 	(in cleanup) 	(in cleanup)  at (eval 364) line 17 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: Use of uninitialized value $alias in lc at /usr/local/lib/perl5/5.32.0/x86_64-linux-gnu/Encode/Alias.pm line 38 during global destruction.
[Mon Aug 23 14:17:02 2021] Main.t: 	(in cleanup) 	(in cleanup)  at /opt/otobo/Kernel/System/Cache/Redis.pm line 112 during global destruction.
Dubious, test returned 255 (wstat 65280, 0xff00)

I'm using database rollbacks in the test case, so it may be that the events are processed after the rollback (for some reason?!) and failing of course then.

@sternenseemann
Copy link
Contributor Author

Okay, a workaround for my issue is calling $Kernel::OM->ObjectEventsHandle();. I still think that this is a bug however: The event handler for Elasticsearch does not check if the Ticket still exists. That the ticket still has to exist is an incorrect assumption I'd say since ObjectEventsHandle() isn't guaranteed to be called immediately after TicketCreate().

@sternenseemann sternenseemann changed the title Unit Tests are tripped up by Elasticsearch event handler Elasticsearch TicketCreate event handler doesn't check if Ticket still exists Aug 23, 2021
@svenoe
Copy link
Contributor

svenoe commented Sep 13, 2021

Hi Sterni,

sorry for the late reply. We still have some people in vacation, so not totally necessary things are postponed a bit.

I just skimmed through things quickly, two things, though - first, we do not have Elasticsearch incorporated into unit tests and just deactivate it for all old and existing tests normally, so some things won't work here. This is definitely work to be done, though.

The assumption with tickets existing is usually valid, also, and it directly being deleted is more of a unit test problem - the check should be done, nonetheless, I agree. Furthermore even if a ticket is existing in the database it is not guaranteed, that it exists in the Elasticsearch index. To really solve this, I would want to develop error handling for the invokers, to have the possibility to appropriately react to the elastic search responses.

Sven

@bschmalhofer
Copy link
Contributor

This bad effect wasn't recognised before, because the unit tests run without ElasticSearch support per default. It should be made easy to set up an environment with ES. Therefore I propose to add a flag --activate-elasticsearch to bin\docker\quick_setup.pl. Then test whether there are failures when running with ES.

@sternenseemann
Copy link
Contributor Author

The assumption with tickets existing is usually valid

That is probably true. in my case, I created and deleted the ticket in the same unit test which caused the issue — something probably unlikely to happen in normal operation. Still an avoidable crash.

Also as a correction: The database rollback doesn't cause such a problem (most likely because the events also get rolled back?). In my case the key was that the ticket is created and deleted, but the events for both processed only after all of that happened, causing the crash. The fix for that is to call ObjectEventsHandle() in between of course.

bschmalhofer added a commit that referenced this issue Sep 16, 2021
Limit the scope of some variables.
bschmalhofer added a commit that referenced this issue Sep 16, 2021
bschmalhofer added a commit that referenced this issue Sep 16, 2021
The target queue was already checked above.
bschmalhofer added a commit that referenced this issue Sep 16, 2021
empty lines before control flow,
no extra parens around map statements
bschmalhofer added a commit that referenced this issue Sep 16, 2021
Because it can be considered as its own special case.
bschmalhofer added a commit that referenced this issue Sep 16, 2021
Use %QueueIsExcluded for the actual lookup.
bschmalhofer added a commit that referenced this issue Sep 16, 2021
As they are not needed above.
bschmalhofer added a commit that referenced this issue Sep 16, 2021
bschmalhofer added a commit that referenced this issue Sep 16, 2021
This is the fallback when the article in no longer found.
@bschmalhofer
Copy link
Contributor

Added checks whether the required ticket, article, or attachments still exist when the events are handled. Running the complete test suite had some performance problems when it was running with ES enabled. But the last run, with all the checks enabled, looked fine. It could be that memory was exhausted on my devel machine.

@svenoe : Could you take a look at the PR?

bschmalhofer added a commit that referenced this issue Sep 21, 2021
…ket_still_exist

Issue #1192 check whether ticket still exist
@bschmalhofer
Copy link
Contributor

Run the unit tests again, and the result looks fine. Merged the PR. Closing later, when no problems crop up.

@bschmalhofer
Copy link
Contributor

Did another test run, this time with Docker images taken from hub.docker.com. Still looking good. Closing this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants