api not syncing

jamiekp
jamiekp
Community Member
in Secrets Automation

Hi

I've followed the instructions to run the api and sync services under docker-compose. I'm using docker-for-mac on an M1 based machine. When I try to make a request against the API this is what I see in the logs:

1password-api on  master [?] on ☁️ kida(default) took 22m19s ❯ docker compose up [+] Running 2/0 ⠿ Container 1password-api_op-connect-api_1 Created 0.0s ⠿ Container 1password-api_op-connect-sync_1 Created 0.0s Attaching to op-connect-api_1, op-connect-sync_1 op-connect-api_1 | {"log_message":"(I) [discovery-local] starting discovery, advertising endpoint 8080 /meta/message","timestamp":"2021-05-05T15:21:09.870819Z","level":3} op-connect-api_1 | {"log_message":"(I) starting 1Password Connect API ...","timestamp":"2021-05-05T15:21:09.887006Z","level":3} op-connect-api_1 | {"log_message":"(I) serving on :8080","timestamp":"2021-05-05T15:21:09.887369Z","level":3} op-connect-sync_1 | {"log_message":"(I) starting 1Password Connect Sync ...","timestamp":"2021-05-05T15:21:11.435617Z","level":3} op-connect-sync_1 | {"log_message":"(I) serving on :8080","timestamp":"2021-05-05T15:21:11.447728Z","level":3} op-connect-sync_1 | {"log_message":"(I) [discovery-local] starting discovery, advertising endpoint 8080 /meta/message","timestamp":"2021-05-05T15:21:11.427598Z","level":3} op-connect-sync_1 | {"log_message":"(I) database initialization complete","timestamp":"2021-05-05T15:21:11.499712Z","level":3} op-connect-sync_1 | {"log_message":"(I) ### syncer credentials bootstrap ### ","timestamp":"2021-05-05T15:21:11.501242Z","level":3} op-connect-api_1 | {"log_message":"(I) GET /v1/vaults","timestamp":"2021-05-05T15:22:06.888455Z","level":3,"scope":{"request_id":"e112a834-4f4a-436a-8237-cc4aa6a423bb"}} op-connect-api_1 | {"log_message":"(I) notifying syncer of new token","timestamp":"2021-05-05T15:22:06.89467Z","level":3,"scope":{"request_id":"e112a834-4f4a-436a-8237-cc4aa6a423bb","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}} op-connect-api_1 | {"log_message":"(I) awaiting healthy syncer before continuing","timestamp":"2021-05-05T15:22:06.916808Z","level":3,"scope":{"request_id":"e112a834-4f4a-436a-8237-cc4aa6a423bb","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}} op-connect-api_1 | {"log_message":"(I) GET /v1/vaults completed (408: Request Timeout)","timestamp":"2021-05-05T15:22:16.936807Z","level":3,"scope":{"request_id":"e112a834-4f4a-436a-8237-cc4aa6a423bb","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}}

I've no idea of the two components are talking to each other correctly and I'm not sure where to go from here. There aren't many knobs to tweak so I'm a little unsure what to do to debug this...

Thanks

1Password Version: Not Provided
Extension Version: Not Provided
OS Version: Not Provided
Sync Type: Not Provided

Comments

  • James_1P
    James_1P

    Hi jaimekp,

    Thanks for reaching out. The container logs you shared look mostly normal. The request can timeout if the initial sync takes longer than 10 seconds but there should be entries from the op-connect-sync_1 container after the notifying syncer of new token message appears from op-connect-api_1 detailing the sync progress.

    Given that there are no sync logs at all I have to assume there is something up with the communication between the two containers. You can use the OP_LOG_LEVEL environment variable in your docker compose to increase the log level to DEBUG to get more details on the websocket communications between the two containers.

  • jamiekp
    jamiekp
    Community Member

    Not much more info I'm afraid (there were more messages from the api container, but didn't seem to be from the sync container even though I set the variable in both):

    ❯ docker compose up [+] Running 2/0 ⠿ Container 1password-api_op-connect-api_1 Created 0.0s ⠿ Container 1password-api_op-connect-sync_1 Created 0.0s Attaching to op-connect-api_1, op-connect-sync_1 op-connect-api_1 | {"log_message":"(I) [discovery-local] starting discovery, advertising endpoint 8080 /meta/message","timestamp":"2021-05-05T18:09:17.584198Z","level":3} op-connect-api_1 | {"log_message":"(D) mounting route GET /heartbeat","timestamp":"2021-05-05T18:09:17.592668Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route GET /health","timestamp":"2021-05-05T18:09:17.597039Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route GET /v1/vaults","timestamp":"2021-05-05T18:09:17.597124Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route GET /v1/vaults/:vaultUUID","timestamp":"2021-05-05T18:09:17.597151Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route GET /v1/vaults/:vaultUUID/items","timestamp":"2021-05-05T18:09:17.598Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route POST /v1/vaults/:vaultUUID/items","timestamp":"2021-05-05T18:09:17.598434Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route GET /v1/vaults/:vaultUUID/items/:uuid","timestamp":"2021-05-05T18:09:17.59881Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route PUT /v1/vaults/:vaultUUID/items/:uuid","timestamp":"2021-05-05T18:09:17.598883Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route DELETE /v1/vaults/:vaultUUID/items/:uuid","timestamp":"2021-05-05T18:09:17.59895Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route PATCH /v1/vaults/:vaultUUID/items/:uuid","timestamp":"2021-05-05T18:09:17.599073Z","level":4} op-connect-api_1 | {"log_message":"(D) mounting route GET /v1/activity","timestamp":"2021-05-05T18:09:17.599113Z","level":4} op-connect-api_1 | {"log_message":"(I) starting 1Password Connect API ...","timestamp":"2021-05-05T18:09:17.599356Z","level":3} op-connect-api_1 | {"log_message":"(I) serving on :8080","timestamp":"2021-05-05T18:09:17.599535Z","level":3} op-connect-sync_1 | {"log_message":"(D) mounting route GET /heartbeat","timestamp":"2021-05-05T18:09:19.267081Z","level":4} op-connect-sync_1 | {"log_message":"(I) [discovery-local] starting discovery, advertising endpoint 8080 /meta/message","timestamp":"2021-05-05T18:09:19.261541Z","level":3} op-connect-sync_1 | {"log_message":"(D) mounting route GET /health","timestamp":"2021-05-05T18:09:19.284285Z","level":4} op-connect-sync_1 | {"log_message":"(I) starting 1Password Connect Sync ...","timestamp":"2021-05-05T18:09:19.284898Z","level":3} op-connect-sync_1 | {"log_message":"(I) serving on :8080","timestamp":"2021-05-05T18:09:19.285539Z","level":3} op-connect-sync_1 | {"log_message":"(I) database initialization complete","timestamp":"2021-05-05T18:09:19.330794Z","level":3} op-connect-sync_1 | {"log_message":"(I) ### syncer credentials bootstrap ### ","timestamp":"2021-05-05T18:09:19.332152Z","level":3} op-connect-api_1 | {"log_message":"(I) GET /v1/vaults","timestamp":"2021-05-05T18:09:51.390356Z","level":3,"scope":{"request_id":"28b40042-05c9-4813-ba84-60260d8f0e51"}} op-connect-api_1 | {"log_message":"(I) notifying syncer of new token","timestamp":"2021-05-05T18:09:51.396058Z","level":3,"scope":{"request_id":"28b40042-05c9-4813-ba84-60260d8f0e51","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}} op-connect-api_1 | {"log_message":"(D) Unable to find existing span for request 28b40042-05c9-4813-ba84-60260d8f0e51","timestamp":"2021-05-05T18:09:51.408233Z","level":4,"scope":{"request_id":"28b40042-05c9-4813-ba84-60260d8f0e51","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}} op-connect-api_1 | {"log_message":"(I) awaiting healthy syncer before continuing","timestamp":"2021-05-05T18:09:51.418558Z","level":3,"scope":{"request_id":"28b40042-05c9-4813-ba84-60260d8f0e51","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}} op-connect-api_1 | {"log_message":"(D) post-handler contenttype: ","timestamp":"2021-05-05T18:10:01.438002Z","level":4,"scope":{"request_id":"28b40042-05c9-4813-ba84-60260d8f0e51","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}} op-connect-api_1 | {"log_message":"(D) setting auto-detected contenttype: application/json","timestamp":"2021-05-05T18:10:01.439369Z","level":4,"scope":{"request_id":"28b40042-05c9-4813-ba84-60260d8f0e51","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}} op-connect-api_1 | {"log_message":"(I) GET /v1/vaults completed (408: Request Timeout)","timestamp":"2021-05-05T18:10:01.442261Z","level":3,"scope":{"request_id":"28b40042-05c9-4813-ba84-60260d8f0e51","jti":"pb7nnde2t7ohdld3xhy2tpzqma"}}

  • James_1P
    James_1P

    Thanks for sharing the DEBUG logs. Something odd is definitely happening here. Both containers use multicast networking to try and discover each other. In debug mode the output should include messages like "(D) received message" and "[discovery-local] potential peer found".

    That your logs don't include this leads me to wonder if there is something different about networking in Docker Desktop on an M1. I will have to get someone on my team to dig a littler further to help you.

  • jamiekp
    jamiekp
    Community Member

    I suspect that there are differences - the arm port of docker-for-mac is pretty immature right now still. Perhaps multicasting isn't supported yet....

    Is there a way to manually specify how the two should find each other?

  • James_1P
    James_1P

    Sadly there is no manual override for discovery right now :(

  • jamiekp
    jamiekp
    Community Member

    Any update here? Perhaps you folks would be able to add a command line option to manually specify the endpoint IPs for each service in a new release?

    Thanks

  • James_1P
    James_1P

    Hi jamiekp

    No immediate update yet, we are still looking in to the root cause

This discussion has been closed.