Uploaded image for project: 'Go Driver'
  1. Go Driver
  2. GODRIVER-846

Unable to authenticate to a replica set member using the keyfile

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 1.0.0-rc1
    • Affects Version/s: None
    • Component/s: None
    • None

      This is a regression introduced by GODRIVER-803.  The commit before that one does not have this problem.

       

      How to reproduce:

       

      1. Start a 1-node replica set with auth and a keyfile containing "testkeyfilecontents" 
      2. Run the attached go-driver-auth.go program.  The following happens

       

      [tim@jazzstep-2 tst]$ go run go-driver-auth.go
      panic: (Unauthorized) not authorized on admin to execute command { serverStatus: 1, locks: false, recordStats: false, $db: "admin", $readPreference: { mode: "primaryPreferred" } }
      
      goroutine 1 [running]:
      main.main()
      	/Users/tim/tst/go-driver-auth.go:38 +0x520
      exit status 2
      

       
      Note that I did not even use the new AuthenticateArbiter option.

      MongoDB logs show that authentication is not even happening.

      2019-02-21T15:23:26.860-0500 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
      2019-02-21T15:23:26.877-0500 I CONTROL  [initandlisten] MongoDB starting : pid=74533 port=27017 dbpath=db1 64-bit host=jazzstep-2.local
      2019-02-21T15:23:26.877-0500 I CONTROL  [initandlisten] db version v4.0.4
      2019-02-21T15:23:26.877-0500 I CONTROL  [initandlisten] git version: f288a3bdf201007f3693c58e140056adf8b04839
      2019-02-21T15:23:26.878-0500 I CONTROL  [initandlisten] allocator: system
      2019-02-21T15:23:26.878-0500 I CONTROL  [initandlisten] modules: none
      2019-02-21T15:23:26.878-0500 I CONTROL  [initandlisten] build environment:
      2019-02-21T15:23:26.878-0500 I CONTROL  [initandlisten]     distarch: x86_64
      2019-02-21T15:23:26.878-0500 I CONTROL  [initandlisten]     target_arch: x86_64
      2019-02-21T15:23:26.878-0500 I CONTROL  [initandlisten] options: { replication: { replSet: "rs0" }, security: { keyFile: "keyfile" }, storage: { dbPath: "db1" } }
      2019-02-21T15:23:26.879-0500 I STORAGE  [initandlisten] Detected data files in db1 created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
      2019-02-21T15:23:26.879-0500 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
      2019-02-21T15:23:27.580-0500 I STORAGE  [initandlisten] WiredTiger message [1550780607:580270][74533:0x119acd5c0], txn-recover: Main recovery loop: starting at 1/22016 to 2/256
      2019-02-21T15:23:27.661-0500 I STORAGE  [initandlisten] WiredTiger message [1550780607:661341][74533:0x119acd5c0], txn-recover: Recovering log 1 through 2
      2019-02-21T15:23:27.723-0500 I STORAGE  [initandlisten] WiredTiger message [1550780607:723243][74533:0x119acd5c0], txn-recover: Recovering log 2 through 2
      2019-02-21T15:23:27.765-0500 I STORAGE  [initandlisten] WiredTiger message [1550780607:765375][74533:0x119acd5c0], txn-recover: Set global recovery timestamp: 0
      2019-02-21T15:23:27.836-0500 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
      2019-02-21T15:23:27.876-0500 I CONTROL  [initandlisten] 
      2019-02-21T15:23:27.876-0500 I CONTROL  [initandlisten] ** WARNING: This server is bound to localhost.
      2019-02-21T15:23:27.876-0500 I CONTROL  [initandlisten] **          Remote systems will be unable to connect to this server. 
      2019-02-21T15:23:27.876-0500 I CONTROL  [initandlisten] **          Start the server with --bind_ip <address> to specify which IP 
      2019-02-21T15:23:27.876-0500 I CONTROL  [initandlisten] **          addresses it should serve responses from, or with --bind_ip_all to
      2019-02-21T15:23:27.876-0500 I CONTROL  [initandlisten] **          bind to all interfaces. If this behavior is desired, start the
      2019-02-21T15:23:27.876-0500 I CONTROL  [initandlisten] **          server with --bind_ip 127.0.0.1 to disable this warning.
      2019-02-21T15:23:27.876-0500 I CONTROL  [initandlisten] 
      2019-02-21T15:23:27.921-0500 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory 'db1/diagnostic.data'
      2019-02-21T15:23:27.926-0500 I REPL     [initandlisten] Did not find local voted for document at startup.
      2019-02-21T15:23:27.930-0500 I REPL     [initandlisten] Rollback ID is 1
      2019-02-21T15:23:27.930-0500 I REPL     [initandlisten] Did not find local replica set configuration document at startup;  NoMatchingDocument: Did not find replica set configuration document in local.system.replset
      2019-02-21T15:23:27.930-0500 I CONTROL  [LogicalSessionCacheRefresh] Sessions collection is not set up; waiting until next sessions refresh interval: Replication has not yet been configured
      2019-02-21T15:23:27.930-0500 I NETWORK  [initandlisten] waiting for connections on port 27017
      2019-02-21T15:23:27.930-0500 I CONTROL  [LogicalSessionCacheReap] Sessions collection is not set up; waiting until next sessions reap interval: config.system.sessions does not exist
      2019-02-21T15:23:39.084-0500 I NETWORK  [listener] connection accepted from 127.0.0.1:62305 #1 (1 connection now open)
      2019-02-21T15:23:39.084-0500 I ACCESS   [conn1] note: no users configured in admin.system.users, allowing localhost access
      2019-02-21T15:23:39.085-0500 I NETWORK  [listener] connection accepted from 127.0.0.1:62306 #2 (2 connections now open)
      2019-02-21T15:23:39.085-0500 I NETWORK  [conn2] received client metadata from 127.0.0.1:62306 conn2: { driver: { name: "mongo-go-driver", version: "v1.0.0-rc1+prerelease" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.10.5" }
      2019-02-21T15:23:39.085-0500 I ACCESS   [conn2] Unauthorized: not authorized on admin to execute command { serverStatus: 1, locks: false, recordStats: false, $db: "admin", $readPreference: { mode: "primaryPreferred" } }
      2019-02-21T15:23:39.086-0500 I NETWORK  [conn2] end connection 127.0.0.1:62306 (1 connection now open)
      2019-02-21T15:23:39.086-0500 I NETWORK  [conn1] end connection 127.0.0.1:62305 (0 connections now open)
      

       

      I am able to login using the keyfile using the mongo shell or the Go driver master commit before the GODRIVER-803 fix.

       

        1. go-driver-auth.go
          0.8 kB
          Timothy Olsen

            Assignee:
            isabella.siu@mongodb.com Isabella Siu (Inactive)
            Reporter:
            tim.olsen@mongodb.com Timothy Olsen (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: