...
location | description | ||
---|---|---|---|
/etc/squirro/ingester.ini | ingester configuration
| ||
/etc/squirro/common.ini | data retention configuration
| ||
/var/log/squirro/ingester/ | ingester log folder with the following files: ingester.log[.123] : Log file of the main ingester process. This mainly contains information about the other subprocesses (or which there are 5 by default) that perform the actual work of procesing data processor_?/processor.log[.123] : Log file of the stateless processors that perform the actual work. In the default logging setting, these files contain information about each item and batch of items | ||
/var/lib/squirro/inputstream/ | ingester data folder where input data is stored temporarily to be processed in the order the data arrived subdirectories have the form YEAR-MONTH-DAY-HOUR e.g. 2018-04-21-10 for 10am on April 21, 2018 in UTC and hold data files that have arrived in that particular hour. Once such "hourly data buckets" have been drained the directory should be automatically removed unless the directory corresponds to the "current hour". The time is in UTC. The "failed" subdirectory holds failed items if there are permanently failed data batched (by default data batches are retried 10 times - if a batch fails that many times). By default failed data files are removed after 30 days. |
Monitoring the backlog
The Squirro REST API provides the following methods.
https://topic_api_url endpoint | Purpose | Parameters | Value | Meaning | ||
---|---|---|---|---|---|---|
/v0/ingester/status (GET) | Exposes metrics about the internal state of the ingester | sections | backlog_total | Returns the number of data batches and items, e.g.:
| ||
backlog_detailed | Breaks down the backlog by subscription_id (or "source" id in the Squirro GUI)
| |||||
errors_total | Shows failed data batches by subscription_id:
| |||||
errors | Shows data batch and item level error information, e.g. in this example a read timeout to ElasticSearch in the "Deduplication" Step:
| |||||
/v0/ingester/action (POST) | Modify the internal state and processing of the ingester | action | reset | DANGEROUS - USE WITH CARE as this short command is irreversible: This deletes all data held in the ingester's input stream.
| ||
reset_subscription | Deletes all data held on behalf of the specified subscription_id
| |||||
reset_all_failed | Deletes all data held in the inputstream/failed directory
| |||||
reset_failed_subscription | Deletes data held in the inpustream/failed directory belonging to the specified subscription_id
|
Under the Hood
With ssh access to the /var/lib/squirro/inputstream/ file system and the /var/lib/squirro/ingester/processor_*/ directories, you can perform more detailed analysis and actions such as retrying failed items even after their maximum number of retries have been exhausted.
Often you will find it useful to inspect the contents of the data directories (/var/lib/squirro/inputstream/) and details in the log files (/var/log/squirro/ingester/processor_*) side by side, so we recomment opening two command line windows.
Internal formats
1. Input Stream
The input stream is represented by one level of directories that place data files into hourly buckets:
Code Block |
---|
2018-04-20-07/ data_subscription_fYFpE1YIR1Syqpwn-9h7eA_batch_DtQv1x5nRpqH69IMRgTiKg_processor_LYhEYu6HTQi9heSNfLy5ZQ.json data_subscription_Q2ZTMosXSw23-3S-rwU45A_batch_foC5xOBBRqqESiHtTLkptA.json 2018-04-20-08/ data_subscription_I_1ZaeAwQdeSylnGwLuA8Q_batch_B5ANcYm3SWWxzQ76tyxhlg.json data_subscription_KnPiaiPiS1OxgkuxQ7NzzQ_batch_UPM-7cT_Q5a2y6X444wROA_processor_0gv18hZ8RRCNNLQCcIkuqQ.json failed/ data_subscription_fVTNoLbKTzO6nPRq1EmRwQ_batch_rTPJYGtRTRizp5rLh9BiUg.json data_subscription_I_1ZaeAwQdeSylnGwLuA8Q_batch_w5MfDB1TRxSGZ4LmzP6YWg.json |
Directories represent the date and time in UTC, the hour, during which the data "arrived" and have the format HOUR-MONTH-DAY-HOUR and there is one optional "failed" directory that holds data that has failed to be enriched and inserted into Squirro. You can move failed items to any of the date folders if you believe that the underlying error has been resolved. More on that to follow.
The data file names contain the subscription id, the batch id - a uniquifier generated and handed out at upload time, and if a particular data file is currently being processed a "processor id" that maps to one of the 1 to n processors (of which there are 5 by default). These identifiers are useful in connecting data batches to the specific Squirro project and sources/subscriptions and to more detailed error information in case something has gone wrong.
For example to find the project, pipeline workflow, and source title, run the following:
Code Block |
---|
# SUBSCRIPTION_ID=I_1ZaeAwQdeSylnGwLuA8Q # mysql topic -e "select concat((select title from projects where id in (select project_id from objects where id = object_id)), ':', (select name from workflows where id = workflow_id), ':', (select title from sources where id = source_id)) as source from subscriptions where id = \"${SUBSCRIPTION_ID}\";" +-----------------------------------------------------+ | source | +-----------------------------------------------------+ | Investment Portfolio:Full:Latest Articles in Stocks | +-----------------------------------------------------+ |
Each data file is a text file containing lines in the JSON format. The first of each of these files contains one lines with the "batch_history" which is only populated in the case of failures and retries. Each subsequent line contains a dictionary in JSON format representing a future Squirro item:
Code Block |
---|
{"batch_history":["G1CyGkMtRsWmmmSO_rzM3w"],"retries":10,"wait_until":15242743 31,"item_history":{"tdyNwCqj67lDox22M2PcgQ":"--> unshorten-link (220) --> Batch G1CyGkMtRsWmmmSO_rzM3w [ deduplication (14) ] --> content-augmentation (18) --> content-conversion (270) --> Batch G1CyGkMtRsWmmmSO_rzM3w [ language-detection (22) ] --> boilerplate-removal (612) --> nearduplicate-detection (893) --> webshot (308) --> cleanup (123) --> Batch G1CyGkMtRsWmmmSO_rzM3w [ index (260) --> filtering [HTTPConnectionPool(host='127.0.0.1', port=81): Read timed out. (read timeout=120)] (120165) ] --error 1"}} {"body":"<html><body>...<\/body><\/html>","new_assoc_subscriptions":["ZYq7KRLHRW6c839VFWe45Q"],"title":"title 1","created_at":"2018-04-15T05:28:22","providers":["bing"],"item_created_at":"2018-04-15T00:47:00","provider":"bing","source_id":"dlQ1BJowSHyFF6stfRsYoQ","id":"Gff11vmq85KNp9tvkGGchQ"} {"body":"<html><body>...<\/body><\/html>","new_assoc_subscriptions":["ZYq7KRLHRW6c839VFWe45Q"],"title":"title 2","created_at":"2018-04-15T05:28:22","providers":["bing"],"item_created_at":"2018-04-15T00:47:00","link":"http:\/\/something.com\/","provider":"bing","source_id":"dlQ1BJowSHyFF6stfRsYoQ","id":"Gff2345q85KNp9tvkGGchQ"} |
2. Log Files
To locate activity on behalf of subscription "KnPiaiPiS1OxgkuxQ7NzzQ", batch "UPM-7cT_Q5a2y6X444wROA" above, you might run:
Code Block |
---|
# grep UPM-7cT_Q5a2y6X444wROA /var/log/squirro/ingester/processor_?/processor.log* /var/log/squirro/ingester/processor_3/processor.log:PV:- MainThread squirro.service.ingester.processor 2018-04-20 10:58:39,833 INFO Batch UPM-7cT_Q5a2y6X444wROA [ deduplication (104) ] processed 1000 items /var/log/squirro/ingester/processor_3/processor.log:PV:- MainThread squirro.service.ingester.processor 2018-04-20 10:59:05,913 INFO Batch UPM-7cT_Q5a2y6X444wROA [ language-detection (146) ] processed 1000 items /var/log/squirro/ingester/processor_3/processor.log:PV:- MainThread squirro.service.ingester.processor 2018-04-20 10:59:42,932 INFO Batch UPM-7cT_Q5a2y6X444wROA [ index (855) --> filtering (14695) --> cache (33) ] processed 1000 items /var/log/squirro/ingester/processor_3/processor.log:PV:- MainThread squirro.service.ingester.processor 2018-04-20 10:59:42,934 INFO Processed u'EJNAMLR_-_7vE72Tsv2D2w' ('KnPiaiPiS1OxgkuxQ7NzzQ') --> unshorten-link (1) --> Batch UPM-7cT_Q5a2y6X444wROA [ deduplication (104) ] --> content-augmentation (1) --> content-conversion (275) --> Batch UPM-7cT_Q5a2y6X444wROA [ language-detection (146) ] --> nearduplicate-detection (285) --> webshot (0) --> cleanup (0) --> Batch UPM-7cT_Q5a2y6X444wROA [ index (855) --> filtering (14695) --> cache (33) ] /var/log/squirro/ingester/processor_3/processor.log:PV:- MainThread squirro.service.ingester.processor 2018-04-20 10:59:42,934 INFO Processed u'ymBL3UGBP87Kyv9OJKSMsQ' ('KnPiaiPiS1OxgkuxQ7NzzQ') --> unshorten-link (1) --> Batch UPM-7cT_Q5a2y6X444wROA [ deduplication (104) ] --> content-augmentation (2) --> content-conversion (225) --> Batch UPM-7cT_Q5a2y6X444wROA [ language-detection (146) ] --> nearduplicate-detection (181) --> webshot (4) --> cleanup (1) --> Batch UPM-7cT_Q5a2y6X444wROA [ index (855) --> filtering (14695) --> cache (33) ] |
The above log lines show how a data batch has been execution some steps in batches: deduplication, language-detection, index, filtering, and cache and others in parallel (last two lines above): unshorten-link, content-augmentation, content-conversion, near-duplicate-detection, webshot and cleanup. The numbers in parentheses following each of the steps indicate the number of milliseconds that step took.
Note that large durations in non-batched steps (in INFO log lines containing the work "Processed") have a larger impact particularly if the batch size is large (as is the case in the example above with a batch size of 1000). While batched steps and their durations are logging inside square brackets [ ], e.g. Batch UPM-7cT_Q5a2y6X444wROA [ language-detection (146) ] while non-batched parallel steps are not, e.g. nearduplicate-detection (181). That is because parallel steps share a pool of 10 threads (by default) such that the a duration of 181 per item for near-duplicate-detection in reality would add out to 181 milliseconds times 100 (181 ms/threads * 1000 items / 10 threads), i.e. over 18 seconds while language-detection takes 146 milliseconds for all 1000 items in the batch together.
Also note that the logged steps are the internal names which as of Squirro release 2.6.0 tend to differ from the external names in the User interface:
Internal Name | Enrichment Type | Internal Name | Enrichment Type | Internal Name | Enrichment Type |
---|---|---|---|---|---|
boilerplate-removal | Noise Removal | content-conversion | Content Extraction | nearduplicate-detection | Near-Duplicate Detection |
cache | Cache Cleaning | deduplication | Deduplication | pipelet | Pipelet (with custom name) |
cleanup | Content Standardization | filtering | Search Tagging and Alerting | unshorten-link | Unshorten Link |
content-augmentation | Content Augmentation | language-detection | Language Detection | webshot | Thumbnail Extraction |
Debugging Scenarios
Some These are some of the scenarios that we have been using repeatedly and might be useful to you.
1. Why is data failing to arrive?
Suppose the "api/topic/v0/ingester/status.json?sections=errors_total" endpoint returns that there are errors. One way to proceed is to look for the batch_history entry in /var/lib/squirro/inputstream/failed/ files or in files that are still active in date-time folders /var/lib/squirro/inputstream/????-??-??-??/ perhaps filtered by a subscription_id, e.g:
Code Block |
---|
# ll -tr /var/lib/squirro/inputstream/*/data_subscription_I_1ZaeAwQdeSylnGwLuA8Q_*
-rw-r--r--. 1 sqingest squirro 508092 Apr 16 11:22 /var/lib/squirro/inputstream/failed/data_subscription_I_1ZaeAwQdeSylnGwLuA8Q_batch_BZPZXCWBQYaZcBMtwLo7gA.json
-rw-r--r--. 1 sqingest squirro 222809 Apr 17 16:12 /var/lib/squirro/inputstream/failed/data_subscription_I_1ZaeAwQdeSylnGwLuA8Q_batch_w5MfDB1TRxSGZ4LmzP6YWg.json
-rw-r--r--. 1 sqingest squirro 555573 Apr 20 14:14 /var/lib/squirro/inputstream/2018-04-20-12/data_subscription_I_1ZaeAwQdeSylnGwLuA8Q_batch_6urzTZ3DTOS-v_l9Uv8njg.json |
The list above provides you with batch ids to further look into in logs, but first it usually makes sense to look at the tail end of the batch history. As the batch history tends to be long, we suggest only looking at the last say 160 characters:
Code Block |
---|
# grep "batch_history" /var/lib/squirro/inputstream/*/data_subscription_I_1ZaeAwQdeSylnGwLuA8Q_* | sed -e "s/^.*\(.\{160\}\)/\1/"
B5ANcYm3SWWxzQ76tyxhlg [ index (275) --> filtering [HTTPConnectionPool(host='127.0.0.1', port=81): Read timed out. (read timeout=120)] (120205) ] --error 10"}}
duplicate-detection (96) --> webshot (135) --> cleanup (7) --> Batch BZPZXCWBQYaZcBMtwLo7gA [ index (158) --> filtering (30382) ] --error NO MORE RETRIES: 10"}}
al (268) --> nearduplicate-detection (526) --> webshot (182) --> cleanup (13) --> Batch qZSekOqcRT-2CaETDvo5dQ [ index (93) --> filtering (82358) ] --error 1"}} |
In the example scenario above it appears that all three occurrences were due to problems with the "filtering" step, or externally "Search Tagging and Alerting". The first instance points to a timeout of 2 minutes (120 thousand milliseconds) while the second and third error also failed with "filtering", but more detail is needed. The first case suggests increasing the filtering service timeout or perhaps submitting smaller batches, but how do we find more details on the latter two occurrences?
Here the two batch ids "BZPZXCWBQYaZcBMtwLo7gA" and "qZSekOqcRT-2CaETDvo5dQ" help to drill down further using the logs under /var/log/squirro/ingester/processor_?/processor.log*. Pulled the date time in front of each log lines, lets you look at all activity on that particular batch in order which is useful as more than one processors likely has worked on that batch for different retries.
Code Block |
---|
# grep "qZSekOqcRT-2CaETDvo5dQ" /var/log/squirro/ingester/processor_?/processor.log* | sed -e "s/^\(.*\)\([0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9] [0-9][0-9]:[0-9][0-9]:[0-9][0-9],[0-9][0-9][0-9] \)/\2\1/" | sort
2018-04-17 16:12:55,225 /var/log/squirro/ingester/processor_3/processor.log.2:PV:- MainThread squirro.service.ingester.processor INFO Processed u'mNkU6HiN12HQLv7L0Dhs3Q' ('I_1ZaeAwQdeSylnGwLuA8Q') --> unshorten-link (216) --> Batch qZSekOqcRT-2CaETDvo5dQ [ deduplication (21) ] --> content-augmentation (16) --> content-conversion (7) --> Batch qZSekOqcRT-2CaETDvo5dQ [ language-detection (258) ] --> boilerplate-removal (704) --> nearduplicate-detection (273) --> webshot (154) --> cleanup (156) --> Batch qZSekOqcRT-2CaETDvo5dQ [ index (93) --> filtering (82358) ] --error 1 |
This shows that processor_3 has work on the batch most recently which allows us to inspect the log file more closely to reveal:
Code Block |
---|
PV:- MainThread squirro.service.ingester.processor 2018-04-17 16:12:55,205 INFO Batch qZSekOqcRT-2CaETDvo5dQ [ index (93) --> filtering (82358) no more items ] processed 0 items
PV:- MainThread squirro.service.ingester.processor 2018-04-17 16:12:55,205 INFO Item_ids to retry are [u'3UQ7q17Q0pq3lohXhrAX1A', u'CWJ3IOyiH5cAybyqYUWG1A', u'mNkU6HiN12HQLv7L0Dhs3Q', u'6hE9yD1vWriHvXiaNeq0Gw', u'ZfFnPSCv45Xm2qWcVSvVpA', u'raHy2ljSNrVvkf_7uE4_ZQ', u'Yu0jsEGvbDjoK0-Xu2BOfw', u'-jsVk2IE1bmGN1EqvSww4A', u'o8ibQNpaaJRXcvkpGvLOAA', u'Ri1niXuX-H6Z-zOucGXzEQ', u'LFi3FzO2IuI-3J0eMTyI8Q', u'OyF7KiMcQ4RH5-P2ilQJaQ', u'4m1XGg1JNpSiJ9UAAbhCsg', u'205C9xY0PovrRkuktqDqjA', u'ucGylIz8ovtqPEnZKhHBaw'] |
The filtering steps calls to the filtering service. Using the rough time of the call "2018-04-17 16:12" reveals the following:
Code Block |
---|
PV:- Thread-749 squirro.lib.topicproxy 2018-04-17 16:12:55,200 WARNING unable to get locator for project u'NM_Ee9nRQqyodzC9MIXssw'
PV:- Thread-749 squirro.service.filtering.main 2018-04-17 16:12:55,200 ERROR Failed to filter items
Traceback (most recent call last):
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/service/filtering/main.py", line 241, in POST
self.filter_processor.process_batch(items, global_config_dict)
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/service/filtering/processor.py", line 76, in process_batch
self._perform_actions(batch_context, item_context)
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/service/filtering/processor.py", line 138, in _perform_actions
filter_obj, item_context.item_dict, batch_context)
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/service/filtering/processor.py", line 232, in _get_filter_if_matches_item
return runner.check_match(item_dict)
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/service/filtering/query.py", line 129, in check_match
items = self.retrieve_items(query)
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/service/filtering/query.py", line 99, in retrieve_items
res = self._read_items(query)
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/service/filtering/query.py", line 104, in _read_items
reader = self._get_reader()
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/service/filtering/query.py", line 111, in _get_reader
locator_dict = self.topicproxy.get_project_locator(project_id)
File "/opt/squirro/virtualenv/lib/python2.7/site-packages/squirro/lib/topicproxy/__init__.py", line 216, in get_project_locator
raise Exception()
Exception |
The above happens to correspond to a bug that we have since fixed and patched with Squirro release 2.6.0-104 .