Description of problem: When taskomatic channel repodata task is running and package from actually processed channel is deleted (completely), task will throw unhandled exception. Version-Release number of selected component (if applicable): How reproducible: always Steps to Reproduce: 1. prepare channel with many packages 2. wait for taskomatic channel repodata task to process this channel 3. delete one of the packages (which was not processed yet) Actual results: exception in taskomatic log: INFO | jvm 1 | 2016/11/24 10:31:01 | 2016-11-24 10:31:01,177 [Thread-1834] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Generating new repository metadata for channel 'jdobes-clone-centos6-x86_64'(sha1) 9004 packages, 0 errata INFO | jvm 1 | 2016/11/24 10:34:59 | 2016-11-24 10:34:59,203 [Thread-1834] ERROR com.redhat.rhn.taskomatic.task.ChannelRepodata - java.lang.NullPointerException INFO | jvm 1 | 2016/11/24 10:34:59 | java.lang.NullPointerException INFO | jvm 1 | 2016/11/24 10:34:59 | at com.redhat.rhn.taskomatic.task.repomd.SimpleContentHandler.addCharacters(SimpleContentHandler.java:99) INFO | jvm 1 | 2016/11/24 10:34:59 | at com.redhat.rhn.taskomatic.task.repomd.PrimaryXmlWriter.addBasicPackageDetails(PrimaryXmlWriter.java:180) INFO | jvm 1 | 2016/11/24 10:34:59 | at com.redhat.rhn.taskomatic.task.repomd.PrimaryXmlWriter.addPackage(PrimaryXmlWriter.java:106) INFO | jvm 1 | 2016/11/24 10:34:59 | at com.redhat.rhn.taskomatic.task.repomd.RpmRepositoryWriter.writeRepomdFiles(RpmRepositoryWriter.java:188) INFO | jvm 1 | 2016/11/24 10:34:59 | at com.redhat.rhn.taskomatic.task.repomd.ChannelRepodataWorker.run(ChannelRepodataWorker.java:104) INFO | jvm 1 | 2016/11/24 10:34:59 | at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:761) INFO | jvm 1 | 2016/11/24 10:34:59 | at java.lang.Thread.run(Thread.java:809) ... INFO | jvm 1 | 2016/11/24 10:41:00 | 2016-11-24 10:41:00,057 [DefaultQuartzScheduler_Worker-5] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:42:00 | 2016-11-24 10:42:00,085 [DefaultQuartzScheduler_Worker-2] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:43:00 | 2016-11-24 10:43:00,062 [DefaultQuartzScheduler_Worker-4] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:44:00 | 2016-11-24 10:44:00,060 [DefaultQuartzScheduler_Worker-6] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:45:00 | 2016-11-24 10:45:00,114 [DefaultQuartzScheduler_Worker-4] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:46:00 | 2016-11-24 10:46:00,039 [DefaultQuartzScheduler_Worker-2] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:47:00 | 2016-11-24 10:47:00,056 [DefaultQuartzScheduler_Worker-10] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:48:00 | 2016-11-24 10:48:00,054 [DefaultQuartzScheduler_Worker-8] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:49:00 | 2016-11-24 10:49:00,110 [DefaultQuartzScheduler_Worker-1] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:50:00 | 2016-11-24 10:50:00,219 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:51:00 | 2016-11-24 10:51:00,063 [DefaultQuartzScheduler_Worker-4] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/24 10:52:00 | 2016-11-24 10:52:00,043 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 Task will keep running state, repodata not updated, taskomatic not processing channel repodata. Expected results: Exception is handled, task marked as failed, taskomatic will try to regenerate it again. Additional info:
I believe it's fixed by these commits in spacewalk master: 20e439382aace1c228af519cc1a77a4539f44240 91f20c19cb7ab691a3c7bac07723263d0a06b17b 8fe5b71bacd82a9acf00be8baa2babae6d9e4b6b 28cb84a6d2c1e8d0ff3c05c17e53d1e2a1ac84e1 013c07239797d48b1a965354f4db9b37eddbd857
Reproduced on spacewalk-java-2.3.8-155. Steps to reproduce: 1. Create a big enough channel. I have repo-synced the Centos 6 x86_64 base channel (6695 packages). 2. Pick a package starting with a late letter of the alphabet (zsh is a good candidate), and get its ID. Taskomatic should supposedly process packages in the alphabetical order, so "Z" is good. 3. Clone the channel from the step 1 and watch the /var/log/rhn/rhn_taskomatic_daemon.log for a message that taskomatic has picked up the task and started to generate repodata for the newly cloned channel: 2016-11-29 08:27:00,074 [Thread-891] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Generating new repository metadata for channel 'centos6cloned'(sha1) 6694 packages, 0 errata 4. Quickly remove the package you have chosen in the step 2 using the "packages.removePackage" API call. Using the "channel.software.removePackages" is not enough to reproduce the issue, as it doesn't remove the package completely. You have to be faster than the taskomatic, to remove the package before taskomatic can process it. 5. Wait for the error message in the /var/log/rhn/rhn_taskomatic_daemon.log: INFO | jvm 1 | 2016/11/29 08:27:19 | java.lang.NullPointerException INFO | jvm 1 | 2016/11/29 08:27:19 | at com.redhat.rhn.taskomatic.task.repomd.SimpleContentHandler.addCharacters(SimpleContentHandler.java:99) INFO | jvm 1 | 2016/11/29 08:27:19 | at com.redhat.rhn.taskomatic.task.repomd.PrimaryXmlWriter.addBasicPackageDetails(PrimaryXmlWriter.java:180) INFO | jvm 1 | 2016/11/29 08:27:19 | at com.redhat.rhn.taskomatic.task.repomd.PrimaryXmlWriter.addPackage(PrimaryXmlWriter.java:106) INFO | jvm 1 | 2016/11/29 08:27:19 | at com.redhat.rhn.taskomatic.task.repomd.RpmRepositoryWriter.writeRepomdFiles(RpmRepositoryWriter.java:188) INFO | jvm 1 | 2016/11/29 08:27:19 | at com.redhat.rhn.taskomatic.task.repomd.ChannelRepodataWorker.run(ChannelRepodataWorker.java:104) INFO | jvm 1 | 2016/11/29 08:27:19 | at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:761) INFO | jvm 1 | 2016/11/29 08:27:19 | at java.lang.Thread.run(Thread.java:809) 6. Taskomatic will detect that channel has been actually changed, and will do another run to generate the metadata, but original failed run will stay in the queue: INFO | jvm 1 | 2016/11/29 08:34:00 | 2016-11-29 08:34:00,022 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:35:00 | 2016-11-29 08:35:00,032 [DefaultQuartzScheduler_Worker-6] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:36:00 | 2016-11-29 08:36:00,023 [DefaultQuartzScheduler_Worker-9] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:37:00 | 2016-11-29 08:37:00,019 [DefaultQuartzScheduler_Worker-6] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:38:00 | 2016-11-29 08:38:00,030 [DefaultQuartzScheduler_Worker-9] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:39:00 | 2016-11-29 08:39:00,021 [DefaultQuartzScheduler_Worker-6] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:40:00 | 2016-11-29 08:40:00,046 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:41:00 | 2016-11-29 08:41:00,018 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:42:00 | 2016-11-29 08:42:00,023 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:43:00 | 2016-11-29 08:43:00,023 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:44:00 | 2016-11-29 08:44:00,036 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:45:00 | 2016-11-29 08:45:00,029 [DefaultQuartzScheduler_Worker-10] INFO com.redhat.rhn.taskomatic.task.SessionCleanup - 1 stale session(s) deleted INFO | jvm 1 | 2016/11/29 08:45:00 | 2016-11-29 08:45:00,032 [DefaultQuartzScheduler_Worker-4] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:46:00 | 2016-11-29 08:46:00,019 [DefaultQuartzScheduler_Worker-6] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:47:00 | 2016-11-29 08:47:00,019 [DefaultQuartzScheduler_Worker-4] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:48:00 | 2016-11-29 08:48:00,015 [DefaultQuartzScheduler_Worker-5] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:49:00 | 2016-11-29 08:49:00,019 [DefaultQuartzScheduler_Worker-4] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:50:00 | 2016-11-29 08:50:00,039 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:51:00 | 2016-11-29 08:51:00,020 [DefaultQuartzScheduler_Worker-5] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:52:00 | 2016-11-29 08:52:00,021 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:53:00 | 2016-11-29 08:53:00,026 [DefaultQuartzScheduler_Worker-5] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:54:00 | 2016-11-29 08:54:00,020 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:55:00 | 2016-11-29 08:55:00,031 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:56:00 | 2016-11-29 08:56:00,020 [DefaultQuartzScheduler_Worker-8] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:57:00 | 2016-11-29 08:57:00,018 [DefaultQuartzScheduler_Worker-6] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:58:00 | 2016-11-29 08:58:00,018 [DefaultQuartzScheduler_Worker-8] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 08:59:00 | 2016-11-29 08:59:00,020 [DefaultQuartzScheduler_Worker-6] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:00:00 | 2016-11-29 09:00:00,062 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:01:00 | 2016-11-29 09:01:00,018 [DefaultQuartzScheduler_Worker-1] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:02:00 | 2016-11-29 09:02:00,020 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:03:00 | 2016-11-29 09:03:00,022 [DefaultQuartzScheduler_Worker-9] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:04:00 | 2016-11-29 09:04:00,026 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:05:00 | 2016-11-29 09:05:00,026 [DefaultQuartzScheduler_Worker-1] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:06:00 | 2016-11-29 09:06:00,017 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:07:00 | 2016-11-29 09:07:00,017 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:08:00 | 2016-11-29 09:08:00,017 [DefaultQuartzScheduler_Worker-7] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:09:00 | 2016-11-29 09:09:00,023 [DefaultQuartzScheduler_Worker-3] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 Updated to spacewalk-java-2.3.8-157.el6sat, and repeated the reproducer steps (with a new "z" starting package, as the previous one was deleted during the reproduction). Content of /var/log/rhn/rhn_taskomatic_daemon.log: INFO | jvm 1 | 2016/11/29 09:29:00 | 2016-11-29 09:29:00,045 [DefaultQuartzScheduler_Worker-5] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 1 INFO | jvm 1 | 2016/11/29 09:29:00 | 2016-11-29 09:29:00,069 [Thread-95] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - File Modified Date:1969-12-31 19:00:00 EST INFO | jvm 1 | 2016/11/29 09:29:00 | 2016-11-29 09:29:00,069 [Thread-95] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Channel Modified Date:2016-11-29 09:26:30 EST INFO | jvm 1 | 2016/11/29 09:29:00 | 2016-11-29 09:29:00,153 [Thread-95] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Generating new repository metadata for channel 'centos6cloned2'(sha1) 6693 packages, 0 errata INFO | jvm 1 | 2016/11/29 09:29:18 | 2016-11-29 09:29:18,712 [Thread-95] ERROR com.redhat.rhn.taskomatic.task.ChannelRepodata - com.redhat.rhn.taskomatic.task.repomd.RepomdRuntimeException: Package with id 53916 removed from server, interrupting repo generation for centos6cloned2 INFO | jvm 1 | 2016/11/29 09:29:18 | com.redhat.rhn.taskomatic.task.repomd.RepomdRuntimeException: Package with id 53916 removed from server, interrupting repo generation for centos6cloned2 INFO | jvm 1 | 2016/11/29 09:29:18 | at com.redhat.rhn.taskomatic.task.repomd.RpmRepositoryWriter.writeRepomdFiles(RpmRepositoryWriter.java:194) INFO | jvm 1 | 2016/11/29 09:29:18 | at com.redhat.rhn.taskomatic.task.repomd.ChannelRepodataWorker.run(ChannelRepodataWorker.java:104) INFO | jvm 1 | 2016/11/29 09:29:18 | at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:761) INFO | jvm 1 | 2016/11/29 09:29:18 | at java.lang.Thread.run(Thread.java:809) INFO | jvm 1 | 2016/11/29 09:30:00 | 2016-11-29 09:30:00,119 [DefaultQuartzScheduler_Worker-1] INFO com.redhat.rhn.taskomatic.task.ChannelRepodata - In the queue: 2 INFO | jvm 1 | 2016/11/29 09:30:00 | 2016-11-29 09:30:00,158 [Thread-100] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - File Modified Date:1969-12-31 19:00:00 EST INFO | jvm 1 | 2016/11/29 09:30:00 | 2016-11-29 09:30:00,158 [Thread-100] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Channel Modified Date:2016-11-29 09:29:02 EST INFO | jvm 1 | 2016/11/29 09:30:00 | 2016-11-29 09:30:00,174 [Thread-101] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - File Modified Date:2016-11-29 08:27:02 EST INFO | jvm 1 | 2016/11/29 09:30:00 | 2016-11-29 09:30:00,174 [Thread-101] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Channel Modified Date:2016-11-29 09:29:02 EST INFO | jvm 1 | 2016/11/29 09:30:00 | 2016-11-29 09:30:00,247 [Thread-100] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Generating new repository metadata for channel 'centos6cloned2'(sha1) 6692 packages, 0 errata INFO | jvm 1 | 2016/11/29 09:30:00 | 2016-11-29 09:30:00,339 [Thread-101] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Generating new repository metadata for channel 'centos6chan'(sha1) 6692 packages, 0 errata INFO | jvm 1 | 2016/11/29 09:30:47 | 2016-11-29 09:30:47,463 [Thread-100] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Repository metadata generation for 'centos6cloned2' finished in 47 seconds INFO | jvm 1 | 2016/11/29 09:30:47 | 2016-11-29 09:30:47,705 [Thread-101] INFO com.redhat.rhn.taskomatic.task.repomd.RepositoryWriter - Repository metadata generation for 'centos6chan' finished in 47 seconds Taskomatic has correctly detected that a package was removed from the channel it's currently processing and restarted the metadata generation. Metadata were correctly generated after that (for all channels containing the removed package), and successfully finished. No stale taskomatic tasks in the queue. VERIFIED
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHBA-2017-0236.html