autobuild[sn-devel-144]: intermittent test failure detected

Sat Jun 16 11:08:03 UTC 2018

The autobuild test system (on sn-devel-144) has detected an intermittent failing test in 
the current master tree.

The autobuild log of the failure is available here:

   https://git.samba.org/autobuild.flakey.sn-devel-144/2018-06-16-1308/flakey.log

The failure seems to be in the "samba-ad-dc" suite, whose build logs are available here:

   https://git.samba.org/autobuild.flakey.sn-devel-144/2018-06-16-1308/samba-ad-dc.stderr
   https://git.samba.org/autobuild.flakey.sn-devel-144/2018-06-16-1308/samba-ad-dc.stdout

The top commit at the time of the failure was:

commit 5d4f2294c9eeec31f9d087e4fb70611d8d824db8
Author: Günther Deschner <gd at samba.org>
Date:   Tue Jun 12 12:54:15 2018 +0200

    s4-dsdb: fix the build of audit_util.c

    Guenther

    Signed-off-by: Guenther Deschner <gd at samba.org>
    Reviewed-by: Volker Lendecke <vl at samba.org>

    Autobuild-User(master): Volker Lendecke <vl at samba.org>
    Autobuild-Date(master): Sat Jun 16 11:56:53 CEST 2018 on sn-devel-144

and the last 50 lines of the stdout log were:

INFO: Received PING message from server 1128664.2147483652 []
INFO: Received PING message from server 1128664.3323252262 []
{"timestamp": "2018-06-16T13:07:47.010873+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131736208670088620"}]}]}, "logonCount": {"actions": [{"action": "replace", "values": [{"value": "2"}]}]}}, "version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Modify", "remoteAddress": null, "performedAsSystem": false, "userSid": "S-1-5-18", "dn": "CN=auditlogtestuser02,CN=Users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "3576a2bc-f4ee-4991-9af4-d7309a9e451c", "sessionId": "ddd78ea9-1601-4a91-9ac0-4e28f2c2fc5c"}}
INFO: Received PING message from server 1128664.195 []
{"timestamp": "2018-06-16T13:07:47.209968+0200", "Authorization": {"authType": "ncacn_np", "domain": "ADDOMAIN", "serviceDescription": "DCE/RPC", "version": {"major": 1, "minor": 1}, "logonServer": "ADDC", "remoteAddress": "ipv4:127.0.0.11:41924", "localAddress": "ipv4:127.0.0.30:445", "account": "auditlogtestuser02", "accountFlags": "0x00000010", "sid": "S-1-5-21-3363883447-1967130412-1579653200-1808", "sessionId": "6e2ec7fa-14d0-43da-817b-e7e0694f501f", "transportProtection": "SMB"}, "type": "Authorization"}
INFO: Received PING message from server 1128664.1134818088 []
{"timestamp": "2018-06-16T13:07:47.220781+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"clearTextPassword": {"actions": [{"action": "replace", "redacted": true}]}}, "version": {"major": 1, "minor": 0}, "status": "insufficient access rights", "statusCode": 50, "operation": "Modify", "remoteAddress": "ipv4:127.0.0.11:41924", "performedAsSystem": false, "userSid": "S-1-5-21-3363883447-1967130412-1579653200-1808", "dn": "CN=auditlogtestuser,CN=Users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "8619f361-7e3b-48ca-aca3-84511f19290a", "sessionId": "6e2ec7fa-14d0-43da-817b-e7e0694f501f"}}
INFO: Received PING message from server 1128664.1134818088 []
{"timestamp": "2018-06-16T13:07:47.220994+0200", "dsdbTransaction": {"action": "rollback", "version": {"major": 1, "minor": 0}, "transactionId": "8619f361-7e3b-48ca-aca3-84511f19290a"}, "type": "dsdbTransaction"}
INFO: Received PING message from server 1128664.2147483652 []
INFO: Received PING message from server 1128664.3323252262 []
{"timestamp": "2018-06-16T13:07:47.425818+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131736208674239370"}]}]}, "logonCount": {"actions": [{"action": "replace", "values": [{"value": "2391"}]}]}}, "version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Modify", "remoteAddress": null, "performedAsSystem": false, "userSid": "S-1-5-18", "dn": "CN=Administrator,CN=Users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "01e0cfad-c6db-40b7-9074-1ef82e2e91c2", "sessionId": "ddd78ea9-1601-4a91-9ac0-4e28f2c2fc5c"}}
INFO: Received PING message from server 1128664.2147483652 []
INFO: Received PING message from server 1128664.3323252262 []
{"timestamp": "2018-06-16T13:07:47.451392+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131736208674495500"}]}]}, "logonCount": {"actions": [{"action": "replace", "values": [{"value": "2392"}]}]}}, "version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Modify", "remoteAddress": null, "performedAsSystem": false, "userSid": "S-1-5-18", "dn": "CN=Administrator,CN=Users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "6dcd1cd6-c17a-46c1-bfd7-1336365eaffa", "sessionId": "ddd78ea9-1601-4a91-9ac0-4e28f2c2fc5c"}}
INFO: Received PING message from server 1128664.196 []
{"timestamp": "2018-06-16T13:07:47.640111+0200", "Authorization": {"authType": "krb5", "domain": "ADDOMAIN", "serviceDescription": "LDAP", "version": {"major": 1, "minor": 1}, "logonServer": "ADDC", "remoteAddress": "ipv4:127.0.0.11:41931", "localAddress": "ipv4:127.0.0.30:389", "account": "Administrator", "accountFlags": "0x00000010", "sid": "S-1-5-21-3363883447-1967130412-1579653200-500", "sessionId": "c487ff82-59b8-43d1-ba75-7da8f0b64096", "transportProtection": "SIGN"}, "type": "Authorization"}
INFO: Received PING message from server 1128664.2269460659 []
{"timestamp": "2018-06-16T13:07:47.651210+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"dSHeuristics": {"actions": [{"action": "replace", "values": [{"value": "000000001"}]}]}}, "version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Modify", "remoteAddress": "ipv4:127.0.0.11:41931", "performedAsSystem": false, "userSid": "S-1-5-21-3363883447-1967130412-1579653200-500", "dn": "CN=Directory Service,CN=Windows NT,CN=Services,CN=Configuration,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "7b58d648-b64a-4ab1-8c90-c1ea1d72a068", "sessionId": "c487ff82-59b8-43d1-ba75-7da8f0b64096"}}
INFO: Received PING message from server 1128664.2269460659 []
{"timestamp": "2018-06-16T13:07:47.657995+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"minPwdAge": {"actions": [{"action": "replace", "values": [{"value": "0"}]}]}}, "version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Modify", "remoteAddress": "ipv4:127.0.0.11:41931", "performedAsSystem": false, "userSid": "S-1-5-21-3363883447-1967130412-1579653200-500", "dn": "DC=addom,DC=samba,DC=example,DC=com", "transactionId": "89847a49-f0ae-49ca-90f8-95c38667378e", "sessionId": "c487ff82-59b8-43d1-ba75-7da8f0b64096"}}
INFO: Received PING message from server 1128664.2269460659 []
{"timestamp": "2018-06-16T13:07:47.677086+0200", "type": "dsdbChange", "dsdbChange": {"version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Delete", "remoteAddress": "ipv4:127.0.0.11:41931", "performedAsSystem": false, "userSid": "S-1-5-21-3363883447-1967130412-1579653200-500", "dn": "cn=auditlogtestuser,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "6a059a61-ceea-40a7-ab6f-22b6ac153e1a", "sessionId": "c487ff82-59b8-43d1-ba75-7da8f0b64096"}}
INFO: Received PING message from server 1128664.2269460659 []
{"timestamp": "2018-06-16T13:07:47.697880+0200", "type": "dsdbChange", "dsdbChange": {"version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Delete", "remoteAddress": "ipv4:127.0.0.11:41931", "performedAsSystem": false, "userSid": "S-1-5-21-3363883447-1967130412-1579653200-500", "dn": "cn=auditlogtestuser02,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "5781e725-b9c9-40e9-8abe-f8fdd2535c0b", "sessionId": "c487ff82-59b8-43d1-ba75-7da8f0b64096"}}
INFO: Received PING message from server 1128664.2269460659 []
{"timestamp": "2018-06-16T13:07:47.942165+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"sAMAccountName": {"actions": [{"action": "add", "values": [{"value": "auditlogtestuser"}]}]}, "objectclass": {"actions": [{"action": "add", "values": [{"value": "user"}]}]}, "userPassword": {"actions": [{"action": "add", "redacted": true}]}}, "version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Add", "remoteAddress": "ipv4:127.0.0.11:41931", "performedAsSystem": false, "userSid": "S-1-5-21-3363883447-1967130412-1579653200-500", "dn": "cn=auditlogtestuser,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "7a44bc81-6c0c-462b-92a5-a0fcf15c3063", "sessionId": "c487ff82-59b8-43d1-ba75-7da8f0b64096"}}
Received 2 messages
UNEXPECTED(failure): samba.tests.audit_log_dsdb.samba.tests.audit_log_dsdb.AuditLogDsdbTests.test_samdb_delete_user(ad_dc:local)
REASON: Exception: Exception: Traceback (most recent call last):
  File "bin/python/samba/tests/audit_log_dsdb.py", line 339, in test_samdb_delete_user
    self.assertEquals("Delete", audit["operation"])
AssertionError: 'Delete' != u'Add'

FAILED (1 failures, 0 errors and 0 unexpected successes in 0 testsuites)

A summary with detailed information can be found in:
  ./bin/ab/summary
TOP 10 slowest tests
samba3.local.nss(ad_dc:local) -> 161
samba.tests.samba_tool.user(ad_dc:local) -> 86
samba3.rpc.samr.passwords.pwdlastset(ad_dc) -> 57
samba3.raw.session krb5(ad_dc) -> 55
samba3.rpc.spoolss.printer(ad_dc) -> 50
samba4.blackbox.net_ads(ad_dc:client)(ad_dc:client) -> 49
samba3.rpc.schannel(ad_dc) -> 44
samba3.smb2.session krb5(ad_dc) -> 40
samba3.smb2.dir(ad_dc) -> 39
samba3.base.delete(ad_dc) -> 38
ERROR: test failed with exit code 1