Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-12827

can't log in again after running mongorestore?

    • Type: Icon: Bug Bug
    • Resolution: Cannot Reproduce
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Tools
    • ALL

      set up as follows:

      1. start up the source replset on 2.4, create user

      {user:"user", pwd:"pwd"}

      , then upgrade the set to 2.6.
      login as "user" and insert a bunch more test users with various roles into the admin db.

      2. start up the target replset on 2.4, create user

      {user:"user", pwd:"pwd"}

      , then upgrade it to 2.6.

      at this point, both source and target have the old auth schema, both contain a user with username:pw equal to "user":"pwd" but the source has a bunch more users that don't exist in the target yet.

      3. run mongodump on the source.

      4. run mongorestore into the target.

      5. i can't login as "user":"pwd" on the target anymore. the logs suggest that the user was deleted and trying to auth as the user fails

         Running mongorestore to target database (2.6) using mongorestore version: 2.4
      2014-02-21T15:06:03.972-0500 shell: started program mongorestore-2.4 --host rs3/Michaels-MacBook-Pro.local:50030,Michaels-MacBook-Pro.local:50031,Michaels-MacBook-Pro.local:50032 --username __system --password abcdefghijklmnopqrstuvwxyz --authenticationDatabase local
      sh84050| Fri Feb 21 15:06:03.992 starting new replica set monitor for replica set rs3 with seed of Michaels-MacBook-Pro.local:50030,Michaels-MacBook-Pro.local:50031,Michaels-MacBook-Pro.local:50032
      sh84050| Fri Feb 21 15:06:03.993 successfully connected to seed Michaels-MacBook-Pro.local:50030 for replica set rs3
       m50030| 2014-02-21T15:06:03.993-0500 [initandlisten] connection accepted from 10.4.122.245:65337 #2 (2 connections now open)
      sh84050| Fri Feb 21 15:06:03.993 changing hosts to { 0: "Michaels-MacBook-Pro.local:50030", 1: "Michaels-MacBook-Pro.local:50032", 2: "Michaels-MacBook-Pro.local:50031" } from rs3/
      sh84050| Fri Feb 21 15:06:03.993 trying to add new host Michaels-MacBook-Pro.local:50030 to replica set rs3
      sh84050| Fri Feb 21 15:06:03.994 successfully connected to new host Michaels-MacBook-Pro.local:50030 in replica set rs3
       m50030| 2014-02-21T15:06:03.994-0500 [initandlisten] connection accepted from 10.4.122.245:65338 #3 (3 connections now open)
      sh84050| Fri Feb 21 15:06:03.994 trying to add new host Michaels-MacBook-Pro.local:50031 to replica set rs3
      sh84050| Fri Feb 21 15:06:03.994 successfully connected to new host Michaels-MacBook-Pro.local:50031 in replica set rs3
      sh84050| Fri Feb 21 15:06:03.994 trying to add new host Michaels-MacBook-Pro.local:50032 to replica set rs3
       m50031| 2014-02-21T15:06:03.994-0500 [initandlisten] connection accepted from 10.4.122.245:65339 #6 (3 connections now open)
      sh84050| Fri Feb 21 15:06:03.994 successfully connected to new host Michaels-MacBook-Pro.local:50032 in replica set rs3
       m50032| 2014-02-21T15:06:03.994-0500 [initandlisten] connection accepted from 10.4.122.245:65340 #5 (3 connections now open)
       m50030| 2014-02-21T15:06:03.995-0500 [initandlisten] connection accepted from 10.4.122.245:65341 #4 (4 connections now open)
       m50031| 2014-02-21T15:06:03.995-0500 [initandlisten] connection accepted from 10.4.122.245:65342 #7 (4 connections now open)
      sh84050| Fri Feb 21 15:06:03.996 Primary for replica set rs3 changed to Michaels-MacBook-Pro.local:50032
       m50031| 2014-02-21T15:06:03.996-0500 [conn7] Unauthorized not authorized on admin to execute command { replSetGetStatus: 1 }
       m50030| 2014-02-21T15:06:03.995-0500 [conn4] Unauthorized not authorized on admin to execute command { replSetGetStatus: 1 }
       m50030| 2014-02-21T15:06:03.995-0500 [conn2] end connection 10.4.122.245:65337 (3 connections now open)
       m50030| 2014-02-21T15:06:03.995-0500 [conn4] Unauthorized not authorized on admin to execute command { replSetGetStatus: 1 }
       m50032| 2014-02-21T15:06:03.996-0500 [initandlisten] connection accepted from 10.4.122.245:65343 #6 (4 connections now open)
       m50032| 2014-02-21T15:06:03.996-0500 [conn6] Unauthorized not authorized on admin to execute command { replSetGetStatus: 1 }
       m50032| 2014-02-21T15:06:03.996-0500 [conn6] Unauthorized not authorized on admin to execute command { replSetGetStatus: 1 }
      sh84050| Fri Feb 21 15:06:03.996 replica set monitor for replica set rs3 started, address is rs3/Michaels-MacBook-Pro.local:50030,Michaels-MacBook-Pro.local:50031,Michaels-MacBook-Pro.local:50032
      sh84050| connected to: rs3/Michaels-MacBook-Pro.local:50030,Michaels-MacBook-Pro.local:50031,Michaels-MacBook-Pro.local:50032
      sh84050| Fri Feb 21 15:06:03.996 [ReplicaSetMonitorWatcher] starting
       m50032| 2014-02-21T15:06:03.997-0500 [initandlisten] connection accepted from 10.4.122.245:65344 #7 (5 connections now open)
       m50032| 2014-02-21T15:06:03.997-0500 [conn7]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
      sh84050| Fri Feb 21 15:06:03.998 dump/admin/system.users.bson
      sh84050| Fri Feb 21 15:06:03.998        going into namespace [admin.system.users]
      sh84050| Fri Feb 21 15:06:03.998 warning: Restoring to admin.system.users without dropping. Restored data will be inserted without raising errors; check your server log
      sh84050| 10 objects found
      sh84050| Fri Feb 21 15:06:03.999        Creating index: { key: { _id: 1 }, ns: "admin.system.users", name: "_id_" }
      sh84050| Fri Feb 21 15:06:03.999        Creating index: { key: { user: 1, userSource: 1 }, unique: true, ns: "admin.system.users", name: "user_1_userSource_1" }
      MONGORESTORE is done.
      sh84050| Fri Feb 21 15:06:03.999 dump/admin/system.version.bson
      sh84050| Fri Feb 21 15:06:03.999        going into namespace [admin.system.version]
      sh84050| 1 objects found
      sh84050| Fri Feb 21 15:06:03.999        Creating index: { key: { _id: 1 }, name: "_id_", ns: "admin.system.version" }
      authing to target db
       m50031| 2014-02-21T15:06:03.998-0500 [initandlisten] connection accepted from 10.4.122.245:65345 #8 (5 connections now open)
       m50030| 2014-02-21T15:06:04.002-0500 [conn4] end connection 10.4.122.245:65341 (2 connections now open)
       m50031| 2014-02-21T15:06:03.998-0500 [conn8]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
      Error: 18 { ok: 0.0, errmsg: "auth failed", code: 18 }
       m50031| 2014-02-21T15:06:04.002-0500 [conn8] end connection 10.4.122.245:65345 (4 connections now open)
       m50031| 2014-02-21T15:06:04.002-0500 [conn6] end connection 10.4.122.245:65339 (3 connections now open)
      0
       m50030| 2014-02-21T15:06:04.003-0500 [conn3] end connection 10.4.122.245:65338 (1 connection now open)
       m50031| 2014-02-21T15:06:04.003-0500 [conn7] end connection 10.4.122.245:65342 (2 connections now open)
       m50032| 2014-02-21T15:06:03.999-0500 [conn7] build index on: admin.system.version properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "admin.system.version" }
       m50032| 2014-02-21T15:06:03.999-0500 [conn7]    added index to empty collection
       m50032| 2014-02-21T15:06:04.002-0500 [conn7] end connection 10.4.122.245:65344 (4 connections now open)
       m50032| 2014-02-21T15:06:04.002-0500 [conn6] end connection 10.4.122.245:65343 (4 connections now open)
       m50032| 2014-02-21T15:06:04.002-0500 [conn5] end connection 10.4.122.245:65340 (3 connections now open)
       m50032| 2014-02-21T15:06:04.004-0500 [conn1] Removed deleted user user@admin from session cache of user information.
       m50032| 2014-02-21T15:06:04.004-0500 [conn1]  authenticate db: admin { authenticate: 1, nonce: "xxx", user: "user", key: "xxx" }
       m50032| 2014-02-21T15:06:04.004-0500 [conn1] Failed to authenticate user@admin with mechanism MONGODB-CR: AuthenticationFailed UserNotFound Could not find user user@admin
       m50031| 2014-02-21T15:06:04.509-0500 [rsHealthPoll] replSet member Michaels-MacBook-Pro.local:50032 is now in state PRIMARY
       m50030| 2014-02-21T15:06:04.510-0500 [initandlisten] connection accepted from 10.4.122.245:65346 #5 (2 connections now open)
       m50030| 2014-02-21T15:06:04.511-0500 [conn5]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50031| 2014-02-21T15:06:04.511-0500 [rsHealthPoll] replset info Michaels-MacBook-Pro.local:50030 thinks that we are down
       m50031| 2014-02-21T15:06:05.509-0500 [rsBackgroundSync] replSet syncing to: Michaels-MacBook-Pro.local:50032
       m50032| 2014-02-21T15:06:05.510-0500 [initandlisten] connection accepted from 10.4.122.245:65347 #8 (3 connections now open)
       m50032| 2014-02-21T15:06:05.511-0500 [conn8]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50032| 2014-02-21T15:06:05.512-0500 [initandlisten] connection accepted from 10.4.122.245:65348 #9 (4 connections now open)
       m50032| 2014-02-21T15:06:05.512-0500 [conn9]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50031| 2014-02-21T15:06:05.513-0500 [repl writer worker 1] build index on: admin.system.version properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "admin.system.version" }
       m50031| 2014-02-21T15:06:05.513-0500 [repl writer worker 1]     added index to empty collection
       m50030| 2014-02-21T15:06:05.716-0500 [initandlisten] connection accepted from 10.4.122.245:65349 #6 (3 connections now open)
       m50030| 2014-02-21T15:06:05.716-0500 [conn6]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50032| 2014-02-21T15:06:05.717-0500 [rsHealthPoll] replset info Michaels-MacBook-Pro.local:50030 thinks that we are down
       m50032| 2014-02-21T15:06:05.804-0500 [initandlisten] connection accepted from 10.4.122.245:65350 #10 (5 connections now open)
       m50031| 2014-02-21T15:06:05.804-0500 [initandlisten] connection accepted from 10.4.122.245:65351 #9 (3 connections now open)
       m50031| 2014-02-21T15:06:05.805-0500 [conn9]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50032| 2014-02-21T15:06:05.805-0500 [conn10]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50030| 2014-02-21T15:06:05.805-0500 [rsHealthPoll] replSet member Michaels-MacBook-Pro.local:50031 is up
       m50030| 2014-02-21T15:06:05.805-0500 [rsHealthPoll] replSet member Michaels-MacBook-Pro.local:50032 is up
       m50030| 2014-02-21T15:06:05.805-0500 [rsHealthPoll] replSet member Michaels-MacBook-Pro.local:50031 is now in state SECONDARY
       m50030| 2014-02-21T15:06:05.805-0500 [rsHealthPoll] replSet member Michaels-MacBook-Pro.local:50032 is now in state PRIMARY
       m50032| 2014-02-21T15:06:06.528-0500 [slaveTracking] build index on: local.slaves properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.slaves" }
       m50032| 2014-02-21T15:06:06.528-0500 [slaveTracking]    added index to empty collection
       m40021| 2014-02-21T15:06:07.049-0500 [conn5] end connection 10.4.122.245:65302 (6 connections now open)
       m40021| 2014-02-21T15:06:07.049-0500 [initandlisten] connection accepted from 10.4.122.245:65352 #13 (7 connections now open)
       m40021| 2014-02-21T15:06:07.050-0500 [conn13]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50030| 2014-02-21T15:06:08.514-0500 [conn5] end connection 10.4.122.245:65346 (2 connections now open)
       m50030| 2014-02-21T15:06:08.514-0500 [initandlisten] connection accepted from 10.4.122.245:65353 #7 (3 connections now open)
       m50030| 2014-02-21T15:06:08.515-0500 [conn7]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50030| 2014-02-21T15:06:09.719-0500 [conn6] end connection 10.4.122.245:65349 (2 connections now open)
       m50030| 2014-02-21T15:06:09.720-0500 [initandlisten] connection accepted from 10.4.122.245:65354 #8 (3 connections now open)
       m50030| 2014-02-21T15:06:09.720-0500 [conn8]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50030| 2014-02-21T15:06:10.808-0500 [rsBackgroundSync] replSet syncing to: Michaels-MacBook-Pro.local:50031
       m50031| 2014-02-21T15:06:10.809-0500 [initandlisten] connection accepted from 10.4.122.245:65355 #10 (4 connections now open)
       m50031| 2014-02-21T15:06:10.809-0500 [conn10]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50031| 2014-02-21T15:06:10.810-0500 [initandlisten] connection accepted from 10.4.122.245:65356 #11 (5 connections now open)
       m50031| 2014-02-21T15:06:10.810-0500 [conn11]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50030| 2014-02-21T15:06:10.811-0500 [rsSyncNotifier] replset setting oplog notifier to Michaels-MacBook-Pro.local:50031
       m50031| 2014-02-21T15:06:10.811-0500 [conn11] end connection 10.4.122.245:65356 (4 connections now open)
       m50031| 2014-02-21T15:06:10.811-0500 [initandlisten] connection accepted from 10.4.122.245:65357 #12 (5 connections now open)
       m50031| 2014-02-21T15:06:10.811-0500 [conn12]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
       m50030| 2014-02-21T15:06:10.812-0500 [rsSync] build index on: local.replset.minvalid properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.replset.minvalid" }
       m50030| 2014-02-21T15:06:10.812-0500 [rsSync]   added index to empty collection
       m50030| 2014-02-21T15:06:10.813-0500 [repl writer worker 1] build index on: admin.system.version properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "admin.system.version" }
       m50030| 2014-02-21T15:06:10.813-0500 [repl writer worker 1]     added index to empty collection
       m50031| 2014-02-21T15:06:12.315-0500 [slaveTracking] build index on: local.slaves properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.slaves" }
       m50031| 2014-02-21T15:06:12.315-0500 [slaveTracking]    added index to empty collection
       m50032| 2014-02-21T15:06:14.007-0500 [conn1] assertion 13 not authorized for query on admin.system.users ns:admin.system.users query:{}
      2014-02-21T15:06:14.008-0500 error: { "$err" : "not authorized for query on admin.system.users", "code" : 13 } at src/mongo/shell/query.js:131
      
      

            Assignee:
            spencer@mongodb.com Spencer Brody (Inactive)
            Reporter:
            mikeo@mongodb.com Michael O'Brien
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: