Stuck on authorize sync state

profff · April 22, 2021, 2:40pm

hello god of linux !
I have created a script that is started only once at first boot that basicaly makes all step for pre authorizing ( key / pem / preauthorize request ) all at first device boot . avoiding me to create a dedicated image for each device
device mender client is disable at first startup
that was working well but I dont understand since 2 days first request to get JWT is geting rejected ( not second one) and once preauthorization is done I’m starting and enabling mender client but it get stuck on autorize [sync] state
next reboot it starts ok
here’s the journal of mender-client.service at first boot :

-- Logs begin at Thu 2021-04-22 14:00:51 BST, end at Thu 2021-04-22 15:12:51 BST. --
Apr 22 15:12:13 DVMissionComp-dev systemd[1]: Started Mender OTA update service.
Apr 22 15:12:14 DVMissionComp-dev mender[952]: time="2021-04-22T15:12:14+01:00" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Apr 22 15:12:14 DVMissionComp-dev mender[952]: time="2021-04-22T15:12:14+01:00" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
Apr 22 15:12:15 DVMissionComp-dev mender[952]: time="2021-04-22T15:12:15+01:00" level=info msg="Mender running on partition: /dev/mmcblk0p2"
Apr 22 15:12:15 DVMissionComp-dev mender[952]: time="2021-04-22T15:12:15+01:00" level=info msg="State transition: init [none] -> init [none]"
Apr 22 15:12:15 DVMissionComp-dev mender[952]: time="2021-04-22T15:12:15+01:00" level=info msg="State transition: init [none] -> idle [Idle]"
Apr 22 15:12:15 DVMissionComp-dev mender[952]: time="2021-04-22T15:12:15+01:00" level=info msg="State transition: idle [Idle] -> authorize-wait [Idle]"
Apr 22 15:12:15 DVMissionComp-dev mender[952]: time="2021-04-22T15:12:15+01:00" level=info msg="State transition: authorize-wait [Idle] -> authorize [Sync]"

here’s the service first boot that do the pre authorization request and launch the mender client at the end

[Unit]
Description=preAuthorisationService
After=network.target
Before=rc-local.service
ConditionFileNotEmpty=/data/mender/preauth/preauth

[Service]
ExecStart=/data/mender/preauth/preauth
ExecStartPost=/bin/mv /data/mender/preauth/preauth /data/mender/preauth/preauth.done
Type=oneshot
RemainAfterExit=no

[Install]
WantedBy=multi-user.target

I’m afraid that I’m setting up mender-client service at wrong time but I can’t understand why it was working 3 days ago
but to be sure I tried to start the preauthorization service in the same steps as mender client

Wants=network-online.target
After=systemd-resolved.service network-online.target

buit it looks not getting better

here’s the preauthorisation script I made :

#!/bin/bash

MENDER_SERVER_URI='https://hosted.mender.io'
MENDER_SERVER_USER='*******@******.***:************'
MENDER_PERSISTANT_FOLDER='/data/mender'
MENDER_PREAUTH_FOLDER=$MENDER_PERSISTANT_FOLDER'/preauth'

JWT=''
getJWT(){
    
    for i in {0..10}
    do
	echo "Get JWT attempt "$i
	JWT=$((curl -X POST -u $MENDER_SERVER_USER $MENDER_SERVER_URI/api/management/v1/useradm/auth/login) 2>/dev/null)
	re=''
	if  [ -z "$JWT" ]; then
	    echo "error"
	else
	    echo $JWT
	    break
	fi
	sleep 2
    done
    if [ -z "$JWT" ]; then
	echo "  error can not reach mender server" >&2
        exit 3
    fi
}

isServiceActive(){
	service=$(systemctl status mender-client.service | grep Active | cut -d ' ' -f 5)
	#service=$(systemctl status apt-daily-upgrade.timer | grep Active | cut -d ' ' -f 5)
    	echo 'checking mender service : ['$service']'
	inactive_re="inactive"
	active_re="active"
	if  [ "$service" = "$inactive_re" ]; then
	    echo "  OK"
	else
	    echo "  stop mender services"
	    systemctl stop mender-client.service 
	    systemctl stop mender-grow-data.service
	    systemctl disable mender-client.service 
	    systemctl disable mender-grow-data.service
	    service=$(systemctl status mender-client.service | grep Active | cut -d ' ' -f 5)
	    if [ "$service" = "$active_re" ]; then
		echo "  error stopping services: contact your supoort" $service >&2
		exit 3
	    else
		echo "  OK"

	    fi
	fi
	return 0
}


isDeviceAlreadyAuth(){
	echo 'checking mender autherisations'
	devs=$((curl -H "Authorization: Bearer $JWT" $MENDER_SERVER_URI/api/management/v2/devauth/devices | jq '.') )
	ident=$(($MENDER_PREAUTH_FOLDER/mender-device-identity-json| cut -d '{' -f 2 | cut -d '}' -f 1)2>/dev/null)
	echo "  ident: "$ident
	echo "  dev list: " $devs
	if [[ $devs == *"$ident"* ]]; then
	    echo "  already preauthorised device" >&2
	    exit 1
	fi
	echo '  OK'
	return 0
	
}

isKeyFilesExists(){
	keys=$MENDER_PREAUTH_FOLDER'/keys-client-generated'
	echo 'checking key files : '$keys
	if [ -d $keys ]; then
	    echo '  keys file exist'
	    echo '  delete '
	    rm -rf $keys
	    if [ -f $keys ]; then
		echo "  error deleting keys: contact your support" >&2
		exit 2
	    fi
	fi
	
	echo '  OK'
	return 0
}

createKeys(){
    echo 'creating keys files'
    cd $MENDER_PREAUTH_FOLDER
    $MENDER_PREAUTH_FOLDER/keygen-client >/dev/null 2>&1
    echo '  OK'
}

isPemFileExists(){
	pem=$MENDER_PERSISTANT_FOLDER'/mender-agent.pem'
	echo 'checking pem file : '$pem
	if [ -f $pem ]; then
	    echo '  pem file exist'
	    echo '  delete pem file'
	    rm -f $pem
	    if [ -f $pem ]; then
		echo "  error deleting pem: contact your support" >&2
		exit 2
	    fi
	fi
	echo '  OK'
	return 0
}

createPem(){
    echo 'creating pem file'
    key=$MENDER_PREAUTH_FOLDER'/keys-client-generated/private.key'
    pem=$MENDER_PERSISTANT_FOLDER'/mender-agent.pem'
    cat $key > $pem
    echo '  OK'
}

preAuthDevice(){
    echo "pre-authorising device"
    DEVICE_IDENTITY_JSON_OBJECT_STRING=$(($MENDER_PREAUTH_FOLDER/mender-device-identity-json) 2>/dev/null)
    DEVICE_PUBLIC_KEY="$(cat $MENDER_PREAUTH_FOLDER/keys-client-generated/public.key | awk 1 ORS='\\n')"
    
    res=$((curl -H "Authorization: Bearer $JWT" -H "Content-Type: application/json" -X POST -d "{ \"identity_data\" : $DEVICE_IDENTITY_JSON_OBJECT_STRING, \"pubkey\" : \"$DEVICE_PUBLIC_KEY\" }" $MENDER_SERVER_URI/api/management/v2/devauth/devices) 2>/dev/null)
    echo "server ans :"$res

    if [ -z "$res" ]; then
	echo "  OK"
    else
	echo 'error : contact your support'
	exit 4 
    fi
    return 0
}

startClientService(){
    echo "enable mender client"
    systemctl start mender-client.service 
    systemctl enable mender-client.service 
    echo '  OK'
}

schred(){
    rm -rf $MENDER_PREAUTH_FOLDER
}

getJWT

isServiceActive
isDeviceAlreadyAuth
isKeyFilesExists
isPemFileExists

createKeys
createPem

preAuthDevice
sleep 3
startClientService

# schred()

thank’s for any idea

drewmoseley · April 22, 2021, 5:09pm

Is it possible that your device is already provisioned within Mender? It may be in the reject tab.

Drew

profff · April 23, 2021, 6:58am

nop it’s just un pre-authorised and when I reboot the state machine’s working correctly
journal a 2nd boot

Apr 22 17:57:09 DVMissionComp-dev systemd[1]: Started Mender OTA update service.
Apr 22 17:57:15 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:15+01:00" level=info msg="Loaded configuration file: /var/lib/mender/mender.conf"
Apr 22 17:57:15 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:15+01:00" level=info msg="Loaded configuration file: /etc/mender/mender.conf"
Apr 22 17:57:15 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:15+01:00" level=info msg="Mender running on partition: /dev/mmcblk0p2"
Apr 22 17:57:15 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:15+01:00" level=info msg="State transition: init [none] -> init [none]"
Apr 22 17:57:15 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:15+01:00" level=info msg="State transition: init [none] -> idle [Idle]"
Apr 22 17:57:15 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:15+01:00" level=info msg="State transition: idle [Idle] -> authorize-wait [Idle]"
Apr 22 17:57:15 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:15+01:00" level=info msg="State transition: authorize-wait [Idle] -> authorize [Sync]"
Apr 22 17:57:16 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:16+01:00" level=info msg="successfully received new authorization data"
Apr 22 17:57:16 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:16+01:00" level=info msg="Server authorization successful"
Apr 22 17:57:16 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:16+01:00" level=info msg="State transition: authorize [Sync] -> check-wait [Idle]"
Apr 22 17:57:16 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:16+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Apr 22 17:57:17 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:17+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Apr 22 17:57:17 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:17+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Apr 22 17:57:17 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:17+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Apr 22 17:57:21 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:21+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Apr 22 17:57:21 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:21+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Apr 22 17:57:22 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:22+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Apr 22 17:57:22 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:22+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Apr 22 17:57:26 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:26+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Apr 22 17:57:26 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:26+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Apr 22 17:57:27 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:27+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Apr 22 17:57:27 DVMissionComp-dev mender[549]: time="2021-04-22T17:57:27+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Apr 23 07:56:14 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:14+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Apr 23 07:56:14 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:14+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Apr 23 07:56:15 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:15+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Apr 23 07:56:15 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:15+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Apr 23 07:56:19 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:19+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Apr 23 07:56:19 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:19+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Apr 23 07:56:20 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:20+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Apr 23 07:56:20 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:20+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Apr 23 07:56:24 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:24+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Apr 23 07:56:24 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:24+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Apr 23 07:56:25 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:25+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Apr 23 07:56:25 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:25+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Apr 23 07:56:29 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:29+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Apr 23 07:56:29 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:29+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Apr 23 07:56:30 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:30+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Apr 23 07:56:30 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:30+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Apr 23 07:56:34 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:34+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"
Apr 23 07:56:34 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:34+01:00" level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]"
Apr 23 07:56:35 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:35+01:00" level=info msg="State transition: check-wait [Idle] -> update-check [Sync]"
Apr 23 07:56:35 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:35+01:00" level=info msg="State transition: update-check [Sync] -> check-wait [Idle]"
Apr 23 07:56:39 DVMissionComp-dev mender[549]: time="2021-04-23T07:56:39+01:00" level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]"

profff · April 23, 2021, 9:32am

after few more test it looks caused by a QMI LTE connection service I’ve added (even if eth0 interface is still connected) may be there is some conflicts in route or in netmanager
here’s the shell script that start QMI config and the service description file that launch it if some of you see what can cause this conflict

[Unit]
Description=qmi network startup 
After=network.target
ConditionFileNotEmpty=/usr/share/qmi/qmi-config
ConditionFileNotEmpty=/usr/share/qmi/module-type
ConditionFileNotEmpty=/usr/share/qmi/startup.sh
WorkingDirectory=/usr/share/qmi/


[Service]
ExecStart=/usr/share/qmi/startup.sh
Type=oneshot
RemainAfterExit=no

[Install]
WantedBy=multi-user.target

  #!/bin/bash
echo "--- QMI LTE startup script ---"

QMI_DIR='/usr/share/qmi'

source $QMI_DIR/module-type
source $QMI_DIR/qmi-config

echo "lte module type : \t $LTE_MODULE"
echo "lte APN : \t $LTE_APN"
echo "lte USER: \t $LTE_USER"
echo "lte PASS: \t $LTE_PASSWD"

echo "configuring module with $QMI_DIR/init-$LTE_MODULE.txt"
minicom -D /dev/ttyUSB2 -b 115200 -S $QMI_DIR/init-$LTE_MODULE.txt

onlinemode=$(sudo qmicli -d /dev/cdc-wdm0 --dms-get-operating-mode |  grep Mode | cut -d ':' -f 2)
expectedonlinestatus="'online'"
echo "mode=$onlinemode"
if ! [[ $onlinemode =~ $expectedonlinestatus ]]; then
	echo "setup online mode" >&2
	res=$(sudo qmicli -d /dev/cdc-wdm0 --dms-set-operating-mode='online')
	onlinemode=$(sudo qmicli -d /dev/cdc-wdm0 --dms-get-operating-mode |  grep Mode | cut -d ':')
	if ! [[ $onlinemode =~ $expectedonlinestatus ]]; then
		echo "error setting up online mode"
		exit 1
	fi
fi
res=$(sudo ip link set wwan0 down)
res=$(echo 'Y' | sudo tee /sys/class/net/wwan0/qmi/raw_ip)
res=$(sudo ip link set wwan0 up)
protocol=$(sudo qmicli -d /dev/cdc-wdm0 --wda-get-data-format | grep "Link layer protocol" | cut -d ':' -f 2)
protocolexpectedmode="'raw-ip'"
echo "protocol=$protocol"
if ! [[ $protocol =~ $protocolexpectedmode ]]; then
	echo "error setting up protocol mode"
        exit 1
fi
res=$(sudo qmicli -p -d /dev/cdc-wdm0 --device-open-net='net-raw-ip|net-no-qos-header' --wds-start-network="apn='$LTE_APN',username='$LTE_USER',password='$LTE_PASSWD',ip-type=4" --client-no-release-cid)
ip=$(sudo udhcpc -q -f -i wwan0 2>&1| grep "lease of" | cut -d ' ' -f 4)
echo "LTE IP= $ip"

thank’s for any idea

Topic		Replies	Views
Mender preauthrization with custom Buildroot image General Discussions buildroot , preauthorization	2	259	March 22, 2023
Migrating a device from one Mender server to another General Discussions yocto , nxp	4	2047	April 2, 2019
Authorization failed General Discussions	1	460	June 25, 2020
Trouble with device authentication/decommission via web UI General Discussions	2	310	June 17, 2022
Device not visible in "Pending" General Discussions	5	1333	January 15, 2020

Stuck on authorize sync state

Related Topics