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

Mon Jun 18 22:48:42 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-19-0048/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-19-0048/samba-ad-dc.stderr
   https://git.samba.org/autobuild.flakey.sn-devel-144/2018-06-19-0048/samba-ad-dc.stdout

The top commit at the time of the failure was:

commit 877266f775004cd43f40a6c46f76b8a85afde0fa
Author: Volker Lendecke <vl at samba.org>
Date:   Mon Jun 18 13:46:32 2018 +0200

    librpc/crypto: Fix a misleading comment

    Probably cut&paste error

    Signed-off-by: Volker Lendecke <vl at samba.org>
    Reviewed-by: Stefan Metzmacher <metze at samba.org>

    Autobuild-User(master): Volker Lendecke <vl at samba.org>
    Autobuild-Date(master): Mon Jun 18 18:34:51 CEST 2018 on sn-devel-144

and the last 50 lines of the stdout log were:

INFO: Received PING message from server 1707575.2147483652 []
INFO: Received PING message from server 1707575.2507135845 []
{"timestamp": "2018-06-19T00:48:28.963300+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131738357089620160"}]}]}, "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": "40a1abf6-7e16-4dc9-973b-bca66f8a6fcc", "sessionId": "7c3e9920-c083-4258-9644-27d1768cc058"}}
INFO: Received PING message from server 1707575.196 []
{"timestamp": "2018-06-19T00:48:29.100846+0200", "Authorization": {"authType": "ncacn_np", "domain": "ADDOMAIN", "serviceDescription": "DCE/RPC", "version": {"major": 1, "minor": 1}, "logonServer": "ADDC", "remoteAddress": "ipv4:127.0.0.11:22361", "localAddress": "ipv4:127.0.0.30:445", "account": "auditlogtestuser02", "accountFlags": "0x00000010", "sid": "S-1-5-21-3998942380-1946107773-3403110605-1808", "sessionId": "0fc18f25-3fc8-4167-b138-14306e88eb25", "transportProtection": "SMB"}, "type": "Authorization"}
INFO: Received PING message from server 1707575.4037220118 []
{"timestamp": "2018-06-19T00:48:29.111058+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:22361", "performedAsSystem": false, "userSid": "S-1-5-21-3998942380-1946107773-3403110605-1808", "dn": "CN=auditlogtestuser,CN=Users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "43cd64c3-cce2-476a-8591-2ee65cc29436", "sessionId": "0fc18f25-3fc8-4167-b138-14306e88eb25"}}
INFO: Received PING message from server 1707575.4037220118 []
{"timestamp": "2018-06-19T00:48:29.111261+0200", "dsdbTransaction": {"action": "rollback", "version": {"major": 1, "minor": 0}, "transactionId": "43cd64c3-cce2-476a-8591-2ee65cc29436"}, "type": "dsdbTransaction"}
INFO: Received PING message from server 1707575.2147483652 []
INFO: Received PING message from server 1707575.2507135845 []
{"timestamp": "2018-06-19T00:48:29.248777+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131738357092474200"}]}]}, "logonCount": {"actions": [{"action": "replace", "values": [{"value": "2389"}]}]}}, "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": "9dd606de-bce2-4e8e-9473-e8b361ad24b9", "sessionId": "7c3e9920-c083-4258-9644-27d1768cc058"}}
INFO: Received PING message from server 1707575.2147483652 []
INFO: Received PING message from server 1707575.2507135845 []
{"timestamp": "2018-06-19T00:48:29.266556+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131738357092652720"}]}]}, "logonCount": {"actions": [{"action": "replace", "values": [{"value": "2390"}]}]}}, "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": "828aa9d2-a053-4ce9-b23e-d3355177f75f", "sessionId": "7c3e9920-c083-4258-9644-27d1768cc058"}}
INFO: Received PING message from server 1707575.197 []
{"timestamp": "2018-06-19T00:48:29.384596+0200", "Authorization": {"authType": "krb5", "domain": "ADDOMAIN", "serviceDescription": "LDAP", "version": {"major": 1, "minor": 1}, "logonServer": "ADDC", "remoteAddress": "ipv4:127.0.0.11:22368", "localAddress": "ipv4:127.0.0.30:389", "account": "Administrator", "accountFlags": "0x00000010", "sid": "S-1-5-21-3998942380-1946107773-3403110605-500", "sessionId": "c66a8cbc-9f30-47a1-ac76-dc2f3e1f9dbf", "transportProtection": "SIGN"}, "type": "Authorization"}
INFO: Received PING message from server 1707575.1472463644 []
{"timestamp": "2018-06-19T00:48:29.392735+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:22368", "performedAsSystem": false, "userSid": "S-1-5-21-3998942380-1946107773-3403110605-500", "dn": "CN=Directory Service,CN=Windows NT,CN=Services,CN=Configuration,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "116e1d0f-b9d2-4160-af02-526b2af0a4fb", "sessionId": "c66a8cbc-9f30-47a1-ac76-dc2f3e1f9dbf"}}
INFO: Received PING message from server 1707575.1472463644 []
{"timestamp": "2018-06-19T00:48:29.397497+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:22368", "performedAsSystem": false, "userSid": "S-1-5-21-3998942380-1946107773-3403110605-500", "dn": "DC=addom,DC=samba,DC=example,DC=com", "transactionId": "e74a9f7b-9a90-40b2-999c-b59061ec92cd", "sessionId": "c66a8cbc-9f30-47a1-ac76-dc2f3e1f9dbf"}}
INFO: Received PING message from server 1707575.1472463644 []
{"timestamp": "2018-06-19T00:48:29.411143+0200", "type": "dsdbChange", "dsdbChange": {"version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Delete", "remoteAddress": "ipv4:127.0.0.11:22368", "performedAsSystem": false, "userSid": "S-1-5-21-3998942380-1946107773-3403110605-500", "dn": "cn=auditlogtestuser,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "8a0b8ac6-be9d-4c63-bc66-7a910a7742cc", "sessionId": "c66a8cbc-9f30-47a1-ac76-dc2f3e1f9dbf"}}
INFO: Received PING message from server 1707575.1472463644 []
{"timestamp": "2018-06-19T00:48:29.425307+0200", "type": "dsdbChange", "dsdbChange": {"version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Delete", "remoteAddress": "ipv4:127.0.0.11:22368", "performedAsSystem": false, "userSid": "S-1-5-21-3998942380-1946107773-3403110605-500", "dn": "cn=auditlogtestuser02,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "039ef276-634c-4536-bbb2-8409466763e0", "sessionId": "c66a8cbc-9f30-47a1-ac76-dc2f3e1f9dbf"}}
INFO: Received PING message from server 1707575.1472463644 []
{"timestamp": "2018-06-19T00:48:29.570910+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:22368", "performedAsSystem": false, "userSid": "S-1-5-21-3998942380-1946107773-3403110605-500", "dn": "cn=auditlogtestuser,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "87471bc5-8d15-4dfb-8540-588ece5e6fda", "sessionId": "c66a8cbc-9f30-47a1-ac76-dc2f3e1f9dbf"}}
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) -> 94
samba.tests.samba_tool.user(ad_dc:local) -> 58
samba3.raw.session krb5(ad_dc) -> 53
samba3.rpc.samr.passwords.pwdlastset(ad_dc) -> 53
samba3.smb2.session krb5(ad_dc) -> 37
samba4.blackbox.net_ads(ad_dc:client)(ad_dc:client) -> 36
samba3.smb2.dir(ad_dc) -> 32
samba3.rpc.schannel(ad_dc) -> 28
samba3.base.delete(ad_dc) -> 26
samba3.local.nss(ad_member:local) -> 23
ERROR: test failed with exit code 1