Chipstack FUOTA Server (V4) hangs on creating transaction

[Pasukaru]

Update TLDR:

It seems that there is an issue with the automigrate.

When I turn that off, everything works. It turn it on again, it stops working and hangs on the first db interaction of the CreateDeployment GRPC call. This is the only config option I changed to verify the behaviour.

Is the automigrate not releasing the connection properly?

---

Hello,

I’m currently in the process of setting up Chirpstack V4 along with the FUOTA server.

The version of the FUOTA server is the current master branch (revision 28a40c2a13af08f47d68964055236264cbc8153e), built with the Dockerfile:

chirpstack/chirpstack-fuota-server/blob/master/Dockerfile

Both applications start fine. The FUOTA server is properly configured and was able to run the migrations in postgres. It’s also logging received uplinks from the application server.

However, when creating a FUOTA deployment via the GRPC call, it hangs on creating the transaction.
I’ve modified the code a little bit to add more logs, and this is what I get:

time="2023-08-31T14:45:23Z" level=info msg="fuota_server: CreateDeployment"
time="2023-08-31T14:45:23Z" level=info msg="fuota_server: Got devices" devices=1
time="2023-08-31T14:45:23Z" level=info msg="fuota_server: creating new deployment"
time="2023-08-31T14:45:23Z" level=info msg="fuota: creating transaction"
time="2023-08-31T14:45:44Z" level=debug msg="[transport]transport: loopyWriter.run returning. connection error: desc = \"transport is closing\""

The logs that I added are for example here in fuota.go:

	log.Info("fuota: creating transaction")
	if err := storage.Transaction(func(tx sqlx.Ext) error {
		st := storage.Deployment{
			ID: d.id,
		}

		log.Info("fuota: creating deployment")
		if err := storage.CreateDeployment(context.Background(), tx, &st); err != nil {
			log.Error(fmt.Errorf("create deployment error: %w", err))
			return fmt.Errorf("create deployment error: %w", err)
		}

The request is as follows:

	var context, _ = context.WithDeadline(context.Background(), time.Now().Add(time.Duration(time.Second)*20))

	resp, err := client.CreateDeployment(context, &fuota.CreateDeploymentRequest{
		Deployment: &fuota.Deployment{
			ApplicationId: "47ee90b7-22cd-414b-a21c-d55c0d4dcd3e",
			Devices: []*fuota.DeploymentDevice{
				{
					DevEui:    "a150cde94c999944",
					McRootKey: mcRootKey.String(),
				},
			},
			MulticastGroupType:                fuota.MulticastGroupType_CLASS_C,
			MulticastDr:                       5,
			MulticastFrequency:                868100000,
			MulticastGroupId:                  0,
			MulticastTimeout:                  6,
			MulticastRegion:                   fuota.Region_EU868,
			UnicastTimeout:                    durationpb.New(60 * time.Second),
			UnicastAttemptCount:               1,
			FragmentationFragmentSize:         50,
			Payload:                           make([]byte, 100),
			FragmentationRedundancy:           1,
			FragmentationSessionIndex:         0,
			FragmentationMatrix:               0,
			FragmentationBlockAckDelay:        1,
			FragmentationDescriptor:           []byte{0, 0, 0, 0},
			RequestFragmentationSessionStatus: fuota.RequestFragmentationSessionStatus_AFTER_SESSION_TIMEOUT,
		},
	})

So as we can see, it tries to create the transaction but hangs doing so.
Since it was able to run the migration, I doubt it’s something with the network in general.
I see a single entry in the migrations table with version 1, dirty=false. I also see that the tables for deployment, deployment_log and deployment_device have been created.

How can I debug this further?
(I’ve never used go before, so I’m not entirely familiar with the syntax or the libraries used)

[Pasukaru]

Couple of additional findings:

The hang happens on any database interaction in the call (as far as I can tell).

WIthout any modifications, it hangs in storage.go on:

tx, err := db.Beginx()

I also tried removing the transaction wrapper, but then it hangs on deployment.go

_, err := db.Exec(`
		insert into deployment (
			id,
			created_at,
			updated_at,
			mc_group_setup_completed_at,
			mc_session_completed_at,
			frag_session_setup_completed_at,
			enqueue_completed_at,
			frag_status_completed_at
		) values ($1, $2, $3, $4, $5, $6, $7, $8)`,
		d.ID,
		d.CreatedAt,
		d.UpdatedAt,
		d.MCGroupSetupCompletedAt,
		d.MCSessionCompletedAt,
		d.FragSessionSetupCompletedAt,
		d.EnqueueCompletedAt,
		d.FragStatusCompletedAt,
	)

The weird thing is that I can see that it has an open connection to the database and postgres is waiting for the client to do something:

select 
pid,usename,datname,"application_name","wait_event_type","wait_event","state",query 
from "pg_stat_activity"
where "usename" = 'RgxsdyMhSoUMgdTO'
and pid <> pg_backend_pid();

3684,RgxsdyMhSoUMgdTO,chirpstack_fuota_v4,Chirpstack-Fuota,Client,ClientRead,idle,"SELECT version, dirty FROM ""schema_migrations"" LIMIT 1"