irpc/tevent losing replies

[Matthieu Patou]

Hello

While working on DRS issues with andrew's branch I started to notice 
message like "IRPC callback failed for DsReplicaSync - NT_STATUS_IO_TIMEOUT"

To my understanding the internal RPC will call drepl_replica_sync when a 
DsReplicaSync RPC is received by the RPC server and when this function 
returns the internal RPC should returns too and via the magic of tevent 
the caller callback will be called informing it that the call is finished.

I started to trace and this is how it looks when everything is ok:
Receved a DsReplicaSync, using timeout 0, ts = 1359007798 (in RPC server)
IRPC send
Received valid dsreplicasync, starting analysis ts = 1359007798 (start 
of drepl_replica_sync)
Received valid dsreplicasync, schedule get nc changes ts = 1359007798 
(end of drepl_replica_sync)
dreplsrv_periodic_schedule(1) rescheduled for: Wed Jan 23 22:10:00 2013 PST
dreplsrv_periodic_schedule(300) scheduled for: Wed Jan 23 22:15:00 2013 PST
../source4/dsdb/samdb/ldb_modules/repl_meta_data.c:3583: Resolving 
conflict record via existing rename 'OU=Test Remote Rename Conflict 
3,DC=samba,DC=example,DC=com' -> '
OU=Test Remote Rename Conflict 
3\0ACNF:c44509f5-b471-48c8-bd8f-b9ff236de218,DC=samba,DC=example,DC=com'
Replicated 1 objects (0 linked attributes) for DC=samba,DC=example,DC=com
IRPC receive ts = 1359007799 (in RPC server)

And here is how it looks like when it goes wrong

Receved a DsReplicaSync, using timeout 30, ts = 1359007803
IRPC send
Received valid dsreplicasync, starting analysis ts = 1359007803
Received valid dsreplicasync, schedule get nc changes ts = 1359007803
dreplsrv_periodic_schedule(1) rescheduled for: Wed Jan 23 22:10:04 2013 PST
dreplsrv_periodic_schedule(300) scheduled for: Wed Jan 23 22:15:04 2013 PST
Replicated 0 objects (0 linked attributes) for DC=samba,DC=example,DC=com
Replicated 0 objects (0 linked attributes) for 
DC=ForestDnsZones,DC=samba,DC=example,DC=com
Replicated 0 objects (0 linked attributes) for 
DC=DomainDnsZones,DC=samba,DC=example,DC=com
Replicated 0 objects (0 linked attributes) for DC=samba,DC=example,DC=com
Replicated 0 objects (0 linked attributes) for 
CN=Schema,CN=Configuration,DC=samba,DC=example,DC=com
Replicated 1 objects (0 linked attributes) for 
CN=Configuration,DC=samba,DC=example,DC=com
dreplsrv_notify_schedule(5) scheduled for: Wed Jan 23 22:10:12 2013 PST
dreplsrv_notify_schedule(5) scheduled for: Wed Jan 23 22:10:17 2013 PST
dreplsrv_notify_schedule(5) scheduled for: Wed Jan 23 22:10:22 2013 PST
dreplsrv_notify_schedule(5) scheduled for: Wed Jan 23 22:10:27 2013 PST
dreplsrv_notify_schedule(5) scheduled for: Wed Jan 23 22:10:32 2013 PST
dreplsrv_notify_schedule(5) scheduled for: Wed Jan 23 22:10:37 2013 PST
IRPC receive ts = 1359007833
IRPC callback failed for DsReplicaSync - NT_STATUS_IO_TIMEOUT at 1359007833

The drepl_replica_sync returns quickly but somehow it seems that either 
the reply is not sent or it is lost, when I force the dc to be run in 
single mode (so that all the tasks are in the same process) the error 
message goes away.

Matthieu.