(FIXED / User Error) Container creation works, but getting "This instance already exists" in LXD debug log

LXD
1

Update:
Issue was due to my own mistake (of course) my code was duplicating the creation request. :man_facepalming:Sorry!

–
I recently recovered from a db corruption issue this morning. The error from that issue was:

Error: Failed to start dqlite server: raft_start(): io: load closed segment 0000000000008786-0000000000008799: entries batch 15 starting at byte 124080: entries count in preamble is zero

I removed 0000000000008786-0000000000008799 and LXD was able to start fine then.

I then noticed this error in the LXD debug log when creating an instance:

DBUG[04-08|19:29:02] Database error: Add instance info to the database: This instance already exists 
DBUG[04-08|19:29:02] Failure for task operation: 4fc45dd6-ba91-41bd-8f23-94ff5a75bfb9: Create instance: Add instance info to the database: This instance already exists

However the instance is created correctly and I’m able to start it just fine.

The instances are created with a random UUID that has not been used before so I don’t believe it’s a naming collision.

Is this due to the database crash or is this a common error that I can safely ignore?

Full debug log for container creation:

DBUG[04-08|19:44:23] Responding to instance create 
DBUG[04-08|19:44:23] New task Operation: 7212e614-30be-4404-9537-c7a2c5b59cc5 
DBUG[04-08|19:44:23] Started task operation: 7212e614-30be-4404-9537-c7a2c5b59cc5 
DBUG[04-08|19:44:23] 
        {
                "type": "async",
                "status": "Operation created",
                "status_code": 100,
                "operation": "/1.0/operations/7212e614-30be-4404-9537-c7a2c5b59cc5",
                "error_code": 0,
                "error": "",
                "metadata": {
                        "id": "7212e614-30be-4404-9537-c7a2c5b59cc5",
                        "class": "task",
                        "description": "Creating container",
                        "created_at": "2020-04-08T19:44:23.87434852Z",
                        "updated_at": "2020-04-08T19:44:23.87434852Z",
                        "status": "Running",
                        "status_code": 103,
                        "resources": {
                                "containers": [
                                        "/1.0/containers/co-591ce20c79d111eab663080027ca2ca5"
                                ],
                                "instances": [
                                        "/1.0/instances/co-591ce20c79d111eab663080027ca2ca5"
                                ]
                        },
                        "metadata": null,
                        "may_cancel": false,
                        "err": "",
                        "location": "none"
                }
        } 
INFO[04-08|19:44:23] Creating container                       project=default name=co-591ce20c79d111eab663080027ca2ca5 ephemeral=false
INFO[04-08|19:44:23] Created container                        name=co-591ce20c79d111eab663080027ca2ca5 ephemeral=false project=default
DBUG[04-08|19:44:23] CreateInstanceFromImage started          driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:23] EnsureImage started                      driver=zfs pool=pool1 fingerprint=5f6884b0ebbbf559d03390354cb262e3908e2af2e27362e9ddb9805925f017d3
DBUG[04-08|19:44:23] EnsureImage finished                     driver=zfs pool=pool1 fingerprint=5f6884b0ebbbf559d03390354cb262e3908e2af2e27362e9ddb9805925f017d3
DBUG[04-08|19:44:24] Mounted ZFS dataset                      driver=zfs pool=pool1 path=/var/snap/lxd/common/lxd/storage-pools/pool1/containers/co-591ce20c79d111eab663080027ca2ca5 dev=pool1/containers/co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] Unmounted ZFS dataset                    driver=zfs pool=pool1 dev=pool1/containers/co-591ce20c79d111eab663080027ca2ca5 path=/var/snap/lxd/common/lxd/storage-pools/pool1/containers/co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] CreateInstanceFromImage finished         driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] SetInstanceQuota started                 pool=pool1 driver=zfs project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] SetInstanceQuota finished                pool=pool1 driver=zfs project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] UpdateInstanceBackupFile started         driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] Mounted ZFS dataset                      driver=zfs pool=pool1 dev=pool1/containers/co-591ce20c79d111eab663080027ca2ca5 path=/var/snap/lxd/common/lxd/storage-pools/pool1/containers/co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] Unmounted ZFS dataset                    driver=zfs pool=pool1 dev=pool1/containers/co-591ce20c79d111eab663080027ca2ca5 path=/var/snap/lxd/common/lxd/storage-pools/pool1/containers/co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] UpdateInstanceBackupFile finished        driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:24] Success for task operation: 7212e614-30be-4404-9537-c7a2c5b59cc5 
DBUG[04-08|19:44:27] Found cert                               name=ebb7d434172d369183460d4d9342114db54b4bbe56535cd9c44e7b4035a68349
DBUG[04-08|19:44:27] Handling                                 url="/1.0/instances/co-591ce20c79d111eab663080027ca2ca5/files?path=/etc/netplan/10-lxc.yaml" ip=127.0.0.1:58064 user=ebb7d434172d369183460d4d9342114db54b4bbe56535cd9c44e7b4035a68349 method=POST
DBUG[04-08|19:44:27] MountInstance started                    driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:27] Mounted ZFS dataset                      driver=zfs pool=pool1 dev=pool1/containers/co-591ce20c79d111eab663080027ca2ca5 path=/var/snap/lxd/common/lxd/storage-pools/pool1/containers/co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:27] MountInstance finished                   driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:27] UnmountInstance started                  driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:28] Unmounted ZFS dataset                    driver=zfs pool=pool1 dev=pool1/containers/co-591ce20c79d111eab663080027ca2ca5 path=/var/snap/lxd/common/lxd/storage-pools/pool1/containers/co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:28] UnmountInstance finished                 driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:28] Found cert                               name=ebb7d434172d369183460d4d9342114db54b4bbe56535cd9c44e7b4035a68349
DBUG[04-08|19:44:28] Handling                                 method=POST url=/1.0/instances ip=127.0.0.1:58064 user=ebb7d434172d369183460d4d9342114db54b4bbe56535cd9c44e7b4035a68349
DBUG[04-08|19:44:28] Responding to instance create 
DBUG[04-08|19:44:28] New task Operation: 52d94fec-c96e-4b8f-b482-f5f824077a97 
DBUG[04-08|19:44:28] Started task operation: 52d94fec-c96e-4b8f-b482-f5f824077a97 
DBUG[04-08|19:44:28] 
        {
                "type": "async",
                "status": "Operation created",
                "status_code": 100,
                "operation": "/1.0/operations/52d94fec-c96e-4b8f-b482-f5f824077a97",
                "error_code": 0,
                "error": "",
                "metadata": {
                        "id": "52d94fec-c96e-4b8f-b482-f5f824077a97",
                        "class": "task",
                        "description": "Creating container",
                        "created_at": "2020-04-08T19:44:28.133850134Z",
                        "updated_at": "2020-04-08T19:44:28.133850134Z",
                        "status": "Running",
                        "status_code": 103,
                        "resources": {
                                "containers": [
                                        "/1.0/containers/co-591ce20c79d111eab663080027ca2ca5"
                                ],
                                "instances": [
                                        "/1.0/instances/co-591ce20c79d111eab663080027ca2ca5"
                                ]
                        },
                        "metadata": null,
                        "may_cancel": false,
                        "err": "",
                        "location": "none"
                }
        } 
DBUG[04-08|19:44:28] Database error: Add instance info to the database: This instance already exists 
DBUG[04-08|19:44:28] Failure for task operation: 52d94fec-c96e-4b8f-b482-f5f824077a97: Create instance: Add instance info to the database: This instance already exists 
DBUG[04-08|19:44:32] Found cert                               name=ebb7d434172d369183460d4d9342114db54b4bbe56535cd9c44e7b4035a68349
DBUG[04-08|19:44:32] Handling                                 user=ebb7d434172d369183460d4d9342114db54b4bbe56535cd9c44e7b4035a68349 method=POST url="/1.0/instances/co-591ce20c79d111eab663080027ca2ca5/files?path=/etc/netplan/10-lxc.yaml" ip=127.0.0.1:58064
DBUG[04-08|19:44:32] MountInstance started                    driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:32] Mounted ZFS dataset                      driver=zfs pool=pool1 path=/var/snap/lxd/common/lxd/storage-pools/pool1/containers/co-591ce20c79d111eab663080027ca2ca5 dev=pool1/containers/co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:32] MountInstance finished                   driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:32] UnmountInstance started                  driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:32] Unmounted ZFS dataset                    driver=zfs pool=pool1 dev=pool1/containers/co-591ce20c79d111eab663080027ca2ca5 path=/var/snap/lxd/common/lxd/storage-pools/pool1/containers/co-591ce20c79d111eab663080027ca2ca5
DBUG[04-08|19:44:32] UnmountInstance finished                 driver=zfs pool=pool1 project=default instance=co-591ce20c79d111eab663080027ca2ca5
2

Digging through the LXD code I think the code below is where that error is propagating from. Somehow func InstanceExists is returning true?

My instances table has 5 entries in it currently:

lxd sql global "select * from instances"
+----+---------+--------------------------------------+--------------+------+-----------+--------------------------------+----------+--------------------------------+-------------+------------+----------------------+
| id | node_id |                 name                 | architecture | type | ephemeral |         creation_date          | stateful |         last_use_date          | description | project_id |     expiry_date      |
+----+---------+--------------------------------------+--------------+------+-----------+--------------------------------+----------+--------------------------------+-------------+------------+----------------------+
| 14 | 1       | c1                                   | 2            | 0    | 0         | 2019-09-30T16:08:14.417822529Z | 0        | 2020-01-25T23:37:26.565025019Z |             | 1          | 0001-01-01T00:00:00Z |
| 15 | 1       | c2                                   | 2            | 0    | 0         | 2019-09-30T16:10:22.167571074Z | 0        | 2020-04-08T19:47:32.979503511Z |             | 1          | 0001-01-01T00:00:00Z |
| 16 | 1       | c3                                   | 2            | 0    | 0         | 2019-09-30T20:45:48.475848573Z | 0        | 2020-04-08T19:47:33.331661933Z |             | 1          | 0001-01-01T00:00:00Z |
| 80 | 1       | co-591ce20c79d111eab663080027ca2ca5  | 2            | 0    | 0         | 2020-04-08T19:44:23.886659933Z | 0        | 1970-01-01T00:00:00Z           |             | 1          | 0001-01-01T00:00:00Z |
| 81 | 1       | co-fff631a079d111ea9a1b080027ca2ca5  | 2            | 0    | 0         | 2020-04-08T19:49:03.886566082Z | 0        | 2020-04-08T19:49:45.676593198Z |             | 1          | 0001-01-01T00:00:00Z |
+----+---------+--------------------------------------+--------------+------+-----------+--------------------------------+----------+--------------------------------+-------------+------------+----------------------+

Code from: https://github.com/lxc/lxd/blob/1a0380d0f1c0f8a22562fc09cd9002f992be74c5/lxd/db/instances.mapper.go#L480

// InstanceExists checks if a instance with the given key exists.
func (c *ClusterTx) InstanceExists(project string, name string) (bool, error) {
	_, err := c.InstanceID(project, name)
	if err != nil {
		if err == ErrNoSuchObject {
			return false, nil
		}
		return false, err
	}

	return true, nil
}

// InstanceCreate adds a new instance to the database.
func (c *ClusterTx) InstanceCreate(object Instance) (int64, error) {
	// Check if a instance with the same key exists.
	exists, err := c.InstanceExists(object.Project, object.Name)
	if err != nil {
		return -1, errors.Wrap(err, "Failed to check for duplicates")
	}
	if exists {
		return -1, fmt.Errorf("This instance already exists")
	}

Just tacking this on in case it helps to debug. Thanks!

3

I’m confused, doesn’t you log specifically show you trying to create the exact same thing twice?

DBUG[04-08|19:44:23] Responding to instance create 
DBUG[04-08|19:44:28] Responding to instance create

Look at the lines after that, both seem to use co-591ce20c79d111eab663080027ca2ca5 as the name.

4

You are right :man_facepalming: my bad, very sorry for the fumble on my end!

Somewhere in my code a duplicate request is being made in succession.

I’ll triple check everything next time before I post!