Probleme bei Softwareinstallation mit der Session
Verfasst: 05 Okt 2009, 16:35
Heute haben wir wieder viele Pakete via OPSI Verteilen müssen. Dabei ist (eigentlich mal wieder) aufgefallen, das bei vielen Rechnern die Rückmeldung nicht funktionierte, obwohl offensichtlich die Pakete ordentlich installiert bzw. geupdatet wurden.
Eine Analyse des LOG Files erbrachte dann das mitten während der Installation auf einmal die Authorisierung für den User verloren gegangen ist. In den Logfiles winnelt es plötzlich bei den JSON Aufrunfen Von Fehlern die wie folgt beginnen: 'Access denied: Connection as user ...'.
Ich habe nun das LOG File auf den Server in den DEBUG Modus gebracht und mal versucht die genaue Ursache für das Problem herauszufinden. Und so wie es aussieht, nehmen sich die Clients gegenseitig die Session bzw. die Authorisierung weg.
Hier mal ein Auszug aus zwei Logfiles:
Wie man sieht, tauchen die Probleme an Rechner1 erst auf,, nachdem Rechner 2 sich angemeldet hat.
Außerdem Taucht im Log File vom Rechner2 auf einmal die IP von Rechner1 auf.
Die Frage ist, wo kommt dieses Problem her. Ich vermute ja, das Problem ist, das wir für unsere Clients keine DNS Auflösung haben und in der Session dann ein Leerstring für den Hostname gespeichert wird, anstatt der IP Adresse (die ja sonst genommen wird).
Wir setzen bei uns in der Firma übrigens noch OPSI 3.1 (opsiconfd 1.0) allerdings mit winst 4.6.1.1, pcpatch 3.8.8.0 und prelogin 1.1.2.13.
Sollte der Bug inzwischen behoben sein wäre das natürlich für mein ein Anlass mal wieder ein Update auszuführen (mein Chef lebt halt nach der Devise: never Change a Running System und bis jetzt ist uns dieser Fehler noch gar nicht so sehr aufgefallen).
Eine Analyse des LOG Files erbrachte dann das mitten während der Installation auf einmal die Authorisierung für den User verloren gegangen ist. In den Logfiles winnelt es plötzlich bei den JSON Aufrunfen Von Fehlern die wie folgt beginnen: 'Access denied: Connection as user ...'.
Ich habe nun das LOG File auf den Server in den DEBUG Modus gebracht und mal versucht die genaue Ursache für das Problem herauszufinden. Und so wie es aussieht, nehmen sich die Clients gegenseitig die Session bzw. die Authorisierung weg.
Hier mal ein Auszug aus zwei Logfiles:
Code: Alles auswählen
./192.168.178.101.log:5246:(6) Okt 05 14:18:18 Modifying Object in LDAP, dn: 'cn=rechner1,ou=Machines,o=HS,dc=domaene,dc=intern' (LDAP.py|3312)
./192.168.178.101.log:5247:(6) Okt 05 14:18:18 RPC method: 'authenticated' params: '[]' (opsiconfd|787)
./192.168.178.101.log:5248:(5) Okt 05 14:18:18 Executing: authenticated() (opsiconfd|813)
./192.168.178.101.log:5249:(5) Okt 05 14:18:18 Got result... (opsiconfd|818)
./192.168.178.101.log:5250:(5) Okt 05 14:18:18 Took 0.000s to process authenticated() (opsiconfd|829)
./192.168.178.101.log:5251:(5) Okt 05 14:18:18 Now using log-file: '/var/log/opsi/opsiconfd/192.168.178.101.log' for thread -1230062704 (Logger.py|233)
./192.168.178.101.log:5252:(5) Okt 05 14:18:18 Reusing session '********************************' for client '192.168.178.101' (opsiconfd|553)
./192.168.178.101.log:5253:(5) Okt 05 14:18:18 Storing hostname '' in session (opsiconfd|586)
./192.168.178.101.log:5254:(5) Okt 05 14:18:18 Got json-rpc request: {'params': ['rechner1.domaene.intern'], 'id': 1, 'method': 'getNetworkConfig_hash'} (opsiconfd|713)
./192.168.178.101.log:5255:(6) Okt 05 14:18:18 RPC method: 'getNetworkConfig_hash' params: '['rechner1.domaene.intern']' (opsiconfd|787)
./192.168.178.101.log:5256:(5) Okt 05 14:18:18 Executing: getNetworkConfig_hash('rechner1.domaene.intern') (opsiconfd|813)
./192.168.178.101.log:5257:(2) Okt 05 14:18:18 line 746 in 'run' in file '/usr/sbin/opsiconfd' (opsiconfd|756)
./192.168.178.101.log:5258:(2) Okt 05 14:18:18 line 817 in 'execute' in file '/usr/sbin/opsiconfd' (opsiconfd|756)
./192.168.178.101.log:5259:(2) Okt 05 14:18:18 line 0 in '?' in file '<string>' (opsiconfd|756)
./192.168.178.101.log:5260:(2) Okt 05 14:18:18 line 75 in 'getNetworkConfig_hash' in file '/etc/opsi/backendManager.d/50_interface.conf' (opsiconfd|756)
./192.168.178.101.log:5261:(2) Okt 05 14:18:18 line 393 in '_verifyUser' in file '/usr/lib/python2.4/site-packages/OPSI/Backend/BackendManager.py' (opsiconfd|756)
./192.168.178.101.log:5262:(2) Okt 05 14:18:18 Access denied: Connection as user 'rechner1.domaene.intern' required! (opsiconfd|760)
./192.168.178.101.log:5263:(5) Okt 05 14:18:18 Now using log-file: '/var/log/opsi/opsiconfd/192.168.178.101.log' for thread -1221670000 (Logger.py|233)
./192.168.178.101.log:5264:(5) Okt 05 14:18:18 Reusing session '********************************' for client '192.168.178.101' (opsiconfd|553)
./192.168.178.101.log:5265:(5) Okt 05 14:18:18 Storing hostname '' in session (opsiconfd|586)
./192.168.178.101.log:5266:(5) Okt 05 14:18:18 Got json-rpc request: {'params': ['rechner1.domaene.intern'], 'id': 1, 'method': 'getNetworkConfig_hash'} (opsiconfd|713)
./192.168.178.101.log:5267:(6) Okt 05 14:18:18 RPC method: 'getNetworkConfig_hash' params: '['rechner1.domaene.intern']' (opsiconfd|787)
./192.168.178.101.log:5268:(5) Okt 05 14:18:18 Executing: getNetworkConfig_hash('rechner1.domaene.intern') (opsiconfd|813)
./192.168.178.101.log:5269:(2) Okt 05 14:18:18 line 746 in 'run' in file '/usr/sbin/opsiconfd' (opsiconfd|756)
./192.168.178.101.log:5270:(2) Okt 05 14:18:18 line 817 in 'execute' in file '/usr/sbin/opsiconfd' (opsiconfd|756)
./192.168.178.101.log:5271:(2) Okt 05 14:18:18 line 0 in '?' in file '<string>' (opsiconfd|756)
./192.168.178.101.log:5272:(2) Okt 05 14:18:18 line 75 in 'getNetworkConfig_hash' in file '/etc/opsi/backendManager.d/50_interface.conf' (opsiconfd|756)
./192.168.178.101.log:5273:(2) Okt 05 14:18:18 line 393 in '_verifyUser' in file '/usr/lib/python2.4/site-packages/OPSI/Backend/BackendManager.py' (opsiconfd|756)
./192.168.178.101.log:5274:(2) Okt 05 14:18:18 Access denied: Connection as user 'rechner1.domaene.intern' required! (opsiconfd|760)
./192.168.178.101.log:5275:(5) Okt 05 14:18:18 Now using log-file: '/var/log/opsi/opsiconfd/192.168.178.101.log' for thread -1240302704 (Logger.py|233)
Code: Alles auswählen
./192.168.178.102.log:1669:(5) Okt 05 14:18:18 Now using log-file: '/var/log/opsi/opsiconfd/192.168.178.102.log' for thread -1221670000 (Logger.py|233)
./192.168.178.102.log:1670:(4) Okt 05 14:18:18 Client '192.168.178.102' did not send cookie (opsiconfd|533)
./192.168.178.102.log:1671:(4) Okt 05 14:18:18 New session created (opsiconfd|550)
./192.168.178.102.log:1672:(5) Okt 05 14:18:18 Storing hostname '' in session (opsiconfd|586)
./192.168.178.102.log:1673:(6) Okt 05 14:18:18 Trying to get username and password from Authorization header (opsiconfd|592)
./192.168.178.102.log:1674:(6) Okt 05 14:18:18 Authorization header found (opsiconfd|595)
./192.168.178.102.log:1675:(5) Okt 05 14:18:18 Got json-rpc request: {'params': [], 'id': 1, 'method': 'authenticated'} (opsiconfd|713)
./192.168.178.102.log:1676:(4) Okt 05 14:18:18 Authorization request from rechner2.domaene.intern@192.168.178.102 (opsiconfd|617)
./192.168.178.102.log:1677:(3) Okt 05 14:18:19 Failed to resolve hostname 'rechner2.domaene.intern': (-2, 'Der Name oder der Dienst ist nicht bekannt') (opsiconfd|633)
./192.168.178.102.log:1678:(4) Okt 05 14:18:19 Host login attempt with username 'rechner2.domaene.intern' from ip '192.168.178.101', but name resolves to '[]', ip verification is disabled (access granted) (opsiconf
d|644)
./192.168.178.102.log:1679:(5) Okt 05 14:18:19 OS reports 'domaene.intern' as default domain (BackendManager.py|84)
./192.168.178.102.log:1680:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/10_file.conf' (BackendManager.py|321)
./192.168.178.102.log:1681:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/11_ldap.conf' (BackendManager.py|321)
./192.168.178.102.log:1682:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/12_univention.conf' (BackendManager.py|321)
./192.168.178.102.log:1683:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/13_dhcpd.conf' (BackendManager.py|321)
./192.168.178.102.log:1684:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/14_reinstmgr.conf' (BackendManager.py|321)
./192.168.178.102.log:1685:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/15_jsonrpc.conf' (BackendManager.py|321)
./192.168.178.102.log:1686:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/16_etherwake.conf' (BackendManager.py|321)
./192.168.178.102.log:1687:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/17_wakeonlan.conf' (BackendManager.py|321)
./192.168.178.102.log:1688:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/18_opsipxeconfd.conf' (BackendManager.py|321)
./192.168.178.102.log:1689:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/20_file31.conf' (BackendManager.py|321)
./192.168.178.102.log:1690:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/30_vars.conf' (BackendManager.py|321)
./192.168.178.102.log:1691:(5) Okt 05 14:18:19 Reading config file '/etc/opsi/backendManager.d/50_interface.conf' (BackendManager.py|321)Außerdem Taucht im Log File vom Rechner2 auf einmal die IP von Rechner1 auf.
Die Frage ist, wo kommt dieses Problem her. Ich vermute ja, das Problem ist, das wir für unsere Clients keine DNS Auflösung haben und in der Session dann ein Leerstring für den Hostname gespeichert wird, anstatt der IP Adresse (die ja sonst genommen wird).
Wir setzen bei uns in der Firma übrigens noch OPSI 3.1 (opsiconfd 1.0) allerdings mit winst 4.6.1.1, pcpatch 3.8.8.0 und prelogin 1.1.2.13.
Sollte der Bug inzwischen behoben sein wäre das natürlich für mein ein Anlass mal wieder ein Update auszuführen (mein Chef lebt halt nach der Devise: never Change a Running System und bis jetzt ist uns dieser Fehler noch gar nicht so sehr aufgefallen).