[Date Prev][Date Next] [Chronological] [Thread] [Top]

No ProxyAuthz with SASL-GSSAPI?



Hi folks,

Although I've been able to get proxy authorization to work on Debian lenny systems using OpenLDAP 2.4.11 and Kerberos authentication with SASL-GSSAPI, and I've been able to get it to work on Debian squeeze using 2.4.23 (with Pierangelo's 2010-04-29 patch) and clear-text passwords, but for some reason I'm not having any same luck with the same patched 2.4.23 version when using Kerberos authentication with SASL-GSSAPI.

If I compare the two squeeze systems -- clear-text vs. SASL-GSSAPI -- while the loglevels are both set to -1, and try submitting a similar change on both consumer servers, lines with "parseProxyAuthz" and "PROXYAUTHZ" show up in the syslog of the clear-text system's provider server, but nothing of the sort shows up in the syslog on the SASL-GSSAPI system's provider server.

Instead, when attempting to add two objects -- cn=ccolumbus and uid=ccolumbus -- using the ldapadd utility as uid=admin on the consumer server, I see this kind of stuff in the logs:

======== begin log fragment consumer server ========================

Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: read active on 17
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Dec 23 18:54:16 ldapks2 slapd[29862]: connection_get(17)
Dec 23 18:54:16 ldapks2 slapd[29862]: connection_get(17): got connid=1003
Dec 23 18:54:16 ldapks2 slapd[29862]: connection_read(17): checking for input on id=1003
Dec 23 18:54:16 ldapks2 slapd[29862]: op tag 0x60, time 1293126856
Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 do_bind
Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnPrettyNormal: <>
Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnPrettyNormal: <>, <>
Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 BIND dn="" method=163
Dec 23 18:54:16 ldapks2 slapd[29862]: do_bind: dn () SASL mech GSSAPI
Dec 23 18:54:16 ldapks2 slapd[29862]: ==> sasl_bind: dn="" mech=<continuing> datalen=32 Dec 23 18:54:16 ldapks2 slapd[29862]: SASL Canonicalize [conn=1003]: authcid="admin" Dec 23 18:54:16 ldapks2 slapd[29862]: slap_sasl_getdn: conn 1003 id=admin [len=5] Dec 23 18:54:16 ldapks2 slapd[29862]: slap_sasl_getdn: u:id converted to uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnNormalize: <uid=admin,cn=EXAMPLE.COM,cn=GSSAPI,cn=auth> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnNormalize: <uid=admin,cn=example.com,cn=gssapi,cn=auth> Dec 23 18:54:16 ldapks2 slapd[29862]: ==>slap_sasl2dn: converting SASL name uid=admin,cn=example.com,cn=gssapi,cn=auth to a DN Dec 23 18:54:16 ldapks2 slapd[29862]: [rw] authid: "uid=admin,cn=example.com,cn=gssapi,cn=auth" -> "uid=admin,ou=people,dc=example,dc=com" Dec 23 18:54:16 ldapks2 slapd[29862]: slap_parseURI: parsing uid=admin,ou=people,dc=example,dc=com Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnNormalize: <uid=admin,ou=people,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnNormalize: <uid=admin,ou=people,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: <==slap_sasl2dn: Converted SASL name to uid=admin,ou=people,dc=example,dc=com Dec 23 18:54:16 ldapks2 slapd[29862]: slap_sasl_getdn: dn:id converted to uid=admin,ou=people,dc=example,dc=com Dec 23 18:54:16 ldapks2 slapd[29862]: SASL Canonicalize [conn=1003]: slapAuthcDN="uid=admin,ou=people,dc=example,dc=com" Dec 23 18:54:16 ldapks2 slapd[29862]: SASL proxy authorize [conn=1003]: authcid="admin@EXAMPLE.COM" authzid="admin@EXAMPLE.COM" Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 BIND authcid="admin@EXAMPLE.COM" authzid="admin@EXAMPLE.COM" Dec 23 18:54:16 ldapks2 slapd[29862]: SASL Authorize [conn=1003]: proxy authorization allowed authzDN=""
Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_sasl: err=0 len=-1
Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 BIND dn="uid=admin,ou=people,dc=example,dc=com" mech=GSSAPI sasl_ssf=56 ssf=56 Dec 23 18:54:16 ldapks2 slapd[29862]: do_bind: SASL/GSSAPI bind: dn="uid=admin,ou=people,dc=example,dc=com" sasl_ssf=56
Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_response: msgid=3 tag=97 err=0
Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=2 RESULT tag=97 err=0 text=
Dec 23 18:54:16 ldapks2 slapd[29862]: <== slap_sasl_bind: rc=0
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on 1 descriptor
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on:
Dec 23 18:54:16 ldapks2 slapd[29862]:
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on 1 descriptor
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on:
Dec 23 18:54:16 ldapks2 slapd[29862]:  17r
Dec 23 18:54:16 ldapks2 slapd[29862]:
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: read active on 17
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Dec 23 18:54:16 ldapks2 slapd[29862]: connection_get(17)
Dec 23 18:54:16 ldapks2 slapd[29862]: connection_get(17): got connid=1003
Dec 23 18:54:16 ldapks2 slapd[29862]: connection_read(17): checking for input on id=1003
Dec 23 18:54:16 ldapks2 slapd[29862]: op tag 0x68, time 1293126856
Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=3 do_add
Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=3 do_add: dn (cn=ccolumbus,ou=groups,dc=example,dc=com) Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com>, <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: conn=1003 op=3 ADD dn="cn=ccolumbus,ou=groups,dc=example,dc=com" Dec 23 18:54:16 ldapks2 slapd[29862]: bdb_dn2entry("cn=ccolumbus,ou=groups,dc=example,dc=com") Dec 23 18:54:16 ldapks2 slapd[29862]: => hdb_dn2id("cn=ccolumbus,ou=groups,dc=example,dc=com") Dec 23 18:54:16 ldapks2 slapd[29862]: <= hdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found (-30988) Dec 23 18:54:16 ldapks2 slapd[29862]: hdb_referrals: tag=104 target="cn=ccolumbus,ou=groups,dc=example,dc=com" matched="ou=groups,dc=example,dc=com"
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on 1 descriptor
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on:
Dec 23 18:54:16 ldapks2 slapd[29862]:
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: conn=1003 op=3 p=3
Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: err=10 matched="" text="" Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: referral="ldap://ldapks.example.com:389/cn=ccolumbus,ou=groups,dc=example,dc=com"; Dec 23 18:54:16 ldapks2 slapd[29862]: >>> dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: <<< dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com>, <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks2 slapd[29862]: ldap_back_db_open: URI=ldap://ldapks.example.com:389 Dec 23 18:54:16 ldapks2 slapd[29862]: ==> ldap_back_add("cn=ccolumbus,ou=groups,dc=example,dc=com")
Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: conn=1003 op=3 p=3
Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: err=8 matched="" text="modifications require authentication" Dec 23 18:54:16 ldapks2 slapd[29862]: <== ldap_back_add("cn=ccolumbus,ou=groups,dc=example,dc=com"): 8
Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: conn=1003 op=3 p=3
Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_result: err=8 matched="" text="" Dec 23 18:54:16 ldapks2 slapd[29862]: send_ldap_response: msgid=4 tag=105 err=8
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on 1 descriptor
Dec 23 18:54:16 ldapks2 slapd[29862]: daemon: activity on:
Dec 23 18:54:16 ldapks2 slapd[29862]:  17r

======== end log fragment consumer server ==========================

The only thing I think looks strange in the above is this line:

   SASL Authorize [conn=1003]:  proxy authorization allowed authzDN=""

Why is the authzDN empty?


======== begin log fragment provider server ========================

Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 1 descriptor
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on:
Dec 23 18:54:16 ldapks1 slapd[1265]:
Dec 23 18:54:16 ldapks1 slapd[1265]: slap_listener_activate(8):
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=8 busy
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Dec 23 18:54:16 ldapks1 slapd[1265]: >>> slap_listener(ldap:///)
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: listen=8, new connection on 18
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: added 18r (active) listener=(nil)
Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 fd=18 ACCEPT from IP=192.168.2.56:43112 (IP=0.0.0.0:389)
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 2 descriptors
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on:
Dec 23 18:54:16 ldapks1 slapd[1265]:  18r
Dec 23 18:54:16 ldapks1 slapd[1265]:
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: read active on 18
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Dec 23 18:54:16 ldapks1 slapd[1265]: connection_get(18)
Dec 23 18:54:16 ldapks1 slapd[1265]: connection_get(18): got connid=1004
Dec 23 18:54:16 ldapks1 slapd[1265]: connection_read(18): checking for input on id=1004
Dec 23 18:54:16 ldapks1 slapd[1265]: op tag 0x60, time 1293126856
Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=0 do_bind
Dec 23 18:54:16 ldapks1 slapd[1265]: >>> dnPrettyNormal: <>
Dec 23 18:54:16 ldapks1 slapd[1265]: <<< dnPrettyNormal: <>, <>
Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=0 BIND dn="" method=128
Dec 23 18:54:16 ldapks1 slapd[1265]: do_bind: version=3 dn="" method=128
Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_result: conn=1004 op=0 p=3
Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_result: err=0 matched="" text=""
Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_response: msgid=1 tag=97 err=0
Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=0 RESULT tag=97 err=0 text=
Dec 23 18:54:16 ldapks1 slapd[1265]: do_bind: v3 anonymous bind
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 1 descriptor
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on:
Dec 23 18:54:16 ldapks1 slapd[1265]:
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 1 descriptor
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on:
Dec 23 18:54:16 ldapks1 slapd[1265]:  18r
Dec 23 18:54:16 ldapks1 slapd[1265]:
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: read active on 18
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=8 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=9 active_threads=0 tvp=zero Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Dec 23 18:54:16 ldapks1 slapd[1265]: connection_get(18)
Dec 23 18:54:16 ldapks1 slapd[1265]: connection_get(18): got connid=1004
Dec 23 18:54:16 ldapks1 slapd[1265]: connection_read(18): checking for input on id=1004
Dec 23 18:54:16 ldapks1 slapd[1265]: op tag 0x68, time 1293126856
Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=1 do_add
Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=1 do_add: dn (cn=ccolumbus,ou=groups,dc=example,dc=com) Dec 23 18:54:16 ldapks1 slapd[1265]: >>> dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks1 slapd[1265]: <<< dnPrettyNormal: <cn=ccolumbus,ou=groups,dc=example,dc=com>, <cn=ccolumbus,ou=groups,dc=example,dc=com> Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=1 ADD dn="cn=ccolumbus,ou=groups,dc=example,dc=com"
Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_result: conn=1004 op=1 p=3
Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_result: err=8 matched="" text="modifications require authentication"
Dec 23 18:54:16 ldapks1 slapd[1265]: send_ldap_response: msgid=2 tag=105 err=8
Dec 23 18:54:16 ldapks1 slapd[1265]: conn=1004 op=1 RESULT tag=105 err=8 text=modifications require authentication
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on 1 descriptor
Dec 23 18:54:16 ldapks1 slapd[1265]: daemon: activity on:

======== end log fragment provider server ==========================

The ldapadd command on the consumer server gives:

   adding new entry "cn=ccolumbus,ou=groups,dc=example,dc=com"
   ldap_add: Strong(er) authentication required (8)


Some more background info. In the DIT, the consumer server is represented by and authorized to function as a proxy via this object:

dn: cn=ldapks2,ou=consumers,dc=example,dc=com
cn: ldapks2
objectClass: simpleSecurityObject
objectClass: organizationalRole
description: LDAP server2 replicator
authzTo: dn.regex:^uid=[^,]+,ou=people,dc=example,dc=com$
userPassword:: e0NSWVBUfSo=
structuralObjectClass: organizationalRole
entryUUID: d939b140-a341-102f-8cd1-6f46e6760f2b
creatorsName: uid=admin,ou=people,dc=example,dc=com
createTimestamp: 20101224003819Z
entryCSN: 20101224003819.303636Z#000000#000#000000
modifiersName: uid=admin,ou=people,dc=example,dc=com
modifyTimestamp: 20101224003819Z

When the consumer, ldapks2, synchronizes with the provider, ldapks1, the consumer also shows up in the syslog on the provider server as cn=ldapks2,ou=consumers,dc=example,dc=com. That's a good sign, although after adding the relevant olcAuthzRegexp on the provider, it began to work that way after I had restarted slapd.


On the provider, the cn=config DIT looks like this:

======== begin cn=config DIT fragment provider server ==============

dn: cn=config
objectClass: olcGlobal
cn: config
olcArgsFile: /var/run/slapd/slapd.args
olcAuthzPolicy: to
olcAuthzRegexp: {0}uid=ldap/([^/\.]+).example.com,cn=example.com,cn=gssapi,cn=
 auth cn=$1,ou=consumers,dc=example,dc=com
olcAuthzRegexp: {1}uid=([^,]+),cn=example.com,cn=gssapi,cn=auth uid=$1,ou=peop
 le,dc=example,dc=com
olcLogLevel: stats
olcPidFile: /var/run/slapd/slapd.pid
olcSaslRealm: EXAMPLE.COM
olcToolThreads: 1

dn: olcDatabase={1}hdb,cn=config
objectClass: olcDatabaseConfig
objectClass: olcHdbConfig
olcDatabase: {1}hdb
olcDbDirectory: /var/lib/ldap
olcSuffix: dc=example,dc=com
olcAccess: {0}to attrs=userPassword,shadowLastChange by dn.one="ou=consumers,d
 c=example,dc=com" read by * none
olcAccess: {1}to attrs=loginShell by dn.one="ou=consumers,dc=example,dc=com" r
 ead by self write by * none
olcAccess: {2}to dn.base="" by * read
olcAccess: {3}to * by users read by * none
olcLastMod: TRUE
olcRootDN: uid=admin,ou=people,dc=example,dc=com
olcDbCheckpoint: 512 30
olcDbConfig: {0}set_cachesize 0 2097152 0
olcDbConfig: {1}set_lk_max_objects 1500
olcDbConfig: {2}set_lk_max_locks 1500
olcDbConfig: {3}set_lk_max_lockers 1500
olcDbIndex: objectClass eq
olcDbIndex: uid eq
olcDbIndex: cn eq
olcDbIndex: ou eq
olcDbIndex: dc eq
olcDbIndex: entryUUID eq
olcDbIndex: entryCSN eq

======== end cn=config DIT fragment provider server ================


Chaining is enabled on the consumer server:

======== begin cn=config DIT fragment consumer server ==============

dn: cn=module{0},cn=config
objectClass: olcModuleList
cn: module{0}
olcModulePath: /usr/lib/ldap
olcModuleLoad: {0}back_hdb
olcModuleLoad: {1}back_ldap

dn: olcOverlay={0}chain,olcDatabase={-1}frontend,cn=config
objectClass: olcOverlayConfig
objectClass: olcChainConfig
olcOverlay: {0}chain
olcChainReturnError: TRUE

dn: olcDatabase={0}ldap,olcOverlay={0}chain,olcDatabase={-1}frontend,cn=config
objectClass: olcLDAPConfig
objectClass: olcChainDatabase
olcDatabase: {0}ldap
olcDbURI: "ldap://ldapks.example.com:389/";
olcDbIDAssertBind: bindmethod=sasl saslmech=gssapi mode=self
olcDbRebindAsUser: TRUE

dn: olcDatabase={1}hdb,cn=config
objectClass: olcDatabaseConfig
objectClass: olcHdbConfig
olcDatabase: {1}hdb
olcDbDirectory: /var/lib/ldap
olcSuffix: dc=example,dc=com
olcAccess: {0}to attrs=userPassword,shadowLastChange by * none
olcAccess: {1}to attrs=loginShell by self read by * none
olcAccess: {2}to dn.base="" by * read
olcAccess: {3}to * by users read by * none
olcLastMod: TRUE
olcRootDN: cn=manager
olcSyncrepl: {0}rid=123 provider="ldap://ldapks.example.com:389/"; type=refresh
 AndPersist retry="60 30 300 +" searchbase="dc=example,dc=com" bindmethod=sasl
  saslmech=gssapi
olcUpdateRef: "ldap://ldapks.example.com:389/";
olcDbCheckpoint: 512 30
olcDbConfig: {0}set_cachesize 0 2097152 0
olcDbConfig: {1}set_lk_max_objects 1500
olcDbConfig: {2}set_lk_max_locks 1500
olcDbConfig: {3}set_lk_max_lockers 1500
olcDbIndex: objectClass eq
olcDbIndex: entryCSN eq
olcDbIndex: entryUUID eq
olcDbIndex: uid eq
olcDbIndex: cn eq
olcDbIndex: ou eq
olcDbIndex: dc eq

======== end cn=config DIT fragment consumer server ================

BTW, "ldapks.example.com" is an alias for "ldapks1.example.com."


That's pretty much it, I think. Is this problem due to another bug, or have I made a mistake somewhere?

Thanks,

Jaap