Microsoft KB Archive/813554

= MNS: Entries in the Cluster Log File Have an INFO Level Even if They Are Errors =

Article ID: 813554

Article Last Modified on 2/28/2007

-

APPLIES TO


 * Microsoft Windows Server 2003, Enterprise Edition (32-bit x86)
 * Microsoft Windows Server 2003, Datacenter Edition (32-bit x86)
 * Microsoft Windows Server 2003, Enterprise x64 Edition

-





SYMPTOMS
The cluster log for the Majority Node Set (MNS) Quorum resource may log most entries as INFO and contain useless Cluster.log file entries.



CAUSE
This behavior occurs because MNS was originally designed as a standalone component, but was ported as a cluster resource for Windows Server 2003. Before porting, it had its own logging functions. During the porting process, logging codes inside the functions were replaced with cluster log API calls with level LOG_INFORMATION. Because of this, not all MNS Cluster.log entries have the correct severity. Many of MNS entries appear as INFO regardless of the severity or importance of the message.



Types of Resource Entries in the Log File
The MNS resource uses 2 types of entries in the Cluster.log file:  Entries that are related to the actual MNS resource use the “Majority Node Set ” string. Note that the format is not consistent, and because the resource name is typically Majority Node Set, the entries are long. Entries that are related to the pseudo file system use the [Qfs] identifier. For example:

Note Time stamps have been removed to shorten entries.

INFO [Qfs] SharedMem_Create: Created E:\WINDOWS\Cluster\MajorityNodeSet_SharedMemTransport_ver_1.0 INFO Majority Node Set : PipeOnline. Path &quot;\\1b97ebae-f5ac-4\1b97ebae-f5ac-4139-bf2c-b0bda607b814$&quot; Share &quot;1b97ebae-f5ac-4139-bf2c-b0bda607b814$&quot;



ForceQuorum
When you are using ForceQuorum, the cluster logs an entry in the cluster log that indicates what was selected:

INFO Local Time is 2002/06/08-15:49:47.375

INFO [CS] Service Starting...

INFO [CS] forcequorum option chosen: force majority node set for nodes mns1,mns2

Example of Error and Warning entries
The following is an example of an error that was recorded in the log file. In this case the error was a failure to create a resource. The resource failed because its name exceeded the MAX_PATH requirement.

INFO [FM] Resmon LRPC EP name is LRPC

INFO Majority Node Set : Open share setup status 234.

INFO Majority Node Set : Open MNS Quorum 2 status 234.

INFO Majority Node Set : Close request.

WARN [RM] RmpInsertResourceList failed, returned 234

ERR [RM] Failed creating resource d98b79b2-70e8-4762-a836-215b13ef2965, error 234.

INFO [FM] FmpRmCreateResource: unable to create resource d98b79b2-70e8-4762-a836-215b13ef2965

Additional Information About MNS Cluster.log Entries
Additional information that you can use to help you decipher MNS log listings during arbitration.

Normal MNS arbitration in a 3 node cluster, networks(10.*, 172.*), (10.*) higher priority:

(Clussvc telling RGP that it is trying to arbitrate for the quorum resource, in this case MNS.)

INFO [MM] MmSetQuorumOwner(1,1), old owner 0.

(Resmon thread calling into MNS to start arbitration, the following logs occur because of some pre-MNS arbitration init work.)

INFO Majority Node Set : Arbitrate request.

INFO Majority Node Set : Maximum arbitration time 120000 msec

(2 minutes timeout on arbitration.)

INFO Majority Node Set : Guid 3a9743cd-7055-450e-8d70-1249c2bfe727

INFO Majority Node Set <QON>: Local path D:\WINDOWS\cluster\MNS.3a9743cd-7055-450e-8d70-1249c2bfe727$

INFO Majority Node Set <QON>: Netshare '3a9743cd-7055-450e-8d70-1249c2bfe727$' already exists

INFO Majority Node Set <QON>: Local node id 1

INFO Majority Node Set <QON>: FsRegister Tid 1 Share '3a9743cd-7055-450e-8d70-1249c2bfe727$' 3 disks

INFO Majority Node Set <QON>: FsArb: Creating arbitration thread

(Main MNS arbitration thread spawned by the thread earlier, and the thread earlier would wait until arbitration succeeds or fails.)

INFO Majority Node Set <QON>: ArbitrateThread begin

INFO Majority Node Set <QON>: ArbitrateThread current AliveSet=0

(0 is the current bitmask of shares that are owned by the node. The bitmask is node-ID-based. For example, if it owns shares of nodes 1, 2, and 5, the bitmask is 0x26. )

(Threads below are spawned to take shares on all the nodes in parallel over all the networks. In an N node cluster with K networks, N*K number of threads would be spawned. The thread blow is trying to grab Node 3's share over 10.* network)

INFO Majority Node Set <QON>: Probe thread for Replica 3 Addr 10.21.1.161

(The thread below is trying to grab node 1's share over 10.* network)

INFO Majority Node Set <QON>: Probe thread for Replica 1 Addr 10.21.1.179

(CreateTreeConnection is the method to force all SMB traffic for this thread to flow over 10.* network.)

INFO Majority Node Set <QON>: CreateTreeConnection(10.21.1.161\3a9743cd-7055-450e-8d70-1249c2bfe727$) returned 0x0 hdl 0x2f0

INFO Majority Node Set <QON>: CreateTreeConnection(10.21.1.179\3a9743cd-7055-450e-8d70-1249c2bfe727$) returned 0x0 hdl 0x10c

(The thread below is trying to take Node 3's share over 172.* network.)

INFO Majority Node Set <QON>: Probe thread for Replica 3 Addr 172.24.21.186

INFO Majority Node Set <QON>: CreateTreeConnection(172.24.21.186\3a9743cd-7055-450e-8d70-1249c2bfe727$) returned 0x0 hdl 0x308

(The thread managed to take node 3's share, and the thread is opening and reading the MNS log file.)

INFO Majority Node Set <QON>: Crs3: (Open) Filesz 8192 max_sec 16

INFO Majority Node Set <QON>: Probe thread for Replica 1 Addr 172.24.21.191

INFO Majority Node Set <QON>: Crs3: loaded 8192 bytes, 128 records

INFO Majority Node Set <QON>: CreateTreeConnection(172.24.21.191\3a9743cd-7055-450e-8d70-1249c2bfe727$) returned 0x0 hdl 0x2f8

INFO Majority Node Set <QON>: Crs3: 304 Last record 42 max 128 epoch 376 seq 1

(The thread below is trying to take node 2's share over 10.* network.)

INFO Majority Node Set <QON>: Probe thread for Replica 2 Addr 10.21.1.173

INFO Majority Node Set <QON>: CreateTreeConnection(10.21.1.173\3a9743cd-7055-450e-8d70-1249c2bfe727$) returned 0x0 hdl 0x340

INFO Majority Node Set <QON>: Probe thread for Replica 2 Addr 172.24.21.174

(The thread managed to take node 1's share.)

INFO Majority Node Set <QON>: Crs1: (Open) Filesz 8192 max_sec 16

INFO Majority Node Set <QON>: CreateTreeConnection(172.24.21.174\3a9743cd-7055-450e-8d70-1249c2bfe727$) returned 0x0 hdl 0x30c

(After reading the MNS log file, the thread mounts (opens) the root share folder.)

INFO Majority Node Set <QON>: Mounted \Device\LanmanRedirector\10.21.1.161\3a9743cd-7055-450e-8d70-1249c2bfe727$\3a9743cd-7055-450e-8d70-1249c2bfe727$\

INFO Majority Node Set <QON>: Crs1: loaded 8192 bytes, 128 records

INFO Majority Node Set <QON>: Crs1: 34c Last record 42 max 128 epoch 376 seq 1

(The thread managed to take node 2's share.)

INFO Majority Node Set <QON>: Crs2: (Open) Filesz 8192 max_sec 16

INFO Majority Node Set <QON>: Mounted \Device\LanmanRedirector\10.21.1.179\3a9743cd-7055-450e-8d70-1249c2bfe727$\3a9743cd-7055-450e-8d70-1249c2bfe727$\

INFO Majority Node Set <QON>: Crs2: loaded 8192 bytes, 128 records

INFO Majority Node Set <QON>: Crs2: 300 Last record 42 max 128 epoch 376 seq 1

INFO Majority Node Set <QON>: Mounted \Device\LanmanRedirector\10.21.1.173\3a9743cd-7055-450e-8d70-1249c2bfe727$\3a9743cd-7055-450e-8d70-1249c2bfe727$\

INFO Majority Node Set <QON>: NtNotifyChangeDirectoryFile(\Device\LanmanRedirector\10.21.1.179\3a9743cd-7055-450e-8d70-1249c2bfe727$\) returns 0x103 FD: 00000370

(Mounting successful, mark the share to be owned, this is share for node ID 1.)

INFO Majority Node Set <QON>: Probe Thread probe replica 1 succeeded, ShareSet 2

(Replica 1, Shareset 2 is the bit for node ID 1.)

INFO Majority Node Set <QON>: FsNotifyCallback: Enqueing Change notification for Fd:0x370

INFO Majority Node Set <QON>: NtNotifyChangeDirectoryFile(\Device\LanmanRedirector\10.21.1.173\3a9743cd-7055-450e-8d70-1249c2bfe727$\) returns 0x103 FD:

INFO Majority Node Set <QON>: NtNotifyChangeDirectoryFile(\Device\LanmanRedirector\10.21.1.161\3a9743cd-7055-450e-8d70-1249c2bfe727$\) returns 0x103 FD: 000002E8

(Mounting successful, mark the share to be owned, this is the share for node ID 2.)

INFO Majority Node Set <QON>: Probe Thread probe replica 2 succeeded, ShareSet 6

(In this example, it took share 1 and 2. Because 2 of the 3 shares (Majority) have been taken, the resmon arbitration thread returns success. However, the MNS arbitration thread would wait for all threads to exit, and then synchronize the shares.)

INFO Majority Node Set <QON>: Arb: status 0.

INFO Majority Node Set <QON>: Arbitrate request status 0.

(This is the MNS health-monitoring thread that is started by the resmon arbitration thread after successful arbitration.)

INFO Majority Node Set <QON>: MNS FsReserve thread start.

INFO Majority Node Set <QON>: FsNotifyCallback: Enqueing Change notification for Fd:0x310

(Finally, the share of node 3 is also mounted.)

INFO Majority Node Set <QON>: Probe Thread probe replica 3 succeeded, ShareSet e

(This occurs because of the threads that are spawned to grab shares over 172.* network. Because the threads that are spawned to take shares over 10.* network have already succeeded, this is getting ERROR_LOCK_VIOLATION. These threads would exit shortly, notice the 2 second delay in this thread's log.)

INFO Majority Node Set <QON>: Crs3 Setting EA err=0x0 status=0x21

INFO Majority Node Set <QON>: Replica '\Device\LanmanRedirector\172.24.21.186\3a9743cd-7055-450e-8d70-1249c2bfe727$\crs.log' already locked

INFO Majority Node Set <QON>: FsNotifyCallback: Enqueing Change notification for Fd:0x2e8

INFO Majority Node Set <QON>: FsNotifyCallback: Enqueing Change notification for Fd:0x2e8

INFO Majority Node Set <QON>: Crs1 Setting EA err=0x0 status=0x21

INFO Majority Node Set <QON>: Crs2 Setting EA err=0x0 status=0x21

INFO Majority Node Set <QON>: Replica '\Device\LanmanRedirector\172.24.21.174\3a9743cd-7055-450e-8d70-1249c2bfe727$\crs.log' already locked

INFO Majority Node Set <QON>: Replica '\Device\LanmanRedirector\172.24.21.191\3a9743cd-7055-450e-8d70-1249c2bfe727$\crs.log' already locked (FspEvict:

(This evicts failed shares from the alive share set. The meaning of the log below:

Wset - Bitmask of shares that are writable.

Rset - Bitmask of shares that are readable.

Aset - Bitmask of alive share set.

EvictMask - Shares in the Aset that have failed.

Because this is a fresh arbitration, all the bitmasks are 0, and because MNS managed to grab all the shares, the evictset is also 0.)

INFO Majority Node Set <QON>: FspEvict Entry: WSet 0 Rset 0 ASet 0 EvictMask 0

INFO Majority Node Set <QON>: FspEvict Exit: vol 3a9743cd-7055-450e-8d70-1249c2bfe727$ WSet 0 RSet 0 ASet 0 (FspJoin:

(This synchronizes and joins the new shares:

JoinMask -Bitmask for newly available shares)

INFO Majority Node Set <QON>: FspJoin Entry: WSet 0 Rset 0 ASet 0 JoinMask e

INFO Majority Node Set <QON>: Crs1 last record 42 epoch 376 seq 1 state 5

INFO Majority Node Set <QON>: Crs2 last record 42 epoch 376 seq 1 state 5

INFO Majority Node Set <QON>: Crs3 last record 42 epoch 376 seq 1 state 5

INFO Majority Node Set <QON>: Vol 3a9743cd-7055-450e-8d70-1249c2bfe727$ done recovery nid 1 mid 1

INFO Majority Node Set <QON>: Vol 3a9743cd-7055-450e-8d70-1249c2bfe727$ done recovery nid 2 mid 1

INFO Majority Node Set <QON>: Vol 3a9743cd-7055-450e-8d70-1249c2bfe727$ done recovery nid 3 mid 1

INFO Majority Node Set <QON>: Crs1: append record 43 epoch 377 seq 0 state b

INFO Majority Node Set <QON>: Crs1: flush 512 bytes record 43 -> 5,2560

INFO Majority Node Set <QON>: Crs2: append record 43 epoch 377 seq 0 state b

INFO Majority Node Set <QON>: Crs2: flush 512 bytes record 43 -> 5,2560

INFO Majority Node Set <QON>: Crs3: append record 43 epoch 377 seq 0 state b

INFO Majority Node Set <QON>: Crs3: flush 512 bytes record 43 -> 5,2560

INFO Majority Node Set <QON>: FsNotifyCallback: Enqueing Change notification for Fd:0x370

INFO Majority Node Set <QON>: FsNotifyCallback: Enqueing Change notification for Fd:0x310

INFO Majority Node Set <QON>: FspJoin Exit: vol 3a9743cd-7055-450e-8d70-1249c2bfe727$ WSet e Rset e ASet e (Exit of FspJoin:

(Note The new Wset, Rset, and Aset are same as the joinmask, and MNS was able to synchronize all the shares it took during arbitration. The Main arbitration thread exits.)

INFO Majority Node Set <QON>: Arbitrate request status 0.

<div class="references_section">