Need to get katello-debug output with these sort of BZs and versions of products (candlepin, pulp, etc.)

katello-debug output is already attached.

the versions of cp pulp etc are whatever is required by the version of katello, but here they are:

/scpc:root.120.93: #$ rpm -qa | grep candlepin*
candlepin-selinux-0.7.22-1.el6.noarch
candlepin-0.7.22-1.el6.noarch
candlepin-tomcat6-0.7.22-1.el6.noarch
katello-candlepin-cert-key-pair-1.0-1.noarch
katello-glue-candlepin-1.3.0-1.git.56.71ad281.el6_3.noarch
/scpc:root.120.93: #$ rpm -qa | grep pulp
python-oauth2-1.5.170-2.pulp.el6.noarch
pulp-1.1.12-1.el6.noarch
m2crypto-0.21.1.pulp-7.el6.x86_64
katello-glue-pulp-1.3.0-1.git.56.71ad281.el6_3.noarch
mod_wsgi-3.3-3.pulp.el6.x86_64
pulp-common-1.1.12-1.el6.noarch
pulp-selinux-server-1.1.12-1.el6.noarch
/scpc:root.120.93: #$ rpm -qa | grep foreman
katello-glue-foreman-1.3.0-1.git.56.71ad281.el6_3.noarch
rubygem-foreman_api-0.0.8-1.el6.noarch
foreman-postgresql-1.0.1-40.fc9ba74.el6.noarch
foreman-1.0.1-40.fc9ba74.el6.noarch
/scpc:root.120.93: #$

I can't seem to find any such error in the catalina.out in the attached zip, are we sure this is from the right server?

Could you check and report on the perms of everything leading to /var/cache/candlepin/sync (assuming they do exist).

Was tomcat recently upgraded on this system?

Logged in myself to check, perms are are looking fine on 10.16.120.93 at least, still can't find evidence of that exception on this system though.

The original report shows Dec 12, all the logs on the system look to start on Dec 13th.

Need some info on this one, something's not adding up.

Thanks!

This was a continuous integration system, next run the error did not surface. CI system is apparently doing some things with how the rpms are installed  and then upgraded before katello-configure is run, rpm upgrades could be involved here but I'm far from certain.

Problem does not surface for developers, and as far as we know nobody's seen this in a regular installation either.

The exception is thrown if /var/cache/candlepin/sync does not exist and we cannot create it (which would be attempted as the tomcat user candlepin is running as).

/var/cache/candlepin is owned by the candlepin-tomcat6 package. 


%defattr(644,tomcat,tomcat,775)
%{_localstatedir}/cache/%{name}

Nothing has changed around this in a very long time. (7-8 months)

Holding until we have a reproducer or environment where it's happening.

Can replicate on a dev server if I move /var/cache/candlepin and try to import.

The fact that nothing is getting logged for candlepin is looking like a bug in our code, if you don't have debug on you won't have any indication of the error in our logs, only the displayMessage in response sent to caller.

This isn't the cause just an explanation of why we're getting nothing in catalina.out.

As for why the CI system suddenly had no /var/cache/candlepin, still unsure, and holding until we see it again.

Bug surfaced again, in both set of logs I now notice something like this:

Dec 12 17:35:45 [http-8443-4] INFO  org.candlepin.resource.OwnerResource - Importing archive /var/cache/tomcat6/temp/pfx1606609630550696439sfx for owner man-reuse-1212-173535-220
Dec 12 17:35:45 [http-8443-3] INFO  org.candlepin.resource.OwnerResource - Importing archive /var/cache/tomcat6/temp/pfx4444889783006217487sfx for owner dup-manifest-1212-173534-903
Dec 12 17:35:45 [http-8443-4] INFO  org.candlepin.sync.Importer - Extracting archive to: /var/cache/candlepin/sync/import1738555957853794164969369865921
Dec 12 17:35:45 [http-8443-4] INFO  org.candlepin.sync.Importer - Extracting archive to: /var/cache/candlepin/sync/import1738555957853794164969369865921
Dec 12 17:35:45 [http-8443-3] INFO  org.candlepin.resource.OwnerResource - Import attempt completed for owner dup-manifest-1212-173534-903
Dec 12 17:35:45 [http-8443-4] WARN  org.candlepin.sync.Importer - Incompatible rules: import version 0.5.11-1 older than our version 0.7.22.
Dec 12 17:35:45 [http-8443-4] WARN  org.candlepin.sync.Importer - Manifest data will be imported without rules import.
Dec 12 17:35:45 [http-8443-3] INFO  org.candlepin.resource.OwnerResource - Deleting all subscriptions from manifests for owner: dup-manifest-1212-173534-903
Dec 12 17:35:46 [http-8443-4] INFO  org.candlepin.resource.OwnerResource - Import attempt completed for owner man-reuse-1212-173535-220

The issue appears to not be related to importing twice into same org but rather two imports coming in at exactly the same second and trying to extract into the same directory.

Working on test reproducer and fix now.

Severity of the bug in the real world is probably quite low, simultaneous imports would be quite hard to trigger, and a repeat attempt would likely work fine. (no serious consequences)

I am not sure how likely a user is to automate importing of manifests.  But if they did, I would guess they would likely just script it with bash and katello cli.

However if they wanted to be clever and make it go faster, they would fork each import command, and then they *would* be likely to hit this problem.

From email discussion with Jesus:

 I noticed that we're using System.nanoTime() to create unique filenames. This javadoc looks suspicious. I wonder if we've hit a case where it actually came back with the same number?

http://docs.oracle.com/javase/1.5.0/docs/api/java/lang/System.html#nanoTime()


Also the two log statements stating "Importing archive" are correctly handled by 2 threads (-4 and -3).

Dec 12 17:35:45 [http-8443-4] INFO  org.candlepin.resource.OwnerResource - Importing archive /var/cache/tomcat6/temp/pfx1606609630550696439sfx for owner man-reuse-1212-173535-220
Dec 12 17:35:45 [http-8443-3] INFO  org.candlepin.resource.OwnerResource - Importing archive /var/cache/tomcat6/temp/pfx4444889783006217487sfx for owner dup-manifest-1212-173534-903

Now notice the lines that indicate "Extracting archive" are showing the SAME thread (-4).

Dec 12 17:35:45 [http-8443-4] INFO  org.candlepin.sync.Importer - Extracting archive to: /var/cache/candlepin/sync/import1738555957853794164969369865921
Dec 12 17:35:45 [http-8443-4] INFO  org.candlepin.sync.Importer - Extracting archive to: /var/cache/candlepin/sync/import1738555957853794164969369865921

Unfortunately, I had four threads going making temp files and each doing 100,000 couldn't get a collision. That's not to say that over time we wouldn't get one, but it's very odd.

One other idea is verify that the Importer code doesn't have any local variables that it is maintaining in this area (nothing popped out at me) and double check Guice to make sure we're not starting it in a dumb manner.

I think we need to postpone to focus on some other more pressing work, but definitely something here we need to investigate particularly if there's a threading issue.

There is now a friendly error message which is shown. Moving this to ON_QA.

Now I see an user message in UI: "Subscription manifest import for provider 'Red Hat' skipped
Reason: Manifest subscriptions unchanged from previous"

But /var/log/katello/delayed_jobs.log still shows the error as mentioned in this BZ.  I think we should not log the exception in delayed_jobs.log if we are catching it and throwing a friendly user message in UI.

Package tested:
* candlepin-0.8.19-1.el6sam.noarch
* candlepin-scl-1-5.el6_4.noarch
* candlepin-scl-quartz-2.1.5-5.el6_4.noarch
* candlepin-scl-rhino-1.7R3-1.el6_4.noarch
* candlepin-scl-runtime-1-5.el6_4.noarch
* candlepin-selinux-0.8.19-1.el6sam.noarch
* candlepin-tomcat6-0.8.19-1.el6sam.noarch
* elasticsearch-0.19.9-8.el6sat.noarch
* katello-candlepin-cert-key-pair-1.0-1.noarch
* katello-certs-tools-1.4.2-2.el6sat.noarch
* katello-cli-1.4.3-5.el6sat.noarch
* katello-cli-common-1.4.3-5.el6sat.noarch
* katello-common-1.4.3-6.el6sam_splice.noarch
* katello-configure-1.4.4-2.el6sat.noarch
* katello-glue-candlepin-1.4.3-6.el6sam_splice.noarch
* katello-glue-elasticsearch-1.4.3-6.el6sam_splice.noarch
* katello-headpin-1.4.3-6.el6sam_splice.noarch
* katello-headpin-all-1.4.3-6.el6sam_splice.noarch
* katello-selinux-1.4.4-2.el6sat.noarch
* thumbslug-0.0.32-1.el6sam.noarch
* thumbslug-selinux-0.0.32-1.el6sam.noarch

Moving to NEW to get it looked at.

Per coment 17, the fix should be to not log the 409 to stdout, since that is a valid use case:

2013-10-30T12:27:21-0400: [Worker(delayed_job host:sam13 pid:1635)] Provider#queue_import_manifest failed with RestClient::Conflict: Resources::Candlepin::Owner: 409 Conflict {"displayMessage":"Import is the same as existing data","requestUuid":"17f3fb96-525f-4c3c-8d43-721578bcd05e","conflicts":["MANIFEST_SAME"]} (POST /candlepin/owners/ACME_Corporation/imports) - 0 failed attempts
2013-10-30T12:27:21-0400: [Worker(delayed_job host:sam13 pid:1635)] PERMANENTLY removing Provider#queue_import_manifest because of 1 consecutive failures.
Resources::Candlepin::Owner: 409 Conflict {"displayMessage":"Import is the same as existing data","requestUuid":"17f3fb96-525f-4c3c-8d43-721578bcd05e","conflicts":["MANIFEST_SAME"]} (POST /candlepin/owners/ACME_Corporation/imports)

Please ignore my comment in Comment 17 requesting to not log the exception.

In SAM 1.4 importing the same manifest again provides the following UI error which is good enough:
Subscription manifest import for provider 'Red Hat' skipped
Reason: Manifest subscriptions unchanged from previous