Copyright © https://mongoose-os.com

Mongoose OS Forum

frame

AWS Shadow Callback not being invoked?

pherrispherris United States

I'm attempting to get the basic shadow example working using the JS API and am not seeing the setStateHandler callback function being invoked at all. Thoughts on what I am doing wrong?

load('api_gpio.js');
load('api_aws.js');
load("api_timer.js");

let state = { on: false, counter: 0 };  // device state: shadow metadata

// Upon startup, report current actual state, "reported"
// When cloud sends us a command to update state ("desired"), do it
AWS.Shadow.setStateHandler(function(data, event, reported, desired) {
  print('a');
  //print(event, JSON.stringify(data));
  if (event === AWS.Shadow.CONNECTED) {
    AWS.Shadow.update(0, {reported: state});  // Report device state
  } else if (event === AWS.Shadow.UPDATE_DELTA) {
    for (let key in state) {
      if (desired[key] !== undefined) state[key] = desired[key];
    }
    AWS.Shadow.update(0, {reported: state});  // Report device state
  }
  print(JSON.stringify(reported), JSON.stringify(desired));
}, state);

Timer.set(10000, true, function() {
  print('1');
  AWS.Shadow.get();
  print('2');
  AWS.Shadow.update(0, state);
  print('3');
}, null);

let pin = 0;   // GPIO 0 is typically a 'Flash' button
GPIO.set_button_handler(pin, GPIO.PULL_UP, GPIO.INT_EDGE_NEG, 50, function(x) {
  AWS.Shadow.update(0, {desired: {on: state.on, counter: state.counter + 1}});
}, true);

In CloudWatch I do see logs like this for the device:

2017-08-06 04:16:04.075 TRACEID:d14e1889-c7d2-cc22-a4ca-941c6ee6cd11 PRINCIPALID:**** [INFO] EVENT:PublishOut TOPICNAME:$aws/things/DEVICEID/shadow/update/accepted MESSAGE:PublishOut Status: SUCCESS

I suppose this means that an update was made to the shadow (the logs are a bit obtuse) but when I look at the shadow in the "Thing Registry" I don't see any update. Also, the log from the device doesn't show the print('a') which I think I should be invoked after the AWS.Shadow.get() method is invoked, regardless of whether I managed to update the shadow in some meaningful way. Here is the console log from the device:

[Aug  5 23:24:12.406] mqtt_global_connect  MQTT connecting to XXXXXXX.iot.us-east-1.amazonaws.com:8883
[Aug  5 23:24:12.422] mqtt_global_reconnec MQTT connecting after 58070 ms
[Aug  5 23:24:19.024] 1 
[Aug  5 23:24:19.024] 2 
[Aug  5 23:24:19.024] 3 
[Aug  5 23:24:29.019] 1 
[Aug  5 23:24:29.019] 2 
[Aug  5 23:24:29.035] 3 
[Aug  5 23:24:39.012] 1 
[Aug  5 23:24:39.028] 2 
[Aug  5 23:24:39.028] 3 
[Aug  5 23:24:49.023] 1 
[Aug  5 23:24:49.023] 2 
[Aug  5 23:24:49.023] 3 
[Aug  5 23:24:59.016] 1 
[Aug  5 23:24:59.016] 2 
[Aug  5 23:24:59.033] 3 
[Aug  5 23:25:09.010] 1 
[Aug  5 23:25:09.026] 2 
[Aug  5 23:25:09.026] 3 
[Aug  5 23:25:10.497] mqtt_global_connect  MQTT connecting to XXXXXXX.iot.us-east-1.amazonaws.com:8883
[Aug  5 23:25:10.518] mqtt_global_reconnec MQTT connecting after 60654 ms
[Aug  5 23:25:19.024] 1 
[Aug  5 23:25:19.024] 2 
[Aug  5 23:25:19.024] 3 
[Aug  5 23:25:29.017] 1 
[Aug  5 23:25:29.017] 2 
[Aug  5 23:25:29.033] 3 

Comments

  • rojerrojer Dublin, Ireland

    mqtt connection does not succeed, mOS keeps retrying. it fails very quickly, so something is wrong. can you post full log of the boot?

  • pherrispherris United States

    I modified the code a bit as I've been troubleshooting so I don't have the timer or calls to AWS.Shadow.get or AWS.Shadow.update in the code that triggered this output:

    [Aug  6 12:40:14.265] rBoot v1.2.1 - richardaburton@gmail.com
    [Aug  6 12:40:14.271] Flash Size:   32 Mbit
    [Aug  6 12:40:14.271] Flas[Aug  6 12:40:14.276] h Mode:   DIO
    [Aug  6 12:40:14.276] Flash Speed:  40 MHz
    [Aug  6 12:40:14.276] rBoot Option: Big flash
    [Aug  6 12:40:14.292] 
    [Aug  6 12:40:14.420] Booting rom 0 (0x100000).
         8  n  > r   n b      l r   b             l <    n    l` > r 8  l  mode : softAP(5e:cf:7f:19:93:09)
    [Aug  6 12:40:14.469] add if1
    [Aug  6 12:40:14.469] esp_mgos_init2       ******* 1.0 (20170806-133941/???)
    [Aug  6 12:40:14.474] esp_mgos_init2       Mongoose OS 2017080613 (20170806-133941/???)
    [Aug  6 12:40:14.480] esp_mgos_init2       SDK 2.1.0(ce90efd); flash: 4M; RAM: 52328 total, 49276 free
    [Aug  6 12:40:14.492] esp_print_reset_info Reset cause: 6 (sys reset)
    [Aug  6 12:40:14.492] mgos_vfs_dev_open    sysflash () -> 0x3ffeffac
    [Aug  6 12:40:14.498] mgos_vfs_mount       Mount SPIFFS @ / (dev 0x3ffeffac, opts {"addr": 32768, "size": 262[Aug  6 12:40:14.518] 144}) -> 0x3ffeffbc
    [Aug  6 12:40:14.566] mgos_vfs_mount       /: size 233681, used: 100400, free: 133281
    [Aug  6 12:40:14.656] mgos_sys_config_init MAC: 5ECF7F199309
    [Aug  6 12:40:14.656] mgos_sys_config_init WDT: 30 seconds
    [Aug  6 12:40:14.663] mgos_aws_init        AWS Greengrass enable (0)
    [Aug  6 12:40:14.663] bcn 0
    [Aug  6 12:40:14.668] del if1
    [Aug  6 12:40:14.668] usl
    [Aug  6 12:40:14.668] mode : null
    [Aug  6 12:40:14.668] mgos_wifi_set_config WiFi mode: AP+STA
    [Aug  6 12:40:14.675] mgos_wifi_set_mode   WiFi mode: AP
    [Aug  6 12:40:14.675] mode : softAP(5e:cf:7f:19:93:09)
    [Aug  6 12:40:14.680] add if1
    [Aug  6 12:40:14.680] dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
    [Aug  6 12:40:14.686] bcn 100
    [Aug  6 12:40:14.686] mgos_wifi_dev_ap_set WiFi AP: SSID CUSTOMNAME_199309, channel 6
    [Aug  6 12:40:15.577] bcn 0
    [Aug  6 12:40:15.577] del if1
    [Aug  6 12:40:15.577] usl
    [Aug  6 12:40:15.577] add if1
    [Aug  6 12:40:15.577] dhcp server start:(ip:192.168.4.1,mask:255.255.255.0,gw:192.168.4.1)
    [Aug  6 12:40:15.582] bcn 100
    [Aug  6 12:40:15.582] mgos_wifi_dev_ap_set WiFi AP IP: 192.168.4.1/255.255.255.0 gw 192.168.4.1, DHCP range 192.168.4.2 - 192.168.4.100
    [Aug  6 12:40:15.594] mgos_wifi_set_mode   WiFi mode: AP+STA
    [Aug  6 12:40:15.600] mode : sta(5c:cf:7f:19:93:09) + softAP(5e:cf:7f:19:93:09)
    [Aug  6 12:40:15.605] add if0
    [Aug  6 12:40:15.605] WPA2 ENTERPRISE VERSION: [v2.0] disable
    [Aug  6 12:40:15.605] mgos_wifi_setup_sta  WiFi STA: Connecting to WIFISSID
    [Aug  6 12:40:15.615] mgos_http_server_ini HTTP server started on [80]
    [Aug  6 12:40:15.625] mg_rpc_channel_uart  0x3fff1b4c UART0
    [Aug  6 12:40:15.632] mgos_init            Init done, RAM: 52328 total, 42064 free, 42080 min free
    mgos_aws_shadow_init Device shadow name: esp8266_199309 (token 8750d77b)
    [Aug  6 12:40:16.061] Flash button is configured on GPIO pin  0 
    [Aug  6 12:40:16.077] Press the flash button now! 
    [Aug  6 12:40:16.077] mongoose_poll        New heap free LWM: 33272
    [Aug  6 12:40:16.084] mgos_net_on_change_c WiF[Aug  6 12:40:16.100] i STA: connecting
    [Aug  6 12:40:18.099] scandone
    [Aug  6 12:40:18.979] state: 0 -> 2 (b0)
    [Aug  6 12:40:18.995] state: 2 -> 3 (0)
    [Aug  6 12:40:19.010] state: 3 -> 5 (10)
    [Aug  6 12:40:19.010] add 0
    [Aug  6 12:40:19.010] aid 4
    [Aug  6 12:40:19.010] cnt 
    
    [Aug  6 12:40:19.019] connected with WIFISSID, channel 1
    [Aug  6 12:40:19.019] dhcp client start...
    [Aug  6 12:40:19.019] mgos_net_on_change_c WiFi STA: connected
    [Aug  6 12:40:20.075] ip:10.0.0.19,mask:255.255.255.0,gw:10.0.0.1
    [Aug  6 12:40:20.080] mgos_net_on_change_c WiFi STA: ready, IP 10.0.0.19, GW 10.0.0.1, DNS 75.75.76.76
    [Aug  6 12:40:20.087] mqtt_global_reconnec MQTT connecting after 2199 ms
    [Aug  6 12:40:21.110] mgos_sntp_query      SNTP query to pool.ntp.org
    [Aug  6 12:40:21.205] mgos_sntp_ev         SNTP reply from 198.206.133.14: time 1502041[Aug  6 12:40:21.226] 221.312307, local 6.902503, delta 1502041214.409804
    [Aug  6 12:40:22.310] mqtt_global_connect  MQTT connecting to a1uwnovmzg4d2j.iot.us-[Aug  6 12:40:22.325] east-1.amazonaws.com:8883
    [Aug  6 12:40:22.341] mongoose_poll        New heap free LWM: 31584
    [Aug  6 12:40:22.357] mongoose_poll        New heap free LWM: 29472
    [Aug  6 12:40:22.405] mongoose_poll        New heap free LWM: 28832
    [Aug  6 12:40:22.581] SW ECDSA verify curve 3 hash_len 32 sig_len 70
    [Aug  6 12:40:27.362] SW ECDSA verify curve 3 hash_len 64 sig_len 70
    
  • pherrispherris United States
    edited August 6

    My goal is to have a very restrictive AWS policy that allows only interaction with the shadow of this one device and a subscription to a RPC topic (potentially with publishing permissions on another topic). But, I haven't locked it down yet and am using the permissive mos-default policy in the examples:

    {
      "Statement": [
        {
          "Effect": "Allow",
          "Action": "iot:*",
          "Resource": "*"
        }
      ],
      "Version": "2012-10-17"
    }
    

    config0.json

    {
      "sntp": {
        "enable": true, 
        "server": "pool.ntp.org", 
        "retry_min": 1, 
        "retry_max": 30, 
        "update_interval": 7200
      }, 
      "device": {
        "id": "esp8266_??????", 
        "password": ""
      }, 
      "debug": {
        "udp_log_addr": "", 
        "mbedtls_level": 0, 
        "level": 2, 
        "filter": "", 
        "stdout_uart": 0, 
        "stderr_uart": 0, 
        "factory_reset_gpio": -1, 
        "mg_mgr_hexdump_file": "", 
        "stdout_topic": "", 
        "stderr_topic": ""
      }, 
      "sys": {
        "mount": {
          "path": "", 
          "dev_type": "", 
          "dev_opts": "", 
          "fs_type": "", 
          "fs_opts": ""
        }, 
        "wdt_timeout": 30
      }, 
      "conf_acl": "*", 
      "mqtt": {
        "enable": true, 
        "server": "XXX.iot.us-east-1.amazonaws.com:8883", 
        "client_id": "", 
        "user": "", 
        "pass": "", 
        "reconnect_timeout_min": 2.0, 
        "reconnect_timeout_max": 60.0, 
        "ssl_cert": "", 
        "ssl_key": "", 
        "ssl_ca_cert": "ca.pem", 
        "ssl_cipher_suites": "", 
        "ssl_psk_identity": "", 
        "ssl_psk_key": "", 
        "clean_session": false, 
        "keep_alive": 60, 
        "will_topic": "", 
        "will_message": ""
      }, 
      "aws": {
        "thing_name": "", 
        "greengrass": {
          "enable": false, 
          "reconnect_timeout_min": 2, 
          "reconnect_timeout_max": 60
        }
      }, 
      "wifi": {
        "sta": {
          "enable": false, 
          "ssid": "", 
          "pass": "", 
          "user": "", 
          "anon_identity": "", 
          "cert": "", 
          "key": "", 
          "ca_cert": "", 
          "ip": "", 
          "netmask": "", 
          "gw": "", 
          "nameserver": "", 
          "dhcp_hostname": ""
        }, 
        "ap": {
          "enable": true, 
          "ssid": "xxx_??????", 
          "pass": "xxx", 
          "hidden": false, 
          "channel": 6, 
          "max_connections": 10, 
          "ip": "192.168.4.1", 
          "netmask": "255.255.255.0", 
          "gw": "192.168.4.1", 
          "dhcp_start": "192.168.4.2", 
          "dhcp_end": "192.168.4.100", 
          "trigger_on_gpio": -1, 
          "keep_enabled": true
        }
      }, 
      "http": {
        "enable": true, 
        "listen_addr": "80", 
        "document_root": "/", 
        "ssl_cert": "", 
        "ssl_key": "", 
        "ssl_ca_cert": "", 
        "upload_acl": "*", 
        "hidden_files": "", 
        "auth_domain": "", 
        "auth_file": ""
      }, 
      "i2c": {
        "enable": false, 
        "freq": 100000, 
        "debug": false, 
        "sda_gpio": 12, 
        "scl_gpio": 14
      }, 
      "mjs": {
        "generate_jsc": true
      }, 
      "rpc": {
        "enable": true, 
        "max_frame_size": 4096, 
        "max_queue_length": 25, 
        "default_out_channel_idle_close_timeout": 10, 
        "ws": {
          "enable": true, 
          "server_address": "", 
          "reconnect_interval_min": 1, 
          "reconnect_interval_max": 60, 
          "ssl_server_name": "", 
          "ssl_ca_file": "", 
          "ssl_client_cert_file": ""
        }, 
        "uart": {
          "uart_no": 0, 
          "baud_rate": 115200, 
          "fc_type": 2, 
          "wait_for_start_frame": true
        }
      }, 
      "spi": {
        "enable": false, 
        "debug": false, 
        "miso_gpio": 12, 
        "mosi_gpio": 13, 
        "sclk_gpio": 14, 
        "cs0_gpio": 5, 
        "cs1_gpio": -1, 
        "cs2_gpio": -1
      }
    }
    

    config9.json

    {
      "device": {
        "id": "esp8266_199309"
      },
      "mqtt": {
        "ssl_cert": "aws-iot-f64f555659.crt.pem",
        "ssl_key": "aws-iot-f64f555659.key.pem"
      },
      "wifi": {
        "sta": {
          "enable": true,
          "ssid": "WIFISSID",
          "pass": "XXXXXX"
        }
      }
    }
    
  • pherrispherris United States

    CloudWatch is showing an error now (had to narrow it down by my external IP - but the logging isn't super helpful I'm afraid)

    2017-08-06 17:40:38.770 TRACEID:c5e992c9-cd2a-d9fa-d278-c0439c2c8adc PRINCIPALID:f64f555659501a2b0b7c6d1af276e7ae567a8e876b0a7c934d2faf7e11d7744d [ERROR] EVENT:MQTT Client Connect MESSAGE:Connect Status: CLIENT_ERROR
    17:40:38
    2017-08-06 17:40:38.770 TRACEID:c5e992c9-cd2a-d9fa-d278-c0439c2c8adc PRINCIPALID:f64f555659501a2b0b7c6d1af276e7ae567a8e876b0a7c934d2faf7e11d7744d [INFO] EVENT:MQTT Client Connect MESSAGE: IpAddress: my.ip.address.v4 SourcePort: 40815
    
  • pherrispherris United States

    That CloudWatch error is on the certificate - FYI.

  • pherrispherris United States

    Must have been some problem with my mos.yml - I rebuilt the app from the example: https://github.com/cesanta/mongoose-os/tree/master/fw/examples/c_aws_shadow and was able to get everything working. If someone else runs across this, my guess is a problem with the libs order or completeness in mos.yml.

Sign In or Register to comment.