Invalid format placeholder in emqx_web_hook_actions.erl

[eshxcmhk]

Environment

• OS: Centos 6
• Erlang/OTP: 22
• EMQ: 4.0.5

Description

A description of the issue

2020-04-11 18:07:40.729 [info] <<"3248bf8a-4da4-40c5-b64e-3d6b02e65227">>@182.139.7.42:27200 PUBLISH to /local/middleware/apis/detect/req/BQCZ02_1: <<"{\"msgid\":\"ac92f6ec-374d-4512-8def-3d8ead82d060\",\"msgbody\":\"<selfinspectiondata>\\r\\n<lineid>1</lineid>\\r\\n<deviceid>1</deviceid>\\r\\n<starttime>2019-01-03 07:30:21</starttime>\\r\\n<endtime>2019-01-03 07:30:21</endtime>\\r\\n<dpowermeterls>\\r\\n<t30v100>2020-04-11 12:00:00</t30v100>\\r\\n<t30v90>2020-04-11 12:00:01</t30v90>\\r\\n<t30v80>2020-04-11 12:00:02</t30v80>\\r\\n<t30v70>2020-04-11 12:00:03</t30v70>\\r\\n<t30v60>2020-04-11 12:00:04</t30v60>\\r\\n<t30v50>2020-04-11 12:00:05</t30v50>\\r\\n<t30v40>2020-04-11 12:00:06</t30v40>\\r\\n<t30v30>2020-04-11 12:00:07</t30v30>\\r\\n<t30v20>2020-04-11 12:00:08</t30v20>\\r\\n<t30v10>2020-04-11 12:00:09</t30v10>\\r\\n<t20v100>2020-04-11 12:00:10</t20v100>\\r\\n<t20v90>2020-04-11 12:00:11</t20v90>\\r\\n<t20v80>2020-04-11 12:00:12</t20v80>\\r\\n<t20v70>2020-04-11 12:00:13</t20v70>\\r\\n<t20v60>2020-04-11 12:00:14</t20v60>\\r\\n<t20v50>2020-04-11 12:00:15</t20v50>\\r\\n<t20v40>2020-04-11 12:00:16</t20v40>\\r\\n<t20v30>2020-04-11 12:00:17</t20v30>\\r\\n<t20v20>2020-04-11 12:00:18</t20v20>\\r\\n<t20v10>2020-04-11 12:00:19</t20v10>\\r\\n<t10v100>2020-04-11 12:00:20</t10v100>\\r\\n<t10v90>2020-04-11 12:00:21</t10v90>\\r\\n<t10v80>2020-04-11 12:00:22</t10v80>\\r\\n<t10v70>2020-04-11 12:00:23</t10v70>\\r\\n<t10v60>2020-04-11 12:00:24</t10v60>\\r\\n<t10v50>2020-04-11 12:00:25</t10v50>\\r\\n<t10v40>2020-04-11 12:00:26</t10v40>\\r\\n<t10v30>2020-04-11 12:00:27</t10v30>\\r\\n<t10v20>2020-04-11 12:00:28</t10v20>\\r\\n<t10v10>2020-04-11 12:00:29</t10v10>\\r\\n<nom>31</nom>\\r\\n<pt3010>32</pt3010>\\r\\n<pt309>33</pt309>\\r\\n<pt308>34</pt308>\\r\\n<pt307>35</pt307>\\r\\n<pt306>36</pt306>\\r\\n<pt305>37</pt305>\\r\\n<pt304>38</pt304>\\r\\n<pt303>39</pt303>\\r\\n<st3010>40</st3010>\\r\\n<st309>41</st309>\\r\\n<st308>42</st308>\\r\\n<st307>43</st307>\\r\\n<st306>44</st306>\\r\\n<st305>45</st305>\\r\\n<st304>46</st304>\\r\\n<st303>47</st303>\\r\\n<pt2010>48</pt2010>\\r\\n<pt209>49</pt209>\\r\\n<pt208>50</pt208>\\r\\n<pt207>51</pt207>\\r\\n<pt206>52</pt206>\\r\\n<pt205>53</pt205>\\r\\n<pt204>54</pt204>\\r\\n<pt203>55</pt203>\\r\\n<st2010>56</st2010>\\r\\n<st209>57</st209>\\r\\n<st208>58</st208>\\r\\n<st207>59</st207>\\r\\n<st206>60</st206>\\r\\n<st205>61</st205>\\r\\n<st204>62</st204>\\r\\n<st203>63</st203>\\r\\n<ps1010>64</ps1010>\\r\\n<ps109>65</ps109>\\r\\n<ps108>66</ps108>\\r\\n<ps107>67</ps107>\\r\\n<ps106>68</ps106>\\r\\n<ps105>69</ps105>\\r\\n<ps104>70</ps104>\\r\\n<ps103>71</ps103>\\r\\n<ss1010>72</ss1010>\\r\\n<ss109>73</ss109>\\r\\n<ss108>74</ss108>\\r\\n<ss107>75</ss107>\\r\\n<ss106>76</ss106>\\r\\n<ss105>77</ss105>\\r\\n<ss104>78</ss104>\\r\\n<ss103>79</ss103>\\r\\n<pp90>80</pp90>\\r\\n<pp80>81</pp80>\\r\\n<pp70>82</pp70>\\r\\n<pp60>83</pp60>\\r\\n<pp50>84</pp50>\\r\\n<pp40>85</pp40>\\r\\n<pp30>86</pp30>\\r\\n<pp20>87</pp20>\\r\\n<con10010>88</con10010>\\r\\n<con8010>89</con8010>\\r\\n<con>90</con>\\r\\n</dpowermeterls>\\r\\n</selfinspectiondata>\",\"msgmethod\":\"epd_selfinspection\"}">>
2020-04-11 18:07:40.731 [debug] <<"3248bf8a-4da4-40c5-b64e-3d6b02e65227">>@182.139.7.42:27200 FORMAT ERROR: "[WebHook Action] ~s to ~s, headers: ~s, body: ~p" - [post,"http://apisyb.local.yeild.top:7000/handle",[{"mqtt","detect"}],#{msgbody => <<"<selfinspectiondata>\r\n<lineid>1</lineid>\r\n<deviceid>1</deviceid>\r\n<starttime>2019-01-03 07:30:21</starttime>\r\n<endtime>2019-01-03 07:30:21</endtime>\r\n<dpowermeterls>\r\n<t30v100>2020-04-11 12:00:00</t30v100>\r\n<t30v90>2020-04-11 12:00:01</t30v90>\r\n<t30v80>2020-04-11 12:00:02</t30v80>\r\n<t30v70>2020-04-11 12:00:03</t30v70>\r\n<t30v60>2020-04-11 12:00:04</t30v60>\r\n<t30v50>2020-04-11 12:00:05</t30v50>\r\n<t30v40>2020-04-11 12:00:06</t30v40>\r\n<t30v30>2020-04-11 12:00:07</t30v30>\r\n<t30v20>2020-04-11 12:00:08</t30v20>\r\n<t30v10>2020-04-11 12:00:09</t30v10>\r\n<t20v100>2020-04-11 12:00:10</t20v100>\r\n<t20v90>2020-04-11 12:00:11</t20v90>\r\n<t20v80>2020-04-11 12:00:12</t20v80>\r\n<t20v70>2020-04-11 12:00:13</t20v70>\r\n<t20v60>2020-04-11 12:00:14</t20v60>\r\n<t20v50>2020-04-11 12:00:15</t20v50>\r\n<t20v40>2020-04-11 12:00:16</t20v40>\r\n<t20v30>2020-04-11 12:00:17</t20v30>\r\n<t20v20>2020-04-11 12:00:18</t20v20>\r\n<t20v10>2020-04-11 12:00:19</t20v10>\r\n<t10v100>2020-04-11 12:00:20</t10v100>\r\n<t10v90>2020-04-11 12:00:21</t10v90>\r\n<t10v80>2020-04-11 12:00:22</t10v80>\r\n<t10v70>2020-04-11 12:00:23</t10v70>\r\n<t10v60>2020-04-11 12:00:24</t10v60>\r\n<t10v50>2020-04-11 12:00:25</t10v50>\r\n<t10v40>2020-04-11 12:00:26</t10v40>\r\n<t10v30>2020-04-11 12:00:27</t10v30>\r\n<t10v20>2020-04-11 12:00:28</t10v20>\r\n<t10v10>2020-04-11 12:00:29</t10v10>\r\n<nom>31</nom>\r\n<pt3010>32</pt3010>\r\n<pt309>33</pt309>\r\n<pt308>34</pt308>\r\n<pt307>35</pt307>\r\n<pt306>36</pt306>\r\n<pt305>37</pt305>\r\n<pt304>38</pt304>\r\n<pt303>39</pt303>\r\n<st3010>40</st3010>\r\n<st309>41</st309>\r\n<st308>42</st308>\r\n<st307>43</st307>\r\n<st306>44</st306>\r\n<st305>45</st305>\r\n<st304>46</st304>\r\n<st303>47</st303>\r\n<pt2010>48</pt2010>\r\n<pt209>49</pt209>\r\n<pt208>50</pt208>\r\n<pt207>51</pt207>\r\n<pt206>52</pt206>\r\n<pt205>53</pt205>\r\n<pt204>54</pt204>\r\n<pt203>55</pt203>\r\n<st2010>56</st2010>\r\n<st209>57</st209>\r\n<st208>58</st208>\r\n<st207>59</st207>\r\n<st206>60</st206>\r\n<st205>61</st205>\r\n<st204>62</st204>\r\n<st203>63</st203>\r\n<ps1010>64</ps1010>\r\n<ps109>65</ps109>\r\n<ps108>66</ps108>\r\n<ps107>67</ps107>\r\n<ps106>68</ps106>\r\n<ps105>69</ps105>\r\n<ps104>70</ps104>\r\n<ps103>71</ps103>\r\n<ss1010>72</ss1010>\r\n<ss109>73</ss109>\r\n<ss108>74</ss108>\r\n<ss107>75</ss107>\r\n<ss106>76</ss106>\r\n<ss105>77</ss105>\r\n<ss104>78</ss104>\r\n<ss103>79</ss103>\r\n<pp90>80</pp90>\r\n<pp80>81</pp80>\r\n<pp70>82</pp70>\r\n<pp60>83</pp60>\r\n<pp50>84</pp50>\r\n<pp40>85</pp40>\r\n<pp30>86</pp30>\r\n<pp20>87</pp20>\r\n<con10010>88</con10010>\r\n<con8010>89</con8010>\r\n<con>90</con>\r\n</dpowermeterls>\r\n</selfinspectiondata>">>,msgid => <<"ac92f6ec-374d-4512-8def-3d8ead82d060">>,msgmethod => <<"epd_selfinspection">>,username => <<"BQCZ02_1">>}]

[HJianBo]

Thanks @eshxcmhk It is a bug. We'll fix it at the next version (v4.1-beta.1 maybe)

In the current, a workaround is turn up the log level instead of debug

[eshxcmhk]

Thanks @eshxcmhk It is a bug. We'll fix it at the next version (v4.1-beta.1 maybe)

In the current, a workaround is turn up the log level instead of debug

不好意思，我没说清楚，这个不是日志打印错误，而是在http中收到的数据只有一个"{"，规则管理页面查看显示失败1，然后通过修改日志级别并用console方式运行后发现的唯一一个错误，web端使用django直接运行，修改了请求的body大小为无限制，减少msgbody中的xml节点数量后一切正常(经过测试，当web_hook发送的body大小在2048字节以下时可以正常接收)，调整mqtt.max_packet_size = 10M也没用

[HJianBo]

I think you should give me detailed params for Rule-Engine and Resource to help me reproducing it

[eshxcmhk]

I think you should give me detailed params for Rule-Engine and Resource to help me reproducing it

the SQL:

SELECT username , payload.msgid as msgid ,payload.msgmethod as msgmethod ,payload.msgbody as msgbody FROM "/middleware/apis/detect/req/#"

the URL:
http://wechat.12328.tv:8180/apis/yibing/detect/handle

topic中的local节点是调试用的，线上需去掉

[HJianBo]

Can you give me a failed payload example?

[eshxcmhk]

Can you give me a failed payload example?

{"msgid":"df415120-faaf-42dd-8f22-050aaaee7f36","msgbody":"<selfinspectiondata>\r\n<lineid>1</lineid>\r\n<deviceid>1</deviceid>\r\n<starttime>2019-01-03 07:30:21</starttime>\r\n<endtime>2019-01-03 07:30:21</endtime>\r\n<dpowermeterls>\r\n<t30v100>2020-04-11 12:00:00</t30v100>\r\n<t30v90>2020-04-11 12:00:01</t30v90>\r\n<t30v80>2020-04-11 12:00:02</t30v80>\r\n<t30v70>2020-04-11 12:00:03</t30v70>\r\n<t30v60>2020-04-11 12:00:04</t30v60>\r\n<t30v50>2020-04-11 12:00:05</t30v50>\r\n<t30v40>2020-04-11 12:00:06</t30v40>\r\n<t30v30>2020-04-11 12:00:07</t30v30>\r\n<t30v20>2020-04-11 12:00:08</t30v20>\r\n<t30v10>2020-04-11 12:00:09</t30v10>\r\n<t20v100>2020-04-11 12:00:10</t20v100>\r\n<t20v90>2020-04-11 12:00:11</t20v90>\r\n<t20v80>2020-04-11 12:00:12</t20v80>\r\n<t20v70>2020-04-11 12:00:13</t20v70>\r\n<t20v60>2020-04-11 12:00:14</t20v60>\r\n<t20v50>2020-04-11 12:00:15</t20v50>\r\n<t20v40>2020-04-11 12:00:16</t20v40>\r\n<t20v30>2020-04-11 12:00:17</t20v30>\r\n<t20v20>2020-04-11 12:00:18</t20v20>\r\n<t20v10>2020-04-11 12:00:19</t20v10>\r\n<t10v100>2020-04-11 12:00:20</t10v100>\r\n<t10v90>2020-04-11 12:00:21</t10v90>\r\n<t10v80>2020-04-11 12:00:22</t10v80>\r\n<t10v70>2020-04-11 12:00:23</t10v70>\r\n<t10v60>2020-04-11 12:00:24</t10v60>\r\n<t10v50>2020-04-11 12:00:25</t10v50>\r\n<t10v40>2020-04-11 12:00:26</t10v40>\r\n<t10v30>2020-04-11 12:00:27</t10v30>\r\n<t10v20>2020-04-11 12:00:28</t10v20>\r\n<t10v10>2020-04-11 12:00:29</t10v10>\r\n<nom>31</nom>\r\n<pt3010>32</pt3010>\r\n<pt309>33</pt309>\r\n<pt308>34</pt308>\r\n<pt307>35</pt307>\r\n<pt306>36</pt306>\r\n<pt305>37</pt305>\r\n<pt304>38</pt304>\r\n<pt303>39</pt303>\r\n<st3010>40</st3010>\r\n<st309>41</st309>\r\n<st308>42</st308>\r\n<st307>43</st307>\r\n<st306>44</st306>\r\n<st305>45</st305>\r\n<st304>46</st304>\r\n<st303>47</st303>\r\n<pt2010>48</pt2010>\r\n<pt209>49</pt209>\r\n<pt208>50</pt208>\r\n<pt207>51</pt207>\r\n<pt206>52</pt206>\r\n<pt205>53</pt205>\r\n<pt204>54</pt204>\r\n<pt203>55</pt203>\r\n<st2010>56</st2010>\r\n<st209>57</st209>\r\n<st208>58</st208>\r\n<st207>59</st207>\r\n<st206>60</st206>\r\n<st205>61</st205>\r\n<st204>62</st204>\r\n<st203>63</st203>\r\n<ps1010>64</ps1010>\r\n<ps109>65</ps109>\r\n<ps108>66</ps108>\r\n<ps107>67</ps107>\r\n<ps106>68</ps106>\r\n<ps105>69</ps105>\r\n<ps104>70</ps104>\r\n<ps103>71</ps103>\r\n<ss1010>72</ss1010>\r\n<ss109>73</ss109>\r\n<ss108>74</ss108>\r\n<ss107>75</ss107>\r\n<ss106>76</ss106>\r\n<ss105>77</ss105>\r\n<ss104>78</ss104>\r\n<ss103>79</ss103>\r\n<pp90>80</pp90>\r\n<pp80>81</pp80>\r\n<pp70>82</pp70>\r\n<pp60>83</pp60>\r\n<pp50>84</pp50>\r\n<pp40>85</pp40>\r\n<pp30>86</pp30>\r\n<pp20>87</pp20>\r\n<con10010>88</con10010>\r\n<con8010>89</con8010>\r\n<con>90</con>\r\n</dpowermeterls>\r\n</selfinspectiondata>","msgmethod":"epd_selfinspection"}

[HJianBo]

This seems to be complete the right parameters. Please capture the HTTP traffic to diagnose the HTTP Request

[eshxcmhk]

This seems to be complete the right parameters. Please capture the HTTP traffic to diagnose the HTTP Request

抓包发现emqx发送的数据中，content是完整的，但header信息中长度错误

POST /apis/yibing/detect/handle HTTP/1.1
content-type: application/json
content-length: 2

[eshxcmhk]

This seems to be complete the right parameters. Please capture the HTTP traffic to diagnose the HTTP Request

我下载源码修改编译后打印日志发现，Params1 = emqx_json:encode(Params),的返回值在2048字节以内是一个完整的<<".*">>包裹起来的，但是超出2048后变成两个了，类似

<<".*">>,
<<".*">>

[eshxcmhk]

This seems to be complete the right parameters. Please capture the HTTP traffic to diagnose the HTTP Request

经过测试，在json编码后Params1 = emqx_json:encode(Params),，增加：

    Params_a = if
      is_list(Params1) ->
        list_to_binary(Params1);
      true ->
        Params1
    end,

这样可以解决问题，但是不知道为什么emqx_json:encode会返回一个list，不确定这样处理是不是有问题

[HJianBo]

Thanks for your digging it.

It had fixed at v4.1-alpha.2 :)