Logs

From SpinetiX Support Wiki

Jump to: navigation, search

Introduction

The HMP includes a logging system that records every event that occurs during its functioning. Multiple log files are being used simultaneously, from general logs that record information about the content rendering and network activity, to complex ones generated by the player operating system.

This page is about the general logs, since they are directly accessible to the user for assessing performance and troubleshooting.


Note Note: In case of player problems, is important to generate and send a report (not any of the individual log files!) to SpinetiX Support as it contains all the player log files and, thus, is crucial for analysis of problems.

Getting the general logs

The HMP general log files can be accessed in few different ways:

Logs maintenance

  • The HMP logs are rotated on a regular basis (every 24h) to avoid having very large log files and to keep them well structured by days.
  • The current day logs are kept as .log file (e.g. info.log, warn.log etc.) - you can find them under "Current Logs" section (except for the accounting.log).
  • The logs from the previous 7 days are also kept, as numbered archives (e.g. info.1.log.gz, info.2.log.gz etc.) - you can find them under "Backup Logs" section (except for the accounting logs archives). The log files older than 7 days are automatically deleted.
  • The logs maintenance (e.g. rotation and clean-up) is done every day at midnight, therefore it's important to keep the HMP powered on overnight. If the HMP is not ON at that time, the information from multiple days will start to accumulate into the same log file and this can have negative effects of the player performance.

Note that manual clearing of logs can be done from the Operations page (respectively Maintenance page on older models), but that should only be done when advised by SpinetiX Support.

Logs page

From the "Logs" page of HMP Control Center, you can access several high-level logs of the HMP, grouped into three sections:

  • Accounting Logs
    Lists the logs containing the information needed for prof of play / accounting, from current day and the archived logs of the last seven days.
  • Current Logs
    Lists the logs from the current day* in plain text format. See more information about these logs further down.
    *Actually more than one day on logs could be present if the player could not performed the logs maintenance (i.e. it was turned off over the night).
  • Backup Logs
    Lists the logs from the previous 7 days (during normal functioning), compressed to save storage on the unit.

The size of the log file and the writing date are also provided.

On HMP200, HMP130 and HMP100, there is a fourth section, "Troubleshooting" which allows generating a full report (by clicking on the "Get Report" button).

Reading the logs

General logs

accounting.log

See Accounting page for more details about this log.

player.log

This log file was introduced in 3.1.0 release and it practically includes the information that before was contained in different log files: info.log, javascript.log, resources.log, and warn.log. Furthermore, the syntax of the performance counters has been redesigned to include CPU performance and FPS drop.

A line containing the performance counters of the player is added every second during the first 20 seconds upon content restart, then every 10 seconds during the first 5 minutes, and finally every minute afterwards. The typical log entry has the following format:

  • dd-mm-yyyy hh:mm:ss INFO spx.stats - rendering_time
    The date and time, the level and the logger for this line, followed by the the rendering time upon content restart (due to a player restart, a publish or a pull action).
  • Period: n_seconds
    The time duration in seconds (e.g., 1s, 10s, 60s) used for aggregation.
  • Pic: n_frames
    The number of frames rendered within the aggregation period. If this is equal to (freq * n_seconds), where freq is the output frequency (e.g., 60Hz (i.e. 60 frames per seconds), 50Hz), then the HMP has no problem rendering the content; a lower number means that some frames were dropped.
  • Usage: n% ( arm | dsp ) (w1s/ w10s/ w60s)
    The resource usage in percentage. In first set of parentheses, the values for ARM and DSP components. In the second set of parentheses, the worst cases (see details below).
  • Peak: n_ms
    The number of milliseconds that the longest frame took to render - this should be below the maximum rendering latency to ensure that no frames are dropped; a larger number means that something took a lot of time to be opened or rendered.
  • Buffers: n_ms (min n_ms)
    The average duration (in milliseconds) of the available buffers. In parentheses, the minimum value for available buffers.
  • FPS Drop: 0% (w1s/ w10s/ w60s)
    The percentage of frames dropped because the rendering speed (FPS) has been reduced. In parentheses, the worst cases (see details below).
  • Peak drop: 0% (w1s/ w10s/ w60s)
    The percentage of frames dropped because of peak rendering. In parentheses, the worst cases (see details below).

Note Note: (w1s/ w10s/ w60s) represents the values calculated for the worst case for any 1s, respectively 10s period within the current aggregation period, while the last value is the worst case for any 60s period from the beginning of the rendering time.

Example:

22-03-2015 16:36:21 INFO spx.stats - 0:10:00 Period: 60s Pic: 2970 Usage: 22% ( 16| 71) (121/ 29/ 26) Peak: 286ms Buffers: 514ms (min 20ms) FPS Drop: 0% ( 28/ 5/ 1) Peak drop: 0% ( 4/ 0/ 6)

uploader.log

This is where operations pertaining to Pull Mode are logged, including both download of projects to the player and upload of logs to a remote server.

Common errors:

  • The following error is characteristic of the server responding to the WebDAV PROPFIND request with an HTML page instead of the actual data.
    File  Line X Column XX 'Opening and ending tag mismatch: META line X and head' (Domain 1 Code 76)
    This could happen because the server is overloaded and returning an HTML page with a warning. Cross-reference the uploader.log file with your server logs to trace what happened.
  • When using a remote ics file to control the Pull Mode, if that file cannot be retrieved by the HMP because of the proxy or the remote web server itself, the following error will be present in the log:
    Bad request : 'http://[path_to_ics_file]/[filename.ics]' -> 403: Forbidden
    • In the first case, the proxy is not allowing the ics type of file to pass or it doesn't allow calls to the remote server.
    • In the second case, the server might not permit requests from that proxy.
    • To troubleshoot this, try to retrieve that file with a browser using the same proxy configuration and from a PC in the same network as the HMP. You could also use a network traffic monitoring tool or contact the administrator of the proxy.

Deprecated logs

These logs were merged into player.log starting with 3.1.0 release.

info.log

The info log main purpose is to keep a real-time "heartbeat" record of the HMP performance. A log entry is added every 10s during the first 5 minutes of playing, and then one entry every minute.

Example log line:

10-12-2010 14:00:31 INFO spx.display.render - Render: 0:00:20 Nb Pic: 600 in 10ms ( 11ms) Max: 30ms Buffers: 62.7 (min 61) Factor: 1-1
  • 10-12-2010 14:00:31: Date and time of entry;
  • spx.display.render: Component of the player related to the log (mostly the renderer);
  • Render: 0:00:20: Player has been rendering 20s of content since the beginning.
  • Nb Pic: 600: The player has rendered 600 pictures since the last log entry.
    • When the output set at 60Hz, the HMP is functioning normally if this number is 600 during the first 5 minutes (when there's a log entry at every 10 seconds) and 3600 thereafter (when there's a log entry at every one minute). When the output set at 50Hz, the values are 500, respectively 3000.
    • A lower number means some frame were dropped - this is also reflected in the factor entry.
  • in 10ms ( 11ms): Average rendering time per frame. This should be below 16ms for optimal rendering at 60fps and below 20ms for 50fps.
    • A large number here means that the content is "difficult" to render and might shutter when displayed on the screen.
    • The number in brackets should be ignored.
  • Max: 30ms: The time the longest frame took to render. This should be below the maximum rendering latency to ensure that no frames are dropped. A larger number here means that a document took a lot of time to be opened.
  • Buffers: 62.7: On average, 62.7 buffer were used (a larger number is better). The maximum number of buffers depends on the resolution of the screen.
  • (min 61): The lowest level of the buffer since the last entry. A number bellow 4 means that some frames were drop. The larger number is better.
  • Factor: 1-1: The lowest and highest factor of the framerate (in this case, 60fps and 60fps). A number larger than 1 means that the player had to drop to a lower framerate to keep up with the rendering.
    • For instance 1-2 would mean that the player dropped to 30fps for some, but not all of the time since the last entry.
    • Some content (e.g. tickers) need a constant 60fps framerate to appear smooth.

Common errors:

  • No memory info messages:
    INFO  spx.display.framebuffer - No Memory : FBIO_POST_SWAP_CHAIN_SLOT no free slots
    These are appearing when changing some settings (that are not triggering a restart) or generating a report. They can safely be ignored.

javascript.log

Contains any errors generated by the JavaScript code within the project running on the HMP.

  • You can write to the javascript.log file using standard JavaScript alert() calls.
  • To change the global logging level, use the logAtLevel() method.

resources.log

This log contains information about each resource played by the HMP, along with the date and time when it started. It can also include extra details about the video / audio streams inside the media, redirects, unsupported media etc.

The typical message that is added when a resource starts to play, has this format:
dd-mm-yyyy hh:mm:ss INFO spx.resource.media   - New Resource 'URI' [flags] (dlc/tcd)
  • URI is starting with spx://localserver/ for local resources and with http(s):// for the external ones.
  • [flags] ([PCIC]) have the following meaning:
    P = PHP processing is done (i.e. the resource is .php).
    C = the caching mechanism is used for this resource (i.e. the resource is not local), but not necessarily that the resource is currently being played from cache.
    I = iCal processing is done (i.e. the resource is .ics).
    C = the resource is currently cached. (added in firmware 3.0).
    This flag is used in combination with the first C flag (i.e. [ C C]) and followed by the caching information (dlc/tcd).
  • (dlc/tcd) means "duration left in cache" from "total cache duration". (added in firmware 3.0)
    • dlc ("duration left in cache") can be either a number (of seconds) <= tcd or the string "----" meaning that the resource will be retrieved from the server.
    • tcd ("total cache duration") can be between 10s and 3600s.

Note: The last 'C' char may be replaced by a '0' (i.e. [ C 0]), indicating that the cache mechanism is used for asynchronous retrieval, but that the resource is NOT cached. It will be retrieved each time it is needed by the player. In this case the (dlc/tcd) is not present.

If a resource is being played continuously in a loop, the above line is added only once at starting time. Nevertheless, in case of a media resource, one or more lines will be added each time the media is restarting - for instance:

date INFO spx.svglib.media - video H.264, 1920x1080  (16:9) 29.97 fps Main profile Level 4.0 NRF=1 MDFB=2
date INFO spx.svglib.media     - Found media stream: audio AAC, 48000Hz stereo
date INFO spx.svglib.media.ffmpeg - [wmv3 @ 0x405bfa30]Extra data: 8 bits left, value: 0

Common errors:

  • Unsupported media stream:
    Unsupported media stream: ffmpeg codec id=0
    If your video/audio file is not playing correctly then check the encoding settings on the Video encoding page. If your video is playing as expected and you still see this error in the logs, then it can safely be ignored; the player is discarding the streams it does not handle, such as subtitles and metadata.
  • Server or proxy hostname lookup failed:
    Server or proxy hostname lookup failed : '[requested_file_url]' -> Could not resolve hostname `[proxy_server]': Host not found
    HMP cannot connect to the Internet - check if you have correctly entered the proxy details.
  • Object Not Found:
    File not found : 'project://AutoServer0-4/index.svg' -> 404: Object Not Found
    The "Autoserver" source (followed by a number) represents a remote network path. If you see this error then you will usually be using Client/Server mode but you have specified the server source incorrectly. Check the source is a directory path, and not a file.
  • Stream demuxing failed:
    WARN  spx.svglib.media - Stream demuxing failed because more than 1048576 bytes of buffering is required
    This is the result of a non-optimal multiplexing of the audio and video streams that requires more than 1 MB (respectively 3 MB in case of streaming media) of buffering of the audio or video stream in order to keep it in sync with the other. The solution is to re-multiplex the audio and the video streams using a software that creates correct multiplexing, like FFMpeg.
  • SSL certificate verification failed:
    HTTP Error : Command: GET on 'https://...' -> 0: Server certificate verification failed: issuer is not trusted
    The HMP could not verify the SSL certification for the resource URL and thus the resource is not loaded. Try using http or manually add the missing certificate on the HMP.

warn.log

This log contains the device's starting events and, whenever possible, the stopping events.

A regular starting event contains the following information:

  • date and time;
  • HMP firmware version;
  • starting flags.
    • When the player boots into safe mode, the -safemode flag is added.

Example log line:

date time WARN spx.player - SpinetiX Hyper Media Player version 'Jungfrau 2.2.5-1.0.16095' started with : '/usr/bin/raperca -daemon'

The "Stopping player" event is written into the log whenever is possible - when the restart is triggered by:

Note: Not all the stopping events can be logged - for example is not possible to log powering off the device.

Example log line:

08-11-2011 01:00:19 WARN  spx.player - SIGINT or SIGTERM received. Stopping player

Troubleshooting

raperca-crash.log

If this log is present, then your device has rebooted due to a problem with the content. In this case, send a report to SpinetiX Support along with a copy of your content / project.

uploader-crash.log

If this log is present, then your device has rebooted due to a problem with the content pull. In this case, send a report to SpinetiX Support.

Memory thrashing

The memory thrashing error occurs when the content being played requires more memory than available, usually due to a large number of objects (i.e. files) that need to be kept into memory. To solve this, the content needs to be optimized in terms of lowering the number of files opened; a good practice to do this is to start creating content using jSignage / JavaScript, rather than using Elementi / HMD (which are easier to use, but are known to increase the number of files opened).

This error is verbosely outputted in both info.log and warn.log files, starting with

date ERROR spx.player           - thrashing detected (...)

followed by multiple lines containing information about malloc, meminfo, memory map sections and ending with:

date FATAL spx.player           - detected memory thrashing, exiting player
This page was last modified on 10 February 2016, at 20:18.