›

Logging problems

jamaloyesjamaloyes
edited January 2017 in Android
Hi.

I'm developing an Android app that have to log Temperature and Accelerometer data. I have started by successfully streaming data from the Temperature sensor to get familiar with the steps of scanning, connection, route configuration and message handling.

Then I tried with logging, but I'm facing some problems.
- The download handler is working since I can see how the download progress reaches 0. However, there are way more entries downloaded than I expected: thousands of entries when I only expected an amount in the order of tens (2 seconds rate). In some occasions, it reaches 0 and keeps writing the last download progress message forever.
- The message handler for the logged data was never executed. So I tried what you suggested in some posts, to override receivedUnhandledLogEntry and receivedUnknownLogEntry. Finally I could see my temperature data in the receivedUnhandledLogEntry and a bunch of dozens of data (not like thousands) through receivedUnknownLogEntry.
- setLogMessageHandler always returns false. Both, when I call the setLogMessageHandler after comitting the route in the completion handler and when I call it in my download method (routemanager id stored and retrieved from sharedpreferences as in the github apps).

What I have tried:
- Reseting the device (via my app, metawear apps and removing battery).
- Remove routes (via routemanager and removeRoutes() board method).
- Tried API 2.5.9, 2.6.5, 2.8.6, 2.8.8
- Logging with Metawear apps: only app MetaBase works as expected and returns data (Temperature, 1s), although a few times I just got the CSV header with no data despite the download proccess took ~40s.

Additional info:
- My board is a model C r0.2, firmware 1.2.5 (firmware version via MetaWear app)
- Route configured for sensor MetaWearProChannel.ON_BOARD_THERMISTOR.
- Streaming is working
- Android SDK version 25

Comments

  • jamaloyesjamaloyes
        private final RouteManager.MessageHandler loggingMessageHandler =  new RouteManager.MessageHandler() {
            @Override
            public void process(Message msg) {
                Log.i(TAG, String.format("Temp: %.2fC",msg.getData(Float.class)));
            }
        };
        private AsyncOperation.CompletionHandler<RouteManager> temperaturaHandler= new AsyncOperation.CompletionHandler<RouteManager>() {
            @Override
            public void success(RouteManager result) {
                result.setLogMessageHandler("temp_log", new RouteManager.MessageHandler() {
                    @Override
                    public void process(Message msg) {
                        Log.i(TAG, String.format("Temp: %.2fC",msg.getData(Float.class)));
                    }
                });

                _editor.putInt(TAG + "_log_id", result.id());
                _editor.apply();
                _editor.commit();

                timerModule.scheduleTask(new Timer.Task() {
                    @Override
                    public void commands() {
                        tempModule.readTemperature(source);
                    }
                }, TEMP_SAMPLE_PERIOD, false).onComplete(new AsyncOperation.CompletionHandler<Timer.Controller>() {
                    @Override
                    public void success(Timer.Controller result) {
                        result.start();
                    }
                });
            }

            @Override
            public void failure(Throwable error) {
                Log.e(TAG, "Error committing route", error);
            }
        };

        public void setup(MetaWearBoard board, SharedPreferences preferences) throws UnsupportedModuleException {
            pref = preferences;
            _editor = pref.edit();
            if (!mInitialized) {
                timerModule= board.getModule(Timer.class);
                loggingModule = board.getModule(Logging.class);
                tempModule= (MultiChannelTemperature) board.getModule(Temperature.class);
                source = tempModule.getSources().get(MultiChannelTemperature.MetaWearProChannel.ON_BOARD_THERMISTOR);
                tempModule.routeData()
                        .fromSource(source)
                        .log(LOG_KEY)
                        .commit()
                        .onComplete(temperaturaHandler);

                mInitialized = true;
            }
        }
        public boolean start(){
            boolean result = true;
            if (mInitialized) {
                loggingModule.startLogging(true);
            }
            else {
                result = false;
            }

            return result;
        }

        public void stop(){
            loggingModule.stopLogging();

            if(timerModule != null)
                timerModule.removeTimers();

            mInitialized = false;
        }

  • jamaloyesjamaloyes
        public void downloadLog(final MetaWearBoard mwBoard){
            final RouteManager route = mwBoard.getRouteManager(pref.getInt(TAG + "_log_id", 0));
            Log.i(TAG, String.format("Routemanager restored ID: %d",route.id()));
            route.setLogMessageHandler("temp_log", loggingMessageHandler);

            loggingModule.downloadLog(0.10f, new Logging.DownloadHandler() {
                @Override
                public void onProgressUpdate(int nEntriesLeft, int totalEntries) {
                    Log.i(TAG, String.format("Temp. Log Progress= %d / %d", nEntriesLeft, totalEntries));

                    if(nEntriesLeft == 0) {
                        loggingModule.clearEntries();
                        route.remove();
                    }
                }

                @Override
                public void receivedUnhandledLogEntry(Message logMessage) {
                    super.receivedUnhandledLogEntry(logMessage);
                    Log.e(TAG, String.format("Temp. receivedUnhandledLogEntry %s %.2fC",
                            logMessage.toString(),logMessage.getData(Float.class)));
                }

                @Override
                public void receivedUnknownLogEntry(byte logId, Calendar timestamp, byte[] data) {
                    super.receivedUnknownLogEntry(logId, timestamp, data);
                    String s = new String(data);
                    Log.e(TAG, String.format("Temp. receivedUnknownLogEntry %s",s));
                }
            });
            Log.i(TAG, "Log size: " + loggingModule.getLogCapacity());
        }
  • EricEric
    edited January 2017
    • What is the value of LOG_KEY? Is it the same value as the string passed into setLogMessageHandler
    • Remove the call to clearEntries from the download handler
  • jamaloyesjamaloyes
    Hi Eric.

    Thank you, the LOG_KEY mistake was the culprit of my problems with setLogMessageHandler. I have also remove the call to clearEntries from the download handler. Now I'm able to retrieve the logged temperature.
    However, I'm still facing the issue of having way more entries downloaded than expected. So I prepared a setup to nail the problem down:
    - After connecting to the selected board, I call removeRoutes(), clearEntries() and resetAfterGarbageCollect() and then reconnect to it.
    - Within the same debugging session of my app, I sequentially started and stopped at least 4 temperature logging.

    By reviewing the Log.i messages I placed, I found that something weird is happening for route managers with IDs 0 and 1:
    - The Log.i messages when downloading data for Routemanager with ID 0 show (at least a couple of) thousands of data, although I'm capturing temperature sensor data at a 2 seconds rate for less than 1 minute. Only my data is going through my message handler.
    - The Log.i messages when downloading data for Routemanager with ID 1 show houndreds of data, but now all data is going through my message handler. Weird temperature data shows a ~40ms logging rate.
    - Afterwards, no more additional data is found when downloading.

    Hope you can shed some light on this issue and how to solve it.
  • jamaloyesjamaloyes
    edited January 2017
    Log.i messages (I/Logger connected: SETUP COMPLETED marks the start of each logging attempt):

    I/Logger connected: SETUP COMPLETED I/TemperaturaLogger: Log started I/Logging started:: true I/TemperaturaLogger: Log Handler set1: true I/TemperaturaLogger: Routemanager ID: 0 I/TemperaturaLogger: Log stopped I/TemperaturaLogger: Routemanager restored ID: 0 I/TemperaturaLogger: Log Handler set2: true I/TemperaturaLogger: Log size: 10624 I/Logging: stopped I/TemperaturaLogger: Temp. Log Progress= 1587 / 1764 I/TemperaturaLogger: Temp. Log Progress= 1411 / 1764 I/TemperaturaLogger: Temp. Log Progress= 1235 / 1764 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:29:46.748 I/TemperaturaLogger: Temp. Log Progress= 1059 / 1764 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:29:48.749 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:29:50.748 I/TemperaturaLogger: Temp. Log Progress= 883 / 1764 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:29:52.749 I/TemperaturaLogger: Temp. Log Progress= 707 / 1764 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:29:54.749 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:29:56.750 I/TemperaturaLogger: Temp. Log Progress= 531 / 1764 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:29:58.749 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:00.750 I/TemperaturaLogger: Temp. Log Progress= 355 / 1764 I/TemperaturaLogger: Temp: 19,62C 2017-01-28T12:30:02.750 I/TemperaturaLogger: Temp. Log Progress= 179 / 1764 I/TemperaturaLogger: Temp: 23,38C 2017-01-28T12:30:04.751 I/TemperaturaLogger: Temp: 22,25C 2017-01-28T12:30:06.750 I/TemperaturaLogger: Temp. Log Progress= 3 / 1764 I/TemperaturaLogger: Temp. Log Progress= 0 / 1764 I/Logger connected: SETUP COMPLETED I/TemperaturaLogger: Log started I/Logging started:: true I/TemperaturaLogger: Log Handler set1: true I/TemperaturaLogger: Routemanager ID: 1 I/TemperaturaLogger: Log stopped I/TemperaturaLogger: Routemanager restored ID: 1 I/TemperaturaLogger: Log Handler set2: true I/TemperaturaLogger: Log size: 10624 I/Logging: stopped I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.082 I/TemperaturaLogger: Temp: -0,25C 2017-01-28T12:30:08.121 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.161 I/TemperaturaLogger: Temp: -0,50C 2017-01-28T12:30:08.200 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.240 I/TemperaturaLogger: Temp: -0,50C 2017-01-28T12:30:08.281 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.320 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.360 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.399 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.443 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.479 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.520 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.559 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.599 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.638 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.678 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.717 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.758 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.798 I/TemperaturaLogger: Temp: -0,50C 2017-01-28T12:30:08.837 I/TemperaturaLogger: Temp: -0,50C 2017-01-28T12:30:08.877 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.917 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.956 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:08.997 I/TemperaturaLogger: Temp: -0,50C 2017-01-28T12:30:09.037 I/TemperaturaLogger: Temp. Log Progress= 458 / 509 I/TemperaturaLogger: Temp: -0,50C 2017-01-28T12:30:09.076 I/TemperaturaLogger: Temp: -0,50C 2017-01-28T12:30:09.116 --------------------------------------------------------- ---------- removed entries in order to post ------------- --------------------------------------------------------- I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:17.753 I/TemperaturaLogger: Temp: -0,50C 2017-01-28T12:30:17.792 I/TemperaturaLogger: Temp: -0,38C 2017-01-28T12:30:17.832 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:33.596 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:35.596 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:37.597 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:39.596 I/TemperaturaLogger: Temp: 19,50C 2017-01-28T12:30:41.597 I/TemperaturaLogger: Temp. Log Progress= 8 / 509 I/TemperaturaLogger: Temp: 19,50C 2017-01-28T12:30:43.597 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:45.598 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:47.597 I/TemperaturaLogger: Temp: 19,50C 2017-01-28T12:30:49.598 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:51.598 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:53.599 I/TemperaturaLogger: Temp: 19,50C 2017-01-28T12:30:55.600 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:30:57.599 I/TemperaturaLogger: Temp. Log Progress= 0 / 509 I/Logger connected: SETUP COMPLETED I/TemperaturaLogger: Log started I/Logging started:: true I/TemperaturaLogger: Log Handler set1: true I/TemperaturaLogger: Routemanager ID: 2 I/TemperaturaLogger: Log stopped I/TemperaturaLogger: Routemanager restored ID: 2 I/TemperaturaLogger: Log Handler set2: true I/TemperaturaLogger: Log size: 10624 I/Logging: stopped I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:32:53.118 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:32:55.118 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:32:57.117 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:32:59.118 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:01.118 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:03.119 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:05.118 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:07.119 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:09.119 I/TemperaturaLogger: Temp. Log Progress= 0 / 9 I/Logger connected: SETUP COMPLETED I/TemperaturaLogger: Log started I/Logging started:: true I/TemperaturaLogger: Log Handler set1: true I/TemperaturaLogger: Routemanager ID: 3 I/TemperaturaLogger: Log stopped I/TemperaturaLogger: Routemanager restored ID: 3 I/TemperaturaLogger: Log Handler set2: true I/TemperaturaLogger: Log size: 10624 I/Logging: stopped I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:51.617 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:53.616 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:55.617 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:57.617 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:33:59.618 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:34:01.619 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:34:03.618 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:34:05.619 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:34:07.619 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:34:09.620 I/TemperaturaLogger: Temp. Log Progress= 2 / 12 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:34:11.619 I/TemperaturaLogger: Temp: 19,38C 2017-01-28T12:34:13.620 I/TemperaturaLogger: Temp. Log Progress= 0 / 12
  • EricEric
    Why are there two route managers if you are only logging temperature?
  • jamaloyesjamaloyes
    In that setup I was creating and removing routes in each logging session: 4 sessions, 4 routes created/removed.
  • jamaloyesjamaloyes
    Hi Eric.

    Finally the problem has been found. There was at least one macro executing on boot that was generating the extra log entries, and I wasn't told about it. Anyway, it results confusing that the entries from the macro appeared as genuine log entries of one of my routes.

    Thank you for your help.
  • EricEric
    Good to hear everything is sorted out.  Out of curiosity, what was that macro doing?
  • jamaloyesjamaloyes
    edited January 2017
    I'm not sure. I just issued the eraseMacros() command and both unkown log entries and every ~40ms entries like -0,38C 2017-01-28T12:30:08.320 stopped appearing in my log. The board is from a customer and he didn't tell us they put a macro on the board.

    Is there any reason for those entries going into my log and being treated as a genuine entry of my route?

  • EricEric
    Hm, that is a good question.  Since we don't know what the macro is, it's difficult to say.  It looks like the macro was enabling the accelerometer at 25Hz given the 40ms time offsets however that is something that we'd need more information in order to properly investigate.
This discussion has been closed.