topic Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2 in Kinetis Software Development Kit

Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

ironsean — Fri, 15 May 2015 17:28:08 GMT

Hello,

I'm moving/rebuilding a project to the new KSD 3 and KSDK 1.2. However, I'm running into some weird behaviour and instability with my program crashing regularly. I'm also having trouble debugging as the Task Aware Debugging is no longer smart enough to parse out the task stacks for each running task. I can only look at the current status of the current executing task. Basically I'm having three tasks trip over each other, outputting their printf characters all at once. I get:

Which is coming from three tasks (the main task, the sonar task, and the sender task).

Icarting Sonar task...Sonar task started su i cneSsisoftunlilayl.r   ztasik rnunnging isnittialaizicng kmes sagoe qfueu es.s.. suczn ReX t ask1 st2art0ed    ces*sfu~lly*. ~*~*~*~*~*~*~*~*~*~*~

I can parse it out to this:

Unknown: Ic  i    sucn     main_task: Starting Sender task...Sender task started successfully. arting Sonar task...Sonar task started su cessfully.   Sonar_task: Sonar task running  nitializing message queues...     RX task started   cessfully.   Sender_task: initil zing stack of s ze 120 *~*~*~*~*~*~*~*~*~*~*~*~ Time to wake Socket Man

But that's even still not quite right, as some of the characters are missing or incorrect.

Original Attachment has been moved to: EMLU_KDS3_K64.zip

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

ironsean — Sat, 16 May 2015 23:59:48 GMT

I can confirm the same behaviour does not happen in the KSDK 1.1 and KDS 2. The print statements all execute appropriately.

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

DavidS — Mon, 18 May 2015 16:05:48 GMT

Hi Sean,

I'm assuming you are running the UART in a polled mode.....correct?

If yes, when a specific task is doing a printf() call, that printf() is part of the running task. If a higher priority task becomes READY, then the low priority task will prempt causing the mixing of characters on the output. If you don't want mixing of characters then you need to synchronize the task with a mutex.

Conversely you might create a task that receives messages (the printf() contents) to handle printf() capabilities and it prints messages in order received.

When transmitting in polled mode I'm not sure why a character might be missing. I would think the driver would wait to place another character in the transmit buffer until the buffer is freed/ready.

Can you try the mutex or printf_task approach?

Regards,

David

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

ironsean — Mon, 18 May 2015 17:13:09 GMT

Hello David,

I can't say if I'm running in a polled mode or not, I'm running with whatever the standard defaults are for MQX in the new project creation guide.

What I find more perplexing is that throughout MQX 4.0.0, 4.0.1, 4.1.0, 4.1.0, 4.1.1, and KSDK 1.1.0 the same code running the same tasks did not cause this behaviour. Printf statements nearly always executed completely and discretely, except for some rare cases where one printf statement would be preempted part way through for another task to execute and print something, before returning and finishing (likely as you describe above).

In this case, my main task is the highest priority with 10, and should be able to finish outputting before another task is given the ability to execute. then sonar has a priority of 11 and should be outputting it's relevant information and blocking before the sender task is allowed to run.

I really do not believe each task rapidly pre-empting each other, printing a single character, then blocking to allow another task to print a single character again could be correct behaviour.

As well, during debugging I see (only with KSDK 1.2) that printf statements do not even finish before the debugger believes it's halting at later statements of code. I need to step through several later lines of code before the characters will finish outputting to the terminal. This was also not the behaviour in any previous versions.

I don't know if this is directly tied to another issue I've been having that I'm likely going to make a post about later today: That the debuggers in the KDS 3.0 seems to be quite buggy, and even more unstable than in KDS 2.0. I'm often running into packet errors, breakpoints that can't be properly set, stepping through code that fails to work properly, etc. With both the Segger and PEMicro debuggers/board firmware. I have not tried the OpenOCD as I was under the impression for debugging it would be the least refined and least recommended.

Sean

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

DavidS — Mon, 18 May 2015 19:05:21 GMT

Hi Sean,

Can you clean the project, re-ZIP and re-post. Our scanner detected a virus.....probably our KDS project ;-)

Regards,

David

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

ironsean — Mon, 18 May 2015 19:35:57 GMT

Oops, I thought it was strange that it was so large. I've cleaned and re-zipped, and edited the top post to have the proper attachment.

Thank you,

Sean

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

DavidS — Tue, 19 May 2015 18:03:58 GMT

Hi Sean,

When I run your project on the FRDM-K64F using KDS_3.0/KSDK_1.2.0 the terminal output is:

Main task has started.

Config loaded, configID is 10 and the errors were 0.

Config from Defaults loaded.

Starting Error Log task...

Config loaded, configID is 10 and the errors were 0.

Error loading SDCARD config.

MAC: 0:0:5e:a0:0:e1

Attempting to bind an IP via DHCP...(60s timeout)

DHCP bind successful.

Current IP info:

IP Address : 10.0.1.183

Subnet Address : 255.255.255.0

Initializing message queues...

Starting Sender task...Sender task started successfully.

Starting Sonar task...Sonar task started suIc

cneSsisoftunlilayl.ri

ztasik rnunnging

Isnittialaizicng kmes sagoe qfueu es.s..i

CAzn ReX t ask1 st2art0ed suc

ces*sfu~lly*.

~*~*~*~*~*~*~*~*~*~*~

Time to wake Socket ManSocket man powering up.

socket man a go

Socketman should be awake now.

*~~*~*~*~*~*~*~*~*~~*~*~*

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2230 and time 1432055952

Got a value from the message queue, value: 2230, seconds: 1432055952, temperature: 69900

.. Attempting to send to thingspeak at time 1432055952 and reading 2230

Creating Body with 2 fields:

***Here is the message body ***

created_at=2015-5-19T17:19:12Z-3:00&field1=2.230&field2=69.900&status=Sending+by+sender+task.

Connected to b86a9995, port 80.

Write successful, we hope.

Received 963 bytes of data.

Here is the received message:

HTTP/1.1 200 OK

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:19:12 GMT

Content-Type: text/html; charset=utf-8

Transfer-Encoding: chunked

Connection: keep-alive

Vary: Accept-Encoding

Status: 200 OK

X-Frame-Options: ALLOWALL

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, PUT, OPTIONS, DELETE, PATCH

Access-Control-Allow-Headers: origin, content-type, X-Requested-With

Access-Control-Max-Age: 1800

ETag: "339ccb1bfecf54ac523f10de978f1128"

Cache-Control: max-age=0, private, must-revalidate

Set-Cookie: request_method=POST; path=/

X-Request-Id: 891c5d33-b701-4968-9714-d605db2a27f7

234032

HTTP/1.1 400 Bad Request

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:19:12 GMT

Content-Type: text/html

Content-Length: 172

Connection: close

<html>

<head><title>400 Bad Request</title></head>

<center><h1>400 Bad Request</h1></center>

<hr><center>nginx/1.7.5</center>

</body>

</html>

Result: 234032

No RTCS error, should have worked?!?! waiting 15 seconds... .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2225 and time 1432055982

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2219 and time 1432056012

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2214 and time 1432056042

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2209 and time 1432056072

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2204 and time 1432056102

Got a value from the message queue, value: 2204, seconds: 1432056102, temperature: 69800

.. Attempting to send to thingspeak at time 1432056102 and reading 2204

Creating Body with 2 fields:

***Here is the message body ***

created_at=2015-5-19T17:21:42Z-3:00&field1=2.204&field2=69.800&status=Sending+by+sender+task.

Connected to b86a9995, port 80.

Write successful, we hope.

Received 963 bytes of data.

Here is the received message:

HTTP/1.1 200 OK

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:21:42 GMT

Content-Type: text/html; charset=utf-8

Transfer-Encoding: chunked

Connection: keep-alive

Vary: Accept-Encoding

Status: 200 OK

X-Frame-Options: ALLOWALL

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, PUT, OPTIONS, DELETE, PATCH

Access-Control-Allow-Headers: origin, content-type, X-Requested-With

Access-Control-Max-Age: 1800

ETag: "95bd0b7b0651529e583113d2bdcfa7b5"

Cache-Control: max-age=0, private, must-revalidate

Set-Cookie: request_method=POST; path=/

X-Request-Id: b952e664-3cdb-4424-9d41-8e01fe9bcf09

234033

HTTP/1.1 400 Bad Request

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:21:42 GMT

Content-Type: text/html

Content-Length: 172

Connection: close

<html>

<head><title>400 Bad Request</title></head>

<center><h1>400 Bad Request</h1></center>

<hr><center>nginx/1.7.5</center>

</body>

</html>

Result: 234033

No RTCS error, should have worked?!?! waiting 15 seconds... .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2201 and time 1432056132

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2199 and time 1432056162

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2196 and time 1432056192

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2194 and time 1432056222

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2191 and time 1432056252

Got a value from the message queue, value: 2191, seconds: 1432056252, temperature: 69800

.. Attempting to send to thingspeak at time 1432056252 and reading 2191

Creating Body with 2 fields:

***Here is the message body ***

created_at=2015-5-19T17:24:12Z-3:00&field1=2.191&field2=69.800&status=Sending+by+sender+task.

Connected to b86a9995, port 80.

Write successful, we hope.

Received 963 bytes of data.

Here is the received message:

HTTP/1.1 200 OK

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:24:12 GMT

Content-Type: text/html; charset=utf-8

Transfer-Encoding: chunked

Connection: keep-alive

Vary: Accept-Encoding

Status: 200 OK

X-Frame-Options: ALLOWALL

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, PUT, OPTIONS, DELETE, PATCH

Access-Control-Allow-Headers: origin, content-type, X-Requested-With

Access-Control-Max-Age: 1800

ETag: "da7c103946de4a9694fdf20b89c6eecf"

Cache-Control: max-age=0, private, must-revalidate

Set-Cookie: request_method=POST; path=/

X-Request-Id: 46f67f05-f13f-4aea-94a5-5ba81c87a692

234034

HTTP/1.1 400 Bad Request

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:24:12 GMT

Content-Type: text/html

Content-Length: 172

Connection: close

<html>

<head><title>400 Bad Request</title></head>

<center><h1>400 Bad Request</h1></center>

<hr><center>nginx/1.7.5</center>

</body>

</html>

Result: 234034

No RTCS error, should have worked?!?! waiting 15 seconds... .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2191 and time 1432056282

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2191 and time 1432056312

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2191 and time 1432056342

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2191 and time 1432056372

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2192 and time 1432056402

Got a value from the message queue, value: 2192, seconds: 1432056402, temperature: 69800

.. Attempting to send to thingspeak at time 1432056402 and reading 2192

Creating Body with 2 fields:

***Here is the message body ***

created_at=2015-5-19T17:26:42Z-3:00&field1=2.192&field2=69.800&status=Sending+by+sender+task.

Connected to b86a9995, port 80.

Write successful, we hope.

Received 963 bytes of data.

Here is the received message:

HTTP/1.1 200 OK

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:26:43 GMT

Content-Type: text/html; charset=utf-8

Transfer-Encoding: chunked

Connection: keep-alive

Vary: Accept-Encoding

Status: 200 OK

X-Frame-Options: ALLOWALL

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, PUT, OPTIONS, DELETE, PATCH

Access-Control-Allow-Headers: origin, content-type, X-Requested-With

Access-Control-Max-Age: 1800

ETag: "0ed9ac76c47607d5e3f12044c24ba658"

Cache-Control: max-age=0, private, must-revalidate

Set-Cookie: request_method=POST; path=/

X-Request-Id: 8a129369-2dbc-4e53-a04e-b6e5b22eb96b

234035

HTTP/1.1 400 Bad Request

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:26:43 GMT

Content-Type: text/html

Content-Length: 172

Connection: close

<html>

<head><title>400 Bad Request</title></head>

<center><h1>400 Bad Request</h1></center>

<hr><center>nginx/1.7.5</center>

</body>

</html>

Result: 234035

No RTCS error, should have worked?!?! waiting 15 seconds... .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2194 and time 1432056432

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2196 and time 1432056462

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2199 and time 1432056492

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2202 and time 1432056522

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2205 and time 1432056552

Got a value from the message queue, value: 2205, seconds: 1432056552, temperature: 69800

.. Attempting to send to thingspeak at time 1432056552 and reading 2205

Creating Body with 2 fields:

***Here is the message body ***

created_at=2015-5-19T17:29:12Z-3:00&field1=2.205&field2=69.800&status=Sending+by+sender+task.

Connected to b86a9995, port 80.

Write successful, we hope.

Received 963 bytes of data.

Here is the received message:

HTTP/1.1 200 OK

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:29:13 GMT

Content-Type: text/html; charset=utf-8

Transfer-Encoding: chunked

Connection: keep-alive

Vary: Accept-Encoding

Status: 200 OK

X-Frame-Options: ALLOWALL

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, PUT, OPTIONS, DELETE, PATCH

Access-Control-Allow-Headers: origin, content-type, X-Requested-With

Access-Control-Max-Age: 1800

ETag: "1e836bde528ee9261659a977686b7134"

Cache-Control: max-age=0, private, must-revalidate

Set-Cookie: request_method=POST; path=/

X-Request-Id: 3311c533-1a13-4e1d-add5-fa255dc27fc1

234036

HTTP/1.1 400 Bad Request

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:29:13 GMT

Content-Type: text/html

Content-Length: 172

Connection: close

<html>

<head><title>400 Bad Request</title></head>

<center><h1>400 Bad Request</h1></center>

<hr><center>nginx/1.7.5</center>

</body>

</html>

Result: 234036

No RTCS error, should have worked?!?! waiting 15 seconds... .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2210 and time 1432056582

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2215 and time 1432056612

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2220 and time 1432056642

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2225 and time 1432056672

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2230 and time 1432056702

Got a value from the message queue, value: 2230, seconds: 1432056702, temperature: 69800

.. Attempting to send to thingspeak at time 1432056702 and reading 2230

Creating Body with 2 fields:

***Here is the message body ***

created_at=2015-5-19T17:31:42Z-3:00&field1=2.230&field2=69.800&status=Sending+by+sender+task.

Connected to b86a9995, port 80.

Write successful, we hope.

Received 963 bytes of data.

Here is the received message:

HTTP/1.1 200 OK

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:31:43 GMT

Content-Type: text/html; charset=utf-8

Transfer-Encoding: chunked

Connection: keep-alive

Vary: Accept-Encoding

Status: 200 OK

X-Frame-Options: ALLOWALL

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, PUT, OPTIONS, DELETE, PATCH

Access-Control-Allow-Headers: origin, content-type, X-Requested-With

Access-Control-Max-Age: 1800

ETag: "7538b7d1f86c053867820b6834d0d1c1"

Cache-Control: max-age=0, private, must-revalidate

Set-Cookie: request_method=POST; path=/

X-Request-Id: 7d0ba06f-2383-4570-8fbb-323d50a9fd22

234037

HTTP/1.1 400 Bad Request

Server: nginx/1.7.5

Date: Tue, 19 May 2015 17:31:43 GMT

Content-Type: text/html

Content-Length: 172

Connection: close

<html>

<head><title>400 Bad Request</title></head>

<center><h1>400 Bad Request</h1></center>

<hr><center>nginx/1.7.5</center>

</body>

</html>

Result: 234037

No RTCS error, should have worked?!?! waiting 15 seconds... .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 2238 and time 1432056732

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ..

I did have to modify your project C/C++ Build->Build Variables->PROJECT_KSDK_PATH from the older KSDK_1.1.0 to KSDK_1.2.0 and fix path to linker file. Is your application pointing to the correct KSDK?

Regards,

David

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

daveedwards — Tue, 19 May 2015 18:18:06 GMT

Hi Sean,

Change in behaviour might be down to KDS2 versus KDS3 differences - they use different versions of the GNU tools and Newlib/Newlib Nano libraries.

Newlib Nano in KDS3 uses less RAM (statically at least, it does some dynamic allocation). Part of the saving is achieved by having no IO buffers. In KDS2 the Nano configuration still had some buffering - this might explain the strange interleaving effects you reported.

Is your project configured to use Newlib Nano or full Newlib?

Both libraries also allow you to make them thread-safe. This is RTOS-specific so you would need to use a recursive mutex (or MQX equivalent) in conjunction with the Newlib/Nano thread safe hooks.

Hope this is useful.

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

ironsean — Tue, 19 May 2015 18:27:21 GMT

Hi David, I see the same garbled, weird behaviour there:
"Starting Sonar task...Sonar task started suIc

cneSsisoftunlilayl.ri

ztasik rnunnging

Isnittialaizicng kmes sagoe qfueu es.s..i

CAzn ReX t ask1 st2art0ed suc

ces*sfu~lly*.

~*~*~*~*~*~*~*~*~*~*~"

Also, I am using the correct KSDK_PATH. The reason you had to change it is my project is defined relative to the KSDK_PATH Environment variable, which KSDK 1.2.0 doesn't set by default. I manually changed the variable to point to the correct KSDK location.

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

DavidS — Tue, 19 May 2015 19:07:11 GMT

Hi Sean,

Ok...good to know you are pointing to correct KSDK.

Please make following change to your small_ram_config.h header:

** NIO serial settings

#ifndef NIO_SERIAL_BUFF_SIZE

#define NIO_SERIAL_BUFF_SIZE 256 //DES was 64

#endif

#endif /* __small_ram_config_h__ */

After re-compiling your application and running it I get the following:

Serial port COM5 opened

.. .. .. .. .. .. .. .. Main task has started.

Config loaded, configID is 10 and the errors were 0.

Config from Defaults loaded.

Starting Error Log task...

Config loaded, configID is 10 and the errors were 0.

Error loading SDCARD config.

MAC: 0:0:5e:a0:0:e1

Attempting to bind an IP via DHCP...(60s timeout)

DHCP bind successful.

Current IP info:

IP Address : 10.0.1.183

Subnet Address : 255.255.255.0

Initializing message queues...

Starting Sender task...Sender task started successfully.

Starting Sonar task...Sonar task started successfully.

Sonar task running

Initializing message queues...

CAn RX task started successfully.

Initilizing stack of size 120

*~*~*~*~*~*~*~*~*~*~*~*~

Time to wake Socket ManSocket man powering up.

socket man a go

Socketman should be awake now.

*~~*~*~*~*~*~*~*~*~~*~*~*

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 3151 and time 1432062166

Got a value from the message queue, value: 3151, seconds: 1432062166, temperature: 69900

.. Attempting to send to thingspeak at time 1432062166 and reading 3151

Creating Body with 2 fields:

***Here is the message body ***

created_at=2015-5-19T19:2:46Z-3:00&field1=3.151&field2=69.900&status=Sending+by+sender+task.

Connected to b86a9995, port 80.

Write successful, we hope.

Received 958 bytes of data.

Here is the received message:

HTTP/1.1 200 OK

Server: nginx/1.7.5

Date: Tue, 19 May 2015 19:02:46 GMT

Content-Type: text/html; charset=utf-8

Transfer-Encoding: chunked

Connection: keep-alive

Vary: Accept-Encoding

Status: 200 OK

X-Frame-Options: ALLOWALL

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, PUT, OPTIONS, DELETE, PATCH

Access-Control-Allow-Headers: origin, content-type, X-Requested-With

Access-Control-Max-Age: 1800

ETag: "cfcd208495d565ef66e7dff9f98764da"

Cache-Control: max-age=0, private, must-revalidate

Set-Cookie: request_method=POST; path=/

X-Request-Id: 17a78006-02b6-4399-9b8f-26584123e842

HTTP/1.1 400 Bad Request

Server: nginx/1.7.5

Date: Tue, 19 May 2015 19:02:46 GMT

Content-Type: text/html

Content-Length: 172

Connection: close

<html>

<head><title>400 Bad Request</title></head>

<center><h1>400 Bad Request</h1></center>

<hr><center>nginx/1.7.5</center>

</body>

</html>

Result: 0

thingspeak returned status 0, did not save, returning error.

Error, processResponse() failed with error code 1704

Error, receiveFromThingSpeak() failed with error code 1704

RTCS error, putting back on stack

.. Attempting to send to thingspeak at time 1432062166 and reading 3151

Creating Body with 2 fields:

***Here is the message body ***

created_at=2015-5-19T19:2:46Z-3:00&field1=3.151&field2=69.900&status=Sending+by+sender+task.

Connected to b86a9995, port 80.

Write successful, we hope.

Received 963 bytes of data.

Here is the received message:

HTTP/1.1 200 OK

Server: nginx/1.7.5

Date: Tue, 19 May 2015 19:02:48 GMT

Content-Type: text/html; charset=utf-8

Transfer-Encoding: chunked

Connection: keep-alive

Vary: Accept-Encoding

Status: 200 OK

X-Frame-Options: ALLOWALL

Access-Control-Allow-Origin: *

Access-Control-Allow-Methods: GET, POST, PUT, OPTIONS, DELETE, PATCH

Access-Control-Allow-Headers: origin, content-type, X-Requested-With

Access-Control-Max-Age: 1800

ETag: "5103750b5ef0ce6f80c2892669f44f34"

Cache-Control: max-age=0, private, must-revalidate

Set-Cookie: request_method=POST; path=/

X-Request-Id: a5c2301c-81c8-40b5-a662-fe87b44f1620

234052

HTTP/1.1 400 Bad Request

Server: nginx/1.7.5

Date: Tue, 19 May 2015 19:02:48 GMT

Content-Type: text/html

Content-Length: 172

Connection: close

<html>

<head><title>400 Bad Request</title></head>

<center><h1>400 Bad Request</h1></center>

<hr><center>nginx/1.7.5</center>

</body>

</html>

Result: 234052

No RTCS error, should have worked?!?! waiting 15 seconds... .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Emulated sensor with reading 3164 and time 1432062196

.. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ..

Regards,

David

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

ironsean — Tue, 19 May 2015 19:10:41 GMT

I'm not positive, but I believe it was using full Newlib, I switched the linker settings to check the "Use newlib-nano" option and the output does not appear to differ. However, my code seems to be running a bit more stable as it's not ceasing without reason like it has been before.

The change in newlib and removal of the output buffers could explain this behaviour, if the output is now getting buffered or processed at some later stage instead of being placed in the buffer before the code moves onto the next statement of execution. This is a bit stranger as far as execution and debugging goes, but output printf output is only for debugging purposes so it may be fine now that I can feel safe it's not indicative of worse underlying problems.

Sean

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

ironsean — Tue, 19 May 2015 19:48:54 GMT

Excellent, that does fix the output jumbling right up. It still doesn't explain why the output lags behind the debugger (it used to be if I stepped past a printf() line it would completely print before the debugger paused at the next breakpoint) but the output is no longer interleaved in the same way. It also doesn't seem to affect some unhandled interrupt errors I'm getting, so I'll keep testing and reading about some of those other issues.

Sean

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

DavidS — Tue, 19 May 2015 20:02:15 GMT

Hi Sean,

The UART is being used in interrupt mode and therefore once the UART transmit buffer is full, the remainder of the printf() string is placed into the UART driver software buffer/fifo. The UART interrupt driver handles pushing the rest out while your code continues to run (i.e. the printf is non-blocking).

In debugger step mode the interrupt process is paused.

Regards,

David

Re: Garbled printf(), multiple tasks printing at once. Why is this output overlapping? KSDK 1.2

rajbatra — Thu, 21 Jan 2016 01:48:36 GMT

Hi Dave,

So I'm confused about the fix. If printf isn't thread safe, how can increasing the buffer size fix the garble?

Thanks,

-Raj