AT+CGDCONT?でモジュールが再起動するときがある

[matsujirushi]

半日〜1日経過後、連続稼働しているとERROR: .../Bg770aNetwork.hpp:236が発生して、USER LEDが点滅する。

07:48:59.547 -> URC> RDY
07:48:59.610 -> URC> +CFUN: 1
07:48:59.610 -> URC> +CPIN: READY
07:48:59.644 -> URC> +QUSIM: 1
07:49:00.619 -> URC> +QIND: SMS DONE
07:49:01.642 -> URC> APP RDY
07:49:01.642 -> CMD> AT+IFC=2,2
07:49:01.642 -> ECO> AT+IFC=2,2 ... 10[ms]
07:49:01.642 -> FRC> OK
07:49:01.642 -> CMD> AT+QSCLK=2
07:49:03.636 -> ECO> AT+QSCLK=2 ... 1998[ms]
07:49:03.636 -> FRC> OK
07:49:03.636 -> CMD> AT+CGDCONT?
07:49:03.636 -> ECO> AT+CGDCONT? ... 8[ms]
07:49:10.619 -> [meas]Power on the grove module
07:49:10.619 -> [meas]Polling GPS data
07:49:13.659 -> ERROR: /Users/.../Arduino/libraries/WioCellular/src/network/Bg770aNetwork.hpp:236
07:49:50.610 -> [meas]Measuring
07:49:50.610 -> [meas]Power off the grove module
07:49:50.610 -> [meas]Free size of storage: 65231
07:49:50.610 -> [meas]Append 34 bytes to storage {"uptime":34848,"time":1744929648}
07:50:10.630 -> [meas]Power on the grove module
07:50:10.630 -> [meas]Polling GPS data
07:50:50.637 -> [meas]Measuring
07:50:50.637 -> [meas]Power off the grove module
07:50:50.637 -> [meas]Free size of storage: 65195
07:50:50.637 -> [meas]Append 34 bytes to storage {"uptime":34908,"time":1744929708}
07:51:10.640 -> [meas]Power on the grove module
07:51:10.640 -> [meas]Polling GPS data
07:51:50.640 -> [meas]Measuring

[matsujirushi]

調査メモ。

エラー表示箇所

wio_cellular/src/network/Bg770aNetwork.hpp

Lines 234 to 237 in fafa874

	if ((result = WioCellular.getPdpContext(&pdpContexts)) != WioCellularResult::Ok)
	{
	abortHandler(__FILE__, __LINE__);
	}

WioCellular.getPdpContext()

07:49:03.636 -> CMD> AT+CGDCONT?
07:49:03.636 -> ECO> AT+CGDCONT? ... 8[ms]
07:49:13.659 -> ERROR: /Users/.../Arduino/libraries/WioCellular/src/network/Bg770aNetwork.hpp:236

• AT+CGDCONT?を送信
• AT+CGDCONT?を受信（エコー）
• 10秒経ってもINF, FRCが受信できなかったため、エラー（0.3秒ではないのは何故か！？）
  

  wio_cellular/src/module/bg770a/commands/Bg770aPacketDomainCommands.hpp

  Line 196 in fafa874

  300);

[susami-lab]

本現象発生時のライブラリバージョンは、（最新のv0.3.8ではなく）WioCellular v0.3.7でした。

[matsujirushi]

手元では事象再現しない。

AT+CGDCONT?は怪しい挙動があったので、AT+CGPADDRに変更して改善されないか確認することにする。

[matsujirushi]

@susami-lab
Q1. SIMはどれを使っていますか？
Q2. セルラー通信の接続周期は何分ですか？

[susami-lab]

@susami-lab Q1. SIMはどれを使っていますか？ Q2. セルラー通信の接続周期は何分ですか？

A1. plan-Dです。
A2. セルラー通信の接続周期5分です。なお、計測周期は1分です。

[matsujirushi]

@susami-lab
デバッグログを増やしたライブラリを用意しました。
https://github.com/SeeedJP/wio_cellular/tree/issue/47

このライブラリとsoracom-gps-trackerで試して、ログを取得していただけませんか？

[susami-lab]

@matsujirushi
再現しました。

下記エラーが出ています。

21:06:56.948 -> ---> 49536109 Finish getPdpContext
21:06:56.948 -> ---> 49536109 ERROR on getPdpContext ReadResponseTimeout
21:06:56.948 -> ---> 49536109 Enter doWorkUntil(60000)

条件は下記です。
・SIMはplan-KM1
・セルラー通信の接続周期は6分（計測周期は2分）

シリアルモニタ詳細は下記です。

21:06:42.831 -> URC> RDY
21:06:42.922 -> URC> +CFUN: 1
21:06:42.922 -> URC> +CPIN: READY
21:06:42.922 -> URC> +QUSIM: 1
21:06:43.902 -> URC> +QIND: SMS DONE
21:06:44.904 -> URC> APP RDY
21:06:44.904 -> CMD> AT+IFC=2,2
21:06:44.941 -> ECO> AT+IFC=2,2 ... 3[ms]
21:06:44.941 -> FRC> OK
21:06:44.941 -> CMD> AT+QSCLK=2
21:06:46.952 -> ECO> AT+QSCLK=2 ... 1999[ms]
21:06:46.952 -> FRC> OK
21:06:46.952 -> ---> 49526105 Execute getPdpContext
21:06:46.952 -> CMD> AT+CGDCONT?
21:06:46.952 -> ECO> AT+CGDCONT? ... 2[ms]
21:06:56.948 -> ---> 49536109 Finish getPdpContext
21:06:56.948 -> ---> 49536109 ERROR on getPdpContext ReadResponseTimeout
21:06:56.948 -> ---> 49536109 Enter doWorkUntil(60000)
21:07:05.740 -> URC> RDY
21:07:05.974 -> URC> +CFUN: 1
21:07:05.974 -> URC> +CPIN: READY
21:07:05.974 -> URC> +QUSIM: 1
21:07:06.982 -> URC> +QIND: SMS DONE
21:07:07.991 -> URC> APP RDY
21:07:28.863 -> [meas]Power on the grove module
21:07:28.863 -> [meas]Polling GPS data
21:07:28.977 -> URC> RDY
21:07:29.190 -> URC> +CFUN: 1
21:07:29.190 -> URC> +CPIN: READY
21:07:29.236 -> URC> +QUSIM: 1
21:07:30.187 -> URC> +QIND: SMS DONE
21:07:31.189 -> URC> APP RDY
21:07:56.945 -> ---> 49596109 Leave doWorkUntil(60000)
21:07:56.945 -> ---> 49596109 Execute 'AT'
21:07:56.945 -> CMD> AT
21:07:56.945 -> ECO> AT ... 1[ms]
21:07:56.945 -> FRC> OK
21:07:56.945 -> ---> 49596111 Done 'AT'
21:07:56.945 -> ---> 49596111 Execute 'AT'
21:07:56.945 -> CMD> AT
21:07:56.945 -> ECO> AT ... 2[ms]
21:07:56.945 -> FRC> OK
21:07:56.945 -> ---> 49596114 Done 'AT'
21:07:56.945 -> ---> 49596114 Execute 'AT'
21:07:56.945 -> CMD> AT
21:07:56.945 -> ECO> AT ... 1[ms]
21:07:56.945 -> FRC> OK
21:07:56.945 -> ---> 49596116 Done 'AT'
21:07:56.945 -> ERROR: xxx\Arduino\libraries\WioCellular\src/network/Bg770aNetwork.hpp:236
21:08:28.896 -> [meas]Measuring
21:08:28.896 -> [meas]Power off the grove module
21:08:28.896 -> [meas]Free size of storage: 65375
21:08:28.896 -> [meas]Append 34 bytes to storage {"time":1745496508,"uptime":49628}
21:09:28.924 -> [meas]Power on the grove module
21:09:28.924 -> [meas]Polling GPS data
21:10:28.925 -> [meas]Measuring
21:10:28.925 -> [meas]Power off the grove module
21:10:28.925 -> [meas]Free size of storage: 65339
21:10:28.925 -> [meas]Append 34 bytes to storage {"time":1745496628,"uptime":49748}
21:11:28.937 -> [meas]Power on the grove module
21:11:28.937 -> [meas]Polling GPS data
21:12:28.913 -> [meas]Measuring
21:12:28.913 -> [meas]Power off the grove module
21:12:28.913 -> [meas]Free size of storage: 65303
21:12:28.913 -> [meas]Append 34 bytes to storage {"time":1745496748,"uptime":49868}
21:13:28.953 -> [meas]Power on the grove module
21:13:28.953 -> [meas]Polling GPS data

松岡メモ

• 送信間隔は15分
• PSM周期は17分
• AT+CGDCONT?のINF/FRCが無い（タイムアウト10秒）
• 約19秒後にモジュール起動

21:06:42.831 -> URC> RDY
...
21:06:44.941 -> CMD> AT+QSCLK=2
21:06:46.952 -> ECO> AT+QSCLK=2 ... 1999[ms]
21:06:46.952 -> FRC> OK

21:06:46.952 -> CMD> AT+CGDCONT?
21:06:46.952 -> ECO> AT+CGDCONT? ... 2[ms]
21:06:56.948 -> ---> 49536109 ERROR on getPdpContext ReadResponseTimeout

21:07:05.740 -> URC> RDY

[matsujirushi]

@susami-lab
デバッグログを増やしました。
https://github.com/SeeedJP/wio_cellular/tree/issue/47

このライブラリとsoracom-gps-trackerで、再度、テストをお願いします。🙏

[susami-lab]

@matsujirushi
再現しました。

18:06:57.164 -> [cell]Power on the cellular module
18:07:09.227 -> ---> 514445 Execute getPdpContext
18:07:10.293 -> ---> 515465 Finish getPdpContext
18:07:10.336 -> [cell]Update clock
18:07:10.336 -> ---> 515538 Execute getPdpContext
18:07:10.336 -> ---> 515554 Finish getPdpContext
18:07:10.336 -> [cell]Read 3 block info from storage
18:07:10.336 -> [cell]Peek 32 bytes from storage {"time":1745571699,"uptime":185}
18:07:10.371 -> [cell]Peek 32 bytes from storage {"time":1745571819,"uptime":305}
18:07:10.371 -> [cell]Peek 32 bytes from storage {"time":1745571939,"uptime":425}
18:07:10.371 -> [cell]Sending {"data":[{"time":1745571699,"uptime":185},{"time":1745571819,"uptime":305},{"time":1745571939,"uptime":425}]}
18:07:10.371 -> [cell]Connecting uni.soracom.io:23080
18:07:10.886 -> [cell]Sending
18:07:10.886 -> [cell]Receiving
18:07:11.442 -> [cell]Received 201 {"total":3,"status":{"successCount":3,"errors":[]}}
18:07:11.442 -> 
18:07:11.442 -> [cell]Processed data from storage
18:07:11.442 -> [cell]Processed data from storage
18:07:11.442 -> [cell]Processed data from storage
18:07:11.442 -> [cell]Read 0 block info from storage
18:07:11.442 -> [cell]Power off the cellular module
18:07:40.103 -> [meas]Measuring
18:07:40.103 -> [meas]Power off the grove module
18:07:40.103 -> [meas]Free size of storage: 65519
18:07:40.103 -> [meas]Append 32 bytes to storage {"time":1745572058,"uptime":545}
18:08:40.104 -> [meas]Power on the grove module
18:08:40.104 -> [meas]Polling GPS data
18:09:40.125 -> [meas]Measuring
18:09:40.125 -> [meas]Power off the grove module
18:09:40.125 -> [meas]Free size of storage: 65485
18:09:40.125 -> [meas]Append 32 bytes to storage {"time":1745572178,"uptime":665}
18:10:40.100 -> [meas]Power on the grove module
18:10:40.100 -> [meas]Polling GPS data
18:11:40.107 -> [meas]Measuring
18:11:40.107 -> [meas]Power off the grove module
18:11:40.151 -> [meas]Free size of storage: 65451
18:11:40.151 -> [meas]Append 32 bytes to storage {"time":1745572298,"uptime":785}
18:12:40.144 -> [meas]Power on the grove module
18:12:40.144 -> [meas]Polling GPS data
18:13:15.377 -> [cell]Check if data is in storage
18:13:15.377 -> [cell]Power on the cellular module
18:13:27.568 -> ---> 892744 Execute getPdpContext
18:13:37.571 -> ---> 902746 Finish getPdpContext
18:13:37.571 -> ---> 902746 ERROR on getPdpContext ReadResponseTimeout
18:13:37.571 -> ---> 902746 Execute 'AT'
18:13:40.129 -> [meas]Measuring
18:13:40.129 -> [meas]Power off the grove module
18:13:40.190 -> [meas]Free size of storage: 65417
18:13:40.190 -> [meas]Append 32 bytes to storage {"time":1745572418,"uptime":905}
18:14:40.144 -> [meas]Power on the grove module
18:14:40.144 -> [meas]Polling GPS data
18:14:49.015 -> ---> 974138 Done 'AT'
18:14:49.015 -> ---> 974138 Execute 'AT'
18:14:49.015 -> ---> 974139 Done 'AT'
18:14:49.015 -> ---> 974139 Execute 'AT'
18:14:49.015 -> ---> 974143 Done 'AT'
18:14:49.015 -> ---> 974143 Enter doWorkUntil(60000)
18:15:40.190 -> [meas]Measuring
18:15:40.190 -> [meas]Power off the grove module
18:15:40.190 -> [meas]Free size of storage: 65383
18:15:40.190 -> [meas]Append 33 bytes to storage {"time":1745572538,"uptime":1025}
18:15:48.988 -> ---> 1034143 Leave doWorkUntil(60000)
18:15:48.988 -> ---> 1034143 Execute 'AT'
18:15:48.988 -> ---> 1034145 Done 'AT'
18:15:48.988 -> ---> 1034145 Execute 'AT'
18:15:48.988 -> ---> 1034146 Done 'AT'
18:15:48.988 -> ---> 1034147 Execute 'AT'
18:15:48.988 -> ---> 1034148 Done 'AT'
18:15:48.988 -> ERROR: xxx\Arduino\libraries\wio_cellular-issue_250425\src/network/Bg770aNetwork.hpp:236
18:16:40.198 -> [meas]Power on the grove module
18:16:40.198 -> [meas]Polling GPS data
18:17:40.204 -> [meas]Measuring
18:17:40.204 -> [meas]Power off the grove module
18:17:40.204 -> [meas]Free size of storage: 65348
18:17:40.204 -> [meas]Append 33 bytes to storage {"time":1745572658,"uptime":1145}
18:18:40.211 -> [meas]Power on the grove module
18:18:40.211 -> [meas]Polling GPS data
18:19:40.195 -> [meas]Measuring
18:19:40.195 -> [meas]Power off the grove module
18:19:40.195 -> [meas]Free size of storage: 65313

[susami-lab]

@matsujirushi

再現しました。いかがでしょうか。

08:39:28.563 -> [cell]Power on the cellular module
08:39:36.380 -> URC> RDY
08:39:36.636 -> URC> +CFUN: 1
08:39:36.636 -> URC> +CPIN: READY
08:39:36.636 -> URC> +QUSIM: 1
08:39:37.632 -> URC> +QIND: SMS DONE
08:39:38.642 -> URC> APP RDY
08:39:38.642 -> CMD> AT+IFC=2,2
08:39:38.642 -> ECO> AT+IFC=2,2 ... 2[ms]
08:39:38.642 -> FRC> OK
08:39:38.642 -> CMD> AT+QSCLK=2
08:39:40.647 -> ECO> AT+QSCLK=2 ... 1999[ms]
08:39:40.647 -> FRC> OK
08:39:40.647 -> ---> 2325625 Execute getPdpContext
08:39:40.647 -> CMD> AT+CGDCONT?
08:39:40.647 -> ECO> AT+CGDCONT? ... 1[ms]
08:39:50.669 -> ---> 2335627 Finish getPdpContext
08:39:50.669 -> ---> 2335627 ERROR on getPdpContext ReadResponseTimeout
08:39:50.669 -> ---> 2335627 Execute 'AT'
08:39:50.669 -> CMD> AT
08:39:57.192 -> [meas]Measuring
08:39:57.192 -> [meas]Power off the grove module
08:39:57.192 -> [meas]Free size of storage: 65414
08:39:57.192 -> [meas]Append 33 bytes to storage {"time":1745797196,"uptime":2342}
08:40:01.985 -> URC> RDY
08:40:02.263 -> URC> +CFUN: 1
08:40:02.263 -> URC> +CPIN: READY
08:40:02.263 -> URC> +QUSIM: 1
08:40:03.240 -> URC> +QIND: SMS DONE
08:40:04.218 -> URC> APP RDY
08:40:57.223 -> [meas]Power on the grove module
08:40:57.223 -> [meas]Polling GPS data
08:41:04.225 -> ---> 2409217 Done 'AT'
08:41:04.225 -> ---> 2409217 Execute 'AT'
08:41:04.225 -> CMD> AT
08:41:04.270 -> ECO> AT ... 0[ms]
08:41:04.270 -> FRC> OK
08:41:04.270 -> ---> 2409218 Done 'AT'
08:41:04.270 -> ---> 2409218 Execute 'AT'
08:41:04.270 -> CMD> AT
08:41:04.270 -> ECO> AT ... 2[ms]
08:41:04.270 -> FRC> OK
08:41:04.270 -> ---> 2409221 Done 'AT'
08:41:04.270 -> ---> 2409221 Enter doWorkUntil(60000)
08:41:57.213 -> [meas]Measuring
08:41:57.213 -> [meas]Power off the grove module
08:41:57.213 -> [meas]Free size of storage: 65379
08:41:57.213 -> [meas]Append 33 bytes to storage {"time":1745797316,"uptime":2462}
08:42:04.234 -> ---> 2469221 Leave doWorkUntil(60000)
08:42:04.234 -> ---> 2469221 Execute 'AT'
08:42:04.234 -> CMD> AT
08:42:04.234 -> ECO> AT ... 1[ms]
08:42:04.280 -> FRC> OK
08:42:04.280 -> ---> 2469222 Done 'AT'
08:42:04.280 -> ---> 2469222 Execute 'AT'
08:42:04.280 -> CMD> AT
08:42:04.280 -> ECO> AT ... 1[ms]
08:42:04.280 -> FRC> OK
08:42:04.280 -> ---> 2469225 Done 'AT'
08:42:04.280 -> ---> 2469225 Execute 'AT'
08:42:04.280 -> CMD> AT
08:42:04.280 -> ECO> AT ... 1[ms]
08:42:04.280 -> FRC> OK
08:42:04.280 -> ---> 2469227 Done 'AT'
08:42:04.280 -> ERROR: xxx\Arduino\libraries\wio_cellular-issue_250425\src/network/Bg770aNetwork.hpp:236
08:42:57.200 -> [meas]Power on the grove module
08:42:57.200 -> [meas]Polling GPS data
08:43:57.227 -> [meas]Measuring
08:43:57.227 -> [meas]Power off the grove module
08:43:57.227 -> [meas]Free size of storage: 65344
08:43:57.227 -> [meas]Append 33 bytes to storage {"time":1745797436,"uptime":2582}
08:44:57.266 -> [meas]Power on the grove module
08:44:57.266 -> [meas]Polling GPS data
08:45:57.266 -> [meas]Measuring
08:45:57.266 -> [meas]Power off the grove module
08:45:57.266 -> [meas]Free size of storage: 65309
08:45:57.266 -> [meas]Append 33 bytes to storage {"time":1745797556,"uptime":2702}

松岡メモ

• 送信間隔は15秒
• PSM無し（電源OFF）
• AT+CGDCONT?のINF/FRCが無い（タイムアウト10秒）
• 約11秒後にモジュール起動

08:39:36.380 -> URC> RDY
...
08:39:38.642 -> CMD> AT+QSCLK=2
08:39:40.647 -> ECO> AT+QSCLK=2 ... 1999[ms]
08:39:40.647 -> FRC> OK

08:39:40.647 -> CMD> AT+CGDCONT?
08:39:40.647 -> ECO> AT+CGDCONT? ... 1[ms]
08:39:50.669 -> ---> 2335627 ERROR on getPdpContext ReadResponseTimeout

08:39:50.669 -> CMD> AT

08:40:01.985 -> URC> RDY

[matsujirushi]

わかったこと。

• AT+CGDCONT?の後にモジュールが再起動している。（ECO有り、INF/FRC無し）
• モジュール再起動までの間、ATコマンドに応答しない。
• PSM使用とは関係なさそう。

[matsujirushi]

@susami-lab
問題を回避するコードにしました。
（AT+CGDCONT?を電源ONの初回だけに限定）
https://github.com/SeeedJP/wio_cellular/tree/issue/47

このライブラリとsoracom-gps-trackerで、問題が発生しないことをテスト願います。🙏

[susami-lab]

@matsujirushi
んーまだ問題が発生します。

19:02:33.958 -> [cell]Power on the cellular module
19:02:41.922 -> URC> RDY
19:02:42.106 -> URC> +CFUN: 1
19:02:42.138 -> URC> +CPIN: READY
19:02:42.138 -> URC> +QUSIM: 1
19:02:43.150 -> URC> +QIND: SMS DONE
19:02:44.147 -> URC> APP RDY
19:02:44.147 -> CMD> AT+IFC=2,2
19:02:44.147 -> ECO> AT+IFC=2,2 ... 2[ms]
19:02:44.147 -> FRC> OK
19:02:44.147 -> CMD> AT+QSCLK=2
19:02:46.154 -> ECO> AT+QSCLK=2 ... 2000[ms]
19:02:46.154 -> FRC> OK
19:02:46.154 -> CMD> AT+QCFG="iotopmode"
19:02:46.154 -> ECO> AT+QCFG="iotopmode" ... 4[ms]
19:02:53.424 -> [meas]Power on the grove module
19:02:53.424 -> [meas]Polling GPS data
19:02:56.150 -> ERROR:xxx\Arduino\libraries\wio_cellular-issue-47_250428\src/network/Bg770aNetwork.hpp:256
19:03:53.438 -> [meas]Measuring
19:03:53.438 -> [meas]Power off the grove module
19:03:53.438 -> [meas]Free size of storage: 65414
19:03:53.438 -> [meas]Append 33 bytes to storage {"time":1745834633,"uptime":2825}
19:04:53.489 -> [meas]Power on the grove module
19:04:53.489 -> [meas]Polling GPS data
19:05:53.473 -> [meas]Measuring
19:05:53.473 -> [meas]Power off the grove module
19:05:53.473 -> [meas]Free size of storage: 65379
19:05:53.473 -> [meas]Append 33 bytes to storage {"time":1745834753,"uptime":2945}
19:06:53.479 -> [meas]Power on the grove module
19:06:53.479 -> [meas]Polling GPS data
19:07:53.470 -> [meas]Measuring
19:07:53.470 -> [meas]Power off the grove module
19:07:53.535 -> [meas]Free size of storage: 65344

[matsujirushi]

@susami-lab
AT+CGDCONT?じゃなくてAT+IFCが悪さをしているのか！？
コードを修正しました。
https://github.com/SeeedJP/wio_cellular/tree/issue/47

このライブラリとsoracom-gps-trackerで、問題が発生しないことをテスト願います。🙏