[SERVER-74134] Calling plist_options is deprecated! Use service.require_root instead Created: 17/Feb/23  Updated: 27/Oct/23  Resolved: 20/Mar/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 6.0.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Riku Kallio Assignee: [DO NOT ASSIGN] Backlog - Server Development Platform Team (SDP) (Inactive)
Resolution: Works as Designed Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File Screenshot 2023-02-17 at 12.33.55.png     PNG File Screenshot 2023-02-28 at 13.09.15.png    
Issue Links:
Duplicate
duplicates SERVER-74025 Package a launchd plist file into mac... Closed
is duplicated by CDRIVER-4581 Calling plist_options is deprecated! ... Closed
Related
is related to SERVER-74156 Package plist files with macosx releases Closed
is related to SERVER-74157 Update brew tap to use plist files ra... Closed
Assigned Teams:
Server Development Platform
Operating System: ALL
Steps To Reproduce:

Upgrade or install latest homebrew

brew update

or

/bin/bash -c "$(curl -fsSL https://raw.githubusercontent.com/Homebrew/install/HEAD/install.sh)"

Install mongo with brew

brew tap mongodb/brew
brew update
brew install mongodb-community@6.0

Start mongo (this is where the error comes)

brew services start mongodb-community@6.0

Participants:

 Description   

Summary
This is considering the brew package of mongodb (https://github.com/mongodb/homebrew-brew).

I consider this a Critical bug, since you mongodb manual is proposing to use home brew to install mongodb on mac os x: https://www.mongodb.com/docs/manual/tutorial/install-mongodb-on-os-x/

After updating to the latest version of brew (4.0.0 https://brew.sh/2023/02/16/homebrew-4.0.0/) mongodb does not start.

Running

brew services start mongodb-community

gives out the following error:

==> Downloading https://formulae.brew.sh/api/formula.jsonWarning: Calling plist_options is deprecated! Use service.require_root instead.
Please report this issue to the mongodb/brew tap (not Homebrew/brew or Homebrew/homebrew-core), or even better, submit a PR to fix it:
  /usr/local/Homebrew/Library/Taps/mongodb/homebrew-brew/Formula/mongodb-community.rb:55Bootstrap failed: 5: Input/output error
Try re-running the command as root for richer errors. 

What this means, is that all the calls to plist_options are deprecated and should be changed to service.require_root.

Environment
OS: MacOS Monterey 12.6

MongoDB community version: 6.0

installed through command

brew install mongodb-community@6.0

TLDR:

plist_options should be replaced with service.require_root



 Comments   
Comment by Riku Kallio [ 28/Feb/23 ]

Hi Iryna, I've managed to get it working. I needed to do an upgrade to my mongo instances first.

Simply by following mongo's upgrade instructions, I've managed to get it working now:

https://www.mongodb.com/docs/manual/release-notes/5.0-upgrade-standalone/
https://www.mongodb.com/docs/manual/release-notes/6.0-upgrade-standalone/

Thank you for your responses and the fixes you've made to the brew package. My local mongo instance works very well again, and running the latest 6.0.4 mongo version (used to be 4.4)!

 

Comment by andy _ [ 21/Feb/23 ]

Here are my logs from service start to finish `tail -f /opt/homebrew/var/log/mongodb/mongo.log`

{"t":{"$date":"2023-02-21T13:11:18.055-05:00"},"s":"I",  "c":"CONTROL",  "id":20698,   "ctx":"-","msg":"***** SERVER RESTARTED *****"}
{"t":{"$date":"2023-02-21T13:11:18.059-05:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"-","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":17},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":17},"outgoing":{"minWireVersion":6,"maxWireVersion":17},"isInternalClient":true}}}
{"t":{"$date":"2023-02-21T13:11:18.059-05:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"thread1","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2023-02-21T13:11:18.059-05:00"},"s":"I",  "c":"NETWORK",  "id":4648602, "ctx":"thread1","msg":"Implicit TCP FastOpen in use."}
{"t":{"$date":"2023-02-21T13:11:18.060-05:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"thread1","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","namespace":"config.tenantMigrationDonors"}}
{"t":{"$date":"2023-02-21T13:11:18.060-05:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"thread1","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","namespace":"config.tenantMigrationRecipients"}}
{"t":{"$date":"2023-02-21T13:11:18.060-05:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"thread1","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"ShardSplitDonorService","namespace":"config.tenantSplitDonors"}}
{"t":{"$date":"2023-02-21T13:11:18.060-05:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"thread1","msg":"Multi threading initialized"}
{"t":{"$date":"2023-02-21T13:11:18.060-05:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":22541,"port":27017,"dbPath":"/opt/homebrew/var/mongodb","architecture":"64-bit","host":"<myhost>"}}
{"t":{"$date":"2023-02-21T13:11:18.060-05:00"},"s":"I",  "c":"CONTROL",  "id":23352,   "ctx":"initandlisten","msg":"Unable to resolve sysctl {sysctlName} (number) ","attr":{"sysctlName":"hw.cpufrequency"}}
{"t":{"$date":"2023-02-21T13:11:18.061-05:00"},"s":"I",  "c":"CONTROL",  "id":23351,   "ctx":"initandlisten","msg":"{sysctlName} unavailable","attr":{"sysctlName":"machdep.cpu.features"}}
{"t":{"$date":"2023-02-21T13:11:18.061-05:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"6.0.4","gitVersion":"44ff59461c1353638a71e710f385a566bcd2f547","modules":[],"allocator":"system","environment":{"distarch":"aarch64","target_arch":"aarch64"}}}}
{"t":{"$date":"2023-02-21T13:11:18.061-05:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"Mac OS X","version":"22.3.0"}}}
{"t":{"$date":"2023-02-21T13:11:18.061-05:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/opt/homebrew/etc/mongod.conf","net":{"bindIp":"127.0.0.1, ::1","ipv6":true},"storage":{"dbPath":"/opt/homebrew/var/mongodb"},"systemLog":{"destination":"file","logAppend":true,"path":"/opt/homebrew/var/log/mongodb/mongo.log"}}}}
{"t":{"$date":"2023-02-21T13:11:18.061-05:00"},"s":"I",  "c":"NETWORK",  "id":5693100, "ctx":"initandlisten","msg":"Asio socket.set_option failed with std::system_error","attr":{"note":"acceptor TCP fast open","option":{"level":6,"name":261,"data":"00 04 00 00"},"error":{"what":"set_option: Invalid argument","message":"Invalid argument","category":"asio.system","value":22}}}
{"t":{"$date":"2023-02-21T13:11:18.061-05:00"},"s":"I",  "c":"NETWORK",  "id":5693100, "ctx":"initandlisten","msg":"Asio socket.set_option failed with std::system_error","attr":{"note":"acceptor TCP fast open","option":{"level":6,"name":261,"data":"00 04 00 00"},"error":{"what":"set_option: Invalid argument","message":"Invalid argument","category":"asio.system","value":22}}}
{"t":{"$date":"2023-02-21T13:11:18.061-05:00"},"s":"I",  "c":"STORAGE",  "id":22270,   "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/opt/homebrew/var/mongodb","storageEngine":"wiredTiger"}}
{"t":{"$date":"2023-02-21T13:11:18.062-05:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=11776M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,remove=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=2000),statistics_log=(wait=0),json_output=(error,message),verbose=[recovery_progress:1,checkpoint_progress:1,compact_progress:1,backup:0,checkpoint:0,compact:0,evict:0,history_store:0,recovery:0,rts:0,salvage:0,tiered:0,timestamp:0,transaction:0,verify:0,log:0],"}}
{"t":{"$date":"2023-02-21T13:11:18.522-05:00"},"s":"I",  "c":"STORAGE",  "id":4795906, "ctx":"initandlisten","msg":"WiredTiger opened","attr":{"durationMillis":460}}
{"t":{"$date":"2023-02-21T13:11:18.523-05:00"},"s":"I",  "c":"RECOVERY", "id":23987,   "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
{"t":{"$date":"2023-02-21T13:11:18.543-05:00"},"s":"W",  "c":"CONTROL",  "id":22120,   "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted","tags":["startupWarnings"]}
{"t":{"$date":"2023-02-21T13:11:18.543-05:00"},"s":"W",  "c":"CONTROL",  "id":22184,   "ctx":"initandlisten","msg":"Soft rlimits for open file descriptors too low","attr":{"currentValue":256,"recommendedMinimum":64000},"tags":["startupWarnings"]}
{"t":{"$date":"2023-02-21T13:11:18.544-05:00"},"s":"F",  "c":"CONTROL",  "id":20573,   "ctx":"initandlisten","msg":"Wrong mongod version","attr":{"error":"UPGRADE PROBLEM: Found an invalid featureCompatibilityVersion document (ERROR: Location4926900: Invalid featureCompatibilityVersion document in admin.system.version: { _id: \"featureCompatibilityVersion\", version: \"4.2\" }. See https://docs.mongodb.com/master/release-notes/5.0-compatibility/#feature-compatibility. :: caused by :: Invalid feature compatibility version value, expected '5.0' or '5.3' or '6.0. See https://docs.mongodb.com/master/release-notes/5.0-compatibility/#feature-compatibility.). If the current featureCompatibilityVersion is below 5.0, see the documentation on upgrading at https://docs.mongodb.com/master/release-notes/5.0/#upgrade-procedures."}}
{"t":{"$date":"2023-02-21T13:11:18.544-05:00"},"s":"I",  "c":"REPL",     "id":4784900, "ctx":"initandlisten","msg":"Stepping down the ReplicationCoordinator for shutdown","attr":{"waitTimeMillis":15000}}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"REPL",     "id":4794602, "ctx":"initandlisten","msg":"Attempting to enter quiesce mode"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"-",        "id":6371601, "ctx":"initandlisten","msg":"Shutting down the FLE Crud thread pool"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"COMMAND",  "id":4784901, "ctx":"initandlisten","msg":"Shutting down the MirrorMaestro"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"SHARDING", "id":4784902, "ctx":"initandlisten","msg":"Shutting down the WaitForMajorityService"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"NETWORK",  "id":20562,   "ctx":"initandlisten","msg":"Shutdown: going to close listening sockets"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"NETWORK",  "id":4784905, "ctx":"initandlisten","msg":"Shutting down the global connection pool"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"CONTROL",  "id":4784906, "ctx":"initandlisten","msg":"Shutting down the FlowControlTicketholder"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"-",        "id":20520,   "ctx":"initandlisten","msg":"Stopping further Flow Control ticket acquisitions."}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"CONTROL",  "id":4784908, "ctx":"initandlisten","msg":"Shutting down the PeriodicThreadToAbortExpiredTransactions"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"REPL",     "id":4784909, "ctx":"initandlisten","msg":"Shutting down the ReplicationCoordinator"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"SHARDING", "id":4784910, "ctx":"initandlisten","msg":"Shutting down the ShardingInitializationMongoD"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"REPL",     "id":4784911, "ctx":"initandlisten","msg":"Enqueuing the ReplicationStateTransitionLock for shutdown"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"-",        "id":4784912, "ctx":"initandlisten","msg":"Killing all operations for shutdown"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"-",        "id":4695300, "ctx":"initandlisten","msg":"Interrupted all currently running operations","attr":{"opsKilled":3}}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"TENANT_M", "id":5093807, "ctx":"initandlisten","msg":"Shutting down all TenantMigrationAccessBlockers on global shutdown"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"COMMAND",  "id":4784913, "ctx":"initandlisten","msg":"Shutting down all open transactions"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"REPL",     "id":4784914, "ctx":"initandlisten","msg":"Acquiring the ReplicationStateTransitionLock for shutdown"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"INDEX",    "id":4784915, "ctx":"initandlisten","msg":"Shutting down the IndexBuildsCoordinator"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"NETWORK",  "id":4784918, "ctx":"initandlisten","msg":"Shutting down the ReplicaSetMonitor"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"SHARDING", "id":4784921, "ctx":"initandlisten","msg":"Shutting down the MigrationUtilExecutor"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"ASIO",     "id":22582,   "ctx":"MigrationUtil-TaskExecutor","msg":"Killing all outstanding egress activity."}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"COMMAND",  "id":4784923, "ctx":"initandlisten","msg":"Shutting down the ServiceEntryPoint"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"CONTROL",  "id":4784925, "ctx":"initandlisten","msg":"Shutting down free monitoring"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"CONTROL",  "id":4784927, "ctx":"initandlisten","msg":"Shutting down the HealthLog"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"CONTROL",  "id":4784928, "ctx":"initandlisten","msg":"Shutting down the TTL monitor"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"CONTROL",  "id":6278511, "ctx":"initandlisten","msg":"Shutting down the Change Stream Expired Pre-images Remover"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"CONTROL",  "id":4784929, "ctx":"initandlisten","msg":"Acquiring the global lock for shutdown"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"CONTROL",  "id":4784930, "ctx":"initandlisten","msg":"Shutting down the storage engine"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":22320,   "ctx":"initandlisten","msg":"Shutting down journal flusher thread"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":22321,   "ctx":"initandlisten","msg":"Finished shutting down journal flusher thread"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":22322,   "ctx":"initandlisten","msg":"Shutting down checkpoint thread"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":22323,   "ctx":"initandlisten","msg":"Finished shutting down checkpoint thread"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":20282,   "ctx":"initandlisten","msg":"Deregistering all the collections"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":22317,   "ctx":"initandlisten","msg":"WiredTigerKVEngine shutting down"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":22318,   "ctx":"initandlisten","msg":"Shutting down session sweeper thread"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":22319,   "ctx":"initandlisten","msg":"Finished shutting down session sweeper thread"}
{"t":{"$date":"2023-02-21T13:11:18.545-05:00"},"s":"I",  "c":"STORAGE",  "id":22324,   "ctx":"initandlisten","msg":"Closing WiredTiger in preparation for reconfiguring","attr":{"closeConfig":"leak_memory=true,"}}
{"t":{"$date":"2023-02-21T13:11:18.592-05:00"},"s":"I",  "c":"STORAGE",  "id":4795905, "ctx":"initandlisten","msg":"WiredTiger closed","attr":{"durationMillis":47}}
{"t":{"$date":"2023-02-21T13:11:18.888-05:00"},"s":"I",  "c":"STORAGE",  "id":4795904, "ctx":"initandlisten","msg":"WiredTiger re-opened","attr":{"durationMillis":296}}
{"t":{"$date":"2023-02-21T13:11:18.889-05:00"},"s":"I",  "c":"STORAGE",  "id":22325,   "ctx":"initandlisten","msg":"Reconfiguring","attr":{"newConfig":"compatibility=(release=3.3)"}}
{"t":{"$date":"2023-02-21T13:11:18.975-05:00"},"s":"I",  "c":"STORAGE",  "id":4795903, "ctx":"initandlisten","msg":"Reconfigure complete","attr":{"durationMillis":86}}
{"t":{"$date":"2023-02-21T13:11:18.975-05:00"},"s":"I",  "c":"STORAGE",  "id":4795902, "ctx":"initandlisten","msg":"Closing WiredTiger","attr":{"closeConfig":"leak_memory=true,"}}
{"t":{"$date":"2023-02-21T13:11:19.028-05:00"},"s":"I",  "c":"STORAGE",  "id":4795901, "ctx":"initandlisten","msg":"WiredTiger closed","attr":{"durationMillis":53}}
{"t":{"$date":"2023-02-21T13:11:19.028-05:00"},"s":"I",  "c":"STORAGE",  "id":22279,   "ctx":"initandlisten","msg":"shutdown: removing fs lock..."}
{"t":{"$date":"2023-02-21T13:11:19.028-05:00"},"s":"I",  "c":"-",        "id":4784931, "ctx":"initandlisten","msg":"Dropping the scope cache for shutdown"}
{"t":{"$date":"2023-02-21T13:11:19.028-05:00"},"s":"I",  "c":"CONTROL",  "id":20565,   "ctx":"initandlisten","msg":"Now exiting"}
{"t":{"$date":"2023-02-21T13:11:19.028-05:00"},"s":"I",  "c":"CONTROL",  "id":23138,   "ctx":"initandlisten","msg":"Shutting down","attr":{"exitCode":62}}

Comment by Iryna Zhuravlova [ 21/Feb/23 ]

Hi riku.kallio.ext@konecranes.com, Would you mind providing us with logs so our team could investigate this. Thank you!

Comment by Riku Kallio [ 21/Feb/23 ]

Hi!

I see there has been an update to the mongo's brew repository:

https://github.com/mongodb/homebrew-brew/pull/174

and

https://github.com/mongodb/homebrew-brew/commit/47b42c4507ca3dd48e2419247bb88772131bd916

 

However, the as Andy commented above, mongo can not be started. Is there going to be another update on this?

Comment by andy _ [ 18/Feb/23 ]

The warning is gone now, but still can't start the service

```
$ brew services start mongodb-community

==> Successfully started `mongodb-community` (label: homebrew.mxcl.mongodb-community)

$ brew services
Name Status User File
mongodb-community error 15872 USER ~/Library/LaunchAgents/homebrew.mxcl.mongodb-community.plist
```

Comment by Yuan Fang [ 17/Feb/23 ]

Hi riku.kallio.ext@konecranes.com,

Thank you for bringing this to our attention. I've passed this along to the team for investigation. Please stay tuned for further updates.

Regards,
Yuan

Comment by Francesco Bresciani [ 17/Feb/23 ]

Also affects 6.0.4

Comment by Riku Kallio [ 17/Feb/23 ]

For reference: there's also a stackoverflow question about this on 10th February 2023: https://stackoverflow.com/questions/75410705/please-report-this-issue-to-the-mongodb-brew-pr-to-fix-it (unanswered as of writing this comment)

Comment by Riku Kallio [ 17/Feb/23 ]

One of the affected code lines is here: https://github.com/mongodb/homebrew-brew/blame/ecb3de46f3ce6dbbf9983fabb97b719b858cccc5/Formula/mongodb-community.rb#L55 

Comment by Riku Kallio [ 17/Feb/23 ]

For reference: Two days ago a user wppoland reported an issue to homebrew, and they directed them to post an issue to mongo: https://github.com/Homebrew/brew/issues/14641

Generated at Thu Feb 08 06:26:36 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.