Ned,
I started my test after 7:34am (you can see this by looking at the date/time
on directories "." and ".." in my message). So the only log entry that is
very suspicious is the one at 7:44am.
To make sure we are looking at right data at right time, I repeated my
actions -- now recording the time of each command execution. I have the
transcript below. According to it, I ran commands from 14:19 to 14:31. I ran
FRSDIAG on both servers after finishing my commands and have frs logs
between those time points also inserted here. The first log reference to
file name 136_3697.JPG is at 14:30:02 on Server#1 and 13:30:03 on Server#2.
This is right after I added a single byte in the hex editor (my dir command
after it was executed at 14:30:09). Also, there is no reference to the
136_3697.TXT in the log files.
Looks like the file actually does not get replicated. To finish once and
forever I decided to send my failing file to you -- to see if it will get
replicated on your side. This is where interesting things started to happen.
I will write about those in my next message -- not to mix with the mess I
have here.
Minas.
Server#1: The current time is: 14:19:48.25 (Empty Directory)
D:\Manufacturing>dir
Volume in drive D is Data
Volume Serial Number is 84E5-4467
Directory of D:\Manufacturing
04/13/2006 02:07 PM <DIR> .
04/13/2006 02:07 PM <DIR> ..
0 File(s) 0 bytes
2 Dir(s) 116,651,122,688 bytes free
Server#2: The current time is: 14:19:52.63
D:\Manufacturing>dir
Volume in drive D is Data Volume
Volume Serial Number is F845-F248
Directory of D:\Manufacturing
04/13/2006 02:07 PM <DIR> .
04/13/2006 02:07 PM <DIR> ..
0 File(s) 0 bytes
2 Dir(s) 18,077,216,768 bytes free
Server#1: The current time is: 14:21:31.80 (copy 136_3693.JPG which
replicates)
D:\Manufacturing>dir
Volume in drive D is Data
Volume Serial Number is 84E5-4467
Directory of D:\Manufacturing
04/13/2006 02:21 PM <DIR> .
04/13/2006 02:21 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
1 File(s) 46,721 bytes
2 Dir(s) 116,651,040,768 bytes free
Server#2: The current time is: 14:21:33.85
D:\Manufacturing>dir
Volume in drive D is Data Volume
Volume Serial Number is F845-F248
Directory of D:\Manufacturing
04/13/2006 02:21 PM <DIR> .
04/13/2006 02:21 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
1 File(s) 46,721 bytes
2 Dir(s) 18,077,134,848 bytes free
Server#1: The current time is: 14:22:40.27 (copy 136_3697.JPG which does not
replicate)
D:\Manufacturing>dir
Volume in drive D is Data
Volume Serial Number is 84E5-4467
Directory of D:\Manufacturing
04/13/2006 02:22 PM <DIR> .
04/13/2006 02:22 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
12/11/2004 10:59 AM 2,377,110 136_3697.JPG
2 File(s) 2,423,831 bytes
2 Dir(s) 116,648,693,760 bytes free
server#2: The current time is: 14:22:41.59
D:\Manufacturing>dir
Volume in drive D is Data Volume
Volume Serial Number is F845-F248
Directory of D:\Manufacturing
04/13/2006 02:21 PM <DIR> .
04/13/2006 02:21 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
1 File(s) 46,721 bytes
2 Dir(s) 18,077,167,616 bytes free
Server#1: The current time is: 14:25:30.76 (fill 136_3697.JPG with ASCII 0
character, still no replication)
D:\Manufacturing>dir
Volume in drive D is Data
Volume Serial Number is 84E5-4467
Directory of D:\Manufacturing
04/13/2006 02:22 PM <DIR> .
04/13/2006 02:22 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
12/11/2004 10:59 AM 2,377,110 136_3697.JPG
2 File(s) 2,423,831 bytes
2 Dir(s) 116,648,693,760 bytes free
Server#2: The current time is: 14:25:31.57
D:\Manufacturing>dir
Volume in drive D is Data Volume
Volume Serial Number is F845-F248
Directory of D:\Manufacturing
04/13/2006 02:21 PM <DIR> .
04/13/2006 02:21 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
1 File(s) 46,721 bytes
2 Dir(s) 18,077,167,616 bytes free
Server#1: The current time is: 14:28:01.16 (copy 136_3697.JPG 136_3697.txt,
no replication for both)
Enter the new time:
D:\Manufacturing>dir
Volume in drive D is Data
Volume Serial Number is 84E5-4467
Directory of D:\Manufacturing
04/13/2006 02:27 PM <DIR> .
04/13/2006 02:27 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
12/11/2004 10:59 AM 2,377,110 136_3697.JPG
12/11/2004 10:59 AM 2,377,110 136_3697.txt
3 File(s) 4,800,941 bytes
2 Dir(s) 116,646,313,984 bytes free
Server#2: The current time is: 14:28:02.18
D:\Manufacturing>dir
Volume in drive D is Data Volume
Volume Serial Number is F845-F248
Directory of D:\Manufacturing
04/13/2006 02:21 PM <DIR> .
04/13/2006 02:21 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
1 File(s) 46,721 bytes
2 Dir(s) 18,077,167,616 bytes free
Server#1: The current time is: 14:30:09.99 (after adding 1 byte to the end
of 136_3697.JPG, now replication worked for 136_3697.JPG)
D:\Manufacturing>dir
Volume in drive D is Data
Volume Serial Number is 84E5-4467
Directory of D:\Manufacturing
04/13/2006 02:29 PM <DIR> .
04/13/2006 02:29 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
04/13/2006 02:29 PM 2,377,111 136_3697.JPG
12/11/2004 10:59 AM 2,377,110 136_3697.txt
3 File(s) 4,800,942 bytes
2 Dir(s) 116,646,305,792 bytes free
Server#2: The current time is: 14:30:11.14
D:\Manufacturing>dir
Volume in drive D is Data Volume
Volume Serial Number is F845-F248
Directory of D:\Manufacturing
04/13/2006 02:30 PM <DIR> .
04/13/2006 02:30 PM <DIR> ..
12/11/2004 04:32 PM 46,721 136_3693.JPG
04/13/2006 02:29 PM 2,377,111 136_3697.JPG
2 File(s) 2,423,832 bytes
2 Dir(s) 18,074,779,648 bytes free
Server#1 FRS Log:
<FrsStageCsSubmitTransfer: 5988: 1828: S1: 14:21:22> Stage: submit
transfer 0xf6faa8
<ProcessOpenByIdStatus: 4452: 3025: S1: 14:21:22> ++
699e7b2a-1ea4-41bc-956f6431c20bf9b6 ObjectId Open failed; NTStatus:
STATUS_OPLOCK_NOT_GRANTED
<FrsOpenSourceFileById: 4452: 3372: S0: 14:21:22> ++ ERROR -
NtCreateFile failed : NTStatus: STATUS_OPLOCK_NOT_GRANTED
4/13-14:21:23 :T: CoG: 45c90bcc CxtG: 92dea886 [LclCo ] Name:
136_3693.JPG
4/13-14:21:23 :T: EventTime: Thu Apr 13, 2006 14:21:19 Ver:
0
4/13-14:21:23 :T: FileG: 699e7b2a-1ea4-41bc-956f6431c20bf9b6 FID:
00020000 00000b8e
4/13-14:21:23 :T: ParentG: 9dae1abb-37fd-4376-ac879c64a5cd61a2 Size:
00000000 0000c000
4/13-14:21:23 :T: OrigG: 28400de8-945d-4a0f-b3772d622dfdd28e Attr:
00000020
4/13-14:21:23 :T: LocnCmd: Create State: IBCO_COMMIT_STARTED
ReplicaName: AOS|MANUFACTURING (4)
4/13-14:21:23 :T: CoFlags: 0100042c [Content Locn LclCo NewFile
CmpresStage ]
4/13-14:21:23 :T: UsnReason: 00008003 [DatOvrWrt DatExt Info ]
4/13-14:21:23 :T: CxtionG: 92dea886-2851-4337-92e0ac801fcec1b8
4/13-14:21:23 :T: CheckSum: d3c1d9d5 75067e65 96a97ef1 e33dcd4c
4/13-14:21:23 :T: CoArrival: <null>
4/13-14:21:23 :T: FullPathName: \\.\D:\Manufacturing\136_3693.JPG
<FrsHashCalcString: 2660: 4842: S0: 14:21:23> Name =
S-1-5-21-3820246116-1162185781-4246705241-1175
<FrsHashCalcString: 2660: 4842: S0: 14:21:23> Name =
S-1-5-21-3820246116-1162185781-4246705241-1175
<FrsDsFindComputer: 2672: 8796: S2: 14:22:26> :DS: Computer
FQDN is cn=ofna,ou=domain controllers,dc=aos,dc=local
<FrsDsFindComputer: 2672: 8802: S2: 14:22:26> :DS: Computer's
dns name is ofna.AOS.local
<FrsDsFindComputer: 2672: 8816: S2: 14:22:26> :DS: Settings
reference is cn=ntds
settings,cn=ofna,cn=servers,cn=default-first-site-name,cn=sites,cn=configuration,dc=aos,dc=local
<FrsDsGetSubscribers: 2672: 8249: S0: 14:22:26> :DS: No
NTFRSSubscriber object found under cn=dfs volumes,cn=ntfrs
subscriptions,cn=ofna,ou=domain controllers,dc=aos,dc=local!
<FrsDsGetSubscribers: 2672: 8249: S0: 14:22:26> :DS: No
NTFRSSubscriber object found under
cn=4dbc857f-f66c-46dc-aec8-7d3cf3355892,cn=dfs volumes,cn=ntfrs
subscriptions,cn=ofna,ou=domain controllers,dc=aos,dc=local!
<ThSupWaitThread: 3120: 505: S1: 14:26:23> :S: StageCs:
Waiting
<ThSupWaitThread: 3120: 533: S1: 14:26:23> :S: StageCs:
normal wait
<ThSupWaitThread: 3120: 505: S1: 14:26:23> :S: FetchCs:
Waiting
<ThSupWaitThread: 3120: 533: S1: 14:26:23> :S: FetchCs:
normal wait
<ThSupWaitThread: 3120: 505: S1: 14:26:23> :S: SndCs:
Waiting
<ThSupWaitThread: 3120: 533: S1: 14:26:23> :S: SndCs: normal
wait
<ThSupWaitThread: 3120: 505: S1: 14:27:26> :S: ReplicaCs:
Waiting
<ThSupWaitThread: 3120: 533: S1: 14:27:26> :S: ReplicaCs:
normal wait
<FrsDsFindComputer: 2672: 8796: S2: 14:27:26> :DS: Computer
FQDN is cn=ofna,ou=domain controllers,dc=aos,dc=local
<FrsDsFindComputer: 2672: 8802: S2: 14:27:26> :DS: Computer's
dns name is ofna.AOS.local
<FrsDsFindComputer: 2672: 8816: S2: 14:27:26> :DS: Settings
reference is cn=ntds
settings,cn=ofna,cn=servers,cn=default-first-site-name,cn=sites,cn=configuration,dc=aos,dc=local
<DbgPrintThreadIds: 2672: 1021: S2: 14:27:26> :H: Known thread
IDs -
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: First
: 440
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: Shutdown
: 2616
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: FrsDs
: 2672
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: SndCs
: 5472
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: DelCs
: 2776
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: OutLog
: 2780
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: ReplicaCs
: 4440
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: JRNL
: 2940
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: DBCs
: 2944
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: JrnlRead
: 3664
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: COAccept
: 3684
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: ChgOrdRetryCS
: 1376
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: Wait
: 880
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: ThCs
: 3120
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: VvJoinCs
: 3196
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: FetchCs
: 5964
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: StageCs
: 4452
<DbgPrintThreadIds: 2672: 1029: S2: 14:27:26> :H: InstallCs
: 2396
<FrsPrintAllocStats: 2672: 234: S2: 14:27:26>
<FrsPrintAllocStats: 2672: 235: S2: 14:27:26> NTFRS MEMORY
USAGE:
<FrsPrintAllocStats: 2672: 238: S2: 14:27:26> ENABLE STATS
: FALSE
<FrsPrintAllocStats: 2672: 242: S2: 14:27:26> Alloced
: 694537 KB (3350000 calls)
<FrsPrintAllocStats: 2672: 246: S2: 14:27:26> Freed
: 0 KB (0 calls)
<FrsPrintAllocStats: 2672: 249: S2: 14:27:26> Delta
: 0 KB
<FrsPrintAllocStats: 2672: 252: S2: 14:27:26> Max delta
: 0 KB
<FrsPrintAllocStats: 2672: 255: S2: 14:27:26> Addr Range
: 36522 KB
<FrsPrintAllocStats: 2672: 256: S2: 14:27:26> OnFreeList
: 0
<FrsPrintAllocStats: 2672: 257: S2: 14:27:26> ReAllocs
: 3346884
<FrsPrintAllocStats: 2672: 258: S2: 14:27:26> NewAllocs
: 3116
<FrsPrintAllocStats: 2672: 259: S2: 14:27:26> MinAddr
: 0x00255810
<FrsPrintAllocStats: 2672: 260: S2: 14:27:26> MaxAddr
: 0x02600060
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
THREAD_CONTEXT_TYPE : 14 Calls, 5 Max, 3 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
REPLICA_TYPE : 13608 Calls, 5 Max, 4 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
REPLICA_THREAD_TYPE : 13676 Calls, 11 Max, 2 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
CONFIG_NODE_TYPE : 144189 Calls, 21 Max, 1 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26> CXTION_TYPE
: 27219 Calls, 11 Max, 9 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26> GUID/RPC
HANDLE : 2 Calls, 2 Max, 2 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26> THREAD_TYPE
: 13270 Calls, 19 Max, 10 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
GEN_TABLE_TYPE : 135877 Calls, 47 Max, 39 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
JBUFFER_TYPE : 3 Calls, 3 Max, 3 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
VOLUME_MONITOR_ENTRY_TYPE : 2 Calls, 2 Max, 1 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
COMMAND_PACKET_TYPE : 178685 Calls, 24 Max, 13 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
GENERIC_HASH_TABLE_TYPE : 3 Calls, 3 Max, 3 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
CHANGE_ORDER_ENTRY_TYPE : 67 Calls, 11 Max, 0 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
FILTER_TABLE_ENTRY_TYPE : 26 Calls, 26 Max, 26 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
QHASH_TABLE_TYPE : 30 Calls, 25 Max, 23 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
OUT_LOG_PARTNER_TYPE : 4 Calls, 3 Max, 3 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
WILDCARD_FILTER_ENTRY_TYPE: 15 Calls, 15 Max, 15 busy
<FrsPrintAllocStats: 2672: 268: S2: 14:27:26>
REPARSE_TAG_TABLE_TYPE : 24360 Calls, 3 Max, 3 busy
<FrsPrintAllocStats: 2672: 270: S2: 14:27:26>
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 0 to
15 : 506712 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 16 to
31 : 602127 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 32 to
47 : 405311 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 48 to
63 : 46755 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 64 to
79 : 382512 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 80 to
95 : 227138 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 96 to
111 : 16375 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 112 to
127 : 41941 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 128 to
143 : 46735 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 144 to
159 : 168993 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 160 to
175 : 11013 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 176 to
191 : 106007 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 192 to
207 : 62546 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 208 to
223 : 64959 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 224 to
239 : 165087 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 240 to
255 : 48934 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 256 to
271 : 29230 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 272 to
287 : 52086 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 288 to
303 : 16243 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 304 to
319 : 21725 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 320 to
335 : 3 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 352 to
367 : 10974 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 368 to
383 : 10972 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 384 to
399 : 836 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 416 to
431 : 13609 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 512 to
527 : 8748 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 560 to
575 : 27218 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 608 to
623 : 2 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 640 to
655 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 784 to
799 : 41679 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 800 to
815 : 40614 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 848 to
863 : 2 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 864 to
879 : 13779 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 880 to
895 : 13667 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 944 to
959 : 27502 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 976 to
991 : 67 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1008 to
1023 : 13667 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1024 to
1039 : 6112 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1088 to
1103 : 13779 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1104 to
1119 : 13779 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1184 to
1199 : 2 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1200 to
1215 : 4 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1216 to
1231 : 27502 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1408 to
1423 : 55 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1616 to
1631 : 3 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 1792 to
1807 : 2 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 2048 to
2063 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 2128 to
2143 : 13610 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 2160 to
2175 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 2480 to
2495 : 10 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 2544 to
2559 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 2736 to
2751 : 13610 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 3152 to
3167 : 11 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 3264 to
3279 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 4000 to
4015 : 13611 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 4096 to
4111 : 4 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 4976 to
4991 : 2 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 4992 to
5007 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 5504 to
5519 : 2 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 5632 to
5647 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 7856 to
7871 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 8192 to
8207 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 8448 to
8463 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 9744 to
9759 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 10368 to
10383 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 12080 to
12095 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 13120 to
13135 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 13696 to
13711 : 1 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 278: S2: 14:27:26> 16368 to
16383 : 2119 Calls, 0 Max, 0 busy
<FrsPrintAllocStats: 2672: 280: S2: 14:27:26>
<FrsDsGetSubscribers: 2672: 8249: S0: 14:27:26> :DS: No
NTFRSSubscriber object found under cn=dfs volumes,cn=ntfrs
subscriptions,cn=ofna,ou=domain controllers,dc=aos,dc=local!
<ThSupWaitThread: 3120: 505: S1: 14:27:26> :S: ReplicaCs:
Waiting
<ThSupWaitThread: 3120: 533: S1: 14:27:26> :S: ReplicaCs:
normal wait
<ThSupWaitThread: 3120: 505: S1: 14:27:26> :S: ReplicaCs:
Waiting
<ThSupWaitThread: 3120: 533: S1: 14:27:26> :S: ReplicaCs:
normal wait
<FrsDsGetSubscribers: 2672: 8249: S0: 14:27:26> :DS: No
NTFRSSubscriber object found under
cn=4dbc857f-f66c-46dc-aec8-7d3cf3355892,cn=dfs volumes,cn=ntfrs
subscriptions,cn=ofna,ou=domain controllers,dc=aos,dc=local!
<FrsStageCsSubmitTransfer: 6104: 1828: S1: 14:30:02> Stage: submit
transfer 0xf6f980
<ProcessOpenByIdStatus: 4548: 3025: S1: 14:30:02> ++
7ff26913-b482-422f-873ebf0c7f6ffb77 ObjectId Open failed; NTStatus:
STATUS_OPLOCK_NOT_GRANTED
<FrsOpenSourceFileById: 4548: 3372: S0: 14:30:02> ++ ERROR -
NtCreateFile failed : NTStatus: STATUS_OPLOCK_NOT_GRANTED
4/13-14:30:02 :T: CoG: d7f4d1be CxtG: 92dea886 [LclCo ] Name:
136_3697.JPG
4/13-14:30:02 :T: EventTime: Thu Apr 13, 2006 14:29:59 Ver:
0
4/13-14:30:02 :T: FileG: 7ff26913-b482-422f-873ebf0c7f6ffb77 FID:
00020000 00000b94
4/13-14:30:02 :T: ParentG: 9dae1abb-37fd-4376-ac879c64a5cd61a2 Size:
00000000 00245000
4/13-14:30:02 :T: OrigG: 28400de8-945d-4a0f-b3772d622dfdd28e Attr:
00000120
4/13-14:30:02 :T: LocnCmd: Create State: IBCO_COMMIT_STARTED
ReplicaName: AOS|MANUFACTURING (4)
4/13-14:30:02 :T: CoFlags: 0100042c [Content Locn LclCo NewFile
CmpresStage ]
4/13-14:30:02 :T: UsnReason: 0000a803 [RenNew DatOvrWrt DatExt Info
Security ]
4/13-14:30:02 :T: CxtionG: 92dea886-2851-4337-92e0ac801fcec1b8
4/13-14:30:02 :T: CheckSum: 84893f8c f279b69f 9ec5d039 8a3713e0
4/13-14:30:02 :T: CoArrival: <null>
4/13-14:30:02 :T: FullPathName: \\.\D:\Manufacturing\136_3697.JPG
<FrsHashCalcString: 2660: 4842: S0: 14:30:02> Name =
S-1-5-21-3820246116-1162185781-4246705241-1175
<FrsHashCalcString: 2660: 4842: S0: 14:30:03> Name =
S-1-5-21-3820246116-1162185781-4246705241-1175
<RcsSetCxtionSchedule: 4312: 7365: S0: 14:30:32> :X: b454415e,
schedule is on
<RcsSetCxtionSchedule: 4312: 7365: S0: 14:30:32> :X: 242cdbff,
schedule is on
<RcsSetCxtionSchedule: 4312: 7365: S0: 14:30:32> :X: 6177bd09,
schedule is on
<RcsSetCxtionSchedule: 4312: 7365: S0: 14:30:32> :X: f938acb4,
schedule is on
Server#2 FRS log:
<FrsDsFindComputer: 2508: 8796: S2: 14:19:02> :DS: Computer
FQDN is cn=amber,ou=domain controllers,dc=aos,dc=local
<FrsDsFindComputer: 2508: 8802: S2: 14:19:02> :DS: Computer's
dns name is amber.AOS.local
<FrsDsFindComputer: 2508: 8816: S2: 14:19:02> :DS: Settings
reference is cn=ntds
settings,cn=amber,cn=servers,cn=default-first-site-name,cn=sites,cn=configuration,dc=aos,dc=local
<FrsDsGetSubscribers: 2508: 8249: S0: 14:19:02> :DS: No
NTFRSSubscriber object found under cn=dfs volumes,cn=ntfrs
subscriptions,cn=amber,ou=domain controllers,dc=aos,dc=local!
<FrsDsGetSubscribers: 2508: 8249: S0: 14:19:02> :DS: No
NTFRSSubscriber object found under
cn=4dbc857f-f66c-46dc-aec8-7d3cf3355892,cn=dfs volumes,cn=ntfrs
subscriptions,cn=amber,ou=domain controllers,dc=aos,dc=local!
<FrsHashCalcString: 7284: 4842: S0: 14:21:23> Name =
S-1-5-21-3820246116-1162185781-4246705241-1005
<MainWait: 7916: 598: S0: 14:21:23> Wait thread has
started.
<FrsHashCalcString: 7284: 4842: S0: 14:21:23> Name =
S-1-5-21-3820246116-1162185781-4246705241-1005
4/13-14:21:23 :T: CoG: 45c90bcc CxtG: b454415e [RemCo ] Name:
136_3693.JPG
4/13-14:21:23 :T: EventTime: Thu Apr 13, 2006 14:21:19 Ver:
0
4/13-14:21:23 :T: FileG: 699e7b2a-1ea4-41bc-956f6431c20bf9b6 FID:
00360000 0000007b
4/13-14:21:23 :T: ParentG: bcae7bcc-3d73-4ff1-9f59b1fcf4514680 Size:
00000000 0000c000
4/13-14:21:23 :T: OrigG: 28400de8-945d-4a0f-b3772d622dfdd28e Attr:
00000020
4/13-14:21:23 :T: LocnCmd: Create State: IBCO_COMMIT_STARTED
ReplicaName: AOS|MANUFACTURING (19)
4/13-14:21:23 :T: CoFlags: 0100040c [Content Locn NewFile CmpresStage ]
4/13-14:21:23 :T: UsnReason: 00008003 [DatOvrWrt DatExt Info ]
4/13-14:21:23 :T: CxtionG: b454415e-05a1-4c63-b668367fefd85bf4
4/13-14:21:23 :T: CheckSum: d3c1d9d5 75067e65 96a97ef1 e33dcd4c
4/13-14:21:23 :T: CoArrival: Thu Apr 13, 2006 14:21:23
4/13-14:21:23 :T: FullPathName:
\\?\D:\Manufacturing\DO_NOT_REMOVE_NtFrs_PreInstall_Directory\NTFRS_45c90bcc-ef87-441c-9f71433bfd0abb9f
<FrsDsFindComputer: 2508: 8796: S2: 14:24:02> :DS: Computer
FQDN is cn=amber,ou=domain controllers,dc=aos,dc=local
<FrsDsFindComputer: 2508: 8802: S2: 14:24:02> :DS: Computer's
dns name is amber.AOS.local
<FrsDsFindComputer: 2508: 8816: S2: 14:24:02> :DS: Settings
reference is cn=ntds
settings,cn=amber,cn=servers,cn=default-first-site-name,cn=sites,cn=configuration,dc=aos,dc=local
<FrsDsGetSubscribers: 2508: 8249: S0: 14:24:02> :DS: No
NTFRSSubscriber object found under cn=dfs volumes,cn=ntfrs
subscriptions,cn=amber,ou=domain controllers,dc=aos,dc=local!
<FrsDsGetSubscribers: 2508: 8249: S0: 14:24:02> :DS: No
NTFRSSubscriber object found under
cn=4dbc857f-f66c-46dc-aec8-7d3cf3355892,cn=dfs volumes,cn=ntfrs
subscriptions,cn=amber,ou=domain controllers,dc=aos,dc=local!
<ThSupWaitThread: 4072: 505: S1: 14:26:23> :S: FetchCs:
Waiting
<ThSupWaitThread: 4072: 533: S1: 14:26:23> :S: FetchCs:
normal wait
<ThSupWaitThread: 4072: 505: S1: 14:26:23> :S: InstallCs:
Waiting
<ThSupWaitThread: 4072: 533: S1: 14:26:23> :S: InstallCs:
normal wait
<ThSupWaitThread: 4072: 505: S1: 14:26:23> :S: SndCs:
Waiting
<ThSupWaitThread: 4072: 533: S1: 14:26:23> :S: SndCs: normal
wait
<ThSupWaitThread: 4072: 505: S1: 14:29:02> :S: ReplicaCs:
Waiting
<ThSupWaitThread: 4072: 533: S1: 14:29:02> :S: ReplicaCs:
normal wait
<ThSupWaitThread: 4072: 505: S1: 14:29:02> :S: ReplicaCs:
Waiting
<ThSupWaitThread: 4072: 533: S1: 14:29:02> :S: ReplicaCs:
normal wait
<ThSupWaitThread: 4072: 505: S1: 14:29:02> :S: ReplicaCs:
Waiting
<ThSupWaitThread: 4072: 533: S1: 14:29:02> :S: ReplicaCs:
normal wait
<FrsDsFindComputer: 2508: 8796: S2: 14:29:02> :DS: Computer
FQDN is cn=amber,ou=domain controllers,dc=aos,dc=local
<FrsDsFindComputer: 2508: 8802: S2: 14:29:02> :DS: Computer's
dns name is amber.AOS.local
<FrsDsFindComputer: 2508: 8816: S2: 14:29:02> :DS: Settings
reference is cn=ntds
settings,cn=amber,cn=servers,cn=default-first-site-name,cn=sites,cn=configuration,dc=aos,dc=local
<FrsDsGetSubscribers: 2508: 8249: S0: 14:29:02> :DS: No
NTFRSSubscriber object found under cn=dfs volumes,cn=ntfrs
subscriptions,cn=amber,ou=domain controllers,dc=aos,dc=local!
<FrsDsGetSubscribers: 2508: 8249: S0: 14:29:02> :DS: No
NTFRSSubscriber object found under
cn=4dbc857f-f66c-46dc-aec8-7d3cf3355892,cn=dfs volumes,cn=ntfrs
subscriptions,cn=amber,ou=domain controllers,dc=aos,dc=local!
<FrsHashCalcString: 7284: 4842: S0: 14:30:02> Name =
S-1-5-21-3820246116-1162185781-4246705241-1005
<FrsHashCalcString: 7284: 4842: S0: 14:30:02> Name =
S-1-5-21-3820246116-1162185781-4246705241-1005
4/13-14:30:03 :T: CoG: d7f4d1be CxtG: b454415e [RemCo ] Name:
136_3697.JPG
4/13-14:30:03 :T: EventTime: Thu Apr 13, 2006 14:29:59 Ver:
0
4/13-14:30:03 :T: FileG: 7ff26913-b482-422f-873ebf0c7f6ffb77 FID:
00980000 0000136c
4/13-14:30:03 :T: ParentG: bcae7bcc-3d73-4ff1-9f59b1fcf4514680 Size:
00000000 00245000
4/13-14:30:03 :T: OrigG: 28400de8-945d-4a0f-b3772d622dfdd28e Attr:
00000120
4/13-14:30:03 :T: LocnCmd: Create State: IBCO_COMMIT_STARTED
ReplicaName: AOS|MANUFACTURING (19)
4/13-14:30:03 :T: CoFlags: 0100040c [Content Locn NewFile CmpresStage ]
4/13-14:30:03 :T: UsnReason: 0000a803 [RenNew DatOvrWrt DatExt Info
Security ]
4/13-14:30:03 :T: CxtionG: b454415e-05a1-4c63-b668367fefd85bf4
4/13-14:30:03 :T: CheckSum: 84893f8c f279b69f 9ec5d039 8a3713e0
4/13-14:30:03 :T: CoArrival: Thu Apr 13, 2006 14:30:02
4/13-14:30:03 :T: FullPathName:
\\?\D:\Manufacturing\DO_NOT_REMOVE_NtFrs_PreInstall_Directory\NTFRS_d7f4d1be-c1d2-48ad-87e151cc4ea9d7f4
<RcsSetCxtionSchedule: 7544: 7365: S0: 14:30:55> :X: 6177bd09,
schedule is on
<RcsSetCxtionSchedule: 7544: 7365: S0: 14:30:55> :X: f938acb4,
schedule is on
<RcsSetCxtionSchedule: 7544: 7365: S0: 14:30:55> :X: b454415e,
schedule is on
<RcsSetCxtionSchedule: 7544: 7365: S0: 14:30:56> :X: 242cdbff,
schedule is on
Post by Ned Pyle (MSFT)From basic examination, everything looks good - no misconfig, no old FRS,
no filters - all is well. So I dug further into the NTFRS_0005.log from
On server1, 136_3697.txt is renamed to 136_3697.jpg and change order is
sent out (at 4/11-07:33:29).
On server2, 136_3697.jpg is transferred in successfully to pre-install (at
4/11-07:33:29)
At 4/11-07:34:27, it's done again, and works again.
At 4/11-07:44:28 , it looks like maybe the file was overwritten with the
same file? It replicates again without issues.
At 4/11-07:46:40, we get a temporary copy of the file (was this when it
was opened in a hex editor?)
At 4/11-07:46:41 the 136_3697.jpg.Hex Editor 3 temp save file shows up -
that replicates fine too.
So, the logs claim everything is replicating normally. I must admit - I'm
scratching my head here, Minas.
Ned