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

Tue Jun 19 23:34:13 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-20-0134/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-20-0134/samba-ad-dc.stderr
   https://git.samba.org/autobuild.flakey.sn-devel-144/2018-06-20-0134/samba-ad-dc.stdout

The top commit at the time of the failure was:

commit e078991ae7660a05687fc803c8a791d7c4287c3e
Author: Volker Lendecke <vl at samba.org>
Date:   Thu May 3 11:47:44 2018 +0200

    winbind: Fix a typo

    Signed-off-by: Volker Lendecke <vl at samba.org>
    Reviewed-by: Andreas Schneider <asn at samba.org>

    Autobuild-User(master): Andreas Schneider <asn at cryptomilk.org>
    Autobuild-Date(master): Tue Jun 19 11:43:16 CEST 2018 on sn-devel-144

and the last 50 lines of the stdout log were:

INFO: Received PING message from server 546745.2147483652 []
INFO: Received PING message from server 546745.3060590727 []
{"timestamp": "2018-06-20T01:33:57.594325+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131739248375929700"}]}]}, "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": "bdcdf6cc-b5d5-43e8-adac-482c27da840b", "sessionId": "8d9a8e28-4ce8-4217-838d-a3e8a107e48c"}}
INFO: Received PING message from server 546745.195 []
{"timestamp": "2018-06-20T01:33:57.759024+0200", "Authorization": {"authType": "ncacn_np", "domain": "ADDOMAIN", "serviceDescription": "DCE/RPC", "version": {"major": 1, "minor": 1}, "logonServer": "ADDC", "remoteAddress": "ipv4:127.0.0.11:32958", "localAddress": "ipv4:127.0.0.30:445", "account": "auditlogtestuser02", "accountFlags": "0x00000010", "sid": "S-1-5-21-2635511087-3443726660-400022665-1808", "sessionId": "4cac9f2d-f7fe-4514-b631-6abc0799173b", "transportProtection": "SMB"}, "type": "Authorization"}
INFO: Received PING message from server 546745.3019458811 []
{"timestamp": "2018-06-20T01:33:57.767701+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:32958", "performedAsSystem": false, "userSid": "S-1-5-21-2635511087-3443726660-400022665-1808", "dn": "CN=auditlogtestuser,CN=Users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "34dc5e73-3a3f-44f3-aba9-fa802000090d", "sessionId": "4cac9f2d-f7fe-4514-b631-6abc0799173b"}}
INFO: Received PING message from server 546745.3019458811 []
{"timestamp": "2018-06-20T01:33:57.767880+0200", "dsdbTransaction": {"action": "rollback", "version": {"major": 1, "minor": 0}, "transactionId": "34dc5e73-3a3f-44f3-aba9-fa802000090d"}, "type": "dsdbTransaction"}
INFO: Received PING message from server 546745.2147483652 []
INFO: Received PING message from server 546745.3060590727 []
{"timestamp": "2018-06-20T01:33:57.986838+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131739248379848820"}]}]}, "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": "427cd7b9-3750-4559-b456-47ebe1fd8f22", "sessionId": "8d9a8e28-4ce8-4217-838d-a3e8a107e48c"}}
INFO: Received PING message from server 546745.2147483652 []
INFO: Received PING message from server 546745.3060590727 []
{"timestamp": "2018-06-20T01:33:58.012909+0200", "type": "dsdbChange", "dsdbChange": {"attributes": {"lastLogon": {"actions": [{"action": "replace", "values": [{"value": "131739248380111160"}]}]}, "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": "6fee739c-19b4-4e80-98ac-39dfd797f66e", "sessionId": "8d9a8e28-4ce8-4217-838d-a3e8a107e48c"}}
INFO: Received PING message from server 546745.196 []
{"timestamp": "2018-06-20T01:33:58.153734+0200", "Authorization": {"authType": "krb5", "domain": "ADDOMAIN", "serviceDescription": "LDAP", "version": {"major": 1, "minor": 1}, "logonServer": "ADDC", "remoteAddress": "ipv4:127.0.0.11:32965", "localAddress": "ipv4:127.0.0.30:389", "account": "Administrator", "accountFlags": "0x00000010", "sid": "S-1-5-21-2635511087-3443726660-400022665-500", "sessionId": "3b4eb97a-ce8d-42c2-96e7-f84d6a36c87c", "transportProtection": "SIGN"}, "type": "Authorization"}
INFO: Received PING message from server 546745.1912831433 []
{"timestamp": "2018-06-20T01:33:58.161432+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:32965", "performedAsSystem": false, "userSid": "S-1-5-21-2635511087-3443726660-400022665-500", "dn": "CN=Directory Service,CN=Windows NT,CN=Services,CN=Configuration,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "32d37710-5cb6-4edb-903d-c9ad6476a785", "sessionId": "3b4eb97a-ce8d-42c2-96e7-f84d6a36c87c"}}
INFO: Received PING message from server 546745.1912831433 []
{"timestamp": "2018-06-20T01:33:58.165856+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:32965", "performedAsSystem": false, "userSid": "S-1-5-21-2635511087-3443726660-400022665-500", "dn": "DC=addom,DC=samba,DC=example,DC=com", "transactionId": "b185d401-cdbd-4e9e-bbcb-a8a78afcb415", "sessionId": "3b4eb97a-ce8d-42c2-96e7-f84d6a36c87c"}}
INFO: Received PING message from server 546745.1912831433 []
{"timestamp": "2018-06-20T01:33:58.178455+0200", "type": "dsdbChange", "dsdbChange": {"version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Delete", "remoteAddress": "ipv4:127.0.0.11:32965", "performedAsSystem": false, "userSid": "S-1-5-21-2635511087-3443726660-400022665-500", "dn": "cn=auditlogtestuser,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "760ff53b-4641-469d-b38f-4315726a9767", "sessionId": "3b4eb97a-ce8d-42c2-96e7-f84d6a36c87c"}}
INFO: Received PING message from server 546745.1912831433 []
{"timestamp": "2018-06-20T01:33:58.191662+0200", "type": "dsdbChange", "dsdbChange": {"version": {"major": 1, "minor": 0}, "status": "Success", "statusCode": 0, "operation": "Delete", "remoteAddress": "ipv4:127.0.0.11:32965", "performedAsSystem": false, "userSid": "S-1-5-21-2635511087-3443726660-400022665-500", "dn": "cn=auditlogtestuser02,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "6a56b8fb-90ba-4dc1-8a98-4f92994467dd", "sessionId": "3b4eb97a-ce8d-42c2-96e7-f84d6a36c87c"}}
INFO: Received PING message from server 546745.1912831433 []
{"timestamp": "2018-06-20T01:33:58.409263+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:32965", "performedAsSystem": false, "userSid": "S-1-5-21-2635511087-3443726660-400022665-500", "dn": "cn=auditlogtestuser,cn=users,DC=addom,DC=samba,DC=example,DC=com", "transactionId": "4551a8c1-a38d-464e-8415-2d8349922ba3", "sessionId": "3b4eb97a-ce8d-42c2-96e7-f84d6a36c87c"}}
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) -> 493
samba.tests.samba_tool.user(ad_dc:local) -> 110
samba4.blackbox.net_ads(ad_dc:client)(ad_dc:client) -> 104
samba3.rpc.spoolss.printer(ad_dc) -> 66
samba4.rpc.schannel with validate(ad_dc) -> 64
samba4.blackbox.trust_utils(fl2008r2dc:local)(fl2008r2dc:local) -> 64
samba4.rpc.schannel with bigendian(ad_dc) -> 63
samba3.rpc.schannel(ad_dc) -> 62
samba4.rpc.schannel with seal,padcheck(ad_dc) -> 61
samba3.rpc.samr.passwords.pwdlastset(ad_dc) -> 60
ERROR: test failed with exit code 1