[Spacewalk-list] Sync profile failure
puck at i29.net
puck at i29.net
Fri Oct 3 14:46:09 UTC 2008
Yes, actually. I hadn't checked the tomcat logs.
[root at rhn ~]# cat catalina.out
Oct 3, 2008 9:17:39 AM
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
WARNING:
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector at 132b08d
-- APPARENT DEADLOCK!!! Creating emergency threads for unassigned
pending tasks!
Oct 3, 2008 9:17:39 AM
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
WARNING:
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector at 132b08d
-- APPARENT DEADLOCK!!! Complete Status: [num_managed_threads: 3,
num_active: 3; activeTasks:
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 3bb430
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0),
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 1b2c6b7
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1),
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 142dc4
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2);
pendingTasks:
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at c8ab35,
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 60500f]
Oct 3, 2008 9:27:39 AM
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
WARNING:
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector at 132b08d
-- APPARENT DEADLOCK!!! Creating emergency threads for unassigned
pending tasks!
Oct 3, 2008 9:27:39 AM
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
WARNING:
com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector at 132b08d
-- APPARENT DEADLOCK!!! Complete Status: [num_managed_threads: 3,
num_active: 3; activeTasks:
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at fe544
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0),
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 194d571
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2),
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 49061e
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1);
pendingTasks:
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 30c6cd,
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 4bbfe7,
com.mchange.v2.resourcepool.BasicResourcePool$5 at 1240e3c,
com.mchange.v2.resourcepool.BasicResourcePool$5 at 22b6f7,
com.mchange.v2.resourcepool.BasicResourcePool$5 at 11a1546,
com.mchange.v2.resourcepool.BasicResourcePool$5 at 16ad043,
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask at 18ee282]
Oct 3, 2008 9:28:44 AM com.mchange.v2.async.ThreadPoolAsynchronousRunner
processReplacedThreads
WARNING: Task
com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask at 49061e
(in deadlocked PoolThread) failed to complete in maximum time 60000ms.
Trying interrupt().
error_log contains an error similar to the following for each of the
matching errors in rhn_server_xmlrpc.log
RHN 29456 2008/10/03 09:15:46 -05:00: ("DATABASE CONNECTION TO 'xe'
LOST", "Exception information: (3114, 'ORA-03114: not connected to
ORACLE\\n', 'select sysdate as ID from dual')")
Exception reported from rhn.fccinteractive.com
Time: Fri Oct 3 09:15:10 2008
Exception type cx_Oracle.DatabaseError
Exception while handling function handler
Request object information:
URI: /XMLRPC
Remote Host: 10.0.1.166
Server Name: rhn.fccinteractive.com:0
Headers passed in:
Accept-Encoding: identity
Content-Length: 156953
Host: rhn.fccinteractive.com
content-type: text/xml
user-agent: rhn.rpclib.py/$Revision: 102540 $
x-client-version: 1
x-info: RPC Processor (C) Red Hat, Inc (version 102540)
x-rhn-client-capability:
packages.verifyAll(1)=1,caneatCheese(1)=1,packages.extended_profile(1)=1,reboot.reboot(1)=1,packages.verify(1)=1,packages.runTransaction(1)=1,packages.rollBack(1)=1
x-rhn-transport-capability: follow-redirects=2
x-transport-info: Extended Capabilities Transport (C) Red Hat, Inc
(version 102540)
x-up2date-version: 0.4.17-8.el5
Extra information about this error:
Unhandled exception type
Exception Handler Information
Traceback (most recent call last):
File "/usr/share/rhn/server/apacheServer.py", line 57, in __call__
ret = f(req)
File "/usr/share/rhn/server/apacheHandler.py", line 201, in handler
rhnSQL.rollback()
File "/usr/share/rhn/server/rhnSQL/__init__.py", line 150, in rollback
return db.rollback(name)
File "/usr/share/rhn/server/rhnSQL/int_oracle.py", line 402, in rollback
return self.dbh.rollback()
DatabaseError: ORA-03114: not connected to ORACLE
Jem Tallon
Coe, Colin C. (Unix Engineer) wrote:
> Anything interesting in /var/log/tomcat5/catalina.out or /var/log/httpd/error_log?
>
> CC
> ________________________________
> From: spacewalk-list-bounces at redhat.com [spacewalk-list-bounces at redhat.com] On Behalf Of puck at i29.net [puck at i29.net]
> Sent: Friday, 3 October 2008 10:34 PM
> To: spacewalk-list at redhat.com
> Subject: Re: [Spacewalk-list] Sync profile failure
>
> I realized after sending that last message that I didn't include enough information. Here is the result of a rhn-profile-sync:
>
> [root at rhn ~]# rhn-profile-sync -vvv
> updateLoginInfo() login info
> D: login(forceUpdate=True) invoked
> D: opening db environment /var/lib/rpm/Packages joinenv
> D: opening db index /var/lib/rpm/Packages rdonly mode=0x0
> D: locked db index /var/lib/rpm/Packages
> D: opening db index /var/lib/rpm/Providename rdonly mode=0x0
> logging into up2date server
> D: writeCachedLogin() invoked
> D: Wrote pickled loginInfo at 1223043347.21 with expiration of 1223046947.21 seconds.
> successfully retrieved authentication token from up2date server
> D: logininfo: {'X-RHN-Server-Id': 1000010127, 'X-RHN-Auth-Server-Time': '1223043347.2', 'X-RHN-Auth': 'VSwy2U4NUYZJNugO9X/fgQ==', 'X-RHN-Auth-Channels': [['centos-5-i386', '20080926021247', '1', '1']], 'X-RHN-Auth-User-Id': '', 'X-RHN-Auth-Expire-Offset': '3600.0'}
> Updating package profile...
> Updating package profile
> A protocol error occurred: Internal Server Error , attempt #1,
> A protocol error occurred: Internal Server Error , attempt #2,
> A protocol error occurred: Internal Server Error , attempt #3,
> A protocol error occurred: Internal Server Error , attempt #4,
> A protocol error occurred: Internal Server Error , attempt #5,
> An error has occurred:
> Internal Server Error
> Error communicating with server. The message was:
> Internal Server Error
> See /var/log/up2date for more information
> D: closed db index /var/lib/rpm/Providename
> D: closed db index /var/lib/rpm/Packages
> D: closed db environment /var/lib/rpm/Packages
> D: May free Score board((nil))
>
> And the accompanying rhn_server_xmlrpc.log output:
>
> 2008/10/03 09:15:46 -05:00 29456 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: (3114, 'ORA-03114: not connected to ORACLE\\n', 'select sysdate as ID from dual')")
> 2008/10/03 09:15:46 -05:00 29456 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 09:15:47 -05:00 29456 10.0.1.166: xmlrpc/up2date.login(1000010127,)
> 2008/10/03 09:15:47 -05:00 29449 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
> 2008/10/03 09:16:19 -05:00 30019 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
> 2008/10/03 09:18:25 -05:00 29453 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: (3114, 'ORA-03114: not connected to ORACLE\\n', 'select sysdate as ID from dual')")
> 2008/10/03 09:18:25 -05:00 29453 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 09:18:25 -05:00 29453 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
> 2008/10/03 09:24:41 -05:00 29457 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: (3114, 'ORA-03114: not connected to ORACLE\\n', 'select sysdate as ID from dual')")
> 2008/10/03 09:24:41 -05:00 29457 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 09:24:41 -05:00 29457 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
> 2008/10/03 09:29:22 -05:00 29591 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: (3114, 'ORA-03114: not connected to ORACLE\\n', 'select sysdate as ID from dual')")
> 2008/10/03 09:29:22 -05:00 29591 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 09:29:22 -05:00 29591 10.0.1.166: xmlrpc/up2date.listChannels(1000010127,)
> 2008/10/03 09:29:22 -05:00 29450 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: (3114, 'ORA-03114: not connected to ORACLE\\n', 'select sysdate as ID from dual')")
> 2008/10/03 09:29:22 -05:00 29450 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 09:29:55 -05:00 30540 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: ('Can not prepare statement', (3114, 'ORA-03114: not connected to ORACLE', ''))")
> 2008/10/03 09:29:55 -05:00 30540 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 09:29:57 -05:00 30540 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
>
> Jem Tallon
>
>
> puck at i29.net<mailto:puck at i29.net> wrote:
> I'm having this exact same issue. rhn_register seems to be able to create a profile but causes errors when trying to populate the package list. I also receive the errors below when I use rhn_check or rhn-profile-sync on a client. yum-rhn works fine and downloads updates, then those packages that were updated are added to the package list. Any ideas what might be causing this?
>
>
> *** Log file from running "rhn-profile-sync" then "yum update" ***
> 2008/10/03 08:47:37 -05:00 29451 10.0.1.166: xmlrpc/up2date.login(1000010127,)
> 2008/10/03 08:47:37 -05:00 29457 10.0.1.166: xmlrpc/up2date.listChannels(1000010127,)
> 2008/10/03 08:48:02 -05:00 29591 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: ('Can not prepare statement', (3114, 'ORA-03114: not connected to ORACLE', ''))")
> 2008/10/03 08:48:02 -05:00 29591 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 08:48:02 -05:00 29450 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: ('Can not prepare statement', (3114, 'ORA-03114: not connected to ORACLE', ''))")
> 2008/10/03 08:48:02 -05:00 29450 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 08:48:02 -05:00 30019 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: (3114, 'ORA-03114: not connected to ORACLE\\n', 'select sysdate as ID from dual')")
> 2008/10/03 08:48:02 -05:00 30019 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 08:48:02 -05:00 29452 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: ('Can not prepare statement', (3114, 'ORA-03114: not connected to ORACLE', ''))")
> 2008/10/03 08:48:02 -05:00 29452 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 08:48:12 -05:00 29592 10.0.1.166: rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO 'xe' LOST", "Exception information: (3114, 'ORA-03114: not connected to ORACLE\\n', 'select sysdate as ID from dual')")
> 2008/10/03 08:48:12 -05:00 29592 10.0.1.166: rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/10/03 08:48:12 -05:00 29592 10.0.1.166: xmlrpc/registration.delta_packages(1000010127, 'added: 6')
> 2008/10/03 08:48:14 -05:00 29590 10.0.1.166: xmlrpc/up2date.listChannels(1000010127,)
> 2008/10/03 08:48:36 -05:00 29449 10.0.1.166: xmlrpc/up2date.listChannels(1000010127,)
> 2008/10/03 08:48:56 -05:00 29455 10.0.1.166: xmlrpc/up2date.login(1000010127,)
> 2008/10/03 08:48:56 -05:00 29591 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
> 2008/10/03 08:49:04 -05:00 29450 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
> 2008/10/03 08:49:11 -05:00 30019 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
> 2008/10/03 08:50:13 -05:00 29452 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
> 2008/10/03 08:51:18 -05:00 29778 10.0.1.166: xmlrpc/registration.update_packages(1000010127, 'packages: 657')
>
>
> Jem Tallon
>
>
> ________________________________
>
> * From: "Jason Frisvold" <xenophage0 gmail com>
> * To: spacewalk-list redhat com
> * Subject: [Spacewalk-list] Sync profile failure
> * Date: Tue, 23 Sep 2008 09:58:45 -0400
>
> ________________________________
>
> Hi there,
>
> I'm getting an error when trying to sync my server profile with
> Spacewalk. This started when 0.2 was installed. As a result, the
> systems overview page doesn't reflect the current status of the system
> correctly, showing packages that need to be installed. If you choose
> details on a specific system, however, the details page shows
> everything up to date.
>
> This information is from the up2date log on the client system:
>
> [Tue Sep 23 09:31:48 2008] up2date updateLoginInfo() login info
> [Tue Sep 23 09:31:49 2008] up2date logging into up2date server
> [Tue Sep 23 09:31:51 2008] up2date successfully retrieved
> authentication token from up2date server
> [Tue Sep 23 09:31:51 2008] up2date Updating package profile
> [Tue Sep 23 09:31:57 2008] up2date A protocol error occurred: Internal
> Server Error , attempt #1,
> [Tue Sep 23 09:32:18 2008] up2date A protocol error occurred: Internal
> Server Error , attempt #2,
> [Tue Sep 23 09:33:15 2008] up2date A protocol error occurred: Internal
> Server Error , attempt #3,
> [Tue Sep 23 09:34:12 2008] up2date A protocol error occurred: Internal
> Server Error , attempt #4,
> [Tue Sep 23 09:36:03 2008] up2date A protocol error occurred: Internal
> Server Error , attempt #5,
> [Tue Sep 23 09:36:03 2008] up2date Error communicating with server.
> The message was:
> Internal Server Error
> [Tue Sep 23 09:36:03 2008] up2date
> Traceback (most recent call last):
> File "/usr/sbin/rhn-profile-sync", line 54, in ?
> cli.run()
> File "/usr/share/rhn/up2date_client/rhncli.py", line 65, in run
> sys.exit(self.main() or 0)
> File "/usr/sbin/rhn-profile-sync", line 42, in main
> rhnPackageInfo.updatePackageProfile()
> File "/usr/share/rhn/up2date_client/rhnPackageInfo.py", line 27, in
> updatePackageProfile
> rpmUtils.getInstalledPackageList(getArch=1))
> File "/usr/share/rhn/up2date_client/rhnserver.py", line 50, in __call__
> return rpcServer.doCall(method, *args, **kwargs)
> File "/usr/share/rhn/up2date_client/rpcServer.py", line 263, in doCall
> raise up2dateErrors.CommunicationError(e.errmsg)
> up2date_client.up2dateErrors.CommunicationError: Error communicating
> with server. The message was:
> Internal Server Error
>
>
> On the Spacewalk server, I have the following in the rhn_server_xmlrpc.log file:
>
> 2008/09/23 09:48:19 -04:00 21923 192.168.1.1:
> rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO
> 'xe' LOST", "Exception information: (3114, 'ORA-03114: not connected
> to ORACLE\\n', 'select sysdate as ID from dual')")
> 2008/09/23 09:48:19 -04:00 21923 192.168.1.1:
> rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/09/23 09:48:19 -04:00 21923 192.168.1.1: xmlrpc/up2date.login(1000010000,)
> 2008/09/23 09:48:20 -04:00 30476 192.168.1.1:
> rhnSQL/int_oracle.check_connection('ERROR', "DATABASE CONNECTION TO
> 'xe' LOST", "Exception information: ('Can not prepare statement',
> (3114, 'ORA-03114: not connected to ORACLE', ''))")
> 2008/09/23 09:48:20 -04:00 30476 192.168.1.1:
> rhnSQL/int_oracle.connect('Connecting to database', 'xe')
> 2008/09/23 09:48:21 -04:00 30476 192.168.1.1:
> xmlrpc/registration.update_packages(1000010000, 'packages: 653')
>
>
> So it appears that Oracle is to blame (again) ... I looked at the
> oracle status during this transaction and I have the following :
>
> [root dev rhn]# /sbin/service oracle-xe status
>
> LSNRCTL for Linux: Version 10.2.0.1.0 - Production on 23-SEP-2008 09:49:07
>
> Copyright (c) 1991, 2005, Oracle. All rights reserved.
>
> Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC_FOR_XE)))
> STATUS of the LISTENER
> ------------------------
> Alias LISTENER
> Version TNSLSNR for Linux: Version 10.2.0.1.0 - Production
> Start Date 19-SEP-2008 16:12:01
> Uptime 3 days 17 hr. 37 min. 6 sec
> Trace Level off
> Security ON: Local OS Authentication
> SNMP OFF
> Default Service XE
> Listener Parameter File
> /usr/lib/oracle/xe/app/oracle/product/10.2.0/server/network/admin/listener.ora
> Listener Log File
> /usr/lib/oracle/xe/app/oracle/product/10.2.0/server/network/log/listener.log
> Listening Endpoints Summary...
> (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC_FOR_XE)))
> (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=dev.example.com)(PORT=1521)))
> (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=127.0.0.1)(PORT=9000))(Presentation=HTTP)(Session=RAW))
> Services Summary...
> Service "PLSExtProc" has 1 instance(s).
> Instance "PLSExtProc", status UNKNOWN, has 1 handler(s) for this service...
> Service "XE" has 1 instance(s).
> Instance "XE", status READY, has 1 handler(s) for this service...
> Service "XEXDB" has 1 instance(s).
> Instance "XE", status READY, has 1 handler(s) for this service...
> Service "XE_XPT" has 1 instance(s).
> Instance "XE", status READY, has 1 handler(s) for this service...
> The command completed successfully
>
>
> I'm not familiar with Oracle, so I could use some assistance. Is the
> above problem caused by the single handler instance? Can that be
> increased? Or is it something else causing the problem?
>
> Thanks!
>
> --
> Jason 'XenoPhage' Frisvold
> XenoPhage0 gmail com
> http://blog.godshell.com
>
>
>
>
> ________________________________
>
> _______________________________________________
> Spacewalk-list mailing list
> Spacewalk-list at redhat.com<mailto:Spacewalk-list at redhat.com>
> https://www.redhat.com/mailman/listinfo/spacewalk-list
>
> NOTICE: This email and any attachments are confidential.
> They may contain legally privileged information or
> copyright material. You must not read, copy, use or
> disclose them without authorisation. If you are not an
> intended recipient, please contact us at once by return
> email and then delete both messages and all attachments.
>
>
>
>
More information about the Spacewalk-list
mailing list