Fix state query startup delay for ClearBlade (#722)

Author: grafnu

bin/reset_config

@@ -36,11 +36,25 @@ echo Setting config timestamp ${now_date}
 jq < ${src_config} .timestamp=\"${now_date}\" |\
     jq .system.testing.sequence_name=\"${config_file%.json}\" > ${dst_config}
 
+if [[ -n $project_id ]]; then
+    quoted_id=\"${project_id##*/}\"
+else
+    quoted_id=null
+fi
+
+if [[ $project_id =~ ^// ]]; then
+    sans_project=${project_id%/*}
+    iot_provider=\"${sans_project#//}\"
+else
+    iot_provider=null
+fi
+
 echo Resetting device ${device_id} config...
 echo Writing config to $REFLECTOR_CONFIG
 cat <<EOF > $REFLECTOR_CONFIG
 {
-  "project_id": "$project_id",
+  "iot_provider": $iot_provider,
+  "project_id": $quoted_id,
   "site_model": "$site_dir",
   "device_id": "$device_id",
   "registry_suffix": $registry_suffix

tests/traces/simple/devices/AHU-22/003_event_system.json

@@ -2,7 +2,7 @@
   "logentries" : [ {
     "message" : "2022-07-19T05:04:39Z sent message #70",
     "category" : "device.log_message",
-    "timestamp" : "2022-07-19T05:04:39Z",
+    "timestamp" : "2022-07-19T05:04:32Z",
     "level" : 200
   } ],
   "timestamp" : "2022-07-19T05:04:39Z",

tests/traces/simple/devices/AHU-22/004_event_pointset.json

@@ -10,6 +10,6 @@
       "present_value" : 21
     }
   },
-  "timestamp" : "2022-07-19T05:04:39Z",
+  "timestamp" : "2022-07-19T05:04:49Z",
   "version" : "1.3.14"
-}
+}

…igurations/UdmiServicePod_configured.xml …igurations/UdmiServicePod_ClearBlade.xmludmis/.idea/runConfigurations/UdmiServicePod_configured.xml renamed to udmis/.idea/runConfigurations/UdmiServicePod_ClearBlade.xml udmis/.idea/runConfigurations/UdmiServicePod_configured.xml renamed to udmis/.idea/runConfigurations/UdmiServicePod_ClearBlade.xml

@@ -0,0 +1,23 @@
+#!/bin/bash -e
+
+ROOT=$(dirname $0)/..
+cd $ROOT
+mkdir -p out
+cd out
+
+podprefix=udmis-pods-
+
+pods=$(kubectl get pods | fgrep $podprefix | awk '{print $1}')
+echo Getting logs for pods $pods
+
+rm -f ${podprefix}*.log
+
+for pod in $pods; do
+  kubectl logs $pod > $pod.log &
+done
+
+wait
+
+cat ${podprefix}*.log | fgrep "Z " | sort -k 1 > pods.log
+
+echo Combined logs available in $(realpath pods.log)

udmis/bin/pod_logs

@@ -183,10 +183,11 @@ protected String updateConfig(String registryId, String deviceId, String config,
               .setName(DeviceName.of(projectId, location, registryId, deviceId).toString())
               .setBinaryData(binaryData).setVersionToUpdate(updateVersion).build();
       DeviceConfig response = deviceManagerClient.modifyCloudToDeviceConfig(request);
-      System.err.println("Config modified version " + response.getVersion());
+      debug("Modified %s/%s config version %s", registryId, deviceId, response.getVersion());
       return config;
     } catch (Exception e) {
-      throw new RuntimeException("While modifying device config", e);
+      throw new RuntimeException(
+          format("While modifying device config %s/%s", registryId, deviceId), e);
     }
   }
 

udmis/src/main/java/com/google/bos/udmi/service/access/ClearBladeIotAccessProvider.java

@@ -280,8 +280,7 @@ public final void sendCommand(String registryId, String deviceId, SubFolder fold
                 backoffKey, getTimestamp(until)));
       }
     } else {
-      debug("Dropping message because registry backoff for %s",
-          backoffKey);
+      debug("Dropping message because registry backoff for %s", backoffKey);
     }
   }
 

udmis/src/main/java/com/google/bos/udmi/service/access/IotAccessBase.java

@@ -14,6 +14,7 @@
 import static com.google.udmi.util.JsonUtil.convertTo;
 import static com.google.udmi.util.JsonUtil.convertToStrict;
 import static com.google.udmi.util.JsonUtil.fromStringStrict;
+import static com.google.udmi.util.JsonUtil.getTimestamp;
 import static com.google.udmi.util.JsonUtil.loadFileStrictRequired;
 import static com.google.udmi.util.JsonUtil.stringify;
 import static com.google.udmi.util.JsonUtil.stringifyTerse;
@@ -138,8 +139,8 @@ private void processException(Envelope reflection, Exception e) {
 
   private void processReflection(Envelope reflection, Envelope envelope,
       Map<String, Object> payload) {
-    debug("Processing reflection %s/%s %s", envelope.subType, envelope.subFolder,
-        envelope.transactionId);
+    debug("Processing reflection %s/%s %s %s", envelope.subType, envelope.subFolder,
+        getTimestamp(envelope.publishTime), envelope.transactionId);
     updateProviderAffinity(envelope, reflection.source);
     CloudModel result = getReflectionResult(envelope, payload);
     ifNotNullThen(result,
@@ -231,7 +232,7 @@ private void reflectStateHandler(Envelope envelope, UdmiState toolState) {
 
     Map<String, Object> configMap = new HashMap<>();
     configMap.put(SubFolder.UDMI.value(), udmiConfig);
-    String contents = stringify(configMap);
+    String contents = stringifyTerse(configMap);
     debug("Setting reflector config %s %s: %s", registryId, deviceId, contents);
     iotAccess.modifyConfig(registryId, deviceId, previous -> contents);
   }
@@ -264,7 +265,7 @@ private void updateRegistryRegions(Map<String, String> regions) {
 
   @Override
   public void activate() {
-    debug("Deployment configuration: " + stringify(DEPLOYED_CONFIG));
+    debug("Deployment configuration: " + stringifyTerse(DEPLOYED_CONFIG));
     super.activate();
   }
 

udmis/src/main/java/com/google/bos/udmi/service/core/ReflectProcessor.java

@@ -138,7 +138,9 @@ public void receiveMessage(PubsubMessage message, AckReplyConsumer reply) {
     receiveMessage(attributesMap, messageString);
     Instant end = Instant.now();
     long seconds = Duration.between(start, end).getSeconds();
-    debug("Receive message took %ss", seconds);
+    if (seconds > 1) {
+      warn("Receive message took %ss", seconds);
+    }
   }
 
   Publisher getPublisher(String topicName) {

udmis/src/main/java/com/google/bos/udmi/service/messaging/impl/PubSubPipe.java

@@ -80,7 +80,7 @@ private String getSimpleName() {
 
   private void output(Level level, String message) {
     PrintStream printStream = level.value() >= Level.WARNING.value() ? System.err : System.out;
-    printStream.printf("%s %s %s: %s %s%n", getExecutionContext(), JsonUtil.getTimestamp(),
+    printStream.printf("%s %s %s: %s %s%n", JsonUtil.getTimestamp(), getExecutionContext(),
         level.name().charAt(0), getSimpleName(), message);
     printStream.flush();
   }