How do I debug the cause of a 500 Internal Server Error?

[jceddy]

I am testing creation of a license, and am getting 500 Internal Server Error. It's unclear what I need to look at in the logs to debug this...I don't see any errors in the logs around the time I made the requests.

I am POSTing this body to /v1/licenses --

{
  "data": {
    "type": "licenses",
    "attributes": {
      "name": "TEST_JOE_LICENSE"
    },
    "relationships": {
      "policy": {
        "data": {
          "type": "policies",
          "id": "0b95ff5c-af0d-4b35-b877-36d3abb1ae84"
        }
      }
    }
  }
}

Getting back a 500 Internal Server Error with the following body --

{
    "meta": {
        "id": "56c42f7c-529f-4f4a-8663-7e38aa703344"
    },
    "errors": [
        {
            "title": "Internal server error",
            "detail": "Looks like something went wrong! Our engineers have been notified. If you continue to have problems, please contact [email protected]."
        }
    ]
}

I've searched the logs for that meta id, as well, and am not seeing it.

Edit: When I re-tried I got a 400 Bad Request, and saw this in the log, which might give me something to go on:

2024-11-05T11:32:09.898549325-06:00 stdout F E, [2024-11-05T17:32:09.898440 #9] ERROR -- : [a5f68213-0b9d-4124-a6cc-468124e5ca3f] PG::NotNullViolation: ERROR: null value in column "product_id" of relation "licenses" violates not-null constraint

[ezekg]

Assuming this is for CE/EE. The application logs will include a full stack trace for any internal server errors. It seems like somehow the licenses.product_id column is being set to null, but it has a not-null constraint so its being rejected by the database. This value is denormalized from the license's policy, i.e. policies.product_id, so that'd indicate that the policy has a null product_id. I'm not sure how that could happen, though, since policies.product_id also has a not-null constraint. Please share the output of:

Policy.find_by(id: '0b95ff5c-af0d-4b35-b877-36d3abb1ae84').inspect

Sharing your Keygen CE/EE version may also be helpful.

[jceddy]

When I check the policy, I do see a product attached.

I'm not sure where to run "Policy.find_by(id: '0b95ff5c-af0d-4b35-b877-36d3abb1ae84').inspect" to get the output.

I ran this in pgsql:

SELECT row_to_json(policies) FROM policies where id = '0b95ff5c-af0d-4b35-b877-36d3abb1ae84'

and got this output:

{
  "id": "0b95ff5c-af0d-4b35-b877-36d3abb1ae84",
  "name": "Feature Distribution Test Policy",
  "duration": 31556952,
  "strict": false,
  "floating": true,
  "use_pool": false,
  "created_at": "2024-11-04T17:16:34.500384",
  "updated_at": "2024-11-04T17:16:34.500384",
  "lock_version": 0,
  "max_machines": null,
  "encrypted": false,
  "protected": true,
  "metadata": null,
  "product_id": "c2399790-559d-43ba-8fe9-633262136c85",
  "account_id": "bb420bd7-5e98-4147-831e-a41b990eeccd",
  "check_in_interval": null,
  "check_in_interval_count": null,
  "require_check_in": false,
  "require_product_scope": false,
  "require_policy_scope": false,
  "require_machine_scope": false,
  "require_fingerprint_scope": true,
  "concurrent": true,
  "max_uses": null,
  "scheme": null,
  "heartbeat_duration": null,
  "fingerprint_uniqueness_strategy": null,
  "fingerprint_matching_strategy": null,
  "max_cores": null,
  "expiration_strategy": "REVOKE_ACCESS",
  "expiration_basis": "FROM_FIRST_ACTIVATION",
  "authentication_strategy": "MIXED",
  "heartbeat_cull_strategy": "DEACTIVATE_DEAD",
  "heartbeat_resurrection_strategy": "NO_REVIVE",
  "require_heartbeat": false,
  "transfer_strategy": "KEEP_EXPIRY",
  "require_user_scope": false,
  "leasing_strategy": null,
  "max_processes": null,
  "overage_strategy": "NO_OVERAGE",
  "environment_id": null,
  "heartbeat_basis": "FROM_FIRST_PING",
  "require_environment_scope": false,
  "require_checksum_scope": false,
  "require_version_scope": false,
  "require_components_scope": false,
  "machine_uniqueness_strategy": "UNIQUE_PER_LICENSE",
  "machine_matching_strategy": "MATCH_ANY",
  "component_uniqueness_strategy": "UNIQUE_PER_MACHINE",
  "component_matching_strategy": "MATCH_ANY",
  "renewal_basis": "FROM_EXPIRY",
  "max_users": null,
  "machine_leasing_strategy": "PER_LICENSE",
  "process_leasing_strategy": "PER_MACHINE"
}

When I re-tried posting this request, it went through and created a license.

The keygen edition is CE.
Latest version (from like 5 months ago, I think 1.3.0?)

It's a clustered system with four nodes sharing external posgres and redis.
I noticed that I am only seeing error logs on one of the servers, so am trying to figure out whether there is something misconfigured on that server.

[ezekg]

Not a stupid question. Via a console session: https://keygen.sh/docs/self-hosting/#opening-a-console

[jceddy]

Okay, now I see I can get them from response headers...maybe.

When I get a 400 Bad Request response, the headers have:

Keygen-Version: 1.5

No Keygen-Revision.

When I get a 201 Created or a 500 Internal Server Error response, the headers have:

Keygen-Version: 1.5
Keygen-Revision: 055c8729cdcc372500a08db659c045e16c4409fb

Not sure whether that means anything.

[jceddy]

I haven't been able to get the console working.

I don't have /etc/keygen, so including the mapping in the example you linked to doesn't work.

When I just exclude that, I get this output, and then am not able to do anything and need to exit out of the shell:

Running command: bundle exec rails console
I, [2024-11-05T22:08:19.268831 #1]  INFO -- : [RailsAutoscale] Preparing middleware
Loading production environment (Rails 7.0.7.1)
▽

[ezekg]

Your bad server returning 400s is running an outdated instance of Keygen if it doesn't have the Keygen-Revision header.

Fix that first and then we can move onto the 500s if it still happens.

[jceddy]

Okay, I got the console working in a different SSH terminal.

On Node 1 I have:
Keygen.version -> 1.5.0
Keygen.revision -> undefined method 'revision' for Keygen:module

On Node 2 I have:
Keygen.version -> 1.5.0
Keygen.revision -> undefined method 'revision' for Keygen:module

On Node 3 I have:
Keygen.version -> 1.7.0
Keygen.revision -> 055c8729cdcc372500a08db659c045e16c4409fb

On Node 4 I have:
Keygen.version -> 1.7.0
Keygen.revision -> 055c8729cdcc372500a08db659c045e16c4409fb

....I guess that might explain it. XD

[jceddy]

Alright, I think I tracked down the issue, and this actually explains another issue I had earlier.

We are provisioning all of this via Ansible scripts, and the task to pull the keygen docker image using the "latest" tag was not including the "force: true" option. This means that when we added two additional nodes to the cluster, only the new nodes got the new version.

The previous issue was that the database migrations for the new version were not being run when I deployed via Ansible, but ran fine when I used the command line (which I just happened to run on one of the new nodes that had the later version installed...).

Updating my Ansible scripts and re-deploying, fingers crossed.

[ezekg]

Ah gotcha. Let me know if this resolves both the 400s and 500s.

[jceddy]

I also had to add "recreate: true" on the container tasks to re-create the containers using the updated image, but after doing that and re-deploying everything, all nodes are at 1.7.0 rev 055c8729cdcc372500a08db659c045e16c4409fb and I have done a bunch of testing and am not seeing 400 or 500 return statuses anymore.

Thanks for your help!