This shouldn't break, is my BLE unstable?

[Michael0123456]

I happened to write some debug log code that broke my Bluetooth.  I don't think it should be doing that.  When I burrow into the logging, I don't see why this difference is important.  I haven't been able to burrow into the BLE, so I don't know what is going on there.

This project (for historical reasons) is nrf5 SDK and starts from the sample HID keyboard.
nRF5_SDK_17.1.0\examples\ble_peripheral\ble_app_hids_keyboard

This code is in my main.  With the first block, everything is as expected EXCEPT my device doesn't show up anymore when I try to attach using Windows.  In the other two cases everything is fine.  In my mind, all I'm doing is putting out a debug log string one or more times.  The case that breaks has the debug log statement in a loop with the same string pointer.  The logging always works fine (I'm using Segger RTT).  It is the Bluetooth that comes and goes!  I don't see any indication of a problem in the logging--other than sometimes when I use the Segger JLink to halt, I see a message about a SoftDevice assert, but it isn't correlated with the behavior run time.

This makes me think that either a) the Bluetooth code is really unstable and needs to be fixed, or b) there is something in the sample HID keyboard that is really bad (but it came that way from GitHub).  At this point I'm totally confounded as to what it might be.  (I know there is something about buffer alignment going into the "SoftDevice," or something, and that is why I tried options to try to make the memory map be identical.  Seems like it is a run time thing.)

int main(void)
{
    bool erase_bonds;
//    int i;

        sd_power_dcdc_mode_set(NRF_POWER_DCDC_ENABLE);
    nrf_power_dcdcen_set(true);
    
    // Initialize.
    log_init();
    timers_init();
//    buttons_leds_init(&erase_bonds);
    power_management_init();
    ble_stack_init();
    scheduler_init();
    gap_params_init();
    gatt_init();
    advertising_init();
    services_init();
    sensor_simulator_init();
    conn_params_init();
    buffer_init();
    peer_manager_init();

#ifdef DEBUG
    NRF_LOG_INFO("DEBUG is defined");
#endif

    // Start execution.
//    NRF_LOG_INFO("HID Keyboard example started.");

#define DONT_RUN_ME_I_BREAK (true)
#ifdef DONT_RUN_ME_I_BREAK
    char * startStr = "====================================HID Keyboard example started===================================";
    int i;
    i = 0;
    while (i < 2) {
        NRF_LOG_INFO(startStr);
        i++;
    }
    NRF_LOG_FLUSH();
#endif

//#define RUN_ME_I_WORK (true)
#ifdef RUN_ME_I_WORK
    char * startStr = "====================================HID Keyboard example started===================================";
    int i;
    i = 0;
    while (i < 1) {
        NRF_LOG_INFO(startStr);
        i++;
    }
    NRF_LOG_FLUSH();
#endif

//#define RUN_ME_I_ALSO_WORK (true)
#ifdef RUN_ME_I_ALSO_WORK
    char * startStr = "====================================HID Keyboard example started===================================";
    int i;
    i = 0;
    while (i < 1) {
        NRF_LOG_INFO(startStr);
        NRF_LOG_INFO(startStr);
        i++;
    }
    NRF_LOG_FLUSH();
#endif

//#define RUN_ME_I_WORK (true)
//#ifdef RUN_ME_I_WORK
//    char * startStr = "====================================HID Keyboard example started===================================";
//    NRF_LOG_INFO(startStr);
//    NRF_LOG_INFO(startStr);
//    NRF_LOG_INFO(startStr);
//    NRF_LOG_INFO(startStr);
//    NRF_LOG_INFO(startStr);
//    NRF_LOG_INFO(startStr);
//    NRF_LOG_INFO(startStr);
//    NRF_LOG_INFO(startStr);
//    NRF_LOG_FLUSH();
//#endif

//    hardfault_genhf_invalid_fp();

    // Start init state
        func_main_init_status();        
        
    timers_start();
    advertising_start(erase_bonds);
        
        // Start state machine timer
        func_main_state_tmr_create();
        
    // Enter main loop.
    for (;;)
    {
        idle_state_handle();
                func_main_state_machine_loop();
    }
}

[Michael0123456]

The AI answer makes sense.  Sending a pointer (potentially to RAM) into the logging system can affect its behavior.  Sure.  But I'd like my code to be fixed, not just accidentally run.

If there is a critical timing relationship among the initialization calls in my main, why is there no information about it in the initialization code?  How come I can log the string 8 times with the literal in the macro but not even twice with an actual pointer.  I CAN log it once with the regular pointer, so that by itself is apparently not a problem.  How much delay can be tolerated?  What if I have some other high priority initialization going on that causes delay?  (And the logging always works, it is the BLE that breaks.  That makes me think the problem is in the BLE code.)

EDIT:  I forgot about the case where I'm logging with the regular pointer, but I make calls each on their own line, and it works.  Even if I log the line 8 times!  What I can't do is log from within a loop (unless the loop only runs once).  It is a true mystery...

[Turbo J]

Its probably just a stack overflow.

I believe all those string constants will end up on the stack - they are not declared const.  And the old SDK has zero stack overflow handling - overflowing stack can silently corrupt (overwrite) other data.

There is a reason why we don't recommend this for new designs.

Another cause could be RTT. By default is set up to throw away log messages when they don't fit in the log buffers, but you might have changed that in the past and forgot about it.

Does the compiler moan about erase_bonds? I don't see an initial value for this variable. Bond erasing behaviour could be random across compiler runs here.

[Michael0123456]

These are some good ideas, but at this point I'm thinking it is just the way the advertising works (or doesn't).

I was trying to measure delays around the logging and found that at the exact point in the code I'm doing that logging, clocks are starting up.That in and of itself is weird because I would think a lot of stuff that the code is starting up is going to be using clocking, and so there ought to be a point where everybody knows the clocks are working, and not try to use them before they are.  But anyway, while I was doing that I noticed I was getting some different messages from the advertising code, depending on changes in the amount of delay from the logging.

That seems wrong to me.  And it also seems wrong that the code can easily go into an advertising mode where Windows ignores it.  But obviously I didn't have any say in how the advertising was written, and I don't know anything about how to advertise "properly" for Windows.  (I admit, I was hoping to learn that from code in the SDK, but people in hell want ice water...)

I did notice that advertising_start() runs right after the logging I'm doing.  So my strong suspicion is that one or more threads that are started because of the logging are affecting the way the advertising starts up.  (And probably shouldn't, but, you know, bugs and stuff.  Like, is the clock running?  Sure, I think so, we need to create some known delays here, etc.)

I certainly don't suspect stack overflow or any other kind of corruption.  There are no error messages, no indication of a crash.  All the code I'm involved with at this point does what I expect without complaint (mostly a heartbeat into the log in the case where I can't connect it, but I think the advertising changes to slow after a while like it normally does).  The only symptom I know of at this point is it doesn't show up in Windows as a device to connect to.  And as I said, I think there are some changes to what the log says about the advertising.  But I'm just barely starting to look at that.  I think I read much of the Bluetooth is actually in the "Soft Device" code and I have no idea how to get logging from that.  (I generally can't even find the code that might be running.)  The first thing I have to figure out is what it does when it works.  Then figure out why it is doing something different.

I'm sure there is another issue with the advertising and connection because when I reboot the device (after having it connected, when it works) it shows in Windows as toggling back and forth between connected and paired.  (My assumption is it would either connect without any intervention, or it would wait for me to connect it, not crash in this way where I have to disconnect it and then reboot it again.)  So I know there is work to do there.

You mentioned erase_bonds.  I don't see any indication of a problem.  But I can only say I started from the SDK.  I don't know what is correct other than that.  Anyway, there are zero compile time warnings.  And zero run time errors reported that seem to have anything to do with the issue.  (Like I say, sometimes it puts up a message if I halt it from the JLink.)  I admit, I don't know what would be logged by this code at this point, since I haven't seen any of the messages of the type we might hope for.

Anyway, thanks for your time and thoughts.

PS.  As far as the string constants.  Note that the whole point of the code I wrote initially was that there was one string and I logged it from within a loop.  If that by itself was a problem it would be a problem when I run the loop one time.  And it isn't a problem then.  It is only a problem when I run the loop two or more times.  (Or, I should say, I only see the problem.  I can't say that the code that is breaking is working reliably with any logging code including what I checked out of GitLab, just that I see it work regularly.)  Changing the loop count limit definitely doesn't take any more space in any memory, stack or otherwise.  The "lazy" code just cuts and pastes the log statement with the string in it.  I suspect the compiler wouldn't notice the string is reusable, so it WOULD exist in memory multiple times.  In later testing I also got a change in behavior by doing the lazy cut and paste, which brought me to this post.  Not to mention this code probably uses a tiny fraction of the stack available to it.  At least I hope so, since it isn't really doing anything yet, and does as close to nothing as it ever would before it is connected.

That said, it probably is a good explanation for how the changes would be changing the delays of the logging executing.  If the string is in ROM or RAM, for example.  (Although I kind of feel like given the code that is there, I should be able to insert any delay I want there and it should still work, no?)