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.

Sign up for GitHub

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

Jump to bottom

Package Garbage Collector failed multiple ways when it can find the date #3044

Closed
leoberliant opened this issue Feb 6, 2023 · 3 comments
Closed

Package Garbage Collector failed multiple ways when it can find the date #3044

leoberliant opened this issue Feb 6, 2023 · 3 comments
Labels
bug enhancement
Milestone
6.0.4

Comments

@leoberliant
Copy link

leoberliant commented Feb 6, 2023 •
edited by davidjgonzalez
Loading

Required Information

On AEM 6.5.12 I'm testing Package Garbage Collector. Note, for test purposes, I copied the required classes from ACS Common Git.
I found several scenarios when the package purge failed

#1. com.*.migrtion group fails (bad_package2)
6.02.2023 15:05:00.066 *ERROR* [sling-threadpool-7d3bb87b-0ce9-4013-a9d4-9ce96856093b-(apache-sling-job-thread-pool)-4-AMS Performance Package Garbage Collection Queue(com/adobe/aem/ams/performance/PackageGarbageCollectionJob)] org.apache.sling.event.impl.jobs.queues.JobQueueImpl.AMS Performance Package Garbage Collection Queue Unhandled error occured in job processor null while processing job Sling Job [topic=com/adobe/aem/ams/performance/PackageGarbageCollectionJob, id=2023/2/6/15/5/696dfd5f-96e3-48cf-be88-43fed1b5ce52_1792, properties=slingevent:application=696dfd5f-96e3-48cf-be88-43fed1b5ce52,jcr:created=java.util.GregorianCalendar(Mon Feb 06 15:05:00 UTC 2023),slingevent:created=java.util.GregorianCalendar(Mon Feb 06 15:05:00 UTC 2023),event.job.queuename=AMS Performance Package Garbage Collection Queue,event.job.queued.time=java.util.GregorianCalendar(Mon Feb 06 15:05:00 UTC 2023),jcr:createdBy=sling-event,sling:resourceType=slingevent:Job,event.job.application=696dfd5f-96e3-48cf-be88-43fed1b5ce52,maxAgeInDays=60,groupName=com.tr.migration,event.job.retries=10,event.job.started.time=java.util.GregorianCalendar(Mon Feb 06 15:05:00 UTC 2023),jcr:primaryType=slingevent:Job,event.job.retrycount=0,:sling:jobs:asynchandler=org.apache.sling.event.impl.jobs.JobConsumerManager$JobConsumerWrapper$1@cb3e564]
java.lang.NullPointerException: null
	at java.base/java.util.Calendar.getMillisOf(Calendar.java:3437)
	at java.base/java.util.Calendar.compareTo(Calendar.java:2816)
	at java.base/java.util.Calendar.compareTo(Calendar.java:319)
	at java.base/java.util.Comparator.lambda$comparing$77a9974f$1(Comparator.java:469)
	at java.base/java.util.function.BinaryOperator.lambda$maxBy$1(BinaryOperator.java:74)
	at java.base/java.util.stream.ReduceOps$2ReducingSink.accept(ReduceOps.java:123)
	at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
	at java.base/java.util.LinkedList$LLSpliterator.forEachRemaining(LinkedList.java:1239)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
	at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.base/java.util.stream.ReferencePipeline.reduce(ReferencePipeline.java:558)
	at java.base/java.util.stream.ReferencePipeline.max(ReferencePipeline.java:594)
	at com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob.isLatestInstalled(PackageGarbageCollectionJob.java:118)
	at com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob.process(PackageGarbageCollectionJob.java:92)
	at org.apache.sling.event.impl.jobs.JobConsumerManager$JobConsumerWrapper.process(JobConsumerManager.java:502)
	at org.apache.sling.event.impl.jobs.queues.JobQueueImpl.startJob(JobQueueImpl.java:351)
	at org.apache.sling.event.impl.jobs.queues.JobQueueImpl.access$100(JobQueueImpl.java:60)
	at org.apache.sling.event.impl.jobs.queues.JobQueueImpl$1.run(JobQueueImpl.java:287)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)

bad_package2.zip

#2. com.*.openweb group (bad_package1) the size of the package is too big to attach, so I zipped only META-INF folder
06.02.2023 15:05:00.500 *INFO* [sling-threadpool-7d3bb87b-0ce9-4013-a9d4-9ce96856093b-(apache-sling-job-thread-pool)-4-AMS Performance Package Garbage Collection Queue(com/adobe/aem/ams/performance/PackageGarbageCollectionJob)] com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob Package Garbage Collector job finished - Removed 0 packages
06.02.2023 15:05:00.561 *INFO* [sling-threadpool-7d3bb87b-0ce9-4013-a9d4-9ce96856093b-(apache-sling-job-thread-pool)-24-AMS Performance Package Garbage Collection Queue(com/adobe/aem/ams/performance/PackageGarbageCollectionJob)] com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob Processing package openweb-ecomm-all:com.tr.openweb:v1.2.6 [/etc/packages/com.tr.openweb/openweb-ecomm-all-1.2.6.zip]
06.02.2023 15:05:00.621 *ERROR* [sling-threadpool-7d3bb87b-0ce9-4013-a9d4-9ce96856093b-(apache-sling-job-thread-pool)-24-AMS Performance Package Garbage Collection Queue(com/adobe/aem/ams/performance/PackageGarbageCollectionJob)] org.apache.sling.event.impl.jobs.queues.JobQueueImpl.AMS Performance Package Garbage Collection Queue Unhandled error occured in job processor null while processing job Sling Job [topic=com/adobe/aem/ams/performance/PackageGarbageCollectionJob, id=2023/2/6/15/5/696dfd5f-96e3-48cf-be88-43fed1b5ce52_1791, properties=slingevent:application=696dfd5f-96e3-48cf-be88-43fed1b5ce52,jcr:created=java.util.GregorianCalendar(Mon Feb 06 15:05:00 UTC 2023),slingevent:created=java.util.GregorianCalendar(Mon Feb 06 15:05:00 UTC 2023),event.job.queuename=AMS Performance Package Garbage Collection Queue,event.job.queued.time=java.util.GregorianCalendar(Mon Feb 06 15:05:00 UTC 2023),jcr:createdBy=sling-event,sling:resourceType=slingevent:Job,event.job.application=696dfd5f-96e3-48cf-be88-43fed1b5ce52,maxAgeInDays=60,groupName=com.tr.openweb,event.job.retries=10,event.job.started.time=java.util.GregorianCalendar(Mon Feb 06 15:05:00 UTC 2023),jcr:primaryType=slingevent:Job,event.job.retrycount=0,:sling:jobs:asynchandler=org.apache.sling.event.impl.jobs.JobConsumerManager$JobConsumerWrapper$1@5c23f9d]
java.lang.NullPointerException: null
	at com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob.isPackageOldEnough(PackageGarbageCollectionJob.java:200)
	at com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob.process(PackageGarbageCollectionJob.java:91)
	at org.apache.sling.event.impl.jobs.JobConsumerManager$JobConsumerWrapper.process(JobConsumerManager.java:502)
	at org.apache.sling.event.impl.jobs.queues.JobQueueImpl.startJob(JobQueueImpl.java:351)
	at org.apache.sling.event.impl.jobs.queues.JobQueueImpl.access$100(JobQueueImpl.java:60)
	at org.apache.sling.event.impl.jobs.queues.JobQueueImpl$1.run(JobQueueImpl.java:287)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Th
[bad_package.zip](https://github.com/Adobe-Consulting-Services/acs-aem-commons/files/10664568/bad_package.zip)
read.run(Thread.java:834)

Where packageCreatedAtCalendar.toInstant() is throwing the NPE.

private boolean isPackageOldEnough(JcrPackage jcrPackage, Integer maxAgeInDays) throws RepositoryException, IOException {
        Period maxAge = Period.ofDays(maxAgeInDays);
        LocalDate oldestAge = LocalDate.now().minus(maxAge);
        Calendar packageCreatedAtCalendar = jcrPackage.getPackage().getCreated();
        LocalDate packageCreatedAt = LocalDateTime.ofInstant(
            packageCreatedAtCalendar.toInstant(),
            packageCreatedAtCalendar.getTimeZone().toZoneId()).toLocalDate();
        String packageDescription = getPackageDescription(jcrPackage);

Expected Behavior

It looks like when the date does not exist or/and the date format follows an old specification it failed to continue. I think in such a scenario we can check lastUnwrapped as it directly related to the package deployment date

Actual Behavior

Failed due to NPE

Steps to Reproduce

Configure package purge tool

Links

Links to related assets, e.g. content packages containing test components
@davidjgonzalez
Copy link
Contributor

@kwin do you have any ideas why/when jcrPackage.getPackage().getCreated() and getLastUnwrapped() would return null? These are both packages that are installed on AEM, so i assume both should exist? If not, thoughts on fallbacks in the JCR to check (IIUC those values get pulled from the package's META-INF/properties.xml? or atleast the created? ... tho im not entirely sure)

@leoberliant
Copy link
Author

leoberliant commented Feb 8, 2023 •
edited
Loading

#It looks like an error like:
INFO [sling-threadpool-7d3bb87b-0ce9-4013-a9d4-9ce96856093b-(apache-sling-job-thread-pool)-20-AMS Performance Package Garbage Collection Queue(com/adobe/aem/ams/performance/PackageGarbageCollectionJob)] com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob Processing package migration-all:com.tr.migration:v4.70.3.2022_0414_1192819_0001245751 [/etc/packages/com.tr.migration/migration-all-4.70.3.2022_0414_1192819_0001245751.zip]
08.02.2023 00:50:00.442 ERROR [sling-threadpool-7d3bb87b-0ce9-4013-a9d4-9ce96856093b-(apache-sling-job-thread-pool)-20-AMS Performance Package Garbage Collection Queue(com/adobe/aem/ams/performance/PackageGarbageCollectionJob)] org.apache.sling.event.impl.jobs.queues.JobQueueImpl.AMS Performance Package Garbage Collection Queue Unhandled error occured in job processor null while processing job Sling Job [topic=com/adobe/aem/ams/performance/PackageGarbageCollectionJob, id=2023/2/8/0/50/696dfd5f-96e3-48cf-be88-43fed1b5ce52_5492, properties=slingevent:application=696dfd5f-96e3-48cf-be88-43fed1b5ce52,jcr:created=java.util.GregorianCalendar(Wed Feb 08 00:50:00 UTC 2023),slingevent:created=java.util.GregorianCalendar(Wed Feb 08 00:50:00 UTC 2023),event.job.queuename=AMS Performance Package Garbage Collection Queue,event.job.queued.time=java.util.GregorianCalendar(Wed Feb 08 00:50:00 UTC 2023),jcr:createdBy=sling-event,sling:resourceType=slingevent:Job,event.job.application=696dfd5f-96e3-48cf-be88-43fed1b5ce52,maxAgeInDays=60,groupName=com.tr.migration,event.job.retries=10,event.job.started.time=java.util.GregorianCalendar(Wed Feb 08 00:50:00 UTC 2023),jcr:primaryType=slingevent:Job,event.job.retrycount=0,:sling:jobs:asynchandler=org.apache.sling.event.impl.jobs.JobConsumerManager$JobConsumerWrapper$1@5ba5c50e]
java.lang.NullPointerException: null
at java.base/java.util.Calendar.getMillisOf(Calendar.java:3437)
at java.base/java.util.Calendar.compareTo(Calendar.java:2816)
at java.base/java.util.Calendar.compareTo(Calendar.java:319)
at java.base/java.util.Comparator.lambda$comparing$77a9974f$1(Comparator.java:469)
at java.base/java.util.function.BinaryOperator.lambda$maxBy$1(BinaryOperator.java:74)
at java.base/java.util.stream.ReduceOps$2ReducingSink.accept(ReduceOps.java:123)
at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
at java.base/java.util.LinkedList$LLSpliterator.forEachRemaining(LinkedList.java:1239)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
at java.base/java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.reduce(ReferencePipeline.java:558)
at java.base/java.util.stream.ReferencePipeline.max(ReferencePipeline.java:594)
at com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob.isLatestInstalled(PackageGarbageCollectionJob.java:118)
at com.adobe.aem.ams.performance.packagegarbagecollector.PackageGarbageCollectionJob.process(PackageGarbageCollectionJob.java:92)
at org.apache.sling.event.impl.jobs.JobConsumerManager$JobConsumerWrapper.process(JobConsumerManager.java:502)
at org.apache.sling.event.impl.jobs.queues.JobQueueImpl.startJob(JobQueueImpl.java:351)
at org.apache.sling.event.impl.jobs.queues.JobQueueImpl.access$100(JobQueueImpl.java:60)
at org.apache.sling.event.impl.jobs.queues.JobQueueImpl$1.run(JobQueueImpl.java:287)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
happens in a situation when one of the packages does not have lastUnpacked property and hence

private boolean isLatestInstalled(JcrPackage jcrPackage, List<JcrPackage> installedPackages) {
        Optional<JcrPackage> lastInstalledPackageOptional = installedPackages.stream().filter(installedPackage -> {
            PackageDefinition definition = new PackageDefinition(installedPackage);
            return definition.isSameNameAndGroup(jcrPackage);
        }).**max(Comparator.comparing(pkg -> new PackageDefinition(pkg).getLastUnpacked()));**

        if (lastInstalledPackageOptional.isPresent()) {
            JcrPackage lastInstalledPackage = lastInstalledPackageOptional.get();
            PackageDefinition lastInstalledPackageDefinition = new PackageDefinition(lastInstalledPackage);
            PackageDefinition thisPackageDefinition = new PackageDefinition(jcrPackage);

Comparator returns NPE. I think it needs a second check for lastUnwrapped property

@leoberliant
Copy link
Author

The tool fails if any package from the group does not have lastUnpacked property:

1_property=lastUnpacked
1_property.operation=not
type=vlt:PackageDefinition
path=/etc/packages/<group_name>
group.1_group.p.not=true
group.1_group.path=/etc/packages/<group_name>/.snapshot
group.1_group.path.self=true
p.limit=-1

@davidjgonzalez davidjgonzalez mentioned this issue Mar 15, 2023
Merged
@davidjgonzalez davidjgonzalez added this to the 6.0.4 milestone Mar 20, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug enhancement
Projects
None yet
Milestone
6.0.4
Development

No branches or pull requests
2 participants
@davidjgonzalez @leoberliant